Emacs hangs with concurrent TLS connections

Emacs hangs with concurrent TLS connections

[Lars Magne Ingebrigtsen]

This can be rather tricky to reproduce, but I seem to be able to
reproduce it kinda reliably with the following.

Don't eval it -- it might hang your Emacs completely.  Start a new one
and try it there:

(progn
  (require 'gnutls)
  (url-retrieve "https://www.google.no" #'ignore)
  (url-retrieve "https://www.google.no" #'ignore))

If it doesn't hang your Emacs, try some other URLs, and more of them.
  
Emacs becomes completely unresponsive, and the only thing that can be
done is to kill Emacs.

I get an infinite loop like this:

select(11, [3 4 6 8 9], [], NULL, {0, 19533}) = 1 (in [9], left {0, 19531})
getrusage(RUSAGE_SELF, {ru_utime={6, 424401}, ru_stime={1, 744109}, ...}) = 0
times({tms_utime=642, tms_stime=174, tms_cutime=0, tms_cstime=0}) = 1846926770
getrusage(RUSAGE_SELF, {ru_utime={6, 424401}, ru_stime={1, 744109}, ...}) = 0
times({tms_utime=642, tms_stime=174, tms_cutime=0, tms_cstime=0}) = 1846926770
read(3, 0xda6174, 4096)                 = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}], 2, 0) = 0 (Timeout)
select(11, [3 4 6 8 9], [], NULL, {0, 19388}) = 1 (in [9], left {0, 19386})

where fd 3 is

lrwx------ 1 larsi larsi 64 Nov 28 15:14 3 -> socket:[5510547]

which is

emacs     20504       larsi    3u     IPv4            5510547       0t0        TCP localhost.localdomain:57459->localhost.localdomain:6010 (ESTABLISHED)

which is the ssh-tunnelled X connection.

So something is up when trying to initialise two gnutls connections at
the same time.  Or something.  A race condition?  Some state shared that
shouldn't be shared?  I don't know.

-- 
(domestic pets only, the antidote for overdose, milk.)
  larsi@gnus.org * Lars Magne Ingebrigtsen

Re: Emacs hangs with concurrent TLS connections

[Ted Zlatanov]

On Sun, 28 Nov 2010 15:20:50 +0100 Lars Magne Ingebrigtsen <larsi@gnus.org> wrote: 

LMI> This can be rather tricky to reproduce, but I seem to be able to
LMI> reproduce it kinda reliably with the following.

LMI> Don't eval it -- it might hang your Emacs completely.  Start a new one
LMI> and try it there:

LMI> (progn
LMI>   (require 'gnutls)
LMI>   (url-retrieve "https://www.google.no" #'ignore)
LMI>   (url-retrieve "https://www.google.no" #'ignore))

LMI> If it doesn't hang your Emacs, try some other URLs, and more of them.
  
LMI> Emacs becomes completely unresponsive, and the only thing that can be
LMI> done is to kill Emacs.

LMI> I get an infinite loop like this:

LMI> select(11, [3 4 6 8 9], [], NULL, {0, 19533}) = 1 (in [9], left {0, 19531})
LMI> getrusage(RUSAGE_SELF, {ru_utime={6, 424401}, ru_stime={1, 744109}, ...}) = 0
LMI> times({tms_utime=642, tms_stime=174, tms_cutime=0, tms_cstime=0}) = 1846926770
LMI> getrusage(RUSAGE_SELF, {ru_utime={6, 424401}, ru_stime={1, 744109}, ...}) = 0
LMI> times({tms_utime=642, tms_stime=174, tms_cutime=0, tms_cstime=0}) = 1846926770
LMI> read(3, 0xda6174, 4096)                 = -1 EAGAIN (Resource temporarily unavailable)
LMI> poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}], 2, 0) = 0 (Timeout)
LMI> select(11, [3 4 6 8 9], [], NULL, {0, 19388}) = 1 (in [9], left {0, 19386})

LMI> where fd 3 is

LMI> lrwx------ 1 larsi larsi 64 Nov 28 15:14 3 -> socket:[5510547]

LMI> which is

LMI> emacs     20504       larsi    3u     IPv4            5510547       0t0        TCP localhost.localdomain:57459->localhost.localdomain:6010 (ESTABLISHED)

LMI> which is the ssh-tunnelled X connection.

LMI> So something is up when trying to initialise two gnutls connections at
LMI> the same time.  Or something.  A race condition?  Some state shared that
LMI> shouldn't be shared?  I don't know.

Have you looked at a verbose log with gnutls-log-level set high?

Ted

Re: Emacs hangs with concurrent TLS connections

[Lars Magne Ingebrigtsen]

Ted Zlatanov <tzz@lifelogs.com> writes:

> Have you looked at a verbose log with gnutls-log-level set high?

Good idea.

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

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

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

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

and here it just loops forever.

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

-- 
(domestic pets only, the antidote for overdose, milk.)
  larsi@gnus.org * Lars Magne Ingebrigtsen

Re: Emacs hangs with concurrent TLS connections

[Ted Zlatanov]

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

Re: Emacs hangs with concurrent TLS connections

[Lars Magne Ingebrigtsen]

Ted Zlatanov <tzz@lifelogs.com> writes:

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

Yes, the following reliably still hangs my Emacs hard and forever:

(progn
  (require 'gnutls)
  (url-retrieve "https://www.google.no" #'ignore)
  (url-retrieve "https://www.google.no" #'ignore))

-- 
(domestic pets only, the antidote for overdose, milk.)
  larsi@gnus.org * Lars Magne Ingebrigtsen