Some correlated KestrelEventSource logs are called with different ExecutionContexts breaking ActivityIds

[halter73]

@MihaZupan brought it to our attention that some of Kestrel's EventSource Start/Stop logs are called with different ExecutionContexts even though they're supposed to be correlated.

This is generally (if not always) caused by dispatching using ThreadPool.UnsafeQueueUserWorkItem() and not manually capturing and restoring the ExecutionContext before emitting the next EventSource log. This breaks the automatic ActivityId tracking that the EventSource Start/Stop convention is supposed to give us.

In particular, Kestrel's ConnectionQueuedStart/Stop logs and Kestrel's HTTP/2+HTTP/3 RequestQueuedStart/Stop logs are emmitted without the same execution context.

aspnetcore/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs

Lines 64 to 66 in 96c082f

	KestrelEventSource.Log.ConnectionQueuedStart(connection);
	ThreadPool.UnsafeQueueUserWorkItem(kestrelConnection, preferLocal: false);

aspnetcore/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs

Lines 1064 to 1066 in 96c082f

	KestrelEventSource.Log.RequestQueuedStart(_currentHeadersStream, AspNetCore.Http.HttpProtocol.Http2);
	// Must not allow app code to block the connection handling loop.
	ThreadPool.UnsafeQueueUserWorkItem(_currentHeadersStream, preferLocal: false);

aspnetcore/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs

Lines 246 to 247 in 96c082f

	KestrelEventSource.Log.RequestQueuedStart(stream, AspNetCore.Http.HttpProtocol.Http3);
	ThreadPool.UnsafeQueueUserWorkItem(stream, preferLocal: false);

This results in ConnectionQueuedStop and RequestQueuedStop logs without any ActivityId at all. Below I've included all the EventWrittenEventArgs emmitted by the KestrelEventSource logger when making an HTTP/2 GET request against Kestrel's sample app. They're collapsed because it's over 600 lines, but you can see the lack of ActivityIds for these logs.

EventWrittenEventArgs as JSON

