|
Amazing.
Best
Regards
Andy Schmidt
Phone: +1 201 934-3414 x20
(Business)
Fax: +1 201 934-9206
Andy,
I actually just confirmed that
this is an MS SMTP issue, or at least related to how they handle this, and as
always the logs are giving us bad information.
I set an instance of MS
SMTP up with a 2 KB limit for the message size, and I then did a manual
session with the server, attempting to send 4 KB of the letter "a". I
made sure to issue a DATA command and not a BDAT. Here's what happened
though:
2005-07-10 05:42:17 66.109.52.96
example.com SMTPSVC3 MIDGARD 66.109.52.96 0
HELO - +example.com 250 0 44 13 0 SMTP - - - -
2005-07-10 05:42:40
66.109.52.96 example.com SMTPSVC3 MIDGARD
66.109.52.96 0 MAIL -
+from:<fake@example.com> 250 0 38 25 16
SMTP - - - -
2005-07-10 05:42:50 66.109.52.96
example.com SMTPSVC3 MIDGARD 66.109.52.96 0
RCPT - +to:<[EMAIL PROTECTED]> 250 0 30 27 0
SMTP - - - -
2005-07-10 05:43:54 66.109.52.96
example.com SMTPSVC3 MIDGARD 66.109.52.96 0
BDAT -
aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa 552 0 46 4 59078 SMTP - - -
-
2005-07-10 05:43:54 66.109.52.96
example.com SMTPSVC3 MIDGARD 66.109.52.96 0
QUIT - example.com 240 107640 46 4 59078 SMTP
- - - -
It logged it as BDAT once the limit was
reached, and threw the extra a's into the log as my response. This is
the same as before with those other messages. I also didn't issue a
QUIT, in fact, the command line telnet session was closed on me and I was
kicked back to a command prompt. This might have been a different issue
with telnet buffers, but I surely didn't issue a <CRLF>.<CRLF> nor
did I issue a QUIT.
So it seems that MS SMTP will in fact log a BDAT
whenever a message is oversize and you are using DATA to transfer that
message. It also makes up it's own QUIT command for the logs
automatically. The sending of the 552 error is out of sequence based on
my read of the RFC 821 as well.
I have a feeling that this might be a
case where many have opted to break with standards in order to solve a problem
with this implementation, and it might have become a de facto standard, though
not a universal one. It makes sense that if your server is going to
limit messages to 50 KB on a bandwidth challenged network for instance, then
there is no good reason to wait for a 100,000 KB DATA transfer to finish
before telling it that it is too big. So sending the response out of
sequence might be widely implemented, and likewise sending servers might
widely implement it. Senders that don't implement it would end up in
this queued retransmission thing. This is all speculation of
course.
The other possibility is also that Microsoft could just simply
be wrong in their implementation, and this might not hardly ever come up
because most servers support EHLO and BDAT nowadays.
I wonder how IMail
would handle it if you were to set up the same test as the one that I did
manually. This might at least confirm if IMail hears and takes action
based on the out of sequence 552 error that MS SMTP is returning. Maybe
I will test this another time.
Matt
Andy
Schmidt wrote:
Hi Matt:
I agree that the IIS log is omitting
information that we would like to see (e.g., it doesn't log the BDAT
parameters for inbound message - only for outgoing - and it doesn't log
the mulit-line response to an EHLO) - but I'd be surprised if the log
"replaced" command values, e.g., confused a DATA with a
BDAT.
Sounds to me as if we're dealing with a poor
implementation on the other side. It doesn't use EHLO to see if chunking is
permitted at all (which it is required to do as per RFCs). That's
all we need to know to point the finger. Everything after that are secondary
issues - the results are "undefined".
If EHLO had been used by the sender, then the
max message size could be checked ahead of time - and if the message
size is permitted, then BDATs chunking would always be less or equal to
that and your IIS would have accepted properly.
What may even be happening is that the other side
(lacking the EHLO information, shouldn't be chunking it all), sends a chunk
size that is unacceptable and your IIS SMTP is aborting the session once it
reaches whatever you may have defined as a session
limit.
Can't see where MS SMTP is at fault, based on what
we've seen so far.
Best Regards
Andy Schmidt
Phone: +1 201 934-3414 x20
(Business)
Fax: +1 201 934-9206
Andy and Sandy,
I do see here
that it is definitely improper to send a response during a DATA or BDAT
transfer (which is really, really stupid and speaks to the age of the SMTP
protocol).
Unfortunately MS SMTP doesn't log the DATA or BDAT command
part of the session, just the stuff before and after it. Go
figure. So I can't really even tell if the session is really BDAT or
just DATA, but it is clear that MS SMTP thinks it is BDAT. I am
thinking that since the sending server didn't support EHLO, it probably
doesn't support BDAT either, but I'm just guessing. So maybe it is
most likely that there is a bug in MS SMTP that makes it think it is BDAT,
or at least it treats it as BDAT when a message goes over the
limit.
I do get Sandy's point about the possibility of there being
errant information in the transfer that makes it look like
<CRLF>.<CRLF> in the middle of the transfer, and while that is a
possibility, I have seen this condition happen twice in with two different
servers with the same exact conditions in the logs. So I think it is
more so that MS SMTP is either thinking it is BDAT, or treating it as BDAT
when the size limit is reached, and apparently that is a bug, and while some
servers might accept a 552 error during a DATA transfer and handle it
appropriately despite being the wrong thing to do, it appears that maybe
some don't, and this causes things to be resent.
FYI, here's all of
the log entries for this message instead of the different pieces in
different messages. Take note of the time stamps as there are one or
two minutes between some of them:
2005-07-09 05:09:26 204.0.181.214
mailhost1.neimanmarcus.com SMTPSVC1 VALHALLA 66.109.52.201 0 HELO -
+mailhost1.neimanmarcus.com 250 0 44 31 0 SMTP - -
2005-07-09 05:09:26
204.0.181.214 mailhost1.neimanmarcus.com SMTPSVC1 VALHALLA 66.109.52.201 0
MAIL - +FROM:<[EMAIL PROTECTED]>
250 0 57 44 0 SMTP - -
2005-07-09 05:09:26 204.0.181.214
mailhost1.neimanmarcus.com SMTPSVC1 VALHALLA 66.109.52.201 0 RCPT - +TO:<[EMAIL PROTECTED]>
250 0 39 36 16 SMTP - -
2005-07-09 05:09:48 204.0.181.214
mailhost1.neimanmarcus.com SMTPSVC1 VALHALLA 66.109.52.201 0 BDAT -
67k1S91KS7n1CQ3Oo3JyHaaXl+uWY5759K/LsyzPGZ5NKS91rSztZW/U+9yrIqeBtVxnxf10Pgj4
qaxcavqd3JKZVjSaaJTCfkUls4I55NZfxP1S6e5g0K3dZYbWe9fdbgbQzuGZgQASG4JJ6HjoK4lk
3s0nTettX8vzPrMLiJyjzUlpZP8A4B8m+Lvt91b3WnpG32Q3InmT+9t6YP8ASt/xQbWysLq4e/V7
hldFgcEeXx16d+1KE5YeVGgoJyV9ddL/ANaHpOhzzjVqtWWiXrqfPtvoy3uo21j/AKRJNfXsdn5M
ILO4dtvCjk11mn2cE0z6nbXU1ve2NsbnTZLclZorkH5SGU8dyDyQa+wy6vUVPmxUlGTso+d/8zy8
dGKV6ME359zlvFVxY2TQ2+nzLDb2tvFA6sV8syxvg89CucEZ/wAKr3Mz3V7cz6nEsV5DIpSSTH+k
d+R/fzkt617sMbVrVoVFJXWj8uXTXzPNnhaUZupbfXVa3628rGhHq96Ip4nuXikuJFumYnAR+vA6
KAegGBXJ634nkMN0ySwusqkOyIv7vDdsDP0xXPKtXqTtPRJ62MIc2HlCLS26dPUtnxQNEN1F5+ZJ
4ZYpQuMZZ8kjI4J9q8S1DU4L0bTueVWcys7cYHTHetoOUZ+3pvTpp+HmEm67ftWmlqvM7/X/ABJD
fuJoUkRUAZY2YHA3cAfTt0rx2TUfIY+WHcvgKCcg4PX/AArP2VepJWV3v6f8OTzU8N7l9kttT0uP
xRrlpGq284..
552 0 46 4 20812 SMTP - -
2005-07-09 05:11:09 204.0.181.214
mailhost1.neimanmarcus.com SMTPSVC1 VALHALLA 66.109.52.201 0 QUIT -
mailhost1.neimanmarcus.com 240 102953 105 4 102719 SMTP -
-
Attached is also a graph of my Friday traffic at
my router showing the effect of just one such message stuck in this
resending loop. Thankfully I can now burst far beyond this, but when
this happened while I only had a T1, it caused major trouble until I found
the problem. In this case all I had to do is tell my gateway to give a
550 error for the sender and after the next try 35 minutes later, it killed
the message permanently, but naturally it could happen again. I'm
probably going to double the size of what I accept which should help
minimize the issue even further.
Thanks for helping me understand
this better.
Matt
--
=====================================================
MailPure custom filters for Declude JunkMail Pro.
http://www.mailpure.com/software/
=====================================================
--
=====================================================
MailPure custom filters for Declude JunkMail Pro.
http://www.mailpure.com/software/
=====================================================
|
