-
Notifications
You must be signed in to change notification settings - Fork 10.4k
Fix HttpLoggingMiddleware Request/Response bodies logging in case of stream being closed by a subsequent middleware #61490
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
e21402b
78855dc
b33ca11
743d1a2
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -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,16 +181,38 @@ public void LogResponseBody() | |
{ | ||
if (_logBody) | ||
{ | ||
var responseBody = GetString(_encoding!); | ||
var responseBody = GetStringInternal(); | ||
_logger.ResponseBody(responseBody); | ||
_hasLogged = true; | ||
} | ||
} | ||
|
||
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() | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
I think the request stream impl is fine, but we should double-check and maybe add a comment about the assumption. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Basically it's going to fetch an interned empty string (refer to BufferingStream.cs#L57), but I agree that it's better to protect this code from this kind of opportunity. I'm going to add |
||
{ | ||
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(); | ||
} | ||
} |
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -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)); | ||
} | ||
|
||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Could we add a test for There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Done |
||
[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() | ||
{ | ||
|
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Can we pass
HttpLoggingInterceptorContext
into the ctor like we do for the response stream and then check if body logging is enabled before getting the string?There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Unlike response stream, the request stream is created only if request body logging is enabled.
Refer to HttpLoggingMiddleware.cs#L97, L107, L153-L176