Bug 2185433 - Regression: OSTree failed to pull remote repository via proxy
Summary: Regression: OSTree failed to pull remote repository via proxy
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: curl
Version: 38
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Kamil Dudka
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2023-04-09 10:12 UTC by Nianqing Yao
Modified: 2023-04-28 02:36 UTC (History)
16 users (show)

Fixed In Version: curl-7.87.0-8.fc38
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2023-04-28 02:36:00 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker FC-805 0 None None None 2023-04-09 10:15:51 UTC

Description Nianqing Yao 2023-04-09 10:12:23 UTC
User-Agent:       Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:111.0) Gecko/20100101 Firefox/111.0
Build Identifier: 

The network part of ostree does not work properly with proxy. When downloading files from remote repository via proxy, ostree always complains that "Timeout was reached". But the relevant file can be fetch with curl via the same proxy. This issue affects both flatpak and rpm-ostree.


Reproducible: Always

Steps to Reproduce:
1. Set up a http proxy
   You can use any proxy server you like. On my machine, this bug can be reproduced with v2ray, clash-meta and tinyproxy. 
   For tinyproxy, I have reproduced this issue with following configure file:

    Port 8888
    Listen 127.0.0.1
    Timeout 6000
    Allow 127.0.0.1

2. Pull repo via this proxy

    cd /tmp
    ostree init --repo myrepository --mode bare-user-only ;

    ostree remote add --repo myrepository flathub https://dl.flathub.org/repo/ ;

    http_proxy="http://127.0.0.1:8888" https_proxy="http://127.0.0.1:8888" \
    ostree --verbose pull --repo myrepository \
    --depth 1 flathub runtime/org.gnome.Sdk/x86_64/43



Actual Results:  
OSTree will fail with output similar to this:
  OT: _ostree_fetcher_should_retry_request: 
  error: 121:0 While fetching https://dl.flathub.org/repo/summary.sig: 
  [28] Timeout was reached, n_retries_remaining: 5
  error: While fetching https://dl.flathub.org/repo/summary.sig: 
  [28] Timeout was reached

But you can fetch the relevant file (https://dl.flathub.org/repo/summary.sig in this example) using curl without this timeout error:
  http_proxy="http://127.0.0.1:8888" https_proxy="http://127.0.0.1:8888" \
  curl -v -L https://dl.flathub.org/repo/summary.sig --output /dev/null


Expected Results:  
OSTree and curl should have consistent result. 

Some software information:

❯ ostree --version
libostree:
 Version: '2023.1'
 Git: 9f2c39c732c4a2221d37f103968480a07f1d37b1
 Features:
  - libcurl
  - libsoup
  - gpgme
  - ex-fsverity
  - libarchive
  - selinux
  - openssl
  - libmount
  - systemd
  - release
  - p2p

❯ curl --version
curl 7.87.0 (x86_64-redhat-linux-gnu) libcurl/7.87.0 OpenSSL/3.0.8 zlib/1.2.13 brotli/1.0.9 libidn2/2.3.4 libpsl/0.21.2 (+libidn2/2.3.4) libssh/0.10.4/openssl/zlib nghttp2/1.52.0
Release-Date: 2022-12-21
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM NTLM_WB PSL SPNEGO SSL threadsafe TLS-SRP UnixSockets

System infomation:

Operating System: Fedora Linux 38
KDE Plasma Version: 5.27.4
KDE Frameworks Version: 5.104.0
Qt Version: 5.15.8
Kernel Version: 6.2.9-300.fc38.x86_64 (64-bit)

Users usually except that proxies works, especially in some enterprise or organization. And this cause that Fedora SilverBlue and Fedora LoT cannot be upgraded via proxy. So I set severity to high.

Comment 1 Joseph Marrero 2023-04-19 20:54:43 UTC
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.

Comment 2 Kamil Dudka 2023-04-19 21:22:05 UTC
Could it be related to this upstream commit, which landed after the 7.87.0 release?
https://github.com/curl/curl/commit/7ad8a7ba9ebdedceafe8859d3bd4d22ee447648d

Comment 3 Joseph Marrero 2023-04-19 22:31:27 UTC
That seems more related to the noproxy code. I am just setting environment variables: 
http_proxy= 
https_proxy=

Comment 4 Kamil Dudka 2023-04-20 06:28:58 UTC
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?

Comment 5 Joseph Marrero 2023-04-20 13:28:25 UTC
I will check our codebase and try to get logs by enabling CURLOPT_VERBOSE in the next few hrs and report back.

Comment 6 Joseph Marrero 2023-04-20 15:57:18 UTC
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.

Comment 7 Joseph Marrero 2023-04-20 16:17:01 UTC
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

Comment 8 Kamil Dudka 2023-04-21 11:02:33 UTC
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

Comment 10 Kamil Dudka 2023-04-21 11:58:10 UTC
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

Comment 11 Joseph Marrero 2023-04-21 12:10:25 UTC
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.

Comment 12 Fedora Update System 2023-04-21 13:13:01 UTC
FEDORA-2023-eec1379708 has been submitted as an update to Fedora 38. https://bodhi.fedoraproject.org/updates/FEDORA-2023-eec1379708

Comment 13 Joseph Marrero 2023-04-21 13:31:51 UTC
@KamilDudka thank you so much for your help and the quick patch, the update looks good on my end.

Comment 14 Kamil Dudka 2023-04-21 13:51:16 UTC
No problem.  Thank you for testing it, Joseph!

Comment 15 Fedora Update System 2023-04-22 01:41:22 UTC
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.

Comment 16 Fedora Update System 2023-04-28 02:36:00 UTC
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.


Note You need to log in before you can comment on or make changes to this bug.