search

dermesser / leveldb-rs

A reimplementation of LevelDB in Rust (no bindings).
Other
521 stars 59 forks source link

Panic in `DB::open` #23

Closed Sword-Smith closed 1 year ago

Sword-Smith commented 1 year ago

Got this panic and stack trace when I called DB::open. Error occurs in recover_log_file -> insert_into_memtable.

I'm running level rusty-leveldb 1.0.6.

Stack trace

thread 'main' panicked at 'range end index 335261 out of range for slice of length 328603', /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/write_batch.rs:136:22
stack backtrace:
   0: rust_begin_unwind
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:579:5
   1: core::panicking::panic_fmt
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/panicking.rs:64:14
   2: core::slice::index::slice_end_index_len_fail_rt
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/slice/index.rs:77:5
   3: core::slice::index::slice_end_index_len_fail
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/slice/index.rs:69:9
   4: <core::ops::range::Range<usize> as core::slice::index::SliceIndex<[T]>>::index
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/slice/index.rs:409:13
   5: core::slice::index::<impl core::ops::index::Index<I> for [T]>::index
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/slice/index.rs:18:9
   6: <alloc::vec::Vec<T,A> as core::ops::index::Index<I>>::index
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/alloc/src/vec/mod.rs:2703:9
   7: <rusty_leveldb::write_batch::WriteBatchIter as core::iter::traits::iterator::Iterator>::next
             at /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/write_batch.rs:136:22
   8: rusty_leveldb::write_batch::WriteBatch::insert_into_memtable
             at /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/write_batch.rs:97:23
   9: rusty_leveldb::db_impl::DB::recover_log_file
             at /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/db_impl.rs:268:13
  10: rusty_leveldb::db_impl::DB::recover
             at /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/db_impl.rs:210:17
  11: rusty_leveldb::db_impl::DB::open
             at /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/db_impl.rs:115:29
Sword-Smith commented 1 year ago

I added some println statements to get a sense of where the problem is. Looks like vlen points beyond the range of self.batch.entries.

pub fn insert_into_memtable(&self, mut seq: SequenceNumber, mt: &mut MemTable) {
        println!("HI from `insert_into_memtable`");
        println!("self.entries.len() = {}", self.entries.len());
        println!("seq = {seq}");
        // println!("{self:#?}");
        for (k, v) in self.iter() {
            match v {
                Some(v_) => mt.add(seq, ValueType::TypeValue, k, v_),
                None => mt.add(seq, ValueType::TypeDeletion, k, b""),
            }
            seq += 1;
        }
    }
impl<'a> Iterator for WriteBatchIter<'a> {
    type Item = (&'a [u8], Option<&'a [u8]>);
    fn next(&mut self) -> Option<Self::Item> {
        println!("HI from `WriteBatchIter::next`");
        if self.ix >= self.batch.entries.len() {
            return None;
        }

        let tag = self.batch.entries[self.ix];
        println!("tag: `{tag}`");
        self.ix += 1;
        println!("self.ix: `{}`", self.ix);

        let (klen, l) = usize::decode_var(&self.batch.entries[self.ix..])?;
        println!("klen: `{klen}`; l: `{l}`");
        self.ix += l;
        println!("self.ix: `{}`", self.ix);
        let k = &self.batch.entries[self.ix..self.ix + klen];
        self.ix += klen;
        println!("self.ix: `{}`", self.ix);

        if tag == ValueType::TypeValue as u8 {
            println!("tag *is* TypeValue");
            let (vlen, m) = usize::decode_var(&self.batch.entries[self.ix..])?;
            println!("vlen = {vlen}; m = {m}");
            self.ix += m;
            println!("self.ix: `{}`", self.ix);
            println!("self.batch.entries.len() = {}", self.batch.entries.len());
            println!("self.ix = {}", self.ix);
            let v = &self.batch.entries[self.ix..self.ix + vlen];
            self.ix += vlen;

            Some((k, Some(v)))
        } else {
            println!("tag is *not* TypeValue");
            Some((k, None))
        }
    }
}

Here's the output

