dotnet msbuild fails to restore from private Azure feed

[jcagme]

Steps to reproduce

1. Install dotnet sdk version 3.0.100-preview5-011568
2. Do dotnet msbuild <proj> where has a reference stored in an internal Azure feed

Project file

<Project Sdk="Microsoft.DotNet.Arcade.Sdk"/>

Package source in nuget.config

<add key="dotnet-core" value="https://pkgs.dev.azure.com/dnceng/_packaging/stable-dotnet-test-1/nuget/v3/index.json" />

(Ping me for the token)

When using dotnet version 2.1 the Arcade SDK is restored correctly as seen in dotnet msbuild 2.1 of https://dev.azure.com/dnceng/internal/_build/results?buildId=219211.

dotnet version 2.1 and 3.0 work fine when doing dotnet restore <proj> as seen in CmdLine of https://dev.azure.com/dnceng/internal/_build/results?buildId=217065 and https://dev.azure.com/dnceng/internal/_build/results?buildId=219105

I don't really know if the issue is in msbuild, nuget or CredProvider.

/fyi: @rainersigwald @zarenner

[zarenner]

@jcagme does your result change if you specify a version, e.g.
<Project Sdk="Microsoft.DotNet.Arcade.Sdk/1.0.0-beta.19306.2" />?

I don't at all know the history here like I'm sure @rainersigwald or @jeffkl do, but at least in the original #2850 implementation it looks like the nuget resolver required a version.

[jcagme]

It didn't fly: https://dev.azure.com/dnceng/internal/_build/results?buildId=219589&view=logs&jobId=16ce49ee-8d0d-5a76-4958-88f78392b71f&taskId=66dcdedb-fba2-5a48-ac41-285184570112&lineStart=51&lineEnd=51&colStart=6&colEnd=158

1>F:\workspace\_work\1\s\eng\common\restore.proj : error MSB4236: The SDK 'Microsoft.DotNet.Arcade.Sdk/1.0.0-beta.19306.2' specified could not be found.

[jcagme]

Don't know if relevant or not but found a difference, at least in the logs, of the endpoints that are attempted to get the package from a 2.1 and a 3.0 CLI: For instance:

3.0

Using C:\Users\vsagent\.nuget\plugins\netcore\CredentialProvider.Microsoft\CredentialProvider.Microsoft.dll as a credential provider plugin.
         GET https://api.nuget.org/v3-flatcontainer/microsoft.dotnet.arcade.sdk/index.json
         NotFound https://api.nuget.org/v3-flatcontainer/microsoft.dotnet.arcade.sdk/index.json 239ms
       Resolving conflicts for .NETStandard,Version=v0.0...

Full log: https://dev.azure.com/dnceng/internal/_build/results?buildId=219589

2.1

Using C:\Users\vsagent\.nuget\plugins\netcore\CredentialProvider.Microsoft\CredentialProvider.Microsoft.dll as a credential provider plugin.
         GET https://pkgs.dev.azure.com/dnceng/_packaging/7ad43c59-454f-43ff-aef9-f6015eb4704b/nuget/v3/flat2/microsoft.dotnet.arcade.sdk/index.json
         GET https://api.nuget.org/v3-flatcontainer/microsoft.dotnet.arcade.sdk/index.json
         NotFound https://api.nuget.org/v3-flatcontainer/microsoft.dotnet.arcade.sdk/index.json 65ms
         OK https://pkgs.dev.azure.com/dnceng/_packaging/7ad43c59-454f-43ff-aef9-f6015eb4704b/nuget/v3/flat2/microsoft.dotnet.arcade.sdk/index.json 154ms
         GET https://pkgs.dev.azure.com/dnceng/_packaging/7ad43c59-454f-43ff-aef9-f6015eb4704b/nuget/v3/flat2/microsoft.dotnet.arcade.sdk/1.0.0-beta.19306.2/microsoft.dotnet.arcade.sdk.1.0.0-beta.19306.2.nupkg
         OK https://pkgs.dev.azure.com/dnceng/_packaging/7ad43c59-454f-43ff-aef9-f6015eb4704b/nuget/v3/flat2/microsoft.dotnet.arcade.sdk/1.0.0-beta.19306.2/microsoft.dotnet.arcade.sdk.1.0.0-beta.19306.2.nupkg 888ms
       Resolving conflicts for .NETStandard,Version=v0.0...
       Acquiring lock for the installation of Microsoft.DotNet.Arcade.Sdk 1.0.0-beta.19306.2

