Diagnostics Middleware API review

[Tratcher]

Martin asked to review all of the experimental content here before RTM.

Microsoft Reviewers: Open in CodeFlow

[geeknoid]

Experimental

[geeknoid]

Experimental

[geeknoid]

Experimental

[geeknoid]

Experimental

[joperezr]

I'm not sure I'm following, is this API that already exists in the library and the purpose of this is to do a snapshot review of it? Or is this new API that will be added?

[Tratcher]

This is for review of the current APIs so they can graduate from Experimental.

[geeknoid]

@joperezr This is to review experimental APIs that are currently present in the code base, with the goal of graduating the APIs to be approved and so we can remove the experimental attribute.

[joperezr]

@joperezr This is to review experimental APIs that are currently present in the code base, with the goal of graduating the APIs to be approved and so we can remove the experimental attribute.

Would it make sense to hold off on changing anything from Experimental -> stable for 8.0 given how close we are to the snap and instead postpone that for 8.1? Ongoing work around documentation, testing, and dogfooding is happening so I think it would make sense to have the least amount of moving pieces as possible. After snapping by the end of this week, we should be able to make these changes next week on the branch that will have 8.1 changes (which as we agreed last week would be main)

[davidfowl]

Looking at some of these bits, have we done the telemetry pass on these assemblies yet? I'm asking specifically about dimension names, tag names (distributed tracing), logging levels (how much gets logged by default and in what category).

[Tratcher]

@davidfowl yes (?) https://github.com/dotnet/r9-planning-private/issues/124.

The http logging components no longer directly log, they delegate to AspNetCore's http logging middleware. They only default they add is the Duration field.

extensions/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Logging/HttpLoggingServiceCollectionExtensions.cs

Lines 42 to 46 in 83b9004

	return services.AddHttpLogging(o =>
	{
	o.CombineLogs = true;
	o.LoggingFields |= HttpLoggingFields.Duration;
	})

The latency middleware doesn't directly emit logs or telemetry, it passes that off to the abstractions in Microsoft.Extensions.Telemetry.Abstractions. Not sure where they send it.

[davidfowl]

The http logging components no longer directly log, they delegate to AspNetCore's http logging middleware. They only default they add is the Duration field.

Ok great! I assume the same goes for metrics and distributed traces?

The latency middleware doesn't directly emit logs or telemetry, it passes that off to the abstractions in Microsoft.Extensions.Telemetry.Abstractions. Not sure where they send it.

Same questions as above. Logs, metrics and traces and and whatever enrichment we do.

[Tratcher]

For this package at least, yes.

[xakep139]

@davidfowl there's no HTTP tracing/metering in extensions repo as we had to remove these bits.
There are only three components that emit metrics:

• ResourceMonitoring
• HealthChecks
• HeaderParsing

All metrics are listed in #4482 (comment)

[davidfowl]

@xakep139 What about logs and various log levels and categories?

Also trace enrichment? Did we remove any activity enrichment as well?

[joperezr]

@xakep139 What about logs and various log levels and categories?

I believe all of that was done here: #4545

[iliar-turdushev]

@xakep139 What about logs and various log levels and categories?

I believe all of that was done here: #4545

@joperezr I checked only log categories when I was working on #4545, and I didn't know that I had to check log levels. How can we ensure that log levels we use are correct/good?

[xakep139]

@xakep139 What about logs and various log levels and categories?

Also trace enrichment? Did we remove any activity enrichment as well?

Correct, all tracing (including enrichment) bits were removed.

[davidfowl]

@joperezr I checked only log categories when I was working on #4545, and I didn't know that I had to check log levels. How can we ensure that log levels we use are correct/good?

This is a bit of an art. I don't know that we have anything written up on best practices here, do we @noahfalk. I will say that there's a tendency to "over log" everything as information by default. The user is going to see everything >= information by default (this is why ASP.NET Core defaults to "Warning" in the template). It results in "logging spam" (and we get feedback from customers about how noisy it is).

I would recommend:

• Having log categories that developers can control (we don't have per log control, just the category)
• Reducing the number of informational logs (these will show up per request)
• Checking the log level for the category before logging, especially if data is being transformed

Anything else @noahfalk ?

[noahfalk]

I don't think these static classes declaring telemetry constants need to be public. I don't understand what the use-case would be. For anyone who wanted to parse the ILogger data after it was emitted or make their own implementation that emits the same values I expect they would just write these same constants into their own code rather than take a ref on this assembly.

[noahfalk]

Same as above, I don't think this needs to be public.

[noahfalk]

This is a bit of an art. I don't know that we have anything written up on best practices here, do we @noahfalk.

I don't think we have any written guidance specific to what log level is most appropriate for a given log message. I agree with your impression that we have historically made informational logging too verbose.
My current mental model would be something like this:

• If a high scale service (a realistic one, not a contrived benchmark) is likely to hit the log statement more than 1000 times/sec then consider it expensive. More than 100K times/sec consider it really expensive.
• Really expensive logs should be Debug or Trace level
• It is OK to have a single expensive log marked informational in a category, as long as the data is high value. Instead of adding a second one you could either combine both into a single log, mark one of them with a higher verbosity, or move them into different sub-categories so they can be filtered independently.

[iliar-turdushev]

• Really expensive logs should be Debug or Trace level

What if a really expensive log logs exception/error information? For example, the following message is logged when an enricher fails to enrich an incoming HTTP request.

extensions/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Log.cs

Line 11 in ebafbeb

[LoggerMessage(0, LogLevel.Warning, "Enricher failed: {Enricher}.")]

It could become really expensive if some enricher starts to fail for each HTTP request. Should we change the level of the log message to Debug in this case?

[noahfalk]

It could become really expensive if some enricher starts to fail for each HTTP request. Should we change the state of the log message to Debug in this case?

I'd consider the 'likely' behavior as the typical, presumably healthy, steady-state app behavior. If having enrichment fail on every request was a typical and ignorable result then Debug might be a good idea, but I'm guessing for this example service owners wouldn't consider that a typical or healthy state. Given the choice between logging getting verbose temporarily in response to the error condition or not seeing anything because the message was marked as Debug, I suspect they'd prefer the verbose logs.

I'd also guess service owners would appreciate some kind of rate limiting to avoid getting spammed with 100K/sec of the same error. That feels like something we would enable as part of overall logging pipeline infrastructure and not request every place in code that can generate an error do its own custom rate limiting implementation or to be really conservative with its verbosity level.

[iliar-turdushev]

I'd consider the 'likely' behavior as the typical

@noahfalk Thank you very much for guidance. I've created a PR to review existing log messages and their log levels. Could you, please, take a look? #4652 In general, our current log levels are good.

cc @davidfowl

[joperezr]

Closing as I believe this is stale now.