[API Proposal]: Add http request/response correlation id to LoggingHttpMessageHandler (Microsoft.Extensions.Http.Logging)

[OlzhabaevSh]

Background and motivation

We have default logger implementation for HTTP client here

In general, it works smoothly, and we can see logs for request and response but in some cases it's really hard to match requests/response information (for example when you send several requests in parallel mode).

It would be nice if we have something like correlationId which can be used to match request and response logs.

The reason why we would like to match request/response logs is we're using DiagnosticsClient for reading logs from an application and visualizing.

In the end we think that this feature will not broke anything and can be useful for other users.

API Proposal

HttpHeadersLogValue class

namespace: Microsoft.Extensions.Http.Logging Path: Microsoft.Extensions.Http.Logging.HttpHeadersLogValue

namespace Microsoft.Extensions.Http.Logging;

internal sealed class HttpHeadersLogValue : IReadOnlyList<KeyValuePair<string, object>>
{

   /* private properties */

   private readonly Guid _correlationId; 

   public HttpHeadersLogValue(Kind kind, HttpHeaders headers, HttpHeaders? contentHeaders, Func<string, bool> shouldRedactHeaderValue, Guid correlationId)
     {
         _kind = kind;
         _shouldRedactHeaderValue = shouldRedactHeaderValue;

         Headers = headers;
         ContentHeaders = contentHeaders;
         _correlationId = correlationId;
     }

     private List<KeyValuePair<string, object>> Values
     {
         get 
         {
            /*some code*/
            values.Add(new KeyValuePair<string, Guid>("CorrelationId", _correlationId));
            /*some code*/
         }
     }
}

LoggingHttpMessageHandler class

namespace: Microsoft.Extensions.Http.Logging Path: Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler

namespace Microsoft.Extensions.Http.Logging;

public class LoggingHttpMessageHandler : DelegatingHandler
{
   /* private properties and methods */

   protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
     {
         ThrowHelper.ThrowIfNull(request);
         return Core(request, cancellationToken);

         async Task<HttpResponseMessage> Core(HttpRequestMessage request, CancellationToken cancellationToken)
         {
             Func<string, bool> shouldRedactHeaderValue = _options?.ShouldRedactHeaderValue ?? _shouldNotRedactHeaderValue;

             Guild correlationId = Guid.NewGuid();

             // Not using a scope here because we always expect this to be at the end of the pipeline, thus there's
             // not really anything to surround.
             Log.RequestStart(_logger, request, shouldRedactHeaderValue, correlationId );
             var stopwatch = ValueStopwatch.StartNew();
             HttpResponseMessage response = await base.SendAsync(request, cancellationToken).ConfigureAwait(false);
             Log.RequestEnd(_logger, response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue, correlationId );

             return response;
         }
     }

}

internal static class Log
{
   /* internal properties and methods */

   public static void RequestStart(ILogger logger, HttpRequestMessage request, Func<string, bool> shouldRedactHeaderValue, Guid correlationId)
   {
      /* code */
      logger.Log(
         LogLevel.Trace,
         EventIds.RequestHeader,
         new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue, correlationId),
         null,
         (state, ex) => state.ToString());
   }

   public static void RequestEnd(ILogger logger, HttpResponseMessage response, TimeSpan duration, Func<string, bool> shouldRedactHeaderValue, Guid correlationId)
   {
      /* code */
      logger.Log(
         LogLevel.Trace,
         EventIds.ResponseHeader,
         new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue, correlationId),
         null,
         (state, ex) => state.ToString());
   }

}

API Usage

In general case you will see correlation id in Window Outputs or Console.

In client-side code the result should be something like:

static void ProcessLogs(processId)
{
   // setup
   var providers = new List<EventPipeProvider>()
      {
         new EventPipeProvider(
            "Microsoft-Extensions-Logging",
            EventLevel.Verbose,
            8)
      };
   var client = new DiagnosticsClient(processId);

   using (EventPipeSession session = client.StartEventPipeSession(providers, false))
   {
      source.Dynamic.All += async (TraceEvent obj) => 
      {
         var eventId = Convert.ToInt32(obj.PayloadByName("EventId"));
         var loggerName = obj.PayloadStringByName("LoggerName");

         if (loggerName == "System.Net.Http.HttpClient.Default.ClientHandler") 
            {
               var data = obj.PayloadByName("ArgumentsJson");
               var deserializedData = JsonSerializer.Deserialize<MyModel>(data.ToString());

               // Now we can use correlationId for matching request/response logs
               //deserializedData.CorrelationId
            }

      }
   }

}

Alternative Designs

No response

Risks

No response

[ghost]

Tagging subscribers to this area: @dotnet/ncl See info in area-owners.md if you want to be subscribed.

Issue Details

---

### Background and motivation We have default logger implementation for HTTP client [here](https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs) In general, it works smoothly, and we can see logs for request and response but in some cases it's really hard to match requests/response information (for example when you send several requests in parallel mode). It would be nice if we have something like `correlationId` which can be used to match request and response logs. The reason why we would like to match request/response logs is we're using `DiagnosticsClient` for reading logs from an application and visualizing. In the end we think that this feature will not broke anything and can be useful for other users. ### API Proposal # HttpHeadersLogValue class namespace: Microsoft.Extensions.Http.Logging Path: [Microsoft.Extensions.Http.Logging.HttpHeadersLogValue](https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Http/src/Logging/HttpHeadersLogValue.cs) ```csharp namespace Microsoft.Extensions.Http.Logging; internal sealed class HttpHeadersLogValue : IReadOnlyList> { /* private properties */ private readonly Guid _correlationId; public HttpHeadersLogValue(Kind kind, HttpHeaders headers, HttpHeaders? contentHeaders, Func shouldRedactHeaderValue, Guid correlationId) { _kind = kind; _shouldRedactHeaderValue = shouldRedactHeaderValue; Headers = headers; ContentHeaders = contentHeaders; _correlationId = correlationId; } private List> Values { get { /*some code*/ values.Add(new KeyValuePair("CorrelationId", _correlationId)); /*some code*/ } } } ``` # LoggingHttpMessageHandler class namespace: Microsoft.Extensions.Http.Logging Path: [Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler](https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs) ```csharp namespace Microsoft.Extensions.Http.Logging; public class LoggingHttpMessageHandler : DelegatingHandler { /* private properties and methods */ protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) { ThrowHelper.ThrowIfNull(request); return Core(request, cancellationToken); async Task Core(HttpRequestMessage request, CancellationToken cancellationToken) { Func shouldRedactHeaderValue = _options?.ShouldRedactHeaderValue ?? _shouldNotRedactHeaderValue; Guild correlationId = Guid.NewGuid(); // Not using a scope here because we always expect this to be at the end of the pipeline, thus there's // not really anything to surround. Log.RequestStart(_logger, request, shouldRedactHeaderValue, correlationId ); var stopwatch = ValueStopwatch.StartNew(); HttpResponseMessage response = await base.SendAsync(request, cancellationToken).ConfigureAwait(false); Log.RequestEnd(_logger, response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue, correlationId ); return response; } } } internal static class Log { /* internal properties and methods */ public static void RequestStart(ILogger logger, HttpRequestMessage request, Func shouldRedactHeaderValue, Guid correlationId) { /* code */ logger.Log( LogLevel.Trace, EventIds.RequestHeader, new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue, correlationId), null, (state, ex) => state.ToString()); } public static void RequestEnd(ILogger logger, HttpResponseMessage response, TimeSpan duration, Func shouldRedactHeaderValue, Guid correlationId) { /* code */ logger.Log( LogLevel.Trace, EventIds.ResponseHeader, new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue, correlationId), null, (state, ex) => state.ToString()); } } ``` ### API Usage In general case you will see correlation id in Window Outputs or Console. In client-side code the result should be something like: ```csharp static void ProcessLogs(processId) { // setup var providers = new List() { new EventPipeProvider( "Microsoft-Extensions-Logging", EventLevel.Verbose, 8) }; var client = new DiagnosticsClient(processId); using (EventPipeSession session = client.StartEventPipeSession(providers, false)) { source.Dynamic.All += async (TraceEvent obj) => { var eventId = Convert.ToInt32(obj.PayloadByName("EventId")); var loggerName = obj.PayloadStringByName("LoggerName"); if (loggerName == "System.Net.Http.HttpClient.Default.ClientHandler") { var data = obj.PayloadByName("ArgumentsJson"); var deserializedData = JsonSerializer.Deserialize(data.ToString()); // Now we can use correlationId for matching request/response logs //deserializedData.CorrelationId } } } } ``` ### Alternative Designs _No response_ ### Risks _No response_

