MailEnable is losing Emails silently

nanobot
Posts: 3
Joined: Sat May 26, 2007 10:21 am

MailEnable is losing Emails silently

Postby nanobot » Thu Aug 11, 2016 3:03 pm

Dear MailEnable Support Team,

our MailEnable 9.15 Enterprise is silently losing Emails under reproducible circumstances.

The log entries below are from a mail transmission of one of our customers.

The ME mailbox h@aaa.de on ME server mail.aaa.com tried to send an email to a foreign mailbox h@bbb.de in this example.

Following happens according to the SMTP-Activity Log File (see below):
- in the first turn, the receiving mail server is rejecting the email due to greylisting enabled on receiver side – ok.
- in the second turn (3 minutes later, 12:41:44) the greylisting does not block the connection anymore, but instead it comes to a timeout 5 minutes later (12:46:46), and the email was finally not delivered successfully.

Nevertheless the SMTP-Debug Log File says (see below):
- in the first turn – rejected due to greylisting – ok
- in the second turn: Send Completed Successfully (302.075s)

The foreign mail server also says as final result (see below):
- SMTP data timeout (message abandoned) on connection from mail.aaa.com


Since both the sending and the receiving mail server report a timeout, and the recipient did not receive that email, it seems to be obvious that the mail was indeed not delivered successfully.

But if so, why MailEnable now just “forgets” this mail? Why this email gets not handled any further? E.g. sent back to the sender, or retry to deliver it later once again?
Shouldn’t one of these actions be taken in that case? Nothing of that happens. So the sender gets not notified that the email couldn’t be delivered, and the recipient didn’t receive that email – the email just vanishes. Also the log entry in the Debug Log “Send Completed Successfully (302.075s)” is irritating, since it actually wasn’t sent properly, as the last Activity log entry (QUIT) included status code 421 (error), so ME should be aware of the data delivery issue.

How can this issue be fixed?

Please see the log data below for more information.

Log Data:

Logs from MailEnable:
________________________________________
SMTP-Activity-160805:
==============
1st try – greylisted
08/05/16 12:38:44 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 2328 6.6.6.6 CONN 220 ***************************** 0 35 h@aaa.de WG: USB
08/05/16 12:38:44 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 2328 6.6.6.6 EHLO EHLO mail.eee.com 250-ast Hello mail.eee.com [7.7.7.7] 24 158 h@aaa.de WG: USB
08/05/16 12:38:44 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 2328 6.6.6.6 MAIL MAIL FROM:<h@aaa.de> SIZE=38054 250 OK 43 8 h@aaa.de WG: USB
08/05/16 12:38:46 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 2328 6.6.6.6 RCPT RCPT TO:<h@bbb.de> 250 Accepted 34 14 h@aaa.de WG: USB
08/05/16 12:38:46 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 2328 6.6.6.6 DATA DATA 354 Enter message, ending with "." on a line by itself 6 56 h@aaa.de WG: USB
08/05/16 12:38:46 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 2328 6.6.6.6 DATE . 451 Temporary local problem, please try again! 38066 48 h@aaa.de WG: USB
08/05/16 12:38:46 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 2328 6.6.6.6 QUIT QUIT 221 ast closing connection 6 41 h@aaa.de WG: USB

2nd try – after greylisting
08/05/16 12:41:44 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 5592 6.6.6.6 CONN 220 ***************************** 0 35 h@aaa.de WG: USB
08/05/16 12:41:44 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 5592 6.6.6.6 EHLO EHLO mail.eee.com 250-ast Hello mail.eee.com [7.7.7.7] 24 158 h@aaa.de WG: USB
08/05/16 12:41:44 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 5592 6.6.6.6 MAIL MAIL FROM:<h@aaa.de> 250 OK 32 8 h@aaa.de WG: USB
08/05/16 12:41:46 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 5592 6.6.6.6 RCPT RCPT TO:<h@bbb.de> 250 Accepted 34 14 h@aaa.de WG: USB
08/05/16 12:41:46 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 5592 6.6.6.6 DATA DATA 354 Enter message, ending with "." on a line by itself 6 56 h@aaa.de WG: USB
08/05/16 12:46:46 SMTP-OU 61D51FAD656A45C3A28348A46E442395.MAI 5592 6.6.6.6 QUIT QUIT 421 ast SMTP incoming data timeout - closing connection. 6 71 h@aaa.de WG: USB
________________________________________


