Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CURLE_HTTP2 with libcurl multi interface #1967

Closed
baines opened this issue Oct 8, 2017 · 10 comments
Closed

CURLE_HTTP2 with libcurl multi interface #1967

baines opened this issue Oct 8, 2017 · 10 comments
Assignees
@bagder
Labels
HTTP/2

Comments

@baines
Copy link

baines commented Oct 8, 2017 •
edited

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 bagder added the HTTP/2 label Oct 8, 2017
@bagder
Copy link
Member

bagder commented Oct 8, 2017

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
Copy link
Author

baines commented Oct 8, 2017

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
Copy link
Author

baines commented Oct 13, 2017

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.

@bagder bagder self-assigned this Oct 28, 2017
@curl curl deleted a comment from sunjunlishi Mar 8, 2018
@terrywh
Copy link

terrywh commented Mar 15, 2018 •
edited

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
Copy link
Member

bagder commented Mar 18, 2018

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 added a commit that referenced this issue Mar 19, 2018
@bagder
http2: read pending frames (including GOAWAY) in connection-check
e97b3e7 
If a connection has received a GOAWAY frame while not being used, the
function now reads frames off the connection before trying to reuse it
to avoid reusing connections the server has told us not to use.

Reported-by: Alex Baines
Fixes #1967
@bagder bagder mentioned this issue Mar 19, 2018
Closed
@bagder
Copy link
Member

bagder commented Mar 19, 2018

@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.

@bagder bagder closed this as completed in db1b2c7 Mar 21, 2018
@baines
Copy link
Author

baines commented Mar 21, 2018

@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
Copy link
Member

bagder commented Mar 21, 2018

Lovely, thanks for confirming!

@terrywh
Copy link

terrywh commented Mar 22, 2018 •
edited

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

@sunilvirus
Copy link

I can also vouch. I was facing the same issue and now I tested with the latest libcurl and it is gone now. Thanks for the fix.

@dustymabe dustymabe mentioned this issue May 1, 2018
Closed
@lock lock bot locked as resolved and limited conversation to collaborators Jul 16, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@bagder bagder

Labels
HTTP/2
Milestone
No milestone
Development

No branches or pull requests
4 participants
@bagder @sunilvirus @terrywh @baines