Bug 2185433

Nianqing Yao thank you for the great steps to reproduce.

I was able to reproduce the issue. Downgrading to libcurl/curl-7.86.0-4 solves the issue, 
also an upgrade to curl/libcurl-8.0.1-2.fc39.x86_64 works as expected. 

However, the first 7.87 build (7.87.0-1) fails as well as the last two ones (curl-7.87.0-6.fc38 & curl-7.87.0-7.fc38). 
I did not test all of the 7.87 builds but based on those 3 I think all the 7.87 builds will fail.

I got the F38 builds from: https://bodhi.fedoraproject.org/updates/?search=&packages=curl&releases=F38
I got the F39/rawhide builds from: https://bodhi.fedoraproject.org/updates/?search=&packages=curl&releases=F39

@kdudka Is this something you can investigate? Looks like we need a backport of a fix into F38 but we don't see a specific one that is exactly our issue.

Could it be related to this upstream commit, which landed after the 7.87.0 release?
https://github.com/curl/curl/commit/7ad8a7ba9ebdedceafe8859d3bd4d22ee447648d

That seems more related to the noproxy code. I am just setting environment variables: 
http_proxy= 
https_proxy=

Are you sure that ostree directly or indirectly does not use the CURLOPT_NOPROXY option or the NO_PROXY environment variable?

Any chance to get libcurl's verbose output (enabled by CURLOPT_VERBOSE)?

Do you have any idea what happens at libcurl level?

Is the issue that libcurl does not use a proxy when the user expects a proxy to be used?

I will check our codebase and try to get logs by enabling CURLOPT_VERBOSE in the next few hrs and report back.

The only CURLOPT related to proxy I see we use is: CURLOPT_PROXY here:

https://github.com/ostreedev/ostree/blob/main/src/libostree/ostree-fetcher-curl.c#L811

I can't seem to get debug output from libcurl by just setting the CURLOPT_VERBOSE ENV, I am trying to modify our code now to pass the debug value to see if we get anything else.

Here is the output with passing CURLOPT_VERBOSE=1

=======================================================

./ostree --verbose pull --repo /tmp/myrepository     --depth 1 flathub runtime/org.gnome.Sdk/x86_64/43
*   Trying 127.0.0.1:8080...
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
* allocate connect buffer
* Establish HTTP proxy tunnel to dl.flathub.org:443
> CONNECT dl.flathub.org:443 HTTP/1.1
Host: dl.flathub.org:443
User-Agent: libostree/2023.3
Proxy-Connection: Keep-Alive

* Proxy CONNECT aborted due to timeout
* Closing connection 0
OT: _ostree_fetcher_should_retry_request: error: 130:24 While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached, n_retries_remaining: 5
OT: Should retry request (remaining: 5 retries), due to transient error: While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached
* Hostname 127.0.0.1 was found in DNS cache
*   Trying 127.0.0.1:8080...
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#1)
* allocate connect buffer
* Establish HTTP proxy tunnel to dl.flathub.org:443
> CONNECT dl.flathub.org:443 HTTP/1.1
Host: dl.flathub.org:443
User-Agent: libostree/2023.3
Proxy-Connection: Keep-Alive

* Proxy CONNECT aborted due to timeout
* Closing connection 1
OT: _ostree_fetcher_should_retry_request: error: 130:24 While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached, n_retries_remaining: 4
OT: Should retry request (remaining: 4 retries), due to transient error: While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached
*   Trying 127.0.0.1:8080...
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#2)
* allocate connect buffer
* Establish HTTP proxy tunnel to dl.flathub.org:443
> CONNECT dl.flathub.org:443 HTTP/1.1
Host: dl.flathub.org:443
User-Agent: libostree/2023.3
Proxy-Connection: Keep-Alive

* Proxy CONNECT aborted due to timeout
* Closing connection 2
OT: _ostree_fetcher_should_retry_request: error: 130:24 While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached, n_retries_remaining: 3
OT: Should retry request (remaining: 3 retries), due to transient error: While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached
* Hostname 127.0.0.1 was found in DNS cache
*   Trying 127.0.0.1:8080...
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#3)
* allocate connect buffer
* Establish HTTP proxy tunnel to dl.flathub.org:443
> CONNECT dl.flathub.org:443 HTTP/1.1
Host: dl.flathub.org:443
User-Agent: libostree/2023.3
Proxy-Connection: Keep-Alive

* Proxy CONNECT aborted due to timeout
* Closing connection 3
OT: _ostree_fetcher_should_retry_request: error: 130:24 While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached, n_retries_remaining: 2
OT: Should retry request (remaining: 2 retries), due to transient error: While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached
*   Trying 127.0.0.1:8080...
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#4)
* allocate connect buffer
* Establish HTTP proxy tunnel to dl.flathub.org:443
> CONNECT dl.flathub.org:443 HTTP/1.1
Host: dl.flathub.org:443
User-Agent: libostree/2023.3
Proxy-Connection: Keep-Alive

