Skip to content

Commit 5a5b2e2

Browse files
gfr-ggfr-g
authored
HttpLoggingMiddleware + Websockets/Upgrade (#40841)
1 parent 5e60992 commit 5a5b2e2

File tree

3 files changed

+324
-2
lines changed

3 files changed

+324
-2
lines changed

‎src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs

Lines changed: 37 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -131,10 +131,25 @@ private async Task InvokeInternal(HttpContext context)
131131
ResponseBufferingStream? responseBufferingStream = null;
132132
IHttpResponseBodyFeature? originalBodyFeature = null;
133133

134+
UpgradeFeatureLoggingDecorator? loggableUpgradeFeature = null;
135+
IHttpUpgradeFeature? originalUpgradeFeature = null;
136+
134137
try
135138
{
136139
var response = context.Response;
137140

141+
if (options.LoggingFields.HasFlag(HttpLoggingFields.ResponseStatusCode) || options.LoggingFields.HasFlag(HttpLoggingFields.ResponseHeaders))
142+
{
143+
originalUpgradeFeature = context.Features.Get<IHttpUpgradeFeature>();
144+
145+
if (originalUpgradeFeature != null && originalUpgradeFeature.IsUpgradableRequest)
146+
{
147+
loggableUpgradeFeature = new UpgradeFeatureLoggingDecorator(originalUpgradeFeature, response, options, _logger);
148+
149+
context.Features.Set<IHttpUpgradeFeature>(loggableUpgradeFeature);
150+
}
151+
}
152+
138153
if (options.LoggingFields.HasFlag(HttpLoggingFields.ResponseBody))
139154
{
140155
originalBodyFeature = context.Features.Get<IHttpResponseBodyFeature>()!;
@@ -159,9 +174,9 @@ private async Task InvokeInternal(HttpContext context)
159174
requestBufferingStream.LogRequestBody();
160175
}
161176

162-
if (responseBufferingStream == null || responseBufferingStream.FirstWrite == false)
177+
if (ResponseHeadersNotYetWritten(responseBufferingStream, loggableUpgradeFeature))
163178
{
164-
// No body, write headers here.
179+
// No body, not an upgradable request or request not upgraded, write headers here.
165180
LogResponseHeaders(response, options, _logger);
166181
}
167182

@@ -189,9 +204,29 @@ private async Task InvokeInternal(HttpContext context)
189204
{
190205
context.Request.Body = originalBody;
191206
}
207+
208+
if (loggableUpgradeFeature != null)
209+
{
210+
context.Features.Set(originalUpgradeFeature);
211+
}
192212
}
193213
}
194214

215+
private static bool ResponseHeadersNotYetWritten(ResponseBufferingStream? responseBufferingStream, UpgradeFeatureLoggingDecorator? upgradeFeatureLogging)
216+
{
217+
return BodyNotYetWritten(responseBufferingStream) && NotUpgradeableRequestOrRequestNotUpgraded(upgradeFeatureLogging);
218+
}
219+
220+
private static bool BodyNotYetWritten(ResponseBufferingStream? responseBufferingStream)
221+
{
222+
return responseBufferingStream == null || responseBufferingStream.FirstWrite == false;
223+
}
224+
225+
private static bool NotUpgradeableRequestOrRequestNotUpgraded(UpgradeFeatureLoggingDecorator? upgradeFeatureLogging)
226+
{
227+
return upgradeFeatureLogging == null || !upgradeFeatureLogging.IsUpgraded;
228+
}
229+
195230
private static void AddToList(List<KeyValuePair<string, object?>> list, string key, string? value)
196231
{
197232
list.Add(new KeyValuePair<string, object?>(key, value));

‎src/Middleware/HttpLogging/src/UpgradeFeatureLoggingDecorator.cs

Lines changed: 41 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,41 @@
1+
// Licensed to the .NET Foundation under one or more agreements.
2+
// The .NET Foundation licenses this file to you under the MIT license.
3+
4+
using Microsoft.AspNetCore.Http;
5+
using Microsoft.AspNetCore.Http.Features;
6+
using Microsoft.Extensions.Logging;
7+
8+
namespace Microsoft.AspNetCore.HttpLogging;
9+
10+
internal sealed class UpgradeFeatureLoggingDecorator : IHttpUpgradeFeature
11+
{
12+
private readonly IHttpUpgradeFeature _innerUpgradeFeature;
13+
private readonly HttpResponse _response;
14+
private readonly HttpLoggingOptions _options;
15+
private readonly ILogger _logger;
16+
17+
private bool _isUpgraded;
18+
19+
public UpgradeFeatureLoggingDecorator(IHttpUpgradeFeature innerUpgradeFeature, HttpResponse response, HttpLoggingOptions options, ILogger logger)
20+
{
21+
_innerUpgradeFeature = innerUpgradeFeature ?? throw new ArgumentNullException(nameof(innerUpgradeFeature));
22+
_response = response ?? throw new ArgumentNullException(nameof(response));
23+
_options = options ?? throw new ArgumentNullException(nameof(options));
24+
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
25+
}
26+
27+
public bool IsUpgradableRequest => _innerUpgradeFeature.IsUpgradableRequest;
28+
29+
public bool IsUpgraded { get => _isUpgraded; }
30+
31+
public async Task<Stream> UpgradeAsync()
32+
{
33+
var upgradeStream = await _innerUpgradeFeature.UpgradeAsync();
34+
35+
_isUpgraded = true;
36+
37+
HttpLoggingMiddleware.LogResponseHeaders(_response, _options, _logger);
38+
39+
return upgradeStream;
40+
}
41+
}

‎src/Middleware/HttpLogging/test/HttpLoggingMiddlewareTests.cs

Lines changed: 246 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33

44
using System.Text;
55
using Microsoft.AspNetCore.Http;
6+
using Microsoft.AspNetCore.Http.Features;
67
using Microsoft.AspNetCore.Testing;
78
using Microsoft.Extensions.Logging;
89
using Microsoft.Extensions.Options;
@@ -838,6 +839,251 @@ public async Task UnrecognizedMediaType()
838839
Assert.Contains(TestSink.Writes, w => w.Message.Contains("Unrecognized Content-Type for body."));
839840
}
840841

