[Bug]: dotnet list package --outdated --interactive makes credential provider invalidate cache for every package listed

[ByAgenT]

NuGet Product Used

dotnet.exe

Product Version

NuGet Command Line 5.11.0.10

Worked before?

No response

Impact

It's more difficult to complete my work

Repro Steps & Context

Hello,

I am from Azure Artifacts team.

We received an issue that when dotnet list package --outdated --interactive command is executed against project that set up with Azure Artifacts feed that require auth through Azure Artifacts Credential Provider, NuGet sends "GetAuthenticationCredentials" request to cred provider for every package in the list, and for every next request starting from second package to the same source, NuGet sets request parameter IsRetry: true to cred provider, which is a signal to invalidate credential cache and issue a new PAT and prompt for credentials interactively again. This behavior results in a looped interactive auth prompt instead of respecting cred provider cache. I was able to reproduce issue on both Windows and Ubuntu.

We don't see a good way how we can work around this behavior and fix issue from cred provider side, because if we won't invalidate cache when IsRetry is true, we will introduce complexity to the user to understand when they need to clear NuGet cache manually when credentials are expired in other scenarios.

Steps to reproduce (Ubuntu):

Note: this is best to repro in Unix system, because in Windows you may not be prompted interactively if your machine is AAD joined and you have permissions to access Azure Artifacts feed.

1. Install Azure Artifacts Credential Provider extension
2. Clear NuGet cache for a stable reproduction
3. Restore project with multiple packages sourced from Azure Artifacts feed dotnet restore --interactive
4. Run dotnet list package --outdated --interactive in the same project

Result behavior:

• Cred Provider prompts for auth on every package for the same source

Expected behavior:

• Cred Provider prompts for auth only once for the same source

Attaching logs of calling dotnet list package --outdated --interactive --verbosity detailed for a project with 2 NuGet packages. In the logs you can see that for the first package cred provider receives request with IsRetry: false and returns credentials from the cache successfully, but for the next package from the same source, cred provider receives IsRetry: true which indicated that previous call was unsuccessful and cred provider should invalidate the cache and prompt for credentials again.

Link to the issue in developer community. Let me know if any additional information needed.

Verbose Logs

> dotnet list package --outdated --interactive --verbosity detailed

The following sources were used:
   https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json

debug: Using /home/akovalyov/.nuget/plugins/netcore/CredentialProvider.Microsoft/CredentialProvider.Microsoft.dll as a credential provider plugin.
trace:     [CredentialProvider.095214]Running in plug-in mode
trace:     [CredentialProvider.095214]Command-line v0.1.25+cb125622a8f121aadf3e82f315b06fdb42198585: /home/akovalyov/.nuget/plugins/netcore/CredentialProvider.Microsoft/CredentialProvider.Microsoft.dll -Plugin
trace:     [CredentialProvider.095214]Handling 'Request' 'Initialize'. Time elapsed in ms: 4 - Payload: {"ClientVersion":"5.8.0","Culture":"en","RequestTimeout":"00:00:05"}
trace:     [CredentialProvider.095214]Sending response: 'Request' 'Initialize'. Time elapsed in ms: 4
trace:     [CredentialProvider.095214]Time elapsed in milliseconds after sending response 'Request' 'Initialize': 5
trace:     [CredentialProvider.095214]Handling 'Request' 'GetOperationClaims'. Time elapsed in ms: 0 - Payload: {}
trace:     [CredentialProvider.095214]Sending response: 'Request' 'GetOperationClaims'. Time elapsed in ms: 3
trace:     [CredentialProvider.095214]Time elapsed in milliseconds after sending response 'Request' 'GetOperationClaims': 9
trace:     [CredentialProvider.095214]Handling 'Request' 'SetLogLevel'. Time elapsed in ms: 1 - Payload: {"LogLevel":"Debug"}
trace:     [CredentialProvider]Sending response: 'Request' 'SetLogLevel'. Time elapsed in ms: 2
trace:     [CredentialProvider]Time elapsed in milliseconds after sending response 'Request' 'SetLogLevel': 9
trace:     [CredentialProvider]Handling 'Request' 'GetAuthenticationCredentials'. Time elapsed in ms: 3 - Payload: {"Uri":"https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json","IsRetry":false,"IsNonInteractive":false,"CanShowDialog":false}
trace:     [CredentialProvider]Creating a progress reporter with interval: 00:00:02
trace:     [CredentialProvider]Handling auth request, Uri: https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json, IsRetry: False, IsNonInteractive: False, CanShowDialog: False
trace:     [CredentialProvider]URI: https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]VstsBuildTaskServiceEndpointCredentialProvider - This credential provider must be run under the Team Build tasks for NuGet with external endpoint credentials. Appropriate environment variable needs to be set.
trace:     [CredentialProvider]Skipping NuGetCredentialProvider.CredentialProviders.VstsBuildTaskServiceEndpoint.VstsBuildTaskServiceEndpointCredentialProvider, cannot provide credentials for https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]VstsBuildTaskCredentialProvider - This credential provider must be run under the Team Build tasks for NuGet. Appropriate environment variables must be set.
trace:     [CredentialProvider]Skipping NuGetCredentialProvider.CredentialProviders.VstsBuildTask.VstsBuildTaskCredentialProvider, cannot provide credentials for https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]GET https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]VstsCredentialProvider - Detected a hosted Azure DevOps Service.
trace:     [CredentialProvider]Using NuGetCredentialProvider.CredentialProviders.Vsts.VstsCredentialProvider to try to get credentials for https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json.
trace:     [CredentialProvider]IsRetry: False
trace:     [CredentialProvider]Found cached SessionToken for https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]Sending response: 'Request' 'GetAuthenticationCredentials'. Time elapsed in ms: 389
trace:     [CredentialProvider]Time elapsed in milliseconds after sending response 'Request' 'GetAuthenticationCredentials': 392
  GET https://pkgs.dev.azure.com/<redacted>/_packaging/abfab4ce-6950-4a26-aec5-1d59681b9cfd/nuget/v3/registrations2-semver2/entityframework/index.json
  GET https://pkgs.dev.azure.com/<redacted>/_packaging/abfab4ce-6950-4a26-aec5-1d59681b9cfd/nuget/v3/registrations2-semver2/automapper/index.json
trace:     [CredentialProvider]Handling 'Request' 'GetAuthenticationCredentials'. Time elapsed in ms: 0 - Payload: {"Uri":"https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json","IsRetry":true,"IsNonInteractive":false,"CanShowDialog":false}
trace:     [CredentialProvider]Creating a progress reporter with interval: 00:00:02
trace:     [CredentialProvider]Handling auth request, Uri: https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json, IsRetry: True, IsNonInteractive: False, CanShowDialog: False
trace:     [CredentialProvider]URI: https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]VstsBuildTaskServiceEndpointCredentialProvider - This credential provider must be run under the Team Build tasks for NuGet with external endpoint credentials. Appropriate environment variable needs to be set.
trace:     [CredentialProvider]Skipping NuGetCredentialProvider.CredentialProviders.VstsBuildTaskServiceEndpoint.VstsBuildTaskServiceEndpointCredentialProvider, cannot provide credentials for https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]VstsBuildTaskCredentialProvider - This credential provider must be run under the Team Build tasks for NuGet. Appropriate environment variables must be set.
trace:     [CredentialProvider]Skipping NuGetCredentialProvider.CredentialProviders.VstsBuildTask.VstsBuildTaskCredentialProvider, cannot provide credentials for https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]GET https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
  OK https://pkgs.dev.azure.com/<redacted>/_packaging/abfab4ce-6950-4a26-aec5-1d59681b9cfd/nuget/v3/registrations2-semver2/automapper/index.json 388ms
trace:     [CredentialProvider]VstsCredentialProvider - Detected a hosted Azure DevOps Service.
trace:     [CredentialProvider]Using NuGetCredentialProvider.CredentialProviders.Vsts.VstsCredentialProvider to try to get credentials for https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json.
trace:     [CredentialProvider]IsRetry: True
trace:     [CredentialProvider]Invalidating SessionToken cache for https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]GET https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]Found AAD Authority from 401 headers: https://login.windows.net/<redacted>
trace:     [CredentialProvider]VstsCredentialProvider - Using AAD authority: https://login.windows.net/<redacted>
trace:     [CredentialProvider]VstsCredentialProvider - Not running bearer token provider 'ADAL Cache'
trace:     [CredentialProvider]VstsCredentialProvider - Not running bearer token provider 'ADAL Windows Integrated Authentication'
trace:     [CredentialProvider]VstsCredentialProvider - Not running bearer token provider 'ADAL UI'
trace:     [CredentialProvider]VstsCredentialProvider - Attempting to acquire bearer token using provider 'ADAL Device Code'
    [CredentialProvider]DeviceFlow: https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
    [CredentialProvider]ATTENTION: User interaction required.

    **********************************************************************

    To sign in, use a web browser to open the page https://microsoft.com/devicelogin and enter the code <redacted> to authenticate.

    **********************************************************************
    [CredentialProvider]VstsCredentialProvider - Acquired bearer token using 'ADAL Device Code'
    [CredentialProvider]VstsCredentialProvider - Attempting to exchange the bearer token for an Azure DevOps session token.
trace:     [CredentialProvider]Requesting a Compact token valid for duration <redacted>, valid until <redacted>. Note that the generated token may have different validity than requested.
trace:     [CredentialProvider]GET https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]VstsCredentialProvider - Found SessionToken for https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]Caching SessionToken for https://pkgs.dev.azure.com/<redacted>/_packaging/akovalyov-test/nuget/v3/index.json
trace:     [CredentialProvider]Sending response: 'Request' 'GetAuthenticationCredentials'. Time elapsed in ms: 18478
trace:     [CredentialProvider]Time elapsed in milliseconds after sending response 'Request' 'GetAuthenticationCredentials': 18478
  OK https://pkgs.dev.azure.com/<redacted>/_packaging/abfab4ce-6950-4a26-aec5-1d59681b9cfd/nuget/v3/registrations2-semver2/entityframework/index.json 663ms
Project `projects` has the following updates to its packages
   [net5.0]:
   Top-level Package      Requested   Resolved   Latest
   > AutoMapper           9.0.0       9.0.0      10.1.1
   > EntityFramework      6.4.0       6.4.0      6.4.4

[nkolev92]

@ByAgenT

Is this something that's still happening with restore as well?
There's a few reports, and it's was unclear to me whether you ever got a repro with restore.

[ByAgenT]

@nkolev92 No, I don’t have a repro with package restore using NuGet CLI 5.10 and latest credprovider (0.1.25), auth prompted only once and credprovider cache is being respected properly. At this moment we’re only aware of the issue with list command.

[zkat]

@erdembayar would you mind looking into this and checking if it's a regression?

[erdembayar]

@ByAgenT
Could you refer any repository which can be used for repro?
I'm not sure if I have any repository which require Azure artifacts with credential.

[erdembayar]

@donnie-msft @aortiz-msft
Maybe we can make this one not P1, because when I manually test this specific case it didn't work with dotnet sdk 5 and 3, so it's not really regression. So I changed to P2 and I already have 2PRs related to this. I need reviews.
NuGet/NuGet.Client#4247
NuGet/NuGet.Client#4240

[erdembayar]

Since this was must fix issue changing back to P1.