auracle fail with libcurl 8.7.1

[eworm-de]

I did this

I pushed curl 8.7.1-1 to the Arch Linux testing repository earlier today. Turns out we have a regression with an AUR helper application auracle, that links against libcurl. Sadly output is little to no useful only:

% auracle clone st
error: UNKNOWN: 

Running git bisect I was pointed at 463472a being the first bad commit.

Investigating the code I landed in src/aur/aur.cc line 468 where msg is assigned, and msg->data.result some lines below is 23, which is CURLE_WRITE_ERROR. With curl 8.6.0 the result was 0 or CURLE_OK.

From the commit message it is not obvious to me if the public api is supposed to change - I guess no. (Everything else should require a soname bump anyway.) So not sure what to blame here... Also possible that the api was misused and worked by chance only.

I expected the following

The application should continue to work as expected, downloading its content with libcurl.

curl/libcurl version

% pacman -Q curl
curl 8.7.1-1

% curl --version
curl 8.7.1 (x86_64-pc-linux-gnu) libcurl/8.7.1 OpenSSL/3.2.1 zlib/1.3.1 brotli/1.1.0 zstd/1.5.5 libidn2/2.3.7 libpsl/0.21.2 libssh2/1.11.0 nghttp2/1.60.0 nghttp3/1.2.0
Release-Date: 2024-03-27
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTP3 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM PSL SPNEGO SSL threadsafe TLS-SRP UnixSockets zstd

operating system

Arch Linux with testing repositories enabled

[eworm-de]

CC @inglor

[eworm-de]

CC @icing (for commit authorship)

[icing]

Browsing the auracle sources, I do not see how exactly the changed write handling can lead to a CURLE_WRITE_ERROR. The callback in auracle is quite simple and never returns an error.

I think we need an auracle debug handler that emits more of curls messages in order to find out what is going wrong here. Any chances of giving that a try, @inglor?

[eworm-de]

Oh, auracle reads an environment variable AURACLE_DEBUG. Does that give any clues?

