Closed Bug 382391 Opened 17 years ago Closed 1 year ago

Sending Unsent Messages fails when going Online, if dialing up takes long

Categories

(MailNews Core :: Networking, defect)

x86
Windows 2000
defect

Tracking

(Not tracked)

RESOLVED WORKSFORME

People

(Reporter: tlmester, Unassigned)

References

(Blocks 1 open bug)

Details

Attachments

(2 files)

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.8.1.3) Gecko/20070309 Firefox/2.0.0.3
Build Identifier: Thunderbird version 2.0.0.0 (20070326)

There is a problem with the "Send Unsent Messages" feature when you go ONLINE.  Thunderbird starts sending the Messages BEFORE it has finished connecting up Online.  The result is an Error Message that Sending Unsent Messages failed because TBird couldn't connect to POP Server.  TBird needs to wait until fully Online before sending.  This problem does not occur when you choose "Send Unsent Messages" from the "File Menu".

Reproducible: Always

Steps to Reproduce:
1.  Make sure TBird is OFFLINE
2.  Store a Message in the "Unsent" Message Box of "Local Folders"
3.  Choose to go ONLINE
4.  Check YES to the Sending Unsent Messages Dialog Box

Actual Results:  
The result is an Error Message that Sending Unsent Messages failed because TBird couldn't connect to POP Server.

