HTTP/2 libcurl regression

[CkNoSFeRaTU]

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]

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]

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]

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]

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]

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)