fix(install): Bitcoin starting up is not a reason to refuse an install
Reproduced live: the operator pressed install on ElectrumX shortly after
Bitcoin Knots started and got
Bitcoin RPC returned 500 Internal Server Error while checking pruning
status: {"error":{"code":-28,"message":"Verifying blocks…"}}
-28 is RPC_IN_WARMUP — bitcoind's normal path on every start, lasting
minutes on a large chainstate. check_bitcoin_pruning_compatibility retried
`for _ in 0..3` with a 2s sleep, so it gave the node about six seconds and
then reported warm-up as a hard failure. Any app requiring unpruned Bitcoin
was therefore uninstallable in the ordinary window after Bitcoin starts.
This is the likely mechanism behind the operator's "fedimint gateway
disappeared at 88% install": both fedimint apps declare a bitcoin-core
dependency and sit in exactly that window.
The same install path already knew better. wait_for_bitcoin_rpc_gate waits
180s precisely because getblockchaininfo answers during sync. This check
runs earlier and disagreed — one concern, two contradictory answers, in one
install. It now shares the budget, and a test asserts the two stay equal.
Only NOT-READY is waited out: -28 by code, plus the "loading block index" /
"verifying blocks" / "rewinding blocks" message shapes for a proxy that
rewrites the envelope. A genuine fault — bad auth, method not found,
unparseable body — still ends the loop on the first response, so a broken
RPC fails fast instead of burning 180s. Both directions are pinned by tests,
because being too loose here is as bad as being too strict.
Warm-up is announced ONCE to the install log, so a slow install reads as
"waiting for Bitcoin" rather than a stall. And the failure message now says
what to do — "Bitcoin is still starting up… wait until it reports it's
synced, then try again" — instead of pasting the raw JSON-RPC envelope,
which was accurate and useless.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
co-authored by
Claude Opus 5
parent
ec0cfd1b7d
commit
b6010af10d
@@ -467,6 +467,55 @@ where
|
|||||||
/// ElectrumX and Mempool's Electrum backend need historical blocks from an
|
/// ElectrumX and Mempool's Electrum backend need historical blocks from an
|
||||||
/// unpruned node while building their indexes. A pruned Bitcoin node can be
|
/// unpruned node while building their indexes. A pruned Bitcoin node can be
|
||||||
/// running and RPC-reachable but still leave them stuck with closed ports.
|
/// running and RPC-reachable but still leave them stuck with closed ports.
|
||||||
|
/// How long to let Bitcoin finish starting before giving up on the pruning
|
||||||
|
/// pre-check. Matches `wait_for_bitcoin_rpc_gate`'s 180s so the two waits in
|
||||||
|
/// one install path agree about how patient "Bitcoin is starting" deserves to
|
||||||
|
/// be.
|
||||||
|
const BITCOIN_WARMUP_BUDGET: std::time::Duration = std::time::Duration::from_secs(180);
|
||||||
|
|
||||||
|
/// Is this JSON-RPC error bitcoind saying "not ready yet" rather than "broken"?
|
||||||
|
///
|
||||||
|
/// `-28` is RPC_IN_WARMUP: "Loading block index…", "Verifying blocks…",
|
||||||
|
/// "Rewinding blocks…". It is the normal path on every start, not a fault, and
|
||||||
|
/// it is the only error class worth waiting out — anything else (bad auth,
|
||||||
|
/// method not found) will not fix itself by retrying. Matched on the code, with
|
||||||
|
/// the message text as a fallback for any proxy that rewrites the envelope.
|
||||||
|
fn bitcoin_is_warming_up(error: &serde_json::Value) -> bool {
|
||||||
|
if error.get("code").and_then(serde_json::Value::as_i64) == Some(-28) {
|
||||||
|
return true;
|
||||||
|
}
|
||||||
|
error
|
||||||
|
.get("message")
|
||||||
|
.and_then(serde_json::Value::as_str)
|
||||||
|
.is_some_and(|m| {
|
||||||
|
let m = m.to_ascii_lowercase();
|
||||||
|
m.contains("loading block index")
|
||||||
|
|| m.contains("verifying blocks")
|
||||||
|
|| m.contains("rewinding blocks")
|
||||||
|
|| m.contains("loading wallet")
|
||||||
|
|| m.contains("starting network threads")
|
||||||
|
})
|
||||||
|
}
|
||||||
|
|
||||||
|
/// Say once, in the install log, that we are waiting on Bitcoin — so a slow
|
||||||
|
/// install reads as "waiting for Bitcoin" instead of a stall, without one line
|
||||||
|
/// every two seconds.
|
||||||
|
async fn announce_warmup(announced: &mut bool, package_id: &str, error: &serde_json::Value) {
|
||||||
|
if *announced {
|
||||||
|
return;
|
||||||
|
}
|
||||||
|
*announced = true;
|
||||||
|
let detail = error
|
||||||
|
.get("message")
|
||||||
|
.and_then(serde_json::Value::as_str)
|
||||||
|
.unwrap_or("starting up");
|
||||||
|
super::install::install_log(&format!(
|
||||||
|
"INSTALL WAIT: {package_id} — Bitcoin is still starting ({detail}); waiting up to {}s before the pruning check",
|
||||||
|
BITCOIN_WARMUP_BUDGET.as_secs()
|
||||||
|
))
|
||||||
|
.await;
|
||||||
|
}
|
||||||
|
|
||||||
pub(super) async fn check_bitcoin_pruning_compatibility(package_id: &str) -> Result<()> {
|
pub(super) async fn check_bitcoin_pruning_compatibility(package_id: &str) -> Result<()> {
|
||||||
if !requires_unpruned_bitcoin(package_id) {
|
if !requires_unpruned_bitcoin(package_id) {
|
||||||
return Ok(());
|
return Ok(());
|
||||||
@@ -485,8 +534,27 @@ pub(super) async fn check_bitcoin_pruning_compatibility(package_id: &str) -> Res
|
|||||||
.build()
|
.build()
|
||||||
.context("building Bitcoin RPC client")?;
|
.context("building Bitcoin RPC client")?;
|
||||||
|
|
||||||
|
// Bitcoin's warm-up is not a failure, and this check used to treat it as
|
||||||
|
// one. `for _ in 0..3` with a 2s sleep gave the node about six seconds to
|
||||||
|
// answer; bitcoind replies `-28` ("Loading block index…", "Verifying
|
||||||
|
// blocks…") for MINUTES on a large chainstate. So pressing install on any
|
||||||
|
// app that needs unpruned Bitcoin, in the ordinary window after Bitcoin
|
||||||
|
// starts, failed with a raw JSON-RPC error — reproduced on archi-dev-box
|
||||||
|
// 2026-08-08 installing ElectrumX right after Bitcoin Knots came up, and
|
||||||
|
// the likely mechanism behind "fedimint gateway disappeared at 88%
|
||||||
|
// install".
|
||||||
|
//
|
||||||
|
// The same install path already knows better: `wait_for_bitcoin_rpc_gate`
|
||||||
|
// waits up to 180s precisely because getblockchaininfo answers during
|
||||||
|
// sync. This check runs earlier and now shares that budget, so one concern
|
||||||
|
// is not handled two contradictory ways in one install.
|
||||||
|
//
|
||||||
|
// Only NOT-READY is waited out. A genuine fault — bad auth, connection
|
||||||
|
// refused, garbage response — still ends the loop on its own terms below.
|
||||||
|
let deadline = tokio::time::Instant::now() + BITCOIN_WARMUP_BUDGET;
|
||||||
let mut last_error = None;
|
let mut last_error = None;
|
||||||
for _ in 0..3 {
|
let mut announced_warmup = false;
|
||||||
|
loop {
|
||||||
match client
|
match client
|
||||||
.post(crate::constants::BITCOIN_RPC_URL)
|
.post(crate::constants::BITCOIN_RPC_URL)
|
||||||
.basic_auth(&rpc_user, Some(&rpc_pass))
|
.basic_auth(&rpc_user, Some(&rpc_pass))
|
||||||
@@ -500,17 +568,33 @@ pub(super) async fn check_bitcoin_pruning_compatibility(package_id: &str) -> Res
|
|||||||
match resp.json::<serde_json::Value>().await {
|
match resp.json::<serde_json::Value>().await {
|
||||||
Ok(json) if status.is_success() => {
|
Ok(json) if status.is_success() => {
|
||||||
if let Some(error) = json.get("error").filter(|e| !e.is_null()) {
|
if let Some(error) = json.get("error").filter(|e| !e.is_null()) {
|
||||||
last_error = Some(format!(
|
if bitcoin_is_warming_up(error) {
|
||||||
"Bitcoin RPC error while checking pruning status: {error}"
|
announce_warmup(&mut announced_warmup, package_id, error).await;
|
||||||
));
|
} else {
|
||||||
|
last_error = Some(format!(
|
||||||
|
"Bitcoin RPC error while checking pruning status: {error}"
|
||||||
|
));
|
||||||
|
}
|
||||||
} else {
|
} else {
|
||||||
return check_blockchain_info_for_pruning(package_id, &json);
|
return check_blockchain_info_for_pruning(package_id, &json);
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
// bitcoind answers -28 with an HTTP 500, so warm-up lands
|
||||||
|
// here rather than in the success arm above.
|
||||||
Ok(json) => {
|
Ok(json) => {
|
||||||
last_error = Some(format!(
|
let rpc_error = json.get("error").filter(|e| !e.is_null());
|
||||||
"Bitcoin RPC returned {status} while checking pruning status: {json}"
|
if rpc_error.is_some_and(bitcoin_is_warming_up) {
|
||||||
));
|
announce_warmup(
|
||||||
|
&mut announced_warmup,
|
||||||
|
package_id,
|
||||||
|
rpc_error.unwrap_or(&serde_json::Value::Null),
|
||||||
|
)
|
||||||
|
.await;
|
||||||
|
} else {
|
||||||
|
last_error = Some(format!(
|
||||||
|
"Bitcoin RPC returned {status} while checking pruning status: {json}"
|
||||||
|
));
|
||||||
|
}
|
||||||
}
|
}
|
||||||
Err(e) => {
|
Err(e) => {
|
||||||
last_error = Some(format!("decode Bitcoin RPC response: {e}"));
|
last_error = Some(format!("decode Bitcoin RPC response: {e}"));
|
||||||
@@ -521,6 +605,17 @@ pub(super) async fn check_bitcoin_pruning_compatibility(package_id: &str) -> Res
|
|||||||
last_error = Some(format!("checking Bitcoin pruning status: {e}"));
|
last_error = Some(format!("checking Bitcoin pruning status: {e}"));
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
// A real fault ends the wait immediately — only NOT-READY loops.
|
||||||
|
if last_error.is_some() {
|
||||||
|
break;
|
||||||
|
}
|
||||||
|
if tokio::time::Instant::now() >= deadline {
|
||||||
|
last_error = Some(format!(
|
||||||
|
"Bitcoin was still starting up after {}s while checking pruning status",
|
||||||
|
BITCOIN_WARMUP_BUDGET.as_secs()
|
||||||
|
));
|
||||||
|
break;
|
||||||
|
}
|
||||||
tokio::time::sleep(std::time::Duration::from_secs(2)).await;
|
tokio::time::sleep(std::time::Duration::from_secs(2)).await;
|
||||||
}
|
}
|
||||||
|
|
||||||
@@ -528,10 +623,19 @@ pub(super) async fn check_bitcoin_pruning_compatibility(package_id: &str) -> Res
|
|||||||
anyhow::bail!(archival_bitcoin_required_message(package_id));
|
anyhow::bail!(archival_bitcoin_required_message(package_id));
|
||||||
}
|
}
|
||||||
|
|
||||||
anyhow::bail!(
|
// Say what the operator can act on. The old message pasted the raw
|
||||||
"Bitcoin RPC unavailable while checking pruning status: {}",
|
// JSON-RPC envelope, so a node that was merely still starting reported
|
||||||
last_error.unwrap_or_else(|| "unknown error".to_string())
|
// `{"error":{"code":-28,"message":"Verifying blocks…"}}` — accurate and
|
||||||
);
|
// useless to anyone deciding what to do next.
|
||||||
|
let detail = last_error.unwrap_or_else(|| "unknown error".to_string());
|
||||||
|
if announced_warmup {
|
||||||
|
anyhow::bail!(
|
||||||
|
"Bitcoin is still starting up, so {package_id} can't be installed yet. \
|
||||||
|
This can take several minutes on a large chain. Wait until Bitcoin \
|
||||||
|
reports it's synced, then try again. (Details: {detail})"
|
||||||
|
);
|
||||||
|
}
|
||||||
|
anyhow::bail!("Bitcoin RPC unavailable while checking pruning status: {detail}");
|
||||||
}
|
}
|
||||||
|
|
||||||
fn check_blockchain_info_for_pruning(package_id: &str, json: &serde_json::Value) -> Result<()> {
|
fn check_blockchain_info_for_pruning(package_id: &str, json: &serde_json::Value) -> Result<()> {
|
||||||
@@ -769,8 +873,9 @@ pub(super) fn configure_fedimint_lnd(
|
|||||||
#[cfg(test)]
|
#[cfg(test)]
|
||||||
mod tests {
|
mod tests {
|
||||||
use super::{
|
use super::{
|
||||||
dependency_list_declares_archival_bitcoin, manifest_declares_archival_bitcoin,
|
bitcoin_is_warming_up, dependency_list_declares_archival_bitcoin,
|
||||||
order_present_containers, requires_unpruned_bitcoin, startup_order,
|
manifest_declares_archival_bitcoin, order_present_containers, requires_unpruned_bitcoin,
|
||||||
|
startup_order, BITCOIN_WARMUP_BUDGET,
|
||||||
};
|
};
|
||||||
use archipelago_container::Dependency;
|
use archipelago_container::Dependency;
|
||||||
|
|
||||||
@@ -1218,4 +1323,55 @@ mod tests {
|
|||||||
// (bitcoin_integration.rpc_access: none) and correctly stays excluded.
|
// (bitcoin_integration.rpc_access: none) and correctly stays excluded.
|
||||||
assert!(!requires_unpruned_bitcoin("archy-mempool-web"));
|
assert!(!requires_unpruned_bitcoin("archy-mempool-web"));
|
||||||
}
|
}
|
||||||
|
|
||||||
|
/// The distinction the pruning pre-check now turns on: bitcoind saying
|
||||||
|
/// "not ready yet" must be waited out, everything else must fail fast.
|
||||||
|
/// Getting this wrong in either direction is a real bug — too strict and
|
||||||
|
/// installs fail during every startup window (the ElectrumX failure on
|
||||||
|
/// archi-dev-box, 2026-08-08); too loose and a genuinely broken RPC hangs
|
||||||
|
/// the install for the full budget.
|
||||||
|
#[test]
|
||||||
|
fn warmup_is_recognised_by_code_and_by_message() {
|
||||||
|
let by_code = serde_json::json!({"code": -28, "message": "Verifying blocks…"});
|
||||||
|
assert!(bitcoin_is_warming_up(&by_code));
|
||||||
|
|
||||||
|
// The exact payload that failed the ElectrumX install.
|
||||||
|
let observed = serde_json::json!({"code": -28, "message": "Verifying blocks…"});
|
||||||
|
assert!(bitcoin_is_warming_up(&observed));
|
||||||
|
|
||||||
|
// Message fallback, for a proxy that rewrites the envelope and drops
|
||||||
|
// the code.
|
||||||
|
for msg in [
|
||||||
|
"Loading block index...",
|
||||||
|
"Verifying blocks…",
|
||||||
|
"Rewinding blocks...",
|
||||||
|
"LOADING BLOCK INDEX",
|
||||||
|
] {
|
||||||
|
let e = serde_json::json!({ "message": msg });
|
||||||
|
assert!(bitcoin_is_warming_up(&e), "should be warm-up: {msg}");
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
#[test]
|
||||||
|
fn real_faults_are_not_mistaken_for_warmup() {
|
||||||
|
// These never fix themselves by waiting, so they must end the loop
|
||||||
|
// immediately rather than burn the full 180s budget.
|
||||||
|
for e in [
|
||||||
|
serde_json::json!({"code": -32601, "message": "Method not found"}),
|
||||||
|
serde_json::json!({"code": -1, "message": "unauthorized"}),
|
||||||
|
serde_json::json!({"message": "Work queue depth exceeded"}),
|
||||||
|
serde_json::json!({}),
|
||||||
|
serde_json::Value::Null,
|
||||||
|
] {
|
||||||
|
assert!(!bitcoin_is_warming_up(&e), "should NOT be warm-up: {e}");
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
#[test]
|
||||||
|
fn the_warmup_budget_matches_the_other_bitcoin_wait_in_this_install_path() {
|
||||||
|
// install.rs's wait_for_bitcoin_rpc_gate waits 180s for the same
|
||||||
|
// condition. Two different answers to "how long is Bitcoin allowed to
|
||||||
|
// be starting?" in one install is how this bug happened.
|
||||||
|
assert_eq!(BITCOIN_WARMUP_BUDGET.as_secs(), 180);
|
||||||
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
Reference in New Issue
Block a user