Merge 'Add tracing_subscriber and test_log::test' from Pere Diaz Bou

I don't know when and why we dropped log::* in favor of tracing but when it was done, it made relevant logs not appear any more while debugging so... I added test_log::test which helps by automatically adding info logs from trace package (useful for printing seeds too). Closes #1097
2026-01-27 11:54:30 +01:00 · 2025-03-05 16:03:51 +01:00
parent acf0fb4425 a79b3f5746
commit c63286215e
8 changed files with 189 additions and 98 deletions
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -249,7 +249,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "531a9155a481e2ee699d4f98f43c0ca4ff8ee1bfd55c31e9e98fb29d2b176fe0"
 dependencies = [
 "memchr",
- "regex-automata",
+ "regex-automata 0.4.9",
 "serde",
 ]

@@ -496,6 +496,9 @@ dependencies = [
 "rexpect",
 "rusqlite",
 "tempfile",
+ "test-log",
+ "tracing",
+ "tracing-subscriber",
 ]

 [[package]]
@@ -1613,6 +1616,8 @@ dependencies = [
 "limbo_core",
 "miette",
 "rustyline",
+ "tracing",
+ "tracing-subscriber",
 ]

 [[package]]
@@ -1665,7 +1670,7 @@ dependencies = [
 "rand 0.8.5",
 "rand_chacha 0.9.0",
 "regex",
- "regex-syntax",
+ "regex-syntax 0.8.5",
 "rstest",
 "rusqlite",
 "rustix",
@@ -1673,6 +1678,7 @@ dependencies = [
 "serde",
 "strum",
 "tempfile",
+ "test-log",
 "thiserror 1.0.69",
 "tracing",
 ]
@@ -1764,7 +1770,7 @@ dependencies = [
 "rand 0.8.5",
 "rand_chacha 0.3.1",
 "regex",
- "regex-syntax",
+ "regex-syntax 0.8.5",
 "rusqlite",
 "serde",
 "serde_json",
@@ -1881,6 +1887,15 @@ version = "0.4.25"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "04cbf5b083de1c7e0222a7a51dbfdba1cbe1c6ab0b15e29fff3f6c077fd9cd9f"

+[[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 = "md5"
 version = "0.7.0"
@@ -2056,6 +2071,16 @@ version = "2.0.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "5e0826a989adedc2a244799e823aece04662b66609d96af8dff7ac6df9a8925d"

+[[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-format"
 version = "0.4.4"
@@ -2111,6 +2136,12 @@ dependencies = [
 "num-traits",
 ]

+[[package]]
+name = "overload"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
+
 [[package]]
 name = "owo-colors"
 version = "4.1.0"
@@ -2599,8 +2630,17 @@ checksum = "b544ef1b4eac5dc2db33ea63606ae9ffcfac26c1416a2806ae0bf5f56b201191"
 dependencies = [
 "aho-corasick",
 "memchr",
- "regex-automata",
- "regex-syntax",
+ "regex-automata 0.4.9",
+ "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]]
@@ -2611,9 +2651,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"
@@ -2855,6 +2901,15 @@ dependencies = [
 "digest",
 ]

+[[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"
@@ -3069,6 +3124,28 @@ version = "0.5.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "8f50febec83f5ee1df3015341d8bd429f2d1cc62bcba7ea2076759d315084683"

+[[package]]
+name = "test-log"
+version = "0.2.17"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "e7f46083d221181166e5b6f6b1e5f1d499f3a76888826e6cb1d057554157cd0f"
+dependencies = [
+ "env_logger 0.11.6",
+ "test-log-macros",
+ "tracing-subscriber",
+]
+
+[[package]]
+name = "test-log-macros"
+version = "0.2.17"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "888d0c3c6db53c0fdab160d2ed5e12ba745383d3e85813f2ea0f2b1475ab553f"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn 2.0.96",
+]
+
 [[package]]
 name = "textwrap"
 version = "0.16.1"
@@ -3119,6 +3196,16 @@ dependencies = [
 "syn 2.0.96",
 ]

+[[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 = "tinystr"
 version = "0.7.6"
@@ -3175,14 +3262,59 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0"
 dependencies = [
 "pin-project-lite",
+ "tracing-attributes",
 "tracing-core",
 ]

+[[package]]
+name = "tracing-attributes"
+version = "0.1.28"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "395ae124c09f9e6918a2310af6038fba074bcf474ac352496d5910dd59a2226d"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn 2.0.96",
+]
+
 [[package]]
 name = "tracing-core"
 version = "0.1.33"
 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]]
 name = "typenum"
@@ -3291,6 +3423,12 @@ dependencies = [
 "getrandom 0.2.15",
 ]

+[[package]]
+name = "valuable"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65"
+
 [[package]]
 name = "vcpkg"
 version = "0.2.15"
--- a/cli/Cargo.toml
+++ b/cli/Cargo.toml
@@ -24,12 +24,18 @@ clap = { version = "4.5", features = ["derive"] }
 comfy-table = "7.1.4"
 dirs = "5.0.1"
 env_logger = "0.10.1"
-limbo_core = { path = "../core", default-features = true, features = ["completion"]}
-rustyline = {version = "15.0.0", default-features = true, features = ["derive"]}
+limbo_core = { path = "../core", default-features = true, features = [
+    "completion",
+] }
+rustyline = { version = "15.0.0", default-features = true, features = [
+    "derive",
+] }
 ctrlc = "3.4.4"
 csv = "1.3.1"
 miette = { version = "7.4.0", features = ["fancy"] }
 cfg-if = "1.0.0"
+tracing-subscriber = { version = "0.3.19", features = ["env-filter"] }
+tracing = "0.1.41"

 [features]
 default = ["io_uring"]
--- a/cli/main.rs
+++ b/cli/main.rs
@@ -7,6 +7,7 @@ mod opcodes_dictionary;

 use rustyline::{error::ReadlineError, Config, Editor};
 use std::sync::atomic::Ordering;
+use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter};

 fn rustyline_config() -> Config {
    Config::builder()
@@ -15,8 +16,15 @@ fn rustyline_config() -> Config {
 }

 fn main() -> anyhow::Result<()> {
-    env_logger::init();
    let mut rl = Editor::with_config(rustyline_config())?;
+    tracing_subscriber::registry()
+        .with(
+            tracing_subscriber::fmt::layer()
+                .with_line_number(true)
+                .with_thread_ids(true),
+        )
+        .with(EnvFilter::from_default_env())
+        .init();
    let mut app = app::Limbo::new(&mut rl)?;
    let home = dirs::home_dir().expect("Could not determine home directory");
    let history_file = home.join(".limbo_history");
--- a/core/Cargo.toml
+++ b/core/Cargo.toml
@@ -48,7 +48,9 @@ limbo_sqlite3_parser = { workspace = true }
 thiserror = "1.0.61"
 getrandom = { version = "0.2.15" }
 regex = "1.11.1"
-regex-syntax = { version = "0.8.5", default-features = false, features = ["unicode"] }
+regex-syntax = { version = "0.8.5", default-features = false, features = [
+    "unicode",
+] }
 chrono = { version = "0.4.38", default-features = false, features = ["clock"] }
 julian_day_converter = "0.4.4"
 jsonb = { version = "0.4.4", optional = true }
@@ -69,8 +71,8 @@ limbo_completion = { workspace = true, optional = true, features = ["static"] }
 miette = "7.4.0"
 strum = "0.26"
 parking_lot = "0.12.3"
-tracing = { version = "0.1.41", default-features = false }
 crossbeam-skiplist = "0.1.3"
+tracing = "0.1.41"
 ryu = "1.0.19"

 [build-dependencies]
@@ -91,9 +93,10 @@ rusqlite = "0.33.0"
 tempfile = "3.8.0"
 quickcheck = { version = "1.0", default-features = false }
 quickcheck_macros = { version = "1.0", default-features = false }
-rand = "0.8.5"  # Required for quickcheck
+rand = "0.8.5" # Required for quickcheck
 rand_chacha = "0.9.0"
 env_logger = "0.11.6"
+test-log = { version = "0.2.17", features = ["trace"] }

 [[bench]]
 name = "benchmark"
--- a/core/storage/btree.rs
+++ b/core/storage/btree.rs
@@ -2744,6 +2744,7 @@ mod tests {
    use rand_chacha::rand_core::RngCore;
    use rand_chacha::rand_core::SeedableRng;
    use rand_chacha::ChaCha8Rng;
+    use test_log::test;

    use super::*;
    use crate::io::{Buffer, Completion, MemoryIO, OpenFlags, IO};
@@ -3242,7 +3243,6 @@ mod tests {
    }

    #[test]
-    #[ignore]
    pub fn btree_insert_fuzz_run_equal_size() {
        for size in 1..8 {
            tracing::info!("======= size:{} =======", size);
@@ -3251,25 +3251,21 @@ mod tests {
    }

    #[test]
-    #[ignore]
    pub fn btree_insert_fuzz_run_random() {
        btree_insert_fuzz_run(128, 16, |rng| (rng.next_u32() % 4096) as usize);
    }

    #[test]
-    #[ignore]
    pub fn btree_insert_fuzz_run_small() {
        btree_insert_fuzz_run(1, 1024, |rng| (rng.next_u32() % 128) as usize);
    }

    #[test]
-    #[ignore]
    pub fn btree_insert_fuzz_run_big() {
        btree_insert_fuzz_run(64, 32, |rng| 3 * 1024 + (rng.next_u32() % 1024) as usize);
    }

    #[test]
-    #[ignore]
    pub fn btree_insert_fuzz_run_overflow() {
        btree_insert_fuzz_run(64, 32, |rng| (rng.next_u32() % 32 * 1024) as usize);
    }
@@ -3570,6 +3566,7 @@ mod tests {
        let usable_space = 4096;
        let mut i = 1000;
        let seed = thread_rng().gen();
+        tracing::info!("seed {}", seed);
        let mut rng = ChaCha8Rng::seed_from_u64(seed);
        while i > 0 {
            i -= 1;
--- a/core/vdbe/mod.rs
+++ b/core/vdbe/mod.rs
@@ -73,6 +73,7 @@ use std::ffi::c_void;
 use std::num::NonZero;
 use std::rc::{Rc, Weak};
 use std::sync::{Arc, Mutex};
+use tracing::instrument;

 #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
 /// Represents a target for a jump instruction.
@@ -348,6 +349,7 @@ impl Program {
        }
    }

+    #[instrument(skip_all)]
    pub fn step(&self, state: &mut ProgramState, pager: Rc<Pager>) -> Result<StepResult> {
        loop {
            if state.is_interrupted() {
--- a/tests/Cargo.toml
+++ b/tests/Cargo.toml
@@ -25,6 +25,11 @@ assert_cmd = "^2"
 rand_chacha = "0.9.0"
 rand = "0.9.0"

+[dev-dependencies]
+test-log = { version = "0.2.17", features = ["trace"] }
+tracing-subscriber = { version = "0.3.19", features = ["env-filter"] }
+tracing = "0.1.41"
+
 # rexpect does not support windows.
 [target.'cfg(not(windows))'.dependencies]
 rexpect = "0.6.0"
--- a/tests/integration/wal/test_wal.rs
+++ b/tests/integration/wal/test_wal.rs
@@ -1,13 +1,15 @@
 use crate::common::{do_flush, TempDatabase};
 use limbo_core::{Connection, LimboError, Result, StepResult};
 use std::cell::RefCell;
-use std::ops::{Add, Deref};
 use std::rc::Rc;
-use std::sync::{Arc, Mutex};
+use tracing_subscriber::layer::SubscriberExt;
+use tracing_subscriber::util::SubscriberInitExt;
+use tracing_subscriber::EnvFilter;

 #[allow(clippy::arc_with_non_send_sync)]
 #[test]
 fn test_wal_checkpoint_result() -> Result<()> {
+    maybe_setup_tracing();
    let tmp_db = TempDatabase::new("test_wal.db");
    let conn = tmp_db.connect_limbo();
    conn.execute("CREATE TABLE t1 (id text);")?;
@@ -31,85 +33,15 @@ fn test_wal_checkpoint_result() -> Result<()> {
    Ok(())
 }

-#[test]
-#[ignore = "Multi threaded seems to not work but this tests proves the point for later fiixes"]
-fn test_wal_1_writer_1_reader() -> Result<()> {
-    let tmp_db = Arc::new(Mutex::new(TempDatabase::new("test_wal.db")));
-    let db = tmp_db.lock().unwrap().limbo_database();
-
-    {
-        let conn = db.connect().unwrap();
-        match conn.query("CREATE TABLE t (id)")? {
-            Some(ref mut rows) => loop {
-                match rows.step().unwrap() {
-                    StepResult::Row => {}
-                    StepResult::IO => {
-                        tmp_db.lock().unwrap().io.run_once().unwrap();
-                    }
-                    StepResult::Interrupt => break,
-                    StepResult::Done => break,
-                    StepResult::Busy => unreachable!(),
-                }
-            },
-            None => todo!(),
-        }
-        do_flush(&conn, tmp_db.lock().unwrap().deref()).unwrap();
-    }
-    let rows = Arc::new(std::sync::Mutex::new(0));
-    let rows_ = rows.clone();
-    const ROWS_WRITE: usize = 1000;
-    let tmp_db_w = db.clone();
-    let writer_thread = std::thread::spawn(move || {
-        let conn = tmp_db_w.connect().unwrap();
-        for i in 0..ROWS_WRITE {
-            println!("adding {}", i);
-            conn.execute(format!("INSERT INTO t values({})", i).as_str())
-                .unwrap();
-            let _ = rows_.lock().unwrap().add(1);
-        }
-    });
-    let rows_ = rows.clone();
-    let reader_thread = std::thread::spawn(move || {
-        let conn = db.connect().unwrap();
-        loop {
-            let rows = *rows_.lock().unwrap();
-            let mut i = 0;
-            // println!("reading {}", rows);
-            match conn.query("SELECT * FROM t") {
-                Ok(Some(ref mut rows)) => loop {
-                    match rows.step().unwrap() {
-                        StepResult::Row => {
-                            let row = rows.row().unwrap();
-                            let first_value = row.get_value(0);
-                            let id = match first_value {
-                                limbo_core::OwnedValue::Integer(i) => *i as i32,
-                                _ => unreachable!(),
-                            };
-                            assert_eq!(id, i);
-                            i += 1;
-                        }
-                        StepResult::IO => {
-                            tmp_db.lock().unwrap().io.run_once().unwrap();
-                        }
-                        StepResult::Interrupt => break,
-                        StepResult::Done => break,
-                        StepResult::Busy => unreachable!(),
-                    }
-                },
-                Ok(None) => {}
-                Err(err) => {
-                    eprintln!("{}", err);
-                }
-            }
-            if rows == ROWS_WRITE {
-                break;
-            }
-        }
-    });
-
-    writer_thread.join().unwrap();
-    reader_thread.join().unwrap();
-    Ok(())
+fn maybe_setup_tracing() {
+    let _ = tracing_subscriber::registry()
+        .with(
+            tracing_subscriber::fmt::layer()
+                .with_line_number(true)
+                .with_thread_ids(true),
+        )
+        .with(EnvFilter::from_default_env())
+        .try_init();
 }

 /// Execute a statement and get strings result