HTTP/2 final frames not processed on server disconnect

[jay]

I did this

(This is from #1013. While investigating that issue this one was uncovered, but I do not believe they are related.)

Attempted to POST multipart chunked data via HTTP/2 to an amazon server that immediately returns a 403 and then attempts a clean disconnect. The 403 and its body do not appear to always be returned to the client, they are lost somewhere. Instead either an SSL_read or SSL_write error is returned:

== Info: SSL read: error:00000000:lib(0):func(0):reason(0), errno 10053

OR:

== Info: SSL_write() returned SYSCALL, errno = 10053

This isn't 100% reproducible, it seems to be timing dependent. Sometimes the body and response are returned.

Wireshark

When things go wrong it looks like:

client       server
------       ------
SETTINGS  ->
HEADERS   ->              (This is the POST)
         <-  SETTINGS
         <-  HEADERS      (This is the 403)

OR:

client       server
------       ------
SETTINGS  ->
         <-  SETTINGS
HEADERS   ->              (This is the POST)
         <-  HEADERS      (This is the 403)

And then in either case:

client       server
------       ------
         <-  DATA         (This is the 403 body)
         <-  DATA         (empty)
         <-  GOAWAY       (NO_ERROR)

At this point the server sends close-notify and FIN/ACK. The client however goes on to send SETTINGS and in some cases DATA before an RST from the server:

client       server
------       ------
SETTINGS  ->

OR:

client       server
------       ------
SETTINGS  ->
DATA      ->              (This is the start of POST body)

Also

I'm not sure if this is a libcurl or nghttp2 issue. I've built with enable-debug mode in both nghttp2 and libcurl and neither output shows that server header and data have been received. To confirm I changed on_frame_recv in libcurl http2.c to output the frame name each time it's called and the only output from that is one SETTINGS frame (the first one).

Reproduce and data files

http2_final_frames_not_processed.zip

capture_anon.keys      <--- ssl keys for capture
capture_anon.pcapng    <--- packet capture of demo
demo_code_modified.c   <--- this was run to create the capture
output.txt             <--- the console debug output from demo
sample.wav             <--- the file that demo attempts to upload

To view the packet capture load the file then load the keys:
Edit > Preferences > Protocols > SSL > Master-Secret log

To reproduce build the demo code and make sure it loads libcurl from curl-7_50_3-6-ge01d0f1 2016-09-16 or later. Or better, to auto decrypt in Wireshark you can use instead the branch I made from there and I adapted @Lekensteyn's sslkeylog and it will dump encryption keys if you use libcurl w/openssl and set environment variable SSLKEYLOGFILE. You will also need to set that path as the master-secret log (see above). master...jay:openssl_dump_secrets (Side note: it would be helpful if something like his code eventually made it in to libcurl)

It is easy for me to reproduce in Windows but difficult in Linux. In Linux it seems very dependent on the amount of data that is sent. The test case attempts to post a 64KB file sound.wav. You may need to increase the size of the file to reproduce. And if you decrease the size to something like 2 bytes the server response should be much more likely to be returned.

I expected the following

For the server's response to be returned in all cases.

curl/libcurl version and operating system

Win 7 x64 Enterprise:

curl-7_50_3-6-ge01d0f1 2016-09-16
curl 7.51.0-DEV (i386-pc-win32) libcurl/7.51.0-DEV OpenSSL/1.0.2h nghttp2/1.14.1
Protocols: dict file ftp ftps gopher http https imap imaps ldap pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: Debug Largefile NTLM SSL HTTP2

Ubuntu 16 x64 LTS:

curl-7_50_3-6-ge01d0f1 2016-09-16
curl 7.51.0-DEV (x86_64-pc-linux-gnu) libcurl/7.51.0-DEV OpenSSL/1.0.2h zlib/1.2.8 libidn/1.32 nghttp2/1.14.1 librtmp/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp smb smbs smtp smtps telnet tftp 
Features: IDN IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets 

/cc @tatsuhiro-t

[tatsuhiro-t]

I played around with demo_code_modified.c, and reproduced the issues several times.

From debug logging, it looks like curl failed to send DATA frame. I saw this logging message:

curl/lib/http2.c

Line 275 in 45c1c54

failf(conn->data, "Failed sending HTTP2 data");

And somehow curl tried to send more frames. This is probably the bug: we should return -1 here

curl/lib/http2.c

Line 1528 in 45c1c54

return 0;

If we fixed the above line of code, then the client now did not send more frames, but it still did not fully receive HEADERS, and DATA from remote server.
I checked incoming bytes, and found that client received first 14 bytes of HEADERS frame. This is the same packet you captured. For some reason, amazon returns HEADERS in 2 TLS record (which is not good for performance reason, but this is not what we care about here). Then client tried to send frames and failed. The failure code from OpenSSL is "SSL_write() returned SYSCALL, errno = 104" or "SSL_write() returned SYSCALL, errno = 32". I did strace as well, and it gave me "write(4,...) = -1 EPIPE (Broken pipe)". That means "connection reset by peer". From the packet capture, RST packet from remote server is well after GOAWAY frames, and not after HEADERS. So it confused me.
Perhaps, TCP stack already knew that socket was closed, and refused to send anything? TCP stack may receive packets asynchronously anyway.

[bagder]

Is this problem perhaps happening less easy now since commit 475c258?

[jay]

Is this problem perhaps happening less easy now since commit 475c258?

No, it's still reproducible. I appreciate Tatsuhiro's analysis as always. I tried returning -1 where he said but I still don't see the headers returned. This is discussed above, and what lib is at fault if any I don't know. This is just a time consuming issue and I've focused on other things instead.

[bagder]

I'm looking into this issue now as I want to go over all our currently open http2 bugs. I can't reproduce the bug mentioned using the attached code. @jay, can you take a quick look and see if you can or if you can alter it slightly to trigger it again? If not, I think we'll need to close this until we see it happen again.

The -1 return code mentioned by @tatsuhiro-t seems spot on and I noticed another such case in the same function that I also want to address, even if they don't actually fix the problem as the comments above say.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.