diff --git a/src/Middleware/HttpLogging/src/RequestBufferingStream.cs b/src/Middleware/HttpLogging/src/RequestBufferingStream.cs index d981cba8d5ce..b65269add321 100644 --- a/src/Middleware/HttpLogging/src/RequestBufferingStream.cs +++ b/src/Middleware/HttpLogging/src/RequestBufferingStream.cs @@ -13,6 +13,7 @@ internal sealed class RequestBufferingStream : BufferingStream private readonly bool _logOnFinish; private readonly int _limit; private BodyStatus _status = BodyStatus.None; + private string? _bodyBeforeClose; public bool HasLogged { get; private set; } @@ -116,7 +117,7 @@ public void LogRequestBody() if (!HasLogged && _logOnFinish) { HasLogged = true; - _logger.RequestBody(GetString(_encoding), GetStatus(showCompleted: false)); + _logger.RequestBody(GetStringInternal(), GetStatus(showCompleted: false)); } } @@ -124,7 +125,7 @@ public void LogRequestBody(HttpLoggingInterceptorContext logContext) { if (logContext.IsAnyEnabled(HttpLoggingFields.RequestBody)) { - logContext.AddParameter("RequestBody", GetString(_encoding)); + logContext.AddParameter("RequestBody", GetStringInternal()); logContext.AddParameter("RequestBodyStatus", GetStatus(showCompleted: true)); } } @@ -138,6 +139,25 @@ public void LogRequestBody(HttpLoggingInterceptorContext logContext) _ => throw new NotImplementedException(_status.ToString()), }; + private string GetStringInternal() + { + var result = _bodyBeforeClose ?? GetString(_encoding); + // Reset the value after its consumption to preserve GetString(encoding) behavior + _bodyBeforeClose = null; + return result; + } + + public override void Close() + { + if (!HasLogged) + { + // Subsequent middleware can close the request stream after reading enough bytes (guided by ContentLength). + // Preserving the body for the final GetStringInternal() call. + _bodyBeforeClose = GetString(_encoding); + } + base.Close(); + } + public override IAsyncResult BeginRead(byte[] buffer, int offset, int count, AsyncCallback? callback, object? state) { return TaskToApm.Begin(ReadAsync(buffer, offset, count), callback, state); diff --git a/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs b/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs index 3a9baa9272c6..b408f633aa28 100644 --- a/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs +++ b/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs @@ -19,7 +19,9 @@ internal sealed class ResponseBufferingStream : BufferingStream, IHttpResponseBo private readonly HttpLoggingOptions _options; private readonly IHttpLoggingInterceptor[] _interceptors; private bool _logBody; + private bool _hasLogged; private Encoding? _encoding; + private string? _bodyBeforeClose; private static readonly StreamPipeWriterOptions _pipeWriterOptions = new StreamPipeWriterOptions(leaveOpen: true); @@ -179,8 +181,9 @@ public void LogResponseBody() { if (_logBody) { - var responseBody = GetString(_encoding!); + var responseBody = GetStringInternal(); _logger.ResponseBody(responseBody); + _hasLogged = true; } } @@ -188,7 +191,28 @@ public void LogResponseBody(HttpLoggingInterceptorContext logContext) { if (_logBody) { - logContext.AddParameter("ResponseBody", GetString(_encoding!)); + logContext.AddParameter("ResponseBody", GetStringInternal()); + _hasLogged = true; } } + + private string GetStringInternal() + { + var result = _bodyBeforeClose ?? GetString(_encoding!); + // Reset the value after its consumption to preserve GetString(encoding) behavior + _bodyBeforeClose = null; + return result; + } + + public override void Close() + { + if (_logBody && !_hasLogged) + { + // Subsequent middleware can close the response stream after writing its body + // Preserving the body for the final GetStringInternal() call. + _bodyBeforeClose = GetString(_encoding!); + } + + base.Close(); + } } diff --git a/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs b/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs index 45601db82f5a..7a67683907a7 100644 --- a/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs +++ b/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs @@ -390,6 +390,46 @@ public async Task RequestBodyCopyToAsyncWorks(string expected) Assert.Contains(TestSink.Writes, w => w.Message.Contains(expected)); } + [Theory] + [MemberData(nameof(BodyData))] + public async Task RequestBodyWithStreamCloseWorks(string expected) + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody; + + var middleware = CreateMiddleware( + async c => + { + var arr = new byte[4096]; + var contentLengthBytesLeft = c.Request.Body.Length; + + // (1) The subsequent middleware reads right up to the buffer size (guided by the ContentLength header) + while (contentLengthBytesLeft > 0) + { + var res = await c.Request.Body.ReadAsync(arr, 0, arr.Length); + contentLengthBytesLeft -= res; + if (res == 0) + { + break; + } + } + + // (2) The subsequent middleware closes the request stream after its consumption + c.Request.Body.Close(); + }, + options); + + var httpContext = new DefaultHttpContext(); + httpContext.Request.ContentType = "text/plain"; + var buffer = Encoding.UTF8.GetBytes(expected); + httpContext.Request.Body = new MemoryStream(buffer); + httpContext.Request.ContentLength = buffer.Length; + + await middleware.Invoke(httpContext); + + Assert.Contains(TestSink.Writes, w => w.Message.Contains(expected)); + } + [Fact] public async Task RequestBodyReadingLimitLongCharactersWorks() { @@ -1155,6 +1195,32 @@ public async Task StartAsyncResponseHeadersLogged() await middlewareTask; } + [Theory] + [MemberData(nameof(BodyData))] + public async Task ResponseBodyWithStreamCloseWorks(string expected) + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseBody; + var middleware = CreateMiddleware( + async c => + { + c.Response.ContentType = "text/plain"; + + // (1) The subsequent middleware writes its response + await c.Response.WriteAsync(expected); + + // (2) The subsequent middleware closes the response stream after it has completed writing to it + c.Response.Body.Close(); + }, + options); + + var httpContext = new DefaultHttpContext(); + + await middleware.Invoke(httpContext); + + Assert.Contains(TestSink.Writes, w => w.Message.Contains(expected)); + } + [Fact] public async Task UnrecognizedMediaType() { @@ -1606,6 +1672,72 @@ public async Task CombineLogs_Exception_RequestLogged() Assert.Equal(lines.Length, i); } + [Theory] + [InlineData(HttpLoggingFields.RequestBody | HttpLoggingFields.ResponseBody)] + [InlineData(HttpLoggingFields.RequestBody)] + [InlineData(HttpLoggingFields.ResponseBody)] + public async Task CombineLogsWithStreamCloseWorks(HttpLoggingFields fields) + { + var options = CreateOptionsAccessor(); + options.CurrentValue.LoggingFields = fields; + options.CurrentValue.CombineLogs = true; + + var middleware = CreateMiddleware( + async c => + { + var arr = new byte[4096]; + var contentLengthBytesLeft = c.Request.Body.Length; + + // (1) The subsequent middleware reads right up to the buffer size (guided by the ContentLength header) + while (contentLengthBytesLeft > 0) + { + var res = await c.Request.Body.ReadAsync(arr, 0, arr.Length); + contentLengthBytesLeft -= res; + if (res == 0) + { + break; + } + } + + // (2) The subsequent middleware closes the request stream after its consumption + c.Request.Body.Close(); + + c.Response.ContentType = "text/plain"; + + // (3) The subsequent middleware writes its response + await c.Response.WriteAsync("test response"); + + // (4) The subsequent middleware closes the response stream after it has completed writing to it + c.Response.Body.Close(); + }, + options); + + var httpContext = new DefaultHttpContext(); + httpContext.Request.ContentType = "text/plain"; + var requestBodyBuffer = Encoding.UTF8.GetBytes("test request"); + httpContext.Request.Body = new MemoryStream(requestBodyBuffer); + httpContext.Request.ContentLength = requestBodyBuffer.Length; + + 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.RequestBody)) + { + Assert.Equal("RequestBody: test request", lines[i++]); + // Here we expect "Only partially consumed by app" status as the middleware reads request body right to its end, + // but never further as it follows the ContentLength header. From logging middleware perspective it looks like + // a partial consumption as it can't know for sure if it has been drained to the end or not. + Assert.Equal("RequestBodyStatus: [Only partially consumed by app]", lines[i++]); + } + if (fields.HasFlag(HttpLoggingFields.ResponseBody)) + { + Assert.Equal("ResponseBody: test response", lines[i++]); + } + Assert.Equal(lines.Length, i); + } + [Fact] public async Task ResponseInterceptorCanDisableResponseLogs() {