Implement tracing for scheduler, set to debug for now

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"

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"] }
 

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() => {},
+            ran = self.run_futures_lua() => ran,
-            _ = self.run_futures_background() => {},
+            ran = self.run_futures_background() => ran,
-            _ = rx.recv() => {},
+            _ = 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
         }
     }

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");
+    tracing_subscriber::fmt()
-    env_logger::Builder::from_env(logger_env)
+        .compact()
-        .format_timestamp(None)
+        .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,