Expected Results:  
TBird should not attempt to send Unsent Messages until properly connected Online.
If it's sending the messages, shouldn't only SMTP server matter? I don't see why it would have to connect to the POP server. Are you sure you copied that over correctly to this bug?
Version: unspecified → 2.0
You're correct.  The Error Message is SMTP
Thunderbird version 2.0.0.4 (20070604)
The optional "Send Unsent Messages" feature when going ONLINE still doesn't work all of the time.  It only works less than half the time.  I have Thunderbird version 2.0.0.4 (20070604). 
(In reply to comment #0)
> Steps to Reproduce:
> 1.  Make sure TBird is OFFLINE
> 2.  Store a Message in the "Unsent" Message Box of "Local Folders"
> 3.  Choose to go ONLINE
> 4.  Check YES to the Sending Unsent Messages Dialog Box
> Actual Results:  
> The result is an Error Message that Sending Unsent Messages failed because
> TBird couldn't connect to POP Server.

Get NSPR log, and attach log file to this bug.
(text/plain if size is accepted. Don't paste long text to this bug, please.)
 - http://kb.mozillazine.org/Session_logging_for_mail/news
 - http://www.mozilla.org/quality/mailnews/mail-troubleshoot.html#smtp
 - http://www.mozilla.org/projects/netlib/http/http-debugging.html
Following is helpful, I think.
  SET NSPR_LOG_MODULES=SMTP:5,nsSocketTransport:5,nsHostResolver:5

Question about your environment:
Dial up connection?
Yes, I am using Dial-Up Connection.  I created a NSPR Log Batch Command as follows:
set NSPR_LOG_MODULES=protocol:5
set NSPR_LOG_FILE=c:\temp\mozillaTB_log.txt
start thunderbird.exe

It created the Log File, but the File is empty.  Can you offer further advice on creating this NSPR Log?
I believe that the only time the "Send Unsent Message Box" fails is when I select "Get Mail" when TBird is OFFLINE, and I am NOT CONNECTED to the Internet.  It first asks me if I want to go ONLINE, and then asks me if I want to Send Unsent Messages, and then goes to the Windows "Connect Box" for dialing up my Internet Connection.  It tries to Send Unsent Messages before the connection is completed.  TBird only needs to wait about a half a second longer to Send Unsent Messages, and then the Internet Connection will have been completed.  Sometimes, the Connect Box comes up right after the Send Unsent Messages Box, and when I make the Internet Connection before choosing "YES" in the Send Unsent Messages Box, it then works.  When choosing to go ONLINE without choosing "Get Mail", the Send Unsent Messages Box works.
set NSPR_LOG_MODULES=protocol:5

should be

set NSPR_LOG_MODULES=SMTP:5

but this is basically an issue with the dial-up connection stuff - we're probably timing out before the connection finishes. How long does dialin take? You might try increasing the timeout in tools | options | advanced, network, though 120 seconds should be plenty.
Attached file My Log File —
Attachment #271963 - Flags: review?
The Log worked with the new command line.  Attached is the Log File.  I sent 3 Messages.  As you can see, the first 2 Messages worked.  The Log ends "0[2346f8]: SMTP Connecting to: mail.niagara.com" which is when TBird failed to send the 3rd Message.  This isn't a "Time-out" problem.  TBird starts sending Unsent Messages as soon as the Window's "Connect" Box closes.  This sending takes place only about 1/2 Second before the connection is completed.

You should be suffering the same problem.  Do you use "Direct connection to the Internet" in "Connection Settings"?  Even if you have High Speed Internet connection, Windows still has to dial up your phone connection to your local Internet Server.  This is where the sending problem occurs.  Right at the point where the Windows Connect Box closes.  When the Windows Connection is completed before choosing YES to "Send Unsent Messages" Box, then it works fine.  The problem only occurs when the "Send Unsent Messages" Box comes up before the Windows Connect Box.
(In reply to comment #8)
> The Log ends "0[2346f8]: SMTP Connecting to: mail.niagara.com"
Did you terminate Thunderbird before save log file? Please note that NSPR log is buffered.
(In reply to comment #9)
> > The Log ends "0[2346f8]: SMTP Connecting to: mail.niagara.com"
> Did you terminate Thunderbird before save log file? Please note that NSPR log
> is buffered.
> 
As soon as I got the Error Message that the sending of my Message failed, I then closed TBird.  The Log File was created and saved automatically.  It stops where the Error occurred.  Is there another type of Log process that would work?
Last "0[2346f8]: SMTP Connecting to: mail.niagara.com" means Tb is waiting for response to connection request.
Get log with following, and see log after last successful SEND.
  SET NSPR_LOG_MODULES=SMTP:5,nsSocketTransport:5,nsHostResolver:5
Attached file New Log File —
OK.  Here's the new Log File with that new Command Line.  I sent 3 Messages.
The 1st Message was sent out when TBird started up.  The Windows "Connect" Box came up before the 'Send Unsent Messages" Box, and the Message was sent out successfully after Windows connected to the Internet.
The 2nd was attempted when I chose to "Get Mail", and was then asked to "Go Online", and then asked to "Send Unsent Messages" BEFORE the Windows "Connect" Box came up.  I chose YES to "Send Unsent Messages", and then the Windows "Connect" Box came up and I chose to dial up my Internet Connection.  Once the Internet Connection was made, the Error Message came up stating that sending messages failed because it was unable to connect to SMTP server.
The 3rd Message was just sent out by selecting "Send Unsent Messages" in the "File Menu".  It went out successfully.

That Log File is pretty long.  I hope it details what went wrong with the 2nd Message.
(In reply to comment #12)
> The 1st Message was sent out when TBird started up.  The Windows "Connect" Box
> came up before the 'Send Unsent Messages" Box, and the Message was sent out
> successfully after Windows connected to the Internet.

(A)It looks to correspond to first "SMTP Connecting to: mail.niagara.com" followed by DNS lookup and successful SEND of a mail.

> The 2nd was attempted when I chose to "Get Mail", and was then asked to "Go
> Online", and then asked to "Send Unsent Messages" BEFORE the Windows "Connect"
> Box came up.  I chose YES to "Send Unsent Messages", and then the Windows
> "Connect" Box came up and I chose to dial up my Internet Connection.  Once the
> Internet Connection was made, the Error Message came up stating that sending
> messages failed because it was unable to connect to SMTP server.

(B)It looks to correspond to second "SMTP Connecting to: mail.niagara.com" followed by DNS lookup logs and next timeout log, 
> 1044[2f7e490]: poll timeout: 120
> 1044[2f7e490]:     timeout = 120000 milliseconds
and many polling logs, and no SMTP flow.

> The 3rd Message was just sent out by selecting "Send Unsent Messages" in the
> "File Menu".  It went out successfully.

(C)It looks to correspond to third "SMTP Connecting to: mail.niagara.com" followed by DNS lookup and successful SEND of a mail.

When case (B), change offline to online, following probably occurs.
1. Request "Get Msgs" (POP3 requesst)
2. Move from offline mode to online mode, according to reply to dialog
3. Connection request to SMTP server is executed immediately
   => TCP request is issued
4. Dialer is kicked => It takes a while
5. Timeout of 120 sec, then try to cancel connection request
6. Because dialing is in progress, response to cancel is postponed
7. Dialing completed, and response to cancel is returned
   => Error message of "Sending failed"

Can larger mailnews.tcptimeout(connection timeout setting) be a workaround?  
I think I figured out what was going wrong.  In "Tools / Options / Advanced", my "Connection timeout" was set to 60 Seconds.  I've just changed it to 120 Seconds, and the problem seems to be solved.  I've just sent a few Messages via "Get Mail" first, and now the "Send Unsent Messages" Box process is working.
What does this "Connection Timeout" apply to?  It doesn't take 60 Seconds for the Windows Internet Connection to be made.  The "Get Mail" feature has never been affected by this problem.
Status: UNCONFIRMED → RESOLVED
Closed: 17 years ago
Resolution: --- → FIXED
->WFM (FIXED is used only when known code changes resolved the issue)
Resolution: FIXED → WORKSFORME
Oops.  I spoke too soon.  The "Send Unsent Messages" Box when going Online is again failing due to error -- even with "Connection Timeout" set at 120 Seconds.  I can't figure this out.  It was working the other day at 120 Seconds.
Status: RESOLVED → UNCONFIRMED
Resolution: WORKSFORME → ---
After using new Version 2.0.0.6 (20070728) for a few weeks, I'm still suffering this failure about half of the time.  I believe that there's a simple way to fix this problem.  If the first attempt to connect to the SMTP Server fails, instead of cancelling the action, have TBird wait 1 Second and make another attempt to connect.  Only if this second attempt fails would the action be cancelled, and the Error Message Box posted.  I believe that this will solve the problem.
Adding "dial-up" in summary for ease of search.
Summary: Sending Unsent Messages fails when going Online → Sending Unsent Messages fails when going Online, if dialing up takes long
(In reply to comment #17)
> I'm still suffering this failure about half of the time.

If you(& your dialer) usually take 3 minutes to finish dialing-up, increase timeout value to 3 minutes(180 sec), and if 5 minutes, to 5 minutes(=300 sec).
Still very frequently occurs?
I have set the Connection Timeout to 300 Seconds (5 Minutes).  However, it only takes about 30 Seconds for the connection to my Internet Server to be completed.  This can't be the problem.

The problem appears to me that TBird is initiating the Send Command at the exact same time that the Windows Dialer Box BEGINS to close -- after my connection is made.  However, it takes about 1 Second for the Dialer Box to finish closing.  This means that the Send is delayed by about 1 Second.  TBird then assumes a failed connection.  A delay of only 1 Second in the Send Command should solve this problem.  Instituting a 1 Second delay (after a failure) and a second attempt as I suggested would also solve the problem.
I double-checked, and I don't have this problem with Outlook Express v6.  OE doesn't attempt to log onto the SMTP Server until the Windows Connection is completed and closed.  This is the problem with TBird.  It's attempting to log onto the SMTP Server BEFORE the Connection Box closes.  I cannot believe that nobody else is suffering this problem.
(In reply to comment #21)
> I cannot believe that nobody else is suffering this problem.

Do you use dial up analog line(charged based on dial-up'ed time) with MODEM such as 28800 bps? (PPP, and TCP/IP over PPP) 
Or you are using ADSL/VDSL modem and dialer(your ISP forces you to use it, because PPP over TCP/IP is used instead of using ADSL modem as rooter).

If latter, dialing up is required at re-boot time only, then only very few people can experience phenomenon like you.
(In reply to comment #22)
> (In reply to comment #21)
> Do you use dial up analog line(charged based on dial-up'ed time) with MODEM
> such as 28800 bps? (PPP, and TCP/IP over PPP) 
> Or you are using ADSL/VDSL modem and dialer(your ISP forces you to use it,
> because PPP over TCP/IP is used instead of using ADSL modem as rooter).
> 
> If latter, dialing up is required at re-boot time only, then only very few
> people can experience phenomenon like you.
> 
I use a 50k regular Dialup Modem:  Intel(R) 537EP.  My connection is PPP with LCP Extensions enabled.  My Internet Protocols are TCP/IP.  As I noted, the connection process with OE v6 is started only after the Connection Box closes.  I never had this connection error with OE.  I'm quite certain that a 1 Second delay and retry after a failure will solve this problem.
(In reply to comment #23)
> I use a 50k regular Dialup Modem:  Intel(R) 537EP.  My connection is PPP with
> LCP Extensions enabled.  My Internet Protocols are TCP/IP.

I've understood your environment. 

Question to rule out different issue.
  Is all of your auto-dialing related setups correct and sufficient?
     http://www.mozilla.org/quality/networking/docs/autodial.html
     http://kb.mozillazine.org/Network.autodial-helper.enabled
  (I think no problem in your setup, because auto-dial itself is working well)

> I'm quite certain that a 1 Second delay and retry after a failure will solve this problem.

I also think Tb should be kinder to dial-up users.
(In reply to comment #22)
> Or you are using ADSL/VDSL modem and dialer(your ISP forces you to use it,
> because PPP over TCP/IP is used instead of using ADSL modem as rooter).
> 
> If latter, dialing up is required at re-boot time only, then only very few
> people can experience phenomenon like you.
> 
I believe there is a simple way for you to realize this problem on your Computer.  Just disconnect your Internet Connection through the Windows OS.  Then select in TBird to go "Offline".  Then save a Message to the "Unsent" Folder.  Then choose to "Get Mail", and "Yes" to going Online and Sending Unsent Messages.  TB will then have to invoke the Windows Dialer to reconnect you to the Internet, and you will experience the same situation I have with Dial-up.
I now have Mozilla Thunderbird Version 2.0.0.9 (20071031).  I've tested it out, and this problem still occurs most of the time.
I have now tested the "Send Unsent Messages" via "Get Mail / Go Online" 17 times with new Thunderbird trunk Version 3 (dated December 22nd), and it worked properly to send the messages fully 13 times.  I am pleased with this success rate.  Can someone answer what change has been made with this new V3?  Is it the 'one second delay / retry' I suggested?
If so, this would explain the partial failure rate.  I suppose if there were two 'one second delay / retry' attempts after an initial error / failure, the success rate would be about 100%.
Maybe you were seeing bug 395374?
(In reply to comment #28)
> Maybe you were seeing bug 395374?
> 

I'm not sure what you mean?  I have been suffering bug 395374 in version 2.0.0.9 (20071031) and I also believe in the previous version, but I didn't bother filing a Report.  395374 is a completely different Bug from this one.

Surely something has been done with this new trunk V3 to fix this Bug?  As of today it has only occurred 4 times in 18 uses.  In V2 this Bug occurs about 50% of the time.
Assignee: mscott → nobody
Confirming - Using comment 25 I can reproduce - TB attempts send unsent before networking is up. So ultimately I don't think this is a dialup problem.  Using trunk build:
1. close network connection - TB goes offline by itself
2. send a message to anywhere
3. click to go online
4. click OK at prompt for sending unsent messages

results: message  "Sending of message failed. An error occurred sending mail: SMTP server mail.lehigh.edu is unknown. The server may be incorrectly configured. Please verify that your SMTP server settings are correct and try again"

perhaps related to one of these [1]

FYI nothing not much significant has been fixed in the dialup world in the last 11200 days [2].  Although something in networking may have improved to affect this whose bug that doesn't mention dial up.

perhaps you might find a match up in the list of open bugs that mention dial [3]

[1] https://bugzilla.mozilla.org/buglist.cgi?query_format=advanced&short_desc_type=allwordssubstr&short_desc=send+sent+&product=MailNews+Core&product=Thunderbird&product=Toolkit&long_desc_type=substring&long_desc=send+unsent&bug_file_loc_type=allwordssubstr&bug_file_loc=&status_whiteboard_type=allwordssubstr&status_whiteboard=&keywords_type=allwords&keywords=&resolution=---&emailreporter1=1&emailtype1=substring&email1=&emailassigned_to2=1&emailreporter2=1&emailqa_contact2=1&emailtype2=substring&email2=&bugidtype=include&bug_id=&votes=&chfieldfrom=&chfieldto=Now&chfieldvalue=&cmdtype=doit&order=Reuse+same+sort+as+last+time&field0-0-0=noop&type0-0-0=noop&value0-0-0=

[2] https://bugzilla.mozilla.org/buglist.cgi?query_format=advanced&short_desc_type=anywords&short_desc=&product=Core&product=Firefox&product=MailNews+Core&product=Thunderbird&product=Toolkit&long_desc_type=anywords&long_desc=dial+dialing+dials+dialup+&bug_file_loc_type=allwordssubstr&bug_file_loc=&status_whiteboard_type=allwordssubstr&status_whiteboard=&keywords_type=allwords&keywords=&resolution=FIXED&bug_severity=blocker&bug_severity=critical&bug_severity=major&bug_severity=normal&bug_severity=minor&emailreporter1=1&emailtype1=substring&email1=&emailassigned_to2=1&emailreporter2=1&emailqa_contact2=1&emailtype2=substring&email2=&bugidtype=include&bug_id=&votes=&chfieldfrom=1200d&chfieldto=Now&chfield=resolution&chfieldvalue=fixed&cmdtype=doit&order=Reuse+same+sort+as+last+time&field0-0-0=component&type0-0-0=substring&value0-0-0=network

[3] https://bugzilla.mozilla.org/buglist.cgi?query_format=advanced&short_desc_type=anywords&short_desc=dial+dialing+dials+dialup+&product=Core&product=Firefox&product=MailNews+Core&product=Thunderbird&product=Toolkit&long_desc_type=allwordssubstr&long_desc=&bug_file_loc_type=allwordssubstr&bug_file_loc=&status_whiteboard_type=allwordssubstr&status_whiteboard=&keywords_type=allwords&keywords=&resolution=---&bug_severity=blocker&bug_severity=critical&bug_severity=major&bug_severity=normal&bug_severity=minor&emailreporter1=1&emailtype1=substring&email1=&emailassigned_to2=1&emailreporter2=1&emailqa_contact2=1&emailtype2=substring&email2=&bugidtype=include&bug_id=&votes=&chfieldfrom=&chfieldto=Now&chfieldvalue=&cmdtype=doit&order=Reuse+same+sort+as+last+time&field0-0-0=noop&type0-0-0=noop&value0-0-0=
Status: UNCONFIRMED → NEW
Component: General → Networking
Ever confirmed: true
Product: Thunderbird → MailNews Core
QA Contact: general → networking
Version: 2.0 → Trunk
Blocks: 678947
Severity: minor → S4

TCW can you reproduce using comment 30?

Flags: needinfo?(thee.chicago.wolf)

(In reply to Wayne Mery (:wsmwk) from comment #31)

TCW can you reproduce using comment 30?

Nope, I can't repro per comment 30. WFM.

My STR:

  1. Go Offline by clicking the Online/Offline icon ((.)) at bottom left of TB
  2. Compose and send a message while in Offline mode (say yes if prompted to send later once you're in Online mode). It gets saved in Local Folders > Outbox
  3. Go back Online and, when prompted to send the unsent message, click the Send Now button
  4. Verify that after pressing the Send Now button that in Local Folders > Outbox the unsent message is now gone (sent)
Flags: needinfo?(thee.chicago.wolf)

Thanks for the test

Status: NEW → RESOLVED
Closed: 17 years ago1 year ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: