CURLE_HTTP2 with libcurl multi interface

[baines]

I did this

I'm developing an application that uses libcurl's multi interface (source code here) and am experiencing outbound PUT messages reproducibly failing with the error CURLE_HTTP2, and the data not being sent. The error buffer for the sending easy handle is empty.

I expected the following

The PUT should complete normally as it does with HTTP/1.1.

More details

To give some context, my application translates the IRC protocol to another http based one (matrix); IRC PRIVMSGs to my application become http PUTs to a server. The problem is reproducable by waiting around ~3 minutes before PRIVMSGing my application. The corresponding PUT to the server will fail with CURLE_HTTP2, but following ones will work fine as long as they are sent without another waiting period.

I did some cursory debugging, and it seems that libcurl's on_stream_close nghttp2 callback is called during the call to nghttp2_session_mem_recv here with an error_code of 8 (CANCEL). libcurl then terminates the stream, and does not make further attempts to send the data.

stack trace:

#0  on_stream_close (session=0x911a00, stream_id=7, error_code=8, userp=0x7dc388) at http2.c:776
#1  0x00007ffff73054cf in ?? () from /usr/lib/x86_64-linux-gnu/libnghttp2.so.14
#2  0x00007ffff7305693 in ?? () from /usr/lib/x86_64-linux-gnu/libnghttp2.so.14
#3  0x00007ffff730a1b8 in nghttp2_session_mem_recv () from /usr/lib/x86_64-linux-gnu/libnghttp2.so.14
#4  0x0000000000473607 in http2_recv (conn=0x7dc388, sockindex=0, mem=0x91eaf8 <incomplete sequence \360\202\202>, len=16384, err=0x7fffffffd3d8) at http2.c:1579
#5  0x000000000043b7cd in Curl_read (conn=0x7dc388, sockfd=15, buf=0x91eaf8 <incomplete sequence \360\202\202>, sizerequested=16384, n=0x7fffffffd468) at sendf.c:733
#6  0x00000000004546ac in readwrite_data (data=0x992658, conn=0x7dc388, k=0x992718, didwhat=0x7fffffffd4e4, done=0x7fffffffd55a, comeback=0x7fffffffd55b) at transfer.c:473
#7  0x0000000000455ba8 in Curl_readwrite (conn=0x7dc388, data=0x992658, done=0x7fffffffd55a, comeback=0x7fffffffd55b) at transfer.c:1139
#8  0x00000000004207ae in multi_runsingle (multi=0x6f3418, now=..., data=0x992658) at multi.c:1895
#9  0x0000000000421e43 in multi_socket (multi=0x6f3418, checkall=false, s=-1, ev_bitmask=1, running_handles=0x7fffffffd754) at multi.c:2651
#10 0x0000000000422691 in curl_multi_socket_action (multi=0x6f3418, s=-1, ev_bitmask=1, running_handles=0x7fffffffd754) at multi.c:2758
#11 0x000000000040b84c in net_update (emask=1, s=0x0) at src/net.c:145
#12 0x000000000040ef3d in epoll_dispatch (e=0x7fffffffdd60) at src/main.c:74
#13 0x000000000040f380 in main (argc=1, argv=0x7fffffffdec8) at src/main.c:179

I have also recorded a log of libcurl's verbose output (with DEBUGBUILD set) from the start of my application to when the problem occurs here.

libcurl version, operating system, etc

OS: Linux 4.4.0 x86_64
libcurl version: 7.56.0
protocol: http2
nghttp2 version: 1.7.1-1 / 0x010701
libcurl configuration:

  curl version:     7.56.0
  Host setup:       x86_64-pc-linux-gnu
  Install prefix:   /usr/local
  Compiler:         gcc
  SSL support:      enabled (OpenSSL)
  SSH support:      no      (--with-libssh2)
  zlib support:     enabled
  GSS-API support:  no      (--with-gssapi)
  TLS-SRP support:  enabled
  resolver:         POSIX threaded
  IPv6 support:     enabled
  Unix sockets support: enabled
  IDN support:      no      (--with-{libidn2,winidn})
  Build libcurl:    Shared=yes, Static=yes
  Built-in manual:  enabled
  --libcurl option: enabled (--disable-libcurl-option)
  Verbose errors:   enabled (--disable-verbose)
  SSPI support:     no      (--enable-sspi)
  ca cert bundle:   /etc/ssl/certs/ca-certificates.crt
  ca cert path:     no
  ca fallback:      no
  LDAP support:     enabled (OpenLDAP)
  LDAPS support:    enabled
  RTSP support:     enabled
  RTMP support:     enabled (librtmp)
  metalink support: no      (--with-libmetalink)
  PSL support:      no      (libpsl not found)
  HTTP2 support:    enabled (nghttp2)
  Protocols:        DICT FILE FTP FTPS GOPHER HTTP HTTPS IMAP IMAPS LDAP LDAPS POP3 POP3S RTMP RTSP SMB SMBS SMTP SMTPS TELNET TFTP

curl -V output

