The mail drop happened again, but it isn't a connection reset. Looks like, for whatever reason, it tried to insert the header twice and didn't catch the error. (I can get the mail logs and doublecheck, but I think three duplicates came in basically together.)
The mail setup isn't "simple" but it isn't super twisted - postfix (tumgreyspf policy) to dspam lmtp, dspam (w/ clamav) to dbmail lmtp. (Postfix normalizes the domain wildcards, etc down to [email protected]) Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[sql] dbpgsql.c,db_query(+287): query failed [INSERT INTO dbmail_headername (headername) VALUES ('x-netstation-spam')] : [ERROR: duplicate key value violates unique constraint "dbmail_headername_1"#012] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[sql] dbpgsql.c,db_query(+287): query failed [INSERT INTO dbmail_tofield (physmessage_id, toname, toaddr) VALUES (182912,'undisclosed-recipients','')] : [ERROR: current transaction is aborted, commands ignored until end of transaction block#012] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[message] dbmail-message.c,insert_address_cache(+1079): insert tofield failed [INSERT INTO dbmail_tofield (physmessage_id, toname, toaddr) VALUES (182912,'undisclosed-recipients','')] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[sql] dbpgsql.c,db_query(+287): query failed [INSERT INTO dbmail_fromfield (physmessage_id, fromname, fromaddr) VALUES (182912,'FedEx Online Team Management','[email protected]')] : [ERROR: current transaction is aborted, commands ignored until end of transaction block#012] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[message] dbmail-message.c,insert_address_cache(+1079): insert fromfield failed [INSERT INTO dbmail_fromfield (physmessage_id, fromname, fromaddr) VALUES (182912,'FedEx Online Team Management','[email protected]')] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[sql] dbpgsql.c,db_query(+287): query failed [INSERT INTO dbmail_datefield (physmessage_id, datefield) VALUES (182912,'2010-10-21 07:43:41')] : [ERROR: current transaction is aborted, commands ignored until end of transaction block#012] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[message] dbmail-message.c,insert_field_cache(+1105): insert datefield failed [INSERT INTO dbmail_datefield (physmessage_id, datefield) VALUES (182912,'2010-10-21 07:43:41')] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[sql] dbpgsql.c,db_query(+287): query failed [INSERT INTO dbmail_replytofield (physmessage_id, replytoname, replytoaddr) VALUES (182912,'','[email protected]')] : [ERROR: current transaction is aborted, commands ignored until end of transaction block#012] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[message] dbmail-message.c,insert_address_cache(+1079): insert replytofield failed [INSERT INTO dbmail_replytofield (physmessage_id, replytoname, replytoaddr) VALUES (182912,'','[email protected]')] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[sql] dbpgsql.c,db_query(+287): query failed [INSERT INTO dbmail_subjectfield (physmessage_id, subjectfield) VALUES (182912,'Dear Customer!')] : [ERROR: current transaction is aborted, commands ignored until end of transaction block#012] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[message] dbmail-message.c,insert_field_cache(+1105): insert subjectfield failed [INSERT INTO dbmail_subjectfield (physmessage_id, subjectfield) VALUES (182912,'Dear Customer!')] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[sql] dbpgsql.c,db_query(+287): query failed [INSERT INTO dbmail_envelope (physmessage_id, envelope) VALUES (182912,'("Thu, 21 Oct 2010 15:43:41 +0800" "[SPAM] Dear Customer!" (("FedEx Online Team Management" NIL "info" "courier.com")) (("FedEx Online Team Management" NIL "info" "courier.com")) ((NIL NIL "SPAMSENDER" "SPAM.com.hk")) ((NIL NIL "undisclosed-recipients" NIL)) NIL NIL NIL "<[email protected]>")')] : [ERROR: current transaction is aborted, commands ignored until end of transaction block#012] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[message] dbmail-message.c,dbmail_message_cache_envelope(+1274): insert envelope failed [INSERT INTO dbmail_envelope (physmessage_id, envelope) VALUES (182912,'("Thu, 21 Oct 2010 15:43:41 +0800" "[SPAM] Dear Customer!" (("FedEx Online Team Management" NIL "info" "courier.com")) (("FedEx Online Team Management" NIL "info" "courier.com")) ((NIL NIL "SPAMSENDER" "SPAM.com.hk")) ((NIL NIL "undisclosed-recipients" NIL)) NIL NIL NIL "<[email protected]>")')] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[db] db.c,db_copymsg(+3812): error getting message size for message [365524] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[sort] sort.c,sort_deliver_to_mailbox(+192): error copying message to user [4] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[sort] sortsieve.c,sort_fileinto(+319): Could not file message into mailbox; not cancelling keep. Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[db] db.c,db_copymsg(+3812): error getting message size for message [365524] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[sort] sort.c,sort_deliver_to_mailbox(+192): error copying message to user [4] Oct 21 04:19:31 mayhem dbmail/lmtpd[29968]: Error:[delivery] pipe.c,insert_messages(+601): unknown temporary failure in sort_and_deliver for useridnr [4] Oct 21 04:19:31 mayhem dspam[13972]: Got error 511 in response to message data: 511 Recipient <[email protected]> Permanent Failure Address Status Bad destination mailbox address#015 On 10/19/10 12:56 PM, [email protected] wrote: > On 10/9/10 5:25 PM, Paul J Stevens wrote: >> On 10/09/2010 05:14 PM, Reindl Harald wrote: >>> I think this is a bug on dbmail-side >>> >>> lmtpd should send a 4xx-temorary-error instead a 5xx-hard-bounce >>> So postfix would try later to deliver the message again >> That is easier said than done. >> >> The current setup will put lmtpd into sleep-mode immediately if the >> database goes away, and stay there until the connection recovers. In >> sleep mode no new client connections are accepted, and indeed in a >> perfect world existing connections should be dealt with gracefully. >> >> So obviously there are race-conditions at play here. Currently queries >> either succeed, or queries fail. The exact nature of the query failure >> is *not* examined, nor communicated back up the call stack! All query >> errors are hard errors. >> >> The solution in this case is simple of course: do not shut down your >> database, unless you've shut down postfix or dbmail-lmtpd first. In >> fact, shutting down lmtpd during dbmail-maintenance runs doesn't sound >> too bad. >> >> > As far as I can tell from other apps (a couple of which also keep > long-lived connections) the db didn't actually do anything - the errors > are limited to dbmail. At this point I'm just waiting to see if it recurs. > > >>> Postfix does this as sample if he losts the connection to lmtp for whatever >>> reason, but not if the target gives a 5xx-error back >>> >>> Am 09.10.2010 17:06, schrieb Dis McCarthy: >>>> I got a bounce message (to the same alias that failed, strangely >>>> enough) during the nightly cron run. It looks >>>> like several messages were outright discarded at that time. Shouldn't a db >>>> connection reset (or db unavailable) be >>>> a temporary error? Is there a place to configure that? >>>> >>>> <[email protected]> (expanded from<root>): host 127.0.0.1[127.0.0.1] >>>> said: 550 >>>> Recipient<[email protected]> FAIL (in reply to RCPT TO command) >>>> >>>> Looking at the logs: >>>> >>>> Oct 9 05:00:03 mayhem postfix/pickup[10082]: 309771C0405: uid=0 >>>> from=<root> >>>> Oct 9 05:00:03 mayhem postfix/cleanup[12188]: 309771C0405: >>>> message-id=<[email protected]> >>>> Oct 9 05:00:03 mayhem postfix/qmgr[21315]: 309771C0405: >>>> from=<[email protected]>, size=763, nrcpt=1 (queue active) >>>> Oct 9 05:00:03 mayhem dbmail/lmtpd[20778]: Message:[serverchild] >>>> serverchild.c,PerformChildTask(+349): incoming connection from [127.0.0.1] >>>> by pid [20778] >>>> Oct 9 05:00:03 mayhem dbmail/lmtpd[20778]: Error:[sql] >>>> dbpgsql.c,db_query(+287): query failed [SELECT deliver_to FROM >>>> dbmail_aliases WHERE lower(alias) = lower('[email protected]') AND >>>> lower(alias)<> lower(deliver_to)] : [FATAL: terminating connection due >>>> to administrator command#012server closed the connection >>>> unexpectedly#012#011This probably means the server terminated >>>> abnormally#012#011before or while processing the request.#012] >>>> Oct 9 05:00:03 mayhem dbmail/lmtpd[20778]: Error:[auth] >>>> authsql.c,__auth_query(+293): error executing query >>>> Oct 9 05:00:03 mayhem postfix/lmtp[12191]: 309771C0405: >>>> to=<[email protected]>, orig_to=<root>, relay=127.0.0.1[127.0.0.1]:24, >>>> delay=0.73, delays=0.46/0.02/0.07/0.18, dsn=5.0.0, status=bounced (host >>>> 127.0.0.1[127.0.0.1] said: 550 Recipient<[email protected]> FAIL (in >>>> reply to RCPT TO command)) >>>> Oct 9 05:00:03 mayhem postfix/cleanup[12188]: 94A9C1C041B: >>>> message-id=<[email protected]> >>>> Oct 9 05:00:03 mayhem postfix/bounce[12193]: 309771C0405: sender >>>> non-delivery notification: 94A9C1C041B >>>> >>>> >>>> >>>> >>>> _______________________________________________ >>>> DBmail mailing list >>>> [email protected] >>>> http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail >>> >>> _______________________________________________ >>> DBmail mailing list >>> [email protected] >>> http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail > _______________________________________________ > DBmail mailing list > [email protected] > http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail _______________________________________________ DBmail mailing list [email protected] http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail
