fix(system-probe-lite): log full error chain to surface EPERM and other causes#50538
Conversation
…rors
`hyper::Error` and `anyhow::Error` both implement `Display` to show only
the top-level message. The `{:#}` alternate format on `anyhow::Error`
traverses the full `.source()` chain, joining all levels with `: `.
Three call sites updated:
- "Error serving connection" (hyper::Error wrapped via anyhow::Error::new)
- "Request handling failed" (already anyhow::Error, just needed `#`)
- "Failed to restrict capabilities" (same)
Without the fix, a seccomp EPERM on `writev` logged only:
Error serving connection: error writing a body to connection
After:
Error serving connection: error writing a body to connection: Operation not permitted (os error 1)
Manual test (request handler path):
Before: Request handling failed: request processing failed
After: Request handling failed: request processing failed: inner cause detail
This was surfaced while debugging helm-charts#2634, which added `writev`,
`shutdown`, and `chown` to the system-probe seccomp profile for SPL.
Co-Authored-By: Claude Sonnet 4.6 <[email protected]>
Files inventory check summaryFile checks results against ancestor ef81861a: Results for datadog-agent_7.80.0~devel.git.601.9685706.pipeline.112154034-1_amd64.deb:No change detected |
Static quality checks✅ Please find below the results from static quality gates Successful checksInfo
24 successful checks with minimal change (< 2 KiB)
|
Regression DetectorRegression Detector ResultsMetrics dashboard Baseline: aeea69d Optimization Goals: ✅ No significant changes detected
|
| perf | experiment | goal | Δ mean % | Δ mean % CI | trials | links |
|---|---|---|---|---|---|---|
| ➖ | docker_containers_cpu | % cpu utilization | +1.46 | [-1.51, +4.42] | 1 | Logs |
Fine details of change detection per experiment
| perf | experiment | goal | Δ mean % | Δ mean % CI | trials | links |
|---|---|---|---|---|---|---|
| ➖ | docker_containers_cpu | % cpu utilization | +1.46 | [-1.51, +4.42] | 1 | Logs |
| ➖ | ddot_metrics_sum_cumulative | memory utilization | +0.70 | [+0.53, +0.86] | 1 | Logs |
| ➖ | uds_dogstatsd_20mb_12k_contexts_20_senders | memory utilization | +0.32 | [+0.27, +0.37] | 1 | Logs |
| ➖ | docker_containers_memory | memory utilization | +0.10 | [+0.00, +0.20] | 1 | Logs |
| ➖ | otlp_ingest_logs | memory utilization | +0.04 | [-0.06, +0.15] | 1 | Logs |
| ➖ | file_to_blackhole_500ms_latency | egress throughput | +0.03 | [-0.38, +0.44] | 1 | Logs |
| ➖ | tcp_dd_logs_filter_exclude | ingress throughput | +0.01 | [-0.09, +0.11] | 1 | Logs |
| ➖ | file_to_blackhole_1000ms_latency | egress throughput | +0.01 | [-0.44, +0.45] | 1 | Logs |
| ➖ | file_to_blackhole_0ms_latency | egress throughput | +0.01 | [-0.50, +0.51] | 1 | Logs |
| ➖ | ddot_metrics | memory utilization | +0.01 | [-0.19, +0.21] | 1 | Logs |
| ➖ | uds_dogstatsd_to_api_v3 | ingress throughput | +0.00 | [-0.20, +0.20] | 1 | Logs |
| ➖ | uds_dogstatsd_to_api | ingress throughput | -0.01 | [-0.20, +0.19] | 1 | Logs |
| ➖ | file_tree | memory utilization | -0.04 | [-0.09, +0.01] | 1 | Logs |
| ➖ | file_to_blackhole_100ms_latency | egress throughput | -0.11 | [-0.25, +0.03] | 1 | Logs |
| ➖ | otlp_ingest_metrics | memory utilization | -0.24 | [-0.39, -0.08] | 1 | Logs |
| ➖ | ddot_metrics_sum_delta | memory utilization | -0.25 | [-0.43, -0.07] | 1 | Logs |
| ➖ | quality_gate_idle | memory utilization | -0.26 | [-0.31, -0.21] | 1 | Logs bounds checks dashboard |
| ➖ | tcp_syslog_to_blackhole | ingress throughput | -0.32 | [-0.51, -0.13] | 1 | Logs |
| ➖ | quality_gate_idle_all_features | memory utilization | -0.50 | [-0.54, -0.47] | 1 | Logs bounds checks dashboard |
| ➖ | ddot_metrics_sum_cumulativetodelta_exporter | memory utilization | -0.51 | [-0.75, -0.28] | 1 | Logs |
| ➖ | quality_gate_logs | % cpu utilization | -0.61 | [-1.59, +0.37] | 1 | Logs bounds checks dashboard |
| ➖ | quality_gate_metrics_logs | memory utilization | -0.70 | [-0.95, -0.44] | 1 | Logs bounds checks dashboard |
| ➖ | ddot_logs | memory utilization | -1.02 | [-1.09, -0.95] | 1 | Logs |
Bounds Checks: ✅ Passed
| perf | experiment | bounds_check_name | replicates_passed | observed_value | links |
|---|---|---|---|---|---|
| ✅ | docker_containers_cpu | simple_check_run | 10/10 | 674 ≥ 26 | |
| ✅ | docker_containers_memory | memory_usage | 10/10 | 241.49MiB ≤ 370MiB | |
| ✅ | docker_containers_memory | simple_check_run | 10/10 | 728 ≥ 26 | |
| ✅ | file_to_blackhole_0ms_latency | memory_usage | 10/10 | 0.16GiB ≤ 1.20GiB | |
| ✅ | file_to_blackhole_0ms_latency | missed_bytes | 10/10 | 0B = 0B | |
| ✅ | file_to_blackhole_1000ms_latency | memory_usage | 10/10 | 0.21GiB ≤ 1.20GiB | |
| ✅ | file_to_blackhole_1000ms_latency | missed_bytes | 10/10 | 0B = 0B | |
| ✅ | file_to_blackhole_100ms_latency | memory_usage | 10/10 | 0.17GiB ≤ 1.20GiB | |
| ✅ | file_to_blackhole_100ms_latency | missed_bytes | 10/10 | 0B = 0B | |
| ✅ | file_to_blackhole_500ms_latency | memory_usage | 10/10 | 0.19GiB ≤ 1.20GiB | |
| ✅ | file_to_blackhole_500ms_latency | missed_bytes | 10/10 | 0B = 0B | |
| ✅ | quality_gate_idle | intake_connections | 10/10 | 3 ≤ 4 | bounds checks dashboard |
| ✅ | quality_gate_idle | memory_usage | 10/10 | 141.53MiB ≤ 147MiB | bounds checks dashboard |
| ✅ | quality_gate_idle_all_features | intake_connections | 10/10 | 3 ≤ 4 | bounds checks dashboard |
| ✅ | quality_gate_idle_all_features | memory_usage | 10/10 | 470.79MiB ≤ 495MiB | bounds checks dashboard |
| ✅ | quality_gate_logs | intake_connections | 10/10 | 4 ≤ 6 | bounds checks dashboard |
| ✅ | quality_gate_logs | memory_usage | 10/10 | 173.26MiB ≤ 195MiB | bounds checks dashboard |
| ✅ | quality_gate_logs | missed_bytes | 10/10 | 0B = 0B | bounds checks dashboard |
| ✅ | quality_gate_metrics_logs | cpu_usage | 10/10 | 349.45 ≤ 2000 | bounds checks dashboard |
| ✅ | quality_gate_metrics_logs | intake_connections | 10/10 | 4 ≤ 6 | bounds checks dashboard |
| ✅ | quality_gate_metrics_logs | memory_usage | 10/10 | 362.40MiB ≤ 430MiB | bounds checks dashboard |
| ✅ | quality_gate_metrics_logs | missed_bytes | 10/10 | 0B = 0B | bounds checks dashboard |
Explanation
Confidence level: 90.00%
Effect size tolerance: |Δ mean %| ≥ 5.00%
Performance changes are noted in the perf column of each table:
- ✅ = significantly better comparison variant performance
- ❌ = significantly worse comparison variant performance
- ➖ = no significant change in performance
A regression test is an A/B test of target performance in a repeatable rig, where "performance" is measured as "comparison variant minus baseline variant" for an optimization goal (e.g., ingress throughput). Due to intrinsic variability in measuring that goal, we can only estimate its mean value for each experiment; we report uncertainty in that value as a 90.00% confidence interval denoted "Δ mean % CI".
For each experiment, we decide whether a change in performance is a "regression" -- a change worth investigating further -- if all of the following criteria are true:
-
Its estimated |Δ mean %| ≥ 5.00%, indicating the change is big enough to merit a closer look.
-
Its 90.00% confidence interval "Δ mean % CI" does not contain zero, indicating that if our statistical model is accurate, there is at least a 90.00% chance there is a difference in performance between baseline and comparison variants.
-
Its configuration does not mark it "erratic".
CI Pass/Fail Decision
✅ Passed. All Quality Gates passed.
- quality_gate_idle, bounds check memory_usage: 10/10 replicas passed. Gate passed.
- quality_gate_idle, bounds check intake_connections: 10/10 replicas passed. Gate passed.
- quality_gate_logs, bounds check memory_usage: 10/10 replicas passed. Gate passed.
- quality_gate_logs, bounds check intake_connections: 10/10 replicas passed. Gate passed.
- quality_gate_logs, bounds check missed_bytes: 10/10 replicas passed. Gate passed.
- quality_gate_metrics_logs, bounds check cpu_usage: 10/10 replicas passed. Gate passed.
- quality_gate_metrics_logs, bounds check intake_connections: 10/10 replicas passed. Gate passed.
- quality_gate_metrics_logs, bounds check missed_bytes: 10/10 replicas passed. Gate passed.
- quality_gate_metrics_logs, bounds check memory_usage: 10/10 replicas passed. Gate passed.
- quality_gate_idle_all_features, bounds check memory_usage: 10/10 replicas passed. Gate passed.
- quality_gate_idle_all_features, bounds check intake_connections: 10/10 replicas passed. Gate passed.
|
🎯 Code Coverage (details) 🔗 Commit SHA: 9685706 | Docs | Datadog PR Page | Give us feedback! |
…er causes (#50538) ### What does this PR do? In \`pkg/discovery/module/rust/src/main.rs\`, three \`error!\`/\`warn!\` call sites now use the \`{:#}\` alternate format (via \`anyhow\`) so the full error cause chain is included in the log line. | Call site | Before | After | |---|---|---| | \`serve_connection\` failure | \`Error serving connection: error writing a body to connection\` | \`Error serving connection: error writing a body to connection: Operation not permitted (os error 1)\` | | \`handle_request\` failure | \`Request handling failed: <top-level>\` | \`Request handling failed: <top-level>: <cause>\` | | \`drop_capabilities\` failure | \`Failed to restrict capabilities: <top-level>; …\` | \`Failed to restrict capabilities: <top-level>: <cause>; …\` | For \`hyper::Error\` (the connection error), wrapping in \`anyhow::Error::new(err)\` is required because \`hyper::Error\`'s own \`Display\` impl does not traverse \`.source()\`. For the two \`anyhow::Error\` sites the change is simply adding \`#\` to the format specifier. ### Motivation While debugging [helm-charts#2634](DataDog/helm-charts#2634), which added \`writev\`, \`shutdown\`, and \`chown\` to the system-probe seccomp allowlist for SPL, the only log produced was: ``` SYS-PROBE-LITE | ERROR | Error serving connection: error writing a body to connection ``` The underlying cause (\`Operation not permitted (os error 1)\`) was invisible, making \`strace\` necessary to identify the blocked syscall. With this fix the EPERM — or any other root cause — appears directly in the log. ### Describe how you validated your changes - \`bazel build --config=lint //pkg/discovery/module/rust/...\` passes - \`bazel test //pkg/discovery/module/rust/...\` — all 7 tests pass - Manual test for the \`serve_connection\` path: ran SPL with an \`LD_PRELOAD\` shim that makes every \`writev(2)\` call return \`EPERM\`, then sent a GET request to the socket: - **Before:** \`Error serving connection: error writing a body to connection\` - **After:** \`Error serving connection: error writing a body to connection: Operation not permitted (os error 1)\` - Manual test for the \`handle_request\` path: ran SPL with a temporary chained-error injection (\`anyhow!("inner").context("outer")\`) at the top of \`handle_request\`: - **Before:** \`Request handling failed: outer\` - **After:** \`Request handling failed: outer: inner\` Co-authored-by: vincent.whitchurch <[email protected]>
What does this PR do?
In `pkg/discovery/module/rust/src/main.rs`, three `error!`/`warn!` call sites now use the `{:#}` alternate format (via `anyhow`) so the full error cause chain is included in the log line.
For `hyper::Error` (the connection error), wrapping in `anyhow::Error::new(err)` is required because `hyper::Error`'s own `Display` impl does not traverse `.source()`. For the two `anyhow::Error` sites the change is simply adding `#` to the format specifier.
Motivation
While debugging helm-charts#2634, which added `writev`, `shutdown`, and `chown` to the system-probe seccomp allowlist for SPL, the only log produced was:
The underlying cause (`Operation not permitted (os error 1)`) was invisible, making `strace` necessary to identify the blocked syscall. With this fix the EPERM — or any other root cause — appears directly in the log.
Describe how you validated your changes