logging and config sweep

wakey-agent/src/dispatch.rs

@@ -1,5 +1,5 @@
 use anyhow::Result;
-use tracing::{debug, instrument};
+use tracing::{debug, info, instrument};
 
 use crate::protocol::{
     AgentCommand, CommandResult, DevsRequest, InventoryRequest, LeasesRequest, StatusRequest,
@@ -8,6 +8,8 @@ use crate::protocol::{
 
 #[instrument(skip_all)]
 pub async fn dispatch_command(command: AgentCommand) -> Result<CommandResult> {
+    let kind = command_kind(&command);
+    info!(command = %kind, "dispatching command into local wakey services");
     match command {
         AgentCommand::Status(req) => dispatch_status(req).await,
         AgentCommand::Leases(req) => dispatch_leases(req).await,
@@ -38,6 +40,7 @@ async fn dispatch_leases(req: LeasesRequest) -> Result<CommandResult> {
         include_state: req.include_state,
     })
     .await?;
+    debug!(rows = leases.len(), include_state = req.include_state, "dispatched leases command");
     Ok(CommandResult::Leases(leases))
 }
 
@@ -50,11 +53,13 @@ async fn dispatch_devs(req: DevsRequest) -> Result<CommandResult> {
     if req.up_only {
         devs.retain(|dev| dev.operstate == "up");
     }
+    debug!(rows = devs.len(), up_only = req.up_only, "dispatched devs command");
     Ok(CommandResult::Devs(devs))
 }
 
 async fn dispatch_inventory(req: InventoryRequest) -> Result<CommandResult> {
     let inventory = wakey::inventory(req.into_device_query()).await?;
+    debug!(rows = inventory.devices.len(), "dispatched inventory command");
     Ok(CommandResult::Inventory(inventory))
 }
 
@@ -65,9 +70,20 @@ async fn dispatch_wake(req: WakeRequest) -> Result<CommandResult> {
         (None, Some(mac), ip) => wakey::wake_explicit(mac, ip).await?,
         _ => unreachable!("wake request validated before dispatch"),
     };
+    debug!("dispatched wake command");
     Ok(CommandResult::Wake(result))
 }
 
+fn command_kind(command: &AgentCommand) -> &'static str {
+    match command {
+        AgentCommand::Status(_) => "status",
+        AgentCommand::Leases(_) => "leases",
+        AgentCommand::Devs(_) => "devs",
+        AgentCommand::Inventory(_) => "inventory",
+        AgentCommand::Wake(_) => "wake",
+    }
+}
+
 pub fn validate_wake_request(req: &WakeRequest) -> Result<()> {
     let has_query = req.query.is_some();
     let has_mac = req.mac.is_some();

wakey-agent/src/enroll.rs

@@ -2,7 +2,7 @@ use anyhow::{Context, Result};
 use reqwest::StatusCode;
 use serde::{Deserialize, Serialize};
 use std::path::Path;
-use tracing::info;
+use tracing::{info, warn};
 
 use crate::config::{AgentConfig, save_config};
 
@@ -21,6 +21,7 @@ struct EnrollResponse {
 pub async fn enroll(server_url: &str, enroll_token: &str, config_path: &Path) -> Result<AgentConfig> {
     let server_url = normalize_server_url(server_url);
     let endpoint = format!("{server_url}/api/v1/agents/enroll");
+    info!(endpoint = %endpoint, config_path = %config_path.display(), "starting agent enrollment");
     let client = reqwest::Client::new();
     let response = client
         .post(endpoint)
@@ -35,6 +36,7 @@ pub async fn enroll(server_url: &str, enroll_token: &str, config_path: &Path) ->
             .text()
             .await
             .unwrap_or_else(|_| "<unable to read enrollment error body>".into());
+        warn!(status = %status, "agent enrollment request rejected by control-plane");
         anyhow::bail!("enrollment failed with {status}: {body}");
     }
 
@@ -51,7 +53,7 @@ pub async fn enroll(server_url: &str, enroll_token: &str, config_path: &Path) ->
         reconnect_max_ms: 30_000,
     };
     save_config(config_path, &config)?;
-    info!(config_path = %config_path.display(), "wrote agent config");
+    info!(agent_id = %config.agent_id, config_path = %config_path.display(), "agent enrollment succeeded and config was written");
     Ok(config)
 }
 

