HTTP stress test improvements (#42313)

Fixes:
    stress client double read of content fixed
    fixed stress client hangs at start and stop
    leveraged HttpVersionPolicy
    increased pipeline timeout since we doubled the runs
    fixed base docker images to avoid missing IO.Pipelines Kestrel exception.

Re-hauled tracing:
    added server file logging
    added log file rotation

Minor renames.

Contributes to: #42211 and #42198

eng/docker/libraries-sdk-aspnetcore.linux.Dockerfile

@@ -1,6 +1,6 @@
 # Builds and copies library artifacts into target dotnet sdk image
 ARG BUILD_BASE_IMAGE=mcr.microsoft.com/dotnet-buildtools/prereqs:centos-7-f39df28-20191023143754
-ARG SDK_BASE_IMAGE=mcr.microsoft.com/dotnet/sdk:5.0-buster-slim
+ARG SDK_BASE_IMAGE=mcr.microsoft.com/dotnet/nightly/sdk:5.0-buster-slim
 
 FROM $BUILD_BASE_IMAGE as corefxbuild
 

eng/docker/libraries-sdk-aspnetcore.windows.Dockerfile

@@ -1,6 +1,6 @@
 # escape=`
 # Simple Dockerfile which copies library build artifacts into target dotnet sdk image
-ARG SDK_BASE_IMAGE=mcr.microsoft.com/dotnet/sdk:5.0-nanoserver-1809
+ARG SDK_BASE_IMAGE=mcr.microsoft.com/dotnet/nightly/sdk:5.0-nanoserver-1809
 FROM $SDK_BASE_IMAGE as target
 
 ARG TESTHOST_LOCATION=".\\artifacts\\bin\\testhost"

eng/docker/libraries-sdk.linux.Dockerfile

@@ -1,6 +1,6 @@
 # Builds and copies library artifacts into target dotnet sdk image
 ARG BUILD_BASE_IMAGE=mcr.microsoft.com/dotnet-buildtools/prereqs:centos-7-f39df28-20191023143754
-ARG SDK_BASE_IMAGE=mcr.microsoft.com/dotnet/sdk:5.0-buster-slim
+ARG SDK_BASE_IMAGE=mcr.microsoft.com/dotnet/nightly/sdk:5.0-buster-slim
 
 FROM $BUILD_BASE_IMAGE as corefxbuild
 

eng/docker/libraries-sdk.windows.Dockerfile

@@ -1,6 +1,6 @@
 # escape=`
 # Simple Dockerfile which copies clr and library build artifacts into target dotnet sdk image
-ARG SDK_BASE_IMAGE=mcr.microsoft.com/dotnet/sdk:5.0-nanoserver-1809
+ARG SDK_BASE_IMAGE=mcr.microsoft.com/dotnet/nightly/sdk:5.0-nanoserver-1809
 FROM $SDK_BASE_IMAGE as target
 
 ARG TESTHOST_LOCATION=".\\artifacts\\bin\\testhost"

eng/pipelines/libraries/stress/http.yml

@@ -25,7 +25,7 @@ variables:
 jobs:
 - job: linux
  displayName: Docker Linux
- timeoutInMinutes: 120
+ timeoutInMinutes: 150
  pool:
  name: NetCorePublic-Pool
  queue: BuildPool.Ubuntu.1604.Amd64.Open
@@ -65,7 +65,7 @@ jobs:
 
 - job: windows
  displayName: Docker NanoServer
- timeoutInMinutes: 120
+ timeoutInMinutes: 150
  pool:
  name: NetCorePublic-Pool
  queue: BuildPool.Server.Amd64.VS2019.Open

src/libraries/System.Net.Http/tests/StressTests/HttpStress/ClientOperations.cs

@@ -216,19 +216,19 @@ public static (string name, Func<RequestContext, Task> operation)[] Operations =
  ctx.PopulateWithRandomHeaders(req.Headers);
  ulong expectedChecksum = CRC.CalculateHeaderCrc(req.Headers.Select(x => (x.Key, x.Value)));
 
- using HttpResponseMessage res = await ctx.SendAsync(req);
+ using HttpResponseMessage m = await ctx.SendAsync(req);
 
- ValidateStatusCode(res);
+ ValidateStatusCode(m);
 
- await res.Content.ReadAsStringAsync();
+ await m.Content.ReadAsStringAsync();
 
- bool isValidChecksum = ValidateServerChecksum(res.Headers, expectedChecksum);
+ bool isValidChecksum = ValidateServerChecksum(m.Headers, expectedChecksum);
  string failureDetails = isValidChecksum ? "server checksum matches client checksum" : "server checksum mismatch";
 
  // Validate that request headers are being echoed
  foreach (KeyValuePair<string, IEnumerable<string>> reqHeader in req.Headers)
  {
- if (!res.Headers.TryGetValues(reqHeader.Key, out IEnumerable<string>? values))
+ if (!m.Headers.TryGetValues(reqHeader.Key, out IEnumerable<string>? values))
  {
  throw new Exception($"Expected response header name {reqHeader.Key} missing. {failureDetails}");
  }
@@ -239,11 +239,11 @@ public static (string name, Func<RequestContext, Task> operation)[] Operations =
  }
 
  // Validate trailing headers are being echoed
- if (res.TrailingHeaders.Count() > 0)
+ if (m.TrailingHeaders.Count() > 0)
  {
  foreach (KeyValuePair<string, IEnumerable<string>> reqHeader in req.Headers)
  {
- if (!res.TrailingHeaders.TryGetValues(reqHeader.Key + "-trailer", out IEnumerable<string>? values))
+ if (!m.TrailingHeaders.TryGetValues(reqHeader.Key + "-trailer", out IEnumerable<string>? values))
  {
  throw new Exception($"Expected trailing header name {reqHeader.Key}-trailer missing. {failureDetails}");
  }
@@ -330,6 +330,7 @@ public static (string name, Func<RequestContext, Task> operation)[] Operations =
  using HttpResponseMessage m = await ctx.SendAsync(req);
 
  ValidateStatusCode(m);
+
  string checksumMessage = ValidateServerChecksum(m.Headers, checksum) ? "server checksum matches client checksum" : "server checksum mismatch";
  ValidateContent(content, await m.Content.ReadAsStringAsync(), checksumMessage);
  }),
@@ -344,6 +345,7 @@ public static (string name, Func<RequestContext, Task> operation)[] Operations =
  using HttpResponseMessage m = await ctx.SendAsync(req);
 
  ValidateStatusCode(m);
+
  string checksumMessage = ValidateServerChecksum(m.Headers, checksum) ? "server checksum matches client checksum" : "server checksum mismatch";
  ValidateContent(formData.expected, await m.Content.ReadAsStringAsync(), checksumMessage);
  }),
