Skip to content

Commit 0e7095b

Browse files
authored
Fix HttpLoggingMiddleware Request/Response bodies logging in case of stream being closed by a subsequent middleware (#61490)
1 parent 1730530 commit 0e7095b

File tree

3 files changed

+180
-4
lines changed

3 files changed

+180
-4
lines changed

src/Middleware/HttpLogging/src/RequestBufferingStream.cs

Lines changed: 22 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ internal sealed class RequestBufferingStream : BufferingStream
1313
private readonly bool _logOnFinish;
1414
private readonly int _limit;
1515
private BodyStatus _status = BodyStatus.None;
16+
private string? _bodyBeforeClose;
1617

1718
public bool HasLogged { get; private set; }
1819

@@ -116,15 +117,15 @@ public void LogRequestBody()
116117
if (!HasLogged && _logOnFinish)
117118
{
118119
HasLogged = true;
119-
_logger.RequestBody(GetString(_encoding), GetStatus(showCompleted: false));
120+
_logger.RequestBody(GetStringInternal(), GetStatus(showCompleted: false));
120121
}
121122
}
122123

123124
public void LogRequestBody(HttpLoggingInterceptorContext logContext)
124125
{
125126
if (logContext.IsAnyEnabled(HttpLoggingFields.RequestBody))
126127
{
127-
logContext.AddParameter("RequestBody", GetString(_encoding));
128+
logContext.AddParameter("RequestBody", GetStringInternal());
128129
logContext.AddParameter("RequestBodyStatus", GetStatus(showCompleted: true));
129130
}
130131
}
@@ -138,6 +139,25 @@ public void LogRequestBody(HttpLoggingInterceptorContext logContext)
138139
_ => throw new NotImplementedException(_status.ToString()),
139140
};
140141

142+
private string GetStringInternal()
143+
{
144+
var result = _bodyBeforeClose ?? GetString(_encoding);
145+
// Reset the value after its consumption to preserve GetString(encoding) behavior
146+
_bodyBeforeClose = null;
147+
return result;
148+
}
149+
150+
public override void Close()
151+
{
152+
if (!HasLogged)
153+
{
154+
// Subsequent middleware can close the request stream after reading enough bytes (guided by ContentLength).
155+
// Preserving the body for the final GetStringInternal() call.
156+
_bodyBeforeClose = GetString(_encoding);
157+
}
158+
base.Close();
159+
}
160+
141161
public override IAsyncResult BeginRead(byte[] buffer, int offset, int count, AsyncCallback? callback, object? state)
142162
{
143163
return TaskToApm.Begin(ReadAsync(buffer, offset, count), callback, state);

src/Middleware/HttpLogging/src/ResponseBufferingStream.cs

Lines changed: 26 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,9 @@ internal sealed class ResponseBufferingStream : BufferingStream, IHttpResponseBo
1919
private readonly HttpLoggingOptions _options;
2020
private readonly IHttpLoggingInterceptor[] _interceptors;
2121
private bool _logBody;
22+
private bool _hasLogged;
2223
private Encoding? _encoding;
24+
private string? _bodyBeforeClose;
2325

2426
private static readonly StreamPipeWriterOptions _pipeWriterOptions = new StreamPipeWriterOptions(leaveOpen: true);
2527

@@ -179,16 +181,38 @@ public void LogResponseBody()
179181
{
180182
if (_logBody)
181183
{
182-
var responseBody = GetString(_encoding!);
184+
var responseBody = GetStringInternal();
183185
_logger.ResponseBody(responseBody);
186+
_hasLogged = true;
184187
}
185188
}
186189

187190
public void LogResponseBody(HttpLoggingInterceptorContext logContext)
188191
{
189192
if (_logBody)
190193
{
191-
logContext.AddParameter("ResponseBody", GetString(_encoding!));
194+
logContext.AddParameter("ResponseBody", GetStringInternal());
195+
_hasLogged = true;
192196
}
193197
}
198+
199+
private string GetStringInternal()
200+
{
201+
var result = _bodyBeforeClose ?? GetString(_encoding!);
202+
// Reset the value after its consumption to preserve GetString(encoding) behavior
203+
_bodyBeforeClose = null;
204+
return result;
205+
}
206+
207+
public override void Close()
208+
{
209+
if (_logBody && !_hasLogged)
210+
{
211+
// Subsequent middleware can close the response stream after writing its body
212+
// Preserving the body for the final GetStringInternal() call.
213+
_bodyBeforeClose = GetString(_encoding!);
214+
}
215+
216+
base.Close();
217+
}
194218
}

src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs

Lines changed: 132 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -390,6 +390,46 @@ public async Task RequestBodyCopyToAsyncWorks(string expected)
390390
Assert.Contains(TestSink.Writes, w => w.Message.Contains(expected));
391391
}
392392

