diff --git a/Cargo.lock b/Cargo.lock index c01aff5f..bdc42108 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1695,6 +1695,7 @@ dependencies = [ "tower", "tower-http 0.7.0", "tracing", + "tracing-subscriber", ] [[package]] diff --git a/docs/swarm/README.md b/docs/swarm/README.md index 2ca6acb2..60c72a18 100644 --- a/docs/swarm/README.md +++ b/docs/swarm/README.md @@ -53,7 +53,10 @@ grafana, the controller, authelia, …) → the agent roster and their wanted state, and the job graph. Creating an agent — from the swarm UI or `swarmctl agent create --hive ` — queues its SSO identity, forge user, config repo, store identity and matrix account, then -sends the hive a deploy message. A new agent starts `paused`. +sends the hive a deploy message. A new agent starts `paused`. A store identity +that fails to mint logs `swarm jobq: mint_agent_identity failed` with the agent +and the error, which the Grafana alert rule `hh-agent-identity-mint-failed` +fires on. The agent is still created, without a store identity. `services.hyperhive.deploy.swarm-controller.enable` runs it on this host; `singleHostSwarm` turns it on. **Otherwise off: set it on the one host that @@ -184,7 +187,9 @@ show the agent nor send it anything, so a harness without one stops: certificate) exits at boot with an error naming what's missing. - A harness whose first connect fails tries again after 5 seconds, doubling the wait each time, and logs a warning for each attempt that fails. After the - seventh, about five minutes in, it logs an error and exits. + seventh, about five minutes in, it logs an error and exits. The error reads + `no swarm queue connection; exiting, since this agent cannot run without one`, + and the Grafana alert rule `hh-swarm-queue-connect-failed` fires on it. Either way the harness exits and comes back until the queue accepts it. Once connected, the client reconnects by itself after a dropped connection, reading diff --git a/hive-agent/Cargo.toml b/hive-agent/Cargo.toml index e6680cf2..725630c3 100644 --- a/hive-agent/Cargo.toml +++ b/hive-agent/Cargo.toml @@ -59,6 +59,8 @@ tracing.workspace = true tempfile = "3" tokio = { workspace = true, features = ["test-util"] } tower = { version = "0.5", features = ["util"] } +# A layer that captures `swarm_queue`'s exhausted-connect log event in a test. +tracing-subscriber.workspace = true # Single harness serve-loop binary: `hive-agent` (from `src/main.rs`). # The sibling MCP server is its own bin crate now (`hive-agent-mcp`). diff --git a/hive-agent/src/swarm_queue.rs b/hive-agent/src/swarm_queue.rs index dffff2a4..c6ea3959 100644 --- a/hive-agent/src/swarm_queue.rs +++ b/hive-agent/src/swarm_queue.rs @@ -45,6 +45,13 @@ const CONNECT_BACKOFF: [Duration; 6] = [ Duration::from_secs(160), ]; +/// Logged at `error` once every first-connect attempt has failed, just before +/// the process exits. The Grafana rule `hh-swarm-queue-connect-failed` +/// (`nix/host-modules/swarm-grafana.nix`) matches this exact text: change both +/// together. +const CONNECT_EXHAUSTED: &str = + "no swarm queue connection; exiting, since this agent cannot run without one"; + /// Where to connect, resolved once at boot by [`init`]. static AGENT: OnceLock = OnceLock::new(); @@ -300,14 +307,15 @@ async fn connect_or_exit() -> async_nats::Client { None => Err(anyhow!("swarm_queue::init has not run")), }; connected.unwrap_or_else(|e| { - tracing::error!( - error = format!("{e:#}"), - "no swarm queue connection; exiting, since this agent cannot run without one" - ); + log_connect_exhausted(&e); std::process::exit(1) }) } +fn log_connect_exhausted(e: &anyhow::Error) { + tracing::error!(error = format!("{e:#}"), "{CONNECT_EXHAUSTED}"); +} + /// One connection attempt with this agent's own credential. async fn connect_once(agent: &AgentPath) -> anyhow::Result { let secret = AgentSecret::new(Arc::clone(&agent.store)); @@ -390,10 +398,11 @@ mod tests { use std::time::Duration; use anyhow::anyhow; + use tracing_subscriber::layer::SubscriberExt as _; use super::{ AgentPath, AgentSecret, CONNECT_BACKOFF, SecretSource, StoreSource, agent_path, - connect_as_agent, retry_first_connect, store_source, + connect_as_agent, log_connect_exhausted, retry_first_connect, store_source, }; /// A lookup standing in for a container that was handed a store and the @@ -546,6 +555,50 @@ mod tests { ); } + /// The level and message of every event. + #[derive(Clone, Default)] + struct Messages(Arc>>); + + impl tracing_subscriber::Layer for Messages { + fn on_event( + &self, + event: &tracing::Event<'_>, + _: tracing_subscriber::layer::Context<'_, S>, + ) { + let mut message = String::new(); + event.record( + &mut |field: &tracing::field::Field, value: &dyn std::fmt::Debug| { + if field.name() == "message" { + message = format!("{value:?}"); + } + }, + ); + self.0 + .lock() + .expect("unpoisoned") + .push((*event.metadata().level(), message)); + } + } + + /// The literal is the `_msg` that `hh-swarm-queue-connect-failed` in + /// `nix/host-modules/swarm-grafana.nix` matches. + #[test] + fn an_exhausted_connect_logs_the_line_the_alert_rule_matches() { + let messages = Messages::default(); + let subscriber = tracing_subscriber::registry().with(messages.clone()); + tracing::subscriber::with_default(subscriber, || { + log_connect_exhausted(&anyhow!("7 connection attempts failed")); + }); + assert_eq!( + *messages.0.lock().expect("unpoisoned"), + [( + tracing::Level::ERROR, + "no swarm queue connection; exiting, since this agent cannot run without one" + .to_owned() + )] + ); + } + enum Answer { Value(&'static str), Absent, diff --git a/nix/host-modules/swarm-grafana.nix b/nix/host-modules/swarm-grafana.nix index fee35331..5de9d826 100644 --- a/nix/host-modules/swarm-grafana.nix +++ b/nix/host-modules/swarm-grafana.nix @@ -1497,17 +1497,19 @@ in for = "5m"; summary = "{{ $labels.hive }}/{{ $labels.agent }} is dropping swarm terminal rows: the harness is not connected to the queue"; }) - # Logged once per agent process: the connection is made - # once and never retried, so the agent stays unconnected - # until it restarts. The window is how long the rule - # stays firing after that one line. + # `CONNECT_EXHAUSTED` in hive-agent's swarm_queue.rs, + # logged when the harness's first-connect retries + # (about five minutes) all fail, just before it exits. + # systemd restarts it 30s later, so an agent that never + # connects logs it about every six minutes. The window + # is how long the rule stays firing after the last one. (logCountRule { uid = "hh-swarm-queue-connect-failed"; title = "swarm queue connect failed"; windowSeconds = 3600; - expr = ''_time:1h _msg:"swarm queue connect failed; this agent publishes nothing upward" | stats by (hive, agent) count() as failures''; + expr = ''_time:1h _msg:"no swarm queue connection; exiting, since this agent cannot run without one" | stats by (hive, agent) count() as failures''; for = "0s"; - summary = "{{ $labels.hive }}/{{ $labels.agent }} could not connect to the swarm queue and publishes nothing upward until it restarts"; + summary = "{{ $labels.hive }}/{{ $labels.agent }} could not connect to the swarm queue and its harness exited; systemd starts it again 30s later"; }) (logCountRule { uid = "hh-swarm-agent-state-publish-skipped"; @@ -1553,6 +1555,19 @@ in for = "15m"; summary = "swarm-controller has failed the agent credential renewal pass on consecutive ticks"; }) + # `MINT_IDENTITY_FAILED` in swarm-controller's main.rs, + # logged once per failed `MintAgentIdentity` job node, at + # agent creation or on a certificate renewal; the window + # is how long the rule stays firing after it. Host + # journal records carry the tracing fields as `F_`. + (logCountRule { + uid = "hh-agent-identity-mint-failed"; + title = "agent identity mint failed"; + windowSeconds = 900; + expr = ''_time:15m _SYSTEMD_UNIT:="swarm-controller.service" _msg:"swarm jobq: mint_agent_identity failed" | stats by (F_AGENT) count() as failures''; + for = "0s"; + summary = "swarm-controller failed to mint agent {{ $labels.F_AGENT }}'s store identity; the reason is the `F_ERROR` field of the swarm-controller log line"; + }) # Logged once per refused deploy request, by # `apply_rev` in hive-c0re's swarm_status.rs; the window is # how long the rule stays firing after it. Host journal diff --git a/swarm-controller/src/main.rs b/swarm-controller/src/main.rs index 24bac328..400fbc41 100644 --- a/swarm-controller/src/main.rs +++ b/swarm-controller/src/main.rs @@ -460,6 +460,12 @@ async fn forge_node( }) } +/// Logged at `warn`, with the agent and the error, when [`mint_identity`] +/// fails. The Grafana rule `hh-agent-identity-mint-failed` +/// (`nix/host-modules/swarm-grafana.nix`) matches this exact text: change both +/// together. +const MINT_IDENTITY_FAILED: &str = "swarm jobq: mint_agent_identity failed"; + /// The `MintAgentIdentity` arm, lifted out so `run_swarm_node` stays under /// `clippy::too_many_lines`. async fn mint_identity(agent: &str) -> hive_jobq::scheduler::Outcome { @@ -467,7 +473,11 @@ async fn mint_identity(agent: &str) -> hive_jobq::scheduler::Outcome { match agent_identity::mint_and_verify(agent).await { Ok(()) => Outcome::Done, - Err(e) => Outcome::Failed(format!("{e:#}")), + Err(e) => { + let error = format!("{e:#}"); + tracing::warn!(%agent, %error, "{MINT_IDENTITY_FAILED}"); + Outcome::Failed(error) + } } } @@ -6364,3 +6374,69 @@ mod create_agent_warning_tests { assert_eq!(json, r#"{"node_id":7,"warnings":["name is reserved"]}"#); } } + +#[cfg(test)] +mod mint_identity_tests { + use std::sync::{Arc, Mutex}; + + use hive_jobq::scheduler::Outcome; + use tracing_subscriber::layer::SubscriberExt as _; + + use super::mint_identity; + + /// One event's level and its fields, each by name. + type Event = (tracing::Level, Vec<(String, String)>); + + /// Every event. + #[derive(Clone, Default)] + struct Events(Arc>>); + + impl tracing_subscriber::Layer for Events { + fn on_event( + &self, + event: &tracing::Event<'_>, + _: tracing_subscriber::layer::Context<'_, S>, + ) { + let mut fields = Vec::new(); + event.record( + &mut |field: &tracing::field::Field, value: &dyn std::fmt::Debug| { + fields.push((field.name().to_owned(), format!("{value:?}"))); + }, + ); + self.0 + .lock() + .expect("unpoisoned") + .push((*event.metadata().level(), fields)); + } + } + + /// An agent name the store would refuse fails the mint before any store + /// call, whatever this process's environment holds. The literal is the + /// `_msg` that `hh-agent-identity-mint-failed` in + /// `nix/host-modules/swarm-grafana.nix` matches. + #[tokio::test] + async fn a_failed_mint_logs_the_agent_and_the_error_on_the_line_the_alert_rule_matches() { + let events = Events::default(); + let _guard = + tracing::subscriber::set_default(tracing_subscriber::registry().with(events.clone())); + + let Outcome::Failed(error) = mint_identity("a/b").await else { + panic!("an illegal agent name cannot be minted"); + }; + + let got = events.0.lock().expect("unpoisoned").clone(); + let [(level, fields)] = got.as_slice() else { + panic!("one event, got {got:?}"); + }; + assert_eq!(*level, tracing::Level::WARN); + let field = |name: &str| { + fields + .iter() + .find(|(n, _)| n == name) + .map_or_else(|| panic!("no {name} in {fields:?}"), |(_, v)| v.clone()) + }; + assert_eq!(field("message"), "swarm jobq: mint_agent_identity failed"); + assert_eq!(field("agent"), "a/b"); + assert_eq!(field("error"), error); + } +}