Configurable logging

Would be good to maybe log more things, and maybe play around with log
levels. But this is okay for now.

stderrlog probably will go at some point, too many unnecessary transient
dependencies

6 files changed, 350 insertions, 8 deletions

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 267a07f..8a8a8df 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -11,6 +11,7 @@ SPDX-License-Identifier: CC-BY-SA-4.0
 
 * Configurable global timeout
 * Configurable per-program timeout
+* Configurable logging
 
 ### Fixed
 
diff --git a/Cargo.lock b/Cargo.lock
index 55f5214..90260da 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -18,6 +18,21 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "512761e0bb2578dd7380c6baaa0f4ce03e84f95e960231d1dec8bf4d7d6e2627"
 
 [[package]]
+name = "android-tzdata"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "e999941b234f3131b00bc13c22d06e8c5ff726d1b6318ac7eb276997bbb4fef0"
+
+[[package]]
+name = "android_system_properties"
+version = "0.1.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "819e7219dbd41043ac279b19830f2efc897156490d7fd6ea916720117ee66311"
+dependencies = [
+ "libc",
+]
+
+[[package]]
 name = "anyhow"
 version = "1.0.98"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -62,6 +77,12 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "1b8e56985ec62d17e9c1001dc89c88ecd7dc08e47eba5ec7c29c7b5eeecde967"
 
 [[package]]
+name = "bumpalo"
+version = "3.19.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "46c5e41b57b8bba42a04676d81cb89e9ee8e859a1a66f80a5a72e1cb76b34d43"
+
+[[package]]
 name = "bytes"
 version = "1.10.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -83,6 +104,20 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"
 
 [[package]]
+name = "chrono"
+version = "0.4.41"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c469d952047f47f91b68d1cba3f10d63c11d73e4636f24f08daf0278abf01c4d"
+dependencies = [
+ "android-tzdata",
+ "iana-time-zone",
+ "js-sys",
+ "num-traits",
+ "wasm-bindgen",
+ "windows-link",
+]
+
+[[package]]
 name = "core-foundation"
 version = "0.9.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -179,6 +214,36 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "84b26c544d002229e640969970a2e74021aadf6e2f96372b9c58eff97de08eb3"
 
 [[package]]
+name = "hermit-abi"
+version = "0.5.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "fc0fef456e4baa96da950455cd02c081ca953b141298e41db3fc7e36b1da849c"
+
+[[package]]
+name = "iana-time-zone"
+version = "0.1.63"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b0c919e5debc312ad217002b8048a17b7d83f80703865bbfcfebb0458b0b27d8"
+dependencies = [
+ "android_system_properties",
+ "core-foundation-sys",
+ "iana-time-zone-haiku",
+ "js-sys",
+ "log",
+ "wasm-bindgen",
+ "windows-core",
+]
+
+[[package]]
+name = "iana-time-zone-haiku"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f31827a206f56af32e590ba56d5d2d085f558508192593743f16b2306495269f"
+dependencies = [
+ "cc",
+]
+
+[[package]]
 name = "indexmap"
 version = "2.9.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -189,6 +254,27 @@ dependencies = [
 ]
 
 [[package]]
+name = "is-terminal"
+version = "0.4.16"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "e04d7f318608d35d4b61ddd75cbdaee86b023ebe2bd5a66ee0915f0bf93095a9"
+dependencies = [
+ "hermit-abi",
+ "libc",
+ "windows-sys 0.59.0",
+]
+
+[[package]]
+name = "js-sys"
+version = "0.3.77"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1cfaf33c695fc6e08064efbc1f72ec937429614f25eef83af942d0e227c3a28f"
+dependencies = [
+ "once_cell",
+ "wasm-bindgen",
+]
+
+[[package]]
 name = "libc"
 version = "0.2.172"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -209,6 +295,9 @@ name = "log"
 version = "0.4.27"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "13dc2df351e3202783a1fe0d44375f7295ffb4049267b0f3018346dc122a1d94"
+dependencies = [
+ "serde",
+]
 
 [[package]]
 name = "memchr"
@@ -253,14 +342,25 @@ name = "mqttr"
 version = "0.2.0"
 dependencies = [
  "anyhow",
+ "log",
  "moro-local",
  "rumqttc",
  "serde",
+ "stderrlog",
  "tokio",
  "toml",
 ]
 
 [[package]]
+name = "num-traits"
+version = "0.2.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "071dfc062690e90b734c0b2273ce72ad0ffa95f0c74596bc250dcfd960262841"
+dependencies = [
+ "autocfg",
+]
+
+[[package]]
 name = "object"
 version = "0.36.7"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -270,6 +370,12 @@ dependencies = [
 ]
 
 [[package]]
