sporadic deferrals - ReadList.com

5 msg	postconf not displaying all options
3 msg	empty_address_recipient not mapped by virtual o...
5 msg	stop smtp from anyone unless sasl auth?
2 msg	'piped' aliases & DSNs
12 msg	Strange From: in headers
5 msg	Mail - Access Denied
4 msg	qpsmtpd support service for postfix
39 msg	pix workaround broken?
2 msg	X-Original-To after bcc contains wrong address
8 msg	/usr/lib/sendmail delivery status/message id's ...
23 msg	Recommended Filesystems?
8 msg	Mail going to backup server instead main server
3 msg	outgoing rate control
5 msg	mail forwarding loop: how do I prevent this?
5 msg	Server relaying existing virtual mailbox
1 msg	how can I rewrite the Mail From
3 msg	Constant connections from user unknown sending ...

sporadic deferrals
\ Aaron Bennett (20 Jul 2007)
. \ (Wietse Venema) (20 Jul 2007)

8 msg	transport_maps: different behavior if discard o...
4 msg	Address verification questions

Subject:	sporadic deferrals
Group:	Postfix-users
From:	Aaron Bennett
Date:	20 Jul 2007

Hello,

I'm getting sporadic mail deferrals with "unknown transport error" -- on
the order of 1% of incoming mail is getting deferred. We've got several
ldap maps in place -- local recipients, transport, alias, and canonical.

That being said, I would expect sporadic deferrals to be the result of
failed ldap lookups. If that were the case, they'd be consistantly
confined to specific addressess. However this is not the case. I can
send to addresses that also have messages deferred, and if I manually
postmap the lookups on addresses which have deferrals, everything looks
copacetic.

Here's some debugging output... I hope it rings a bell somewhere with
someone. First you'll see the message going through our content filter;
the deferrals are always post-content filter...

thanks,

Aaron Bennett

