cargo-binstall icon indicating copy to clipboard operation
cargo-binstall copied to clipboard

`cargo-binstall` takes a lot of time to resolve package: Reqwest error: builder error: failed to parse header value

Open simonsan opened this issue 1 year ago • 28 comments

Currently, installing updates via cargo-update takes much longer due to cargo-binstall involved. I know, that I can use the -r cargo flag to circumvent cargo-binstall. I get this weird error, though, which seems related to the time taken.

Updating cargo-udeps
 INFO resolve: Resolving package: 'cargo-udeps'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher QuickInstall: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN The package cargo-udeps v0.1.42 will be installed from source (with cargo)
...
 INFO Cargo finished successfully
 INFO Done in 435.0226976s

Overall, it takes now >3-7 minutes to install each update (where it has been 30 seconds before), due to cargo-binstall blocking the process. I think it would be also nice to integrate more deeply with cargo-update then, so cargo-binstall can fetch in parallel all needed binaries while installation is happening (e.g. for a crate that doesn't have binaries already built).

Regarding the issue up there, how can I help diagnosing the problem?

simonsan avatar Aug 27 '23 14:08 simonsan

  • You can try passing a GITHUB_TOKEN if you have one, it will speedup resolution a lot
  • Try upgrading to the latest binstall.
  • You said it takes only 30s then suddenly bumps to minutes, did you upgrade binstall or is there any change to your network configure
  • try --log-level debug which would give you debug messages

NobodyXu avatar Aug 27 '23 21:08 NobodyXu

This is my Justfile task:

# Update Rust stuff
update-rust:
	rustup self update
	rustup update
	$env:GITHUB_TOKEN = Invoke-Expression "gh auth token"
	cargo +nightly install-update -ag
  • the so GITHUB_TOKEN is set,
  • I have the latest binstall,
  • normal compilation takes 30s, when run with cargo +nightly install-update -r cargo -ag so circumventing binstall, else (with binstall it takes several minutes per crate)
  • how do I pass --log-level debug to my install-update command, do you happen to know?

simonsan avatar Aug 27 '23 22:08 simonsan

You can pass via env: LOG_LEVEL=debug, binstall supports that.

NobodyXu avatar Aug 27 '23 23:08 NobodyXu

Running it with LOG_LEVEL=debug on Win 11 shows still the same output as above. 🤷🏽

simonsan avatar Aug 28 '23 00:08 simonsan

Sorry it should be BINSTALL_LOG_LEVEL

NobodyXu avatar Aug 28 '23 01:08 NobodyXu

Attached the logfile. Doesn't seem anything unnatural in there, just that it takes super long to actually gets to checking for the different releases with their extension. Alone to that stage it takes around a minute.

binstall.log

simonsan avatar Aug 28 '23 02:08 simonsan

I've read the debug log and cargo-binstall is using github API as intended.

I noticed that you are installing cargo-audit, which is probably why it's taking so long.

cargo-audit is stored in a repository with multiple subcrates (cargo-binstall looks at its url in Cargo.toml and discover this), so cargo-binstall would check for extra release names (cargo-audit/{ version }, cargo-audit/v{ version } in additional to { version }, v{ version }).

I'm not sure how it would be this slow though, tried installing cargo-audit with latest cargo-binstall locally (on a relatively good network) and it only takes 1.6s

NobodyXu avatar Aug 28 '23 03:08 NobodyXu

It's not only this slow for cargo-audit, though. I can't think of any crates in the past that worked for me, so I think it might be something with my system. I even thought about some DNS issue or so (using a PiHole here).

simonsan avatar Aug 28 '23 09:08 simonsan

It's not only this slow for cargo-audit, though. I can't think of any crates in the past that worked for me, so I think it might be something with my system. I even thought about some DNS issue or so (using a PiHole here).

One thing to note is that cargo-binstall recently enables QUIC since v1.2.0, so you can test v1.1.2 and v1.2.0 and see if there's a significant difference.

NobodyXu avatar Aug 28 '23 09:08 NobodyXu

Just tried, doesn't make a difference. That's weird.

simonsan avatar Aug 28 '23 11:08 simonsan

@simonsan Do you remember which is the last version that can install your package within seconds? Or could it be a network problem?

NobodyXu avatar Aug 28 '23 11:08 NobodyXu

@simonsan Do you remember which is the last version that can install your package within seconds? Or could it be a network problem?

NobodyXu avatar Aug 28 '23 11:08 NobodyXu

@simonsan Do you remember which is the last version that can install your package within seconds? Or could it be a network problem?

NobodyXu avatar Aug 28 '23 11:08 NobodyXu

@simonsan Do you remember which is the last version that can install your package within seconds? Or could it be a network problem?

NobodyXu avatar Aug 28 '23 11:08 NobodyXu

Sorry I have a network issue here

NobodyXu avatar Aug 28 '23 11:08 NobodyXu

I think this may have to do with having the GitHub CLI (gh) installed and authenticated. I installed it recently, authenticated it, and binstall stopped being able to communicate with the GitHub API with the same errors as above. After uninstalling gh binstall worked again. I'm on Fedora 38 using Fedora's gh package. Perhaps it is setting GITHUB_TOKEN weirdly? Or some other environment variable? I'm not sure which environment variables binstall reads.

k9withabone avatar Aug 29 '23 15:08 k9withabone

I think this may have to do with having the GitHub CLI (gh) installed and authenticated. I installed it recently, authenticated it, and binstall stopped being able to communicate with the GitHub API with the same errors as above. After uninstalling gh binstall worked again. I'm on Fedora 38 using Fedora's gh package. Perhaps it is setting GITHUB_TOKEN weirdly? Or some other environment variable? I'm not sure which environment variables binstall reads.

https://github.com/cargo-bins/cargo-binstall/blob/88702011c6e059ddffd976389f83539e390a8ac1/crates/bin/src/args.rs#L544

We use gh-token for obtaining gh token, it recently adds ability to fetch gh secret token, so that might be the reason:

https://github.com/dtolnay/star-history/blob/970911e1d2ca79fb90fbb438ee29f85f347e019b/gh-token/src/lib.rs#L165

NobodyXu avatar Aug 29 '23 21:08 NobodyXu

I use gh cli in my env and got same issue. As a workaround I use --no-discover-github-token option.

GNQG % pwsh : ~ [11:29:47]
$ cargo binstall cargo-binstall --force
 INFO resolve: Resolving package: 'cargo-binstall'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher QuickInstall: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN resolve: Error while checking fetcher invalid url: Failed to render template: Context: 'GraphQL API', err: 'Remote Error: Reqwest error: builder error: failed to parse header value'
 WARN The package cargo-binstall v1.3.0 will be installed from source (with cargo)
Do you wish to continue? yes/[no]
? 
GNQG % pwsh : ~ [11:30:00]
$ cargo binstall cargo-binstall --force --no-discover-github-token
 INFO resolve: Resolving package: 'cargo-binstall'
 WARN The package cargo-binstall v1.3.0 will be downloaded from github.com
 INFO This will install the following binaries:
 INFO   - cargo-binstall.exe (cargo-binstall.exe -> C:\Users\GNQG\.xdg-dirs\data\cargo\bin\cargo-binstall.exe)
Do you wish to continue? yes/[no]
? 

GNQG avatar Aug 30 '23 02:08 GNQG

I finally spotted the issue here:

 Reqwest error: builder error: failed to parse header value

I will need to investigate this

NobodyXu avatar Aug 30 '23 02:08 NobodyXu

It's true, it works for me as well with the --no-discover-github-token flag, but it's still not very fast I would say:

PS C:\Users\dailyuse> cargo binstall cargo-binstall --force --no-discover-github-token
 INFO resolve: Resolving package: 'cargo-binstall'
 WARN The package cargo-binstall v1.3.0 will be downloaded from github.com
 INFO This will install the following binaries:
 INFO   - cargo-binstall.exe (cargo-binstall.exe -> C:\Users\dailyuse\.cargo\bin\cargo-binstall.exe)
Do you wish to continue? yes/[no]
? yes
 INFO Installing binaries...
 WARN Attempting at atomic rename failed: Access is denied. (os error 5), fallback to other methods.
 INFO Done in 180.1663572s

3 Minutes, where it would take 30 seconds to install from source, kind of.

simonsan avatar Aug 30 '23 11:08 simonsan

The error comes from here, it's from the reqwest builder.

NobodyXu avatar Aug 31 '23 06:08 NobodyXu

gh-token recently adds token_from_cli in https://github.com/dtolnay/star-history/pull/23 , which I suspects might be the culprit

cc @simonsan @GNQG can you please try running

gh auth token

and see if it provides valid ASCII (ASCII-only, not utf-8)?

Also cc @CAD97

NobodyXu avatar Aug 31 '23 06:08 NobodyXu

Also @GNQG what is your target triple?

I'd like to invest on why it installs from source instead of using our pre-built artifacts.

NobodyXu avatar Aug 31 '23 06:08 NobodyXu

I use x86_64-pc-windows-msvc. In my env gn auth token shows gho_***** style ASCII only token. Additionally I tested token_from_cli in local and got Some("gho_*****\n").

GNQG avatar Aug 31 '23 10:08 GNQG

reqwest's HeaderValue does not accept \n, so that's why the error occurs.

I will remove gh-token as a dependency and instead run gh auth token directly in cargo-binstall.

Thank you @GNQG !

NobodyXu avatar Aug 31 '23 11:08 NobodyXu

Ah, gh-token should probably be doing a trim. But generally I'd agree that running gh auth token directly is a reasonable choice.

CAD97 avatar Sep 03 '23 17:09 CAD97

Has this been tested without a gh token? As of Monday (so just after the latest release) we are seeing failures in calls to cargo binstall that run in e.g. docker without gh cli. The download fails, so binstall falls back to building but the docker canisters don't have the necessary target architecture. We are still debugging and would really like to get the binary downloads working again.

bitdivine avatar Sep 19 '23 09:09 bitdivine

@bitdivine Can you provide the output from cargo-binstall, with --log-level debug? I have the feeling it might have something to do with #1364

NobodyXu avatar Sep 19 '23 12:09 NobodyXu