bug#23311: TLS handshake error

[Ludovic Courtès]

Continuing my monologue.  :-)

On the client side (with gnutls-cli), the handshake looks like:

--8<---------------cut here---------------start------------->8---
connect(4, {sa_family=AF_INET, sin_port=htons(443), 
sin_addr=inet_addr("131.159.14.26")}, 16) = 0
writev(4, 
[{"\26\3\1\1\0\1\0\0\374\3\3W\26\244\271\231\376\373\234\244+\253S\314\263\347$\363$[\337\215\360\255'\340\231#R\37]~\344\0\0l\300+\300,\300\206\300\207\300\t\300#\300\n\300$\300r\300s\300\254\300\255\300\10\300/\3000\300\212\300\213\300\23\300'\300\24\300(\300v\300w\300\22\0\234\0\235\300z\300{\0/\0<\0005\0=\0A\0\272\0\204\0\300\300\234\300\235\0\n\0\236\0\237\300|\300}\0003\0g\0009\0k\0E\0\276\0\210\0\304\300\236\300\237\0\26\1\0\0g\0\27\0\0\0\26\0\0\0\5\0\5\1\0\0\0\0\0\0\0\31\0\27\0\0\24mirror.hydra.gnu.org\377\1\0\1\0\0#\0\0\0\n\0\f\0\n\0\27\0\30\0\31\0\25\0\23\0\v\0\2\1\0\0\r\0\26\0\24\4\1\4\3\5\1\5\3\6\1\6\3\3\1\3\3\2\1\2\3",
 261}], 1) = 261
select(5, [4], NULL, NULL, {40, 0})     = 0 (Timeout)
write(2, "*** Fatal error: The operation timed out\n", 41) = 41
--8<---------------cut here---------------end--------------->8---

On the server side (nginx 1.8.1 with OpenSSL 1.0.2f), a successful
handshake looks like this:

--8<---------------cut here---------------start------------->8---
accept4(14, {sa_family=AF_INET, sin_port=htons(52680), 
sin_addr=inet_addr("XX.XX.XX.XX")}, [16], SOCK_NONBLOCK) = 12
epoll_ctl(10, EPOLL_CTL_ADD, 12, {EPOLLIN|EPOLLRDHUP|EPOLLET, {u32=2707653273, 
u64=139997166666393}}) = 0
epoll_wait(10, {{EPOLLIN, {u32=2707653273, u64=139997166666393}}}, 512, 60000) 
= 1
recvfrom(12, "\26", 1, MSG_PEEK, NULL, NULL) = 1
read(12, "\26\3\1\1\0\1\0\0\374\3\3", 11) = 11
read(12, 
"W\26\244\247\331\372\233o\343\210\362{\265'b\343A\240*\212\336jk\330\245\33W\10\311?\33\274\0\0l\300+\300,\300\206\300\207\300\t\300#\300\n\300$\300r\300s\300\254\300\255\300\10\300/\3000\300\212\300\213\300\23\300'\
300\24\300(\300v\300w\300\22\0\234\0\235\300z\300{\0/\0<\0005\0=\0A\0\272\0\204\0\300\300\234\300\235\0\n\0\236\0\237\300|\300}\0003\0g\0009\0k\0E\0\276\0\210\0\304\300\236\300\237\0\26\1\0\0g\0\27\0\0\0\26\0\0\0\5\0\5\1\0\0\0
\0\0\0\0\31\0\27\0\0\24mirror.hydra.gnu.org\377\1\0\1\0\0#\0\0\0\n\0\f\0\n\0\27\0\30\0\31\0\25\0\23\0\v\0\2\1\0\0\r\0\26\0\24\4\1\4\3\5\1\5\3\6\1\6\3\3\1\3\3\2\1\2\3",
 250) = 250
write(12, 
"\26\3\3\0=\2\0\0009\3\3R)\306\6O\365\23\3\210\4\204\331\23\272\225D\vGN:!\234\366\345\244h\347\335\36712\223\0\3000\0\0\21\377\1\0\1\0\0\v\0\4\3\0\1\2\0#\0\0\26\3\3\t\352\v\0\t\346\0\t\343\0\00510\202\5-0\202\4\25\2
40\3\2\1\2\2\22\1#v\v\263\357\2151&\20p\247\346P\30\3778\3710\r\6\t*\206H\206\367\r\1\1\v\5\0000J1\v0\t\6\3U\4\6\23\2US1\0260\24\6\3U\4\n\23\rLet's
 Encrypt1#0!\6\3U\4\3\23\32Let's Encrypt Authority X10\36\27\r160319222600Z\27\
r160617222600Z0\0331\0310\27\6\3U\4\3\23\20hydra.gnunet.org0\202\1\"0\r\6\t*\206H\206\367\r\1\1\1\5\0\3\202\1\17\0000\202\1\n\2\202\1\1\0\333\2259t\\z%p\210\353\233z\331L\253\334\37fo\35xNd\210\215~g\344T~\257\3317\3027\223[~\
304'\252\340m\252\374\226"..., 2956) = 2956

[...]

write(12, 
"\25\3\3\0\32\335t\334'\343\31\347.D\362\22\254c\f4\34\270\226\201\34f\243h\302\354g",
 31) = 31
close(12)                               = 0
--8<---------------cut here---------------end--------------->8---

(Note the 250 + 11 = 261 bytes sent by the client.)

In the faulty case, nginx seems stuck in epoll_wait, not seeing activity
on FD 12, even though the client did send its 261 bytes:

--8<---------------cut here---------------start------------->8---
accept4(14, {sa_family=AF_INET, sin_port=htons(52682), 
sin_addr=inet_addr("XX.XX.XX.XX")}, [16], SOCK_NONBLOCK) = 12
epoll_ctl(10, EPOLL_CTL_ADD, 12, {EPOLLIN|EPOLLRDHUP|EPOLLET, {u32=2707653272, 
u64=139997166666392}}) = 0
epoll_wait(10,  <detached ...>
--8<---------------cut here---------------end--------------->8---

The server is using a relatively old kernel version.

To be continued…

Ludo’.