Full log: https://dev.azure.com/dnceng/internal/_build/results?buildId=219593

Even though 3.0 doesn't log the internal feed the logged error claims it couldn't load the index from it F:\workspace\_work\1\s\eng\common\restore.proj : warning : Unable to load the service index for source https://pkgs.dev.azure.com/dnceng/_packaging/stable-dotnet-test-1/nuget/v3/index.json.

[livarcocc]

This seems like something that NuGet should be looking at, since the differences seem to be happening in restore.

@rrelyea @nkolev92

[nkolev92]

The logs are coming from the SDK resolver. I don't know of anything that has changed there.
//cc @jeffkl

I don't have access ( 😢 ) to the logs to see if there's something obvious happening.

Basically NuGet fails fast if there's a source that's unreachable.
Is it possible that the plugin is not configured to support the specific feed?

What are the versions of 2.1 and 3.0 that your testing. For all we know they could have the same exact same NuGet bits.

[jeffkl]

This is pretty complicated. Arcade running eng/common/internal-feed-operations.ps1 which does the following:

1. Download the Artifacts Services credential provider installer
2. Run the installcredprovider.ps1 script
3. Harvests feed names and URLs from Versions.props and NuGet.config
4. Sets environment variables that the Artifacts Services credential provider will read
5. Emits an empty restore.proj with <Project Sdk="Microsoft.DotNet.Arcade.Sdk/1.0.0-beta.19306.2"/>

The log then contains:

F:\workspace\_work\1\s\.dotnet\dotnet.exe msbuild F:\workspace\_work\1\s\eng\common\restore.proj -verbosity:d
Microsoft (R) Build Engine version 16.0.462+g62fb89029d for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

Build started 6/11/2019 3:23:47 AM.
     0>Resolving SDK 'Microsoft.DotNet.Arcade.Sdk/1.0.0-beta.19306.2'...
       Running restore with 4 concurrent jobs.
       Reading project file C:\Users\vsagent\AppData\Local\Temp\1b44969e-5433-48e1-838b-397efbdb772d.
       Persisting no-op dg to C:\Users\vsagent\AppData\Local\Temp\1b44969e-5433-48e1-838b-397efbdb772d.nuget.dgspec.json
       Restoring packages for C:\Users\vsagent\AppData\Local\Temp\1b44969e-5433-48e1-838b-397efbdb772d...
       Restoring packages for .NETStandard,Version=v0.0...
       Using C:\Users\vsagent\.nuget\plugins\netcore\CredentialProvider.Microsoft\CredentialProvider.Microsoft.dll as a credential provider plugin.
         GET https://api.nuget.org/v3-flatcontainer/microsoft.dotnet.arcade.sdk/index.json
         NotFound https://api.nuget.org/v3-flatcontainer/microsoft.dotnet.arcade.sdk/index.json 239ms
       Resolving conflicts for .NETStandard,Version=v0.0...
     0>F:\workspace\_work\1\s\eng\common\restore.proj : warning : Unable to load the service index for source https://pkgs.dev.azure.com/dnceng/_packaging/stable-dotnet-test-1/nuget/v3/index.json.
     0>F:\workspace\_work\1\s\eng\common\restore.proj : error : Unable to find package Microsoft.DotNet.Arcade.Sdk. No packages exist with this id in source(s): dotnet-core-internal, nuget.org
     1>Project "F:\workspace\_work\1\s\eng\common\restore.proj" on node 1 (default targets).
     1>Building with tools version "Current".
     1>F:\workspace\_work\1\s\eng\common\restore.proj : error MSB4236: The SDK 'Microsoft.DotNet.Arcade.Sdk/1.0.0-beta.19306.2' specified could not be found.
     1>Done Building Project "F:\workspace\_work\1\s\eng\common\restore.proj" (default targets) -- FAILED.

