Hi, I have repeating problem with delivering mail to one of our customers. It looks like e-mail stays endlessly in active queue. At first I've thought that it might be some network issue on customer side as my netstat shows something waits for a long time in Send-Q:
tcp 0 86284 myserver:41488 mailin.customer.pl:smtp ESTABLISHED But then I realised that this time customer server answered: Jul 8 12:16:58 zonk postfix/smtp[10732]: DF7C21811E53: to=<[email protected]>, relay=mailin.tpsa.pl[212.160.172.68]:25, delay=4.5, +delays=0.96/0.03/0.17/3.3, dsn=4.0.0, status=deferred (host mailin.tpsa.pl[212.160.172.68] said: 451 Requested mail action not taken: mailbox +unavailable (in reply to RCPT TO command)) (They use "451 Requested mail action not taken" as a kind of greylisting) So I guess this e-mail should be in deferred queue. But then I see: Jul 8 12:43:33 zonk postfix/qmgr[7095]: DF7C21811E53: from=<[email protected]>, size=4254293, nrcpt=2 (queue active) Jul 8 13:33:40 zonk postfix/qmgr[16317]: DF7C21811E53: skipped, still being delivered Jul 8 13:34:41 zonk postfix/qmgr[16317]: DF7C21811E53: skipped, still being delivered Jul 8 13:35:58 zonk postfix/qmgr[16317]: DF7C21811E53: skipped, still being delivered [...] messages repeated as above up to the moment I requeued a message with postsuper. After that story repeated the same way. In the morning I requeued message again. This time I got nothing from mailin.customer.pl in mail.log. What could be the reason for that? What else can I check? The problem is only with one customer... Thank you in advance, Jakub More detailed log messages (I've excluded amavis logs - if they are of any use I can send them too of course): Jul 8 12:16:12 zonk postfix/smtpd[5940]: 7D1091811E35: client=unknown[11.22.33.44] Jul 8 12:16:13 zonk postfix/cleanup[9867]: 7D1091811E35: message-id=<ff36880904aa4a91b31d2f22df5f4...@somehost> Jul 8 12:16:51 zonk postfix/qmgr[7095]: 7D1091811E35: from=<[email protected]>, size=4253875, nrcpt=2 (queue active) Jul 8 12:16:53 zonk postfix/smtpd[10271]: connect from localhost[127.0.0.1] Jul 8 12:16:53 zonk postfix/smtpd[10271]: 356B71811E50: client=localhost[127.0.0.1] Jul 8 12:16:53 zonk postfix/cleanup[9285]: 356B71811E50: message-id=<ff36880904aa4a91b31d2f22df5f4...@somehost> Jul 8 12:16:53 zonk postfix/qmgr[7095]: 356B71811E50: from=<[email protected]>, size=4254391, nrcpt=3 (queue active) Jul 8 12:16:53 zonk postfix/smtpd[10271]: connect from localhost[127.0.0.1] Jul 8 12:16:53 zonk postfix/smtpd[10271]: DF7C21811E53: client=localhost[127.0.0.1] Jul 8 12:16:53 zonk postfix/cleanup[9867]: DF7C21811E53: message-id=<ff36880904aa4a91b31d2f22df5f4...@somehost> Jul 8 12:16:53 zonk postfix/smtpd[5940]: disconnect from unknown[11.22.33.44] Jul 8 12:16:54 zonk postfix/virtual[10697]: 356B71811E50: to=<[email protected]>, relay=virtual, delay=1.6, delays=0.65/0/0/0.9 9, dsn=2.0.0, status=sent (delivered to maildir) Jul 8 12:16:54 zonk postfix/qmgr[7095]: DF7C21811E53: from=<[email protected]>, size=4254293, nrcpt=2 (queue active) Jul 8 12:16:54 zonk postfix/smtpd[10271]: disconnect from localhost[127.0.0.1] Jul 8 12:16:54 zonk postfix/smtp[9761]: 7D1091811E35: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=42, delay s=39/0/0.01/3.5, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=10714-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 356B71811E50) Jul 8 12:16:54 zonk postfix/smtp[9761]: 7D1091811E35: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=42, delays=39/0/0.01/3.5, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=10714-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 356B71811E50) Jul 8 12:16:54 zonk postfix/qmgr[7095]: 7D1091811E35: removed Jul 8 12:16:58 zonk postfix/smtp[10732]: DF7C21811E53: to=<[email protected]>, relay=mailin.tpsa.pl[212.160.172.68]:25, d elay=4.5, delays=0.96/0.03/0.17/3.3, dsn=4.0.0, status=deferred (host mailin.tpsa.pl[212.160.172.68] said: 451 Requested mail action not taken: m ailbox unavailable (in reply to RCPT TO command)) Jul 8 12:43:33 zonk postfix/qmgr[7095]: DF7C21811E53: from=<[email protected]>, size=4254293, nrcpt=2 (queue active) Jul 8 13:33:40 zonk postfix/qmgr[16317]: DF7C21811E53: skipped, still being delivered Jul 8 13:34:41 zonk postfix/qmgr[16317]: DF7C21811E53: skipped, still being delivered [...] messages repeated as above Jul 8 17:42:27 zonk postfix/qmgr[16317]: DF7C21811E53: skipped, still being delivered --- postsuper -r DF7C21811E53 Jul 8 18:12:49 zonk postfix/postsuper[30562]: DF7C21811E53: requeued Jul 8 18:12:49 zonk postfix/postsuper[30562]: Requeued: 1 message Jul 8 18:13:00 zonk postfix/pickup[28126]: CF6BC1811E5F: uid=101 from=<[email protected]> orig_id=DF7C21811E53 Jul 8 18:13:00 zonk postfix/cleanup[30466]: CF6BC1811E5F: message-id=<ff36880904aa4a91b31d2f22df5f4...@somehost> Jul 8 18:13:01 zonk postfix/qmgr[16317]: CF6BC1811E5F: from=<[email protected]>, size=4254404, nrcpt=2 (queue active) Jul 8 18:13:03 zonk postfix/smtpd[30572]: connect from localhost[127.0.0.1] Jul 8 18:13:03 zonk postfix/smtpd[30572]: 878AC1811E60: client=localhost[127.0.0.1] Jul 8 18:13:03 zonk postfix/cleanup[30466]: 878AC1811E60: message-id=<ff36880904aa4a91b31d2f22df5f4...@somehost> Jul 8 18:13:04 zonk postfix/qmgr[16317]: 878AC1811E60: from=<[email protected]>, size=4254909, nrcpt=3 (queue active) Jul 8 18:13:04 zonk postfix/smtpd[30572]: disconnect from localhost[127.0.0.1] Jul 8 18:13:04 zonk postfix/smtpd[30572]: connect from localhost[127.0.0.1] Jul 8 18:13:04 zonk postfix/smtpd[30572]: 496151811E61: client=localhost[127.0.0.1] Jul 8 18:13:04 zonk postfix/cleanup[30466]: 496151811E61: message-id=<ff36880904aa4a91b31d2f22df5f4...@somehost> Jul 8 18:13:04 zonk postfix/virtual[30574]: 878AC1811E60: to=<[email protected]>, relay=virtual, delay=1, delays=0.69/0.01/0/0.3, dsn=2 .0.0, status=sent (delivered to maildir) Jul 8 18:13:04 zonk postfix/virtual[30574]: 878AC1811E60: to=<[email protected]>, relay=virtual, delay=1.2, delays=0.69/0.01/0/0.46, dsn=2 .0.0, status=sent (delivered to maildir) Jul 8 18:13:04 zonk postfix/virtual[30574]: 878AC1811E60: to=<[email protected]>, relay=virtual, delay=1.3, delays=0.69/0.01/0/0.63, dsn=2 .0.0, status=sent (delivered to maildir) Jul 8 18:13:04 zonk postfix/qmgr[16317]: 878AC1811E60: removed Jul 8 18:13:04 zonk postfix/qmgr[16317]: 496151811E61: from=<[email protected]>, size=4254822, nrcpt=2 (queue active) Jul 8 18:13:04 zonk postfix/smtpd[30572]: disconnect from localhost[127.0.0.1] Jul 8 18:13:04 zonk postfix/smtp[30467]: CF6BC1811E5F: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=21371, delays=21368 /0/0/3.3, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=30255-08, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 878AC1811E60) Jul 8 18:13:04 zonk postfix/smtp[30467]: CF6BC1811E5F: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=21 371, delays=21368/0/0/3.3, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=30255-08, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 878AC1811E60) Jul 8 18:13:04 zonk postfix/qmgr[16317]: CF6BC1811E5F: removed Jul 8 18:13:05 zonk postfix/virtual[30574]: 496151811E61: to=<[email protected]>, relay=virtual, delay=0.78, delays=0.59/0.02/0/0.17, dsn= 2.0.0, status=sent (delivered to maildir) Jul 8 18:13:08 zonk postfix/smtp[30576]: 496151811E61: to=<[email protected]>, relay=mailin.tpsa.pl[212.160.172.68]:25, d elay=3.9, delays=0.59/0.02/0.12/3.1, dsn=4.0.0, status=deferred (host mailin.tpsa.pl[212.160.172.68] said: 451 Requested mail action not taken: m ailbox unavailable (in reply to RCPT TO command)) Jul 8 18:33:40 zonk postfix/qmgr[16317]: 496151811E61: from=<[email protected]>, size=4254822, nrcpt=2 (queue active) Jul 8 18:34:25 zonk postfix/qmgr[31581]: 496151811E61: skipped, still being delivered [...] message repeats Jul 8 23:33:40 zonk postfix/qmgr[31581]: 496151811E61: skipped, still being delivered Jul 8 23:34:46 zonk postfix/qmgr[6250]: 496151811E61: from=<[email protected]>, size=4254822, nrcpt=2 (queue active) Jul 9 04:35:28 zonk postfix/qmgr[19716]: 496151811E61: from=<[email protected]>, size=4254822, nrcpt=2 (queue active) ----- Jul 9 08:40:01 zonk postfix/postsuper[9196]: 496151811E61: requeued Jul 9 08:40:01 zonk postfix/postsuper[9196]: Requeued: 1 message Jul 9 08:41:00 zonk postfix/pickup[7926]: 283B21811E64: uid=101 from=<[email protected]> orig_id=496151811E61 Jul 9 08:41:00 zonk postfix/cleanup[8912]: 283B21811E64: message-id=<ff36880904aa4a91b31d2f22df5f4...@somehost> Jul 9 08:41:01 zonk postfix/qmgr[19716]: 283B21811E64: from=<[email protected]>, size=4254933, nrcpt=2 (queue active) Jul 9 08:41:02 zonk postfix/smtpd[9094]: connect from localhost[127.0.0.1] Jul 9 08:41:02 zonk postfix/smtpd[9094]: ED064160021: client=localhost[127.0.0.1] Jul 9 08:41:02 zonk postfix/cleanup[8912]: ED064160021: message-id=<ff36880904aa4a91b31d2f22df5f4...@somehost> Jul 9 08:41:04 zonk postfix/qmgr[19716]: ED064160021: from=<[email protected]>, size=4255437, nrcpt=3 (queue active) Jul 9 08:41:04 zonk postfix/smtpd[9094]: disconnect from localhost[127.0.0.1] Jul 9 08:41:04 zonk postfix/smtpd[9094]: connect from localhost[127.0.0.1] Jul 9 08:41:04 zonk postfix/smtpd[9094]: 4737C178001: client=localhost[127.0.0.1] Jul 9 08:41:04 zonk postfix/cleanup[8912]: 4737C178001: message-id=<ff36880904aa4a91b31d2f22df5f4...@somehost> Jul 9 08:41:04 zonk postfix/virtual[9097]: ED064160021: to=<[email protected]>, relay=virtual, delay=1.7, delays=1.3/0/0/0.46, dsn=2.0. 0, status=sent (delivered to maildir) Jul 9 08:41:05 zonk postfix/virtual[9097]: ED064160021: to=<[email protected]>, relay=virtual, delay=2.8, delays=1.3/0/0/1.6, dsn=2.0.0, s tatus=sent (delivered to maildir) Jul 9 08:41:05 zonk postfix/qmgr[19716]: 4737C178001: from=<[email protected]>, size=4255350, nrcpt=2 (queue active) Jul 9 08:41:05 zonk postfix/smtpd[9094]: disconnect from localhost[127.0.0.1] Jul 9 08:41:05 zonk postfix/smtp[8913]: 283B21811E64: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=52082, delays=52077/ 0/0/4.7, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=08617-09, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as ED064160021) Jul 9 08:41:05 zonk postfix/smtp[8913]: 283B21811E64: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=520 82, delays=52077/0/0/4.7, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=08617-09, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as ED064160021) Jul 9 08:41:05 zonk postfix/qmgr[19716]: 283B21811E64: removed Jul 9 08:41:06 zonk postfix/virtual[9097]: ED064160021: to=<[email protected]>, relay=virtual, delay=3.7, delays=1.3/0/0/2.4, dsn=2.0.0, s tatus=sent (delivered to maildir) Jul 9 08:41:06 zonk postfix/qmgr[19716]: ED064160021: removed Jul 9 08:41:06 zonk postfix/virtual[9236]: 4737C178001: to=<[email protected]>, relay=virtual, delay=2.4, delays=1.5/0.06/0/0.8, dsn=2.0.0 , status=sent (delivered to maildir)