@@ -361,7 +363,7 @@ public static (string name, Func<RequestContext, Task> operation)[] Operations =
  string response = await m.Content.ReadAsStringAsync();
 
  string checksumMessage = ValidateServerChecksum(m.TrailingHeaders, checksum, required: false) ? "server checksum matches client checksum" : "server checksum mismatch";
- ValidateContent(content, await m.Content.ReadAsStringAsync(), checksumMessage);
+ ValidateContent(content, response, checksumMessage);
  }),
 
  ("POST Duplex Slow",
@@ -414,6 +416,7 @@ public static (string name, Func<RequestContext, Task> operation)[] Operations =
  using HttpResponseMessage m = await ctx.SendAsync(req, HttpCompletionOption.ResponseHeadersRead);
 
  ValidateStatusCode(m);
+
  string checksumMessage = ValidateServerChecksum(m.Headers, checksum) ? "server checksum matches client checksum" : "server checksum mismatch";
  ValidateContent(content, await m.Content.ReadAsStringAsync(), checksumMessage);
  }),
@@ -431,8 +434,8 @@ public static (string name, Func<RequestContext, Task> operation)[] Operations =
  {
  throw new Exception($"Expected {expectedLength}, got {m.Content.Headers.ContentLength}");
  }
- string r = await m.Content.ReadAsStringAsync();
- if (r.Length > 0) throw new Exception($"Got unexpected response: {r}");
+ string response = await m.Content.ReadAsStringAsync();
+ if (response.Length > 0) throw new Exception($"Got unexpected response: {response}");
  }),
 
  ("PUT",
@@ -445,8 +448,8 @@ public static (string name, Func<RequestContext, Task> operation)[] Operations =
 
  ValidateStatusCode(m);
 
- string r = await m.Content.ReadAsStringAsync();
- if (r != "") throw new Exception($"Got unexpected response: {r}");
+ string response = await m.Content.ReadAsStringAsync();
+ if (response != "") throw new Exception($"Got unexpected response: {response}");
  }),
 
  ("PUT Slow",
@@ -459,8 +462,8 @@ public static (string name, Func<RequestContext, Task> operation)[] Operations =
 
  ValidateStatusCode(m);
 
- string r = await m.Content.ReadAsStringAsync();
- if (r != "") throw new Exception($"Got unexpected response: {r}");
+ string response = await m.Content.ReadAsStringAsync();
+ if (response != "") throw new Exception($"Got unexpected response: {response}");
  }),
 
  ("GET Slow",

src/libraries/System.Net.Http/tests/StressTests/HttpStress/Configuration.cs

@@ -43,8 +43,8 @@ public class Configuration
  public double CancellationProbability { get; set; }
 
  public bool UseHttpSys { get; set; }
- public string? LogPath { get; set; }
  public bool LogAspNet { get; set; }
+ public bool Trace { get; set; }
  public int? ServerMaxConcurrentStreams { get; set; }
  public int? ServerMaxFrameSize { get; set; }
  public int? ServerInitialConnectionWindowSize { get; set; }

src/libraries/System.Net.Http/tests/StressTests/HttpStress/Dockerfile

@@ -1,4 +1,4 @@
-ARG SDK_BASE_IMAGE=mcr.microsoft.com/dotnet/sdk:5.0-buster-slim
+ARG SDK_BASE_IMAGE=mcr.microsoft.com/dotnet/nightly/sdk:5.0-buster-slim
 FROM $SDK_BASE_IMAGE
 
 RUN echo "DOTNET_SDK_VERSION="$DOTNET_SDK_VERSION

src/libraries/System.Net.Http/tests/StressTests/HttpStress/HttpEventListener.cs

@@ -3,18 +3,37 @@
 
 using System;
 using System.Diagnostics.Tracing;
+using System.Threading.Channels;
 using System.Text;
 using System.IO;
+using System.Linq;
+using System.Threading;
+using System.Threading.Tasks;
 
 namespace HttpStress
 {
  public sealed class LogHttpEventListener : EventListener
  {
- private readonly StreamWriter _log;
+ private int _lastLogNumber = 0;
+ private StreamWriter _log;
+ private Channel<string> _messagesChannel = Channel.CreateUnbounded<string>();
+ private Task _processMessages;
+ private CancellationTokenSource _stopProcessing;
 
- public LogHttpEventListener(string logPath)
+ public LogHttpEventListener()
  {
- _log = new StreamWriter(logPath, true) { AutoFlush = true };
+ foreach (var filename in Directory.GetFiles(".", "client*.log"))
+ {
+ try
+ {
+ File.Delete(filename);
+ } catch {}
+ }
+ _log = new StreamWriter("client.log", false) { AutoFlush = true };
+
+ _messagesChannel = Channel.CreateUnbounded<string>();
+ _processMessages = ProcessMessagesAsync();
+ _stopProcessing = new CancellationTokenSource();
  }
 
  protected override void OnEventSourceCreated(EventSource eventSource)
@@ -25,63 +44,63 @@ protected override void OnEventSourceCreated(EventSource eventSource)
  }
  }
 
- protected override void OnEventWritten(EventWrittenEventArgs eventData)
+ private async Task ProcessMessagesAsync()
  {
- lock (_log)
+ await Task.Yield();
+
+ try
  {
- var sb = new StringBuilder().Append($"{eventData.TimeStamp:HH:mm:ss.fffffff}[{eventData.EventName}] ");
- for (int i = 0; i < eventData.Payload?.Count; i++)
+ int i = 0;
+ await foreach (string message in _messagesChannel.Reader.ReadAllAsync(_stopProcessing.Token))
  {
- if (i > 0)
+ if ((++i % 10_000) == 0)
  {
- sb.Append(", ");
+ RotateFiles();
  }
- sb.Append(eventData.PayloadNames?[i]).Append(": ").Append(eventData.Payload[i]);
+
+ _log.WriteLine(message);
  }
- _log.WriteLine(sb.ToString());
  }
- }
+ catch (OperationCanceledException)
+ {
+ return;
+ }
 
- public override void Dispose()
- {
- _log.Dispose();
- base.Dispose();
+ void RotateFiles()
+ {
+ // Rotate the log if it reaches 50 MB size.
+ if (_log.BaseStream.Length > (50 << 20))
+ {
+ _log.Close();
+ _log = new StreamWriter($"client_{++_lastLogNumber:000}.log", false) { AutoFlush = true };
+ }
+ }
  }
- }
-
- public sealed class ConsoleHttpEventListener : EventListener
- {
- public ConsoleHttpEventListener()
- { }
 
- protected override void OnEventSourceCreated(EventSource eventSource)
+ protected override async void OnEventWritten(EventWrittenEventArgs eventData)
  {
- if (eventSource.Name == "Private.InternalDiagnostics.System.Net.Http")
+ var sb = new StringBuilder().Append($"{eventData.TimeStamp:HH:mm:ss.fffffff}[{eventData.EventName}] ");
+ for (int i = 0; i < eventData.Payload?.Count; i++)
  {
- EnableEvents(eventSource, EventLevel.LogAlways);
+ if (i > 0)
+ {
+ sb.Append(", ");
+ }
+ sb.Append(eventData.PayloadNames?[i]).Append(": ").Append(eventData.Payload[i]);
  }
+ await _messagesChannel.Writer.WriteAsync(sb.ToString());
  }
 
- protected override void OnEventWritten(EventWrittenEventArgs eventData)
+ public override void Dispose()
  {
- lock (Console.Out)
+ base.Dispose();
+
+ if (!_processMessages.Wait(TimeSpan.FromSeconds(30)))
  {
- Console.ForegroundColor = ConsoleColor.DarkYellow;
- Console.Write($"{eventData.TimeStamp:HH:mm:ss.fffffff}[{eventData.EventName}] ");
- Console.ResetColor();
- for (int i = 0; i < eventData.Payload?.Count; i++)
- {
- if (i > 0)
- {
- Console.Write(", ");
- }
- Console.ForegroundColor = ConsoleColor.DarkGray;
- Console.Write(eventData.PayloadNames?[i] + ": ");
- Console.ResetColor();
- Console.Write(eventData.Payload[i]);
- }
- Console.WriteLine();
+ _stopProcessing.Cancel();
+ _processMessages.Wait();
  }
+ _log.Dispose();
  }
  }
 }

