[7.460][BUG][NOTABUG] Intermittent: Outgoing SMTP Proxy failure

[microgluf]

Hi,

I am experiencing issues with emails from my internal server using the Astaro as a relay host.
Some messages have been waiting for up to 3 days in the queue of my internal mail server.

I haven't been able to find the cause, only the effects. The message is released for the mail server queue and sent to the Astaro. After the header is accepted by the ASG, the message body times-out.

2009:06:21-21:27:06 coyote exim[11647]: 2009-06-21 21:27:06 [172.16.0.8] F=<cameron@somedomain.com> R=<user@mydomain.com> Accepted: from relay
....
2009-06-21 21:32:06 1MILCU-00031r-0v SMTP data timeout (message abandoned) on connection from mail.internal.mydomain.net [172.16.0.8]:37354 F=<cameron@somedomain.com>

My mail server is a strait postfix server (v 2.5.1), that has been running for a few years without a problem and with older versions of the ASG without any glitches.

Steps I have tried:
- Triple checked all my SMTP configuration settings on the ASG as well as the internal mail server.
- Restarted postfix on internal server, even rebooted out of desperation.
- retried multiple times to release the queues from the internal server, same message every time.
- restarted SMTP daemon on the ASG
- finally also rebooted the ASG

Solution:
- I bypassed the relaying to the ASG and the messages were all sent successfully.

ASG Configuration:
- Nothing special there, the internal server is allowed to relay.
- Domain signing is disabled.
- Scan relayed (outgoing) messages is disabled.
- Encryption is enabled but only one user.

Has anyone experienced similar issues ??

[microgluf]

Something I did notice, is that most if not ALL the troubled emails seemed to have attachements, mostly only jpg images.

Other note: the outgoing emails were not all from internal users. Some were genuine relayed domains.
Example schematic path: third party SMTP server -> ASG Incoming proxy -> internal email server -> envelope rewrite -> ASG Outgoing relay -> final destination.
as well as: internal user -> internal email server -> ASG Outgoing relay -> final destination.

Hope that will help.

[BAlfson]

Is this repeatable in any way - an email from a specific user with a specific file - whatever.

Can you post the relevant log from the postfix server? And the complete SMTP transaction from the Astaro instead of just an excerpt?

Cheers - Bob

[microgluf]

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.

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

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).

[microgluf]

I haven't been able to fault the system again, so I'll put that as one of those life quirks, unsolved mysteries...

[Astaro Beta Bot]

Astaro Beta Report
--------------------------------
Version: 7.460
Type: BUG
State: NOTABUG
Reporter: microgluf
Contributor: 
MantisID: 
--------------------------------