diff --git a/src/Middleware/HttpLogging/samples/HttpLogging.Sample/SampleHttpLoggingInterceptor.cs b/src/Middleware/HttpLogging/samples/HttpLogging.Sample/SampleHttpLoggingInterceptor.cs new file mode 100644 index 000000000000..b14f656ac215 --- /dev/null +++ b/src/Middleware/HttpLogging/samples/HttpLogging.Sample/SampleHttpLoggingInterceptor.cs @@ -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 + 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"); + } +} diff --git a/src/Middleware/HttpLogging/samples/HttpLogging.Sample/Startup.cs b/src/Middleware/HttpLogging/samples/HttpLogging.Sample/Startup.cs index 59af7f6312c4..e3afaca2208b 100644 --- a/src/Middleware/HttpLogging/samples/HttpLogging.Sample/Startup.cs +++ b/src/Middleware/HttpLogging/samples/HttpLogging.Sample/Startup.cs @@ -15,6 +15,7 @@ public void ConfigureServices(IServiceCollection services) { logging.LoggingFields = HttpLoggingFields.All; }); + services.AddHttpLoggingInterceptor(); } // This method gets called by the runtime. Use this method to configure the HTTP request pipeline. diff --git a/src/Middleware/HttpLogging/src/BufferingStream.cs b/src/Middleware/HttpLogging/src/BufferingStream.cs index 53fa1c8cbfa1..f015e11a73b4 100644 --- a/src/Middleware/HttpLogging/src/BufferingStream.cs +++ b/src/Middleware/HttpLogging/src/BufferingStream.cs @@ -47,7 +47,7 @@ public override int WriteTimeout set => _innerStream.WriteTimeout = value; } - public string GetString(Encoding? encoding) + public string GetString(Encoding encoding) { try { @@ -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; @@ -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 ReadAsync(Memory buffer, CancellationToken cancellationToken = default) { @@ -314,9 +299,4 @@ public override ValueTask DisposeAsync() { return _innerStream.DisposeAsync(); } - - public override int Read(Span buffer) - { - return _innerStream.Read(buffer); - } } diff --git a/src/Middleware/HttpLogging/src/HttpRequestLog.cs b/src/Middleware/HttpLogging/src/HttpLog.cs similarity index 80% rename from src/Middleware/HttpLogging/src/HttpRequestLog.cs rename to src/Middleware/HttpLogging/src/HttpLog.cs index 9b744e577480..c0da7f7e84c9 100644 --- a/src/Middleware/HttpLogging/src/HttpRequestLog.cs +++ b/src/Middleware/HttpLogging/src/HttpLog.cs @@ -6,16 +6,18 @@ namespace Microsoft.AspNetCore.HttpLogging; -internal sealed class HttpRequestLog : IReadOnlyList> +internal sealed class HttpLog : IReadOnlyList> { private readonly List> _keyValues; + private readonly string _title; private string? _cachedToString; - internal static readonly Func Callback = (state, exception) => ((HttpRequestLog)state).ToString(); + internal static readonly Func Callback = (state, exception) => ((HttpLog)state).ToString(); - public HttpRequestLog(List> keyValues) + public HttpLog(List> keyValues, string title) { _keyValues = keyValues; + _title = title; } public KeyValuePair this[int index] => _keyValues[index]; @@ -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++) diff --git a/src/Middleware/HttpLogging/src/HttpLoggingExtensions.cs b/src/Middleware/HttpLogging/src/HttpLoggingExtensions.cs index a5f04101c3c2..f545abe0ab82 100644 --- a/src/Middleware/HttpLogging/src/HttpLoggingExtensions.cs +++ b/src/Middleware/HttpLogging/src/HttpLoggingExtensions.cs @@ -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); @@ -34,4 +34,14 @@ internal static partial class HttpLoggingExtensions [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); } diff --git a/src/Middleware/HttpLogging/src/HttpLoggingFields.cs b/src/Middleware/HttpLogging/src/HttpLoggingFields.cs index cd81fd647389..41dd6ee7025a 100644 --- a/src/Middleware/HttpLogging/src/HttpLoggingFields.cs +++ b/src/Middleware/HttpLogging/src/HttpLoggingFields.cs @@ -135,6 +135,11 @@ public enum HttpLoggingFields : long /// ResponseBody = 0x800, + /// + /// Flag for logging how long it took to process the request and response in milliseconds. + /// + Duration = 0x1000, + /// /// Flag for logging a collection of HTTP Request properties, /// including , , @@ -158,7 +163,7 @@ public enum HttpLoggingFields : long /// /// Flag for logging HTTP Response properties and headers. - /// Includes and + /// Includes and . /// ResponsePropertiesAndHeaders = ResponseStatusCode | ResponseHeaders, @@ -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 . /// - Response = ResponseStatusCode | ResponseHeaders | ResponseBody, + Response = ResponsePropertiesAndHeaders | ResponseBody, /// /// Flag for logging both the HTTP Request and Response. - /// Includes and . + /// Includes , , and . /// Logging the request and response body has performance implications, as it requires buffering /// the entire request and response body up to the /// and . @@ -193,5 +198,5 @@ public enum HttpLoggingFields : long /// The HTTP Request is not included with this flag as it may contain private information. /// If desired, it should be explicitly specified with . /// - All = Request | Response + All = Request | Response | Duration } diff --git a/src/Middleware/HttpLogging/src/HttpLoggingInterceptorContext.cs b/src/Middleware/HttpLogging/src/HttpLoggingInterceptorContext.cs new file mode 100644 index 000000000000..5416f5eac723 --- /dev/null +++ b/src/Middleware/HttpLogging/src/HttpLoggingInterceptorContext.cs @@ -0,0 +1,152 @@ +// 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.Builder; +using Microsoft.AspNetCore.Http; + +namespace Microsoft.AspNetCore.HttpLogging; + +/// +/// The context used for . +/// +/// +/// Settings will be pre-initialized with the relevant values from and updated with endpoint specific +/// values from or +/// . +/// All settings can be modified per request. All settings will carry over from +/// +/// to except the +/// which are cleared after logging the request. +/// +public sealed class HttpLoggingInterceptorContext +{ + private HttpContext? _httpContext; + + /// + /// The request context. + /// + /// + /// This property should not be set by user code except for testing purposes. + /// + public HttpContext HttpContext + { + get => _httpContext ?? throw new InvalidOperationException("HttpContext was not initialized."); + // Public for 3rd party testing of interceptors. + // We'd make this a required constructor/init parameter but ObjectPool requires a parameterless constructor. + set => _httpContext = value ?? throw new ArgumentNullException(nameof(value)); + } + + /// + /// Gets or sets which parts of the request and response to log. + /// + /// + /// This is pre-populated with the value from , + /// , or + /// . + /// + public HttpLoggingFields LoggingFields { get; set; } + + /// + /// Gets or sets the maximum number of bytes of the request body to log. + /// + /// + /// This is pre-populated with the value from , + /// , or + /// . + /// + public int RequestBodyLogLimit { get; set; } + + /// + /// Gets or sets the maximum number of bytes of the response body to log. + /// + /// + /// This is pre-populated with the value from , + /// , or + /// . + /// + public int ResponseBodyLogLimit { get; set; } + + internal long StartTimestamp { get; set; } + internal TimeProvider TimeProvider { get; set; } = null!; + internal List> InternalParameters { get; set; } = new(); + + /// + /// Gets a list of parameters that will be logged as part of the request or response. Values specified in + /// will be added automatically after all interceptors run. All values are cleared after logging the request. + /// All other relevant settings will carry over to the response. + /// + /// + /// If is enabled, the parameters will be logged as part of the combined log. + /// + public IList> Parameters => InternalParameters; + + /// + /// Adds data that will be logged as part of the request or response. See . + /// + /// The parameter name. + /// The parameter value. + public void AddParameter(string key, object? value) + { + InternalParameters.Add(new(key, value)); + } + + /// + /// Adds the given fields to what's currently enabled in . + /// + /// Additional fields to enable. + public void Enable(HttpLoggingFields fields) + { + LoggingFields |= fields; + } + + /// + /// Checks if any of the given fields are currently enabled in . + /// + /// One or more field flags to check. + public bool IsAnyEnabled(HttpLoggingFields fields) + { + return (LoggingFields & fields) != HttpLoggingFields.None; + } + + /// + /// Removes the given fields from what's currently enabled in . + /// + /// Fields to disable. + public void Disable(HttpLoggingFields fields) + { + LoggingFields &= ~fields; + } + + /// + /// Disables the given fields if any are currently enabled in . + /// + /// One or more field flags to disable if present. + /// if any of the fields were previously enabled. + public bool TryDisable(HttpLoggingFields fields) + { + if (IsAnyEnabled(fields)) + { + Disable(fields); + return true; + } + + return false; + } + + internal void Reset() + { + _httpContext = null; + LoggingFields = HttpLoggingFields.None; + RequestBodyLogLimit = 0; + ResponseBodyLogLimit = 0; + StartTimestamp = 0; + TimeProvider = null!; + // Not pooled, the logger may store a reference to this instance. + InternalParameters = new(); + } + + internal double GetDuration() + { + return TimeProvider.GetElapsedTime(StartTimestamp).TotalMilliseconds; + } +} diff --git a/src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs b/src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs index 98fc0afcb56e..476fed3ec4ce 100644 --- a/src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs +++ b/src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs @@ -1,9 +1,11 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System.Linq; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Http.Features; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.ObjectPool; using Microsoft.Extensions.Options; namespace Microsoft.AspNetCore.HttpLogging; @@ -15,26 +17,28 @@ internal sealed class HttpLoggingMiddleware { private readonly RequestDelegate _next; private readonly ILogger _logger; + private readonly ObjectPool _contextPool; + private readonly TimeProvider _timeProvider; + private readonly IHttpLoggingInterceptor[] _interceptors; private readonly IOptionsMonitor _options; - private const int DefaultRequestFieldsMinusHeaders = 7; - private const int DefaultResponseFieldsMinusHeaders = 2; private const string Redacted = "[Redacted]"; - /// - /// Initializes . - /// - /// - /// - /// - public HttpLoggingMiddleware(RequestDelegate next, IOptionsMonitor options, ILogger logger) + public HttpLoggingMiddleware(RequestDelegate next, IOptionsMonitor options, ILogger logger, + IEnumerable interceptors, ObjectPool contextPool, TimeProvider timeProvider) { ArgumentNullException.ThrowIfNull(next); ArgumentNullException.ThrowIfNull(options); ArgumentNullException.ThrowIfNull(logger); + ArgumentNullException.ThrowIfNull(interceptors); + ArgumentNullException.ThrowIfNull(contextPool); + ArgumentNullException.ThrowIfNull(timeProvider); _next = next; _options = options; _logger = logger; + _interceptors = interceptors.ToArray(); + _contextPool = contextPool; + _timeProvider = timeProvider; } /// @@ -50,88 +54,125 @@ public Task Invoke(HttpContext context) return _next(context); } - return InvokeInternal(context); + var options = _options.CurrentValue; + var loggingAttribute = context.GetEndpoint()?.Metadata.GetMetadata(); + var loggingFields = loggingAttribute?.LoggingFields ?? options.LoggingFields; + + if (_interceptors.Length == 0 && loggingFields == HttpLoggingFields.None) + { + // Logging is disabled for this endpoint and there are no interceptors to turn it on. + return _next(context); + } + + return InvokeInternal(context, options, loggingAttribute, loggingFields); } - private async Task InvokeInternal(HttpContext context) + private async Task InvokeInternal(HttpContext context, HttpLoggingOptions options, + HttpLoggingAttribute? loggingAttribute, HttpLoggingFields loggingFields) { - var options = _options.CurrentValue; RequestBufferingStream? requestBufferingStream = null; Stream? originalBody = null; - var loggingAttribute = context.GetEndpoint()?.Metadata.GetMetadata(); - var loggingFields = loggingAttribute?.LoggingFields ?? options.LoggingFields; + var logContext = _contextPool.Get(); + logContext.HttpContext = context; + logContext.LoggingFields = loggingFields; + logContext.RequestBodyLogLimit = options.RequestBodyLogLimit; + logContext.ResponseBodyLogLimit = options.ResponseBodyLogLimit; + logContext.StartTimestamp = _timeProvider.GetTimestamp(); + logContext.TimeProvider = _timeProvider; + + if (loggingAttribute?.IsRequestBodyLogLimitSet is true) + { + logContext.RequestBodyLogLimit = loggingAttribute.RequestBodyLogLimit; + } + if (loggingAttribute?.IsResponseBodyLogLimitSet is true) + { + logContext.ResponseBodyLogLimit = loggingAttribute.ResponseBodyLogLimit; + } - if ((HttpLoggingFields.Request & loggingFields) != HttpLoggingFields.None) + try + { + for (var i = 0; i < _interceptors.Length; i++) + { + await _interceptors[i].OnRequestAsync(logContext); + } + } + catch (Exception) { - var request = context.Request; - var list = new List>( - request.Headers.Count + DefaultRequestFieldsMinusHeaders); + logContext.Reset(); + _contextPool.Return(logContext); + throw; + } + loggingFields = logContext.LoggingFields; + + var request = context.Request; + if (logContext.IsAnyEnabled(HttpLoggingFields.RequestPropertiesAndHeaders)) + { if (loggingFields.HasFlag(HttpLoggingFields.RequestProtocol)) { - AddToList(list, nameof(request.Protocol), request.Protocol); + logContext.AddParameter(nameof(request.Protocol), request.Protocol); } if (loggingFields.HasFlag(HttpLoggingFields.RequestMethod)) { - AddToList(list, nameof(request.Method), request.Method); + logContext.AddParameter(nameof(request.Method), request.Method); } if (loggingFields.HasFlag(HttpLoggingFields.RequestScheme)) { - AddToList(list, nameof(request.Scheme), request.Scheme); + logContext.AddParameter(nameof(request.Scheme), request.Scheme); } if (loggingFields.HasFlag(HttpLoggingFields.RequestPath)) { - AddToList(list, nameof(request.PathBase), request.PathBase); - AddToList(list, nameof(request.Path), request.Path); + logContext.AddParameter(nameof(request.PathBase), request.PathBase); + logContext.AddParameter(nameof(request.Path), request.Path); } if (loggingFields.HasFlag(HttpLoggingFields.RequestQuery)) { - AddToList(list, nameof(request.QueryString), request.QueryString.Value); + logContext.AddParameter(nameof(request.QueryString), request.QueryString.Value); } if (loggingFields.HasFlag(HttpLoggingFields.RequestHeaders)) { - FilterHeaders(list, request.Headers, options._internalRequestHeaders); + FilterHeaders(logContext, request.Headers, options._internalRequestHeaders); } - if (loggingFields.HasFlag(HttpLoggingFields.RequestBody)) + if (logContext.InternalParameters.Count > 0 && !options.CombineLogs) { - if (request.ContentType is null) - { - _logger.NoMediaType("request"); - } - else if (MediaTypeHelpers.TryGetEncodingForMediaType(request.ContentType, - options.MediaTypeOptions.MediaTypeStates, - out var encoding)) - { - var requestBodyLogLimit = options.RequestBodyLogLimit; - if (loggingAttribute?.IsRequestBodyLogLimitSet is true) - { - requestBodyLogLimit = loggingAttribute.RequestBodyLogLimit; - } + var httpRequestLog = new HttpLog(logContext.InternalParameters, "Request"); - originalBody = request.Body; - requestBufferingStream = new RequestBufferingStream( - request.Body, - requestBodyLogLimit, - _logger, - encoding); - request.Body = requestBufferingStream; - } - else - { - _logger.UnrecognizedMediaType("request"); - } - } + _logger.RequestLog(httpRequestLog); - var httpRequestLog = new HttpRequestLog(list); + logContext.InternalParameters = new(); + } + } - _logger.RequestLog(httpRequestLog); + if (loggingFields.HasFlag(HttpLoggingFields.RequestBody)) + { + if (request.ContentType is null) + { + _logger.NoMediaType("request"); + } + else if (MediaTypeHelpers.TryGetEncodingForMediaType(request.ContentType, + options.MediaTypeOptions.MediaTypeStates, + out var encoding)) + { + originalBody = request.Body; + requestBufferingStream = new RequestBufferingStream( + request.Body, + logContext.RequestBodyLogLimit, + _logger, + encoding, + !options.CombineLogs); + request.Body = requestBufferingStream; + } + else + { + _logger.UnrecognizedMediaType("request"); + } } ResponseBufferingStream? responseBufferingStream = null; @@ -144,61 +185,81 @@ private async Task InvokeInternal(HttpContext context) { var response = context.Response; - if (loggingFields.HasFlag(HttpLoggingFields.ResponseStatusCode) || loggingFields.HasFlag(HttpLoggingFields.ResponseHeaders)) + if (logContext.IsAnyEnabled(HttpLoggingFields.ResponsePropertiesAndHeaders)) { originalUpgradeFeature = context.Features.Get(); if (originalUpgradeFeature != null && originalUpgradeFeature.IsUpgradableRequest) { - loggableUpgradeFeature = new UpgradeFeatureLoggingDecorator(originalUpgradeFeature, response, options._internalResponseHeaders, loggingFields, _logger); + loggableUpgradeFeature = new UpgradeFeatureLoggingDecorator(originalUpgradeFeature, + logContext, options, _interceptors, _logger); context.Features.Set(loggableUpgradeFeature); } } - if (loggingFields.HasFlag(HttpLoggingFields.ResponseBody)) + // Hook the response body when there are interceptors in case they want to conditionally log the body. + if (loggingFields.HasFlag(HttpLoggingFields.ResponseBody) || _interceptors.Length > 0) { originalBodyFeature = context.Features.Get()!; - var responseBodyLogLimit = options.ResponseBodyLogLimit; - if (loggingAttribute?.IsRequestBodyLogLimitSet is true) - { - responseBodyLogLimit = loggingAttribute.ResponseBodyLogLimit; - } - // TODO pool these. responseBufferingStream = new ResponseBufferingStream(originalBodyFeature, - responseBodyLogLimit, - _logger, - context, - options.MediaTypeOptions.MediaTypeStates, - options._internalResponseHeaders, - loggingFields); + _logger, logContext, options, _interceptors); response.Body = responseBufferingStream; context.Features.Set(responseBufferingStream); } - await _next(context); - - if (requestBufferingStream?.HasLogged == false) + try { - // If the middleware pipeline didn't read until 0 was returned from readasync, - // make sure we log the request body. - requestBufferingStream.LogRequestBody(); + await _next(context); } - - if (ResponseHeadersNotYetWritten(responseBufferingStream, loggableUpgradeFeature)) + finally { - // No body, not an upgradable request or request not upgraded, write headers here. - LogResponseHeaders(response, loggingFields, options._internalResponseHeaders, _logger); - } + if (options.CombineLogs) + { + if (ResponseHeadersNotYetWritten(responseBufferingStream, loggableUpgradeFeature)) + { + // No body, not an upgradable request or request not upgraded, write headers here. + await LogResponseHeadersAsync(logContext, options, _interceptors, _logger); + } - if (responseBufferingStream != null) - { - var responseBody = responseBufferingStream.GetString(responseBufferingStream.Encoding); - if (!string.IsNullOrEmpty(responseBody)) + // Now that the interceptors have run, add the request & response body logs (if they're still enabled). + requestBufferingStream?.LogRequestBody(logContext); + responseBufferingStream?.LogResponseBody(logContext); + + if (logContext.IsAnyEnabled(HttpLoggingFields.Duration)) + { + logContext.AddParameter(nameof(HttpLoggingFields.Duration), logContext.GetDuration()); + } + + if (logContext.InternalParameters.Count > 0) + { + var log = new HttpLog(logContext.InternalParameters, "Request and Response"); + _logger.RequestResponseLog(log); + } + } + else { - _logger.ResponseBody(responseBody); + // If the middleware pipeline didn't read until 0 was returned from ReadAsync, + // make sure we log the request body. + requestBufferingStream?.LogRequestBody(); + + if (ResponseHeadersNotYetWritten(responseBufferingStream, loggableUpgradeFeature)) + { + // No body, not an upgradable request or request not upgraded, write headers here. + await LogResponseHeadersAsync(logContext, options, _interceptors, _logger); + } + else + { + // There will only be a response body if the headers were already written. + responseBufferingStream?.LogResponseBody(); + } + + if (logContext.IsAnyEnabled(HttpLoggingFields.Duration)) + { + _logger.Duration(logContext.GetDuration()); + } } } } @@ -222,6 +283,9 @@ private async Task InvokeInternal(HttpContext context) { context.Features.Set(originalUpgradeFeature); } + + logContext.Reset(); + _contextPool.Return(logContext); } } @@ -240,35 +304,50 @@ private static bool NotUpgradeableRequestOrRequestNotUpgraded(UpgradeFeatureLogg return upgradeFeatureLogging == null || !upgradeFeatureLogging.IsUpgraded; } - private static void AddToList(List> list, string key, string? value) + // Called from the response body stream sync Write and Flush APIs. These are disabled by the server by default, so we're not as worried about the sync-over-async code needed here. + public static void LogResponseHeadersSync(HttpLoggingInterceptorContext logContext, HttpLoggingOptions options, IHttpLoggingInterceptor[] interceptors, ILogger logger) { - list.Add(new KeyValuePair(key, value)); + for (var i = 0; i < interceptors.Length; i++) + { + interceptors[i].OnResponseAsync(logContext).AsTask().GetAwaiter().GetResult(); + } + + LogResponseHeadersCore(logContext, options, logger); + } + + public static async ValueTask LogResponseHeadersAsync(HttpLoggingInterceptorContext logContext, HttpLoggingOptions options, IHttpLoggingInterceptor[] interceptors, ILogger logger) + { + for (var i = 0; i < interceptors.Length; i++) + { + await interceptors[i].OnResponseAsync(logContext); + } + + LogResponseHeadersCore(logContext, options, logger); } - public static void LogResponseHeaders(HttpResponse response, HttpLoggingFields loggingFields, HashSet allowedResponseHeaders, ILogger logger) + private static void LogResponseHeadersCore(HttpLoggingInterceptorContext logContext, HttpLoggingOptions options, ILogger logger) { - var list = new List>( - response.Headers.Count + DefaultResponseFieldsMinusHeaders); + var loggingFields = logContext.LoggingFields; + var response = logContext.HttpContext.Response; if (loggingFields.HasFlag(HttpLoggingFields.ResponseStatusCode)) { - list.Add(new KeyValuePair(nameof(response.StatusCode), response.StatusCode)); + logContext.AddParameter(nameof(response.StatusCode), response.StatusCode); } if (loggingFields.HasFlag(HttpLoggingFields.ResponseHeaders)) { - FilterHeaders(list, response.Headers, allowedResponseHeaders); + FilterHeaders(logContext, response.Headers, options._internalResponseHeaders); } - if (list.Count > 0) + if (logContext.InternalParameters.Count > 0 && !options.CombineLogs) { - var httpResponseLog = new HttpResponseLog(list); - + var httpResponseLog = new HttpLog(logContext.InternalParameters, "Response"); logger.ResponseLog(httpResponseLog); } } - internal static void FilterHeaders(List> keyValues, + internal static void FilterHeaders(HttpLoggingInterceptorContext logContext, IHeaderDictionary headers, HashSet allowedHeaders) { @@ -277,10 +356,10 @@ public static void LogResponseHeaders(HttpResponse response, HttpLoggingFields l if (!allowedHeaders.Contains(key)) { // Key is not among the "only listed" headers. - keyValues.Add(new KeyValuePair(key, Redacted)); + logContext.AddParameter(key, Redacted); continue; } - keyValues.Add(new KeyValuePair(key, value.ToString())); + logContext.AddParameter(key, value.ToString()); } } } diff --git a/src/Middleware/HttpLogging/src/HttpLoggingOptions.cs b/src/Middleware/HttpLogging/src/HttpLoggingOptions.cs index bcd5989b427a..298c83bdfd40 100644 --- a/src/Middleware/HttpLogging/src/HttpLoggingOptions.cs +++ b/src/Middleware/HttpLogging/src/HttpLoggingOptions.cs @@ -109,4 +109,10 @@ public sealed class HttpLoggingOptions /// Maximum response body size to log (in bytes). Defaults to 32 KB. /// public int ResponseBodyLogLimit { get; set; } = 32 * 1024; + + /// + /// Gets or sets if the middleware will combine the request, request body, response, response body, + /// and duration logs into a single log entry. The default is . + /// + public bool CombineLogs { get; set; } } diff --git a/src/Middleware/HttpLogging/src/HttpLoggingServicesExtensions.cs b/src/Middleware/HttpLogging/src/HttpLoggingServicesExtensions.cs index 077f8b19c1c4..f84d1f6dc075 100644 --- a/src/Middleware/HttpLogging/src/HttpLoggingServicesExtensions.cs +++ b/src/Middleware/HttpLogging/src/HttpLoggingServicesExtensions.cs @@ -1,7 +1,9 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System.Diagnostics.CodeAnalysis; using Microsoft.AspNetCore.HttpLogging; +using Microsoft.Extensions.DependencyInjection.Extensions; namespace Microsoft.Extensions.DependencyInjection; @@ -15,22 +17,37 @@ public static class HttpLoggingServicesExtensions /// /// The for adding services. /// A delegate to configure the . - /// + /// The original service collection for chaining. public static IServiceCollection AddHttpLogging(this IServiceCollection services, Action configureOptions) { ArgumentNullException.ThrowIfNull(services); ArgumentNullException.ThrowIfNull(configureOptions); + services.TryAddSingleton(ObjectPool.ObjectPool.Create()); + services.TryAddSingleton(TimeProvider.System); services.Configure(configureOptions); return services; } + /// + /// Registers the given type as a in the DI container. + /// + /// A type that implements . + /// The service collection. + /// The original service collection for chaining. + public static IServiceCollection AddHttpLoggingInterceptor<[DynamicallyAccessedMembers(DynamicallyAccessedMemberTypes.PublicConstructors)] T> + (this IServiceCollection services) where T : class, IHttpLoggingInterceptor + { + services.TryAddEnumerable(ServiceDescriptor.Singleton()); + return services; + } + /// /// Adds W3C Logging services. /// /// The for adding services. /// A delegate to configure the . - /// + /// The original service collection for chaining. public static IServiceCollection AddW3CLogging(this IServiceCollection services, Action configureOptions) { ArgumentNullException.ThrowIfNull(services); diff --git a/src/Middleware/HttpLogging/src/HttpResponseLog.cs b/src/Middleware/HttpLogging/src/HttpResponseLog.cs deleted file mode 100644 index 260e27321f0d..000000000000 --- a/src/Middleware/HttpLogging/src/HttpResponseLog.cs +++ /dev/null @@ -1,71 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System.Collections; -using System.Text; - -namespace Microsoft.AspNetCore.HttpLogging; - -internal sealed class HttpResponseLog : IReadOnlyList> -{ - private readonly List> _keyValues; - private string? _cachedToString; - - internal static readonly Func Callback = (state, exception) => ((HttpResponseLog)state).ToString(); - - public HttpResponseLog(List> keyValues) - { - _keyValues = keyValues; - } - - public KeyValuePair this[int index] => _keyValues[index]; - - public int Count => _keyValues.Count; - - public IEnumerator> GetEnumerator() - { - var count = _keyValues.Count; - for (var i = 0; i < count; i++) - { - yield return _keyValues[i]; - } - } - - public override string ToString() - { - if (_cachedToString == null) - { - // Use 2kb as a rough average size for response headers - var builder = new ValueStringBuilder(2 * 1024); - var count = _keyValues.Count; - builder.Append("Response:"); - builder.Append(Environment.NewLine); - - for (var i = 0; i < count - 1; i++) - { - var kvp = _keyValues[i]; - builder.Append(kvp.Key); - builder.Append(": "); - builder.Append(kvp.Value?.ToString()); - builder.Append(Environment.NewLine); - } - - if (count > 0) - { - var kvp = _keyValues[count - 1]; - builder.Append(kvp.Key); - builder.Append(": "); - builder.Append(kvp.Value?.ToString()); - } - - _cachedToString = builder.ToString(); - } - - return _cachedToString; - } - - IEnumerator IEnumerable.GetEnumerator() - { - return GetEnumerator(); - } -} diff --git a/src/Middleware/HttpLogging/src/IHttpLoggingInterceptor.cs b/src/Middleware/HttpLogging/src/IHttpLoggingInterceptor.cs new file mode 100644 index 000000000000..cb268412920e --- /dev/null +++ b/src/Middleware/HttpLogging/src/IHttpLoggingInterceptor.cs @@ -0,0 +1,37 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.AspNetCore.HttpLogging; + +/// +/// Callbacks used to extend the HttpLogging middleware. +/// +public interface IHttpLoggingInterceptor +{ + /// + /// A callback to customize the logging of the request and response. + /// + /// + /// This is called when the request is first received and can be used to configure both request and response options. All settings will carry over to + /// except the + /// will be cleared after logging the request. may be changed per request to control the logging behavior. + /// If no request fields are enabled, and the collection is empty, no request logging will occur. + /// If is enabled then will carry over from the request to response + /// and be logged together. + /// + ValueTask OnRequestAsync(HttpLoggingInterceptorContext logContext); + + /// + /// A callback to customize the logging of the response. + /// + /// + /// This is called when the first write to the response happens, or the response ends without a write, just before anything is sent to the client. Settings are carried + /// over from (except the ) and response settings may + /// still be modified. Changes to request settings will have no effect. If no response fields are enabled, and the + /// collection is empty, no response logging will occur. + /// If is enabled then will carry over from the request to response + /// and be logged together. and can also be disabled in OnResponseAsync to prevent + /// logging any buffered body data. + /// + ValueTask OnResponseAsync(HttpLoggingInterceptorContext logContext); +} diff --git a/src/Middleware/HttpLogging/src/MediaTypeHelpers.cs b/src/Middleware/HttpLogging/src/MediaTypeHelpers.cs index 40abc67afaa2..656d264b3eea 100644 --- a/src/Middleware/HttpLogging/src/MediaTypeHelpers.cs +++ b/src/Middleware/HttpLogging/src/MediaTypeHelpers.cs @@ -18,6 +18,7 @@ internal static class MediaTypeHelpers Encoding.Latin1 // TODO allowed by default? Make this configurable? }; + // TODO Binary format https://github.com/dotnet/aspnetcore/issues/31884 public static bool TryGetEncodingForMediaType(string? contentType, List mediaTypeList, [NotNullWhen(true)] out Encoding? encoding) { encoding = null; @@ -31,16 +32,23 @@ public static bool TryGetEncodingForMediaType(string? contentType, List + diff --git a/src/Middleware/HttpLogging/src/PublicAPI.Unshipped.txt b/src/Middleware/HttpLogging/src/PublicAPI.Unshipped.txt index d0353a9d828e..a91169f56fbb 100644 --- a/src/Middleware/HttpLogging/src/PublicAPI.Unshipped.txt +++ b/src/Middleware/HttpLogging/src/PublicAPI.Unshipped.txt @@ -9,4 +9,29 @@ Microsoft.AspNetCore.HttpLogging.HttpLoggingAttribute.RequestBodyLogLimit.get -> Microsoft.AspNetCore.HttpLogging.HttpLoggingAttribute.RequestBodyLogLimit.set -> void Microsoft.AspNetCore.HttpLogging.HttpLoggingAttribute.ResponseBodyLogLimit.get -> int Microsoft.AspNetCore.HttpLogging.HttpLoggingAttribute.ResponseBodyLogLimit.set -> void +*REMOVED*Microsoft.AspNetCore.HttpLogging.HttpLoggingFields.All = Microsoft.AspNetCore.HttpLogging.HttpLoggingFields.Request | Microsoft.AspNetCore.HttpLogging.HttpLoggingFields.Response -> Microsoft.AspNetCore.HttpLogging.HttpLoggingFields +Microsoft.AspNetCore.HttpLogging.HttpLoggingFields.All = Microsoft.AspNetCore.HttpLogging.HttpLoggingFields.Request | Microsoft.AspNetCore.HttpLogging.HttpLoggingFields.Response | Microsoft.AspNetCore.HttpLogging.HttpLoggingFields.Duration -> Microsoft.AspNetCore.HttpLogging.HttpLoggingFields +Microsoft.AspNetCore.HttpLogging.HttpLoggingFields.Duration = 4096 -> Microsoft.AspNetCore.HttpLogging.HttpLoggingFields +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.AddParameter(string! key, object? value) -> void +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.Disable(Microsoft.AspNetCore.HttpLogging.HttpLoggingFields fields) -> void +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.Enable(Microsoft.AspNetCore.HttpLogging.HttpLoggingFields fields) -> void +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.HttpContext.get -> Microsoft.AspNetCore.Http.HttpContext! +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.HttpContext.set -> void +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.HttpLoggingInterceptorContext() -> void +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.IsAnyEnabled(Microsoft.AspNetCore.HttpLogging.HttpLoggingFields fields) -> bool +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.LoggingFields.get -> Microsoft.AspNetCore.HttpLogging.HttpLoggingFields +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.LoggingFields.set -> void +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.Parameters.get -> System.Collections.Generic.IList>! +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.RequestBodyLogLimit.get -> int +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.RequestBodyLogLimit.set -> void +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.ResponseBodyLogLimit.get -> int +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.ResponseBodyLogLimit.set -> void +Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext.TryDisable(Microsoft.AspNetCore.HttpLogging.HttpLoggingFields fields) -> bool +Microsoft.AspNetCore.HttpLogging.HttpLoggingOptions.CombineLogs.get -> bool +Microsoft.AspNetCore.HttpLogging.HttpLoggingOptions.CombineLogs.set -> void +Microsoft.AspNetCore.HttpLogging.IHttpLoggingInterceptor +Microsoft.AspNetCore.HttpLogging.IHttpLoggingInterceptor.OnRequestAsync(Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext! logContext) -> System.Threading.Tasks.ValueTask +Microsoft.AspNetCore.HttpLogging.IHttpLoggingInterceptor.OnResponseAsync(Microsoft.AspNetCore.HttpLogging.HttpLoggingInterceptorContext! logContext) -> System.Threading.Tasks.ValueTask static Microsoft.AspNetCore.Builder.HttpLoggingEndpointConventionBuilderExtensions.WithHttpLogging(this TBuilder builder, Microsoft.AspNetCore.HttpLogging.HttpLoggingFields loggingFields, int? requestBodyLogLimit = null, int? responseBodyLogLimit = null) -> TBuilder +static Microsoft.Extensions.DependencyInjection.HttpLoggingServicesExtensions.AddHttpLoggingInterceptor(this Microsoft.Extensions.DependencyInjection.IServiceCollection! services) -> Microsoft.Extensions.DependencyInjection.IServiceCollection! diff --git a/src/Middleware/HttpLogging/src/RequestBufferingStream.cs b/src/Middleware/HttpLogging/src/RequestBufferingStream.cs index d39415b1304e..d981cba8d5ce 100644 --- a/src/Middleware/HttpLogging/src/RequestBufferingStream.cs +++ b/src/Middleware/HttpLogging/src/RequestBufferingStream.cs @@ -10,17 +10,20 @@ namespace Microsoft.AspNetCore.HttpLogging; internal sealed class RequestBufferingStream : BufferingStream { private readonly Encoding _encoding; + private readonly bool _logOnFinish; private readonly int _limit; + private BodyStatus _status = BodyStatus.None; public bool HasLogged { get; private set; } - public RequestBufferingStream(Stream innerStream, int limit, ILogger logger, Encoding encoding) + public RequestBufferingStream(Stream innerStream, int limit, ILogger logger, Encoding encoding, bool logOnFinish) : base(innerStream, logger) { _logger = logger; _limit = limit; _innerStream = innerStream; _encoding = encoding; + _logOnFinish = logOnFinish; } public override async ValueTask ReadAsync(Memory destination, CancellationToken cancellationToken = default) @@ -73,18 +76,21 @@ private void WriteToBuffer(ReadOnlySpan span) // get what was read into the buffer var remaining = _limit - _bytesBuffered; - if (remaining == 0) + if (remaining == 0 || _status > BodyStatus.Incomplete) { return; } - if (span.Length == 0 && !HasLogged) + if (span.Length == 0) { // Done reading, log the string. + _status = BodyStatus.Complete; LogRequestBody(); return; } + _status = BodyStatus.Incomplete; + var innerCount = Math.Min(remaining, span.Length); if (span.Slice(0, innerCount).TryCopyTo(_tailMemory.Span)) @@ -98,22 +104,40 @@ private void WriteToBuffer(ReadOnlySpan span) BuffersExtensions.Write(this, span.Slice(0, innerCount)); } - if (_limit - _bytesBuffered == 0 && !HasLogged) + if (_limit - _bytesBuffered == 0) { + _status = BodyStatus.Truncated; LogRequestBody(); } } public void LogRequestBody() { - var requestBody = GetString(_encoding); - if (requestBody != null) + if (!HasLogged && _logOnFinish) + { + HasLogged = true; + _logger.RequestBody(GetString(_encoding), GetStatus(showCompleted: false)); + } + } + + public void LogRequestBody(HttpLoggingInterceptorContext logContext) + { + if (logContext.IsAnyEnabled(HttpLoggingFields.RequestBody)) { - _logger.RequestBody(requestBody); + logContext.AddParameter("RequestBody", GetString(_encoding)); + logContext.AddParameter("RequestBodyStatus", GetStatus(showCompleted: true)); } - HasLogged = true; } + private string GetStatus(bool showCompleted) => _status switch + { + BodyStatus.None => "[Not consumed by app]", + BodyStatus.Incomplete => "[Only partially consumed by app]", + BodyStatus.Complete => showCompleted ? "[Completed]" : "", + BodyStatus.Truncated => "[Truncated by RequestBodyLogLimit]", + _ => throw new NotImplementedException(_status.ToString()), + }; + public override IAsyncResult BeginRead(byte[] buffer, int offset, int count, AsyncCallback? callback, object? state) { return TaskToApm.Begin(ReadAsync(buffer, offset, count), callback, state); @@ -123,4 +147,27 @@ public override int EndRead(IAsyncResult asyncResult) { return TaskToApm.End(asyncResult); } + + private enum BodyStatus + { + /// + /// The body was not read. + /// + None, + + /// + /// The body was partially read. + /// + Incomplete, + + /// + /// The body was completely read. + /// + Complete, + + /// + /// The body was read and truncated. + /// + Truncated, + } } diff --git a/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs b/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs index 628801dfe77d..3a9baa9272c6 100644 --- a/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs +++ b/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs @@ -4,46 +4,37 @@ using System.Buffers; using System.IO.Pipelines; using System.Text; -using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Http.Features; using Microsoft.Extensions.Logging; -using static Microsoft.AspNetCore.HttpLogging.MediaTypeOptions; namespace Microsoft.AspNetCore.HttpLogging; -/// -/// Stream that buffers reads -/// internal sealed class ResponseBufferingStream : BufferingStream, IHttpResponseBodyFeature { private readonly IHttpResponseBodyFeature _innerBodyFeature; - private readonly int _limit; + private int _limit; private PipeWriter? _pipeAdapter; - private readonly HttpContext _context; - private readonly List _encodings; - private readonly HashSet _allowedResponseHeaders; - private readonly HttpLoggingFields _loggingFields; + private readonly HttpLoggingInterceptorContext _logContext; + private readonly HttpLoggingOptions _options; + private readonly IHttpLoggingInterceptor[] _interceptors; + private bool _logBody; private Encoding? _encoding; private static readonly StreamPipeWriterOptions _pipeWriterOptions = new StreamPipeWriterOptions(leaveOpen: true); internal ResponseBufferingStream(IHttpResponseBodyFeature innerBodyFeature, - int limit, ILogger logger, - HttpContext context, - List encodings, - HashSet allowedResponseHeaders, - HttpLoggingFields loggingFields) + HttpLoggingInterceptorContext logContext, + HttpLoggingOptions options, + IHttpLoggingInterceptor[] interceptors) : base(innerBodyFeature.Stream, logger) { _innerBodyFeature = innerBodyFeature; _innerStream = innerBodyFeature.Stream; - _limit = limit; - _context = context; - _encodings = encodings; - _allowedResponseHeaders = allowedResponseHeaders; - _loggingFields = loggingFields; + _logContext = logContext; + _options = options; + _interceptors = interceptors; } public bool HeadersWritten { get; private set; } @@ -52,8 +43,6 @@ internal sealed class ResponseBufferingStream : BufferingStream, IHttpResponseBo public PipeWriter Writer => _pipeAdapter ??= PipeWriter.Create(Stream, _pipeWriterOptions); - public Encoding? Encoding { get => _encoding; } - public override void Write(byte[] buffer, int offset, int count) { Write(buffer.AsSpan(offset, count)); @@ -71,6 +60,7 @@ public override void EndWrite(IAsyncResult asyncResult) public override void Write(ReadOnlySpan span) { + OnFirstWriteSync(); CommonWrite(span); _innerStream.Write(span); @@ -83,6 +73,7 @@ public override async Task WriteAsync(byte[] buffer, int offset, int count, Canc public override async ValueTask WriteAsync(ReadOnlyMemory buffer, CancellationToken cancellationToken = default) { + await OnFirstWriteAsync(); CommonWrite(buffer.Span); await _innerStream.WriteAsync(buffer, cancellationToken); @@ -93,9 +84,7 @@ private void CommonWrite(ReadOnlySpan span) var remaining = _limit - _bytesBuffered; var innerCount = Math.Min(remaining, span.Length); - OnFirstWrite(); - - if (innerCount > 0) + if (_logBody && innerCount > 0) { var slice = span.Slice(0, innerCount); if (slice.TryCopyTo(_tailMemory.Span)) @@ -111,49 +100,95 @@ private void CommonWrite(ReadOnlySpan span) } } - private void OnFirstWrite() + private void OnFirstWriteSync() { if (!HeadersWritten) { // Log headers as first write occurs (headers locked now) - HttpLoggingMiddleware.LogResponseHeaders(_context.Response, _loggingFields, _allowedResponseHeaders, _logger); + HttpLoggingMiddleware.LogResponseHeadersSync(_logContext, _options, _interceptors, _logger); + OnFirstWriteCore(); + } + } - MediaTypeHelpers.TryGetEncodingForMediaType(_context.Response.ContentType, _encodings, out _encoding); - HeadersWritten = true; + private async ValueTask OnFirstWriteAsync() + { + if (!HeadersWritten) + { + // Log headers as first write occurs (headers locked now) + await HttpLoggingMiddleware.LogResponseHeadersAsync(_logContext, _options, _interceptors, _logger); + OnFirstWriteCore(); } } + private void OnFirstWriteCore() + { + // The callback in LogResponseHeaders could disable body logging or adjust limits. + if (_logContext.LoggingFields.HasFlag(HttpLoggingFields.ResponseBody) && _logContext.ResponseBodyLogLimit > 0) + { + if (MediaTypeHelpers.TryGetEncodingForMediaType(_logContext.HttpContext.Response.ContentType, + _options.MediaTypeOptions.MediaTypeStates, out _encoding)) + { + _logBody = true; + _limit = _logContext.ResponseBodyLogLimit; + } + else + { + _logger.UnrecognizedMediaType("response"); + } + } + + HeadersWritten = true; + } + public void DisableBuffering() { _innerBodyFeature.DisableBuffering(); } - public Task SendFileAsync(string path, long offset, long? count, CancellationToken cancellation) + public async Task SendFileAsync(string path, long offset, long? count, CancellationToken cancellation) { - OnFirstWrite(); - return _innerBodyFeature.SendFileAsync(path, offset, count, cancellation); + await OnFirstWriteAsync(); + await _innerBodyFeature.SendFileAsync(path, offset, count, cancellation); } - public Task StartAsync(CancellationToken token = default) + public async Task StartAsync(CancellationToken token = default) { - OnFirstWrite(); - return _innerBodyFeature.StartAsync(token); + await OnFirstWriteAsync(); + await _innerBodyFeature.StartAsync(token); } public async Task CompleteAsync() { + await OnFirstWriteAsync(); await _innerBodyFeature.CompleteAsync(); } public override void Flush() { - OnFirstWrite(); + OnFirstWriteSync(); base.Flush(); } - public override Task FlushAsync(CancellationToken cancellationToken) + public override async Task FlushAsync(CancellationToken cancellationToken) + { + await OnFirstWriteAsync(); + await base.FlushAsync(cancellationToken); + } + + public void LogResponseBody() { - OnFirstWrite(); - return base.FlushAsync(cancellationToken); + if (_logBody) + { + var responseBody = GetString(_encoding!); + _logger.ResponseBody(responseBody); + } + } + + public void LogResponseBody(HttpLoggingInterceptorContext logContext) + { + if (_logBody) + { + logContext.AddParameter("ResponseBody", GetString(_encoding!)); + } } } diff --git a/src/Middleware/HttpLogging/src/UpgradeFeatureLoggingDecorator.cs b/src/Middleware/HttpLogging/src/UpgradeFeatureLoggingDecorator.cs index b1162b77b85b..da0ff2fc3a1d 100644 --- a/src/Middleware/HttpLogging/src/UpgradeFeatureLoggingDecorator.cs +++ b/src/Middleware/HttpLogging/src/UpgradeFeatureLoggingDecorator.cs @@ -1,7 +1,6 @@ // 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.Http; using Microsoft.AspNetCore.Http.Features; using Microsoft.Extensions.Logging; @@ -10,20 +9,21 @@ namespace Microsoft.AspNetCore.HttpLogging; internal sealed class UpgradeFeatureLoggingDecorator : IHttpUpgradeFeature { private readonly IHttpUpgradeFeature _innerUpgradeFeature; - private readonly HttpResponse _response; - private readonly HashSet _allowedResponseHeaders; + private readonly HttpLoggingInterceptorContext _logContext; + private readonly HttpLoggingOptions _options; + private readonly IHttpLoggingInterceptor[] _interceptors; private readonly ILogger _logger; - private readonly HttpLoggingFields _loggingFields; private bool _isUpgraded; - public UpgradeFeatureLoggingDecorator(IHttpUpgradeFeature innerUpgradeFeature, HttpResponse response, HashSet allowedResponseHeaders, HttpLoggingFields loggingFields, ILogger logger) + public UpgradeFeatureLoggingDecorator(IHttpUpgradeFeature innerUpgradeFeature, HttpLoggingInterceptorContext logContext, HttpLoggingOptions options, + IHttpLoggingInterceptor[] interceptors, ILogger logger) { _innerUpgradeFeature = innerUpgradeFeature ?? throw new ArgumentNullException(nameof(innerUpgradeFeature)); - _response = response ?? throw new ArgumentNullException(nameof(response)); - _allowedResponseHeaders = allowedResponseHeaders ?? throw new ArgumentNullException(nameof(allowedResponseHeaders)); + _logContext = logContext ?? throw new ArgumentNullException(nameof(logContext)); + _options = options ?? throw new ArgumentNullException(nameof(options)); + _interceptors = interceptors; _logger = logger ?? throw new ArgumentNullException(nameof(logger)); - _loggingFields = loggingFields; } public bool IsUpgradableRequest => _innerUpgradeFeature.IsUpgradableRequest; @@ -33,10 +33,9 @@ public UpgradeFeatureLoggingDecorator(IHttpUpgradeFeature innerUpgradeFeature, H public async Task UpgradeAsync() { var upgradeStream = await _innerUpgradeFeature.UpgradeAsync(); - _isUpgraded = true; - HttpLoggingMiddleware.LogResponseHeaders(_response, _loggingFields, _allowedResponseHeaders, _logger); + await HttpLoggingMiddleware.LogResponseHeadersAsync(_logContext, _options, _interceptors, _logger); return upgradeStream; } diff --git a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs index 8634f58ee98a..12dfdf8c27b3 100644 --- a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs +++ b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs @@ -19,7 +19,7 @@ public class FileLoggerProcessorTests public FileLoggerProcessorTests() { - TempPath = Path.GetTempFileName() + "_"; + TempPath = Environment.CurrentDirectory + "_"; } public string TempPath { get; } diff --git a/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs b/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs index 80ecc848b6f1..f57397c89e05 100644 --- a/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs +++ b/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs @@ -9,9 +9,11 @@ using Microsoft.AspNetCore.Http.Features; using Microsoft.AspNetCore.TestHost; using Microsoft.AspNetCore.Testing; +using Microsoft.AspNetCore.WebUtilities; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.ObjectPool; using Microsoft.Extensions.Options; using Microsoft.Net.Http.Headers; using Moq; @@ -39,21 +41,60 @@ public void Ctor_ThrowsExceptionsWhenNullArgs() Assert.Throws(() => new HttpLoggingMiddleware( null, CreateOptionsAccessor(), - LoggerFactory.CreateLogger())); + LoggerFactory.CreateLogger(), + Array.Empty(), + ObjectPool.Create(), + TimeProvider.System)); + + Assert.Throws(() => new HttpLoggingMiddleware(c => + { + return Task.CompletedTask; + }, + null, + LoggerFactory.CreateLogger(), + Array.Empty(), + ObjectPool.Create(), + TimeProvider.System)); + + Assert.Throws(() => new HttpLoggingMiddleware(c => + { + return Task.CompletedTask; + }, + CreateOptionsAccessor(), + null, + Array.Empty(), + ObjectPool.Create(), + TimeProvider.System)); + + Assert.Throws(() => new HttpLoggingMiddleware(c => + { + return Task.CompletedTask; + }, + CreateOptionsAccessor(), + LoggerFactory.CreateLogger(), + null, + ObjectPool.Create(), + TimeProvider.System)); Assert.Throws(() => new HttpLoggingMiddleware(c => { return Task.CompletedTask; }, - null, - LoggerFactory.CreateLogger())); + CreateOptionsAccessor(), + LoggerFactory.CreateLogger(), + Array.Empty(), + null, + TimeProvider.System)); Assert.Throws(() => new HttpLoggingMiddleware(c => { return Task.CompletedTask; }, - CreateOptionsAccessor(), - null)); + CreateOptionsAccessor(), + LoggerFactory.CreateLogger(), + Array.Empty(), + ObjectPool.Create(), + null)); } [Fact] @@ -62,25 +103,9 @@ public async Task NoopWhenLoggingDisabled() var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.None; - var middleware = new HttpLoggingMiddleware( - c => - { - c.Response.StatusCode = 200; - return Task.CompletedTask; - }, - options, - LoggerFactory.CreateLogger()); + var middleware = CreateMiddleware(options: options); - var httpContext = new DefaultHttpContext(); - httpContext.Request.Protocol = "HTTP/1.0"; - httpContext.Request.Method = "GET"; - httpContext.Request.Scheme = "http"; - httpContext.Request.Path = new PathString("/foo"); - httpContext.Request.PathBase = new PathString("/foo"); - httpContext.Request.QueryString = new QueryString("?foo"); - httpContext.Request.Headers["Connection"] = "keep-alive"; - httpContext.Request.ContentType = "text/plain"; - httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes("test")); + var httpContext = CreateRequest(); await middleware.Invoke(httpContext); @@ -90,7 +115,7 @@ public async Task NoopWhenLoggingDisabled() [Fact] public async Task DefaultRequestInfoOnlyHeadersAndRequestInfo() { - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -102,19 +127,9 @@ public async Task DefaultRequestInfoOnlyHeadersAndRequestInfo() break; } } - }, - CreateOptionsAccessor(), - LoggerFactory.CreateLogger()); + }); - var httpContext = new DefaultHttpContext(); - httpContext.Request.Protocol = "HTTP/1.0"; - httpContext.Request.Method = "GET"; - httpContext.Request.Scheme = "http"; - httpContext.Request.Path = new PathString("/foo"); - httpContext.Request.PathBase = new PathString("/foo"); - httpContext.Request.Headers["Connection"] = "keep-alive"; - httpContext.Request.ContentType = "text/plain"; - httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes("test")); + var httpContext = CreateRequest(); await middleware.Invoke(httpContext); Assert.Contains(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); @@ -131,7 +146,7 @@ public async Task RequestLogsAllRequestInfo() { var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.Request; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -144,18 +159,9 @@ public async Task RequestLogsAllRequestInfo() } } }, - options, - LoggerFactory.CreateLogger()); + options); - var httpContext = new DefaultHttpContext(); - httpContext.Request.Protocol = "HTTP/1.0"; - httpContext.Request.Method = "GET"; - httpContext.Request.Scheme = "http"; - httpContext.Request.Path = new PathString("/foo"); - httpContext.Request.PathBase = new PathString("/foo"); - httpContext.Request.Headers["Connection"] = "keep-alive"; - httpContext.Request.ContentType = "text/plain"; - httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes("test")); + var httpContext = CreateRequest(); await middleware.Invoke(httpContext); Assert.Contains(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); @@ -172,7 +178,7 @@ public async Task RequestPropertiesLogs() { var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.RequestProperties; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -185,18 +191,9 @@ public async Task RequestPropertiesLogs() } } }, - options, - LoggerFactory.CreateLogger()); + options); - var httpContext = new DefaultHttpContext(); - httpContext.Request.Protocol = "HTTP/1.0"; - httpContext.Request.Method = "GET"; - httpContext.Request.Scheme = "http"; - httpContext.Request.Path = new PathString("/foo"); - httpContext.Request.PathBase = new PathString("/foo"); - httpContext.Request.Headers["Connection"] = "keep-alive"; - httpContext.Request.ContentType = "text/plain"; - httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes("test")); + var httpContext = CreateRequest(); await middleware.Invoke(httpContext); Assert.Contains(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); @@ -213,7 +210,7 @@ public async Task RequestHeadersLogs() { var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.RequestHeaders; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -226,19 +223,9 @@ public async Task RequestHeadersLogs() } } }, - options, - LoggerFactory.CreateLogger()); + options); - var httpContext = new DefaultHttpContext(); - httpContext.Request.Protocol = "HTTP/1.0"; - httpContext.Request.Method = "GET"; - httpContext.Request.Scheme = "http"; - httpContext.Request.Path = new PathString("/foo"); - httpContext.Request.PathBase = new PathString("/foo"); - httpContext.Request.QueryString = new QueryString("?foo"); - httpContext.Request.Headers["Connection"] = "keep-alive"; - httpContext.Request.ContentType = "text/plain"; - httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes("test")); + var httpContext = CreateRequest(); await middleware.Invoke(httpContext); Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); @@ -254,7 +241,7 @@ public async Task RequestHeadersLogs() [Fact] public async Task UnknownRequestHeadersRedacted() { - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -266,9 +253,7 @@ public async Task UnknownRequestHeadersRedacted() break; } } - }, - CreateOptionsAccessor(), - LoggerFactory.CreateLogger()); + }); var httpContext = new DefaultHttpContext(); @@ -285,13 +270,7 @@ public async Task CanConfigureRequestAllowList() var options = CreateOptionsAccessor(); options.CurrentValue.RequestHeaders.Clear(); options.CurrentValue.RequestHeaders.Add("foo"); - var middleware = new HttpLoggingMiddleware( - c => - { - return Task.CompletedTask; - }, - options, - LoggerFactory.CreateLogger()); + var middleware = CreateMiddleware(options: options); var httpContext = new DefaultHttpContext(); @@ -307,6 +286,23 @@ public async Task CanConfigureRequestAllowList() Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Connection: keep-alive")); } + [Fact] + public async Task LogsMessageIfNotConsumed() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; + + var middleware = CreateMiddleware(options: options); + + var httpContext = new DefaultHttpContext(); + httpContext.Request.ContentType = "text/plain"; + httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes("Hello World")); + + await middleware.Invoke(httpContext); + + Assert.Contains(TestSink.Writes, w => w.Message.Contains("RequestBody: [Not consumed by app]")); + } + [Theory] [MemberData(nameof(BodyData))] public async Task RequestBodyReadingWorks(string expected) @@ -314,7 +310,7 @@ public async Task RequestBodyReadingWorks(string expected) var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -327,8 +323,63 @@ public async Task RequestBodyReadingWorks(string expected) } } }, - options, - LoggerFactory.CreateLogger()); + options); + + var httpContext = new DefaultHttpContext(); + httpContext.Request.ContentType = "text/plain"; + httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes(expected)); + + await middleware.Invoke(httpContext); + + Assert.Contains(TestSink.Writes, w => w.Message.Contains(expected)); + } + + [Theory] + [MemberData(nameof(BodyData))] + public async Task RequestBodyCopyToWorks(string expected) + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; + + var middleware = CreateMiddleware( + async c => + { + var ms = new MemoryStream(); + c.Request.Body.CopyTo(ms); + ms.Position = 0; + var sr = new StreamReader(ms); + var body = await sr.ReadToEndAsync(); + Assert.Equal(expected, body); + }, + options); + + var httpContext = new DefaultHttpContext(); + httpContext.Request.ContentType = "text/plain"; + httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes(expected)); + + await middleware.Invoke(httpContext); + + Assert.Contains(TestSink.Writes, w => w.Message.Contains(expected)); + } + + [Theory] + [MemberData(nameof(BodyData))] + public async Task RequestBodyCopyToAsyncWorks(string expected) + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; + + var middleware = CreateMiddleware( + async c => + { + var ms = new MemoryStream(); + await c.Request.Body.CopyToAsync(ms); + ms.Position = 0; + var sr = new StreamReader(ms); + var body = await sr.ReadToEndAsync(); + Assert.Equal(expected, body); + }, + options); var httpContext = new DefaultHttpContext(); httpContext.Request.ContentType = "text/plain"; @@ -347,7 +398,7 @@ public async Task RequestBodyReadingLimitLongCharactersWorks() options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; options.CurrentValue.RequestBodyLogLimit = 4; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -364,15 +415,14 @@ public async Task RequestBodyReadingLimitLongCharactersWorks() Assert.Equal(15, count); }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); httpContext.Request.ContentType = "text/plain"; httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes(input)); await middleware.Invoke(httpContext); - var expected = input.Substring(0, options.CurrentValue.RequestBodyLogLimit / 3); + var expected = input.Substring(0, options.CurrentValue.RequestBodyLogLimit / 3) + "[Truncated by RequestBodyLogLimit]"; Assert.Contains(TestSink.Writes, w => w.Message.Equals("RequestBody: " + expected)); } @@ -384,7 +434,7 @@ public async Task RequestBodyReadingLimitWorks() var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -401,15 +451,14 @@ public async Task RequestBodyReadingLimitWorks() Assert.Equal(63000, count); }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); httpContext.Request.ContentType = "text/plain"; httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes(input)); await middleware.Invoke(httpContext); - var expected = input.Substring(0, options.CurrentValue.ResponseBodyLogLimit); + var expected = input.Substring(0, options.CurrentValue.RequestBodyLogLimit) + "[Truncated by RequestBodyLogLimit]"; Assert.Contains(TestSink.Writes, w => w.Message.Equals("RequestBody: " + expected)); } @@ -421,21 +470,20 @@ public async Task PartialReadBodyStillLogs() var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; var res = await c.Request.Body.ReadAsync(arr); }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); httpContext.Request.ContentType = "text/plain"; httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes(input)); await middleware.Invoke(httpContext); - var expected = input.Substring(0, 4096); + var expected = input.Substring(0, 4096) + "[Only partially consumed by app]"; Assert.Contains(TestSink.Writes, w => w.Message.Equals("RequestBody: " + expected)); } @@ -447,22 +495,21 @@ public async Task ZeroByteReadStillLogsRequestBody() var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; _ = await c.Request.Body.ReadAsync(new byte[0]); var res = await c.Request.Body.ReadAsync(arr); }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); httpContext.Request.ContentType = "text/plain"; httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes(input)); await middleware.Invoke(httpContext); - var expected = input.Substring(0, 4096); + var expected = input.Substring(0, 4096) + "[Only partially consumed by app]"; Assert.Contains(TestSink.Writes, w => w.Message.Equals("RequestBody: " + expected)); } @@ -481,7 +528,7 @@ public async Task VerifyDefaultMediaTypeHeaders(string contentType) var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -494,8 +541,7 @@ public async Task VerifyDefaultMediaTypeHeaders(string contentType) } } }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); httpContext.Request.ContentType = contentType; @@ -508,6 +554,7 @@ public async Task VerifyDefaultMediaTypeHeaders(string contentType) [Theory] [InlineData("application/invalid")] + [InlineData("application/invalid; charset=utf-8")] [InlineData("multipart/form-data")] public async Task RejectedContentTypes(string contentType) { @@ -516,7 +563,7 @@ public async Task RejectedContentTypes(string contentType) var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -534,8 +581,7 @@ public async Task RejectedContentTypes(string contentType) Assert.Equal(1000, count); }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); httpContext.Request.ContentType = contentType; @@ -557,7 +603,7 @@ public async Task DifferentEncodingsWork() options.CurrentValue.MediaTypeOptions.Clear(); options.CurrentValue.MediaTypeOptions.AddText("text/plain", encoding); - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { var arr = new byte[4096]; @@ -574,8 +620,7 @@ public async Task DifferentEncodingsWork() Assert.Equal(2000, count); }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); httpContext.Request.ContentType = "text/plain"; @@ -587,162 +632,405 @@ public async Task DifferentEncodingsWork() } [Fact] - public async Task DefaultResponseInfoOnlyHeadersAndRequestInfo() + public async Task CharsetHonoredIfSupported() { - var middleware = new HttpLoggingMiddleware( + var encoding = Encoding.Unicode; + var expected = new string('a', 1000); + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; + options.CurrentValue.MediaTypeOptions.Clear(); + options.CurrentValue.MediaTypeOptions.AddText("text/plain", encoding); + + var middleware = CreateMiddleware( async c => { - c.Response.StatusCode = 200; - c.Response.Headers[HeaderNames.TransferEncoding] = "test"; - c.Response.ContentType = "text/plain"; - await c.Response.WriteAsync("test"); + var arr = new byte[4096]; + var count = 0; + while (true) + { + var res = await c.Request.Body.ReadAsync(arr); + if (res == 0) + { + break; + } + count += res; + } + + Assert.Equal(1000, count); }, - CreateOptionsAccessor(), - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); + httpContext.Request.ContentType = "text/plain; charset=" + Encoding.ASCII.WebName; + httpContext.Request.Body = new MemoryStream(Encoding.ASCII.GetBytes(expected)); await middleware.Invoke(httpContext); - Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 200")); - Assert.Contains(TestSink.Writes, w => w.Message.Contains("Transfer-Encoding: test")); - Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Body: test")); + + Assert.Contains(TestSink.Writes, w => w.Message.Contains("RequestBody:")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains(expected)); } [Fact] - public async Task ResponseInfoLogsAll() + public async Task CharsetNotHonoredIfNotSupported() { + var encoding = Encoding.Unicode; + var expected = new string('a', 1000); var options = CreateOptionsAccessor(); - options.CurrentValue.LoggingFields = HttpLoggingFields.Response; + options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; + options.CurrentValue.MediaTypeOptions.Clear(); + options.CurrentValue.MediaTypeOptions.AddText("text/plain", encoding); - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { - c.Response.StatusCode = 200; - c.Response.Headers[HeaderNames.TransferEncoding] = "test"; - c.Response.ContentType = "text/plain"; - await c.Response.WriteAsync("test"); + var arr = new byte[4096]; + var count = 0; + while (true) + { + var res = await c.Request.Body.ReadAsync(arr); + if (res == 0) + { + break; + } + count += res; + } + + Assert.Equal(4000, count); }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); + httpContext.Request.ContentType = "text/plain; charset=" + Encoding.UTF32.WebName; + httpContext.Request.Body = new MemoryStream(Encoding.UTF32.GetBytes(expected)); await middleware.Invoke(httpContext); - Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 200")); - Assert.Contains(TestSink.Writes, w => w.Message.Contains("Transfer-Encoding: test")); - Assert.Contains(TestSink.Writes, w => w.Message.Contains("Body: test")); + + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("RequestBody:")); } [Fact] - public async Task StatusCodeLogs() + public async Task RequestInterceptorCanDisableRequestAndResponseLogs() { var options = CreateOptionsAccessor(); - options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseStatusCode; + options.CurrentValue.LoggingFields = HttpLoggingFields.All; - var middleware = new HttpLoggingMiddleware( - async c => - { - c.Response.StatusCode = 200; - c.Response.Headers["Server"] = "Kestrel"; - c.Response.ContentType = "text/plain"; - await c.Response.WriteAsync("test"); - }, - options, - LoggerFactory.CreateLogger()); + var middleware = CreateMiddleware(RequestResponseApp, options, new FakeInterceptor(context => + { + context.LoggingFields = HttpLoggingFields.None; + })); - var httpContext = new DefaultHttpContext(); + var httpContext = CreateRequest(); await middleware.Invoke(httpContext); - Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 200")); - Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Server: Kestrel")); - Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Body: test")); + + Assert.Empty(TestSink.Writes); } [Fact] - public async Task ResponseHeadersLogs() + public async Task RequestInterceptorCanEnableRequestAndResponseLogs() { var options = CreateOptionsAccessor(); - options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseHeaders; + options.CurrentValue.LoggingFields = HttpLoggingFields.None; - var middleware = new HttpLoggingMiddleware( - async c => + var middleware = CreateMiddleware(RequestResponseApp, options, + interceptor: new FakeInterceptor(context => { - c.Response.StatusCode = 200; - c.Response.Headers[HeaderNames.TransferEncoding] = "test"; - c.Response.ContentType = "text/plain"; - await c.Response.WriteAsync("test"); - }, - options, - LoggerFactory.CreateLogger()); + context.LoggingFields = HttpLoggingFields.All; + })); - var httpContext = new DefaultHttpContext(); + var httpContext = CreateRequest(); await middleware.Invoke(httpContext); - Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("StatusCode: 200")); - Assert.Contains(TestSink.Writes, w => w.Message.Contains("Transfer-Encoding: test")); - Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Body: test")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Method: GET")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Scheme: http")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Path: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("PathBase: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Connection: keep-alive")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("RequestBody: test")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 418")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Content-Type: text/plain")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Body: Hello World")); } [Fact] - public async Task ResponseHeadersRedacted() + public async Task RequestInterceptorCanAugmentRequestLogs() { var options = CreateOptionsAccessor(); - options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseHeaders; + options.CurrentValue.LoggingFields = HttpLoggingFields.All; - var middleware = new HttpLoggingMiddleware( - c => + var middleware = CreateMiddleware(RequestResponseApp, options, + interceptor: new FakeInterceptor(context => { - c.Response.Headers["Test"] = "Kestrel"; - return Task.CompletedTask; - }, - options, - LoggerFactory.CreateLogger()); + context.AddParameter("foo", "bar"); + })); - var httpContext = new DefaultHttpContext(); + var httpContext = CreateRequest(); await middleware.Invoke(httpContext); - Assert.Contains(TestSink.Writes, w => w.Message.Contains("Test: [Redacted]")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Method: GET")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Scheme: http")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Path: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("PathBase: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Connection: keep-alive")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("RequestBody: test")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 418")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Content-Type: text/plain")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Body: Hello World")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("foo: bar")); } [Fact] - public async Task AllowedResponseHeadersModify() + public async Task RequestInterceptorCanReplaceRequestLogs() { var options = CreateOptionsAccessor(); - options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseHeaders; - options.CurrentValue.ResponseHeaders.Clear(); - options.CurrentValue.ResponseHeaders.Add("Test"); + options.CurrentValue.LoggingFields = HttpLoggingFields.All; - var middleware = new HttpLoggingMiddleware( - c => + var middleware = CreateMiddleware(RequestResponseApp, options, + interceptor: new FakeInterceptor(context => { - c.Response.Headers["Test"] = "Kestrel"; - c.Response.Headers["Server"] = "Kestrel"; - return Task.CompletedTask; - }, - options, - LoggerFactory.CreateLogger()); + Assert.True(context.TryDisable(HttpLoggingFields.RequestPath)); + context.AddParameter("Path", "ReplacedPath"); + })); - var httpContext = new DefaultHttpContext(); + var httpContext = CreateRequest(); await middleware.Invoke(httpContext); - Assert.Contains(TestSink.Writes, w => w.Message.Contains("Test: Kestrel")); - Assert.Contains(TestSink.Writes, w => w.Message.Contains("Server: [Redacted]")); - } - - [Theory] + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Method: GET")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Scheme: http")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Path: /foo")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("PathBase: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Connection: keep-alive")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("RequestBody: test")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 418")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Content-Type: text/plain")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Body: Hello World")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Path: ReplacedPath")); + } + + [Fact] + public async Task DefaultResponseInfoOnlyHeadersAndRequestInfo() + { + var middleware = CreateMiddleware( + async c => + { + c.Response.StatusCode = 200; + c.Response.Headers[HeaderNames.TransferEncoding] = "test"; + c.Response.ContentType = "text/plain"; + await c.Response.WriteAsync("test"); + }); + + var httpContext = new DefaultHttpContext(); + + await middleware.Invoke(httpContext); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 200")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Transfer-Encoding: test")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Body: test")); + } + + [Fact] + public async Task ResponseInfoLogsAll() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.Response; + + var middleware = CreateMiddleware( + async c => + { + c.Response.StatusCode = 200; + c.Response.Headers[HeaderNames.TransferEncoding] = "test"; + c.Response.ContentType = "text/plain"; + await c.Response.WriteAsync("test"); + }, + options); + + var httpContext = new DefaultHttpContext(); + + await middleware.Invoke(httpContext); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 200")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Transfer-Encoding: test")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Body: test")); + } + + [Fact] + public async Task DurationLogs() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.Duration; + + var middleware = CreateMiddleware( + async c => + { + c.Response.StatusCode = 200; + c.Response.Headers[HeaderNames.TransferEncoding] = "test"; + c.Response.ContentType = "text/plain"; + await c.Response.WriteAsync("test"); + }, + options); + + var httpContext = new DefaultHttpContext(); + + await middleware.Invoke(httpContext); + Assert.Contains(TestSink.Writes, w => w.Message.StartsWith("Duration: ", StringComparison.Ordinal)); + } + + [Fact] + public async Task ResponseWithExceptionBeforeBodyLogged() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.Response; + + var middleware = CreateMiddleware( + c => + { + c.Response.StatusCode = 200; + c.Response.Headers[HeaderNames.TransferEncoding] = "test"; + c.Response.ContentType = "text/plain"; + + throw new IOException("Test exception"); + }, + options); + + var httpContext = new DefaultHttpContext(); + + await Assert.ThrowsAsync(() => middleware.Invoke(httpContext)); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 200")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Transfer-Encoding: test")); + } + + [Fact] + public async Task ResponseWithExceptionAfterBodyLogged() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.Response; + + var middleware = CreateMiddleware( + async c => + { + c.Response.StatusCode = 200; + c.Response.Headers[HeaderNames.TransferEncoding] = "test"; + c.Response.ContentType = "text/plain"; + await c.Response.WriteAsync("test"); + + throw new IOException("Test exception"); + }, + options); + + var httpContext = new DefaultHttpContext(); + + await Assert.ThrowsAsync(() => middleware.Invoke(httpContext)); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 200")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Transfer-Encoding: test")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Body: test")); + } + + [Fact] + public async Task StatusCodeLogs() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseStatusCode; + + var middleware = CreateMiddleware( + async c => + { + c.Response.StatusCode = 200; + c.Response.Headers["Server"] = "Kestrel"; + c.Response.ContentType = "text/plain"; + await c.Response.WriteAsync("test"); + }, + options); + + var httpContext = new DefaultHttpContext(); + + await middleware.Invoke(httpContext); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 200")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Server: Kestrel")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Body: test")); + } + + [Fact] + public async Task ResponseHeadersLogs() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseHeaders; + + var middleware = CreateMiddleware( + async c => + { + c.Response.StatusCode = 200; + c.Response.Headers[HeaderNames.TransferEncoding] = "test"; + c.Response.ContentType = "text/plain"; + await c.Response.WriteAsync("test"); + }, + options); + + var httpContext = new DefaultHttpContext(); + + await middleware.Invoke(httpContext); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("StatusCode: 200")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Transfer-Encoding: test")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Body: test")); + } + + [Fact] + public async Task ResponseHeadersRedacted() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseHeaders; + + var middleware = CreateMiddleware( + c => + { + c.Response.Headers["Test"] = "Kestrel"; + return Task.CompletedTask; + }, + options); + + var httpContext = new DefaultHttpContext(); + + await middleware.Invoke(httpContext); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Test: [Redacted]")); + } + + [Fact] + public async Task AllowedResponseHeadersModify() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseHeaders; + options.CurrentValue.ResponseHeaders.Clear(); + options.CurrentValue.ResponseHeaders.Add("Test"); + + var middleware = CreateMiddleware( + c => + { + c.Response.Headers["Test"] = "Kestrel"; + c.Response.Headers["Server"] = "Kestrel"; + return Task.CompletedTask; + }, + options); + + var httpContext = new DefaultHttpContext(); + + await middleware.Invoke(httpContext); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Test: Kestrel")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Server: [Redacted]")); + } + + [Theory] [MemberData(nameof(BodyData))] public async Task ResponseBodyWritingWorks(string expected) { var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseBody; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( c => { c.Response.ContentType = "text/plain"; return c.Response.WriteAsync(expected); }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); @@ -751,20 +1039,39 @@ public async Task ResponseBodyWritingWorks(string expected) Assert.Contains(TestSink.Writes, w => w.Message.Contains(expected)); } + [Fact] + public async Task ResponseBodyNotLoggedIfEmpty() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseBody; + var middleware = CreateMiddleware( + c => + { + c.Response.ContentType = "text/plain"; + return Task.CompletedTask; + }, + options); + + var httpContext = new DefaultHttpContext(); + + await middleware.Invoke(httpContext); + + Assert.Empty(TestSink.Writes); + } + [Fact] public async Task ResponseBodyWritingLimitWorks() { var input = string.Concat(new string('a', 30000), new string('b', 3000)); var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseBody; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( c => { c.Response.ContentType = "text/plain"; return c.Response.WriteAsync(input); }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); @@ -783,7 +1090,7 @@ public async Task FirstWriteResponseHeadersLogged() var writtenHeaders = new TaskCompletionSource(); var letBodyFinish = new TaskCompletionSource(); - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { c.Response.StatusCode = 200; @@ -793,8 +1100,7 @@ public async Task FirstWriteResponseHeadersLogged() writtenHeaders.SetResult(); await letBodyFinish.Task; }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); @@ -822,7 +1128,7 @@ public async Task StartAsyncResponseHeadersLogged() var writtenHeaders = new TaskCompletionSource(); var letBodyFinish = new TaskCompletionSource(); - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { c.Response.StatusCode = 200; @@ -832,8 +1138,7 @@ public async Task StartAsyncResponseHeadersLogged() writtenHeaders.SetResult(); await letBodyFinish.Task; }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); @@ -856,14 +1161,13 @@ public async Task UnrecognizedMediaType() var expected = "Hello world"; var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseBody; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( c => { c.Response.ContentType = "foo/*"; return c.Response.WriteAsync(expected); }, - options, - LoggerFactory.CreateLogger()); + options); var httpContext = new DefaultHttpContext(); @@ -877,26 +1181,10 @@ public async Task NoMediaType() { var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; - var middleware = new HttpLoggingMiddleware( - async c => - { - c.Request.ContentType = null; - var arr = new byte[4096]; - while (true) - { - var res = await c.Request.Body.ReadAsync(arr); - if (res == 0) - { - break; - } - } - }, - options, - LoggerFactory.CreateLogger()); + var middleware = CreateMiddleware(RequestResponseApp, options); var httpContext = new DefaultHttpContext(); - - httpContext.Request.Headers["foo"] = "bar"; + httpContext.Request.Headers.Remove(HeaderNames.ContentType); await middleware.Invoke(httpContext); @@ -926,15 +1214,14 @@ public async Task UpgradeToWebSocketLogsResponseStatusCodeWhenResponseIsFlushed( .ReturnsAsync(Stream.Null); httpContext.Features.Set(upgradeFeatureMock.Object); - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { await c.Features.Get().UpgradeAsync(); writtenHeaders.SetResult(); await letBodyFinish.Task; }, - options, - LoggerFactory.CreateLogger()); + options); var middlewareTask = middleware.Invoke(httpContext); @@ -947,6 +1234,67 @@ public async Task UpgradeToWebSocketLogsResponseStatusCodeWhenResponseIsFlushed( await middlewareTask; } + [Fact] + public async Task UpgradeWithCombineLogs_OneLog() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.All; + options.CurrentValue.CombineLogs = true; + + var writtenHeaders = new TaskCompletionSource(); + var letBodyFinish = new TaskCompletionSource(); + + var httpContext = new DefaultHttpContext(); + httpContext.Request.Protocol = "HTTP/1.1"; + httpContext.Request.Method = "GET"; + httpContext.Request.Scheme = "http"; + httpContext.Request.Path = "/"; + httpContext.Request.Headers.Connection = HeaderNames.Upgrade; + httpContext.Request.Headers.Upgrade = "websocket"; + + var upgradeFeatureMock = new Mock(); + upgradeFeatureMock.Setup(m => m.IsUpgradableRequest).Returns(true); + upgradeFeatureMock + .Setup(m => m.UpgradeAsync()) + .Callback(() => + { + httpContext.Response.StatusCode = StatusCodes.Status101SwitchingProtocols; + httpContext.Response.Headers.Connection = HeaderNames.Upgrade; + }) + .ReturnsAsync(Stream.Null); + httpContext.Features.Set(upgradeFeatureMock.Object); + + var middleware = CreateMiddleware( + async c => + { + await c.Features.Get().UpgradeAsync(); + }, + options); + + await middleware.Invoke(httpContext); + + Assert.True(TestSink.Writes.TryTake(out var contentTypeLog)); + Assert.Equal("No Content-Type header for request body.", contentTypeLog.Message); + + Assert.True(TestSink.Writes.TryTake(out var requestLog)); + var lines = requestLog.Message.Split(Environment.NewLine); + var i = 0; + Assert.Equal("Request and Response:", lines[i++]); + Assert.Equal("Protocol: HTTP/1.1", lines[i++]); + Assert.Equal("Method: GET", lines[i++]); + Assert.Equal("Scheme: http", lines[i++]); + Assert.Equal("PathBase: ", lines[i++]); + Assert.Equal("Path: /", lines[i++]); + Assert.Equal("Connection: Upgrade", lines[i++]); + Assert.Equal("Upgrade: websocket", lines[i++]); + Assert.Equal("StatusCode: 101", lines[i++]); + Assert.Equal("Connection: Upgrade", lines[i++]); + Assert.StartsWith("Duration: ", lines[i++]); + Assert.Equal(lines.Length, i); + + Assert.False(TestSink.Writes.TryTake(out var _)); + } + [Fact] public async Task UpgradeToWebSocketLogsResponseHeadersWhenResponseIsFlushed() { @@ -970,15 +1318,14 @@ public async Task UpgradeToWebSocketLogsResponseHeadersWhenResponseIsFlushed() .ReturnsAsync(Stream.Null); httpContext.Features.Set(upgradeFeatureMock.Object); - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { await c.Features.Get().UpgradeAsync(); writtenHeaders.SetResult(); await letBodyFinish.Task; }, - options, - LoggerFactory.CreateLogger()); + options); var middlewareTask = middleware.Invoke(httpContext); @@ -1014,15 +1361,14 @@ public async Task UpgradeToWebSocketDoesNotLogWhenResponseIsFlushedIfLoggingOpti .ReturnsAsync(Stream.Null); httpContext.Features.Set(upgradeFeatureMock.Object); - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { await c.Features.Get().UpgradeAsync(); writtenHeaders.SetResult(); await letBodyFinish.Task; }, - options, - LoggerFactory.CreateLogger()); + options); var middlewareTask = middleware.Invoke(httpContext); @@ -1050,7 +1396,7 @@ public async Task LogsWrittenOutsideUpgradeWrapperIfUpgradeDoesNotOccur(bool isU upgradeFeatureMock.Setup(m => m.IsUpgradableRequest).Returns(isUpgradableRequest); httpContext.Features.Set(upgradeFeatureMock.Object); - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { c.Response.StatusCode = 200; @@ -1058,8 +1404,7 @@ public async Task LogsWrittenOutsideUpgradeWrapperIfUpgradeDoesNotOccur(bool isU c.Response.ContentType = "text/plain"; await c.Response.StartAsync(); }, - options, - LoggerFactory.CreateLogger()); + options); var middlewareTask = middleware.Invoke(httpContext); @@ -1097,13 +1442,12 @@ public async Task UpgradeToWebSocketLogsWrittenOnlyOnce(HttpLoggingFields loggin var writeCount = 0; TestSink.MessageLogged += (context) => { writeCount++; }; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { await c.Features.Get().UpgradeAsync(); }, - options, - LoggerFactory.CreateLogger()); + options); await middleware.Invoke(httpContext); @@ -1129,14 +1473,13 @@ public async Task OriginalUpgradeFeatureIsRestoredBeforeMiddlewareCompletes(Http IHttpUpgradeFeature upgradeFeature = null; - var middleware = new HttpLoggingMiddleware( + var middleware = CreateMiddleware( async c => { upgradeFeature = c.Features.Get(); await letBodyFinish.Task; }, - options, - LoggerFactory.CreateLogger()); + options); var middlewareTask = middleware.Invoke(httpContext); @@ -1148,6 +1491,235 @@ public async Task OriginalUpgradeFeatureIsRestoredBeforeMiddlewareCompletes(Http Assert.False(httpContext.Features.Get() is UpgradeFeatureLoggingDecorator); } + [Theory] + [InlineData(HttpLoggingFields.All, true, true)] + [InlineData(HttpLoggingFields.All, false, false)] + [InlineData(HttpLoggingFields.RequestPropertiesAndHeaders, true, true)] + [InlineData(HttpLoggingFields.RequestPropertiesAndHeaders, false, false)] + [InlineData(HttpLoggingFields.ResponsePropertiesAndHeaders, true, true)] + [InlineData(HttpLoggingFields.ResponsePropertiesAndHeaders, false, false)] + public async Task CombineLogs_OneLog(HttpLoggingFields fields, bool hasRequestBody, bool hasResponseBody) + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = fields; + options.CurrentValue.CombineLogs = true; + + var middleware = CreateMiddleware( + async c => + { + await c.Request.Body.DrainAsync(default); + c.Response.Headers[HeaderNames.TransferEncoding] = "test"; + if (hasResponseBody) + { + c.Response.ContentType = "text/plain2"; + await c.Response.WriteAsync("test response"); + } + }, + options); + + var httpContext = CreateRequest(); + if (!hasRequestBody) + { + httpContext.Request.ContentType = null; + httpContext.Request.Body = Stream.Null; + } + await middleware.Invoke(httpContext); + + var lines = Assert.Single(TestSink.Writes.Where(w => w.LogLevel >= LogLevel.Information)).Message.Split(Environment.NewLine); + var i = 0; + Assert.Equal("Request and Response:", lines[i++]); + if (fields.HasFlag(HttpLoggingFields.RequestPropertiesAndHeaders)) + { + Assert.Equal("Protocol: HTTP/1.0", lines[i++]); + Assert.Equal("Method: GET", lines[i++]); + Assert.Equal("Scheme: http", lines[i++]); + Assert.Equal("PathBase: /foo", lines[i++]); + Assert.Equal("Path: /foo", lines[i++]); + Assert.Equal("Connection: keep-alive", lines[i++]); + if (hasRequestBody) + { + Assert.Equal("Content-Type: text/plain", lines[i++]); + } + } + if (fields.HasFlag(HttpLoggingFields.ResponsePropertiesAndHeaders)) + { + Assert.Equal("StatusCode: 200", lines[i++]); + Assert.Equal("Transfer-Encoding: test", lines[i++]); + if (hasResponseBody) + { + Assert.Equal("Content-Type: text/plain2", lines[i++]); + } + } + if (fields.HasFlag(HttpLoggingFields.RequestBody) && hasRequestBody) + { + Assert.Equal("RequestBody: test", lines[i++]); + Assert.Equal("RequestBodyStatus: [Completed]", lines[i++]); + } + if (fields.HasFlag(HttpLoggingFields.ResponseBody) && hasResponseBody) + { + Assert.Equal("ResponseBody: test response", lines[i++]); + } + if (fields.HasFlag(HttpLoggingFields.Duration)) + { + Assert.StartsWith("Duration: ", lines[i++]); + } + Assert.Equal(lines.Length, i); + } + + [Fact] + public async Task CombineLogs_Exception_RequestLogged() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.All; + options.CurrentValue.CombineLogs = true; + + var middleware = CreateMiddleware( + async c => + { + await c.Request.Body.DrainAsync(default); + c.Response.Headers[HeaderNames.TransferEncoding] = "test"; + c.Response.ContentType = "text/plain2"; + + throw new IOException("Test exception"); + }, + options); + + var httpContext = CreateRequest(); + await Assert.ThrowsAsync(() => middleware.Invoke(httpContext)); + + var lines = Assert.Single(TestSink.Writes).Message.Split(Environment.NewLine); + var i = 0; + Assert.Equal("Request and Response:", lines[i++]); + Assert.Equal("Protocol: HTTP/1.0", lines[i++]); + Assert.Equal("Method: GET", lines[i++]); + Assert.Equal("Scheme: http", lines[i++]); + Assert.Equal("PathBase: /foo", lines[i++]); + Assert.Equal("Path: /foo", lines[i++]); + Assert.Equal("Connection: keep-alive", lines[i++]); + Assert.Equal("Content-Type: text/plain", lines[i++]); + Assert.Equal("StatusCode: 200", lines[i++]); + Assert.Equal("Transfer-Encoding: test", lines[i++]); + Assert.Equal("Content-Type: text/plain2", lines[i++]); + Assert.Equal("RequestBody: test", lines[i++]); + Assert.Equal("RequestBodyStatus: [Completed]", lines[i++]); + Assert.StartsWith("Duration: ", lines[i++]); + Assert.Equal(lines.Length, i); + } + + [Fact] + public async Task ResponseInterceptorCanDisableResponseLogs() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.All; + + var middleware = CreateMiddleware(RequestResponseApp, options, new FakeInterceptor(_ => { }, context => + { + context.LoggingFields = HttpLoggingFields.None; + })); + + var httpContext = CreateRequest(); + + await middleware.Invoke(httpContext); + + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Method: GET")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Scheme: http")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Path: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("PathBase: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Connection: keep-alive")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("RequestBody: test")); + // Only response is disabled + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("StatusCode: 418")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Content-Type: text/plain; p=response")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Body: Hello World")); + } + + [Fact] + public async Task ResponseInterceptorCanEnableResponseLogs() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.None; + + var middleware = CreateMiddleware(RequestResponseApp, options, + interceptor: new FakeInterceptor(_ => { }, context => + { + context.LoggingFields = HttpLoggingFields.All; + })); + + var httpContext = CreateRequest(); + + await middleware.Invoke(httpContext); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Method: GET")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Scheme: http")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Path: /foo")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("PathBase: /foo")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Connection: keep-alive")); + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("RequestBody: test")); + // Only Response is enabled + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 418")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Content-Type: text/plain")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Body: Hello World")); + } + + [Fact] + public async Task ResponseInterceptorCanAugmentResponseLogs() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.All; + + var middleware = CreateMiddleware(RequestResponseApp, options, + interceptor: new FakeInterceptor(_ => { }, context => + { + context.AddParameter("foo", "bar"); + })); + + var httpContext = CreateRequest(); + + await middleware.Invoke(httpContext); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Method: GET")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Scheme: http")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Path: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("PathBase: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Connection: keep-alive")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("RequestBody: test")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 418")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Content-Type: text/plain")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Body: Hello World")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("foo: bar")); + } + + [Fact] + public async Task ResponseInterceptorCanReplaceResponseLogs() + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.All; + + var middleware = CreateMiddleware(RequestResponseApp, options, + interceptor: new FakeInterceptor(_ => { }, context => + { + Assert.True(context.TryDisable(HttpLoggingFields.ResponseStatusCode)); + context.AddParameter("StatusCode", "412"); + })); + + var httpContext = CreateRequest(); + + await middleware.Invoke(httpContext); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Protocol: HTTP/1.0")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Method: GET")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Scheme: http")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Path: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("PathBase: /foo")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Connection: keep-alive")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("RequestBody: test")); + + Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("StatusCode: 418")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Content-Type: text/plain")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("Body: Hello World")); + Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 412")); + } + [Fact] public async Task HttpLoggingAttributeWithLessOptionsAppliesToEndpoint() { @@ -1206,10 +1778,38 @@ public async Task HttpLoggingAttributeCanModifyRequestAndResponseSizeOnEndpoint( var initialResponse = await client.SendAsync(request); var filteredLogs = TestSink.Writes.Where(w => w.LoggerName.Contains("HttpLogging")); - Assert.Contains(filteredLogs, w => w.Message.Equals("RequestBody: fro")); + Assert.Contains(filteredLogs, w => w.Message.Equals("RequestBody: fro[Truncated by RequestBodyLogLimit]")); Assert.Contains(filteredLogs, w => w.Message.Equals("ResponseBody: testin")); } + [Fact] + public async Task InterceptorCanSeeAndOverrideAttributeSettings() + { + var app = CreateApp(HttpLoggingFields.None, new FakeInterceptor(requestContext => + { + Assert.Equal(HttpLoggingFields.All, requestContext.LoggingFields); + requestContext.Disable(HttpLoggingFields.RequestHeaders); + }, + responseContext => + { + Assert.Equal(HttpLoggingFields.All & ~HttpLoggingFields.RequestHeaders, responseContext.LoggingFields); + responseContext.Disable(HttpLoggingFields.ResponseHeaders); + })); + await app.StartAsync(); + + using var server = app.GetTestServer(); + var client = server.CreateClient(); + var request = new HttpRequestMessage(HttpMethod.Get, "/attr_responseandrequest"); + request.Headers.TryAddWithoutValidation("Accept", "application/json"); + var initialResponse = await client.SendAsync(request); + + var filteredLogs = TestSink.Writes.Where(w => w.LoggerName.Contains("HttpLogging")); + Assert.Contains(filteredLogs, w => w.Message.Contains("Request")); + Assert.DoesNotContain(filteredLogs, w => w.Message.Contains("Accept")); + Assert.Contains(filteredLogs, w => w.Message.Contains("StatusCode: 200")); + Assert.DoesNotContain(filteredLogs, w => w.Message.Contains("Content-Type: text/plain")); + } + [Fact] public async Task HttpLoggingExtensionWithLessOptionsAppliesToEndpoint() { @@ -1268,10 +1868,103 @@ public async Task HttpLoggingExtensionCanModifyRequestAndResponseSizeOnEndpoint( var initialResponse = await client.SendAsync(request); var filteredLogs = TestSink.Writes.Where(w => w.LoggerName.Contains("HttpLogging")); - Assert.Contains(filteredLogs, w => w.Message.Equals("RequestBody: fro")); + Assert.Contains(filteredLogs, w => w.Message.Equals("RequestBody: fro[Truncated by RequestBodyLogLimit]")); Assert.Contains(filteredLogs, w => w.Message.Equals("ResponseBody: testin")); } + [Fact] + public async Task InterceptorCanSeeAndOverrideExtensions() + { + var app = CreateApp(HttpLoggingFields.None, new FakeInterceptor(requestContext => + { + Assert.Equal(HttpLoggingFields.All, requestContext.LoggingFields); + requestContext.Disable(HttpLoggingFields.RequestHeaders); + }, + responseContext => + { + Assert.Equal(HttpLoggingFields.All & ~HttpLoggingFields.RequestHeaders, responseContext.LoggingFields); + responseContext.Disable(HttpLoggingFields.ResponseHeaders); + })); + await app.StartAsync(); + + using var server = app.GetTestServer(); + var client = server.CreateClient(); + var request = new HttpRequestMessage(HttpMethod.Get, "/ext_responseandrequest"); + request.Headers.TryAddWithoutValidation("Accept", "application/json"); + var initialResponse = await client.SendAsync(request); + + var filteredLogs = TestSink.Writes.Where(w => w.LoggerName.Contains("HttpLogging")); + Assert.Contains(filteredLogs, w => w.Message.Contains("Request")); + Assert.DoesNotContain(filteredLogs, w => w.Message.Contains("Accept")); + Assert.Contains(filteredLogs, w => w.Message.Contains("StatusCode: 200")); + Assert.DoesNotContain(filteredLogs, w => w.Message.Contains("Content-Type: text/plain")); + } + + [Fact] + public async Task MultipleInterceptorsRun() + { + var builder = new HostBuilder() + .ConfigureWebHost(webHostBuilder => + { + webHostBuilder + .UseTestServer() + .ConfigureServices(services => + { + services.AddRouting(); + services.AddHttpLogging(o => o.LoggingFields = HttpLoggingFields.All); + services.AddHttpLoggingInterceptor(); + services.AddHttpLoggingInterceptor(); + services.AddSingleton(LoggerFactory); + }) + .Configure(app => + { + app.UseRouting(); + app.UseHttpLogging(); + app.UseEndpoints(endpoint => + { + endpoint.MapGet("/", async (HttpContext c) => + { + await c.Request.Body.ReadAsync(new byte[100]); + return "testing"; + }); + }); + }); + }); + using var host = builder.Build(); + await host.StartAsync(); + + using var server = host.GetTestServer(); + var client = server.CreateClient(); + var request = new HttpRequestMessage(HttpMethod.Get, "/"); + request.Headers.TryAddWithoutValidation("Accept", "application/json"); + var initialResponse = await client.SendAsync(request); + + var filteredLogs = TestSink.Writes.Where(w => w.LoggerName.Contains("HttpLogging")); + + var requestLog = Assert.Single(filteredLogs, w => w.Message.Contains("Request:")); + Assert.Contains("i0request: v0", requestLog.Message); + Assert.Contains("i1request: v1", requestLog.Message); + + var responseLog = Assert.Single(filteredLogs, w => w.Message.Contains("Response:")); + Assert.Contains("i0response: v0", responseLog.Message); + Assert.Contains("i1response: v1", responseLog.Message); + } + + private static DefaultHttpContext CreateRequest() + { + var httpContext = new DefaultHttpContext(); + httpContext.Request.Protocol = "HTTP/1.0"; + httpContext.Request.Method = "GET"; + httpContext.Request.Scheme = "http"; + httpContext.Request.Path = new PathString("/foo"); + httpContext.Request.PathBase = new PathString("/foo"); + httpContext.Request.QueryString = new QueryString("?foo"); + httpContext.Request.Headers["Connection"] = "keep-alive"; + httpContext.Request.ContentType = "text/plain"; + httpContext.Request.Body = new MemoryStream(Encoding.UTF8.GetBytes("test")); + return httpContext; + } + private IOptionsMonitor CreateOptionsAccessor() { var options = new HttpLoggingOptions(); @@ -1279,7 +1972,37 @@ private IOptionsMonitor CreateOptionsAccessor() return optionsAccessor; } - private IHost CreateApp(HttpLoggingFields defaultFields = HttpLoggingFields.All) + private HttpLoggingMiddleware CreateMiddleware(RequestDelegate app = null, + IOptionsMonitor options = null, + IHttpLoggingInterceptor interceptor = null) + { + return new HttpLoggingMiddleware( + app ?? (c => Task.CompletedTask), + options ?? CreateOptionsAccessor(), + LoggerFactory.CreateLogger(), + interceptor == null ? Array.Empty() : [interceptor], + ObjectPool.Create(), + TimeProvider.System); + } + + private static async Task RequestResponseApp(HttpContext context) + { + var arr = new byte[4096]; + while (true) + { + var res = await context.Request.Body.ReadAsync(arr); + if (res == 0) + { + break; + } + } + + context.Response.StatusCode = StatusCodes.Status418ImATeapot; + context.Response.ContentType = "text/plain; p=response"; + await context.Response.WriteAsync("Hello World"); + } + + private IHost CreateApp(HttpLoggingFields defaultFields = HttpLoggingFields.All, IHttpLoggingInterceptor interceptor = null) { var builder = new HostBuilder() .ConfigureWebHost(webHostBuilder => @@ -1293,6 +2016,10 @@ private IHost CreateApp(HttpLoggingFields defaultFields = HttpLoggingFields.All) { o.LoggingFields = defaultFields; }); + if (interceptor != null) + { + services.AddSingleton(interceptor); + } services.AddSingleton(LoggerFactory); }) .Configure(app => @@ -1313,9 +2040,10 @@ private IHost CreateApp(HttpLoggingFields defaultFields = HttpLoggingFields.All) return "testing"; }).WithHttpLogging(HttpLoggingFields.Response); - endpoint.MapGet("/attr_responseandrequest", [HttpLogging(HttpLoggingFields.Request | HttpLoggingFields.Response)] async (HttpContext c) => + endpoint.MapGet("/attr_responseandrequest", [HttpLogging(HttpLoggingFields.All)] async (HttpContext c) => { await c.Request.Body.ReadAsync(new byte[100]); + c.Response.ContentType = "text/plain"; return "testing"; }); @@ -1323,7 +2051,7 @@ private IHost CreateApp(HttpLoggingFields defaultFields = HttpLoggingFields.All) { await c.Request.Body.ReadAsync(new byte[100]); return "testing"; - }).WithHttpLogging(HttpLoggingFields.Request | HttpLoggingFields.Response); + }).WithHttpLogging(HttpLoggingFields.All); endpoint.MapGet("/attr_restrictedheaders", [HttpLogging((HttpLoggingFields.Request & ~HttpLoggingFields.RequestScheme) | (HttpLoggingFields.Response & ~HttpLoggingFields.ResponseStatusCode))] async (HttpContext c) => { @@ -1337,7 +2065,7 @@ private IHost CreateApp(HttpLoggingFields defaultFields = HttpLoggingFields.All) return "testing"; }).WithHttpLogging((HttpLoggingFields.Request & ~HttpLoggingFields.RequestScheme) | (HttpLoggingFields.Response & ~HttpLoggingFields.ResponseStatusCode)); - endpoint.MapGet("/attr_restrictedsize", [HttpLogging(HttpLoggingFields.Request | HttpLoggingFields.Response, RequestBodyLogLimit = 3, ResponseBodyLogLimit = 6)] async (HttpContext c) => + endpoint.MapGet("/attr_restrictedsize", [HttpLogging(HttpLoggingFields.RequestBody | HttpLoggingFields.ResponseBody, RequestBodyLogLimit = 3, ResponseBodyLogLimit = 6)] async (HttpContext c) => { await c.Request.Body.ReadAsync(new byte[100]); return "testing"; @@ -1347,10 +2075,55 @@ private IHost CreateApp(HttpLoggingFields defaultFields = HttpLoggingFields.All) { await c.Request.Body.ReadAsync(new byte[100]); return "testing"; - }).WithHttpLogging(HttpLoggingFields.Request | HttpLoggingFields.Response, requestBodyLogLimit: 3, responseBodyLogLimit: 6); + }).WithHttpLogging(HttpLoggingFields.RequestBody | HttpLoggingFields.ResponseBody, requestBodyLogLimit: 3, responseBodyLogLimit: 6); }); }); }); return builder.Build(); } + + private class FakeInterceptor(Action interceptRequest, Action interceptResponse = null) : IHttpLoggingInterceptor + { + public ValueTask OnRequestAsync(HttpLoggingInterceptorContext logContext) + { + interceptRequest(logContext); + return default; + } + + public ValueTask OnResponseAsync(HttpLoggingInterceptorContext logContext) + { + interceptResponse?.Invoke(logContext); + return default; + } + } + + private class FakeInterceptor0() : IHttpLoggingInterceptor + { + public ValueTask OnRequestAsync(HttpLoggingInterceptorContext logContext) + { + logContext.AddParameter("i0request", "v0"); + return default; + } + + public ValueTask OnResponseAsync(HttpLoggingInterceptorContext logContext) + { + logContext.AddParameter("i0response", "v0"); + return default; + } + } + + private class FakeInterceptor1() : IHttpLoggingInterceptor + { + public ValueTask OnRequestAsync(HttpLoggingInterceptorContext logContext) + { + logContext.AddParameter("i1request", "v1"); + return default; + } + + public ValueTask OnResponseAsync(HttpLoggingInterceptorContext logContext) + { + logContext.AddParameter("i1response", "v1"); + return default; + } + } }