SMTP-Debug-160805:
=============
1st try – greylisted
08/05/16 12:38:43 ME-I0018: [27AAE1B5DD8A496698007E5DCBAAA5A6.MAI] Outbound message from ([SMTP:h@aaa.de]) requeued as [61D51FAD656A45C3A28348A46E442395.MAI] to the target domain []
08/05/16 12:38:43 ME-I0123: Domain [] has MX list [ast]
08/05/16 12:38:43 ME-I0026: [61D51FAD656A45C3A28348A46E442395.MAI] Sending message
08/05/16 12:38:43 ME-IXXXX: [61D51FAD656A45C3A28348A46E442395.MAI] DNS resolved to the following record: IP Address=6.6.6.6, Family=2, Type=1, Protocol=6
08/05/16 12:38:43 ME-IXXXX: [61D51FAD656A45C3A28348A46E442395.MAI] Failed SSL handshake.
08/05/16 12:38:43 ME-E0037: [61D51FAD656A45C3A28348A46E442395.MAI] Failed to create outbound TLS connection. Message will be retried without TLS.
08/05/16 12:38:44 ME-I0123: Domain [] has MX list [ast]
08/05/16 12:38:44 ME-I0026: [61D51FAD656A45C3A28348A46E442395.MAI] Sending message
08/05/16 12:38:44 ME-IXXXX: [61D51FAD656A45C3A28348A46E442395.MAI] DNS resolved to the following record: IP Address=6.6.6.6, Family=2, Type=1, Protocol=6
08/05/16 12:38:46 ME-IXXXX: [61D51FAD656A45C3A28348A46E442395.MAI] Remote server returned a response indicating a temporary failure. Server Response: (451 Temporary local problem, please try again!**)
08/05/16 12:38:46 ME-I0148: [61D51FAD656A45C3A28348A46E442395.MAI] DATE (DATA Termination) command failed with temporary return code.
08/05/16 12:38:46 ME-E0033: [61D51FAD656A45C3A28348A46E442395.MAI] DATA Transmission failed.
08/05/16 12:38:46 ME-E0059: [61D51FAD656A45C3A28348A46E442395.MAI] Message Delivery Failure. Attempt (0): Domain () returned temporary error for email. Message has been requeued.

2nd try – after greylisting
08/05/16 12:41:44 ME-I0123: Domain [] has MX list [ast]
08/05/16 12:41:44 ME-I0026: [61D51FAD656A45C3A28348A46E442395.MAI] Sending message
08/05/16 12:41:44 ME-IXXXX: [61D51FAD656A45C3A28348A46E442395.MAI] DNS resolved to the following record: IP Address=6.6.6.6, Family=2, Type=1, Protocol=6
08/05/16 12:46:46 ME-I0049: [61D51FAD656A45C3A28348A46E442395.MAI] Send Completed Successfully (302.075s).
________________________________________


Log from foreign mail server:
------------------------------------------------------------------------------------
1st try, canceled due to greylisting
------------------------------------------------------------------------------------
2016:08:05-12:36:35 ast exim-in[30603]: 2016-08-05 12:36:35 [7.7.7.7] F=<h@aaa.de> R=<h@bbb.de> Verifying recipient address with callout
2016:08:05-12:36:36 ast exim-in[30603]: 2016-08-05 12:36:36 1bVcUW-0007xb-0w ctasd reports 'Unknown' RefID:str=0001.0A0C0203.57A46C34.011B,ss=1,re=0.000,recu=0.000,reip=0.000,cl=1,cld=1,fgs=0
2016:08:05-12:36:36 ast exim-in[30603]: 2016-08-05 12:36:36 1bVcUW-0007xb-0w Greylisting: Greylisted 7.7.7.7
------------------------------------------------------------------------------------

------------------------------------------------------------------------------------
2nd try - after greylisting
------------------------------------------------------------------------------------
2016:08:05-12:39:35 ast exim-in[30824]: 2016-08-05 12:39:35 H=mail.eee.com [7.7.7.7]:52695 Warning: profile excludes SANDBOX scan
2016:08:05-12:39:35 ast exim-in[30824]: 2016-08-05 12:39:35 [7.7.7.7] F=<h@aaa.de> R=<h@bbb.de> Verifying recipient address with callout
2016:08:05-12:44:36 ast exim-in[30824]: 2016-08-05 12:44:36 1bVcXQ-00081A-1P SMTP data timeout (message abandoned) on connection from mail.eee.com [7.7.7.7]:52695 F=<h@aaa.de>
------------------------------------------------------------------------------------


Thank you.

Kind Regards,

