diff --git a/Cargo.lock b/Cargo.lock index 47f3717..a07e32f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1068,6 +1068,8 @@ dependencies = [ "tokio", "tokio-tungstenite", "toml", + "tracing", + "tracing-subscriber", "urlencoding", ] @@ -1181,6 +1183,16 @@ dependencies = [ "static_assertions", ] +[[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.16" @@ -1239,6 +1251,12 @@ dependencies = [ "memchr", ] +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking_lot" version = "0.12.1" @@ -1928,6 +1946,15 @@ version = "1.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ae1a47186c03a32177042e55dbc5fd5aee900b8e0069a8d70fba96a9375cd012" +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "shell-words" version = "1.1.0" @@ -2130,6 +2157,16 @@ dependencies = [ "syn 2.0.28", ] +[[package]] +name = "thread_local" +version = "1.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3fdd6f064ccff2d6567adcb3873ca630700f00b5ad3f060c25b5dcfd9a4ce152" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "time" version = "0.2.27" @@ -2329,9 +2366,21 @@ checksum = "8ce8c33a8d48bd45d624a6e523445fd21ec13d3653cd51f681abf67418f54eb8" dependencies = [ "cfg-if", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.26" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5f4f31f56159e98206da9efd823404b79b6ef3143b4a7ab76e67b1751b25a4ab" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.28", +] + [[package]] name = "tracing-core" version = "0.1.31" @@ -2339,6 +2388,32 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0955b8137a1df6f1a2e9a37d8a6656291ff0297c1a97c24e0d8425fe2312f79a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.17" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77" +dependencies = [ + "nu-ansi-term", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", + "tracing-log", ] [[package]] @@ -2457,6 +2532,12 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "711b9620af191e0cdc7468a8d14e709c3dcdb115b36f838e601583af800a370a" +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "version_check" version = "0.9.4" diff --git a/Cargo.toml b/Cargo.toml index ab74227..aedd4df 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -78,6 +78,8 @@ urlencoding = "2.1" ### RUNTIME +tracing = "0.1" +tracing-subscriber = "0.3" mlua = { version = "0.9.0", features = ["luau", "luau-jit", "serialize"] } tokio = { version = "1.24", features = ["full"] } diff --git a/src/lune/scheduler/impl_runner.rs b/src/lune/scheduler/impl_runner.rs index 73780d9..0f4866c 100644 --- a/src/lune/scheduler/impl_runner.rs +++ b/src/lune/scheduler/impl_runner.rs @@ -4,6 +4,7 @@ use futures_util::StreamExt; use mlua::prelude::*; use tokio::task::LocalSet; +use tracing::debug; use crate::lune::util::traits::LuaEmitErrorExt; @@ -13,14 +14,14 @@ impl<'fut> Scheduler<'fut> { /** Runs all lua threads to completion. - Returns `true` if any thread was resumed, `false` otherwise. + Returns the number of threads that were resumed. */ - fn run_lua_threads(&self, lua: &Lua) -> bool { + fn run_lua_threads(&self, lua: &Lua) -> usize { if self.state.has_exit_code() { - return false; + return 0; } - let mut resumed_any = false; + let mut resumed_count = 0; // Pop threads from the scheduler until there are none left while let Some(thread) = self @@ -43,7 +44,7 @@ impl<'fut> Scheduler<'fut> { let res = thread.resume::<_, LuaMultiValue>(args); self.state.set_current_thread_id(None); - resumed_any = true; + resumed_count += 1; // If we got any resumption (lua-side) error, increment // the error count of the scheduler so we can exit with @@ -78,49 +79,55 @@ impl<'fut> Scheduler<'fut> { } } - resumed_any + resumed_count } /** Runs futures until none are left or a future spawned a new lua thread. */ - async fn run_futures_lua(&self) { + async fn run_futures_lua(&self) -> usize { let mut futs = self .futures_lua .try_lock() .expect("Failed to lock lua futures for resumption"); + let mut fut_count = 0; while futs.next().await.is_some() { + fut_count += 1; if self.has_thread() { break; } } + fut_count } /** Runs background futures until none are left or a future spawned a new lua thread. */ - async fn run_futures_background(&self) { + async fn run_futures_background(&self) -> usize { let mut futs = self .futures_background .try_lock() .expect("Failed to lock background futures for resumption"); + let mut fut_count = 0; while futs.next().await.is_some() { + fut_count += 1; if self.has_thread() { break; } } + fut_count } - async fn run_futures(&self) { + async fn run_futures(&self) -> usize { let mut rx = self.futures_break_signal.subscribe(); tokio::select! { - _ = self.run_futures_lua() => {}, - _ = self.run_futures_background() => {}, - _ = rx.recv() => {}, - }; + ran = self.run_futures_lua() => ran, + ran = self.run_futures_background() => ran, + _ = rx.recv() => 0, + } } /** @@ -140,7 +147,10 @@ impl<'fut> Scheduler<'fut> { loop { // 1. Run lua threads until exit or there are none left - self.run_lua_threads(lua); + let lua_count = self.run_lua_threads(lua); + if lua_count > 0 { + debug!("Ran {lua_count} lua threads"); + } // 2. If we got a manual exit code from lua we should // not try to wait for any pending futures to complete @@ -151,7 +161,10 @@ impl<'fut> Scheduler<'fut> { // 3. Keep resuming futures until there are no futures left to // resume, or until we manually break out of resumption for any // reason, this may be because a future spawned a new lua thread - self.run_futures().await; + let fut_count = self.run_futures().await; + if fut_count > 0 { + debug!("Ran {fut_count} futures"); + } // 4. Once again, check for an exit code, in case a future sets one if self.state.has_exit_code() { @@ -167,10 +180,13 @@ impl<'fut> Scheduler<'fut> { } if let Some(code) = self.state.exit_code() { + debug!("Scheduler ran to completion, exit code {}", code); ExitCode::from(code) } else if self.state.has_errored() { + debug!("Scheduler ran to completion, with failure"); ExitCode::FAILURE } else { + debug!("Scheduler ran to completion, with success"); ExitCode::SUCCESS } } diff --git a/src/main.rs b/src/main.rs index d5b3430..f5650d9 100644 --- a/src/main.rs +++ b/src/main.rs @@ -19,9 +19,12 @@ use console::style; #[tokio::main(flavor = "multi_thread")] async fn main() -> ExitCode { - let logger_env = env_logger::Env::default().default_filter_or("error"); - env_logger::Builder::from_env(logger_env) - .format_timestamp(None) + tracing_subscriber::fmt() + .compact() + .with_max_level(tracing::Level::DEBUG) + .with_target(true) + .with_timer(tracing_subscriber::fmt::time::uptime()) + .with_level(true) .init(); match Cli::parse().run().await { Ok(code) => code,