diff --git a/eng/pipelines/libraries/stress/http.yml b/eng/pipelines/libraries/stress/http.yml index 257334fce3e99c..da69a82e409478 100644 --- a/eng/pipelines/libraries/stress/http.yml +++ b/eng/pipelines/libraries/stress/http.yml @@ -30,73 +30,73 @@ 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 - timeoutInMinutes: 150 + timeoutInMinutes: 250 variables: DUMPS_SHARE_MOUNT_ROOT: "C:/dumps-share" DUMPS_SHARE: "$(Build.ArtifactStagingDirectory)/dumps/" @@ -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 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 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; 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/ChunkedEncodingReadStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs index 207c431678c864..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,6 +238,7 @@ private async ValueTask ReadAsyncCore(Memory buffer, CancellationToke finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -253,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) @@ -283,6 +285,7 @@ private async Task CopyToAsyncCore(Stream destination, CancellationToken cancell finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -314,6 +317,8 @@ private int ReadChunksFromConnectionBuffer(Span buffer, CancellationTokenR { Debug.Assert(_connection != null); + HttpConnection connection = _connection; + try { ReadOnlySpan currentLine; @@ -406,6 +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()}"); 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..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,6 +92,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation finally { ctr.Dispose(); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Killed CTR {ctr.GetHashCode()}"); } } @@ -144,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 { @@ -156,6 +159,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 0b03489d93aff3..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 @@ -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, @@ -531,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, @@ -773,6 +779,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. @@ -843,6 +850,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)) @@ -858,7 +866,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}, 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 @@ -949,20 +957,37 @@ 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(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. // - 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; + HttpRequestMessage? r = t.Request; + + if (NetEventSource.Log.IsEnabled()) + 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(); - }, this); + }, tracker); + tracker.CtrId = ctr.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) @@ -2033,11 +2058,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; @@ -2058,7 +2085,7 @@ private void CompleteResponse() // 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(); } 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/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..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,6 +114,11 @@ protected override async void OnEventWritten(EventWrittenEventArgs eventData) _stringBuilderPool.Return(sb); } + public void WriteLine(string message) + { + _messagesChannel.Writer.TryWrite($"** {DateTime.Now:HH:mm:ss.fffffff} ** {message}{Environment.NewLine}"); + } + public override void Dispose() { base.Dispose(); 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..adf57c48de3017 100644 --- a/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs +++ b/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs @@ -26,14 +26,16 @@ 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; - 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,13 @@ 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"); + _eventListener?.WriteLine($"ODE request: {requestContext.RequestHashCode}"); + _globalTcs.SetResult(false); + } catch (OperationCanceledException) when (requestContext.IsCancellationRequested || _cts.IsCancellationRequested) { _aggregator.RecordCancellation(opIndex, stopwatch.Elapsed); 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"