ci: failure in `logging

fanquake commented at 1:36 pm on August 15, 2025: member

Seen in https://cirrus-ci.com/task/5318274667249664:

  0[09:01:31.792]  50/144 Test  [#54](/bitcoin-bitcoin/54/): logging_tests ........................***Failed   23.39 sec
  1[09:01:31.796] Running 10 test cases...
  2[09:01:31.796] [1;36;49mTest cases order is shuffled using seed: 51669747[0;39;49m
  3[09:01:31.796] [1;34;49mEntering test module "Bitcoin Core Test Suite"
  4[09:01:31.796] [0;39;49m[1;33;49mtest/coins_tests.cpp(295): Test suite "coins_tests_dbbase" is skipped because disabled
  5[09:01:31.796] [0;39;49m[1;33;49mtest/pmt_tests.cpp(32): Test suite "pmt_tests" is skipped because disabled
  6[09:01:31.796] [0;39;49m[1;33;49mtest/serialize_tests.cpp(16): Test suite "serialize_tests" is skipped because disabled
  7[09:01:31.796] [0;39;49m[1;33;49mtest/cuckoocache_tests.cpp(32): Test suite "cuckoocache_tests" is skipped because disabled
  8[09:01:31.796] [0;39;49m[1;33;49mtest/bip324_tests.cpp(164): Test suite "bip324_tests" is skipped because disabled
  9[09:01:31.796] [0;39;49m[1;33;49mwallet/test/walletdb_tests.cpp(15): Test suite "walletdb_tests" is skipped because disabled
 10[09:01:31.796] [0;39;49m[1;33;49mtest/txvalidation_tests.cpp(21): Test suite "txvalidation_tests" is skipped because disabled
 11[09:01:31.796] [0;39;49m[1;33;49mtest/validation_chainstate_tests.cpp(23): Test suite "validation_chainstate_tests" is skipped because disabled
 12[09:01:31.796] [0;39;49m[1;33;49mtest/bip32_tests.cpp(160): Test suite "bip32_tests" is skipped because disabled
 13[09:01:31.796] [0;39;49m[1;33;49mtest/util_trace_tests.cpp(18): Test suite "util_trace_tests" is skipped because disabled
 14[09:01:31.796] [0;39;49m[1;33;49mtest/transaction_tests.cpp(193): Test suite "transaction_tests" is skipped because disabled
 15[09:01:31.796] [0;39;49m[1;33;49mtest/merkleblock_tests.cpp(14): Test suite "merkleblock_tests" is skipped because disabled
 16[09:01:31.796] [0;39;49m[1;33;49mtest/multisig_tests.cpp(20): Test suite "multisig_tests" is skipped because disabled
 17[09:01:31.796] [0;39;49m[1;33;49mwallet/test/wallet_rpc_tests.cpp(23): Test suite "wallet_rpc_tests" is skipped because disabled
 18[09:01:31.796] [0;39;49m[1;33;49mtest/sanity_tests.cpp(10): Test suite "sanity_tests" is skipped because disabled
 19[09:01:31.796] [0;39;49m[1;33;49mtest/key_io_tests.cpp(21): Test suite "key_io_tests" is skipped because disabled
 20[09:01:31.796] [0;39;49m[1;33;49mtest/disconnected_transactions.cpp(10): Test suite "disconnected_transactions" is skipped because disabled
 21[09:01:31.796] [0;39;49m[1;33;49mtest/peerman_tests.cpp(14): Test suite "peerman_tests" is skipped because disabled
 22[09:01:31.796] [0;39;49m[1;34;49mtest/logging_tests.cpp(32): Entering test suite "logging_tests"
 23[09:01:31.796] [0;39;49m[1;34;49mtest/logging_tests.cpp(321): Entering test case "logging_log_rate_limiter"
 24[09:01:31.796] [0;39;49m2025-08-15T13:01:08.582455Z [unknown] [test/util/random.cpp:48] [void SeedRandomStateForTest(SeedRand)] Setting random seed for current tests to RANDOM_CTX_SEED=3e87065736559106b08797466cf01b4285ae1494a30793a746aaebc2b2df3a81
 25[09:01:31.796] 2025-08-15T13:01:08.597607Z [test] [init/common.cpp:153] [void init::LogPackageVersion()] Bitcoin Core version v29.99.0-126a372db6bf-dirty (debug build)
 26[09:01:31.796] 2025-08-15T13:01:08.604851Z [test] [kernel/context.cpp:20] [auto kernel::Context::Context()::(anonymous class)::operator()() const] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation
 27[09:01:31.796] 2025-08-15T13:01:08.605864Z [test] [random.cpp:110] [void (anonymous namespace)::ReportHardwareRand()] Using RdSeed as an additional entropy source
 28[09:01:31.796] 2025-08-15T13:01:08.606646Z [test] [random.cpp:113] [void (anonymous namespace)::ReportHardwareRand()] Using RdRand as an additional entropy source
 29[09:01:31.796] 2025-08-15T13:01:08.615439Z [unknown] [logging.cpp:567] [void BCLog::LogRateLimiter::Reset()] [warning] Restarting logging from test/logging_tests.cpp:331 (void logging_tests::logging_log_rate_limiter::test_method()): 1 bytes were dropped during the last 60s.
 30[09:01:31.796] 2025-08-15T13:01:08.616424Z [unknown] [logging.cpp:567] [void BCLog::LogRateLimiter::Reset()] [warning] Restarting logging from test/logging_tests.cpp:330 (void logging_tests::logging_log_rate_limiter::test_method()): 2 bytes were dropped during the last 60s.
 31[09:01:31.796] [1;34;49mtest/logging_tests.cpp(321): Leaving test case "logging_log_rate_limiter"; testing time: 47949us
 32[09:01:31.796] [0;39;49m[1;34;49mtest/logging_tests.cpp(233): Entering test case "logging_Conf"
 33[09:01:31.796] [0;39;49m2025-08-15T13:01:08.630405Z [test] [test/util/random.cpp:48] [void SeedRandomStateForTest(SeedRand)] Setting random seed for current tests to RANDOM_CTX_SEED=3e87065736559106b08797466cf01b4285ae1494a30793a746aaebc2b2df3a81
 34[09:01:31.796] 2025-08-15T13:01:08.648316Z [test] [init/common.cpp:153] [void init::LogPackageVersion()] Bitcoin Core version v29.99.0-126a372db6bf-dirty (debug build)
 35[09:01:31.796] Sentinel log to reopen log file
 36[09:01:31.796] [1;34;49mtest/logging_tests.cpp(233): Leaving test case "logging_Conf"; testing time: 47485us
 37[09:01:31.796] [0;39;49m[1;34;49mtest/logging_tests.cpp(362): Entering test case "logging_log_limit_stats"
 38[09:01:31.796] [0;39;49m2025-08-15T13:01:08.677789Z [test] [test/util/random.cpp:48] [void SeedRandomStateForTest(SeedRand)] Setting random seed for current tests to RANDOM_CTX_SEED=3e87065736559106b08797466cf01b4285ae1494a30793a746aaebc2b2df3a81
 39[09:01:31.796] 2025-08-15T13:01:08.694298Z [test] [init/common.cpp:153] [void init::LogPackageVersion()] Bitcoin Core version v29.99.0-126a372db6bf-dirty (debug build)
 40[09:01:31.796] [1;34;49mtest/logging_tests.cpp(362): Leaving test case "logging_log_limit_stats"; testing time: 37941us
 41[09:01:31.796] [0;39;49m[1;34;49mtest/logging_tests.cpp(112): Entering test case "logging_LogPrintStr"
 42[09:01:31.796] [0;39;49m2025-08-15T13:01:08.715831Z [test] [test/util/random.cpp:48] [void SeedRandomStateForTest(SeedRand)] Setting random seed for current tests to RANDOM_CTX_SEED=3e87065736559106b08797466cf01b4285ae1494a30793a746aaebc2b2df3a81
 43[09:01:31.796] 2025-08-15T13:01:08.730847Z [test] [init/common.cpp:153] [void init::LogPackageVersion()] Bitcoin Core version v29.99.0-126a372db6bf-dirty (debug build)
 44[09:01:31.796] [test/logging_tests.cpp:125] [void logging_tests::logging_LogPrintStr::test_method()] [net] foo1: bar1
 45[09:01:31.796] [test/logging_tests.cpp:126] [void logging_tests::logging_LogPrintStr::test_method()] [net:info] foo2: bar2
 46[09:01:31.796] [test/logging_tests.cpp:127] [void logging_tests::logging_LogPrintStr::test_method()] [debug] foo3: bar3
 47[09:01:31.796] [test/logging_tests.cpp:128] [void logging_tests::logging_LogPrintStr::test_method()] foo4: bar4
 48[09:01:31.796] [test/logging_tests.cpp:129] [void logging_tests::logging_LogPrintStr::test_method()] [debug] foo5: bar5
 49[09:01:31.796] [test/logging_tests.cpp:130] [void logging_tests::logging_LogPrintStr::test_method()] foo6: bar6
 50[09:01:31.796] [test/logging_tests.cpp:91] [logging_tests::LogSetup::~LogSetup()] Sentinel log to reopen log file
 51[09:01:31.796] [1;34;49mtest/logging_tests.cpp(112): Leaving test case "logging_LogPrintStr"; testing time: 58642us
 52[09:01:31.796] [0;39;49m[1;34;49mtest/logging_tests.cpp(162): Entering test case "logging_LogPrintMacros"
 53[09:01:31.796] [0;39;49m2025-08-15T13:01:08.774783Z [test] [test/util/random.cpp:48] [void SeedRandomStateForTest(SeedRand)] Setting random seed for current tests to RANDOM_CTX_SEED=3e87065736559106b08797466cf01b4285ae1494a30793a746aaebc2b2df3a81
 54[09:01:31.796] 2025-08-15T13:01:08.795096Z [test] [init/common.cpp:153] [void init::LogPackageVersion()] Bitcoin Core version v29.99.0-126a372db6bf-dirty (debug build)
 55[09:01:31.796] [net] foo7: bar7
 56[09:01:31.796] foo8: bar8
 57[09:01:31.796] [warning] foo9: bar9
 58[09:01:31.796] [error] foo10: bar10
 59[09:01:31.796] Sentinel log to reopen log file
 60[09:01:31.796] [1;34;49mtest/logging_tests.cpp(162): Leaving test case "logging_LogPrintMacros"; testing time: 63845us
 61[09:01:31.796] [0;39;49m[1;34;49mtest/logging_tests.cpp(180): Entering test case "logging_LogPrintMacros_CategoryName"
 62[09:01:31.796] [0;39;49m2025-08-15T13:01:08.838731Z [test] [test/util/random.cpp:48] [void SeedRandomStateForTest(SeedRand)] Setting random seed for current tests to RANDOM_CTX_SEED=3e87065736559106b08797466cf01b4285ae1494a30793a746aaebc2b2df3a81
 63[09:01:31.796] 2025-08-15T13:01:08.860282Z [test] [init/common.cpp:153] [void init::LogPackageVersion()] Bitcoin Core version v29.99.0-126a372db6bf-dirty (debug build)
 64[09:01:31.796] [addrman] foo: bar
 65[09:01:31.796] [bench] foo: bar
 66[09:01:31.796] [blockstorage] foo: bar
 67[09:01:31.796] [cmpctblock] foo: bar
 68[09:01:31.796] [coindb] foo: bar
 69[09:01:31.796] [estimatefee] foo: bar
 70[09:01:31.796] [http] foo: bar
 71[09:01:31.796] [i2p] foo: bar
 72[09:01:31.796] [ipc] foo: bar
 73[09:01:31.796] [leveldb] foo: bar
 74[09:01:31.796] [libevent] foo: bar
 75[09:01:31.796] [lock] foo: bar
 76[09:01:31.796] [mempool] foo: bar
 77[09:01:31.796] [mempoolrej] foo: bar
 78[09:01:31.796] [net] foo: bar
 79[09:01:31.796] [proxy] foo: bar
 80[09:01:31.796] [prune] foo: bar
 81[09:01:31.796] [qt] foo: bar
 82[09:01:31.796] [rand] foo: bar
 83[09:01:31.796] [reindex] foo: bar
 84[09:01:31.796] [rpc] foo: bar
 85[09:01:31.796] [scan] foo: bar
 86[09:01:31.796] [selectcoins] foo: bar
 87[09:01:31.796] [tor] foo: bar
 88[09:01:31.796] [txpackages] foo: bar
 89[09:01:31.796] [txreconciliation] foo: bar
 90[09:01:31.796] [validation] foo: bar
 91[09:01:31.796] [walletdb] foo: bar
 92[09:01:31.796] [zmq] foo: bar
 93[09:01:31.796] Sentinel log to reopen log file
 94[09:01:31.796] [1;34;49mtest/logging_tests.cpp(180): Leaving test case "logging_LogPrintMacros_CategoryName"; testing time: 97807us
 95[09:01:31.796] [0;39;49m[1;34;49mtest/logging_tests.cpp(206): Entering test case "logging_SeverityLevels"
 96[09:01:31.796] [0;39;49m2025-08-15T13:01:08.936681Z [test] [test/util/random.cpp:48] [void SeedRandomStateForTest(SeedRand)] Setting random seed for current tests to RANDOM_CTX_SEED=3e87065736559106b08797466cf01b4285ae1494a30793a746aaebc2b2df3a81
 97[09:01:31.796] 2025-08-15T13:01:08.958237Z [test] [init/common.cpp:153] [void init::LogPackageVersion()] Bitcoin Core version v29.99.0-126a372db6bf-dirty (debug build)
 98[09:01:31.796] [http:info] foo1: bar1
 99[09:01:31.796] [validation:warning] foo3: bar3
100[09:01:31.796] [rpc:error] foo4: bar4
101[09:01:31.796] [net:warning] foo5: bar5
102[09:01:31.796] [net:error] foo7: bar7
103[09:01:31.796] Sentinel log to reopen log file
104[09:01:31.796] [1;34;49mtest/logging_tests.cpp(206): Leaving test case "logging_SeverityLevels"; testing time: 74579us
105[09:01:31.796] [0;39;49m[1;34;49mtest/logging_tests.cpp(448): Entering test case "logging_filesize_rate_limit"
106[09:01:31.796] [0;39;49m2025-08-15T13:01:09.011189Z [test] [test/util/random.cpp:48] [void SeedRandomStateForTest(SeedRand)] Setting random seed for current tests to RANDOM_CTX_SEED=3e87065736559106b08797466cf01b4285ae1494a30793a746aaebc2b2df3a81
107[09:01:31.796] 2025-08-15T13:01:09.029747Z [test] [init/common.cpp:153] [void init::LogPackageVersion()] Bitcoin Core version v29.99.0-126a372db6bf-dirty (debug build)
108[09:01:31.796] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
109[09:01:31.796] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
110[09:01:31.796] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
111[09:01:31.796] <snip>
112aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
113[09:01:31.798] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
114[09:01:31.798] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
115[09:01:31.798] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
116[09:01:31.798] a
117[09:01:31.798] test/logging_tests.cpp(435): [4;31;49mfatal error: in "logging_tests/logging_filesize_rate_limit": critical check log_lines.size() == 2 has failed [1 != 2]
118[09:01:31.798] Failure occurred in a following context:
119[09:01:31.798]     TestLogFromLocation failed from test/logging_tests.cpp:470[0;39;49m
120[09:01:31.798] Sentinel log to reopen log file
121[09:01:31.798] [1;34;49mtest/logging_tests.cpp(448): Leaving test case "logging_filesize_rate_limit"; testing time: 22705157us
122[09:01:31.798] [0;39;49m[1;34;49mtest/logging_tests.cpp(142): Entering test case "logging_LogPrintMacrosDeprecated"
123[09:01:31.798] [0;39;49m2025-08-15T13:01:31.717284Z [test] [test/util/random.cpp:48] [void SeedRandomStateForTest(SeedRand)] Setting random seed for current tests to RANDOM_CTX_SEED=3e87065736559106b08797466cf01b4285ae1494a30793a746aaebc2b2df3a81
124[09:01:31.798] 2025-08-15T13:01:31.733279Z [test] [init/common.cpp:153] [void init::LogPackageVersion()] Bitcoin Core version v29.99.0-126a372db6bf-dirty (debug build)
125[09:01:31.798] foo5: bar5
126[09:01:31.798] [net] foo7: bar7
127[09:01:31.798] [net:info] foo8: bar8
128[09:01:31.798] [net:warning] foo9: bar9
129[09:01:31.798] [net:error] foo10: bar10
130[09:01:31.798] Sentinel log to reopen log file
131[09:01:31.798] [1;34;49mtest/logging_tests.cpp(142): Leaving test case "logging_LogPrintMacrosDeprecated"; testing time: 27864us

stickies-v commented at 2:17 pm on August 15, 2025: contributor

This is the relevant log output:

0[09:01:31.798] test/logging_tests.cpp(435): �[4;31;49mfatal error: in "logging_tests/logging_filesize_rate_limit": critical check log_lines.size() == 2 has failed [1 != 2]
1[09:01:31.798] Failure occurred in a following context:
2[09:01:31.798]     TestLogFromLocation failed from test/logging_tests.cpp:470�[0;39;49m

When a log line is newly suppressed, we always expect exactly 2 lines to be output:

the announcement that logging for this location will be suppressed (src)
the log line that is suppressed

The error indicates that only 1 log line was found, but that doesn’t really seem possible from our current logic. The fact that the issue is intermittent, would seem to indicate that there’s some race condition between the logs being created, and the logs being read. Our logging should be unbuffered (src), but I’m not sure how strong that guarantee is?

If the above reasoning is correct and flushing is the issue, I think we can either:

add a Logger::FlushFile() function that calls fflush(m_fileout);, which can then be called from the test-only ReadDebugLogLines, ensuring no more race conditions without affecting non-test code paths.
add fflush(m_fileout) to FileWriteStr

Option 1 seems more sensible, even if it’s adding test-only functions?

stickies-v referenced this in commit e7758593ba on Aug 15, 2025

stickies-v commented at 2:46 pm on August 15, 2025: contributor

Opened #33198 - if anyone is able to reproduce the issue, please leave a comment if 33198 fixes it for you so I can undraft.

stickies-v commented at 3:27 pm on August 15, 2025: contributor

I’m able to reproduce it pretty much at 100% by running the test on a slow external USB2.0 flash drive. I couldn’t figure out how to run test_bitcoin from a different datadir so I just modified the LogSetup ctor as a quick workaround:

 0diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
 1index eb0ca846df..ae1fc720fe 100644
 2--- a/src/test/logging_tests.cpp
 3+++ b/src/test/logging_tests.cpp
 4@@ -71,7 +71,8 @@ struct LogSetup : public BasicTestingSetup {
 5                  prev_log_level{LogInstance().LogLevel()},
 6                  prev_category_mask{LogInstance().GetCategoryMask()}
 7     {
 8-        LogInstance().m_file_path = tmp_log_path;
 9+        LogInstance().m_file_path = fs::path{"/Volumes/ExtDrive/tmp_debug.log"};
10+        // LogInstance().m_file_path = tmp_log_path;
11         LogInstance().m_reopen_file = true;
12         LogInstance().m_print_to_file = true;
13         LogInstance().m_log_timestamps = false;

Edit: running the test from the flash drive just made the test so slow that it was triggering the 20s reset window, causing the log test to fail because the suppression status was reset. This is however not what happened in https://cirrus-ci.com/task/5318274667249664?logs=ci#L721, as the test started and failed all in a span of a few milliseconds.

Crypt-iQ commented at 10:16 pm on August 15, 2025: contributor

I’ll look into this. There are 1023 aaaaaa...aaaa log lines (there should be 1024) in the CI logs followed by a single a. The a should be prefixed with [*] regardless of race conditions because asterisk prefix happens before writing to disk and LogRateLimiter isn’t racy. I have a few hunches that I’ll investigate.

fanquake added this to the milestone 30.0 on Aug 17, 2025

maflcko added the label CI failed on Aug 18, 2025

Crypt-iQ commented at 2:41 pm on August 18, 2025: contributor

This is however not what happened in https://cirrus-ci.com/task/5318274667249664?logs=ci#L721, as the test started and failed all in a span of a few milliseconds.

I think the CI logs are a bit weird and are printing the time from the boost test log – the test actually took ~22.7 seconds: [09:01:31.798] [1;34;49mtest/logging_tests.cpp(448): Leaving test case "logging_filesize_rate_limit"; testing time: 22705157us. This would be enough to trigger the Reset. I am not sure why it took this long as a later successful run took about a second.

maflcko commented at 3:45 pm on August 18, 2025: member

Edit: running the test from the flash drive just made the test so slow that it was triggering the 20s reset window, causing the log test to fail because the suppression status was reset. This is however not what happened in https://cirrus-ci.com/task/5318274667249664?logs=ci#L721, as the test started and failed all in a span of a few milliseconds.

I guess it is rare that someone runs this test on a slow storage device, but I don’t see why the test requires a tight reset window of 20s, because it is using mocking anyway. The windows could be hours and mocking could be the same amount of hours and the test would still run equally fast without intermittent failures on slow IO?

stickies-v commented at 4:10 pm on August 18, 2025: contributor

There are 1023 aaaaaa…aaaa log lines (there should be 1024) in the CI logs

It seems the 835th iteration got corrupted (scroll down a bit):

0[09:01:31.798] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa��������aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa

If you include that in your count, I think there are 1024 lines in total, as expected.

The a should be prefixed with [*] regardless of race conditions

That’s a good point, and seems a strong indicater that Reset() was called before we expected it would.

but I don’t see why the test requires a tight reset window of 20s, because it is using mocking anyway.

Yeah I don’t see any issues with relaxing the window either. I’m also not sure if there’d be any downsides to reducing constexpr int64_t num_lines{1024}; to a smaller number, I don’t think the reliability of the test depends on this being such a large number? This used to be a requirement, but more recent iterations have made LogRateLimiter parameterized wrt max_bytes, so I think we can bring it down now.

It’s still a bit surprising that this test suddenly took so long to run, but I suppose with hardware being shared these kinds of occurrences need to be accounted for?

Crypt-iQ commented at 8:37 pm on August 18, 2025: contributor

I’ve opened #33211 to fix this. It changes the time window to 1h which should be more than enough. Also, it reduces num_lines quite a bit as suggested by @stickies-v above.

It seems the 835th iteration got corrupted (scroll down a bit)

Interesting… now I’m curious why it was corrupted? But I’ll let that be for now.

maflcko commented at 8:24 am on August 19, 2025: member

It’s still a bit surprising that this test suddenly took so long to run, but I suppose with hardware being shared these kinds of occurrences need to be accounted for?

Yeah, it seems odd that there is an intermittent 20x slowdown. It could be a hardware fault, and hopefully new CI hardware will be deployed soon. However, we also want the test to pass locally (in the rare case when someone uses a slow USB thumb drive) or on cloud boxes (which sometimes use slow network storage).

Interesting… now I’m curious why it was corrupted? But I’ll let that be for now.

It is not possible to run the unit tests with clang without stdout-IO races (UB) (see #23366), so I guess this is just one of the expected intermittent UBs.

fanquake closed this on Aug 20, 2025

fanquake referenced this in commit 9cf7b3d90c on Aug 20, 2025

ci: failure in logging_tests #33195

ci: failure in `logging_tests` #33195