opentelemetry-dotnet
opentelemetry-dotnet copied to clipboard
open-telemetry
Many logs from OtlpMetricExporter. Exporting telemetry shouldn't generate new telemetry unless there is an error.
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
APIs to remove logging are in Microsoft.Extensions.Http 8.0 and greater:
See https://github.com/dotnet/runtime/issues/77312#issuecomment-1631264572
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
@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?
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.
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.
@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 https://github.com/open-telemetry/opentelemetry-dotnet/pull/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.
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?
Any progress on this?
The latest version of the OTLP exporter for .NET no longer depends on Grpc.Net.Client and allows users to control HttpClient similarly to OTLP/HTTP. Have you tried it?
Can you elaborate on which version should be used and how to control the logging. I am currently seeing System.Net.Http 9.0.0 in my assemblies list
Came here to complain that OTEL generates more telemetry about itself than my app does. I see I'm in the same boat as others :)
I think that's the important thing here: Exporting telemetry shouldn't generate new telemetry unless there is an error.
As an aside, suppressing the exporter noise with the tricks above still leaves Polly squawking continually about her pipelines [that are used in the exporter.]
I think this note belongs here because it should be part of the same effort to stop OTEL generating noise.
Solving your problems
builder.Services
.AddHttpClient("OtlpMetricExporter")
.RemoveAllLoggers();
builder.Services
.AddHttpClient("OtlpTraceExporter")
.RemoveAllLoggers();
As an aside, I couldn't find any easy way to shut [OTEL dotnet's use of] polly up either.
https://github.com/open-telemetry/opentelemetry-dotnet/tree/main/docs/trace/extending-the-sdk#exporter Should be modified with any guidance for exporter author (including exporters maintained in this repo).
It currently has "Exporters should avoid generating telemetry and causing live-loop, this can be done via OpenTelemetry.SuppressInstrumentationScope." and from what I can tell, is already followed by OTLP Exporters.
If we need to modify it to talk about suppressing ILogger separately, so that Non-OTEL providers will also not get the logs, that should be added to the above doc.
@JamesNK can you share if that is what you intended to convey? i.e OTLPExporters should itself shutoff ILogger providers (any) from getting logs from itself?
My expectation is it should be up to end-users to turn it off, but I haven't thought fully through the implications..
Here is my scenario:
.NET Aspire configures apps to export telemetry every second. It does this because it knows the apps are running in a development environment and it makes telemetry feel very responsive.
The problem is metrics change every second. That means every second they're exported, and the default behavior of ILogger in most .NET apps is write to the console. Every second 5 logs are written to the console that telemetry is being exported:
2025-04-28T15:33:15 info: System.Net.Http.HttpClient.OtlpMetricExporter.LogicalHandler[100]
2025-04-28T15:33:15 Start processing HTTP request POST https://localhost:16038/v1/metrics
2025-04-28T15:33:15 info: System.Net.Http.HttpClient.OtlpMetricExporter.ClientHandler[100]
2025-04-28T15:33:15 Sending HTTP request POST https://localhost:16038/v1/metrics
2025-04-28T15:33:15 info: System.Net.Http.HttpClient.OtlpMetricExporter.ClientHandler[101]
2025-04-28T15:33:15 Received HTTP response headers after 1.4139ms - 200
2025-04-28T15:33:15 info: Polly[3]
2025-04-28T15:33:15 Execution attempt. Source: '-standard//Standard-Retry', Operation Key: '', Result: '200', Handled: 'False', Attempt: '0', Execution Time: 4.0729ms
2025-04-28T15:33:15 info: System.Net.Http.HttpClient.OtlpMetricExporter.LogicalHandler[101]
2025-04-28T15:33:15 End processing HTTP request after 7.0343ms - 200
.NET Aspire is an extreme case of this problem because of how aggressively it exports data, but every .NET app is going to get this to a lesser degree. The evidence is people complaining about it here. Even if a user's app is idle, logs are going to fill up with repeating messages about telemetry being exported. I will add that the logs written here are at a pretty high level too: info, rather than something lower like debug or trace.
What I think should happen is OTEL should automatically filter ILogger logs unless the SDK log level is set, aka OTEL_LOG_LEVEL. It should be easy enough to add a filter for System.Net.Http.HttpClient.OtlpMetricExporter (and the other exporter names) to logging configuration depending on what the SDK log level is.
My expectation is it should be up to end-users to turn it off, but I haven't thought fully through the implications..
I don't want to require more code in users apps for a good experience. A good experience should be the default.