460419 - Security protocol not enabled (IMAP with STARTTLS)

Status: RESOLVED INCOMPLETE

(MailNews Core :: Networking: IMAP, defect)

Description

[Gaétan RYCKEBOER]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.3) Gecko/2008092417 Firefox/3.0.3
Build Identifier: version 2.0.0.17 (20080914)

The thunderbird secure connexion to TLS/SSL imap servers fails if the connexion is broken for a reason :
Thunderbird dont check for server enabled protocols after such a failure.
The only way to have the connexion restablished after such a disconnexion is a stop/restart.

Reproducible: Always

Steps to Reproduce:
1. Establish a secured IMAP connexion to slow server (SSL, or TLS)
2. Try to read a lot of headers of mails
3. At a time, Thunderbird will complain about "this server is not an imap server" or "secured connexion cannot be established because of a security protocol which is not enabled".
4. Retry again, until the "security protocol" message.
Actual Results:  
Any further try to obtain any information from the server after the "security protocol" will fail with the message "ecured connexion cannot be established because of a security protocol which is not enabled"

Expected Results:  
Close the persistant connexion, and try a fresh IMAP connexion, with interrogation of the supported protocols.

This is easier to obtain under a very slow connexion, like a modem dialup, or a slow up DSL line.

Comment 1

[rsx11m]

I can reproduce the "this server is not an imap server" message, which may actually be bug 363039, but haven't seen the "secured connexion cannot be established..." one yet, using IMAP over SSL and interrupting network while connected. Can you give further details, also on your IMAP settings?

See https://wiki.mozilla.org/MailNews:Logging for instructions how to create
an IMAP log, which may give some further insights on what's going on. You can attach it here for further analysis, feel free to remove any information you don't want to post publicly, or just extract the relevant parts if it becomes obvious which ones are related to the issue.

Comment 2

[Gaétan RYCKEBOER]

Got a log.

http://greedo.ryckeboer.org/imap-tls-thunderbig.log

Comment 3

[rsx11m]

Thanks for the log. I'm using SSL rather than TLS for my IMAP servers, so this would be a difference.

It is interesting that the log shows a "PSEUDO-Interrupted" message right where the TLS negotiation should take place. While the first occurrence shows:

> SendData: 1 capability, CreateNewLineFromSocket: 1 OK Completed
> SendData: 2 STARTTLS, CreateNewLineFromSocket: 2 OK Begin TLS negotiation now
> SendData: 3 capability, CONTROL: PSEUDO-Interrupted
> SendData: 4 logout, TellThreadToDie: close socket connection

the following reconnection attempts don't even get there:

> SendData: 1 capability, CreateNewLineFromSocket: 1 OK Completed
> SendData: 2 STARTTLS, CONTROL: PSEUDO-Interrupted
> SendData: 3 logout, TellThreadToDie: close socket connection

So that looks indeed rather suspicious.

Comment 4

[Gaétan RYCKEBOER]

Another way to reproduce it :
Have a TLS certificate belonging to another server (www.foo.bar, and address it via a ssh tunnel, for instance).
This will generate a confirmation warning, which is absolutely normal.
Do not accept the certificate before the server connexion timeout occurs.

It will show the "security protocol not enabled", and a further internal error (which is another bug).
But we will be in the same case : impossible to parse again the capabilities without stop/restarting thunderbird.

Comment 5

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #3)
> It is interesting that the log shows a "PSEUDO-Interrupted" message right where
> the TLS negotiation should take place. While the first occurrence shows:
> 
> > SendData: 1 capability, CreateNewLineFromSocket: 1 OK Completed
> > SendData: 2 STARTTLS, CreateNewLineFromSocket: 2 OK Begin TLS negotiation now
> > SendData: 3 capability, CONTROL: PSEUDO-Interrupted
> > SendData: 4 logout, TellThreadToDie: close socket connection

(A) Following is normal flow when STARTTLS is used, which is explained in "3.1. STARTTLS Command" of RFC 2595. RFC says that first command after TLS negotiation should be "CAPABILITY".
> http://www.ietf.org/rfc/rfc2595.txt
> 3.1. STARTTLS Command
>(snip)
>   Example:    C: a001 CAPABILITY
>               S: * CAPABILITY IMAP4rev1 STARTTLS LOGINDISABLED
>               S: a001 OK CAPABILITY completed
>               C: a002 STARTTLS
>               S: a002 OK Begin TLS negotiation now
>               <TLS negotiation, further commands are under TLS layer>
>               C: a003 CAPABILITY
>               S: * CAPABILITY IMAP4rev1 AUTH=EXTERNAL
>               S: a003 OK CAPABILITY completed
>               C: a004 LOGIN joe password
>               S: a004 OK LOGIN completed

(B) An example of PSEUDO-Interrupt usage is written in following document.
> http://www-archive.mozilla.org/quality/mailnews/tests/sea-mn-imap-interop.html
> 3) PSEUDO-Interrupt IMAP msg loading (close, exit, stop......etc)(e.g. load a 6MB message over a slow connection)

Log of "CONTROL: PSEUDO-Interrupted" just after "2 OK Begin TLS negotiation" and "3 capability" looks for me that;
(1-1) Tb issues CAPABILITY even when something wrong occurs during TLS negotiation, then log of "CONTROL: PSEUDO-Interrupted".
(1-2) Server somehow returns error for packets for CAPABILITY command even after successful TLS negotiation, or something wrong occurs after successful TLS negotiation, then log of "CONTROL: PSEUDO-Interrupted".

To Gaétan RYCKEBOER(bug opener):

I suspect (1-1), because you say ; 
> It will show the "security protocol not enabled", and a further internal error (which is another bug).
NSPR log for Socket level flow is usually required to see what is happening around TLS negotiation. See documents listed in meta Bug 402793 Comment #1, and get & check NSPR log with following parameter first.
> SET NSPR_LOG_MODULES=imap:5,nsSocketTransport:5,nsHostResolver:5

When timing related problem is involved, timestamp of NSPR log will help problem analysis. See meta Bug 402793 Comment #6 for getting NSPR log with timestamp by DebugView on MS Windows.

Comment 6

[Gaétan RYCKEBOER]

OK. So here it is.
http://greedo.ryckeboer.org/thunderbig-login-tls-imap.log

I presume it is a bit verbose.

I started the debug as soon as possible after TF launch.
- launch TF
- launch debug
- Warn for TLS certificate bad issuer
- don't respond
- respond - popup disapears
- clic on any mail - Popup with "security protocol is not enabled"
- second clic on another mail - Popup with "security protocol is not enabled"
- stop debug

Comment 7

[Marcin Cieślak (:saper)]

I have the same problem using Mozilla/5.0 (X11; U; FreeBSD amd64; en-US; rv:1.8.1.18) Gecko/20081228 SeaMonkey/1.1.13. I've been having this problem for a long time connection to one specific IMAP server that is based on UW-IMAP.
When I have some connectivity issues (TCP connection gets lost or sth) sometimes after that I get the message "Seamonkey cannot connect securely to server XXX" with "security protocol is enabled".

At the same time I have got this message I have tried connecting with 
"openssl s_client -connect host:port -starttls imap" and I also got connection interrupted!

Having sniffed the openssl connection attempt I have found out that "openssl" sends the STARTTLS IMAP command and after this it presents SSL23 client hello:

Secure Socket Layer
    SSLv2 Record Layer: Client Hello
        [Version: SSL 2.0 (0x0002)]
        Length: 118
        Handshake Message Type: Client Hello (1)
        Version: TLS 1.0 (0x0301)
        Cipher Spec Length: 93
        Session ID Length: 0
        Challenge Length: 16
        Cipher Specs (31 specs)
            Cipher Spec: TLS_DHE_RSA_WITH_AES_256_CBC_SHA (0x000039)
            Cipher Spec: TLS_DHE_DSS_WITH_AES_256_CBC_SHA (0x000038)
            Cipher Spec: TLS_RSA_WITH_AES_256_CBC_SHA (0x000035)
            Cipher Spec: TLS_DHE_RSA_WITH_CAMELLIA_256_CBC_SHA (0x000088)
            Cipher Spec: TLS_DHE_DSS_WITH_CAMELLIA_256_CBC_SHA (0x000087)
            Cipher Spec: TLS_RSA_WITH_CAMELLIA_256_CBC_SHA (0x000084)
            Cipher Spec: TLS_DHE_RSA_WITH_3DES_EDE_CBC_SHA (0x000016)
            Cipher Spec: TLS_DHE_DSS_WITH_3DES_EDE_CBC_SHA (0x000013)
            Cipher Spec: TLS_RSA_WITH_3DES_EDE_CBC_SHA (0x00000a)
            Cipher Spec: SSL2_DES_192_EDE3_CBC_WITH_MD5 (0x0700c0)
            Cipher Spec: TLS_DHE_RSA_WITH_AES_128_CBC_SHA (0x000033)
            Cipher Spec: TLS_DHE_DSS_WITH_AES_128_CBC_SHA (0x000032)
            Cipher Spec: TLS_RSA_WITH_AES_128_CBC_SHA (0x00002f)
            Cipher Spec: TLS_DHE_RSA_WITH_CAMELLIA_128_CBC_SHA (0x000045)
            Cipher Spec: TLS_DHE_DSS_WITH_CAMELLIA_128_CBC_SHA (0x000044)
            Cipher Spec: TLS_RSA_WITH_CAMELLIA_128_CBC_SHA (0x000041)
            Cipher Spec: SSL2_RC2_CBC_128_CBC_WITH_MD5 (0x030080)
            Cipher Spec: TLS_RSA_WITH_RC4_128_SHA (0x000005)
            Cipher Spec: TLS_RSA_WITH_RC4_128_MD5 (0x000004)
            Cipher Spec: SSL2_RC4_128_WITH_MD5 (0x010080)
            Cipher Spec: TLS_DHE_RSA_WITH_DES_CBC_SHA (0x000015)
            Cipher Spec: TLS_DHE_DSS_WITH_DES_CBC_SHA (0x000012)
            Cipher Spec: TLS_RSA_WITH_DES_CBC_SHA (0x000009)
            Cipher Spec: SSL2_DES_64_CBC_WITH_MD5 (0x060040)
            Cipher Spec: TLS_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA (0x000014)
            Cipher Spec: TLS_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA (0x000011)
            Cipher Spec: TLS_RSA_EXPORT_WITH_DES40_CBC_SHA (0x000008)
            Cipher Spec: TLS_RSA_EXPORT_WITH_RC2_CBC_40_MD5 (0x000006)
            Cipher Spec: SSL2_RC2_CBC_128_CBC_WITH_MD5 (0x040080)
            Cipher Spec: TLS_RSA_EXPORT_WITH_RC4_40_MD5 (0x000003)
            Cipher Spec: SSL2_RC4_128_EXPORT40_WITH_MD5 (0x020080)
        Challenge

After this the connection gets closed from the server (FIN+ACK).

However, when I try

openssl s_client -connect host:port -starttls imap -tls1

I get the connection working, with this TLS client hello:

Secure Socket Layer
    TLSv1 Record Layer: Handshake Protocol: Client Hello
        Content Type: Handshake (22)
        Version: TLS 1.0 (0x0301)
        Length: 93
        Handshake Protocol: Client Hello
            Handshake Type: Client Hello (1)
            Length: 89
            Version: TLS 1.0 (0x0301)
            Random
            Session ID Length: 0
            Cipher Suites Length: 50
            Cipher Suites (25 suites)
                Cipher Suite: TLS_DHE_RSA_WITH_AES_256_CBC_SHA (0x0039)
                Cipher Suite: TLS_DHE_DSS_WITH_AES_256_CBC_SHA (0x0038)
                Cipher Suite: TLS_RSA_WITH_AES_256_CBC_SHA (0x0035)
                Cipher Suite: TLS_DHE_RSA_WITH_CAMELLIA_256_CBC_SHA (0x0088)
                Cipher Suite: TLS_DHE_DSS_WITH_CAMELLIA_256_CBC_SHA (0x0087)
                Cipher Suite: TLS_RSA_WITH_CAMELLIA_256_CBC_SHA (0x0084)
                Cipher Suite: TLS_DHE_RSA_WITH_3DES_EDE_CBC_SHA (0x0016)
                Cipher Suite: TLS_DHE_DSS_WITH_3DES_EDE_CBC_SHA (0x0013)
                Cipher Suite: TLS_RSA_WITH_3DES_EDE_CBC_SHA (0x000a)
                Cipher Suite: TLS_DHE_RSA_WITH_AES_128_CBC_SHA (0x0033)
                Cipher Suite: TLS_DHE_DSS_WITH_AES_128_CBC_SHA (0x0032)
                Cipher Suite: TLS_RSA_WITH_AES_128_CBC_SHA (0x002f)
                Cipher Suite: TLS_DHE_RSA_WITH_CAMELLIA_128_CBC_SHA (0x0045)
                Cipher Suite: TLS_DHE_DSS_WITH_CAMELLIA_128_CBC_SHA (0x0044)
                Cipher Suite: TLS_RSA_WITH_CAMELLIA_128_CBC_SHA (0x0041)
                Cipher Suite: TLS_RSA_WITH_RC4_128_SHA (0x0005)
                Cipher Suite: TLS_RSA_WITH_RC4_128_MD5 (0x0004)
                Cipher Suite: TLS_DHE_RSA_WITH_DES_CBC_SHA (0x0015)
                Cipher Suite: TLS_DHE_DSS_WITH_DES_CBC_SHA (0x0012)
                Cipher Suite: TLS_RSA_WITH_DES_CBC_SHA (0x0009)
                Cipher Suite: TLS_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA (0x0014)
                Cipher Suite: TLS_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA (0x0011)
                Cipher Suite: TLS_RSA_EXPORT_WITH_DES40_CBC_SHA (0x0008)
                Cipher Suite: TLS_RSA_EXPORT_WITH_RC2_CBC_40_MD5 (0x0006)
                Cipher Suite: TLS_RSA_EXPORT_WITH_RC4_40_MD5 (0x0003)
            Compression Methods Length: 1
            Compression Methods (1 method)

Additionally, as explained 

This is demonstrated with openssl (and easily reproducible with UW imapd), but maybe we have similar fallback mechanism -> if connection breaks, go back to SSLv23 client hello instead of TLVs2 client hello?

Those posts on the IMAP-UW lists:

http://mailman2.u.washington.edu/pipermail/imap-uw/2005-July/000136.html
http://mailman2.u.washington.edu/pipermail/imap-uw/2005-July/000103.html

explan that IMAP UW server does not accept SSLv23 client hello using STARTTLS method (it does when connecting to the SSL-only port like 993).

Comment 8

[Marcin Cieślak (:saper)]

I think this bug is related to the TLS "intolerant server" logic in 
security/manager/ssl/src/nsNSSIOLayer.cpp, so bug 392743, 412834, 412848 or even 368130.

I think this bug should be reassigned to "[e-mail]" as others are.

Comment 9

[Ludovic Hirlimann [:Usul]]

Nelson should this be duped to one of the bugs mentioned in comment 8 ?

Comment 10

[Nelson Bolyard (seldom reads bugmail)]

There's no record in this bug that any analysis was ever done on the more
detailed log file that the bug's reporter made available in comment 6. 
Neither of the reporter's log files is now available at the URLs given above.
So, all I have to go on here are the excerpts of the first, less detailed,
log, which appear in comment 3 and comment 5.  From those comments, I gather
that the reporter was using STARTTLS with his server, and his client was 
reporting the "security protocol is disabled" error.  If that is a correct 
summary of the reporter's situation, then this bug is a duplicate of 
bug 412848.  If not, then more info is needed.

I think the problem with all the bugs cited in comment 8 above is that 
there appears to be a deadlock between the mail/news developers and the 
PSM developers over whose job it is to fix these bugs.  I think that both
parties need to make code changes to fix these bugs, but as long as they
keep expecting the other to make the changes, these problems will continue 
to stagnate.

Comment 11

[Ludovic Hirlimann [:Usul]]

Gaetan, could you resubmit the log  ? if you still have them

Comment 12

[Gaétan RYCKEBOER]

it seems you went to my server the week it went down.

Tracebacks and logs are still available for bug #460419 :

http://greedo.ryckeboer.org/private/thunderbig-login-tls-imap.log
http://greedo.ryckeboer.org/private/thunderbig-tls-imap.log
http://greedo.ryckeboer.org/private/imap-tls-thunderbig.log

Comment 13

[Ludovic Hirlimann [:Usul]]

(In reply to comment #10)
> There's no record in this bug that any analysis was ever done on the more
> detailed log file that the bug's reporter made available in comment 6. 

Nelson - who should I ping to look into these log files ?

Comment 14

[Wayne Mery (:wsmwk)]

Gaétan, it would be helpful to know if ... you still see this problem?


(In reply to Ludovic Hirlimann [:Usul] from comment #13)
> (In reply to comment #10)
> > There's no record in this bug that any analysis was ever done on the more
> > detailed log file that the bug's reporter made available in comment 6. 
> 
> Nelson - who should I ping to look into these log files ?

Comment 15

[Joshua Cranmer [:jcranmer]]

RESOLVED INCOMPLETE due to lack of response to the previous comment. If you feel this change was made in error, please respond to this bug with your reasons why.