% AURACLE_DEBUG=1 auracle clone st
* Host aur.archlinux.org:443 was resolved.
* IPv6: 2a01:4f9:c010:50::1
* IPv4: 95.216.144.15
*   Trying 95.216.144.15:443...
* Connected to aur.archlinux.org (95.216.144.15) port 443
* ALPN: curl offers h2,http/1.1
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / x25519 / RSASSA-PSS
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=aur.archlinux.org
*  start date: Mar 11 22:47:13 2024 GMT
*  expire date: Jun  9 22:47:12 2024 GMT
*  subjectAltName: host "aur.archlinux.org" matched cert's "aur.archlinux.org"
*  issuer: C=US; O=Let's Encrypt; CN=R3
*  SSL certificate verify ok.
*   Certificate level 0: Public key type RSA (4096/152 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 1: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 2: Public key type RSA (4096/152 Bits/secBits), signed using sha256WithRSAEncryption
* using HTTP/2
* [HTTP/2] [1] OPENED stream for https://aur.archlinux.org/rpc?v=5&type=info&arg[]=st
* [HTTP/2] [1] [:method: GET]
* [HTTP/2] [1] [:scheme: https]
* [HTTP/2] [1] [:authority: aur.archlinux.org]
* [HTTP/2] [1] [:path: /rpc?v=5&type=info&arg[]=st]
* [HTTP/2] [1] [user-agent: Auracle/0]
* [HTTP/2] [1] [accept: */*]
* [HTTP/2] [1] [accept-encoding: deflate, gzip, br, zstd]
> GET /rpc?v=5&type=info&arg[]=st HTTP/2
Host: aur.archlinux.org
User-Agent: Auracle/0
Accept: */*
Accept-Encoding: deflate, gzip, br, zstd

* Request completely sent off
* old SSL session ID is stale, removing
< HTTP/2 200 
< server: nginx
< date: Wed, 27 Mar 2024 20:43:01 GMT
< content-type: application/json
< strict-transport-security: max-age=31536000; includeSubdomains; preload
< content-encoding: br
< 
* Connection #0 to host aur.archlinux.org left intact
error: UNKNOWN: 

The same with curl 8.6.0:

% AURACLE_DEBUG=1 auracle clone st
* Host aur.archlinux.org:443 was resolved.
* IPv6: 2a01:4f9:c010:50::1
* IPv4: 95.216.144.15
*   Trying 95.216.144.15:443...
* Connected to aur.archlinux.org (95.216.144.15) port 443
* ALPN: curl offers h2,http/1.1
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / x25519 / RSASSA-PSS
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=aur.archlinux.org
*  start date: Mar 11 22:47:13 2024 GMT
*  expire date: Jun  9 22:47:12 2024 GMT
*  subjectAltName: host "aur.archlinux.org" matched cert's "aur.archlinux.org"
*  issuer: C=US; O=Let's Encrypt; CN=R3
*  SSL certificate verify ok.
*   Certificate level 0: Public key type RSA (4096/152 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 1: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 2: Public key type RSA (4096/152 Bits/secBits), signed using sha256WithRSAEncryption
* using HTTP/2
* [HTTP/2] [1] OPENED stream for https://aur.archlinux.org/rpc?v=5&type=info&arg[]=st
* [HTTP/2] [1] [:method: GET]
* [HTTP/2] [1] [:scheme: https]
* [HTTP/2] [1] [:authority: aur.archlinux.org]
* [HTTP/2] [1] [:path: /rpc?v=5&type=info&arg[]=st]
* [HTTP/2] [1] [user-agent: Auracle/0]
* [HTTP/2] [1] [accept: */*]
* [HTTP/2] [1] [accept-encoding: deflate, gzip, br, zstd]
> GET /rpc?v=5&type=info&arg[]=st HTTP/2
Host: aur.archlinux.org
User-Agent: Auracle/0
Accept: */*
Accept-Encoding: deflate, gzip, br, zstd

* old SSL session ID is stale, removing
< HTTP/2 200 
< server: nginx
< date: Wed, 27 Mar 2024 20:44:41 GMT
< content-type: application/json
< strict-transport-security: max-age=31536000; includeSubdomains; preload
< content-encoding: br
< 
* Connection #0 to host aur.archlinux.org left intact
clone complete: /home/user/st

[dfandrich]

I can reproduce what's likely the same issue with this command: docker run --rm curlimages/curl -v --compressed 'https://aur.archlinux.org/rpc?v=5&type=info&arg' which results in curl: (23) Failed writing received data to disk/application The key is the addition of --compressed which results in Brotli being negotiated and used.

[dfandrich]

Could you test that theory by modifying the auracle source to comment out the CURLOPT_ACCEPT_ENCODING option setting and/or replacing the empty string "" that's it's likely being set to with "gzip" or another method?

[eworm-de]

Confirmed to work:

% AURACLE_DEBUG=1 auracle/build/auracle clone st
* Host aur.archlinux.org:443 was resolved.
* IPv6: 2a01:4f9:c010:50::1
* IPv4: 95.216.144.15
*   Trying 95.216.144.15:443...
* Connected to aur.archlinux.org (95.216.144.15) port 443
* ALPN: curl offers h2,http/1.1
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / x25519 / RSASSA-PSS
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=aur.archlinux.org
*  start date: Mar 11 22:47:13 2024 GMT
*  expire date: Jun  9 22:47:12 2024 GMT
*  subjectAltName: host "aur.archlinux.org" matched cert's "aur.archlinux.org"
*  issuer: C=US; O=Let's Encrypt; CN=R3
*  SSL certificate verify ok.
*   Certificate level 0: Public key type RSA (4096/152 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 1: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 2: Public key type RSA (4096/152 Bits/secBits), signed using sha256WithRSAEncryption
* using HTTP/2
* [HTTP/2] [1] OPENED stream for https://aur.archlinux.org/rpc?v=5&type=info&arg[]=st
* [HTTP/2] [1] [:method: GET]
* [HTTP/2] [1] [:scheme: https]
* [HTTP/2] [1] [:authority: aur.archlinux.org]
* [HTTP/2] [1] [:path: /rpc?v=5&type=info&arg[]=st]
* [HTTP/2] [1] [user-agent: Auracle/0]
* [HTTP/2] [1] [accept: */*]
> GET /rpc?v=5&type=info&arg[]=st HTTP/2
Host: aur.archlinux.org
User-Agent: Auracle/0
Accept: */*

* Request completely sent off
* old SSL session ID is stale, removing
< HTTP/2 200 
< server: nginx
< date: Wed, 27 Mar 2024 23:45:00 GMT
< content-type: application/json
< content-length: 532
< strict-transport-security: max-age=31536000; includeSubdomains; preload
< 
* Connection #0 to host aur.archlinux.org left intact
update complete: /home/user/st

[dfandrich]

I've also confirmed that adding -H 'Accept-Encoding: zstd' or -H 'Accept-Encoding: gzip' alongside --compressed also fixes the problem. The last commit to touch Brotli directly was d7b6ce6 but that code doesn't show this problem.

[dfandrich]

I was able to bisect the problem to this commit: commit 463472a (HEAD, refs/bisect/bad) Author: Stefan Eissing ***@***.***> Date: Wed Feb 7 12:05:05 2024 +0100 lib: move client writer into own source Refactoring of the client writer that passes the data to the client/application's callback functions. - split out into own source cw-out.[ch] from sendf.c - move tempwrite and tempcount from data->state into the context of the client writer - redesign the 3 tempwrite dynbufs as a linked list of dynbufs. On paused transfers, this allows to "record" interleaved HEADER/BODY chunks to be "played back" in the same order on unpausing. - keep the overall size limit of all buffered data to DYN_PAUSE_BUFFER. On exceeding that, return CURLE_TOO_LARGE instead of CURLE_OUT_OF_MEMORY as before. - add method to be called when a transfer is DONE to allow writing of any data still buffered - when paused, record HEADER writes exactly as they come for later playback. HEADERs are documented to be written one-by-one. Closes #12898

[eworm-de]

I was able to bisect the problem to this commit: commit 463472a

I had bisected already, see initial post. But we came to the same conclusion. 👍

[dfandrich]

I missed that line completely! At least it's confirmed…

[eworm-de]

Yes, definitely no wasted time. I had thought about doing another git bisect myself, just to be sure I did not mess up. After all it is not obvious why the commit could have influence to the observed behavior - more like the contrary.

[eworm-de]

It's this CURLE_WRITE_ERROR being passed through:

curl/lib/content_encoding.c

Line 676 in c77bdf1

return CURLE_WRITE_ERROR; /* Stream already ended. */

Wondering if this is correct... Is an ended stream a write error here? I guess no.