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
