Navigation-Menus (Do Not Edit Here!)

Wednesday, March 5, 2014

SmarterMail SMTP Log "Data transfer failed" error

We ran in to this error few weeks back. with our Backup email relay and spooling system.

We have a Watchguard firewall with a "SMTP proxy" filtering spam on all inbound traffic to the relay servers

We noticed that we are having a lot log entries where the email delivery failed with the following entry in the SMTP log

[2014.03.05] 09:45:46 [89.249.234.3][18261257] cmd: DATA

[2014.03.05] 09:45:51 [89.249.234.3][18261257] rsp: 354 Start mail input; end with <CRLF>.<CRLF>

[2014.03.05] 09:47:49 [89.249.234.3][18261257] rsp: 421 Command timeout, closing transmission channel

[2014.03.05] 09:47:49 [89.249.234.3][18261257] data transfer failed.

[2014.03.05] 09:47:49 [89.249.234.3][18261257] disconnected at 05/03/2014 09:47:49

Cause:


The emails that are dropped with the "data transfer failed." error are emails that were quarantined or blocked by the WG Spam firewall

Details:



What's interesting was we were not able to reproduce the issue. it seems to be happening for random emails. then we checked the firewall logs to see if something was happening to the email from the WG firewall 

Firewall log for the effected email


ProxyMatch

ProxyQuarantine: SMTP Classified as confirmed SPAM

pri=6

disp=Allow

policy=VPS072-SMRelay1_SMTP_Proxy_IN-00

protocol=smtp/tcp

src_ip=89.249.234.3

src_port=56029

dst_ip=185.17.174.55

dst_port=25

src_intf=1-WAN1

dst_intf=104-INBAY_SYSTEMS

rc=600

proxy_act=SMTP incoming SM-Relay Proxy

sender=iqbal0791@yahoo.com

recipients=user@mydomain.co.uk

Smartermail log


Initial handshake and the SM server creates the connection
-----------------------------------------------------------------------------------------------------
[2014.03.05] 09:44:37 [89.249.234.3][18261257] rsp: 220 relay1.inbaysystems.com

[2014.03.05] 09:44:37 [89.249.234.3][18261257] connected at 05/03/2014 09:44:37

[2014.03.05] 09:44:41 [89.249.234.3][18261257] cmd: EHLO [89.249.234.3]

[2014.03.05] 09:44:41 [89.249.234.3][18261257] rsp: 250-relay1.inbaysystems.com Hello [89.249.234.3]250-SIZE 52428800250-AUTH LOGIN CRAM-MD5250-STARTTLS250 OK

[2014.03.05] 09:44:44 [89.249.234.3][18261257] cmd: MAIL FROM:<iqbal0791@yahoo.com>

[2014.03.05] 09:44:49 [89.249.234.3][18261257] rsp: 250 OK <iqbal0791@yahoo.com> Sender ok

[2014.03.05] 09:45:20 [89.249.234.3][18261257] cmd: RCPT TO:<user@mydomain.co.uk>

[2014.03.05] 09:45:20 [89.249.234.3][18261257] rsp: 250 OK <user@mydomain.co.uk> Recipient ok


The email data transfer starts and during this time the email is scanned and quarantined by the WG firewall 
causing the "data transfer failed." error
----------------------------------------------------------------------------------------------------------------------------
[2014.03.05] 09:45:46 [89.249.234.3][18261257] cmd: DATA

[2014.03.05] 09:45:51 [89.249.234.3][18261257] rsp: 354 Start mail input; end with <CRLF>.<CRLF>

[2014.03.05] 09:47:49 [89.249.234.3][18261257] rsp: 421 Command timeout, closing transmission channel

[2014.03.05] 09:47:49 [89.249.234.3][18261257] data transfer failed.

[2014.03.05] 09:47:49 [89.249.234.3][18261257] disconnected at 05/03/2014 09:47:49
 ----------------------------------------------------------------------------------------------------------------------------

 
I did a lot of research online looking for an explanation for this stumbled upon a few other things that may cause similar issues

MTU value issues with ISP's and the local network


http://www.tweakservers.com/421-command-timeout/

Hope this will help save some time for you guys, since there are no proper explanations or fixes for this issue on the internet