Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[BUG]: publishing test run data from behind corporate proxy fails with socket timeout error while accessing ufxtcmprodweu21.vstmrblob.vsassets.io:443 #5066

Open
1 of 4 tasks
klapantius opened this issue Dec 18, 2024 · 1 comment
Open
1 of 4 tasks

[BUG]: publishing test run data from behind corporate proxy fails with socket timeout error while accessing ufxtcmprodweu21.vstmrblob.vsassets.io:443 #5066

klapantius opened this issue Dec 18, 2024 · 1 comment
Labels
Area: Agent bug triage

Comments

@klapantius
Copy link

klapantius commented Dec 18, 2024 •
edited
Loading

What happened?

We are preparing for maintaining our code in a hybrid setup: codebase is archived in cloud, pipelines are stored and started from cloud, azure pipelines agents are hosted on-premises.

The agents are configured with a proxy server and proper bypass rules. Access to internal and external targets is basically working properly with exception of publishing test run data. We observe the following exception in our worker-logs (Worker_20241217-123930-utc.log):

[2024-12-17 12:56:43Z VERB JobServerQueue] Enqueue web console line queue: ##[warning]Failed to upload file TestResultDetails_202412171341402018.tau to Blob Transfer exception with errorcode Unknown, exception message Microsoft.Azure.Storage.DataMovement.TransferException: The transfer failed.
 ---> Microsoft.Azure.Storage.StorageException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond. (ufxtcmprodweu21.vstmrblob.vsassets.io:443)
 ---> System.Net.Http.HttpRequestException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond. (ufxtcmprodweu21.vstmrblob.vsassets.io:443)
 ---> System.Net.Sockets.SocketException (10060): A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
   at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|277_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectToTcpHostAsync(String host, Int32 port, HttpRequestMessage initialRequest, Boolean async, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpConnectionPool.ConnectToTcpHostAsync(String host, Int32 port, HttpRequestMessage initialRequest, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.AddHttp11ConnectionAsync(HttpRequestMessage request)
   at System.Threading.Tasks.TaskCompletionSourceWithCancellation`1.WaitWithCancellationAsync(CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.GetHttp11ConnectionAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
   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.Azure.Storage.DataMovement.TransferScheduler.ExecuteJobInternalAsync(TransferJob job, CancellationToken cancellationToken)
   at Microsoft.Azure.Storage.DataMovement.SingleObjectTransfer.ExecuteAsync(TransferScheduler scheduler, CancellationToken cancellationToken)
   at Microsoft.Azure.Storage.DataMovement.TransferManager.DoTransfer(Transfer transfer, TransferContext transferContext, CancellationToken cancellationToken)
   at Microsoft.TeamFoundation.TestClient.PublishTestResults.TestLogStoreDALImpl.UploadLogFile(TestLogFileTransferModel uploadLogFileParam)
   at Microsoft.TeamFoundation.TestClient.PublishTestResults.TestLogStore._getContainerAndUpload(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 isDuplicate, Boolean isSasExpired, TestLogCompressionType logCompressionType, String originalFileContentType)
   at Microsoft.TeamFoundation.TestClient.PublishTestResults.TestLogStore.<>c__DisplayClass19_0.<<UploadInternalAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   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)

Notice: we use a custom build task wrapping a tool which coordinates the test execution and collects the test results. Each test run will be followed by a test attachment publisher method which utilizes a vso command:

        public void NotifyBuildAgentToPublishResultsForTFS(string resultFile)
        {
            string vsoCommand = $"##vso[results.publish type=VsTest;mergeResults=false;publishRunAttachments=true;resultFiles={resultFile};]";
            Tracer.Info("VsoCommand: {0}", vsoCommand);
            Console.WriteLine(vsoCommand);
        }

We see in the logs, that the processing of these console commands happens after the tool has terminated:
Image
proxy-4-test-upload.build.log

Versions

Azure DevOps version 2.100.1

Environment type (Please select at least one environment where you face this issue)

  • Self-Hosted
  • Microsoft Hosted
  • VMSS Pool
  • Container

Azure DevOps Server type

dev.azure.com (formerly visualstudio.com)

Azure DevOps Server Version (if applicable)

No response

Operation system

Windows

Version controll system

git

Relevant log output

Here is a somehow longer excerpt from the worker-log. There is a longer period before the exception happens repeating the same two lines:


[2024-12-17 12:41:59Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'd2d6039d-ae59-57d7-8db1-c55c44054d5d', success rate: 1/1.
[2024-12-17 12:42:00Z VERB Variables] Get 'task.skipTranslatorForCheckout': 'False'
[2024-12-17 12:42:00Z VERB Variables] Get 'agent.workfolder': 'c:\b\juba'
[2024-12-17 12:42:05Z VERB Variables] Get 'task.skipTranslatorForCheckout': 'False'
[2024-12-17 12:42:05Z VERB Variables] Get 'agent.workfolder': 'c:\b\juba'
[2024-12-17 12:42:10Z VERB Variables] Get 'task.skipTranslatorForCheckout': 'False'
[2024-12-17 12:42:10Z VERB Variables] Get 'agent.workfolder': 'c:\b\juba'
[2024-12-17 12:42:15Z VERB Variables] Get 'task.skipTranslatorForCheckout': 'False'
[2024-12-17 12:42:15Z VERB Variables] Get 'agent.workfolder': 'c:\b\juba'
[2024-12-17 12:42:20Z VERB Variables] Get 'task.skipTranslatorForCheckout': 'False'
[2024-12-17 12:42:20Z VERB Variables] Get 'agent.workfolder': 'c:\b\juba'
.
.
.
[2024-12-17 12:56:39Z VERB Variables] Get 'task.skipTranslatorForCheckout': 'False'
[2024-12-17 12:56:39Z VERB Variables] Get 'task.skipTranslatorForCheckout': 'False'
[2024-12-17 12:56:39Z VERB Variables] Get 'agent.workfolder': 'c:\b\juba'
[2024-12-17 12:56:39Z VERB Variables] Get 'agent.workfolder': 'c:\b\juba'
[2024-12-17 12:56:43Z VERB JobServerQueue] Enqueue web console line queue: ##[warning]Failed to upload file TestResultDetails_202412171341402018.tau to Blob Transfer exception with errorcode Unknown, exception message Microsoft.Azure.Storage.DataMovement.TransferException: The transfer failed.
 ---> Microsoft.Azure.Storage.StorageException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond. (ufxtcmprodweu21.vstmrblob.vsassets.io:443)
 ---> System.Net.Http.HttpRequestException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond. (ufxtcmprodweu21.vstmrblob.vsassets.io:443)
 ---> System.Net.Sockets.SocketException (10060): A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)



As a proof of basically good configuration here are the logs short before the above exception happened. It shows that communication with external targets outside of the organization can be done successful.


[2024-12-17 12:41:55Z VERB VisualStudioServices] Started GET request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/_apis/FeatureFlags/TestManagement.PublishTestResultsTask.EnableXUnitHeirarchicalParsing
[2024-12-17 12:41:55Z VERB VisualStudioServices] Finished GET request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/_apis/FeatureFlags/TestManagement.PublishTestResultsTask.EnableXUnitHeirarchicalParsing with status code 200
[2024-12-17 12:41:55Z VERB VisualStudioServices] Started GET request to https://tcmprodweu2.vstmr.visualstudio.com/A96abf037-9950-4c6d-9a40-0be2afe4024f/_apis/FeatureFlags/TestManagement.Server.CustomTestFieldsInPTRInputFilesEnabled
[2024-12-17 12:41:55Z VERB VisualStudioServices] Finished GET request to https://tcmprodweu2.vstmr.visualstudio.com/A96abf037-9950-4c6d-9a40-0be2afe4024f/_apis/FeatureFlags/TestManagement.Server.CustomTestFieldsInPTRInputFilesEnabled with status code 200
[2024-12-17 12:41:55Z VERB Variables] Get 'DECODE_PERCENTS' (not found)
[2024-12-17 12:41:55Z VERB VisualStudioServices] Started GET request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/_apis/projects/native
[2024-12-17 12:41:55Z VERB VisualStudioServices] Started POST request to https://vstmr.dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/native/_apis/testresults/runs
[2024-12-17 12:41:55Z VERB VisualStudioServices] Started POST request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/14a774bf-8f3b-4780-8e5b-c2490de7db54/_apis/distributedtask/hubs/Build/plans/c65e2c3c-adc0-4522-8595-888215dde5ba/timelines/c65e2c3c-adc0-4522-8595-888215dde5ba/records/fd490c07-0b22-5182-fac9-6d67fe1e939b/feed
[2024-12-17 12:41:55Z VERB VisualStudioServices] Finished GET request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/_apis/projects/native with status code 200
[2024-12-17 12:41:55Z VERB VisualStudioServices] Finished POST request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/14a774bf-8f3b-4780-8e5b-c2490de7db54/_apis/distributedtask/hubs/Build/plans/c65e2c3c-adc0-4522-8595-888215dde5ba/timelines/c65e2c3c-adc0-4522-8595-888215dde5ba/records/fd490c07-0b22-5182-fac9-6d67fe1e939b/feed with status code 204
[2024-12-17 12:41:55Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'd2d6039d-ae59-57d7-8db1-c55c44054d5d', success rate: 1/1.
[2024-12-17 12:41:55Z VERB VisualStudioServices] Finished POST request to https://vstmr.dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/native/_apis/testresults/runs with status code 200
[2024-12-17 12:41:56Z VERB VisualStudioServices] Started GET request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/_apis/projects/native
[2024-12-17 12:41:56Z VERB VisualStudioServices] Finished GET request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/_apis/projects/native with status code 200
[2024-12-17 12:41:56Z VERB JobServerQueue] Enqueue web console line queue: Publishing test results to test run '111768156'.
[2024-12-17 12:41:56Z VERB JobServerQueue] Enqueue web console line queue: TestResults To Publish 2, Test run id:111768156
[2024-12-17 12:41:56Z VERB JobServerQueue] Enqueue web console line queue: Test results publishing 2, remaining: 0. Test run id: 111768156
[2024-12-17 12:41:56Z VERB VisualStudioServices] Started POST request to https://tcmprodweu2.vstmr.visualstudio.com/A96abf037-9950-4c6d-9a40-0be2afe4024f/native/_apis/testresults/runs/111768156/results
[2024-12-17 12:41:56Z VERB VisualStudioServices] Started POST request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/14a774bf-8f3b-4780-8e5b-c2490de7db54/_apis/distributedtask/hubs/Build/plans/c65e2c3c-adc0-4522-8595-888215dde5ba/timelines/c65e2c3c-adc0-4522-8595-888215dde5ba/records/fd490c07-0b22-5182-fac9-6d67fe1e939b/feed
[2024-12-17 12:41:56Z VERB VisualStudioServices] Finished POST request to https://tcmprodweu2.vstmr.visualstudio.com/A96abf037-9950-4c6d-9a40-0be2afe4024f/native/_apis/testresults/runs/111768156/results with status code 200
[2024-12-17 12:41:56Z VERB VisualStudioServices] Started PATCH request to https://vstmr.dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/native/_apis/testresults/runs/111768156
[2024-12-17 12:41:56Z VERB VisualStudioServices] Finished POST request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/14a774bf-8f3b-4780-8e5b-c2490de7db54/_apis/distributedtask/hubs/Build/plans/c65e2c3c-adc0-4522-8595-888215dde5ba/timelines/c65e2c3c-adc0-4522-8595-888215dde5ba/records/fd490c07-0b22-5182-fac9-6d67fe1e939b/feed with status code 204
[2024-12-17 12:41:56Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'd2d6039d-ae59-57d7-8db1-c55c44054d5d', success rate: 1/1.
[2024-12-17 12:41:56Z VERB VisualStudioServices] Finished PATCH request to https://vstmr.dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/native/_apis/testresults/runs/111768156 with status code 200
[2024-12-17 12:41:56Z VERB VisualStudioServices] Started GET request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/_apis/projects/native
[2024-12-17 12:41:56Z VERB VisualStudioServices] Finished GET request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/_apis/projects/native with status code 200
[2024-12-17 12:41:56Z VERB VisualStudioServices] Started POST request to https://tcmprodweu2.vstmr.visualstudio.com/A96abf037-9950-4c6d-9a40-0be2afe4024f/14a774bf-8f3b-4780-8e5b-c2490de7db54/_apis/testresults/runs/111768156/testlogstoreendpoint
[2024-12-17 12:41:56Z VERB VisualStudioServices] Finished POST request to https://tcmprodweu2.vstmr.visualstudio.com/A96abf037-9950-4c6d-9a40-0be2afe4024f/14a774bf-8f3b-4780-8e5b-c2490de7db54/_apis/testresults/runs/111768156/testlogstoreendpoint with status code 200
[2024-12-17 12:41:58Z VERB Variables] Get 'DECODE_PERCENTS' (not found)
[2024-12-17 12:41:58Z VERB JobServerQueue] Enqueue web console line queue: Message: Done
[2024-12-17 12:41:58Z VERB Variables] Get 'DECODE_PERCENTS' (not found)
[2024-12-17 12:41:58Z VERB JobServerQueue] Enqueue web console line queue: Message: ExitCode = 0 (Ok)
[2024-12-17 12:41:58Z VERB Variables] Get 'DECODE_PERCENTS' (not found)
[2024-12-17 12:41:58Z VERB JobServerQueue] Enqueue web console line queue: Task completed.
[2024-12-17 12:41:58Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2024-12-17 12:41:58Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2024-12-17 12:41:58Z INFO ProcessInvokerWrapper] Exited process 2240 with exit code 0
[2024-12-17 12:41:58Z INFO ProcessInvokerWrapper] Finished process 2240 with exit code 0, and elapsed time 00:02:15.9705004.
[2024-12-17 12:41:58Z VERB Variables] Unset 'task.displayname'
[2024-12-17 12:41:58Z VERB Variables] Unset 'task.publishTelemetry'
[2024-12-17 12:41:58Z VERB Variables] Unset 'system.taskInstanceId'
[2024-12-17 12:41:58Z VERB Variables] Unset 'system.taskDisplayName'
[2024-12-17 12:41:58Z VERB Variables] Unset 'system.taskInstanceName'
[2024-12-17 12:41:58Z VERB AsyncCommandContext] Entering WaitAsync
[2024-12-17 12:41:58Z INFO AsyncCommandContext] Start flush buffered output.
[2024-12-17 12:41:58Z VERB JobServerQueue] Enqueue web console line queue: ##[section]Async Command Start: Publish test results
[2024-12-17 12:41:59Z VERB VisualStudioServices] Started POST request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/14a774bf-8f3b-4780-8e5b-c2490de7db54/_apis/distributedtask/hubs/Build/plans/c65e2c3c-adc0-4522-8595-888215dde5ba/timelines/c65e2c3c-adc0-4522-8595-888215dde5ba/records/fd490c07-0b22-5182-fac9-6d67fe1e939b/feed
[2024-12-17 12:41:59Z VERB VisualStudioServices] Finished POST request to https://dev.azure.com/SHS-IKMTPCProjects-dryrun-dryrun/14a774bf-8f3b-4780-8e5b-c2490de7db54/_apis/distributedtask/hubs/Build/plans/c65e2c3c-adc0-4522-8595-888215dde5ba/timelines/c65e2c3c-adc0-4522-8595-888215dde5ba/records/fd490c07-0b22-5182-fac9-6d67fe1e939b/feed with status code 204
@klapantius klapantius added the bug label Dec 18, 2024
@klapantius
Copy link
Author

klapantius commented Dec 20, 2024 •
edited
Loading

The logs show that SyncTransferController uses HtmlClient
Image

The constructor of TestLogStoreDALImpl passes the webProxy object to the init() method of the base class TestLogStoreDAL and that associates it to WebRequest.DefaultWebProxy

If I initialize HttpClient.DefaultProxy in the agent, then the error disappears.

Image

This is most probably not the solution but clearly shows the root cause.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Area: Agent bug triage
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@klapantius