Use logging

Cargo.lock

@@ -1755,6 +1755,12 @@ version = "3.1.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "e2db585e1d738fc771bf08a151420d3ed193d9d895a36df7f6f8a9456b911ddc"
 
+[[package]]
+name = "lazy_static"
+version = "1.5.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe"
+
 [[package]]
 name = "lemur"
 version = "0.2.7"
@@ -1788,6 +1794,8 @@ dependencies = [
  "serde_json",
  "thread-priority",
  "tokio",
+ "tracing",
+ "tracing-subscriber",
  "wgpu",
  "windows 0.58.0",
  "winit",
@@ -1883,6 +1891,15 @@ dependencies = [
  "libc",
 ]
 
+[[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.4"
@@ -2068,6 +2085,16 @@ dependencies = [
  "minimal-lexical",
 ]
 
+[[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-complex"
 version = "0.4.6"
@@ -2408,6 +2435,12 @@ dependencies = [
  "pin-project-lite",
 ]
 
+[[package]]
+name = "overload"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
+
 [[package]]
 name = "owned_ttf_parser"
 version = "0.25.0"
@@ -2701,8 +2734,17 @@ checksum = "b544ef1b4eac5dc2db33ea63606ae9ffcfac26c1416a2806ae0bf5f56b201191"
 dependencies = [
  "aho-corasick",
  "memchr",
- "regex-automata",
+ "regex-automata 0.4.9",
- "regex-syntax",
+ "regex-syntax 0.8.5",
+]
+
+[[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]]
@@ -2713,9 +2755,15 @@ checksum = "809e8dc61f6de73b46c85f4c96486310fe304c434cfa43669d7b40f711150908"
 dependencies = [
  "aho-corasick",
  "memchr",
- "regex-syntax",
+ "regex-syntax 0.8.5",
 ]
 
+[[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.5"
@@ -2906,6 +2954,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 = "shlex"
 version = "1.3.0"
@@ -3123,6 +3180,16 @@ dependencies = [
  "winapi",
 ]
 
+[[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 = "tiny-skia"
 version = "0.11.4"
@@ -3248,6 +3315,36 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "e672c95779cf947c5311f83787af4fa8fffd12fb27e4993211a84bdfd9610f9c"
 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.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "e8189decb5ac0fa7bc8b96b7cb9b2701d60d48805aca84a238004d665fcc4008"
+dependencies = [
+ "matchers",
+ "nu-ansi-term",
+ "once_cell",
+ "regex",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing",
+ "tracing-core",
+ "tracing-log",
 ]
 
 [[package]]
@@ -3358,6 +3455,12 @@ version = "1.11.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "f8c5f0a0af699448548ad1a2fbf920fb4bee257eae39953ba95cb84891a0446a"
 
+[[package]]
+name = "valuable"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
+
 [[package]]
 name = "vec_map"
 version = "0.8.2"

Cargo.toml

@@ -36,6 +36,8 @@ serde = { version = "1", features = ["derive"] }
 serde_json = "1"
 thread-priority = "1"
 tokio = { version = "1", features = ["io-util", "macros", "net", "rt", "sync"] }
+tracing = { version = "0.1", features = ["release_max_level_info"] }
+tracing-subscriber = { version = "0.3", features = ["env-filter"] }
 wgpu = "23"
 winit = { version = "0.30", features = ["serde"] }
 

src/app.rs

@@ -6,6 +6,7 @@ use egui::{
     ViewportCommand, ViewportId, ViewportInfo,
 };
 use gilrs::{EventType, Gilrs};
+use tracing::{error, warn};
 use winit::{
     application::ApplicationHandler,
     event::WindowEvent,
@@ -230,8 +231,8 @@ impl ApplicationHandler<UserEvent> for Application {
     fn exiting(&mut self, _event_loop: &ActiveEventLoop) {
         let (sender, receiver) = oneshot::channel();
         if self.client.send_command(EmulatorCommand::Exit(sender)) {
-            if let Err(err) = receiver.recv_timeout(Duration::from_secs(5)) {
+            if let Err(error) = receiver.recv_timeout(Duration::from_secs(5)) {
-                eprintln!("could not gracefully exit: {}", err);
+                error!(%error, "could not gracefully exit.");
             }
         }
     }
@@ -434,9 +435,12 @@ fn create_window_and_state(
 }
 
 fn process_gamepad_input(mappings: MappingProvider, proxy: EventLoopProxy<UserEvent>) {
-    let Ok(mut gilrs) = Gilrs::new() else {
+    let mut gilrs = match Gilrs::new() {
-        eprintln!("could not connect gamepad listener");
+        Ok(gilrs) => gilrs,
+        Err(error) => {
+            warn!(%error, "could not connect gamepad listener");
             return;
+        }
     };
     while let Some(event) = gilrs.next_event_blocking(None) {
         if event.event == EventType::Connected {

src/audio.rs

@@ -4,6 +4,7 @@ use anyhow::{bail, Result};
 use cpal::traits::{DeviceTrait, HostTrait, StreamTrait};
 use itertools::Itertools;
 use rubato::{FftFixedInOut, Resampler};
+use tracing::error;
 
 pub struct Audio {
     #[allow(unused)]
@@ -54,7 +55,7 @@ impl Audio {
                 }
                 chunk.commit_all();
             },
-            move |err| eprintln!("stream error: {err}"),
+            move |error| error!(%error, "stream error"),
             None,
         )?;
         stream.play()?;

src/emulator.rs

@@ -15,6 +15,7 @@ use anyhow::Result;
 use atomic::Atomic;
 use bytemuck::NoUninit;
 use egui_toast::{Toast, ToastKind, ToastOptions};
+use tracing::{error, warn};
 
 use crate::{audio::Audio, graphics::TextureSink};
 use shrooms_vb_core::{Sim, StopReason, EXPECTED_FRAME_SIZE};
@@ -608,7 +609,7 @@ impl Emulator {
                 return;
             }
         }
-        eprintln!("{}", message);
+        error!("{}", message);
     }
 }
 
@@ -704,7 +705,7 @@ impl EmulatorClient {
         match self.queue.send(command) {
             Ok(()) => true,
             Err(err) => {
-                eprintln!(
+                warn!(
                     "could not send command {:?} as emulator is shut down",
                     err.0
                 );

src/gdbserver.rs

@@ -12,6 +12,7 @@ use tokio::{
     select,
     sync::{mpsc, oneshot},
 };
+use tracing::{debug, enabled, error, info, Level};
 
 use crate::emulator::{
     DebugEvent, DebugStopReason, EmulatorClient, EmulatorCommand, SimId, VBWatchpointType,
@@ -78,15 +79,19 @@ async fn run_server(
     port: u16,
     status: &Mutex<GdbServerStatus>,
 ) {
+    info!("Connecting to debugger on port {port}...");
     let Some(stream) = try_connect(port, status).await else {
         return;
     };
+    info!("Connected!");
     let mut connection = GdbConnection::new(sim_id, client);
     match connection.run(stream).await {
         Ok(()) => {
+            info!("Finished debugging.");
             *status.lock().unwrap() = GdbServerStatus::Stopped;
         }
         Err(error) => {
+            error!(%error, "Error from debugger.");
             *status.lock().unwrap() = GdbServerStatus::Error(error.to_string());
         }
     }
@@ -97,6 +102,7 @@ async fn try_connect(port: u16, status: &Mutex<GdbServerStatus>) -> Option<TcpSt
     let listener = match TcpListener::bind(("127.0.0.1", port)).await {
         Ok(l) => l,
         Err(err) => {
+            error!(%err, "Could not open port.");
             *status.lock().unwrap() = GdbServerStatus::Error(err.to_string());
             return None;
         }
@@ -107,6 +113,7 @@ async fn try_connect(port: u16, status: &Mutex<GdbServerStatus>) -> Option<TcpSt
             Some(stream)
         }
         Err(err) => {
+            error!(%err, "Could not connect to debugger.");
             *status.lock().unwrap() = GdbServerStatus::Error(err.to_string());
             None
         }
@@ -169,9 +176,11 @@ impl GdbConnection {
             };
             if let Some(res) = response {
                 let buffer = res.finish();
+                if enabled!(Level::DEBUG) {
                     match std::str::from_utf8(&buffer) {
-                    Ok(text) => println!("response: {text}"),
+                        Ok(text) => debug!("response: {text}"),
-                    Err(_) => println!("response: {buffer:02x?}"),
+                        Err(_) => debug!("response: {buffer:02x?}"),
+                    }
                 }
                 tx.write_all(&buffer).await?;
                 self.response_buf = Some(buffer);
@@ -196,7 +205,7 @@ impl GdbConnection {
     }
 
     fn handle_request(&mut self, mut req: Request<'_>) -> Result<Option<Response>> {
-        println!("received {:02x?}", req);
+        debug!("received {:02x?}", req);
 
         if req.kind == RequestKind::Signal {
             self.client

src/main.rs

@@ -8,6 +8,8 @@ use app::Application;
 use clap::Parser;
 use emulator::EmulatorBuilder;
 use thread_priority::{ThreadBuilder, ThreadPriority};
+use tracing::error;
+use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, Layer};
 use winit::event_loop::{ControlFlow, EventLoop};
 
 mod app;
@@ -29,6 +31,13 @@ struct Args {
     debug_port: Option<u16>,
 }
 
+fn init_logger() {
+    let directives = std::env::var("RUST_LOG").unwrap_or("error,lemur=info".into());
+    let filter = EnvFilter::builder().parse_lossy(directives);
+    let layer = tracing_subscriber::fmt::layer().with_filter(filter);
+    tracing_subscriber::registry().with(layer).init();
+}
+
 fn set_panic_handler() {
     std::panic::set_hook(Box::new(|info| {
         let mut message = String::new();
@@ -76,6 +85,8 @@ fn set_process_priority_to_high() -> Result<()> {
 }
 
 fn main() -> Result<()> {
+    init_logger();
+
     set_panic_handler();
 
     #[cfg(windows)]
@@ -97,8 +108,8 @@ fn main() -> Result<()> {
         .spawn_careless(move || {
             let mut emulator = match builder.build() {
                 Ok(e) => e,
-                Err(err) => {
+                Err(error) => {
-                    eprintln!("Error initializing emulator: {err}");
+                    error!(%error, "Error initializing emulator");
                     process::exit(1);
                 }
             };