Skip to content

Commit 17699f0

Browse files
BurgynBurgyn
authored
Merge pull request #77 from mchlkntrv/feature/requests-logging
Structured HTTP Request Logging via Serilog JSON Sink
2 parents ee77717 + fad56fa commit 17699f0

9 files changed

Lines changed: 231 additions & 8 deletions

File tree

‎src/TeaPie.DotnetTool/ExploreCommand.cs‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,12 +11,13 @@ protected override ApplicationBuilder ConfigureApplication(Settings settings)
1111
var pathToLogFile = settings.LogFile ?? string.Empty;
1212
var logLevel = Helper.ResolveLogLevel(settings);
1313
var path = PathResolver.Resolve(settings.Path, Directory.GetCurrentDirectory());
14+
var pathToRequestsLogFile = settings.RequestsLogFile;
1415

1516
var appBuilder = ApplicationBuilder.Create(path.IsCollectionPath());
1617

1718
appBuilder
1819
.WithPath(path)
19-
.WithLogging(logLevel, pathToLogFile, settings.LogFileLogLevel)
20+
.WithLogging(logLevel, pathToLogFile, settings.LogFileLogLevel, pathToRequestsLogFile)
2021
.WithEnvironmentFile(PathResolver.Resolve(settings.EnvironmentFile, string.Empty))
2122
.WithInitializationScript(PathResolver.Resolve(settings.InitializationScriptPath, string.Empty))
2223
.WithStructureExplorationPipeline();

‎src/TeaPie.DotnetTool/LoggingSettings.cs‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,10 @@ internal class LoggingSettings : CommandSettings
1515
"Supported levels: Trace, Debug, Information, Warning, Error, Critical, None.")]
1616
public LogLevel LogFileLogLevel { get; init; } = LogLevel.Information;
1717

18+
[CommandOption("--requests-log-file")]
19+
[Description("Path to the file where structured JSON data about HTTP requests will be saved.")]
20+
public string? RequestsLogFile { get; init; }
21+
1822
[CommandOption("-l|--log-level")]
1923
[Description("Log level for console output. " +
2024
"Supported levels: Trace, Debug, Information, Warning, Error, Critical, None.")]

‎src/TeaPie.DotnetTool/TestCommand.cs‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,13 +11,14 @@ protected override ApplicationBuilder ConfigureApplication(Settings settings)
1111
var pathToLogFile = settings.LogFile ?? string.Empty;
1212
var logLevel = Helper.ResolveLogLevel(settings);
1313
var path = PathResolver.Resolve(settings.Path, Directory.GetCurrentDirectory());
14+
var pathToRequestsLogFile = settings.RequestsLogFile;
1415

1516
var appBuilder = ApplicationBuilder.Create(path.IsCollectionPath());
1617

1718
appBuilder
1819
.WithPath(path)
1920
.WithTemporaryPath(settings.TemporaryPath ?? string.Empty)
20-
.WithLogging(logLevel, pathToLogFile, settings.LogFileLogLevel)
21+
.WithLogging(logLevel, pathToLogFile, settings.LogFileLogLevel, pathToRequestsLogFile)
2122
.WithEnvironment(settings.Environment ?? string.Empty)
2223
.WithEnvironmentFile(PathResolver.Resolve(settings.EnvironmentFilePath, string.Empty))
2324
.WithReportFile(PathResolver.Resolve(settings.ReportFilePath, string.Empty))

‎src/TeaPie/ApplicationBuilder.cs‎

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@ public sealed class ApplicationBuilder
3131
private LogLevel _minimumLogLevel = LogLevel.None;
3232
private string _pathToLogFile = string.Empty;
3333
private LogLevel _minimumLevelForLogFile = LogLevel.None;
34+
private string? _pathToRequestsLogFile;
3435

3536
private bool _variablesCaching = true;
3637

@@ -59,11 +60,13 @@ public ApplicationBuilder WithTemporaryPath(string temporaryPath)
5960
public ApplicationBuilder WithLogging(
6061
LogLevel minimumLevel,
6162
string pathToLogFile = "",
62-
LogLevel minimumLevelForLogFile = LogLevel.None)
63+
LogLevel minimumLevelForLogFile = LogLevel.None,
64+
string? pathToRequestsLogFile = null)
6365
{
6466
_minimumLogLevel = minimumLevel;
6567
_pathToLogFile = pathToLogFile;
6668
_minimumLevelForLogFile = minimumLevelForLogFile;
69+
_pathToRequestsLogFile = pathToRequestsLogFile;
6770
return this;
6871
}
6972

