Conversation with x.x.x.x[x.x.x.x] timed out while sending end of data

[Kristjan Nii]

Hi,

It/I might sound dumb, but please  bear with me...

For some reason my external email gateway fails to deliver some emails to my internal machine.

The gateway runs postfix+amavis+spamassasin+clamav. Internal machine has postfix+clamav with very small load. All emails in question are from the same source, from my ISP.

Log info about a particular email:

Apr 22 16:32:12 mailhost postfix/smtpd[22832]: E2A36C84B2: client=localhost[127.0.0.1]

Apr 22 16:32:12 mailhost postfix/cleanup[22738]: E2A36C84B2: message-id=<201504221332...@mailhost.example.zz>

Apr 22 16:32:12 mailhost postfix/qmgr[30648]: E2A36C84B2: from=<noreply...@isp.zz>, size=7385, nrcpt=1 (queue active)

Apr 22 16:32:12 mailhost amavis[22879]: (22879-15-3) FWD from <noreply...@isp.zz> -> <us...@example.zz>,BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E2A36C84B2

Apr 22 16:32:12 mailhost postfix/smtp[22632]: E2A36C84B2: enabling PIX workarounds: disable_esmtp delay_dotcrlf for x.x.x.x[x.x.x.x]:25

Apr 22 16:32:12 mailhost amavis[22879]: (22879-15-3) Passed BAD-HEADER-8 {RelayedInbound,Quarantined}, [xxx.xxx.xxx.xxx]:55925 [xx.xx.xx.xx] <noreply...@isp.zz> -> <us...@example.zz>, quarantine: k/badh-kptbg9M-W8dx, Queue-ID: 04F22C848E, mail_id: kptbg9M-W8dx, Hits: -0.041, size: 6451, queued_as: E2A36C84B2, 2886 ms

Apr 22 16:32:12 mailhost postfix/smtp[22989]: 04F22C848E: to=<us...@example.zz>, relay=127.0.0.1[127.0.0.1]:10024, conn_use=3, delay=18, delays=0.08/15/0/2.9, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E2A36C84B2)

Apr 22 16:42:13 mailhost postfix/smtp[22632]: E2A36C84B2: to=<us...@example.zz>, relay=x.x.x.x[x.x.x.x]:25, delay=600, delays=0.02/0/0.01/600, dsn=4.4.2, status=deferred (conversation with x.x.x.x[x.x.x.x] timed out while sending end of data -- message may be sent more than once)

Apr 22 16:55:01 mailhost postfix/qmgr[30648]: E2A36C84B2: from=<noreply...@isp.zz>, size=7385, nrcpt=1 (queue active)

Apr 22 16:55:22 mailhost postfix/smtp[23649]: E2A36C84B2: enabling PIX workarounds: disable_esmtp delay_dotcrlf for x.x.x.x[x.x.x.x]:25

Apr 22 17:05:32 mailhost postfix/smtp[23649]: E2A36C84B2: to=<us...@example.zz>, relay=x.x.x.x[x.x.x.x]:25, delay=1999, delays=1369/20/0.02/610, dsn=4.4.2, status=deferred (conversation with x.x.x.x[x.x.x.x] timed out while sending end of data -- message may be sent more than once)

Apr 22 17:40:01 mailhost postfix/qmgr[30648]: E2A36C84B2: from=<noreply...@isp.zz>, size=7385, nrcpt=1 (queue active)

Apr 22 17:40:02 mailhost postfix/smtp[24761]: E2A36C84B2: enabling PIX workarounds: disable_esmtp delay_dotcrlf for x.x.x.x[x.x.x.x]:25

Apr 22 17:50:12 mailhost postfix/smtp[24761]: E2A36C84B2: to=<us...@example.zz>, relay=x.x.x.x[x.x.x.x]:25, delay=4680, delays=4068/0.12/1.1/610, dsn=4.4.2, status=deferred (conversation with x.x.x.x[x.x.x.x] timed out while sending end of data -- message may be sent more than once)

Apr 22 19:00:01 mailhost postfix/qmgr[30648]: E2A36C84B2: from=<noreply...@isp.zz>, size=7385, nrcpt=1 (queue active)

Apr 22 19:10:11 mailhost postfix/error[26558]: E2A36C84B2: to=<us...@example.zz>, relay=none, delay=9478, delays=8868/610/0/0.01, dsn=4.4.2, status=deferred (delivery temporarily suspended: conversation with x.x.x.x[x.x.x.x] timed out while sending end of data -- message may be sent more than once)

Apr 22 20:20:01 mailhost postfix/qmgr[30648]: E2A36C84B2: from=<noreply...@isp.zz>, size=7385, nrcpt=1 (queue active)

Apr 22 20:20:01 mailhost postfix/smtp[28154]: E2A36C84B2: enabling PIX workarounds: disable_esmtp delay_dotcrlf for x.x.x.x[x.x.x.x]:25