Jul 19 14:08:00 ajax postfix/smtpd[15646]: < pc-118-42-86-200.cm.vtr.net[200.86.42.118]: RCPT TO: <ultimate>
Jul 19 14:08:00 ajax postfix/smtpd[15646]: extract_addr: input: <ultimate>
Jul 19 14:08:00 ajax postfix/smtpd[15646]: smtpd_check_addr: addr=ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: send attr address = ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: input attribute value: ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: rewrite_clnt: local: ultimate -> ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: send attr address = ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: input attribute value: ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: resolve_clnt: `ultimate' -> transp=`relay' host=`[iris.clarku.edu]' rcpt=`ultimate' flags= class=local
Jul 19 14:08:00 ajax postfix/smtpd[15646]: ctable_locate: install entry key ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: extract_addr: result: ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: check_mail_access: ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: ctable_locate: leave existing entry key ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: check_access: ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: dict_pcre_lookup: /etc/postfix/valid_domains: ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: reject_unauth_destination: ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: permit_auth_destination: ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: ctable_locate: leave existing entry key ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: ctable_locate: leave existing entry key ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: maps_find: recipient_canonical_maps: ultimate: not found
Jul 19 14:08:00 ajax postfix/smtpd[15646]: mail_addr_find: ultimate -> (not found)
Jul 19 14:08:00 ajax postfix/smtpd[15646]: send attr key = ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap-canonical.cf flags=0100 key=ultimate -> status=1 result=
Jul 19 14:08:00 ajax postfix/smtpd[15646]: maps_find: canonical_maps: ultimate: not found
Jul 19 14:08:00 ajax postfix/smtpd[15646]: mail_addr_find: ultimate -> (not found)
Jul 19 14:08:00 ajax postfix/smtpd[15646]: send attr key = ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap-alias.cf flags=0100 key=ultimate -> status=1 result=
Jul 19 14:08:00 ajax postfix/smtpd[15646]: maps_find: virtual_alias_maps: ultimate: not found
Jul 19 14:08:00 ajax postfix/smtpd[15646]: mail_addr_find: ultimate -> (not found)
Jul 19 14:08:00 ajax postfix/smtpd[15646]: send attr key = ultimate
Jul 19 14:08:00 ajax postfix/smtpd[15646]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap-localrecipient.cf flags=0100 key=ultimate -> status=0 result=cuuf
Jul 19 14:08:00 ajax postfix/smtpd[15646]: maps_find: local_recipient_maps: proxy:ldap:/etc/postfix/ldap-localrecipient.cf(0,100): ultimate = cuuf
Jul 19 14:08:00 ajax postfix/smtpd[15646]: mail_addr_find: ultimate -> cuuf
Jul 19 14:08:02 ajax postfix/qmgr[15521]: qmgr_message_sort: ultimate
Jul 19 14:08:02 ajax postfix/qmgr[15521]: qmgr_message_sort: ultimate
Jul 19 14:08:02 ajax postfix/qmgr[15521]: send attr original_recipient = ultimate
Jul 19 14:08:02 ajax postfix/qmgr[15521]: send attr recipient = ultimate
Jul 19 14:08:07 ajax postfix/qmgr[15521]: qmgr_message_sort: ultimate
Jul 19 14:08:07 ajax postfix/qmgr[15521]: send attr address = ultimate
Jul 19 14:08:07 ajax postfix/smtp[15632]: B8B36522FEA: to=<ultimate>, relay=127.0.0.1[127.0.0.1], delay=10, status=sent (250 2.6.0 Ok, id=15149-16, from MTA: 250 Ok: queued as 7A5D1522FFB, but 4 DISCARD)
Jul 19 14:08:07 ajax postfix/qmgr[15521]: input attribute value: ultimate
Jul 19 14:08:07 ajax postfix/qmgr[15521]: resolve_clnt: `ultimate' -> transp=`relay' host=`[iris.clarku.edu]' rcpt=`ultimate' flags= class=local
Jul 19 14:08:07 ajax postfix/qmgr[15521]: qmgr_message_sort: ultimate
Jul 19 14:08:07 ajax postfix/qmgr[15521]: send attr original_recipient = ultimate
Jul 19 14:08:07 ajax postfix/qmgr[15521]: send attr recipient = ultimate
Jul 19 14:08:07 ajax postfix/smtp[15697]: input attribute value: ultimate
Jul 19 14:08:07 ajax postfix/smtp[15697]: input attribute value: ultimate
Jul 19 14:08:07 ajax postfix/smtp[15697]: > iris.clarku.edu[140.232.1.234]: RCPT TO:<ultimate>
Jul 19 14:08:07 ajax postfix/smtp[15697]: < iris.clarku.edu[140.232.1.234]: 250 2.1.5 ultimate
Jul 19 14:08:08 ajax postfix/smtp[15697]: 7A5D1522FFB: to=<ultimate>, relay=iris.clarku.edu[140.232.1.234], delay=1, status=sent (250 2.6.0 <36144b04279.91g55079148> Queued mail for delivery)
Jul 19 14:22:44 ajax postfix/smtpd[15646]: ctable_locate: purge entry key ultimate
____broken one ______
Jul 19 14:24:02 ajax postfix/smtpd[16128]: < 66-169-120-175.dhcp.ftwo.tx.charter.com[66.169.120.175]: RCPT TO: <ultimate>
Jul 19 14:24:02 ajax postfix/smtpd[16128]: extract_addr: input: <ultimate>
Jul 19 14:24:02 ajax postfix/smtpd[16128]: smtpd_check_addr: addr=ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: send attr address = ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: input attribute value: ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: rewrite_clnt: local: ultimate -> ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: send attr address = ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: input attribute value: ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: resolve_clnt: `ultimate' -> transp=`relay' host=`[iris.clarku.edu]' rcpt=`ultimate' flags= class=local
Jul 19 14:24:02 ajax postfix/smtpd[16128]: ctable_locate: install entry key ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: extract_addr: result: ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: check_mail_access: ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: ctable_locate: leave existing entry key ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: check_access: ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: dict_pcre_lookup: /etc/postfix/valid_domains: ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: reject_unauth_destination: ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: permit_auth_destination: ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: ctable_locate: leave existing entry key ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: ctable_locate: leave existing entry key ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: maps_find: recipient_canonical_maps: ultimate: not found
Jul 19 14:24:02 ajax postfix/smtpd[16128]: mail_addr_find: ultimate -> (not found)
Jul 19 14:24:02 ajax postfix/smtpd[16128]: send attr key = ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap-canonical.cf flags=0100 key=ultimate -> status=1 result=
Jul 19 14:24:02 ajax postfix/smtpd[16128]: maps_find: canonical_maps: ultimate: not found
Jul 19 14:24:02 ajax postfix/smtpd[16128]: mail_addr_find: ultimate -> (not found)
Jul 19 14:24:02 ajax postfix/smtpd[16128]: send attr key = ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap-alias.cf flags=0100 key=ultimate -> status=1 result=
Jul 19 14:24:02 ajax postfix/smtpd[16128]: maps_find: virtual_alias_maps: ultimate: not found
Jul 19 14:24:02 ajax postfix/smtpd[16128]: mail_addr_find: ultimate -> (not found)
Jul 19 14:24:02 ajax postfix/smtpd[16128]: send attr key = ultimate
Jul 19 14:24:02 ajax postfix/smtpd[16128]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap-localrecipient.cf flags=0100 key=ultimate -> status=0 result=cuuf
Jul 19 14:24:02 ajax postfix/smtpd[16128]: maps_find: local_recipient_maps: proxy:ldap:/etc/postfix/ldap-localrecipient.cf(0,100): ultimate = cuuf
Jul 19 14:24:02 ajax postfix/smtpd[16128]: mail_addr_find: ultimate -> cuuf
Jul 19 14:24:03 ajax postfix/qmgr[15521]: qmgr_message_sort: ultimate
Jul 19 14:24:03 ajax postfix/qmgr[15521]: qmgr_message_sort: ultimate
Jul 19 14:24:03 ajax postfix/qmgr[15521]: send attr original_recipient = ultimate
Jul 19 14:24:03 ajax postfix/qmgr[15521]: send attr recipient = ultimate
Jul 19 14:24:04 ajax postfix/smtp[17013]: F124F522F4C: to=<ultimate>, relay=127.0.0.1[127.0.0.1], delay=2, status=sent (250 2.6.0 Ok, id=16996-20, from MTA: 250 Ok: queued as 7F724522F63)
Jul 19 14:24:04 ajax postfix/qmgr[15521]: qmgr_message_sort: ultimate
Jul 19 14:24:04 ajax postfix/qmgr[15521]: send attr address = ultimate
Jul 19 14:24:04 ajax postfix/qmgr[15521]: input attribute value: ultimate
Jul 19 14:24:04 ajax postfix/qmgr[15521]: resolve_clnt: `ultimate' -> transp=`relay' host=`[iris.clarku.edu]' rcpt=`ultimate' flags= class=local
Jul 19 14:24:04 ajax postfix/qmgr[15521]: send attr original_recipient = ultimate
Jul 19 14:24:04 ajax postfix/qmgr[15521]: send attr recipient = ultimate
Jul 19 14:24:04 ajax postfix/qmgr[15521]: 7F724522F63: to=<ultimate>, relay=none, delay=0, status=deferred (delivery temporarily suspended: unknown mail transport error)
Jul 19 14:24:04 ajax postfix/qmgr[15521]: qmgr_message_sort: ultimate