Issue
I've been struggling now for some days with a failing deployment on VSTS Release Management. I made a release definition to deploy an Azure Cloud Service based on artifacts containing the cskpg and cscfg files. At first I didn't get much information using the hosted build controller. The logs for the deployment are empty and only the message "Deployment on this environment was cancelled." is shown in the release logs.
To get more useful debug information, I downloaded the Windows build agent and installed it as a service on my local machine. In the logs I see a security exception: Microsoft.VisualStudio.Services.Common.VssUnauthorizedException. Below is an extract of the Windows Build Agent log:
09:36:41.217088 WorkerRunner.RunJobOnWorker - enter
09:36:41.232710 WorkerRunner.RunJobOnWorker - starting the job
09:36:41.232710 BaseLogger.LogStatus(scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa, scope.TimelineRecordId = 77c25a08-adf0-44e9-a546-7115ebc413f8, record.Name = Release)
09:36:41.232710 JobManager.LogStatus (scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa, record.Name = Release)
09:36:41.232710 JobManager.LogStatus - job not found in dictionary (scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa)
09:36:41.232710 [77c25a08-adf0-44e9-a546-7115ebc413f8][b85840a5-bbf5-4c92-8b46-414ea85e29fa]Record: t=Job, n=Release, s=InProgress, st=12/4/2015 9:36:41 AM, 0%, ft=, r=: Starting
09:36:41.232710 BaseLogger.LogConsoleMessage(scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa, message = Agent version: 1.91.1)
09:36:41.232710 JobManager.LogConsoleMessage (scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa, message = Agent version: 1.91.1)
09:36:41.232710 JobManager.LogConsoleMessage - job not found in dictionary (scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa)
09:36:41.232710 [77c25a08-adf0-44e9-a546-7115ebc413f8][b85840a5-bbf5-4c92-8b46-414ea85e29fa]Agent version: 1.91.1
09:36:41.232710 BaseLogger.LogConsoleMessage(scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa, message = Starting job)
09:36:41.232710 JobManager.LogConsoleMessage (scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa, message = Starting job)
09:36:41.232710 JobManager.LogConsoleMessage - job not found in dictionary (scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa)
09:36:41.232710 [77c25a08-adf0-44e9-a546-7115ebc413f8][b85840a5-bbf5-4c92-8b46-414ea85e29fa]Starting job
09:36:41.232710 JobManager.StartJob(job.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa)
09:36:41.232710 JobInfo.ctor
09:36:41.232710 JobInfo.ctor - leave
09:36:41.232710 JobManager.StartJob - calling JobWriter.StartJob
09:36:41.232710 JobWriter.StartJob - enter
09:36:41.232710 JobWriter.StartJob - (SKIPPING)first renew
09:36:41.326473 JobWriter.StartJob - start continual renewing
09:36:41.326473 AuthorizationType : OAuth
09:36:41.748960 ConsoleTimer_Callback - enter (22)
09:36:41.748960 ConsoleTimer_Callback - Inside Lock
09:36:41.748960 ConsoleTimer_Callback - processing job b85840a5-bbf5-4c92-8b46-414ea85e29fa
09:36:41.748960 ConsoleTimer_Callback - leave
09:36:41.986477 StatusTimer_Callback - enter (26)
09:36:41.986477 StatusTimer_Callback - processing job b85840a5-bbf5-4c92-8b46-414ea85e29fa
09:36:41.986477 StatusTimer_Callback - leave
09:36:42.232703 LogFileTimer_Callback - enter (21)
09:36:42.232703 LogFileTimer_Callback - processing job b85840a5-bbf5-4c92-8b46-414ea85e29fa
09:36:42.232703 LogFileTimer_Callback - found 0 records for job b85840a5-bbf5-4c92-8b46-414ea85e29fa
09:36:42.232703 LogFileTimer_Callback - leave
09:36:42.263938 ConsoleTimer_Callback - enter (18)
09:36:42.263938 ConsoleTimer_Callback - Inside Lock
09:36:42.263938 ConsoleTimer_Callback - processing job b85840a5-bbf5-4c92-8b46-414ea85e29fa
09:36:42.263938 ConsoleTimer_Callback - leave
09:36:42.518076 ---------------------------------------------------------------------------
09:36:42.523266 Microsoft.VisualStudio.Services.Common.VssUnauthorizedException: TF400813: The user 'Build\{guid_removed_intentionally}' is not authorized to access this resource.
09:36:42.523266 at Microsoft.VisualStudio.Services.Common.VssHttpMessageHandler.<SendAsync>d__17.MoveNext()
09:36:42.523266 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523266 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523266 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523266 at Microsoft.VisualStudio.Services.WebApi.VssHttpRetryMessageHandler.<SendAsync>d__3.MoveNext()
09:36:42.523266 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523266 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523266 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523266 at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<SendAsync>d__50.MoveNext()
09:36:42.523266 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523266 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523266 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523266 at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<SendAsync>d__47`1.MoveNext()
09:36:42.523266 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523266 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523790 at Microsoft.VisualStudio.Services.Location.Client.LocationHttpClient.<GetConnectionDataAsync>d__6.MoveNext()
09:36:42.523790 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523790 at Microsoft.VisualStudio.Services.Client.VssServerDataProvider.<ConnectAsync>d__39.MoveNext()
09:36:42.523790 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523790 at Microsoft.TeamFoundation.DistributedTask.Agent.Common.ConnectionHelper.GetConnection(Uri serverUri, VssCredentials credentials)
09:36:42.523790 at Microsoft.TeamFoundation.DistributedTask.Agent.JobWriter.StartJob()
09:36:42.523790 at Microsoft.VisualStudio.Services.Common.VssHttpMessageHandler.<SendAsync>d__17.MoveNext()
09:36:42.523790 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523790 at Microsoft.VisualStudio.Services.WebApi.VssHttpRetryMessageHandler.<SendAsync>d__3.MoveNext()
09:36:42.523790 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523790 at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<SendAsync>d__50.MoveNext()
09:36:42.523790 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523790 at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<SendAsync>d__47`1.MoveNext()
09:36:42.523790 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523790 at Microsoft.VisualStudio.Services.Location.Client.LocationHttpClient.<GetConnectionDataAsync>d__6.MoveNext()
09:36:42.523790 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523790 at Microsoft.VisualStudio.Services.Client.VssServerDataProvider.<ConnectAsync>d__39.MoveNext()
09:36:42.523790 --- End of stack trace from previous location where exception was thrown ---
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
09:36:42.523790 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
09:36:42.523790 at Microsoft.TeamFoundation.DistributedTask.Agent.Common.ConnectionHelper.GetConnection(Uri serverUri, VssCredentials credentials)
09:36:42.523790 at Microsoft.TeamFoundation.DistributedTask.Agent.JobWriter.StartJob()
09:36:42.523790 ---------------------------------------------------------------------------
09:36:42.525271 Process logging event with context handler.
09:36:42.525271 BaseLogger.LogConsoleMessage(scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa, message = ##[error]The Agent failed to start this job. Error: TF400813: The user 'Build\985376fd-d1bd-45eb-b657-a7fd22d51cb9' is not authorized to access this resource.)
09:36:42.525271 JobManager.LogConsoleMessage (scope.JobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa, message = ##[error]The Agent failed to start this job. Error: TF400813: The user 'Build\985376fd-d1bd-45eb-b657-a7fd22d51cb9' is not authorized to access this resource.)
09:36:42.525271 JobManager.LogConsoleMessage - message enqueued
09:36:42.525271 [77c25a08-adf0-44e9-a546-7115ebc413f8][b85840a5-bbf5-4c92-8b46-414ea85e29fa]##[error]The Agent failed to start this job. Error: TF400813: The user 'Build\985376fd-d1bd-45eb-b657-a7fd22d51cb9' is not authorized to access this resource.
09:36:42.525271 JobManager.FinishJob(jobId = b85840a5-bbf5-4c92-8b46-414ea85e29fa, result = Failed)
09:36:42.748347 StatusTimer_Callback - enter (22)
09:36:42.748347 StatusTimer_Callback - processing job b85840a5-bbf5-4c92-8b46-414ea85e29fa
09:36:42.748347 StatusTimer_Callback - leave
...
09:36:53.551559 JobInfo.Dispose - leave
09:36:53.551559 JobManager.FinishJob - Removing JobId b85840a5-bbf5-4c92-8b46-414ea85e29fa from Jobs
09:36:53.551559 Failed to start the job, could not create the http client with the given credentials.
Additional information
I should mention that I also have problems accessing the storage account and cloud service from the drop down boxes in the Azure Cloud Service Deployment taks.
Azure Cloud Service Deployment
I don't know if both issues are related to each other but it can be useful information.I've created the necessary Service Endpoints in the VSTS Service configuration tab. To test I've made one of each version: Credentials, Certificated Based and Service Principal Authentication. Unfortunately none of them seem to be able to list the Storage Account and Service name. (only the Credentials and Certificate based endpoints are showing up in the Azure Subscription drop down on the Azure Cloud Service Deployment task). When I switch accounts in this drop down, I see HTTP errors in the network log, one for the storage account drop down and one for the cloud service drop down which makes me belief that it fails to authenticate to the Azure account. The service principal based service connection does not show up in the Azure Subscription drop down. The Azure resources were made by using the Azure Resource manager.
For the certificate based service endpoint I get the following response:
HTTP/1.1 500 Internal Server Error
Cache-Control: no-cache
Pragma: no-cache
Content-Type: application/json; charset=utf-8
Expires: -1
Server: Microsoft-IIS/8.5
X-TFS-ProcessId: {guid}
Strict-Transport-Security: max-age=31536000; includeSubDomains
Access-Control-Allow-Origin: https://<accountName>.visualstudio.com
Access-Control-Max-Age: 3600
Access-Control-Allow-Methods: OPTIONS,GET,POST,PATCH,PUT,DELETE
Access-Control-Expose-Headers: ActivityId,X-TFS-Session,X-MS-ContinuationToken
Access-Control-Allow-Credentials: true
Access-Control-Allow-Headers: authorization
Set-Cookie: Tfs-SessionId={guid}; path=/; secure
Set-Cookie: Tfs-SessionActive=2015-12-04T10:14:11; path=/; secure
X-VSS-UserData: {guid}:{userName}
ActivityId: {guid}
X-TFS-Session: {guid}
X-AspNet-Version: 4.0.30319
X-Powered-By: ASP.NET
P3P: CP="CAO DSP COR ADMa DEV CONo TELo CUR PSA PSD TAI IVDo OUR SAMi BUS DEM NAV STA UNI COM INT PHY ONL FIN PUR LOC CNT"
X-Content-Type-Options: nosniff
Date: Fri, 04 Dec 2015 10:14:11 GMT
Content-Length: 262
{"$id":"1","innerException":null,"message":"The remote server returned an error: (403) Forbidden.","typeName":"System.Net.WebException, System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089","typeKey":"WebException","errorCode":0,"eventId":0}
Console Log:
POST https://{accountName}.visualstudio.com/DefaultCollection/_apis/distributedtask/endpoint 500 (Internal Server Error)
TFS.WebApi.Exception: The remote server returned an error: (403) Forbidden.
at k (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/corejs?v=orNy3-42L65GzhafvD4v3Rya12botjCuxnjQZ8VrhzI1:40:375)
at https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/corejs?v=orNy3-42L65GzhafvD4v3Rya12botjCuxnjQZ8VrhzI1:40:2955
at d (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/corejs?v=orNy3-42L65GzhafvD4v3Rya12botjCuxnjQZ8VrhzI1:40:635)
at https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/corejs?v=orNy3-42L65GzhafvD4v3Rya12botjCuxnjQZ8VrhzI1:40:2888
at l (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:8122)
at https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:8348
at t.when (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:3780)
at t.u.promiseDispatch (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:2824)
at https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:1649
at MessagePort.t (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:5773)
For the credentials based service endpoint I get the following response:
HTTP/1.1 500 Internal Server Error
Cache-Control: no-cache
Pragma: no-cache
Content-Type: application/json; charset=utf-8
Expires: -1
Server: Microsoft-IIS/8.5
X-TFS-ProcessId: {guid}
Strict-Transport-Security: max-age=31536000; includeSubDomains
Access-Control-Allow-Origin: https://{accountName}.visualstudio.com
Access-Control-Max-Age: 3600
Access-Control-Allow-Methods: OPTIONS,GET,POST,PATCH,PUT,DELETE
Access-Control-Expose-Headers: ActivityId,X-TFS-Session,X-MS-ContinuationToken
Access-Control-Allow-Credentials: true
Access-Control-Allow-Headers: authorization
Set-Cookie: Tfs-SessionId={guid}; path=/; secure
Set-Cookie: Tfs-SessionActive=2015-12-04T10:21:01; path=/; secure
X-VSS-UserData: {guid}:{userName}
ActivityId: {guid}
X-TFS-Session: {guid}
X-AspNet-Version: 4.0.30319
X-Powered-By: ASP.NET
P3P: CP="CAO DSP COR ADMa DEV CONo TELo CUR PSA PSD TAI IVDo OUR SAMi BUS DEM NAV STA UNI COM INT PHY ONL FIN PUR LOC CNT"
X-Content-Type-Options: nosniff
Date: Fri, 04 Dec 2015 10:21:02 GMT
Content-Length: 327
{"$id":"1","innerException":null,"message":"TF400898: An Internal Error Occurred. Activity Id: {guid}.","typeName":"System.Net.Http.HttpRequestException, System.Net.Http, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a","typeKey":"HttpRequestException","errorCode":0,"eventId":0}
Console Log:
POST https://{accountName}.visualstudio.com/DefaultCollection/_apis/distributedtask/endpoint 500 (Internal Server Error)
TFS.WebApi.Exception: TF400898: An Internal Error Occurred. Activity Id: {guid}.
at k (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/corejs?v=orNy3-42L65GzhafvD4v3Rya12botjCuxnjQZ8VrhzI1:40:375)
at https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/corejs?v=orNy3-42L65GzhafvD4v3Rya12botjCuxnjQZ8VrhzI1:40:2955
at d (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/corejs?v=orNy3-42L65GzhafvD4v3Rya12botjCuxnjQZ8VrhzI1:40:635)
at https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/corejs?v=orNy3-42L65GzhafvD4v3Rya12botjCuxnjQZ8VrhzI1:40:2888
at l (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:8122)
at https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:8348
at t.when (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:3780)
at t.u.promiseDispatch (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:2824)
at https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:1649
at MessagePort.t (https://{accountName}.visualstudio.com/_static/tfs/20151124T220927/_scripts/TFS/min/q.js:27:5773)
Any guidance or help is much appreciated!
