Compare commits

...

7 Commits

Author SHA1 Message Date
l0rinc
132fd71f23
Merge 6f049e1230090baa64d1bf1a3d9c2064ee913e39 into 5f4422d68dc3530c353af1f87499de1c864b60ad 2025-03-17 03:52:13 +01:00
merge-script
5f4422d68d
Merge bitcoin/bitcoin#32010: qa: Fix TxIndex race conditions
3301d2cbe8c3b76c97285d75fa59637cb6952d0b qa: Wait for txindex to avoid race condition (Hodlinator)
9bfb0d75ba10591cc6c9620f9fd1ecc0e55e7a48 qa: Remove unnecessary -txindex args (Hodlinator)
7ac281c19cd3d11f316dbbb3308eabf1ad4f26d6 qa: Add missing coverage of corrupt indexes (Hodlinator)

Pull request description:

  - Add synchronization in 3 places where if the Transaction Index happens to be slow, we get rare test failures when querying it for transactions (one such case experienced on Windows, prompting investigation).
  - Remove unnecessary TxIndex initialization in some tests.
  - Add some test coverage where TxIndex aspect could be tested in feature_init.py.

ACKs for top commit:
  fjahr:
    re-ACK 3301d2cbe8c3b76c97285d75fa59637cb6952d0b
  mzumsande:
    Code Review ACK 3301d2cbe8c3b76c97285d75fa59637cb6952d0b
  furszy:
    Code review ACK 3301d2cbe8c3b76c97285d75fa59637cb6952d0b
  Prabhat1308:
    Concept ACK [`3301d2c`](3301d2cbe8)

Tree-SHA512: 7c2019e38455f344856aaf6b381faafbd88d53dc88d13309deb718c1dcfbee4ccca7c7f1b66917395503a6f94c3b216a007ad432cc8b93d0309db9805f38d602
2025-03-17 10:28:14 +08:00
Hodlinator
3301d2cbe8
qa: Wait for txindex to avoid race condition
Can be verified to be necessary through adding std::this_thread::sleep_for(0.5s) at the beginning of TxIndex::CustomAppend.
2025-03-10 15:24:16 +01:00
Hodlinator
9bfb0d75ba
qa: Remove unnecessary -txindex args
(Parent commit ensured indexes in feature_init.py are actually used, otherwise they would be removed here as well).
2025-03-07 22:22:31 +01:00
Hodlinator
7ac281c19c
qa: Add missing coverage of corrupt indexes 2025-03-07 22:22:31 +01:00
Lőrinc
6f049e1230 log,optimization: use original log string when no suspicious chars found
> build/src/bench/bench_bitcoin -filter='LogEscapeMessage.+' --min-time=10000

> C compiler ............................ AppleClang 16.0.0.16000026

|               ns/op |                op/s |    err% |     total | benchmark
|--------------------:|--------------------:|--------:|----------:|:----------
|              106.54 |        9,386,391.31 |    0.2% |     11.01 | `LogEscapeMessageNormal`
|              335.58 |        2,979,947.73 |    0.3% |     10.96 | `LogEscapeMessageSuspicious`
2025-02-24 15:24:41 +01:00
Lőrinc
a445c688ab bench: measure LogEscapeMessage in normal & suspicious cases
> build/src/bench/bench_bitcoin -filter='LogEscapeMessage.+' --min-time=10000

> C compiler ............................ AppleClang 16.0.0.16000026

|               ns/op |                op/s |    err% |     total | benchmark
|--------------------:|--------------------:|--------:|----------:|:----------
|              216.10 |        4,627,429.03 |    0.2% |     10.81 | `LogEscapeMessageNormal`
|              328.77 |        3,041,669.54 |    0.7% |     10.97 | `LogEscapeMessageSuspicious`
2025-02-24 15:19:04 +01:00
8 changed files with 86 additions and 16 deletions

View File

