refactor: route pxe logs through the fleet's logfmt subscriber#3460
Conversation
PXE was the last binary logging through raw `println!`/`eprintln!` -- its lines had no level, no component, no span_id, and bypassed every filter. It now installs the same instrumentation subscriber as the rest of the fleet, tagged with the `nico-pxe` component, so its output is filterable and greppable like everything else and its warning/error rate feeds the fleet-wide `carbide_log_events_total` signal (pxe was the one binary missing from it).
Primary callouts are:
- `setup_tracing()` installs the fleet-standard subscriber at startup (`logfmt` layer + the `LogEventsMetric` counting layer + `EnvFilter` at INFO, `RUST_LOG`-overridable, with the usual per-dependency caps) -- pxe had none before. The log-events counter is an already-documented metric joining pxe's own `/metrics`, so the catalogue is untouched.
- The twelve logging prints become structured `tracing` calls at the right level: the seven error paths (`eprintln!`) are `error!` with the error and any URL as fields; the three operational prints are `info!`; and the request logger's hand-rolled logfmt renderer is replaced by a real `info_span!("request", ...)`, which now also carries the `component`, `span_id`, and timing it emitted by hand before.
- The one surviving `println!` is `--version`, which writes the bare version string to stdout by design -- machine-readable CLI output, not a log.
- `print_and_generate_generic_error` becomes `log_and_generate_generic_error` now that it logs rather than prints.
This supports NVIDIA#3180
Signed-off-by: Chet Nichols III <chetn@nvidia.com>
|
@coderabbitai full_review, thanks! |
Summary by CodeRabbit
WalkthroughPXE adds centralized tracing initialization, log-event metric registration, structured request spans, and structured error logging across extractors and routes while preserving existing response and fallback behavior. ChangesPXE observability pipeline
Estimated code review effort: 3 (Moderate) | ~25 minutes Sequence Diagram(s)sequenceDiagram
participant PXE
participant TracingSubscriber
participant RequestMiddleware
participant OTelMetrics
PXE->>TracingSubscriber: initialize filtered logfmt subscriber
PXE->>OTelMetrics: register log-events counter
RequestMiddleware->>TracingSubscriber: emit request span fields
TracingSubscriber->>OTelMetrics: count log events
Possibly related issues
🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches🧪 Generate unit tests (beta)
Comment |
|
🐇✨ ✅ Action performedFull review finished. |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 1
🧹 Nitpick comments (1)
crates/pxe/src/extractors/machine.rs (1)
47-51: 📐 Maintainability & Code Quality | 🔵 Trivial | 💤 Low valueMinor formatting inconsistency:
?(Debug) vs.%(Display) forerror/url.Every other new
tracing::error!call added in this PR (cloud_init.rs,ipxe.rs,tls.rs,main.rs) formats its error field with%. Hereerrorandurluse?, which — if the underlying types implementDisplay— will render quoted/escaped Debug output in logfmt instead of the plain value used elsewhere.♻️ Suggested fix (if `Display` is available on both types)
tracing::error!( - error = ?err, - url = ?state.runtime_config.internal_api_url, + error = %err, + url = %state.runtime_config.internal_api_url, "error connecting to forge api from pxe" );🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@crates/pxe/src/extractors/machine.rs` around lines 47 - 51, Update the tracing::error! call in the machine extractor to format both the error and internal_api_url fields with Display (`%`) instead of Debug (`?`), matching the other error logs in the diff. Keep the existing field names and message unchanged.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@crates/pxe/src/main.rs`:
- Around line 163-170: Update the EnvFilter construction near the `env_filter`
binding so directives from `RUST_LOG` take precedence over the hardcoded
`hyper`, `h2`, `tower`, `rustls`, and `tokio_util::codec` caps. Apply those
default caps only when the environment filter is absent, or merge them without
overriding same-target directives loaded by `from_env_lossy()`.
---
Nitpick comments:
In `@crates/pxe/src/extractors/machine.rs`:
- Around line 47-51: Update the tracing::error! call in the machine extractor to
format both the error and internal_api_url fields with Display (`%`) instead of
Debug (`?`), matching the other error logs in the diff. Keep the existing field
names and message unchanged.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Path: .coderabbit.yaml
Review profile: CHILL
Plan: Enterprise
Run ID: ef4f70de-88b5-4ed1-b47f-08308e298796
⛔ Files ignored due to path filters (1)
Cargo.lockis excluded by!**/*.lock
📒 Files selected for processing (8)
crates/pxe/Cargo.tomlcrates/pxe/src/extractors/machine.rscrates/pxe/src/main.rscrates/pxe/src/middleware/logging.rscrates/pxe/src/routes/cloud_init.rscrates/pxe/src/routes/ipxe.rscrates/pxe/src/routes/metrics.rscrates/pxe/src/routes/tls.rs
| let env_filter = EnvFilter::builder() | ||
| .with_default_directive(LevelFilter::INFO.into()) | ||
| .from_env_lossy() | ||
| .add_directive("hyper=warn".parse()?) | ||
| .add_directive("h2=warn".parse()?) | ||
| .add_directive("tower=warn".parse()?) | ||
| .add_directive("rustls=warn".parse()?) | ||
| .add_directive("tokio_util::codec=warn".parse()?); |
There was a problem hiding this comment.
🎯 Functional Correctness | 🟡 Minor | ⚡ Quick win
🧩 Analysis chain
🏁 Script executed:
#!/bin/bash
set -euo pipefail
echo "== File context =="
git ls-files crates/pxe/src/main.rs
cat -n crates/pxe/src/main.rs | sed -n '145,185p'
echo
echo "== Search for EnvFilter usage in repo =="
rg -n "EnvFilter::builder|from_env_lossy|try_from_default_env|add_directive\\(" crates -S
echo
echo "== tracing-subscriber version / dependency context =="
rg -n 'tracing-subscriber|tracing_subscriber' Cargo.toml crates/**/Cargo.toml -S
echo
echo "== If available, show local docs/comments mentioning override behavior =="
rg -n "overrid|directive|RUST_LOG|from_env_lossy|try_from_default_env" -S .Repository: NVIDIA/infra-controller
Length of output: 50381
🌐 Web query:
tracing-subscriber EnvFilter add_directive ordering overrides same target from_env_lossy docs
💡 Result:
In tracing-subscriber, the EnvFilter handles directive ordering and overrides based on directive specificity rather than the order in which they are added [1][2]. When you use add_directive, the new directive is added to the set of existing directives [3][1]. If you add a directive that matches exactly the same spans and events as a previous one but specifies a different level, the new directive overwrites the previous one [1][4]. Internally, EnvFilter maintains directives in a collection ordered by their specificity (e.g., target length and number of field filters) [2]. When filtering a span or event, the system searches this set starting from the most specific directive [2]. This ensures that specific overrides (such as a directive for a particular module) take precedence over more general ones (such as a global level), regardless of the order in which they were added to the filter instance [2]. Regarding from_env_lossy and related builder methods: - The builder's from_env_lossy method (and similar methods like from_env) is designed to load directives from an environment variable [5][6]. - If the environment variable is empty, these methods fall back to a default directive (if one has been configured via with_default_directive) [5][6]. - If the environment variable contains valid directives, those directives are used, and the default directive is ignored [6]. - The lossy variants specifically ignore any invalid directives found within the environment variable string [5][6]. If you need to ensure certain directives are applied as "defaults" that can be overridden by environment variables, you should configure a default directive using the Builder and then use from_env_lossy [6][7]. If you add directives manually using add_directive, they will be treated as part of the primary directive set and will participate in the specificity-based matching and overwriting behavior described above [1][2].
Citations:
- 1: https://docs.rs/tracing-subscriber/latest/src/tracing_subscriber/filter/env/mod.rs.html
- 2: https://paritytech.github.io/try-runtime-cli/src/tracing_subscriber/filter/directive.rs.html
- 3: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html
- 4: https://docs.rs/tracing-subscriber/0.3.6/tracing_subscriber/filter/struct.EnvFilter.html
- 5: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.Builder.html
- 6: https://docs.rs/tracing-subscriber/latest/src/tracing_subscriber/filter/env/builder.rs.html
- 7: https://docs.rs/tracing-subscriber/0.3.20/tracing_subscriber/filter/struct.EnvFilter.html
Let RUST_LOG take precedence over the hardcoded caps. The add_directive("hyper=warn")-style caps can overwrite same-target directives loaded by from_env_lossy(), so RUST_LOG=hyper=debug still gets forced back to warn. That makes the “overridable via RUST_LOG” behavior misleading; apply the caps only when the env filter is absent, or merge them in a way that preserves env overrides.
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@crates/pxe/src/main.rs` around lines 163 - 170, Update the EnvFilter
construction near the `env_filter` binding so directives from `RUST_LOG` take
precedence over the hardcoded `hyper`, `h2`, `tower`, `rustls`, and
`tokio_util::codec` caps. Apply those default caps only when the environment
filter is absent, or merge them without overriding same-target directives loaded
by `from_env_lossy()`.
There was a problem hiding this comment.
🧹 Nitpick comments (1)
crates/pxe/src/routes/cloud_init.rs (1)
65-79: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winExpose
interface/domain/machineas discrete structured fields instead of pre-formatting them into theerrorstring.Callers currently build the
errorargument viaformat!("...: {interface:?}")-style interpolation (lines 251-259, 282-285) before it ever reacheslog_and_generate_generic_error(lines 65-69). The resulting logfmt line still carries the context only as embedded Debug text inside oneerror=field, so it isn't independently greppable/filterable byinterface=,domain=, ormachine=the way the PR's structured-tracing goal intends.Consider logging the structured context at each call site and reducing the helper to just the reason/metric:
♻️ Proposed refactor
-fn log_and_generate_generic_error( - error: String, - reason: OutcomeReason, -) -> (String, HashMap<String, String>) { - tracing::error!(error = %error, "cloud-init request could not be served"); +fn log_and_generate_generic_error(reason: OutcomeReason) -> (String, HashMap<String, String>) { emit(PxeBootOutcome { endpoint: BootEndpoint::CloudInit, reason, }); let mut template_data: HashMap<String, String> = HashMap::new(); template_data.insert( "error".to_string(), "An error occurred while rendering the request".to_string(), ); ("error".to_string(), template_data) // Send a generic error back }- None => log_and_generate_generic_error( - format!("The interface ID should not be null: {interface:?}"), - OutcomeReason::InterfaceNotFound, - ), + None => { + tracing::error!(interface = ?interface, "interface ID should not be null"); + log_and_generate_generic_error(OutcomeReason::InterfaceNotFound) + }- (interface, domain) => log_and_generate_generic_error( - format!("The interface and domain were not found: {interface:?}, {domain:?}"), - OutcomeReason::InterfaceNotFound, - ), + (interface, domain) => { + tracing::error!(interface = ?interface, domain = ?domain, "interface and domain were not found"); + log_and_generate_generic_error(OutcomeReason::InterfaceNotFound) + }- None => log_and_generate_generic_error( - format!("No metadata was found for machine {machine:?}"), - OutcomeReason::MetadataNotFound, - ), + None => { + tracing::error!(machine = ?machine, "no metadata was found for machine"); + log_and_generate_generic_error(OutcomeReason::MetadataNotFound) + }Based on coding guidelines, "common searchable values should be passed as structured tracing fields rather than interpolated into log strings."
Also applies to: 251-259, 282-285
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@crates/pxe/src/routes/cloud_init.rs` around lines 65 - 79, Update log_and_generate_generic_error and its callers so interface, domain, and machine are emitted as separate structured tracing fields rather than interpolated into the error string. Add the appropriate context fields at the call sites around the cloud-init error handling, and keep the helper focused on logging the generic error/reason and emitting the existing outcome and response.Source: Coding guidelines
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Nitpick comments:
In `@crates/pxe/src/routes/cloud_init.rs`:
- Around line 65-79: Update log_and_generate_generic_error and its callers so
interface, domain, and machine are emitted as separate structured tracing fields
rather than interpolated into the error string. Add the appropriate context
fields at the call sites around the cloud-init error handling, and keep the
helper focused on logging the generic error/reason and emitting the existing
outcome and response.
ℹ️ Review info
⚙️ Run configuration
Configuration used: Path: .coderabbit.yaml
Review profile: CHILL
Plan: Enterprise
Run ID: 5890d30f-286f-4302-8cff-a69895351040
⛔ Files ignored due to path filters (1)
Cargo.lockis excluded by!**/*.lock
📒 Files selected for processing (8)
crates/pxe/Cargo.tomlcrates/pxe/src/extractors/machine.rscrates/pxe/src/main.rscrates/pxe/src/middleware/logging.rscrates/pxe/src/routes/cloud_init.rscrates/pxe/src/routes/ipxe.rscrates/pxe/src/routes/metrics.rscrates/pxe/src/routes/tls.rs
🔍 Container Scan Summary
Per-CVE detail lives in the per-service |
2 participants
PXE was the last binary logging through raw
println!/eprintln!-- its lines had no level, no component, no span_id, and bypassed every filter. It now installs the same instrumentation subscriber as the rest of the fleet, tagged with thenico-pxecomponent, so its output is filterable and greppable like everything else and its warning/error rate feeds the fleet-widecarbide_log_events_totalsignal (pxe was the one binary missing from it).setup_tracing()installs the fleet-standard subscriber at startup -- thelogfmtlayer, theLogEventsMetriccounting layer, and anEnvFilterat INFO (RUST_LOG-overridable, with the usual per-dependency caps). The log-events counter is an already-documented metric joining pxe's own/metrics, socore_metrics.mdis untouched.tracingcalls at the right level: sevenerror!(with the error and any URL as fields), threeinfo!, and the request logger's hand-rolled logfmt renderer becomes a realinfo_span!("request", ...)-- now carrying a per-requestspan_id(matching api-core's request middleware) so the request line and its child events share a correlation key.println!is--version, machine-readable stdout by design.This supports #3180