Adjust Log levels in OltpExporter#8133
Conversation
BenchmarksBenchmark execution time: 2026-03-16 19:09:36 Comparing candidate commit 62a162e in PR branch Found 2 performance improvements and 11 performance regressions! Performance is the same for 158 metrics, 21 unstable metrics. scenario:Benchmarks.Trace.ActivityBenchmark.StartStopWithChild net6.0
scenario:Benchmarks.Trace.AgentWriterBenchmark.WriteAndFlushEnrichedTraces net6.0
scenario:Benchmarks.Trace.Asm.AppSecBodyBenchmark.AllCycleSimpleBody net472
scenario:Benchmarks.Trace.Asm.AppSecBodyBenchmark.ObjectExtractorMoreComplexBody netcoreapp3.1
scenario:Benchmarks.Trace.CharSliceBenchmark.OptimizedCharSlice net6.0
scenario:Benchmarks.Trace.DbCommandBenchmark.ExecuteNonQuery net6.0
scenario:Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearchAsync net472
scenario:Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearchAsync net6.0
scenario:Benchmarks.Trace.HttpClientBenchmark.SendAsync netcoreapp3.1
scenario:Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatAspectBenchmark netcoreapp3.1
scenario:Benchmarks.Trace.Log4netBenchmark.EnrichedLog netcoreapp3.1
scenario:Benchmarks.Trace.SingleSpanAspNetCoreBenchmark.SingleSpanAspNetCore netcoreapp3.1
|
andrewlock
left a comment
There was a problem hiding this comment.
Thanks, I think most of these Should stay as errors, but mostly because AFAICT, they never occur. And we're missing some logs in some places we should have them I think
| // Seeing network connectivity errors so skipping telemetry | ||
| Log.ErrorSkipTelemetry(ex, "Error sending OTLP request (attempt {Attempt})", (attempt + 1).ToString()); |
There was a problem hiding this comment.
Arguably, this shouldn't be an error at all IMO. Transient errors are expected, so this almost certainly shouldn't be logging an error at all. In Api for example, these "intermediate" attempts are Debug. Also nit, AI did the ToString() I assume 🙄
| // Seeing network connectivity errors so skipping telemetry | |
| Log.ErrorSkipTelemetry(ex, "Error sending OTLP request (attempt {Attempt})", (attempt + 1).ToString()); | |
| Log.Debug<int>(ex, "Error sending OTLP request (attempt {Attempt})", attempt + 1);``` |
There was a problem hiding this comment.
Ah yes, I ran my /analyze-error on it, forgot to add the label
There was a problem hiding this comment.
I'll swap these over thanks!
Execution-Time Benchmarks Report ⏱️Execution-time results for samples comparing This PR (8133) and master. ✅ No regressions detected - check the details below Full Metrics ComparisonFakeDbCommand
HttpMessageHandler
Comparison explanationExecution-time benchmarks measure the whole time it takes to execute a program, and are intended to measure the one-off costs. Cases where the execution time results for the PR are worse than latest master results are highlighted in **red**. The following thresholds were used for comparing the execution times:
Note that these results are based on a single point-in-time result for each branch. For full results, see the dashboard. Graphs show the p99 interval based on the mean and StdDev of the test run, as well as the mean value of the run (shown as a diamond below the graph). Duration chartsFakeDbCommand (.NET Framework 4.8)gantt
title Execution time (ms) FakeDbCommand (.NET Framework 4.8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8133) - mean (77ms) : 74, 79
master - mean (79ms) : 76, 82
section Bailout
This PR (8133) - mean (81ms) : 79, 84
master - mean (84ms) : 81, 87
section CallTarget+Inlining+NGEN
This PR (8133) - mean (1,115ms) : 1058, 1172
master - mean (1,122ms) : 1073, 1171
FakeDbCommand (.NET Core 3.1)gantt
title Execution time (ms) FakeDbCommand (.NET Core 3.1)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8133) - mean (120ms) : 116, 125
master - mean (121ms) : 116, 125
section Bailout
This PR (8133) - mean (123ms) : 119, 126
master - mean (122ms) : 120, 125
section CallTarget+Inlining+NGEN
This PR (8133) - mean (777ms) : 743, 810
master - mean (772ms) : 743, 800
FakeDbCommand (.NET 6)gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8133) - mean (107ms) : 103, 110
master - mean (106ms) : 103, 109
section Bailout
This PR (8133) - mean (107ms) : 105, 109
master - mean (107ms) : 105, 109
section CallTarget+Inlining+NGEN
This PR (8133) - mean (755ms) : 715, 795
master - mean (761ms) : 719, 804
FakeDbCommand (.NET 8)gantt
title Execution time (ms) FakeDbCommand (.NET 8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8133) - mean (105ms) : 103, 108
master - mean (106ms) : 102, 109
section Bailout
This PR (8133) - mean (107ms) : 105, 110
master - mean (107ms) : 105, 110
section CallTarget+Inlining+NGEN
This PR (8133) - mean (698ms) : 671, 725
master - mean (692ms) : 664, 720
HttpMessageHandler (.NET Framework 4.8)gantt
title Execution time (ms) HttpMessageHandler (.NET Framework 4.8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8133) - mean (194ms) : 190, 198
master - mean (194ms) : 190, 199
section Bailout
This PR (8133) - mean (198ms) : 194, 202
master - mean (198ms) : 195, 200
section CallTarget+Inlining+NGEN
This PR (8133) - mean (1,169ms) : 1091, 1246
master - mean (1,157ms) : 1094, 1220
HttpMessageHandler (.NET Core 3.1)gantt
title Execution time (ms) HttpMessageHandler (.NET Core 3.1)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8133) - mean (278ms) : 271, 284
master - mean (278ms) : 271, 285
section Bailout
This PR (8133) - mean (279ms) : 275, 283
master - mean (279ms) : 276, 282
section CallTarget+Inlining+NGEN
This PR (8133) - mean (902ms) : 873, 930
master - mean (902ms) : 874, 930
HttpMessageHandler (.NET 6)gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8133) - mean (271ms) : 267, 276
master - mean (274ms) : 268, 279
section Bailout
This PR (8133) - mean (271ms) : 267, 275
master - mean (272ms) : 268, 275
section CallTarget+Inlining+NGEN
This PR (8133) - mean (936ms) : 908, 963
master - mean (940ms) : 916, 963
HttpMessageHandler (.NET 8)gantt
title Execution time (ms) HttpMessageHandler (.NET 8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8133) - mean (271ms) : 265, 277
master - mean (270ms) : 266, 275
section Bailout
This PR (8133) - mean (270ms) : 267, 274
master - mean (271ms) : 267, 275
section CallTarget+Inlining+NGEN
This PR (8133) - mean (840ms) : 807, 873
master - mean (842ms) : 820, 865
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
## Summary of changes Updates `/analyze-error` to not update all `Log.Error` calls in the to `Log.ErrorSkipTelemetry` as it did in #8133 Added some more generic logging considerations to `AGENTS.md` ## Reason for change The `/analyze-error` command was instructing to update all instances of `Log.Error` instead of just the correct / expected one. AGENTS.md had some logging information but I think it lacked some specificity, so updating very basically with some "best practices" ## Implementation details ## Test coverage ## Other details <!-- Fixes #{issue} --> I reran the `/analyze-error` command with these changes again on the same error I did with #8133 and with both of these it changed to this following diff. It isn't _perfect_ but at least it isn't super wrong, it also changed the `ToString` used to a generic call. Note that the initial change was 5ab5b10 ```diff diff --git a/tracer/src/Datadog.Trace/OpenTelemetry/Metrics/OtlpExporter.cs b/tracer/src/Datadog.Trace/OpenTelemetry/Metrics/OtlpExporter.cs index e90bee8..8c2acd3c2 100644 --- a/tracer/src/Datadog.Trace/OpenTelemetry/Metrics/OtlpExporter.cs +++ b/tracer/src/Datadog.Trace/OpenTelemetry/Metrics/OtlpExporter.cs @@ -353,21 +353,27 @@ namespace Datadog.Trace.OpenTelemetry.Metrics } catch (TaskCanceledException) when (attempt < maxRetries) { + Log.Debug<int>("OTLP request timed out (attempt {Attempt}), retrying...", attempt + 1); + retryDelay = TimeSpan.FromMilliseconds((long)(retryDelay.TotalMilliseconds * 2)); + await Task.Delay(retryDelay).ConfigureAwait(false); + } + catch (TaskCanceledException ex) + { + // Final timeout after all retries exhausted + Log.ErrorSkipTelemetry<Uri, int>(ex, "OTLP request to {Endpoint} timed out after {Attempt} attempts. See https://docs.datadoghq.com/tracing/troubleshooting/ for troubleshooting.", _endpoint, attempt + 1); + return false; + } + catch (Exception ex) when (attempt < maxRetries) + { + Log.Debug<int>(ex, "Error sending OTLP request (attempt {Attempt}), retrying...", attempt + 1); retryDelay = TimeSpan.FromMilliseconds((long)(retryDelay.TotalMilliseconds * 2)); await Task.Delay(retryDelay).ConfigureAwait(false); } catch (Exception ex) { - Log.Error(ex, "Error sending OTLP request (attempt {Attempt})", (attempt + 1).ToString()); - if (attempt < maxRetries) - { - retryDelay = TimeSpan.FromMilliseconds((long)(retryDelay.TotalMilliseconds * 2)); - await Task.Delay(retryDelay).ConfigureAwait(false); - } - else - { - return false; - } + // Final failure after all retries exhausted + Log.ErrorSkipTelemetry<Uri, int>(ex, "Failed to send OTLP request to {Endpoint} after {Attempt} attempts. See https://docs.datadoghq.com/tracing/troubleshooting/ for troubleshooting.", _endpoint, attempt + 1); + return false; } } ``` <!--⚠️ Note: Where possible, please obtain 2 approvals prior to merging. Unless CODEOWNERS specifies otherwise, for external teams it is typically best to have one review from a team member, and one review from apm-dotnet. Trivial changes do not require 2 reviews. MergeQueue is NOT enabled in this repository. If you have write access to the repo, the PR has 1-2 approvals (see above), and all of the required checks have passed, you can use the Squash and Merge button to merge the PR. If you don't have write access, or you need help, reach out in the #apm-dotnet channel in Slack. --> --------- Co-authored-by: Andrew Lock <[email protected]>
- Use Log.Error for 400 Bad Request (indicates a bug in our payload) - Use Log.Debug for intermediate retry attempts (transient/expected) - Add ErrorSkipTelemetry with endpoint and troubleshooting link on final failure - Fix ToString() allocation in log call by using generic method Co-Authored-By: Claude Opus 4.6 (1M context) <[email protected]>
efa17bc to
62a162e
Compare
Summary of changes
Changes the log levels in
OtlpExporterto skip telemetry for some errors (while making them go from Debug to Error) and swapping some DebugReason for change
Noticed a lot of new errors but they just seem to be transient networking errors.
https://app.datadoghq.com/error-tracking/issue/443da854-fe18-11f0-ae87-da7ad0900002
Some of the current logs were either the wrong level or absent.
Implementation details
Log.ErrorSkipTelemetry("An error occurred while sending OTLP request to {AgentEndpoint}.for when we get transient network issueLog.Error(ex, "Error sending OTLP request (attempt {Attempt})", (attempt + 1).ToString());->Log.Debug<int>(ex, "Error sending OTLP request (attempt {Attempt})", attempt + 1);along with removing the string allocationTest coverage
Other details