Database locked on 3.1.0.0.0

[wileyj]

WARN [1733917813.641069] [stacks-common/./src/util/db.rs:83] [p2p-(0.0.0.0:20444,0.0.0.0:20443)] Database is locked; sleeping 108ms and trying again, run_count: 74720

full log entry shared:

WARN [1733917813.641069] [stacks-common/./src/util/db.rs:83] [p2p-(0.0.0.0:20444,0.0.0.0:20443)] Database is locked; sleeping 108ms and trying again, run_count: 74720, backtrace: Backtrace [{ fn: "stacks_common::util::db::tx_busy_handler", file: "./build/stacks-common/./src/util/db.rs", line: 85 }, { fn: "blockstack_lib::util_lib::db::tx_busy_handler", file: "./build/stackslib/src/util_lib/db.rs", line: 661 }, { fn: "rusqlite::busy::<impl rusqlite::Connection>::busy_handler::busy_handler_callback::{{closure}}", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/rusqlite-0.31.0/src/busy.rs", line: 61 }, { fn: "std::panicking::try::do_call", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/std/src/panicking.rs", line: 557 }, { fn: "std::panicking::try", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/std/src/panicking.rs", line: 520 }, { fn: "std::panic::catch_unwind", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/std/src/panic.rs", line: 358 }, { fn: "rusqlite::busy::<impl rusqlite::Connection>::busy_handler::busy_handler_callback", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/rusqlite-0.31.0/src/busy.rs", line: 61 }, { fn: "sqlite3InvokeBusyHandler", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/libsqlite3-sys-0.28.0/sqlite3/sqlite3.c", line: 179852 }, { fn: "btreeInvokeBusyHandler", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/libsqlite3-sys-0.28.0/sqlite3/sqlite3.c", line: 72572 }, { fn: "btreeBeginTrans", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/libsqlite3-sys-0.28.0/sqlite3/sqlite3.c", line: 73769 }, { fn: "sqlite3BtreeBeginTrans", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/libsqlite3-sys-0.28.0/sqlite3/sqlite3.c", line: 73839 }, { fn: "sqlite3VdbeExec", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/libsqlite3-sys-0.28.0/sqlite3/sqlite3.c", line: 96577 }, { fn: "sqlite3Step", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/libsqlite3-sys-0.28.0/sqlite3/sqlite3.c", line: 90654 }, { fn: "sqlite3_step", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/libsqlite3-sys-0.28.0/sqlite3/sqlite3.c", line: 90715 }, { fn: "sqlite3_step", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/libsqlite3-sys-0.28.0/sqlite3/sqlite3.c", line: 90704 }, { fn: "rusqlite::raw_statement::RawStatement::step", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/rusqlite-0.31.0/src/raw_statement.rs", line: 106 }, { fn: "rusqlite::statement::Statement::step", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/rusqlite-0.31.0/src/statement.rs", line: 852 }, { fn: "rusqlite::Connection::execute_batch", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/rusqlite-0.31.0/src/lib.rs", line: 556 }, { fn: "rusqlite::transaction::Transaction::new_unchecked", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/rusqlite-0.31.0/src/transaction.rs", line: 125 }, { fn: "rusqlite::transaction::Transaction::new", file: "./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/rusqlite-0.31.0/src/transaction.rs", line: 107 }, { fn: "blockstack_lib::util_lib::db::tx_begin_immediate_sqlite", file: "./build/stackslib/src/util_lib/db.rs", line: 677 }, { fn: "blockstack_lib::util_lib::db::tx_begin_immediate", file: "./build/stackslib/src/util_lib/db.rs", line: 668 }, { fn: "blockstack_lib::core::mempool::MemPoolDB::tx_begin", file: "./build/stackslib/src/core/mempool.rs", line: 1957 }, { fn: "blockstack_lib::core::mempool::MemPoolDB::submit", file: "./build/stackslib/src/core/mempool.rs", line: 2456 }, { fn: "<blockstack_lib::net::api::posttransaction::RPCPostTransactionRequestHandler as blockstack_lib::net::httpcore::RPCRequestHandler>::try_handle_request::{{closure}}", file: "./build/stackslib/src/net/api/posttransaction.rs", line: 233 }, { fn: "blockstack_lib::net::StacksNodeState::with_node_state", file: "./build/stackslib/src/net/mod.rs", line: 715 }, { fn: "<blockstack_lib::net::api::posttransaction::RPCPostTransactionRequestHandler as blockstack_lib::net::httpcore::RPCRequestHandler>::try_handle_request", file: "./build/stackslib/src/net/api/posttransaction.rs", line: 200 }, { fn: "blockstack_lib::net::httpcore::StacksHttp::try_handle_request", file: "./build/stackslib/src/net/httpcore.rs", line: 1194 }, { fn: "blockstack_lib::net::rpc::ConversationHttp::handle_request", file: "./build/stackslib/src/net/rpc.rs", line: 274 }, { fn: "blockstack_lib::net::rpc::ConversationHttp::chat::{{closure}}", file: "./build/stackslib/src/net/rpc.rs", line: 548 }, { fn: "blockstack_lib::monitoring::instrument_http_request_handler", file: "./build/stackslib/src/monitoring/mod.rs", line: 65 }, { fn: "blockstack_lib::net::rpc::ConversationHttp::chat", file: "./build/stackslib/src/net/rpc.rs", line: 545 }, { fn: "blockstack_lib::net::server::HttpPeer::process_http_conversation", file: "./build/stackslib/src/net/server.rs", line: 487 }, { fn: "blockstack_lib::net::server::HttpPeer::process_ready_sockets", file: "./build/stackslib/src/net/server.rs", line: 573 }, { fn: "blockstack_lib::net::server::HttpPeer::run", file: "./build/stackslib/src/net/server.rs", line: 646 }, { fn: "blockstack_lib::net::p2p::PeerNetwork::run::{{closure}}::{{closure}}", file: "./build/stackslib/src/net/p2p.rs", line: 5291 }, { fn: "blockstack_lib::net::p2p::PeerNetwork::with_http", file: "./build/stackslib/src/net/p2p.rs", line: 663 }, { fn: "blockstack_lib::net::p2p::PeerNetwork::run::{{closure}}", file: "./build/stackslib/src/net/p2p.rs", line: 5288 }, { fn: "blockstack_lib::net::p2p::PeerNetwork::with_network_state", file: "./build/stackslib/src/net/p2p.rs", line: 865 }, { fn: "blockstack_lib::net::p2p::PeerNetwork::run", file: "./build/stackslib/src/net/p2p.rs", line: 5287 }, { fn: "stacks_node::nakamoto_node::peer::PeerThread::run_one_pass", file: "./build/testnet/stacks-node/src/nakamoto_node/peer.rs", line: 278 }, { fn: "stacks_node::nakamoto_node::peer::PeerThread::main", file: "./build/testnet/stacks-node/src/nakamoto_node/peer.rs", line: 112 }, { fn: "stacks_node::nakamoto_node::StacksNode::spawn::{{closure}}", file: "./build/testnet/stacks-node/src/nakamoto_node.rs", line: 259 }, { fn: "std::sys::backtrace::__rust_begin_short_backtrace", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/std/src/sys/backtrace.rs", line: 154 }, { fn: "std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/std/src/thread/mod.rs", line: 538 }, { fn: "<core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/core/src/panic/unwind_safe.rs", line: 272 }, { fn: "std::panicking::try::do_call", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/std/src/panicking.rs", line: 557 }, { fn: "std::panicking::try", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/std/src/panicking.rs", line: 520 }, { fn: "std::panic::catch_unwind", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/std/src/panic.rs", line: 358 }, { fn: "std::thread::Builder::spawn_unchecked_::{{closure}}", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/std/src/thread/mod.rs", line: 537 }, { fn: "core::ops::function::FnOnce::call_once{{vtable.shim}}", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/core/src/ops/function.rs", line: 250 }, { fn: "<alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/alloc/src/boxed.rs", line: 2454 }, { fn: "<alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/alloc/src/boxed.rs", line: 2454 }, { fn: "std::sys::pal::unix::thread::Thread::new::thread_start", file: "./rustc/90b35a6239c3d8bdabc530a6a0816f7ff89a0aaf/library/std/src/sys/pal/unix/thread.rs", line: 105 }, { fn: "__clone" }]

[jcnelson]

If this node has an event observer, and it has been stalled for this long, there's a chance that the node itself is going to stall due to a deadlock.

This backtrace is not a a panic; it's a Backtrace struct that gets logged every 10 attempts to lock the underlying DB. Every 3,000 attempts, it prints an ERRO with the database lock table entry.

What is needed is to determine the root cause of this large number of lock attempts. That should essentially never happen. It may be due to a slow event observer, for example.==

There's a case to be made for reverting the panicking behavior -- it can get it out of this deadlock state. But this had been removed earlier because it led to unnecessary panics.

[jcnelson]

@wileyj Looking at the stack trace here, I see that it was caused in the HTTP handler for a mempool transaction POST request. The code that handles this opens a DB transaction on the mempool DB, and will hold it open until it can upload an event to the event observer about the newly-arrived transaction. I wonder if this is the reason why you see public nodes occasionally freeze up, but not private ones? Public ones will be getting HTTP-submitted transactions all the time.

[wileyj]

#5663

not quite the same issue, but they may be related (logs attached to linked issue). basically, there were a flood of mempool http requests, at which point the node (when public) starts to fall behind and never recovers until a restart.
disabling the ports publicly allows the node to stay in sync (by virtue of blocking the http requests).