nanobot
Posts: 3
Joined: Sat May 26, 2007 10:21 am

Re: MailEnable is losing Emails silently

Postby nanobot » Thu Aug 11, 2016 3:31 pm

In the meantime I captured the IP packets exchanged between the email servers.

I think the actual problem is that ME does not send the final "." anymore, which indicates that the email has completely been sent to the receiving server.

In the first try (which is rejected by greylisting) this IP packet gets still sent properly:

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 56
15:54:05 - Flags: PSH, ACK
15:54:05 - 354 Enter message, ending with "." on a line by itself

15:54:05 - >7.7.7.7:62070 - 6.6.6.6:25 :: 1356
15:54:05 - Flags: PSH, ACK
15:54:05 - dkim-signature:v=1; c=relaxed/relaxed;... -> Email header + body

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 0
15:54:05 - Flags: ACK

15:54:05 - >7.7.7.7:62070 - 6.6.6.6:25 :: 3
15:54:05 - Flags: PSH, ACK
15:54:05 - .

So end of message is indicated properly here.

In the second try to deliver this email, ME does not send this packet anymore, and thus the receiving mail server listens until the timeout happens:

15:57:03 - <6.6.6.6:25 - 7.7.7.7:62221 :: 56
15:57:03 - Flags: PSH, ACK
15:57:03 - 354 Enter message, ending with "." on a line by itself

15:57:03 - >7.7.7.7:62221 - 6.6.6.6:25 :: 1356
15:57:03 - Flags: PSH, ACK
15:57:03 - dkim-signature:v=1; c=relaxed/relaxed;... -> Email header + body

15:57:03 - <6.6.6.6:25 - 7.7.7.7:62221 :: 0
15:57:03 - Flags: ACK

15:57:03 - >7.7.7.7:62221 - 6.6.6.6:25 :: 6
15:57:03 - Flags: PSH, ACK
15:57:03 - QUIT

The IP packet with the "." payload gets not sent anymore. So the receiving mail server thinks the message was incomplete and omits it, and ME thinks it was delivered successfully, which isn't true. So the email vanishes silently, and neither the sender nor the receiver of that email get any notification on it!

That's a grave issue for an email server!

Maybe the circumstance that initially a TLS connection gets tried to be established, which finally fails and thus a fallback to unencrypted email takes place, plays a role in this issue, too.



Here the complete IP packet flow:

first try - rejected by greylisting
===================================

15:54:00 - >7.7.7.7:62069 - 6.6.6.6:25 :: 0
15:54:00 - Flags: SYN, ECH, CWR

15:54:00 - <6.6.6.6:25 - 7.7.7.7:62069 :: 0
15:54:00 - Flags: SYN, ACK

15:54:00 - >7.7.7.7:62069 - 6.6.6.6:25 :: 0
15:54:00 - Flags: ACK

15:54:00 - <6.6.6.6:25 - 7.7.7.7:62069 :: 35
15:54:00 - Flags: PSH, ACK
15:54:00 - 220 *****************************

15:54:00 - >7.7.7.7:62069 - 6.6.6.6:25 :: 24
15:54:00 - Flags: PSH, ACK
15:54:00 - EHLO mail.eee.com

15:54:00 - <6.6.6.6:25 - 7.7.7.7:62069 :: 0
15:54:00 - Flags: ACK

15:54:00 - <6.6.6.6:25 - 7.7.7.7:62069 :: 158
15:54:00 - Flags: PSH, ACK
15:54:00 - 250-ast.bbb.de Hello mail.eee.com [7.7.7.7]

15:54:00 - >7.7.7.7:62069 - 6.6.6.6:25 :: 10
15:54:00 - Flags: PSH, ACK
15:54:00 - STARTTLS

15:54:00 - <6.6.6.6:25 - 7.7.7.7:62069 :: 18
15:54:00 - Flags: PSH, ACK
15:54:00 - 220 TLS go ahead

15:54:00 - >7.7.7.7:62069 - 6.6.6.6:25 :: 184
15:54:00 - Flags: PSH, ACK

15:54:00 - <6.6.6.6:25 - 7.7.7.7:62069 :: 1380
15:54:00 - Flags: ACK

15:54:00 - <6.6.6.6:25 - 7.7.7.7:62069 :: 485
15:54:00 - Flags: PSH, ACK

15:54:00 - >7.7.7.7:62069 - 6.6.6.6:25 :: 0
15:54:00 - Flags: ACK

15:54:00 - >7.7.7.7:62069 - 6.6.6.6:25 :: 6
15:54:00 - Flags: PSH, ACK
15:54:00 - QUIT

15:54:00 - <6.6.6.6:25 - 7.7.7.7:62069 :: 7
15:54:00 - Flags: PSH, ACK

15:54:00 - >7.7.7.7:62069 - 6.6.6.6:25 :: 0
15:54:00 - Flags: ACK

15:54:00 - <6.6.6.6:25 - 7.7.7.7:62069 :: 22
15:54:00 - Flags: PSH, ACK
15:54:00 - 554 Security failure

15:54:00 - >7.7.7.7:62069 - 6.6.6.6:25 :: 0
15:54:00 - Flags: FIN, ACK

15:54:00 - <6.6.6.6:25 - 7.7.7.7:62069 :: 0
15:54:00 - Flags: FIN, ACK

15:54:00 - >7.7.7.7:62069 - 6.6.6.6:25 :: 0
15:54:00 - Flags: ACK

15:54:02 - >7.7.7.7:62070 - 6.6.6.6:25 :: 0
15:54:02 - Flags: SYN, ECH, CWR

15:54:02 - <6.6.6.6:25 - 7.7.7.7:62070 :: 0
15:54:02 - Flags: SYN, ACK

15:54:02 - >7.7.7.7:62070 - 6.6.6.6:25 :: 0
15:54:02 - Flags: ACK

15:54:02 - <6.6.6.6:25 - 7.7.7.7:62070 :: 35
15:54:02 - Flags: PSH, ACK
15:54:02 - 220 *****************************

15:54:02 - >7.7.7.7:62070 - 6.6.6.6:25 :: 24
15:54:02 - Flags: PSH, ACK
15:54:02 - EHLO mail.eee.com

15:54:02 - <6.6.6.6:25 - 7.7.7.7:62070 :: 0
15:54:02 - Flags: ACK

15:54:02 - <6.6.6.6:25 - 7.7.7.7:62070 :: 158
15:54:02 - Flags: PSH, ACK
15:54:02 - 250-ast.bbb.de Hello mail.eee.com [7.7.7.7]

15:54:02 - >7.7.7.7:62070 - 6.6.6.6:25 :: 46
15:54:02 - Flags: PSH, ACK
15:54:02 - MAIL FROM:<h@aaa.de> SIZE=903

15:54:02 - <6.6.6.6:25 - 7.7.7.7:62070 :: 8
15:54:02 - Flags: PSH, ACK
15:54:02 - 250 OK

15:54:02 - >7.7.7.7:62070 - 6.6.6.6:25 :: 36
15:54:02 - Flags: PSH, ACK
15:54:02 - RCPT TO:<h@bbb.de>

15:54:02 - <6.6.6.6:25 - 7.7.7.7:62070 :: 0
15:54:02 - Flags: ACK

15:54:04 - <6.6.6.6:25 - 7.7.7.7:62070 :: 14
15:54:04 - Flags: PSH, ACK
15:54:04 - 250 Accepted

15:54:04 - >7.7.7.7:62070 - 6.6.6.6:25 :: 0
15:54:04 - Flags: ACK

15:54:05 - >7.7.7.7:62070 - 6.6.6.6:25 :: 6
15:54:05 - Flags: PSH, ACK
15:54:05 - DATA

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 0
15:54:05 - Flags: ACK

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 56
15:54:05 - Flags: PSH, ACK
15:54:05 - 354 Enter message, ending with "." on a line by itself

15:54:05 - >7.7.7.7:62070 - 6.6.6.6:25 :: 1356
15:54:05 - Flags: PSH, ACK
15:54:05 - dkim-signature:v=1; c=relaxed/relaxed;... -> Email header + body

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 0
15:54:05 - Flags: ACK

15:54:05 - >7.7.7.7:62070 - 6.6.6.6:25 :: 3
15:54:05 - Flags: PSH, ACK
15:54:05 - .

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 0
15:54:05 - Flags: ACK

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 48
15:54:05 - Flags: PSH, ACK
15:54:05 - 451 Temporary local problem, please try again!

15:54:05 - >7.7.7.7:62070 - 6.6.6.6:25 :: 6
15:54:05 - Flags: PSH, ACK
15:54:05 - QUIT

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 0
15:54:05 - Flags: ACK

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 41
15:54:05 - Flags: PSH, ACK
15:54:05 - 221 ast.bbb.de closing connection

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 0
15:54:05 - Flags: FIN, ACK

