diff --git a/apps/nescope/src/main.rs b/apps/nescope/src/main.rs index eef9469f..ea72abe0 100644 --- a/apps/nescope/src/main.rs +++ b/apps/nescope/src/main.rs @@ -30,7 +30,7 @@ //! | `PROTON_ENABLE_WAYLAND` | Set to `1` always, so Proton renders through Wayland | //! | `XCURSOR_THEME` | XCursor theme name for the software cursor | //! | `XCURSOR_SIZE` | XCursor size in pixels | -//! | `RUST_LOG` | Tracing filter (e.g. `nescope=debug`) | +//! | `RUST_LOG` | Tracing filter, default `info` (e.g. `nescope=debug`) | //! //! # Ctrl+C / shutdown //! @@ -193,9 +193,20 @@ struct Args { // Entry point // --------------------------------------------------------------------------- +/// Filter from `RUST_LOG`, or `info` when it is unset or unparsable. +/// +/// `EnvFilter::from_default_env` alone defaults to ERROR, which hid every +/// info/warn line from the host journal (nesinit only forwards `RUST_LOG` if +/// it has it itself). Same fallback as neshub, nesinit and nesgamepad. +fn log_filter(rust_log: Option<&str>) -> tracing_subscriber::EnvFilter { + rust_log + .and_then(|v| tracing_subscriber::EnvFilter::try_new(v).ok()) + .unwrap_or_else(|| "info".into()) +} + fn main() { tracing_subscriber::fmt() - .with_env_filter(tracing_subscriber::EnvFilter::from_default_env()) + .with_env_filter(log_filter(std::env::var("RUST_LOG").ok().as_deref())) .init(); let args = Args::parse(); @@ -857,3 +868,38 @@ fn kill_all_children_sigkill() { } } } + +#[cfg(test)] +mod log_filter_tests { + use super::log_filter; + use tracing::Level; + use tracing_subscriber::filter::LevelFilter; + + #[test] + fn unset_defaults_to_info_so_warn_is_visible() { + let f = log_filter(None); + assert_eq!(f.max_level_hint(), Some(LevelFilter::INFO)); + assert!(Level::WARN <= Level::INFO); + } + + #[test] + fn debug_stays_out_of_the_default() { + assert_ne!(log_filter(None).max_level_hint(), Some(LevelFilter::DEBUG)); + } + + #[test] + fn explicit_rust_log_wins() { + assert_eq!( + log_filter(Some("debug")).max_level_hint(), + Some(LevelFilter::DEBUG) + ); + } + + #[test] + fn garbage_falls_back_to_info() { + assert_eq!( + log_filter(Some("=== not a filter ===")).max_level_hint(), + Some(LevelFilter::INFO) + ); + } +} diff --git a/apps/neswire/src/main.rs b/apps/neswire/src/main.rs index 86699804..6cd1022c 100644 --- a/apps/neswire/src/main.rs +++ b/apps/neswire/src/main.rs @@ -28,7 +28,7 @@ struct Args { fn main() -> anyhow::Result<()> { tracing_subscriber::fmt() - .with_env_filter(tracing_subscriber::EnvFilter::from_default_env()) + .with_env_filter(tracing_subscriber::EnvFilter::try_from_default_env().unwrap_or_else(|_| "info".into())) .init(); let args = Args::parse(); diff --git a/apps/neswire/src/sink.rs b/apps/neswire/src/sink.rs index e9cd1b9c..69483110 100644 --- a/apps/neswire/src/sink.rs +++ b/apps/neswire/src/sink.rs @@ -83,6 +83,9 @@ pub fn run(sample_rate: u32, channels: u32, frame_size: u32, tx: Sender) /// Where the accumulator ends when the graph gives no position: a count /// of the frames received, so packets still carry a continuous timeline. counted_end: u64, + /// Frames dropped because the encoder was behind. A stalled encoder + /// drops ~50 a second, so only the first and every 250th are logged. + dropped: u64, } let state = State { @@ -93,6 +96,7 @@ pub fn run(sample_rate: u32, channels: u32, frame_size: u32, tx: Sender) sample_rate, next_ticks: None, counted_end: 0, + dropped: 0, }; let _listener = stream @@ -174,7 +178,10 @@ pub fn run(sample_rate: u32, channels: u32, frame_size: u32, tx: Sender) }; if state.tx.try_send(packet).is_err() { - tracing::warn!("encoder falling behind, dropping frame"); + state.dropped += 1; + if state.dropped % 250 == 1 { + tracing::warn!(dropped = state.dropped, "encoder falling behind, dropping frames"); + } } } }