src/libraries/System.Net.Http/tests/StressTests/HttpStress/HttpStress.csproj

@@ -8,6 +8,9 @@
  </PropertyGroup>
 
  <ItemGroup>
+ <PackageReference Include="Serilog.AspNetCore" Version="3.4.0" />
+ <PackageReference Include="Serilog.Extensions.Logging.File" Version="2.0.0" />
+ <PackageReference Include="Serilog.Sinks.File" Version="4.1.0" />
  <PackageReference Include="System.CommandLine.Experimental" Version="0.3.0-alpha.19577.1" />
  <PackageReference Include="System.Net.Http.WinHttpHandler" Version="4.5.4" />
  </ItemGroup>

src/libraries/System.Net.Http/tests/StressTests/HttpStress/Program.cs

@@ -18,7 +18,6 @@
 /// </summary>
 public static class Program
 {
-
  public enum ExitCode { Success = 0, StressError = 1, CliError = 2 };
 
  public static async Task<int> Main(string[] args)
@@ -46,7 +45,7 @@ private static bool TryParseCli(string[] args, [NotNullWhen(true)] out Configura
  cmd.AddOption(new Option("-connectionLifetime", "Max connection lifetime length (milliseconds).") { Argument = new Argument<int?>("connectionLifetime", null) });
  cmd.AddOption(new Option("-ops", "Indices of the operations to use") { Argument = new Argument<int[]?>("space-delimited indices", null) });
  cmd.AddOption(new Option("-xops", "Indices of the operations to exclude") { Argument = new Argument<int[]?>("space-delimited indices", null) });
- cmd.AddOption(new Option("-trace", "Enable System.Net.Http.InternalDiagnostics tracing.") { Argument = new Argument<string>("\"console\" or path") });
+ cmd.AddOption(new Option("-trace", "Enable System.Net.Http.InternalDiagnostics (client) and/or ASP.NET dignostics (server) tracing.") { Argument = new Argument<bool>("enable", false) });
  cmd.AddOption(new Option("-aspnetlog", "Enable ASP.NET warning and error logging.") { Argument = new Argument<bool>("enable", false) });
  cmd.AddOption(new Option("-listOps", "List available options.") { Argument = new Argument<bool>("enable", false) });
  cmd.AddOption(new Option("-seed", "Seed for generating pseudo-random parameters for a given -n argument.") { Argument = new Argument<int?>("seed", null) });
@@ -99,7 +98,7 @@ private static bool TryParseCli(string[] args, [NotNullWhen(true)] out Configura
 
  UseHttpSys = cmdline.ValueForOption<bool>("-httpSys"),
  LogAspNet = cmdline.ValueForOption<bool>("-aspnetlog"),
- LogPath = cmdline.HasOption("-trace") ? cmdline.ValueForOption<string>("-trace") : null,
+ Trace = cmdline.ValueForOption<bool>("-trace"),
  ServerMaxConcurrentStreams = cmdline.ValueForOption<int?>("-serverMaxConcurrentStreams"),
  ServerMaxFrameSize = cmdline.ValueForOption<int?>("-serverMaxFrameSize"),
  ServerInitialConnectionWindowSize = cmdline.ValueForOption<int?>("-serverInitialConnectionWindowSize"),
@@ -158,11 +157,12 @@ private static async Task<ExitCode> Run(Configuration config)
  Console.WriteLine(" System.Net.Http: " + GetAssemblyInfo(typeof(System.Net.Http.HttpClient).Assembly));
  Console.WriteLine(" Server: " + (config.UseHttpSys ? "http.sys" : "Kestrel"));
  Console.WriteLine(" Server URL: " + config.ServerUri);
- Console.WriteLine(" Tracing: " + (config.LogPath == null ? (object)false : config.LogPath.Length == 0 ? (object)true : config.LogPath));
+ Console.WriteLine(" Client Tracing: " + (config.Trace && config.RunMode.HasFlag(RunMode.client) ? "ON (client.log)" : "OFF"));
+ Console.WriteLine(" Server Tracing: " + (config.Trace && config.RunMode.HasFlag(RunMode.server) ? "ON (server.log)" : "OFF"));
  Console.WriteLine(" ASP.NET Log: " + config.LogAspNet);
  Console.WriteLine(" Concurrency: " + config.ConcurrentRequests);
  Console.WriteLine(" Content Length: " + config.MaxContentLength);
- Console.WriteLine(" HTTP2 Version: " + config.HttpVersion);
+ Console.WriteLine("  HTTP Version: " + config.HttpVersion);
  Console.WriteLine(" Lifetime: " + (config.ConnectionLifetime.HasValue ? $"{config.ConnectionLifetime.Value.TotalMilliseconds}ms" : "(infinite)"));
  Console.WriteLine(" Operations: " + string.Join(", ", usedClientOperations.Select(o => o.name)));
  Console.WriteLine(" Random Seed: " + config.RandomSeed);