feature_init.py loadblk thread start']" does not partially match log: #24060

1. 
   MarcoFalke commented at 4:20 PM on January 13, 2022: member

   https://cirrus-ci.com/task/6559642787512320?logs=ci#L5346

    test  2022-01-13T11:41:43.569000Z TestFramework (ERROR): Assertion failed 
                                      Traceback (most recent call last):
                                        File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
                                          self.run_test()
                                        File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/feature_init.py", line 81, in run_test
                                          num_total_logs = node.wait_for_debug_log([terminate_line], ignore_case=True)
                                        File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 458, in wait_for_debug_log
                                          str(expected_msgs), print_log))
                                        File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 167, in _raise_assertion_error
                                          raise AssertionError(self._node_msg(msg))
                                      AssertionError: [node 0] Expected messages "['loadblk thread start']" does not partially match log:
                                       - 2022-01-13T11:35:03.562576Z [txindex] [util/thread.cpp:17] [TraceThread] txindex thread start
                                       - 2022-01-13T11:35:03.597525Z [txindex] [index/base.cpp:196] [ThreadSync] txindex is enabled at height 200
                                       - 2022-01-13T11:35:03.657927Z [txindex] [util/thread.cpp:19] [TraceThread] txindex thread exit
                                       - 2022-01-13T11:35:03.658008Z [addcon] [util/thread.cpp:17] [TraceThread] addcon thread start
                                       - 2022-01-13T11:35:03.658038Z [net] [util/thread.cpp:17] [TraceThread] net thread start
                                       - 2022-01-13T11:35:48.557835Z [scheduler] [net.h:866] [StartExtraBlockRelayPeers] net: enabling extra block-relay-only peers
                                       - 2022-01-13T11:36:03.527809Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 33048 bytes of dynamic environment data into RNG
                                       - 2022-01-13T11:37:03.539139Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 33046 bytes of dynamic environment data into RNG
                                       - 2022-01-13T11:38:03.550191Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 33056 bytes of dynamic environment data into RNG
                                       - 2022-01-13T11:39:03.561817Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 33042 bytes of dynamic environment data into RNG
                                       - 2022-01-13T11:39:59.700827Z [net] [logging/timer.h:57] [Log] Enter: lock contention m_nodes_mutex, net.cpp:1256 started
                                       - 2022-01-13T11:39:59.700882Z [net] [logging/timer.h:57] [Log] Enter: lock contention m_nodes_mutex, net.cpp:1256 completed (2μs)
                                       - 2022-01-13T11:40:03.573567Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 33036 bytes of dynamic environment data into RNG
                                       - 2022-01-13T11:41:03.588927Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 33036 bytes of dynamic environment data into RNG
    test  2022-01-13T11:41:43.570000Z TestFramework (DEBUG): Closing down network thread 
    test  2022-01-13T11:41:43.621000Z TestFramework (INFO): Stopping nodes 
    test  2022-01-13T11:41:43.655000Z TestFramework.node0 (DEBUG): Stopping node 
   

2. MarcoFalke added the label Bug on Jan 13, 2022
3. 
   maektwain commented at 11:46 AM on January 15, 2022: none

   I tried running the test locally test/functional/test_runner.py feature_init.py this is passing

4. 
   MarcoFalke commented at 2:12 PM on January 15, 2022: member

   It is an intermittent issue, so it can not be reproduced

5. 
   MarcoFalke commented at 9:41 AM on January 25, 2022: member

   This happens more often on valgrind and qemu

6. MarcoFalke added this to the milestone 23.0 on Jan 25, 2022
7. MarcoFalke referenced this in commit 8f137e69ca on Jan 31, 2022
8. MarcoFalke closed this on Jan 31, 2022

   ---

9. sidhujag referenced this in commit 6dfc084488 on Feb 1, 2022
10. DrahtBot locked this on Jan 31, 2023

Milestone
23.0