Merge bitcoin/bitcoin#30497: rpc: Return errors in loadtxoutset that currently go to logs

fa530ec543 rpc: Return precise loadtxoutset error messages (MarcoFalke)
faa5c86dbf refactor: Use untranslated error message in ActivateSnapshot (MarcoFalke)

Pull request description:

  The error messages should never happen in normal operation. However, if
  they do, they are helpful to return to the user to debug the issue. For
  example, to notice a truncated file.

  This fixes https://github.com/bitcoin/bitcoin/issues/28621

  Also includes a minor refactor commit.

ACKs for top commit:
  fjahr:
    Code review ACK fa530ec543
  ryanofsky:
    Code review ACK fa530ec543, just adjusting error messages a little since last review. (Thanks!)

Tree-SHA512: 224968c9b13d082ca2ed1f6a8fcc5f51ff16d6c96bd38c3679699505b54337b99cccaf7a8474391f6b11f9ccb101977b4e626898c1217eae95802e290cf105f1
This commit is contained in:
Ryan Ofsky 2024-08-05 12:46:33 -04:00
commit 69df012e74
No known key found for this signature in database
GPG Key ID: 46800E30FC748A66
3 changed files with 38 additions and 49 deletions

View File

@ -1,5 +1,5 @@
// Copyright (c) 2009-2010 Satoshi Nakamoto
// Copyright (c) 2009-2022 The Bitcoin Core developers
// Copyright (c) 2009-present The Bitcoin Core developers
// Distributed under the MIT software license, see the accompanying
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
@ -5681,7 +5681,7 @@ util::Result<void> ChainstateManager::ActivateSnapshot(
}
if (!m_best_header || m_best_header->GetAncestor(base_blockheight) != snapshot_start_block) {
return util::Error{_("A forked headers-chain with more work than the chain with the snapshot base block header exists. Please proceed to sync without AssumeUtxo.")};
return util::Error{Untranslated("A forked headers-chain with more work than the chain with the snapshot base block header exists. Please proceed to sync without AssumeUtxo.")};
}
auto mempool{m_active_chainstate->GetMempool()};
@ -5735,7 +5735,7 @@ util::Result<void> ChainstateManager::ActivateSnapshot(
static_cast<size_t>(current_coinstip_cache_size * SNAPSHOT_CACHE_PERC));
}
auto cleanup_bad_snapshot = [&](bilingual_str&& reason) EXCLUSIVE_LOCKS_REQUIRED(::cs_main) {
auto cleanup_bad_snapshot = [&](bilingual_str reason) EXCLUSIVE_LOCKS_REQUIRED(::cs_main) {
this->MaybeRebalanceCaches();
// PopulateAndValidateSnapshot can return (in error) before the leveldb datadir
@ -5754,9 +5754,9 @@ util::Result<void> ChainstateManager::ActivateSnapshot(
return util::Error{std::move(reason)};
};
if (!this->PopulateAndValidateSnapshot(*snapshot_chainstate, coins_file, metadata)) {
if (auto res{this->PopulateAndValidateSnapshot(*snapshot_chainstate, coins_file, metadata)}; !res) {
LOCK(::cs_main);
return cleanup_bad_snapshot(Untranslated("population failed"));
return cleanup_bad_snapshot(strprintf(Untranslated("Population failed: %s"), util::ErrorString(res)));
}
LOCK(::cs_main); // cs_main required for rest of snapshot activation.
@ -5821,7 +5821,7 @@ static void SnapshotUTXOHashBreakpoint(const util::SignalInterrupt& interrupt)
if (interrupt) throw StopHashingException();
}
bool ChainstateManager::PopulateAndValidateSnapshot(
util::Result<void> ChainstateManager::PopulateAndValidateSnapshot(
Chainstate& snapshot_chainstate,
AutoFile& coins_file,
const SnapshotMetadata& metadata)
@ -5837,18 +5837,16 @@ bool ChainstateManager::PopulateAndValidateSnapshot(
if (!snapshot_start_block) {
// Needed for ComputeUTXOStats to determine the
// height and to avoid a crash when base_blockhash.IsNull()
LogPrintf("[snapshot] Did not find snapshot start blockheader %s\n",
base_blockhash.ToString());
return false;
return util::Error{strprintf(Untranslated("Did not find snapshot start blockheader %s"),
base_blockhash.ToString())};
}
int base_height = snapshot_start_block->nHeight;
const auto& maybe_au_data = GetParams().AssumeutxoForHeight(base_height);
if (!maybe_au_data) {
LogPrintf("[snapshot] assumeutxo height in snapshot metadata not recognized "
"(%d) - refusing to load snapshot\n", base_height);
return false;
return util::Error{strprintf(Untranslated("Assumeutxo height in snapshot metadata not recognized "
"(%d) - refusing to load snapshot"), base_height)};
}
const AssumeutxoData& au_data = *maybe_au_data;
@ -5857,8 +5855,7 @@ bool ChainstateManager::PopulateAndValidateSnapshot(
// ActivateSnapshot(), but is done so that we avoid doing the long work of staging
// a snapshot that isn't actually usable.
if (WITH_LOCK(::cs_main, return !CBlockIndexWorkComparator()(ActiveTip(), snapshot_start_block))) {
LogPrintf("[snapshot] activation failed - work does not exceed active chainstate\n");
return false;
return util::Error{Untranslated("Work does not exceed active chainstate")};
}
const uint64_t coins_count = metadata.m_coins_count;
@ -5875,8 +5872,7 @@ bool ChainstateManager::PopulateAndValidateSnapshot(
coins_per_txid = ReadCompactSize(coins_file);
if (coins_per_txid > coins_left) {
LogPrintf("[snapshot] mismatch in coins count in snapshot metadata and actual snapshot data\n");
return false;
return util::Error{Untranslated("Mismatch in coins count in snapshot metadata and actual snapshot data")};
}
for (size_t i = 0; i < coins_per_txid; i++) {
@ -5888,14 +5884,12 @@ bool ChainstateManager::PopulateAndValidateSnapshot(
if (coin.nHeight > base_height ||
outpoint.n >= std::numeric_limits<decltype(outpoint.n)>::max() // Avoid integer wrap-around in coinstats.cpp:ApplyHash
) {
LogPrintf("[snapshot] bad snapshot data after deserializing %d coins\n",
coins_count - coins_left);
return false;
return util::Error{strprintf(Untranslated("Bad snapshot data after deserializing %d coins"),
coins_count - coins_left)};
}
if (!MoneyRange(coin.out.nValue)) {
LogPrintf("[snapshot] bad snapshot data after deserializing %d coins - bad tx out value\n",
coins_count - coins_left);
return false;
return util::Error{strprintf(Untranslated("Bad snapshot data after deserializing %d coins - bad tx out value"),
coins_count - coins_left)};
}
coins_cache.EmplaceCoinInternalDANGER(std::move(outpoint), std::move(coin));
@ -5915,7 +5909,7 @@ bool ChainstateManager::PopulateAndValidateSnapshot(
// means <5MB of memory imprecision.
if (coins_processed % 120000 == 0) {
if (m_interrupt) {
return false;
return util::Error{Untranslated("Aborting after an interrupt was requested")};
}
const auto snapshot_cache_state = WITH_LOCK(::cs_main,
@ -5933,9 +5927,8 @@ bool ChainstateManager::PopulateAndValidateSnapshot(
}
}
} catch (const std::ios_base::failure&) {
LogPrintf("[snapshot] bad snapshot format or truncated snapshot after deserializing %d coins\n",
coins_processed);
return false;
return util::Error{strprintf(Untranslated("Bad snapshot format or truncated snapshot after deserializing %d coins"),
coins_processed)};
}
}
@ -5955,9 +5948,8 @@ bool ChainstateManager::PopulateAndValidateSnapshot(
out_of_coins = true;
}
if (!out_of_coins) {
LogPrintf("[snapshot] bad snapshot - coins left over after deserializing %d coins\n",
coins_count);
return false;
return util::Error{strprintf(Untranslated("Bad snapshot - coins left over after deserializing %d coins"),
coins_count)};
}
LogPrintf("[snapshot] loaded %d (%.2f MB) coins from snapshot %s\n",
@ -5980,18 +5972,16 @@ bool ChainstateManager::PopulateAndValidateSnapshot(
maybe_stats = ComputeUTXOStats(
CoinStatsHashType::HASH_SERIALIZED, snapshot_coinsdb, m_blockman, [&interrupt = m_interrupt] { SnapshotUTXOHashBreakpoint(interrupt); });
} catch (StopHashingException const&) {
return false;
return util::Error{Untranslated("Aborting after an interrupt was requested")};
}
if (!maybe_stats.has_value()) {
LogPrintf("[snapshot] failed to generate coins stats\n");
return false;
return util::Error{Untranslated("Failed to generate coins stats")};
}
// Assert that the deserialized chainstate contents match the expected assumeutxo value.
if (AssumeutxoHash{maybe_stats->hashSerialized} != au_data.hash_serialized) {
LogPrintf("[snapshot] bad snapshot content hash: expected %s, got %s\n",
au_data.hash_serialized.ToString(), maybe_stats->hashSerialized.ToString());
return false;
return util::Error{strprintf(Untranslated("Bad snapshot content hash: expected %s, got %s"),
au_data.hash_serialized.ToString(), maybe_stats->hashSerialized.ToString())};
}
snapshot_chainstate.m_chain.SetTip(*snapshot_start_block);
@ -6031,7 +6021,7 @@ bool ChainstateManager::PopulateAndValidateSnapshot(
LogPrintf("[snapshot] validated snapshot (%.2f MB)\n",
coins_cache.DynamicMemoryUsage() / (1000 * 1000));
return true;
return {};
}
// Currently, this function holds cs_main for its duration, which could be for

View File

@ -918,7 +918,7 @@ private:
//! To reduce space the serialization format of the snapshot avoids
//! duplication of tx hashes. The code takes advantage of the guarantee by
//! leveldb that keys are lexicographically sorted.
[[nodiscard]] bool PopulateAndValidateSnapshot(
[[nodiscard]] util::Result<void> PopulateAndValidateSnapshot(
Chainstate& snapshot_chainstate,
AutoFile& coins_file,
const node::SnapshotMetadata& metadata);

View File

@ -60,9 +60,8 @@ class AssumeutxoTest(BitcoinTestFramework):
bad_snapshot_path = valid_snapshot_path + '.mod'
node = self.nodes[1]
def expected_error(log_msg="", rpc_details=""):
with node.assert_debug_log([log_msg]):
assert_raises_rpc_error(-32603, f"Unable to load UTXO snapshot{rpc_details}", node.loadtxoutset, bad_snapshot_path)
def expected_error(msg):
assert_raises_rpc_error(-32603, f"Unable to load UTXO snapshot: Population failed: {msg}", node.loadtxoutset, bad_snapshot_path)
self.log.info(" - snapshot file with invalid file magic")
parsing_error_code = -22
@ -114,19 +113,19 @@ class AssumeutxoTest(BitcoinTestFramework):
f.write(valid_snapshot_contents[:47])
f.write((valid_num_coins + off).to_bytes(8, "little"))
f.write(valid_snapshot_contents[47 + 8:])
expected_error(log_msg=f"bad snapshot - coins left over after deserializing 298 coins" if off == -1 else f"bad snapshot format or truncated snapshot after deserializing 299 coins")
expected_error(msg="Bad snapshot - coins left over after deserializing 298 coins." if off == -1 else "Bad snapshot format or truncated snapshot after deserializing 299 coins.")
self.log.info(" - snapshot file with alternated but parsable UTXO data results in different hash")
cases = [
# (content, offset, wrong_hash, custom_message)
[b"\xff" * 32, 0, "7d52155c9a9fdc4525b637ef6170568e5dad6fabd0b1fdbb9432010b8453095b", None], # wrong outpoint hash
[(2).to_bytes(1, "little"), 32, None, "[snapshot] bad snapshot data after deserializing 1 coins"], # wrong txid coins count
[b"\xfd\xff\xff", 32, None, "[snapshot] mismatch in coins count in snapshot metadata and actual snapshot data"], # txid coins count exceeds coins left
[(2).to_bytes(1, "little"), 32, None, "Bad snapshot data after deserializing 1 coins."], # wrong txid coins count
[b"\xfd\xff\xff", 32, None, "Mismatch in coins count in snapshot metadata and actual snapshot data"], # txid coins count exceeds coins left
[b"\x01", 33, "9f4d897031ab8547665b4153317ae2fdbf0130c7840b66427ebc48b881cb80ad", None], # wrong outpoint index
[b"\x81", 34, "3da966ba9826fb6d2604260e01607b55ba44e1a5de298606b08704bc62570ea8", None], # wrong coin code VARINT
[b"\x80", 34, "091e893b3ccb4334378709578025356c8bcb0a623f37c7c4e493133c988648e5", None], # another wrong coin code
[b"\x84\x58", 34, None, "[snapshot] bad snapshot data after deserializing 0 coins"], # wrong coin case with height 364 and coinbase 0
[b"\xCA\xD2\x8F\x5A", 39, None, "[snapshot] bad snapshot data after deserializing 0 coins - bad tx out value"], # Amount exceeds MAX_MONEY
[b"\x84\x58", 34, None, "Bad snapshot data after deserializing 0 coins"], # wrong coin case with height 364 and coinbase 0
[b"\xCA\xD2\x8F\x5A", 39, None, "Bad snapshot data after deserializing 0 coins - bad tx out value"], # Amount exceeds MAX_MONEY
]
for content, offset, wrong_hash, custom_message in cases:
@ -136,8 +135,8 @@ class AssumeutxoTest(BitcoinTestFramework):
f.write(content)
f.write(valid_snapshot_contents[(5 + 2 + 4 + 4 + 32 + 8 + offset + len(content)):])
log_msg = custom_message if custom_message is not None else f"[snapshot] bad snapshot content hash: expected a4bf3407ccb2cc0145c49ebba8fa91199f8a3903daf0883875941497d2493c27, got {wrong_hash}"
expected_error(log_msg=log_msg)
msg = custom_message if custom_message is not None else f"Bad snapshot content hash: expected a4bf3407ccb2cc0145c49ebba8fa91199f8a3903daf0883875941497d2493c27, got {wrong_hash}."
expected_error(msg)
def test_headers_not_synced(self, valid_snapshot_path):
for node in self.nodes[1:]:
@ -188,8 +187,8 @@ class AssumeutxoTest(BitcoinTestFramework):
def test_snapshot_with_less_work(self, dump_output_path):
self.log.info("Test bitcoind should fail when snapshot has less accumulated work than this node.")
node = self.nodes[0]
with node.assert_debug_log(expected_msgs=["[snapshot] activation failed - work does not exceed active chainstate"]):
assert_raises_rpc_error(-32603, "Unable to load UTXO snapshot", node.loadtxoutset, dump_output_path)
msg = "Unable to load UTXO snapshot: Population failed: Work does not exceed active chainstate."
assert_raises_rpc_error(-32603, msg, node.loadtxoutset, dump_output_path)
def test_snapshot_block_invalidated(self, dump_output_path):
self.log.info("Test snapshot is not loaded when base block is invalid.")