From 1be02ec8adfab482a92f2cd0ded01e6476c1a72c Mon Sep 17 00:00:00 2001 From: Stan Grams Date: Fri, 13 Mar 2026 11:57:34 +0100 Subject: [PATCH] [debug](trx-server): trace listener and rig task activity Co-authored-by: OpenAI Codex Signed-off-by: Stan Grams --- src/trx-server/src/listener.rs | 50 ++++++++++++++++++++++++++++++++++ src/trx-server/src/rig_task.rs | 18 ++++++++++++ 2 files changed, 68 insertions(+) diff --git a/src/trx-server/src/listener.rs b/src/trx-server/src/listener.rs index 72279ee..ee384e2 100644 --- a/src/trx-server/src/listener.rs +++ b/src/trx-server/src/listener.rs @@ -35,6 +35,7 @@ use crate::rig_handle::RigHandle; const IO_TIMEOUT: Duration = Duration::from_secs(10); const REQUEST_TIMEOUT: Duration = Duration::from_secs(12); const MAX_JSON_LINE_BYTES: usize = 16 * 1024; +const LISTENER_HEARTBEAT_INTERVAL: Duration = Duration::from_secs(30); /// Run the JSON TCP listener, accepting client connections. /// @@ -50,6 +51,7 @@ pub async fn run_listener( ) -> std::io::Result<()> { let listener = TcpListener::bind(addr).await?; info!("Listening on {}", addr); + let mut heartbeat = time::interval(LISTENER_HEARTBEAT_INTERVAL); let validator = Arc::new(SimpleTokenValidator::new(auth_tokens)); @@ -69,6 +71,14 @@ pub async fn run_listener( } }); } + _ = heartbeat.tick() => { + info!( + "Listener heartbeat: addr={}, rigs={}, default_rig_id={}", + addr, + rigs.len(), + default_rig_id + ); + } changed = shutdown_rx.changed() => { match changed { Ok(()) if *shutdown_rx.borrow() => { @@ -278,6 +288,17 @@ async fn handle_client( }; let rig_cmd = mapping::client_command_to_rig(envelope.cmd); + let rig_cmd_label = format!("{:?}", rig_cmd); + let log_request = !matches!(rig_cmd, RigCommand::GetSpectrum | RigCommand::GetSnapshot); + let request_started = time::Instant::now(); + if log_request { + info!( + "Client {} request start: rig_id='{}' cmd={}", + addr, + target_rig_id, + rig_cmd_label + ); + } // Fast path: serve GetSnapshot directly from the watch channel // so clients get a response even while the rig task is initializing. @@ -362,6 +383,15 @@ async fn handle_client( } } { Ok(Ok(snapshot)) => { + if log_request { + info!( + "Client {} request ok: rig_id='{}' cmd={} elapsed={:?}", + addr, + target_rig_id, + rig_cmd_label, + request_started.elapsed() + ); + } let resp = ClientResponse { success: true, rig_id: Some(target_rig_id.clone()), @@ -372,6 +402,16 @@ async fn handle_client( send_response(&mut writer, &resp).await?; } Ok(Err(err)) => { + if log_request { + warn!( + "Client {} request rig error: rig_id='{}' cmd={} elapsed={:?}: {}", + addr, + target_rig_id, + rig_cmd_label, + request_started.elapsed(), + err.message + ); + } let resp = ClientResponse { success: false, rig_id: Some(target_rig_id.clone()), @@ -382,6 +422,16 @@ async fn handle_client( send_response(&mut writer, &resp).await?; } Err(e) => { + if log_request { + error!( + "Client {} request response channel error: rig_id='{}' cmd={} elapsed={:?}: {:?}", + addr, + target_rig_id, + rig_cmd_label, + request_started.elapsed(), + e + ); + } error!("Rig response oneshot recv error: {:?}", e); let resp = ClientResponse { success: false, diff --git a/src/trx-server/src/rig_task.rs b/src/trx-server/src/rig_task.rs index 0c959a8..fe76ecd 100644 --- a/src/trx-server/src/rig_task.rs +++ b/src/trx-server/src/rig_task.rs @@ -29,6 +29,7 @@ use crate::error::is_invalid_bcd_error; const POLL_REFRESH_TIMEOUT: Duration = Duration::from_secs(8); const COMMAND_EXEC_TIMEOUT: Duration = Duration::from_secs(10); +const RIG_TASK_HEARTBEAT_INTERVAL: Duration = Duration::from_secs(30); /// Configuration for the rig task. pub struct RigTaskConfig { @@ -237,6 +238,7 @@ pub async fn run_rig_task( let mut current_poll_duration = polling.interval(state.status.tx_en); let mut poll_sleep: std::pin::Pin> = Box::pin(tokio::time::sleep(current_poll_duration)); + let mut heartbeat = time::interval(RIG_TASK_HEARTBEAT_INTERVAL); loop { // Update sleep duration if tx_en state changed let new_duration = polling.interval(state.status.tx_en); @@ -311,6 +313,19 @@ pub async fn run_rig_task( } } }, + _ = heartbeat.tick() => { + info!( + "[{}] rig_task heartbeat: initialized={}, freq_hz={}, mode={:?}, tx_en={}, poll_paused={}", + config.rig_id, + state.initialized, + state.status.freq.hz, + state.status.mode, + state.status.tx_en, + poll_pause_until + .map(|until| Instant::now() < until) + .unwrap_or(false) + ); + } maybe_req = rx.recv() => { let Some(first_req) = maybe_req else { break; }; @@ -374,6 +389,9 @@ pub async fn run_rig_task( let cmd_label = format!("{:?}", cmd); let log_command = !matches!(&cmd, RigCommand::GetSpectrum); let started = Instant::now(); + if log_command { + info!("[{}] rig command start: {}", config.rig_id, cmd_label); + } let mut cmd_ctx = CommandExecContext { rig: &mut rig,