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

Introduce new extended logging model. #4110

Merged
merged 18 commits into from
Jul 27, 2023
Merged

Introduce new extended logging model. #4110

merged 18 commits into from
Jul 27, 2023

Conversation

geeknoid
Copy link
Member

@geeknoid geeknoid commented Jun 23, 2023

Introduce new extended logging model.

  • Replace the OpenTelemetry-specific logger design with a
    LoggerFactory-based approach independent of OpenTelemetry. This
    delivers enrichment and redaction to all ILogger users.

The basic idea is that the code generator will no longer be responsible
for doing redaction. Instead, the generated code will accumulate
normal properties in one collection and will accumulate classified
properties in a different collection.

Within the Logger type, the classified properties are run through
redaction and added to the normal property list. This list is then
used to enrich into. And then the final thing is given to the set of
currently registered ILogger instances in the system. So all these
loggers get redacted and enriched state.

This separates static vs. dynamic log enrichment. The idea is to
reduce overhead for stuff that never changes. Thus, we have the new
IStaticLogEnricher type.

NOTES:

  • This PR doesn't currently include an updated logging code generator
    that will take advantage of this new functionality.
Microsoft Reviewers: Open in CodeFlow

@ghost ghost assigned geeknoid Jun 23, 2023
@geeknoid geeknoid requested a review from xakep139 June 23, 2023 15:20
@geeknoid
Copy link
Member Author

Second round:

  • This now introduced static log enrichment to reduce overhead of copying the same stuff for every request.

  • This now includes a clean customer-facing LoggerMessageProperties class that is designed to be used by the code generator and by hand-written code.

  • This now includes the StructuredLog extension method which uses LoggerMessageProperties to deliver a first class structured logging experience, with full support for enrichment and redaction.

@davidfowl
Copy link
Member

This looks much cleaner than what's currently there and its marked experimental. Are you going to measure the overhead?

@geeknoid
Copy link
Member Author

Third round:

  • Further enhance performance, in particular for classic logging that's not using the new code generator.

  • Made ExtendedLoggerFactory public. It is not a clean superset of what LoggerFactory exposes so it can be used as a complete substitute with no regrets.

  • Replaced LoggingOptions with ExtendedLoggerFilterOptions, which extends the existing LoggerFilterOptions type.

  • Made AddExtendedLogging exist on IServiceCollection instead of ILoggingBuilder, to match AddLogging.

@geeknoid geeknoid force-pushed the geeknoid/logger branch 4 times, most recently from a25f03b to d4ce094 Compare June 26, 2023 03:00
@geeknoid
Copy link
Member Author

@noahfalk @dpk83 The PR is now in pretty good shape. I have some basic tests that show the machinery is generally working. I'll get to 100% coverage Monday. Please see the few outstanding notes in the description above.

Relative to the original R9 solution, I expect this to be faster as we now have zero-copy static log enrichment, and I've replaced pools with faster thread-local storage instead for working state. All calls to ILogger.Log now involve going through an additional ILogger instance than before, so we pay for a new interface call.

A quick way to eliminate the overhead is to take the logic that's in the default logger from Microsoft.Extensions.Logging and embed directly into the new Logger. We wouldn't need the indirection that way, at the cost of cut & paste of logic.

#if NET5_0_OR_GREATER
var pid = Environment.ProcessId;
#else
var pid = System.Diagnostics.Process.GetCurrentProcess().Id;
Copy link
Contributor

Choose a reason for hiding this comment

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

Shouldn't System.Diagnostics.Process.GetCurrentProcess() be disposed?

Copy link
Contributor

Choose a reason for hiding this comment

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

IIRC it allocates some unmanaged resources

{
try
{
enricher(joiner.PropertyBag);
Copy link
Contributor

@xakep139 xakep139 Jul 20, 2023

Choose a reason for hiding this comment

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

@geeknoid what if we provide here an additional information/context to an enricher? TState from ILogger.Log<TState>() maybe.
Otherwise IStaticLogEnricher is not that different from ILogEnricher, apart from using some fancy things like AsyncContext.
cc @andrey-noskov

Copy link
Member Author

Choose a reason for hiding this comment

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

What would the enricher do with the tstate? I'm fine with the idea of doing this, so long as we have a use case to justify it.

Martin Taillefer added 18 commits July 27, 2023 09:53
- Replace the OpenTelemetry-specific logger design with a
LoggerFactory-based approach independent of OpenTelemetry. This
delivers enrichment and redaction to all ILogger users.

The basic idea is that the code generator will no longer be responsible
for doing redaction. Instead, the generated code will accumulate
normal properties in one collection and will accumulate classified
properties in a different collection.

Within the Logger type, the classified properties are run through
redaction and added to the normal property list. This list is then
used to enrich into. And then the final thing is given to the set of
currently registered ILogger instances in the system. So all these
loggers get redacted and enriched state.

This separates static vs. dynamic log enrichment. The idea is to
reduce overhead for stuff that never changes. Thus, we have the new
IStaticLogEnricher type.

We now support structured logging as a first class concept using the
new StructuredLog extension methods around ILogger.

NOTES:

- The idea is that the customer should call AddExtendedLogging
instead of AddLogging. By virtue of using this call, they'll also
be using the newer code generator which will take advantage of the
new features.

- This PR doesn't currently include an updated logging code generator
that will take advantage of this new functionality.

- Right now, if a user calls AddLogging after they had already called
AddExtendedLogging, this will undo the extended logging stuff and leave
the system in classic mode. We need to find a strategy to deal with
this.
@geeknoid geeknoid enabled auto-merge (squash) July 27, 2023 18:03
@geeknoid geeknoid merged commit 48f8597 into main Jul 27, 2023
6 checks passed
@geeknoid geeknoid deleted the geeknoid/logger branch July 27, 2023 18:24
@ghost ghost added this to the 8.0 RC1 milestone Jul 27, 2023
@ghost ghost locked as resolved and limited conversation to collaborators Aug 26, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants