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.

Sign up for GitHub

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

HTTP/2 libcurl regression #13292

Closed
CkNoSFeRaTU opened this issue Apr 5, 2024 · 5 comments
Closed

HTTP/2 libcurl regression #13292

CkNoSFeRaTU opened this issue Apr 5, 2024 · 5 comments
Labels
HTTP/2 regression

Comments

@CkNoSFeRaTU
Copy link

I did this

ArchLinux's pacman which is using libcurl through libalpm started to timeout on mirror synchronization if this mirror have http/2 enabled. Bisect is pointing to commit 0dc0362.
I also hacked a bit libalpm and here is an output:

== Info: using HTTP/2
== Info: [HTTP/2] [1] OPENED stream for https://mirror.kraski.tv/linux/archlinux/core/os/x86_64/core.db
== Info: [HTTP/2] [1] [:method: GET]
== Info: [HTTP/2] [1] [:scheme: https]
== Info: [HTTP/2] [1] [:authority: mirror.kraski.tv]
== Info: [HTTP/2] [1] [:path: /linux/archlinux/core/os/x86_64/core.db]
== Info: [HTTP/2] [1] [user-agent: pacman/6.1.0 (Linux x86_64) libalpm/14.0.0]
== Info: Connection #0 to host mirror.kraski.tv left intact                                         15.9 KiB  0.00   B/s --:-- [#########--------------------------------------------------------------------]  12%
== Info: Couldn't find host mirror.kraski.tv in the .netrc file; using defaults                    128.4 KiB  4.18 MiB/s 00:00 [#############################################################################] 100%
== Info: Found bundle for host: 0x64c5f2a95bc0 [can multiplex]
== Info: Re-using existing connection with host mirror.kraski.tv
== Info: [HTTP/2] [3] OPENED stream for https://mirror.kraski.tv/linux/archlinux/core/os/x86_64/core.db.sig
== Info: [HTTP/2] [3] [:method: GET]
== Info: [HTTP/2] [3] [:scheme: https]
== Info: [HTTP/2] [3] [:authority: mirror.kraski.tv]
== Info: [HTTP/2] [3] [:path: /linux/archlinux/core/os/x86_64/core.db.sig]
== Info: [HTTP/2] [3] [user-agent: pacman/6.1.0 (Linux x86_64) libalpm/14.0.0]
== Info: [HTTP/2] [3] [accept: */*]
== Info: Exceeded the maximum allowed file size (16384) with 16384 bytes
== Info: process_pending_input: nghttp2_session_mem_recv() returned -902:The user callback function failed
== Info: Connection #0 to host mirror.kraski.tv left intact
 extra
== Info: Couldn't find host mirror.kraski.tv in the .netrc file; using defaults
== Info: Found bundle for host: 0x64c5f2a95bc0 [can multiplex]
== Info: Re-using existing connection with host mirror.kraski.tv
== Info: [HTTP/2] [5] OPENED stream for https://mirror.kraski.tv/linux/archlinux/extra/os/x86_64/extra.db
== Info: [HTTP/2] [5] [:method: GET]
== Info: [HTTP/2] [5] [:scheme: https]
== Info: [HTTP/2] [5] [:authority: mirror.kraski.tv]
== Info: [HTTP/2] [5] [:path: /linux/archlinux/extra/os/x86_64/extra.db]
== Info: [HTTP/2] [5] [user-agent: pacman/6.1.0 (Linux x86_64) libalpm/14.0.0]
== Info: [HTTP/2] [5] [accept: */*]
== Info: Operation too slow. Less than 1 bytes/sec transferred the last 10 seconds
== Info: Closing connection
 extra.db failed to download
error: failed retrieving file 'extra.db' from mirror.kraski.tv : Operation too slow. Less than 1 bytes/sec transferred the last 10 seconds
error: failed to synchronize all databases (download library error)

It seems there is some trouble with client callbacks (according to "nghttp2_session_mem_recv() returned -902:The user callback function failed") when some file is not present on server (core.db.sig in the case above). Which then prevents downloading subsequent files.

I expected the following

Log with build before aformentioned commit:

== Info: using HTTP/2
== Info: [HTTP/2] [1] OPENED stream for https://mirror.kraski.tv/linux/archlinux/core/os/x86_64/core.db
== Info: [HTTP/2] [1] [:method: GET]
== Info: [HTTP/2] [1] [:scheme: https]
== Info: [HTTP/2] [1] [:authority: mirror.kraski.tv]
== Info: [HTTP/2] [1] [:path: /linux/archlinux/core/os/x86_64/core.db]
== Info: [HTTP/2] [1] [user-agent: pacman/6.1.0 (Linux x86_64) libalpm/14.0.0]
== Info: Connection #0 to host mirror.kraski.tv left intact                                          0.0   B  0.00   B/s --:-- [-----------------------------------------------------------------------------]   0%
== Info: Couldn't find host mirror.kraski.tv in the .netrc file; using defaults                    128.4 KiB  4.82 MiB/s 00:00 [#############################################################################] 100%
== Info: Found bundle for host: 0x650a688f0bc0 [can multiplex]
== Info: Re-using existing connection with host mirror.kraski.tv
== Info: [HTTP/2] [3] OPENED stream for https://mirror.kraski.tv/linux/archlinux/core/os/x86_64/core.db.sig
== Info: [HTTP/2] [3] [:method: GET]
== Info: [HTTP/2] [3] [:scheme: https]
== Info: [HTTP/2] [3] [:authority: mirror.kraski.tv]
== Info: [HTTP/2] [3] [:path: /linux/archlinux/core/os/x86_64/core.db.sig]
== Info: [HTTP/2] [3] [user-agent: pacman/6.1.0 (Linux x86_64) libalpm/14.0.0]
== Info: [HTTP/2] [3] [accept: */*]
== Info: Exceeded the maximum allowed file size (16384) with 16384 bytes
== Info: Connection #0 to host mirror.kraski.tv left intact
 extra
== Info: Couldn't find host mirror.kraski.tv in the .netrc file; using defaults
== Info: Found bundle for host: 0x650a688f0bc0 [can multiplex]
== Info: Re-using existing connection with host mirror.kraski.tv
== Info: [HTTP/2] [5] OPENED stream for https://mirror.kraski.tv/linux/archlinux/extra/os/x86_64/extra.db
== Info: [HTTP/2] [5] [:method: GET]
== Info: [HTTP/2] [5] [:scheme: https]
== Info: [HTTP/2] [5] [:authority: mirror.kraski.tv]
== Info: [HTTP/2] [5] [:path: /linux/archlinux/extra/os/x86_64/extra.db]
== Info: [HTTP/2] [5] [user-agent: pacman/6.1.0 (Linux x86_64) libalpm/14.0.0]
== Info: Connection #0 to host mirror.kraski.tv left intact                                         15.9 KiB  0.00   B/s --:-- [-----------------------------------------------------------------------------]   0%
== Info: Couldn't find host mirror.kraski.tv in the .netrc file; using defaults                      8.1 MiB  67.4 MiB/s 00:00 [#############################################################################] 100%
== Info: Found bundle for host: 0x650a688f0bc0 [can multiplex]
== Info: Re-using existing connection with host mirror.kraski.tv
== Info: [HTTP/2] [7] OPENED stream for https://mirror.kraski.tv/linux/archlinux/extra/os/x86_64/extra.db.sig
== Info: [HTTP/2] [7] [:method: GET]
== Info: [HTTP/2] [7] [:scheme: https]
== Info: [HTTP/2] [7] [:authority: mirror.kraski.tv]
== Info: [HTTP/2] [7] [:path: /linux/archlinux/extra/os/x86_64/extra.db.sig]
== Info: [HTTP/2] [7] [user-agent: pacman/6.1.0 (Linux x86_64) libalpm/14.0.0]
== Info: [HTTP/2] [7] [accept: */*]
== Info: Exceeded the maximum allowed file size (16384) with 16384 bytes
== Info: Connection #0 to host mirror.kraski.tv left intact
 multilib