curl 7.56.0 (x86_64-pc-linux-gnu) libcurl/7.56.0 OpenSSL/1.0.2g zlib/1.2.8 nghttp2/1.7.1 librtmp/2.3
Release-Date: 2017-10-04
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp smb smbs smtp smtps telnet tftp 
Features: AsynchDNS Debug TrackMemory IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy 

[bagder]

That's a very old nghttp2 version, have you tried a more recent version to at least see if the bug is still there or not? With HTTP/2 problems it isn't always easy to say if the problem is in lbcurl or in nghttp2 without looking very closely.

[baines]

I just built curl against nghttp2 1.26.0 and get the same behaviour: Start my program, send a message immediately, wait 3-4 mins, send another and it will seemingly always fail with CURLE_HTTP2.

This did fill in the ??s in the stack trace though:

#0  on_stream_close (session=0x90fb40, stream_id=7, error_code=8, userp=0x7d14d8) at http2.c:776
#1  0x00007ffff7301f72 in nghttp2_session_close_stream (session=session@entry=0x90fb40, stream_id=7, error_code=error_code@entry=8) at nghttp2_session.c:1169
#2  0x00007ffff7302143 in session_close_stream_on_goaway (session=0x90fb40, last_stream_id=<optimised out>, incoming=<optimised out>) at nghttp2_session.c:2426
#3  0x00007ffff7307c14 in session_process_goaway_frame (session=0x90fb40) at nghttp2_session.c:4692
#4  nghttp2_session_mem_recv (session=0x90fb40, in=0x935489 "\256\021[etc]", inlen=17) at nghttp2_session.c:6210
#5  0x00000000004736be in http2_recv (conn=0x7d14d8, sockindex=0, mem=0x7e01f8 "\210\002\204\366\377\177", len=16384, err=0x7fffffffd3d8) at http2.c:1579
#6  0x000000000043b8fd in Curl_read (conn=0x7d14d8, sockfd=15, buf=0x7e01f8 "\210\002\204\366\377\177", sizerequested=16384, n=0x7fffffffd468) at sendf.c:733
#7  0x00000000004547dc in readwrite_data (data=0x7d7388, conn=0x7d14d8, k=0x7d7448, didwhat=0x7fffffffd4e4, done=0x7fffffffd55a, comeback=0x7fffffffd55b) at transfer.c:473
#8  0x0000000000455cd8 in Curl_readwrite (conn=0x7d14d8, data=0x7d7388, done=0x7fffffffd55a, comeback=0x7fffffffd55b) at transfer.c:1139
#9  0x00000000004208de in multi_runsingle (multi=0x6f3418, now=..., data=0x7d7388) at multi.c:1895
#10 0x0000000000421f73 in multi_socket (multi=0x6f3418, checkall=false, s=-1, ev_bitmask=1, running_handles=0x7fffffffd754) at multi.c:2651
#11 0x00000000004227c1 in curl_multi_socket_action (multi=0x6f3418, s=-1, ev_bitmask=1, running_handles=0x7fffffffd754) at multi.c:2758
#12 0x000000000040b97c in net_update (emask=1, s=0x0) at src/net.c:145
#13 0x000000000040f06d in epoll_dispatch (e=0x7fffffffdd60) at src/main.c:74
#14 0x000000000040f4b0 in main (argc=1, argv=0x7fffffffdec8) at src/main.c:179

[baines]

I was able to create a much smaller test case that exhibits the same problem available here. It just makes two GET requests to wikipedia over http/2 with a 3½ minute wait between them. The second one always seems to fail with CURLE_HTTP2.

[terrywh]

we encounter something:

by setting "http2_max_requests 1;" in nginx and using libcurl (multi handle + libuv) and it gives the error Failure when receiving data from the peer (almost) every time (every 10 ~ 15 request there will be a success).

(nginx 1.12.2 curl 7.58.0/7.59.0 nghttp2 1.29).

with the same version, using curl cmd, everyting is fine.

By capture tcp packet we see that the data has finished transfering and follow by "Encrypted Alert" and FIN from server.

so i guess that it has something to do with connection reusing inside multi handle. hopes this help.

[bagder]

In the "smaller test case", the server sends a GOAWAY after the stream has been inactive for 180 seconds.

The message doesn't seem to be handled by curl correctly (which should find the goaway, close the existing connection and create a new one for the next transfer) but instead it appears as if it still reuses the original connection and sends a HEADERS on it, to which the server responds with by sending a TCP RST ...

[bagder]

@baines: I'm sorry its taken me ages to get around to work on this, but at least I now have a first take on a fix (in #2402). It does fix the "simplified" test case you made. It would be lovely if you could perhaps take it for a spin in your original use case you had to make sure it actually is the same issue/fix.

@terrywh: that sounds like a different error than this. Please file a new issue and please provide source code for us to reproduce this, or give us every imaginable detail you can think of.

[baines]

@bagder I re-tested my original program with @miblodelcarpio (who originally let me know it was failing occasionally due to this), and we're pretty sure it's fixed now, thanks!

[bagder]

Lovely, thanks for confirming!

[terrywh]

@bagder i file another issue at #2416 and be using a small example code to reproduce the similar sitiation.