fix(nescope): default log filter to info when RUST_LOG is unset (#441)

nescope used `EnvFilter::from_default_env()`, whose default is ERROR, so
its info/warn lines never reached the host journal. nesinit only
forwards RUST_LOG if it has it itself.

- nescope: fall back to `info` when RUST_LOG is unset or unparsable
(same as neshub, nesinit, nesgamepad); debug stays opt-in. 4 unit tests
on the filter helper.
- neswire: same ERROR default, same fix.
- Not changed: nescapture (library inside the game process, env_logger).

Tested on nestripc-1: `cargo test -p nescope log_filter` 4 passed,
`cargo check -p neswire` ok.
Note: no 'configure_request clamped' warn exists on this base; once it
lands at warn level it is covered by the info default.
This commit is contained in:
Wanjohi
2026-10-18 12:53:26 +00:00
committed by GitHub
3 changed files with 57 additions and 4 deletions
+48 -2
View File
@@ -30,7 +30,7 @@
//! | `PROTON_ENABLE_WAYLAND` | Set to `1` always, so Proton renders through Wayland | //! | `PROTON_ENABLE_WAYLAND` | Set to `1` always, so Proton renders through Wayland |
//! | `XCURSOR_THEME` | XCursor theme name for the software cursor | //! | `XCURSOR_THEME` | XCursor theme name for the software cursor |
//! | `XCURSOR_SIZE` | XCursor size in pixels | //! | `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 //! # Ctrl+C / shutdown
//! //!
@@ -193,9 +193,20 @@ struct Args {
// Entry point // 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() { fn main() {
tracing_subscriber::fmt() 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(); .init();
let args = Args::parse(); 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)
);
}
}
+1 -1
View File
@@ -28,7 +28,7 @@ struct Args {
fn main() -> anyhow::Result<()> { fn main() -> anyhow::Result<()> {
tracing_subscriber::fmt() 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(); .init();
let args = Args::parse(); let args = Args::parse();
+8 -1
View File
@@ -83,6 +83,9 @@ pub fn run(sample_rate: u32, channels: u32, frame_size: u32, tx: Sender<Packet>)
/// Where the accumulator ends when the graph gives no position: a count /// Where the accumulator ends when the graph gives no position: a count
/// of the frames received, so packets still carry a continuous timeline. /// of the frames received, so packets still carry a continuous timeline.
counted_end: u64, 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 { let state = State {
@@ -93,6 +96,7 @@ pub fn run(sample_rate: u32, channels: u32, frame_size: u32, tx: Sender<Packet>)
sample_rate, sample_rate,
next_ticks: None, next_ticks: None,
counted_end: 0, counted_end: 0,
dropped: 0,
}; };
let _listener = stream let _listener = stream
@@ -174,7 +178,10 @@ pub fn run(sample_rate: u32, channels: u32, frame_size: u32, tx: Sender<Packet>)
}; };
if state.tx.try_send(packet).is_err() { 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");
}
} }
} }
} }