HI from `insert_into_memtable`
self.entries.len() = 12
seq = 78927
HI from `WriteBatchIter::next`
HI from `insert_into_memtable`
self.entries.len() = 328603
seq = 78927
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `13`
klen: `9`; l: `1`
self.ix: `14`
self.ix: `23`
tag *is* TypeValue
vlen = 382; m = 2
self.ix: `25`
self.batch.entries.len() = 328603
self.ix = 25
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `408`
klen: `9`; l: `1`
self.ix: `409`
self.ix: `418`
tag *is* TypeValue
vlen = 5234; m = 2
self.ix: `420`
self.batch.entries.len() = 328603
self.ix = 420
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `5655`
klen: `9`; l: `1`
self.ix: `5656`
self.ix: `5665`
tag *is* TypeValue
vlen = 3118; m = 2
self.ix: `5667`
self.batch.entries.len() = 328603
self.ix = 5667
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `8786`
klen: `9`; l: `1`
self.ix: `8787`
self.ix: `8796`
tag *is* TypeValue
vlen = 2338; m = 2
self.ix: `8798`
self.batch.entries.len() = 328603
self.ix = 8798
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `11137`
klen: `9`; l: `1`
self.ix: `11138`
self.ix: `11147`
tag *is* TypeValue
vlen = 5050; m = 2
self.ix: `11149`
self.batch.entries.len() = 328603
self.ix = 11149
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `16200`
klen: `9`; l: `1`
self.ix: `16201`
self.ix: `16210`
tag *is* TypeValue
vlen = 2362; m = 2
self.ix: `16212`
self.batch.entries.len() = 328603
self.ix = 16212
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `18575`
klen: `9`; l: `1`
self.ix: `18576`
self.ix: `18585`
tag *is* TypeValue
vlen = 5422; m = 2
self.ix: `18587`
self.batch.entries.len() = 328603
self.ix = 18587
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `24010`
klen: `9`; l: `1`
self.ix: `24011`
self.ix: `24020`
tag *is* TypeValue
vlen = 5734; m = 2
self.ix: `24022`
self.batch.entries.len() = 328603
self.ix = 24022
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `29757`
klen: `9`; l: `1`
self.ix: `29758`
self.ix: `29767`
tag *is* TypeValue
vlen = 4558; m = 2
self.ix: `29769`
self.batch.entries.len() = 328603
self.ix = 29769
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `34328`
klen: `9`; l: `1`
self.ix: `34329`
self.ix: `34338`
tag *is* TypeValue
vlen = 2746; m = 2
self.ix: `34340`
self.batch.entries.len() = 328603
self.ix = 34340
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `37087`
klen: `9`; l: `1`
self.ix: `37088`
self.ix: `37097`
tag *is* TypeValue
vlen = 3274; m = 2
self.ix: `37099`
self.batch.entries.len() = 328603
self.ix = 37099
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `40374`
klen: `9`; l: `1`
self.ix: `40375`
self.ix: `40384`
tag *is* TypeValue
vlen = 2506; m = 2
self.ix: `40386`
self.batch.entries.len() = 328603
self.ix = 40386
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `42893`
klen: `9`; l: `1`
self.ix: `42894`
self.ix: `42903`
tag *is* TypeValue
vlen = 1534; m = 2
self.ix: `42905`
self.batch.entries.len() = 328603
self.ix = 42905
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `44440`
klen: `9`; l: `1`
self.ix: `44441`
self.ix: `44450`
tag *is* TypeValue
vlen = 6034; m = 2
self.ix: `44452`
self.batch.entries.len() = 328603
self.ix = 44452
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `50487`
klen: `9`; l: `1`
self.ix: `50488`
self.ix: `50497`
tag *is* TypeValue
vlen = 2062; m = 2
self.ix: `50499`
self.batch.entries.len() = 328603
self.ix = 50499
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `52562`
klen: `9`; l: `1`
self.ix: `52563`
self.ix: `52572`
tag *is* TypeValue
vlen = 3706; m = 2
self.ix: `52574`
self.batch.entries.len() = 328603
self.ix = 52574
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `56281`
klen: `9`; l: `1`
self.ix: `56282`
self.ix: `56291`
tag *is* TypeValue
vlen = 7462; m = 2
self.ix: `56293`
self.batch.entries.len() = 328603
self.ix = 56293
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `63756`
klen: `9`; l: `1`
self.ix: `63757`
self.ix: `63766`
tag *is* TypeValue
vlen = 6554; m = 2
self.ix: `63768`
self.batch.entries.len() = 328603
self.ix = 63768
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `70323`
klen: `9`; l: `1`
self.ix: `70324`
self.ix: `70333`
tag *is* TypeValue
vlen = 4654; m = 2
self.ix: `70335`
self.batch.entries.len() = 328603
self.ix = 70335
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `74990`
klen: `9`; l: `1`
self.ix: `74991`
self.ix: `75000`
tag *is* TypeValue
vlen = 3310; m = 2
self.ix: `75002`
self.batch.entries.len() = 328603
self.ix = 75002
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `78313`
klen: `9`; l: `1`
self.ix: `78314`
self.ix: `78323`
tag *is* TypeValue
vlen = 3442; m = 2
self.ix: `78325`
self.batch.entries.len() = 328603
self.ix = 78325
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `81768`
klen: `9`; l: `1`
self.ix: `81769`
self.ix: `81778`
tag *is* TypeValue
vlen = 3742; m = 2
self.ix: `81780`
self.batch.entries.len() = 328603
self.ix = 81780
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `85523`
klen: `9`; l: `1`
self.ix: `85524`
self.ix: `85533`
tag *is* TypeValue
vlen = 3778; m = 2
self.ix: `85535`
self.batch.entries.len() = 328603
self.ix = 85535
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `89314`
klen: `9`; l: `1`
self.ix: `89315`
self.ix: `89324`
tag *is* TypeValue
vlen = 2326; m = 2
self.ix: `89326`
self.batch.entries.len() = 328603
self.ix = 89326
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `91653`
klen: `9`; l: `1`
self.ix: `91654`
self.ix: `91663`
tag *is* TypeValue
vlen = 2614; m = 2
self.ix: `91665`
self.batch.entries.len() = 328603
self.ix = 91665
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `94280`
klen: `9`; l: `1`
self.ix: `94281`
self.ix: `94290`
tag *is* TypeValue
vlen = 1654; m = 2
self.ix: `94292`
self.batch.entries.len() = 328603
self.ix = 94292
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `95947`
klen: `9`; l: `1`
self.ix: `95948`
self.ix: `95957`
tag *is* TypeValue
vlen = 8126; m = 2
self.ix: `95959`
self.batch.entries.len() = 328603
self.ix = 95959
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `104086`
klen: `9`; l: `1`
self.ix: `104087`
self.ix: `104096`
tag *is* TypeValue
vlen = 2242; m = 2
self.ix: `104098`
self.batch.entries.len() = 328603
self.ix = 104098
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `106341`
klen: `9`; l: `1`
self.ix: `106342`
self.ix: `106351`
tag *is* TypeValue
vlen = 1294; m = 2
self.ix: `106353`
self.batch.entries.len() = 328603
self.ix = 106353
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `107648`
klen: `9`; l: `1`
self.ix: `107649`
self.ix: `107658`
tag *is* TypeValue
vlen = 2062; m = 2
self.ix: `107660`
self.batch.entries.len() = 328603
self.ix = 107660
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `109723`
klen: `9`; l: `1`
self.ix: `109724`
self.ix: `109733`
tag *is* TypeValue
vlen = 2998; m = 2
self.ix: `109735`
self.batch.entries.len() = 328603
self.ix = 109735
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `112734`
klen: `9`; l: `1`
self.ix: `112735`
self.ix: `112744`
tag *is* TypeValue
vlen = 1534; m = 2
self.ix: `112746`
self.batch.entries.len() = 328603
self.ix = 112746
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `114281`
klen: `9`; l: `1`
self.ix: `114282`
self.ix: `114291`
tag *is* TypeValue
vlen = 3214; m = 2
self.ix: `114293`
self.batch.entries.len() = 328603
self.ix = 114293
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `117508`
klen: `9`; l: `1`
self.ix: `117509`
self.ix: `117518`
tag *is* TypeValue
vlen = 4030; m = 2
self.ix: `117520`
self.batch.entries.len() = 328603
self.ix = 117520
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `121551`
klen: `9`; l: `1`
self.ix: `121552`
self.ix: `121561`
tag *is* TypeValue
vlen = 3442; m = 2
self.ix: `121563`
self.batch.entries.len() = 328603
self.ix = 121563
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `125006`
klen: `9`; l: `1`
self.ix: `125007`
self.ix: `125016`
tag *is* TypeValue
vlen = 4414; m = 2
self.ix: `125018`
self.batch.entries.len() = 328603
self.ix = 125018
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `129433`
klen: `9`; l: `1`
self.ix: `129434`
self.ix: `129443`
tag *is* TypeValue
vlen = 2398; m = 2
self.ix: `129445`
self.batch.entries.len() = 328603
self.ix = 129445
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `131844`
klen: `9`; l: `1`
self.ix: `131845`
self.ix: `131854`
tag *is* TypeValue
vlen = 9146; m = 2
self.ix: `131856`
self.batch.entries.len() = 328603
self.ix = 131856
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `141003`
klen: `9`; l: `1`
self.ix: `141004`
self.ix: `141013`
tag *is* TypeValue
vlen = 1294; m = 2
self.ix: `141015`
self.batch.entries.len() = 328603
self.ix = 141015
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `142310`
klen: `9`; l: `1`
self.ix: `142311`
self.ix: `142320`
tag *is* TypeValue
vlen = 3202; m = 2
self.ix: `142322`
self.batch.entries.len() = 328603
self.ix = 142322
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `145525`
klen: `9`; l: `1`
self.ix: `145526`
self.ix: `145535`
tag *is* TypeValue
vlen = 6718; m = 2
self.ix: `145537`
self.batch.entries.len() = 328603
self.ix = 145537
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `152256`
klen: `9`; l: `1`
self.ix: `152257`
self.ix: `152266`
tag *is* TypeValue
vlen = 2134; m = 2
self.ix: `152268`
self.batch.entries.len() = 328603
self.ix = 152268
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `154403`
klen: `9`; l: `1`
self.ix: `154404`
self.ix: `154413`
tag *is* TypeValue
vlen = 7034; m = 2
self.ix: `154415`
self.batch.entries.len() = 328603
self.ix = 154415
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `161450`
klen: `9`; l: `1`
self.ix: `161451`
self.ix: `161460`
tag *is* TypeValue
vlen = 6962; m = 2
self.ix: `161462`
self.batch.entries.len() = 328603
self.ix = 161462
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `168425`
klen: `9`; l: `1`
self.ix: `168426`
self.ix: `168435`
tag *is* TypeValue
vlen = 5606; m = 2
self.ix: `168437`
self.batch.entries.len() = 328603
self.ix = 168437
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `174044`
klen: `9`; l: `1`
self.ix: `174045`
self.ix: `174054`
tag *is* TypeValue
vlen = 4414; m = 2
self.ix: `174056`
self.batch.entries.len() = 328603
self.ix = 174056
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `178471`
klen: `9`; l: `1`
self.ix: `178472`
self.ix: `178481`
tag *is* TypeValue
vlen = 1978; m = 2
self.ix: `178483`
self.batch.entries.len() = 328603
self.ix = 178483
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `180462`
klen: `9`; l: `1`
self.ix: `180463`
self.ix: `180472`
tag *is* TypeValue
vlen = 2722; m = 2
self.ix: `180474`
self.batch.entries.len() = 328603
self.ix = 180474
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `183197`
klen: `9`; l: `1`
self.ix: `183198`
self.ix: `183207`
tag *is* TypeValue
vlen = 1294; m = 2
self.ix: `183209`
self.batch.entries.len() = 328603
self.ix = 183209
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `184504`
klen: `9`; l: `1`
self.ix: `184505`
self.ix: `184514`
tag *is* TypeValue
vlen = 790; m = 2
self.ix: `184516`
self.batch.entries.len() = 328603
self.ix = 184516
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `185307`
klen: `9`; l: `1`
self.ix: `185308`
self.ix: `185317`
tag *is* TypeValue
vlen = 3442; m = 2
self.ix: `185319`
self.batch.entries.len() = 328603
self.ix = 185319
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `188762`
klen: `9`; l: `1`
self.ix: `188763`
self.ix: `188772`
tag *is* TypeValue
vlen = 2962; m = 2
self.ix: `188774`
self.batch.entries.len() = 328603
self.ix = 188774
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `191737`
klen: `9`; l: `1`
self.ix: `191738`
self.ix: `191747`
tag *is* TypeValue
vlen = 7046; m = 2
self.ix: `191749`
self.batch.entries.len() = 328603
self.ix = 191749
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `198796`
klen: `9`; l: `1`
self.ix: `198797`
self.ix: `198806`
tag *is* TypeValue
vlen = 4558; m = 2
self.ix: `198808`
self.batch.entries.len() = 328603
self.ix = 198808
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `203367`
klen: `9`; l: `1`
self.ix: `203368`
self.ix: `203377`
tag *is* TypeValue
vlen = 2914; m = 2
self.ix: `203379`
self.batch.entries.len() = 328603
self.ix = 203379
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `206294`
klen: `9`; l: `1`
self.ix: `206295`
self.ix: `206304`
tag *is* TypeValue
vlen = 8026; m = 2
self.ix: `206306`
self.batch.entries.len() = 328603
self.ix = 206306
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `214333`
klen: `9`; l: `1`
self.ix: `214334`
self.ix: `214343`
tag *is* TypeValue
vlen = 3454; m = 2
self.ix: `214345`
self.batch.entries.len() = 328603
self.ix = 214345
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `217800`
klen: `9`; l: `1`
self.ix: `217801`
self.ix: `217810`
tag *is* TypeValue
vlen = 7078; m = 2
self.ix: `217812`
self.batch.entries.len() = 328603
self.ix = 217812
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `224891`
klen: `9`; l: `1`
self.ix: `224892`
self.ix: `224901`
tag *is* TypeValue
vlen = 4030; m = 2
self.ix: `224903`
self.batch.entries.len() = 328603
self.ix = 224903
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `228934`
klen: `9`; l: `1`
self.ix: `228935`
self.ix: `228944`
tag *is* TypeValue
vlen = 4858; m = 2
self.ix: `228946`
self.batch.entries.len() = 328603
self.ix = 228946
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `233805`
klen: `9`; l: `1`
self.ix: `233806`
self.ix: `233815`
tag *is* TypeValue
vlen = 6106; m = 2
self.ix: `233817`
self.batch.entries.len() = 328603
self.ix = 233817
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `239924`
klen: `9`; l: `1`
self.ix: `239925`
self.ix: `239934`
tag *is* TypeValue
vlen = 7990; m = 2
self.ix: `239936`
self.batch.entries.len() = 328603
self.ix = 239936
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `247927`
klen: `9`; l: `1`
self.ix: `247928`
self.ix: `247937`
tag *is* TypeValue
vlen = 6082; m = 2
self.ix: `247939`
self.batch.entries.len() = 328603
self.ix = 247939
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `254022`
klen: `9`; l: `1`
self.ix: `254023`
self.ix: `254032`
tag *is* TypeValue
vlen = 5542; m = 2
self.ix: `254034`
self.batch.entries.len() = 328603
self.ix = 254034
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `259577`
klen: `9`; l: `1`
self.ix: `259578`
self.ix: `259587`
tag *is* TypeValue
vlen = 4054; m = 2
self.ix: `259589`
self.batch.entries.len() = 328603
self.ix = 259589
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `263644`
klen: `9`; l: `1`
self.ix: `263645`
self.ix: `263654`
tag *is* TypeValue
vlen = 5098; m = 2
self.ix: `263656`
self.batch.entries.len() = 328603
self.ix = 263656
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `268755`
klen: `9`; l: `1`
self.ix: `268756`
self.ix: `268765`
tag *is* TypeValue
vlen = 7006; m = 2
self.ix: `268767`
self.batch.entries.len() = 328603
self.ix = 268767
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `275774`
klen: `9`; l: `1`
self.ix: `275775`
self.ix: `275784`
tag *is* TypeValue
vlen = 3418; m = 2
self.ix: `275786`
self.batch.entries.len() = 328603
self.ix = 275786
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `279205`
klen: `9`; l: `1`
self.ix: `279206`
self.ix: `279215`
tag *is* TypeValue
vlen = 4678; m = 2
self.ix: `279217`
self.batch.entries.len() = 328603
self.ix = 279217
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `283896`
klen: `9`; l: `1`
self.ix: `283897`
self.ix: `283906`
tag *is* TypeValue
vlen = 9182; m = 2
self.ix: `283908`
self.batch.entries.len() = 328603
self.ix = 283908
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `293091`
klen: `9`; l: `1`
self.ix: `293092`
self.ix: `293101`
tag *is* TypeValue
vlen = 2770; m = 2
self.ix: `293103`
self.batch.entries.len() = 328603
self.ix = 293103
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `295874`
klen: `9`; l: `1`
self.ix: `295875`
self.ix: `295884`
tag *is* TypeValue
vlen = 2590; m = 2
self.ix: `295886`
self.batch.entries.len() = 328603
self.ix = 295886
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `298477`
klen: `9`; l: `1`
self.ix: `298478`
self.ix: `298487`
tag *is* TypeValue
vlen = 3070; m = 2
self.ix: `298489`
self.batch.entries.len() = 328603
self.ix = 298489
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `301560`
klen: `9`; l: `1`
self.ix: `301561`
self.ix: `301570`
tag *is* TypeValue
vlen = 6182; m = 2
self.ix: `301572`
self.batch.entries.len() = 328603
self.ix = 301572
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `307755`
klen: `9`; l: `1`
self.ix: `307756`
self.ix: `307765`
tag *is* TypeValue
vlen = 2098; m = 2
self.ix: `307767`
self.batch.entries.len() = 328603
self.ix = 307767
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `309866`
klen: `9`; l: `1`
self.ix: `309867`
self.ix: `309876`
tag *is* TypeValue
vlen = 7838; m = 2
self.ix: `309878`
self.batch.entries.len() = 328603
self.ix = 309878
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `317717`
klen: `9`; l: `1`
self.ix: `317718`
self.ix: `317727`
tag *is* TypeValue
vlen = 6250; m = 2
self.ix: `317729`
self.batch.entries.len() = 328603
self.ix = 317729
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `323980`
klen: `9`; l: `1`
self.ix: `323981`
self.ix: `323990`
tag *is* TypeValue
vlen = 3274; m = 2
self.ix: `323992`
self.batch.entries.len() = 328603
self.ix = 323992
HI from `WriteBatchIter::next`
tag: `1`
self.ix: `327267`
klen: `9`; l: `1`
self.ix: `327268`
self.ix: `327277`
tag *is* TypeValue
vlen = 7982; m = 2
self.ix: `327279`
self.batch.entries.len() = 328603
self.ix = 327279
thread 'main' panicked at 'range end index 335261 out of range for slice of length 328603', /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/write_batch.rs:152:22
stack backtrace:
   0: rust_begin_unwind
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:579:5
   1: core::panicking::panic_fmt
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/panicking.rs:64:14
   2: core::slice::index::slice_end_index_len_fail_rt
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/slice/index.rs:77:5
   3: core::slice::index::slice_end_index_len_fail
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/slice/index.rs:69:9
   4: <core::ops::range::Range<usize> as core::slice::index::SliceIndex<[T]>>::index
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/slice/index.rs:409:13
   5: core::slice::index::<impl core::ops::index::Index<I> for [T]>::index
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/slice/index.rs:18:9
   6: <alloc::vec::Vec<T,A> as core::ops::index::Index<I>>::index
             at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/alloc/src/vec/mod.rs:2703:9
   7: <rusty_leveldb::write_batch::WriteBatchIter as core::iter::traits::iterator::Iterator>::next
             at /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/write_batch.rs:152:22
   8: rusty_leveldb::write_batch::WriteBatch::insert_into_memtable
             at /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/write_batch.rs:102:23
   9: rusty_leveldb::db_impl::DB::recover_log_file
             at /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/db_impl.rs:268:13
  10: rusty_leveldb::db_impl::DB::recover
             at /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/db_impl.rs:210:17
  11: rusty_leveldb::db_impl::DB::open
             at /home/thv/.cargo/registry/src/github.com-1ecc6299db9ec823/rusty-leveldb-1.0.6/src/db_impl.rs:115:2
