From fa6c6885ffac1cd893024d50b379900463a613d7 Mon Sep 17 00:00:00 2001 From: leynos Date: Sat, 13 Jun 2026 16:44:00 +0200 Subject: [PATCH] Add phase labels and structured fields to config-load observability (#304) Extend the config-load instrumentation from #303 so operators can attribute failures and latency to a specific startup phase and a coarse error cause. Metrics: `record_config_load_phase` now records the `diag_mode` and `merge` phases separately, adding a `phase` label to both `netsuke_config_load_total` (alongside `outcome`) and `netsuke_config_load_duration_seconds`. Diagnostic-mode resolution is infallible at the call boundary, so its phase is always `outcome=success`. Structured log fields: `handle_config_load_error` now annotates the `configuration load failed` event with `operation = "config_merge"` and an `error_category` derived from the `OrthoError` variant (`parse`/`io`/`validation`/`aggregate`/`other`). Document the per-phase labels, the structured-log-field contract, and the `error_category` mapping in `docs/developers-guide.md`. Add unit tests for the phase/outcome labels and the error classification. --- docs/developers-guide.md | 51 ++++++++++++----- src/main.rs | 121 ++++++++++++++++++++++++++++++--------- 2 files changed, 133 insertions(+), 39 deletions(-) diff --git a/docs/developers-guide.md b/docs/developers-guide.md index 067891f7..5f5a9fb2 100644 --- a/docs/developers-guide.md +++ b/docs/developers-guide.md @@ -640,23 +640,48 @@ installs a recorder (for example a Prometheus or OpenTelemetry exporter) at process start. Netsuke does not bundle a recorder; it only emits the measurements. -Instruments emitted by `record_config_load_metrics`: - -- `netsuke_config_load_total` — a counter incremented once per startup - configuration-load attempt. It carries a single label `outcome` with values - `success` or `failure`, where `failure` corresponds to a `merge_with_config` - error. Use it to compute the configuration-load failure rate. +Instruments emitted by `record_config_load_phase` (called once per phase): + +- `netsuke_config_load_total` — a counter incremented once per + configuration-load phase. It carries two labels: `phase` + (`diag_mode` for diagnostic-mode resolution, `merge` for the layer merge) + and `outcome` (`success` or `failure`). Diagnostic-mode resolution has an + internal fallback and cannot fail at this boundary, so `phase="diag_mode"` + is always `outcome="success"`; a `merge` failure corresponds to a + `merge_with_config` error. Use the `merge`/`failure` series to compute the + configuration-load failure rate. - `netsuke_config_load_duration_seconds` — a histogram recording the - wall-clock duration of the configuration-load phase in seconds (one sample - per startup). Suggested operator bucket boundaries: `0.001, 0.005, 0.01, - 0.05, 0.1, 0.5, 1.0` seconds; configuration loading is expected to complete - in single-digit milliseconds, so buckets above one second exist only to - catch pathological filesystem or environment stalls. + wall-clock duration of each configuration-load phase in seconds (one sample + per phase per startup), labelled by `phase`. Suggested operator bucket + boundaries: `0.001, 0.005, 0.01, 0.05, 0.1, 0.5, 1.0` seconds; + configuration loading is expected to complete in single-digit milliseconds, + so buckets above one second exist only to catch pathological filesystem or + environment stalls. Naming convention: metric names use the `netsuke_` prefix and a `snake_case` unit suffix (`_total` for counters, `_seconds` for duration histograms), -matching Prometheus conventions. Label values are bounded constant strings -(`success`/`failure`) to keep cardinality fixed. +matching Prometheus conventions. Label values are bounded constant strings to +keep cardinality fixed. + +#### Structured log fields + +When a configuration load fails in human-output mode, `handle_config_load_error` +in `src/main.rs` emits a `tracing::error!` event with the message +`configuration load failed` and these structured fields: + +- `operation` — the failing startup phase. Any error reaching this handler + comes from the layer merge, so the value is `config_merge`. (Diagnostic-mode + resolution cannot fail at the call boundary; the field exists so a future + fallible diagnostic-resolution path can record `diag_mode_resolution`.) +- `error_category` — a coarse classification of the underlying + `ortho_config::OrthoError`, mapped by `error_category`: `parse` + (`CliParsing`, `Gathering`), `io` (`File`), `validation` (`CyclicExtends`, + `Merge`, `Validation`), `aggregate` (`Aggregate`), or `other`. +- `error` — the `Display` rendering of the error. + +In diagnostic-JSON mode (`--diag-json` / `--output-format json`) the failure is +rendered as a JSON diagnostic instead, keeping stderr machine-readable; the +structured fields above apply to the human-output path only. ## BDD command helpers and environment handling diff --git a/src/main.rs b/src/main.rs index fcea27de..ae338f22 100644 --- a/src/main.rs +++ b/src/main.rs @@ -19,16 +19,23 @@ use std::time::{Duration, Instant}; use tracing::Level; use tracing_subscriber::fmt; -/// Counter recording the outcome of each configuration-load attempt. +/// Counter recording the outcome of each configuration-load phase. /// -/// Labelled by `outcome` (`success` or `failure`) so operators can track the -/// startup configuration-load failure rate. +/// Labelled by `phase` (`diag_mode` or `merge`) and `outcome` (`success` or +/// `failure`) so operators can track the startup configuration-load failure +/// rate per phase. const CONFIG_LOAD_TOTAL: &str = "netsuke_config_load_total"; -/// Histogram recording the wall-clock duration of the configuration-load -/// phase (diagnostic-mode resolution through layer merge) in seconds. +/// Histogram recording the wall-clock duration of each configuration-load +/// phase in seconds, labelled by `phase` (`diag_mode` or `merge`). const CONFIG_LOAD_DURATION_SECONDS: &str = "netsuke_config_load_duration_seconds"; +/// The `diag_mode` configuration-load phase: diagnostic-mode resolution. +const PHASE_DIAG_MODE: &str = "diag_mode"; + +/// The `merge` configuration-load phase: full layer merge. +const PHASE_MERGE: &str = "merge"; + #[derive(Debug, Clone, Copy, PartialEq, Eq)] enum DiagMode { Human, @@ -136,30 +143,62 @@ fn resolve_configuration( parsed_cli: &cli::Cli, matches: &ArgMatches, ) -> (DiagMode, Result>) { - let start = Instant::now(); + let diag_start = Instant::now(); let mode = DiagMode::from_json_enabled(cli::resolve_merged_diag_json(parsed_cli, matches)); + // Diagnostic-mode resolution has an internal fallback and cannot fail at + // this boundary, so its phase outcome is always `success`. + record_config_load_phase(PHASE_DIAG_MODE, diag_start.elapsed(), true); + + let merge_start = Instant::now(); let merged = cli::merge_with_config(parsed_cli, matches); - record_config_load_metrics(start.elapsed(), merged.is_ok()); + record_config_load_phase(PHASE_MERGE, merge_start.elapsed(), merged.is_ok()); (mode, merged) } -/// Emit the configuration-load metrics for one startup attempt. +/// Emit the configuration-load metrics for one phase of one startup attempt. /// /// Recording goes through the `metrics` façade, so it is a no-op unless the /// operator has installed a recorder. -fn record_config_load_metrics(elapsed: Duration, succeeded: bool) { +fn record_config_load_phase(phase: &'static str, elapsed: Duration, succeeded: bool) { let outcome = if succeeded { "success" } else { "failure" }; - metrics::histogram!(CONFIG_LOAD_DURATION_SECONDS).record(elapsed.as_secs_f64()); - metrics::counter!(CONFIG_LOAD_TOTAL, "outcome" => outcome).increment(1); + metrics::histogram!(CONFIG_LOAD_DURATION_SECONDS, "phase" => phase) + .record(elapsed.as_secs_f64()); + metrics::counter!(CONFIG_LOAD_TOTAL, "phase" => phase, "outcome" => outcome).increment(1); +} + +/// Coarse classification of a configuration-load error for log correlation. +/// +/// Groups [`OrthoError`] variants into operational categories so operators can +/// filter failures by cause without depending on the full error text. +const fn error_category(err: &OrthoError) -> &'static str { + match err { + OrthoError::CliParsing(_) | OrthoError::Gathering(_) => "parse", + OrthoError::File { .. } => "io", + OrthoError::CyclicExtends { .. } + | OrthoError::Merge { .. } + | OrthoError::Validation { .. } => "validation", + OrthoError::Aggregate(_) => "aggregate", + _ => "other", + } } /// Render a configuration-load failure to the user and map it to an exit code. +/// +/// Any error reaching this point comes from the `config_merge` phase +/// (diagnostic-mode resolution cannot fail at the call boundary), so the +/// structured log records `operation = "config_merge"` alongside a coarse +/// `error_category`. fn handle_config_load_error(err: &Arc, mode: DiagMode) -> ExitCode { if mode.is_json() { diagnostic_json::emit_or_fallback(diagnostic_json::render_error_json(err.as_ref())) } else { init_tracing(Level::ERROR); - tracing::error!(error = %err, "configuration load failed"); + tracing::error!( + error = %err, + operation = "config_merge", + error_category = error_category(err), + "configuration load failed" + ); ExitCode::FAILURE } } @@ -247,10 +286,16 @@ mod tests { .collect() } + fn has_label(labels: &[Label], key: &str, value: &str) -> bool { + labels + .iter() + .any(|label| label.key() == key && label.value() == value) + } + #[test] - fn record_config_load_metrics_counts_failure_outcome() { + fn record_config_load_phase_counts_failure_outcome_with_phase_label() { let metrics = captured_metrics(|| { - record_config_load_metrics(Duration::from_millis(5), false); + record_config_load_phase(PHASE_MERGE, Duration::from_millis(5), false); }); let counter = metrics @@ -258,11 +303,8 @@ mod tests { .find(|(name, _, _)| name == CONFIG_LOAD_TOTAL) .expect("config-load counter should be recorded"); assert!( - counter - .1 - .iter() - .any(|label| label.key() == "outcome" && label.value() == "failure"), - "counter should carry outcome=failure: {:?}", + has_label(&counter.1, "phase", "merge") && has_label(&counter.1, "outcome", "failure"), + "counter should carry phase=merge, outcome=failure: {:?}", counter.1 ); assert_eq!(counter.2, DebugValue::Counter(1)); @@ -271,6 +313,11 @@ mod tests { .iter() .find(|(name, _, _)| name == CONFIG_LOAD_DURATION_SECONDS) .expect("config-load duration histogram should be recorded"); + assert!( + has_label(&histogram.1, "phase", "merge"), + "histogram should carry phase=merge: {:?}", + histogram.1 + ); let DebugValue::Histogram(samples) = &histogram.2 else { panic!("expected a histogram value, got {:?}", histogram.2); }; @@ -278,21 +325,43 @@ mod tests { } #[test] - fn record_config_load_metrics_counts_success_outcome() { + fn record_config_load_phase_counts_success_outcome() { let metrics = captured_metrics(|| { - record_config_load_metrics(Duration::from_millis(1), true); + record_config_load_phase(PHASE_DIAG_MODE, Duration::from_millis(1), true); }); let counter = metrics .iter() .find(|(name, _, _)| name == CONFIG_LOAD_TOTAL) .expect("config-load counter should be recorded"); assert!( - counter - .1 - .iter() - .any(|label| label.key() == "outcome" && label.value() == "success"), - "counter should carry outcome=success: {:?}", + has_label(&counter.1, "phase", "diag_mode") + && has_label(&counter.1, "outcome", "success"), + "counter should carry phase=diag_mode, outcome=success: {:?}", counter.1 ); } + + #[test] + fn error_category_classifies_ortho_error_variants() { + assert_eq!( + error_category(&OrthoError::Validation { + key: "jobs".into(), + message: "out of range".into(), + }), + "validation" + ); + assert_eq!( + error_category(&OrthoError::File { + path: std::path::PathBuf::from("netsuke.toml"), + source: Box::new(std::io::Error::new(std::io::ErrorKind::NotFound, "missing",)), + }), + "io" + ); + assert_eq!( + error_category(&OrthoError::CyclicExtends { + cycle: "a -> b -> a".into(), + }), + "validation" + ); + } }