Structured HTTP Request Logging via Serilog JSON Sink

src/TeaPie.DotnetTool/ExploreCommand.cs

@@ -11,12 +11,13 @@ protected override ApplicationBuilder ConfigureApplication(Settings settings)
         var pathToLogFile = settings.LogFile ?? string.Empty;
         var logLevel = Helper.ResolveLogLevel(settings);
         var path = PathResolver.Resolve(settings.Path, Directory.GetCurrentDirectory());
+        var pathToRequestsLogFile = settings.RequestsLogFile;
 
         var appBuilder = ApplicationBuilder.Create(path.IsCollectionPath());
 
         appBuilder
             .WithPath(path)
-            .WithLogging(logLevel, pathToLogFile, settings.LogFileLogLevel)
+            .WithLogging(logLevel, pathToLogFile, settings.LogFileLogLevel, pathToRequestsLogFile)
             .WithEnvironmentFile(PathResolver.Resolve(settings.EnvironmentFile, string.Empty))
             .WithInitializationScript(PathResolver.Resolve(settings.InitializationScriptPath, string.Empty))
             .WithStructureExplorationPipeline();

src/TeaPie.DotnetTool/LoggingSettings.cs

@@ -15,6 +15,10 @@ internal class LoggingSettings : CommandSettings
         "Supported levels: Trace, Debug, Information, Warning, Error, Critical, None.")]
     public LogLevel LogFileLogLevel { get; init; } = LogLevel.Information;
 
+    [CommandOption("--requests-log-file")]
+    [Description("Path to the file where structured JSON data about HTTP requests will be saved.")]
+    public string? RequestsLogFile { get; init; }
+
     [CommandOption("-l|--log-level")]
     [Description("Log level for console output. " +
         "Supported levels: Trace, Debug, Information, Warning, Error, Critical, None.")]

src/TeaPie.DotnetTool/TestCommand.cs

@@ -11,13 +11,14 @@ protected override ApplicationBuilder ConfigureApplication(Settings settings)
         var pathToLogFile = settings.LogFile ?? string.Empty;
         var logLevel = Helper.ResolveLogLevel(settings);
         var path = PathResolver.Resolve(settings.Path, Directory.GetCurrentDirectory());
+        var pathToRequestsLogFile = settings.RequestsLogFile;
 
         var appBuilder = ApplicationBuilder.Create(path.IsCollectionPath());
 
         appBuilder
             .WithPath(path)
             .WithTemporaryPath(settings.TemporaryPath ?? string.Empty)
-            .WithLogging(logLevel, pathToLogFile, settings.LogFileLogLevel)
+            .WithLogging(logLevel, pathToLogFile, settings.LogFileLogLevel, pathToRequestsLogFile)
             .WithEnvironment(settings.Environment ?? string.Empty)
             .WithEnvironmentFile(PathResolver.Resolve(settings.EnvironmentFilePath, string.Empty))
             .WithReportFile(PathResolver.Resolve(settings.ReportFilePath, string.Empty))

src/TeaPie/ApplicationBuilder.cs

@@ -31,6 +31,7 @@ public sealed class ApplicationBuilder
     private LogLevel _minimumLogLevel = LogLevel.None;
     private string _pathToLogFile = string.Empty;
     private LogLevel _minimumLevelForLogFile = LogLevel.None;
+    private string? _pathToRequestsLogFile;
 
     private bool _variablesCaching = true;
 
@@ -59,11 +60,13 @@ public ApplicationBuilder WithTemporaryPath(string temporaryPath)
     public ApplicationBuilder WithLogging(
         LogLevel minimumLevel,
         string pathToLogFile = "",
-        LogLevel minimumLevelForLogFile = LogLevel.None)
+        LogLevel minimumLevelForLogFile = LogLevel.None,
+        string? pathToRequestsLogFile = null)
     {
         _minimumLogLevel = minimumLevel;
         _pathToLogFile = pathToLogFile;
         _minimumLevelForLogFile = minimumLevelForLogFile;
+        _pathToRequestsLogFile = pathToRequestsLogFile;
         return this;
     }
 
@@ -153,7 +156,7 @@ private ApplicationContext GetApplicationContext(IServiceProvider provider)
     private void ConfigureServices()
         => _services.AddTeaPie(
             _isCollectionRun,
-            () => _services.ConfigureLogging(_minimumLogLevel, _pathToLogFile, _minimumLevelForLogFile));
+            () => _services.ConfigureLogging(_minimumLogLevel, _pathToLogFile, _minimumLevelForLogFile, _pathToRequestsLogFile));
 
     private static TeaPie CreateUserContext(IServiceProvider provider, ApplicationContext applicationContext)
         => TeaPie.Create(

src/TeaPie/Http/Auth/Setup.cs

@@ -12,6 +12,7 @@ public static IServiceCollection AddAuthentication(this IServiceCollection servi
 
         services.AddHttpClient<ExecuteRequestStep>()
             .AddHttpMessageHandler<AuthHttpMessageHandler>()
+            .AddHttpMessageHandler<RequestsLoggingHandler>()
             .AddHttpMessageHandler<LoggingInterceptorHandler>();
 
         services.AddSingleton<IAuthProviderRegistry, AuthProviderRegistry>();

src/TeaPie/Http/ExecuteRequestStep.cs

@@ -22,6 +22,7 @@ internal class ExecuteRequestStep(
     private readonly IAuthProviderAccessor _authProviderAccessor = defaultAuthProviderAccessor;
     private readonly IPipeline _pipeline = pipeline;
     private readonly ITestScheduler _testScheduler = testScheduler;
+    private static readonly HttpRequestOptionsKey<RequestExecutionContext> _contextKey = new("__TeaPie_Context__");
 
     public async Task Execute(ApplicationContext context, CancellationToken cancellationToken = default)
     {
@@ -100,10 +101,13 @@ private async Task<HttpResponseMessage> ExecuteRequest(
         var messageUsed = false;
         var retryAttemptNumber = -1;
 
+        originalMessage.Options.Set(_contextKey, requestExecutionContext);
+
         return await resiliencePipeline.ExecuteAsync(async token =>
         {
             retryAttemptNumber = UpdateRetryAttemptNumber(logger, retryAttemptNumber);
             var request = GetMessage(requestExecutionContext, originalMessage, content, ref messageUsed);
+            request.Options.Set(_contextKey, requestExecutionContext);
             return await client.SendAsync(request, token);
         }, cancellationToken);
     }

src/TeaPie/Logging/RequestLogFileEntry.cs

@@ -0,0 +1,53 @@
+using System.Text.Json.Serialization;
+
+namespace TeaPie.Logging;
+
+internal class RequestLogFileEntry
+{
+    public string RequestId { get; init; } = Guid.NewGuid().ToString();
+    public DateTime StartTime { get; set; }
+    public DateTime? EndTime { get; set; }
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public double? DurationMs => EndTime?.Subtract(StartTime).TotalMilliseconds;
+    public RequestInfo Request { get; set; } = new();
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public ResponseInfo? Response { get; set; }
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public AuthInfo? Authentication { get; set; }
+    public List<string> Errors { get; set; } = [];
+}
+
+internal class RequestInfo
+{
+    public string Name { get; set; } = string.Empty;
+    public string Method { get; set; } = string.Empty;
+    public string Uri { get; set; } = string.Empty;
+    public Dictionary<string, string> Headers { get; set; } = [];
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public string? Body { get; set; }
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public string? ContentType { get; set; }
+    public string FilePath { get; set; } = string.Empty;
+}
+
+internal class ResponseInfo
+{
+    public int StatusCode { get; set; }
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public string? ReasonPhrase { get; set; }
+    public Dictionary<string, string> Headers { get; set; } = [];
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public string? Body { get; set; }
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public string? ContentType { get; set; }
+    public DateTime ReceivedAt { get; set; } = DateTime.UtcNow;
+}
+
+internal class AuthInfo
+{
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public string? ProviderType { get; set; }
+    public bool IsDefault { get; set; }
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public DateTime? AuthenticatedAt { get; set; }
+}

src/TeaPie/Logging/RequestsLoggingHandler.cs

@@ -0,0 +1,117 @@
+using System.Net.Http.Headers;
+using TeaPie.Http;
+using TeaPie.Http.Auth;
+using Microsoft.Extensions.Logging;
+
+namespace TeaPie.Logging;
+
+internal class RequestsLoggingHandler(IAuthProviderAccessor authProviderAccessor, ILoggerFactory loggerFactory) : DelegatingHandler
+{
+    private readonly IAuthProviderAccessor _authProviderAccessor = authProviderAccessor;
+    private readonly ILogger _logger = loggerFactory.CreateLogger("HttpRequests");
+    private static readonly HttpRequestOptionsKey<RequestExecutionContext> _contextKey = new("__TeaPie_Context__");
+
+    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
+    {
+        request.Options.TryGetValue(_contextKey, out var requestContext);
+
+        var attemptStartTime = DateTime.UtcNow;
+        try
+        {
+            var response = await base.SendAsync(request, cancellationToken);
+            if (requestContext is not null)
+            {
+                await LogRequestAsync(requestContext, request, response, null, attemptStartTime);
+            }
+            return response;
+        }
+        catch (Exception ex)
+        {
+            if (requestContext is not null)
+            {
+                await LogRequestAsync(requestContext, request, null, ex, attemptStartTime);
+            }
+            throw;
+        }
+    }
+
+    private async Task LogRequestAsync(
+        RequestExecutionContext requestContext,
+        HttpRequestMessage request,
+        HttpResponseMessage? response,
+        Exception? exception,
+        DateTime attemptStartTime)
+    {
+        var logEntry = new RequestLogFileEntry
+        {
+            StartTime = attemptStartTime,
+            EndTime = DateTime.UtcNow,
+            Request = await CreateRequestInfoAsync(requestContext, request),
+            Response = response != null ? await CreateResponseInfoAsync(response) : null,
+            Authentication = CreateAuthInfo(),
+            Errors = exception != null ? [exception.Message] : []
+        };
+
+        _logger.LogInformation("{@RequestLogFileEntry}", logEntry);
+    }
+
+    private static async Task<RequestInfo> CreateRequestInfoAsync(RequestExecutionContext requestContext, HttpRequestMessage request)
+    {
+        return new RequestInfo
+        {
+            Name = requestContext.Name,
+            Method = request.Method.ToString(),
+            Uri = request.RequestUri?.ToString() ?? string.Empty,
+            Headers = ProcessHeaders(request.Headers),
+            Body = await GetContentBodyAsync(request.Content),
+            ContentType = request.Content?.Headers.ContentType?.MediaType,
+            FilePath = requestContext.RequestFile.RelativePath
+        };
+    }
+
+    private static async Task<ResponseInfo> CreateResponseInfoAsync(HttpResponseMessage response)
+    {
+        return new ResponseInfo
+        {
+            StatusCode = (int)response.StatusCode,
+            ReasonPhrase = response.ReasonPhrase,
+            Headers = ProcessHeaders(response.Headers),
+            Body = await GetContentBodyAsync(response.Content),
+            ContentType = response.Content?.Headers.ContentType?.MediaType,
+            ReceivedAt = DateTime.UtcNow
+        };
+    }
+
+    private static async Task<string?> GetContentBodyAsync(HttpContent? content)
+    {
+        if (content == null)
+        {
+            return null;
+        }
+
+        try
+        {
+            return await content.ReadAsStringAsync();
+        }
+        catch (OperationCanceledException ex)
+        {
+            return ($"Content reading failed: {ex.Message}");
+        }
+    }
+
+    private AuthInfo? CreateAuthInfo()
+    {
+        var currentProvider = _authProviderAccessor.CurrentProvider;
+        return currentProvider == null ? null : new AuthInfo
+        {
+            ProviderType = currentProvider.GetType().Name,
+            IsDefault = currentProvider == _authProviderAccessor.DefaultProvider,
+            AuthenticatedAt = DateTime.UtcNow
+        };
+    }
+
+    private static Dictionary<string, string> ProcessHeaders(HttpHeaders headers)
+    {
+        return headers.ToDictionary(h => h.Key, h => string.Join(", ", h.Value));
+    }
+}

src/TeaPie/Logging/Setup.cs

@@ -2,6 +2,8 @@
 using Microsoft.Extensions.Logging;
 using Serilog;
 using Serilog.Events;
+using Serilog.Filters;
+using Serilog.Formatting.Json;
 
 namespace TeaPie.Logging;
 
@@ -12,6 +14,7 @@ public static IServiceCollection AddLogging(this IServiceCollection services, Ac
         configure();
 
         services.AddTransient<LoggingInterceptorHandler>();
+        services.AddTransient<RequestsLoggingHandler>();
         services.AddSingleton<NuGet.Common.ILogger, NuGetLoggerAdapter>();
         services.AddLogging(loggingBuilder => loggingBuilder.AddSerilog(dispose: true));
 
@@ -22,7 +25,8 @@ public static IServiceCollection ConfigureLogging(
         this IServiceCollection services,
         LogLevel minimumLevel,
         string pathToLogFile = "",
-        LogLevel minimumLevelForLogFile = LogLevel.Debug)
+        LogLevel minimumLevelForLogFile = LogLevel.Debug,
+        string? pathToRequestsLogFile = null)
     {
         if (minimumLevel == LogLevel.None)
         {
@@ -33,12 +37,18 @@ public static IServiceCollection ConfigureLogging(
             var config = new LoggerConfiguration()
                 .MinimumLevel.Is(GetMaximumFromMinimalLevels(minimumLevel, minimumLevelForLogFile))
                 .MinimumLevel.Override("System.Net.Http", ApplyRestrictiveLogLevelRule(minimumLevel))
-                .MinimumLevel.Override("TeaPie.Logging.NuGetLoggerAdapter", ApplyRestrictiveLogLevelRule(minimumLevel))
-                .WriteTo.Console(restrictedToMinimumLevel: minimumLevel.ToSerilogLogLevel());
+                .MinimumLevel.Override("TeaPie.Logging.NuGetLoggerAdapter", ApplyRestrictiveLogLevelRule(minimumLevel));
+
+            AddConsoleSink(config, minimumLevel);
 
             if (!pathToLogFile.Equals(string.Empty) && minimumLevelForLogFile < LogLevel.None)
             {
-                config.WriteTo.File(pathToLogFile, restrictedToMinimumLevel: minimumLevelForLogFile.ToSerilogLogLevel());
+                AddLogFileSink(config, pathToLogFile, minimumLevelForLogFile);
+            }
+
+            if (!string.IsNullOrEmpty(pathToRequestsLogFile))
+            {
+                AddRequestsFileSink(config, pathToRequestsLogFile, minimumLevelForLogFile);
             }
 
             Log.Logger = config.CreateLogger();
@@ -54,4 +64,33 @@ private static LogEventLevel GetMaximumFromMinimalLevels(LogLevel minimumLevel1,
 
     private static LogEventLevel ApplyRestrictiveLogLevelRule(LogLevel minimumLevel)
         => minimumLevel >= LogLevel.Information ? LogEventLevel.Warning : LogEventLevel.Debug;
+
+    private static void AddConsoleSink(LoggerConfiguration config, LogLevel minimumLevel)
+    {
+        config.WriteTo.Logger(lc => lc
+            .Filter.ByExcluding(Matching.FromSource("HttpRequests"))
+            .WriteTo.Console(restrictedToMinimumLevel: minimumLevel.ToSerilogLogLevel()));
+    }
+
+    private static void AddLogFileSink(LoggerConfiguration config, string pathToLogFile, LogLevel minimumLevelForLogFile)
+    {
+        config.WriteTo.Logger(lc => lc
+            .Filter.ByExcluding(Matching.FromSource("HttpRequests"))
+            .WriteTo.File(pathToLogFile, restrictedToMinimumLevel: minimumLevelForLogFile.ToSerilogLogLevel()));
+    }
+
+    private static void AddRequestsFileSink(LoggerConfiguration config, string pathToRequestsLogFile, LogLevel minimumLevelForLogFile)
+    {
+        if (File.Exists(pathToRequestsLogFile))
+        {
+            File.Delete(pathToRequestsLogFile);
+        }
+
+        config.WriteTo.Logger(lc => lc
+            .Filter.ByIncludingOnly(Matching.FromSource("HttpRequests"))
+            .WriteTo.File(
+                new JsonFormatter(renderMessage: false),
+                pathToRequestsLogFile,
+                restrictedToMinimumLevel: minimumLevelForLogFile.ToSerilogLogLevel()));
+    }
 }