Spam Filter ISP Forums : Hit a brick wall - unexpected disconnect

Hit a brick wall - unexpected disconnect : That was it. Outstanding! For...

Wed, 29 Oct 2008 10:16:32 +0000

Author: dotme
Subject: 6571
Posted: 29 October 2008 at 10:16am

That was it. Outstanding!

For others who may stumble upon this later, the original issue was that HTML emails containing quarantine reports for users were getting stuck in the SMTP Queue on IIS when sent using CDOSYS. The same emails sent using the deprecated CDONTS were delivered without problems.

The HTML messages were created in VB6 with a chr(13) added to the end of each line in the HTML code.

The message body needed a chr(10) as well. Replacing chr(13) in the generating code with vbcrlf accomplishes the same thing.

After replacing all instances of chr(13) with vbcrlf in the VB code that generates the email reports, the messages now deliver consistently.

I suspect that the deprecated CDONTS forces linewraps at 72 characters regardless of how the message body is formed, which probably explains why those messages always made it.

Issue resolved, with many thanks to Roberto for the help!!

Edited by dotme - 29 October 2008 at 10:17am

Hit a brick wall - unexpected disconnect : Mistery solved (as far as your...

Tue, 28 Oct 2008 23:45:21 +0000

Author: LogSat
Subject: 6571
Posted: 28 October 2008 at 11:45pm

Mistery solved (as far as your sample is concerned).

Please take a look at the queued email you will find in the \InetPub\Mailroot\queue directory on the IIS server. If you edit it, you will see that the body contains a single line of 360,000 characters. Furthermore, there is not . sequence in the email that indicates the end-of-transmission.

This is because the code you used to generate the test does not include any line breaks. Per RFC 2821 (http://www.ietf.org/rfc/rfc2821.txt) each line of text in an email should be no more than 1,000 characters. SpamFilter will accept up to 16,384 characters in lenght, but in this case we are well over the limits!

Hit a brick wall - unexpected disconnect : Hey Roberto I'll ask about...

Tue, 28 Oct 2008 17:12:21 +0000

Author: dotme
Subject: 6571
Posted: 28 October 2008 at 5:12pm

Hey Roberto

I'll ask about sniffer availability - have to go up the chain of command to find that out.

But I did as you asked. IIS will pool connections (Default is max of 20 messages delivered per connection). Result was the same. CDOSYS made it to the queue first. So it was the first message to be delivered when the connection was established. It resulted in a "disconnect", so the CDONTS message was not able to be delivered in the same session. We set retries to 60 seconds. On the next connection attempt, CDONTS message was natually queued first since the IIS server never even got to have a conversation with Logsat about it. It was delivered successfully. The CDOSYS message followed, and was again disconnected.

Logfiles:

10/28/08 16:00:21:506 -- (4668) Connection from: x.x.x.x - Originating country : United States
10/28/08 16:00:21:847 -- (4668) Received MAIL FROM: <testing-CDOSYS@s---.com>
10/28/08 16:00:21:897 -- (4668) Received RCPT TO: j---@j---.com
10/28/08 16:00:21:897 -- (4668) Bypassed all rules for: j---@j---.com from testing-CDOSYS@s---.com ( Whitelisted Email From Domain)
10/28/08 16:00:22:187 -- (4668) Disconnect
10/28/08 16:01:22:414 -- (292) Connection from: x.x.x.x - Originating country : United States
10/28/08 16:01:22:664 -- (292) Received MAIL FROM: <testing-CDONTS@s---.com>
10/28/08 16:01:22:704 -- (292) Received RCPT TO: j---@j---.com
10/28/08 16:01:22:714 -- (292) Bypassed all rules for: j---@j---.com from testing-CDONTS@spamblockerservices.com ( Whitelisted Email From Domain)
10/28/08 16:01:25:668 -- (292) Start virus scan
10/28/08 16:01:25:718 -- (292) Starting queueing procedures
10/28/08 16:01:25:728 -- (292) EMail from testing-CDONTS@spamblockerservices.com to j---@j---.com was queued. Size: 261 KB, 267264 bytes
10/28/08 16:01:25:738 -- (5768) Sending email from testing-CDONTS@s---.com to j---@j---.com --
10/28/08 16:01:25:819 -- (292) Received MAIL FROM: <testing-CDOSYS@s---.com>
10/28/08 16:01:25:869 -- (292) Received RCPT TO: j---@j---.com
10/28/08 16:01:25:869 -- (292) Bypassed all rules for: j---@j---.com from testing-CDOSYS@s---.com ( Whitelisted Email From Domain)
10/28/08 16:01:26:139 -- (292) Disconnect

I have tried from other IIS servers with same script - same result. Don't have much else to go on at this point. It could be as simple as unexpected or bad headers from the CDOSYS object, but I'm betting MS won't fix that if that's the case :-)

For now, we'll revert to CDONTS for what we're needing to do, but I will keep watch on this thread and will be happy to try any other suggestions. If I can get pcap data, I'll post back.

Cheers!

Hit a brick wall - unexpected disconnect : We're going to try to reproduce...

Tue, 28 Oct 2008 16:35:49 +0000

Author: LogSat
Subject: 6571
Posted: 28 October 2008 at 4:35pm

We're going to try to reproduce this shortly. In the meantime, what's a bit unusual is that while your code sends two separate emails, one with each object, your IIS server is combining them into one single SMTP session when delivering them. In fact, in SpamFilter's logfile, there is only one "Connection from" and both emails are receied by the same thread (connection).
Seeing this, while we work on our end, could you please try to "switch" around the two objects, sending the first email with CDO.Message and the second one with CDONTS.NewMail? If when you do this, and you do not receive the first email, then yes, that would point to an issue with CDO.message. If instead you again receive the first email and not the second... then the problem may be related to IIS as a whole and not the two CDO objects.

Also, if you're able to use WireShark, Ethereal, or Microsoft's Network Monitor to capture the complete SMTp traffic and provide us with the pcap data, that will hopefully help even more.
Whi

Hit a brick wall - unexpected disconnect : Hi Robert - Thanks for the response......

Tue, 28 Oct 2008 09:45:19 +0000

Author: dotme
Subject: 6571
Posted: 28 October 2008 at 9:45am

Hi Robert - Thanks for the response...

The plot thickens. This is a lot to absorb, so I'll begin with my findings...

Regardless of the sending server, I now have consistent FAIL results when generating a message of 150kbps or more using the native Windows 2003 CDOSYS. For grins, I installed CDONTS.dll on the Windows 2003 server (CDONTS is deprecated, but used on NT 4). CDONTS delivers every time.

So this almost appears to be an incompatibility between Logsat and larger emails generated by Microsoft's CDOSYS via the IIS built in SMTP server.

As requested, I'm posting the full information. Hope this is helpful...

Sending server:
Windows 2003 Server - Service Pack 2. Installed and registered CDONTS.dll from NT (Old way of sending email) as a test.

Receiving server:
Windows 2003 Server - Service Pack 2 - Logsat 4.0.1.785 (I know, but that's what my boss is running at the moment)

Consistently FAILS on use of native CDO SYS on Windows 2003 with a good sized message - although after several retries, the message may eventually arrive.

(If you do not have access to CDONTS, just REM out the first sending routine in the script below...)

ASP CODE (Change email addresses to your settings):
<%
for i = 1 to 20000
message = message & "Hello world! "
Next

' Using CDONTS
Set objCDO = CreateObject("CDONTS.NewMail")
objCDO.Subject = "Test Subject"
objCDO.From = "Sending Test From CDONTS <testing-CDONTS@s----.com>"
objCDO.To = "j---@j---.com"
objCDO.body = message
objCDO.Send
Set objCDO = Nothing

' Using CDOSYS
Set objCDO = CreateObject("CDO.Message")
objCDO.Subject = "Test Subject"
objCDO.From = "Sending Test From CDOSYS <testing-CDOSYS@s----.com>"
objCDO.To = "j---@j---.com"
objCDO.TextBody = message
objCDO.Send
Set objCDO = Nothing
response.write "Messages Sent"
%>

LOGFILES:::

Logsat

10/28/08 07:55:47:029 -- (3944) Connection from: xx.xx.xx.xx - Originating country : United States
10/28/08 07:55:47:259 -- (3944) Received MAIL FROM: <testing-CDONTS@s----.com>
10/28/08 07:55:47:309 -- (3944) Received RCPT TO: j---@j---.com
10/28/08 07:55:47:309 -- (3944) Bypassed all rules for: j---@j---.com from testing-CDONTS@s----.com ( Whitelisted Email From Domain)
10/28/08 07:55:48:882 -- (3944) Start virus scan
10/28/08 07:55:48:912 -- (3944) Starting queueing procedures
10/28/08 07:55:48:922 -- (3944) EMail from testing-CDONTS@s----.com to j---@j---.com was queued. Size: 130 KB, 133120 bytes
10/28/08 07:55:49:012 -- (3944) Received MAIL FROM: <testing-CDOSYS@s----.com>
10/28/08 07:55:49:062 -- (3944) Received RCPT TO: j---@j---.com
10/28/08 07:55:49:062 -- (3944) Bypassed all rules for: j---@j---.com from testing-CDOSYS@s----.com ( Whitelisted Email From Domain)
10/28/08 07:55:49:332 -- (3944) Disconnect

IIS

2008-10-28 12:49:12 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 220+mx30.s----.com+Welcome+to+SServices+2.0 0 0 67 0 47 SMTP - - - -
2008-10-28 12:49:12 216.243.198.11 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 EHLO - s----.com 0 0 4 0 47 SMTP - - - -
2008-10-28 12:49:12 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250-8BITMIME 0 0 12 0 78 SMTP - - - -
2008-10-28 12:49:12 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250+HELP 0 0 8 0 234 SMTP - - - -
2008-10-28 12:49:12 216.243.198.11 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 MAIL - FROM:<testing-CDONTS@s----.com> 0 0 4 0 234 SMTP - - - -
2008-10-28 12:49:12 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250++Address+Okay 0 0 17 0 281 SMTP - - - -
2008-10-28 12:49:12 216.243.198.11 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 RCPT - TO:<j---@j---.com> 0 0 4 0 281 SMTP - - - -
2008-10-28 12:49:12 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250+j---@j---.com+Address+Okay 0 0 28 0 328 SMTP - - - -
2008-10-28 12:49:12 216.243.198.11 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 DATA - - 0 0 4 0 328 SMTP - - - -
2008-10-28 12:49:12 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 354+Start+mail+input;+end+with+. 0 0 44 0 359 SMTP - - - -
2008-10-28 12:49:14 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250+Ok 0 0 6 0 1938 SMTP - - - -
2008-10-28 12:49:14 216.243.198.11 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 RSET - - 0 0 4 0 1953 SMTP - - - -
2008-10-28 12:49:14 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250+Ok 0 0 6 0 1984 SMTP - - - -
2008-10-28 12:49:14 216.243.198.11 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 MAIL - FROM:<testing-CDOSYS@s----.com> 0 0 4 0 1984 SMTP - - - -
2008-10-28 12:49:14 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250++Address+Okay 0 0 17 0 2031 SMTP - - - -
2008-10-28 12:49:14 216.243.198.11 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 RCPT - TO:<j---@j---.com> 0 0 4 0 2031 SMTP - - - -
2008-10-28 12:49:14 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250+j---@j---.com+Address+Okay 0 0 28 0 2078 SMTP - - - -
2008-10-28 12:49:14 216.243.198.11 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 DATA - - 0 0 4 0 2078 SMTP - - - -
2008-10-28 12:49:14 216.243.198.11 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 354+Start+mail+input;+end+with+. 0 0 44 0 2125 SMTP - - - -
... Nothing further until next connection attempt 15 minutes later.

Contents of Debug View (subsequent attempt, but it shows what happens. Pretty much nothing, but maybe the empty lines hold a clue?)

>>EHLO s---.com
<<250-8BITMIME
<<250 HELP
>>MAIL FROM:<testing-CDOSYS@s----.com>
<<250 Address Okay
>>RCPT TO:<j---@j---.com>
<<250 j---@j---.com Address Okay
>>DATA
<<354 Start mail input; end with .
>>Received: from mail pickup service by spamblockerservices.com with Microsoft SMTPSVC;
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>

Edited by dotme - 28 October 2008 at 9:47am

Hit a brick wall - unexpected disconnect : dotme, The logs do not appear...

Mon, 27 Oct 2008 22:11:40 +0000

Author: LogSat
Subject: 6571
Posted: 27 October 2008 at 10:11pm

dotme,

The logs do not appear to be relative to the same SMTP conversation, as SpamFilter's timestamp is 11:38:47, while your IIS server's is 17:14:50. The hours difference could be caused by IIS logging in GMT time, but there is still a difference of about half an hour in the minutes difference.

Can you please either post or email us both logs showing the correct timestamps?

Also, If you are able to either reproduce this at will, we could try to enable the “Debug” monitor in SpamFilter to capture the SMTP conversations with the remote server and see if we can have a better understanding on what is going on with a specific IP.

To do so, please go to the "Settings - Debug View" tab in SpamFilter, enter the IP to monitor, for example in this case 192.168.65.116. in the "IP to monitor" box, and check the "Enable Debug Monitor" box. When you receive another email from 192.168.65.116, "stuff" regarding the connection should appear in that tab showing what kind of SMTP traffic is being exchanged. If this happens, could you please forward it to us as well?
Of course, if you’re familiar with Ethereal (Wireshark), the Microsoft Network Monitor utility, or any other packet capture utility, and would like to provide us with a more detailed PCAP file, we’ll gladly accept that as it will be more accurate than SpamFilter’s built-in capture.

Hit a brick wall - unexpected disconnect : I will add that grelisting is...

Mon, 27 Oct 2008 13:56:48 +0000

Author: dotme
Subject: 6571
Posted: 27 October 2008 at 1:56pm

I will add that grelisting is DISABLED and the IP is not in any blacklist.

Hit a brick wall - unexpected disconnect : I've tried everything I can...

Mon, 27 Oct 2008 13:53:30 +0000

Author: dotme
Subject: 6571
Posted: 27 October 2008 at 1:53pm

I've tried everything I can think of. I have no ideas why this is happening. Each day, an IIS server sends quarantined email notices to customers. Those messages are not being delivered. Here's the Logsat logfile on one attempt...

10/27/08 11:38:47:302 -- (3460) Connection from: 192.168.65.116 - Originating country : N/A
10/27/08 11:38:47:652 -- (3460) Received MAIL FROM: <blocker@s---.com>
10/27/08 11:38:47:712 -- (3460) Received RCPT TO: b---@a---.net
10/27/08 11:38:47:712 -- (3460) Bypassed all rules for: b---@a---.net from blocker@s---.com ( Whitelisted Email From Domain)
10/27/08 11:38:47:883 -- (3460) Disconnect

(I hyphenated users and domains in the post to protect the innocent)

On the IIS server, here's the conversation...

2008-10-27 17:14:50 192.168.65.112 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 220+mx3.s---.com+Welcome+to+SpamFilterISP+SMTP+Server+v4.0.1.785 0 0 79 0 0 SMTP - - - -
2008-10-27 17:14:50 192.168.65.112 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 EHLO - s---.com 0 0 4 0 0 SMTP - - - -
2008-10-27 17:14:50 192.168.65.112 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250-8BITMIME 0 0 12 0 15 SMTP - - - -
2008-10-27 17:14:51 192.168.65.112 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250+HELP 0 0 8 0 250 SMTP - - - -
2008-10-27 17:14:51 192.168.65.112 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 MAIL - FROM:<blocker@s---.com> 0 0 4 0 250 SMTP - - - -
2008-10-27 17:14:51 192.168.65.112 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250++Address+Okay 0 0 17 0 250 SMTP - - - -
2008-10-27 17:14:51 192.168.65.112 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 RCPT - TO:<b---@a---.net> 0 0 4 0 250 SMTP - - - -
2008-10-27 17:14:51 192.168.65.112 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 250+b---@a---.net+Address+Okay 0 0 41 0 265 SMTP - - - -
2008-10-27 17:14:51 192.168.65.112 OutboundConnectionCommand SMTPSVC1 SPAMDB - 25 DATA - - 0 0 4 0 265 SMTP - - - -
2008-10-27 17:14:51 192.168.65.112 OutboundConnectionResponse SMTPSVC1 SPAMDB - 25 - - 354+Start+mail+input;+end+with+. 0 0 44 0 265 SMTP - - - -

Is there an incompatibility between Microsoft's SMTP Service in IIS and Logsat?

Why is Logsat issuing a "disconnect" on the connection attempt? Tearing my hear out... lol

Thanks in advance for any assistance.

Edited by dotme - 27 October 2008 at 1:55pm