A NOTE has been added to this issue. ====================================================================== http://www.dbmail.org/mantis/view.php?id=475 ====================================================================== Reported By: lrosenman Assigned To: aaron ====================================================================== Project: DBMail Issue ID: 475 Category: Database layer Reproducibility: always Severity: major Priority: normal Status: assigned target: ====================================================================== Date Submitted: 14-Dec-06 23:56 CET Last Modified: 17-Jan-07 15:55 CET ====================================================================== Summary: Invalid timestamps generated to PostgreSQL backend Description: Random messages coming in via dbmail-smtp are failed going into a PostgreSQL 8.1.5 (SQL_ASCII) Database.
====================================================================== ---------------------------------------------------------------------- lrosenman - 14-Dec-06 23:59 ---------------------------------------------------------------------- Here's the DB log for the same message (First one): $ grep 'pg-prod\[38071\]' /var/log/pg-prod.log Dec 14 15:42:45 thebighonker pg-prod[38071]: [1-1] <[unknown]%[unknown]> LOG: connection received: host=localhost port=63419 Dec 14 15:42:45 thebighonker pg-prod[38071]: [2-1] <ler%dbmail> LOG: connection authorized: user=ler database=dbmail Dec 14 15:42:45 thebighonker pg-prod[38071]: [3-1] <ler%dbmail> LOG: statement: SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0 Dec 14 15:42:45 thebighonker pg-prod[38071]: [4-1] <ler%dbmail> LOG: duration: 6.107 ms Dec 14 15:42:45 thebighonker pg-prod[38071]: [5-1] <ler%dbmail> LOG: statement: SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0 Dec 14 15:42:45 thebighonker pg-prod[38071]: [6-1] <ler%dbmail> LOG: duration: 1.287 ms Dec 14 15:42:45 thebighonker pg-prod[38071]: [7-1] <ler%dbmail> LOG: statement: SELECT 1=1 FROM dbmail_envelope LIMIT 1 OFFSET 0 Dec 14 15:42:45 thebighonker pg-prod[38071]: [8-1] <ler%dbmail> LOG: duration: 1.443 ms Dec 14 15:42:45 thebighonker pg-prod[38071]: [9-1] <ler%dbmail> LOG: statement: SELECT deliver_to FROM dbmail_aliases WHERE lower(alias) = lower('ler') AND lower(alias) <> Dec 14 15:42:45 thebighonker pg-prod[38071]: [9-2] lower(deliver_to) Dec 14 15:42:45 thebighonker pg-prod[38071]: [10-1] <ler%dbmail> LOG: duration: 2.517 ms Dec 14 15:42:45 thebighonker pg-prod[38071]: [11-1] <ler%dbmail> LOG: statement: SELECT user_idnr FROM dbmail_users WHERE lower(userid) = lower('ler') Dec 14 15:42:45 thebighonker pg-prod[38071]: [12-1] <ler%dbmail> LOG: duration: 1.482 ms Dec 14 15:42:45 thebighonker pg-prod[38071]: [13-1] <ler%dbmail> LOG: statement: BEGIN Dec 14 15:42:45 thebighonker pg-prod[38071]: [14-1] <ler%dbmail> LOG: duration: 0.258 ms Dec 14 15:42:45 thebighonker pg-prod[38071]: [15-1] <ler%dbmail> LOG: statement: SELECT user_idnr FROM dbmail_users WHERE lower(userid) = lower('[EMAIL PROTECTED]@__') Dec 14 15:42:45 thebighonker pg-prod[38071]: [16-1] <ler%dbmail> LOG: duration: 0.565 ms Dec 14 15:42:45 thebighonker pg-prod[38071]: [17-1] <ler%dbmail> LOG: statement: SELECT mailbox_idnr FROM dbmail_mailboxes WHERE name ILIKE 'INBOX' AND owner_idnr=1 Dec 14 15:42:45 thebighonker pg-prod[38071]: [18-1] <ler%dbmail> LOG: duration: 1.737 ms Dec 14 15:42:45 thebighonker pg-prod[38071]: [19-1] <ler%dbmail> LOG: statement: INSERT INTO dbmail_physmessage (messagesize, internal_date) VALUES (0, Dec 14 15:42:45 thebighonker pg-prod[38071]: [19-2] TO_TIMESTAMP('1166132546-05-07 15:42:45', 'YYYY-MM-DD HH:MI:SS')) Dec 14 15:42:45 thebighonker pg-prod[38071]: [20-1] <ler%dbmail> ERROR: timestamp out of range Dec 14 15:42:45 thebighonker pg-prod[38071]: [20-2] <ler%dbmail> STATEMENT: INSERT INTO dbmail_physmessage (messagesize, internal_date) VALUES (0, TO_TIMESTAMP('1166132546-05-07 Dec 14 15:42:45 thebighonker pg-prod[38071]: [20-3] 15:42:45', 'YYYY-MM-DD HH:MI:SS')) Dec 14 15:42:45 thebighonker pg-prod[38071]: [21-1] <ler%dbmail> LOG: statement: ROLLBACK Dec 14 15:42:45 thebighonker pg-prod[38071]: [22-1] <ler%dbmail> LOG: duration: 0.174 ms Dec 14 15:42:45 thebighonker pg-prod[38071]: [23-1] <ler%dbmail> LOG: disconnection: session time: 0:00:00.03 user=ler database=dbmail host=localhost port=63419 $ I may be able to get the message from my MBX store if y'all feel it's necessary. Thanks! ---------------------------------------------------------------------- lrosenman - 15-Dec-06 17:26 ---------------------------------------------------------------------- I just attached a copy of the message that caused this, as it exists in my MBX file (the first line is the MBX header for it, IIRC). ---------------------------------------------------------------------- lrosenman - 15-Dec-06 17:28 ---------------------------------------------------------------------- gmime version is 2.2.3. Platform, more specifically, is FreeBSD/amd64 6.2-PRERELEASE. the kernel/userland is from a day or 2 ago. It is running in 64-bit mode. ---------------------------------------------------------------------- lrosenman - 15-Dec-06 17:39 ---------------------------------------------------------------------- I can give shell access to the machine if that would be helpful, btw. ---------------------------------------------------------------------- aaron - 15-Dec-06 17:50 ---------------------------------------------------------------------- I have an AMD64 Xen box. I'll try to fire up a FreeBSD guest image today and see what happens. ---------------------------------------------------------------------- lrosenman - 15-Dec-06 18:32 ---------------------------------------------------------------------- Aaron, While you are looking at this one, I saw a bunch of warnings out of the code that might be worth looking at (wrong format's, etc). I used the DBMail from ports, and it installed the gmime, etc. ---------------------------------------------------------------------- aaron - 15-Dec-06 19:17 ---------------------------------------------------------------------- Please compile the timestring.c file I've uploaded and post the output. Should be as simple as 'gcc -Wall timestring.c -o timestring' and then './timestring' Let me know if you have any complications. ---------------------------------------------------------------------- lrosenman - 15-Dec-06 19:32 ---------------------------------------------------------------------- $ gcc -Wall timestring.c -o timestring timestring.c: In function `create_current_timestring': timestring.c:20: warning: statement with no effect $ ./timestring 2006-12-15 12:32:21 $ ---------------------------------------------------------------------- aaron - 15-Dec-06 19:52 ---------------------------------------------------------------------- Ok, let's try this one. ---------------------------------------------------------------------- lrosenman - 15-Dec-06 19:57 ---------------------------------------------------------------------- $ gcc -Wall -o timestring2 timestring2.c timestring2.c: In function `create_current_timestring': timestring2.c:35: warning: statement with no effect $ ./timestring2 2006-12-15 12:57:23 TO_TIMESTAMP('2006-12-15 12:57:23', 'YYYY-MM-DD HH:MI:SS') $ ---------------------------------------------------------------------- lrosenman - 16-Dec-06 18:30 ---------------------------------------------------------------------- Ok, I've found 2 things. 1) gmime 2.2.3 has a stray printf that causes exim to return the output: --- gmime-utils.c.orig Fri Jun 16 10:56:15 2006 +++ gmime-utils.c Sat Dec 16 10:25:26 2006 @@ -646,7 +646,7 @@ goto next; } else if (!tm.tm_year) { if ((n = get_year (token->start, token->len)) != -1) { - printf ("2-digit year; "); + d(printf ("2-digit year; ")); tm.tm_year = n - 1900; } goto next; 2) Yahoo headers seem to trigger the timestamp issue. attached are the 2 queue file pieces of a message that RELIABLY create the PGSQL timestamp issue. I've attached a tarball with the queue files. What else do y'all need? Thanks a ton for looking into it. LER ---------------------------------------------------------------------- aaron - 16-Dec-06 20:21 ---------------------------------------------------------------------- I emailed this bug to Jeff Stedfast, GMime maintainer. ---------------------------------------------------------------------- lrosenman - 16-Dec-06 22:23 ---------------------------------------------------------------------- Aaron, Did you email just the printf thing, or the whole kit and kaboodle? (Just curious)... Thanks! ---------------------------------------------------------------------- lrosenman - 16-Dec-06 23:17 ---------------------------------------------------------------------- Interestingly, I did a search in my PostgreSQL log for TO_TIMESTAMP(' and where the next 4 characters are NOT 2006: Dec 16 15:46:13 thebighonker pg-prod[53701]: [19-1] <ler%dbmail> LOG: statement: INSERT INTO dbmail_physmessage (messagesize, internal_date) VALUES (0, TO_TIMESTAMP('53045-12-16 Dec 16 15:49:37 thebighonker pg-prod[53805]: [19-1] <ler%dbmail> LOG: statement: INSERT INTO dbmail_physmessage (messagesize, internal_date) VALUES (0, TO_TIMESTAMP('106429-12-16 Dec 16 15:51:36 thebighonker pg-prod[53885]: [19-1] <ler%dbmail> LOG: statement: INSERT INTO dbmail_physmessage (messagesize, internal_date) VALUES (0, TO_TIMESTAMP('53046-12-16 Dec 16 15:54:25 thebighonker pg-prod[53980]: [19-1] <ler%dbmail> LOG: statement: INSERT INTO dbmail_physmessage (messagesize, internal_date) VALUES (0, TO_TIMESTAMP('53047-12-16 Dec 16 16:03:11 thebighonker pg-prod[54360]: [19-1] <ler%dbmail> LOG: statement: INSERT INTO dbmail_physmessage (messagesize, internal_date) VALUES (0, TO_TIMESTAMP('53048-12-16 Dec 16 16:03:21 thebighonker pg-prod[54391]: [19-1] <ler%dbmail> LOG: statement: INSERT INTO dbmail_physmessage (messagesize, internal_date) VALUES (0, TO_TIMESTAMP('24595-12-16 $ So, I think GMime is getting confused. ---------------------------------------------------------------------- lrosenman - 18-Dec-06 16:02 ---------------------------------------------------------------------- It's definitely YahooGroups mail. I have a number of examples. Do we need more to pass on to Jeff? What else can I do to help? ---------------------------------------------------------------------- aaron - 31-Dec-06 22:32 ---------------------------------------------------------------------- Proposed solution per mailing list discussion is to check if GMime thinks that the year is > the current year, and replace with the current year if that's the case. ---------------------------------------------------------------------- lrosenman - 15-Jan-07 20:34 ---------------------------------------------------------------------- Any news from Jeff Steadfast or on a work-around in DBMail code? This is a showstopper for me, fwiw. ---------------------------------------------------------------------- aaron - 16-Jan-07 05:57 ---------------------------------------------------------------------- Larry, sorry for the delay. I haven't heard back from Jeff at all. Please test the attached patch as a workaround. ---------------------------------------------------------------------- lrosenman - 17-Jan-07 15:55 ---------------------------------------------------------------------- so far, so good. I applied this patch yesterday am, and no PG errors about timestamps have been thrown. I don't have a good way to tell if any messages tripped the fixup, but have to assume that since I received my usual collection of Yahoo Groups mail, that some of them did. Issue History Date Modified Username Field Change ====================================================================== 14-Dec-06 23:56 lrosenman New Issue 14-Dec-06 23:59 lrosenman Note Added: 0001678 15-Dec-06 17:25 lrosenman File Added: bad.msg 15-Dec-06 17:26 lrosenman Note Added: 0001679 15-Dec-06 17:28 lrosenman Note Added: 0001680 15-Dec-06 17:39 lrosenman Note Added: 0001681 15-Dec-06 17:50 aaron Note Added: 0001682 15-Dec-06 18:32 lrosenman Note Added: 0001684 15-Dec-06 19:15 aaron File Added: timestring.c 15-Dec-06 19:17 aaron Note Added: 0001685 15-Dec-06 19:32 lrosenman Note Added: 0001686 15-Dec-06 19:51 aaron File Added: timestring2.c 15-Dec-06 19:52 aaron Note Added: 0001687 15-Dec-06 19:57 lrosenman Note Added: 0001688 16-Dec-06 18:29 lrosenman File Added: bad.msg.spool.tar.gz 16-Dec-06 18:30 lrosenman Note Added: 0001692 16-Dec-06 20:21 aaron Note Added: 0001695 16-Dec-06 22:23 lrosenman Note Added: 0001696 16-Dec-06 23:17 lrosenman Note Added: 0001697 18-Dec-06 16:02 lrosenman Note Added: 0001698 31-Dec-06 22:32 aaron Note Added: 0001704 15-Jan-07 20:34 lrosenman Note Added: 0001722 16-Jan-07 05:53 aaron Status new => assigned 16-Jan-07 05:53 aaron Assigned To => aaron 16-Jan-07 05:56 aaron File Added: emailfromthefuturefix.diff 16-Jan-07 05:57 aaron Note Added: 0001723 17-Jan-07 15:55 lrosenman Note Added: 0001725 ====================================================================== _______________________________________________ Dbmail-dev mailing list Dbmail-dev@dbmail.org http://twister.fastxs.net/mailman/listinfo/dbmail-dev