Closed Bug 325379 Opened 19 years ago Closed 18 years ago

STARTTLS negotiation skipped when account set to "TLS, if available"

Categories

(MailNews Core :: Networking: IMAP, defect)

Product:
MailNews Core
Component:
Networking: IMAP
Type:
defect
Priority:
Not set
Severity:
major

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: mozilla-ri, Assigned: Bienvenu)

References

Details

(Keywords: fixed1.8.0.7, fixed1.8.1, Whiteboard: [sg:high])

Attachments

(2 files)

proposed fix
7.82 KB, patch
mscott
: superreview+
dveditz
: approval1.8.0.7+
Details | Diff | Splinter Review
fix as checked into 1.5.0.x branch
8.94 KB, patch
Details | Diff | Splinter Review 
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8) Gecko/20051111 Firefox/1.5
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8) Gecko/20051111 Firefox/1.5

Fresh install of Mozilla Thunderbird version 1.5 (20051201) (on Windows XP) (old profile deleted before installing).  Account set to "TLS, if available".  "Use secure authentication" is NOT checked.  IMAP server is a default Dovecot 1.0_beta2 installation (except I turned on AUTH=LOGIN as well was AUTH=PLAIN to test if that might fix it).  Dovecot is running on a Gentoo box.

When TB first starts, it fails to start the TLS negotiation after issuing "STARTTLS".  Here's an ethereal capture of the session:

<< * OK Dovecot ready.
>> 1 capability
<< * CAPABILITY IMAP4rev1 SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS STARTTLS LOGINDISABLED
<< 1 OK Capability completed.
>> 2 STARTTLS
<< 2 OK Begin TLS negotiation now.
>> 3 capability

And then Thunderbird sits and waits for the server's response, which never comes.  Of course, it shouldn't have issused a "capability" command until after the TLS session was established.

Here's a protocol trace of the session (personal information removed):

0[274868]: 153fc70:imap.censored.host:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
3396[14af510]: ImapThreadMainLoop entering [this=153fc70]
3396[14af510]: 153fc70:imap.censored.host:NA:ProcessCurrentURL: entering
3396[14af510]: 153fc70:imap.censored.host:NA:ProcessCurrentURL:imap://username@imap.censored.host:143/select%3E%5EINBOX:  = currentUrl
3396[14af510]: ReadNextLine [stream=2059128 nb=21 needmore=0]
3396[14af510]: 153fc70:imap.censored.host:NA:CreateNewLineFromSocket: * OK Dovecot ready.

3396[14af510]: 153fc70:imap.censored.host:NA:SendData: 1 capability

3396[14af510]: ReadNextLine [stream=2059128 nb=140 needmore=0]
3396[14af510]: 153fc70:imap.censored.host:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4rev1 SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS STARTTLS LOGINDISABLED

3396[14af510]: ReadNextLine [stream=2059128 nb=28 needmore=0]
3396[14af510]: 153fc70:imap.censored.host:NA:CreateNewLineFromSocket: 1 OK Capability completed.

3396[14af510]: 153fc70:imap.censored.host:NA:SendData: 2 STARTTLS

3396[14af510]: ReadNextLine [stream=2059128 nb=33 needmore=0]
3396[14af510]: 153fc70:imap.censored.host:NA:CreateNewLineFromSocket: 2 OK Begin TLS negotiation now.

3396[14af510]: 153fc70:imap.censored.host:NA:SendData: 3 capability

3396[14af510]: ReadNextLine [stream=2059128 nb=0 needmore=1]
3396[14af510]: 153fc70:imap.censored.host:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b0014
3396[14af510]: 153fc70:imap.censored.host:NA:TellThreadToDie: close socket connection
3396[14af510]: 153fc70:imap.censored.host:NA:CreateNewLineFromSocket: (null)
3396[14af510]: 153fc70:imap.censored.host:NA:ProcessCurrentURL: aborting queued urls
3396[14af510]: ImapThreadMainLoop leaving [this=153fc70]


Note that the above happens only on startup of TB (at least that's what I've noticed).  If I hit the "Get Mail" button, it connects and properly negotiates the TLS session.  But then it fails to log in and check my e-mail.  I get an error message that says "You cannot log in to imap.censored.host because the server has disabled login.  You may need to connect via SSL or TLS.  Please check the account settings for your mail server."  Here is a protocol trace:

0[274868]: 2289f78:imap.censored.host:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
2816[14a85a0]: ImapThreadMainLoop entering [this=2289f78]
2816[14a85a0]: 2289f78:imap.censored.host:NA:ProcessCurrentURL: entering
2816[14a85a0]: 2289f78:imap.censored.host:NA:ProcessCurrentURL:imap://username@imap.censored.host:143/select%3E%5EINBOX:  = currentUrl
2816[14a85a0]: ReadNextLine [stream=21f3010 nb=21 needmore=0]
2816[14a85a0]: 2289f78:imap.censored.host:NA:CreateNewLineFromSocket: * OK Dovecot ready.

2816[14a85a0]: 2289f78:imap.censored.host:NA:SendData: 1 STARTTLS

2816[14a85a0]: ReadNextLine [stream=21f3010 nb=33 needmore=0]
2816[14a85a0]: 2289f78:imap.censored.host:NA:CreateNewLineFromSocket: 1 OK Begin TLS negotiation now.

2816[14a85a0]: 2289f78:imap.censored.host:NA:SendData: 2 capability

2816[14a85a0]: ReadNextLine [stream=21f3010 nb=139 needmore=0]
2816[14a85a0]: 2289f78:imap.censored.host:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4rev1 SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS AUTH=PLAIN AUTH=LOGIN

2816[14a85a0]: ReadNextLine [stream=21f3010 nb=28 needmore=0]
2816[14a85a0]: 2289f78:imap.censored.host:NA:CreateNewLineFromSocket: 2 OK Capability completed.

2816[14a85a0]: 2289f78:imap.censored.host:NA:ProcessCurrentURL: aborting queued urls
2816[14a85a0]: 2289f78:imap.censored.host:NA:SendData: 3 logout

2816[14a85a0]: ReadNextLine [stream=21f3010 nb=19 needmore=0]
2816[14a85a0]: 2289f78:imap.censored.host:NA:CreateNewLineFromSocket: * BYE Logging out

2816[14a85a0]: 2289f78:imap.censored.host:NA:TellThreadToDie: close socket connection
2816[14a85a0]: ImapThreadMainLoop leaving [this=2289f78]

Even though AUTH=LOGIN and AUTH=PLAIN are advertised, Thunderbird simply logs out and gives the error message instead of asking for my password and checking my e-mail.

Note that Dovecot is set to issue LOGINDISABLED unless a TLS session has been established.  If I turn that feature off and have TB log in without TLS or SSL, it connects just fine and works well.

Bugs that seem similar:
Bug 324138
Bug 321005 (maybe?)
Bug 317540
Bug 312009

Please let me know if there is any more information I can provide.

Thanks!

