dotnet
How do I use AddHttpClientLatencyTelemetry?
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.
https://github.com/dotnet/extensions/blob/16acdbf1442f579862cfea15ffd0782510078ff0/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Logging/HttpClientLoggingHttpClientBuilderExtensions.cs#L96-L100
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.
