On 2012-05-20 at 17:11 +0700, Janne Snabb wrote:
> On 2012-05-20 16:24, Phil Pennock wrote:
> > I find it interesting that ssltap does show the length=4 packet but
> > *not* the length=9 packet which GnuTLS claims it was sent.
>
> Look at the log closer:
*sigh* I wish I hadn't run Thunderbird ;) as polled all my mail in such
a way that it no longer appears "new" and I missed this message until
I'd written to help-gnutls.
> 4011 GnuTLS<4>: REC[0x1213b00]: Sending Packet[1] Handshake(22) with
> length: 455
> 4011 GnuTLS<4>: REC[0x1213b00]: Sent Packet[2] Handshake(22) with
> length: 460
> 4011 GnuTLS<4>: REC[0x1213b00]: Sending Packet[2] Handshake(22) with
> length: 749
> 4011 GnuTLS<4>: REC[0x1213b00]: Sent Packet[3] Handshake(22) with
> length: 754
> 4011 GnuTLS<4>: REC[0x1213b00]: Sending Packet[3] Handshake(22) with
> length: 4
> 4011 GnuTLS<4>: REC[0x1213b00]: Sent Packet[4] Handshake(22) with length: 9
>
> There are actually two lines for each sent packet. The "Sending" line
> and "Sent" line disagree about the packet length consistently with 5.
> Thus there is no packet with length 9 but it is the same packet as the
> packet with length 4. I suppose one of the log messages includes a
> packet header and the other one does not.
Oh crap. I parsed it as "we are sending packet" and "we have been sent
packet". Deoh. Okay, 6am, I *really* need to go get some sleep.
FWIW, I've modified git head so that Exim now checks for a trailing
newline in the message sent from GnuTLS and the output is no longer so
spaced out.
In a *working* session I see:
31728 GnuTLS<4>: REC[0x803193000]: Sending Packet[3] Handshake(22) with length: 4
31728 GnuTLS<4>: REC[0x803193000]: Sent Packet[4] Handshake(22) with length: 9
31728 GnuTLS<4>: REC[0x803193000]: Expected Packet[1] Handshake(22) with length: 1
31728 GnuTLS<4>: REC[0x803193000]: Received Packet[1] Handshake(22) with length: 310
31728 GnuTLS<4>: REC[0x803193000]: Decrypted Packet[1] Handshake(22) with length: 310
31728 GnuTLS<3>: HSK[0x803193000]: CLIENT KEY EXCHANGE was received [310 bytes]
So where a working session logs "Expected Packet", the broken sessions
log:
29792 GnuTLS<2>: ASSERT: gnutls_buffers.c:640
29792 GnuTLS<2>: ASSERT: gnutls_record.c:969
29792 GnuTLS<2>: ASSERT: gnutls_handshake.c:3054
> I looked the handshake using Wireshark, it seems to be able to decode it
> well. It shows something interesting: It is the client (NSS) who closes
> the TCP connection right after receiving the "Server Hello" from
> Exim/GnuTLS. It looks like NSS is *receiving* something that it does not
> like. It would be good to figure out how to get some debug output from
> NSS...
Since ssltap never sees the data, those GnuTLS assertions must be
resulting from a torn-down session, and so Exim's subsequent regular log
of session closed by EOF is not EOF by client after TLS abort, but the
EOF triggered the ASSERT failures.
Woot! Checked out origin/gnutls_2_12_x in my git clone of GnuTLS, and
check gnutls_buffers.c and I see:
if (ret == 0)
{ /* EOF */
gnutls_assert ();
return 0;
}
That could do with something more graceful, so that the application can
find out what really happened. We log:
(gnutls_handshake): A TLS packet with unexpected length was received.
so the "unexpected length" is gnutls_strerror(), even though
<gnutls/gnutls.h> says:
#define GNUTLS_E_UNEXPECTED_PACKET_LENGTH -9 /* GNUTLS_A_RECORD_OVERFLOW */
I don't see a better error code for peer EOF, but calling EOF a record
overflow is still a little confusing to dumbasses like me.
Okay, is clearly NSS disliking the server_hello_done.
-Phil
