From e21402bb665d6d248d23ad4e3738ef507702cfba Mon Sep 17 00:00:00 2001 From: ExtraClock <35864862+ExtraClock@users.noreply.github.com> Date: Mon, 14 Apr 2025 16:43:39 +0300 Subject: [PATCH 1/4] Fix HttpLoggingMiddleware Request/Response bodies logging in case of stream being closed by a subsequent middleware (#61489) --- .../HttpLogging/src/RequestBufferingStream.cs | 24 ++++++- .../src/ResponseBufferingStream.cs | 25 ++++++- .../test/HttpLoggingMiddlewareTests.cs | 66 +++++++++++++++++++ 3 files changed, 111 insertions(+), 4 deletions(-) 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..768de34453b4 100644 --- a/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs +++ b/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs @@ -20,6 +20,7 @@ internal sealed class ResponseBufferingStream : BufferingStream, IHttpResponseBo private readonly IHttpLoggingInterceptor[] _interceptors; private bool _logBody; private Encoding? _encoding; + private string? _bodyBeforeClose; private static readonly StreamPipeWriterOptions _pipeWriterOptions = new StreamPipeWriterOptions(leaveOpen: true); @@ -179,7 +180,7 @@ public void LogResponseBody() { if (_logBody) { - var responseBody = GetString(_encoding!); + var responseBody = GetStringInternal(); _logger.ResponseBody(responseBody); } } @@ -188,7 +189,27 @@ public void LogResponseBody(HttpLoggingInterceptorContext logContext) { if (_logBody) { - logContext.AddParameter("ResponseBody", GetString(_encoding!)); + logContext.AddParameter("ResponseBody", GetStringInternal()); } } + + 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) + { + // 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..7ed307ff02f6 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, (int)Math.Min(arr.Length, contentLengthBytesLeft)); + 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() { From 78855dc53b9ac0988117cf54780e1b386c24869f Mon Sep 17 00:00:00 2001 From: ExtraClock <35864862+ExtraClock@users.noreply.github.com> Date: Sat, 5 Jul 2025 16:11:27 +0300 Subject: [PATCH 2/4] handle "has logged" case in the response stream --- src/Middleware/HttpLogging/src/ResponseBufferingStream.cs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs b/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs index 768de34453b4..b408f633aa28 100644 --- a/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs +++ b/src/Middleware/HttpLogging/src/ResponseBufferingStream.cs @@ -19,6 +19,7 @@ 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; @@ -182,6 +183,7 @@ public void LogResponseBody() { var responseBody = GetStringInternal(); _logger.ResponseBody(responseBody); + _hasLogged = true; } } @@ -190,6 +192,7 @@ public void LogResponseBody(HttpLoggingInterceptorContext logContext) if (_logBody) { logContext.AddParameter("ResponseBody", GetStringInternal()); + _hasLogged = true; } } @@ -203,7 +206,7 @@ private string GetStringInternal() public override void Close() { - if (_logBody) + if (_logBody && !_hasLogged) { // Subsequent middleware can close the response stream after writing its body // Preserving the body for the final GetStringInternal() call. From b33ca1112c70360a5912167e3fa4cc1b251bd78a Mon Sep 17 00:00:00 2001 From: ExtraClock <35864862+ExtraClock@users.noreply.github.com> Date: Sat, 5 Jul 2025 16:11:46 +0300 Subject: [PATCH 3/4] add CombineLogsWithStreamCloseWorks test --- .../test/HttpLoggingMiddlewareTests.cs | 69 ++++++++++++++++++- 1 file changed, 68 insertions(+), 1 deletion(-) diff --git a/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs b/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs index 7ed307ff02f6..79baa2bde89e 100644 --- a/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs +++ b/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs @@ -406,7 +406,7 @@ public async Task RequestBodyWithStreamCloseWorks(string expected) // (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, (int)Math.Min(arr.Length, contentLengthBytesLeft)); + var res = await c.Request.Body.ReadAsync(arr, 0, arr.Length); contentLengthBytesLeft -= res; if (res == 0) { @@ -1672,6 +1672,73 @@ public async Task CombineLogs_Exception_RequestLogged() Assert.Equal(lines.Length, i); } + [Theory] + [InlineData(HttpLoggingFields.RequestBody | HttpLoggingFields.ResponseBody, true, true)] + [InlineData(HttpLoggingFields.RequestBody, true, false)] + [InlineData(HttpLoggingFields.ResponseBody, false, true)] + public async Task CombineLogsWithStreamCloseWorks(HttpLoggingFields fields, bool hasRequestBody, bool hasResponseBody) + { + 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() { From 743d1a2e12f5fed3358fdda87b9862da34bcd0ab Mon Sep 17 00:00:00 2001 From: ExtraClock <35864862+ExtraClock@users.noreply.github.com> Date: Sat, 5 Jul 2025 16:36:18 +0300 Subject: [PATCH 4/4] fix CI warnings --- .../HttpLogging/test/HttpLoggingMiddlewareTests.cs | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs b/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs index 79baa2bde89e..7a67683907a7 100644 --- a/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs +++ b/src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs @@ -1673,10 +1673,10 @@ public async Task CombineLogs_Exception_RequestLogged() } [Theory] - [InlineData(HttpLoggingFields.RequestBody | HttpLoggingFields.ResponseBody, true, true)] - [InlineData(HttpLoggingFields.RequestBody, true, false)] - [InlineData(HttpLoggingFields.ResponseBody, false, true)] - public async Task CombineLogsWithStreamCloseWorks(HttpLoggingFields fields, bool hasRequestBody, bool hasResponseBody) + [InlineData(HttpLoggingFields.RequestBody | HttpLoggingFields.ResponseBody)] + [InlineData(HttpLoggingFields.RequestBody)] + [InlineData(HttpLoggingFields.ResponseBody)] + public async Task CombineLogsWithStreamCloseWorks(HttpLoggingFields fields) { var options = CreateOptionsAccessor(); options.CurrentValue.LoggingFields = fields; @@ -1702,7 +1702,6 @@ public async Task CombineLogsWithStreamCloseWorks(HttpLoggingFields fields, bool // (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