@ -9,6 +9,8 @@
#include <functional>
#include <vector>
using namespace std::literals;
// All but 2 of the benchmarks should have roughly similar performance:
//
// LogWithoutDebug should be ~3 orders of magnitude faster, as nothing is logged.
@ -57,8 +59,48 @@ static void LogWithoutWriteToFile(benchmark::Bench& bench)
});
}
namespace BCLog {
bool IsSuspicious(const char ch) noexcept;
std::string LogEscapeMessage(std::string_view str);
}
static void LogEscapeMessageNormal(benchmark::Bench& bench) {
const std::vector<std::string> normal_logs{
"UpdateTip: new best=000000000000000000003c4c32d94a9363241a84d42cbbc1ec9f5f12f84f4feb height=875371 version=0x20000004 log2_work=95.334853 tx=1133590694 date='2024-12-19T01:57:26Z' progress=0.993026 cache=8.3MiB(56574txo)"s,
"received: headers (162 bytes) peer=15"s,
"Config file arg: datadir=/Users/bitcoin/data"s,
"Verified block header at height 12345 hash: 你好 🔤"s
};
bench.batch(normal_logs.size()).run([&] {
for (const auto& msg : normal_logs) {
const auto& res{std::ranges::none_of(msg, BCLog::IsSuspicious) ? msg : BCLog::LogEscapeMessage(msg)};
ankerl::nanobench::doNotOptimizeAway(res);
}
});
}
static void LogEscapeMessageSuspicious(benchmark::Bench& bench) {
// Based on the test cases
const std::vector<std::string> suspicious_logs{
"Received strange message\0from peer=12"s,
"Got malformed packet\x01\x02\x03\x7F from peer=13"s,
"Peer=14 sent:\x0D\x0Econtent-length: 100\x0D\x0A"s,
"Validation failed on\x1B[31mERROR\x1B[0m block=123456"s
};
bench.batch(suspicious_logs.size()).run([&] {
for (const auto& msg : suspicious_logs) {
const auto& res{std::ranges::none_of(msg, BCLog::IsSuspicious) ? msg : BCLog::LogEscapeMessage(msg)};
ankerl::nanobench::doNotOptimizeAway(res);
}
});
}
BENCHMARK(LogWithDebug, benchmark::PriorityLevel::HIGH);
BENCHMARK(LogWithoutDebug, benchmark::PriorityLevel::HIGH);
BENCHMARK(LogWithThreadNames, benchmark::PriorityLevel::HIGH);
BENCHMARK(LogWithoutThreadNames, benchmark::PriorityLevel::HIGH);
BENCHMARK(LogWithoutWriteToFile, benchmark::PriorityLevel::HIGH);
BENCHMARK(LogEscapeMessageNormal, benchmark::PriorityLevel::LOW);
BENCHMARK(LogEscapeMessageSuspicious, benchmark::PriorityLevel::LOW);

View File

@ -315,6 +315,11 @@ std::string BCLog::Logger::LogTimestampStr(SystemClock::time_point now, std::chr
}
namespace BCLog {
bool IsSuspicious(const char ch) noexcept
{
const auto uch{static_cast<uint8_t>(ch)};
return (uch < ' ' && uch != '\n') || uch == '\x7f';
}
/** Belts and suspenders: make sure outgoing log messages don't contain
* potentially suspicious characters, such as terminal control codes.
*
@ -322,14 +327,15 @@ namespace BCLog {
* It escapes instead of removes them to still allow for troubleshooting
* issues where they accidentally end up in strings.
*/
std::string LogEscapeMessage(std::string_view str) {
std::string LogEscapeMessage(std::string_view str)
{
std::string ret;
for (char ch_in : str) {
uint8_t ch = (uint8_t)ch_in;
if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
ret += ch_in;
} else {
ret.reserve(3 + str.size()); // Assume at least one suspicious character
for (auto ch : str) {
if (IsSuspicious(ch)) {
ret += strprintf("\\x%02x", ch);
} else {
ret += ch;
}
}
return ret;
@ -392,7 +398,7 @@ void BCLog::Logger::LogPrintStr(std::string_view str, std::string_view logging_f
void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
{
std::string str_prefixed = LogEscapeMessage(str);
std::string str_prefixed{std::ranges::none_of(str, IsSuspicious) ? str : LogEscapeMessage(str)};
if (m_buffering) {
{

View File

@ -88,7 +88,7 @@ class InitTest(BitcoinTestFramework):
args = ['-txindex=1', '-blockfilterindex=1', '-coinstatsindex=1']
for terminate_line in lines_to_terminate_after:
self.log.info(f"Starting node and will exit after line {terminate_line}")
self.log.info(f"Starting node and will terminate after line {terminate_line}")
with node.busy_wait_for_debug_log([terminate_line]):
if platform.system() == 'Windows':
# CREATE_NEW_PROCESS_GROUP is required in order to be able
@ -108,12 +108,22 @@ class InitTest(BitcoinTestFramework):
'blocks/index/*.ldb': 'Error opening block database.',
'chainstate/*.ldb': 'Error opening coins database.',
'blocks/blk*.dat': 'Error loading block database.',
'indexes/txindex/MANIFEST*': 'LevelDB error: Corruption: CURRENT points to a non-existent file',
# Removing these files does not result in a startup error:
# 'indexes/blockfilter/basic/*.dat', 'indexes/blockfilter/basic/db/*.*', 'indexes/coinstats/db/*.*',
# 'indexes/txindex/*.log', 'indexes/txindex/CURRENT', 'indexes/txindex/LOCK'
}
files_to_perturb = {
'blocks/index/*.ldb': 'Error loading block database.',
'chainstate/*.ldb': 'Error opening coins database.',
'blocks/blk*.dat': 'Corrupted block database detected.',
'indexes/blockfilter/basic/db/*.*': 'LevelDB error: Corruption',
'indexes/coinstats/db/*.*': 'LevelDB error: Corruption',
'indexes/txindex/*.log': 'LevelDB error: Corruption',
'indexes/txindex/CURRENT': 'LevelDB error: Corruption',
# Perturbing these files does not result in a startup error:
# 'indexes/blockfilter/basic/*.dat', 'indexes/txindex/MANIFEST*', 'indexes/txindex/LOCK'
}
for file_patt, err_fragment in files_to_delete.items():
@ -135,9 +145,10 @@ class InitTest(BitcoinTestFramework):
self.stop_node(0)
self.log.info("Test startup errors after perturbing certain essential files")
dirs = ["blocks", "chainstate", "indexes"]
for file_patt, err_fragment in files_to_perturb.items():
shutil.copytree(node.chain_path / "blocks", node.chain_path / "blocks_bak")
shutil.copytree(node.chain_path / "chainstate", node.chain_path / "chainstate_bak")
for dir in dirs:
shutil.copytree(node.chain_path / dir, node.chain_path / f"{dir}_bak")
target_files = list(node.chain_path.glob(file_patt))
for target_file in target_files:
@ -151,10 +162,9 @@ class InitTest(BitcoinTestFramework):
start_expecting_error(err_fragment)
shutil.rmtree(node.chain_path / "blocks")
shutil.rmtree(node.chain_path / "chainstate")
shutil.move(node.chain_path / "blocks_bak", node.chain_path / "blocks")
shutil.move(node.chain_path / "chainstate_bak", node.chain_path / "chainstate")
for dir in dirs:
shutil.rmtree(node.chain_path / dir)
shutil.move(node.chain_path / f"{dir}_bak", node.chain_path / dir)
def init_pid_test(self):
BITCOIN_PID_FILENAME_CUSTOM = "my_fancy_bitcoin_pid_file.foobar"

View File

@ -45,6 +45,7 @@ from test_framework.util import (
assert_equal,
assert_greater_than,
assert_raises_rpc_error,
sync_txindex,
)
from test_framework.wallet import MiniWallet
from test_framework.wallet_util import generate_keypair
@ -270,6 +271,7 @@ class MempoolAcceptanceTest(BitcoinTestFramework):
self.log.info('A coinbase transaction')
# Pick the input of the first tx we created, so it has to be a coinbase tx
sync_txindex(self, node)
raw_tx_coinbase_spent = node.getrawtransaction(txid=node.decoderawtransaction(hexstring=raw_tx_in_block)['vin'][0]['txid'])
tx = tx_from_hex(raw_tx_coinbase_spent)
self.check_mempool_result(

View File

@ -34,6 +34,7 @@ from test_framework.util import (
assert_equal,
assert_greater_than,
assert_raises_rpc_error,
sync_txindex,
)
from test_framework.wallet import (
getnewdestination,
@ -70,7 +71,7 @@ class RawTransactionsTest(BitcoinTestFramework):
self.num_nodes = 3
self.extra_args = [
["-txindex"],
["-txindex"],
[],
["-fastprune", "-prune=1"],
]
# whitelist peers to speed up tx relay / mempool sync
@ -109,6 +110,7 @@ class RawTransactionsTest(BitcoinTestFramework):
self.log.info(f"Test getrawtransaction {'with' if n == 0 else 'without'} -txindex")
if n == 0:
sync_txindex(self, self.nodes[n])
# With -txindex.
# 1. valid parameters - only supply txid
assert_equal(self.nodes[n].getrawtransaction(txId), tx['hex'])

View File

@ -12,6 +12,7 @@ from test_framework.test_framework import BitcoinTestFramework
from test_framework.util import (
assert_equal,
assert_raises_rpc_error,
sync_txindex,
)
from test_framework.wallet import MiniWallet
@ -77,6 +78,7 @@ class MerkleBlockTest(BitcoinTestFramework):
assert_equal(sorted(self.nodes[0].verifytxoutproof(self.nodes[0].gettxoutproof([txid1, txid2]))), sorted(txlist))
assert_equal(sorted(self.nodes[0].verifytxoutproof(self.nodes[0].gettxoutproof([txid2, txid1]))), sorted(txlist))
# We can always get a proof if we have a -txindex
sync_txindex(self, self.nodes[1])
assert_equal(self.nodes[0].verifytxoutproof(self.nodes[1].gettxoutproof([txid_spent])), [txid_spent])
# We can't get a proof if we specify transactions from different blocks
assert_raises_rpc_error(-5, "Not all transactions found in specified or retrieved block", self.nodes[0].gettxoutproof, [txid1, txid3])

View File

@ -592,3 +592,10 @@ def find_vout_for_address(node, txid, addr):
if addr == tx["vout"][i]["scriptPubKey"]["address"]:
return i
raise RuntimeError("Vout not found for address: txid=%s, addr=%s" % (txid, addr))
def sync_txindex(test_framework, node):
test_framework.log.debug("Waiting for node txindex to sync")
sync_start = int(time.time())
test_framework.wait_until(lambda: node.getindexinfo("txindex")["txindex"]["synced"])
test_framework.log.debug(f"Synced in {time.time() - sync_start} seconds")

View File

@ -117,7 +117,6 @@ class AddressInputTypeGrouping(BitcoinTestFramework):
self.extra_args = [
[
"-addresstype=bech32",
"-txindex",
],
[
"-addresstype=p2sh-segwit",