Bound transaction trace polling in test harness

[huangminghuang]

Summary

Bound TestHarness clio get transaction_trace polling so a single stuck clio subprocess cannot outlive the harness wait budget.

What changed

• Added optional subprocess timeout plumbing to the shared TestHarness command helpers.
• Passed the existing 3-second transaction-trace poll interval as a per-command timeout.
• Handled subprocess.TimeoutExpired in processClioCmd the same way other silent polling failures are handled.

Why

publishContract(..., waitForTransBlock=True) uses a bounded wait for transaction inclusion, but the nested clio get transaction_trace call previously had no subprocess timeout. If that command blocked, bootstrap could stall for many minutes and later contract-publish transactions could expire against the advanced chain time.

This was observed while validating performance_test_basic_p2p on macOS arm64 after PR #369.

Testing

• python3 -m py_compile tests/TestHarness/testUtils.py tests/TestHarness/queries.py
• On the source worktree with the same patch applied:
  • ctest --test-dir build/macos-arm64-jit-chain-release -j 1 -R "^performance_test_basic_p2p$" --output-on-failure --timeout 1000
  • Result: passed in 104.73 sec

[heifner]

Reviewed all three commits. The core fix is solid: the kill / reap-with-communicate() / re-raise pattern in checkDelayedOutput is exactly what the Python docs prescribe for TimeoutExpired, attaching the captured output and chaining from ex is better than most hand-rolled versions, every new timeout kwarg defaults to None so existing callers are unaffected (I checked the call sites), and time.perf_counter() is the right clock for the deadline. Two logic gaps in the rewritten getTransaction polling loop are worth fixing before merge though - both land in exactly the slow-CI regime this PR targets.

1. The final attempt isn't guaranteed to run, so exitOnError/silentErrors can be silently dropped

wire-sysio/tests/TestHarness/queries.py

Lines 252 to 272 in 42cb303

	while True:
	remainingBudget=pollDeadline - time.perf_counter()
	if remainingBudget <= 0:
	break
	finalAttempt=remainingBudget <= pollTimeout
	timeout=min(pollTimeout, remainingBudget)
	attemptStart=time.perf_counter()
	trans=self.processClioCmd(cmd, cmdDesc,
	silentErrors=silentErrors if finalAttempt else True,
	exitOnError=exitOnError if finalAttempt else exitOnErrorForDelayed,
	exitMsg=msg, timeout=timeout)
	if trans is not None or not delayedRetry:
	return trans
	if finalAttempt:
	break
	remainingBudget=pollDeadline - time.perf_counter()
	if remainingBudget <= 0:
	break
	if Utils.Debug: Utils.Print("Could not find transaction with id %s, delay and retry" % (transId))
	attemptElapsed=time.perf_counter() - attemptStart
	time.sleep(min(max(0, pollTimeout - attemptElapsed), remainingBudget))

The loop defers the caller's silentErrors/exitOnError to the designated final attempt (finalAttempt = remainingBudget <= pollTimeout), but the two remainingBudget <= 0 break paths can exit the loop without that attempt ever running. Example: loop-top remaining budget is 3.2s, so finalAttempt=False and the attempt runs silenced; the subprocess times out at its full 3s cap, and kill/reap/log-write overhead pushes the attempt's elapsed time past 3.2s; the post-attempt check then breaks out of the loop.

In that case getTransaction(transId, silentErrors=False, exitOnError=True) returns None with no error printed and no errorExit. The old code unconditionally made the trailing processClioCmd(...) call with the caller's semantics, so the error contract always held. trace_plugin_test.py (lines 99 and 145) relies on the hard exit, and getBlockNumByTransId turns the silent None into a misleading "transaction ... not found. Transaction: None" instead of a timeout diagnostic.

2. The final attempt can get a nearly-zero subprocess timeout

wire-sysio/tests/TestHarness/queries.py

Lines 256 to 257 in 42cb303

	finalAttempt=remainingBudget <= pollTimeout
	timeout=min(pollTimeout, remainingBudget)

When attempts time out back-to-back (slow node), the inter-poll sleep is skipped (max(0, pollTimeout - attemptElapsed) is 0), so each cycle consumes 3s + overhead and the residual budget at the final loop-top lands roughly uniformly in (0, 3]. timeout=min(pollTimeout, remainingBudget) then gives the one attempt that surfaces errors e.g. 0.15s to fork clio, connect, and run the query - a near-guaranteed spurious TimeoutExpired. With exitOnError=True that errorExits the whole test run even if the trace had just become available (the old final attempt was unbounded).

Suggested fix for both

Run the final attempt unconditionally with a full pollTimeout window:

while True:
    remainingBudget=pollDeadline - time.perf_counter()
    finalAttempt=remainingBudget <= pollTimeout
    attemptStart=time.perf_counter()
    trans=self.processClioCmd(cmd, cmdDesc,
                              silentErrors=silentErrors if finalAttempt else True,
                              exitOnError=exitOnError if finalAttempt else exitOnErrorForDelayed,
                              exitMsg=msg, timeout=pollTimeout)
    if trans is not None or not delayedRetry:
        return trans
    if finalAttempt:
        break
    if Utils.Debug: Utils.Print("Could not find transaction with id %s, delay and retry" % (transId))
    attemptElapsed=time.perf_counter() - attemptStart
    time.sleep(max(0, pollTimeout - attemptElapsed))

Worst case overshoots the 60s budget by one poll interval (~63s), guarantees a meaningful final attempt with the caller's error semantics, and deletes both <= 0 breaks plus the second remainingBudget recomputation.

Worth discussing

• transactions.py:301-310 - a SIGKILLed clio push may already have broadcast the transaction, so (False, msg) on timeout doesn't mean state is unchanged. Not retrying is the right call (a re-push re-signs with a fresh expiration -> new trx id -> double-apply risk), but a comment noting the ambiguity would help callers that treat False as "action not applied".
• testUtils.py:206-225 - latent hang: with a string cmd, delayedCheckOutput spawns via shell=True, so popen.kill() SIGKILLs only the shell; the orphaned child keeps the pipe write-ends open and the post-kill communicate() blocks forever. Every current timeout user passes a list cmd, so it isn't reachable today - but an assert (list cmd when timeout is not None) or start_new_session=True + killpg would keep it that way.
• None of the three new TimeoutExpired handlers is exercised by any test. A tiny self-test - Utils.checkOutput(["sleep", "100"], timeout=1) asserting the raise happens promptly, ex.output is attached, and the child is gone - would lock in the kill/reap/re-raise contract cheaply.
• pushMessage's 45s default vs free-form opts: no current caller passes retry flags, but a future --retry-num-blocks/--retry-irreversible push could legitimately exceed 45s waiting for inclusion and get killed mid-wait (see the broadcast ambiguity above). Worth a sentence on the constant.

Minor

• queries.py:616 vs queries.py:628: the CalledProcessError message reports cumulative end-start while the new timeout message reports per-attempt end-attemptStart; aligning them keeps mixed retry/timeout logs readable.
• The TimeoutExpired handler block is near-verbatim in processClioCmd and processSysioUtilCmd, with a third variant in pushMessage - a small shared helper would keep the message format and exit behavior in one place.
• The .decode("utf-8") calls on killed-process output can hit a truncated multi-byte sequence and raise UnicodeDecodeError inside the except handler, masking the timeout diagnostic; errors="replace" is the cheap guard (killed-mid-write is exactly where truncation happens).
• transactions.py:267 - timeout=push_message_timeout_default binds 45 at def time, so runtime or subclass overrides of the class constant won't take effect. The sibling retry_num_blocks_default uses the None-default + resolve-at-call pattern, so the two class constants now behave differently.
• processSysioUtilCmd's new timeout parameter has no callers yet - fine as plumbing, just noting the handler is unreachable today.
• Drive-by observation: self.missingTransaction is write-only across the repo (set here, initialized in Node.__init__, never read) - might be worth deleting or hooking up while touching it.