Cannot run ord server after a crash due to cberner/redb#515

[hantuzun]

A bug in the underlying db (cberner/redb#515) is preventing ord to run server after a crash.

I interrupted ord as it was indexing and seemed stuck at block 494299:

th 0, needed 12.
[indexing blocks] ████████████████████░░░░░░░░░░░░░░░░░░░░░░ 384299/774744[2023-02-02T17:10:08Z ERROR ord::index::updater] failed to fetch block 384332, retrying in 2s: JSON-RPC error: transport error: HTTP response too short: length 0, needed 12.
[indexing blocks] █████████████████████░░░░░░░░░░░░░░░░░░░░░ 404299/774744[2023-02-02T17:25:51Z ERROR ord::index::updater] failed to fetch block 404332, retrying in 2s: JSON-RPC error: transport error: HTTP response too short: length 0, needed 12.
[indexing blocks] ██████████████████████░░░░░░░░░░░░░░░░░░░░ 409299/774744[2023-02-02T17:30:41Z ERROR ord::index::updater] failed to fetch block 409332, retrying in 2s: JSON-RPC error: transport error: HTTP response too short: length 0, needed 12.
[indexing blocks] ██████████████████████░░░░░░░░░░░░░░░░░░░░ 414299/774744[2023-02-02T17:35:18Z ERROR ord::index::updater] failed to fetch block 414332, retrying in 2s: JSON-RPC error: transport error: HTTP response too short: length 0, needed 12.
[indexing blocks] ██████████████████████░░░░░░░░░░░░░░░░░░░░ 419299/774744[2023-02-02T17:40:51Z ERROR ord::index::updater] failed to fetch block 419332, retrying in 2s: JSON-RPC error: transport error: HTTP response too short: length 0, needed 12.
[indexing blocks] ███████████████████████░░░░░░░░░░░░░░░░░░░ 424299/774744[2023-02-02T17:45:45Z ERROR ord::index::updater] failed to fetch block 424332, retrying in 2s: JSON-RPC error: transport error: HTTP response too short: length 0, needed 12.
[indexing blocks] ███████████████████████░░░░░░░░░░░░░░░░░░░ 429299/774744[2023-02-02T17:50:27Z ERROR ord::index::updater] failed to fetch block 429332, retrying in 2s: JSON-RPC error: transport error: HTTP response too short: length 0, needed 12.
[indexing blocks] ███████████████████████░░░░░░░░░░░░░░░░░░░ 439299/774744[2023-02-02T17:59:29Z ERROR ord::index::updater] failed to fetch block 439332, retrying in 2s: JSON-RPC error: transport error: HTTP response too short: length 0, needed 12.
[indexing blocks] ████████████████████████░░░░░░░░░░░░░░░░░░ 444299/774744[2023-02-02T18:04:46Z ERROR ord::index::updater] failed to fetch block 444332, retrying in 2s: JSON-RPC error: transport error: HTTP response too short: length 0, needed 12.
[indexing blocks] ████████████████████████░░░░░░░░░░░░░░░░░░ 454299/774744[2023-02-02T18:15:34Z ERROR ord::index::updater] failed to fetch block 454332, retrying in 2s: JSON-RPC error: transport error: HTTP response too short: length 0, needed 12.
[indexing blocks] ████████████████████████░░░░░░░░░░░░░░░░░░ 459299/774744[2023-02-02T18:22:13Z ERROR ord::index::updater] failed to fetch block 459332, retrying in 2s: JSON-RPC error: transport error: Couldn't connect to host: Broken pipe (os error 32)
[indexing blocks] █████████████████████████░░░░░░░░░░░░░░░░░ 469299/774744[2023-02-02T18:36:16Z ERROR ord::index::updater] failed to fetch block 469332, retrying in 2s: JSON-RPC error: transport error: Couldn't connect to host: Broken pipe (os error 32)
[indexing blocks] █████████████████████████░░░░░░░░░░░░░░░░░ 474299/774744[2023-02-02T18:46:38Z ERROR ord::index::updater] failed to fetch block 474332, retrying in 2s: JSON-RPC error: transport error: Couldn't connect to host: Broken pipe (os error 32)
[indexing blocks] █████████████████████████░░░░░░░░░░░░░░░░░ 479299/774744[2023-02-02T18:57:32Z ERROR ord::index::updater] failed to fetch block 479332, retrying in 2s: JSON-RPC error: transport error: Couldn't connect to host: Broken pipe (os error 32)
[indexing blocks] ██████████████████████████░░░░░░░░░░░░░░░░ 484299/774744[2023-02-02T19:07:30Z ERROR ord::index::updater] failed to fetch block 484332, retrying in 2s: JSON-RPC error: transport error: Couldn't connect to host: Broken pipe (os error 32)
[indexing blocks] ██████████████████████████░░░░░░░░░░░░░░░░ 489299/774744[2023-02-02T19:16:56Z ERROR ord::index::updater] failed to fetch block 489332, retrying in 2s: JSON-RPC error: transport error: Couldn't connect to host: Broken pipe (os error 32)
[indexing blocks] ██████████████████████████░░░░░░░░░░░░░░░░ 494299/774744^C^C^C

Afterwards, I cannot run ord again:

han@sofa bin % RUST_BACKTRACE=1 ord server
Listening on http://0.0.0.0:80
[indexing blocks] ██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ 494301/774764thread '<unnamed>' panicked at 'internal error: entered unreachable code', /Users/han/.cargo/registry/src/gitpro.ttaallkk.top-1ecc6299db9ec823/redb-0.12.1/src/tree_store/btree_mutator.rs:971:18
stack backtrace:
   0: rust_begin_unwind
             at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:575:5
   1: core::panicking::panic_fmt
             at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panicking.rs:64:14
   2: core::panicking::panic
             at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panicking.rs:111:5
   3: redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper
   4: redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper
   5: redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper
   6: redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper
   7: redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper
   8: redb::tree_store::btree_mutator::MutateHelper<K,V>::delete
   9: redb::tree_store::btree::BtreeMut<K,V>::remove
  10: ord::index::updater::inscription_updater::InscriptionUpdater::index_transaction_inscriptions
  11: ord::index::updater::Updater::update
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

This index is created from scratch with the latest commit (casey@10f8469).

[casey]

Nice, thanks for the report! We should leave this open, but if it's an issue with redb, then we're blocked on our end. Chris is a solo open source dev (and also a great guy!) so keep in mind that he might have limited resources to look into this.

[hantuzun]

I've faced more panics and now I suspect that these crashes are a result of bugs in ord and redb. redb should not allow corrupted files. But, I can reproduce panics with ord index on healthy files, without interruptions, creating corrupted files now.

Running ord index from a snapshot at height 370,000 or 360,000 result in this panic at block 370,116:

[indexing blocks] ████████████████████░░░░░░░░░░░░░░░░░░░░░░ 370116/774790thread 'main' panicked at 'internal error: entered unreachable code', /Users/han/.cargo/registry/src/gitpro.ttaallkk.top-1ecc6299db9ec823/redb-0.12.1/src/tree_store/btree_mutator.rs:971:18
stack backtrace:
   0:        0x10f602216 - std::backtrace_rs::backtrace::libunwind::trace::h310cbd77a7d2ae59
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:        0x10f602216 - std::backtrace_rs::backtrace::trace_unsynchronized::h5768bae568840507
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:        0x10f602216 - std::sys_common::backtrace::_print_fmt::hd104a205649a2ffb
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:65:5
   3:        0x10f602216 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h521420ec33f3769d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:44:22
   4:        0x10f6234ba - core::fmt::write::h694a0d7c23f57ada
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/fmt/mod.rs:1208:17
   5:        0x10f5fb64c - std::io::Write::write_fmt::h1920a3973ad439e5
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/io/mod.rs:1682:15
   6:        0x10f601ffa - std::sys_common::backtrace::_print::h75582c4ed1a04abb
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:47:5
   7:        0x10f601ffa - std::sys_common::backtrace::print::hef1aa4dbdc07ee06
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:34:9
   8:        0x10f603c23 - std::panicking::default_hook::{{closure}}::h529701a1070b4ce0
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:267:22
   9:        0x10f603978 - std::panicking::default_hook::hfeeab2c667b2d7c2
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:286:9
  10:        0x10f604353 - std::panicking::rust_panic_with_hook::h1b5245192f90251d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:688:13
  11:        0x10f6040e3 - std::panicking::begin_panic_handler::{{closure}}::h3658f3a9566379d4
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:577:13
  12:        0x10f6026b8 - std::sys_common::backtrace::__rust_end_short_backtrace::h9e01645d962f8882
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:137:18
  13:        0x10f603ded - rust_begin_unwind
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:575:5
  14:        0x10f654ad3 - core::panicking::panic_fmt::h0097ad8ec0b07517
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panicking.rs:64:14
  15:        0x10f654ba7 - core::panicking::panic::ha47a4f67bad0ba2d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panicking.rs:111:5
  16:        0x10eeda712 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  17:        0x10eed6c46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  18:        0x10eed6c46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  19:        0x10eed6c46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  20:        0x10eed6c46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  21:        0x10ef08fff - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete::h29ae2cb93920f9e8
  22:        0x10f01ae3f - redb::tree_store::btree::BtreeMut<K,V>::remove::hb3e22d5a358d036a
  23:        0x10f0300ce - ord::index::updater::inscription_updater::InscriptionUpdater::index_transaction_inscriptions::hb10f2eb470695894
  24:        0x10ef244db - ord::index::updater::Updater::update::hedc89b041ebaa722
  25:        0x10eeba1a6 - ord::subcommand::index::run::hab3781d4830fe16d
  26:        0x10f104c87 - ord::subcommand::Subcommand::run::hcbc1fe1f2071848e
  27:        0x10f033f1b - ord::main::h29af978464f7cf50
  28:        0x10ee49c46 - std::sys_common::backtrace::__rust_begin_short_backtrace::h67a26858a530fb6d
  29:        0x10ee49c5c - std::rt::lang_start::{{closure}}::h6317b92bd7626759
  30:        0x10f5f5354 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h2302f1d25ef2ca9b
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:606:13
  31:        0x10f5f5354 - std::panicking::try::do_call::h6695e32a593de2cc
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40
  32:        0x10f5f5354 - std::panicking::try::hd4a93095627721a9
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19
  33:        0x10f5f5354 - std::panic::catch_unwind::he41b3dba63feca94
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14
  34:        0x10f5f5354 - std::rt::lang_start_internal::{{closure}}::hbf45583011495a61
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/rt.rs:148:48
  35:        0x10f5f5354 - std::panicking::try::do_call::ha3e6b3edab7da449
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40
  36:        0x10f5f5354 - std::panicking::try::hd4e0f354bf7022b9
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19
  37:        0x10f5f5354 - std::panic::catch_unwind::h1035b163871a4269
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14
  38:        0x10f5f5354 - std::rt::lang_start_internal::hd56d2fa7efb2dd60
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/rt.rs:148:20
  39:        0x10ee49cbc - _main
  40:     0x7ff80e547310 - <unknown>
error: Recipe `build-snapshots` failed with exit code 101

As always, i'm on the current master (10f8469).

Are index.redb files portable? If needed, I can upload the healthy one at 370000 which faces a panic soon after, and a snapshot another broken index that panics immidiately. I would also appreciate a recent snapshot.

[hantuzun]

I interrupted a healthy ord index to back up its index.redb. It shut down without any messages. The last log is:

[indexing blocks] █████████████████████░░░░░░░░░░░░░░░░░░░░░ 393913/774781

When I run it again, it increases the progress bar from 393,914 to 393,918, and panics with: 'range end index 74056 out of range for slice of length 4096'.

Here's the trace:

$ ord index
[indexing blocks] █████████████████████░░░░░░░░░░░░░░░░░░░░░ 393918/774793thread 'main' panicked at 'internal error: entered unreachable code', /Users/han/.cargo/registry/src/gitpro.ttaallkk.top-1ecc6299db9ec823/redb-0.12.1/src/tree_store/btree_mutator.rs:971:18
stack backtrace:
   0:        0x10cb8b216 - std::backtrace_rs::backtrace::libunwind::trace::h310cbd77a7d2ae59
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:        0x10cb8b216 - std::backtrace_rs::backtrace::trace_unsynchronized::h5768bae568840507
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:        0x10cb8b216 - std::sys_common::backtrace::_print_fmt::hd104a205649a2ffb
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:65:5
   3:        0x10cb8b216 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h521420ec33f3769d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:44:22
   4:        0x10cbac4ba - core::fmt::write::h694a0d7c23f57ada
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/fmt/mod.rs:1208:17
   5:        0x10cb8464c - std::io::Write::write_fmt::h1920a3973ad439e5
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/io/mod.rs:1682:15
   6:        0x10cb8affa - std::sys_common::backtrace::_print::h75582c4ed1a04abb
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:47:5
   7:        0x10cb8affa - std::sys_common::backtrace::print::hef1aa4dbdc07ee06
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:34:9
   8:        0x10cb8cc23 - std::panicking::default_hook::{{closure}}::h529701a1070b4ce0
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:267:22
   9:        0x10cb8c978 - std::panicking::default_hook::hfeeab2c667b2d7c2
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:286:9
  10:        0x10cb8d353 - std::panicking::rust_panic_with_hook::h1b5245192f90251d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:688:13
  11:        0x10cb8d0e3 - std::panicking::begin_panic_handler::{{closure}}::h3658f3a9566379d4
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:577:13
  12:        0x10cb8b6b8 - std::sys_common::backtrace::__rust_end_short_backtrace::h9e01645d962f8882
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:137:18
  13:        0x10cb8cded - rust_begin_unwind
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:575:5
  14:        0x10cbddad3 - core::panicking::panic_fmt::h0097ad8ec0b07517
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panicking.rs:64:14
  15:        0x10cbddba7 - core::panicking::panic::ha47a4f67bad0ba2d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panicking.rs:111:5
  16:        0x10c463712 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  17:        0x10c45fc46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  18:        0x10c45fc46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  19:        0x10c45fc46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  20:        0x10c45fc46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  21:        0x10c491fff - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete::h29ae2cb93920f9e8
  22:        0x10c5a3e3f - redb::tree_store::btree::BtreeMut<K,V>::remove::hb3e22d5a358d036a
  23:        0x10c5b90ce - ord::index::updater::inscription_updater::InscriptionUpdater::index_transaction_inscriptions::hb10f2eb470695894
  24:        0x10c4ad4db - ord::index::updater::Updater::update::hedc89b041ebaa722
  25:        0x10c4431a6 - ord::subcommand::index::run::hab3781d4830fe16d
  26:        0x10c68dc87 - ord::subcommand::Subcommand::run::hcbc1fe1f2071848e
  27:        0x10c5bcf1b - ord::main::h29af978464f7cf50
  28:        0x10c3d2c46 - std::sys_common::backtrace::__rust_begin_short_backtrace::h67a26858a530fb6d
  29:        0x10c3d2c5c - std::rt::lang_start::{{closure}}::h6317b92bd7626759
  30:        0x10cb7e354 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h2302f1d25ef2ca9b
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:606:13
  31:        0x10cb7e354 - std::panicking::try::do_call::h6695e32a593de2cc
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40
  32:        0x10cb7e354 - std::panicking::try::hd4a93095627721a9
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19
  33:        0x10cb7e354 - std::panic::catch_unwind::he41b3dba63feca94
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14
  34:        0x10cb7e354 - std::rt::lang_start_internal::{{closure}}::hbf45583011495a61
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/rt.rs:148:48
  35:        0x10cb7e354 - std::panicking::try::do_call::ha3e6b3edab7da449
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40
  36:        0x10cb7e354 - std::panicking::try::hd4e0f354bf7022b9
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19
  37:        0x10cb7e354 - std::panic::catch_unwind::h1035b163871a4269
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14
  38:        0x10cb7e354 - std::rt::lang_start_internal::hd56d2fa7efb2dd60
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/rt.rs:148:20
  39:        0x10c3d2cbc - _main
  40:     0x7ff80e547310 - <unknown>

[hantuzun]

I've snapshots at every 10k blocks.

• build-snapshosts starting at 370k: Panics at 370,116.

• build-snapshosts starting at 360k: Panics at 370,116.

• build-snapshosts starting at 350k: At 365054 and counting... Created a new 360k snaphot.

• index starting at 370k: Panics at 370,116.

• index starting at 360k: Panics at 370,116.

• index starting at 340k: At 591,896 and counting... I want to back this up but the last time I interrupted index resulted in: https://github.com/casey/ord/issues/1471#issuecomment-1414511606

Edit: One of those ord index processes crashed my macOS -- I don't know which and I don't have new data to add.

[hantuzun]

Start indexing from a snapshot at 590,000 and interrupt after a while:

$ rm index.redb && cp 590000.redb index.redb && ./ord --data-dir . index
[indexing blocks] ██████████████████████████████████████████████████████████████████████████████████████████░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ 590327/774879

Start indexing again. It interrupts shortly after:

$ ./ord --data-dir . index
[indexing blocks] ██████████████████████████████████████████████████████████████████████████████████████████░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ 590330/774880thread 'main' panicked at 'internal error: entered unreachable code', /Users/han/.cargo/registry/src/gitpro.ttaallkk.top-1ecc6299db9ec823/redb-0.12.1/src/tree_store/btree_mutator.rs:971:18
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Actually, the problem is not about interrupt. It can be replicated with gracefully stoping index even after a single block with height-limit:

$ rm index.redb && cp 590000.redb index.redb && RUST_BACKTRACE=full ./ord --data-dir . --height-limit 590001

████████████████████████████████████████████████████████████████████████████████████████████████████████░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ 590001/774875thread 'main' panicked at 'assertion failed: offset + len <= self.len()', /Users/han/.cargo/registry/src/gitpro.ttaallkk.top-1ecc6299db9ec823/redb-0.12.1/src/tree_store/page_store/mmap.rs:203:9
stack backtrace:
   0:        0x102f3d216 - std::backtrace_rs::backtrace::libunwind::trace::h310cbd77a7d2ae59
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:        0x102f3d216 - std::backtrace_rs::backtrace::trace_unsynchronized::h5768bae568840507
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:        0x102f3d216 - std::sys_common::backtrace::_print_fmt::hd104a205649a2ffb
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:65:5
   3:        0x102f3d216 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h521420ec33f3769d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:44:22
   4:        0x102f5e4ba - core::fmt::write::h694a0d7c23f57ada
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/fmt/mod.rs:1208:17
   5:        0x102f3664c - std::io::Write::write_fmt::h1920a3973ad439e5
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/io/mod.rs:1682:15
   6:        0x102f3cffa - std::sys_common::backtrace::_print::h75582c4ed1a04abb
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:47:5
   7:        0x102f3cffa - std::sys_common::backtrace::print::hef1aa4dbdc07ee06
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:34:9
   8:        0x102f3ec23 - std::panicking::default_hook::{{closure}}::h529701a1070b4ce0
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:267:22
   9:        0x102f3e978 - std::panicking::default_hook::hfeeab2c667b2d7c2
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:286:9
  10:        0x102f3f353 - std::panicking::rust_panic_with_hook::h1b5245192f90251d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:688:13
  11:        0x102f3f0e3 - std::panicking::begin_panic_handler::{{closure}}::h3658f3a9566379d4
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:577:13
  12:        0x102f3d6b8 - std::sys_common::backtrace::__rust_end_short_backtrace::h9e01645d962f8882
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:137:18
  13:        0x102f3eded - rust_begin_unwind
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:575:5
  14:        0x102f8fad3 - core::panicking::panic_fmt::h0097ad8ec0b07517
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panicking.rs:64:14
  15:        0x102f8fba7 - core::panicking::panic::ha47a4f67bad0ba2d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panicking.rs:111:5
  16:        0x102d6fc8e - <redb::tree_store::page_store::mmap::Mmap as redb::tree_store::page_store::base::PhysicalStorage>::read::h2eccff886d073f50
  17:        0x102d654ec - redb::tree_store::page_store::page_manager::TransactionalMemory::get_page::h2d2cb3307db7c74d
  18:        0x102811bd2 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  19:        0x102811c46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  20:        0x102811c46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  21:        0x102811c46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  22:        0x102843fff - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete::h29ae2cb93920f9e8
  23:        0x102955e3f - redb::tree_store::btree::BtreeMut<K,V>::remove::hb3e22d5a358d036a
  24:        0x10296b0ce - ord::index::updater::inscription_updater::InscriptionUpdater::index_transaction_inscriptions::hb10f2eb470695894
  25:        0x10285f4db - ord::index::updater::Updater::update::hedc89b041ebaa722
  26:        0x1027f51a6 - ord::subcommand::index::run::hab3781d4830fe16d
  27:        0x102a3fc87 - ord::subcommand::Subcommand::run::hcbc1fe1f2071848e
  28:        0x10296ef1b - ord::main::h29af978464f7cf50
  29:        0x102784c46 - std::sys_common::backtrace::__rust_begin_short_backtrace::h67a26858a530fb6d
  30:        0x102784c5c - std::rt::lang_start::{{closure}}::h6317b92bd7626759
  31:        0x102f30354 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h2302f1d25ef2ca9b
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:606:13
  32:        0x102f30354 - std::panicking::try::do_call::h6695e32a593de2cc
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40
  33:        0x102f30354 - std::panicking::try::hd4a93095627721a9
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19
  34:        0x102f30354 - std::panic::catch_unwind::he41b3dba63feca94
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14
  35:        0x102f30354 - std::rt::lang_start_internal::{{closure}}::hbf45583011495a61
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/rt.rs:148:48
  36:        0x102f30354 - std::panicking::try::do_call::ha3e6b3edab7da449
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40
  37:        0x102f30354 - std::panicking::try::hd4e0f354bf7022b9
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19
  38:        0x102f30354 - std::panic::catch_unwind::h1035b163871a4269
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14
  39:        0x102f30354 - std::rt::lang_start_internal::hd56d2fa7efb2dd60
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/rt.rs:148:20
  40:        0x102784cbc - _main
  41:     0x7ff816b30310 - <unknown>

One may ask, why bother? Just keep indexing from Keeps indexing from 590,000.

In that case, ord indexes until 595,000 where it panics.

[hantuzun]

My snapshot at 590,000 is 19732570112 bytes. I run ord index. As soon as the progress bar is printed, the index file size reduces to 18860756992. Afterwards, if I interrupt or say to stop at a block, the file size shrinks even further (Such as 18424852480 bytes when interrupted at 590,887). Running ord index from this smaller file, but supposed to include indexes of more blocks, panics.

[hantuzun]

I think I know where the bug could be: index.redb could have wrong number of heights. I've also got a case that where the loaded index.redb starts the progress from blocks never processed.

The index command panicked around 595,000 or 595,033:

$ rm 595000.redb index.redb&& cp 590000.redb index.redb&& RUST_BACKTRACE=full ./ord --data-dir . --height-limit 600000 index
[indexing blocks] ████████████████████████████████░░░░░░░░░░ 595000/774890[2023-02-03T17:22:24Z ERROR ord::index::updater] failed to fetch block 595033, retrying in 2s: JSON-RPC error: transport error: Couldn't connect to host: Broken pipe (os error 32)

Then, when I run the command again, the progress bar starts from 600,000 -- the height-limit of the previously panicked command:

$ RUST_BACKTRACE=full ./ord --data-dir . index
[indexing blocks] ████████████████████████████████░░░░░░░░░░ 600012/774894thread 'main' panicked at 'internal error: entered unreachable code', /Users/han/.cargo/registry/src/gitpro.ttaallkk.top-1ecc6299db9ec823/redb-0.12.1/src/tree_store/btree_mutator.rs:971:18
stack backtrace:
   0:        0x10bb87216 - std::backtrace_rs::backtrace::libunwind::trace::h310cbd77a7d2ae59
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:        0x10bb87216 - std::backtrace_rs::backtrace::trace_unsynchronized::h5768bae568840507
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:        0x10bb87216 - std::sys_common::backtrace::_print_fmt::hd104a205649a2ffb
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:65:5
   3:        0x10bb87216 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h521420ec33f3769d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:44:22
   4:        0x10bba84ba - core::fmt::write::h694a0d7c23f57ada
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/fmt/mod.rs:1208:17
   5:        0x10bb8064c - std::io::Write::write_fmt::h1920a3973ad439e5
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/io/mod.rs:1682:15
   6:        0x10bb86ffa - std::sys_common::backtrace::_print::h75582c4ed1a04abb
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:47:5
   7:        0x10bb86ffa - std::sys_common::backtrace::print::hef1aa4dbdc07ee06
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:34:9
   8:        0x10bb88c23 - std::panicking::default_hook::{{closure}}::h529701a1070b4ce0
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:267:22
   9:        0x10bb88978 - std::panicking::default_hook::hfeeab2c667b2d7c2
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:286:9
  10:        0x10bb89353 - std::panicking::rust_panic_with_hook::h1b5245192f90251d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:688:13
  11:        0x10bb890e3 - std::panicking::begin_panic_handler::{{closure}}::h3658f3a9566379d4
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:577:13
  12:        0x10bb876b8 - std::sys_common::backtrace::__rust_end_short_backtrace::h9e01645d962f8882
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:137:18
  13:        0x10bb88ded - rust_begin_unwind
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:575:5
  14:        0x10bbd9ad3 - core::panicking::panic_fmt::h0097ad8ec0b07517
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panicking.rs:64:14
  15:        0x10bbd9ba7 - core::panicking::panic::ha47a4f67bad0ba2d
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panicking.rs:111:5
  16:        0x10b45f712 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  17:        0x10b45bc46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  18:        0x10b45bc46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  19:        0x10b45bc46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  20:        0x10b45bc46 - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete_helper::h0f30e752f74cd4bf
  21:        0x10b48dfff - redb::tree_store::btree_mutator::MutateHelper<K,V>::delete::h29ae2cb93920f9e8
  22:        0x10b59fe3f - redb::tree_store::btree::BtreeMut<K,V>::remove::hb3e22d5a358d036a
  23:        0x10b5b50ce - ord::index::updater::inscription_updater::InscriptionUpdater::index_transaction_inscriptions::hb10f2eb470695894
  24:        0x10b4a94db - ord::index::updater::Updater::update::hedc89b041ebaa722
  25:        0x10b43f1a6 - ord::subcommand::index::run::hab3781d4830fe16d
  26:        0x10b689c87 - ord::subcommand::Subcommand::run::hcbc1fe1f2071848e
  27:        0x10b5b8f1b - ord::main::h29af978464f7cf50
  28:        0x10b3cec46 - std::sys_common::backtrace::__rust_begin_short_backtrace::h67a26858a530fb6d
  29:        0x10b3cec5c - std::rt::lang_start::{{closure}}::h6317b92bd7626759
  30:        0x10bb7a354 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h2302f1d25ef2ca9b
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:606:13
  31:        0x10bb7a354 - std::panicking::try::do_call::h6695e32a593de2cc
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40
  32:        0x10bb7a354 - std::panicking::try::hd4a93095627721a9
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19
  33:        0x10bb7a354 - std::panic::catch_unwind::he41b3dba63feca94
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14
  34:        0x10bb7a354 - std::rt::lang_start_internal::{{closure}}::hbf45583011495a61
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/rt.rs:148:48
  35:        0x10bb7a354 - std::panicking::try::do_call::ha3e6b3edab7da449
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40
  36:        0x10bb7a354 - std::panicking::try::hd4e0f354bf7022b9
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19
  37:        0x10bb7a354 - std::panic::catch_unwind::h1035b163871a4269
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14
  38:        0x10bb7a354 - std::rt::lang_start_internal::hd56d2fa7efb2dd60
                               at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/rt.rs:148:20
  39:        0x10b3cecbc - _main
  40:     0x7ff816b30310 - <unknown>

[hantuzun]

I replicated this issue on different machines, operating systems (macOS & Ubuntu), and processors (M1, Xeon on computer and on AWS).

I came across this over and over again: Let's say we've a snaphot index.redb with size A and hash X. I run ord index and it goes fine unless Interrupt it. If I interrupt it (and I observed with height limits as well) now index.redb has the same size A`` but a different hash Y`.

ord index with index.redb (Y) panics soon after. ord index with index.redb (X) passes that block without panic. However, sooner or later it will panic as well, and the index.redb file it leaves will behave like index.redb (Y), panicking soon after.

Now the The index.db size stays the same but changes its hash.

[brandonblack]

I've seem similar issues when running on redb 12.1 from master. Downgraded to 11.0 (previously committed version) and have reached height 626500 FWIW.

[casey]

Can you guys confirm that this is an issue with redb 12.1, and it doesn't appear on 11.0? If so, we can downgrade master to 11.0 easily. We're not relying on any new features in 12.1.

[hantuzun]

We're trying with redb master (cberner/redb@1293d4f) as suggested with @cberner. redb v0.11.0 doesn't have the suspected bug introduced by cberner/redb#476.

[casey]

This should be fixed by #1513! Thanks so much to @hantuzun and others for debugging and @cberner for shipping a fix so quickly, and on a weekend to boot.

[bliotti]

FYI

debug ENV var in Rust.
RUST_LOG=debug

example:
$ RUST_BACKTRACE=1 RUST_LOG=debug ord --rpc-url 172.16.0.3 --first-inscription-height 767430 index
@hantuzun

[bliotti]

Inconsistent start heights likely from commit and rollback transactions.
when process is stopped, data rows are rolled back to last commit.

[2023-02-06T11:27:46Z INFO  ord::index::updater] Wrote 0 sat ranges from 0 outputs in 63 ms

[2023-02-06T11:27:46Z INFO  ord::index::updater] Committing at block height 395033, 0 outputs traversed, 0 in map, 0 cached

[2023-02-06T11:27:46Z DEBUG bitcoincore_rpc] JSON-RPC request: getblockhash [395036]
[2023-02-06T11:27:46Z DEBUG bitcoincore_rpc] JSON-RPC request: getblock ["0000000000000000047b894238c6250b75f7ccb66ff80a56cd73debe0bda3dc0",0]

[casey]

FYI

debug ENV var in Rust. RUST_LOG=debug

example: $ RUST_BACKTRACE=1 RUST_LOG=debug ord --rpc-url 172.16.0.3 --first-inscription-height 767430 index @hantuzun

Definitely consider opening a discussion item like "how can i debug ord?" and then self-answer mentioning RUST_LOG. Also if it's not in the readme that would be a great PR.