TIDSmptServer does not receive mail from certain client [Fixed]

[mvanrijnen 123]

Hi, i'm having a problem receiving mails with TIdSmtpServer from a specific  client (it's a server enclosure, there the coolling alarm from) .

Receive from all other kinds of clients works,

 

(I use this in a service i call "ProtcolBridge", i can go 

 - from simple smtp -> o365, gmail, etc

- from ftp -> smtp

- from smtp -> ftp 

 

i use this for "old" devices which have limited smtp and/or ftp support.

)

This is a log of the chronical events of TidSmtpServer:

	22-11-2020 00:56:46.587 [INFO ] - Connection from: 172.16.29.250:1498 [smtpReceiverConnect/MAIN]
22-11-2020 00:56:46.587 [INFO ] - Command Receieved from: 172.16.29.250:1498 | EHLO 172.16.29.250 [smtpReceiverBeforeCommandHandler/MAIN]
22-11-2020 00:56:46.587 [ERROR] - Reset [MAIN]
22-11-2020 00:56:46.587 [INFO ] - SPFcheck OK [smtpReceiverSPFCheck/MAIN]
22-11-2020 00:56:46.587 [INFO ] - Command Receieved from: 172.16.29.250:1498 | MAIL FROM:<address1@company.name> [smtpReceiverBeforeCommandHandler/MAIN]
22-11-2020 00:56:46.587 [INFO ] - SPFcheck OK [smtpReceiverSPFCheck/MAIN]
22-11-2020 00:56:46.587 [INFO ] - MailFrom: address1@company.name [smtpReceiverMailFrom/MAIN]
22-11-2020 00:56:46.602 [INFO ] - Command Receieved from: 172.16.29.250:1498 | RCPT TO:<meldingen@company.name> [smtpReceiverBeforeCommandHandler/MAIN]
	22-11-2020 00:56:46.602 [INFO ] - RCPTTO: meldingen@company.name [smtpReceiverRcptTo/MAIN]
22-11-2020 00:56:46.602 [INFO ] - Command Receieved from: 172.16.29.250:1498 | BDAT 350 [smtpReceiverBeforeCommandHandler/MAIN]
22-11-2020 00:56:46.602 [INFO ] - BeforeMessage [MAIN]
22-11-2020 00:56:51.149 [INFO ] - Command Receieved from: 172.16.29.250:1498 | QUIT [smtpReceiverBeforeCommandHandler/MAIN]
22-11-2020 00:56:51.149 [ERROR] - Reset [MAIN]
22-11-2020 00:56:51.149 [INFO ] - Disconnected from: 172.16.29.250:1498 [smtpReceiverDisconnect/MAIN]
	

 

The message received never fires ??

 

 

here's an example of a client which works:

	22-11-2020 00:32:22.513 [INFO ] - RCPTTO: meldingen@company.name [smtpReceiverRcptTo/MAIN]
22-11-2020 00:32:22.513 [INFO ] - Command Receieved from: 192.168.1.15:50656 | DATA [smtpReceiverBeforeCommandHandler/MAIN]
22-11-2020 00:32:22.513 [INFO ] - BeforeMessage [MAIN]
22-11-2020 00:32:22.856 [INFO ] - Connected with smtp.office365.com:587 [SMTP_TO_SMTP:smtp.ict@company]
22-11-2020 00:32:23.356 [INFO ] - StartReceive. [MAIN]
22-11-2020 00:32:23.356 [ERROR] - 1 [MAIN]
22-11-2020 00:32:23.356 [INFO ] - Incoming message (sender: address1@company.name), subject: Healthy System - no action required (SN:00C0FF289B0F) for meldingen@company.name, on 192.168.1.18:25, from 192.168.1.15:50656 [MAIN]
22-11-2020 00:32:23.356 [INFO ] - EndReceive. [MAIN]
22-11-2020 00:32:23.356 [ERROR] - Reset [MAIN]
22-11-2020 00:32:23.356 [INFO ] - Command Receieved from: 192.168.1.15:50656 | QUIT [smtpReceiverBeforeCommandHandler/MAIN]
22-11-2020 00:32:23.356 [ERROR] - Reset [MAIN]
22-11-2020 00:32:23.356 [INFO ] - Disconnected from: 192.168.1.15:50656 [smtpReceiverDisconnect/MAIN]
22-11-2020 00:32:23.700 [INFO ] - Message for file e:\Data\Hesi\ProtoBridge\SMTP\smtp.ict@company\smtp.ict@company_20201122003222231.eml, send. [SMTP_TO_SMTP:smtp.ict@company]
22-11-2020 00:32:26.216 [INFO ] - Connected with smtp.office365.com:587 [SMTP_TO_SMTP:smtp.ict@company]
22-11-2020 00:32:27.169 [INFO ] - Message for file e:\Data\Hesi\ProtoBridge\SMTP\smtp.ict@company\smtp.ict@company_20201122003223356.eml, send. [SMTP_TO_SMTP:smtp.ict@company]

 

 

