Add proper tracing2

Cargo.lock

@@ -17,6 +17,15 @@ version = "1.0.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "f26201604c87b1e01bd3d98f8d5d9a8fcbb815e8cedb41ffccbeb4bf593a35fe"
 
+[[package]]
+name = "aho-corasick"
+version = "1.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b2969dcb958b36655471fc61f7e416fa76033bdd4bfed0678d8fee1e2d07a1f0"
+dependencies = [
+ "memchr",
+]
+
 [[package]]
 name = "android-tzdata"
 version = "0.1.1"
@@ -649,6 +658,8 @@ dependencies = [
  "symphonia",
  "tokio",
  "tokio-stream",
+ "tracing",
+ "tracing-subscriber",
 ]
 
 [[package]]
@@ -694,6 +705,15 @@ version = "0.4.21"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "90ed8c1e510134f979dbc4f070f87d4313098b704861a105fe34231c70a3901c"
 
+[[package]]
+name = "matchers"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558"
+dependencies = [
+ "regex-automata 0.1.10",
+]
+
 [[package]]
 name = "memchr"
 version = "2.7.1"
@@ -764,6 +784,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-traits"
 version = "0.2.18"
@@ -852,6 +882,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"
 version = "2.2.0"
@@ -968,6 +1004,50 @@ dependencies = [
  "bitflags 1.3.2",
 ]
 
+[[package]]
+name = "regex"
+version = "1.10.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b62dbe01f0b06f9d8dc7d49e05a0785f153b00b2c227856282f671e0318c9b15"
+dependencies = [
+ "aho-corasick",
+ "memchr",
+ "regex-automata 0.4.6",
+ "regex-syntax 0.8.2",
+]
+
+[[package]]
+name = "regex-automata"
+version = "0.1.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132"
+dependencies = [
+ "regex-syntax 0.6.29",
+]
+
+[[package]]
+name = "regex-automata"
+version = "0.4.6"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "86b83b8b9847f9bf95ef68afb0b8e6cdb80f498442f5179a29fad448fcc1eaea"
+dependencies = [
+ "aho-corasick",
+ "memchr",
+ "regex-syntax 0.8.2",
+]
+
+[[package]]
+name = "regex-syntax"
+version = "0.6.29"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1"
+
+[[package]]
+name = "regex-syntax"
+version = "0.8.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c08c74e62047bb2de4ff487b251e4a92e24f48745648451635cec7d591162d9f"
+
 [[package]]
 name = "reqwest"
 version = "0.11.26"
@@ -1125,6 +1205,15 @@ dependencies = [
  "serde",
 ]
 
+[[package]]
+name = "sharded-slab"
+version = "0.1.7"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6"
+dependencies = [
+ "lazy_static",
+]
+
 [[package]]
 name = "signal-hook-registry"
 version = "1.4.1"
@@ -1415,6 +1504,16 @@ dependencies = [
  "windows-sys 0.52.0",
 ]
 
+[[package]]
+name = "thread_local"
+version = "1.1.8"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c"
+dependencies = [
+ "cfg-if",
+ "once_cell",
+]
+
 [[package]]
 name = "tinyvec"
 version = "1.6.0"
@@ -1509,9 +1608,21 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef"
 dependencies = [
  "pin-project-lite",
+ "tracing-attributes",
  "tracing-core",
 ]
 
+[[package]]
+name = "tracing-attributes"
+version = "0.1.27"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn 2.0.53",
+]
+
 [[package]]
 name = "tracing-core"
 version = "0.1.32"