393+
[Theory]
394+
[MemberData(nameof(BodyData))]
395+
public async Task RequestBodyWithStreamCloseWorks(string expected)
396+
{
397+
var options = CreateOptionsAccessor();
398+
options.CurrentValue.LoggingFields = HttpLoggingFields.RequestBody;
399+
400+
var middleware = CreateMiddleware(
401+
async c =>
402+
{
403+
var arr = new byte[4096];
404+
var contentLengthBytesLeft = c.Request.Body.Length;
405+
406+
// (1) The subsequent middleware reads right up to the buffer size (guided by the ContentLength header)
407+
while (contentLengthBytesLeft > 0)
408+
{
409+
var res = await c.Request.Body.ReadAsync(arr, 0, arr.Length);
410+
contentLengthBytesLeft -= res;
411+
if (res == 0)
412+
{
413+
break;
414+
}
415+
}
416+
417+
// (2) The subsequent middleware closes the request stream after its consumption
418+
c.Request.Body.Close();
419+
},
420+
options);
421+
422+
var httpContext = new DefaultHttpContext();
423+
httpContext.Request.ContentType = "text/plain";
424+
var buffer = Encoding.UTF8.GetBytes(expected);
425+
httpContext.Request.Body = new MemoryStream(buffer);
426+
httpContext.Request.ContentLength = buffer.Length;
427+
428+
await middleware.Invoke(httpContext);
429+
430+
Assert.Contains(TestSink.Writes, w => w.Message.Contains(expected));
431+
}
432+
393433
[Fact]
394434
public async Task RequestBodyReadingLimitLongCharactersWorks()
395435
{
@@ -1155,6 +1195,32 @@ public async Task StartAsyncResponseHeadersLogged()
11551195
await middlewareTask;
11561196
}
11571197

1198+
[Theory]
1199+
[MemberData(nameof(BodyData))]
1200+
public async Task ResponseBodyWithStreamCloseWorks(string expected)
1201+
{
1202+
var options = CreateOptionsAccessor();
1203+
options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseBody;
1204+
var middleware = CreateMiddleware(
1205+
async c =>
1206+
{
1207+
c.Response.ContentType = "text/plain";
1208+
1209+
// (1) The subsequent middleware writes its response
1210+
await c.Response.WriteAsync(expected);
1211+
1212+
// (2) The subsequent middleware closes the response stream after it has completed writing to it
1213+
c.Response.Body.Close();
1214+
},
1215+
options);
1216+
1217+
var httpContext = new DefaultHttpContext();
1218+
1219+
await middleware.Invoke(httpContext);
1220+
1221+
Assert.Contains(TestSink.Writes, w => w.Message.Contains(expected));
1222+
}
1223+
11581224
[Fact]
11591225
public async Task UnrecognizedMediaType()
11601226
{
@@ -1606,6 +1672,72 @@ public async Task CombineLogs_Exception_RequestLogged()
16061672
Assert.Equal(lines.Length, i);
16071673
}
16081674

1675+
[Theory]
1676+
[InlineData(HttpLoggingFields.RequestBody | HttpLoggingFields.ResponseBody)]
1677+
[InlineData(HttpLoggingFields.RequestBody)]
1678+
[InlineData(HttpLoggingFields.ResponseBody)]
1679+
public async Task CombineLogsWithStreamCloseWorks(HttpLoggingFields fields)
1680+
{
1681+
var options = CreateOptionsAccessor();
1682+
options.CurrentValue.LoggingFields = fields;
1683+
options.CurrentValue.CombineLogs = true;
1684+
1685+
var middleware = CreateMiddleware(
1686+
async c =>
1687+
{
1688+
var arr = new byte[4096];
1689+
var contentLengthBytesLeft = c.Request.Body.Length;
1690+
1691+
// (1) The subsequent middleware reads right up to the buffer size (guided by the ContentLength header)
1692+
while (contentLengthBytesLeft > 0)
1693+
{
1694+
var res = await c.Request.Body.ReadAsync(arr, 0, arr.Length);
1695+
contentLengthBytesLeft -= res;
1696+
if (res == 0)
1697+
{
1698+
break;
1699+
}
1700+
}
1701+
1702+
// (2) The subsequent middleware closes the request stream after its consumption
1703+
c.Request.Body.Close();
1704+
1705+
c.Response.ContentType = "text/plain";
1706+
1707+
// (3) The subsequent middleware writes its response
1708+
await c.Response.WriteAsync("test response");
1709+
1710+
// (4) The subsequent middleware closes the response stream after it has completed writing to it
1711+
c.Response.Body.Close();
1712+
},
1713+
options);
1714+
1715+
var httpContext = new DefaultHttpContext();
1716+
httpContext.Request.ContentType = "text/plain";
1717+
var requestBodyBuffer = Encoding.UTF8.GetBytes("test request");
1718+
httpContext.Request.Body = new MemoryStream(requestBodyBuffer);
1719+
httpContext.Request.ContentLength = requestBodyBuffer.Length;
1720+
1721+
await middleware.Invoke(httpContext);
1722+
1723+
var lines = Assert.Single(TestSink.Writes.Where(w => w.LogLevel >= LogLevel.Information)).Message.Split(Environment.NewLine);
1724+
var i = 0;
1725+
Assert.Equal("Request and Response:", lines[i++]);
1726+
if (fields.HasFlag(HttpLoggingFields.RequestBody))
1727+
{
1728+
Assert.Equal("RequestBody: test request", lines[i++]);
1729+
// Here we expect "Only partially consumed by app" status as the middleware reads request body right to its end,
1730+
// but never further as it follows the ContentLength header. From logging middleware perspective it looks like
1731+
// a partial consumption as it can't know for sure if it has been drained to the end or not.
1732+
Assert.Equal("RequestBodyStatus: [Only partially consumed by app]", lines[i++]);
1733+
}
1734+
if (fields.HasFlag(HttpLoggingFields.ResponseBody))
1735+
{
1736+
Assert.Equal("ResponseBody: test response", lines[i++]);
1737+
}
1738+
Assert.Equal(lines.Length, i);
1739+
}
1740+
16091741
[Fact]
16101742
public async Task ResponseInterceptorCanDisableResponseLogs()
16111743
{

0 commit comments

Comments
 (0)