[BUG] Positive console-progress host fixture expires before completion #25

New issue

Open

opened 2026-09-12 15:05:04 +02:00 by erikinkinen · 0 comments

erikinkinen commented

2026-09-12 15:05:04 +02:00

Owner

Summary

A positive console-progress host fixture fails in Integration CI before the VM
catalog. Its watchdog returns status 125 instead of zero while a synthetic Python
child is intended to emit verified framebuffer milestones without serial output.
The complete 15-test group reports one failure; no guest VM is involved in this
failure.

Reproduction

At Integration b518b6ad1d2f3e7a36a5d796eaff3103c051bb84, the maintained workflow
runs:

python3 tests/console_progress_watchdog_test.py

The failing case is
ConsoleWatchdogProcessTests.test_verified_completions_allow_framebuffer_work_without_serial_output.
The retained observation is push CI 1567.
No isolated rerun or failure-frequency estimate has been established.

Expected and actual behavior

The positive fixture expects the watchdog to accept its complete ordered
framebuffer transcript and return the synthetic child's zero status despite
absent serial output.

Instead, the assertion at test line 297 receives 125. The diagnostic says no
change in the fixture's selected serial file for 0.25 seconds. The group ends
Ran 15 tests in 5.537s, FAILED (failures=1), and the workflow step returns 1.
Earlier invalid-argument diagnostics belong to expected negative cases and are
not this failure.

The watchdog supervises a host python -c event writer, not QEMU. It may credit
only four verified milestone types; activity and late evidence cannot revive an
expired deadline. The retained diagnostic does not report the last emitted or
accepted milestone, child start/completion timestamps, or scheduler activity.
It therefore does not establish whether writer progress, watchdog polling,
startup or another cause accounts for the observed deadline.

Environment and identity

Integration: b518b6ad1d2f3e7a36a5d796eaff3103c051bb84; push run 1567,
API run 9037, integration job 19432, attempt 1; terminal failure.
The exact failing test, watchdog and milestone-plan source bytes match
Integration e2b1cf5995bcf6334839cda9a013e90fa97787d5. This observation does not
identify a causal source commit.
Configuration: existing container host fixture; a fresh temporary serial path
and observer file, framebuffer mode, 0.25-second stall interval, 0.02-second
polling interval, 0.1-second termination grace and a five-second outer wait.
The synthetic child writes 33 planned events, sleeping 0.04 seconds after
each. Source-derived nominal spacing between credited milestones is at most
0.16 seconds, excluding Python startup, file I/O, scheduler and polling delay.
These are planned values, not measured timestamps for the failing invocation.
No image, firmware, guest runtime or exact host executable hash was established
by this log review. No contention or common cause with filesystem VM failures
is inferred.

Evidence and prior checks

The complete job log and exact run/job metadata are retained. The assertion is
reported at 2026-09-12 12:30:27 UTC. Rust and Markdown jobs pass at the same head;
the Rust job records 320 default and 321 all-feature tests. The VM catalog and
later image gates are not reached. Exact-head PR run 1568 was waiting at the
observation; it is not replacement acceptance.

The test deletes its temporary directory after its subprocess returns, and the
retained CI log contains no observer-file snapshot. A read-only source review
establishes the fixture construction but cannot reconstruct the actual failing
event timeline. No retries, deadline changes, source changes or warning
suppression were used to classify the failure.

Tracking

Related validation stream: Integration #5;
component audit: Integration #11;
implementation tracking: WIP PR #12.
Determine the failing fixture timeline and preserve the verified-progress,
negative/stale-evidence and expiry-order assertions. Host test reliability and
full VM acceptance require distinct evidence; relaxing guest deadlines is not
an established remedy.

A fixture-only follow-up is published at Integration 4bb694279e4a83aad95d14780434340beb4c649c in PR 12. Synthetic writers close each record explicitly, and failed status assertions now include bounded scalar file observations captured before temporary cleanup. Existing cadence, expiry order, deadlines and assertions are unchanged; all 15 focused warning-denied tests pass locally. The production watchdog is unchanged. Written records are distinct from accepted progress, so this does not establish the earlier failure cause or close the issue. The later current-head CI observation is recorded below.

