From 12f1d81af8c2dc3597fa313ee5c746c5cb1e3d3c Mon Sep 17 00:00:00 2001
From: Stan Grams <sjg@haxx.space>
Date: Fri, 13 Mar 2026 13:19:21 +0100
Subject: [PATCH] [debug](trx-server): trace backend control flow

Co-authored-by: OpenAI Codex <codex@openai.com>
Signed-off-by: Stan Grams <sjg@haxx.space>
---
 src/trx-server/src/rig_task.rs                | 14 +++++++
 .../trx-backend-soapysdr/src/lib.rs           | 37 +++++++++++++++++++
 2 files changed, 51 insertions(+)

diff --git a/src/trx-server/src/rig_task.rs b/src/trx-server/src/rig_task.rs
index fe76ecd..60e9bc5 100644
--- a/src/trx-server/src/rig_task.rs
+++ b/src/trx-server/src/rig_task.rs
@@ -773,6 +773,13 @@ async fn refresh_state_with_retry(
 
 /// Read current state from the rig via CAT.
 async fn refresh_state_from_cat(rig: &mut Box<dyn RigCat>, state: &mut RigState) -> DynResult<()> {
+    let started = std::time::Instant::now();
+    info!(
+        "CAT refresh start: freq_hz={}, mode={:?}, tx_en={}",
+        state.status.freq.hz,
+        state.status.mode,
+        state.status.tx_en
+    );
     let (freq, mode, vfo) = rig.get_status().await?;
     state.filter = rig.filter_state();
     state.control.enabled = Some(true);
@@ -816,6 +823,13 @@ async fn refresh_state_from_cat(rig: &mut Box<dyn RigCat>, state: &mut RigState)
     }
 
     state.status.lock = Some(state.control.lock.unwrap_or(false));
+    info!(
+        "CAT refresh done in {:?}: freq_hz={}, mode={:?}, tx_en={}",
+        started.elapsed(),
+        state.status.freq.hz,
+        state.status.mode,
+        state.status.tx_en
+    );
     Ok(())
 }
 
diff --git a/src/trx-server/trx-backend/trx-backend-soapysdr/src/lib.rs b/src/trx-server/trx-backend/trx-backend-soapysdr/src/lib.rs
index 5bab256..eb4fe07 100644
--- a/src/trx-server/trx-backend/trx-backend-soapysdr/src/lib.rs
+++ b/src/trx-server/trx-backend/trx-backend-soapysdr/src/lib.rs
@@ -10,6 +10,7 @@ pub mod vchan_impl;
 use std::pin::Pin;
 use std::sync::atomic::Ordering;
 use std::sync::{Arc, Mutex};
+use std::time::Instant;
 
 use trx_core::radio::freq::{Band, Freq};
 use trx_core::rig::response::RigError;
@@ -451,6 +452,13 @@ impl RigCat for SoapySdrRig {
         freq: Freq,
     ) -> Pin<Box<dyn std::future::Future<Output = DynResult<()>> + Send + 'a>> {
         Box::pin(async move {
+            let started = Instant::now();
+            tracing::info!(
+                "SoapySdrRig::set_freq start: target={} Hz, current_center={} Hz, mode={:?}",
+                freq.hz,
+                self.center_hz,
+                self.mode
+            );
             tracing::debug!("SoapySdrRig: set_freq -> {} Hz", freq.hz);
             let freq_changed = self.freq.hz != freq.hz;
             self.freq = freq;
@@ -488,6 +496,12 @@ impl RigCat for SoapySdrRig {
                 }
             }
             self.update_ais_channel_offsets();
+            tracing::info!(
+                "SoapySdrRig::set_freq done in {:?}: dial={} Hz, center={} Hz",
+                started.elapsed(),
+                self.freq.hz,
+                self.center_hz
+            );
             Ok(())
         })
     }
@@ -497,6 +511,12 @@ impl RigCat for SoapySdrRig {
         freq: Freq,
     ) -> Pin<Box<dyn std::future::Future<Output = DynResult<()>> + Send + 'a>> {
         Box::pin(async move {
+            let started = Instant::now();
+            tracing::info!(
+                "SoapySdrRig::set_center_freq start: target={} Hz, current_center={} Hz",
+                freq.hz,
+                self.center_hz
+            );
             tracing::debug!("SoapySdrRig: set_center_freq -> {} Hz", freq.hz);
             self.center_hz = freq.hz as i64;
             if let Ok(mut cmd) = self.retune_cmd.lock() {
@@ -511,6 +531,11 @@ impl RigCat for SoapySdrRig {
                 }
             }
             self.update_ais_channel_offsets();
+            tracing::info!(
+                "SoapySdrRig::set_center_freq done in {:?}: center={} Hz",
+                started.elapsed(),
+                self.center_hz
+            );
             Ok(())
         })
     }
@@ -520,6 +545,12 @@ impl RigCat for SoapySdrRig {
         mode: RigMode,
     ) -> Pin<Box<dyn std::future::Future<Output = DynResult<()>> + Send + 'a>> {
         Box::pin(async move {
+            let started = Instant::now();
+            tracing::info!(
+                "SoapySdrRig::set_mode start: target={:?}, current={:?}",
+                mode,
+                self.mode
+            );
             tracing::debug!("SoapySdrRig: set_mode -> {:?}", mode);
             self.mode = mode.clone();
             self.bandwidth_hz = Self::default_bandwidth_for_mode(&mode);
@@ -534,6 +565,12 @@ impl RigCat for SoapySdrRig {
             }
             self.apply_ais_channel_activity();
             self.apply_ais_channel_filters();
+            tracing::info!(
+                "SoapySdrRig::set_mode done in {:?}: mode={:?}, bandwidth_hz={}",
+                started.elapsed(),
+                self.mode,
+                self.bandwidth_hz
+            );
             Ok(())
         })
     }