Edited November 24, 2020 by mvanrijnen

[timfrost 78]

Your logs only show what is coming in, not what is going out, but my guess is that the Indy server rejected the BDAT command (binary data) as invalid.  I have never seen one before in the wild, and I see that the RFC1830 that introduced this command in August 1995 marks it as 'experimental'.

[Remy Lebeau 1396]

33 minutes ago, timfrost said:

my guess is that the Indy server rejected the BDAT command (binary data) as invalid.

Actually, it should not be, otherwise the OnBeforeMsg event would not be fired, but the log clearly shows that it is.  TIdSMTPServer fully supports BDAT.  After firing the OnBeforeMsg event, it will read the 350 bytes that the client claims to be sending, and then it will send a 250 reply, and wait for the next BDAT command to arrive.

 

The real issue I see is that the failing client is issuing a QUIT command before sending a final "BDAT ... LAST" command to indicate the email data is done being sent.  That is why the OnMsgReceive event is not being fired.

 

I agree, though, that the logging should be expanded to include the server's actual responses.

Edited November 24, 2020 by Remy Lebeau

[mvanrijnen 123]

Things work now.

Some how two version in two different folders where placed on the server by the sysadmin.

So a few weeks ago i update the wrong folder and wrong config.

I'v had added the possibility to enable/disable SMTP AllowPipelining property.

 

For completion the logs with the BDAT sequence.

 

 

INDY Intercept:

172.16.29.250:1545 Stat Connected.
172.16.29.250:1545 Sent 11/25/2020 10:36:58 AM: 220 Welcom to the ProtocolBridge<EOL>
172.16.29.250:1545 Recv 11/25/2020 10:36:58 AM: EHLO 172.16.29.250<EOL>
172.16.29.250:1545 Sent 11/25/2020 10:36:58 AM: 250-Hello 172.16.29.250<EOL>250-AUTH LOGIN<EOL>250-ENHANCEDSTATUSCODES<EOL>250-PIPELINING<EOL>250-SIZE 0<EOL>250-CHUNKING<EOL>250-8BITMIME<EOL>250 BINARYMIME<EOL>
172.16.29.250:1545 Recv 11/25/2020 10:36:58 AM: MAIL FROM:<company@company.eu><EOL>
172.16.29.250:1545 Sent 11/25/2020 10:36:58 AM: 250 2.1.0 company@company.eu Address Okay<EOL>
172.16.29.250:1545 Recv 11/25/2020 10:36:58 AM: RCPT TO:<meldingengroep@company.eu><EOL>
172.16.29.250:1545 Sent 11/25/2020 10:36:58 AM: 250 2.1.5 meldingengroep@company.eu Address Okay<EOL>
172.16.29.250:1545 Recv 11/25/2020 10:36:58 AM: BDAT 355<EOL>Sender: company@company.eu<EOL>From: company@company.eu<EOL>To: meldingengroep@company.eu<EOL>Reply-To: <EOL>Date: Wed Nov 25 10:32:49 2020 +0000<EOL>Message-Id: <1606300369.99074@company.eu><EOL>Subject: Rittal CMC-TC: company (172.16.29.250), myplace<EOL>Message(s) from Rittal CMC-TC<EOL>-----------------------------<EOL>Name:     company (IP: 172.16.29.250)<EOL>Location: myplace<EOL>Contact:  xxx xxxx <EOL><EOL>BDAT 141<EOL>Message of 25.11.2020, 10:32:04<EOL>Blussing[02|01], Service/Blocked: Alarm  <EOL><EOL><EOL>http://172.16.29.250<EOL><EOL>-- Do not reply to this E-Mail!! --<EOL>BDAT 0 LAST<EOL>
172.16.29.250:1545 Sent 11/25/2020 10:37:02 AM: 250 Ok<EOL>
172.16.29.250:1545 Sent 11/25/2020 10:37:02 AM: 250 Ok<EOL>
172.16.29.250:1545 Sent 11/25/2020 10:37:02 AM: 250 Ok<EOL>
172.16.29.250:1545 Recv 11/25/2020 10:37:02 AM: QUIT<EOL>
172.16.29.250:1545 Sent 11/25/2020 10:37:02 AM: 221 Signing Off<EOL>
172.16.29.250:1545 Stat Disconnected.
0.0.0.0:0 Stat Disconnected.

 

ServicesLog:

25-11-2020 10:36:32.184 [INFO ] - Connection from: 172.16.29.250:1544 [smtpReceiverConnect/MAIN]
25-11-2020 10:36:32.184 [INFO ] - Command Recieved from: 172.16.29.250:1544 | EHLO 172.16.29.250 [smtpReceiverBeforeCommandHandler/MAIN]
25-11-2020 10:36:32.184 [ERROR] - Reset [MAIN]
25-11-2020 10:36:32.184 [INFO ] - SPFcheck OK [smtpReceiverSPFCheck/MAIN]
25-11-2020 10:36:32.184 [INFO ] - Command Recieved from: 172.16.29.250:1544 | MAIL FROM:<ict@company.eu> [smtpReceiverBeforeCommandHandler/MAIN]
25-11-2020 10:36:32.184 [INFO ] - SPFcheck OK [smtpReceiverSPFCheck/MAIN]
25-11-2020 10:36:32.184 [INFO ] - MailFrom: ict@company.eu [smtpReceiverMailFrom/MAIN]
25-11-2020 10:36:32.200 [INFO ] - Command Recieved from: 172.16.29.250:1544 | RCPT TO:<ict@company.eu> [smtpReceiverBeforeCommandHandler/MAIN]
25-11-2020 10:36:32.200 [INFO ] - RCPTTO: ict@company.eu [smtpReceiverRcptTo/MAIN]
25-11-2020 10:36:32.200 [INFO ] - Command Recieved from: 172.16.29.250:1544 | BDAT 344 [smtpReceiverBeforeCommandHandler/MAIN]
25-11-2020 10:36:32.200 [INFO ] - BeforeMessage [MAIN]
25-11-2020 10:36:36.731 [INFO ] - Command Recieved from: 172.16.29.250:1544 | BDAT 216 [smtpReceiverBeforeCommandHandler/MAIN]
25-11-2020 10:36:36.731 [INFO ] - Command Recieved from: 172.16.29.250:1544 | BDAT 0 LAST [smtpReceiverBeforeCommandHandler/MAIN]
25-11-2020 10:36:36.731 [INFO ] - StartReceive. [MAIN]
25-11-2020 10:36:36.731 [ERROR] - 1 [MAIN]
25-11-2020 10:36:36.731 [INFO ] - Incoming message (sender: ict@company.eu), subject: Rittal CMC-TC: company (172.16.29.250), myplace for ict@company.eu, on 172.16.29.4:25, from 172.16.29.250:1544 [MAIN]
25-11-2020 10:36:36.731 [INFO ] - EndReceive. [MAIN]
25-11-2020 10:36:36.731 [ERROR] - Reset [MAIN]
25-11-2020 10:36:36.764 [INFO ] - Command Recieved from: 172.16.29.250:1544 | QUIT [smtpReceiverBeforeCommandHandler/MAIN]
25-11-2020 10:36:36.764 [ERROR] - Reset [MAIN]
25-11-2020 10:36:36.764 [INFO ] - Disconnected from: 172.16.29.250:1544 [smtpReceiverDisconnect/MAIN]
25-11-2020 10:36:37.247 [INFO ] - Connected with smtp.office365.com:587 [SMTP_TO_SMTP:smtp.ict@company]
25-11-2020 10:36:37.950 [INFO ] - Message for file e:\Data\company\ProtoBridge\SMTP\smtp.ict@company\smtp.ict@company_20201125103636731.eml, send. [SMTP_TO_SMTP:smtp.ict@company]

Edited November 25, 2020 by mvanrijnen