Build FAILED.

         F:\workspace\_work\1\s\eng\common\restore.proj : warning : Unable to load the service index for source https://pkgs.dev.azure.com/dnceng/_packaging/stable-dotnet-test-1/nuget/v3/index.json.


         F:\workspace\_work\1\s\eng\common\restore.proj : error : Unable to find package Microsoft.DotNet.Arcade.Sdk. No packages exist with this id in source(s): dotnet-core-internal, nuget.org


       "F:\workspace\_work\1\s\eng\common\restore.proj" (default target) (1) ->
         F:\workspace\_work\1\s\eng\common\restore.proj : error MSB4236: The SDK 'Microsoft.DotNet.Arcade.Sdk/1.0.0-beta.19306.2' specified could not be found.

    1 Warning(s)
    2 Error(s)

Time Elapsed 00:00:06.95

The SDK resolver is just calling RestoreRunner which ties into the configured credential provider. The log shows the credential provider being used, so it makes me wonder if the credential provider can't provide credentials. But the internal-feed-operations.ps1 does not log whether or not the env vars were set. I doubt its related to the SDK resolver, it looks like authentication isn't working which is a contract between NuGet and the credential provider.

[jcagme]

3.0:

.NET Core SDK (reflecting any global.json):
 Version:   3.0.100-preview5-011568
 Commit:    b487ff10aa
NuGet Command Line
5.1.0.0

2.1

.NET Core SDK (reflecting any global.json):
 Version:   2.1.503
 Commit:    4c506e0f35
NuGet Command Line
4.9.0.6

[jcagme]

But the internal-feed-operations.ps1 does not log whether or not the env vars were set.

Credentials are set correctly. Two things I did to check, which are no longer in the build, 1) Printed the environment variable which was set correctly, 2) Ran the Cred Provider in standalone mode which basically checks whether it can fetch a token from envvar, VS, etc. and if it can, then it makes sure it is valid. If needed I can put these back in the build.

[zarenner]

FYI the cred provider does not check tokens for validity.

