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 file with information 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

@@ -2,6 +2,7 @@
 using Polly;
 using TeaPie.Http.Auth;
 using TeaPie.Http.Headers;
+using TeaPie.Logging;
 using TeaPie.Pipelines;
 using TeaPie.Testing;
 
@@ -22,6 +23,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 +102,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);
     }
@@ -149,6 +154,10 @@ private HttpRequestMessage CloneMessage(
         };
 
         _headersHandler.SetHeaders(originalMessage, request);
+        if (originalMessage.Options.TryGetValue(RequestsLoggingHandler.LogEntryKey, out var logEntry))
+        {
+            request.Options.Set(RequestsLoggingHandler.LogEntryKey, logEntry);
+        }
         return request;
     }
 

src/TeaPie/Logging/RequestLogFileEntry.cs

@@ -0,0 +1,75 @@
+using System.Text.Json.Serialization;
+
+namespace TeaPie.Logging;
+
+internal class RequestLogFileEntry
+{
+    public string RequestId { get; set; } = Guid.NewGuid().ToString();
+    public DateTime StartTime { get; set; } = DateTime.UtcNow;
+    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; }
+    public RetryInfo Retries { get; set; } = new();
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public AuthInfo? Authentication { get; set; }
+    public List<string> Errors { get; set; } = [];
+    public Dictionary<string, object> Metadata { 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 RetryInfo
+{
+    public int AttemptCount { get; set; } = 1;
+    public List<RetryAttempt> Attempts { get; set; } = [];
+}
+
+internal class RetryAttempt
+{
+    public int AttemptNumber { get; set; }
+    public DateTime Timestamp { get; set; } = DateTime.UtcNow;
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public string? Reason { get; set; }
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public ResponseInfo? Response { get; set; }
+    [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
+    public Exception? Exception { get; set; }
+    public bool IsSuccessful { get; set; }
+    public double DurationMs { get; set; }
+}
+
+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,175 @@
+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__");
+    public static readonly HttpRequestOptionsKey<RequestLogFileEntry> LogEntryKey = new("__TeaPie_LogEntry__");
+
+    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
+    {
+        if (!request.Options.TryGetValue(_contextKey, out var requestContext) || requestContext is null)
+        {
+            return await base.SendAsync(request, cancellationToken);
+        }
+
+        var logEntry = await GetOrCreateLogEntryAsync(request, requestContext);
+        var attemptStartTime = DateTime.UtcNow;
+        HttpResponseMessage? response = null;
+        Exception? exception = null;
+
+        try
+        {
+            response = await base.SendAsync(request, cancellationToken);
+            return response;
+        }
+        catch (Exception ex)
+        {
+            exception = ex;
+            throw;
+        }
+        finally
+        {
+            await RecordAttemptAsync(logEntry, response, exception, attemptStartTime);
+            await LogCompletedRequestAsync(request, response);
+        }
+    }
+
+    private async Task<RequestLogFileEntry> GetOrCreateLogEntryAsync(HttpRequestMessage request, RequestExecutionContext requestContext)
+    {
+        if (request.Options.TryGetValue(LogEntryKey, out var existingEntry) && existingEntry != null)
+        {
+            return existingEntry;
+        }
+
+        var logEntry = new RequestLogFileEntry
+        {
+            RequestId = Guid.NewGuid().ToString(),
+            StartTime = DateTime.UtcNow,
+            Request = await CreateRequestInfoAsync(requestContext, request),
+            Authentication = CreateAuthInfo(),
+            Metadata = CreateMetadata(requestContext),
+            Retries = new RetryInfo { AttemptCount = 0, Attempts = [] },
+            Errors = []
+        };
+
+        request.Options.Set(LogEntryKey, logEntry);
+        return logEntry;
+    }
+
+    private static async Task RecordAttemptAsync(RequestLogFileEntry logEntry, HttpResponseMessage? response, Exception? exception, DateTime attemptStartTime)
+    {
+        var attemptNumber = logEntry.Retries.AttemptCount + 1;
+        var attempt = new RetryAttempt
+        {
+            AttemptNumber = attemptNumber,
+            Timestamp = attemptStartTime,
+            Reason = attemptNumber == 1 ? "Initial attempt" : "Resilience policy triggered retry",
+            IsSuccessful = response?.IsSuccessStatusCode ?? false,
+            DurationMs = (DateTime.UtcNow - attemptStartTime).TotalMilliseconds,
+            Exception = exception
+        };
+
+        if (response != null)
+        {
+            attempt.Response = await CreateResponseInfoAsync(response);
+        }
+
+        logEntry.Retries.Attempts.Add(attempt);
+        logEntry.Retries.AttemptCount = attemptNumber;
+        logEntry.EndTime = DateTime.UtcNow;
+
+        if (exception != null)
+        {
+            logEntry.Errors.Add(exception.Message);
+        }
+    }
+
+    public async Task LogCompletedRequestAsync(HttpRequestMessage request, HttpResponseMessage? finalResponse)
+    {
+        if (request.Options.TryGetValue(LogEntryKey, out var logEntry) && logEntry != null)
+        {
+            if (finalResponse != null && logEntry.Response == null)
+            {
+                logEntry.Response = await CreateResponseInfoAsync(finalResponse);
+            }
+
+            _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
+        {
+            return "[Content reading failed]";
+        }
+    }
+
+    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, object> CreateMetadata(RequestExecutionContext requestContext)
+    {
+        return new Dictionary<string, object>
+        {
+            ["testCaseId"] = requestContext.TestCaseExecutionContext?.Id.ToString() ?? "none",
+            ["hasResiliencePipeline"] = requestContext.ResiliencePipeline != null
+        };
+    }
+
+    private static Dictionary<string, string> ProcessHeaders(HttpHeaders headers)
+    {
+        return headers.ToDictionary(h => h.Key, h => string.Join(", ", h.Value));
+    }
+}