Paket Restore task not authenticating to VSTS

[jason-gill]

Description

I am trying to use the "Setup Paket Credential Provider" and "Paket Restore" tasks but it is not working. When the "Paket Restore" task runs it tries to connect to the VSTS NuGet instance but it just hangs and eventually gives and error like "Possible Performance degradation, blacklist" and the build terminates because of timeout.

Repro steps

Prerequisites

At least how my environment is setup

• NuGet Repo hosted on VSTS (e.g. https://company123.pkgs.visualstudio.com/_packaging/SRC/nuget/v3/index.json)
• Build Server running on an AWS EC2 instance
• A project setup with Paket to get NuGet packages from the VSTS NuGet Repo

Steps to reproduce

1. Create a VSTS build pipeline
2. Include Setup Paket Credential Manager task
3. Include Restore Paket dependencies task
4. Queue a build to run on the AWS EC2 build agent

Expected behavior

NuGet packages hosted on VSTS would be restored

Actual behavior

Paket restore hangs and the build is eventually terminated because of a timeout

Details

2018-12-19T15:23:56.7194078Z ##[debug]Evaluating condition for step: 'Setup Paket Credential Manager'
2018-12-19T15:23:56.7195035Z ##[debug]Evaluating: succeeded()
2018-12-19T15:23:56.7195172Z ##[debug]Evaluating succeeded:
2018-12-19T15:23:56.7195383Z ##[debug]=> True
2018-12-19T15:23:56.7195602Z ##[debug]Result: True
2018-12-19T15:23:56.7195828Z ##[section]Starting: Setup Paket Credential Manager
2018-12-19T15:23:56.7198541Z ==============================================================================
2018-12-19T15:23:56.7198614Z Task         : Paket Credential Manager
2018-12-19T15:23:56.7198651Z Description  : Creates a credential manager for Paket to access internal NuGet feeds.
2018-12-19T15:23:56.7198686Z Version      : 0.2.5
2018-12-19T15:23:56.7198759Z Author       : Matthias Dittrich
2018-12-19T15:23:56.7198794Z Help         : This task allows you to consume NuGet packages hosted in your own private feed by providing a credential manager.
2018-12-19T15:23:56.7198829Z ==============================================================================
2018-12-19T15:23:56.9451524Z ##[debug]agent.TempDirectory=C:\EC2AMAZ-1JI32VU\work\_temp
2018-12-19T15:23:56.9522424Z ##[debug]loading inputs and endpoints
2018-12-19T15:23:56.9528292Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_SYSTEMVSSCONNECTION_ACCESSTOKEN
2018-12-19T15:23:56.9538512Z ##[debug]loading ENDPOINT_AUTH_SCHEME_SYSTEMVSSCONNECTION
2018-12-19T15:23:56.9541573Z ##[debug]loading ENDPOINT_AUTH_SYSTEMVSSCONNECTION
2018-12-19T15:23:56.9546058Z ##[debug]loaded 3
2018-12-19T15:23:56.9559960Z ##[debug]Agent.ProxyUrl=undefined
2018-12-19T15:23:56.9562337Z ##[debug]Agent.CAInfo=undefined
2018-12-19T15:23:56.9562466Z ##[debug]Agent.ClientCert=undefined
2018-12-19T15:23:56.9563322Z ##[debug]Agent.SkipCertValidation=undefined
2018-12-19T15:23:57.0095861Z ##[debug]Agent.ProxyUrl=undefined
2018-12-19T15:23:57.0099640Z ##[debug]check path : C:\EC2AMAZ-1JI32VU\work\_tasks\setCredentialManager_5bfdd7ca-9bf4-40f7-b753-fd674e7ff85c\0.2.5\node_modules\vsts-task-tool-lib\lib.json
2018-12-19T15:23:57.0101244Z ##[debug]adding resource file: C:\EC2AMAZ-1JI32VU\work\_tasks\setCredentialManager_5bfdd7ca-9bf4-40f7-b753-fd674e7ff85c\0.2.5\node_modules\vsts-task-tool-lib\lib.json
2018-12-19T15:23:57.0101508Z ##[debug]system.culture=en-US
2018-12-19T15:23:57.0137976Z ##[debug]Adding 'C:\EC2AMAZ-1JI32VU\work\_tasks\setCredentialManager_5bfdd7ca-9bf4-40f7-b753-fd674e7ff85c\0.2.5\node_modules\vsts-fsharp-task-common\CredentialProvider' to 'NUGET_CREDENTIALPROVIDERS_PATH'
2018-12-19T15:23:57.0139989Z ##[debug]set NUGET_CREDENTIALPROVIDERS_PATH=C:\EC2AMAZ-1JI32VU\work\_tasks\setCredentialManager_5bfdd7ca-9bf4-40f7-b753-fd674e7ff85c\0.2.5\node_modules\vsts-fsharp-task-common\CredentialProvider
2018-12-19T15:23:57.0157302Z ##[debug]Processed: ##vso[task.setvariable variable=NUGET_CREDENTIALPROVIDERS_PATH;issecret=false;]C:\EC2AMAZ-1JI32VU\work\_tasks\setCredentialManager_5bfdd7ca-9bf4-40f7-b753-fd674e7ff85c\0.2.5\node_modules\vsts-fsharp-task-common\CredentialProvider
2018-12-19T15:23:57.0162617Z SYSTEMVSSCONNECTION exists true
2018-12-19T15:23:57.0162884Z ##[debug]SYSTEMVSSCONNECTION exists true
2018-12-19T15:23:57.0163360Z ##[debug]set PAKET_VSS_NUGET_ACCESSTOKEN=***
2018-12-19T15:23:57.0165097Z ##[debug]Processed: ##vso[task.setvariable variable=PAKET_VSS_NUGET_ACCESSTOKEN;issecret=false;]***
2018-12-19T15:23:57.0262984Z ##[section]Finishing: Setup Paket Credential Manager

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

2018-12-19T15:23:57.0344810Z ##[debug]Evaluating condition for step: 'Restore Paket dependencies'
2018-12-19T15:23:57.0345341Z ##[debug]Evaluating: succeeded()
2018-12-19T15:23:57.0345445Z ##[debug]Evaluating succeeded:
2018-12-19T15:23:57.0345630Z ##[debug]=> True
2018-12-19T15:23:57.0345816Z ##[debug]Result: True
2018-12-19T15:23:57.0345981Z ##[section]Starting: Restore Paket dependencies
2018-12-19T15:23:57.0348931Z ==============================================================================
2018-12-19T15:23:57.0348987Z Task         : Paket Restore
2018-12-19T15:23:57.0349021Z Description  : Restores your Paket dependencies.
2018-12-19T15:23:57.0349055Z Version      : 0.4.5
2018-12-19T15:23:57.0349107Z Author       : Isaac Abraham
2018-12-19T15:23:57.0349141Z Help         : This task restores your dependencies from the paket.dependencies file located in your repository.
2018-12-19T15:23:57.0349174Z ==============================================================================
2018-12-19T15:23:57.0461133Z ##[debug]Working directory: 'C:\EC2AMAZ-1JI32VU\work\2\s\.paket'
2018-12-19T15:23:57.0461762Z ##[debug]Fail on standard error: 'True'
2018-12-19T15:23:57.0461816Z ##[debug]Modify environment: 'False'
2018-12-19T15:23:57.0461883Z ##[debug]C:\Windows\system32\cmd.exe /c "C:\EC2AMAZ-1JI32VU\work\_tasks\PaketRestore_1ba72b0a-f476-4a91-90a0-b8e7a0cc4338\0.4.5\Paket.bat "
2018-12-19T15:23:57.0461958Z ##[command]C:\EC2AMAZ-1JI32VU\work\_tasks\PaketRestore_1ba72b0a-f476-4a91-90a0-b8e7a0cc4338\0.4.5\Paket.bat 
2018-12-19T15:23:57.1310615Z Checking Paket version (downloading latest stable)...
2018-12-19T15:23:57.5909356Z Paket.exe 5.194.3 is up to date.
2018-12-19T15:23:57.6734229Z Paket version 5.194.3
2018-12-19T15:24:01.2936335Z Starting full restore process.
2018-12-19T15:24:01.5807402Z Downloading PG_API 20181213.1.0
2018-12-19T15:34:01.7183893Z Possible Performance degradation, V3 was not working: One or more errors occurred.
2018-12-19T15:44:01.8162775Z Possible Performance degradation, blacklist '1_https://company123.pkgs.visualstudio.com/_packaging/UI/nuget/v2/Packages(Id='pg_api',Version='20181213.1.0')'
2018-12-19T16:04:01.8623774Z Possible Performance degradation, blacklist '1_https://company123.pkgs.visualstudio.com/_packaging/UI/nuget/v2/Packages(Id='PG_API',Version='20181213.1.0')'
2018-12-19T16:23:50.7229484Z ##[debug]Re-evaluate condition on job cancellation for step: 'Restore Paket dependencies'.
2018-12-19T16:23:50.7695175Z ##[error]^C

2018-12-19T16:23:50.7716804Z Terminate batch job (Y/N)? 
2018-12-19T16:23:50.7934677Z ##[error]The operation was canceled.
2018-12-19T16:23:50.7937720Z ##[debug]System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at Microsoft.VisualStudio.Services.Agent.Util.ProcessInvoker.ExecuteAsync(String workingDirectory, String fileName, String arguments, IDictionary`2 environment, Boolean requireExitCodeZero, Encoding outputEncoding, Boolean killProcessOnCancel, IList`1 contentsToStandardIn, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.Agent.ProcessInvokerWrapper.ExecuteAsync(String workingDirectory, String fileName, String arguments, IDictionary`2 environment, Boolean requireExitCodeZero, Encoding outputEncoding, Boolean killProcessOnCancel, IList`1 contentsToStandardIn, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.Agent.Worker.Handlers.ProcessHandler.RunAsync()
   at Microsoft.VisualStudio.Services.Agent.Worker.TaskRunner.RunAsync()
   at Microsoft.VisualStudio.Services.Agent.Worker.StepsRunner.RunStepAsync(IStep step, CancellationToken jobCancellationToken)
2018-12-19T16:23:50.7939318Z ##[section]Finishing: Restore Paket dependencies

Known workarounds

None

[jason-gill]

Turns out that adding CredentialProvider.VSS.exe to our build script had unintended consequences.

I changed our build script to copy the CredentialProvider.VSS.exe to the %LocalAppData%\NuGet\CredentialProviders directory which is the first directory Paket looks in for credentialing providers. In an AWS environment that provider doesn’t work because you need an access token to authenticate to VSTS. Because that credentialing provider was the first one found, Paket would hang trying to authenticate itself. Once that provider was removed, then Paket restore was able to find the credentialing provider installed by the “Setup Paket Credential Manager” task and everything works like it should.

[matthid]

Thanks a lot for this analysis, does that mean the first provider was trying to get interactive input from the user? Maybe we can improve that scenario by printing a warning in paket after a while when the credentials provider doesn't exit?

[jason-gill]

Yes, I do think that is what happens. I remember during my testing running the build manually on one of the build boxes and I got a login popup. After putting in my credentials that build box never had the authentication problem again but the other build boxes did.