Switched to tracing

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",
+ "regex-syntax",
- "memchr",
+]
+
+[[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"

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

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))
             },
         }

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);
         })
     }

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,13 +117,14 @@ 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,6 +136,7 @@ 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 {

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))
         }

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 tracing::{error, info, metadata::LevelFilter};
-use log::{error, info, debug, 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
+    let filter = EnvFilter::builder()
-    Builder::new()
+        .with_default_directive(LevelFilter::INFO.into())
-        .filter_module("automation", LevelFilter::Trace)
+        .from_env_lossy();
-        .parse_default_env()
+
+    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);
         });
 

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,

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::*;

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() {