Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HttpLogging redaction and enrichment #50163

Merged
merged 34 commits into from
Aug 31, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
34 commits
Select commit Hold shift + click to select a range
8addb4f
Proof of concept for extending http logging
Tratcher Jun 2, 2023
a40b2d8
Feedback, cleanup
Tratcher Jun 9, 2023
affbe55
Nits
Tratcher Jun 12, 2023
f051458
Add duration
Tratcher Jun 12, 2023
dedc429
Fix log, test
Tratcher Jun 13, 2023
429137a
Pool log contexts
Tratcher Jun 13, 2023
c01fa22
API review
Tratcher Aug 17, 2023
c99ea47
Cleanup, TimeProvider
Tratcher Aug 17, 2023
60b503f
Duration
Tratcher Aug 22, 2023
cc1fc7c
Write temp files to the current dir, it might be on a different/faste…
Tratcher Aug 22, 2023
613f38b
Cleanup
Tratcher Aug 22, 2023
2a67078
Tests
Tratcher Aug 23, 2023
9dec914
Fix CopyTo/Async #49989
Tratcher Aug 23, 2023
fb37ff9
Apply suggestions from code review
Tratcher Aug 24, 2023
ca1b2ec
Clarify code check error
Tratcher Aug 23, 2023
be501ae
Comments, copyto, TryOverride
Tratcher Aug 24, 2023
3e3a8ca
Usings
Tratcher Aug 24, 2023
6734921
Code review, comments, tests
Tratcher Aug 25, 2023
8f732ec
Restructuring
Tratcher Aug 25, 2023
98d8261
Note when the request body was not fully logged #49063
Tratcher Aug 25, 2023
607e628
Powershell fix?
Tratcher Aug 25, 2023
d319c7d
Revert "Clarify code check error"
Tratcher Aug 28, 2023
a846c79
Feedback
Tratcher Aug 28, 2023
e09a349
Feedback
Tratcher Aug 29, 2023
9c847fd
Combine logs, log even if an exception happens
Tratcher Aug 30, 2023
bf48e46
Clarify
Tratcher Aug 30, 2023
b73c3f7
Don't log empty response body
Tratcher Aug 30, 2023
0678c83
Getting cozy
Tratcher Aug 31, 2023
80b0a80
Simplify Duration
Tratcher Aug 31, 2023
40e35f0
Less pooling
Tratcher Aug 31, 2023
cee71fb
Clean up comments
Tratcher Aug 31, 2023
ec5aad6
Even less re-use
Tratcher Aug 31, 2023
c9b6c46
Clean up Unshipped.txt
Tratcher Aug 31, 2023
d12739d
Re-fix Unshipped
Tratcher Aug 31, 2023
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -0,0 +1,87 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using Microsoft.AspNetCore.HttpLogging;

namespace HttpLogging.Sample;

internal sealed class SampleHttpLoggingInterceptor : IHttpLoggingInterceptor
{
public ValueTask OnRequestAsync(HttpLoggingInterceptorContext logContext)
{
// Compare to ExcludePathStartsWith
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need to reference ExcludePathStartsWith here? I don't think that folks reviewing this sample should take into account https://github.com/dotnet/extensions/blob/a387e38dc927035db5492b47e9607867da7d5005/src/Libraries/Microsoft.AspNetCore.Telemetry.Middleware/Logging/LoggingOptions.cs#L216

Copy link
Contributor

@xakep139 xakep139 Aug 25, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I presume this sample targets external audience that might not be aware of dotnet/extensions

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These samples are for our own usage. I have this one currently set up to mimic what we want to accomplish in extensions. I may clean out some of the references before merging.

if (!logContext.HttpContext.Request.Path.StartsWithSegments("/api"))
{
logContext.LoggingFields = HttpLoggingFields.None;
}

// Don't enrich if we're not going to log any part of the request
if (!logContext.IsAnyEnabled(HttpLoggingFields.Request))
{
return default;
}

if (logContext.TryDisable(HttpLoggingFields.RequestPath))
{
RedactPath(logContext);
}

if (logContext.TryDisable(HttpLoggingFields.RequestHeaders))
{
RedactRequestHeaders(logContext);
}

EnrichRequest(logContext);

return default;
}

private void RedactRequestHeaders(HttpLoggingInterceptorContext logContext)
{
foreach (var header in logContext.HttpContext.Request.Headers)
{
logContext.AddParameter(header.Key, "RedactedHeader"); // TODO: Redact header value
}
}

private void RedactResponseHeaders(HttpLoggingInterceptorContext logContext)
{
foreach (var header in logContext.HttpContext.Response.Headers)
{
logContext.AddParameter(header.Key, "RedactedHeader"); // TODO: Redact header value
}
}

public ValueTask OnResponseAsync(HttpLoggingInterceptorContext logContext)
{
// Don't enrich if we're not going to log any part of the response
if (!logContext.IsAnyEnabled(HttpLoggingFields.Response))
{
return default;
}

if (logContext.TryDisable(HttpLoggingFields.ResponseHeaders))
{
RedactResponseHeaders(logContext);
}

EnrichResponse(logContext);

return default;
}

private void EnrichResponse(HttpLoggingInterceptorContext logContext)
{
logContext.AddParameter("ResponseEnrichment", "Stuff");
}

private void EnrichRequest(HttpLoggingInterceptorContext logContext)
{
logContext.AddParameter("RequestEnrichment", "Stuff");
}

private void RedactPath(HttpLoggingInterceptorContext logContext)
{
logContext.AddParameter(nameof(logContext.HttpContext.Request.Path), "RedactedPath");
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@ public void ConfigureServices(IServiceCollection services)
{
logging.LoggingFields = HttpLoggingFields.All;
});
services.AddHttpLoggingInterceptor<SampleHttpLoggingInterceptor>();
}

