From 19ce9f8d77e050668bab0bb3c71bf8a9fbf68e8f Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Wed, 5 Feb 2025 22:02:03 +0100 Subject: [PATCH 01/16] investigation --- eng/pipelines/libraries/stress/http.yml | 164 +++++++++--------- .../Http/SocketsHttpHandler/HttpConnection.cs | 4 +- .../StressTests/HttpStress/entrypoint.ps1 | 5 + 3 files changed, 90 insertions(+), 83 deletions(-) diff --git a/eng/pipelines/libraries/stress/http.yml b/eng/pipelines/libraries/stress/http.yml index 257334fce3e99c..92d007079b725e 100644 --- a/eng/pipelines/libraries/stress/http.yml +++ b/eng/pipelines/libraries/stress/http.yml @@ -30,69 +30,69 @@ extends: stages: - stage: Build jobs: - - job: linux - displayName: Docker Linux - timeoutInMinutes: 240 - variables: - DUMPS_SHARE_MOUNT_ROOT: "/dumps-share" - DUMPS_SHARE: "$(Build.ArtifactStagingDirectory)/dumps/" - pool: - name: $(DncEngPublicBuildPool) - demands: ImageOverride -equals Build.Ubuntu.2204.Amd64.Open - - steps: - - checkout: self - clean: true - fetchDepth: 5 - - - bash: | - $(dockerfilesFolder)/build-docker-sdk.sh -t $(sdkBaseImage) -c $(BUILD_CONFIGURATION) && \ - echo "##vso[task.setvariable variable=succeeded;isOutput=true]true" - name: buildRuntime - displayName: Build CLR and Libraries - - - bash: | - $(httpStressProject)/run-docker-compose.sh -o -c $(BUILD_CONFIGURATION) -t $(sdkBaseImage) && \ - echo "##vso[task.setvariable variable=succeeded;isOutput=true]true" - name: buildStress - displayName: Build HttpStress - - - bash: | - cd '$(httpStressProject)' - export STRESS_CLIENT_ARGS="$HTTPSTRESS_CLIENT_ARGS -http 3.0" - export STRESS_SERVER_ARGS="$HTTPSTRESS_SERVER_ARGS -http 3.0" - mkdir -p $DUMPS_SHARE - docker-compose up --abort-on-container-exit --no-color - timeoutInMinutes: 35 # In case the HTTP/3.0 run hangs, we timeout shortly after the expected 30 minute run - displayName: Run HttpStress - HTTP 3.0 - condition: and(eq(variables['buildRuntime.succeeded'], 'true'), eq(variables['buildStress.succeeded'], 'true')) - - - bash: | - cd '$(httpStressProject)' - export STRESS_CLIENT_ARGS="$HTTPSTRESS_CLIENT_ARGS -http 2.0" - export STRESS_SERVER_ARGS="$HTTPSTRESS_SERVER_ARGS -http 2.0" - mkdir -p $DUMPS_SHARE - docker-compose up --abort-on-container-exit --no-color - displayName: Run HttpStress - HTTP 2.0 - condition: and(eq(variables['buildRuntime.succeeded'], 'true'), eq(variables['buildStress.succeeded'], 'true')) - - - bash: | - cd '$(httpStressProject)' - export STRESS_CLIENT_ARGS="$HTTPSTRESS_CLIENT_ARGS -http 1.1" - export STRESS_SERVER_ARGS="$HTTPSTRESS_SERVER_ARGS -http 1.1" - mkdir -p $DUMPS_SHARE - docker-compose up --abort-on-container-exit --no-color - displayName: Run HttpStress - HTTP 1.1 - condition: and(eq(variables['buildRuntime.succeeded'], 'true'), eq(variables['buildStress.succeeded'], 'true')) - - - bash: | - sudo chown -R $(id -u):$(id -g) $(Build.ArtifactStagingDirectory)/dumps - displayName: Own shared dumps and files - condition: failed() - - - publish: $(Build.ArtifactStagingDirectory)/dumps - artifact: DumpsLinux - condition: failed() + # - job: linux + # displayName: Docker Linux + # timeoutInMinutes: 240 + # variables: + # DUMPS_SHARE_MOUNT_ROOT: "/dumps-share" + # DUMPS_SHARE: "$(Build.ArtifactStagingDirectory)/dumps/" + # pool: + # name: $(DncEngPublicBuildPool) + # demands: ImageOverride -equals Build.Ubuntu.2204.Amd64.Open + + # steps: + # - checkout: self + # clean: true + # fetchDepth: 5 + + # - bash: | + # $(dockerfilesFolder)/build-docker-sdk.sh -t $(sdkBaseImage) -c $(BUILD_CONFIGURATION) && \ + # echo "##vso[task.setvariable variable=succeeded;isOutput=true]true" + # name: buildRuntime + # displayName: Build CLR and Libraries + + # - bash: | + # $(httpStressProject)/run-docker-compose.sh -o -c $(BUILD_CONFIGURATION) -t $(sdkBaseImage) && \ + # echo "##vso[task.setvariable variable=succeeded;isOutput=true]true" + # name: buildStress + # displayName: Build HttpStress + + # - bash: | + # cd '$(httpStressProject)' + # export STRESS_CLIENT_ARGS="$HTTPSTRESS_CLIENT_ARGS -http 3.0" + # export STRESS_SERVER_ARGS="$HTTPSTRESS_SERVER_ARGS -http 3.0" + # mkdir -p $DUMPS_SHARE + # docker-compose up --abort-on-container-exit --no-color + # timeoutInMinutes: 35 # In case the HTTP/3.0 run hangs, we timeout shortly after the expected 30 minute run + # displayName: Run HttpStress - HTTP 3.0 + # condition: and(eq(variables['buildRuntime.succeeded'], 'true'), eq(variables['buildStress.succeeded'], 'true')) + + # - bash: | + # cd '$(httpStressProject)' + # export STRESS_CLIENT_ARGS="$HTTPSTRESS_CLIENT_ARGS -http 2.0" + # export STRESS_SERVER_ARGS="$HTTPSTRESS_SERVER_ARGS -http 2.0" + # mkdir -p $DUMPS_SHARE + # docker-compose up --abort-on-container-exit --no-color + # displayName: Run HttpStress - HTTP 2.0 + # condition: and(eq(variables['buildRuntime.succeeded'], 'true'), eq(variables['buildStress.succeeded'], 'true')) + + # - bash: | + # cd '$(httpStressProject)' + # export STRESS_CLIENT_ARGS="$HTTPSTRESS_CLIENT_ARGS -http 1.1" + # export STRESS_SERVER_ARGS="$HTTPSTRESS_SERVER_ARGS -http 1.1" + # mkdir -p $DUMPS_SHARE + # docker-compose up --abort-on-container-exit --no-color + # displayName: Run HttpStress - HTTP 1.1 + # condition: and(eq(variables['buildRuntime.succeeded'], 'true'), eq(variables['buildStress.succeeded'], 'true')) + + # - bash: | + # sudo chown -R $(id -u):$(id -g) $(Build.ArtifactStagingDirectory)/dumps + # displayName: Own shared dumps and files + # condition: failed() + + # - publish: $(Build.ArtifactStagingDirectory)/dumps + # artifact: DumpsLinux + # condition: failed() - job: windows displayName: Docker NanoServer @@ -129,27 +129,27 @@ extends: name: disableFirewall displayName: Disable Firewall - - powershell: | - cd '$(httpStressProject)' - $env:STRESS_CLIENT_ARGS = "$env:HTTPSTRESS_CLIENT_ARGS -http 3.0" - $env:STRESS_SERVER_ARGS = "$env:HTTPSTRESS_SERVER_ARGS -http 3.0" - New-Item -Force $env:DUMPS_SHARE -ItemType Directory - docker compose up --abort-on-container-exit --no-color - displayName: Run HttpStress - HTTP 3.0 - condition: and(eq(variables['buildRuntime.succeeded'], 'true'), eq(variables['buildStress.succeeded'], 'true')) - - - powershell: | - cd '$(httpStressProject)' - $env:STRESS_CLIENT_ARGS = "$env:HTTPSTRESS_CLIENT_ARGS -http 2.0" - $env:STRESS_SERVER_ARGS = "$env:HTTPSTRESS_SERVER_ARGS -http 2.0" - New-Item -Force $env:DUMPS_SHARE -ItemType Directory - docker compose up --abort-on-container-exit --no-color - displayName: Run HttpStress - HTTP 2.0 - condition: and(eq(variables['buildRuntime.succeeded'], 'true'), eq(variables['buildStress.succeeded'], 'true')) + # - powershell: | + # cd '$(httpStressProject)' + # $env:STRESS_CLIENT_ARGS = "$env:HTTPSTRESS_CLIENT_ARGS -http 3.0" + # $env:STRESS_SERVER_ARGS = "$env:HTTPSTRESS_SERVER_ARGS -http 3.0" + # New-Item -Force $env:DUMPS_SHARE -ItemType Directory + # docker compose up --abort-on-container-exit --no-color + # displayName: Run HttpStress - HTTP 3.0 + # condition: and(eq(variables['buildRuntime.succeeded'], 'true'), eq(variables['buildStress.succeeded'], 'true')) + + # - powershell: | + # cd '$(httpStressProject)' + # $env:STRESS_CLIENT_ARGS = "$env:HTTPSTRESS_CLIENT_ARGS -http 2.0" + # $env:STRESS_SERVER_ARGS = "$env:HTTPSTRESS_SERVER_ARGS -http 2.0" + # New-Item -Force $env:DUMPS_SHARE -ItemType Directory + # docker compose up --abort-on-container-exit --no-color + # displayName: Run HttpStress - HTTP 2.0 + # condition: and(eq(variables['buildRuntime.succeeded'], 'true'), eq(variables['buildStress.succeeded'], 'true')) - powershell: | cd '$(httpStressProject)' - $env:STRESS_CLIENT_ARGS = "$env:HTTPSTRESS_CLIENT_ARGS -http 1.1" + $env:STRESS_CLIENT_ARGS = "-maxExecutionTime 5 -displayInterval 60 -http 1.1 -trace" $env:STRESS_SERVER_ARGS = "$env:HTTPSTRESS_SERVER_ARGS -http 1.1" New-Item -Force $env:DUMPS_SHARE -ItemType Directory docker compose up --abort-on-container-exit --no-color @@ -158,7 +158,7 @@ extends: - publish: $(Build.ArtifactStagingDirectory)/dumps artifact: DumpsWindows - condition: failed() + # condition: failed() - powershell: | Set-NetFirewallProfile -Profile Domain, Public, Private -Enabled True diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs index 0b03489d93aff3..8b8e7e2c39d6fd 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs @@ -68,6 +68,7 @@ internal sealed partial class HttpConnection : HttpConnectionBase private bool _connectionClose; // Connection: close was seen on last response private volatile bool _disposed; + private volatile bool _canceled; public HttpConnection( HttpConnectionPool pool, @@ -858,7 +859,7 @@ public async Task SendAsync(HttpRequestMessage request, boo LogExceptions(_readAheadTask.AsTask()); } - if (NetEventSource.Log.IsEnabled()) Trace($"Error sending request: {error}"); + if (NetEventSource.Log.IsEnabled()) Trace($"Error sending request. _canceled:{_canceled}, error: {error}, inner: {error.InnerException}"); // In the rare case where Expect: 100-continue was used and then processing // of the response headers encountered an error such that we weren't able to @@ -961,6 +962,7 @@ private CancellationTokenRegistration RegisterCancellation(CancellationToken can { var connection = (HttpConnection)s!; if (NetEventSource.Log.IsEnabled()) connection.Trace("Cancellation requested. Disposing of the connection."); + connection._canceled = true; connection.Dispose(); }, this); } diff --git a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/entrypoint.ps1 b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/entrypoint.ps1 index d2e5d8f6033897..e76bb4a8fbb0c8 100644 --- a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/entrypoint.ps1 +++ b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/entrypoint.ps1 @@ -9,6 +9,11 @@ $env:DOTNET_DbgMiniDumpName = "$env:DUMPS_SHARE_MOUNT_ROOT/$env:STRESS_ROLE/core $ExitCode = $LASTEXITCODE +if ($env:DUMPS_SHARE_MOUNT_ROOT) { + Write-Host "copy logs" + Copy-Item -Recurse C:/app/logs/ $env:DUMPS_SHARE_MOUNT_ROOT/ +} + if ($ExitCode -ne 0) { Write-Host "HttpStress failed, copying artifacts for investigation" From 2c9cfc752100000e9ce914fb83f52bbf4f4765f7 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Thu, 6 Feb 2025 02:50:32 +0100 Subject: [PATCH 02/16] setup long run --- eng/pipelines/libraries/stress/http.yml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/eng/pipelines/libraries/stress/http.yml b/eng/pipelines/libraries/stress/http.yml index 92d007079b725e..d09797a22a5c07 100644 --- a/eng/pipelines/libraries/stress/http.yml +++ b/eng/pipelines/libraries/stress/http.yml @@ -96,7 +96,7 @@ extends: - job: windows displayName: Docker NanoServer - timeoutInMinutes: 150 + timeoutInMinutes: 250 variables: DUMPS_SHARE_MOUNT_ROOT: "C:/dumps-share" DUMPS_SHARE: "$(Build.ArtifactStagingDirectory)/dumps/" @@ -149,7 +149,7 @@ extends: - powershell: | cd '$(httpStressProject)' - $env:STRESS_CLIENT_ARGS = "-maxExecutionTime 5 -displayInterval 60 -http 1.1 -trace" + $env:STRESS_CLIENT_ARGS = "-maxExecutionTime 180 -displayInterval 60 -http 1.1 -trace" $env:STRESS_SERVER_ARGS = "$env:HTTPSTRESS_SERVER_ARGS -http 1.1" New-Item -Force $env:DUMPS_SHARE -ItemType Directory docker compose up --abort-on-container-exit --no-color From 43fa83ed4ceb3c881cb9851fc3be485ce7e105d9 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Thu, 6 Feb 2025 16:47:53 +0100 Subject: [PATCH 03/16] please --- eng/pipelines/libraries/stress/http.yml | 2 +- .../tests/StressTests/HttpStress/Program.cs | 11 +++++++---- .../tests/StressTests/HttpStress/StressClient.cs | 9 ++++++++- 3 files changed, 16 insertions(+), 6 deletions(-) diff --git a/eng/pipelines/libraries/stress/http.yml b/eng/pipelines/libraries/stress/http.yml index d09797a22a5c07..9681b08c39be95 100644 --- a/eng/pipelines/libraries/stress/http.yml +++ b/eng/pipelines/libraries/stress/http.yml @@ -149,7 +149,7 @@ extends: - powershell: | cd '$(httpStressProject)' - $env:STRESS_CLIENT_ARGS = "-maxExecutionTime 180 -displayInterval 60 -http 1.1 -trace" + $env:STRESS_CLIENT_ARGS = "-maxExecutionTime 3 -displayInterval 60 -http 1.1 -trace" $env:STRESS_SERVER_ARGS = "$env:HTTPSTRESS_SERVER_ARGS -http 1.1" New-Item -Force $env:DUMPS_SHARE -ItemType Directory docker compose up --abort-on-container-exit --no-color diff --git a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/Program.cs b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/Program.cs index d5962dfba4d096..7e72dd41ccb52a 100644 --- a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/Program.cs +++ b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/Program.cs @@ -195,17 +195,20 @@ private static async Task Run(Configuration config) Console.WriteLine($"Server started at {server.ServerUri}"); } + TaskCompletionSource taskCompletionSource = WaitUntilMaxExecutionTimeElapsedOrKeyboardInterrupt(config.MaximumExecutionTime); StressClient? client = null; if (config.RunMode.HasFlag(RunMode.client)) { // Start the client. Console.WriteLine($"Starting {config.ConcurrentRequests} client workers."); - client = new StressClient(usedClientOperations, config); + client = new StressClient(usedClientOperations, config, taskCompletionSource); client.Start(); } - await WaitUntilMaxExecutionTimeElapsedOrKeyboardInterrupt(config.MaximumExecutionTime); + + + await taskCompletionSource.Task; client?.Stop(); client?.PrintFinalReport(); @@ -214,7 +217,7 @@ private static async Task Run(Configuration config) return client?.TotalErrorCount == 0 ? ExitCode.Success : ExitCode.StressError; } - private static async Task WaitUntilMaxExecutionTimeElapsedOrKeyboardInterrupt(TimeSpan? maxExecutionTime = null) + private static TaskCompletionSource WaitUntilMaxExecutionTimeElapsedOrKeyboardInterrupt(TimeSpan? maxExecutionTime = null) { var tcs = new TaskCompletionSource(); Console.CancelKeyPress += (sender, args) => { Console.Error.WriteLine("Keyboard interrupt"); args.Cancel = true; tcs.TrySetResult(false); }; @@ -225,7 +228,7 @@ private static async Task WaitUntilMaxExecutionTimeElapsedOrKeyboardInterrupt(Ti cts.Token.Register(() => { Console.WriteLine("Max execution time elapsed"); tcs.TrySetResult(false); }); } - await tcs.Task; + return tcs; } private static S? Select(this T? value, Func mapper) where T : struct where S : struct diff --git a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs index 7520b49fae7f1e..440036c7caf796 100644 --- a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs +++ b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs @@ -27,13 +27,15 @@ public class StressClient : IDisposable private readonly CancellationTokenSource _cts = new CancellationTokenSource(); private Task? _clientTask; private EventListener? _eventListener; + private TaskCompletionSource _globalTcs; public long TotalErrorCount => _aggregator.TotalErrorCount; - public StressClient((string name, Func operation)[] clientOperations, Configuration configuration) + public StressClient((string name, Func operation)[] clientOperations, Configuration configuration, TaskCompletionSource globalTcs) { _clientOperations = clientOperations; _config = configuration; + _globalTcs = globalTcs; _baseAddress = new Uri(configuration.ServerUri); _aggregator = new StressResultAggregator(clientOperations); @@ -207,6 +209,11 @@ async Task RunWorker(int taskNum) _aggregator.RecordSuccess(opIndex, stopwatch.Elapsed); } + catch (HttpRequestException e) when (e.InnerException is ObjectDisposedException ode && ode.ObjectName is "System.Net.Security.SslStream") + { + _aggregator.RecordFailure(e, opIndex, stopwatch.Elapsed, requestContext.IsCancellationRequested, taskNum: taskNum, iteration: i); + Console.WriteLine("Caught SslStream disposal, aborting"); + } catch (OperationCanceledException) when (requestContext.IsCancellationRequested || _cts.IsCancellationRequested) { _aggregator.RecordCancellation(opIndex, stopwatch.Elapsed); From 8da4068323aca037e3804044fd08e9c1aba04177 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Thu, 6 Feb 2025 17:32:35 +0100 Subject: [PATCH 04/16] go --- eng/pipelines/libraries/stress/http.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/eng/pipelines/libraries/stress/http.yml b/eng/pipelines/libraries/stress/http.yml index 9681b08c39be95..d09797a22a5c07 100644 --- a/eng/pipelines/libraries/stress/http.yml +++ b/eng/pipelines/libraries/stress/http.yml @@ -149,7 +149,7 @@ extends: - powershell: | cd '$(httpStressProject)' - $env:STRESS_CLIENT_ARGS = "-maxExecutionTime 3 -displayInterval 60 -http 1.1 -trace" + $env:STRESS_CLIENT_ARGS = "-maxExecutionTime 180 -displayInterval 60 -http 1.1 -trace" $env:STRESS_SERVER_ARGS = "$env:HTTPSTRESS_SERVER_ARGS -http 1.1" New-Item -Force $env:DUMPS_SHARE -ItemType Directory docker compose up --abort-on-container-exit --no-color From 8db29413b114ce29c500222e575fc255183be450 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Thu, 6 Feb 2025 23:25:15 +0100 Subject: [PATCH 05/16] meh --- .../System.Net.Http/tests/StressTests/HttpStress/StressClient.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs index 440036c7caf796..7d8aa19f3e9291 100644 --- a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs +++ b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs @@ -213,6 +213,7 @@ async Task RunWorker(int taskNum) { _aggregator.RecordFailure(e, opIndex, stopwatch.Elapsed, requestContext.IsCancellationRequested, taskNum: taskNum, iteration: i); Console.WriteLine("Caught SslStream disposal, aborting"); + _globalTcs.SetResult(false); } catch (OperationCanceledException) when (requestContext.IsCancellationRequested || _cts.IsCancellationRequested) { From e0601dd79c9b3e746fe9af7417960961ff702b47 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Thu, 6 Feb 2025 23:44:24 +0100 Subject: [PATCH 06/16] kzzzzz --- .../tests/StressTests/HttpStress/ClientOperations.cs | 3 ++- .../tests/StressTests/HttpStress/LogHttpEventListener.cs | 5 +++++ .../tests/StressTests/HttpStress/StressClient.cs | 3 ++- 3 files changed, 9 insertions(+), 2 deletions(-) diff --git a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/ClientOperations.cs b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/ClientOperations.cs index b8f3bbe3d654d2..067f2f94f05658 100644 --- a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/ClientOperations.cs +++ b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/ClientOperations.cs @@ -25,7 +25,7 @@ public sealed class RequestContext private readonly HttpClient _client; private readonly CancellationToken _globalToken; private readonly Configuration _config; - + public int RequestHashCode { get; set; } public RequestContext(Configuration config, HttpClient httpClient, Random random, CancellationToken globalToken, int taskNum) { Debug.Assert(httpClient.BaseAddress != null); @@ -56,6 +56,7 @@ public async Task SendAsync(HttpRequestMessage request, Htt { request.Version = HttpVersion; request.VersionPolicy = VersionPolicy; + RequestHashCode = request.GetHashCode(); if (token != null) { diff --git a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/LogHttpEventListener.cs b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/LogHttpEventListener.cs index 785e9a32073fec..c2bf062b11be4e 100644 --- a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/LogHttpEventListener.cs +++ b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/LogHttpEventListener.cs @@ -114,6 +114,11 @@ protected override async void OnEventWritten(EventWrittenEventArgs eventData) _stringBuilderPool.Return(sb); } + public void Write(string message) + { + _messagesChannel.Writer.TryWrite($"** {DateTime.Now:HH:mm:ss.fffffff} ** {message}"); + } + public override void Dispose() { base.Dispose(); diff --git a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs index 7d8aa19f3e9291..7a86f87aac0887 100644 --- a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs +++ b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs @@ -26,7 +26,7 @@ public class StressClient : IDisposable private readonly Stopwatch _stopwatch = new Stopwatch(); private readonly CancellationTokenSource _cts = new CancellationTokenSource(); private Task? _clientTask; - private EventListener? _eventListener; + private LogHttpEventListener? _eventListener; private TaskCompletionSource _globalTcs; public long TotalErrorCount => _aggregator.TotalErrorCount; @@ -213,6 +213,7 @@ async Task RunWorker(int taskNum) { _aggregator.RecordFailure(e, opIndex, stopwatch.Elapsed, requestContext.IsCancellationRequested, taskNum: taskNum, iteration: i); Console.WriteLine("Caught SslStream disposal, aborting"); + _eventListener?.Write($"ODE request: {requestContext.RequestHashCode}"); _globalTcs.SetResult(false); } catch (OperationCanceledException) when (requestContext.IsCancellationRequested || _cts.IsCancellationRequested) From c599b2ee8bac209271718fd16057b4c9f6aa4564 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Fri, 7 Feb 2025 14:35:57 +0100 Subject: [PATCH 07/16] log more stuff around CTR --- .../ChunkedEncodingReadStream.cs | 3 +++ .../ConnectionCloseReadStream.cs | 2 ++ .../ContentLengthReadStream.cs | 2 ++ .../Http/SocketsHttpHandler/HttpConnection.cs | 21 +++++++++++++------ .../SocketsHttpHandler/RawConnectionStream.cs | 3 +++ .../HttpStress/LogHttpEventListener.cs | 4 ++-- .../StressTests/HttpStress/StressClient.cs | 2 +- 7 files changed, 28 insertions(+), 9 deletions(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs index 207c431678c864..a82717b3764d27 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs @@ -238,6 +238,7 @@ private async ValueTask ReadAsyncCore(Memory buffer, CancellationToke finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) _connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -283,6 +284,7 @@ private async Task CopyToAsyncCore(Stream destination, CancellationToken cancell finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) _connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -406,6 +408,7 @@ private int ReadChunksFromConnectionBuffer(Span buffer, CancellationTokenR // we then return a connection to the pool that has been or will be disposed // (e.g. if a timer is used and has already queued its callback but the // callback hasn't yet run). + if (NetEventSource.Log.IsEnabled()) _connection.Trace($"Killed CTR {cancellationRegistration.GetHashCode()}"); cancellationRegistration.Dispose(); CancellationHelper.ThrowIfCancellationRequested(cancellationRegistration.Token); diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionCloseReadStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionCloseReadStream.cs index 7bddf399572202..4f791a4f97b381 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionCloseReadStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionCloseReadStream.cs @@ -66,6 +66,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -126,6 +127,7 @@ private async Task CompleteCopyToAsync(Task copyTask, HttpConnection connection, } finally { + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); ctr.Dispose(); } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs index 7840efb4e7eba8..2b10955b06753a 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs @@ -91,6 +91,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) _connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -156,6 +157,7 @@ private async Task CompleteCopyToAsync(Task copyTask, CancellationToken cancella finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) _connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } Finish(); diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs index 8b8e7e2c39d6fd..0e20f4fef3d292 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs @@ -774,6 +774,7 @@ public async Task SendAsync(HttpRequestMessage request, boo // here (if an exception has occurred or does occur while creating/returning the stream, // we'll still dispose of it in the catch below as part of Dispose'ing the connection). cancellationRegistration.Dispose(); + if (NetEventSource.Log.IsEnabled()) Trace($"Killed CTR {cancellationRegistration.GetHashCode()}"); CancellationHelper.ThrowIfCancellationRequested(cancellationToken); // in case cancellation may have disposed of the stream // Create the response stream. @@ -844,6 +845,7 @@ public async Task SendAsync(HttpRequestMessage request, boo { // Clean up the cancellation registration in case we're still registered. cancellationRegistration.Dispose(); + if (NetEventSource.Log.IsEnabled()) Trace($"Killed CTR {cancellationRegistration.GetHashCode()}"); // Make sure to complete the allowExpect100ToContinue task if it exists. if (allowExpect100ToContinue is not null && !allowExpect100ToContinue.TrySetResult(false)) @@ -859,7 +861,7 @@ public async Task SendAsync(HttpRequestMessage request, boo LogExceptions(_readAheadTask.AsTask()); } - if (NetEventSource.Log.IsEnabled()) Trace($"Error sending request. _canceled:{_canceled}, error: {error}, inner: {error.InnerException}"); + if (NetEventSource.Log.IsEnabled()) Trace($"Error sending request. _canceled:{_canceled}, cancellationToken.IsCancellationRequested:{cancellationToken.IsCancellationRequested}, sendRequestContentTask?.IsCompletedSuccessfully:[{sendRequestContentTask?.IsCompletedSuccessfully}], error: {error}, inner: {error.InnerException}"); // In the rare case where Expect: 100-continue was used and then processing // of the response headers encountered an error such that we weren't able to @@ -950,23 +952,30 @@ private HttpContentWriteStream CreateRequestContentStream(HttpRequestMessage req return requestContentStream; } - private CancellationTokenRegistration RegisterCancellation(CancellationToken cancellationToken) + private CancellationTokenRegistration RegisterCancellation(CancellationToken cancellationToken, [CallerMemberName] string? caller = null) { + CtrTracker tracker = new CtrTracker { Connection = this }; // Cancellation design: // - We register with the SendAsync CancellationToken for the duration of the SendAsync operation. // - We register with the Read/Write/CopyToAsync methods on the response stream for each such individual operation. // - The registration disposes of the connection, tearing it down and causing any pending operations to wake up. // - Because such a tear down can result in a variety of different exception types, we check for a cancellation // request and prioritize that over other exceptions, wrapping the actual exception as an inner of an OCE. - return cancellationToken.Register(static s => + CancellationTokenRegistration ctr = cancellationToken.Register(static s => { - var connection = (HttpConnection)s!; - if (NetEventSource.Log.IsEnabled()) connection.Trace("Cancellation requested. Disposing of the connection."); + CtrTracker t = (CtrTracker)s!; + HttpConnection connection = t.Connection!; + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Cancellation requested by {t.CtrId}. Disposing of the connection."); connection._canceled = true; connection.Dispose(); - }, this); + }, tracker); + tracker.CtrId = ctr.GetHashCode(); + if (NetEventSource.Log.IsEnabled()) Trace($"{caller} registered CTR {tracker.CtrId}"); + return ctr; } + private sealed class CtrTracker { public HttpConnection? Connection; public int CtrId; } + private async ValueTask SendRequestContentAsync(HttpRequestMessage request, HttpContentWriteStream stream, bool async, CancellationToken cancellationToken) { Debug.Assert(stream.BytesWritten == 0); diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RawConnectionStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RawConnectionStream.cs index 15ff3ad465511c..89603b5c53151b 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RawConnectionStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RawConnectionStream.cs @@ -73,6 +73,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -129,6 +130,7 @@ private async Task CompleteCopyToAsync(Task copyTask, HttpConnection connection, finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } // If cancellation is requested and tears down the connection, it could cause the copy @@ -220,6 +222,7 @@ private static async Task WaitWithConnectionCancellationAsync(ValueTask task, Ht finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } } diff --git a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/LogHttpEventListener.cs b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/LogHttpEventListener.cs index c2bf062b11be4e..1df90a5159363f 100644 --- a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/LogHttpEventListener.cs +++ b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/LogHttpEventListener.cs @@ -114,9 +114,9 @@ protected override async void OnEventWritten(EventWrittenEventArgs eventData) _stringBuilderPool.Return(sb); } - public void Write(string message) + public void WriteLine(string message) { - _messagesChannel.Writer.TryWrite($"** {DateTime.Now:HH:mm:ss.fffffff} ** {message}"); + _messagesChannel.Writer.TryWrite($"** {DateTime.Now:HH:mm:ss.fffffff} ** {message}{Environment.NewLine}"); } public override void Dispose() diff --git a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs index 7a86f87aac0887..adf57c48de3017 100644 --- a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs +++ b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs @@ -213,7 +213,7 @@ async Task RunWorker(int taskNum) { _aggregator.RecordFailure(e, opIndex, stopwatch.Elapsed, requestContext.IsCancellationRequested, taskNum: taskNum, iteration: i); Console.WriteLine("Caught SslStream disposal, aborting"); - _eventListener?.Write($"ODE request: {requestContext.RequestHashCode}"); + _eventListener?.WriteLine($"ODE request: {requestContext.RequestHashCode}"); _globalTcs.SetResult(false); } catch (OperationCanceledException) when (requestContext.IsCancellationRequested || _cts.IsCancellationRequested) From 168a3ff3c0948cd736d2dab1c9f84c6910365e2e Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Fri, 7 Feb 2025 14:53:00 +0100 Subject: [PATCH 08/16] cancelRate --- eng/pipelines/libraries/stress/http.yml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/eng/pipelines/libraries/stress/http.yml b/eng/pipelines/libraries/stress/http.yml index d09797a22a5c07..da69a82e409478 100644 --- a/eng/pipelines/libraries/stress/http.yml +++ b/eng/pipelines/libraries/stress/http.yml @@ -149,7 +149,7 @@ extends: - powershell: | cd '$(httpStressProject)' - $env:STRESS_CLIENT_ARGS = "-maxExecutionTime 180 -displayInterval 60 -http 1.1 -trace" + $env:STRESS_CLIENT_ARGS = "-maxExecutionTime 180 -displayInterval 60 -cancelRate 0.5 -http 1.1 -trace" $env:STRESS_SERVER_ARGS = "$env:HTTPSTRESS_SERVER_ARGS -http 1.1" New-Item -Force $env:DUMPS_SHARE -ItemType Directory docker compose up --abort-on-container-exit --no-color @@ -158,7 +158,7 @@ extends: - publish: $(Build.ArtifactStagingDirectory)/dumps artifact: DumpsWindows - # condition: failed() + condition: failed() - powershell: | Set-NetFirewallProfile -Profile Domain, Public, Private -Enabled True From 89f941349bef6cf3b2dafa305f0409d9349c91d8 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Fri, 7 Feb 2025 15:19:37 +0100 Subject: [PATCH 09/16] meh --- .../ChunkedEncodingReadStream.cs | 15 +++++++++------ .../SocketsHttpHandler/ContentLengthReadStream.cs | 6 ++++-- 2 files changed, 13 insertions(+), 8 deletions(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs index a82717b3764d27..67f02e6046c01b 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs @@ -164,8 +164,8 @@ private async ValueTask ReadAsyncCore(Memory buffer, CancellationToke // Should only be called if ReadChunksFromConnectionBuffer returned 0. Debug.Assert(_connection != null); - - CancellationTokenRegistration ctr = _connection.RegisterCancellation(cancellationToken); + HttpConnection connection = _connection; + CancellationTokenRegistration ctr = connection.RegisterCancellation(cancellationToken); try { while (true) @@ -238,7 +238,7 @@ private async ValueTask ReadAsyncCore(Memory buffer, CancellationToke finally { ctr.Dispose(); - if (NetEventSource.Log.IsEnabled()) _connection.Trace($"Killed CTR {ctr.GetHashCode()}"); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -254,7 +254,8 @@ public override Task CopyToAsync(Stream destination, int bufferSize, Cancellatio private async Task CopyToAsyncCore(Stream destination, CancellationToken cancellationToken) { - CancellationTokenRegistration ctr = _connection!.RegisterCancellation(cancellationToken); + HttpConnection connection = _connection!; + CancellationTokenRegistration ctr = connection.RegisterCancellation(cancellationToken); try { while (true) @@ -284,7 +285,7 @@ private async Task CopyToAsyncCore(Stream destination, CancellationToken cancell finally { ctr.Dispose(); - if (NetEventSource.Log.IsEnabled()) _connection.Trace($"Killed CTR {ctr.GetHashCode()}"); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -316,6 +317,8 @@ private int ReadChunksFromConnectionBuffer(Span buffer, CancellationTokenR { Debug.Assert(_connection != null); + HttpConnection connection = _connection; + try { ReadOnlySpan currentLine; @@ -408,7 +411,7 @@ private int ReadChunksFromConnectionBuffer(Span buffer, CancellationTokenR // we then return a connection to the pool that has been or will be disposed // (e.g. if a timer is used and has already queued its callback but the // callback hasn't yet run). - if (NetEventSource.Log.IsEnabled()) _connection.Trace($"Killed CTR {cancellationRegistration.GetHashCode()}"); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {cancellationRegistration.GetHashCode()}"); cancellationRegistration.Dispose(); CancellationHelper.ThrowIfCancellationRequested(cancellationRegistration.Token); diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs index 2b10955b06753a..ec449a9d54d6cc 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs @@ -79,6 +79,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation } else { + HttpConnection connection = _connection; CancellationTokenRegistration ctr = _connection.RegisterCancellation(cancellationToken); try { @@ -91,7 +92,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation finally { ctr.Dispose(); - if (NetEventSource.Log.IsEnabled()) _connection.Trace($"Killed CTR {ctr.GetHashCode()}"); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -145,6 +146,7 @@ public override Task CopyToAsync(Stream destination, int bufferSize, Cancellatio private async Task CompleteCopyToAsync(Task copyTask, CancellationToken cancellationToken) { Debug.Assert(_connection != null); + HttpConnection connection = _connection; CancellationTokenRegistration ctr = _connection.RegisterCancellation(cancellationToken); try { @@ -157,7 +159,7 @@ private async Task CompleteCopyToAsync(Task copyTask, CancellationToken cancella finally { ctr.Dispose(); - if (NetEventSource.Log.IsEnabled()) _connection.Trace($"Killed CTR {ctr.GetHashCode()}"); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } Finish(); From 5bc4961e64510682a8f8bdf85f71bd336a988ddd Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Sat, 8 Feb 2025 01:32:41 +0100 Subject: [PATCH 10/16] zombiehunting --- .../src/System/Net/Http/HttpRequestMessage.cs | 5 ++++ .../Http/SocketsHttpHandler/HttpConnection.cs | 25 ++++++++++++++----- 2 files changed, 24 insertions(+), 6 deletions(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs b/src/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs index 691db4059a2481..f3400ea10b255d 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs @@ -19,6 +19,7 @@ public class HttpRequestMessage : IDisposable private const int MessageAlreadySent = 1; private const int MessageIsRedirect = 2; private const int MessageDisposed = 4; + private const int MessageCompleted = 8; // Track whether the message has been sent. // The message shouldn't be sent again if this field is equal to MessageAlreadySent. @@ -176,6 +177,10 @@ public override string ToString() internal bool WasRedirected() => (_sendStatus & MessageIsRedirect) != 0; + internal void MarkAsCompleted() => _sendStatus |= MessageCompleted; + + internal bool WasCompleted() => (_sendStatus & MessageCompleted) != 0; + private bool Disposed { get => (_sendStatus & MessageDisposed) != 0; diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs index 0e20f4fef3d292..c27ddb9dad56c5 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs @@ -532,6 +532,11 @@ static void ThrowForInvalidCharEncoding() => public async Task SendAsync(HttpRequestMessage request, bool async, CancellationToken cancellationToken) { + if (_currentRequest is not null) + { + throw new InvalidOperationException($"Expected null {nameof(_currentRequest)}."); + } + Debug.Assert(_currentRequest == null, $"Expected null {nameof(_currentRequest)}."); Debug.Assert(_readBuffer.ActiveLength == 0, "Unexpected data in read buffer"); Debug.Assert(_readAheadTaskStatus != ReadAheadTask_Started, @@ -954,7 +959,7 @@ private HttpContentWriteStream CreateRequestContentStream(HttpRequestMessage req private CancellationTokenRegistration RegisterCancellation(CancellationToken cancellationToken, [CallerMemberName] string? caller = null) { - CtrTracker tracker = new CtrTracker { Connection = this }; + CtrTracker tracker = new CtrTracker(this, _currentRequest); // Cancellation design: // - We register with the SendAsync CancellationToken for the duration of the SendAsync operation. // - We register with the Read/Write/CopyToAsync methods on the response stream for each such individual operation. @@ -964,17 +969,23 @@ private CancellationTokenRegistration RegisterCancellation(CancellationToken can CancellationTokenRegistration ctr = cancellationToken.Register(static s => { CtrTracker t = (CtrTracker)s!; - HttpConnection connection = t.Connection!; - if (NetEventSource.Log.IsEnabled()) connection.Trace($"Cancellation requested by {t.CtrId}. Disposing of the connection."); + HttpConnection connection = t.Connection; + HttpRequestMessage? r = t.Request; + + if (NetEventSource.Log.IsEnabled()) + connection.Trace($"Cancellation requested by {t.CtrId} tracker:{t.GetHashCode()} originating req:{r} comp:{r?.WasCompleted()}. Disposing of the connection."); connection._canceled = true; connection.Dispose(); }, tracker); tracker.CtrId = ctr.GetHashCode(); - if (NetEventSource.Log.IsEnabled()) Trace($"{caller} registered CTR {tracker.CtrId}"); + if (NetEventSource.Log.IsEnabled()) Trace($"{caller} registered CTR {tracker.CtrId} tracker:{tracker.GetHashCode()}"); return ctr; } - private sealed class CtrTracker { public HttpConnection? Connection; public int CtrId; } + private sealed record class CtrTracker(HttpConnection Connection, HttpRequestMessage? Request) + { + public int CtrId = -42; + } private async ValueTask SendRequestContentAsync(HttpRequestMessage request, HttpContentWriteStream stream, bool async, CancellationToken cancellationToken) { @@ -2044,11 +2055,13 @@ internal void DetachFromPool() _detachedFromPool = true; } - private void CompleteResponse() + private void CompleteResponse([CallerMemberName]string? caller = null) { Debug.Assert(_currentRequest != null, "Expected the connection to be associated with a request."); Debug.Assert(_writeBuffer.ActiveLength == 0, "Everything in write buffer should have been flushed."); + if (NetEventSource.Log.IsEnabled()) Trace($"{caller} completed response."); + _currentRequest.MarkAsCompleted(); // Disassociate the connection from a request. _currentRequest = null; From 675854d0152c8b496b595c2bcf362b54e23399b9 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Sat, 8 Feb 2025 12:26:50 +0100 Subject: [PATCH 11/16] meaow --- .../src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs index c27ddb9dad56c5..5ac9241fbd96b0 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs @@ -973,7 +973,7 @@ private CancellationTokenRegistration RegisterCancellation(CancellationToken can HttpRequestMessage? r = t.Request; if (NetEventSource.Log.IsEnabled()) - connection.Trace($"Cancellation requested by {t.CtrId} tracker:{t.GetHashCode()} originating req:{r} comp:{r?.WasCompleted()}. Disposing of the connection."); + connection.Trace($"Cancellation requested by {t.CtrId} tracker:{t.GetHashCode()} originating req:{r.GetHashCode()} comp:{r?.WasCompleted()}. Disposing of the connection."); connection._canceled = true; connection.Dispose(); }, tracker); From 5aa8f1b9a89d275ab00ce6fe5208fa5faf03d583 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Sat, 8 Feb 2025 12:37:28 +0100 Subject: [PATCH 12/16] =?UTF-8?q?=C3=BC?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs index 5ac9241fbd96b0..603eed7041c96d 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs @@ -973,7 +973,7 @@ private CancellationTokenRegistration RegisterCancellation(CancellationToken can HttpRequestMessage? r = t.Request; if (NetEventSource.Log.IsEnabled()) - connection.Trace($"Cancellation requested by {t.CtrId} tracker:{t.GetHashCode()} originating req:{r.GetHashCode()} comp:{r?.WasCompleted()}. Disposing of the connection."); + connection.Trace($"Cancellation requested by {t.CtrId} tracker:{t.GetHashCode()} originating req:{r?.GetHashCode()} comp:{r?.WasCompleted()}. Disposing of the connection."); connection._canceled = true; connection.Dispose(); }, tracker); From a6a184e498e371b43e060f3bb4c6b8b2399e7a00 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Sat, 8 Feb 2025 13:18:24 +0100 Subject: [PATCH 13/16] track ctr better --- .../System/Net/Http/SocketsHttpHandler/HttpConnection.cs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs index 603eed7041c96d..41b7343cca82e5 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs @@ -973,18 +973,20 @@ private CancellationTokenRegistration RegisterCancellation(CancellationToken can HttpRequestMessage? r = t.Request; if (NetEventSource.Log.IsEnabled()) - connection.Trace($"Cancellation requested by {t.CtrId} tracker:{t.GetHashCode()} originating req:{r?.GetHashCode()} comp:{r?.WasCompleted()}. Disposing of the connection."); + connection.Trace($"Cancellation requested by {t.CtrId} tracker:{t} originating req:{r?.GetHashCode()} comp:{r?.WasCompleted()}. Disposing of the connection."); connection._canceled = true; connection.Dispose(); }, tracker); tracker.CtrId = ctr.GetHashCode(); - if (NetEventSource.Log.IsEnabled()) Trace($"{caller} registered CTR {tracker.CtrId} tracker:{tracker.GetHashCode()}"); + if (NetEventSource.Log.IsEnabled()) Trace($"{caller} registered CTR {tracker.CtrId} tracker:{tracker}"); return ctr; } private sealed record class CtrTracker(HttpConnection Connection, HttpRequestMessage? Request) { + public long Id = Random.Shared.NextInt64(); public int CtrId = -42; + public override string ToString() => Id.ToString(); } private async ValueTask SendRequestContentAsync(HttpRequestMessage request, HttpContentWriteStream stream, bool async, CancellationToken cancellationToken) From 0a67d75d7c7f59f8dc0afc28b1e642e50d32e465 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Sat, 8 Feb 2025 13:26:25 +0100 Subject: [PATCH 14/16] more verbosity --- .../src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs index 41b7343cca82e5..c716e710547dc1 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs @@ -960,6 +960,7 @@ private HttpContentWriteStream CreateRequestContentStream(HttpRequestMessage req private CancellationTokenRegistration RegisterCancellation(CancellationToken cancellationToken, [CallerMemberName] string? caller = null) { CtrTracker tracker = new CtrTracker(this, _currentRequest); + if (NetEventSource.Log.IsEnabled()) Trace($"Created tracker:{tracker}, caller:{caller}, _currentRequest:{_currentRequest?.GetHashCode()}"); // Cancellation design: // - We register with the SendAsync CancellationToken for the duration of the SendAsync operation. // - We register with the Read/Write/CopyToAsync methods on the response stream for each such individual operation. From e95def5fe55f9a379f09c561afe694bb418f3dce Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Sat, 8 Feb 2025 16:18:08 +0100 Subject: [PATCH 15/16] more log --- .../System.Net.Http/src/System/Net/Http/HttpClient.cs | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs b/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs index 22d22ed58cc749..28466eb10203a6 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs @@ -532,7 +532,15 @@ async Task Core( responseContentTelemetryStarted = true; } + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Log.HandlerMessage(0, 0, request.GetHashCode(), "HttpClient.SendAsync.Core", "LoadIntoBufferAsync started."); + } await response.Content.LoadIntoBufferAsync(_maxResponseContentBufferSize, cts.Token).ConfigureAwait(false); + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Log.HandlerMessage(0, 0, request.GetHashCode(), "HttpClient.SendAsync.Core", "LoadIntoBufferAsync finished."); + } } return response; From e67f7ddf83aad5001339f2660ee9258372c02800 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Mon, 10 Feb 2025 23:24:19 +0100 Subject: [PATCH 16/16] fix --- .../src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs index c716e710547dc1..994b77930bc715 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs @@ -2085,7 +2085,7 @@ private void CompleteResponse([CallerMemberName]string? caller = null) // If the connection is no longer in use (i.e. for NT authentication), then we can return it to the pool now. // Otherwise, it will be returned when the connection is no longer in use (i.e. Release above is called). - if (!_inUse) + if (!_inUse && !_disposed) { ReturnConnectionToPool(); }