Azure artifacts auth fails on first attempt but works on second.

[jenshnielsen]

For example running

uv pip install numpy --verbose

with the following env variables set

UV_INDEX_URL=https://VssSessionToken@pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/
UV_KEYRING_PROVIDER=subprocess

the first time fails but rerunning it again works correctly.

UV version 0.1.38 but has been an issue since support for this type of auth landed in #2976

Redacted log of non working execution

❯ uv pip install numpy --verbose
INFO Found a virtualenv through CONDA_PREFIX at: C:\Users\username\Miniconda3\envs\testuv
DEBUG Probing interpreter info for: \\?\C:\Users\username\Miniconda3\envs\testuv\python.exe
DEBUG Found Python 3.12.3 for: \\?\C:\Users\username\Miniconda3\envs\testuv\python.exe
DEBUG Using Python 3.12.3 environment at C:\Users\username\Miniconda3\envs\testuv\python.exe
DEBUG Trying to lock if free: C:\Users\username\AppData\Local\Temp\uv-53f2e5d017b1b435.lock
TRACE Caching credentials for https://VssSessionToken@pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/
DEBUG Using registry request timeout of 30s
DEBUG Solving with target Python version 3.12.3
DEBUG Adding direct dependency: numpy*
INFO add_decision: root @ 0a0.dev0
TRACE Fetching metadata for numpy from https://VssSessionToken@pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE No cache entry exists for \\?\C:\Users\username\AppData\Local\uv\cache\simple-v7\cf3a2cb28c077ae5\numpy.rkyv
DEBUG No cache entry for: https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE Sending fresh GET request for https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE Handling request for https://VssSessionToken@pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE Request for https://VssSessionToken@pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/ is missing a password, looking for credentials
TRACE No password in cache for realm VssSessionToken@https://pkgs.dev.azure.com
DEBUG Checking keyring for credentials for VssSessionToken@https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE Checking keyring for URL https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
DEBUG Found credentials in keyring for https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE checkout waiting for idle connection: ("https", pkgs.dev.azure.com)
DEBUG starting new connection: https://pkgs.dev.azure.com/
TRACE Http::connect; scheme=Some("https"), host=Some("pkgs.dev.azure.com"), port=None
DEBUG resolving host="pkgs.dev.azure.com"
DEBUG connecting to [2620:1ec:21::20]:443
DEBUG connected to [2620:1ec:21::20]:443
DEBUG No cached session for DnsName("pkgs.dev.azure.com")
DEBUG Not resuming any session
TRACE Sending ClientHello Message {
    ...
}
TRACE We got ServerHello ServerHelloPayload {
    ...
}
DEBUG ALPN protocol is Some(b"http/1.1")
DEBUG Using ciphersuite TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
DEBUG Server supports tickets
DEBUG Server may staple OCSP response
TRACE Server stapled OCSP response is [...]
DEBUG ECDHE curve is EcParameters { curve_type: NamedCurve, named_group: secp384r1 }
TRACE Server cert is CertificateChain([CertificateDer(...)])
DEBUG Server DNS name is DnsName("pkgs.dev.azure.com")
TRACE Unvalidated OCSP response: [...]
TRACE http1 handshake complete, spawning background dispatcher task
TRACE checkout dropped for ("https", pkgs.dev.azure.com)
TRACE put; add idle connection for ("https", pkgs.dev.azure.com)
DEBUG pooling idle connection for ("https", pkgs.dev.azure.com)
DEBUG Sending warning alert CloseNotify
error: HTTP status client error (401 Unauthorized) for url (https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/)

Redacted log of working execution

❯ uv pip install numpy --verbose
INFO Found a virtualenv through CONDA_PREFIX at: C:\Users\username\Miniconda3\envs\testuv
DEBUG Cached interpreter info for Python 3.12.3, skipping probing: C:\Users\username\Miniconda3\envs\testuv\python.exe
DEBUG Using Python 3.12.3 environment at C:\Users\username\Miniconda3\envs\testuv\python.exe