== Info: Couldn't find host mirror.kraski.tv in the .netrc file; using defaults
== Info: Found bundle for host: 0x650a688f0bc0 [can multiplex]
== Info: Re-using existing connection with host mirror.kraski.tv
== Info: [HTTP/2] [9] OPENED stream for https://mirror.kraski.tv/linux/archlinux/multilib/os/x86_64/multilib.db
== Info: [HTTP/2] [9] [:method: GET]
== Info: [HTTP/2] [9] [:scheme: https]
== Info: [HTTP/2] [9] [:authority: mirror.kraski.tv]
== Info: [HTTP/2] [9] [:path: /linux/archlinux/multilib/os/x86_64/multilib.db]
== Info: [HTTP/2] [9] [user-agent: pacman/6.1.0 (Linux x86_64) libalpm/14.0.0]
== Info: Connection #0 to host mirror.kraski.tv left intact                                         15.9 KiB  0.00   B/s --:-- [########---------------------------------------------------------------------]  11%
== Info: Couldn't find host mirror.kraski.tv in the .netrc file; using defaults                    138.8 KiB  33.9 MiB/s 00:00 [#############################################################################] 100%
== Info: Found bundle for host: 0x650a688f0bc0 [can multiplex]
== Info: Re-using existing connection with host mirror.kraski.tv
== Info: [HTTP/2] [11] OPENED stream for https://mirror.kraski.tv/linux/archlinux/multilib/os/x86_64/multilib.db.sig
== Info: [HTTP/2] [11] [:method: GET]
== Info: [HTTP/2] [11] [:scheme: https]
== Info: [HTTP/2] [11] [:authority: mirror.kraski.tv]
== Info: [HTTP/2] [11] [:path: /linux/archlinux/multilib/os/x86_64/multilib.db.sig]
== Info: [HTTP/2] [11] [user-agent: pacman/6.1.0 (Linux x86_64) libalpm/14.0.0]
== Info: [HTTP/2] [11] [accept: */*]
== Info: Exceeded the maximum allowed file size (16384) with 16384 bytes
== Info: Connection #0 to host mirror.kraski.tv left intact

curl/libcurl version

curl 8.7.1 and current master branch

operating system

Archlinux
Linux xxx.xxx.xxx 6.8.1-arch1-1 #1 SMP PREEMPT_DYNAMIC Sat, 16 Mar 2024 17:15:35 +0000 x86_64 GNU/Linux
@icing
Copy link
Contributor

icing commented Apr 5, 2024

I think I have an idea what is going wrong here. Your CURLOPT_WRITEFUNCTION callback returns an error on that resource, right? This seem to lead to a failure in connection processing thereafter...

@CkNoSFeRaTU
Copy link
Author

CkNoSFeRaTU commented Apr 5, 2024 •
edited

It doesn't seem to use CURLOPT_WRITEFUNCTION...
Only CURLOPT_XFERINFOFUNCTION and CURLOPT_HEADERFUNCTION callbacks:
https://gitlab.archlinux.org/pacman/pacman/-/blob/f86c15e7804311df6469e020f07e4bc8b2644bb6/lib/libalpm/dload.c#L379
And CURLOPT_WRITEDATA:
https://gitlab.archlinux.org/pacman/pacman/-/blob/f86c15e7804311df6469e020f07e4bc8b2644bb6/lib/libalpm/dload.c#L805

icing added a commit to icing/curl that referenced this issue Apr 5, 2024
@icing
http2, emit RST when client write fails
d833fe5 
- When the writing of response data fails, reset the stream
  and do not return a callback error to nghttp2. That would
  be a fatal error for the connection and harm other requests.
- add test cases for various abort scenarios
- refs curl#13292
@icing icing mentioned this issue Apr 5, 2024
Closed
@icing
Copy link
Contributor

icing commented Apr 5, 2024

I see. Thanks for the links. I added more tests around this situation. Aborting a transfer from the XFERINFO callback works, but when the writing of the response fails, this brought the connection into a fatal state.

Maybe there was some ulimit on the file or the disk was full? Anyways, I'd be curious if #13298 works for you.

@icing
Copy link
Contributor

icing commented Apr 5, 2024

Another theory is that the target file was closed before the easy handle was shutdown and incoming data tried to write to it. Just an idea.

@CkNoSFeRaTU
Copy link
Author

CkNoSFeRaTU commented Apr 5, 2024 •
edited

Maybe there was some ulimit on the file or the disk was full?

It seems pacman sets 16kb filesize limit for signature files (*.sig) with CURLOPT_MAXFILESIZE_LARGE. But server was responding with 404 error and accompanied error page for these files due to their absence for database files in official distro's repositories. And on this particular server error page exceed 16kb limit almost twice (~29kb) due to embedded base64'd image.

Anyways, I'd be curious if #13298 works for you.

Seems to work and doesn't timeout for subsequent files anymore. In debug info for absent files I have this now:

== Info: Exceeded the maximum allowed file size (16384) with 16384 bytes
== Info: HTTP/2 stream XXX was not closed cleanly: unknown (err 4294966394)

@bagder bagder closed this as completed in 1302aa6 Apr 8, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
HTTP/2 regression
Milestone
No milestone
Development

No branches or pull requests
3 participants
@icing @bagder @CkNoSFeRaTU