325649 - "SMTP Send" fails due to SMTP connection drop when relatively large mail size, because SMTP send timeout occurs in 600 msec even when mailnews.tcptimeout=600(seconds) or 60000(60*1000 seconds) is set

Status: RESOLVED INCOMPLETE

(MailNews Core :: Networking: SMTP, defect)

Description

[WADA:World Anti-bad-Duping Agency]

When Thunderbird 1.5, SMTP send timeout occurs in 600 msec,
even though mailnews.tcptimeout is set to 600(sec),
and even though nsSocketTransport:5 says "poll timeout: 600".

(1) SMTP:5 log when normal send(small mail)
> 0[2c48c8]: SMTP Send: .
> 0[2c48c8]: SMTP entering state: 0
> 0[2c48c8]: SMTP Response: 250 ok 1136166991 qp 19840
> 0[2c48c8]: SMTP entering state: 10
> 0[2c48c8]: SMTP Send: QUIT

(2) SMTP:5 log when connection lost on send(mail with very large attachment)
> 0[2c48c8]: SMTP Send: .
> 0[2c48c8]: SMTP connection dropped after 195 total bytes read

(3) SMTP:5 log when connection lost with timestamp(mailnews.tcptimeout=600)
    (Obtained by DebugView, which is mentioned by Bug 86396 comment #6)
> 00000534 1:31:13.075 [2524] 0[2c48e8]: SMTP Send: .
> 00000633 1:31:13.676 [2524] 0[2c48e8]: SMTP connection dropped
>                                             after 195 total bytes read

Comment 1

[WADA:World Anti-bad-Duping Agency]

NSPR log(NSPR_LOG_MODULES=SMTP:5,nsHttp:5,nsSocketTransport:5,nsHostResolver:5)
 http://bugzilla.mozilla.gr.jp/attachment.cgi?id=3099&action=view

See Bug 86396 comment #6 and http://www.sysinternals.com/Utilities/DebugView.html for NSPR log with DebugView.

Comment 2

[WADA:World Anti-bad-Duping Agency]

NSPR log when mailnews.tcptimeout is changed to 60000(=60*1000).
 http://bugzilla.mozilla.gr.jp/attachment.cgi?id=3100&action=view
Connection is still lost in very short period, almost 800msec in this log, although log says "poll timeout: 60000".

Comment 3

[WADA:World Anti-bad-Duping Agency]

Funny "poll timeout: xxx" log is seen ( xxx = mailnews.tcptimeout + 60 ).

When mailnews.tcptimeout=600(log in comment #1) 
> 00000155  1:31:12.734 [2524] 2828[11a96f0]: poll timeout: 660
When mailnews.tcptimeout=60000(log in comment #2) 
> 00000073 10:04:59.272	[2112] 2168[11a96f0]: poll timeout: 60060

Comment 4

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #3)
> Funny "poll timeout: xxx" log is seen ( xxx = mailnews.tcptimeout + 60 ).

Added "60" was for TIMEOUT_CONNECT.
nsMsgProtocol::OpenNetworkSocketWithInfo adds 60 to mailnews.tcptimeout when TIMEOUT_CONNECT, while mailnews.tcptimeout is used for TIMEOUT_READ_WRITE.  
http://lxr.mozilla.org/seamonkey/source/mailnews/base/util/nsMsgProtocol.cpp#120
>158 prefBranch->GetIntPref("mailnews.tcptimeout",&gSocketTimeout);
>(snip)
>162 strans->SetTimeout(nsISocketTransport::TIMEOUT_CONNECT,gSocketTimeout+60);  
>163 strans->SetTimeout(nsISocketTransport::TIMEOUT_READ_WRITE,gSocketTimeout); 

Comment 5

[WADA:World Anti-bad-Duping Agency]

CC-ingto David.
David, mailnews.tcptimeout value is put in nsISocketTransport::TIMEOUT_READ_WRITE, but the value doesn't seem to be used when requesting socket I/O.
Which module should I look into?  

Comment 6

[Wayne Mery (:wsmwk)]

OS=ALL?

Comment 7

[WADA:World Anti-bad-Duping Agency]

I forgot to write down error message when connection lost.
Next error message was displayed. (No timeout related error was mentioned.)
> The message could not be sent because connecting to SMTP server failed.

Comment 8

[Mike Mazanek]

I may have  Bug 361905 rather than Bug 325649:

I cannot EVER send an EMail with more than 2MB attached using TB V2, however, I can using OE V6 or my ISP Webmail.  I think I was able to send the larger attachment size before I had V2, but not certain as it's been quite a while since trying.  I can always send EMails with less than a 1MB attachment, and sometimes one with a 1-2MB attachment.  However, even if a 1-2MB attachment EMail goes I usually get an error msg.

The only error msg I ever get is:
"Sending of msg failed-

The msg could not be sent bec connection to the SMTP server mail.bellsouth.net
failed.  The server may be unavailable or is refusing SMTP connections.  Please
verify that your SMTP server setting is correct and try again, or contact your
network admin"

Comment 9

[WADA:World Anti-bad-Duping Agency]

Full error message when send failure(by connection loss due to internal timeout).
> Sending of msg failed-
> The msg could not be sent bec connection to the SMTP server xxx.yyy.zzz failed.  > The server may be unavailable or is refusing SMTP connections.
> Please verify that your SMTP server setting is correct and try again,
> or contact your network admin
(As reporter of this problem is a Japanese people, I can't know English message.)
(Above message is copy from Bug 361905 Comment #17. Thanks to Mike Mazanek.)

Comment 10

[WADA:World Anti-bad-Duping Agency]

Oh, comment #8 is already wrote by Mike... Sorry for meaningless comment #9

Mike, this bug's problem is initially reported to a bug of Bugzilla Japan, and initial phenomenon of the bug in Japan is as follows.
 (1) When small attachment, no problem occur.
 (2) When attachment's size is several mega bytes or more,
     "Sending of msg failed" almost always occurs. (SMTP servers of Yahoo Japan)
 (3) Mail server doesn't receive mail when "Sending of msg failed" is displayed.
 (4) Disabling of Anti-virus software does do nothing.
And in analysis of above(analysis of NSPR log), this bug's problem, connection loss while SMTP SEND due to timeout, is found.

Above is almost same phenomenon as yours, but (3) is different from your case.
    - In your case, yout SMTP server receives mail sometimes
      even when "Sending of msg failed" occurs.
This difference may be caused ;
 1. Outgoing mail scan by firewall(or firewall function of Anti-Virus software)
 2. Simply timing depend difference 
 3. Difference of SMTP server
    - bellsouth in your case, but unfortunately Yahoo Japan in our case :)

Anyway, get NSPR log and attach it to this bug.

Comment 11

[WADA:World Anti-bad-Duping Agency]

According to http://kb.mozillazine.org/Session_logging_for_mail/news , meaning of SMTP state is following (log in comment #2). 
>10:04:59.432 SMTP Response: 354 Start mail input; end with <CRLF>.<CRLF>	
>10:04:59.442 SMTP entering state: 8  (8 = SEND_DATA_RESPONSE) 	
>10:04:59.442 SMTP entering state: 9  (9 = SEND_POST_DATA)
>10:04:59.503 SMTP Send: .
>10:04:59.523 poll timeout: 60000
>10:04:59.523 poll timeout: 60000
>10:05:00.314 SMTP connection dropped after 195 total bytes read

It looks that SMTP server of Yahoo! Japan killed connection when received "."(indicator of end of mail data). How can we know this by client side logging or tracing? 

Comment 12

[WADA:World Anti-bad-Duping Agency]

Possibly Bug 437494. Setting dependency.
I'm not sure this bug is same problm as Bug 437494, but if problem of Bug 437494 occurred in this bug's case, phenomenon of this bug can be explained.

Comment 14

[Wayne Mery (:wsmwk)]

Version 91 has all new smtp backend code. If you can still reproduce this issue, please file a new bug report https://bugzilla.mozilla.org/enter_bug.cgi?product=MailNews%20Core&component=Networking%3A%20SMTP