AND SO ON........

In mailq it is tagged with "delivery temporarily suspended: conversation with x.x.x.x[x.x.x.x] timed out while sending end of data -- message may be sent more than once"

Can someone point me in the right direction? I can and will provide any further details You may need!

Sincerely,

Kristjan 

[Wietse Venema]

Kristjan Nii:

> Apr 22 16:55:01 mailhost postfix/qmgr[30648]: E2A36C84B2:
> from=<noreply...@isp.zz>, size=7385, nrcpt=1 (queue active)
> Apr 22 16:55:22 mailhost postfix/smtp[23649]: E2A36C84B2: enabling PIX
> workarounds: disable_esmtp delay_dotcrlf for x.x.x.x[x.x.x.x]:25
> Apr 22 17:05:32 mailhost postfix/smtp[23649]: E2A36C84B2:
> to=<us...@example.zz>, relay=x.x.x.x[x.x.x.x]:25, delay=1999,
> delays=1369/20/0.02/610, dsn=4.4.2, status=deferred (conversation with
> x.x.x.x[x.x.x.x] timed out while sending end of data -- message may be sent
> more than once)

The Cisco PIX (ASA) has a history of bugs that break email. As the
logging shows, Postfix can work around some bugs but but it cannot
work around other bugs, such as bugs in their handling of DKIM-signed
email.

Wietse

[Kristjan Nii]

Thank you for your response! 

I viewed the some emails in the queue and did not see DKIM signatures in them. Also, our network guys confirmed, that ASA version is 7.3, which should be bug-free. 

Any other ideas or things I should/could check and test?

Kristjan  

[Bill Cole]

On 28 Apr 2015, at 8:45, Kristjan Nii wrote:

> Thank you for your response!
> I viewed the some emails in the queue and did not see DKIM signatures
> in
> them. Also, our network guys confirmed, that ASA version is 7.3, which
> should be bug-free.

Perhaps it "should be" (a slippery English idiom that might mean a few
different things...) but your logging indicates otherwise. The "enabling
PIX workarounds" warnings are not random accidents.

The Cisco implementation of semi-transparent SMTP proxying that
interferes with what extensions a server is allowed to advertise to a
client is one big bug in design: a functional mode that should not have
ever been offered. It is impossible to operate a sound modern mail
server behind that filter. Historically it has also had a series of
implementation bugs as well (i.e. malfunctions that were not part of the
intentional design) and it would be unwise to assume that series has
ended, but ultimately any MTA behind an ASA with that switched on will
have chronic insoluble problems even if Cisco's code is finally doing
precisely all that they intend and nothing more.

> Any other ideas or things I should/could check and test?

Note that by obliterating all of the domain name and IP address details
from your log excerpt you protect nothing and assure that no one else is
able to examine the problem directly or inform your troubleshooting with
specific useful information. The relationship between these two machines
is unclear and made more so by your obfuscation. So my recommendations
are necessarily vague...

Examine the behavior of any other devices and software besides the
supposedly "bug-free" ASA that might be interfering with the
conversation. This could include other networking devices or local
packet filtering software with an unusual configuration. If this
connection is not using TLS, you might also benefit from an examination
of packet captures of a session on both ends.

Also, you may need to figure out exactly what this log line means:

Apr 22 16:32:12 mailhost amavis[22879]: (22879-15-3) Passed BAD-HEADER-8
{RelayedInbound,Quarantined}, [xxx.xxx.xxx.xxx]:55925 [xx.xx.xx.xx]
<noreply...@isp.zz> -> <us...@example.zz>, quarantine:
k/badh-kptbg9M-W8dx, Queue-ID: 04F22C848E, mail_id: kptbg9M-W8dx, Hits:
-0.041, size: 6451, queued_as: E2A36C84B2, 2886 ms

I don't run Amavis so I don't know exactly what that signifies, but it
looks a bit ominous. I suppose it might be possible that Amavis is doing
something unobvious to the messages that is somehow causing the inside
machine to take a very long time to analyze them and so causing the
timeouts at end of data.

Correlating the log entries of the internal and external machines for a
more complete picture may also help.

[Wietse Venema]

Kristjan Nii:

> Thank you for your response!
> I viewed the some emails in the queue and did not see DKIM signatures in
> them. Also, our network guys confirmed, that ASA version is 7.3, which
> should be bug-free.

> Any other ideas or things I should/could check and test?

Other issues may have to do with broken IP path MTU discovery
(which an be worked around by turning that off in the sender's
TCP/IP stack), or broken window scaling, or some other bug.
This can be diagnosed by looking at a packet recording.

And one should not exclude the possibility that your email
is blocked by some firewalling rule, which will have te same
result that packets are silently discarded.

Wietse

[Kristjan Nii]

Thank you, Wietse ja Bill for your advice and tips (and patience); we were able to resolve the issue. In fact, it was still ASA-related.