Many logs from OtlpMetricExporter

[JamesNK]

Package

OpenTelemetry.Exporter.OpenTelemetryProtocol

Package Version

Package Name	Version
OpenTelemetry.Api	1.8.0
OpenTelemetry	1.8.0
TBD	TBD

Runtime Version

net8.0

Description

I have configured OtlpMetricExporter to frequently export logs/metrics/traces. The console output of my app is overwhelmed by messages about sending logs:

2024-06-25T09:44:20.1475445 info: System.Net.Http.HttpClient.OtlpMetricExporter.LogicalHandler[100]
      Start processing HTTP request POST https://localhost:16038/v1/metrics
2024-06-25T09:44:20.1489914 info: System.Net.Http.HttpClient.OtlpMetricExporter.ClientHandler[100]
      Sending HTTP request POST https://localhost:16038/v1/metrics
2024-06-25T09:44:20.1538312 info: System.Net.Http.HttpClient.OtlpMetricExporter.ClientHandler[101]
      Received HTTP response headers after 3.5605ms - 200
2024-06-25T09:44:20.1561990 info: System.Net.Http.HttpClient.OtlpMetricExporter.LogicalHandler[101]
      End processing HTTP request after 8.6638ms - 200
2024-06-25T09:44:21.1417709 info: System.Net.Http.HttpClient.OtlpMetricExporter.LogicalHandler[100]
      Start processing HTTP request POST https://localhost:16038/v1/metrics
2024-06-25T09:44:21.1433057 info: System.Net.Http.HttpClient.OtlpMetricExporter.ClientHandler[100]
      Sending HTTP request POST https://localhost:16038/v1/metrics
2024-06-25T09:44:21.1489110 info: System.Net.Http.HttpClient.OtlpMetricExporter.ClientHandler[101]
      Received HTTP response headers after 4.3301ms - 200
2024-06-25T09:44:21.1508084 info: System.Net.Http.HttpClient.OtlpMetricExporter.LogicalHandler[101]
      End processing HTTP request after 9.0477ms - 200
2024-06-25T09:44:22.1385920 info: System.Net.Http.HttpClient.OtlpMetricExporter.LogicalHandler[100]
      Start processing HTTP request POST https://localhost:16038/v1/metrics
2024-06-25T09:44:22.1406961 info: System.Net.Http.HttpClient.OtlpMetricExporter.ClientHandler[100]
      Sending HTTP request POST https://localhost:16038/v1/metrics
2024-06-25T09:44:22.1471257 info: System.Net.Http.HttpClient.OtlpMetricExporter.ClientHandler[101]
      Received HTTP response headers after 4.6983ms - 200

The problem is the metrics (and tracing) exporters are configured to create the HttpClient from Microsoft.Extensions.Http, and it adds logging that outputs these messages. Every export writes 4 messages (8 lines) to console logs.

HttpClient logging should be disabled for these clients.

Steps to Reproduce

Configure OTLP export using OTLP/gRPC. Set export interval to a low number.

Expected Result

Clean console output.

Actual Result

Unhelpful log messages everywhere.

Additional Context

No response

[JamesNK]

APIs to remove logging are in Microsoft.Extensions.Http 8.0 and greater:

See dotnet/runtime#77312 (comment)

You want to call RemoveAllLoggers when configuring the OTLP/HTTP clients. You can write more reflection in TryEnableIHttpClientFactoryIntegration to test if the API is available and then invoke it if it is.

cc @CarnaViire

[stevejgordon]

@JamesNK I'm still getting up to speed in this repo, so I'm adding some notes that may or may not be obvious to anyone finding
this issue. I was also unaware of these new extensions, so thanks for teaching me something new!

The SDK doesn't specifically register (AFAIK) the named client using AddHttpClient("name") but relies on CreateClient("name") falling back to a default client if a name is not matched (again, AFAIK). The workaround right now is to control this in your app during service registration by specifying the named clients and configuring their builder.

builder.Services.AddHttpClient("OtlpTraceExporter").RemoveAllLoggers();
builder.Services.AddHttpClient("OtlpMetricExporter").RemoveAllLoggers();

Or appsettings.json could also be used to filter these out.

The code you linked to doesn't seem like it would facilitate using RemoveAllLoggers because, by that point, the IServiceProvider is built. Or am I missing something?

[JamesNK]

You're right that it can't happen in that location. Configuration could be added to the app to disable logging, but logging OTLP HTTP requests at an info level doesn't seem desirable in the first place.

And I think it's weird how HttpClientFactory is used:

• OTLP/HTTP metrics - Yes
• OTLP/HTTP tracing - Yes
• OTLP/HTTP logging - No
• OTLP/gRPC metrics - No
• OTLP/gRPC tracing - No
• OTLP/gRPC logging - No

Using it selectively like this creates confusion.

[stevejgordon]

Yes, the fact that gRPC doesn't use OtlpExporterOptions. ' HttpClientFactory is a pain, and I ran into that with something else, too. From a quick scan of the code, it should be possible to use an HttpClient created by the factory when setting up the GrpcChannel. This would align the behaviour between HTTP and gRPC.

@cijothomas / @vishweshbankwar - Do you know why the gRPC client doesn't use the HttpClientFactory? Would you be open to a PR from me to add that?

The Logging exporter doesn't currently use the factory due to a circular dependency, but I assume the intent is to fix that. I agree; it would be nice for that to be consistent across OTLP exporters.

The HTTP request logging at info is coming from Microsoft.Extensions.Http. Given the verbosity of these events, I am a bit surprised the implementation uses info. I can see the value in these being logged at trace to help diagnose failures. Four info messages per outbound HTTP request seems a bit extreme.

One option in this library is to explicitly register a named client and configure the removal of all loggers. That might impact the ease of diagnosing transient problems with the export, though. It might also be possible to hack around with the configuration to filter them automatically, although that behaviour might also be surprising. The maintainers might need to weigh in with a view on the preferred behaviour. I'd be happy to investigate further if the decision is to change the current behaviour. Alternatively, we should consider documenting how these can be disabled in customer applications.

[vishweshbankwar]

@stevejgordon

Do you know why the gRPC client doesn't use the HttpClientFactory? Would you be open to a PR from me to add that?

I am currently working on #5731 to remove dependency on Grpc.Net.Client entirely and use HttpClient for gRPC calls as well. With that, users would be able to control the HttpClient similar to OTLP/HTTP. I am looking to gather some initial feedback on it.

[FoxTes]

As a result: at the moment is this some kind of effective and relatively "correct" way to disable or change the log level of opentelemetry?