Bug#348046: exim4-daemon-heavy: TLS delivery attempts fail with: (gnutls_handshake): A TLS packet with unexpected length was received.

Wed Aug 9 16:42:54 UTC 2006

I am seeing this bug with exim version 4.62-4.

To me, it happens with Thunderbird and Mozilla MUAs (on different 
computers).  It does not happen all the time.  If the MUA fails sending 
the message, a repeat attempt will eventually succeed.

I tried connecting manually with:
gnutls-cli --port 25 -d 5 --starttls mail.mclemente.net
and it worked four times in a row. I attach a debug output of gnutls-cli.

Entropy available?  How do I know?
cat /proc/sys/kernel/random/entropy_avail
gives me a number.  But how do I know what the number was when I get the 
error?

I don't know how to reliably reproduce this error, but let me know if I 
can help debug the problem.

Marc (marc at mclemente.net)
-------------- next part --------------
mc-laptop:~> gnutls-cli --port 25 -d 5 --starttls mail.mclemente.net
|<2>| ASSERT: gnutls_psk.c:101
Resolving 'mail.mclemente.net'...
Connecting to '24.182.131.218:25'...

- Simple Client Mode:

220 mail.mclemente.net ESMTP Exim 4.62 Wed, 09 Aug 2006 10:57:54 -0500
ehlo mclemente.net
250-mail.mclemente.net Hello 24-178-49-83.static.stls.mo.charter.com [24.178.49.83]
250-SIZE 52428800
250-PIPELINING
250-AUTH CRAM-MD5
250-STARTTLS
250 HELP
starttls
220 TLS go ahead
*** Starting TLS handshake
|<3>| HSK[8071bc0]: Keeping ciphersuite: DHE_RSA_AES_256_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: DHE_RSA_AES_128_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: DHE_RSA_3DES_EDE_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: DHE_DSS_AES_256_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: DHE_DSS_AES_128_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: DHE_DSS_3DES_EDE_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: DHE_DSS_ARCFOUR_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: RSA_AES_256_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: RSA_AES_128_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: RSA_3DES_EDE_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: RSA_ARCFOUR_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: RSA_ARCFOUR_MD5
|<3>| HSK[8071bc0]: Keeping ciphersuite: SRP_SHA_RSA_AES_256_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: SRP_SHA_RSA_AES_128_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: SRP_SHA_RSA_3DES_EDE_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: SRP_SHA_DSS_AES_256_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: SRP_SHA_DSS_AES_128_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: SRP_SHA_DSS_3DES_EDE_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: SRP_SHA_AES_256_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: SRP_SHA_AES_128_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: SRP_SHA_3DES_EDE_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: PSK_SHA_AES_256_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: PSK_SHA_AES_128_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: PSK_SHA_3DES_EDE_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: PSK_SHA_ARCFOUR_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: RSA_EXPORT_ARCFOUR_40_MD5
|<3>| HSK[8071bc0]: Keeping ciphersuite: ANON_DH_AES_256_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: ANON_DH_AES_128_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: ANON_DH_3DES_EDE_CBC_SHA1
|<3>| HSK[8071bc0]: Keeping ciphersuite: ANON_DH_ARCFOUR_MD5
|<2>| EXT[8071bc0]: Sending extension CERT_TYPE
|<2>| EXT[8071bc0]: Sending extension SERVER_NAME
|<3>| HSK[8071bc0]: CLIENT HELLO was send [140 bytes]
|<4>| REC[8071bc0]: Sending Packet[0] Handshake(22) with length: 140
|<4>| REC[8071bc0]: Sent Packet[1] Handshake(22) with length: 145
|<4>| REC[8071bc0]: Expected Packet[0] Handshake(22) with length: 1
|<4>| REC[8071bc0]: Received Packet[0] Handshake(22) with length: 74
|<4>| REC[8071bc0]: Decrypted Packet[0] Handshake(22) with length: 74
|<3>| HSK[8071bc0]: SERVER HELLO was received [74 bytes]
|<3>| HSK[8071bc0]: Server's version: 3.1
|<3>| HSK[8071bc0]: SessionID length: 32
|<3>| HSK[8071bc0]: SessionID: b371ba8fe867339f14446af7ff2cc71895a9593fbf54c48eac68218600bbaa20
|<3>| HSK[8071bc0]: Selected cipher suite: DHE_RSA_AES_256_CBC_SHA1
|<2>| ASSERT: gnutls_extensions.c:153
|<4>| REC[8071bc0]: Expected Packet[1] Handshake(22) with length: 1
|<4>| REC[8071bc0]: Received Packet[1] Handshake(22) with length: 447
|<4>| REC[8071bc0]: Decrypted Packet[1] Handshake(22) with length: 447
|<3>| HSK[8071bc0]: CERTIFICATE was received [447 bytes]
|<4>| REC[8071bc0]: Expected Packet[2] Handshake(22) with length: 1
|<4>| REC[8071bc0]: Received Packet[2] Handshake(22) with length: 333
|<4>| REC[8071bc0]: Decrypted Packet[2] Handshake(22) with length: 333
|<3>| HSK[8071bc0]: SERVER KEY EXCHANGE was received [333 bytes]
|<4>| REC[8071bc0]: Expected Packet[3] Handshake(22) with length: 1
|<4>| REC[8071bc0]: Received Packet[3] Handshake(22) with length: 14187
|<4>| REC[8071bc0]: Decrypted Packet[3] Handshake(22) with length: 14187
|<3>| HSK[8071bc0]: CERTIFICATE REQUEST was received [14187 bytes]
- Successfully sent 0 certificate(s) to server.
|<4>| REC[8071bc0]: Expected Packet[4] Handshake(22) with length: 1
|<4>| REC[8071bc0]: Received Packet[4] Handshake(22) with length: 4
|<4>| REC[8071bc0]: Decrypted Packet[4] Handshake(22) with length: 4
|<3>| HSK[8071bc0]: SERVER HELLO DONE was received [4 bytes]
|<3>| HSK[8071bc0]: CERTIFICATE was send [7 bytes]
|<4>| REC[8071bc0]: Sending Packet[1] Handshake(22) with length: 7
|<4>| REC[8071bc0]: Sent Packet[2] Handshake(22) with length: 12
|<3>| HSK[8071bc0]: CLIENT KEY EXCHANGE was send [102 bytes]
|<4>| REC[8071bc0]: Sending Packet[2] Handshake(22) with length: 102
|<4>| REC[8071bc0]: Sent Packet[3] Handshake(22) with length: 107
|<3>| REC[8071bc0]: Sent ChangeCipherSpec
|<4>| REC[8071bc0]: Sending Packet[3] Change Cipher Spec(20) with length: 1
|<4>| REC[8071bc0]: Sent Packet[4] Change Cipher Spec(20) with length: 6
|<3>| HSK[8071bc0]: Cipher Suite: DHE_RSA_AES_256_CBC_SHA1
|<3>| HSK[8071bc0]: Initializing internal [write] cipher sessions
|<3>| HSK[8071bc0]: FINISHED was send [16 bytes]
|<4>| REC[8071bc0]: Sending Packet[0] Handshake(22) with length: 16
|<4>| REC[8071bc0]: Sent Packet[1] Handshake(22) with length: 197
|<4>| REC[8071bc0]: Expected Packet[5] Change Cipher Spec(20) with length: 1
|<4>| REC[8071bc0]: Received Packet[5] Change Cipher Spec(20) with length: 1
|<4>| REC[8071bc0]: ChangeCipherSpec Packet was received
|<3>| HSK[8071bc0]: Cipher Suite: DHE_RSA_AES_256_CBC_SHA1
|<3>| HSK[8071bc0]: Initializing internal [read] cipher sessions
|<4>| REC[8071bc0]: Expected Packet[0] Handshake(22) with length: 1
|<4>| REC[8071bc0]: Received Packet[0] Handshake(22) with length: 192
|<4>| REC[8071bc0]: Decrypted Packet[0] Handshake(22) with length: 16
|<3>| HSK[8071bc0]: FINISHED was received [16 bytes]
|<2>| ASSERT: ext_server_name.c:244
- Certificate type: X.509
 - Got a certificate list of 1 certificates.

 - Certificate[0] info:
 # The hostname in the certificate matches 'mail.mclemente.net'.
 # valid since: Fri Jan  6 10:19:37 CST 2006
 # expires at: Mon Jan  5 10:19:37 CST 2009
 # fingerprint: 69:28:FD:31:E0:D8:6C:95:5F:1C:71:74:E2:62:5E:AA
 # Subject's DN: CN=mail.mclemente.net
 # Issuer's DN: CN=mail.mclemente.net

|<2>| ASSERT: verify.c:242
|<2>| ASSERT: verify.c:398

- Peer's certificate issuer is unknown
- Peer's certificate is NOT trusted
- Version: TLS 1.0
- Key Exchange: DHE RSA
- Cipher: AES 256 CBC
- MAC: SHA
- Compression: NULL
mail from:mclemente.net
|<4>| REC[8071bc0]: Sending Packet[1] Application Data(23) with length: 24
|<4>| REC[8071bc0]: Sent Packet[2] Application Data(23) with length: 101
|<4>| REC[8071bc0]: Expected Packet[1] Application Data(23) with length: 4096
|<4>| REC[8071bc0]: Received Packet[1] Application Data(23) with length: 112
|<4>| REC[8071bc0]: Decrypted Packet[1] Application Data(23) with length: 57
501 mclemente.net: sender address must contain a domain
mail from:marc at mclemente.net
|<4>| REC[8071bc0]: Sending Packet[2] Application Data(23) with length: 29
|<4>| REC[8071bc0]: Sent Packet[3] Application Data(23) with length: 229
|<4>| REC[8071bc0]: Expected Packet[2] Application Data(23) with length: 4096
|<4>| REC[8071bc0]: Received Packet[2] Application Data(23) with length: 64
|<4>| REC[8071bc0]: Decrypted Packet[2] Application Data(23) with length: 8
250 OK
rcpt to:marc at mclemente.net
|<4>| REC[8071bc0]: Sending Packet[3] Application Data(23) with length: 27
|<4>| REC[8071bc0]: Sent Packet[4] Application Data(23) with length: 133
|<4>| REC[8071bc0]: Expected Packet[3] Application Data(23) with length: 4096
|<4>| REC[8071bc0]: Received Packet[3] Application Data(23) with length: 192
|<4>| REC[8071bc0]: Decrypted Packet[3] Application Data(23) with length: 14
250 Accepted
data
|<4>| REC[8071bc0]: Sending Packet[4] Application Data(23) with length: 5
|<4>| REC[8071bc0]: Sent Packet[5] Application Data(23) with length: 117
|<4>| REC[8071bc0]: Expected Packet[4] Application Data(23) with length: 4096
|<4>| REC[8071bc0]: Received Packet[4] Application Data(23) with length: 128
|<4>| REC[8071bc0]: Decrypted Packet[4] Application Data(23) with length: 56
354 Enter message, ending with "." on a line by itself
From: marc at mclemente.net
|<4>| REC[8071bc0]: Sending Packet[5] Application Data(23) with length: 25
|<4>| REC[8071bc0]: Sent Packet[6] Application Data(23) with length: 69

|<4>| REC[8071bc0]: Sending Packet[6] Application Data(23) with length: 1
|<4>| REC[8071bc0]: Sent Packet[7] Application Data(23) with length: 101
test4
|<4>| REC[8071bc0]: Sending Packet[7] Application Data(23) with length: 6
|<4>| REC[8071bc0]: Sent Packet[8] Application Data(23) with length: 149
.
|<4>| REC[8071bc0]: Sending Packet[8] Application Data(23) with length: 2
|<4>| REC[8071bc0]: Sent Packet[9] Application Data(23) with length: 213
|<4>| REC[8071bc0]: Expected Packet[5] Application Data(23) with length: 4096
|<4>| REC[8071bc0]: Received Packet[5] Application Data(23) with length: 192
|<4>| REC[8071bc0]: Decrypted Packet[5] Application Data(23) with length: 28
250 OK id=1GAqRy-0000NC-Qm
quit
|<4>| REC[8071bc0]: Sending Packet[9] Application Data(23) with length: 5
|<4>| REC[8071bc0]: Sent Packet[10] Application Data(23) with length: 101
|<4>| REC[8071bc0]: Expected Packet[6] Application Data(23) with length: 4096
|<4>| REC[8071bc0]: Received Packet[6] Application Data(23) with length: 256
|<4>| REC[8071bc0]: Decrypted Packet[6] Application Data(23) with length: 43
221 mail.mclemente.net closing connection
|<4>| REC[8071bc0]: Expected Packet[7] Application Data(23) with length: 4096
|<4>| REC[8071bc0]: Received Packet[7] Alert(21) with length: 224
|<4>| REC[8071bc0]: Decrypted Packet[7] Alert(21) with length: 2
|<4>| REC[8071bc0]: Alert[1|0] - Close notify - was received
- Peer has closed the GNUTLS connection