Skip to content
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

HttpLogging redaction and enrichment #50163

Merged
merged 34 commits into from
Aug 31, 2023

Conversation

Tratcher
Copy link
Member

@Tratcher Tratcher commented Aug 17, 2023

This adds extensibility to the logging middleware so that what gets logged can be granularly customized per request.

Description

See the API review notes at #31844 (comment)

Fixes #31844, contributes to dotnet/extensions#4330
Fixes #49989, CopyTo/Async not logging the request body.
Fixes #49063, Clarify when the request body is not fully logged.

IHttpLoggingInterceptor:

  • This is a new interface that can have multiple instances registered and injected into the logging middleware. The callbacks run before the normal request/response logging and enable adjusting what should be logged per request, as well as adding custom fields.
  • ValueTask OnRequestAsync(HttpLoggingInterceptorContext logContext);
  • ValueTask OnResponseAsync(HttpLoggingInterceptorContext logContext);

Duration:

  • This is a new field that can be logged, reported as milliseconds since the middleware first saw the request. This is logged once at the end of the response.
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      Response:
      Content-Type: RedactedHeader
      ResponseEnrichment: Stuff
      StatusCode: 200
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[8]
      Duration: 0.3027ms

Combine Logs:
bool HttpLoggingOptions.CombineLogs { get; set; } has been added to support writing one unified log of request, request body, response, and response body data at the end of the response. The extensions components require this.

Exception handling:

  • The middleware has been updated to ensure that all data collected so far is logged even in the event of an exception thrown from the middleware pipeline. This is especially important for the new CombineLogs option since the request data won't have been logged before calling next. Note that since this middleware does not handle the exception, it does not log it so as to avoid duplicating it in the logs.

@Tratcher Tratcher added the area-middleware Includes: URL rewrite, redirect, response cache/compression, session, and other general middlesware label Aug 17, 2023
@Tratcher Tratcher added this to the 8.0-rc2 milestone Aug 17, 2023
@Tratcher Tratcher self-assigned this Aug 17, 2023
@ghost ghost added the area-runtime label Aug 17, 2023
@Tratcher
Copy link
Member Author

Tratcher commented Aug 22, 2023

Checking for changes to API baseline files release/8.0
Found changes in 1 API baseline files
##[error]Detected modification to baseline API files. PublicAPI.Shipped.txt files should only be updated after a major release. See /docs/APIBaselines.md for more information.
error : Detected modification to baseline API files. PublicAPI.Shipped.txt files should only be updated after a major release. See /docs/APIBaselines.md for more information.
##[error]Modified API baseline files:
error : Modified API baseline files:
##[error]src/Middleware/HttpLogging/src/PublicAPI.Unshipped.txt
error : src/Middleware/HttpLogging/src/PublicAPI.Unshipped.txt

https://dev.azure.com/dnceng-public/public/_build/results?buildId=384096&view=logs&j=efda9e5f-cf98-536e-4181-9b6c13ac35b3&t=dca754b7-8b76-5f52-60ef-6b0e8f7eb325&l=801

@wtgodbe any idea why it's complaining about modifying the Unshipped file? Is the release branch more strict about that?

edit Figured this out, the error message is just incomplete. It doesn't want us modifying even the Unshipped file in release branches since we shouldn't be adding APIs in servicing. However that doesn't account for rc2 work which is going into release/8.0 until rc2 branches. I'll clarify the error in the script, but it won't fix it, we'll need to override it.

@Tratcher Tratcher requested a review from a team as a code owner August 24, 2023 19:30
src/Middleware/HttpLogging/src/HttpLoggingExtensions.cs Outdated Show resolved Hide resolved

context.Features.Set<IHttpUpgradeFeature>(loggableUpgradeFeature);
}
}

if (loggingFields.HasFlag(HttpLoggingFields.ResponseBody))
if (loggingFields.HasFlag(HttpLoggingFields.ResponseBody) || _interceptors.Length > 0)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is the response body captured if there is an interceptor? Is there a situation where this wouldn't be wanted?

Add comment?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The response body isn't captured until after interceptors run, but we need to hook it in advance so that an interceptor can decide to capture the body or not.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That seems like a limitation of interceptors. Someone might want to redact fields with an interceptor, but an interceptor forces the body to be captured which can have a big performance overhead.

Have you considered a property on the interceptor interface to control whether the body is captured? bool CanCaptureResponseBody or bool SuppressCaptureResponseBody

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We're not always capturing the response body, we're only shimming it so we can see when it starts and make the decision to capture it. This should not cause significant overhead.

src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs Outdated Show resolved Hide resolved
@Tratcher
Copy link
Member Author

I've updated the description to include two recent requirements changes based on feedback from the Extensions folks, CombineLogs and exception handling.

@Tratcher
Copy link
Member Author

@wtgodbe ready to merge.

@wtgodbe wtgodbe merged commit af54f0b into dotnet:release/8.0 Aug 31, 2023
@ghost ghost modified the milestone: 8.0-rc2 Aug 31, 2023
@ghost ghost added the area-infrastructure Includes: MSBuild projects/targets, build scripts, CI, Installers and shared framework label Aug 31, 2023
@Tratcher Tratcher deleted the tratcher/logextensions branch September 1, 2023 15:52
@Tratcher Tratcher added blog-candidate Consider mentioning this in the release blog post and removed area-infrastructure Includes: MSBuild projects/targets, build scripts, CI, Installers and shared framework labels Sep 1, 2023
@ghost
Copy link

ghost commented Sep 1, 2023

@Tratcher, this change will be considered for inclusion in the blog post for the release it'll ship in. Nice work!

Please ensure that the original comment in this thread contains a clear explanation of what the change does, why it's important (what problem does it solve?), and, if relevant, include things like code samples and/or performance numbers.

This content may not be exactly what goes into the blog post, but it will help the team putting together the announcement.

Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area-middleware Includes: URL rewrite, redirect, response cache/compression, session, and other general middlesware blog-candidate Consider mentioning this in the release blog post
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants