Self-hosted linux agent ignores proxy settings during PublishTestResults step

[petermicuch]

Agent Version and Platform

2.185.1 (also tested with 2.181.0)

OS of the machine running the agent? Linux Ubuntu 18.04

Azure DevOps Type and Version

dev.azure.com (formerly visualstudio.com)

If dev.azure.com, what is your organization name? https://dev.azure.com/iii40

What's not working?

When running tests on selfhosted linux agent, tests are running fine, agent is online all the time, but the step to PublishTestResults fails. It hangs for a long time. We have proxy configured in our setup and agent was installed with --proxyurl option. Besides that also HTTP_PROXY and HTTPS_PROXY variables are set in the system correctly. However during publishing of test results, proxy settings are simply ignored and URLs are accessed directly.

PublishTestResults output:

2021-04-21T13:05:35.8960507Z ##[section]Starting: PublishTestResults
2021-04-21T13:05:36.0594599Z ==============================================================================
2021-04-21T13:05:36.0595383Z Task         : Publish Test Results
2021-04-21T13:05:36.0596031Z Description  : Publish test results to Azure Pipelines
2021-04-21T13:05:36.0596578Z Version      : 2.180.0
2021-04-21T13:05:36.0597094Z Author       : Microsoft Corporation
2021-04-21T13:05:36.0597851Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/test/publish-test-results
2021-04-21T13:05:36.0598758Z ==============================================================================
2021-04-21T13:05:40.4783726Z Result Attachments will be stored in LogStore
2021-04-21T13:05:40.5405523Z Run Attachments will be stored in LogStore
2021-04-21T13:05:40.8950387Z Publishing test results to test run '1002590'.
2021-04-21T13:05:40.9002656Z TestResults To Publish 66, Test run id:1002590
2021-04-21T13:05:40.9073331Z Test results publishing 66, remaining: 0. Test run id: 1002590
2021-04-21T13:05:41.4085019Z ##[section]Async Command Start: Publish test results
2021-04-21T13:11:15.0947206Z ##[warning]Failed to publish test result attachments
2021-04-21T13:11:15.1387958Z ##[warning]Failed to publish test run data: System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.AuthenticationHelper.SendWithAuthAsync(HttpRequestMessage request, Uri authUri, ICredentials credentials, Boolean preAuthenticate, Boolean isProxyAuth, Boolean doRequestAuth, HttpConnectionPool pool, CancellationToken cancellationToken)
   at System.Net.Http.DecompressionHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.Common.VssHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.Common.VssHttpRetryMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.SendAsync(HttpRequestMessage message, HttpCompletionOption completionOption, Object userState, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.SendAsync[T](HttpRequestMessage message, Object userState, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.SendAsync[T](HttpMethod method, IEnumerable`1 additionalHeaders, Guid locationId, Object routeValues, ApiResourceVersion version, HttpContent content, IEnumerable`1 queryParameters, Object userState, CancellationToken cancellationToken)
   at Microsoft.TeamFoundation.TestClient.PublishTestResults.TestRunPublisher.UpdateTestRunAsync(String projectName, Int32 testRunId, RunUpdateModel updateRunModel, CancellationToken cancellationToken)
   at Microsoft.TeamFoundation.TestClient.PublishTestResults.TestRunPublisher.InternalEndTestRunAsync(RunUpdateModel updateModel, Int32 testRunId, Boolean isAddTestRunAttachments, PublishAttachmentsOptions publishAttachmentsOptions, IList`1 attachmentsFilePathList, CancellationToken cancellationToken)
   at Microsoft.TeamFoundation.TestClient.PublishTestResults.TestRunPublisher.<>c__DisplayClass17_0.<<PublishToNewTestRunPerTestResultFileAsync>b__4>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.TeamFoundation.TestClient.PublishTestResults.TestRunPublisher.PublishToNewTestRunPerTestResultFileAsync(IList`1 testRuns, TestRunContext runContext, Int32 batchSize, CancellationToken cancellationToken, PublishOptions publishOptions)
   at Microsoft.TeamFoundation.TestClient.PublishTestResults.TestRunPublisher.PublishTestRunDataAsync(TestRunContext runContext, String projectName, IList`1 testRuns, PublishOptions publishOptions, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.Agent.Worker.TestResults.TestDataPublisher.PublishAsync(TestRunContext runContext, List`1 testResultFiles, PublishOptions publishOptions, CancellationToken cancellationToken)
2021-04-21T13:11:15.2044072Z ##[section]Async Command End: Publish test results
2021-04-21T13:11:15.2046732Z ##[section]Finishing: PublishTestResults

Communication captured on the agent:

myuser@ds-aipc-cl01-ln:~/Az/CL_A01/_diag$ sudo tcpdump -i lo -A
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 262144 bytes
13:10:10.610348 IP localhost.localdomain.41568 > localhost.domain: 53672+ [1au] A? etqtcmprodweu11.vstmrblob.vsassets.io. (66)
E..^.A@.@.5........5.`.5.J...............etqtcmprodweu11        vstmrblob.vsassets.io.......)........
13:10:10.610377 IP localhost.localdomain.41568 > localhost.domain: 60863+ [1au] AAAA? etqtcmprodweu11.vstmrblob.vsassets.io. (66)
E..^.B@.@.5........5.`.5.J...............etqtcmprodweu11        vstmrblob.vsassets.io.......)........
13:10:10.610890 IP localhost.localdomain.49676 > localhost.domain: 55682+ [1au] PTR? 53.0.0.127.in-addr.arpa. (52)
E..P.C@.@.5$.......5...5.<...............53.0.0.127.in-addr.arpa.......)........
13:10:10.611364 IP localhost.domain > localhost.localdomain.49676: 55682 1/0/1 PTR localhost. (75)
E..g..@.@..!...5.....5...S...............53.0.0.127.in-addr.arpa.................       localhost...)........
13:10:10.667009 IP localhost.domain > localhost.localdomain.41568: 53672 3/0/1 CNAME vstmrblob-vsassets-io.b-0020.b-msedge.net., CNAME b-0020.b-msedge.net., A 13.107.6.175 (151)
E....0@.@......5.....5.`.................etqtcmprodweu11        vstmrblob.vsassets.io................+.vstmrblob-vsassets-io.b-0020.b-msedge.net..C...........Y.Y...........k....)........
13:10:10.669395 IP localhost.domain > localhost.localdomain.41568: 60863 3/0/1 CNAME vstmrblob-vsassets-io.b-0020.b-msedge.net., CNAME b-0020.b-msedge.net., AAAA 2620:1ec:a92::175 (163)
E....1@.@......5.....5.`.................etqtcmprodweu11        vstmrblob.vsassets.io................+.vstmrblob-vsassets-io.b-0020.b-msedge.net..C...........Y.Y..........& ..
..........u..)........

Because of this I had to ask for temporal exception for our machine, so that I get direct internet access.

Agent and Worker's Diagnostic Logs

Agent_20210421-125145-utc.log:

[2021-04-21 12:51:45Z INFO AgentProcess] Agent package linux-x64.
[2021-04-21 12:51:45Z INFO AgentProcess] Running on Linux (X64).
[2021-04-21 12:51:45Z INFO AgentProcess] RuntimeInformation: Linux 4.15.0-142-generic microsoft/azure-pipelines-agent#146-Ubuntu SMP Tue Apr 13 01:11:19 UTC 2021.
[2021-04-21 12:51:45Z INFO AgentProcess] Version: 2.185.1
[2021-04-21 12:51:45Z INFO AgentProcess] Commit: 45c52d01eec6c18e3a3e5d8e2a4859fbfc90eff7
[2021-04-21 12:51:45Z INFO AgentProcess] Culture: en-US
[2021-04-21 12:51:45Z INFO AgentProcess] UI Culture: en-US
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO AgentProcess] Validating directory permissions for: '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO CommandSettings] Run {
  "Commit": false,
  "Diagnostics": false,
  "RunOnce": false,
  "StartupType": "service",
  "Help": false,
  "Version": false
}
[2021-04-21 12:51:45Z INFO AgentProcess] Arguments parsed
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'Proxy': '/home/myuser/Az/CL_A01/.proxy'
[2021-04-21 12:51:45Z INFO VstsAgentWebProxy] Config proxy at: http://139.22.102.14:8888.
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'ProxyCredentials': '/home/myuser/Az/CL_A01/.proxycredentials'
[2021-04-21 12:51:45Z INFO VstsAgentWebProxy] Config proxy use DefaultNetworkCredentials.
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'ProxyBypass': '/home/myuser/Az/CL_A01/.proxybypass'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'Certificates': '/home/myuser/Az/CL_A01/.certificates'
[2021-04-21 12:51:45Z INFO AgentCertificateManager] No certificate setting found.
[2021-04-21 12:51:45Z INFO Agent] ExecuteCommand
[2021-04-21 12:51:45Z INFO ConfigurationStore] currentAssemblyLocation: /home/myuser/Az/CL_A01/bin/Agent.Listener.dll
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO ConfigurationStore] binPath: /home/myuser/Az/CL_A01/bin
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO ConfigurationStore] RootFolder: /home/myuser/Az/CL_A01
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'Agent': '/home/myuser/Az/CL_A01/.agent'
[2021-04-21 12:51:45Z INFO ConfigurationStore] ConfigFilePath: /home/myuser/Az/CL_A01/.agent
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'Credentials': '/home/myuser/Az/CL_A01/.credentials'
[2021-04-21 12:51:45Z INFO ConfigurationStore] CredFilePath: /home/myuser/Az/CL_A01/.credentials
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'Service': '/home/myuser/Az/CL_A01/.service'
[2021-04-21 12:51:45Z INFO ConfigurationStore] ServiceConfigFilePath: /home/myuser/Az/CL_A01/.service
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'Autologon': '/home/myuser/Az/CL_A01/.autologon'
[2021-04-21 12:51:45Z INFO ConfigurationStore] AutoLogonSettingsFilePath: /home/myuser/Az/CL_A01/.autologon
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'Options': '/home/myuser/Az/CL_A01/.options'
[2021-04-21 12:51:45Z INFO ConfigurationStore] RuntimeOptionsFilePath: /home/myuser/Az/CL_A01/.options
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'SetupInfo': '/home/myuser/Az/CL_A01/.setup_info'
[2021-04-21 12:51:45Z INFO ConfigurationStore] SetupInfoFilePath: /home/myuser/Az/CL_A01/.setup_info
[2021-04-21 12:51:45Z INFO ConfigurationManager] LoadSettings
[2021-04-21 12:51:45Z INFO ConfigurationStore] IsConfigured()
[2021-04-21 12:51:45Z INFO ConfigurationStore] IsConfigured: True
[2021-04-21 12:51:45Z INFO ConfigurationManager] Is configured: True
[2021-04-21 12:51:45Z INFO ConfigurationStore] Read setting file: 224 chars
[2021-04-21 12:51:45Z INFO ConfigurationManager] Settings Loaded
[2021-04-21 12:51:45Z INFO ConfigurationStore] IsServiceConfigured()
[2021-04-21 12:51:45Z INFO ConfigurationStore] IsServiceConfigured: True
[2021-04-21 12:51:45Z INFO ConfigurationStore] IsConfigured()
[2021-04-21 12:51:45Z INFO ConfigurationStore] IsConfigured: True
[2021-04-21 12:51:45Z INFO ConfigurationManager] Is configured: True
[2021-04-21 12:51:45Z INFO Agent] Set agent startup type - Service
[2021-04-21 12:51:45Z INFO CommandSettings] Flag 'once': 'False'
[2021-04-21 12:51:45Z INFO CommandSettings] Flag 'once': 'False'
[2021-04-21 12:51:45Z INFO Agent] RunAsync
[2021-04-21 12:51:45Z INFO ConfigurationManager] LoadSettings
[2021-04-21 12:51:45Z INFO ConfigurationStore] IsConfigured()
[2021-04-21 12:51:45Z INFO ConfigurationStore] IsConfigured: True
[2021-04-21 12:51:45Z INFO ConfigurationManager] Is configured: True
[2021-04-21 12:51:45Z INFO ConfigurationManager] Settings Loaded
[2021-04-21 12:51:45Z INFO MessageListener] {
  "AcceptTeeEula": true,
  "AgentId": 16,
  "AgentName": "DS-AIPC-CL01-LN_CL_A01",
  "AlwaysExtractTask": true,
  "PoolId": 13,
  "PoolName": "AIPC",
  "ServerUrl": "https://dev.azure.com/iii40/",
  "WorkFolder": "_work"
}
[2021-04-21 12:51:45Z INFO Terminal] WRITE LINE: Scanning for tool capabilities.
[2021-04-21 12:51:45Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Capabilities.ICapabilitiesProvider'
[2021-04-21 12:51:45Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Capabilities.AgentCapabilitiesProvider, Microsoft.VisualStudio.Services.Agent
[2021-04-21 12:51:45Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Capabilities.EnvironmentCapabilitiesProvider, Microsoft.VisualStudio.Services.Agent
[2021-04-21 12:51:45Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Capabilities.NixCapabilitiesProvider, Microsoft.VisualStudio.Services.Agent
[2021-04-21 12:51:45Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Capabilities.UserCapabilitiesProvider, Microsoft.VisualStudio.Services.Agent
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Adding '_': './externals/node10/bin/node'
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Adding 'HOME': '/home/myuser'
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Adding 'INVOCATION_ID': 'e0b1fbc350c943468aae3483dfa11a1a'
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Adding 'JOURNAL_STREAM': '9:92237'
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Adding 'LANG': 'en_US.UTF-8'
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Adding 'LOGNAME': 'myuser'
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Adding 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin'
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Adding 'PWD': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Adding 'SHELL': '/bin/bash'
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Skipping: 'SHLVL'
[2021-04-21 12:51:45Z INFO EnvironmentCapabilitiesProvider] Adding 'USER': 'myuser'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'android'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Checking file: 'tools/android'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Checking file: '/home/myuser/Library/Developer/Xamarin/android-sdk-macosx/tools/android'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'ant'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'waagent'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'bundle'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'clang'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'cmake'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'curl'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Location: '{matches.First()}'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Adding 'curl': '/usr/bin/curl'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'docker'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Location: '{matches.First()}'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Adding 'docker': '/usr/bin/docker'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'dotnet'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'git'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Location: '{matches.First()}'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Adding 'git': '/usr/bin/git'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'gulp'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'java'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'javac'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'make'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Location: '{matches.First()}'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Adding 'make': '/usr/bin/make'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'mvn'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'xbuild'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Checking file: '/Library/Frameworks/Mono.framework/Commands/xbuild'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'msbuild'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Checking file: '/Library/Frameworks/Mono.framework/Commands/msbuild'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'node'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'nodejs'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'npm'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'python'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Location: '{matches.First()}'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Adding 'python': '/usr/bin/python'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'python3'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Location: '{matches.First()}'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Adding 'python3': '/usr/bin/python3'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'sh'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Location: '{matches.First()}'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Adding 'sh': '/bin/sh'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'svn'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'ruby'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'rake'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'svn'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'mdtool'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Checking file: '/Applications/Xamarin Studio.app/Contents/MacOS/mdtool'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Checking file: '/Applications/Visual Studio.app/Contents/MacOS/vstool'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'generator'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Checking file: '/Library/Frameworks/Xamarin.Android.framework/Commands/generator'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Checking file: '/Library/Frameworks/Xamarin.Android.framework/Versions/Current/Version'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Which: 'xcode-select'
[2021-04-21 12:51:45Z INFO CapabilitiesBuilder] Not found.
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO AgentCapabilitiesProvider] Adding 'Agent.Name': 'DS-AIPC-CL01-LN_CL_A01'
[2021-04-21 12:51:45Z INFO AgentCapabilitiesProvider] Adding 'Agent.OS': 'Linux'
[2021-04-21 12:51:45Z INFO AgentCapabilitiesProvider] Adding 'Agent.OSArchitecture': 'X64'
[2021-04-21 12:51:45Z INFO AgentCapabilitiesProvider] Adding 'InteractiveSession': 'False'
[2021-04-21 12:51:45Z INFO AgentCapabilitiesProvider] Adding 'Agent.Version': '2.185.1'
[2021-04-21 12:51:45Z INFO AgentCapabilitiesProvider] Adding 'Agent.ComputerName': 'ds-aipc-cl01-ln'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO AgentCapabilitiesProvider] Adding 'Agent.HomeDirectory': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO MessageListener] Loading Credentials
[2021-04-21 12:51:45Z INFO ConfigurationStore] HasCredentials()
[2021-04-21 12:51:45Z INFO ConfigurationStore] stored True
[2021-04-21 12:51:45Z INFO CredentialManager] GetCredentialProvider
[2021-04-21 12:51:45Z INFO CredentialManager] Creating type OAuth
[2021-04-21 12:51:45Z INFO CredentialManager] Creating credential type: OAuth
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:51:45Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:51:45Z INFO HostContext] Well known config file 'RSACredentials': '/home/myuser/Az/CL_A01/.credentials_rsaparams'
[2021-04-21 12:51:45Z INFO RSAFileKeyManager] Loading RSA key parameters from file /home/myuser/Az/CL_A01/.credentials_rsaparams
[2021-04-21 12:51:45Z INFO Terminal] WRITE LINE: Connecting to the server.
[2021-04-21 12:51:45Z INFO MessageListener] Attempt to create session.
[2021-04-21 12:51:45Z INFO MessageListener] Connecting to the Agent Server...
[2021-04-21 12:51:46Z INFO AgentServer] Establish connection with 100 seconds timeout.
[2021-04-21 12:51:46Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 12:51:46Z WARN VisualStudioServices] Authentication failed with status code 401.
Cache-Control: no-cache
Pragma: no-cache
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"
WWW-Authenticate: Bearer authorization_uri=https://login.microsoftonline.com/5dbf1add-202a-4b8d-815b-bf0fb024e033, Basic realm="https://tfsprodweu2.app.visualstudio.com/", TFS-Federated
X-TFS-ProcessId: ffc78ef5-0f8d-40ab-bb40-ad61acd99599
Strict-Transport-Security: max-age=31536000; includeSubDomains
ActivityId: 82b69e7d-d56c-4ebd-bd6b-5f56d0f878c5
X-TFS-Session: db486bcc-9cbf-4b53-aa93-a938e65872c3
X-VSS-E2EID: 02121d2e-b621-4a6a-b666-a329f42d0c30
X-Frame-Options: SAMEORIGIN
X-TFS-FedAuthRealm: https://tfsprodweu2.app.visualstudio.com/
X-TFS-FedAuthIssuer: https://dev.azure.com/iii40/
X-VSS-AuthorizationEndpoint: https://iii40.vssps.visualstudio.com/
X-VSS-ResourceTenant: 5dbf1add-202a-4b8d-815b-bf0fb024e033
X-VSS-S2STargetService: 00000002-0000-8888-8000-000000000000/visualstudio.com
X-TFS-FedAuthRedirect: https://spsprodweu4.vssps.visualstudio.com/_signin?realm=dev.azure.com&reply_to=https%3A%2F%2Fdev.azure.com%2Fiii40%2F_apis%2FconnectionData%3FconnectOptions%3D1%26lastChangeId%3D-1%26lastChangeId64%3D-1&redirect=1&hid=b319efdf-6832-4088-a44f-f5f9d1287f67&context=eyJodCI6MiwiaGlkIjoiODg4NWRkNzEtYmJhOC00MDI3LTgwNDQtNDYyZDg2ZWM5YWU0IiwicXMiOnt9LCJyciI6IiIsInZoIjoiIiwiY3YiOiIiLCJjcyI6IiJ90#ctx=eyJTaWduSW5Db29raWVEb21haW5zIjpbImh0dHBzOi8vbG9naW4ubWljcm9zb2Z0b25saW5lLmNvbSIsImh0dHBzOi8vbG9naW4ubWljcm9zb2Z0b25saW5lLmNvbSJdfQ2
Request-Context: appId=cid-v1:a32646d4-6542-4ff0-b4b1-416ef6b2d466
Access-Control-Expose-Headers: Request-Context
X-Content-Type-Options: nosniff
X-MSEdge-Ref: Ref A: 7511112430B045FA8A794B28F8CE22C5 Ref B: FRAEDGE0809 Ref C: 2021-04-21T12:51:46Z
Date: Wed, 21 Apr 2021 12:51:46 GMT

[2021-04-21 12:51:46Z INFO RSAFileKeyManager] Loading RSA key parameters from file /home/myuser/Az/CL_A01/.credentials_rsaparams
[2021-04-21 12:51:46Z INFO RSAFileKeyManager] Loading RSA key parameters from file /home/myuser/Az/CL_A01/.credentials_rsaparams
[2021-04-21 12:51:47Z INFO VisualStudioServices] AAD Correlation ID for this token request: Unknown
[2021-04-21 12:51:47Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 12:51:48Z INFO AgentServer] Establish connection with 60 seconds timeout.
[2021-04-21 12:51:48Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 12:51:48Z INFO AgentServer] Establish connection with 60 seconds timeout.
[2021-04-21 12:51:48Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 12:51:48Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 12:51:48Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 12:51:49Z INFO MessageListener] VssConnection created
[2021-04-21 12:51:49Z INFO MessageListener] Session created.
[2021-04-21 12:51:49Z INFO Terminal] WRITE LINE: 2021-04-21 12:51:49Z: Listening for Jobs
[2021-04-21 12:51:49Z INFO JobDispatcher] Set agent/worker IPC timeout to 30 seconds.
[2021-04-21 12:54:45Z INFO RSAFileKeyManager] Loading RSA key parameters from file /home/myuser/Az/CL_A01/.credentials_rsaparams
[2021-04-21 12:54:45Z INFO MessageListener] Message '1' received from session '11724fd5-0523-414b-8604-04d7d897fd0d'.
[2021-04-21 12:54:45Z INFO JobDispatcher] Job request 6354 for plan b25ced20-4a18-4eca-b318-2979a6244fb9 job 3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4 received.
[2021-04-21 12:54:45Z INFO Terminal] WRITE LINE: 2021-04-21 12:54:45Z: Running job: Workload
[2021-04-21 12:54:45Z INFO AgentServer] Refresh JobRequest VssConnection to get on a different AFD node.
[2021-04-21 12:54:45Z INFO AgentServer] Establish connection with 30 seconds timeout.
[2021-04-21 12:54:45Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 12:54:45Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 12:54:46Z INFO JobDispatcher] Start renew job request 6354 for job 3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4.
[2021-04-21 12:54:46Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:04:46 PM
[2021-04-21 12:54:46Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper] Starting process:
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper]   File name: '/home/myuser/Az/CL_A01/bin/Agent.Worker'
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper]   Arguments: 'spawnclient 115 118'
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper]   Working directory: '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper]   Require exit code zero: 'False'
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper]   Encoding web name:  ; code page: ''
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper]   Force kill process on cancellation: 'True'
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper]   Redirected STDIN: 'False'
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper]   Persist current code page: 'False'
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper]   Keep redirected STDIN open: 'False'
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper]   High priority process: 'True'
[2021-04-21 12:54:46Z INFO ProcessInvokerWrapper] Process started with process id 19101, waiting for process exit.
[2021-04-21 12:54:46Z INFO JobDispatcher] Send job request message to worker for job 3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4 (30 KB).
[2021-04-21 12:54:46Z INFO JobDispatcher] Took 9 ms to send job message to worker
[2021-04-21 12:54:46Z INFO JobNotification] Entering JobStarted Notification
[2021-04-21 12:54:46Z INFO JobNotification] Entering StartMonitor
[2021-04-21 12:55:46Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:05:46 PM
[2021-04-21 12:56:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:06:46 PM
[2021-04-21 12:57:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:07:46 PM
[2021-04-21 12:58:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:08:47 PM
[2021-04-21 12:59:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:09:47 PM
[2021-04-21 13:00:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:10:47 PM
[2021-04-21 13:01:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:11:47 PM
[2021-04-21 13:02:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:12:47 PM
[2021-04-21 13:03:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:13:47 PM
[2021-04-21 13:04:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:14:47 PM
[2021-04-21 13:05:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:15:47 PM
[2021-04-21 13:06:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:16:47 PM
[2021-04-21 13:07:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:17:47 PM
[2021-04-21 13:08:47Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:18:47 PM
[2021-04-21 13:09:48Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:19:48 PM
[2021-04-21 13:10:48Z INFO JobDispatcher] Successfully renew job request 6354, job is valid till 4/21/2021 1:20:48 PM
[2021-04-21 13:11:04Z INFO RSAFileKeyManager] Loading RSA key parameters from file /home/myuser/Az/CL_A01/.credentials_rsaparams
[2021-04-21 13:11:04Z INFO MessageListener] Message '2' received from session '11724fd5-0523-414b-8604-04d7d897fd0d'.
[2021-04-21 13:11:04Z INFO JobDispatcher] Job cancellation request 3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4 received, cancellation timeout 5 minutes.
[2021-04-21 13:11:04Z INFO JobDispatcher] Send job cancellation message to worker for job 3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4.
[2021-04-21 13:11:17Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2021-04-21 13:11:17Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2021-04-21 13:11:17Z INFO ProcessInvokerWrapper] Exited process 19101 with exit code 103
[2021-04-21 13:11:17Z INFO ProcessInvokerWrapper] Finished process 19101 with exit code 103, and elapsed time 00:16:30.7875053.
[2021-04-21 13:11:17Z INFO JobDispatcher] finish job request for job 3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4 with result: Canceled
[2021-04-21 13:11:17Z INFO Terminal] WRITE LINE: 2021-04-21 13:11:17Z: Job Workload completed with result: Canceled
[2021-04-21 13:11:17Z INFO JobDispatcher] Stop renew job request for job 3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4.
[2021-04-21 13:11:17Z INFO JobDispatcher] job renew has been canceled, stop renew job request 6354.
[2021-04-21 13:11:17Z INFO JobNotification] Entering JobCompleted Notification
[2021-04-21 13:11:17Z INFO JobNotification] Entering EndMonitor

Worker_20210421-125447-utc.log

[2021-04-21 12:54:47Z INFO Program] Version: 2.185.1
[2021-04-21 12:54:47Z INFO Program] Commit: 45c52d01eec6c18e3a3e5d8e2a4859fbfc90eff7
[2021-04-21 12:54:47Z INFO Program] Culture: en-US
[2021-04-21 12:54:47Z INFO Program] UI Culture: en-US
[2021-04-21 12:54:47Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:47Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:47Z INFO HostContext] Well known config file 'Proxy': '/home/myuser/Az/CL_A01/.proxy'
[2021-04-21 12:54:47Z INFO VstsAgentWebProxy] Config proxy at: http://139.22.102.14:8888.
[2021-04-21 12:54:47Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:47Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:47Z INFO HostContext] Well known config file 'ProxyCredentials': '/home/myuser/Az/CL_A01/.proxycredentials'
[2021-04-21 12:54:47Z INFO VstsAgentWebProxy] Config proxy use DefaultNetworkCredentials.
[2021-04-21 12:54:47Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:47Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:47Z INFO HostContext] Well known config file 'ProxyBypass': '/home/myuser/Az/CL_A01/.proxybypass'
[2021-04-21 12:54:47Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:47Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:47Z INFO HostContext] Well known config file 'Certificates': '/home/myuser/Az/CL_A01/.certificates'
[2021-04-21 12:54:47Z INFO AgentCertificateManager] No certificate setting found.
[2021-04-21 12:54:47Z INFO Worker] Waiting to receive the job message from the channel.
[2021-04-21 12:54:47Z INFO Worker] Message received.
[2021-04-21 12:54:47Z INFO Worker] Job message:
 {
  "mask": [
    {
      "type": "regex",
      "value": "***"
    },
    {
      "type": "regex",
      "value": "***"
    }
  ],
  "steps": [
    {
      "inputs": {
        "repository": "self",
        "clean": "false",
        "fetchDepth": "0",
        "lfs": "false"
      },
      "type": "task",
      "reference": {
        "id": "6d15af64-176c-496d-b583-fd2ae21d4df4",
        "name": "Checkout",
        "version": "1.0.0"
      },
      "id": "a3e98e35-6a93-5792-7618-3fb133883d3a",
      "name": "__system_1",
      "displayName": "Checkout"
    },
    {
      "environment": {
        "REPOSITORY_PATH": "$(Build.Repository.LocalPath)",
        "DOCKER_PWD": "$(IDSContainerRegistry_PWD)",
        "NLP_ACCESS_SERVICE_URI": " THIS WAS REMOVED DUE TO PHI "
      },
      "inputs": {
        "targetType": "inline",
        "script": " THIS WAS REMOVED DUE TO PHI "
      },
      "type": "task",
      "reference": {
        "id": "6c731c3c-3c68-459a-a5c9-bde6e6595b5b",
        "name": "Bash",
        "version": "3.182.0"
      },
      "id": "5ff46123-0783-578c-d76d-bac996bea75d",
      "name": "Bash",
      "displayName": "Run tests"
    },
    {
      "inputs": {
        "testRunner": "NUnit",
        "testResultsFiles": "test_results.xml",
        "searchFolder": "$(Build.Repository.LocalPath)",
        "failTaskOnFailedTests": "true",
        "testRunTitle": "iTests NLP.QueryData (queries)",
        "platform": "aipc-nlp"
      },
      "type": "task",
      "reference": {
        "id": "0b0f01ed-7dde-43ff-9cbb-e48954daf9b1",
        "name": "PublishTestResults",
        "version": "2.180.0"
      },
      "id": "454f32c1-0af2-5b24-ae79-c15ff910edfe",
      "name": "PublishTestResults",
      "displayName": "PublishTestResults"
    }
  ],
  "variables": {
    "system.debug": {
      "value": "false"
    },
    "AZURE_BLOB_PASSWORD": {
      "value": "***",
      "isSecret": true
    },
    "AZURE_BLOB_USERNAME": {
      "value": "***",
      "isSecret": true
    },
    "AZURE_NPM_TOKEN": {
      "value": "***",
      "isSecret": true
    },
    "IDSContainerRegistry_PWD": {
      "value": "***",
      "isSecret": true
    },
    "SHSDS_NPM_TOKEN": {
      "value": "***",
      "isSecret": true
    },
    "SHUI_NPM_TOKEN": {
      "value": "***",
      "isSecret": true
    },
    "VSTS_PAT": {
      "value": "***",
      "isSecret": true
    },
    "QUERY_BUNDLE_PRIVATE_KEY": {
      "value": "***",
      "isSecret": true
    },
    "resources.triggeringCategory": {
      "value": ""
    },
    "resources.triggeringAlias": {
      "value": ""
    },
    "system": {
      "value": "build",
      "isReadOnly": true
    },
    "system.hosttype": {
      "value": "build",
      "isReadOnly": true
    },
    "system.servertype": {
      "value": "Hosted",
      "isReadOnly": true
    },
    "system.culture": {
      "value": "en-US",
      "isReadOnly": true
    },
    "system.collectionId": {
      "value": "b319efdf-6832-4088-a44f-f5f9d1287f67",
      "isReadOnly": true
    },
    "system.collectionUri": {
      "value": "https://dev.azure.com/iii40/",
      "isReadOnly": true
    },
    "system.teamFoundationCollectionUri": {
      "value": "https://dev.azure.com/iii40/",
      "isReadOnly": true
    },
    "system.taskDefinitionsUri": {
      "value": "https://dev.azure.com/iii40/",
      "isReadOnly": true
    },
    "system.pipelineStartTime": {
      "value": "2021-04-21 12:54:43+00:00",
      "isReadOnly": true
    },
    "system.teamProject": {
      "value": "IDS_Prototypes",
      "isReadOnly": true
    },
    "system.teamProjectId": {
      "value": "48b0cff6-904c-4085-ab25-5917962932eb",
      "isReadOnly": true
    },
    "system.definitionId": {
      "value": "116",
      "isReadOnly": true
    },
    "build.definitionName": {
      "value": "QueryDataRegressionTests(iTests - Queries)",
      "isReadOnly": true
    },
    "build.definitionVersion": {
      "value": "4",
      "isReadOnly": true
    },
    "build.queuedBy": {
      "value": "[PII]",
      "isReadOnly": true
    },
    "build.queuedById": {
      "value": "30b446c1-0f47-66b0-a10c-32dcd3edb2d5",
      "isReadOnly": true
    },
    "build.requestedFor": {
      "value": "[PII]",
      "isReadOnly": true
    },
    "build.requestedForId": {
      "value": "30b446c1-0f47-66b0-a10c-32dcd3edb2d5",
      "isReadOnly": true
    },
    "build.requestedForEmail": {
      "value": "[PII]",
      "isReadOnly": true
    },
    "build.sourceVersion": {
      "value": "[PII]",
      "isReadOnly": true
    },
    "build.sourceBranch": {
      "value": "[PII]",
      "isReadOnly": true
    },
    "build.sourceBranchName": {
      "value": "[PII]",
      "isReadOnly": true
    },
    "build.reason": {
      "value": "Manual",
      "isReadOnly": true
    },
    "system.pullRequest.isFork": {
      "value": "False",
      "isReadOnly": true
    },
    "system.jobParallelismTag": {
      "value": "Private",
      "isReadOnly": true
    },
    "system.enableAccessToken": {
      "value": "SecretVariable",
      "isReadOnly": true
    },
    "MSDEPLOY_HTTP_USER_AGENT": {
      "value": "VSTS_b319efdf-6832-4088-a44f-f5f9d1287f67_build_116_0",
      "isReadOnly": true
    },
    "AZURE_HTTP_USER_AGENT": {
      "value": "VSTS_b319efdf-6832-4088-a44f-f5f9d1287f67_build_116_0",
      "isReadOnly": true
    },
    "build.buildId": {
      "value": "5106",
      "isReadOnly": true
    },
    "build.buildUri": {
      "value": "vstfs:///Build/Build/5106",
      "isReadOnly": true
    },
    "build.buildNumber": {
      "value": "20210421.11",
      "isReadOnly": true
    },
    "build.containerId": {
      "value": "7649494",
      "isReadOnly": true
    },
    "system.isScheduled": {
      "value": "False",
      "isReadOnly": true
    },
    "system.definitionName": {
      "value": "QueryDataRegressionTests(iTests - Queries)",
      "isReadOnly": true
    },
    "system.planId": {
      "value": "b25ced20-4a18-4eca-b318-2979a6244fb9",
      "isReadOnly": true
    },
    "system.timelineId": {
      "value": "b25ced20-4a18-4eca-b318-2979a6244fb9",
      "isReadOnly": true
    },
    "system.stageDisplayName": {
      "value": "__default",
      "isReadOnly": true
    },
    "system.stageId": {
      "value": "96ac2280-8cb4-5df5-99de-dd2da759617d",
      "isReadOnly": true
    },
    "system.stageName": {
      "value": "__default",
      "isReadOnly": true
    },
    "system.stageAttempt": {
      "value": "1",
      "isReadOnly": true
    },
    "system.phaseDisplayName": {
      "value": "Workload",
      "isReadOnly": true
    },
    "system.phaseId": {
      "value": "2178fd71-e0a4-5da3-6b29-a5cc38ca2c2a",
      "isReadOnly": true
    },
    "system.phaseName": {
      "value": "Workload",
      "isReadOnly": true
    },
    "system.phaseAttempt": {
      "value": "1",
      "isReadOnly": true
    },
    "system.jobIdentifier": {
      "value": "Workload.__default",
      "isReadOnly": true
    },
    "system.jobAttempt": {
      "value": "1",
      "isReadOnly": true
    },
    "System.JobPositionInPhase": {
      "value": "1",
      "isReadOnly": true
    },
    "System.TotalJobsInPhase": {
      "value": "1",
      "isReadOnly": true
    },
    "system.jobDisplayName": {
      "value": "Workload",
      "isReadOnly": true
    },
    "system.jobId": {
      "value": "3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4",
      "isReadOnly": true
    },
    "system.jobName": {
      "value": "__default",
      "isReadOnly": true
    },
    "system.jobTimeout": {
      "value": "60",
      "isReadOnly": true
    },
    "system.accessToken": {
      "value": ***,
      "isSecret": true
    },
    "agent.retainDefaultEncoding": {
      "value": "false",
      "isReadOnly": true
    },
    "agent.readOnlyVariables": {
      "value": "true",
      "isReadOnly": true
    },
    "agent.useWorkspaceId": {
      "value": "true",
      "isReadOnly": true
    },
    "agent.taskRestrictionsEnforcementMode": {
      "value": "WarningOnly",
      "isReadOnly": true
    },
    "agent.enableTaskRestrictionsTelemetry": {
      "value": "true",
      "isReadOnly": true
    },
    "agent.disablelogplugin.TestResultLogPlugin": {
      "value": "true",
      "isReadOnly": true
    },
    "agent.disablelogplugin.TestFilePublisherPlugin": {
      "value": "true",
      "isReadOnly": true
    },
    "build.repository.id": {
      "value": "f66f5b70-9dd1-442c-be6d-e1b42634b15a",
      "isReadOnly": true
    },
    "build.repository.name": {
      "value": "Fork.Tools.NlpQueryData",
      "isReadOnly": true
    },
    "build.repository.uri": {
      "value": "https://iii40@dev.azure.com/iii40/IDS_Prototypes/_git/Fork.Tools.NlpQueryData",
      "isReadOnly": true
    },
    "build.sourceVersionAuthor": {
      "value": "[PII]",
      "isReadOnly": true
    },
    "build.sourceVersionMessage": {
      "value": "Merged PR 1457: nl metastasis added attributes\n\nnl metastasis added attributes",
      "isReadOnly": true
    }
  },
  "messageType": "PipelineAgentJobRequest",
  "plan": {
    "scopeIdentifier": "48b0cff6-904c-4085-ab25-5917962932eb",
    "planType": "Build",
    "version": 16,
    "planId": "b25ced20-4a18-4eca-b318-2979a6244fb9",
    "planGroup": "Build:48b0cff6-904c-4085-ab25-5917962932eb:5106",
    "artifactUri": "vstfs:///Build/Build/5106",
    "artifactLocation": null,
    "definition": {
      "_links": {
        "web": {
          "href": "https://iii40.visualstudio.com/48b0cff6-904c-4085-ab25-5917962932eb/_build/definition?definitionId=116"
        },
        "self": {
          "href": "https://iii40.visualstudio.com/48b0cff6-904c-4085-ab25-5917962932eb/_apis/build/Definitions/116"
        }
      },
      "id": 116,
      "name": "QueryDataRegressionTests(iTests - Queries)"
    },
    "owner": {
      "_links": {
        "web": {
          "href": "https://iii40.visualstudio.com/48b0cff6-904c-4085-ab25-5917962932eb/_build/results?buildId=5106"
        },
        "self": {
          "href": "https://iii40.visualstudio.com/48b0cff6-904c-4085-ab25-5917962932eb/_apis/build/Builds/5106"
        }
      },
      "id": 5106,
      "name": "20210421.11"
    }
  },
  "timeline": {
    "id": "b25ced20-4a18-4eca-b318-2979a6244fb9",
    "changeId": 5,
    "location": null
  },
  "jobId": "3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4",
  "jobDisplayName": "Workload",
  "jobName": "__default",
  "jobContainer": null,
  "requestId": 0,
  "lockedUntil": "0001-01-01T00:00:00",
  "resources": {
    "endpoints": [
      {
        "data": {
          "ServerId": "b319efdf-6832-4088-a44f-f5f9d1287f67",
          "ServerName": "iii40"
        },
        "name": "SystemVssConnection",
        "url": "https://dev.azure.com/iii40/",
        "authorization": {
          "parameters": {
            "AccessToken": ***
          },
          "scheme": "OAuth"
        },
        "isShared": false,
        "isReady": true
      }
    ],
    "repositories": [
      {
        "properties": {
          "id": "f66f5b70-9dd1-442c-be6d-e1b42634b15a",
          "type": "Git",
          "version": "89fa75e1fb97dc13274c1ef63ae87729f5220507",
          "name": "Fork.Tools.NlpQueryData",
          "project": "48b0cff6-904c-4085-ab25-5917962932eb",
          "defaultBranch": "refs/heads/master",
          "ref": "refs/heads/master",
          "url": "https://iii40@dev.azure.com/iii40/IDS_Prototypes/_git/Fork.Tools.NlpQueryData",
          "versionInfo": {
            "author": "[PII]"
          },
          "checkoutOptions": {
            "clean": "false",
            "fetchDepth": "0",
            "lfs": "false"
          }
        },
        "alias": "self",
        "endpoint": {
          "name": "SystemVssConnection"
        }
      }
    ]
  },
  "workspace": {
    "clean": "all"
  }
}
[2021-04-21 12:54:47Z INFO JobRunner] Job ID 3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4
[2021-04-21 12:54:47Z INFO JobRunner] Creating job server with URL: https://dev.azure.com/iii40/
[2021-04-21 12:54:47Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 12:54:47Z INFO Worker] Listening for cancel message from the channel.
[2021-04-21 12:54:47Z INFO Worker] Waiting for the job to complete or for a cancel message from the channel.
[2021-04-21 12:54:48Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 12:54:48Z INFO JobServerQueue] Start process web console line queue.
[2021-04-21 12:54:48Z INFO JobServerQueue] Start process file upload queue.
[2021-04-21 12:54:48Z INFO JobServerQueue] Start process timeline update queue.
[2021-04-21 12:54:48Z INFO ConfigurationStore] currentAssemblyLocation: /home/myuser/Az/CL_A01/bin/Agent.Worker.dll
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO ConfigurationStore] binPath: /home/myuser/Az/CL_A01/bin
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO ConfigurationStore] RootFolder: /home/myuser/Az/CL_A01
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known config file 'Agent': '/home/myuser/Az/CL_A01/.agent'
[2021-04-21 12:54:48Z INFO ConfigurationStore] ConfigFilePath: /home/myuser/Az/CL_A01/.agent
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known config file 'Credentials': '/home/myuser/Az/CL_A01/.credentials'
[2021-04-21 12:54:48Z INFO ConfigurationStore] CredFilePath: /home/myuser/Az/CL_A01/.credentials
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known config file 'Service': '/home/myuser/Az/CL_A01/.service'
[2021-04-21 12:54:48Z INFO ConfigurationStore] ServiceConfigFilePath: /home/myuser/Az/CL_A01/.service
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known config file 'Autologon': '/home/myuser/Az/CL_A01/.autologon'
[2021-04-21 12:54:48Z INFO ConfigurationStore] AutoLogonSettingsFilePath: /home/myuser/Az/CL_A01/.autologon
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known config file 'Options': '/home/myuser/Az/CL_A01/.options'
[2021-04-21 12:54:48Z INFO ConfigurationStore] RuntimeOptionsFilePath: /home/myuser/Az/CL_A01/.options
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known config file 'SetupInfo': '/home/myuser/Az/CL_A01/.setup_info'
[2021-04-21 12:54:48Z INFO ConfigurationStore] SetupInfoFilePath: /home/myuser/Az/CL_A01/.setup_info
[2021-04-21 12:54:48Z INFO ConfigurationStore] Read setting file: 224 chars
[2021-04-21 12:54:48Z INFO ExecutionContext] WorkspaceIdentifier '28b61e01a4009ff5e6c0dff78d2508bfee58a7b3' created for repos Microsoft.VisualStudio.Services.Agent.Worker.Build.RepositoryTrackingInfo
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Diag': '/home/myuser/Az/CL_A01/_diag'
[2021-04-21 12:54:48Z INFO JobRunner] Starting the job execution context.
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:48Z INFO JobRunner] Validating directory permissions for: '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Tools': '/home/myuser/Az/CL_A01/_work/_tool'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:48Z INFO HostContext] Well known directory 'Temp': '/home/myuser/Az/CL_A01/_work/_temp'
[2021-04-21 12:54:48Z INFO JobRunner] Creating task server with https://dev.azure.com/iii40/
[2021-04-21 12:54:48Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 12:54:49Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 12:54:49Z INFO JobServerQueue] Try to append 1 batches web console lines for record '3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4', success rate: 1/1.
[2021-04-21 12:54:50Z INFO JobRunner] Getting job extension.
[2021-04-21 12:54:50Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.IJobExtension'
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.BuildJobExtension, Agent.Worker
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Release.ReleaseJobExtension, Agent.Worker
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Release.DeploymentJobExtension, Agent.Worker
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Maintenance.MaintenanceJobExtension, Agent.Worker
[2021-04-21 12:54:50Z INFO JobRunner] Initialize job. Getting all job steps.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Diag': '/home/myuser/Az/CL_A01/_diag'
[2021-04-21 12:54:50Z INFO BuildJobExtension] Run initial step from extension BuildJobExtension.
[2021-04-21 12:54:50Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.Build.ISourceProvider'
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.ExternalGitSourceProvider, Agent.Worker
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.GitHubSourceProvider, Agent.Worker
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.GitHubEnterpriseSourceProvider, Agent.Worker
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.BitbucketSourceProvider, Agent.Worker
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.SvnSourceProvider, Agent.Worker
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.TfsGitSourceProvider, Agent.Worker
[2021-04-21 12:54:50Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.TfsVCSourceProvider, Agent.Worker
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO BuildDirectoryManager] Checking if build directory exists: '/home/myuser/Az/CL_A01/_work/1'
[2021-04-21 12:54:50Z INFO BuildDirectoryManager] Creating build directory.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO BuildDirectoryManager] Checking if artifacts directory exists: '/home/myuser/Az/CL_A01/_work/1/a'
[2021-04-21 12:54:50Z INFO BuildDirectoryManager] Creating artifacts directory.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO BuildDirectoryManager] Checking if test results directory exists: '/home/myuser/Az/CL_A01/_work/1/TestResults'
[2021-04-21 12:54:50Z INFO BuildDirectoryManager] Creating test results directory.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO BuildDirectoryManager] Creating binaries directory.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO BuildDirectoryManager] Creating source directory.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO BuildDirectoryManager] Set repository path for repository self to '/home/myuser/Az/CL_A01/_work/1/s'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO BuildJobExtension] Checking repository name self
[2021-04-21 12:54:50Z INFO BuildJobExtension] Downloading task definitions.
[2021-04-21 12:54:50Z INFO TaskManager] Skip download checkout task.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 12:54:50Z INFO TaskManager] Ensuring task exists: ID '6c731c3c-3c68-459a-a5c9-bde6e6595b5b', version '3.182.0', name 'Bash', directory '/home/myuser/Az/CL_A01/_work/_tasks/Bash_6c731c3c-3c68-459a-a5c9-bde6e6595b5b/3.182.0'.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'TaskZips': '/home/myuser/Az/CL_A01/_work/_taskzips'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 12:54:50Z INFO JobServerQueue] Try to append 1 batches web console lines for record '88c79989-d538-490f-9df7-9c4079986a8c', success rate: 1/1.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'TaskZips': '/home/myuser/Az/CL_A01/_work/_taskzips'
[2021-04-21 12:54:50Z INFO TaskManager] Finished getting task.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 12:54:50Z INFO TaskManager] Ensuring task exists: ID '0b0f01ed-7dde-43ff-9cbb-e48954daf9b1', version '2.180.0', name 'PublishTestResults', directory '/home/myuser/Az/CL_A01/_work/_tasks/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1/2.180.0'.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'TaskZips': '/home/myuser/Az/CL_A01/_work/_taskzips'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 12:54:50Z INFO JobServerQueue] Try to append 1 batches web console lines for record '88c79989-d538-490f-9df7-9c4079986a8c', success rate: 1/1.
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:50Z INFO HostContext] Well known directory 'TaskZips': '/home/myuser/Az/CL_A01/_work/_taskzips'
[2021-04-21 12:54:51Z INFO TaskManager] Finished getting task.
[2021-04-21 12:54:51Z INFO BuildJobExtension] Parsing all task's condition inputs.
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'TaskZips': '/home/myuser/Az/CL_A01/_work/_taskzips'
[2021-04-21 12:54:51Z INFO TaskManager] Loading task definition '/home/myuser/Az/CL_A01/_work/_tasks/Bash_6c731c3c-3c68-459a-a5c9-bde6e6595b5b/3.182.0/task.json'.
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'TaskZips': '/home/myuser/Az/CL_A01/_work/_taskzips'
[2021-04-21 12:54:51Z INFO TaskManager] Loading task definition '/home/myuser/Az/CL_A01/_work/_tasks/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1/2.180.0/task.json'.
[2021-04-21 12:54:51Z INFO BuildJobExtension] Adding pre-job step from extension.
[2021-04-21 12:54:51Z INFO BuildJobExtension] Adding post-job step from extension.
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Diag': '/home/myuser/Az/CL_A01/_diag'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Diag': '/home/myuser/Az/CL_A01/_diag'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Diag': '/home/myuser/Az/CL_A01/_diag'
[2021-04-21 12:54:51Z INFO BuildJobExtension] Adding post-job steps from tasks.
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Diag': '/home/myuser/Az/CL_A01/_diag'
[2021-04-21 12:54:51Z INFO BuildJobExtension] Total accessible running process: 117.
[2021-04-21 12:54:51Z INFO JobRunner] Total job steps: 4.
[2021-04-21 12:54:51Z INFO JobRunner] Run all job steps.
[2021-04-21 12:54:51Z INFO StepsRunner] Processing step: DisplayName='Checkout Fork.Tools.NlpQueryData@master to s', ContinueOnError=False, Enabled=True
[2021-04-21 12:54:51Z INFO ExpressionManager] Evaluating: SucceededNode()
[2021-04-21 12:54:51Z INFO ExpressionManager] Result: True
[2021-04-21 12:54:51Z INFO StepsRunner] Starting the step.
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 12:54:51Z INFO TaskRunner] Get handler data for target platform Linux
[2021-04-21 12:54:51Z INFO TaskRunner] Handler data is of type Microsoft.VisualStudio.Services.Agent.Worker.AgentPluginHandlerData
[2021-04-21 12:54:51Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.IWorkerCommandExtension'
[2021-04-21 12:54:51Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.TaskCommandExtension, Agent.Worker
[2021-04-21 12:54:51Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.ArtifactCommandExtension, Agent.Worker
[2021-04-21 12:54:51Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.BuildCommandExtension, Agent.Worker
[2021-04-21 12:54:51Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.CodeCoverage.CodeCoverageCommandExtension, Agent.Worker
[2021-04-21 12:54:51Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.TestResults.ResultsCommandExtension, Agent.Worker
[2021-04-21 12:54:51Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Telemetry.TelemetryCommandExtension, Agent.Worker
[2021-04-21 12:54:51Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Release.ReleaseCommandExtension, Agent.Worker
[2021-04-21 12:54:51Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.PluginInternalCommandExtension, Agent.Worker
[2021-04-21 12:54:51Z INFO WorkerCommandManager] Register command extension for area task
[2021-04-21 12:54:51Z INFO WorkerCommandManager] Register command extension for area artifact
[2021-04-21 12:54:51Z INFO WorkerCommandManager] Register command extension for area build
[2021-04-21 12:54:51Z INFO WorkerCommandManager] Register command extension for area codecoverage
[2021-04-21 12:54:51Z INFO WorkerCommandManager] Register command extension for area results
[2021-04-21 12:54:51Z INFO WorkerCommandManager] Register command extension for area telemetry
[2021-04-21 12:54:51Z INFO WorkerCommandManager] Register command extension for area release
[2021-04-21 12:54:51Z INFO WorkerCommandManager] Register command extension for area plugininternal
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.Repository.CheckoutTask, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id '6d15af64-176c-496d-b583-fd2ae21d4df4' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.Repository.CleanupTask, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id '6d15af64-176c-496d-b583-fd2ae21d4df4' (post).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineArtifact.DownloadPipelineArtifactTask, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id '61f2a582-95ae-4948-b34d-a1b3c4f6a737' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineArtifact.PublishPipelineArtifactTask, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id 'ecdc45f6-832d-4ad9-b52b-ee49e94659be' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineArtifact.PublishPipelineArtifactTaskV1, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id 'ecdc45f6-832d-4ad9-b52b-ee49e94659be' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineArtifact.DownloadPipelineArtifactTaskV1, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id '61f2a582-95ae-4948-b34d-a1b3c4f6a737' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineArtifact.DownloadPipelineArtifactTaskV1_1_0, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id '61f2a582-95ae-4948-b34d-a1b3c4f6a737' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineCache.SavePipelineCacheV0, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id 'd53ccab4-555e-4494-9d06-11db043fb4a9' (post).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineCache.RestorePipelineCacheV0, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id 'd53ccab4-555e-4494-9d06-11db043fb4a9' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineArtifact.DownloadPipelineArtifactTaskV1_1_1, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id '61f2a582-95ae-4948-b34d-a1b3c4f6a737' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineArtifact.DownloadPipelineArtifactTaskV1_1_2, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id '61f2a582-95ae-4948-b34d-a1b3c4f6a737' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineArtifact.DownloadPipelineArtifactTaskV1_1_3, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id '61f2a582-95ae-4948-b34d-a1b3c4f6a737' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineArtifact.DownloadPipelineArtifactTaskV2_0_0, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id '61f2a582-95ae-4948-b34d-a1b3c4f6a737' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.PipelineArtifact.PublishPipelineArtifactTaskV0_140_0, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id 'ecdc45f6-832d-4ad9-b52b-ee49e94659be' (main).
[2021-04-21 12:54:51Z INFO AgentPluginManager] Load task plugin from 'Agent.Plugins.BuildArtifacts.DownloadBuildArtifactTaskV1_0_0, Agent.Plugins'.
[2021-04-21 12:54:51Z INFO AgentPluginManager] Loaded task plugin id 'a433f589-fce1-4460-9ee6-44a624aeb1fb' (main).
[2021-04-21 12:54:51Z INFO WorkerCommandManager] Enable plugin internal command extension.
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:51Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper] Starting process:
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper]   File name: '/home/myuser/Az/CL_A01/bin/Agent.PluginHost'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper]   Arguments: 'task "Agent.Plugins.Repository.CheckoutTask, Agent.Plugins"'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper]   Working directory: '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper]   Require exit code zero: 'True'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper]   Encoding web name: utf-8 ; code page: '65001'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper]   Force kill process on cancellation: 'False'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper]   Redirected STDIN: 'True'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper]   Persist current code page: 'False'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper]   Keep redirected STDIN open: 'False'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper]   High priority process: 'False'
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper] Updated oom_score_adj to 500 for PID: 19120.
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper] Process started with process id 19120, waiting for process exit.
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper] Close STDIN after the first redirect finished.
[2021-04-21 12:54:51Z INFO ProcessInvokerWrapper] STDIN stream write finished.
[2021-04-21 12:54:51Z INFO JobServerQueue] Try to append 1 batches web console lines for record '88c79989-d538-490f-9df7-9c4079986a8c', success rate: 1/1.
[2021-04-21 12:54:52Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'a3e98e35-6a93-5792-7618-3fb133883d3a', success rate: 1/1.
[2021-04-21 12:54:52Z INFO JobServerQueue] Try to upload 1 log files or attachments, success rate: 1/1.
[2021-04-21 12:54:52Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'a3e98e35-6a93-5792-7618-3fb133883d3a', success rate: 1/1.
[2021-04-21 12:54:52Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'a3e98e35-6a93-5792-7618-3fb133883d3a', success rate: 1/1.
[2021-04-21 12:54:52Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'a3e98e35-6a93-5792-7618-3fb133883d3a', success rate: 1/1.
[2021-04-21 12:54:53Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'a3e98e35-6a93-5792-7618-3fb133883d3a', success rate: 1/1.
[2021-04-21 12:54:53Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 12:54:53Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 12:54:53Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2021-04-21 12:54:53Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2021-04-21 12:54:54Z INFO JobServerQueue] Try to append 2 batches web console lines for record 'a3e98e35-6a93-5792-7618-3fb133883d3a', success rate: 2/2.
[2021-04-21 12:54:54Z INFO ProcessInvokerWrapper] Exited process 19120 with exit code 0
[2021-04-21 12:54:55Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 12:54:55Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 12:54:55Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'a3e98e35-6a93-5792-7618-3fb133883d3a', success rate: 1/1.
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper] Finished process 19120 with exit code 0, and elapsed time 00:00:04.7863936.
[2021-04-21 12:54:56Z INFO WorkerCommandManager] Disable plugin internal command extension.
[2021-04-21 12:54:56Z INFO StepsRunner] Step result: 
[2021-04-21 12:54:56Z INFO StepsRunner] No need for updating job result with current step result 'Succeeded'.
[2021-04-21 12:54:56Z INFO StepsRunner] Current state: job state = ''
[2021-04-21 12:54:56Z INFO StepsRunner] Processing step: DisplayName='Run tests', ContinueOnError=False, Enabled=True
[2021-04-21 12:54:56Z INFO ExpressionManager] Evaluating: SucceededNode()
[2021-04-21 12:54:56Z INFO ExpressionManager] Result: True
[2021-04-21 12:54:56Z INFO StepsRunner] Starting the step.
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'TaskZips': '/home/myuser/Az/CL_A01/_work/_taskzips'
[2021-04-21 12:54:56Z INFO TaskManager] Loading task definition '/home/myuser/Az/CL_A01/_work/_tasks/Bash_6c731c3c-3c68-459a-a5c9-bde6e6595b5b/3.182.0/task.json'.
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'TaskZips': '/home/myuser/Az/CL_A01/_work/_taskzips'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 12:54:56Z INFO TaskRunner] Get handler data for target platform Linux
[2021-04-21 12:54:56Z INFO TaskRunner] Handler data is of type Microsoft.VisualStudio.Services.Agent.Worker.Node10HandlerData
[2021-04-21 12:54:56Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.IJobExtension'
[2021-04-21 12:54:56Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.Build.ISourceProvider'
[2021-04-21 12:54:56Z INFO BuildJobExtension] Build JobExtension resolving path use source provide: 
[2021-04-21 12:54:56Z INFO BuildJobExtension] The Default Path Root of Build JobExtension is repository.path: /home/myuser/Az/CL_A01/_work/1/s
[2021-04-21 12:54:56Z INFO BuildJobExtension] After prefix Default Path Root provide by JobExtension: /home/myuser/Az/CL_A01/_work/1/s
[2021-04-21 12:54:56Z INFO BuildJobExtension] Return absolute path after prefix DefaultPathRoot: /home/myuser/Az/CL_A01/_work/1/s
[2021-04-21 12:54:56Z INFO TaskRunner] Build JobExtension resolved a rooted path:: /home/myuser/Az/CL_A01/_work/1/s
[2021-04-21 12:54:56Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.IJobExtension'
[2021-04-21 12:54:56Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.Build.ISourceProvider'
[2021-04-21 12:54:56Z INFO BuildJobExtension] Build JobExtension resolving path use source provide: 
[2021-04-21 12:54:56Z INFO BuildJobExtension] The Default Path Root of Build JobExtension is repository.path: /home/myuser/Az/CL_A01/_work/1/s
[2021-04-21 12:54:56Z INFO BuildJobExtension] After prefix Default Path Root provide by JobExtension: /home/myuser/Az/CL_A01/_work/1/s
[2021-04-21 12:54:56Z INFO BuildJobExtension] Return absolute path after prefix DefaultPathRoot: /home/myuser/Az/CL_A01/_work/1/s
[2021-04-21 12:54:56Z INFO TaskRunner] Build JobExtension resolved a rooted path:: /home/myuser/Az/CL_A01/_work/1/s
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Externals': '/home/myuser/Az/CL_A01/externals'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 12:54:56Z INFO NodeHandler] Inspect node_modules folder, make sure vsts-task-lib doesn't overwrite String.startsWith/endsWith.
[2021-04-21 12:54:56Z INFO NodeHandler] Scan node_modules folder, looking for vsts-task-lib\extensions.js
[2021-04-21 12:54:56Z INFO NodeHandler] Finished scan and correct extensions.js under vsts-task-lib
[2021-04-21 12:54:56Z INFO NodeHandler] Task.json has node10 handler data: True, use node10 for node tasks: False
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 12:54:56Z INFO HostContext] Well known directory 'Externals': '/home/myuser/Az/CL_A01/externals'
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper] Starting process:
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper]   File name: '/home/myuser/Az/CL_A01/externals/node10/bin/node'
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper]   Arguments: '"/home/myuser/Az/CL_A01/_work/_tasks/Bash_6c731c3c-3c68-459a-a5c9-bde6e6595b5b/3.182.0/bash.js"'
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper]   Working directory: '/home/myuser/Az/CL_A01/_work/1/s'
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper]   Require exit code zero: 'True'
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper]   Encoding web name:  ; code page: ''
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper]   Force kill process on cancellation: 'False'
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper]   Redirected STDIN: 'False'
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper]   Persist current code page: 'False'
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper]   Keep redirected STDIN open: 'False'
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper]   High priority process: 'False'
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper] Updated oom_score_adj to 500 for PID: 19169.
[2021-04-21 12:54:56Z INFO ProcessInvokerWrapper] Process started with process id 19169, waiting for process exit.
[2021-04-21 12:54:56Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'a3e98e35-6a93-5792-7618-3fb133883d3a', success rate: 1/1.
[2021-04-21 12:54:56Z INFO JobServerQueue] Try to append 1 batches web console lines for record '5ff46123-0783-578c-d76d-bac996bea75d', success rate: 1/1.
[2021-04-21 12:54:56Z INFO JobServerQueue] Try to append 1 batches web console lines for record '5ff46123-0783-578c-d76d-bac996bea75d', success rate: 1/1.
[2021-04-21 12:54:57Z INFO JobServerQueue] Try to upload 1 log files or attachments, success rate: 1/1.
[2021-04-21 12:54:57Z INFO JobServerQueue] Try to append 1 batches web console lines for record '5ff46123-0783-578c-d76d-bac996bea75d', success rate: 1/1.
[2021-04-21 12:54:57Z INFO JobServerQueue] Try to append 1 batches web console lines for record '5ff46123-0783-578c-d76d-bac996bea75d', success rate: 1/1.
[2021-04-21 12:55:53Z INFO JobServerQueue] Stop aggressive process web console line queue.
[2021-04-21 13:05:35Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2021-04-21 13:05:35Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2021-04-21 13:05:35Z INFO ProcessInvokerWrapper] Exited process 19169 with exit code 0
[2021-04-21 13:05:35Z INFO ExecutionContext] Force finish current task in 5 sec.
[2021-04-21 13:05:35Z INFO ProcessInvokerWrapper] Finished process 19169 with exit code 0, and elapsed time 00:10:39.4968951.
[2021-04-21 13:05:35Z INFO StepsRunner] Step result: Succeeded
[2021-04-21 13:05:35Z INFO StepsRunner] No need for updating job result with current step result 'Succeeded'.
[2021-04-21 13:05:35Z INFO StepsRunner] Current state: job state = ''
[2021-04-21 13:05:35Z INFO StepsRunner] Processing step: DisplayName='PublishTestResults', ContinueOnError=False, Enabled=True
[2021-04-21 13:05:35Z INFO ExpressionManager] Evaluating: SucceededNode()
[2021-04-21 13:05:35Z INFO ExpressionManager] Result: True
[2021-04-21 13:05:35Z INFO StepsRunner] Starting the step.
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'TaskZips': '/home/myuser/Az/CL_A01/_work/_taskzips'
[2021-04-21 13:05:35Z INFO TaskManager] Loading task definition '/home/myuser/Az/CL_A01/_work/_tasks/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1/2.180.0/task.json'.
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'TaskZips': '/home/myuser/Az/CL_A01/_work/_taskzips'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 13:05:35Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 13:05:36Z INFO TaskRunner] Get handler data for target platform Linux
[2021-04-21 13:05:36Z INFO TaskRunner] Handler data is of type Microsoft.VisualStudio.Services.Agent.Worker.NodeHandlerData
[2021-04-21 13:05:36Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:05:36Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 13:05:36Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 13:05:36Z INFO NodeHandler] Inspect node_modules folder, make sure vsts-task-lib doesn't overwrite String.startsWith/endsWith.
[2021-04-21 13:05:36Z INFO NodeHandler] Scan node_modules folder, looking for vsts-task-lib\extensions.js
[2021-04-21 13:05:36Z INFO NodeHandler] Finished scan and correct extensions.js under vsts-task-lib
[2021-04-21 13:05:36Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:05:36Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 13:05:36Z INFO HostContext] Well known directory 'Externals': '/home/myuser/Az/CL_A01/externals'
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper] Starting process:
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper]   File name: '/home/myuser/Az/CL_A01/externals/node/bin/node'
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper]   Arguments: '"/home/myuser/Az/CL_A01/_work/_tasks/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1/2.180.0/publishtestresults.js"'
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper]   Working directory: '/home/myuser/Az/CL_A01/_work/1/s'
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper]   Require exit code zero: 'True'
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper]   Encoding web name:  ; code page: ''
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper]   Force kill process on cancellation: 'False'
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper]   Redirected STDIN: 'False'
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper]   Persist current code page: 'False'
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper]   Keep redirected STDIN open: 'False'
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper]   High priority process: 'False'
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper] Updated oom_score_adj to 500 for PID: 19943.
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper] Process started with process id 19943, waiting for process exit.
[2021-04-21 13:05:36Z INFO JobServerQueue] Try to append 3 batches web console lines for record '5ff46123-0783-578c-d76d-bac996bea75d', success rate: 3/3.
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2021-04-21 13:05:36Z INFO ProcessInvokerWrapper] Exited process 19943 with exit code 0
[2021-04-21 13:05:36Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 13:05:36Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 13:05:37Z INFO JobServerQueue] Try to upload 1 log files or attachments, success rate: 1/1.
[2021-04-21 13:05:37Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 13:05:37Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 13:05:37Z INFO JobServerQueue] Try to append 6 batches web console lines for record '5ff46123-0783-578c-d76d-bac996bea75d', success rate: 6/6.
[2021-04-21 13:05:37Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 13:05:38Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 13:05:38Z INFO JobServerQueue] Try to append 3 batches web console lines for record '5ff46123-0783-578c-d76d-bac996bea75d', success rate: 3/3.
[2021-04-21 13:05:38Z INFO JobServerQueue] Try to append 1 batches web console lines for record '454f32c1-0af2-5b24-ae79-c15ff910edfe', success rate: 1/1.
[2021-04-21 13:05:39Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 13:05:39Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 13:05:40Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.TestResults.IParser'
[2021-04-21 13:05:40Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.TestResults.JUnitParser, Agent.Worker
[2021-04-21 13:05:40Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.TestResults.NUnitParser, Agent.Worker
[2021-04-21 13:05:40Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.TestResults.CTestParser, Agent.Worker
[2021-04-21 13:05:40Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.TestResults.TrxParser, Agent.Worker
[2021-04-21 13:05:40Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.TestResults.XUnitParser, Agent.Worker
[2021-04-21 13:05:40Z INFO JobServerQueue] Try to append 1 batches web console lines for record '454f32c1-0af2-5b24-ae79-c15ff910edfe', success rate: 1/1.
[2021-04-21 13:05:40Z INFO VisualStudioServices] Starting operation Location.GetConnectionData
[2021-04-21 13:05:40Z INFO VisualStudioServices] Finished operation Location.GetConnectionData
[2021-04-21 13:05:41Z INFO JobServerQueue] Try to append 1 batches web console lines for record '454f32c1-0af2-5b24-ae79-c15ff910edfe', success rate: 1/1.
[2021-04-21 13:05:41Z INFO ProcessInvokerWrapper] Finished process 19943 with exit code 0, and elapsed time 00:00:05.3326032.
[2021-04-21 13:05:41Z INFO AsyncCommandContext] Start flush buffered output.
[2021-04-21 13:05:41Z INFO JobServerQueue] Try to append 1 batches web console lines for record '454f32c1-0af2-5b24-ae79-c15ff910edfe', success rate: 1/1.
[2021-04-21 13:11:04Z INFO Worker] Cancellation/Shutdown message received.
[2021-04-21 13:11:04Z INFO ExpressionManager] Evaluating: SucceededNode()
[2021-04-21 13:11:04Z INFO ExpressionManager] Result: False
[2021-04-21 13:11:04Z INFO StepsRunner] Cancel current running step.
[2021-04-21 13:11:15Z WARN VisualStudioServices] PATCH request to https://iii40.vstmr.visualstudio.com/IDS_Prototypes/_apis/testresults/runs/1002590 has been cancelled.
[2021-04-21 13:11:15Z INFO AsyncCommandContext] Finsh flush buffered output.
[2021-04-21 13:11:15Z INFO AsyncCommandContext] Wait till async command task to finish.
[2021-04-21 13:11:15Z INFO StepsRunner] Step result: Succeeded
[2021-04-21 13:11:15Z INFO StepsRunner] No need for updating job result with current step result 'Succeeded'.
[2021-04-21 13:11:15Z INFO StepsRunner] Current state: job state = 'Canceled'
[2021-04-21 13:11:15Z INFO StepsRunner] Processing step: DisplayName='Checkout Fork.Tools.NlpQueryData@master to s', ContinueOnError=False, Enabled=True
[2021-04-21 13:11:15Z INFO ExpressionManager] Evaluating: AlwaysNode()
[2021-04-21 13:11:15Z INFO ExpressionManager] Result: True
[2021-04-21 13:11:15Z INFO StepsRunner] Starting the step.
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Tasks': '/home/myuser/Az/CL_A01/_work/_tasks'
[2021-04-21 13:11:15Z INFO TaskRunner] Get handler data for target platform Linux
[2021-04-21 13:11:15Z INFO TaskRunner] Handler data is of type Microsoft.VisualStudio.Services.Agent.Worker.AgentPluginHandlerData
[2021-04-21 13:11:15Z INFO WorkerCommandManager] Enable plugin internal command extension.
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper] Starting process:
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper]   File name: '/home/myuser/Az/CL_A01/bin/Agent.PluginHost'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper]   Arguments: 'task "Agent.Plugins.Repository.CleanupTask, Agent.Plugins"'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper]   Working directory: '/home/myuser/Az/CL_A01/_work'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper]   Require exit code zero: 'True'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper]   Encoding web name: utf-8 ; code page: '65001'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper]   Force kill process on cancellation: 'False'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper]   Redirected STDIN: 'True'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper]   Persist current code page: 'False'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper]   Keep redirected STDIN open: 'False'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper]   High priority process: 'False'
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper] Updated oom_score_adj to 500 for PID: 20011.
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper] Process started with process id 20011, waiting for process exit.
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper] Close STDIN after the first redirect finished.
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper] STDIN stream write finished.
[2021-04-21 13:11:15Z INFO JobServerQueue] Try to append 1 batches web console lines for record '454f32c1-0af2-5b24-ae79-c15ff910edfe', success rate: 1/1.
[2021-04-21 13:11:15Z INFO JobServerQueue] Try to append 1 batches web console lines for record '4c30bbe0-52d3-4fcd-ab9a-1c8cb0f8570e', success rate: 1/1.
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper] Exited process 20011 with exit code 0
[2021-04-21 13:11:15Z INFO ProcessInvokerWrapper] Finished process 20011 with exit code 0, and elapsed time 00:00:00.4864609.
[2021-04-21 13:11:15Z INFO WorkerCommandManager] Disable plugin internal command extension.
[2021-04-21 13:11:15Z INFO StepsRunner] Step result: 
[2021-04-21 13:11:15Z INFO StepsRunner] No need for updating job result with current step result 'Succeeded'.
[2021-04-21 13:11:15Z INFO StepsRunner] Current state: job state = 'Canceled'
[2021-04-21 13:11:15Z INFO JobRunner] Finalize job.
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Diag': '/home/myuser/Az/CL_A01/_diag'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Bin': '/home/myuser/Az/CL_A01/bin'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Root': '/home/myuser/Az/CL_A01'
[2021-04-21 13:11:15Z INFO HostContext] Well known directory 'Work': '/home/myuser/Az/CL_A01/_work'
[2021-04-21 13:11:15Z INFO BuildJobExtension] Total accessible running process: 114.
[2021-04-21 13:11:15Z INFO BuildJobExtension] Inspecting process environment variables. PID: 19422 (sshd: myuser [priv])
[2021-04-21 13:11:15Z INFO ProcessExtensions] Read env from /proc/19422/environ
[2021-04-21 13:11:15Z WARN BuildJobExtension] Ignore exception during read process environment variables: Access to the path '/proc/19422/environ' is denied.
[2021-04-21 13:11:15Z INFO BuildJobExtension] Inspecting process environment variables. PID: 19535 (sshd)
[2021-04-21 13:11:15Z INFO ProcessExtensions] Read env from /proc/19535/environ
[2021-04-21 13:11:15Z WARN BuildJobExtension] Ignore exception during read process environment variables: Access to the path '/proc/19535/environ' is denied.
[2021-04-21 13:11:15Z INFO BuildJobExtension] Inspecting process environment variables. PID: 19536 (bash)
[2021-04-21 13:11:15Z INFO ProcessExtensions] Read env from /proc/19536/environ
[2021-04-21 13:11:15Z INFO BuildJobExtension] Inspecting process environment variables. PID: 19619 (kworker/u480:0)
[2021-04-21 13:11:15Z INFO ProcessExtensions] Read env from /proc/19619/environ
[2021-04-21 13:11:15Z WARN BuildJobExtension] Ignore exception during read process environment variables: Access to the path '/proc/19619/environ' is denied.
[2021-04-21 13:11:15Z INFO BuildJobExtension] Inspecting process environment variables. PID: 19900 (kworker/u480:2)
[2021-04-21 13:11:15Z INFO ProcessExtensions] Read env from /proc/19900/environ
[2021-04-21 13:11:15Z WARN BuildJobExtension] Ignore exception during read process environment variables: Access to the path '/proc/19900/environ' is denied.
[2021-04-21 13:11:15Z INFO BuildJobExtension] Inspecting process environment variables. PID: 19901 (kworker/u480:3)
[2021-04-21 13:11:15Z INFO ProcessExtensions] Read env from /proc/19901/environ
[2021-04-21 13:11:15Z WARN BuildJobExtension] Ignore exception during read process environment variables: Access to the path '/proc/19901/environ' is denied.
[2021-04-21 13:11:15Z INFO BuildJobExtension] Inspecting process environment variables. PID: 19908 (kworker/3:1)
[2021-04-21 13:11:15Z INFO ProcessExtensions] Read env from /proc/19908/environ
[2021-04-21 13:11:15Z WARN BuildJobExtension] Ignore exception during read process environment variables: Access to the path '/proc/19908/environ' is denied.
[2021-04-21 13:11:15Z INFO BuildJobExtension] Inspecting process environment variables. PID: 19909 (kworker/1:1)
[2021-04-21 13:11:15Z INFO ProcessExtensions] Read env from /proc/19909/environ
[2021-04-21 13:11:15Z WARN BuildJobExtension] Ignore exception during read process environment variables: Access to the path '/proc/19909/environ' is denied.
[2021-04-21 13:11:15Z INFO JobRunner] Job result after all job steps finish: Canceled
[2021-04-21 13:11:15Z INFO JobRunner] Completing the job execution context.
[2021-04-21 13:11:15Z INFO JobRunner] Shutting down the job server queue.
[2021-04-21 13:11:15Z INFO JobServerQueue] Fire signal to shutdown all queues.
[2021-04-21 13:11:16Z INFO JobServerQueue] All queue process task stopped.
[2021-04-21 13:11:16Z INFO JobServerQueue] Try to append 1 batches web console lines for record '4c30bbe0-52d3-4fcd-ab9a-1c8cb0f8570e', success rate: 1/1.
[2021-04-21 13:11:16Z INFO JobServerQueue] Try to append 1 batches web console lines for record '59eed522-cd91-403f-9d81-8536fbfca343', success rate: 1/1.
[2021-04-21 13:11:16Z INFO JobServerQueue] Try to append 1 batches web console lines for record '3f03d2a6-5a0d-5e8b-e05d-e1590a84c0c4', success rate: 1/1.
[2021-04-21 13:11:16Z INFO JobServerQueue] Web console line queue drained.
[2021-04-21 13:11:16Z INFO JobServerQueue] Uploading 4 files in one shot.
[2021-04-21 13:11:17Z INFO JobServerQueue] Try to upload 4 log files or attachments, success rate: 4/4.
[2021-04-21 13:11:17Z INFO JobServerQueue] File upload queue drained.
[2021-04-21 13:11:17Z INFO JobServerQueue] Timeline update queue drained.
[2021-04-21 13:11:17Z INFO JobServerQueue] All queue process tasks have been stopped, and all queues are drained.
[2021-04-21 13:11:17Z INFO TempDirectoryManager] Cleaning agent temp folder: /home/myuser/Az/CL_A01/_work/_temp
[2021-04-21 13:11:17Z INFO JobRunner] Raising job completed event.

[anatolybolshakov]

Hi @petermicuch this task does not support proxy at the moment - moving to azure-pipelines-tasks since it's related to the task itself.

[petermicuch]

Hi @anatolybolshakov which other task that does the same job do you propose to use? Or can fix for this issue be expected shortly? Thank you.

[EzzhevNikita]

Hi @petermicuch, I'm investigating this issue now. And I tried to repro this, but task PublishTestResults finishes successfully for me. Also, I see that publishing of results completes through proxy, not directly. Could you please provide me output of task started with marked checkbox "Enable system diagnostic"? The checkbox is placed in the bottom of "Run pipeline" window.

[petermicuch]

Hi @EzzhevNikita,

here are the logs. Note that agent might have been updated in the meantime and we are actually having exception from proxy there right now. I would have to setup another one to test it without the bypass as this one is occupied with tests and I can not take it away from the team.

2021-09-30T10:28:01.0972392Z ##[debug]Evaluating condition for step: 'PublishTestResults'
2021-09-30T10:28:01.0976083Z ##[debug]Evaluating: SucceededNode()
2021-09-30T10:28:01.0977748Z ##[debug]Evaluating SucceededNode:
2021-09-30T10:28:01.0980273Z ##[debug]=> True
2021-09-30T10:28:01.0981747Z ##[debug]Result: True
2021-09-30T10:28:01.0983169Z ##[section]Starting: PublishTestResults
2021-09-30T10:28:01.1006476Z ##[debug]Extracting task PublishTestResults from /home/anonymuser/Az/CL_A01/_work/_taskzips/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1_2.192.1.zip to /home/anonymuser/Az/CL_A01/_work/_tasks/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1/2.192.1.
2021-09-30T10:28:01.3741157Z ==============================================================================
2021-09-30T10:28:01.3741829Z Task         : Publish Test Results
2021-09-30T10:28:01.3742349Z Description  : Publish test results to Azure Pipelines
2021-09-30T10:28:01.3742851Z Version      : 2.192.1
2021-09-30T10:28:01.3743270Z Author       : Microsoft Corporation
2021-09-30T10:28:01.3743990Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/test/publish-test-results
2021-09-30T10:28:01.3744728Z ==============================================================================
2021-09-30T10:28:01.3842951Z ##[debug]Using node path: /home/anonymuser/Az/CL_A01/externals/node10/bin/node
2021-09-30T10:28:01.5508982Z ##[debug]agent.TempDirectory=/home/anonymuser/Az/CL_A01/_work/_temp
2021-09-30T10:28:01.5543828Z ##[debug]loading inputs and endpoints
2021-09-30T10:28:01.5551312Z ##[debug]loading INPUT_TESTRUNNER
2021-09-30T10:28:01.5570072Z ##[debug]loading INPUT_TESTRESULTSFILES
2021-09-30T10:28:01.5572039Z ##[debug]loading INPUT_SEARCHFOLDER
2021-09-30T10:28:01.5573917Z ##[debug]loading INPUT_MERGETESTRESULTS
2021-09-30T10:28:01.5575416Z ##[debug]loading INPUT_FAILTASKONFAILEDTESTS
2021-09-30T10:28:01.5577327Z ##[debug]loading INPUT_TESTRUNTITLE
2021-09-30T10:28:01.5579314Z ##[debug]loading INPUT_PLATFORM
2021-09-30T10:28:01.5581288Z ##[debug]loading INPUT_PUBLISHRUNATTACHMENTS
2021-09-30T10:28:01.5583012Z ##[debug]loading ENDPOINT_AUTH_SYSTEMVSSCONNECTION
2021-09-30T10:28:01.5586631Z ##[debug]loading ENDPOINT_AUTH_SCHEME_SYSTEMVSSCONNECTION
2021-09-30T10:28:01.5588483Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_SYSTEMVSSCONNECTION_ACCESSTOKEN
2021-09-30T10:28:01.5595352Z ##[debug]loading SECRET_AZURE_BLOB_PASSWORD
2021-09-30T10:28:01.5596864Z ##[debug]loading SECRET_SYSTEM_ACCESSTOKEN
2021-09-30T10:28:01.5599013Z ##[debug]loading SECRET_anonymCONTAINERREGISTRY_PWD
2021-09-30T10:28:01.5600522Z ##[debug]loading SECRET_AZURE_BLOB_USERNAME
2021-09-30T10:28:01.5602387Z ##[debug]loading SECRET_AZURE_NPM_TOKEN
2021-09-30T10:28:01.5604177Z ##[debug]loading SECRET_QUERY_BUNDLE_PRIVATE_KEY
2021-09-30T10:28:01.5605984Z ##[debug]loading SECRET_VSTS_PAT
2021-09-30T10:28:01.5607384Z ##[debug]loading SECRET_SHSDS_NPM_TOKEN
2021-09-30T10:28:01.5609992Z ##[debug]loading SECRET_SHUI_NPM_TOKEN
2021-09-30T10:28:01.5611380Z ##[debug]loaded 20
2021-09-30T10:28:01.5618436Z ##[debug]Agent.ProxyUrl=http://139.22.102.14:8888
2021-09-30T10:28:01.5619932Z ##[debug]Agent.ProxyUsername=undefined
2021-09-30T10:28:01.5621006Z ##[debug]Agent.ProxyPassword=undefined
2021-09-30T10:28:01.5622071Z ##[debug]Agent.ProxyBypassList=undefined
2021-09-30T10:28:01.5625156Z ##[debug]expose agent proxy configuration.
2021-09-30T10:28:01.5626527Z ##[debug]Agent.CAInfo=undefined
2021-09-30T10:28:01.5627802Z ##[debug]Agent.ClientCert=undefined
2021-09-30T10:28:01.5629099Z ##[debug]Agent.SkipCertValidation=undefined
2021-09-30T10:28:01.5727560Z ##[debug]check path : /home/anonymuser/Az/CL_A01/_work/_tasks/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1/2.192.1/task.json
2021-09-30T10:28:01.5731231Z ##[debug]adding resource file: /home/anonymuser/Az/CL_A01/_work/_tasks/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1/2.192.1/task.json
2021-09-30T10:28:01.5733971Z ##[debug]system.culture=en-US
2021-09-30T10:28:01.5752497Z ##[debug]testRunner=NUnit
2021-09-30T10:28:01.5754567Z ##[debug]testResultsFiles=test_results.xml
2021-09-30T10:28:01.5756632Z ##[debug]mergeTestResults=false
2021-09-30T10:28:01.5758594Z ##[debug]platform=anonym-nlp
2021-09-30T10:28:01.5760525Z ##[debug]configuration=undefined
2021-09-30T10:28:01.5762567Z ##[debug]testRunTitle=iTests NLP.QueryData (queries)
2021-09-30T10:28:01.5764470Z ##[debug]publishRunAttachments=true
2021-09-30T10:28:01.5766293Z ##[debug]failTaskOnFailedTests=true
2021-09-30T10:28:01.5768360Z ##[debug]searchFolder=/home/anonymuser/Az/CL_A01/_work/1/s
2021-09-30T10:28:01.5770398Z ##[debug]testRunner: NUnit
2021-09-30T10:28:01.5772445Z ##[debug]testResultsFiles: test_results.xml
2021-09-30T10:28:01.5774423Z ##[debug]mergeResults: false
2021-09-30T10:28:01.5776749Z ##[debug]platform: anonym-nlp
2021-09-30T10:28:01.5778900Z ##[debug]config: undefined
2021-09-30T10:28:01.5780871Z ##[debug]testRunTitle: iTests NLP.QueryData (queries)
2021-09-30T10:28:01.5782838Z ##[debug]publishRunAttachments: true
2021-09-30T10:28:01.5784747Z ##[debug]failTaskOnFailedTests: true
2021-09-30T10:28:01.5786773Z ##[debug]System.DefaultWorkingDirectory=/home/anonymuser/Az/CL_A01/_work/1/s
2021-09-30T10:28:01.5789375Z ##[debug]defaultRoot: '/home/anonymuser/Az/CL_A01/_work/1/s'
2021-09-30T10:28:01.5792226Z ##[debug]findOptions.allowBrokenSymbolicLinks: 'true'
2021-09-30T10:28:01.5794693Z ##[debug]findOptions.followSpecifiedSymbolicLink: 'true'
2021-09-30T10:28:01.5797057Z ##[debug]findOptions.followSymbolicLinks: 'true'
2021-09-30T10:28:01.5799248Z ##[debug]matchOptions.debug: 'false'
2021-09-30T10:28:01.5801517Z ##[debug]matchOptions.nobrace: 'true'
2021-09-30T10:28:01.5803873Z ##[debug]matchOptions.noglobstar: 'false'
2021-09-30T10:28:01.5806158Z ##[debug]matchOptions.dot: 'true'
2021-09-30T10:28:01.5808498Z ##[debug]matchOptions.noext: 'false'
2021-09-30T10:28:01.5810845Z ##[debug]matchOptions.nocase: 'false'
2021-09-30T10:28:01.5812924Z ##[debug]matchOptions.nonull: 'false'
2021-09-30T10:28:01.5814505Z ##[debug]matchOptions.matchBase: 'false'
2021-09-30T10:28:01.5816085Z ##[debug]matchOptions.nocomment: 'false'
2021-09-30T10:28:01.5818253Z ##[debug]matchOptions.nonegate: 'false'
2021-09-30T10:28:01.5819927Z ##[debug]matchOptions.flipNegate: 'false'
2021-09-30T10:28:01.5821468Z ##[debug]pattern: 'test_results.xml'
2021-09-30T10:28:01.5823096Z ##[debug]findPath: '/home/anonymuser/Az/CL_A01/_work/1/s/test_results.xml'
2021-09-30T10:28:01.5824998Z ##[debug]statOnly: 'true'
2021-09-30T10:28:01.5826257Z ##[debug]found 1 paths
2021-09-30T10:28:01.5827479Z ##[debug]applying include pattern
2021-09-30T10:28:01.5829127Z ##[debug]adjustedPattern: '/home/anonymuser/Az/CL_A01/_work/1/s/test_results.xml'
2021-09-30T10:28:01.5830546Z ##[debug]1 matches
2021-09-30T10:28:01.5831748Z ##[debug]1 final results
2021-09-30T10:28:01.5832997Z ##[debug]Detected 1 test result files
2021-09-30T10:28:01.5834449Z ##[debug]which 'dotnet'
2021-09-30T10:28:01.5859302Z ##[debug]not found
2021-09-30T10:28:01.5863614Z ##[debug]PublishTestResults.OverrideExeFlow=undefined
2021-09-30T10:28:01.5865082Z ##[debug]OS type: Linux
2021-09-30T10:28:15.4512951Z ##[debug]Object of TestLogStore created.
2021-09-30T10:28:15.4514771Z Result Attachments will be stored in LogStore
2021-09-30T10:28:15.4515722Z ##[debug]Object of TestResultsPublisher created.
2021-09-30T10:28:15.4784605Z ##[debug]Object of TestLogStore created.
2021-09-30T10:28:15.4785452Z Run Attachments will be stored in LogStore
2021-09-30T10:28:15.4786838Z ##[debug]Object of TestRunPublisher created.
2021-09-30T10:28:15.4789982Z ##[debug]Object of TestLogStore created.
2021-09-30T10:28:15.5075875Z ##[debug]Object of NUnitResultParser created.
2021-09-30T10:28:15.5084616Z ##[debug]Entering ParseTestResultFiles
2021-09-30T10:28:15.5088715Z ##[debug]runContext.ReleaseURI is null
2021-09-30T10:28:15.5089795Z ##[debug]runContext.ReleaseEnvironmentUri is null
2021-09-30T10:28:15.5114224Z ##[debug]Reading test results from file '/home/anonymuser/Az/CL_A01/_work/1/s/test_results.xml'.
2021-09-30T10:28:15.5409323Z ##[debug]Total test results: 110.
2021-09-30T10:28:15.5412983Z ##[debug]Leaving ParseTestResultFiles
2021-09-30T10:28:15.5444242Z ##[debug]Processed: ##vso[results.publish type=NUnit;mergeResults=false;platform=anonym-nlp;runTitle=iTests NLP.QueryData (queries);publishRunAttachments=true;resultFiles=/home/anonymuser/Az/CL_A01/_work/1/s/test_results.xml;failTaskOnFailedTests=true;testRunSystem=VSTS - PTR;]
2021-09-30T10:28:15.5446969Z ##[debug]runContext.ReleaseURI is null
2021-09-30T10:28:15.5448139Z ##[debug]task result: Succeeded
2021-09-30T10:28:15.5448237Z ##[debug]runContext.ReleaseEnvironmentUri is null
2021-09-30T10:28:15.5452586Z ##[debug]Processed: ##vso[task.complete result=Succeeded;]
2021-09-30T10:28:15.5454144Z ##[debug]Release.ReleaseUri=undefined
2021-09-30T10:28:15.5455602Z ##[debug]Release.ReleaseId=undefined
2021-09-30T10:28:15.5457038Z ##[debug]Build.BuildUri=vstfs:///Build/Build/7766
2021-09-30T10:28:15.5458716Z ##[debug]Build.Buildid=7766
2021-09-30T10:28:15.5488373Z ##[debug]Uploading build level attachements individually
2021-09-30T10:28:15.5515827Z ##[debug]Entering PublishToNewTestRunPerTestResultFileAsync
2021-09-30T10:28:15.5621821Z ##[debug]Entering CreateTestRunAsync
2021-09-30T10:28:15.5622753Z ##[debug]Leaving CreateTestRunAsync
2021-09-30T10:28:15.6041440Z ##[debug]Total build level attachments: 0.
2021-09-30T10:28:16.8087072Z ##[debug]Processed: ##vso[telemetry.publish area=TestExecution;feature=PublishTestResultsTask]{"builduri":"vstfs:///Build/Build/7766","buildid":"7766","osType":"Linux","testRunner":"NUnit","failTaskOnFailedTests":"true","mergeResultsUserPreference":"false","platform":"anonym-nlp","testResultsFilesCount":1,"dotnetVersion":"","subFeature":"publishTestResultsTaskConsolidatedCiEvent"}
2021-09-30T10:28:16.8134256Z ##[section]Async Command Start: Publish test results
2021-09-30T10:28:17.0743963Z ##[debug]Entering AddTestResultsAsync
2021-09-30T10:28:17.2936408Z Publishing test results to test run '1004286'.
2021-09-30T10:28:17.2981889Z TestResults To Publish 110, Test run id:1004286
2021-09-30T10:28:17.3039006Z Test results publishing 110, remaining: 0. Test run id: 1004286
2021-09-30T10:28:19.5504089Z ##[debug]Entering UploadTestRunStreamAsync
2021-09-30T10:28:20.5292516Z ##[debug]Blob name: Result-100003/GeneralAttachment/Standard_Console_Output.log .
2021-09-30T10:28:21.0152026Z ##[debug]Transfer Succeeds. stream -> Result-100003/GeneralAttachment/Standard_Console_Output.log.
2021-09-30T10:28:21.0435058Z ##[debug]File uploaded successsfully on LogStore Standard_Console_Output.log
2021-09-30T10:28:21.0458802Z ##[debug]Entering UploadTestRunStreamAsync
2021-09-30T10:28:21.0471010Z ##[debug]Blob name: Result-100009/GeneralAttachment/Standard_Console_Output.log .
2021-09-30T10:28:21.1066610Z ##[debug]Transfer Succeeds. stream -> Result-100009/GeneralAttachment/Standard_Console_Output.log.
2021-09-30T10:28:21.1281613Z ##[debug]File uploaded successsfully on LogStore Standard_Console_Output.log
2021-09-30T10:28:21.1282974Z ##[debug]Entering UploadTestRunStreamAsync
2021-09-30T10:28:21.1285821Z ##[debug]Blob name: Result-100010/GeneralAttachment/Standard_Console_Output.log .
2021-09-30T10:28:21.1771338Z ##[debug]Transfer Succeeds. stream -> Result-100010/GeneralAttachment/Standard_Console_Output.log.
2021-09-30T10:28:21.1969519Z ##[debug]File uploaded successsfully on LogStore Standard_Console_Output.log
2021-09-30T10:28:21.1975258Z ##[debug]Entering UploadTestRunStreamAsync
2021-09-30T10:28:21.1983934Z ##[debug]Blob name: Result-100036/GeneralAttachment/Standard_Console_Output.log .
2021-09-30T10:28:21.2557837Z ##[debug]Transfer Succeeds. stream -> Result-100036/GeneralAttachment/Standard_Console_Output.log.
2021-09-30T10:28:21.2760517Z ##[debug]File uploaded successsfully on LogStore Standard_Console_Output.log
2021-09-30T10:28:21.2764923Z ##[debug]Entering UploadTestRunStreamAsync
2021-09-30T10:28:21.2772676Z ##[debug]Blob name: Result-100039/GeneralAttachment/Standard_Console_Output.log .
2021-09-30T10:28:21.3280764Z ##[debug]Transfer Succeeds. stream -> Result-100039/GeneralAttachment/Standard_Console_Output.log.
2021-09-30T10:28:21.3479984Z ##[debug]File uploaded successsfully on LogStore Standard_Console_Output.log
2021-09-30T10:28:21.3483048Z ##[debug]Entering UploadTestRunStreamAsync
2021-09-30T10:28:21.3490702Z ##[debug]Blob name: Result-100053/GeneralAttachment/Standard_Console_Output.log .
2021-09-30T10:28:21.4034436Z ##[debug]Transfer Succeeds. stream -> Result-100053/GeneralAttachment/Standard_Console_Output.log.
2021-09-30T10:28:21.4231675Z ##[debug]File uploaded successsfully on LogStore Standard_Console_Output.log
2021-09-30T10:28:21.4234493Z ##[debug]Entering UploadTestRunStreamAsync
2021-09-30T10:28:21.4240654Z ##[debug]Blob name: Result-100070/GeneralAttachment/Standard_Console_Output.log .
2021-09-30T10:28:21.4772369Z ##[debug]Transfer Succeeds. stream -> Result-100070/GeneralAttachment/Standard_Console_Output.log.
2021-09-30T10:28:21.4974200Z ##[debug]File uploaded successsfully on LogStore Standard_Console_Output.log
2021-09-30T10:28:21.4976631Z ##[debug]Entering UploadTestRunStreamAsync
2021-09-30T10:28:21.4984040Z ##[debug]Blob name: Result-100091/GeneralAttachment/Standard_Console_Output.log .
2021-09-30T10:28:21.5515887Z ##[debug]Transfer Succeeds. stream -> Result-100091/GeneralAttachment/Standard_Console_Output.log.
2021-09-30T10:28:21.5714429Z ##[debug]File uploaded successsfully on LogStore Standard_Console_Output.log
2021-09-30T10:28:21.5787830Z ##[debug]Leaving AddTestResultsAsync
2021-09-30T10:28:21.5816772Z ##[debug]Entering UpdateTestRunAsync
2021-09-30T10:28:21.5817389Z ##[debug]Leaving UpdateTestRunAsync
2021-09-30T10:28:21.6647810Z ##[debug]Entering CreateTestRunAttachmentsAsync
2021-09-30T10:28:21.7159005Z ##[debug]Leaving CreateTestRunAttachmentsAsync
2021-09-30T10:28:21.7176514Z ##[debug]Uploading test run attachements individually
2021-09-30T10:28:21.7222542Z ##[debug]Entering UploadTestRunLogAsync
2021-09-30T10:28:21.7270722Z ##[debug]Blob name: GeneralAttachment/test_results.xml .
2021-09-30T10:28:21.8420246Z ##[debug]File uploaded successsfully on LogStore test_results.xml
2021-09-30T10:28:21.8458861Z Published Test Run : https://anonymized.visualstudio.com/anonym_Prototypes/_TestManagement/Runs?runId=1004286&_a=runCharts
2021-09-30T10:28:21.8472160Z ##[debug]Leaving PublishToNewTestRunPerTestResultFileAsync
2021-09-30T10:28:21.8828564Z ##[debug]RESOURCE_URIS:
2021-09-30T10:28:21.8862444Z ##[debug]Setting task variable METADATA_f6b99e5a-07a1-42b7-a5d9-be86805b7138: {"name":"19f262a1-d391-411a-a780-408a9f37b13b","resourceUris":[],"metadata":{"description":"","relatedUrls":[{"url":"https://dev.azure.com/anonymized/anonym_Prototypes/_build/results?buildId=7766","label":"pipeline-url"}],"humanReadableName":"Test Results from Publish Test Results utility","serializedPayload":"{\"testId\":\"PublishTestResults\",\"testTool\":\"NUnit\",\"testResultAttestation\":{\"total\":110,\"failed\":8,\"passed\":102,\"skipped\":0},\"testDurationSeconds\":0.0,\"testPassPercentage\":\"92.72727272727272\",\"relatedUrls\":[{\"url\":\"https://dev.azure.com/anonymized/anonym_Prototypes/_build/results?buildId=7766\",\"label\":\"pipeline-url\"}]}"}} 
2021-09-30T10:28:24.9597391Z Flaky failed test results are opted out of pass percentage
2021-09-30T10:28:24.9612158Z ##[error]There are one or more test failures detected in result files. Detailed summary of published test results can be viewed in the Tests tab.
2021-09-30T10:28:24.9872712Z ##[section]Async Command End: Publish test results
2021-09-30T10:28:24.9875153Z ##[section]Finishing: PublishTestResults