dermesser commented 1 year ago

This is an interesting issue for sure. Have you been able to reproduce this for a certain size or set of keys? Or is this a singular instance? This kind of issue might be trivially caused by data corruption otherwise, in which case our search would be futile... however, it doesn't appear to be a single bit flip from what I can see. Unless through some unfortunate combination, the corruption occurred earlier in the log and only manifests when hitting (past) the end.

I will keep looking at it though and try tracing through what is going on. Maybe a good opportunity to improve my Rust debugging skills :-)

Sword-Smith commented 1 year ago

The running instance could have been killed somehow, maybe, causing an incomplete write. That's my best guess.

Sword-Smith commented 1 year ago

Fixed with the merge of #27 I think.

dermesser commented 1 year ago

I'm glad to hear!

appelgriebsch commented 1 month ago

Hmmm looks like I stumbled into the same issue today - on version 3.0.0.... (user id retracted for security reasons)

thread 'main' panicked at /Users/<userid>/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rusty-leveldb-3.0.0/src/write_batch.rs:136:40:
range end index 11848 out of range for slice of length 9433
stack backtrace:
   0: rust_begin_unwind
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:665:5
   1: core::panicking::panic_fmt
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panicking.rs:74:14
   2: core::slice::index::slice_end_index_len_fail_rt
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/slice/index.rs:65:5
   3: core::slice::index::slice_end_index_len_fail
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/slice/index.rs:58:5
   4: index<u8>
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/slice/index.rs:466:13
   5: index<u8, core::ops::range::Range<usize>>
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/slice/index.rs:17:9
   6: index<u8, core::ops::range::Range<usize>, alloc::alloc::Global>
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/alloc/src/vec/mod.rs:2912:9
   7: next
             at /Users/<userid>/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rusty-leveldb-3.0.0/src/write_batch.rs:136:40
   8: insert_into_memtable
             at /Users/<userid>/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rusty-leveldb-3.0.0/src/write_batch.rs:97:23
   9: recover_log_file
             at /Users/<userid>/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rusty-leveldb-3.0.0/src/db_impl.rs:268:13
  10: recover
             at /Users/<userid>/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rusty-leveldb-3.0.0/src/db_impl.rs:210:17
  11: rusty_leveldb::db_impl::DB::open
             at /Users/<userid>/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rusty-leveldb-3.0.0/src/db_impl.rs:115:29

