diff --git a/Cargo.lock b/Cargo.lock index 125b6eb..09c0fc4 100644 --- a/Cargo.lock +++ b/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", ] diff --git a/Cargo.toml b/Cargo.toml index 4c0e284..af6b4b7 100644 --- a/Cargo.toml +++ b/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" diff --git a/src/lib.rs b/src/lib.rs index 553d867..275a760 100644 --- a/src/lib.rs +++ b/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, diff --git a/src/main.rs b/src/main.rs index 15a855b..f9d4db7 100644 --- a/src/main.rs +++ b/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> { - 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(); diff --git a/src/sources/gpsd.rs b/src/sources/gpsd.rs index c908524..5cd4891 100644 --- a/src/sources/gpsd.rs +++ b/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>, @@ -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, Box> { - 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 { diff --git a/src/sources/prs10.rs b/src/sources/prs10.rs index 9930ca0..4055172 100644 --- a/src/sources/prs10.rs +++ b/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, tx: WriteHalf, @@ -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, 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; - - debug!("stats polled in {}ms", duration.as_secs_f64() * 1000.0); + drop(stats_guard); Ok(ChimemonMessage::SourceReport(SourceReport { name: "prs10".into(),