@@ -153,7 +156,7 @@ private ApplicationContext GetApplicationContext(IServiceProvider provider)
153156
private void ConfigureServices()
154157
=> _services.AddTeaPie(
155158
_isCollectionRun,
156-
() => _services.ConfigureLogging(_minimumLogLevel, _pathToLogFile, _minimumLevelForLogFile));
159+
() => _services.ConfigureLogging(_minimumLogLevel, _pathToLogFile, _minimumLevelForLogFile, _pathToRequestsLogFile));
157160

158161
private static TeaPie CreateUserContext(IServiceProvider provider, ApplicationContext applicationContext)
159162
=> TeaPie.Create(

‎src/TeaPie/Http/Auth/Setup.cs‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@ public static IServiceCollection AddAuthentication(this IServiceCollection servi
1212

1313
services.AddHttpClient<ExecuteRequestStep>()
1414
.AddHttpMessageHandler<AuthHttpMessageHandler>()
15+
.AddHttpMessageHandler<RequestsLoggingHandler>()
1516
.AddHttpMessageHandler<LoggingInterceptorHandler>();
1617

1718
services.AddSingleton<IAuthProviderRegistry, AuthProviderRegistry>();

‎src/TeaPie/Http/ExecuteRequestStep.cs‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ internal class ExecuteRequestStep(
2222
private readonly IAuthProviderAccessor _authProviderAccessor = defaultAuthProviderAccessor;
2323
private readonly IPipeline _pipeline = pipeline;
2424
private readonly ITestScheduler _testScheduler = testScheduler;
25+
private static readonly HttpRequestOptionsKey<RequestExecutionContext> _contextKey = new("__TeaPie_Context__");
2526

2627
public async Task Execute(ApplicationContext context, CancellationToken cancellationToken = default)
2728
{
@@ -100,10 +101,13 @@ private async Task<HttpResponseMessage> ExecuteRequest(
100101
var messageUsed = false;
101102
var retryAttemptNumber = -1;
102103

104+
originalMessage.Options.Set(_contextKey, requestExecutionContext);
105+
103106
return await resiliencePipeline.ExecuteAsync(async token =>
104107
{
105108
retryAttemptNumber = UpdateRetryAttemptNumber(logger, retryAttemptNumber);
106109
var request = GetMessage(requestExecutionContext, originalMessage, content, ref messageUsed);
110+
request.Options.Set(_contextKey, requestExecutionContext);
107111
return await client.SendAsync(request, token);
108112
}, cancellationToken);
109113
}

‎src/TeaPie/Logging/RequestLogFileEntry.cs‎

Lines changed: 53 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,53 @@
1+
using System.Text.Json.Serialization;
2+
3+
namespace TeaPie.Logging;
4+
5+
internal class RequestLogFileEntry
6+
{
7+
public string RequestId { get; init; } = Guid.NewGuid().ToString();
8+
public DateTime StartTime { get; set; }
9+
public DateTime? EndTime { get; set; }
10+
[JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
11+
public double? DurationMs => EndTime?.Subtract(StartTime).TotalMilliseconds;
12+
public RequestInfo Request { get; set; } = new();
13+
[JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
14+
public ResponseInfo? Response { get; set; }
15+
[JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
16+
public AuthInfo? Authentication { get; set; }
17+
public List<string> Errors { get; set; } = [];
18+
}
19+
20+
internal class RequestInfo
21+
{
22+
public string Name { get; set; } = string.Empty;
23+
public string Method { get; set; } = string.Empty;
24+
public string Uri { get; set; } = string.Empty;
25+
public Dictionary<string, string> Headers { get; set; } = [];
26+
[JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
27+
public string? Body { get; set; }
28+
[JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
29+
public string? ContentType { get; set; }
30+
public string FilePath { get; set; } = string.Empty;
31+
}
32+
33+
internal class ResponseInfo
34+
{
35+
public int StatusCode { get; set; }
36+
[JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
37+
public string? ReasonPhrase { get; set; }
38+
public Dictionary<string, string> Headers { get; set; } = [];
39+
[JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
40+
public string? Body { get; set; }
41+
[JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
42+
public string? ContentType { get; set; }
43+
public DateTime ReceivedAt { get; set; } = DateTime.UtcNow;
44+
}
45+
46+
internal class AuthInfo
47+
{
48+
[JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
49+
public string? ProviderType { get; set; }
50+
public bool IsDefault { get; set; }
51+
[JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)]
52+
public DateTime? AuthenticatedAt { get; set; }
53+
}

‎src/TeaPie/Logging/RequestsLoggingHandler.cs‎

Lines changed: 117 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,117 @@
1+
using System.Net.Http.Headers;
2+
using TeaPie.Http;
3+
using TeaPie.Http.Auth;
4+
using Microsoft.Extensions.Logging;
5+
6+
namespace TeaPie.Logging;
7+
8+
internal class RequestsLoggingHandler(IAuthProviderAccessor authProviderAccessor, ILoggerFactory loggerFactory) : DelegatingHandler
9+
{
10+
private readonly IAuthProviderAccessor _authProviderAccessor = authProviderAccessor;
11+
private readonly ILogger _logger = loggerFactory.CreateLogger("HttpRequests");
12+
private static readonly HttpRequestOptionsKey<RequestExecutionContext> _contextKey = new("__TeaPie_Context__");
13+
14+
protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
15+
{
16+
request.Options.TryGetValue(_contextKey, out var requestContext);
17+
18+
var attemptStartTime = DateTime.UtcNow;
19+
try
20+
{
21+
var response = await base.SendAsync(request, cancellationToken);
22+
if (requestContext is not null)
23+
{
24+
await LogRequestAsync(requestContext, request, response, null, attemptStartTime);
25+
}
26+
return response;
27+
}
28+
catch (Exception ex)
29+
{
30+
if (requestContext is not null)
31+
{
32+
await LogRequestAsync(requestContext, request, null, ex, attemptStartTime);
33+
}
34+
throw;
35+
}
36+
}
37+
38+
private async Task LogRequestAsync(
39+
RequestExecutionContext requestContext,
40+
HttpRequestMessage request,
41+
HttpResponseMessage? response,
42+
Exception? exception,
43+
DateTime attemptStartTime)
44+
{
45+
var logEntry = new RequestLogFileEntry
46+
{
47+
StartTime = attemptStartTime,
48+
EndTime = DateTime.UtcNow,
49+
Request = await CreateRequestInfoAsync(requestContext, request),
50+
Response = response != null ? await CreateResponseInfoAsync(response) : null,
51+
Authentication = CreateAuthInfo(),
52+
Errors = exception != null ? [exception.Message] : []
53+
};
54+
55+
_logger.LogInformation("{@RequestLogFileEntry}", logEntry);
56+
}
57+
58+
private static async Task<RequestInfo> CreateRequestInfoAsync(RequestExecutionContext requestContext, HttpRequestMessage request)
59+
{
60+
return new RequestInfo
61+
{
62+
Name = requestContext.Name,
63+
Method = request.Method.ToString(),
64+
Uri = request.RequestUri?.ToString() ?? string.Empty,
65+
Headers = ProcessHeaders(request.Headers),
66+
Body = await GetContentBodyAsync(request.Content),
67+
ContentType = request.Content?.Headers.ContentType?.MediaType,
68+
FilePath = requestContext.RequestFile.RelativePath
69+
};
70+
}
71+
72+
private static async Task<ResponseInfo> CreateResponseInfoAsync(HttpResponseMessage response)
73+
{
74+
return new ResponseInfo
75+
{
76+
StatusCode = (int)response.StatusCode,
77+
ReasonPhrase = response.ReasonPhrase,
78+
Headers = ProcessHeaders(response.Headers),
79+
Body = await GetContentBodyAsync(response.Content),
80+
ContentType = response.Content?.Headers.ContentType?.MediaType,
81+
ReceivedAt = DateTime.UtcNow
82+
};
83+
}
84+
85+
private static async Task<string?> GetContentBodyAsync(HttpContent? content)
86+
{
87+
if (content == null)
88+
{
89+
return null;
90+
}
91+
92+
try
93+
{
94+
return await content.ReadAsStringAsync();
95+
}
96+
catch (OperationCanceledException ex)
97+
{
98+
return ($"Content reading failed: {ex.Message}");
99+
}
100+
}
101+
102+
private AuthInfo? CreateAuthInfo()
103+
{
104+
var currentProvider = _authProviderAccessor.CurrentProvider;
105+
return currentProvider == null ? null : new AuthInfo
106+
{
107+
ProviderType = currentProvider.GetType().Name,
108+
IsDefault = currentProvider == _authProviderAccessor.DefaultProvider,
109+
AuthenticatedAt = DateTime.UtcNow
110+
};
111+
}
112+
113+
private static Dictionary<string, string> ProcessHeaders(HttpHeaders headers)
114+
{
115+
return headers.ToDictionary(h => h.Key, h => string.Join(", ", h.Value));
116+
}
117+
}

‎src/TeaPie/Logging/Setup.cs‎

Lines changed: 43 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,8 @@
22
using Microsoft.Extensions.Logging;
33
using Serilog;
44
using Serilog.Events;
5+
using Serilog.Filters;
6+
using Serilog.Formatting.Json;
57

68
namespace TeaPie.Logging;
79

@@ -12,6 +14,7 @@ public static IServiceCollection AddLogging(this IServiceCollection services, Ac
1214
configure();
1315

1416
services.AddTransient<LoggingInterceptorHandler>();
17+
services.AddTransient<RequestsLoggingHandler>();
1518
services.AddSingleton<NuGet.Common.ILogger, NuGetLoggerAdapter>();
1619
services.AddLogging(loggingBuilder => loggingBuilder.AddSerilog(dispose: true));
1720

@@ -22,7 +25,8 @@ public static IServiceCollection ConfigureLogging(
2225
this IServiceCollection services,
2326
LogLevel minimumLevel,
2427
string pathToLogFile = "",
25-
LogLevel minimumLevelForLogFile = LogLevel.Debug)
28+
LogLevel minimumLevelForLogFile = LogLevel.Debug,
29+
string? pathToRequestsLogFile = null)
2630
{
2731
if (minimumLevel == LogLevel.None)
2832
{
@@ -33,12 +37,18 @@ public static IServiceCollection ConfigureLogging(
3337
var config = new LoggerConfiguration()
3438
.MinimumLevel.Is(GetMaximumFromMinimalLevels(minimumLevel, minimumLevelForLogFile))
3539
.MinimumLevel.Override("System.Net.Http", ApplyRestrictiveLogLevelRule(minimumLevel))
36-
.MinimumLevel.Override("TeaPie.Logging.NuGetLoggerAdapter", ApplyRestrictiveLogLevelRule(minimumLevel))
37-
.WriteTo.Console(restrictedToMinimumLevel: minimumLevel.ToSerilogLogLevel());
40+
.MinimumLevel.Override("TeaPie.Logging.NuGetLoggerAdapter", ApplyRestrictiveLogLevelRule(minimumLevel));
41+
42+
AddConsoleSink(config, minimumLevel);
3843

3944
if (!pathToLogFile.Equals(string.Empty) && minimumLevelForLogFile < LogLevel.None)
4045
{
41-
config.WriteTo.File(pathToLogFile, restrictedToMinimumLevel: minimumLevelForLogFile.ToSerilogLogLevel());
46+
AddLogFileSink(config, pathToLogFile, minimumLevelForLogFile);
47+
}
48+
49+
if (!string.IsNullOrEmpty(pathToRequestsLogFile))
50+
{
51+
AddRequestsFileSink(config, pathToRequestsLogFile, minimumLevelForLogFile);
4252
}
4353

4454
Log.Logger = config.CreateLogger();
@@ -54,4 +64,33 @@ private static LogEventLevel GetMaximumFromMinimalLevels(LogLevel minimumLevel1,
5464

5565
private static LogEventLevel ApplyRestrictiveLogLevelRule(LogLevel minimumLevel)
5666
=> minimumLevel >= LogLevel.Information ? LogEventLevel.Warning : LogEventLevel.Debug;
67+
68+
private static void AddConsoleSink(LoggerConfiguration config, LogLevel minimumLevel)
69+
{
70+
config.WriteTo.Logger(lc => lc
71+
.Filter.ByExcluding(Matching.FromSource("HttpRequests"))
72+
.WriteTo.Console(restrictedToMinimumLevel: minimumLevel.ToSerilogLogLevel()));
73+
}
74+
75+
private static void AddLogFileSink(LoggerConfiguration config, string pathToLogFile, LogLevel minimumLevelForLogFile)
76+
{
77+
config.WriteTo.Logger(lc => lc
78+
.Filter.ByExcluding(Matching.FromSource("HttpRequests"))
79+
.WriteTo.File(pathToLogFile, restrictedToMinimumLevel: minimumLevelForLogFile.ToSerilogLogLevel()));
80+
}
81+
82+
private static void AddRequestsFileSink(LoggerConfiguration config, string pathToRequestsLogFile, LogLevel minimumLevelForLogFile)
83+
{
84+
if (File.Exists(pathToRequestsLogFile))
85+
{
86+
File.Delete(pathToRequestsLogFile);
87+
}
88+
89+
config.WriteTo.Logger(lc => lc
90+
.Filter.ByIncludingOnly(Matching.FromSource("HttpRequests"))
91+
.WriteTo.File(
92+
new JsonFormatter(renderMessage: false),
93+
pathToRequestsLogFile,
94+
restrictedToMinimumLevel: minimumLevelForLogFile.ToSerilogLogLevel()));
95+
}
5796
}

0 commit comments

Comments
 (0)