Help troubleshooting a weird exchange SMTP error

Forums › IT Pro and developers › Help troubleshooting a weird exchange SMTP error

pomtom44

128 posts

Master Geek

#290225 28-Oct-2021 16:01

Hi all

Im trying to troubleshoot a odd SMTP bug at work, and so far no one has been able to help me figure it out, so moving across the few forums I use looking for that magic bit of advise

The short version is:

Two exchange servers, different sites, same WAN, setup in a DAG group

As far as I can see both servers are setup exactly the same, same version numbers, same configs, etc
When sending a test email to server 1, I can see both on my test application (SMTP Diag Tool), and on the exchange logs, the SMTP process working, and then I get the test email in my inbox
When sending to server 2, I can see the logs working, but then it fails
The server shows "Receving message with InternetMessageID" and then nothing else on those logs
On the test software, I can see Connection closed error,
Same test with telnet and get a Connection to host lost error on server 2

Iv tried searching every log file I can find, and all over the internet, but so far nothing seems to tell me why server 2 fails and server 1 works fine

Im sure im missing something somewhere, but no idea what?

Any ideas or help please?

1 | 2

2838 posts

Uber Geek

#2802959 28-Oct-2021 16:13

Things to check...

Are you sending e-mail directly to the servers in both cases or are the messages being routed via other SMTP servers?
Is there any sort of filtering in place which may be intercepting the e-mails and causing the disconnect? (e.g. MailMarshal or similar)
Although you mention Telnet, are the connections using STARTTLS?

On #3, I've seen some inconsistency when connecting to Microsoft servers (may have common code with Exchange?), where TLS negotiation failed connecting to some servers. I believe this was related to SNI (used for Web hosting), but the user who reported the problem never confirmed this was fixed and I've not had anyone contact me since with similar issues. Failure to negotiate common encryption or certificate verification may also be issues with TLS connections and may show different behaviour between hosts.

GoodSync

GoodSync. Easily back up and sync your files with GoodSync. Simple and secure file backup and synchronisation software will ensure that your files are never lost (affiliate link).

pomtom44

128 posts

Master Geek

#2802960 28-Oct-2021 16:19

SirHumphreyAppleby:

Things to check...

Are you sending e-mail directly to the servers in both cases or are the messages being routed via other SMTP servers?
Is there any sort of filtering in place which may be intercepting the e-mails and causing the disconnect? (e.g. MailMarshal or similar)
Although you mention Telnet, are the connections using STARTTLS?

One #3, I've seen some inconsistency when connecting to Microsoft servers (may have common code with Exchange?), where TLS negotiation failed connecting to some servers. I believe this was related to SNI (used for Web hosting), but the user who reported the problem never confirmed this was fixed and I've not had anyone contact me since with similar issues. Failure to negotiate common encryption or certificate verification may also be issues with TLS connections and may show different behaviour between hosts.

1) Directly to both servers
Also tested from devices on the same subnet as these servers just to rule out any WAN routing or issues like that

2) Nope, connecting directly to the port 25 on each of the servers, and no third party tools installed which are intercepting them (that im aware of at least)

3) im testing using plain smtp with basic auth, no certs involved

SirHumphreyAppleby

2838 posts

Uber Geek

#2802980 28-Oct-2021 16:41

It's been about eight years since I last touched Exchange, but the logging stopping at "Receving message with InternetMessageID" suggests it's getting as far as the DATA command and possibly terminating the connection.

The usual cause of issues there are MTU issues etc., but you've ruled those out using the local network.

Does your test tool log the SMTP transaction? It'd be interesting to see if it's stopping or if it sees the message as delivered and if that delivery is ever acknowledged by Exchange, either with a 250 response or error code.

I assume you're delivering to local recipients in both cases, but if not, one thing to check is if Exchange is configured to allow relaying on port 25. It's usually only permitted on port 587 these days. Even so, there should be logs to tell you that.

pomtom44

128 posts

Master Geek

