Create a logging scope per connection

[halter73]

After seeing HostingLogScope, I realized we need the equivalent for Kestrel connections.

11 of the 13 special log functions defined in KestrelTrace take the connect id as a logging parameter. Of the remaining 2, KestrelTrace.ApplicationError really should log the connection id but doesn't. It would be far more elegant to create a logging scope that includes the connection id assuming that these can be nested. This will also prevent future oversights like the one in ApplicationError.

An added benefit is that we could lazily serialize the connection id like we do with the request id since we're not constantly passing a connection id string to logging methods. See #638

Note: we will have to be careful when logging outside of the connection's async loop (such as in callbacks on the libuv thread) since the AsyncLocal backing for the scope (I assume that what's being used) won't be available. In those cases I imagine we log connection id's like we do today, but check the loglevel before calling the log method so we don't have to serialize the connection id unnecessarily. That's assuming we can't delay the logging until we get back on the async loop.

[benaadams]

Isn't AsyncLocal for HostingLogScope as AsyncLocal modifies the execution context from default and would be seeing lots of ExectionContext allocations and slow path awaits like you see when using the HttpContextAccessor

[halter73]

Ultimately I think it's up to the logger how they implement scopes. The console logger uses AsyncLocal/CallContext, but it seems you would only pay for it if you use it.

It looks like our NLogLoggerProvider uses a NestedDiagnosticsContext for scopes which is only backed by a thread-local structure. I imagine this would be more efficient, but completely break HostingLogScope and the suggested connection scope. Maybe we should use MappedDiagnosticsLogicalContext instead?

I don't think performance should be a concern here since Hosting creates even more scopes, and Hosting's request scopes will be implemented the same way as connection scopes.

[benaadams]

I don't think performance should be a concern here since Hosting creates even more scopes,

Working on it ;-) aspnet/Hosting#609 and aspnet/Logging#366

[halter73]

Cool. We can follow whatever pattern we decide on for Hosting then 😄

[benaadams]

Max pooling (https://github.com/aspnet/Performance/pull/67) allocs currently looks like this over 1M req - though the QUWI is now lower.

[muratg]

Backlogging for now, we'll bring it back as needed.

[muratg]

cc @shirhatti, what's the wanted behavior?

[davidfowl]

We should do this in 2.1

[davidfowl]

Turns out this is a little more complicated than the current implementation as it doesn't always work. Seems like the connection scope is getting cleared sometimes. I'm not sure if this is a log provider issue or a kestrel issue. Investigating.

[davidfowl]

Turns out this is a false alarm. Seems like I was running old kestrel bits...