incremental improvements

Cargo.lock

@@ -396,6 +396,15 @@ dependencies = [
  "num_cpus",
 ]
 
+[[package]]
+name = "deranged"
+version = "0.5.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ececcb659e7ba858fb4f10388c250a7252eb0a27373f1a72b8748afdd248e587"
+dependencies = [
+ "powerfmt",
+]
+
 [[package]]
 name = "displaydoc"
 version = "0.2.5"
@@ -1099,6 +1108,15 @@ dependencies = [
  "regex-automata 0.1.10",
 ]
 
+[[package]]
+name = "matchers"
+version = "0.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9"
+dependencies = [
+ "regex-automata 0.4.13",
+]
+
 [[package]]
 name = "memchr"
 version = "2.7.6"
@@ -1201,6 +1219,12 @@ dependencies = [
  "windows-sys 0.61.2",
 ]
 
+[[package]]
+name = "num-conv"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "51d515d32fb182ee37cda2ccdcb92950d6a3c2893aa280e540671c2cd0f3b1d9"
+
 [[package]]
 name = "num-traits"
 version = "0.2.19"
@@ -1404,6 +1428,12 @@ dependencies = [
  "zerovec",
 ]
 
+[[package]]
+name = "powerfmt"
+version = "0.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "439ee305def115ba05938db6eb1644ff94165c5ab5e9420d1c1bcedbba909391"
+
 [[package]]
 name = "ppv-lite86"
 version = "0.2.21"
@@ -1958,6 +1988,37 @@ dependencies = [
  "cfg-if",
 ]
 
+[[package]]
+name = "time"
+version = "0.3.44"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "91e7d9e3bb61134e77bde20dd4825b97c010155709965fedf0f49bb138e52a9d"
+dependencies = [
+ "deranged",
+ "itoa",
+ "num-conv",
+ "powerfmt",
+ "serde",
+ "time-core",
+ "time-macros",
+]
+
+[[package]]
+name = "time-core"
+version = "0.1.6"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "40868e7c1d2f0b8d73e4a8c7f0ff63af4f6d19be117e90bd73eb1d62cf831c6b"
+
+[[package]]
+name = "time-macros"
+version = "0.2.24"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "30cfb0125f12d9c277f35663a0a33f8c30190f4e4574868a330595412d34ebf3"
+dependencies = [
+ "num-conv",
+ "time-core",
+]
+
 [[package]]
 name = "tinystr"
 version = "0.8.2"
@@ -2163,7 +2224,7 @@ dependencies = [
  "ansi_term",
  "chrono",
  "lazy_static",
- "matchers",
+ "matchers 0.0.1",
  "parking_lot",
  "regex",
  "serde",
@@ -2182,10 +2243,15 @@ version = "0.3.22"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "2f30143827ddab0d256fd843b7a66d164e9f271cfa0dde49142c5ca0ca291f1e"
 dependencies = [
+ "matchers 0.2.0",
  "nu-ansi-term",
+ "once_cell",
+ "regex-automata 0.4.13",
  "sharded-slab",
  "smallvec",
  "thread_local",
+ "time",
+ "tracing",
  "tracing-core",
  "tracing-log",
 ]

Cargo.toml

@@ -19,7 +19,6 @@ tokio-stream = { version = "0.1.11", features = ["sync"] }
 byteorder = "1.4.3"
 tokio-serial = "5.4.4"
 bytes = "1.2.1"
-chrono = "0.4.23"
 libc = "0.2.137"
 async-stream = "0.3.6"
 itertools = "0.14.0"
@@ -29,11 +28,12 @@ serde_json = "1.0.146"
 backoff = { version = "0.4.0", features = ["tokio"] }
 serde_repr = "0.1.20"
 tracing = "0.1.44"
-tracing-subscriber = { version = "0.3.22", features = ["fmt"] }
+tracing-subscriber = { version = "0.3.22", features = ["fmt", "ansi", "time", "env-filter"] }
 serialport = "4.8.1"
 gethostname = "1.1.0"
 bitflags = "2.10.0"
 influxdb2 = "0.3.9"
+chrono = "0.4.43"
 
 [dependencies.chrony-candm]
 git = "https://github.com/aws/chrony-candm"

src/lib.rs

@@ -107,7 +107,7 @@ impl Default for HwmonConfig {
     }
 }
 
-#[derive(Serialize, Deserialize, Clone)]
+#[derive(Serialize, Deserialize, Clone, Debug)]
 pub struct GpsdConfig {
     pub enabled: bool,
     pub interval: u64,
@@ -124,7 +124,7 @@ impl Default for GpsdConfig {
     }
 }
 