wakey-agent/src/main.rs

@@ -17,8 +17,12 @@ async fn main() -> Result<()> {
     tracing::init(cli.verbose);
 
     match cli.command {
-        Command::Serve(args) => serve::serve(args).await?,
+        Command::Serve(args) => {
+            ::tracing::info!("wakey-agent command: serve");
+            serve::serve(args).await?
+        }
         Command::Enroll(args) => {
+            ::tracing::info!(server_url = %args.server_url, config = %args.config.display(), "wakey-agent command: enroll");
             let config = enroll::enroll(&args.server_url, &args.enroll_token, &args.config).await?;
             println!("agent_id={}", config.agent_id);
             println!("config={}", args.config.display());
@@ -29,8 +33,14 @@ async fn main() -> Result<()> {
                 }
             }
         }
-        Command::InitConfig(args) => init_config(args)?,
-        Command::Reload(args) => serve::reload_daemon(&args.pid_file)?,
+        Command::InitConfig(args) => {
+            ::tracing::info!(config = %args.config.display(), force = args.force, "wakey-agent command: init-config");
+            init_config(args)?
+        }
+        Command::Reload(args) => {
+            ::tracing::info!(pid_file = %args.pid_file.display(), "wakey-agent command: reload");
+            serve::reload_daemon(&args.pid_file)?
+        }
     }
 
     Ok(())

wakey-agent/src/serve.rs

@@ -16,6 +16,7 @@ pub async fn serve(args: ServeArgs) -> Result<()> {
     }
 
     write_pid_file(&args.pid_file)?;
+    info!(pid_file = %args.pid_file.display(), "wrote wakey-agent pid file");
 
     let mut cfg = config::load_config(&args.config)?;
     info!(config_path = %args.config.display(), agent_id = %cfg.agent_id, "starting wakey-agent");
@@ -48,6 +49,7 @@ pub async fn serve(args: ServeArgs) -> Result<()> {
                     }
                 }
                 join = &mut worker => {
+                    warn!("agent worker task exited; shutting down daemon");
                     let _ = remove_pid_file(&args.pid_file);
                     return join.context("agent session join failed")?;
                 }
@@ -69,6 +71,7 @@ pub async fn serve(args: ServeArgs) -> Result<()> {
 
 pub fn reload_daemon(pid_file: &Path) -> Result<()> {
     let pid = read_pid(pid_file)?;
+    info!(pid, pid_file = %pid_file.display(), "sending wakey-agent reload signal");
     send_hup(pid)
 }
 

wakey-agent/src/session.rs

@@ -2,11 +2,11 @@ use anyhow::{Context, Result};
 use futures_util::{SinkExt, StreamExt};
 use tokio::time::{Duration, MissedTickBehavior, interval, sleep};
 use tokio_tungstenite::{connect_async, tungstenite::Message};
-use tracing::{debug, error, info, warn};
+use tracing::{debug, error, info, info_span, warn};
 
 use crate::config::AgentConfig;
 use crate::dispatch::dispatch_command;
-use crate::protocol::{ClientMessage, ErrorPayload, ServerMessage};
+use crate::protocol::{AgentCommand, ClientMessage, ErrorPayload, ServerMessage};
 
 pub async fn run(config: AgentConfig) -> Result<()> {
     let mut backoff = config.reconnect_base_ms.max(100);
@@ -25,6 +25,17 @@ pub async fn run(config: AgentConfig) -> Result<()> {
 }
 
 async fn run_once(config: &AgentConfig) -> Result<()> {
+    let session_id = format!(
+        "{}-{}",
+        std::process::id(),
+        std::time::SystemTime::now()
+            .duration_since(std::time::UNIX_EPOCH)
+            .map(|d| d.as_millis())
+            .unwrap_or_default()
+    );
+    let span = info_span!("agent_session", session_id = %session_id, agent_id = %config.agent_id);
+    let _span_guard = span.enter();
+
     let ws_url = websocket_url(&config.server_url)?;
     info!(%ws_url, agent_id = %config.agent_id, "connecting agent websocket");
     let (stream, _) = connect_async(ws_url.as_str())
@@ -44,6 +55,7 @@ async fn run_once(config: &AgentConfig) -> Result<()> {
         },
     )
     .await?;
+    info!(agent_id = %config.agent_id, "agent websocket session authenticated");
 
     let mut heartbeat = interval(Duration::from_secs(30));
     heartbeat.set_missed_tick_behavior(MissedTickBehavior::Skip);
@@ -54,11 +66,15 @@ async fn run_once(config: &AgentConfig) -> Result<()> {
                 send_json(&mut sink, &ClientMessage::Heartbeat {
                     agent_id: config.agent_id.clone(),
                 }).await?;
+                debug!(agent_id = %config.agent_id, "heartbeat sent");
             }
             maybe_msg = source.next() => {
                 let msg = match maybe_msg {
                     Some(msg) => msg.context("websocket frame failed")?,
-                    None => anyhow::bail!("websocket closed by server"),
+                    None => {
+                        info!("websocket stream closed by server");
+                        anyhow::bail!("websocket closed by server");
+                    }
                 };
 
                 match msg {
@@ -79,6 +95,7 @@ async fn run_once(config: &AgentConfig) -> Result<()> {
                     }
                     Message::Pong(_) => {}
                     Message::Close(frame) => {
+                        info!(close = ?frame, "received close frame from server");
                         anyhow::bail!("websocket closed: {:?}", frame);
                     }
                     Message::Binary(_) => {
@@ -105,26 +122,31 @@ where
         ServerMessage::Command {
             request_id,
             command,
-        } => match dispatch_command(command).await {
-            Ok(result) => {
-                send_json(sink, &ClientMessage::Result { request_id, result }).await?;
-            }
-            Err(err) => {
-                error!(request_id = %request_id, error = %err, "command dispatch failed");
-                send_json(
-                    sink,
-                    &ClientMessage::Error {
-                        request_id,
-                        error: ErrorPayload {
-                            code: "command_dispatch_failed".into(),
-                            message: err.to_string(),
-                            retryable: None,
+        } => {
+            let kind = command_kind(&command);
+            info!(request_id = %request_id, command = %kind, "received command from control-plane");
+            match dispatch_command(command).await {
+                Ok(result) => {
+                    info!(request_id = %request_id, command = %kind, "command execution completed");
+                    send_json(sink, &ClientMessage::Result { request_id, result }).await?;
+                }
+                Err(err) => {
+                    error!(request_id = %request_id, command = %kind, error = %err, "command dispatch failed");
+                    send_json(
+                        sink,
+                        &ClientMessage::Error {
+                            request_id,
+                            error: ErrorPayload {
+                                code: "command_dispatch_failed".into(),
+                                message: err.to_string(),
+                                retryable: None,
+                            },
                         },
-                    },
-                )
-                .await?;
+                    )
+                    .await?;
+                }
             }
-        },
+        }
     }
     Ok(())
 }
@@ -135,12 +157,33 @@ where
     <S as futures_util::Sink<Message>>::Error: std::error::Error + Send + Sync + 'static,
 {
     let payload = serde_json::to_string(message).context("failed to serialize websocket message")?;
+    debug!(message_type = %client_message_kind(message), "sending websocket message");
     sink.send(Message::Text(payload))
         .await
         .context("failed to send websocket message")?;
     Ok(())
 }
 
+fn command_kind(command: &AgentCommand) -> &'static str {
+    match command {
+        AgentCommand::Status(_) => "status",
+        AgentCommand::Leases(_) => "leases",
+        AgentCommand::Devs(_) => "devs",
+        AgentCommand::Inventory(_) => "inventory",
+        AgentCommand::Wake(_) => "wake",
+    }
+}
+
+fn client_message_kind(message: &ClientMessage) -> &'static str {
+    match message {
+        ClientMessage::Hello { .. } => "hello",
+        ClientMessage::Auth { .. } => "auth",
+        ClientMessage::Heartbeat { .. } => "heartbeat",
+        ClientMessage::Result { .. } => "result",
+        ClientMessage::Error { .. } => "error",
+    }
+}
+
 pub fn websocket_url(server_url: &str) -> Result<url::Url> {
     let base = url::Url::parse(server_url).context("invalid server_url")?;
     let scheme = match base.scheme() {