At Integration 381bccd87c5632e9d1af8aa9d0aca295cbc00e1f, PR CI 1574 fails the same positive assertion before the VM catalog at 2026-09-12 14:48:22 UTC. It returns 125 rather than zero. The new scalar observation records 279 bytes, three complete written records and last event console_disabled_input_rejected; no preexisting or truncated file, no serial file, total wall interval 0.434021529 seconds. All 15 tests ran in 5.634 seconds with one failure. These fields do not identify when events were written or accepted, so neither scheduling contention nor a watchdog defect is established. The exact-head push run passes this host group and later enters the VM catalog; both outcomes remain recorded, and the failure is not closed.

A deterministic fixture correction is published at Integration 96f1c21848d534683fc077779dd92d332e3e4779 in PR 12. The test-local clock and child schedule exercise the actual watchdog run loop and reader against real files. All 21 focused warning-denied tests pass locally, covering 33 events, 14 independent milestone credits, before/exact/late expiry, non-credit and serial-only activity, malformed evidence and preservation of nonzero child status. Four independent sensitivity mutations are rejected. The five existing real negative subprocess cases remain unchanged, as does the production watchdog. Test-local termination mocks establish control flow rather than complete process-tree cleanup. This removes wall-clock scheduling from the positive policy fixture without attributing the historical failure to a proven cause.

At 2026-09-12 16:02 UTC, exact-head push CI 1575 and PR CI 1576 both pass the 21-case group (2.660 and 2.661 seconds). Rust and Markdown jobs pass; both main jobs remain running in later host checks. Full CI acceptance is pending, and the preceding failed runs remain separately retained.

At 16:04:48 UTC, push CI 1575 subsequently fails a separate host process-cleanup test while reading proc stat (ProcessLookupError, 36-test group with one error), before the VM catalog. Its watchdog acceptance above remains valid. PR CI 1576 continues independently; neither outcome establishes full current-head acceptance.