[petermicuch]

Adding also network activity for that last run:

root@ds-aipc-cl01-ln:/home/idsuser# sudo tcpdump -i lo -A
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 262144 bytes
11:31:39.530148 IP localhost.localdomain.47074 > localhost.domain: 20078+ [1au] A? etqtcmprodweu11.vstmrblob.vsassets.io. (66)
E..^..@.@.s{.......5...5.J..Nn...........etqtcmprodweu11        vstmrblob.vsassets.io.......)........
11:31:39.530193 IP localhost.localdomain.47074 > localhost.domain: 39555+ [1au] AAAA? etqtcmprodweu11.vstmrblob.vsassets.io. (66)
E..^..@.@.sz.......5...5.J...............etqtcmprodweu11        vstmrblob.vsassets.io.......)........
11:31:39.530542 IP localhost.localdomain.54678 > localhost.domain: 4062+ [1au] PTR? 53.0.0.127.in-addr.arpa. (52)
E..P..@.@.s........5...5.<...............53.0.0.127.in-addr.arpa.......)........
11:31:39.531206 IP localhost.domain > localhost.localdomain.54678: 4062 1/0/1 PTR localhost. (75)
E..gh:@.@......5.....5...S...............53.0.0.127.in-addr.arpa.................       localhost...)........
11:31:39.643829 IP localhost.domain > localhost.localdomain.47074: 39555 3/0/1 CNAME vstmrblob-vsassets-io.b-0020.b-msedge.net., CNAME b-0020.b-msedge.net., AAAA 2620:1ec:a92::175 (163)
E...hN@.@......5.....5...................etqtcmprodweu11        vstmrblob.vsassets.io..............h.+.vstmrblob-vsassets-io.b-0020.b-msedge.net..C...........Y.Y..........& ..
..........u..)........
11:31:39.644029 IP localhost.domain > localhost.localdomain.47074: 20078 3/0/1 CNAME vstmrblob-vsassets-io.b-0020.b-msedge.net., CNAME b-0020.b-msedge.net., A 13.107.6.175 (151)
E...hO@.@......5.....5......Nn...........etqtcmprodweu11        vstmrblob.vsassets.io..............h.+.vstmrblob-vsassets-io.b-0020.b-msedge.net..C...........Y.Y...........k....)........