When using the leveldb cli (https://github.com/cions/leveldb-cli) I can still access the database entries though

appelgriebsch commented 1 month ago

The running instance could have been killed somehow, maybe, causing an incomplete write. That's my best guess.

Yeah, similar situation might have happened here. Some power outage has happened as far as I can tell. And it's erroring out on this line

let v = &self.batch.entries[self.ix..self.ix + vlen];

due to an access beyond bounds of the array. Currently there doesn't seem to be a way to go around this as the application will just panic at runtime....

so, what's next steps? adding some bound checks to this access? how should this actually being handled then? ignoring the "corrupted" value all together, or just reading the parts that are available (which may also lead to a corrupted value anyway)?

appelgriebsch commented 1 month ago

@dermesser any idea how to continue with this?

dermesser commented 1 month ago

Sorry, no idea right away. How this should be handled really depends on the application, whether you can live with skipped keys, etc. Frankly, robustness against crashes/power outages is not a key aspect of LevelDB, as far as I can tell, and unfortunately not of this crate either.

What I've done in the past is trying to repair the file itself. As the on-disk format is not very complicated, it's sometimes possible to do so. Maybe it would even be worth writing a tool to deal with corrupted databases... although the fundamental issue with corruption is obviously that you don't know what to trust.

dermesser commented 1 month ago

I guess though that the issue occurs - as you say - during recovery in DB::recover_log_file(). What you can try doing is truncating the log file (000123.log) if it exists. Removing it might also work although I would recommend truncating first. In any case, keep a copy. That way, the more recently written entries from the log will be lost but the database can be opened again.