{
  "EventName": "ConnectionQueuedStart",
  "EventId": 6,
  "ActivityId": "00000011-0000-0000-0000-0000d6dc9d59",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TC",
    "127.0.0.1:5001",
    "127.0.0.1:52875"
  ],
  "PayloadNames": [
    "connectionId",
    "localEndPoint",
    "remoteEndPoint"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 1,
  "Task": 65528,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 30692,
  "TimeStamp": "2020-10-02T21:06:56.3466532Z"
}
{
  "EventName": "ConnectionQueuedStop",
  "EventId": 7,
  "ActivityId": "00000000-0000-0000-0000-000000000000",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TC",
    "127.0.0.1:5001",
    "127.0.0.1:52875"
  ],
  "PayloadNames": [
    "connectionId",
    "localEndPoint",
    "remoteEndPoint"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 2,
  "Task": 65528,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 1448,
  "TimeStamp": "2020-10-02T21:06:56.4866333Z"
}
{
  "EventName": "ConnectionStart",
  "EventId": 1,
  "ActivityId": "00000012-0000-0000-0000-0000d7dc9d59",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TC",
    "127.0.0.1:5001",
    "127.0.0.1:52875"
  ],
  "PayloadNames": [
    "connectionId",
    "localEndPoint",
    "remoteEndPoint"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 1,
  "Task": 65533,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 1448,
  "TimeStamp": "2020-10-02T21:06:56.4985967Z"
}
{
  "EventName": "TlsHandshakeStart",
  "EventId": 8,
  "ActivityId": "00001012-0000-0000-0000-0000d7ec9d59",
  "RelatedActivityId": "00000012-0000-0000-0000-0000d7dc9d59",
  "Payload": [
    "0HM372SC5G6TC",
    "Tls12"
  ],
  "PayloadNames": [
    "connectionId",
    "sslProtocols"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 1,
  "Task": 65526,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 14204,
  "TimeStamp": "2020-10-02T21:06:56.5286266Z"
}
{
  "EventName": "ConnectionQueuedStart",
  "EventId": 6,
  "ActivityId": "00000013-0000-0000-0000-0000a8dc9d59",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TD",
    "127.0.0.1:5001",
    "127.0.0.1:52876"
  ],
  "PayloadNames": [
    "connectionId",
    "localEndPoint",
    "remoteEndPoint"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 1,
  "Task": 65528,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 30692,
  "TimeStamp": "2020-10-02T21:06:56.5344486Z"
}
{
  "EventName": "ConnectionQueuedStop",
  "EventId": 7,
  "ActivityId": "00000000-0000-0000-0000-000000000000",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TD",
    "127.0.0.1:5001",
    "127.0.0.1:52876"
  ],
  "PayloadNames": [
    "connectionId",
    "localEndPoint",
    "remoteEndPoint"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 2,
  "Task": 65528,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 3796,
  "TimeStamp": "2020-10-02T21:06:56.5486159Z"
}
{
  "EventName": "ConnectionStart",
  "EventId": 1,
  "ActivityId": "00000014-0000-0000-0000-0000a9dc9d59",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TD",
    "127.0.0.1:5001",
    "127.0.0.1:52876"
  ],
  "PayloadNames": [
    "connectionId",
    "localEndPoint",
    "remoteEndPoint"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 1,
  "Task": 65533,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 3796,
  "TimeStamp": "2020-10-02T21:06:56.5616893Z"
}
{
  "EventName": "TlsHandshakeStart",
  "EventId": 8,
  "ActivityId": "00001014-0000-0000-0000-0000a9ec9d59",
  "RelatedActivityId": "00000014-0000-0000-0000-0000a9dc9d59",
  "Payload": [
    "0HM372SC5G6TD",
    "Tls12"
  ],
  "PayloadNames": [
    "connectionId",
    "sslProtocols"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 1,
  "Task": 65526,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 45188,
  "TimeStamp": "2020-10-02T21:06:56.5754408Z"
}
{
  "EventName": "TlsHandshakeStop",
  "EventId": 9,
  "ActivityId": "00001012-0000-0000-0000-0000d7ec9d59",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TC",
    "Tls12",
    "h2",
    ""
  ],
  "PayloadNames": [
    "connectionId",
    "sslProtocols",
    "applicationProtocol",
    "hostName"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 2,
  "Task": 65526,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 45188,
  "TimeStamp": "2020-10-02T21:06:56.6340278Z"
}
{
  "EventName": "TlsHandshakeStop",
  "EventId": 9,
  "ActivityId": "00001014-0000-0000-0000-0000a9ec9d59",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TD",
    "Tls12",
    "h2",
    ""
  ],
  "PayloadNames": [
    "connectionId",
    "sslProtocols",
    "applicationProtocol",
    "hostName"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 2,
  "Task": 65526,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 1448,
  "TimeStamp": "2020-10-02T21:06:56.6340238Z"
}
{
  "EventName": "ConnectionStop",
  "EventId": 2,
  "ActivityId": "00000012-0000-0000-0000-0000d7dc9d59",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TC"
  ],
  "PayloadNames": [
    "connectionId"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 2,
  "Task": 65533,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 45188,
  "TimeStamp": "2020-10-02T21:06:56.7179434Z"
}
{
  "EventName": "RequestQueuedStart",
  "EventId": 11,
  "ActivityId": "00002014-0000-0000-0000-0000a9fc9d59",
  "RelatedActivityId": "00000014-0000-0000-0000-0000a9dc9d59",
  "Payload": [
    "0HM372SC5G6TD",
    "0HM372SC5G6TD:00000001",
    "HTTP/2"
  ],
  "PayloadNames": [
    "connectionId",
    "requestId",
    "httpVersion"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 1,
  "Task": 65523,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 1448,
  "TimeStamp": "2020-10-02T21:06:56.8038564Z"
}
{
  "EventName": "RequestQueuedStop",
  "EventId": 12,
  "ActivityId": "00000000-0000-0000-0000-000000000000",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TD",
    "0HM372SC5G6TD:00000001",
    "HTTP/2"
  ],
  "PayloadNames": [
    "connectionId",
    "requestId",
    "httpVersion"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 2,
  "Task": 65523,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 3796,
  "TimeStamp": "2020-10-02T21:06:56.8133605Z"
}
{
  "EventName": "RequestStart",
  "EventId": 3,
  "ActivityId": "00003014-0000-0000-0000-0000a98c9d59",
  "RelatedActivityId": "00000014-0000-0000-0000-0000a9dc9d59",
  "Payload": [
    "0HM372SC5G6TD",
    "0HM372SC5G6TD:00000001",
    "HTTP/2",
    "/",
    "GET"
  ],
  "PayloadNames": [
    "connectionId",
    "requestId",
    "httpVersion",
    "path",
    "method"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 1,
  "Task": 65531,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 3796,
  "TimeStamp": "2020-10-02T21:06:56.8856163Z"
}
{
  "EventName": "RequestStop",
  "EventId": 4,
  "ActivityId": "00003014-0000-0000-0000-0000a98c9d59",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TD",
    "0HM372SC5G6TD:00000001",
    "HTTP/2",
    "/",
    "GET"
  ],
  "PayloadNames": [
    "connectionId",
    "requestId",
    "httpVersion",
    "path",
    "method"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 2,
  "Task": 65531,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 3796,
  "TimeStamp": "2020-10-02T21:06:56.9876021Z"
}
{
  "EventName": "RequestQueuedStart",
  "EventId": 11,
  "ActivityId": "00004014-0000-0000-0000-0000a99c9d59",
  "RelatedActivityId": "00000014-0000-0000-0000-0000a9dc9d59",
  "Payload": [
    "0HM372SC5G6TD",
    "0HM372SC5G6TD:00000003",
    "HTTP/2"
  ],
  "PayloadNames": [
    "connectionId",
    "requestId",
    "httpVersion"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 1,
  "Task": 65523,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 3796,
  "TimeStamp": "2020-10-02T21:06:57.1221589Z"
}
{
  "EventName": "RequestQueuedStop",
  "EventId": 12,
  "ActivityId": "00000000-0000-0000-0000-000000000000",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TD",
    "0HM372SC5G6TD:00000003",
    "HTTP/2"
  ],
  "PayloadNames": [
    "connectionId",
    "requestId",
    "httpVersion"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 2,
  "Task": 65523,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 1448,
  "TimeStamp": "2020-10-02T21:06:57.1346162Z"
}
{
  "EventName": "RequestStart",
  "EventId": 3,
  "ActivityId": "00005014-0000-0000-0000-0000a9ac9d59",
  "RelatedActivityId": "00000014-0000-0000-0000-0000a9dc9d59",
  "Payload": [
    "0HM372SC5G6TD",
    "0HM372SC5G6TD:00000003",
    "HTTP/2",
    "/favicon.ico",
    "GET"
  ],
  "PayloadNames": [
    "connectionId",
    "requestId",
    "httpVersion",
    "path",
    "method"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 1,
  "Task": 65531,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 1448,
  "TimeStamp": "2020-10-02T21:06:57.1519997Z"
}
{
  "EventName": "RequestStop",
  "EventId": 4,
  "ActivityId": "00005014-0000-0000-0000-0000a9ac9d59",
  "RelatedActivityId": "00000000-0000-0000-0000-000000000000",
  "Payload": [
    "0HM372SC5G6TD",
    "0HM372SC5G6TD:00000003",
    "HTTP/2",
    "/favicon.ico",
    "GET"
  ],
  "PayloadNames": [
    "connectionId",
    "requestId",
    "httpVersion",
    "path",
    "method"
  ],
  "EventSource": {
    "Name": "Microsoft-AspNetCore-Server-Kestrel",
    "Guid": "bdeb4676-a36e-5442-db99-4764e2326c7d",
    "Settings": 4,
    "ConstructionException": null
  },
  "Keywords": 263882790666240,
  "Opcode": 2,
  "Task": 65531,
  "Tags": 0,
  "Message": null,
  "Channel": 0,
  "Version": 0,
  "Level": 4,
  "OSThreadId": 1448,
  "TimeStamp": "2020-10-02T21:06:57.1675146Z"
}

[Pilchie]

👀

[davidfowl]

Good catch

[halter73]

Moving to 6.0.0-alpha1 to track actually fixing the events instead of removing them.