initialize_chain hangs forever: no-timeout wallet-sync loop + zebrad nodes left at divergent heights after final restart

[zancas]

Summary

full_test_suite.py (and any rpc-test using the cached chain) hangs forever during initialize_chain cache generation. The wait loop in qa/rpc-tests/test_framework/util.py that blocks on all wallets reaching the node tip has no timeout, and the 8 zebrad nodes it waits on end up stuck at divergent block heights that never converge — so the loop can never exit and the suite hangs instead of failing.

Symptom

Running:

uv run ./qa/zcash/full_test_suite.py

hangs with zallet repeatedly logging Reached chain tip, streaming mempool and re-scanning the same block range, with no further progress and no error.

Diagnosis

The hang is in initialize_chain, in the final wallet-sync wait:

https://github.com/zcash/integration-tests/blob/main/qa/rpc-tests/test_framework/util.py#L485

# Wait for zallets to synchronize with the nodes.
while True:                                    # <-- no timeout
    wallet_status = [ x.getwalletstatus() for x in wallets ]
    if all('wallet_tip' in w for w in wallet_status):
        tips = [ (w['node_tip']['blockhash'], w['wallet_tip']['blockhash']) for w in wallet_status ]
        if tips == [ tips[0] ]*len(tips) and tips[0][0] == tips[0][1]:
            break
    time.sleep(0.25)

This loop only breaks when all 8 wallets share one identical node_tip (tips == [tips[0]]*len(tips)) and each wallet's wallet_tip == node_tip. Unlike sync_blocks/sync_mempools (which have a 60s timeout and raise AssertionError), this one has no escape hatch.

Live evidence

Probing getwalletstatus on the hung run (5 samples, 1s apart — all stable):

wallet	node_tip.height	wallet_tip.height
0	162	162
1	162	162
2	162	162
3	180	180
4	177	177
5	176	176
6	176	176
7	186	186

Each wallet's wallet_tip exactly matches its own node_tip and is stable — i.e. the wallets are fully synced; zallet is not the problem. The 8 zebrad nodes are stuck at different heights (162–186) and never converge, so the all-equal condition can never hold.

Why the nodes diverge

The block-generation loop mines on one peer, then stops and restarts all 8 zebrad nodes every round as a workaround for ZcashFoundation/zebra#10329 / #10332 ("zebrad won't broadcast received blocks to other connected nodes"):

https://github.com/zcash/integration-tests/blob/main/qa/rpc-tests/test_framework/util.py#L424-L459

for i in range(2):
    for peer in range(4):
        # Connect the other nodes to the mining peer.
        for i in range(0, MAX_NODES):
            if i != peer:
                connect_nodes_bi(rpcs, i, peer)
        # Mine the blocks
        for j in range(25):
            rpcs[peer].generate(1)
            block_time += PRE_BLOSSOM_BLOCK_TARGET_SPACING
        # Must sync before next peer starts generating blocks
        sync_blocks(rpcs)
        # Shut down and restart every zebrad node. (workaround for zebra#10329/#10332)
        stop_nodes(rpcs)
        wait_bitcoinds()
        for i in range(MAX_NODES):
            ...restart each node...
        for i in range(MAX_NODES):
            rpcs.append(get_rpc_proxy(rpc_url(i), i))   # (1) appends instead of replacing

Two structural problems compound here:

1. No reconnect / final sync_blocks after the last restart. connect_nodes_bi runs only at the top of each round. After the final round's stop_nodes + restart, the nodes come back up not peered to each other and with no final sync_blocks — so they sit at divergent heights forever. (Confirmed: there is no connect_nodes/sync_blocks/generate between the loop and the wallet startup at lines 460–485.) This likely interacts with the ephemeral node state ([state] cache_dir = "", [network] cache_dir = false in qa/defaults/zebrad/config.toml): on restart each node has nothing to re-sync from.

2. rpcs.append(...) grows the list unbounded (line marked (1)) instead of replacing it — after 8 restarts rpcs holds ~72 proxy objects (all pointing at the same 8 ports). Latent, but it makes sync_blocks(rpcs) and rpcs[peer] increasingly confusing.

Note: the exact mechanism by which the heights end up different (rather than equal-but-isolated) after the final restart still needs confirmation — it may be the ephemeral-state + no-reconnect interaction above, or a deeper restart/IBD issue. The two facts that are fully verified: (a) the nodes are stable at divergent heights, and (b) the wait loop has no timeout so the suite hangs rather than failing.

Suggested fixes

1. Give the :485 loop a timeout (mirroring sync_blocks) so a non-converging chain fails loudly with the tip table printed, instead of hanging. This alone makes every future occurrence debuggable.
2. Reconnect + sync_blocks(rpcs) after the final restart (or restructure so the last round ends in a converged, synced state) so the 8 nodes actually share a tip before the wallets start.
3. Replace, don't append, rpcs after each restart (rpcs[:] = [...] or rebuild the list).

Environment

• integration-tests @ 175585714 (main)
• zallet 0.1.0-alpha.4, built from zallet main
• zebrad / zainod from current main
• Linux x86_64

[linear]

COR-1366

[zancas]

Update: root cause confirmed — single-chain height-lag, no reconnect after final restart

Added instrumentation to initialize_chain (per-round node-height logging + a timeout on the final wallet-sync loop) and recovered the decisive evidence from the zallet stderr logs of a failing run. This supersedes the speculative ephemeral-state / non-finalized-drop mechanism in the original report.

Evidence

The 8 "Reached chain tip" events in a single failing run, with the node tip at each:

event	tip height	hash
1	143	2b24ed87…
2	145	0c0080ef…
3	120	60872b55…
4	121	e23790b8…
5	112	55744949…
6	147	35fd8949…
7	189	35b6c143…
8	189	35b6c143…

No fork. Every height maps to exactly one block hash across the whole log:

height 150: 1 hash -> ee0004b8
height 160: 1 hash -> 2c2d1f36
height 170: 1 hash -> da3c9097
height 180: 1 hash -> cb8ed168
height 183: 1 hash -> a54f5638
height 185: 1 hash -> bd74dabe
height 188: 1 hash -> c1b91a1c
height 189: 1 hash -> 35b6c143

All 8 wallets eventually scan through block 188; only 7 reach 189.

Conclusion

• The nodes are on one identical chain — mining is coherent, no competing chains.
• The divergence is pure height-lag: laggard nodes stuck at different lengths (112–189) along that one chain.
• The nodes do acquire the chain from each other (via IBD on restart), but live block propagation between already-running peers is broken (zebra #10329 / #10332). Because the cache-generation loop's final restart has no subsequent connect_nodes_bi + sync_blocks, the lagging nodes never catch up, and the harness's exact-equality wait (all 8 nodes at the identical tip) becomes unsatisfiable.

This rules out the two earlier guesses (fork; non-finalized-state loss on restart). It's simpler: one chain, nodes left at unequal lengths with no mechanism to converge after the last restart.

Failure modes reconciled

Both observed symptoms are the same underlying issue:

• Per-round sync_blocks barely passes every round → lag accumulates → hang at the final wallet-sync loop (original report).
• One round's sync_blocks times out → Block sync failed. (This path also hit a separate latent bug: sync_blocks printed the undefined wallet_status when called with wallets=None, masking the real error — see fix below.)

Fixes (updated priority)

1. Reconnect + sync_blocks(rpcs) after the final restart in the generation loop (or restructure so the last round ends connected and synced). This is the primary fix and is now strongly supported by the evidence.
2. Add a timeout to the final wallet-sync while True (util.py, the getwalletstatus convergence loop) so a non-converging chain fails loudly with the divergent tips printed, instead of hanging forever.
3. sync_blocks: guard the wallet_status print behind if wallets: so a failed node-only sync raises Block sync failed cleanly instead of NameError.
4. Replace, don't append, rpcs after each restart (rpcs[:] = …) so the proxy list stays the canonical MAX_NODES nodes.

(Instrumentation used to obtain this: per-round log_node_heights printed to stderr at each after mine+sync / after restart step. Diagnostics must go to stderr+flush — the test runner buffers/drops subprocess stdout on failure, so stdout prints were lost.)