-#[derive(Serialize, Deserialize, Clone)]
+#[derive(Serialize, Deserialize, Clone, Debug)]
 pub struct Prs10Config {
     pub enabled: bool,
     pub port: String,

src/main.rs

@@ -3,7 +3,11 @@ use futures::future::join_all;
 use std::path::Path;
 use tokio::sync::broadcast;
 use tracing::{Instrument, debug, error, info, info_span, warn};
-use tracing_subscriber;
+use tracing_subscriber::{
+    self, EnvFilter,
+    fmt::format::{self, FmtSpan},
+    prelude::*,
+};
 
 use chimemon::*;
 use sources::{
@@ -34,7 +38,11 @@ struct Args {
 
 #[tokio::main(flavor = "current_thread")]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
-    tracing_subscriber::fmt::init();
+    tracing_subscriber::fmt()
+        .with_env_filter(EnvFilter::try_from_default_env().unwrap_or(EnvFilter::default()))
+        // .event_format(format::Format::default().pretty())
+        .with_span_events(FmtSpan::CLOSE)
+        .init();
 
     let args = Args::parse();
 

src/sources/gpsd.rs

@@ -20,7 +20,7 @@ use serde_json;
 use tokio::net::{TcpStream, ToSocketAddrs, lookup_host};
 use tokio::time::{interval, timeout};
 use tokio_util::codec::{Framed, LinesCodec};
-use tracing::{debug, debug_span, info, warn};
+use tracing::{debug, debug_span, info, instrument, warn};
 
 pub struct GpsdSource {
     pub config: Config,
@@ -190,6 +190,7 @@ impl ChimemonSource for GpsdSource {
     }
 }
 
+#[derive(Debug)]
 struct GpsdTransport {
     host: SocketAddr,
     framed: Option<Framed<TcpStream, LinesCodec>>,
@@ -381,16 +382,14 @@ impl GpsdTransport {
         Ok(self.framed.as_mut().unwrap())
     }
 
+    #[instrument(level = "debug", skip_all, fields(cmd = cmd.to_string()))]
     async fn cmd_response(
         &mut self,
         cmd: &GpsdCommand,
     ) -> Result<Vec<UnifiedResponse>, Box<dyn std::error::Error>> {
-        debug!("Command: `{cmd:?}`");
-
         let mut responses = Vec::new();
         let conn = self.conn().await?;
 
-        debug!("Raw command: `{}`", cmd.to_string());
         conn.send(cmd.to_string()).await?;
         for _ in 0..cmd.expected_responses() {
             match conn.next().await {

src/sources/prs10.rs

@@ -14,7 +14,7 @@ use tokio::sync::OnceCell;
 use tokio::time::{interval, timeout};
 use tokio_serial;
 use tokio_serial::{SerialPort, SerialStream};
-use tracing::{debug, error, info, warn};
+use tracing::{debug, debug_span, error, info, instrument, warn};
 
 #[derive(Debug)]
 pub struct Prs10Info {
@@ -318,6 +318,7 @@ impl SourceReportDetails for Prs10Stats {
     }
 }
 
+#[derive(Debug)]
 pub struct Prs10Monitor {
     rx: ReadHalf<SerialStream>,
     tx: WriteHalf<SerialStream>,
@@ -354,15 +355,15 @@ impl Prs10Monitor {
         self.info.get().expect("info() used before run()")
     }
 
+    #[instrument(level = "debug", skip_all, fields(cmd = String::from_utf8_lossy(cmd).to_string()))]
     pub async fn cmd_response(&mut self, cmd: &[u8]) -> Result<Vec<u8>, std::io::Error> {
-        debug!("cmd: `{:?}`", String::from_utf8_lossy(cmd));
         self.tx.write_all(cmd).await.unwrap();
         self.tx.write_u8(b'\r').await.unwrap();
         let mut reader = BufReader::new(&mut self.rx);
         let mut buf = Vec::new();
         let read = timeout(self.config.timeout, reader.read_until(b'\r', &mut buf)).await??;
         buf.truncate(buf.len() - 1); // strip "\r"
-        debug!("cmd response: ({read}) `{buf:?}`");
+        debug!("response: ({read}) `{buf:?}`");
         Ok(buf)
     }
 
@@ -461,7 +462,8 @@ impl Prs10Monitor {
 
         debug!("polling stats");
 
-        let start = std::time::Instant::now();
+        let stats_span = debug_span!("get_stats_serial");
+        let stats_guard = stats_span.enter();
         let ocxo_efc = self.get_ocxo_efc().await?;
         let (error_signal_volts, detect_signal_volts) = self.get_detected_signals().await?;
         let freq_offset_ppt = self.get_parsed(b"SF?").await?;
@@ -470,9 +472,7 @@ impl Prs10Monitor {
         for i in 1u16..=19 {
             analog_values[i as usize] = self.get_analog(i).await? * ANALOG_SCALING[i as usize]
         }
-        let duration = std::time::Instant::now() - start;
+        drop(stats_guard);
-
-        debug!("stats polled in {}ms", duration.as_secs_f64() * 1000.0);
 
         Ok(ChimemonMessage::SourceReport(SourceReport {
             name: "prs10".into(),