15:54:05 - >7.7.7.7:62070 - 6.6.6.6:25 :: 0
15:54:05 - Flags: ACK

15:54:05 - >7.7.7.7:62070 - 6.6.6.6:25 :: 0
15:54:05 - Flags: FIN, ACK

15:54:05 - <6.6.6.6:25 - 7.7.7.7:62070 :: 0
15:54:05 - Flags: ACK


3 minutes later 2nd try, now greylisting on receiver side doesn't block anymore
===============================================================================

15:57:02 - >7.7.7.7:62221 - 6.6.6.6:25 :: 0
15:57:02 - Flags: SYN, ECH, CWR

15:57:02 - <6.6.6.6:25 - 7.7.7.7:62221 :: 0
15:57:02 - Flags: SYN, ACK

15:57:02 - >7.7.7.7:62221 - 6.6.6.6:25 :: 0
15:57:02 - Flags: ACK

15:57:02 - <6.6.6.6:25 - 7.7.7.7:62221 :: 35
15:57:02 - Flags: PSH, ACK
15:57:02 - 220 *****************************

15:57:02 - >7.7.7.7:62221 - 6.6.6.6:25 :: 24
15:57:02 - Flags: PSH, ACK
15:57:02 - EHLO mail.eee.com

15:57:02 - <6.6.6.6:25 - 7.7.7.7:62221 :: 0
15:57:02 - Flags: ACK

15:57:02 - <6.6.6.6:25 - 7.7.7.7:62221 :: 158
15:57:02 - Flags: PSH, ACK
15:57:02 - 250-ast.bbb.de Hello mail.eee.com [7.7.7.7]

15:57:02 - >7.7.7.7:62221 - 6.6.6.6:25 :: 37
15:57:02 - Flags: PSH, ACK
15:57:02 - MAIL FROM:<h@aaa.de>

15:57:02 - <6.6.6.6:25 - 7.7.7.7:62221 :: 8
15:57:02 - Flags: PSH, ACK
15:57:02 - 250 OK

15:57:02 - >7.7.7.7:62221 - 6.6.6.6:25 :: 36
15:57:02 - Flags: PSH, ACK
15:57:02 - RCPT TO:<h@bbb.de>

15:57:02 - <6.6.6.6:25 - 7.7.7.7:62221 :: 0
15:57:02 - Flags: ACK

15:57:03 - <6.6.6.6:25 - 7.7.7.7:62221 :: 14
15:57:03 - Flags: PSH, ACK
15:57:03 - 250 Accepted

15:57:03 - >7.7.7.7:62221 - 6.6.6.6:25 :: 6
15:57:03 - Flags: PSH, ACK
15:57:03 - DATA

15:57:03 - <6.6.6.6:25 - 7.7.7.7:62221 :: 0
15:57:03 - Flags: ACK

15:57:03 - <6.6.6.6:25 - 7.7.7.7:62221 :: 56
15:57:03 - Flags: PSH, ACK
15:57:03 - 354 Enter message, ending with "." on a line by itself

15:57:03 - >7.7.7.7:62221 - 6.6.6.6:25 :: 1356
15:57:03 - Flags: PSH, ACK
15:57:03 - dkim-signature:v=1; c=relaxed/relaxed;... -> Email header + body

15:57:03 - <6.6.6.6:25 - 7.7.7.7:62221 :: 0
15:57:03 - Flags: ACK

15:57:03 - >7.7.7.7:62221 - 6.6.6.6:25 :: 6
15:57:03 - Flags: PSH, ACK
15:57:03 - QUIT

15:57:04 - <6.6.6.6:25 - 7.7.7.7:62221 :: 0
15:57:04 - Flags: ACK

16:02:04 - <6.6.6.6:25 - 7.7.7.7:62221 :: 71
16:02:04 - Flags: PSH, ACK
16:02:04 - 421 ast.bbb.de SMTP incoming data timeout - closing connection.

16:02:04 - <6.6.6.6:25 - 7.7.7.7:62221 :: 0
16:02:04 - Flags: FIN, ACK

16:02:04 - >7.7.7.7:62221 - 6.6.6.6:25 :: 0
16:02:04 - Flags: ACK

16:02:04 - >7.7.7.7:62221 - 6.6.6.6:25 :: 0
16:02:04 - Flags: FIN, ACK

16:02:04 - <6.6.6.6:25 - 7.7.7.7:62221 :: 0
16:02:04 - Flags: ACK

Who is online

Users browsing this forum: Google [Bot] and 1 guest