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/
=====================================================
|