842+
[Fact]
843+
public async Task UpgradeToWebSocketLogsResponseStatusCodeWhenResponseIsFlushed()
844+
{
845+
var options = CreateOptionsAccessor();
846+
options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseStatusCode;
847+
848+
var writtenHeaders = new TaskCompletionSource();
849+
var letBodyFinish = new TaskCompletionSource();
850+
851+
var httpContext = new DefaultHttpContext();
852+
853+
var upgradeFeatureMock = new Mock<IHttpUpgradeFeature>();
854+
upgradeFeatureMock.Setup(m => m.IsUpgradableRequest).Returns(true);
855+
upgradeFeatureMock
856+
.Setup(m => m.UpgradeAsync())
857+
.Callback(() =>
858+
{
859+
httpContext.Response.StatusCode = StatusCodes.Status101SwitchingProtocols;
860+
httpContext.Response.Headers[HeaderNames.Connection] = HeaderNames.Upgrade;
861+
})
862+
.ReturnsAsync(Stream.Null);
863+
httpContext.Features.Set<IHttpUpgradeFeature>(upgradeFeatureMock.Object);
864+
865+
var middleware = new HttpLoggingMiddleware(
866+
async c =>
867+
{
868+
await c.Features.Get<IHttpUpgradeFeature>().UpgradeAsync();
869+
writtenHeaders.SetResult();
870+
await letBodyFinish.Task;
871+
},
872+
options,
873+
LoggerFactory.CreateLogger<HttpLoggingMiddleware>());
874+
875+
var middlewareTask = middleware.Invoke(httpContext);
876+
877+
await writtenHeaders.Task;
878+
879+
Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 101"));
880+
881+
letBodyFinish.SetResult();
882+
883+
await middlewareTask;
884+
}
885+
886+
[Fact]
887+
public async Task UpgradeToWebSocketLogsResponseHeadersWhenResponseIsFlushed()
888+
{
889+
var options = CreateOptionsAccessor();
890+
options.CurrentValue.LoggingFields = HttpLoggingFields.ResponseHeaders;
891+
892+
var writtenHeaders = new TaskCompletionSource();
893+
var letBodyFinish = new TaskCompletionSource();
894+
895+
var httpContext = new DefaultHttpContext();
896+
897+
var upgradeFeatureMock = new Mock<IHttpUpgradeFeature>();
898+
upgradeFeatureMock.Setup(m => m.IsUpgradableRequest).Returns(true);
899+
upgradeFeatureMock
900+
.Setup(m => m.UpgradeAsync())
901+
.Callback(() =>
902+
{
903+
httpContext.Response.StatusCode = StatusCodes.Status101SwitchingProtocols;
904+
httpContext.Response.Headers[HeaderNames.Connection] = HeaderNames.Upgrade;
905+
})
906+
.ReturnsAsync(Stream.Null);
907+
httpContext.Features.Set<IHttpUpgradeFeature>(upgradeFeatureMock.Object);
908+
909+
var middleware = new HttpLoggingMiddleware(
910+
async c =>
911+
{
912+
await c.Features.Get<IHttpUpgradeFeature>().UpgradeAsync();
913+
writtenHeaders.SetResult();
914+
await letBodyFinish.Task;
915+
},
916+
options,
917+
LoggerFactory.CreateLogger<HttpLoggingMiddleware>());
918+
919+
var middlewareTask = middleware.Invoke(httpContext);
920+
921+
await writtenHeaders.Task;
922+
923+
Assert.Contains(TestSink.Writes, w => w.Message.Contains("Connection: Upgrade"));
924+
925+
letBodyFinish.SetResult();
926+
927+
await middlewareTask;
928+
}
929+
930+
[Fact]
931+
public async Task UpgradeToWebSocketDoesNotLogWhenResponseIsFlushedIfLoggingOptionsAreOtherThanResponseStatusCodeOrResponseHeaders()
932+
{
933+
var options = CreateOptionsAccessor();
934+
options.CurrentValue.LoggingFields = HttpLoggingFields.All ^ HttpLoggingFields.ResponsePropertiesAndHeaders;
935+
936+
var writtenHeaders = new TaskCompletionSource();
937+
var letBodyFinish = new TaskCompletionSource();
938+
939+
var httpContext = new DefaultHttpContext();
940+
941+
var upgradeFeatureMock = new Mock<IHttpUpgradeFeature>();
942+
upgradeFeatureMock.Setup(m => m.IsUpgradableRequest).Returns(true);
943+
upgradeFeatureMock
944+
.Setup(m => m.UpgradeAsync())
945+
.Callback(() =>
946+
{
947+
httpContext.Response.StatusCode = StatusCodes.Status101SwitchingProtocols;
948+
httpContext.Response.Headers[HeaderNames.Connection] = HeaderNames.Upgrade;
949+
})
950+
.ReturnsAsync(Stream.Null);
951+
httpContext.Features.Set<IHttpUpgradeFeature>(upgradeFeatureMock.Object);
952+
953+
var middleware = new HttpLoggingMiddleware(
954+
async c =>
955+
{
956+
await c.Features.Get<IHttpUpgradeFeature>().UpgradeAsync();
957+
writtenHeaders.SetResult();
958+
await letBodyFinish.Task;
959+
},
960+
options,
961+
LoggerFactory.CreateLogger<HttpLoggingMiddleware>());
962+
963+
var middlewareTask = middleware.Invoke(httpContext);
964+
965+
await writtenHeaders.Task;
966+
967+
Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("StatusCode: 101"));
968+
Assert.DoesNotContain(TestSink.Writes, w => w.Message.Contains("Connection: Upgrade"));
969+
970+
letBodyFinish.SetResult();
971+
972+
await middlewareTask;
973+
}
974+
975+
[Theory]
976+
[InlineData(false)]
977+
[InlineData(true)]
978+
public async Task LogsWrittenOutsideUpgradeWrapperIfUpgradeDoesNotOccur(bool isUpgradableRequest)
979+
{
980+
var options = CreateOptionsAccessor();
981+
options.CurrentValue.LoggingFields = HttpLoggingFields.ResponsePropertiesAndHeaders;
982+
983+
var httpContext = new DefaultHttpContext();
984+
985+
var upgradeFeatureMock = new Mock<IHttpUpgradeFeature>();
986+
upgradeFeatureMock.Setup(m => m.IsUpgradableRequest).Returns(isUpgradableRequest);
987+
httpContext.Features.Set<IHttpUpgradeFeature>(upgradeFeatureMock.Object);
988+
989+
var middleware = new HttpLoggingMiddleware(
990+
async c =>
991+
{
992+
c.Response.StatusCode = 200;
993+
c.Response.Headers[HeaderNames.TransferEncoding] = "test";
994+
c.Response.ContentType = "text/plain";
995+
await c.Response.StartAsync();
996+
},
997+
options,
998+
LoggerFactory.CreateLogger<HttpLoggingMiddleware>());
999+
1000+
var middlewareTask = middleware.Invoke(httpContext);
1001+
1002+
Assert.Contains(TestSink.Writes, w => w.Message.Contains("StatusCode: 200"));
1003+
Assert.Contains(TestSink.Writes, w => w.Message.Contains("Transfer-Encoding: test"));
1004+
Assert.Contains(TestSink.Writes, w => w.Message.Contains("Content-Type: text/plain"));
1005+
Assert.Null(
1006+
Record.Exception(() => upgradeFeatureMock.Verify(m => m.UpgradeAsync(), Times.Never)));
1007+
1008+
await middlewareTask;
1009+
}
1010+
1011+
[Theory]
1012+
[InlineData(HttpLoggingFields.ResponseStatusCode)]
1013+
[InlineData(HttpLoggingFields.ResponseHeaders)]
1014+
public async Task UpgradeToWebSocketLogsWrittenOnlyOnce(HttpLoggingFields loggingFields)
1015+
{
1016+
var options = CreateOptionsAccessor();
1017+
options.CurrentValue.LoggingFields = loggingFields;
1018+
1019+
var httpContext = new DefaultHttpContext();
1020+
1021+
var upgradeFeatureMock = new Mock<IHttpUpgradeFeature>();
1022+
upgradeFeatureMock.Setup(m => m.IsUpgradableRequest).Returns(true);
1023+
upgradeFeatureMock
1024+
.Setup(m => m.UpgradeAsync())
1025+
.Callback(() =>
1026+
{
1027+
httpContext.Response.StatusCode = StatusCodes.Status101SwitchingProtocols;
1028+
httpContext.Response.Headers[HeaderNames.Connection] = HeaderNames.Upgrade;
1029+
})
1030+
.ReturnsAsync(Stream.Null);
1031+
httpContext.Features.Set<IHttpUpgradeFeature>(upgradeFeatureMock.Object);
1032+
1033+
var writeCount = 0;
1034+
TestSink.MessageLogged += (context) => { writeCount++; };
1035+
1036+
var middleware = new HttpLoggingMiddleware(
1037+
async c =>
1038+
{
1039+
await c.Features.Get<IHttpUpgradeFeature>().UpgradeAsync();
1040+
},
1041+
options,
1042+
LoggerFactory.CreateLogger<HttpLoggingMiddleware>());
1043+
1044+
await middleware.Invoke(httpContext);
1045+
1046+
Assert.Equal(1, writeCount);
1047+
}
1048+
1049+
[Theory]
1050+
[InlineData(HttpLoggingFields.ResponseStatusCode)]
1051+
[InlineData(HttpLoggingFields.ResponseHeaders)]
1052+
public async Task OriginalUpgradeFeatureIsRestoredBeforeMiddlewareCompletes(HttpLoggingFields loggingFields)
1053+
{
1054+
var options = CreateOptionsAccessor();
1055+
options.CurrentValue.LoggingFields = loggingFields;
1056+
1057+
var letBodyFinish = new TaskCompletionSource();
1058+
1059+
var httpContext = new DefaultHttpContext();
1060+
1061+
var upgradeFeatureMock = new Mock<IHttpUpgradeFeature>();
1062+
upgradeFeatureMock.Setup(m => m.IsUpgradableRequest).Returns(true);
1063+
upgradeFeatureMock.Setup(m => m.UpgradeAsync()).ReturnsAsync(Stream.Null);
1064+
httpContext.Features.Set<IHttpUpgradeFeature>(upgradeFeatureMock.Object);
1065+
1066+
IHttpUpgradeFeature upgradeFeature = null;
1067+
1068+
var middleware = new HttpLoggingMiddleware(
1069+
async c =>
1070+
{
1071+
upgradeFeature = c.Features.Get<IHttpUpgradeFeature>();
1072+
await letBodyFinish.Task;
1073+
},
1074+
options,
1075+
LoggerFactory.CreateLogger<HttpLoggingMiddleware>());
1076+
1077+
var middlewareTask = middleware.Invoke(httpContext);
1078+
1079+
Assert.True(upgradeFeature is UpgradeFeatureLoggingDecorator);
1080+
1081+
letBodyFinish.SetResult();
1082+
await middlewareTask;
1083+
1084+
Assert.False(httpContext.Features.Get<IHttpUpgradeFeature>() is UpgradeFeatureLoggingDecorator);
1085+
}
1086+
8411087
private IOptionsMonitor<HttpLoggingOptions> CreateOptionsAccessor()
8421088
{
8431089
var options = new HttpLoggingOptions();

0 commit comments

Comments
 (0)