DEBUG Trying to lock if free: C:\Users\username\AppData\Local\Temp\uv-53f2e5d017b1b435.lock
TRACE Caching credentials for https://VssSessionToken@pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/
DEBUG Using registry request timeout of 30s
DEBUG Solving with target Python version 3.12.3
DEBUG Adding direct dependency: numpy*
INFO add_decision: root @ 0a0.dev0
TRACE Fetching metadata for numpy from https://VssSessionToken@pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE No cache entry exists for \\?\C:\Users\username\AppData\Local\uv\cache\simple-v7\cf3a2cb28c077ae5\numpy.rkyv
DEBUG No cache entry for: https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE Sending fresh GET request for https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE Handling request for https://VssSessionToken@pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE Request for https://VssSessionToken@pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/ is missing a password, looking for credentials
TRACE No password in cache for realm VssSessionToken@https://pkgs.dev.azure.com
DEBUG Checking keyring for credentials for VssSessionToken@https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE Checking keyring for URL https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
DEBUG Found credentials in keyring for https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/
TRACE checkout waiting for idle connection: ("https", pkgs.dev.azure.com)
DEBUG starting new connection: https://pkgs.dev.azure.com/
TRACE Http::connect; scheme=Some("https"), host=Some("pkgs.dev.azure.com"), port=None
DEBUG resolving host="pkgs.dev.azure.com"
DEBUG connecting to [2620:1ec:21::20]:443
DEBUG connected to [2620:1ec:21::20]:443
DEBUG No cached session for DnsName("pkgs.dev.azure.com")
DEBUG Not resuming any session
TRACE Sending ClientHello Message {
    ...
}
TRACE We got ServerHello ServerHelloPayload {
    ...
}
DEBUG ALPN protocol is Some(b"http/1.1")
DEBUG Using ciphersuite TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
DEBUG Server supports tickets
DEBUG Server may staple OCSP response
TRACE Server stapled OCSP response is [...]
DEBUG ECDHE curve is EcParameters { curve_type: NamedCurve, named_group: secp384r1 }
TRACE Server cert is CertificateChain([CertificateDer(...)])
DEBUG Server DNS name is DnsName("pkgs.dev.azure.com")
TRACE Unvalidated OCSP response: [...]
TRACE http1 handshake complete, spawning background dispatcher task
TRACE checkout dropped for ("https", pkgs.dev.azure.com)
TRACE Updating cached credentials for https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/ to Credentials { username: Username(Some("VssSessionToken")), password: Some("...") }
TRACE cached request https://pkgs.dev.azure.com/project-name/_packaging/feed-name/pypi/simple/numpy/ is not storable because its response has a 'no-store' cache-control directive
TRACE attempting to decode a frame
TRACE frame decoded from buffer
...

[zanieb]

Thanks for the logs that's super helpful for telling what's going on.

So what changed in #2976 is we use the URL as the service name for keyring before using just the host. Is it possible your keyring backend is returning different credentials in this case?

I don't see anything that could be going wrong on our end in those logs. In both cases, we find credentials in the keyring and use them for the request.

[jenshnielsen]

Thanks @zanieb I don't necessarily think this broke with #2976 but before that PR cannot easily test this since there was no way for me to inject the username. If useful I can manually recompile version 0.1.33 with the hardcoded username changed to match what Azure Artifacts expects.

I would not expect the keyring responsens to be different between the 2 requests but perhaps its possible.

[zanieb]

You could manually call keyring <url> <user> and see if it is idempotent.

I don't necessarily think this broke with #2976 but before that PR cannot easily test this since there was no way for me to inject the username.

Ah thanks for clarifying. I wouldn't bother trying an older version in that case.

[jenshnielsen]

@zanieb Found the problem by adding the credentials to the trace message when the credentials are found.
e.g something like

debug!("Found credentials in keyring for {url} as {credentials:?}");

The issue is that artifacts-keyring (the keyring extension that azure artifacts uses) may print information like:

[Information] [CredentialProvider]VstsCredentialProvider - Acquired bearer token using 'MSAL Silent'\r\r\n[Information] [CredentialProvider]VstsCredentialProvider - Attempting to exchange the bearer token for an Azure DevOps session token.\r\r\n

On the first fetch from keyring. This currently leaks into the credentials which naturally are not valid then.

[charliermarsh]

Oh wow, like that goes to stdout and so we consider them "part of" the credentials?

[jenshnielsen]

@charliermarsh Yes that seems to be the case.

[charliermarsh]

@zanieb - We may want to instead take the last line rather than the full output? \cc @jaraco in case you have advice on the contract that we should respect from the keyring CLI.

[charliermarsh]

Err, wait, it looks like we might be inspecting both stdout and stderr? I'll fix that.

[charliermarsh]

Nevermind, we're only collecting stdout, I misread.

[jenshnielsen]

It does not look like the implementation in pip does anything special https://github.com/pypa/pip/blob/main/src/pip/_internal/network/auth.py#L145 It reads stdout and strips newline.

However, for some reason that I do not understand calling keyring from uv seems to result in a token exchange much more frequently than from pip making this much easier to observe.

[charliermarsh]

Very strange that there's any difference in behavior here then.

[jenshnielsen]

@charliermarsh I am guessing the main reason that this goes relatively unnoticed with pip is that the keyring CLI is only a fallback for the in-process keyring implementation which does not have this issue.

[jenshnielsen]

For reference the issue is likely this code https://github.com/microsoft/artifacts-keyring/blob/master/src/artifacts_keyring/plugin.py#L116-L119 which converts stderr from the .net tool that artifacts-keyring wraps to stdout.

[zanieb]

Nice investigation! Thank you!

I'm not sure we can just read the last line of output, there's nothing guaranteeing the password does not include new lines. We recently discussed this at jaraco/keyring#678 (comment). Frankly this sounds like bad behavior by the Azure Artifacts keyring plugin — we should open an issue requesting that they change it to stream the logs to stderr as appropriate.