GNOME Bugzilla – Bug 698203
Socket times out with gnutls3 and some TLS servers
Last modified: 2013-04-22 14:03:31 UTC
The following IMAP conversation over SSL (not using STARTTLS) with Red Hat's Zimbra instance leads to a socket timeout when using GIO: < * OK IMAP4 ready > A001 LOGIN "username" "password" It should reply with: > A001 OK [CAPABILITY ...] LOGIN completed Steps to reproduce: 1. Create a new IMAP/SMTP account from the Online Accounts panel in Settings 2. Set IMAP Server to "mail.corp.redhat.com" 3. Set Encryption to "SSL on a dedicated port" 4. Ignore the warning about the invalid certificate It works with gnutls2/GIO, and gnutls3/gnutls-cli. OpenSSL and NSS work too. These worked for me: - gnutls-cli --no-ca-verification mail.corp.redhat.com -p 993 - openssl s_client -connect mail.corp.redhat.com:99 3 - evolution Here is the backtrace. Thread 6 is where the action is. (gdb) thread apply all bt
+ Trace 231807
Thread 1 (Thread 0x7ffff7f75a40 (LWP 12248))
Here is the console output with GTLS_GNUTLS_DEBUG defined: GTLS: REC[0x1036600]: Allocating epoch #0 GTLS: Note that the security level of the Diffie-Hellman key exchange has been lowered to 256 bits and this may allow decryption of the session data GTLS: ASSERT: gnutls_constate.c:715 GTLS: REC[0x1036600]: Allocating epoch #1 GTLS: HSK[0x1036600]: Keeping ciphersuite: RSA_AES_128_GCM_SHA256 (00.9C) GTLS: HSK[0x1036600]: Keeping ciphersuite: RSA_AES_128_CBC_SHA1 (00.2F) GTLS: HSK[0x1036600]: Keeping ciphersuite: RSA_AES_128_CBC_SHA256 (00.3C) GTLS: HSK[0x1036600]: Keeping ciphersuite: RSA_AES_256_CBC_SHA1 (00.35) GTLS: HSK[0x1036600]: Keeping ciphersuite: RSA_AES_256_CBC_SHA256 (00.3D) GTLS: HSK[0x1036600]: Keeping ciphersuite: RSA_CAMELLIA_128_CBC_SHA1 (00.41) GTLS: HSK[0x1036600]: Keeping ciphersuite: RSA_CAMELLIA_256_CBC_SHA1 (00.84) GTLS: HSK[0x1036600]: Keeping ciphersuite: RSA_3DES_EDE_CBC_SHA1 (00.0A) GTLS: HSK[0x1036600]: Keeping ciphersuite: RSA_ARCFOUR_SHA1 (00.05) GTLS: HSK[0x1036600]: Keeping ciphersuite: RSA_ARCFOUR_MD5 (00.04) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_RSA_AES_128_GCM_SHA256 (00.9E) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_RSA_AES_128_CBC_SHA1 (00.33) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_RSA_AES_128_CBC_SHA256 (00.67) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_RSA_AES_256_CBC_SHA1 (00.39) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_RSA_AES_256_CBC_SHA256 (00.6B) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_RSA_CAMELLIA_128_CBC_SHA1 (00.45) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_RSA_CAMELLIA_256_CBC_SHA1 (00.88) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_RSA_3DES_EDE_CBC_SHA1 (00.16) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_DSS_AES_128_GCM_SHA256 (00.A2) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_DSS_AES_128_CBC_SHA1 (00.32) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_DSS_AES_128_CBC_SHA256 (00.40) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_DSS_AES_256_CBC_SHA1 (00.38) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_DSS_AES_256_CBC_SHA256 (00.6A) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_DSS_CAMELLIA_128_CBC_SHA1 (00.44) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_DSS_CAMELLIA_256_CBC_SHA1 (00.87) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_DSS_3DES_EDE_CBC_SHA1 (00.13) GTLS: HSK[0x1036600]: Keeping ciphersuite: DHE_DSS_ARCFOUR_SHA1 (00.66) GTLS: EXT[0x1036600]: Sending extension STATUS REQUEST (5 bytes) GTLS: EXT[0x1036600]: Sending extension SERVER NAME (25 bytes) GTLS: EXT[0x1036600]: Sending extension SAFE RENEGOTIATION (1 bytes) GTLS: EXT[0x1036600]: Sending extension SESSION TICKET (176 bytes) GTLS: EXT[0x1036600]: sent signature algo (4.1) RSA-SHA256 GTLS: EXT[0x1036600]: sent signature algo (4.2) DSA-SHA256 GTLS: EXT[0x1036600]: sent signature algo (5.1) RSA-SHA384 GTLS: EXT[0x1036600]: sent signature algo (6.1) RSA-SHA512 GTLS: EXT[0x1036600]: sent signature algo (3.1) RSA-SHA224 GTLS: EXT[0x1036600]: sent signature algo (3.2) DSA-SHA224 GTLS: EXT[0x1036600]: sent signature algo (2.1) RSA-SHA1 GTLS: EXT[0x1036600]: sent signature algo (2.2) DSA-SHA1 GTLS: EXT[0x1036600]: Sending extension SIGNATURE ALGORITHMS (18 bytes) GTLS: HSK[0x1036600]: CLIENT HELLO was queued [376 bytes] GTLS: REC[0x1036600]: Preparing Packet Handshake(22) with length: 376 and target length: 376 GTLS: ENC[0x1036600]: cipher: NULL, MAC: MAC-NULL, Epoch: 0 GTLS: REC[0x1036600]: Sent Packet[1] Handshake(22) in epoch 0 and length: 381 GTLS: ASSERT: gnutls_buffers.c:1015 GTLS: REC[0x1036600]: SSL 3.3 Handshake packet received. Epoch 0, length: 81 GTLS: REC[0x1036600]: Expected Packet Handshake(22) GTLS: REC[0x1036600]: Received Packet Handshake(22) with length: 81 GTLS: REC[0x1036600]: Decrypted Packet[0] Handshake(22) with length: 81 GTLS: HSK[0x1036600]: SERVER HELLO (2) was received. Length 77[77], frag offset 0, frag length: 77, sequence: 0 GTLS: HSK[0x1036600]: Server's version: 3.3 GTLS: HSK[0x1036600]: SessionID length: 32 GTLS: HSK[0x1036600]: SessionID: 4bfc2a31fb0c9038a41c23109bc884a01c029ff553db354e51114738fdc72ca3 GTLS: EXT[0x1036600]: Parsing extension 'SAFE RENEGOTIATION/65281' (1 bytes) GTLS: HSK[0x1036600]: Safe renegotiation succeeded GTLS: REC[0x1036600]: SSL 3.3 ChangeCipherSpec packet received. Epoch 0, length: 1 GTLS: REC[0x1036600]: Expected Packet ChangeCipherSpec(20) GTLS: REC[0x1036600]: Received Packet ChangeCipherSpec(20) with length: 1 GTLS: REC[0x1036600]: Decrypted Packet[1] ChangeCipherSpec(20) with length: 1 GTLS: REC[0x1036600]: Initializing epoch #1 GTLS: INT: KEY BLOCK[160]: 5039e150408861a36b2004d8d34333029efe3fd13c98cf05af52b3c064685ab0 GTLS: INT: CLIENT WRITE KEY [32]: 4447437b0e2cf44bd7b39a9e2f2eb0b66cb25902a9df1838af6a7ee09e021523 GTLS: INT: SERVER WRITE KEY [32]: c49ce6ab643e0429a4dfb3cad2344e746ca33acfb8fafb69e09133981f20cc14 GTLS: REC[0x1036600]: Epoch #1 ready GTLS: HSK[0x1036600]: Cipher Suite: DHE_RSA_AES_256_CBC_SHA256 GTLS: ASSERT: gnutls_buffers.c:1015 GTLS: REC[0x1036600]: SSL 3.3 Handshake packet received. Epoch 0, length: 80 GTLS: REC[0x1036600]: Expected Packet Handshake(22) GTLS: REC[0x1036600]: Received Packet Handshake(22) with length: 80 GTLS: REC[0x1036600]: Decrypted Packet[0] Handshake(22) with length: 16 GTLS: HSK[0x1036600]: FINISHED (20) was received. Length 12[12], frag offset 0, frag length: 12, sequence: 0 GTLS: HSK[0x1036600]: recording tls-unique CB (recv) GTLS: REC[0x1036600]: Sent ChangeCipherSpec GTLS: HSK[0x1036600]: Cipher Suite: DHE_RSA_AES_256_CBC_SHA256 GTLS: HSK[0x1036600]: Initializing internal [write] cipher sessions GTLS: HSK[0x1036600]: FINISHED was queued [16 bytes] GTLS: REC[0x1036600]: Preparing Packet ChangeCipherSpec(20) with length: 1 and target length: 1 GTLS: ENC[0x1036600]: cipher: NULL, MAC: MAC-NULL, Epoch: 0 GTLS: REC[0x1036600]: Sent Packet[2] ChangeCipherSpec(20) in epoch 0 and length: 6 GTLS: REC[0x1036600]: Preparing Packet Handshake(22) with length: 16 and target length: 16 GTLS: ENC[0x1036600]: cipher: AES-256-CBC, MAC: SHA256, Epoch: 1 GTLS: REC[0x1036600]: Sent Packet[1] Handshake(22) in epoch 1 and length: 85 GTLS: REC[0x1036600]: Start of epoch cleanup GTLS: REC[0x1036600]: Epoch #0 freed GTLS: REC[0x1036600]: End of epoch cleanup GTLS: ASSERT: common.c:846 GTLS: ASSERT: dn.c:1051 GTLS: ASSERT: common.c:846 GTLS: ASSERT: verify.c:399 GTLS: ASSERT: verify.c:659 (gnome-control-center:28914): GoaBackend-DEBUG: > A001 LOGIN "********************" "********************" GTLS: REC[0x1036600]: Preparing Packet Application Data(23) with length: 42 and target length: 42 GTLS: ENC[0x1036600]: cipher: AES-256-CBC, MAC: SHA256, Epoch: 1 GTLS: REC[0x1036600]: Sent Packet[2] Application Data(23) in epoch 1 and length: 101 GTLS: REC[0x1036600]: SSL 3.3 Application Data packet received. Epoch 0, length: 80 GTLS: REC[0x1036600]: Expected Packet Application Data(23) GTLS: REC[0x1036600]: Received Packet Application Data(23) with length: 80 GTLS: REC[0x1036600]: Decrypted Packet[1] Application Data(23) with length: 18 (gnome-control-center:28914): GoaBackend-DEBUG: < * OK IMAP4 ready GTLS: ASSERT: gnutls_buffers.c:322 GTLS: ASSERT: gnutls_buffers.c:508 GTLS: ASSERT: gnutls_record.c:1008 GTLS: ASSERT: gnutls_record.c:1120 GTLS: ASSERT: gnutls_record.c:1350 16:35:31.373:[28914]:[WARNING]: goa_mail_auth_run() failed: Socket I/O timed out (g-io-error-quark, 24) [goamailclient.c:156, mail_client_check_auth_run_cb()] GTLS: ASSERT: gnutls_buffers.c:610 GTLS: REC: Sending Alert[1|0] - Close notify GTLS: REC[0x1036600]: Preparing Packet Alert(21) with length: 2 and target length: 2 GTLS: ENC[0x1036600]: cipher: AES-256-CBC, MAC: SHA256, Epoch: 1 GTLS: REC[0x1036600]: Sent Packet[3] Alert(21) in epoch 1 and length: 69 GTLS: REC[0x1036600]: Start of epoch cleanup GTLS: REC[0x1036600]: End of epoch cleanup GTLS: REC[0x1036600]: Epoch #1 freed
OK, so, tcpdump shows that when g-o-a connects, the first Application Data record (ie, the encrypted "A001 LOGIN ...") gets sent in the same TCP packet as the final record in the TLS Handshake. (And then the server doesn't send a response.) But when you use gnutls-cli, the last Handshake record and first Application Data record are sent in separate TCP packets. If you set a breakpoint at g_tls_connection_gnutls_push_func() and pause for a second between the last handshake record and the first data record, then everything works. :-O So, this really looks like a bug on the server end, where it ends up losing the first data record if it arrives in the same TCP packet as a handshake record... The simplest hackaround for you would be to fix the code so that it doesn't actually send the LOGIN until it gets the "* OK". Or maybe just g_usleep(1000) or something after handshaking... But you might want to talk to our admins, and/or upstream Zimbra.
Thanks for the detailed analysis. I have implemented the hackaround in both master & gnome-3-8.