CI Flake `test_bwatch_reorg_at_startup`

[ddustin]

Appears to be an issue with the log order being different than the test expects. Notice Reorg detected... does appear in the log but before Added block...

Could be related to recent changes in bwatch in #9202

(CI Log)

@pytest.mark.slow_test
def test_bwatch_reorg_at_startup(node_factory, bitcoind):
    """Test bwatch handles reorg that happened while node was down"""
    l1 = node_factory.get_node(options=BWATCH_OPTS)

    # Wait for bwatch to initialize and fully sync
    wait_bwatch_caught_up(l1)

    bitcoind.generate_block(5)
    expected_height = bitcoind.rpc.getblockcount()
    # Wait for bwatch to catch up to these new blocks
    l1.daemon.wait_for_log(rf'Added block {expected_height} to history', timeout=60)

    # Get block hash before stopping
    height = bitcoind.rpc.getblockcount()
    reorg_from_hash = bitcoind.rpc.getblockhash(height - 2)

    # Stop the node
    l1.stop()

    # Cause a reorg while node is down
    bitcoind.rpc.invalidateblock(reorg_from_hash)
    bitcoind.generate_block(5)

    # Restart the node
    l1.start()

    # bwatch should detect the chain changed and handle reorg during catch-up
    # (reorg detection happens during catch-up, before "initialized" message)
    l1.daemon.wait_for_log(r'Reorg detected', timeout=60)

    # Wait for it to finish syncing
    l1.daemon.wait_for_log(r'No block change')

    # Verify the node is tracking the correct chain
    info = l1.rpc.getinfo()
    assert info['blockheight'] == bitcoind.rpc.getblockcount()

lightningd-1 2026-06-17T15:09:35.703Z DEBUG   lightningd: block_reverted: 105 -> 105
lightningd-1 2026-06-17T15:09:35.704Z INFO    plugin-cln-bwatch: Reorg detected at block 107: expected parent b4f95efe413f505fd910681bc8334241c950555321110375a979723644ede47a, got 816fbb7a941161e4bcd169d7c2cbb150011e98ba6fc49a412613ef95325b7a6d (fetched block hash: 8cf501086c040c6ce7c9e4ff1e0d260bc71a5673f6a5308f2bbe16cbd8c6834a)
lightningd-1 2026-06-17T15:09:35.704Z DEBUG   plugin-cln-bwatch: Removing stale block 106: b4f95efe413f505fd910681bc8334241c950555321110375a979723644ede47a
lightningd-1 2026-06-17T15:09:35.704Z DEBUG   plugin-cln-bwatch: Deleted block 106 from datastore
lightningd-1 2026-06-17T15:09:35.712Z DEBUG   lightningd: block_reverted: 105 -> 104
lightningd-1 2026-06-17T15:09:35.712Z INFO    plugin-cln-bwatch: Reorg detected at block 106: expected parent 768dc2e179d262c8917a613f78bcbdf21c771fab32631830a63922b23e4cd89e, got 388e0c8496c0c646225b03afe1791da4fdabc000cb3c399ec0bec7347c9d894b (fetched block hash: 816fbb7a941161e4bcd169d7c2cbb150011e98ba6fc49a412613ef95325b7a6d)
lightningd-1 2026-06-17T15:09:35.712Z DEBUG   plugin-cln-bwatch: Removing stale block 105: 768dc2e179d262c8917a613f78bcbdf21c771fab32631830a63922b23e4cd89e
lightningd-1 2026-06-17T15:09:35.712Z DEBUG   plugin-cln-bwatch: Deleted block 105 from datastore
lightningd-1 2026-06-17T15:09:35.720Z DEBUG   lightningd: block_reverted: 104 -> 103
lightningd-1 2026-06-17T15:09:35.720Z INFO    plugin-cln-bwatch: Reorg detected at block 105: expected parent a4669e36954b2538254f0e25a42a47b97c7d0a9db9dff69dd09b4f9f3845732e, got 0a308e9dba7ee725285fc0360635b23e596753279055253f355909a081d7e585 (fetched block hash: 388e0c8496c0c646225b03afe1791da4fdabc000cb3c399ec0bec7347c9d894b)
lightningd-1 2026-06-17T15:09:35.720Z DEBUG   plugin-cln-bwatch: Removing stale block 104: a4669e36954b2538254f0e25a42a47b97c7d0a9db9dff69dd09b4f9f3845732e
lightningd-1 2026-06-17T15:09:35.720Z DEBUG   plugin-cln-bwatch: Deleted block 104 from datastore
lightningd-1 2026-06-17T15:09:35.728Z DEBUG   plugin-cln-bwatch: Added block 104 to history (now 4 blocks)
lightningd-1 2026-06-17T15:09:35.728Z DEBUG   plugin-cln-bwatch: Added block 104 to datastore
lightningd-1 2026-06-17T15:09:35.728Z INFO    lightningd: block_processed: 103 -> 104
lightningd-1 2026-06-17T15:09:35.729Z DEBUG   connectd: REPLY WIRE_CONNECTD_ACTIVATE_REPLY with 0 fds
lightningd-1 2026-06-17T15:09:35.729Z DEBUG   lightningd: io_break: connect_activate_done
lightningd-1 2026-06-17T15:09:35.729Z DEBUG   lightningd: io_loop: connectd_activate
lightningd-1 2026-06-17T15:09:35.729Z INFO    lightningd: --------------------------------------------------
lightningd-1 2026-06-17T15:09:35.729Z INFO    lightningd: Server started with public key 038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b, alias STRANGEBOUNCE-98237af-modded (color #038194) and lightningd 98237af-modded
lightningd-1 2026-06-17T15:09:35.730Z DEBUG   plugin-cln-bwatch: Received block_processed ack for height 104
lightningd-1 2026-06-17T15:09:35.754Z DEBUG   lightningd: Adding block 106: 816fbb7a941161e4bcd169d7c2cbb150011e98ba6fc49a412613ef95325b7a6d
lightningd-1 2026-06-17T15:09:35.769Z DEBUG   lightningd: Adding block 107: 8cf501086c040c6ce7c9e4ff1e0d260bc71a5673f6a5308f2bbe16cbd8c6834a
lightningd-1 2026-06-17T15:09:35.770Z DEBUG   plugin-cln-bwatch: Added block 105 to history (now 5 blocks)
lightningd-1 2026-06-17T15:09:35.770Z DEBUG   plugin-cln-bwatch: Added block 105 to datastore
lightningd-1 2026-06-17T15:09:35.771Z INFO    lightningd: block_processed: 104 -> 105
lightningd-1 2026-06-17T15:09:35.772Z DEBUG   plugin-cln-bwatch: Received block_processed ack for height 105
lightningd-1 2026-06-17T15:09:35.781Z DEBUG   lightningd: Adding block 108: 84ad0eba80128356b456f1c5f3a641877b43dffcc90498cf3afda455e870ce66
lightningd-1 2026-06-17T15:09:35.792Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
lightningd-1 2026-06-17T15:09:35.793Z DEBUG   plugin-cln-bwatch: Added block 106 to history (now 6 blocks)
lightningd-1 2026-06-17T15:09:35.793Z DEBUG   plugin-cln-bwatch: Added block 106 to datastore
lightningd-1 2026-06-17T15:09:35.793Z INFO    lightningd: block_processed: 105 -> 106
lightningd-1 2026-06-17T15:09:35.794Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
lightningd-1 2026-06-17T15:09:35.794Z DEBUG   plugin-cln-bwatch: Received block_processed ack for height 106
lightningd-1 2026-06-17T15:09:35.806Z DEBUG   plugin-cln-bwatch: Added block 107 to history (now 7 blocks)
lightningd-1 2026-06-17T15:09:35.806Z DEBUG   plugin-cln-bwatch: Added block 107 to datastore
lightningd-1 2026-06-17T15:09:35.806Z INFO    lightningd: block_processed: 106 -> 107
lightningd-1 2026-06-17T15:09:35.807Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
lightningd-1 2026-06-17T15:09:35.807Z DEBUG   plugin-cln-bwatch: Received block_processed ack for height 107
lightningd-1 2026-06-17T15:09:35.819Z DEBUG   plugin-cln-bwatch: Added block 108 to history (now 8 blocks)
lightningd-1 2026-06-17T15:09:35.819Z DEBUG   plugin-cln-bwatch: Added block 108 to datastore
lightningd-1 2026-06-17T15:09:35.820Z INFO    lightningd: block_processed: 107 -> 108
lightningd-1 2026-06-17T15:09:35.820Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
lightningd-1 2026-06-17T15:09:35.821Z DEBUG   plugin-cln-bwatch: Received block_processed ack for height 108
lightningd-1 2026-06-17T15:09:35.825Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:09:36.331Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:09:36.840Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:09:37.345Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:09:37.849Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:09:38.355Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:09:38.897Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:09:39.403Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:03.054Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:03.567Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:04.076Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:04.582Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:05.098Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:05.603Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:05.670Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-1 2026-06-17T15:10:06.127Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:06.688Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:07.193Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:07.785Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:08.292Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:08.799Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:09.306Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:09.812Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:10.317Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:10.674Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-1 2026-06-17T15:10:10.825Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:11.399Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:11.905Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:12.434Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:12.985Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:13.492Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:13.999Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:15.050Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:15.679Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:15.709Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-1 2026-06-17T15:10:16.728Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:17.228Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:17.819Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:18.324Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:18.847Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:19.415Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:19.920Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:20.426Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:20.711Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-1 2026-06-17T15:10:20.937Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:21.442Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:21.947Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:22.455Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:22.959Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:23.465Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:23.968Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:24.474Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:24.979Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:25.485Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:25.714Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-1 2026-06-17T15:10:26.002Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:26.507Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:27.032Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:27.538Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:28.054Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:28.559Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:29.221Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:29.726Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:30.244Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:30.735Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-1 2026-06-17T15:10:30.770Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:31.377Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:31.884Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:32.489Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:32.995Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:33.511Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:34.018Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:34.535Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:35.041Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:35.570Z DEBUG   plugin-cln-bwatch: No block change, current_height remains 108
lightningd-1 2026-06-17T15:10:35.732Z DEBUG   gossipd: seeker: no peers, waiting
Time-out: can't find [re.compile('Reorg detected')] in logs
(re.compile('Reorg detected') was previously in logs!)
{'run_id': 325642318519767040, 'github_repository': 'ElementsProject/lightning', 'github_sha': '98237afef3dc3396678cfa32256580115f551adb', 'github_ref': 'refs/pull/9228/merge', 'github_ref_name': 'HEAD', 'github_run_id': 27693807830, 'github_head_ref': 'ddustin/pr_test', 'github_run_number': 16765, 'github_base_ref': 'master', 'github_run_attempt': '1', 'testname': 'test_bwatch_reorg_at_startup', 'start_time': 1781708973, 'end_time': 1781709035, 'outcome': 'fail'}