* Proxy CONNECT aborted due to timeout
* Closing connection 4
OT: _ostree_fetcher_should_retry_request: error: 130:24 While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached, n_retries_remaining: 1
OT: Should retry request (remaining: 1 retries), due to transient error: While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached
* Hostname 127.0.0.1 was found in DNS cache
*   Trying 127.0.0.1:8080...
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#5)
* allocate connect buffer
* Establish HTTP proxy tunnel to dl.flathub.org:443
> CONNECT dl.flathub.org:443 HTTP/1.1
Host: dl.flathub.org:443
User-Agent: libostree/2023.3
Proxy-Connection: Keep-Alive

* Proxy CONNECT aborted due to timeout
* Closing connection 5
OT: _ostree_fetcher_should_retry_request: error: 130:24 While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached, n_retries_remaining: 0

error: While fetching https://dl.flathub.org/repo/summary.sig: [28] Timeout was reached

What is the proxy you are trying to connect through?

Are you able to reproduce it with the curl tool?

I tried to connect the server through squid on my f38 VM and it worked just fine:

$ sudo dnf install -y squid
$ sudo systemctl start squid
$ rpm -q {,lib}curl squid
curl-7.87.0-7.fc38.x86_64
libcurl-7.87.0-7.fc38.x86_64
squid-5.8-1.fc38.x86_64

$ http_proxy=http://127.0.0.1:3128 https_proxy=http://127.0.0.1:3128 curl -fsvo/dev/null https://dl.flathub.org/repo/summary.sig
* Uses proxy env variable https_proxy == 'http://127.0.0.1:3128'
*   Trying 127.0.0.1:3128...
* Connected to 127.0.0.1 (127.0.0.1) port 3128 (#0)
* allocate connect buffer
* Establish HTTP proxy tunnel to dl.flathub.org:443
> CONNECT dl.flathub.org:443 HTTP/1.1
> Host: dl.flathub.org:443
> User-Agent: curl/7.87.0
> Proxy-Connection: Keep-Alive
> 
< HTTP/1.1 200 Connection established
< 
* CONNECT phase completed
* CONNECT tunnel established, response 200
* ALPN: offers h2
* ALPN: offers http/1.1
*  CAfile: /etc/pki/tls/certs/ca-bundle.crt
*  CApath: none
* [CONN-0-0][CF-SSL] TLSv1.0 (OUT), TLS header, Certificate Status (22):
} [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Certificate Status (22):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Finished (20):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [19 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [2822 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [264 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Finished (20):
{ [36 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Finished (20):
} [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (OUT), TLS handshake, Finished (20):
} [36 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=dl.flathub.org
*  start date: Aug 30 21:42:18 2022 GMT
*  expire date: Oct  1 21:42:17 2023 GMT
*  subjectAltName: host "dl.flathub.org" matched cert's "dl.flathub.org"
*  issuer: C=BE; O=GlobalSign nv-sa; CN=GlobalSign Atlas R3 DV TLS CA 2022 Q3
*  SSL certificate verify ok.
* Using HTTP2, server supports multiplexing
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
* h2h3 [:method: GET]
* h2h3 [:path: /repo/summary.sig]
* h2h3 [:scheme: https]
* h2h3 [:authority: dl.flathub.org]
* h2h3 [user-agent: curl/7.87.0]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x55b549ac53b0)
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
> GET /repo/summary.sig HTTP/2
> Host: dl.flathub.org
> user-agent: curl/7.87.0
> accept: */*
> 
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [169 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
< HTTP/2 200 
< server: nginx/1.18.0 (Ubuntu)
< content-type: application/octet-stream
< last-modified: Fri, 21 Apr 2023 10:28:53 GMT
< etag: "64426565-250"
< expires: Fri, 21 Apr 2023 11:28:55 GMT
< cache-control: max-age=3600
< backend-name: 3DxooTFj8SlVTdJ0UTX8Jd--F_front_hex2
< accept-ranges: bytes
< date: Fri, 21 Apr 2023 11:00:28 GMT
< via: 1.1 varnish
< age: 1893
< x-served-by: cache-fra-eddf8230107-FRA
< x-cache: HIT
< x-cache-hits: 40
< x-timer: S1682074828.187633,VS0,VE0
< strict-transport-security: max-age=300
< content-length: 592
< 
{ [592 bytes data]
* Connection #0 to host 127.0.0.1 left intact

Sorry for not trying the steps to reproduce sooner.  I do not use ostree myself and thought it would need some extra configuration.

Once I was able to reproduce it locally, it was easy to use git-bisect to find the upstream fix:
https://github.com/curl/curl/commit/728400f875e845f72ee5602edb905f6301ade3e7

Fedora commit:
https://src.fedoraproject.org/rpms/curl/c/7a1d94d30cbb5b05d30659355ea407955b49905b?branch=f38

not a problem at all, I appreciate you willing to jump into a quick meeting and providing the fix so quick. Once we got a koji build I will give this a try and report back.

FEDORA-2023-eec1379708 has been submitted as an update to Fedora 38. https://bodhi.fedoraproject.org/updates/FEDORA-2023-eec1379708

@KamilDudka thank you so much for your help and the quick patch, the update looks good on my end.

No problem.  Thank you for testing it, Joseph!

FEDORA-2023-eec1379708 has been pushed to the Fedora 38 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --refresh --advisory=FEDORA-2023-eec1379708`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2023-eec1379708

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

FEDORA-2023-eec1379708 has been pushed to the Fedora 38 stable repository.
If problem still persists, please make note of it in this bug report.