ci: failure in `logging_tests` #33195

issue fanquake opened this issue on August 15, 2025
  1. fanquake commented at 1:36 PM on August 15, 2025: member

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

    [09:01:31.792]  50/144 Test  [#54](/bitcoin-bitcoin/54/): logging_tests ........................***Failed   23.39 sec
[09:01:31.796] Running 10 test cases...
[09:01:31.796] Test cases order is shuffled using seed: 51669747
[09:01:31.796] Entering test module "Bitcoin Core Test Suite"
[09:01:31.796] test/coins_tests.cpp(295): Test suite "coins_tests_dbbase" is skipped because disabled
[09:01:31.796] test/pmt_tests.cpp(32): Test suite "pmt_tests" is skipped because disabled
[09:01:31.796] test/serialize_tests.cpp(16): Test suite "serialize_tests" is skipped because disabled
[09:01:31.796] test/cuckoocache_tests.cpp(32): Test suite "cuckoocache_tests" is skipped because disabled
[09:01:31.796] test/bip324_tests.cpp(164): Test suite "bip324_tests" is skipped because disabled
[09:01:31.796] wallet/test/walletdb_tests.cpp(15): Test suite "walletdb_tests" is skipped because disabled
[09:01:31.796] test/txvalidation_tests.cpp(21): Test suite "txvalidation_tests" is skipped because disabled
[09:01:31.796] test/validation_chainstate_tests.cpp(23): Test suite "validation_chainstate_tests" is skipped because disabled
[09:01:31.796] test/bip32_tests.cpp(160): Test suite "bip32_tests" is skipped because disabled
[09:01:31.796] test/util_trace_tests.cpp(18): Test suite "util_trace_tests" is skipped because disabled
[09:01:31.796] test/transaction_tests.cpp(193): Test suite "transaction_tests" is skipped because disabled
[09:01:31.796] test/merkleblock_tests.cpp(14): Test suite "merkleblock_tests" is skipped because disabled
[09:01:31.796] test/multisig_tests.cpp(20): Test suite "multisig_tests" is skipped because disabled
[09:01:31.796] wallet/test/wallet_rpc_tests.cpp(23): Test suite "wallet_rpc_tests" is skipped because disabled
[09:01:31.796] test/sanity_tests.cpp(10): Test suite "sanity_tests" is skipped because disabled
[09:01:31.796] test/key_io_tests.cpp(21): Test suite "key_io_tests" is skipped because disabled
[09:01:31.796] test/disconnected_transactions.cpp(10): Test suite "disconnected_transactions" is skipped because disabled
[09:01:31.796] test/peerman_tests.cpp(14): Test suite "peerman_tests" is skipped because disabled
[09:01:31.796] test/logging_tests.cpp(32): Entering test suite "logging_tests"
[09:01:31.796] test/logging_tests.cpp(321): Entering test case "logging_log_rate_limiter"
[09:01:31.796] 2025-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
[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)
[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
[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
[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
[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.
[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.
[09:01:31.796] test/logging_tests.cpp(321): Leaving test case "logging_log_rate_limiter"; testing time: 47949us
[09:01:31.796] test/logging_tests.cpp(233): Entering test case "logging_Conf"
[09:01:31.796] 2025-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
[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)
[09:01:31.796] Sentinel log to reopen log file
[09:01:31.796] test/logging_tests.cpp(233): Leaving test case "logging_Conf"; testing time: 47485us
[09:01:31.796] test/logging_tests.cpp(362): Entering test case "logging_log_limit_stats"
[09:01:31.796] 2025-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
[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)
[09:01:31.796] test/logging_tests.cpp(362): Leaving test case "logging_log_limit_stats"; testing time: 37941us
[09:01:31.796] test/logging_tests.cpp(112): Entering test case "logging_LogPrintStr"
[09:01:31.796] 2025-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
[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)
[09:01:31.796] [test/logging_tests.cpp:125] [void logging_tests::logging_LogPrintStr::test_method()] [net] foo1: bar1
[09:01:31.796] [test/logging_tests.cpp:126] [void logging_tests::logging_LogPrintStr::test_method()] [net:info] foo2: bar2
[09:01:31.796] [test/logging_tests.cpp:127] [void logging_tests::logging_LogPrintStr::test_method()] [debug] foo3: bar3
[09:01:31.796] [test/logging_tests.cpp:128] [void logging_tests::logging_LogPrintStr::test_method()] foo4: bar4
[09:01:31.796] [test/logging_tests.cpp:129] [void logging_tests::logging_LogPrintStr::test_method()] [debug] foo5: bar5
[09:01:31.796] [test/logging_tests.cpp:130] [void logging_tests::logging_LogPrintStr::test_method()] foo6: bar6
[09:01:31.796] [test/logging_tests.cpp:91] [logging_tests::LogSetup::~LogSetup()] Sentinel log to reopen log file
[09:01:31.796] test/logging_tests.cpp(112): Leaving test case "logging_LogPrintStr"; testing time: 58642us
[09:01:31.796] test/logging_tests.cpp(162): Entering test case "logging_LogPrintMacros"
[09:01:31.796] 2025-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
[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)
[09:01:31.796] [net] foo7: bar7
[09:01:31.796] foo8: bar8
[09:01:31.796] [warning] foo9: bar9
[09:01:31.796] [error] foo10: bar10
[09:01:31.796] Sentinel log to reopen log file
[09:01:31.796] test/logging_tests.cpp(162): Leaving test case "logging_LogPrintMacros"; testing time: 63845us
[09:01:31.796] test/logging_tests.cpp(180): Entering test case "logging_LogPrintMacros_CategoryName"
[09:01:31.796] 2025-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
[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)
[09:01:31.796] [addrman] foo: bar
[09:01:31.796] [bench] foo: bar
[09:01:31.796] [blockstorage] foo: bar
[09:01:31.796] [cmpctblock] foo: bar
[09:01:31.796] [coindb] foo: bar
[09:01:31.796] [estimatefee] foo: bar
[09:01:31.796] [http] foo: bar
[09:01:31.796] [i2p] foo: bar
[09:01:31.796] [ipc] foo: bar
[09:01:31.796] [leveldb] foo: bar
[09:01:31.796] [libevent] foo: bar
[09:01:31.796] [lock] foo: bar
[09:01:31.796] [mempool] foo: bar
[09:01:31.796] [mempoolrej] foo: bar
[09:01:31.796] [net] foo: bar
[09:01:31.796] [proxy] foo: bar
[09:01:31.796] [prune] foo: bar
[09:01:31.796] [qt] foo: bar
[09:01:31.796] [rand] foo: bar
[09:01:31.796] [reindex] foo: bar
[09:01:31.796] [rpc] foo: bar
[09:01:31.796] [scan] foo: bar
[09:01:31.796] [selectcoins] foo: bar
[09:01:31.796] [tor] foo: bar
[09:01:31.796] [txpackages] foo: bar
[09:01:31.796] [txreconciliation] foo: bar
[09:01:31.796] [validation] foo: bar
[09:01:31.796] [walletdb] foo: bar
[09:01:31.796] [zmq] foo: bar
[09:01:31.796] Sentinel log to reopen log file
[09:01:31.796] test/logging_tests.cpp(180): Leaving test case "logging_LogPrintMacros_CategoryName"; testing time: 97807us
[09:01:31.796] test/logging_tests.cpp(206): Entering test case "logging_SeverityLevels"
[09:01:31.796] 2025-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
[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)
[09:01:31.796] [http:info] foo1: bar1
[09:01:31.796] [validation:warning] foo3: bar3
[09:01:31.796] [rpc:error] foo4: bar4
[09:01:31.796] [net:warning] foo5: bar5
[09:01:31.796] [net:error] foo7: bar7
[09:01:31.796] Sentinel log to reopen log file
[09:01:31.796] test/logging_tests.cpp(206): Leaving test case "logging_SeverityLevels"; testing time: 74579us
[09:01:31.796] test/logging_tests.cpp(448): Entering test case "logging_filesize_rate_limit"
[09:01:31.796] 2025-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
[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)
[09:01:31.796] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[09:01:31.796] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[09:01:31.796] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[09:01:31.796] <snip>
aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[09:01:31.798] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[09:01:31.798] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[09:01:31.798] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[09:01:31.798] a
[09:01:31.798] test/logging_tests.cpp(435): fatal error: in "logging_tests/logging_filesize_rate_limit": critical check log_lines.size() == 2 has failed [1 != 2]
[09:01:31.798] Failure occurred in a following context:
[09:01:31.798]     TestLogFromLocation failed from test/logging_tests.cpp:470
[09:01:31.798] Sentinel log to reopen log file
[09:01:31.798] test/logging_tests.cpp(448): Leaving test case "logging_filesize_rate_limit"; testing time: 22705157us
[09:01:31.798] test/logging_tests.cpp(142): Entering test case "logging_LogPrintMacrosDeprecated"
[09:01:31.798] 2025-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
[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)
[09:01:31.798] foo5: bar5
[09:01:31.798] [net] foo7: bar7
[09:01:31.798] [net:info] foo8: bar8
[09:01:31.798] [net:warning] foo9: bar9
[09:01:31.798] [net:error] foo10: bar10
[09:01:31.798] Sentinel log to reopen log file
[09:01:31.798] test/logging_tests.cpp(142): Leaving test case "logging_LogPrintMacrosDeprecated"; testing time: 27864us
  2. stickies-v commented at 2:17 PM on August 15, 2025: contributor

    This is the relevant log output:

    [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]
[09:01:31.798] Failure occurred in a following context:
[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:

    1. the announcement that logging for this location will be suppressed (src)
    2. 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:

    1. 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.
    2. add fflush(m_fileout) to FileWriteStr

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

  3. stickies-v referenced this in commit e7758593ba on Aug 15, 2025
  4. 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.

  5. 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:

    <details> <summary>git diff</summary>

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

    </details>

    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.

  6. 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.

  7. fanquake added this to the milestone 30.0 on Aug 17, 2025
  8. maflcko added the label CI failed on Aug 18, 2025
  9. 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] test/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.

  10. 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?

  11. 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):

    [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?

  12. 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.

  13. 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.

  14. fanquake closed this on Aug 20, 2025
  15. fanquake referenced this in commit 9cf7b3d90c on Aug 20, 2025
Contributors
fanquakestickies-vCrypt-iQmaflcko
Labels
CI failed

Milestone
30.0

Linked (view graph)
#54 do not create "Your Address" account when creating a new wallet#33198 test: ensure logs are flushed before reading them#33211 test: modify logging_filesize_rate_limit params
github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-04-19 06:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me