Adds HttpLogging middleware #31816

jkotalik · 2021-04-14T21:22:57Z

Fixes #3700

There are a few follow up issues that I'll file:

W3C Logging
Request Response Trailers Logging
Redaction/Additional logging

I'll write the API proposal in the issue linked with the information here.

There are a few tests failing ATM as I have some questions that review will help with.

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs

src/Middleware/HttpLogging/src/HttpLoggingExtensions.cs

src/Middleware/HttpLogging/src/HttpLoggingOptions.cs

src/Middleware/HttpLogging/src/ResponseBufferingStream.cs

src/Middleware/HttpLogging/src/HttpLoggingFields.cs

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs

src/Middleware/HttpLogging/src/HttpLoggingOptions.cs

src/Middleware/HttpLogging/src/HttpLoggingServicesExtensions.cs

src/Middleware/HttpLogging/src/HttpRequestLog.cs

src/Middleware/HttpLogging/src/HttpResponseLog.cs

davidfowl · 2021-04-15T02:50:41Z

We need to do an api review

jkotalik · 2021-04-15T02:58:25Z

For sure; I'm scheduling one for tomorrow/friday one off.

ghost · 2021-04-15T02:59:36Z

Thank you for submitting this for API review. This will be reviewed by @dotnet/aspnet-api-review at the next meeting of the ASP.NET Core API Review group. Please ensure you take a look at the API review process documentation and ensure that:

The PR contains changes to the reference-assembly that describe the API change. Or, you have included a snippet of reference-assembly-style code that illustrates the API change.
The PR describes the impact to users, both positive (useful new APIs) and negative (breaking changes).
Someone is assigned to "champion" this change in the meeting, and they understand the impact and design of the change.

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs

src/Middleware/HttpLogging/src/HttpLoggingOptions.cs

src/Middleware/HttpLogging/src/ResponseBufferingStream.cs

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs

davidfowl · 2021-04-20T05:36:30Z

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs

+        private readonly IOptionsMonitor<HttpLoggingOptions> _options;
+        private const int DefaultRequestFieldsMinusHeaders = 7;
+        private const int DefaultResponseFieldsMinusHeaders = 2;
+        private const string Redacted = "X";


[Redacted] instead of X

davidfowl · 2021-04-20T05:42:12Z

src/Middleware/HttpLogging/src/HttpLoggingOptions.cs

+        /// <summary>
+        /// Maximum request body size to log (in bytes). Defaults to 32 KB.
+        /// </summary>
+        public int RequestBodyLogLimit { get; set; } = 32 * 1024;


Do we need Size in this name? We have size everywhere else in Kestrel.

long RequestBodySizeLimit long ResponseBodySizeLimit

Why didn't we go with longs, we didn't learn from IIS 😄

It's a long in Kestrel. I can only imagine the logs with 2 GB+ bodies inside 😆

We could even make it nullable for consistency with Kestrel. Why force an upper bound of 2^63 bytes!

Is this a serious conversation? I guess we can make it a long....

OK we can leave it as an int and rename it to SizeLimit

We covered this in the API review and picked LogLimit over SizeLimit. In kestrel it's an absolute size limit and exceeding it causes the request to fail. Here it's a limit on the amount that will be logged before we truncate.

You really want to support GB of logged data? We'll definitely need to switch to a chunking/streaming model then to avoid buffering the whole thing.

Lets stick with an int (2GB is still GB) but I think Size should be in the name. It's the size of the request and response body in bytes.

I agree with @Tratcher, unless we have a name like RequestBodyLogSizeLimit which seems needlessly verbose.

src/Middleware/HttpLogging/src/HttpRequestLog.cs

src/Middleware/HttpLogging/src/MediaTypeOptions.cs

davidfowl · 2021-04-20T06:14:12Z

src/Middleware/HttpLogging/src/MediaTypeOptions.cs

+        /// <param name="contentType">The content type to add.</param>
+        public void AddBinary(string contentType)
+        {
+            throw new NotSupportedException();


What's the deal here?

Wanted to have the APIs present for binary logging format, which are currently not supported.

davidfowl · 2021-04-20T06:56:00Z

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs

+            RequestBufferingStream? requestBufferingStream = null;
+            Stream? originalBody = null;
+
+            if ((HttpLoggingFields.Request & options.LoggingFields) != HttpLoggingFields.None)


I notice we don't check if Logging is enabled before we do any of this stuff. Seems like we should no?

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs

davidfowl · 2021-04-20T07:03:31Z

src/Middleware/HttpLogging/src/BufferingStream.cs

+
+                // Afterwards, we need to call convert in a loop until complete is true.
+                // The first call to convert many return true, but if it doesn't, we call
+                // Convert with a empty ReadOnlySequence and flush: true until we get completed: true.


Why? There's no more data coming in right?

src/Middleware/HttpLogging/src/RequestBufferingStream.cs

davidfowl · 2021-04-20T18:06:36Z

src/Middleware/HttpLogging/src/HttpLoggingExtensions.cs

+
+        private static readonly Action<ILogger, Exception?> _unrecognizedMediaType =
+            LoggerMessage.Define(LogLevel.Debug, new EventId(6, "UnrecognizedMediaType"), "Unrecognized Content-Type for body.");
+


nit: Remove space

davidfowl

LGTM

jkotalik · 2021-04-20T18:59:10Z

I did a bunch of perf runs locally to generally get a picture of what's going on.

With a custom logging provider which noop'd (to remove the impact of the actual logging), I saw around a 3% regression with logging the request, response, and response body.

Before (no HttpLoggingMiddleware)

Bombarding http://localhost:5000 for 10s using 125 connection(s)
[=================================================================================================================================================================================================================================================================================] 10s
Done!
Statistics        Avg      Stdev        Max
  Reqs/sec     70548.12   12436.92  144929.16
  Latency        1.72ms   763.52us    70.14ms
  HTTP codes:
    1xx - 0, 2xx - 713518, 3xx - 0, 4xx - 0, 5xx - 0
    others - 0
  Throughput:    14.36MB/s

After (with middleware and noop logging)

Bombarding http://localhost:5000 for 10s using 125 connection(s)
[=================================================================================================================================================================================================================================================================================] 10s
Done!
Statistics        Avg      Stdev        Max
  Reqs/sec     68877.66   14550.83  114951.68
  Latency        1.77ms   629.66us   139.06ms
  HTTP codes:
    1xx - 0, 2xx - 696073, 3xx - 0, 4xx - 0, 5xx - 0
    others - 0
  Throughput:    14.01MB/s

I averaged a few runs here and in general, removing the middleware showed around a 3% gain, which is expected.

I'm going to try some worst case scenarios just for kicks now. But there isn't anything obscenely wrong perf wise.

jkotalik · 2021-04-20T19:10:45Z

To no surprise, a larger response body affects perf even more, seeing around a 40% regression. Writing a 50 KB response, perf numbers go from 21k RPS to 13K RPS.

Bombarding http://localhost:5000 for 10s using 125 connection(s)
[=================================================================================================================================================================================================================================================================================] 10s
Done!
Statistics        Avg      Stdev        Max
  Reqs/sec     20990.03    8384.13   52401.26
  Latency        5.97ms     1.81ms    70.33ms
  HTTP codes:
    1xx - 0, 2xx - 209109, 3xx - 0, 4xx - 0, 5xx - 0
    others - 0
  Throughput:     0.98GB/s
C:\Users\jukotali> ^C
C:\Users\jukotali> bombardier localhost:5000
Bombarding http://localhost:5000 for 10s using 125 connection(s)
[=================================================================================================================================================================================================================================================================================] 10s
Done!
Statistics        Avg      Stdev        Max
  Reqs/sec     12807.25    5641.34   28040.42
  Latency        9.52ms     3.94ms   226.19ms
  HTTP codes:
    1xx - 0, 2xx - 131084, 3xx - 0, 4xx - 0, 5xx - 0
    others - 0
  Throughput:   628.02MB/s

Tratcher · 2021-04-20T19:20:53Z

To no surprise, a larger response body affects perf even more, seeing around a 40% regression. Writing a 50 KB response, perf numbers go from 21k RPS to 13K RPS.

Buffering the bytes shouldn't cause much throughput overhead(?). Is it the decoding and logging a big string that slows it down? I suspect streaming/chunked body logging will help here.

jkotalik · 2021-04-20T19:26:23Z

Buffering the bytes shouldn't cause much throughput overhead(?). Is it the decoding and logging a big string that slows it down? I suspect streaming/chunked body logging will help here.

Yeah there are many things we can do to improve perf here, but that's for after this PR is merged 😄 . I mostly wanted to make sure there wasn't something horrendously wrong.

BrennanConroy · 2021-04-20T19:31:37Z

Buffering the bytes shouldn't cause much throughput overhead(?).

Console logging pushes to a BlockingCollection which will hold a few items before blocking more logs. So once the queue is full, it completely blocks the thread.

davidfowl · 2021-04-20T19:31:44Z

Buffering the bytes shouldn't cause much throughput overhead(?). Is it the decoding and logging a big string that slows it down? I suspect streaming/chunked body logging will help here.

Copying the body will have CPU overhead and decoding UTF8 will have even more CPU overhead.

jkotalik · 2021-04-20T19:35:22Z

This isn't logging to console atm, it's nooping that portion. This is to primarily check the perf of the middleware and buffering.

BrennanConroy · 2021-04-20T19:37:51Z

Oh, that doesn't seem great then 😄

jkotalik · 2021-04-20T20:49:51Z

@dotnet/aspnet-build please merge.

jkotalik added 5 commits April 14, 2021 14:16

Adding logging

08531c4

Progress

b56367f

Logging

cef0a0e

nit

6c6f371

Polishing HttpLogging

cb167a3

jkotalik added the area-runtime label Apr 14, 2021

jkotalik added this to the 6.0-preview4 milestone Apr 14, 2021

jkotalik requested review from Tratcher and a team as code owners April 14, 2021 21:22

jkotalik commented Apr 14, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs Outdated Show resolved Hide resolved

jkotalik commented Apr 14, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs Outdated Show resolved Hide resolved

jkotalik commented Apr 14, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpLoggingExtensions.cs Outdated Show resolved Hide resolved

jkotalik commented Apr 14, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpLoggingOptions.cs Outdated Show resolved Hide resolved

jkotalik commented Apr 14, 2021

View reviewed changes

src/Middleware/HttpLogging/src/ResponseBufferingStream.cs Outdated Show resolved Hide resolved

rynowak reviewed Apr 14, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpLoggingFields.cs Outdated Show resolved Hide resolved

jkotalik added 2 commits April 14, 2021 14:46

Namespace and nit

e3c2bb9

System

a82072a

davidfowl requested a review from halter73 April 14, 2021 22:13

JamesNK reviewed Apr 14, 2021

View reviewed changes

Fix public API

5b4d902

jkotalik added the api-ready-for-review API is ready for formal API review - https://github.com/dotnet/apireviews label Apr 15, 2021

gfoidl reviewed Apr 15, 2021

View reviewed changes

Kahbazi reviewed Apr 15, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs Outdated Show resolved Hide resolved

jkotalik mentioned this pull request Apr 15, 2021

Log HTTP Request and Response Trailers #31840

Open

davidfowl reviewed Apr 15, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs Outdated Show resolved Hide resolved

davidfowl reviewed Apr 15, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs Outdated Show resolved Hide resolved

davidfowl reviewed Apr 20, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpRequestLog.cs Show resolved Hide resolved

davidfowl reviewed Apr 20, 2021

View reviewed changes

src/Middleware/HttpLogging/src/MediaTypeOptions.cs Outdated Show resolved Hide resolved

davidfowl reviewed Apr 20, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs Outdated Show resolved Hide resolved

davidfowl reviewed Apr 20, 2021

View reviewed changes

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs Outdated Show resolved Hide resolved

davidfowl reviewed Apr 20, 2021

View reviewed changes

src/Middleware/HttpLogging/src/RequestBufferingStream.cs Outdated Show resolved Hide resolved

Feedback

8b3f610

davidfowl reviewed Apr 20, 2021

View reviewed changes

davidfowl approved these changes Apr 20, 2021

View reviewed changes

Pilchie mentioned this pull request Apr 20, 2021

Ignore Unshipped.txt in previews #31982

Merged

Fixing some small parts

1073605

Fixing response buffering check

fc0073d

dougbu merged commit 4ee074f into release/6.0-preview4 Apr 20, 2021

dougbu deleted the jkotalik/httpLogging branch April 20, 2021 20:57

amcasey added area-middleware Includes: URL rewrite, redirect, response cache/compression, session, and other general middlesware area-networking Includes servers, yarp, json patch, bedrock, websockets, http client factory, and http abstractions and removed area-runtime labels Jun 6, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adds HttpLogging middleware #31816

Adds HttpLogging middleware #31816

jkotalik commented Apr 14, 2021

davidfowl commented Apr 15, 2021

jkotalik commented Apr 15, 2021

ghost commented Apr 15, 2021

davidfowl Apr 20, 2021 •

edited

Loading

davidfowl Apr 20, 2021

halter73 Apr 20, 2021

halter73 Apr 20, 2021

jkotalik Apr 20, 2021

davidfowl Apr 20, 2021

Tratcher Apr 20, 2021

davidfowl Apr 20, 2021

jkotalik Apr 20, 2021

davidfowl Apr 20, 2021

jkotalik Apr 20, 2021

halter73 Apr 20, 2021

davidfowl Apr 20, 2021

davidfowl Apr 20, 2021 •

edited

Loading

davidfowl Apr 20, 2021

davidfowl left a comment

jkotalik commented Apr 20, 2021

jkotalik commented Apr 20, 2021

Tratcher commented Apr 20, 2021

jkotalik commented Apr 20, 2021

BrennanConroy commented Apr 20, 2021

davidfowl commented Apr 20, 2021

jkotalik commented Apr 20, 2021

BrennanConroy commented Apr 20, 2021

jkotalik commented Apr 20, 2021


		private static readonly Action<ILogger, Exception?> _unrecognizedMediaType =
		LoggerMessage.Define(LogLevel.Debug, new EventId(6, "UnrecognizedMediaType"), "Unrecognized Content-Type for body.");

Adds HttpLogging middleware #31816

Adds HttpLogging middleware #31816

Conversation

jkotalik commented Apr 14, 2021

davidfowl commented Apr 15, 2021

jkotalik commented Apr 15, 2021

ghost commented Apr 15, 2021

davidfowl Apr 20, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davidfowl Apr 20, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davidfowl left a comment

Choose a reason for hiding this comment

jkotalik commented Apr 20, 2021

jkotalik commented Apr 20, 2021

Tratcher commented Apr 20, 2021

jkotalik commented Apr 20, 2021

BrennanConroy commented Apr 20, 2021

davidfowl commented Apr 20, 2021

jkotalik commented Apr 20, 2021

BrennanConroy commented Apr 20, 2021

jkotalik commented Apr 20, 2021

davidfowl Apr 20, 2021 •

edited

Loading

davidfowl Apr 20, 2021 •

edited

Loading