## Summary A positive console-progress host fixture fails in Integration CI before the VM catalog. Its watchdog returns status 125 instead of zero while a synthetic Python child is intended to emit verified framebuffer milestones without serial output. The complete 15-test group reports one failure; no guest VM is involved in this failure. ## Reproduction At Integration `b518b6ad1d2f3e7a36a5d796eaff3103c051bb84`, the maintained workflow runs: ```sh python3 tests/console_progress_watchdog_test.py ``` The failing case is `ConsoleWatchdogProcessTests.test_verified_completions_allow_framebuffer_work_without_serial_output`. The retained observation is [push CI 1567](https://git.erikinkinen.fi/erix/integration/actions/runs/1567). No isolated rerun or failure-frequency estimate has been established. ## Expected and actual behavior The positive fixture expects the watchdog to accept its complete ordered framebuffer transcript and return the synthetic child's zero status despite absent serial output. Instead, the assertion at test line 297 receives 125. The diagnostic says no change in the fixture's selected serial file for 0.25 seconds. The group ends `Ran 15 tests in 5.537s`, `FAILED (failures=1)`, and the workflow step returns 1. Earlier invalid-argument diagnostics belong to expected negative cases and are not this failure. The watchdog supervises a host `python -c` event writer, not QEMU. It may credit only four verified milestone types; activity and late evidence cannot revive an expired deadline. The retained diagnostic does not report the last emitted or accepted milestone, child start/completion timestamps, or scheduler activity. It therefore does not establish whether writer progress, watchdog polling, startup or another cause accounts for the observed deadline. ## Environment and identity - Integration: `b518b6ad1d2f3e7a36a5d796eaff3103c051bb84`; push run 1567, API run 9037, integration job 19432, attempt 1; terminal failure. - The exact failing test, watchdog and milestone-plan source bytes match Integration `e2b1cf5995bcf6334839cda9a013e90fa97787d5`. This observation does not identify a causal source commit. - Configuration: existing container host fixture; a fresh temporary serial path and observer file, framebuffer mode, 0.25-second stall interval, 0.02-second polling interval, 0.1-second termination grace and a five-second outer wait. - The synthetic child writes 33 planned events, sleeping 0.04 seconds after each. Source-derived nominal spacing between credited milestones is at most 0.16 seconds, excluding Python startup, file I/O, scheduler and polling delay. These are planned values, not measured timestamps for the failing invocation. - No image, firmware, guest runtime or exact host executable hash was established by this log review. No contention or common cause with filesystem VM failures is inferred. ## Evidence and prior checks The complete job log and exact run/job metadata are retained. The assertion is reported at 2026-09-12 12:30:27 UTC. Rust and Markdown jobs pass at the same head; the Rust job records 320 default and 321 all-feature tests. The VM catalog and later image gates are not reached. Exact-head PR run 1568 was waiting at the observation; it is not replacement acceptance. The test deletes its temporary directory after its subprocess returns, and the retained CI log contains no observer-file snapshot. A read-only source review establishes the fixture construction but cannot reconstruct the actual failing event timeline. No retries, deadline changes, source changes or warning suppression were used to classify the failure. ## Tracking Related validation stream: [Integration #5](https://git.erikinkinen.fi/erix/integration/issues/5); component audit: [Integration #11](https://git.erikinkinen.fi/erix/integration/issues/11); implementation tracking: [WIP PR #12](https://git.erikinkinen.fi/erix/integration/pulls/12). Determine the failing fixture timeline and preserve the verified-progress, negative/stale-evidence and expiry-order assertions. Host test reliability and full VM acceptance require distinct evidence; relaxing guest deadlines is not an established remedy. A fixture-only follow-up is published at Integration `4bb694279e4a83aad95d14780434340beb4c649c` in [PR 12](https://git.erikinkinen.fi/erix/integration/pulls/12). Synthetic writers close each record explicitly, and failed status assertions now include bounded scalar file observations captured before temporary cleanup. Existing cadence, expiry order, deadlines and assertions are unchanged; all 15 focused warning-denied tests pass locally. The production watchdog is unchanged. Written records are distinct from accepted progress, so this does not establish the earlier failure cause or close the issue. The later current-head CI observation is recorded below. At Integration `381bccd87c5632e9d1af8aa9d0aca295cbc00e1f`, [PR CI 1574](https://git.erikinkinen.fi/erix/integration/actions/runs/1574) fails the same positive assertion before the VM catalog at 2026-09-12 14:48:22 UTC. It returns 125 rather than zero. The new scalar observation records 279 bytes, three complete written records and last event `console_disabled_input_rejected`; no preexisting or truncated file, no serial file, total wall interval 0.434021529 seconds. All 15 tests ran in 5.634 seconds with one failure. These fields do not identify when events were written or accepted, so neither scheduling contention nor a watchdog defect is established. The exact-head push run passes this host group and later enters the VM catalog; both outcomes remain recorded, and the failure is not closed. A deterministic fixture correction is published at Integration `96f1c21848d534683fc077779dd92d332e3e4779` in [PR 12](https://git.erikinkinen.fi/erix/integration/pulls/12). The test-local clock and child schedule exercise the actual watchdog run loop and reader against real files. All 21 focused warning-denied tests pass locally, covering 33 events, 14 independent milestone credits, before/exact/late expiry, non-credit and serial-only activity, malformed evidence and preservation of nonzero child status. Four independent sensitivity mutations are rejected. The five existing real negative subprocess cases remain unchanged, as does the production watchdog. Test-local termination mocks establish control flow rather than complete process-tree cleanup. This removes wall-clock scheduling from the positive policy fixture without attributing the historical failure to a proven cause. At 2026-09-12 16:02 UTC, exact-head [push CI 1575](https://git.erikinkinen.fi/erix/integration/actions/runs/1575) and [PR CI 1576](https://git.erikinkinen.fi/erix/integration/actions/runs/1576) both pass the 21-case group (2.660 and 2.661 seconds). Rust and Markdown jobs pass; both main jobs remain running in later host checks. Full CI acceptance is pending, and the preceding failed runs remain separately retained. At 16:04:48 UTC, push CI 1575 subsequently fails a separate host process-cleanup test while reading proc stat (`ProcessLookupError`, 36-test group with one error), before the VM catalog. Its watchdog acceptance above remains valid. PR CI 1576 continues independently; neither outcome establishes full current-head acceptance.

erikinkinen added the

bug

phase-6

labels

2026-09-12 15:05:04 +02:00

~~erikinkinen referenced this issue 2026-09-12 15:24:49 +02:00~~

WIP: Coordinate native authority, shell workspace and source transport #12

erikinkinen referenced this issue

2026-09-12 15:42:02 +02:00

[BUG] Dynamic build cache fixture omits newly declared helper inputs #26

erikinkinen referenced this issue

2026-09-12 18:14:02 +02:00