Re: Emacs hangs with concurrent TLS connections

[Ted Zlatanov <tzz@lifelogs.com>]

On Mon, 13 Dec 2010 04:36:18 +0100 Lars Magne Ingebrigtsen <larsi@gnus.org> wrote: 

LMI> Ted Zlatanov <tzz@lifelogs.com> writes:
>> Have you looked at a verbose log with gnutls-log-level set high?

LMI> Good idea.

LMI> It starts off normal with all the tls chatter, and then it ends up
LMI> here... 

LMI> gnutls.c: [9] INT: CLIENT WRITE KEY [16]: 6cecebb7aa1e56ee74f24771b39f996a
LMI> gnutls.c: [9] INT: SERVER WRITE KEY [16]: 70c92720b41a6e281485e907d8a439c9
LMI> gnutls.c: [3] HSK[0x1848300]: Cipher Suite: RSA_ARCFOUR_SHA1
LMI> gnutls.c: [3] HSK[0x1848300]: Initializing internal [write] cipher sessions
LMI> gnutls.c: [6] BUF[HSK]: Peeked 0 bytes of Data
LMI> gnutls.c: [6] BUF[HSK]: Emptied buffer
LMI> gnutls.c: [3] HSK[0x1848300]: FINISHED was send [16 bytes]
LMI> gnutls.c: [6] BUF[HSK]: Peeked 0 bytes of Data
LMI> gnutls.c: [6] BUF[HSK]: Emptied buffer
LMI> gnutls.c: [4] REC[0x1848300]: Sending Packet[0] Handshake(22) with length: 16
LMI> gnutls.c: [7] WRITE: Will write 41 bytes to 0x8.
LMI> gnutls.c: [7] WRITE: wrote 41 bytes to 0x8. Left 0 bytes. Total 41 bytes.
LMI> gnutls.c: [7] 0000 - 16 03 01 00 24 50 ca 9f d8 2c d4 34 33 15 cb 33 
LMI> gnutls.c: [7] 0001 - d7 8a de 9c ab 5c 72 0c 5b b2 4b 5b 74 ce d1 47 
LMI> gnutls.c: [7] 0002 - 1b f9 db 44 d1 57 9d 9c 21 
LMI> gnutls.c: [4] REC[0x1848300]: Sent Packet[1] Handshake(22) with length: 41
LMI> gnutls.c: [7] READ: -1 returned from 0x8, errno=11 gerrno=0
LMI> gnutls.c: [2] ASSERT: gnutls_buffers.c:322
LMI> gnutls.c: [2] ASSERT: gnutls_handshake.c:2525
LMI> gnutls.c: [7] READ: Got 5 bytes from 0x9
LMI> gnutls.c: [7] READ: read 5 bytes from 0x9
LMI> gnutls.c: [7] 0000 - 48 54 54 50 2f 
LMI> gnutls.c: [7] RB: Have 0 bytes into buffer. Adding 5 bytes.
LMI> gnutls.c: [7] RB: Requested 5 bytes
LMI> gnutls.c: [2] ASSERT: gnutls_record.c:507

LMI> I think everything up to here is normal.  And then things go wonky:

LMI> gnutls.c: [4] REC[0x1841540]: Expected Packet[0] Handshake(22) with length: 1
LMI> gnutls.c: [4] REC[0x1841540]: Received Packet[0] Unknown Packet(72) with length: 20527
LMI> gnutls.c: [4] REC[0x1841540]: FATAL ERROR: Received packet with length: 20527
LMI> gnutls.c: [2] ASSERT: gnutls_record.c:960
LMI> gnutls.c: [2] ASSERT: gnutls_buffers.c:1032
LMI> gnutls.c: [2] ASSERT: gnutls_handshake.c:1045
LMI> gnutls.c: [2] ASSERT: gnutls_handshake.c:2364
LMI> gnutls.c: [6] BUF[HSK]: Cleared Data from buffer
LMI> gnutls.c: [2] ASSERT: gnutls_record.c:879
LMI> gnutls.c: [2] ASSERT: gnutls_buffers.c:1032
LMI> gnutls.c: [2] ASSERT: gnutls_handshake.c:1045
LMI> gnutls.c: [2] ASSERT: gnutls_handshake.c:2364
LMI> gnutls.c: [6] BUF[HSK]: Cleared Data from buffer
LMI> gnutls.c: [2] ASSERT: gnutls_record.c:879
LMI> gnutls.c: [2] ASSERT: gnutls_buffers.c:1032
LMI> gnutls.c: [2] ASSERT: gnutls_handshake.c:1045
LMI> gnutls.c: [2] ASSERT: gnutls_handshake.c:2364

LMI> and here it just loops forever.

LMI> Is the wrong socket being asked to handle the TLS data or something?
LMI> Hm...  I don't really know how to proceed to debug this, but it's 100%
LMI> reproducible for me, so if you have any suggestions, I can test it out
LMI> easily enough.

Is this still happening?  I plan to hit GnuTLS support after we've
battled it out with auth-source.

Ted