From 06e511758b73533157131624062ed417f20aaea5 Mon Sep 17 00:00:00 2001 From: Dreaded_X Date: Thu, 29 Dec 2022 06:14:01 +0100 Subject: [PATCH] Switched to tracing --- Cargo.lock | 215 ++++++++++++++++++------------------- Cargo.toml | 4 +- src/config.rs | 6 +- src/devices.rs | 11 +- src/devices/ikea_outlet.rs | 18 ++-- src/devices/wake_on_lan.rs | 13 +-- src/main.rs | 15 +-- src/mqtt.rs | 8 +- src/ntfy.rs | 2 +- src/presence.rs | 5 +- 10 files changed, 145 insertions(+), 152 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 9065251..c089407 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2,15 +2,6 @@ # It is not intended for manual editing. version = 3 -[[package]] -name = "aho-corasick" -version = "0.7.20" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "cc936419f96fa211c1b9166887b38e5e40b19958e5b895be7c1f93adec7071ac" -dependencies = [ - "memchr", -] - [[package]] name = "anyhow" version = "1.0.68" @@ -41,10 +32,8 @@ dependencies = [ "anyhow", "axum", "dotenv", - "env_logger", "google-home", "impl_cast", - "log", "paste", "reqwest", "rumqttc", @@ -53,6 +42,8 @@ dependencies = [ "serde_repr", "tokio", "toml", + "tracing", + "tracing-subscriber", ] [[package]] @@ -172,40 +163,6 @@ dependencies = [ "cfg-if", ] -[[package]] -name = "env_logger" -version = "0.10.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "85cdab6a89accf66733ad5a1693a4dcced6aeff64602b634530dd73c1f3ee9f0" -dependencies = [ - "humantime", - "is-terminal", - "log", - "regex", - "termcolor", -] - -[[package]] -name = "errno" -version = "0.2.8" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f639046355ee4f37944e44f60642c6f3a7efa3cf6b78c78a0d989a8ce6c396a1" -dependencies = [ - "errno-dragonfly", - "libc", - "winapi", -] - -[[package]] -name = "errno-dragonfly" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "aa68f1b12764fab894d2755d2518754e71b4fd80ecfb822714a1206c2aab39bf" -dependencies = [ - "cc", - "libc", -] - [[package]] name = "fastrand" version = "1.8.0" @@ -445,12 +402,6 @@ version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c4a1e36c821dbe04574f602848a19f742f4fb3c98d40449f11bcad18d6b17421" -[[package]] -name = "humantime" -version = "2.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" - [[package]] name = "hyper" version = "0.14.23" @@ -524,34 +475,12 @@ dependencies = [ "cfg-if", ] -[[package]] -name = "io-lifetimes" -version = "1.0.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "46112a93252b123d31a119a8d1a1ac19deac4fac6e0e8b0df58f0d4e5870e63c" -dependencies = [ - "libc", - "windows-sys 0.42.0", -] - [[package]] name = "ipnet" version = "2.7.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "11b0d96e660696543b251e58030cf9787df56da39dab19ad60eae7353040917e" -[[package]] -name = "is-terminal" -version = "0.4.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "28dfb6c8100ccc63462345b67d1bbc3679177c75ee4bf59bf29c8b1d110b8189" -dependencies = [ - "hermit-abi", - "io-lifetimes", - "rustix", - "windows-sys 0.42.0", -] - [[package]] name = "itoa" version = "1.0.4" @@ -579,12 +508,6 @@ version = "0.2.138" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db6d7e329c562c5dfab7a46a2afabc8b987ab9a4834c9d1ca04dc54c1546cef8" -[[package]] -name = "linux-raw-sys" -version = "0.1.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f051f77a7c8e6957c0696eac88f26b0117e54f52d3fc682ab19397a8812846a4" - [[package]] name = "lock_api" version = "0.4.9" @@ -604,6 +527,15 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata", +] + [[package]] name = "matchit" version = "0.7.0" @@ -661,6 +593,16 @@ dependencies = [ "tempfile", ] +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num_cpus" version = "1.15.0" @@ -722,6 +664,12 @@ dependencies = [ "vcpkg", ] +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking_lot" version = "0.12.1" @@ -834,8 +782,15 @@ version = "1.7.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e076559ef8e241f2ae3479e36f97bd5741c0330689e217ad51ce2c76808b868a" dependencies = [ - "aho-corasick", - "memchr", + "regex-syntax", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ "regex-syntax", ] @@ -924,20 +879,6 @@ dependencies = [ "tokio-rustls", ] -[[package]] -name = "rustix" -version = "0.36.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a3807b5d10909833d3e9acd1eb5fb988f79376ff10fce42937de71a449c4c588" -dependencies = [ - "bitflags", - "errno", - "io-lifetimes", - "libc", - "linux-raw-sys", - "windows-sys 0.42.0", -] - [[package]] name = "rustls" version = "0.20.7" @@ -1104,6 +1045,15 @@ dependencies = [ "serde", ] +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "signal-hook-registry" version = "1.4.0" @@ -1184,15 +1134,6 @@ dependencies = [ "winapi", ] -[[package]] -name = "termcolor" -version = "1.1.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "bab24d30b911b2376f3a13cc2cd443142f0c81dda04c118693e35b3835757755" -dependencies = [ - "winapi-util", -] - [[package]] name = "thiserror" version = "1.0.37" @@ -1213,6 +1154,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180" +dependencies = [ + "once_cell", +] + [[package]] name = "tinyvec" version = "1.6.0" @@ -1359,9 +1309,21 @@ dependencies = [ "cfg-if", "log", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4017f8f45139870ca7e672686113917c71c7a6e02d4924eda67186083c03081a" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "tracing-core" version = "0.1.30" @@ -1369,6 +1331,36 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "24eb03ba0eab1fd845050058ce5e616558e8f8d8fca633e6b163fe25c797213a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a6176eae26dd70d0c919749377897b54a9276bd7061339665dd68777926b5a70" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", ] [[package]] @@ -1415,6 +1407,12 @@ dependencies = [ "percent-encoding", ] +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "vcpkg" version = "0.2.15" @@ -1539,15 +1537,6 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" -[[package]] -name = "winapi-util" -version = "0.1.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178" -dependencies = [ - "winapi", -] - [[package]] name = "winapi-x86_64-pc-windows-gnu" version = "0.4.0" diff --git a/Cargo.toml b/Cargo.toml index 86d54a6..36bc300 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -17,14 +17,14 @@ impl_cast = {path = "./impl_cast"} google-home = {path = "./google-home"} paste = "1.0.10" tokio = { version = "1", features = ["full"] } -log = "0.4" -env_logger = "0.10" toml = "0.5.10" dotenv = "0.15.0" anyhow = "1.0.68" reqwest = "0.11.13" axum = "0.6.1" serde_repr = "0.1.10" +tracing = "0.1.37" +tracing-subscriber = { version = "0.3.16", features = ["env-filter"] } [profile.release] lto=true diff --git a/src/config.rs b/src/config.rs index e98a96a..32b04bd 100644 --- a/src/config.rs +++ b/src/config.rs @@ -1,6 +1,6 @@ use std::{fs, error::Error, collections::HashMap}; -use log::{debug, trace}; +use tracing::{debug, trace}; use rumqttc::AsyncClient; use serde::Deserialize; @@ -103,11 +103,11 @@ impl Device { pub fn into(self, identifier: String, client: AsyncClient) -> DeviceBox { match self { Device::IkeaOutlet { info, mqtt, kettle } => { - trace!("\tIkeaOutlet [{} in {:?}]", info.name, info.room); + trace!(id = identifier, "IkeaOutlet [{} in {:?}]", info.name, info.room); Box::new(IkeaOutlet::new(identifier, info, mqtt, kettle, client)) }, Device::WakeOnLAN { info, mqtt, mac_address } => { - trace!("\tWakeOnLan [{} in {:?}]", info.name, info.room); + trace!(id = identifier, "WakeOnLan [{} in {:?}]", info.name, info.room); Box::new(WakeOnLAN::new(identifier, info, mqtt, mac_address, client)) }, } diff --git a/src/devices.rs b/src/devices.rs index 336e16a..5eea5ef 100644 --- a/src/devices.rs +++ b/src/devices.rs @@ -7,7 +7,7 @@ pub use self::wake_on_lan::WakeOnLAN; use std::collections::HashMap; use google_home::{GoogleHomeDevice, traits::OnOff}; -use log::trace; +use tracing::{trace, debug, span, Level}; use crate::{mqtt::OnMqtt, presence::OnPresence}; @@ -51,6 +51,7 @@ impl Devices { } pub fn add_device(&mut self, device: DeviceBox) { + debug!(id = device.get_id(), "Adding device"); self.devices.insert(device.get_id(), device); } @@ -69,9 +70,9 @@ impl Devices { impl OnMqtt for Devices { fn on_mqtt(&mut self, message: &rumqttc::Publish) { - trace!("OnMqtt for devices"); self.as_on_mqtts().iter_mut().for_each(|(id, listener)| { - trace!("OnMqtt: {id}"); + let _span = span!(Level::TRACE, "on_mqtt").entered(); + trace!(id, "Handling"); listener.on_mqtt(message); }) } @@ -79,9 +80,9 @@ impl OnMqtt for Devices { impl OnPresence for Devices { fn on_presence(&mut self, presence: bool) { - trace!("OnPresence for devices"); self.as_on_presences().iter_mut().for_each(|(id, device)| { - trace!("OnPresence: {id}"); + let _span = span!(Level::TRACE, "on_presence").entered(); + trace!(id, "Handling"); device.on_presence(presence); }) } diff --git a/src/devices/ikea_outlet.rs b/src/devices/ikea_outlet.rs index 3762c82..888e1d3 100644 --- a/src/devices/ikea_outlet.rs +++ b/src/devices/ikea_outlet.rs @@ -4,7 +4,7 @@ use google_home::errors::ErrorCode; use google_home::{GoogleHomeDevice, device, types::Type, traits}; use rumqttc::{AsyncClient, Publish}; use serde::{Deserialize, Serialize}; -use log::{debug, trace, warn}; +use tracing::{debug, trace, warn}; use tokio::task::JoinHandle; use crate::config::{KettleConfig, InfoConfig, MqttDeviceConfig}; @@ -79,7 +79,7 @@ impl OnMqtt for IkeaOutlet { let new_state = match StateMessage::try_from(message) { Ok(state) => state, Err(err) => { - warn!("Failed to parse message: {err}"); + warn!(id = self.identifier, "Failed to parse message: {err}"); return; } }.state == "ON"; @@ -94,7 +94,7 @@ impl OnMqtt for IkeaOutlet { handle.abort(); } - trace!("Updating state: {} => {}", self.last_known_state, new_state); + debug!(id = self.identifier, "Updating state to {new_state}"); self.last_known_state = new_state; // If this is a kettle start a timeout for turning it of again @@ -107,7 +107,7 @@ impl OnMqtt for IkeaOutlet { let timeout = match kettle.timeout.clone() { Some(timeout) => timeout, None => { - trace!("Outlet is a kettle without timeout"); + trace!(id = self.identifier, "Outlet is a kettle without timeout"); return; }, }; @@ -117,16 +117,17 @@ impl OnMqtt for IkeaOutlet { // get dropped let client = self.client.clone(); let topic = self.mqtt.topic.clone(); + let id = self.identifier.clone(); self.handle = Some( tokio::spawn(async move { - debug!("Starting timeout ({timeout}s) for kettle..."); + debug!(id, "Starting timeout ({timeout}s) for kettle..."); tokio::time::sleep(Duration::from_secs(timeout)).await; // @TODO We need to call set_on(false) in order to turn the device off // again, how are we going to do this? - debug!("Turning kettle off!"); + debug!(id, "Turning kettle off!"); set_on(client, topic, false).await; }) - ); + ); } } } @@ -135,10 +136,11 @@ impl OnPresence for IkeaOutlet { fn on_presence(&mut self, presence: bool) { // Turn off the outlet when we leave the house if !presence { + debug!(id = self.identifier, "Turning device off"); let client = self.client.clone(); let topic = self.mqtt.topic.clone(); tokio::spawn(async move { - set_on(client, topic, false).await; + set_on(client, topic, false).await; }); } } diff --git a/src/devices/wake_on_lan.rs b/src/devices/wake_on_lan.rs index 75b28c8..2e3bf4f 100644 --- a/src/devices/wake_on_lan.rs +++ b/src/devices/wake_on_lan.rs @@ -1,5 +1,5 @@ use google_home::{GoogleHomeDevice, types::Type, device, traits::{self, Scene}, errors::{ErrorCode, DeviceError}}; -use log::{debug, warn}; +use tracing::{debug, warn}; use rumqttc::{AsyncClient, Publish}; use serde::Deserialize; @@ -56,7 +56,7 @@ impl OnMqtt for WakeOnLAN { let payload = match StateMessage::try_from(message) { Ok(state) => state, Err(err) => { - warn!("Failed to parse message: {err}"); + warn!(id = self.identifier, "Failed to parse message: {err}"); return; } }; @@ -96,23 +96,24 @@ impl traits::Scene for WakeOnLAN { // @TODO In the future send the wake on lan package directly, this is kind of annoying // if we are inside of docker, so for now just call a webhook that does it for us let mac_address = self.mac_address.clone(); + let id = self.identifier.clone(); tokio::spawn(async move { - debug!("Activating Computer: {}", mac_address); + debug!(id, "Activating Computer: {}", mac_address); let req = match reqwest::get(format!("http://10.0.0.2:9000/start-pc?mac={mac_address}")).await { Ok(req) => req, Err(err) => { - warn!("Failed to call webhook: {err}"); + warn!(id, "Failed to call webhook: {err}"); return; } }; if req.status() != 200 { - warn!("Failed to call webhook: {}", req.status()); + warn!(id, "Failed to call webhook: {}", req.status()); } }); Ok(()) } else { - debug!("Trying to deactive computer, this is not currently supported"); + debug!(id = self.identifier, "Trying to deactive computer, this is not currently supported"); // We do not support deactivating this scene Err(ErrorCode::DeviceError(DeviceError::ActionNotAvailable)) } diff --git a/src/main.rs b/src/main.rs index e78bb74..b04b652 100644 --- a/src/main.rs +++ b/src/main.rs @@ -6,20 +6,22 @@ use axum::{Router, Json, routing::post, http::StatusCode}; use automation::{config::Config, presence::Presence, ntfy::Ntfy}; use dotenv::dotenv; use rumqttc::{MqttOptions, Transport, AsyncClient}; -use env_logger::Builder; -use log::{error, info, debug, LevelFilter}; +use tracing::{error, info, metadata::LevelFilter}; use automation::{devices::Devices, mqtt::Mqtt}; use google_home::{GoogleHome, Request}; +use tracing_subscriber::EnvFilter; #[tokio::main] async fn main() { dotenv().ok(); - // Setup logger - Builder::new() - .filter_module("automation", LevelFilter::Trace) - .parse_default_env() + let filter = EnvFilter::builder() + .with_default_directive(LevelFilter::INFO.into()) + .from_env_lossy(); + + tracing_subscriber::fmt() + .with_env_filter(filter) .init(); let config = std::env::var("AUTOMATION_CONFIG").unwrap_or("./config/config.toml".to_owned()); @@ -67,7 +69,6 @@ async fn main() { device_config.into(identifier, client.clone()) }) .for_each(|device| { - debug!("Adding device {}", device.get_id()); devices.write().unwrap().add_device(device); }); diff --git a/src/mqtt.rs b/src/mqtt.rs index 7e8a9b6..65ab094 100644 --- a/src/mqtt.rs +++ b/src/mqtt.rs @@ -1,8 +1,7 @@ use std::sync::{Weak, RwLock}; -use log::{error, debug}; +use tracing::{error, debug, trace, span, Level}; use rumqttc::{Publish, Event, Incoming, EventLoop}; -use log::trace; use tokio::task::JoinHandle; pub trait OnMqtt { @@ -21,8 +20,6 @@ impl Mqtt { } fn notify(&mut self, message: Publish) { - trace!("Listener count: {}", self.listeners.len()); - self.listeners.retain(|listener| { if let Some(listener) = listener.upgrade() { listener.write().unwrap().on_mqtt(&message); @@ -46,7 +43,8 @@ impl Mqtt { let notification = self.eventloop.poll().await; match notification { Ok(Event::Incoming(Incoming::Publish(p))) => { - trace!("{:?}", p); + // Could cause problems in async + let _span = span!(Level::TRACE, "mqtt_message").entered(); self.notify(p); }, Ok(..) => continue, diff --git a/src/ntfy.rs b/src/ntfy.rs index f343366..c8258d1 100644 --- a/src/ntfy.rs +++ b/src/ntfy.rs @@ -1,6 +1,6 @@ use std::collections::HashMap; -use log::{warn, error}; +use tracing::{warn, error}; use reqwest::StatusCode; use serde::Serialize; use serde_repr::*; diff --git a/src/presence.rs b/src/presence.rs index d0acebb..63c496b 100644 --- a/src/presence.rs +++ b/src/presence.rs @@ -1,6 +1,6 @@ use std::{sync::{Weak, RwLock}, collections::HashMap}; -use log::{debug, warn, trace}; +use tracing::{debug, warn, trace, span, Level}; use rumqttc::{AsyncClient, Publish}; use serde::{Serialize, Deserialize}; @@ -75,7 +75,8 @@ impl OnMqtt for Presence { debug!("Overall presence updated: {overall_presence}"); self.overall_presence = overall_presence; - trace!("Listener count: {}", self.listeners.len()); + // This has problems in async + let _span = span!(Level::TRACE, "presence_update").entered(); self.listeners.retain(|listener| { if let Some(listener) = listener.upgrade() {