+name = "once_cell"
+version = "1.21.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "42f5e15c9953c5e4ccceeb2e7382a716482c34515315f7b03532b8b4e8393d2d"
+
+[[package]]
 name = "openssl-probe"
 version = "0.1.6"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -400,6 +506,12 @@ dependencies = [
 ]
 
 [[package]]
+name = "rustversion"
+version = "1.0.21"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8a0d197bd2c9dc6e53b84da9556a69ba4cdfab8619eb41a8bd1cc2027a0f6b1d"
+
+[[package]]
 name = "schannel"
 version = "0.1.27"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -510,6 +622,19 @@ dependencies = [
 ]
 
 [[package]]
+name = "stderrlog"
+version = "0.6.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "61c910772f992ab17d32d6760e167d2353f4130ed50e796752689556af07dc6b"
+dependencies = [
+ "chrono",
+ "is-terminal",
+ "log",
+ "termcolor",
+ "thread_local",
+]
+
+[[package]]
 name = "subtle"
 version = "2.6.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -527,6 +652,15 @@ dependencies = [
 ]
 
 [[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.69"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -547,6 +681,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "thread_local"
+version = "1.1.9"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f60246a4944f24f6e018aa17cdeffb7818b76356965d03b07d6a9886e8962185"
+dependencies = [
+ "cfg-if",
+]
+
+[[package]]
 name = "tokio"
 version = "1.45.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -638,6 +781,132 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "9c8d87e72b64a3b4db28d11ce29237c246188f4f51057d65a7eab63b7987e423"
 
 [[package]]
+name = "wasm-bindgen"
+version = "0.2.100"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1edc8929d7499fc4e8f0be2262a241556cfc54a0bea223790e71446f2aab1ef5"
+dependencies = [
+ "cfg-if",
+ "once_cell",
+ "rustversion",
+ "wasm-bindgen-macro",
+]
+
+[[package]]
+name = "wasm-bindgen-backend"
+version = "0.2.100"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "2f0a0651a5c2bc21487bde11ee802ccaf4c51935d0d3d42a6101f98161700bc6"
+dependencies = [
+ "bumpalo",
+ "log",
+ "proc-macro2",
+ "quote",
+ "syn",
+ "wasm-bindgen-shared",
+]
+
+[[package]]
+name = "wasm-bindgen-macro"
+version = "0.2.100"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "7fe63fc6d09ed3792bd0897b314f53de8e16568c2b3f7982f468c0bf9bd0b407"
+dependencies = [
+ "quote",
+ "wasm-bindgen-macro-support",
+]
+
+[[package]]
+name = "wasm-bindgen-macro-support"
+version = "0.2.100"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8ae87ea40c9f689fc23f209965b6fb8a99ad69aeeb0231408be24920604395de"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+ "wasm-bindgen-backend",
+ "wasm-bindgen-shared",
+]
+
+[[package]]
+name = "wasm-bindgen-shared"
+version = "0.2.100"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1a05d73b933a847d6cccdda8f838a22ff101ad9bf93e33684f39c1f5f0eece3d"
+dependencies = [
+ "unicode-ident",
+]
+
+[[package]]
+name = "winapi-util"
+version = "0.1.9"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "cf221c93e13a30d793f7645a0e7762c55d169dbb0a49671918a2319d289b10bb"
+dependencies = [
+ "windows-sys 0.59.0",
+]
+
+[[package]]
+name = "windows-core"
+version = "0.61.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c0fdd3ddb90610c7638aa2b3a3ab2904fb9e5cdbecc643ddb3647212781c4ae3"
+dependencies = [
+ "windows-implement",
+ "windows-interface",
+ "windows-link",
+ "windows-result",
+ "windows-strings",
+]
+
+[[package]]
+name = "windows-implement"
+version = "0.60.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a47fddd13af08290e67f4acabf4b459f647552718f683a7b415d290ac744a836"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
+[[package]]
+name = "windows-interface"
+version = "0.59.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "bd9211b69f8dcdfa817bfd14bf1c97c9188afa36f4750130fcdf3f400eca9fa8"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
+[[package]]
+name = "windows-link"
+version = "0.1.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5e6ad25900d524eaabdbbb96d20b4311e1e7ae1699af4fb28c17ae66c80d798a"
+
+[[package]]
+name = "windows-result"
+version = "0.3.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "56f42bd332cc6c8eac5af113fc0c1fd6a8fd2aa08a0119358686e5160d0586c6"
+dependencies = [
+ "windows-link",
+]
+
+[[package]]
+name = "windows-strings"
+version = "0.4.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "56e6c93f3a0c3b36176cb1327a4958a0353d5d166c2a35cb268ace15e91d3b57"
+dependencies = [
+ "windows-link",
+]
+
+[[package]]
 name = "windows-sys"
 version = "0.52.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
diff --git a/Cargo.toml b/Cargo.toml
index a5db89e..3a9a2e9 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -8,8 +8,10 @@ edition = "2021"
 
 [dependencies]
 anyhow = "1.0.98"
+log = { version = "0.4.27", features = ["serde"] }
 moro-local = { git = "https://github.com/EliteTK/moro-local.git", branch = "dependency-reduction" }
 rumqttc = "0.24.0"
 serde = { version = "1.0.219", features = ["derive"] }
+stderrlog = "0.6.0"
 tokio = { version = "1.45.1", features = ["rt", "macros", "process", "time"] }
 toml = { version = "0.8.22", default-features = false, features = ["parse"] }
diff --git a/README.md b/README.md
index 6f7e3b9..a5ba2aa 100644
--- a/README.md
+++ b/README.md
@@ -38,6 +38,10 @@ port = 1883             # MQTT server port
 qos = "exactly-once"    # Default subscription QoS
                         # at-least-once (=0), at-most-once (=1), exactly-once (=2)
 timeout = 10.5          # Timeout in seconds (0 means (effectively) no timeout)
+[log]
+level = "info"          # The log level
+                        # ("off", "error", "warn", "info", # "debug", "trace")
+timestamps = false      # Whether to prepend millisecond timestamps to log entries
 # [credentials]         # Uncomment to specify MQTT connection credentials
 # username = "username"
 # password = "password"
@@ -84,7 +88,6 @@ it being ran every time a new MQTT message is published to this topic.
 
 ## Missing Features
 
-* Configurable logging
 * Ability to configure programs with non-UTF-8 in paths
 * Maybe config reloading on SIGHUP
 * TLS
diff --git a/src/config.rs b/src/config.rs
index 2ba10ec..c110825 100644
--- a/src/config.rs
+++ b/src/config.rs
@@ -7,6 +7,7 @@ use std::{
 };
 
 use anyhow::bail;
+use log::LevelFilter;
 use rumqttc::{AsyncClient, EventLoop, MqttOptions, QoS};
 use serde::{
     de::{self, Visitor},
@@ -15,6 +16,23 @@ use serde::{
 
 use crate::PROGRAM;
 
+#[derive(Deserialize, Debug, PartialEq)]
+pub struct Logging {
+    #[serde(default = "default_level_filter")]
+    pub level: LevelFilter,
+    #[serde(default)] // Off
+    pub timestamps: bool,
+}
+
+impl Default for Logging {
+    fn default() -> Self {
+        Self {
+            level: default_level_filter(),
+            timestamps: bool::default(),
+        }
+    }
+}
+
 #[derive(Deserialize, Debug)]
 pub struct Credentials {
     pub username: String,
@@ -41,6 +59,10 @@ fn default_timeout() -> Duration {
     Duration::from_secs(60)
 }
 
+fn default_level_filter() -> LevelFilter {
+    LevelFilter::Info
+}
+
 #[allow(clippy::enum_variant_names)]
 #[derive(Deserialize, Debug)]
 #[serde(remote = "QoS", rename_all = "kebab-case")]
@@ -248,6 +270,8 @@ pub struct Config {
     pub qos: QoS,
     #[serde(default = "default_timeout", deserialize_with = "deserialize_timeout")]
     pub timeout: Duration,
+    #[serde(default)]
+    pub log: Logging,
     pub credentials: Option<Credentials>,
     #[serde(default = "default_id")]
     pub id: String,
@@ -317,6 +341,10 @@ mod tests {
             username = "testuser"
             password = "testpassword"
 
+            [log]
+            level = "trace"
+            timestamps = true
+
             [routes]
             "topic/map" = { programs = [
                     ["/bin/program1"],
@@ -341,6 +369,9 @@ mod tests {
         assert_eq!(creds.username, "testuser");
         assert_eq!(creds.password, "testpassword");
 
+        assert_eq!(config.log.level, LevelFilter::Trace);
+        assert_eq!(config.log.timestamps, true);
+
         assert_eq!(config.routes.len(), 2);
 
         let route_map = config.routes.get("topic/map").unwrap();
@@ -377,6 +408,7 @@ mod tests {
         assert_eq!(config.id, default_id());
         assert_eq!(config.timeout, default_timeout());
         assert!(config.credentials.is_none());
+        assert_eq!(config.log, Logging::default());
         assert!(config.routes.is_empty());
     }
 
diff --git a/src/main.rs b/src/main.rs
index 396c66a..b071620 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -1,15 +1,15 @@
 // SPDX-FileCopyrightText: 2025 Tomasz Kramkowski <tomasz@kramkow.ski>
 // SPDX-License-Identifier: GPL-3.0-or-later
 
-// TODO: Log levels
-
 use std::{
+    os::unix::process::ExitStatusExt,
     path::PathBuf,
     process::{ExitStatus, Stdio},
     rc::Rc,
 };
 
 use anyhow::Context;
+use log::{debug, error, trace, warn};
 use rumqttc::{Event::Incoming, Packet, Publish, QoS};
 use tokio::{io::AsyncWriteExt, process::Command, time::timeout};
 
@@ -18,6 +18,7 @@ mod config;
 const PROGRAM: &str = "mqttr";
 
 async fn run(program: &[String], message: &Publish) -> anyhow::Result<ExitStatus> {
+    debug!("Starting program {program:?} for message {message:?}");
     let mut command = Command::new(&program[0]);
     command
         .args(&program[1..])
@@ -29,6 +30,10 @@ async fn run(program: &[String], message: &Publish) -> anyhow::Result<ExitStatus
         command.arg(format!("{}", message.pkid));
     }
     let mut proc = command.stdin(Stdio::piped()).spawn()?;
+    trace!(
+        "Started program {program:?} with PID {}",
+        proc.id().expect("missing PID")
+    );
     let mut stdin = proc.stdin.take().context("No stdin")?;
     stdin.write_all(&message.payload).await?;
     drop(stdin);
@@ -76,21 +81,38 @@ async fn main() -> anyhow::Result<()> {
     conf_path.push(format!("{PROGRAM}.toml"));
     let conf = config::load(&conf_path)
         .with_context(|| format!("Failed to load config: {:?}", &conf_path))?;
+    stderrlog::new()
+        .color(stderrlog::ColorChoice::Never)
+        .module(module_path!())
+        .verbosity(conf.log.level)
+        .timestamp(if conf.log.timestamps {
+            stderrlog::Timestamp::Millisecond
+        } else {
+            stderrlog::Timestamp::Off
+        })
+        .init()
+        .unwrap();
+    // TODO: This will print creds
+    trace!("Configuration: {conf:?}");
     let (client, mut event_loop) = conf.mqtt_client();
     for (topic, route) in conf.routes.iter() {
         if let Err(e) = client.subscribe(topic, route.qos.unwrap_or(conf.qos)).await {
-            eprintln!("warning: Failed to subscribe to '{topic}': {e:?}");
+            warn!("Failed to subscribe to '{topic}': {e:?}");
+        } else {
+            debug!("Subscribed to: '{topic}'");
         }
     }
     moro_local::async_scope!(|scope| -> anyhow::Result<()> {
         loop {
             let notification = event_loop.poll().await;
             if let Incoming(Packet::Publish(p)) = notification? {
+                debug!("Received message: {p:?}");
                 let p = Rc::new(p);
                 for (topic, route) in conf.routes.iter() {
                     if !topic_match(topic, &p.topic) {
                         continue;
                     }
+                    debug!("Message {p:?} matched topic {topic}");
                     for program in route.programs.iter() {
                         let p = p.clone();
                         scope.spawn(async move {
@@ -100,11 +122,24 @@ async fn main() -> anyhow::Result<()> {
                             )
                             .await
                             {
-                                Err(_) => eprintln!(
-                                    "error: Execution of {program:?} for message {p:?} timed out"
+                                Err(_) => error!(
+                                    "Execution of {program:?} for message {p:?} timed out"
                                 ),
-                                Ok(Err(e)) => eprintln!("error: Failed to run {program:?}: {e:?}"),
-                                _ => (),
+                                Ok(Err(e)) => error!("error: Failed to run {program:?}: {e:?}"),
+                                Ok(Ok(c)) => {
+                                    if !c.success() {
+                                        if let Some(code) = c.code() {
+                                            if code != 0 {
+                                                warn!("Program exited with non-zero exit code: {code}")
+                                            } else {
+                                                debug!("Program exited successfully.");
+                                            }
+                                        } else if let Some(signal) = c.signal() {
+                                            let core_dumped = if c.core_dumped() { " (core dumped)" } else { "" };
+                                            warn!("Program received signal: {signal}{core_dumped}");
+                                        }
+                                    }
+                                },
                             }
                         });
                     }