search

spacejam / sled

the champagne of beta embedded databases
Apache License 2.0
8.19k stars 384 forks source link

sled seems to have a bug in initialization when simplelog is used #1384

Open iesahin opened 3 years ago

iesahin commented 3 years ago

Expected

I have a code that starts up sled in a function, like

        let db = sled::Config::new()
            .path(path)
            .use_compression(false)
            .mode(sled::Mode::HighThroughput)
            .open()
            .expect("Error opening Key Value store");

        watch!(db);

I tried several different options but it stops at the watch! line. watch! is a self made macro that runs log::trace! with the variable name.

Actual result

I have a test function like the following.

pub fn test_xvc_kvstore() {
    use common::keyvaluestore::XvcKeyValueStore;
    use common::xvcfile::XvcFileMetadata;
    setup::logging(LevelFilter::Trace);
    let the_dir = run_in_temp_xvc_dir();
    let kvs_path = PathBuf::from("kvstore");
    let xvc_root = XvcRoot::new(&the_dir).unwrap();
    let kv_store = XvcKeyValueStore::from_root(&xvc_root);
    // assert!(kvs_path.exists());
    // assert!(the_dir.join(kvs_path).exists());
    let filename = Path::new("file1.bin");
    generate_random_file(&filename, &100000);
    let mut count0 = 0;
    for kv1 in kv_store.iter() {
        count0 += 1;
    }
    assert!(count0 == 0);

The trace stops at the watch! line above. 

18:05:37 [TRACE] (5) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:900] expected stabilization lsn -524288 to be greater than the previous value of -1
18:05:37 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1595] getting page iter for META
18:05:37 [TRACE] (2) xvc::common::keyvaluestore: [src/common/keyvaluestore.rs:28] db: Db {
    Tree: "__sled__default" contents: Tree: 
        PageCache { max: 4 free: Mutex { data: [] } }
        level 0:
test test_xvc_kvstore has been running for over 60 seconds

When I comment out the line

setup::logging(LevelFilter::Trace);

the test runs as normally.

That line calls a log initialization code as the following:


use simplelog::*;
use std::sync::Once;
use log::trace;

static INIT: Once = Once::new();

pub fn setup_logging(term_level: Option<LevelFilter>, file_level: Option<LevelFilter>) {
    INIT.call_once(|| init_logging(term_level, file_level));
}

fn init_logging(term_level: Option<LevelFilter>, file_level: Option<LevelFilter>) {
    let mut loggers: Vec<Box<dyn SharedLogger>> = Vec::new();

    match term_level {
        Some(level) => loggers.push(TermLogger::new(
            level,
            Config::default(),
            TerminalMode::Mixed,
            ColorChoice::Auto,
        )),
        None => {}
    };

    match file_level {
        Some(level) => {
            let logfile = format!(
                "/tmp/xvc-{}.log",
                time::SystemTime::now()
                    .duration_since(time::UNIX_EPOCH)
                    .expect("Wow!")
                    .as_secs()
            );

            println!("LOG FILE: {}", logfile);
            loggers.push(WriteLogger::new(
                level,
                Config::default(),
                File::create(logfile).unwrap(),
            ));
        }
        None => {}
    }

    match CombinedLogger::init(loggers) {
        Ok(()) => println!("Logger enabled."),
        Err(err) => panic!("{:?}", err),
    }
}

sled version

sled  = "^0.34"
simplelog = "^0.10.0"

From the logs, it looks sled is at 0.34.7

rustc version

rustc --version
rustc 1.55.0 (c8dfcfe04 2021-09-06)

operating system

Ubuntu 20.04 on WSL 2 on Windows 11

Adding a main function to the above should be enough to reproduce.


use sled;

fn main() {
   setup_logging(LevelFilter::Trace, LevelFilter::Trace);
   let db = sled::open("/tmp/mydb").expect("Error opening Key Value store");

   trace!("DB: {:?}", db);
}

logs, panic messages, stack traces

The whole trace (that includes my trace) before freeze is this: 

running 1 test
LOG FILE: /tmp/xvc-1634495037.log
Logger enabled.
18:23:57 [TRACE] (2) test_common::setup: [tests/setup.rs:59] temp_dir: "/tmp/2596589676"
18:23:57 [TRACE] (2) test_common::setup: [tests/setup.rs:49] temp_dir: "/tmp/2596589676"
18:23:57 [TRACE] (2) test_common::setup: [tests/setup.rs:65] temp_dir: "/tmp/2596589676"
18:23:57 [TRACE] (2) test_common::setup: [tests/setup.rs:81] the_dir: "/tmp/2596589676"
18:23:57 [TRACE] (2) test_common::setup: [tests/setup.rs:83] init_config: InitConfig { path: XvcConfigOption { source: CommandLine, option: "/tmp/2596589676" }, no_git: XvcConfigOption { source: CommandLine, option: Some(false) }, force: XvcConfigOption { source: CommandLine, option: Some(false) }, subdir: XvcConfigOption { source: CommandLine, option: Some(false) } }
18:23:57 [TRACE] (2) test_common::setup: [tests/setup.rs:85] xvc_config: XvcConfig { current_dir: XvcConfigOption { source: Default, option: "." }, xvc_root: XvcConfigOption { source: Default, option: None }, local_cache_dir: XvcConfigOption { source: Default, option: None }, current_command: XvcConfigOption { source: Default, option: None }, verbosity: XvcConfigOption { source: Default, option: Default }, cache_type: XvcConfigOption { source: Default, option: Copy }, add_recursive_always: XvcConfigOption { source: Default, option: false }, add_commit_always: XvcConfigOption { source: Default, option: true }, xvcignore: XvcConfigOption { source: Default, option: None }, use_git: XvcConfigOption { source: Default, option: true } }
18:23:57 [TRACE] (2) xvc::init: [src/init/mod.rs:130] the_root: None
18:23:57 [TRACE] (2) xvc::init: [src/init/mod.rs:154] path: "/tmp/2596589676"
18:23:57 [TRACE] (2) xvc::init: [src/init/mod.rs:154] no_git: false
18:23:57 [TRACE] (2) xvc::init: [src/init/mod.rs:154] subdir: false
18:23:57 [TRACE] (2) xvc::init: [src/init/mod.rs:157] canonic: "/tmp/2596589676"
18:23:57 [TRACE] (2) xvc::init: [src/init/mod.rs:160] git_res: Some("/tmp/2596589676")
18:23:57 [TRACE] (2) xvc::init: [src/init/mod.rs:106] path: "/tmp/2596589676"
18:23:57 [TRACE] (2) xvc::init: [src/init/mod.rs:108] no_scm: false
18:23:57 [TRACE] (2) xvc::init: [src/init/mod.rs:110] xvc_dir: "/tmp/2596589676/.dvc"
18:23:57 [TRACE] (2) xvc::common: [src/common/mod.rs:79] "/tmp/2596589676"
18:23:57 [TRACE] (2) xvc::common: [src/common/mod.rs:84] pb: "/tmp/2596589676"
18:23:57 [TRACE] (2) xvc::common: [src/common/mod.rs:86] Found XVC DIR: "/tmp/2596589676"
18:23:57 [TRACE] (2) xvc::common: [src/common/mod.rs:58] xvc_dir: "/tmp/2596589676/.dvc"
18:23:57 [TRACE] (2) xvc::common: [src/common/mod.rs:60] kv_path: "/tmp/2596589676/.dvc/xvcstore"
18:23:57 [TRACE] (2) xvc::common: [src/common/mod.rs:67] xvc_root: XvcRoot { absolute_path: "/tmp/2596589676", local_cache_dir: "/tmp/2596589676/.dvc/cache", xvc_dir: "/tmp/2596589676/.dvc", kv_store_path: "/tmp/2596589676/.dvc/xvcstore" }
18:23:57 [TRACE] (2) sled::context: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/context.rs:42] starting context
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:581] starting pagecache
18:23:57 [DEBUG] (2) sled::pagecache::snapshot: no previous snapshot found
18:23:57 [TRACE] (2) sled::pagecache::iterator: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/iterator.rs:329] file len: 0 segment len 524288 segments: 0
18:23:57 [DEBUG] (2) sled::pagecache::iterator: ordering before clearing tears: {}, max_header_stable_lsn: 0
18:23:57 [DEBUG] (2) sled::pagecache::iterator: in clean_tail_tears, found missing item in tail: None and we'll scan segments {} above lowest lsn 0
18:23:57 [DEBUG] (2) sled::pagecache::iterator: unable to load new segment: Io(Custom { kind: Other, error: "no segments remaining to iterate over" })
18:23:57 [DEBUG] (2) sled::pagecache::iterator: filtering out segments after detected tear at (lsn, lid) -1
18:23:57 [TRACE] (2) sled::pagecache::iterator: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/iterator.rs:488] trying to find the max stable tip for bounding batch manifests with segment iter {} of segments >= first_tip -1
18:23:57 [TRACE] (2) sled::pagecache::iterator: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/iterator.rs:496] generated iterator over segments {} with lsn >= 0
18:23:57 [TRACE] (2) sled::pagecache::snapshot: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/snapshot.rs:218] building on top of old snapshot: Snapshot { stable_lsn: None, active_segment: None, pt: [] }
18:23:57 [DEBUG] (2) sled::pagecache::iterator: unable to load new segment: Io(Custom { kind: Other, error: "no segments remaining to iterate over" })
18:23:57 [TRACE] (2) sled::pagecache::snapshot: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/snapshot.rs:274] db is empty, returning default snapshot
18:23:57 [TRACE] (2) sled::pagecache::snapshot: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/snapshot.rs:357] generated snapshot: Snapshot { stable_lsn: None, active_segment: None, pt: [] }
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:655] initialized self.segments to []
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:670] initialized self.ordering to {}
18:23:57 [DEBUG] (2) sled::pagecache::segment: SA starting with tip 0 stable -1 free {}
18:23:57 [DEBUG] (2) sled::pagecache::iobuf: starting log for a totally fresh system
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:1013] evaluating free list {} in SA::next
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:998] advancing file tip from 0 to 524288
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:238] setting Segment to Active with new lsn 0
18:23:57 [DEBUG] (2) sled::pagecache::segment: segment accountant returning offset: 0 for lsn 0 on deck: {}
18:23:57 [DEBUG] (2) sled::pagecache::iobuf: starting IoBufs with next_lsn: 0 next_lid: 0
18:23:57 [DEBUG] (2) sled::pagecache::iobuf: storing lsn 0 in beginning of buffer
18:23:57 [DEBUG] (2) sled::pagecache: load_snapshot loading pages from 0..0
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1595] getting page iter for META
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:821] allocating pid 0 for the first time
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1456] cas_page called on pid 0 to Meta(Meta { inner: {} }) with old ts 0
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1464] cas_page on pid 0 has log kind: Replace
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:277] reserving buf of len 8
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:349] reserved 8 bytes at lsn 20 lid 20
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1530] cas_page succeeded on pid 0
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:807] mark_link pid 0 at cache info CacheInfo { ts: 1, lsn: 20, pointer: Inline(20), log_size: 8 }
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:752] mark_replace pid 0 from cache infos [] to cache info CacheInfo { ts: 1, lsn: 20, pointer: Inline(20), log_size: 8 } with lsn 0
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1549] accessed pid 0 -> paging out pids []
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1624] getting page iter for idgen
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:821] allocating pid 1 for the first time
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1456] cas_page called on pid 1 to Counter(0) with old ts 0
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1464] cas_page on pid 1 has log kind: Replace
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:277] reserving buf of len 9
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:349] reserved 9 bytes at lsn 28 lid 28
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1530] cas_page succeeded on pid 1
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:807] mark_link pid 1 at cache info CacheInfo { ts: 1, lsn: 28, pointer: Inline(28), log_size: 9 }
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:752] mark_replace pid 1 from cache infos [] to cache info CacheInfo { ts: 1, lsn: 28, pointer: Inline(28), log_size: 9 } with lsn 0
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1549] accessed pid 1 -> paging out pids []
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1624] getting page iter for idgen
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:754] pagecache started
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1595] getting page iter for META
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:821] allocating pid 2 for the first time
18:23:57 [TRACE] (3) sled::pagecache::iobuf: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/iobuf.rs:866] sealing ioubuf from  roll_iobuf
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1456] cas_page called on pid 2 to Node(Node { prefix_len: 0, next: None, merging_child: None, merging: false, lo: [], hi: [], data: Leaf(Leaf { keys: [], values: [] }) }) with old ts 0
18:23:57 [TRACE] (3) sled::pagecache::iobuf: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/iobuf.rs:1057] sealed iobuf with lsn 0
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1464] cas_page on pid 2 has log kind: Replace
18:23:57 [DEBUG] (3) sled::pagecache::iobuf: advancing offset within the current segment from 0 to 37
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:239] io buffer already sealed, spinning
18:23:57 [TRACE] (3) sled::pagecache::iobuf: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/iobuf.rs:1177] asynchronously writing iobuf with lsn 0 to log from maybe_seal
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:277] reserving buf of len 16
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:349] reserved 16 bytes at lsn 37 lid 37
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1530] cas_page succeeded on pid 2
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:807] mark_link pid 2 at cache info CacheInfo { ts: 1, lsn: 37, pointer: Inline(37), log_size: 16 }
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:752] mark_replace pid 2 from cache infos [] to cache info CacheInfo { ts: 1, lsn: 37, pointer: Inline(37), log_size: 16 } with lsn 0
18:23:57 [TRACE] (6) sled::pagecache::iobuf: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/iobuf.rs:593] write_to_log log_offset 0 lsn 0 len 37
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1549] accessed pid 2 -> paging out pids []
18:23:57 [TRACE] (2) sled::meta: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/meta.rs:78] allocated pid 2 for leaf in new_tree for namespace [95, 95, 115, 108, 101, 100, 95, 95, 100, 101, 102, 97, 117, 108, 116]
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:821] allocating pid 3 for the first time
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1456] cas_page called on pid 3 to Node(Node { prefix_len: 0, next: None, merging_child: None, merging: false, lo: [], hi: [], data: Index(Index { keys: [[]], pointers: [2] }) }) with old ts 0
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1464] cas_page on pid 3 has log kind: Replace
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:277] reserving buf of len 18
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:349] reserved 18 bytes at lsn 53 lid 53
18:23:57 [DEBUG] (6) sled::pagecache::iobuf: wrote lsns 0-36 to disk at offsets 0-36, maxed false complete_len 37
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1530] cas_page succeeded on pid 3
18:23:57 [DEBUG] (6) sled::pagecache::iobuf: mark_interval(0, 37)
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:807] mark_link pid 3 at cache info CacheInfo { ts: 1, lsn: 53, pointer: Inline(53), log_size: 18 }
18:23:57 [TRACE] (6) sled::pagecache::iobuf: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/iobuf.rs:196] pushing interval (0, 36) into fsynced_ranges []
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:752] mark_replace pid 3 from cache infos [] to cache info CacheInfo { ts: 1, lsn: 53, pointer: Inline(53), log_size: 18 } with lsn 0
18:23:57 [DEBUG] (6) sled::pagecache::iobuf: new highest interval: 0 - 36
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1549] accessed pid 3 -> paging out pids []
18:23:57 [TRACE] (6) sled::pagecache::iobuf: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/iobuf.rs:824] mark_interval new highest lsn 36
18:23:57 [DEBUG] (2) sled::meta: allocated pid 3 for root of new_tree [95, 95, 115, 108, 101, 100, 95, 95, 100, 101, 102, 97, 117, 108, 116]
18:23:57 [TRACE] (6) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:893] stabilize(0), normalized: -524288, last: -1
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1595] getting page iter for META
18:23:57 [TRACE] (6) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:900] expected stabilization lsn -524288 to be greater than the previous value of -1
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1456] cas_page called on pid 0 to Meta(Meta { inner: {[95, 95, 115, 108, 101, 100, 95, 95, 100, 101, 102, 97, 117, 108, 116]: 3} }) with old ts 1
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1464] cas_page on pid 0 has log kind: Replace
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:277] reserving buf of len 25
18:23:57 [TRACE] (2) sled::pagecache::logger: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/logger.rs:349] reserved 25 bytes at lsn 71 lid 71
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1530] cas_page succeeded on pid 0
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:807] mark_link pid 0 at cache info CacheInfo { ts: 2, lsn: 71, pointer: Inline(71), log_size: 25 }
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:752] mark_replace pid 0 from cache infos [CacheInfo { ts: 1, lsn: 20, pointer: Inline(20), log_size: 8 }] to cache info CacheInfo { ts: 2, lsn: 71, pointer: Inline(71), log_size: 25 } with lsn 0
18:23:57 [TRACE] (2) sled::pagecache::segment: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/segment.rs:380] removing pid 0 at lsn 0 from segment Active(Active { lsn: 0, rss: 76, deferred_replaced_rss: 0, deferred_replaced_pids: {}, pids: {0, 1, 2, 3}, latest_replacement_lsn: 0, can_free_upon_deactivation: {}, deferred_rm_blob: {} })
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1549] accessed pid 0 -> paging out pids []
18:23:57 [TRACE] (2) sled::pagecache: [/home/iex/.cargo/registry/src/github.com-1ecc6299db9ec823/sled-0.34.7/src/pagecache/mod.rs:1595] getting page iter for META
18:23:57 [TRACE] (2) xvc::common::keyvaluestore: [src/common/keyvaluestore.rs:28] db: Db {
    Tree: "__sled__default" contents: Tree: 
        PageCache { max: 4 free: Mutex { data: [] } }
        level 0:
test test_xvc_kvstore has been running for over 60 seconds

Thank you very much for sled. 🙏🏼

divergentdave commented 3 years ago

The issue here is that simplelog is deadlocking when there's a re-entrant call to the log from formatting calls it makes. I cannot reproduce this issue when using env_logger, but I can recreate the same behavior with sled out of the loop. Here's the code I reproduced it with. https://gist.github.com/divergentdave/cc05fdbb61bfd6e9238d5600937628ce

iesahin commented 3 years ago

Thank you @divergentdave I can use another logging implementation, and report this to simplelog if you're certain that sled runs the logging as it should be.

I'm looking for a point to put "possible interactions with other crates" section in the documentation to put this info for the short term. Where do you think is a better point?

iesahin commented 3 years ago

I've replaced the logging implementation with fern, and the problem seems to persist.

divergentdave commented 3 years ago

This is a similar issue, turn on fern's meta-logging-in-format feature, as seen here https://docs.rs/fern/0.6.0/fern/meta/index.html

iesahin commented 3 years ago

Oh, thanks. Could you point me to the most appropriate document in the docs to summarize this? I would like to submit a PR for this.