[EzzhevNikita]

@petermicuch, thank you for providing these logs. But unfortunately, I don't see that this task failed due to the proxy configuration. You have mentioned that there is an exception for the agent machine to bypass proxy. Could you please share diagnostics logs for the task without proxy bypassing on the agent machine, since the current log doesn't give much information for an investigation?

[petermicuch]

@EzzhevNikita - you can ignore that test is failing or not. Important is the publish test results part, no matter if publishing of the failed or passed test. Here you have logs from the same client, but I asked our IT to remove exception from proxy for it. Exception seems a bit different than the one I posted very first time, but behavior is similar, except that instead of failing after 5 minutes, it now took 15 minutes to fail. So I guess the code was changed since I tried this the last time for this task. I tried with agent version 2.185.1 and later also with 2.192.0. Result is the same.

2021-10-04T09:24:25.1453211Z ##[debug]Evaluating condition for step: 'PublishTestResults'
2021-10-04T09:24:25.1456815Z ##[debug]Evaluating: SucceededNode()
2021-10-04T09:24:25.1458003Z ##[debug]Evaluating SucceededNode:
2021-10-04T09:24:25.1459909Z ##[debug]=> True
2021-10-04T09:24:25.1461022Z ##[debug]Result: True
2021-10-04T09:24:25.1462198Z ##[section]Starting: PublishTestResults
2021-10-04T09:24:25.1481004Z ##[debug]Extracting task PublishTestResults from /home/anonymuser/Az/CL_A01/_work/_taskzips/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1_2.192.1.zip to /home/anonymuser/Az/CL_A01/_work/_tasks/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1/2.192.1.
2021-10-04T09:24:25.4962745Z ==============================================================================
2021-10-04T09:24:25.4963599Z Task         : Publish Test Results
2021-10-04T09:24:25.4964201Z Description  : Publish test results to Azure Pipelines
2021-10-04T09:24:25.4964804Z Version      : 2.192.1
2021-10-04T09:24:25.4965293Z Author       : Microsoft Corporation
2021-10-04T09:24:25.4966175Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/test/publish-test-results
2021-10-04T09:24:25.4967042Z ==============================================================================
2021-10-04T09:24:25.5074413Z ##[debug]Using node path: /home/anonymuser/Az/CL_A01/externals/node10/bin/node
2021-10-04T09:24:25.7426211Z ##[debug]agent.TempDirectory=/home/anonymuser/Az/CL_A01/_work/_temp
2021-10-04T09:24:25.7476335Z ##[debug]loading inputs and endpoints
2021-10-04T09:24:25.7487172Z ##[debug]loading INPUT_TESTRUNNER
2021-10-04T09:24:25.7516283Z ##[debug]loading INPUT_TESTRESULTSFILES
2021-10-04T09:24:25.7519559Z ##[debug]loading INPUT_SEARCHFOLDER
2021-10-04T09:24:25.7522842Z ##[debug]loading INPUT_MERGETESTRESULTS
2021-10-04T09:24:25.7525343Z ##[debug]loading INPUT_FAILTASKONFAILEDTESTS
2021-10-04T09:24:25.7527969Z ##[debug]loading INPUT_TESTRUNTITLE
2021-10-04T09:24:25.7531940Z ##[debug]loading INPUT_PLATFORM
2021-10-04T09:24:25.7533792Z ##[debug]loading INPUT_PUBLISHRUNATTACHMENTS
2021-10-04T09:24:25.7536250Z ##[debug]loading ENDPOINT_AUTH_SYSTEMVSSCONNECTION
2021-10-04T09:24:25.7539332Z ##[debug]loading ENDPOINT_AUTH_SCHEME_SYSTEMVSSCONNECTION
2021-10-04T09:24:25.7542336Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_SYSTEMVSSCONNECTION_ACCESSTOKEN
2021-10-04T09:24:25.7551399Z ##[debug]loading SECRET_VSTS_PAT
2021-10-04T09:24:25.7554945Z ##[debug]loading SECRET_QUERY_BUNDLE_PRIVATE_KEY
2021-10-04T09:24:25.7556772Z ##[debug]loading SECRET_anonymCONTAINERREGISTRY_PWD
2021-10-04T09:24:25.7558895Z ##[debug]loading SECRET_AZURE_BLOB_USERNAME
2021-10-04T09:24:25.7563106Z ##[debug]loading SECRET_SHSDS_NPM_TOKEN
2021-10-04T09:24:25.7566008Z ##[debug]loading SECRET_AZURE_BLOB_PASSWORD
2021-10-04T09:24:25.7568616Z ##[debug]loading SECRET_AZURE_NPM_TOKEN
2021-10-04T09:24:25.7570647Z ##[debug]loading SECRET_SHUI_NPM_TOKEN
2021-10-04T09:24:25.7576292Z ##[debug]loading SECRET_SYSTEM_ACCESSTOKEN
2021-10-04T09:24:25.7578095Z ##[debug]loaded 20
2021-10-04T09:24:25.7589463Z ##[debug]Agent.ProxyUrl=http://139.22.102.14:8888
2021-10-04T09:24:25.7593341Z ##[debug]Agent.ProxyUsername=undefined
2021-10-04T09:24:25.7594980Z ##[debug]Agent.ProxyPassword=undefined
2021-10-04T09:24:25.7597105Z ##[debug]Agent.ProxyBypassList=undefined
2021-10-04T09:24:25.7598805Z ##[debug]expose agent proxy configuration.
2021-10-04T09:24:25.7600414Z ##[debug]Agent.CAInfo=undefined
2021-10-04T09:24:25.7602561Z ##[debug]Agent.ClientCert=undefined
2021-10-04T09:24:25.7604176Z ##[debug]Agent.SkipCertValidation=undefined
2021-10-04T09:24:25.7771988Z ##[debug]check path : /home/anonymuser/Az/CL_A01/_work/_tasks/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1/2.192.1/task.json
2021-10-04T09:24:25.7778716Z ##[debug]adding resource file: /home/anonymuser/Az/CL_A01/_work/_tasks/PublishTestResults_0b0f01ed-7dde-43ff-9cbb-e48954daf9b1/2.192.1/task.json
2021-10-04T09:24:25.7780644Z ##[debug]system.culture=en-US
2021-10-04T09:24:25.7816423Z ##[debug]testRunner=NUnit
2021-10-04T09:24:25.7820555Z ##[debug]testResultsFiles=test_results.xml
2021-10-04T09:24:25.7824979Z ##[debug]mergeTestResults=false
2021-10-04T09:24:25.7827365Z ##[debug]platform=anonym-nlp
2021-10-04T09:24:25.7828822Z ##[debug]configuration=undefined
2021-10-04T09:24:25.7830180Z ##[debug]testRunTitle=iTests NLP.QueryData (queries)
2021-10-04T09:24:25.7832818Z ##[debug]publishRunAttachments=true
2021-10-04T09:24:25.7834244Z ##[debug]failTaskOnFailedTests=true
2021-10-04T09:24:25.7835796Z ##[debug]searchFolder=/home/anonymuser/Az/CL_A01/_work/1/s
2021-10-04T09:24:25.7836895Z ##[debug]testRunner: NUnit
2021-10-04T09:24:25.7842224Z ##[debug]testResultsFiles: test_results.xml
2021-10-04T09:24:25.7843972Z ##[debug]mergeResults: false
2021-10-04T09:24:25.7845930Z ##[debug]platform: anonym-nlp
2021-10-04T09:24:25.7847432Z ##[debug]config: undefined
2021-10-04T09:24:25.7849307Z ##[debug]testRunTitle: iTests NLP.QueryData (queries)
2021-10-04T09:24:25.7850640Z ##[debug]publishRunAttachments: true
2021-10-04T09:24:25.7853727Z ##[debug]failTaskOnFailedTests: true
2021-10-04T09:24:25.7855803Z ##[debug]System.DefaultWorkingDirectory=/home/anonymuser/Az/CL_A01/_work/1/s
2021-10-04T09:24:25.7858267Z ##[debug]defaultRoot: '/home/anonymuser/Az/CL_A01/_work/1/s'
2021-10-04T09:24:25.7860381Z ##[debug]findOptions.allowBrokenSymbolicLinks: 'true'
2021-10-04T09:24:25.7864482Z ##[debug]findOptions.followSpecifiedSymbolicLink: 'true'
2021-10-04T09:24:25.7866713Z ##[debug]findOptions.followSymbolicLinks: 'true'
2021-10-04T09:24:25.7868456Z ##[debug]matchOptions.debug: 'false'
2021-10-04T09:24:25.7869714Z ##[debug]matchOptions.nobrace: 'true'
2021-10-04T09:24:25.7873357Z ##[debug]matchOptions.noglobstar: 'false'
2021-10-04T09:24:25.7875034Z ##[debug]matchOptions.dot: 'true'
2021-10-04T09:24:25.7876288Z ##[debug]matchOptions.noext: 'false'
2021-10-04T09:24:25.7877852Z ##[debug]matchOptions.nocase: 'false'
2021-10-04T09:24:25.7879093Z ##[debug]matchOptions.nonull: 'false'
2021-10-04T09:24:25.7880405Z ##[debug]matchOptions.matchBase: 'false'
2021-10-04T09:24:25.7883184Z ##[debug]matchOptions.nocomment: 'false'
2021-10-04T09:24:25.7884533Z ##[debug]matchOptions.nonegate: 'false'
2021-10-04T09:24:25.7885817Z ##[debug]matchOptions.flipNegate: 'false'
2021-10-04T09:24:25.7887076Z ##[debug]pattern: 'test_results.xml'
2021-10-04T09:24:25.7914156Z ##[debug]findPath: '/home/anonymuser/Az/CL_A01/_work/1/s/test_results.xml'
2021-10-04T09:24:25.7916389Z ##[debug]statOnly: 'true'
2021-10-04T09:24:25.7917397Z ##[debug]found 1 paths
2021-10-04T09:24:25.7918399Z ##[debug]applying include pattern
2021-10-04T09:24:25.7919818Z ##[debug]adjustedPattern: '/home/anonymuser/Az/CL_A01/_work/1/s/test_results.xml'
2021-10-04T09:24:25.7930449Z ##[debug]1 matches
2021-10-04T09:24:25.7934899Z ##[debug]1 final results
2021-10-04T09:24:25.7936336Z ##[debug]Detected 1 test result files
2021-10-04T09:24:25.7939518Z ##[debug]which 'dotnet'
2021-10-04T09:24:25.7955792Z ##[debug]not found
2021-10-04T09:24:25.7960036Z ##[debug]PublishTestResults.OverrideExeFlow=undefined
2021-10-04T09:24:25.7962274Z ##[debug]OS type: Linux
2021-10-04T09:24:33.5518858Z ##[debug]Object of TestLogStore created.
2021-10-04T09:24:33.5522561Z Result Attachments will be stored in LogStore
2021-10-04T09:24:33.5523741Z ##[debug]Object of TestResultsPublisher created.
2021-10-04T09:24:33.6056056Z ##[debug]Object of TestLogStore created.
2021-10-04T09:24:33.6057172Z Run Attachments will be stored in LogStore
2021-10-04T09:24:33.6058413Z ##[debug]Object of TestRunPublisher created.
2021-10-04T09:24:33.6062307Z ##[debug]Object of TestLogStore created.
2021-10-04T09:24:33.7196007Z ##[debug]Object of NUnitResultParser created.
2021-10-04T09:24:33.7212779Z ##[debug]Entering ParseTestResultFiles
2021-10-04T09:24:33.7218356Z ##[debug]runContext.ReleaseURI is null
2021-10-04T09:24:33.7219530Z ##[debug]runContext.ReleaseEnvironmentUri is null
2021-10-04T09:24:33.7260373Z ##[debug]Reading test results from file '/home/anonymuser/Az/CL_A01/_work/1/s/test_results.xml'.
2021-10-04T09:24:33.7793898Z ##[debug]Total test results: 110.
2021-10-04T09:24:33.7798352Z ##[debug]Leaving ParseTestResultFiles
2021-10-04T09:24:33.7843314Z ##[debug]runContext.ReleaseURI is null
2021-10-04T09:24:33.7844662Z ##[debug]Processed: ##vso[results.publish type=NUnit;mergeResults=false;platform=anonym-nlp;runTitle=iTests NLP.QueryData (queries);publishRunAttachments=true;resultFiles=/home/anonymuser/Az/CL_A01/_work/1/s/test_results.xml;failTaskOnFailedTests=true;testRunSystem=VSTS - PTR;]
2021-10-04T09:24:33.7845472Z ##[debug]runContext.ReleaseEnvironmentUri is null
2021-10-04T09:24:33.7848510Z ##[debug]task result: Succeeded
2021-10-04T09:24:33.7856509Z ##[debug]Processed: ##vso[task.complete result=Succeeded;]
2021-10-04T09:24:33.7858432Z ##[debug]Release.ReleaseUri=undefined
2021-10-04T09:24:33.7860157Z ##[debug]Release.ReleaseId=undefined
2021-10-04T09:24:33.7862494Z ##[debug]Build.BuildUri=vstfs:///Build/Build/7786
2021-10-04T09:24:33.7864220Z ##[debug]Build.Buildid=7786
2021-10-04T09:24:33.7909152Z ##[debug]Uploading build level attachements individually
2021-10-04T09:24:33.7937909Z ##[debug]Entering PublishToNewTestRunPerTestResultFileAsync
2021-10-04T09:24:33.8086896Z ##[debug]Entering CreateTestRunAsync
2021-10-04T09:24:33.8088188Z ##[debug]Leaving CreateTestRunAsync
2021-10-04T09:24:33.8578145Z ##[debug]Total build level attachments: 0.
2021-10-04T09:24:34.1874523Z ##[debug]Entering AddTestResultsAsync
2021-10-04T09:24:34.3049699Z Publishing test results to test run '1004296'.
2021-10-04T09:24:34.3117756Z TestResults To Publish 110, Test run id:1004296
2021-10-04T09:24:34.3201833Z Test results publishing 110, remaining: 0. Test run id: 1004296
2021-10-04T09:24:34.6722273Z ##[debug]Leaving AddTestResultsAsync
2021-10-04T09:24:34.6769675Z ##[debug]Entering UpdateTestRunAsync
2021-10-04T09:24:34.6772021Z ##[debug]Leaving UpdateTestRunAsync
2021-10-04T09:24:34.7605400Z ##[debug]Processed: ##vso[telemetry.publish area=TestExecution;feature=PublishTestResultsTask]{"builduri":"vstfs:///Build/Build/7786","buildid":"7786","osType":"Linux","testRunner":"NUnit","failTaskOnFailedTests":"true","mergeResultsUserPreference":"false","platform":"anonym-nlp","testResultsFilesCount":1,"dotnetVersion":"","subFeature":"publishTestResultsTaskConsolidatedCiEvent"}
2021-10-04T09:24:34.7690353Z ##[section]Async Command Start: Publish test results
2021-10-04T09:24:34.7693490Z ##[debug]Entering CreateTestRunAttachmentsAsync
2021-10-04T09:24:34.8127328Z ##[debug]Leaving CreateTestRunAttachmentsAsync
2021-10-04T09:24:34.8144195Z ##[debug]Uploading test run attachements individually
2021-10-04T09:24:34.8194976Z ##[debug]Entering UploadTestRunLogAsync
2021-10-04T09:24:35.0427710Z ##[debug]Blob name: GeneralAttachment/test_results.xml .
2021-10-04T09:39:09.7937794Z ##[warning]Failed to upload file test_results.xml to Blob Transfer exception with errorcode Unknown, exception message Microsoft.Azure.Storage.DataMovement.TransferException: The transfer failed.
 ---> Microsoft.Azure.Storage.StorageException: Network is unreachable
 ---> System.Net.Http.HttpRequestException: Network is unreachable
 ---> System.Net.Sockets.SocketException (101): Network is unreachable
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Microsoft.Azure.Storage.Core.Executor.Executor.ExecuteAsync[T](RESTCommand`1 cmd, IRetryPolicy policy, OperationContext operationContext, CancellationToken token)
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Storage.DataMovement.TransferControllers.BlockBlobWriter.HandleFetchAttributesResultAsync(Exception e)
   at Microsoft.Azure.Storage.DataMovement.TransferControllers.BlockBlobWriter.FetchAttributesAsync()
   at Microsoft.Azure.Storage.DataMovement.TransferControllers.BlockBlobWriter.DoWorkInternalAsync()
   at Microsoft.Azure.Storage.DataMovement.TransferControllers.SyncTransferController.DoWorkInternalAsync()
   at Microsoft.Azure.Storage.DataMovement.TransferControllers.TransferControllerBase.DoWorkAsync()
   at Microsoft.Azure.Storage.DataMovement.TransferScheduler.ExecuteJobInternalAsync(TransferJob job, CancellationToken cancellationToken)
Request Information
RequestID:
RequestDate:
StatusMessage:
ErrorCode:

   --- End of inner exception stack trace ---
   at Microsoft.TeamFoundation.TestClient.PublishTestResults.TestLogStore._executeWithRetry(Func`1 action, Func`1 actionWithRename, Func`1 actionOnSasExpiry, Boolean allowDuplicate, Boolean allowRetryOnNetworkingError, TelemetryTracker telemetryTracker)
   at Microsoft.TeamFoundation.TestClient.PublishTestResults.TestLogStore.UploadInternalAsync(Guid projectId, TestLogScope scope, Int32 buildId, Int32 runId, String logFileSourcePath, Stream stream, String fileName, TestLogType logType, Int32 testResultId, Int32 testSubResultId, Dictionary`2 metaData, TelemetryTracker telTracker, Boolean allowDuplicate, TestLogCompressionType logCompressionType, String originalFileContentType)
2021-10-04T09:39:09.8063377Z ##[debug]Failed to Upload on log store with error code TransferFailed
2021-10-04T09:39:09.8065132Z Failed to upload run logs to LogStore, Trying to upload to FileService
2021-10-04T09:39:10.5499582Z Failed to publish Telemetry Exception: Object reference not set to an instance of an object.
2021-10-04T09:39:13.0928578Z Published Test Run : https://anonym.visualstudio.com/anonym_Prototypes/_TestManagement/Runs?runId=1004296&_a=runCharts
2021-10-04T09:39:13.0944630Z ##[debug]Leaving PublishToNewTestRunPerTestResultFileAsync
2021-10-04T09:39:13.5884918Z ##[debug]RESOURCE_URIS:
2021-10-04T09:39:13.5933443Z ##[debug]Setting task variable METADATA_801ad287-a9d1-4de5-909e-77243e7405c6: {"name":"80ba4053-c4c0-4d73-bb23-a250b4437465","resourceUris":[],"metadata":{"description":"","relatedUrls":[{"url":"https://dev.azure.com/anonym/anonym_Prototypes/_build/results?buildId=7786","label":"pipeline-url"}],"humanReadableName":"Test Results from Publish Test Results utility","serializedPayload":"{\"testId\":\"PublishTestResults\",\"testTool\":\"NUnit\",\"testResultAttestation\":{\"total\":110,\"failed\":0,\"passed\":110,\"skipped\":0},\"testDurationSeconds\":0.0,\"testPassPercentage\":\"100\",\"relatedUrls\":[{\"url\":\"https://dev.azure.com/anonym/anonym_Prototypes/_build/results?buildId=7786\",\"label\":\"pipeline-url\"}]}"}} 
2021-10-04T09:39:13.8608666Z ##[section]Async Command End: Publish test results
2021-10-04T09:39:13.8612080Z ##[section]Finishing: PublishTestResults

[EzzhevNikita]

@petermicuch, thank you for providing detailed logs. I see from the logs that network connection is restricted for uploading process: "Failed to upload file test_results.xml ... StorageException: Network is unreachable". At the same time other operations from PublishTestResults task are fine. And there are no issues during using of exception for agent on proxy server. It looks like some service Microsoft URLs are blocked by proxy server. Just as example, blocking of URLs tcmproduks1.vstmr.visualstudio.com and vstmr.dev.azure.com can cause similar issue but with other error message. Please find full list of URLs and IPs used by Microsoft services below and make sure that they aren't blocked by proxy server. https://docs.microsoft.com/en-us/azure/devops/organizations/security/allow-list-ip-url https://docs.microsoft.com/en-us/visualstudio/install/install-and-use-visual-studio-behind-a-firewall-or-proxy-server

[petermicuch]

@EzzhevNikita I think we already do have all URLs in the whitelist, but I will ask to check again.

[petermicuch]

@EzzhevNikita guys checked proxy logs. There were no blocks noticed going out of this machine in the proxy.

[EzzhevNikita]

@petermicuch, I can assure you that task PublishTaskResults works with proxy servers correctly. When exception for an agent is active, proxy isn't disabled for the agent. In this case traffic from the agent still goes through proxy server, but restriction rules declared on proxy server aren't used for this traffic. And I see in logs of successful attempt of task PublishTaskResults above that proxy used for task in this case, but rules from proxy server didn't block connections, so publish was successful. And I have question about exceptions granted on your proxy server. Is it allowing for ignoring of all rules declared by proxy server or declaring of some additional rules to allow some connections for the agent? If it's adding of additional rules then could you please share info about the rules to me? Maybe it can help in looking for root cause of the issue.

Error 101 presented in latest logs can be caused by restricted connection or network issues. At the same time we see that turning off all restrictions for the agent on proxy server fixes the issue. As additional ways to solve the issue I can suggest following:

• make sure that ports used for connections aren't closed. Please make a note that not only ports 80 and 443 are used here
• make sure that your internet service provider support IPv6. Some connections can be established using IPv6
• check for routing on proxy server. Perhaps some connections can be routed to non-existed or currently unavailable resources

[petermicuch]

@EzzhevNikita I understand what you are saying, but I also got info from our IT that observed logs of the proxy server and have not seen any blocked traffic for this proxy server. Could you maybe be a bit more specific about exact URL and ports that are used to publish that test_results.xml? That would help me to formulate more specific request to the IT on my side. Thank you in advance.

[petermicuch]

@EzzhevNikita just checked proxy logs and firewall logs. We can see, that during publishing of test results, all traffic is routed via proxy except of one URL: etqtcmprodweu11.vstmrblob.vsassets.io. This one never went over the proxy (we checked logs for last week) and we see in our firewall logs, that this is accessed directly. You can see in the picture below, that most of the traffic during publishing goes over our proxy http://139.22.102.14:8888 which is also seen as ##[debug]Agent.ProxyUrl=http://139.22.102.14:8888 in your diagnostic logs, but one request is not. 10.81.17.73 is the IP of the machine with the azure agent running the test:

So to simulate this on your side, you actually have to block all the traffic that does not go over the proxy and tries to access 443 directly bypassing the proxy. Then you should be able to reproduce this.

BTW - our proxy white lists also complete .vsassets.io if that would be the question. Thanks.

[denis-tikhomirov]

I checked this issue, and found that 1 operation in task Publish Test Results doesn't use proxy for connection to MS services. And during investigation of root cause of issue I have found that this can be induced by interface from library Microsoft.VisualStudio.Services.Common. @SadagopanRajaram, I sent you details about the issue yesterday by email. Please take a look at this.

[shailesh-sk]

@upadhyayap can you look into this issue and help customer here.

[triptijain2112]

Acknowledging the issue, We are trying to repro the issue at our end. Will share our findings here.

[triptijain2112]

Hi @petermicuch , Apologies for delay in the resolution. Could you please provide access for the pipeline (triptijain@microsoft.com)

https://dev.azure.com/iii40

[triptijain2112]

Hi @petermicuch , following up on the above request.

[JanneRantala]

@triptijain2112 Any news about this? I'm having similar issue with pool with two on-prem agents where another one is able to publish test results but the other one is not. Both are using agent version 2.200.2. PublishTestResults -task gets stuck for 15 minutes. Both agents are using same proxy server.

[petermicuch]

@triptijain2112 sorry for very late response, I've been out of office for couple of months. Unfortunately that agent has been removed during my absence. But my colleague has agent that has the same issue. @marusinp could you please assist @triptijain2112 .

[marusinp]

Hi @triptijain2112 unfortunately I'm unable to share the pipeline - corporate policy. However I also observed the issue w/ publishing the test results - currently the pipeline is stuck for a while while trying to upload logs to FileService since the LogStore upload failed. Sometimes FileService upload finishes successfully, sometimes not. I'll reach out via e-mail, maybe we could schedule a live session.

[github-actions[bot]]

This issue is stale because it has been open for 180 days with no activity. Remove the stale label or comment on the issue otherwise this will be closed in 5 days

[pixdrift]

Can this issue be re-opened? I am seeing this issue with current release (3.220.2) of self-hosted Linux agent.

Have any fixes been proposed or released?

[kruese]

We are also seeing this issue. Has not been resolved from our side.

[petermicuch]

Yes, this was not fixed and no one contacted @marusinp further to investigate. Unfortunatelly there is no possibility for me to reopen this issue. @rasunkar could you please reopen this? It would be nice if this could be solved. There are obviously multiple people having the same problem.

[grahamfurner]

@triptijain2112 Could you please reopen this bug? It was closed in error. I can confirm this issue is still present in 3.232.1.