Author:	OlzhabaevSh
Assignees:	-
Labels:	`api-suggestion`, `area-System.Net.Http`
Milestone:	-

[CarnaViire]

@OlzhabaevSh thanks for the suggestions.

In the meantime, did you consider leveraging .NET Networking Telemetry? https://devblogs.microsoft.com/dotnet/net-5-new-networking-improvements/#telemetry It contains RequestStart, RequestStop along many other events, and there's also ActivityId -- the correlation ID you were asking about.

The events can be consumed via PerfView or dotnet-trace, or with a custom event listener.

[MihaZupan]

You can also attach your own correlation info to these logs via logger.BeginScope, see https://learn.microsoft.com/aspnet/core/fundamentals/logging#log-scopes.

[OlzhabaevSh]

@CarnaViire Thank for your reply. Unfortunately, in our case HttpEventListenerwill not work, because we would like to read logs outside of running app. We also tried to use dotnet trace tool but dotnet trace doesn't work in realtime. I mean it collect logs and provide it after finishing the program. In our case we would like to read logs in realtime.

In general, we would like to not touch the client-side code (I mean no additional libs or code injection). That's reason why we didn't try to just pass our custom HttpMessageHandler.

In the best scenario our tool should be able to read http logs from any dotnet core based app, if they enabled logs for http in DI container

[OlzhabaevSh]

@MihaZupan thank you for your reply, Yes, that should work as well, thank you. In cases when we trying to read http logs from our own app - it should work, but we also would like to read logs from third party app (when we can't or shouldn't modify source code). We found DiagnosticsClient and we can get logs from external app.

[MihaZupan]

The events @CarnaViire pointed you to can be consumed outside of the process as well. You can access the same data source dotnet trace uses, but do so in real time. See https://github.com/microsoft/perfview/blob/main/documentation/TraceEvent/TraceEventProgrammersGuide.md#real-time-processing-of-events

[MihaZupan]

Or since you're already subscribed to Microsoft-Extensions-Logging events, just listen to System.Net.Http as well.

[ghost]

Tagging subscribers to this area: @dotnet/ncl See info in area-owners.md if you want to be subscribed.

Issue Details

---

### Background and motivation We have default logger implementation for HTTP client [here](https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs) In general, it works smoothly, and we can see logs for request and response but in some cases it's really hard to match requests/response information (for example when you send several requests in parallel mode). It would be nice if we have something like `correlationId` which can be used to match request and response logs. The reason why we would like to match request/response logs is we're using `DiagnosticsClient` for reading logs from an application and visualizing. In the end we think that this feature will not broke anything and can be useful for other users. ### API Proposal # HttpHeadersLogValue class namespace: Microsoft.Extensions.Http.Logging Path: [Microsoft.Extensions.Http.Logging.HttpHeadersLogValue](https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Http/src/Logging/HttpHeadersLogValue.cs) ```csharp namespace Microsoft.Extensions.Http.Logging; internal sealed class HttpHeadersLogValue : IReadOnlyList> { /* private properties */ private readonly Guid _correlationId; public HttpHeadersLogValue(Kind kind, HttpHeaders headers, HttpHeaders? contentHeaders, Func shouldRedactHeaderValue, Guid correlationId) { _kind = kind; _shouldRedactHeaderValue = shouldRedactHeaderValue; Headers = headers; ContentHeaders = contentHeaders; _correlationId = correlationId; } private List> Values { get { /*some code*/ values.Add(new KeyValuePair("CorrelationId", _correlationId)); /*some code*/ } } } ``` # LoggingHttpMessageHandler class namespace: Microsoft.Extensions.Http.Logging Path: [Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler](https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs) ```csharp namespace Microsoft.Extensions.Http.Logging; public class LoggingHttpMessageHandler : DelegatingHandler { /* private properties and methods */ protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) { ThrowHelper.ThrowIfNull(request); return Core(request, cancellationToken); async Task Core(HttpRequestMessage request, CancellationToken cancellationToken) { Func shouldRedactHeaderValue = _options?.ShouldRedactHeaderValue ?? _shouldNotRedactHeaderValue; Guild correlationId = Guid.NewGuid(); // Not using a scope here because we always expect this to be at the end of the pipeline, thus there's // not really anything to surround. Log.RequestStart(_logger, request, shouldRedactHeaderValue, correlationId ); var stopwatch = ValueStopwatch.StartNew(); HttpResponseMessage response = await base.SendAsync(request, cancellationToken).ConfigureAwait(false); Log.RequestEnd(_logger, response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue, correlationId ); return response; } } } internal static class Log { /* internal properties and methods */ public static void RequestStart(ILogger logger, HttpRequestMessage request, Func shouldRedactHeaderValue, Guid correlationId) { /* code */ logger.Log( LogLevel.Trace, EventIds.RequestHeader, new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue, correlationId), null, (state, ex) => state.ToString()); } public static void RequestEnd(ILogger logger, HttpResponseMessage response, TimeSpan duration, Func shouldRedactHeaderValue, Guid correlationId) { /* code */ logger.Log( LogLevel.Trace, EventIds.ResponseHeader, new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue, correlationId), null, (state, ex) => state.ToString()); } } ``` ### API Usage In general case you will see correlation id in Window Outputs or Console. In client-side code the result should be something like: ```csharp static void ProcessLogs(processId) { // setup var providers = new List() { new EventPipeProvider( "Microsoft-Extensions-Logging", EventLevel.Verbose, 8) }; var client = new DiagnosticsClient(processId); using (EventPipeSession session = client.StartEventPipeSession(providers, false)) { source.Dynamic.All += async (TraceEvent obj) => { var eventId = Convert.ToInt32(obj.PayloadByName("EventId")); var loggerName = obj.PayloadStringByName("LoggerName"); if (loggerName == "System.Net.Http.HttpClient.Default.ClientHandler") { var data = obj.PayloadByName("ArgumentsJson"); var deserializedData = JsonSerializer.Deserialize(data.ToString()); // Now we can use correlationId for matching request/response logs //deserializedData.CorrelationId } } } } ``` ### Alternative Designs _No response_ ### Risks _No response_

Author:	OlzhabaevSh
Assignees:	-
Labels:	`api-suggestion`, `untriaged`, `area-Extensions-HttpClientFactory`
Milestone:	-

[jander-msft]

@CarnaViire Thank for your reply.

Unfortunately, in our case HttpEventListenerwill not work, because we would like to read logs outside of running app.

We also tried to use dotnet trace tool but dotnet trace doesn't work in realtime. I mean it collect logs and provide it after finishing the program. In our case we would like to read logs in realtime.

In general, we would like to not touch the client-side code (I mean no additional libs or code injection). That's reason why we didn't try to just pass our custom HttpMessageHandler.

In the best scenario our tool should be able to read http logs from any dotnet core based app, if they enabled logs for http in DI container