@@ -1519,6 +1630,36 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54"
 dependencies = [
  "once_cell",
+ "valuable",
+]
+
+[[package]]
+name = "tracing-log"
+version = "0.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3"
+dependencies = [
+ "log",
+ "once_cell",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.18"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b"
+dependencies = [
+ "matchers",
+ "nu-ansi-term",
+ "once_cell",
+ "regex",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing",
+ "tracing-core",
+ "tracing-log",
 ]
 
 [[package]]
@@ -1559,6 +1700,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"
@@ -1669,6 +1816,28 @@ dependencies = [
  "wasm-bindgen",
 ]
 
+[[package]]
+name = "winapi"
+version = "0.3.9"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5c839a674fcd7a98952e593242ea400abe93992746761e38641405d28b00f419"
+dependencies = [
+ "winapi-i686-pc-windows-gnu",
+ "winapi-x86_64-pc-windows-gnu",
+]
+
+[[package]]
+name = "winapi-i686-pc-windows-gnu"
+version = "0.4.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6"
+
+[[package]]
+name = "winapi-x86_64-pc-windows-gnu"
+version = "0.4.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "712e227841d057c1ee1cd2fb22fa7e5a5461ae8e48fa2ca79ec42cfc1931183f"
+
 [[package]]
 name = "windows-core"
 version = "0.52.0"

Cargo.toml

@@ -25,3 +25,5 @@ envconfig = "0.10"
 chrono = "0.4.35"
 itertools = "0.12.1"
 rand = "0.8.5"
+tracing-subscriber = { version = "0.3", features = ["env-filter"] }
+tracing = "0.1"

src/main.rs

@@ -4,6 +4,7 @@ use hyper::server::conn::http1;
 use hyper_util::rt::TokioIo;
 use std::{net::SocketAddr, time::Duration};
 use tokio::net::TcpListener;
+use tracing_subscriber::fmt::format::FmtSpan;
 
 mod jellyfin;
 mod player;
@@ -78,6 +79,12 @@ async fn get_time_file_map(
 
 #[tokio::main]
 async fn main() -> anyhow::Result<()> {
+    let filter = std::env::var("RUST_LOG")
+        .unwrap_or_else(|_| "jellyfin_radio=debug,tracing=info,hyper=info".to_owned());
+    tracing_subscriber::fmt()
+        .with_env_filter(filter)
+        .with_span_events(FmtSpan::CLOSE)
+        .init();
     let config = Config::init_from_env().unwrap();
 
     let client =
@@ -119,7 +126,7 @@ async fn main() -> anyhow::Result<()> {
             tokio::task::yield_now().await;
             player_controller.wait_for_queue().await;
 
-            println!("Queuing song");
+            tracing::info!("Queuing song");
 
             loop {
                 let result = async {
@@ -127,9 +134,9 @@ async fn main() -> anyhow::Result<()> {
                         .random_audio(&admin_user.id, &matched_collection.id)
                         .await?;
 
-                    println!("Fetching {} - {}", item.artists.join(","), item.name);
+                    tracing::info!("Fetching {} - {}", item.artists.join(","), item.name);
                     let sound = client.fetch_audio(item).await?;
-                    println!("Fetched Song!");
+                    tracing::info!("Fetched Song!");
                     if sound.channel_count() > 2 {
                         anyhow::bail!("Too many channels, skipping!");
                     }
@@ -138,7 +145,7 @@ async fn main() -> anyhow::Result<()> {
                 }
                 .await;
                 if let Err(e) = result {
-                    println!("Error fetching new song: {}", e);
+                    tracing::error!("Error fetching new song: {}", e);
                     tokio::time::sleep(Duration::from_secs(1)).await;
                 } else {
                     break;
@@ -151,13 +158,13 @@ async fn main() -> anyhow::Result<()> {
 
     tokio::task::spawn(async move {
         if config.interstitial_path.is_none() {
-            println!("No interstitials, skipping interstitial task. Specify a folder with INTERSTITIAL_PATH.");
+            tracing::info!("No interstitials, skipping interstitial task. Specify a folder with INTERSTITIAL_PATH.");
             return;
         }
 
         let mut time_file_path = std::path::PathBuf::from(config.interstitial_path.unwrap());
         time_file_path.push("time");
-        println!("Looking for time files at {:?}", time_file_path);
+        tracing::info!("Looking for time files at {:?}", time_file_path);
 
         let time_file_map = get_time_file_map(&time_file_path).await;
         loop {
@@ -205,7 +212,7 @@ async fn main() -> anyhow::Result<()> {
                 }
                 .unwrap();
 
-                println!(
+                tracing::info!(
                     "Next Internstitial time {interstitial_time}: {:?}",
                     next_path
                 );
@@ -215,7 +222,7 @@ async fn main() -> anyhow::Result<()> {
                 )
                 .await;
 
-                println!("Playing interstitial {:?}", next_path);
+                tracing::info!("Playing interstitial {:?}", next_path);
 
                 if let Ok(sound) = awedio::sounds::open_file(next_path.as_path()) {
                     let (sound, completion_notifier) = sound.with_async_completion_notifier();
@@ -234,7 +241,7 @@ async fn main() -> anyhow::Result<()> {
                         tokio::time::sleep(fade_duration / (fade_steps_max - fade_steps_min)).await;
                     }
                 } else {
-                    println!("Error playing interstitial");
+                    tracing::error!("Error playing interstitial");
                 }
             }
         }
@@ -243,17 +250,17 @@ async fn main() -> anyhow::Result<()> {
     streamer_manager.play(Box::new(mixer));
 
     let listener = TcpListener::bind(addr).await?;
-    println!("Listening on http://{}", addr);
+    tracing::info!("Listening on http://{}", addr);
     loop {
         let (tcp, _) = listener.accept().await?;
         let io = TokioIo::new(tcp);
         let backend = streamer_backend.clone();
 
-        println!("New connection!");
+        tracing::debug!("New connection!");
 
         tokio::task::spawn(async move {
             if let Err(err) = http1::Builder::new().serve_connection(io, backend).await {
-                println!("Error serving connection: {:?}", err);
+                tracing::error!("Error serving connection: {:?}", err);
             }
         });
     }

src/player.rs

@@ -104,7 +104,7 @@ impl Sound for Player {
 
         let next_sample = next_sound.next_sample();
         if let Err(e) = &next_sample {
-            println!("Error playing track: {:?}", e);
+            tracing::error!("Error playing track: {:?}", e);
         }
 
         let ret = match next_sample {