Reproducible: Always
(In reply to comment #0)
> Of course, it shouldn't have issused a "capability" command until after
> the TLS session was established.

Duplicate of Core bug 311939 comment 13?
David, might this be another duplicate of bug 311939 or bug 312009 ?
It's quite possible this has been fixed on the trunk. If the reporter could try a nightly trunk build and let me know if the problem still occurs on the trunk or not, that would be useful. I need to land the patch for bug 311939 on the 1.8 branch if it's not already there, and potentially the 1.8.0.x branch.
(using version 3 alpha 1 (20060714))

I now get the following message whenever I start Thunderbird or click on the "Get Mail" button (with the setting "TLS, if available"):

"You cannot log in to imap.censored.host because the server has disabled login.  You may need to connect via SSL or TLS.  Please check the account settings for your mail server."

Here is the Ethereal capture:

<< * OK [CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS STARTTLS LOGINDISABLED] Dovecot ready.
>> 1 capability
<< * CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS STARTTLS LOGINDISABLED
<< 1 OK Capability completed.
>> 2 STARTTLS
<< 2 OK Begin TLS negotiation now.
>> 3 logout

Would a protocol trace be helpful?  If so, I'll work on remembering how to get one.  :)

Thanks for your help!
I got a protocol trace, although it's not very enlightening:

3440[221ce00]: ImapThreadMainLoop entering [this=227ad80]
0[284518]: 227ad80:imap.censored.host:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
3440[221ce00]: 227ad80:imap.censored.host:NA:ProcessCurrentURL: entering
3440[221ce00]: 227ad80:imap.censored.host:NA:ProcessCurrentURL:imap://username@imap.censored.host:143/select%3E.INBOX:  = currentUrl
3440[221ce00]: ReadNextLine [stream=1d51c68 nb=168 needmore=0]
3440[221ce00]: 227ad80:imap.censored.host:NA:CreateNewLineFromSocket: * OK [CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS STARTTLS LOGINDISABLED] Dovecot ready.
3440[221ce00]: 227ad80:imap.censored.host:NA:SendData: 1 capability
3440[221ce00]: ReadNextLine [stream=1d51c68 nb=148 needmore=0]
3440[221ce00]: 227ad80:imap.censored.host:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS STARTTLS LOGINDISABLED
3440[221ce00]: ReadNextLine [stream=1d51c68 nb=28 needmore=0]
3440[221ce00]: 227ad80:imap.censored.host:NA:CreateNewLineFromSocket: 1 OK Capability completed.
3440[221ce00]: 227ad80:imap.censored.host:NA:SendData: 2 STARTTLS
3440[221ce00]: ReadNextLine [stream=1d51c68 nb=33 needmore=0]
3440[221ce00]: 227ad80:imap.censored.host:NA:CreateNewLineFromSocket: 2 OK Begin TLS negotiation now.
3440[221ce00]: 227ad80:imap.censored.host:NA:ProcessCurrentURL: aborting queued urls
3440[221ce00]: 227ad80:imap.censored.host:NA:SendData: 3 logout
3440[221ce00]: ReadNextLine [stream=1d51c68 nb=0 needmore=1]
3440[221ce00]: 227ad80:imap.censored.host:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e
3440[221ce00]: 227ad80:imap.censored.host:NA:TellThreadToDie: close socket connection
3440[221ce00]: 227ad80:imap.censored.host:NA:CreateNewLineFromSocket: (null)
3440[221ce00]: 227ad80:imap.censored.host:NA:TellThreadToDie: close socket connection
3440[221ce00]: ImapThreadMainLoop leaving [this=227ad80]

0x804b000e is NET_ERROR_TIMEOUT - which implies the STARTTLS negotiation timed out - is that possible? 
According to Ethereal, the time between receiving "2 OK Begin TLS negotiation now" and sending "3 logout" is about 1.4 seconds (although the Thunderbird error message appears to pop up the instant "2 OK Begin TLS" is received).

If it is timing out, the timeout value must be really short.  :)
Thinking about it more, the ball is in Tunderbird's court after receiving "2 OK Begin TLS negotiation now."  Nothing should time out unless it's waiting for the server to do something, right?
Too bad there aren't any timestamps in that log (or are there?).

David, Are you asking me if a timeout is technically feasible?

A timeout while waiting for the SSL handshake to finish is certainly feasible.  
I don't know what libSSL function you're code is calling (through NSPR) to 
do the handshake.  PR_Write?  PR_Send?  SSL_ForceHandshake?  

PR_Write implicitly sets an infinite timeout (IIRC).  
PR_Send lets the caller set the timeout explicitly.
SSL_ForceHandshake uses the timeout value from the preceding PR_Write or 
PR_Send operation.  (You can do a zero-length PR_Send to set it).  
SSL_ForceHandshakeWithTimeout lets the caller set the timeout explicitly.

But if libSSL and/or NSPR returned a PR_IO_TIMEOUT_ERROR, that would not
have had the value you cited.  So, I wonder what code translates the error
code from NSPR error space to this other space.  
TB uses necko timeouts for our i/o, which are useable settable but default to 60 seconds. There are some known problems on certain windows dual cpu machines where timeouts don't work right (see bug 307527) but most of these have been fixed as of TB 1.5.0.2, I believe. Do you have a multi-cpu machine?

At this point in the log, we should be calling nsISSLSocketControl->StartTLS()

Was you last log, in #5, from a trunk build or a 1.5 build? In trunk builds, it should log errors from nsISSLSocketControl->StartTLS() explicitly
Status: UNCONFIRMED → NEW
Ever confirmed: true
(In reply to comment #10)
> Do you have a multi-cpu machine?

Nope, single CPU (it happens on both my Pentium M laptop and on my Athlon XP desktop).

> Was you last log, in #5, from a trunk build or a 1.5 build?

The log in comment #5 was generated using a trunk build (version 3 alpha 1 (20060714)).

Here we issue the STARTTLS command, and parse the response:

http://lxr.mozilla.org/seamonkey/source/mailnews/imap/src/nsImapProtocol.cpp#1377

From the protocol log, it seems like that should have parsed fine and we should proceed to nsISSLSocketControl->StartTLS(). But we're behaving as if we failed to parse the OK response. I'll look a little more.
Attached patch proposed fix — — Splinter Review 
The first imap connection made to a server wasn't checking the previously cached capability flags (the ones we write out to prefs.js). Thus, it didn't know to try to create a STARTTLS connection. 

Furthermore, Courier imap wasn't returning STARTTLS for the capability we request after doing STARTTLS, so we were clearing that flag before writing it out to prefs.js, so the next time you ran, we wouldn't know to do STARTTLS. So I ignore the clearing of that flag if we've just successfully done a STARTTLS.

Finally, I made it so if we connect to a server that we don't know does STARTTLS, but it tells us it does, then we retry the url using a STARTTLS connection. This handles the first time use case where you create an imap server account and pick use TLS if available, but we don't know to use STARTTLS because we've never connected. In this case, we will now close out the first connection, and open a new connection that will be made with STARTTLS.

And, I make sure we don't try to do a STARTTLS if we didn't create the connection as of type "starttls", because that doesn't work in necko.

The potential downside to this patch is that we will issue a CAPABILITY command for every connection we make to the server (i.e., for each folder), instead of just for the first connection. I could fix this by not writing out the kCapabilityDefined flag to the prefs, and instead of checking for kCapabilityUndefined before sending Capability, check for !(capability & kCapabilityDefined). But it's not so obvious that it's wrong to issue a CAPABILITY command for each connection.
Assignee: mscott → bienvenu
Status: NEW → ASSIGNED
Attachment #229572 - Flags: superreview?(mscott)
Comment on attachment 229572 [details] [diff] [review]
proposed fix

You would know better than me if it's ok to issue the capability command for each connection.
Attachment #229572 - Flags: superreview?(mscott) → superreview+
fixed on trunk - please try tomorrow's trunk build. If you can, please let me know ASAP as I'd like to get this into 2.0 Alpha, which would mean I'd have to check it in by tomorrow at the latest...Thx!
Status: ASSIGNED → RESOLVED
Closed: 18 years ago
Resolution: --- → FIXED
It's working well for me so far.  I'll poke it harder by trying more cases (different server settings, etc.) to see if I can make it break.  :)
fixed on 2.0 branch - fix should be in 2.0 Alpha
Keywords: fixed1.8.1
OS: Windows XP → All
Product: Thunderbird → Core
Hardware: PC → All
Version: unspecified → Trunk
Component: General → Networking: IMAP
Comment on attachment 229572 [details] [diff] [review]
proposed fix

this should really be fixed...
Attachment #229572 - Flags: approval1.8.0.7?
*** Bug 329239 has been marked as a duplicate of this bug. ***
*** Bug 338243 has been marked as a duplicate of this bug. ***
Flags: blocking1.8.0.7+
Flags: blocking-thunderbird2?
Comment on attachment 229572 [details] [diff] [review]
proposed fix

approved for 1.8.0 branch, a=dveditz for drivers
Attachment #229572 - Flags: approval1.8.0.7? → approval1.8.0.7+
Whiteboard: [sg:high]
I rolled the changes in bug 311939 into this patch, so the patch that's part of this bug would apply cleanly. It just adds a bit more error checking and logging.
fixed for 1.5.0.7 as well.
Keywords: fixed1.8.0.7
*** Bug 311939 has been marked as a duplicate of this bug. ***
retro-active pixie dust. this is already fixed for tb2.
Flags: blocking-thunderbird2? → blocking-thunderbird2+
Product: Core → MailNews Core
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: