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

[Ian Zimmerman]

>> itz at ahiker:~$ gnutls-cli --port 25 -d 5 --starttls localhost |<2>|
>> ASSERT: gnutls_psk.c:101 Resolving 'localhost'...  Connecting to
>> '127.0.0.1:25'...
>> 
>> - Simple Client Mode:
>> 
>> 220 ahiker.homeip.net ESMTP Exim 4.62 Wed, 26 Jul 2006 22:08:04 -0400
>> 

Ian> It hangs here, have to hit ^C,

Marc> You need to manually say STARTTLS, and then hit Ctrl-D to switch
Marc> the client to TLS mode.

Okay, now gnutls-cli seems to work; immediately after, I try to connect
with openssl, still same error.

itz at madbat:~$ gnutls-cli --port 587  -d 5 --starttls localhost
|<2>| ASSERT: gnutls_psk.c:101
Resolving 'localhost'...
Connecting to '127.0.0.1:587'...

- Simple Client Mode:

220 madbat.mine.nu ESMTP Exim 4.62 Fri, 28 Jul 2006 00:05:49 -0400
EHLO localhost
250-madbat.mine.nu Hello localhost [127.0.0.1]
250-SIZE 10240000
250-PIPELINING
250-STARTTLS
250 HELP
STARTTLS
220 TLS go ahead
*** Starting TLS handshake
|<3>| HSK[80714a8]: Keeping ciphersuite: DHE_RSA_AES_256_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: DHE_RSA_AES_128_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: DHE_RSA_3DES_EDE_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: DHE_DSS_AES_256_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: DHE_DSS_AES_128_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: DHE_DSS_3DES_EDE_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: DHE_DSS_ARCFOUR_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: RSA_AES_256_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: RSA_AES_128_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: RSA_3DES_EDE_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: RSA_ARCFOUR_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: RSA_ARCFOUR_MD5
|<3>| HSK[80714a8]: Keeping ciphersuite: SRP_SHA_RSA_AES_256_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: SRP_SHA_RSA_AES_128_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: SRP_SHA_RSA_3DES_EDE_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: SRP_SHA_DSS_AES_256_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: SRP_SHA_DSS_AES_128_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: SRP_SHA_DSS_3DES_EDE_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: SRP_SHA_AES_256_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: SRP_SHA_AES_128_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: SRP_SHA_3DES_EDE_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: PSK_SHA_AES_256_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: PSK_SHA_AES_128_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: PSK_SHA_3DES_EDE_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: PSK_SHA_ARCFOUR_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: RSA_EXPORT_ARCFOUR_40_MD5
|<3>| HSK[80714a8]: Keeping ciphersuite: ANON_DH_AES_256_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: ANON_DH_AES_128_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: ANON_DH_3DES_EDE_CBC_SHA1
|<3>| HSK[80714a8]: Keeping ciphersuite: ANON_DH_ARCFOUR_MD5
|<2>| EXT[80714a8]: Sending extension CERT_TYPE
|<2>| EXT[80714a8]: Sending extension SERVER_NAME
|<3>| HSK[80714a8]: CLIENT HELLO was send [131 bytes]
|<4>| REC[80714a8]: Sending Packet[0] Handshake(22) with length: 131
|<4>| REC[80714a8]: Sent Packet[1] Handshake(22) with length: 136
|<4>| REC[80714a8]: Expected Packet[0] Handshake(22) with length: 1
|<4>| REC[80714a8]: Received Packet[0] Handshake(22) with length: 74
|<4>| REC[80714a8]: Decrypted Packet[0] Handshake(22) with length: 74
|<3>| HSK[80714a8]: SERVER HELLO was received [74 bytes]
|<3>| HSK[80714a8]: Server's version: 3.1
|<3>| HSK[80714a8]: SessionID length: 32
|<3>| HSK[80714a8]: SessionID: c4f6780c4d2527abc8cc041d00a257f0dcc0a33573ed9a8eb65a7cb5c4b22717
|<3>| HSK[80714a8]: Selected cipher suite: DHE_RSA_AES_256_CBC_SHA1
|<2>| ASSERT: gnutls_extensions.c:153
|<4>| REC[80714a8]: Expected Packet[1] Handshake(22) with length: 1
|<4>| REC[80714a8]: Received Packet[1] Handshake(22) with length: 687
|<4>| REC[80714a8]: Decrypted Packet[1] Handshake(22) with length: 687
|<3>| HSK[80714a8]: CERTIFICATE was received [687 bytes]
|<4>| REC[80714a8]: Expected Packet[2] Handshake(22) with length: 1
|<4>| REC[80714a8]: Received Packet[2] Handshake(22) with length: 333
|<4>| REC[80714a8]: Decrypted Packet[2] Handshake(22) with length: 333
|<3>| HSK[80714a8]: SERVER KEY EXCHANGE was received [333 bytes]
|<4>| REC[80714a8]: Expected Packet[3] Handshake(22) with length: 1
|<4>| REC[80714a8]: Received Packet[3] Handshake(22) with length: 14187
|<4>| REC[80714a8]: Decrypted Packet[3] Handshake(22) with length: 14187
|<3>| HSK[80714a8]: CERTIFICATE REQUEST was received [14187 bytes]
- Successfully sent 0 certificate(s) to server.
|<4>| REC[80714a8]: Expected Packet[4] Handshake(22) with length: 1
|<4>| REC[80714a8]: Received Packet[4] Handshake(22) with length: 4
|<4>| REC[80714a8]: Decrypted Packet[4] Handshake(22) with length: 4
|<3>| HSK[80714a8]: SERVER HELLO DONE was received [4 bytes]
|<3>| HSK[80714a8]: CERTIFICATE was send [7 bytes]
|<4>| REC[80714a8]: Sending Packet[1] Handshake(22) with length: 7
|<4>| REC[80714a8]: Sent Packet[2] Handshake(22) with length: 12
|<3>| HSK[80714a8]: CLIENT KEY EXCHANGE was send [102 bytes]
|<4>| REC[80714a8]: Sending Packet[2] Handshake(22) with length: 102
|<4>| REC[80714a8]: Sent Packet[3] Handshake(22) with length: 107
|<3>| REC[80714a8]: Sent ChangeCipherSpec
|<4>| REC[80714a8]: Sending Packet[3] Change Cipher Spec(20) with length: 1
|<4>| REC[80714a8]: Sent Packet[4] Change Cipher Spec(20) with length: 6
|<3>| HSK[80714a8]: Cipher Suite: DHE_RSA_AES_256_CBC_SHA1
|<3>| HSK[80714a8]: Initializing internal [write] cipher sessions
|<3>| HSK[80714a8]: FINISHED was send [16 bytes]
|<4>| REC[80714a8]: Sending Packet[0] Handshake(22) with length: 16
|<4>| REC[80714a8]: Sent Packet[1] Handshake(22) with length: 229
|<4>| REC[80714a8]: Expected Packet[5] Change Cipher Spec(20) with length: 1
|<4>| REC[80714a8]: Received Packet[5] Change Cipher Spec(20) with length: 1
|<4>| REC[80714a8]: ChangeCipherSpec Packet was received
|<3>| HSK[80714a8]: Cipher Suite: DHE_RSA_AES_256_CBC_SHA1
|<3>| HSK[80714a8]: Initializing internal [read] cipher sessions
|<4>| REC[80714a8]: Expected Packet[0] Handshake(22) with length: 1
|<4>| REC[80714a8]: Received Packet[0] Handshake(22) with length: 80
|<4>| REC[80714a8]: Decrypted Packet[0] Handshake(22) with length: 16
|<3>| HSK[80714a8]: 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 does NOT match 'localhost'.
 # valid since: Wed Jul 26 00:09:36 EDT 2006
 # expires at: Fri Aug 25 00:09:36 EDT 2006
 # fingerprint: 7F:68:15:10:FC:23:79:17:0E:37:10:C1:DA:4B:D2:32
 # Subject's DN: C=??,ST=Nostate,L=Nocity,O=Internet Widgits Pty Ltd,CN=madbat.mine.nu,EMAIL=itz at madbat.mine.nu
 # Issuer's DN: C=??,ST=Nostate,L=Nocity,O=Internet Widgits Pty Ltd,CN=madbat.mine.nu,EMAIL=itz at madbat.mine.nu

|<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
QUIT
|<4>| REC[80714a8]: Sending Packet[1] Application Data(23) with length: 5
|<4>| REC[80714a8]: Sent Packet[2] Application Data(23) with length: 229
|<4>| REC[80714a8]: Expected Packet[1] Application Data(23) with length: 4096
|<4>| REC[80714a8]: Received Packet[1] Application Data(23) with length: 128
|<4>| REC[80714a8]: Decrypted Packet[1] Application Data(23) with length: 39
221 madbat.mine.nu closing connection
|<4>| REC[80714a8]: Expected Packet[2] Application Data(23) with length: 4096
|<4>| REC[80714a8]: Received Packet[2] Alert(21) with length: 48
|<4>| REC[80714a8]: Decrypted Packet[2] Alert(21) with length: 2
|<4>| REC[80714a8]: Alert[1|0] - Close notify - was received
- Peer has closed the GNUTLS connection
itz at madbat:~$ openssl s_client -connect localhost:587 -starttls smtp
CONNECTED(00000003)
32522:error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol:s23_clnt.c:567:


-- 
A true pessimist won't be discouraged by a little success.