#2802994 28-Oct-2021 17:02

SirHumphreyAppleby:

It's been about eight years since I last touched Exchange, but the logging stopping at "Receving message with InternetMessageID" suggests it's getting as far as the DATA command and possibly terminating the connection.

The usual cause of issues there are MTU issues etc., but you've ruled those out using the local network.

Does your test tool log the SMTP transaction? It'd be interesting to see if it's stopping or if it sees the message as delivered and if that delivery is ever acknowledged by Exchange, either with a 250 response or error code.

I assume you're delivering to local recipients in both cases, but if not, one thing to check is if Exchange is configured to allow relaying on port 25. It's usually only permitted on port 587 these days. Even so, there should be logs to tell you that.

100% not network related (at least LAN level) I can send a message just fine from LAN 2 to the server on LAN 1, but not to server 2 on lan 2

yes it has the SMTP logs as well

Errors at the same place
sender and recpt OK
354 Start Mail Input,
Disconnected, connection closed
Failed to send message

testing using a from and to on our domain, so not leaving the exchange server
we have 25 open for a few applications which we use internally, as they dont support cert based authentications
Once thats working im going to move onto the other applications like exchange and other one which use certs, but for now just trying to troubleshoot 25

(and if 25 wasnt open then i wouldnt even be able to telnet in and get the sender and rept OK back from the server)

Dynamic

3830 posts

Uber Geek

ID Verified

Trusted

Lifetime subscriber

#2802997 28-Oct-2021 17:07

What do the time stamps tell you? Does the disconnection happen immediately or is there a timeout?

“Don't believe anything you read on the net. Except this. Well, including this, I suppose.” Douglas Adams

Referral links to services I use, really like, and may be rewarded if you sign up:
PocketSmith for budgeting and personal finance management. A great Kiwi company.

pomtom44

128 posts

Master Geek

#2803000 28-Oct-2021 17:12

Dynamic:

What do the time stamps tell you? Does the disconnection happen immediately or is there a timeout?

Theres no timestamp on the testing tool logs, and the server logs dont show the disconnect so not sure there
but from testing the tool pretty much immediately errors when I hit send, so if there is a timeout is in the milliseconds range

pomtom44

128 posts

Master Geek

#2803004 28-Oct-2021 17:16

Dynamic:

What do the time stamps tell you? Does the disconnection happen immediately or is there a timeout?

When I test using telnet it happens instantly as well the moment I sent the "." after entering the body of the email

SirHumphreyAppleby

2838 posts

Uber Geek

#2803011 28-Oct-2021 17:33

The fact this is occurring after .\r\n is handy to know. I was going to suggest Wireshark to see how far the e-mail actually got, and that may still be helpful.

The fact it is happening so late in the transaction but you aren't receiving any sort of error, suggests one of three possible things to me. There is an internal error such as failure to write to disk which isn't being reported, Exchange is returning an error but your client isn't reading/displaying it, or something else is terminating the connection. After the DATA command, the only way to stop mail delivery is to drop the connection. Some third party filters work this way. They forward data to the server, but once they have the full text they will scan it and do the only thing they can do... drop the connection.

pomtom44

128 posts

Master Geek

#2803012 28-Oct-2021 17:47

SirHumphreyAppleby:

The fact this is occurring after .\r\n is handy to know. I was going to suggest Wireshark to see how far the e-mail actually got, and that may still be helpful.

The fact it is happening so late in the transaction but you aren't receiving any sort of error, suggests one of three possible things to me. There is an internal error such as failure to write to disk which isn't being reported, Exchange is returning an error but your client isn't reading/displaying it, or something else is terminating the connection. After the DATA command, the only way to stop mail delivery is to drop the connection. Some third party filters work this way. They forward data to the server, but once they have the full text they will scan it and do the only thing they can do... drop the connection.

I can try a wireshark and see if there is any more debug info in there which either exchange or the smtp client isnt showing, but I dont feel like there would be

Iv tried to look though the exchange logs and event viewer for errors but nothings coming up
Either its not logging the error like you say, or it is and I dont know where to find it

SirHumphreyAppleby

2838 posts

Uber Geek

#2803014 28-Oct-2021 17:51

pomtom44:

I can try a wireshark and see if there is any more debug info in there which either exchange or the smtp client isnt showing, but I dont feel like there would be

I think you're right. Telnet should show any response from the server, but I think it's still helpful to be certain.

pomtom44

128 posts

Master Geek

#2803017 28-Oct-2021 17:59

SirHumphreyAppleby:

pomtom44:

I can try a wireshark and see if there is any more debug info in there which either exchange or the smtp client isnt showing, but I dont feel like there would be

I think you're right. Telnet should show any response from the server, but I think it's still helpful to be certain.

I have a capture, sending to both servers
there is alot of other crap in the capture from other network traffic and im not expert enough to know how to filter it
What do you want me to look for / do with it?

SirHumphreyAppleby

2838 posts

Uber Geek

#2803020 28-Oct-2021 18:07

pomtom44:

I have a capture, sending to both servers
there is alot of other crap in the capture from other network traffic and im not expert enough to know how to filter it
What do you want me to look for / do with it?

I don't have Wireshark installed here to tell you the exact steps, but you can filter by by IP/port to find the connection, then look at the text data in the packets. If Exchange is returning an error, you should see it immediately after the .\r\n is sent. IIRC, the SMTP RFC indicates servers should send a reason for disconnection if it is forcibly closed for some reason. The client won't be expecting this, so won't always display it. In this case, after .\r\n, it should be expecting something.

pomtom44

128 posts

Master Geek

#2803025 28-Oct-2021 18:17

SirHumphreyAppleby:

pomtom44:

I have a capture, sending to both servers
there is alot of other crap in the capture from other network traffic and im not expert enough to know how to filter it
What do you want me to look for / do with it?

I don't have Wireshark installed here to tell you the exact steps, but you can filter by by IP/port to find the connection, then look at the text data in the packets. If Exchange is returning an error, you should see it immediately after the .\r\n is sent. IIRC, the SMTP RFC indicates servers should send a reason for disconnection if it is forcibly closed for some reason. The client won't be expecting this, so won't always display it. In this case, after .\r\n, it should be expecting something.

Comparing the two there does appear to be a TCP reset sent from the server for some reason
I have attached screenshots of the logs

Good server

Bad Server

SirHumphreyAppleby

2838 posts

Uber Geek

#2803040 28-Oct-2021 18:43

pomtom44:

Comparing the two there does appear to be a TCP reset sent from the server for some reason
I have attached screenshots of the logs

Some reason is still a big unknown, unfortunately. About the only thing we can be certain of is that the data exchange has an abnormal termination.

I would check the event logs to make sure Exchange isn't dying for some reason, then go on the hunt for a transparent SMTP proxy since I know they work by killing connections in this way. Otherwise, I'm out of ideas. Hopefully someone else with up-to-date Exchange experience will be able to help further.

pomtom44

128 posts

Master Geek

#2803046 28-Oct-2021 18:57

SirHumphreyAppleby:

Some reason is still a big unknown, unfortunately. About the only thing we can be certain of is that the data exchange has an abnormal termination.

I would check the event logs to make sure Exchange isn't dying for some reason, then go on the hunt for a transparent SMTP proxy since I know they work by killing connections in this way. Otherwise, I'm out of ideas. Hopefully someone else with up-to-date Exchange experience will be able to help further.

I have spent a while trying to dig though the event logs, as theres so many of them, but from what I can see there hasn't been any errors relating to this problem
The only place the proxy would be is on the server as im pointing to its IP directly and as far as I can see there isnt any unknown services like that running on the server

either way thanks for the help
Helped to narrow it down a bit more and confirm it is exchange throwing a fit, so I can take that to other forums (and MS if I can get them to help) and see if we can take it further

1 | 2