How do I use AddHttpClientLatencyTelemetry?

[aetos382]

Description

See the reproduction steps section for the code I wrote.

The code outputs the following log.

{
  "EventId": 1,
  "LogLevel": "Information",
  "Category": "Microsoft.Extensions.Http.Logging.HttpClientLogger",
  "Message": "GET dot.net/REDACTED",
  "State": {
    "Message": "LatencyInfo=,,http.request.method=GET,server.address=dot.net,url.path=REDACTED,Duration=2613,http.response.status_code=200",
    "LatencyInfo": ",",
    "http.request.method": "GET",
    "server.address": "dot.net",
    "url.path": "REDACTED",
    "Duration": 2613,
    "http.response.status_code": 200
  }
}

The LatencyInfo in log is empty. How can I get it to output a valid value here?

I apologise if I have misunderstood how to use this library. In that case, please tell me how to use it correctly.

Reproduction Steps

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;

var services = new ServiceCollection();

services
    .AddHttpClient()
    .AddRedaction()
    .AddLatencyContext()
    .AddExtendedHttpClientLogging()
    .AddHttpClientLatencyTelemetry();

services.AddLogging(static builder =>
    builder.AddJsonConsole(static options =>
    {
        options.JsonWriterOptions = new()
        {
            Indented = true
        };
    }));

await using var serviceProvider = services.BuildServiceProvider();

var client = serviceProvider.GetRequiredService<HttpClient>();

using var response = await client.GetAsync("http://dot.net").ConfigureAwait(false);

Console.WriteLine(response.StatusCode);

Expected behavior

The LatencyInfo in the log should be as follows, shouldn't it?

"LatencyInfo": ",handreqs/dnss/dnse/cons/cone/cones/rlq/reqhs/reqhe/reshs/reshe/enrin/,0.1706/68.8664/81.0259/86.9632/335.9692/341.1706/341.921/342.4656/342.7676/629.649/630.2728/1358.2388999999998/"

Actual behavior

The LatencyInfo in the log is as follows

"LatencyInfo":","

Regression?

The behavior was the same in ver 8.0.0.

Known Workarounds

No response

Configuration

<Project Sdk="Microsoft.NET.Sdk">

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net9.0</TargetFramework>
    <ImplicitUsings>enable</ImplicitUsings>
    <Nullable>enable</Nullable>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Microsoft.Extensions.Compliance.Redaction" Version="9.0.0" />
    <PackageReference Include="Microsoft.Extensions.Http.Diagnostics" Version="9.0.0" />
    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="9.0.0" />
  </ItemGroup>

</Project>

Other information

HttpClientLoggerHandler runs outside HttpLatencyTelemetryHandler because the wrapHandlersPipeline parameter is set to true when the HttpClientLogger is added.

extensions/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Logging/HttpClientLoggingHttpClientBuilderExtensions.cs

Lines 96 to 100 in 16acdbf

	return builder
	.RemoveAllLoggers()
	.AddLogger(
	serviceProvider => serviceProvider.GetRequiredKeyedService<HttpClientLogger>(builder.Name),
	wrapHandlersPipeline: true);

The ILatencyContext is stored in AsyncLocal, so it is not possible to read the value that was set downstream of the call from upstream.
In other words, I think that the HttpClientLoggerHandler cannot get the values set by the HttpLatencyTelemetryHandler.

When I changed the wrapHandlersPipeline parameter to false while debugging, I got the output I wrote in the Expected behaviour section. Is it correct that this parameter is true?

Alternatively, using AsyncState instead of AsyncLocal.

[iliar-turdushev]

@aetos382 Thank you for reporting the bug.