// This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
Expand Down
24 changes: 2 additions & 22 deletions src/Middleware/HttpLogging/src/BufferingStream.cs
Original file line number Diff line number Diff line change
Expand Up @@ -47,7 +47,7 @@ public override int WriteTimeout
set => _innerStream.WriteTimeout = value;
}

public string GetString(Encoding? encoding)
public string GetString(Encoding encoding)
{
try
{
Expand All @@ -57,13 +57,6 @@ public string GetString(Encoding? encoding)
return "";
}

if (encoding == null)
{
// This method is used only for the response body
_logger.UnrecognizedMediaType("response");
return "";
}

// Only place where we are actually using the buffered data.
// update tail here.
_tail.End = _tailBytesBuffered;
Expand Down Expand Up @@ -295,15 +288,7 @@ public override void EndWrite(IAsyncResult asyncResult)
_innerStream.EndWrite(asyncResult);
}

public override void CopyTo(Stream destination, int bufferSize)
{
_innerStream.CopyTo(destination, bufferSize);
}

public override Task CopyToAsync(Stream destination, int bufferSize, CancellationToken cancellationToken)
{
return _innerStream.CopyToAsync(destination, bufferSize, cancellationToken);
}
// Do not override CopyTo/Async, they call Read/Async internally.

public override ValueTask<int> ReadAsync(Memory<byte> buffer, CancellationToken cancellationToken = default)
{
Expand All @@ -314,9 +299,4 @@ public override ValueTask DisposeAsync()
{
return _innerStream.DisposeAsync();
}

public override int Read(Span<byte> buffer)
{
return _innerStream.Read(buffer);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -6,16 +6,18 @@

namespace Microsoft.AspNetCore.HttpLogging;

internal sealed class HttpRequestLog : IReadOnlyList<KeyValuePair<string, object?>>
internal sealed class HttpLog : IReadOnlyList<KeyValuePair<string, object?>>
{
private readonly List<KeyValuePair<string, object?>> _keyValues;
private readonly string _title;
private string? _cachedToString;

internal static readonly Func<object, Exception?, string> Callback = (state, exception) => ((HttpRequestLog)state).ToString();
internal static readonly Func<object, Exception?, string> Callback = (state, exception) => ((HttpLog)state).ToString();

public HttpRequestLog(List<KeyValuePair<string, object?>> keyValues)
public HttpLog(List<KeyValuePair<string, object?>> keyValues, string title)
{
_keyValues = keyValues;
_title = title;
Tratcher marked this conversation as resolved.
Show resolved Hide resolved
}

public KeyValuePair<string, object?> this[int index] => _keyValues[index];
Expand All @@ -35,10 +37,11 @@ public override string ToString()
{
if (_cachedToString == null)
{
// Use 2kb as a rough average size for request headers
// Use 2kb as a rough average size for request/response headers
var builder = new ValueStringBuilder(2 * 1024);
var count = _keyValues.Count;
builder.Append("Request:");
builder.Append(_title);
builder.Append(':');
builder.Append(Environment.NewLine);

for (var i = 0; i < count - 1; i++)
Expand Down
22 changes: 16 additions & 6 deletions src/Middleware/HttpLogging/src/HttpLoggingExtensions.cs
Original file line number Diff line number Diff line change
Expand Up @@ -7,21 +7,21 @@ namespace Microsoft.AspNetCore.HttpLogging;

internal static partial class HttpLoggingExtensions
{
public static void RequestLog(this ILogger logger, HttpRequestLog requestLog) => logger.Log(
public static void RequestLog(this ILogger logger, HttpLog requestLog) => logger.Log(
LogLevel.Information,
new EventId(1, "RequestLog"),
requestLog,
exception: null,
formatter: HttpRequestLog.Callback);
public static void ResponseLog(this ILogger logger, HttpResponseLog responseLog) => logger.Log(
formatter: HttpLog.Callback);
public static void ResponseLog(this ILogger logger, HttpLog responseLog) => logger.Log(
LogLevel.Information,
new EventId(2, "ResponseLog"),
responseLog,
exception: null,
formatter: HttpResponseLog.Callback);
formatter: HttpLog.Callback);

[LoggerMessage(3, LogLevel.Information, "RequestBody: {Body}", EventName = "RequestBody")]
public static partial void RequestBody(this ILogger logger, string body);
[LoggerMessage(3, LogLevel.Information, "RequestBody: {Body}{Status}", EventName = "RequestBody")]
public static partial void RequestBody(this ILogger logger, string body, string status);

[LoggerMessage(4, LogLevel.Information, "ResponseBody: {Body}", EventName = "ResponseBody")]
public static partial void ResponseBody(this ILogger logger, string body);
Expand All @@ -34,4 +34,14 @@ public static void ResponseLog(this ILogger logger, HttpResponseLog responseLog)

[LoggerMessage(7, LogLevel.Debug, "No Content-Type header for {Name} body.", EventName = "NoMediaType")]
public static partial void NoMediaType(this ILogger logger, string name);

[LoggerMessage(8, LogLevel.Information, "Duration: {Duration}ms", EventName = "Duration")]
public static partial void Duration(this ILogger logger, double duration);

public static void RequestResponseLog(this ILogger logger, HttpLog log) => logger.Log(
LogLevel.Information,
new EventId(9, "RequestResponseLog"),
log,
exception: null,
formatter: HttpLog.Callback);
}
13 changes: 9 additions & 4 deletions src/Middleware/HttpLogging/src/HttpLoggingFields.cs
Original file line number Diff line number Diff line change
Expand Up @@ -135,6 +135,11 @@ public enum HttpLoggingFields : long
/// </summary>
ResponseBody = 0x800,

/// <summary>
/// Flag for logging how long it took to process the request and response in milliseconds.
/// </summary>
Duration = 0x1000,

/// <summary>
/// Flag for logging a collection of HTTP Request properties,
/// including <see cref="RequestPath"/>, <see cref="RequestProtocol"/>,
Expand All @@ -158,7 +163,7 @@ public enum HttpLoggingFields : long

/// <summary>
/// Flag for logging HTTP Response properties and headers.
/// Includes <see cref="ResponseStatusCode"/> and <see cref="ResponseHeaders"/>
/// Includes <see cref="ResponseStatusCode"/> and <see cref="ResponseHeaders"/>.
/// </summary>
ResponsePropertiesAndHeaders = ResponseStatusCode | ResponseHeaders,

Expand All @@ -180,11 +185,11 @@ public enum HttpLoggingFields : long
/// Logging the response body has performance implications, as it requires buffering
/// the entire response body up to <see cref="HttpLoggingOptions.ResponseBodyLogLimit"/>.
/// </summary>
Response = ResponseStatusCode | ResponseHeaders | ResponseBody,
Response = ResponsePropertiesAndHeaders | ResponseBody,

/// <summary>
/// Flag for logging both the HTTP Request and Response.
/// Includes <see cref="Request"/> and <see cref="Response"/>.
/// Includes <see cref="Request"/>, <see cref="Response"/>, and <see cref="Duration"/>.
/// Logging the request and response body has performance implications, as it requires buffering
/// the entire request and response body up to the <see cref="HttpLoggingOptions.RequestBodyLogLimit"/>
/// and <see cref="HttpLoggingOptions.ResponseBodyLogLimit"/>.
Expand All @@ -193,5 +198,5 @@ public enum HttpLoggingFields : long
/// The HTTP Request <see cref="HttpRequest.QueryString"/> is not included with this flag as it may contain private information.
/// If desired, it should be explicitly specified with <see cref="RequestQuery"/>.
/// </remarks>
All = Request | Response
All = Request | Response | Duration
}
Loading