Take a look at dotnet-monitor, which provides the ability to capture logs from outside of the target process in real time, among other capabilities: https://github.com/dotnet/dotnet-monitor/blob/main/documentation/api/logs.md

[OlzhabaevSh]

@OlzhabaevSh thanks for the suggestions.

In the meantime, did you consider leveraging .NET Networking Telemetry? https://devblogs.microsoft.com/dotnet/net-5-new-networking-improvements/#telemetry It contains RequestStart, RequestStop along many other events, and there's also ActivityId -- the correlation ID you were asking about.

The events can be consumed via PerfView or dotnet-trace, or with a custom event listener.

Hm... We also think that ActivityId should work but there is some issue:

1. ActivityId can be an empty GUID sometimes (and I don't know why).
2. Also, let me know if I'm mistake, but looks like ActivityId should be using as key for the chain. In real situations we are going to visualize not only events when a request started and finished, we are also going to present some metadata (like content body, status codes, headers and etc.)

Could it be just easier to everyone if correlationId would be contained in the body of log message?

From my point of view, it can simplify the logs processing for the future as well.

[OlzhabaevSh]

@jander-msft Thank you for your reply!

In general, we also found the way how to read logs externally. Our solution use DiagnisticsClient as dotnet-monitor does.

The second question is could we add CorrelationId into request/response log message body to match when we process logs or it can be done somehow else?

[CarnaViire]

ActivityId can be an empty GUID sometimes (and I don't know why).

@MihaZupan do you know when and why this could happen?

Also, let me know if I'm mistake, but looks like ActivityId should be using as key for the chain.

What do you mean by "key for the chain" @OlzhabaevSh?

[MihaZupan]

First of, ActivityID is not a Guid, the type is lying to you. It's a custom 16-byte encoding of the async hierarchy stuffed into a Guid. See https://learn.microsoft.com/en-gb/dotnet/core/diagnostics/eventsource-activity-ids and https://learn.microsoft.com/en-gb/dotnet/fundamentals/networking/networking-telemetry#correlation-outside-the-process.

When decoded, ActivityIDs will look something like this

System.Net.Http/Request/Start           ActivityID="/#14396/1/1/"
System.Net.Http/RequestHeaders/Start    ActivityID="/#14396/1/1/2/"
System.Net.Http/RequestHeaders/Stop     ActivityID="/#14396/1/1/2/"
System.Net.Http/ResponseHeaders/Start   ActivityID="/#14396/1/1/3/"
System.Net.Http/ResponseHeaders/Stop    ActivityID="/#14396/1/1/3/"
System.Net.Http/Request/Stop            ActivityID="/#14396/1/1/"

You can use this gist to parse and visualize the ID: https://gist.github.com/MihaZupan/cc63ee68b4146892f2e5b640ed57bc09 (ActivityHelpers.ActivityPathString).

ActivityID can be empty if the event is not associated with any ambient correlation state (e.g. an event fired in some background processing task). It can also be empty if you don't enable its collection. Since you're using TraceEvent, you must enable the System.Threading.Tasks.TplEventSource provider with the 0x80 keywords set.

ActivityID is the only mechanism you can use to correlate the majority of EventSource events outside of the process with a given HTTP request. Adding a correlation ID on the logs in LoggingHttpMessageHandler wouldn't achieve much. You should use events provided by System.Net.Http instead of the ILogger messages in this case.

Also, let me know if I'm mistake, but looks like ActivityId should be using as key for the chain

It should not be. Each request will have many different ActivityIDs associated with it. You should decode the IDs into hierarchical representation (see above) and match events by the prefix you care about (e.g. the prefix of the System.Net.Http/RequestStart event.

[CarnaViire]

Triage: Closing this issue in favor of #77312

@OlzhabaevSh in the meantime, please refer to @MihaZupan's answer above on how to use ActivityID. Let us know if you need any additional help with that, or if we missed something.