Hi Bob,
As I mentioned, I have a fairly limited amount of information.
Nevertheless, here's the log data. To debug such problems, I will enable debug logging on both the ASG and the postfix server next time I have a problem.
Furthermore, I haven't seen any problem since, even after putting back the ASG as a relay server. I will wait an other few days and see if such errors crawl back in.
Here's the ASG logs including a bit of noise data. I did a replace all on all email addresses to keep anonymity, but the replace is the same across both logs to keep it consistent.
Code:
2009:06:21-21:26:47 coyote exim[11631]: 2009-06-21 21:26:47 SMTP connection from (QJZGENO) [122.45.43.230]:25775 closed by DROP in ACL
2009:06:21-21:27:06 coyote exim[27259]: 2009-06-21 21:27:06 SMTP connection from [172.16.0.8]:37353 (TCP/IP connection count = 1)
2009:06:21-21:27:06 coyote exim[27259]: 2009-06-21 21:27:06 SMTP connection from [172.16.0.8]:37354 (TCP/IP connection count = 2)
2009:06:21-21:27:06 coyote exim[11646]: 2009-06-21 21:27:06 [172.16.0.8] F=<abcdef@gmail.com> R=<mmaaa@internode.on.net> Accepted: from relay
2009:06:21-21:27:06 coyote exim[11647]: 2009-06-21 21:27:06 [172.16.0.8] F=<cameron@somedomain.com.au> R=<uuueeee@gmail.com> Accepted: from relay
2009:06:21-21:27:14 coyote exim[27259]: 2009-06-21 21:27:14 SMTP connection from [123.17.172.89]:13852 (TCP/IP connection count = 3)
2009:06:21-21:27:14 coyote exim[11662]: 2009-06-21 21:27:14 id="1003" severity="info" sys="SecureMail" sub="smtp" name="email rejected" srcip="123.17.172.89" from="schoolyardt59%40scp.ch" to="hs_flickapolitan%40netadvanced.com" size="-1" reason="rdns_helo" extra="RDNS missing"
2009:06:21-21:27:14 coyote exim[11662]: 2009-06-21 21:27:14 H=(UQGIADJYJB) [123.17.172.89]:13852 F=<schoolyardt59@scp.ch> rejected RCPT <hs_flickapolitan@netadvanced.com>: No RDNS entry for 123.17.172.89
2009:06:21-21:27:14 coyote exim[11662]: 2009-06-21 21:27:14 SMTP connection from (UQGIADJYJB) [123.17.172.89]:13852 closed by DROP in ACL
2009:06:21-21:27:15 coyote exim[27259]: 2009-06-21 21:27:15 SMTP connection from [123.17.172.89]:13915 (TCP/IP connection count = 3)
2009:06:21-21:27:16 coyote exim[11669]: 2009-06-21 21:27:16 id="1003" severity="info" sys="SecureMail" sub="smtp" name="email rejected" srcip="123.17.172.89" from="tinfoil%40siena.vic.edu.au" to="hs_flickapolitan%40netadvanced.com" size="-1" reason="rdns_helo" extra="RDNS missing"
2009:06:21-21:27:16 coyote exim[11669]: 2009-06-21 21:27:16 H=(QDSIIWUY) [123.17.172.89]:13915 F=<tinfoil@siena.vic.edu.au> rejected RCPT <hs_flickapolitan@netadvanced.com>: No RDNS entry for 123.17.172.89
2009:06:21-21:27:16 coyote exim[11669]: 2009-06-21 21:27:16 SMTP connection from (QDSIIWUY) [123.17.172.89]:13915 closed by DROP in ACL
2009:06:21-21:32:06 coyote exim[11646]: 2009-06-21 21:32:06 SMTP connection from mail.fallscreek.netadvanced.net [172.16.0.8]:37353 lost while reading message data
2009:06:21-21:32:06 coyote exim[11647]: 2009-06-21 21:32:06 1MILCU-00031r-0v SMTP data timeout (message abandoned) on connection from mail.fallscreek.netadvanced.net [172.16.0.8]:37354 F=<cameron@somedomain.com.au>
2009:06:21-21:36:25 coyote exim[27259]: 2009-06-21 21:36:25 SMTP connection from [62.179.121.38]:7268 (TCP/IP connection count = 1)
and here's the postfix data including the noise.
You will notice that the message queue was released manually at that time (postqueue -f)
I had 10 messages in the queue at the time. postfix initial_destination_concurrency = 2
Code:
Jun 21 21:27:08 [postfix/qmgr] 1587CE201D: from=<abcdef@gmail.com>, size=82467, nrcpt=1 (queue active)
Jun 21 21:27:08 [postfix/qmgr] F3D80A2004: from=<cameron@somedomain.com.au>, size=96719, nrcpt=1 (queue active)
Jun 21 21:27:08 [postfix/qmgr] 58D33E2025: from=<aaabbbb@dodo.com.au>, size=1210137, nrcpt=1 (queue active)
Jun 21 21:27:08 [postfix/qmgr] 67AE3E2019: from=<cccdddd@yahoo.com>, size=859193, nrcpt=1 (queue active)
Jun 21 21:27:08 [postfix/qmgr] 95A9342009: from=<prvs=john.smith/0420d9ab16@abcd.com.au>, size=5518865, nrcpt=1 (queue active)
Jun 21 21:27:08 [postfix/qmgr] 937E842008: from=<abcdef@gmail.com>, size=98111, nrcpt=1 (queue active)
Jun 21 21:27:08 [postfix/qmgr] E7A0512201D: from=<prvs=john.smith/042157ffa1@abcd.com.au>, size=3346212, nrcpt=1 (queue active)
Jun 21 21:27:08 [postfix/qmgr] 766C62A010: from=<sssdddfff@bigpond.net.au>, size=3320159, nrcpt=1 (queue active)
Jun 21 21:27:08 [postfix/qmgr] 76B9D12201C: from=<prvs=john.smith/042157ffa1@abcd.com.au>, size=2198097, nrcpt=1 (queue active)
Jun 21 21:27:08 [postfix/qmgr] 384D9E201A: from=<cccdddd@yahoo.com>, size=859193, nrcpt=1 (queue active)
Jun 21 21:27:51 [postfix/smtpd] connect from localhost[127.0.0.1]
Jun 21 21:27:51 [postfix/smtpd] disconnect from localhost[127.0.0.1]
Jun 21 21:28:50 [postfix/smtpd] connect from localhost[127.0.0.1]
Jun 21 21:28:50 [postfix/smtpd] disconnect from localhost[127.0.0.1]
Jun 21 21:29:50 [postfix/smtpd] connect from localhost[127.0.0.1]
Jun 21 21:29:50 [postfix/smtpd] disconnect from localhost[127.0.0.1]
Jun 21 21:30:08 [postfix/smtp] F3D80A2004: to=<uuueeee@gmail.com>, relay=172.16.0.1[172.16.0.1]:25, delay=212879, delays=212699/0.06/0.02/180, dsn=4.4.2, status=deferred (conversation with 172.16.0.1[172.16.0.1] timed out while sending message body)
Jun 21 21:30:08 [postfix/smtp] 1587CE201D: to=<mmaaa@internode.on.net>, relay=172.16.0.1[172.16.0.1]:25, delay=283830, delays=283650/0.07/0.01/180, dsn=4.4.2, status=deferred (conversation with 172.16.0.1[172.16.0.1] timed out while sending message body)
Jun 21 21:30:08 [postfix/error] 58D33E2025: to=<mmaaa@internode.on.net>, relay=none, delay=277419, delays=277238/180/0/0.01, dsn=4.4.2, status=deferred (delivery temporarily suspended: conversation with 172.16.0.1[172.16.0.1] timed out while sending message body)
Jun 21 21:30:08 [postfix/error] 67AE3E2019: to=<mmaaa@internode.on.net>, relay=none, delay=385141, delays=384960/180/0/0.04, dsn=4.4.2, status=deferred (delivery temporarily suspended: conversation with 172.16.0.1[172.16.0.1] timed out while sending message body)
Jun 21 21:30:08 [postfix/error] 95A9342009: to=<uuueeee@gmail.com>, relay=none, delay=216518, delays=216338/180/0/0.04, dsn=4.4.2, status=deferred (delivery temporarily suspended: conversation with 172.16.0.1[172.16.0.1] timed out while sending message body)
Jun 21 21:30:08 [postfix/error] E7A0512201D: to=<uuueeee@gmail.com>, relay=none, delay=194928, delays=194748/180/0/0.03, dsn=4.4.2, status=deferred (delivery temporarily suspended: conversation with 172.16.0.1[172.16.0.1] timed out while sending message body)
Jun 21 21:30:08 [postfix/error] 937E842008: to=<mmaaa@internode.on.net>, relay=none, delay=111917, delays=111737/180/0/0.06, dsn=4.4.2, status=deferred (delivery temporarily suspended: conversation with 172.16.0.1[172.16.0.1] timed out while sending message body)
Jun 21 21:30:08 [postfix/error] 766C62A010: to=<mmaaa@internode.on.net>, relay=none, delay=257117, delays=256936/180/0/0.03, dsn=4.4.2, status=deferred (delivery temporarily suspended: conversation with 172.16.0.1[172.16.0.1] timed out while sending message body)
Jun 21 21:30:08 [postfix/error] 384D9E201A: to=<ooouuuu@internode.on.net>, relay=none, delay=385140, delays=384960/180/0/0.04, dsn=4.4.2, status=deferred (delivery temporarily suspended: conversation with 172.16.0.1[172.16.0.1] timed out while sending message body)
Jun 21 21:30:08 [postfix/error] 76B9D12201C: to=<uuueeee@gmail.com>, relay=none, delay=194935, delays=194755/180/0/0.05, dsn=4.4.2, status=deferred (delivery temporarily suspended: conversation with 172.16.0.1[172.16.0.1] timed out while sending message body)
Jun 21 21:30:51 [postfix/smtpd] connect from localhost[127.0.0.1]
Jun 21 21:30:51 [postfix/smtpd] disconnect from localhost[127.0.0.1]
Jun 21 21:31:50 [postfix/smtpd] connect from localhost[127.0.0.1]
Jun 21 21:31:50 [postfix/smtpd] disconnect from localhost[127.0.0.1]
At the time of these logs, I had already restarted the daemons on both machines as well as rebooted both machines (ASG+Postfix).