Can you set NUGET_CREDENTIALPROVIDER_LOG_PATH (https://github.com/Microsoft/artifacts-credprovider#help) and then emit the log? I'm not sure why detailed logging isn't enough to get the credential provider's verbose output on the console, but apparently it isn't.

You're looking for either the line
Found credentials for endpoint https://pkgs.dev.azure.com/dnceng/_packaging/stable-dotnet-test-1/nuget/v3/index.json
or the line
Environment variable VSS_NUGET_EXTERNAL_FEED_ENDPOINTS did not have credentials for endpoint https://pkgs.dev.azure.com/dnceng/_packaging/stable-dotnet-test-1/nuget/v3/index.json

[jcagme]

More info per preview version.

3.0.100-preview-009812 (preview 2)

NuGet Command Line 5.0.0.1
msbuild 16.0.225-preview+g5ebeba52a1

3.0.100-preview3-010431 (preview3)

NuGet Command Line 5.0.0.4
msbuild 16.0.443+g5775d0d6bb

3.0.100-preview4-011223 (preview4)

NuGet Command Line 5.1.0.0
msbuild 16.1.54-preview+gd004974104

3.0.100-preview5-011568 (preview5)

NuGet Command Line 5.1.0.0
msbuild 16.0.462+g62fb89029d

3.0.100-preview6-012264 (preview6)

NuGet Command Line 5.2.0.1
msbuild 16.2.0-preview-19278-01+d635043bd

setting the envvar for logs now...

[jcagme]

The other piece of the issue we are hitting is similar to NuGet/Home#6609 where I've included information and logs about our particular scenario. Issue is closed tho...

/fyi: @markwilkie

[jcagme]

Can you set NUGET_CREDENTIALPROVIDER_LOG_PATH (https://github.com/Microsoft/artifacts-credprovider#help) and then emit the log? I'm not sure why detailed logging isn't enough to get the credential provider's verbose output on the console, but apparently it isn't.

I tried a bunch of different things and the only logs flushed into the file are those of running the CredProvider tool in standalone mode:

[Verbose] [CredentialProvider]Running in stand-alone mode
[Verbose] [CredentialProvider]Command-line v0.1.17: c:\users\user\.nuget\plugins\netcore\CredentialProvider.Microsoft\CredentialProvider.Microsoft.dll -U https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json -R -V Debug
[Verbose] [CredentialProvider]Handling auth request, Uri: https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json, IsRetry: False, IsNonInteractive: False, CanShowDialog: False
[Verbose] [CredentialProvider]URI: https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json
[Verbose] [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.
[Verbose] [CredentialProvider]Skipping NuGetCredentialProvider.CredentialProviders.VstsBuildTaskServiceEndpoint.VstsBuildTaskServiceEndpointCredentialProvider, cannot provide credentials for https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json
[Verbose] [CredentialProvider]VstsBuildTaskCredentialProvider - This credential provider must be run under the Team Build tasks for NuGet. Appropriate environment variables must be set.
[Verbose] [CredentialProvider]Skipping NuGetCredentialProvider.CredentialProviders.VstsBuildTask.VstsBuildTaskCredentialProvider, cannot provide credentials for https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json
[Verbose] [CredentialProvider]GET https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json
[Verbose] [CredentialProvider]IsRetry: False
[Verbose] [CredentialProvider]Could not find cached SessionToken for https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json
[Verbose] [CredentialProvider]GET https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json
[Verbose] [CredentialProvider]Found AAD Authority from 401 headers: https://login.windows.net/GUID
[Verbose] [CredentialProvider]VstsCredentialProvider - Using AAD authority: https://login.windows.net/GUID
[Verbose] [CredentialProvider]VstsCredentialProvider - Attempting to acquire bearer token using provider 'ADAL Cache'
[Verbose] [CredentialProvider]VstsCredentialProvider - Bearer token provider 'ADAL Cache' didn't acquire a token
[Verbose] [CredentialProvider]VstsCredentialProvider - Attempting to acquire bearer token using provider 'ADAL Windows Integrated Authentication'
[Information] [CredentialProvider]VstsCredentialProvider - Acquired bearer token using 'ADAL Windows Integrated Authentication'
[Information] [CredentialProvider]VstsCredentialProvider - Attempting to exchange the bearer token for an Azure DevOps session token.
[Verbose] [CredentialProvider]Requesting a SelfDescribing token valid for duration 04:00:00, valid until 6/12/2019 4:07:53 AM UTC. Note that the generated token may have different validity than requested.
[Verbose] [CredentialProvider]GET https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json
[Verbose] [CredentialProvider]VstsCredentialProvider - Found SessionToken for https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json
[Verbose] [CredentialProvider]Caching SessionToken for https://pkgs.dev.azure.com/****/_packaging/****/nuget/v3/index.json
[Information] [CredentialProvider]Username: VssSessionToken
[Information] [CredentialProvider]Password: [REDACTED]

[jcagme]

This is a verbose log build with shows that the PAT was set correctly since CredProvider was able to read it from the envvar so auth is fine (I think). Now, during msbuild /t:restore we get
“NuGet.Protocol.Core.Types.FatalProtocolException: Failed to retrieve information about 'Microsoft.DotNet.Build.Tasks.Feed' from remote source 'https://dnceng.pkgs.visualstudio.com/_packaging/a5d2de38-9eb4-419b-98f6-6a69c4bd0eb9/nuget/v3/flat2/microsoft.dotnet.build.tasks.feed/index.json'. ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.”