[BUG] Development startup capture reaches the silence deadline before shell readiness #33

New issue

Open

opened 2026-09-12 22:00:10 +02:00 by erikinkinen · 0 comments

erikinkinen commented

2026-09-12 22:00:10 +02:00

Owner

Summary

A controlled local development-image startup capture reached the 15-second silence deadline before Rootd final readiness or the first shell prompt. The last recorded progress marker was ERIX_DEVICED:READY:DRV_RTC_CMOS. This prevented the baseline from reaching the startup acceptance checks; the planned candidate was not launched.

This is one observed pre-shell startup failure, not a CI result. The stalled operation and cause are unknown.

Reproduction

One capture was performed on 2026-09-12 with the identities below. There was no guest retry or threshold change. A deterministic trigger, recurrence rate and exact-source last-known-working guest comparison have not been established.

Use the recorded 132-MiB development image, with a fresh writable copy initially matching its digest and a fresh writable copy of the selected OVMF VARS template.
Select QEMU 10.2.2, q35 (pc-q35-10.2), KVM, one vCPU, 1 GiB RAM, the virtio boot disk, no additional disks, -nic none, and no display/video. Select RTC base 2035-04-05T06:37:00 with clock=vm.
From the selected Integration tooling revision, run bash scripts/run-disk-image-vm.sh with the development runtime, the physical native-ls input profile, a 120-second VM limit, 15-second serial-progress stall limit and 10-second command limit. Serial input is disabled.
Arm the selected scripts/measure-startup.py observer before the runner, using explicit serial/output/ready/done paths and --require-editor-caret --stop-marker LSSTATUS0 --timeout 120 --silence-seconds 15 --poll-seconds 0.002.

The actual capture used a reviewed bounded coordinator around those maintained commands, with separate waited role receipts and process containment. It did not directly execute the maintained startup test wrapper. The outer owner had a 190-second hard limit and 8-MiB output budget; the supervisor had a 180-second active limit and at most 5 seconds for cleanup. These details describe the retained attempt rather than a newly verified standalone reproducer.

Expected and actual behavior

Expected: the selected development image reaches ERIX_ROOTD:READY, the exact shell prompt and required caret/input milestones, then completes LSSTATUS0 so the unchanged startup gates can be evaluated.

Actual:

The observer retained 61 events and failed after 17.922501789 seconds of observation with startup observation exceeded its silence deadline.
The runner reported error: qemu stalled with no serial progress for 15s.
ERIX_ROOTD:READY, the first exact shell prompt and LSSTATUS0 were missing. The input log was empty; this does not establish that the injector never started.
The observer was waited with status 1. After observer failure, termination was requested for the runner, which was also waited with status 1. The runner status is a composed command result, not a recovered raw QEMU exit status. QEMU stderr records SIGTERM termination.
The outer owner, supervisor and coordinator all retained status 1. Their cleanup evidence records no cleanup error, an empty owned cgroup and successful removal. The candidate remained unlaunched.

No startup oracle or profile reporter ran. This is neither an accepted timing sample nor evidence of a speedup. The final progress marker alone does not identify a failing driver, deadlock, guest crash, host contention or toolchain regression.

Environment and identity

Original input image: 138,412,032 bytes; SHA-256 70f144f91b36536e4a9a9e7b2fe06272bb8aa47ea7a007664c0501d070878cd8; development runtime with program loader enabled, 64-MiB ESP and 64-MiB data partition; SOURCE_DATE_EPOCH=1789206335.
The writable disk changed during this attempt: its retained post-run SHA-256 is 2b88646ac423809f3d69dcfc56138c42afbd4259bd33d3a8b710225e7472ea32. The original input identity and the writable poststate are distinct; no claim of an untouched run disk is made.
The recorded graph has 73 original product revisions; its manifest SHA-256 is 87fb22258a5ffa843dfa8a79c3348a4960d78742ef4f89c561a078989afdff0a. The graph's Integration product node is 2efa2fc7122dc459649630b0baa736981e0a4bfc. The separately selected build/capture tooling is Integration 381bccd87c5632e9d1af8aa9d0aca295cbc00e1f.
Selected product revisions: Kernel fec1113a259c3cfff7d2dd942409b7f3f9df5e64; Bootloader 1563a4d9a5d523aa866896e13eb7fdc6ae728fb2; Rootd ac3c1847af9915164d4a819f5f15e1827884e8b1; Procd c7607afcbe8691a4c10a1e8e811c6542759db72f; Loaderd 9960bee61b4731a7bc4b0585cccc04c5ea03c0cc; Deviced dd6287e6538e7645fb02344a2ed696637f55c480; RTC driver a482e6fb28526c42e5692a99162cfc92d84b6be0.
Recorded image-build toolchain: rustc 1.93.0 (254b59607 2026-01-19) and cargo 1.93.0 (083ac5135 2025-12-15), using its selected bundled linker. These are build receipts, not versions inferred from a later local compiler.
QEMU 10.2.2 (qemu-10.2.2-1.fc44), executable SHA-256 27cd395848940fc6482256d85096fc64bc4fe3f3e909824d51c202f8314cd9e9. Its default CPU selection was used; the effective CPU model was not independently observed.
OVMF CODE SHA-256 904bfa3e0d966372b43b804c4fe323ae63751566687c2bfdf52ca947f47eb13a; initial VARS template SHA-256 6ed987af3a3c155be71665f510eae3e007eda9b8b94afd59d45e91c4a11565cc. The run used writable VARS, whose poststate was separately retained.
Host: x86-64 Linux 7.2.4-200.fc44.x86_64, glibc 2.43, Intel Core i7-10510U. A quiet local measurement window was reserved; host snapshots do not prove complete system-wide inactivity.

Evidence and prior checks

The retained serial tail contains readiness markers for PS/2 keyboard, PS/2 mouse, ACPI, virtio block and finally RTC CMOS. The complete 2,514-byte serial record has SHA-256 53c2789884dbe8cfe24bdc1f9ea0f26dd093bff8482d3b11475beaff2d5ba63d; the failed timing receipt has SHA-256 72ce287bb0db4d2d4da80edbad0d7f58185d7487eaf7c6739fe86ae8cde383e1.

The original image, source manifest, selected tooling and capture receipts were retained and rechecked. The maintained runner/observer source was checked against original Git objects. Successful preceding host image builds and artifact comparisons establish their scoped host results, not successful guest startup. The input disk and VARS poststates were preserved separately, and no second guest was used to seek a pass.

The existing startup gates remain unchanged: Rootd launch to final readiness at most 5 seconds, each readiness gap at most 1 second, final readiness to full caret at most 1 second, and all four native commands together at most 2 seconds. Those gates were not reached in this attempt.

Tracking

Related profiling work: Integration #3 and PR #12. The scoped preceding host artifact correction is #28.

This observation precedes shell readiness. Existing filesystem scenario timeouts (#20) and post-shell repeated-interrupt failure (#31) have different recorded phases; no shared cause is asserted. The next investigation should identify the missing startup progress boundary using the retained exact-source evidence while preserving the original failure and current deadlines.

## Summary A controlled local development-image startup capture reached the 15-second silence deadline before Rootd final readiness or the first shell prompt. The last recorded progress marker was `ERIX_DEVICED:READY:DRV_RTC_CMOS`. This prevented the baseline from reaching the startup acceptance checks; the planned candidate was not launched. This is one observed pre-shell startup failure, not a CI result. The stalled operation and cause are unknown. ## Reproduction One capture was performed on 2026-09-12 with the identities below. There was no guest retry or threshold change. A deterministic trigger, recurrence rate and exact-source last-known-working guest comparison have not been established. 1. Use the recorded 132-MiB development image, with a fresh writable copy initially matching its digest and a fresh writable copy of the selected OVMF VARS template. 2. Select QEMU 10.2.2, `q35` (`pc-q35-10.2`), KVM, one vCPU, 1 GiB RAM, the virtio boot disk, no additional disks, `-nic none`, and no display/video. Select RTC base `2035-04-05T06:37:00` with `clock=vm`. 3. From the selected Integration tooling revision, run `bash scripts/run-disk-image-vm.sh` with the development runtime, the physical `native-ls` input profile, a 120-second VM limit, 15-second serial-progress stall limit and 10-second command limit. Serial input is disabled. 4. Arm the selected `scripts/measure-startup.py` observer before the runner, using explicit serial/output/ready/done paths and `--require-editor-caret --stop-marker LSSTATUS0 --timeout 120 --silence-seconds 15 --poll-seconds 0.002`. The actual capture used a reviewed bounded coordinator around those maintained commands, with separate waited role receipts and process containment. It did not directly execute the maintained startup test wrapper. The outer owner had a 190-second hard limit and 8-MiB output budget; the supervisor had a 180-second active limit and at most 5 seconds for cleanup. These details describe the retained attempt rather than a newly verified standalone reproducer. ## Expected and actual behavior Expected: the selected development image reaches `ERIX_ROOTD:READY`, the exact shell prompt and required caret/input milestones, then completes `LSSTATUS0` so the unchanged startup gates can be evaluated. Actual: - The observer retained 61 events and failed after 17.922501789 seconds of observation with `startup observation exceeded its silence deadline`. - The runner reported `error: qemu stalled with no serial progress for 15s`. - `ERIX_ROOTD:READY`, the first exact shell prompt and `LSSTATUS0` were missing. The input log was empty; this does not establish that the injector never started. - The observer was waited with status 1. After observer failure, termination was requested for the runner, which was also waited with status 1. The runner status is a composed command result, not a recovered raw QEMU exit status. QEMU stderr records SIGTERM termination. - The outer owner, supervisor and coordinator all retained status 1. Their cleanup evidence records no cleanup error, an empty owned cgroup and successful removal. The candidate remained unlaunched. No startup oracle or profile reporter ran. This is neither an accepted timing sample nor evidence of a speedup. The final progress marker alone does not identify a failing driver, deadlock, guest crash, host contention or toolchain regression. ## Environment and identity - Original input image: 138,412,032 bytes; SHA-256 `70f144f91b36536e4a9a9e7b2fe06272bb8aa47ea7a007664c0501d070878cd8`; development runtime with program loader enabled, 64-MiB ESP and 64-MiB data partition; `SOURCE_DATE_EPOCH=1789206335`. - The writable disk changed during this attempt: its retained post-run SHA-256 is `2b88646ac423809f3d69dcfc56138c42afbd4259bd33d3a8b710225e7472ea32`. The original input identity and the writable poststate are distinct; no claim of an untouched run disk is made. - The recorded graph has 73 original product revisions; its manifest SHA-256 is `87fb22258a5ffa843dfa8a79c3348a4960d78742ef4f89c561a078989afdff0a`. The graph's Integration product node is `2efa2fc7122dc459649630b0baa736981e0a4bfc`. The separately selected build/capture tooling is Integration `381bccd87c5632e9d1af8aa9d0aca295cbc00e1f`. - Selected product revisions: Kernel `fec1113a259c3cfff7d2dd942409b7f3f9df5e64`; Bootloader `1563a4d9a5d523aa866896e13eb7fdc6ae728fb2`; Rootd `ac3c1847af9915164d4a819f5f15e1827884e8b1`; Procd `c7607afcbe8691a4c10a1e8e811c6542759db72f`; Loaderd `9960bee61b4731a7bc4b0585cccc04c5ea03c0cc`; Deviced `dd6287e6538e7645fb02344a2ed696637f55c480`; RTC driver `a482e6fb28526c42e5692a99162cfc92d84b6be0`. - Recorded image-build toolchain: `rustc 1.93.0 (254b59607 2026-01-19)` and `cargo 1.93.0 (083ac5135 2025-12-15)`, using its selected bundled linker. These are build receipts, not versions inferred from a later local compiler. - QEMU 10.2.2 (`qemu-10.2.2-1.fc44`), executable SHA-256 `27cd395848940fc6482256d85096fc64bc4fe3f3e909824d51c202f8314cd9e9`. Its default CPU selection was used; the effective CPU model was not independently observed. - OVMF CODE SHA-256 `904bfa3e0d966372b43b804c4fe323ae63751566687c2bfdf52ca947f47eb13a`; initial VARS template SHA-256 `6ed987af3a3c155be71665f510eae3e007eda9b8b94afd59d45e91c4a11565cc`. The run used writable VARS, whose poststate was separately retained. - Host: x86-64 Linux `7.2.4-200.fc44.x86_64`, glibc 2.43, Intel Core i7-10510U. A quiet local measurement window was reserved; host snapshots do not prove complete system-wide inactivity. ## Evidence and prior checks The retained serial tail contains readiness markers for PS/2 keyboard, PS/2 mouse, ACPI, virtio block and finally RTC CMOS. The complete 2,514-byte serial record has SHA-256 `53c2789884dbe8cfe24bdc1f9ea0f26dd093bff8482d3b11475beaff2d5ba63d`; the failed timing receipt has SHA-256 `72ce287bb0db4d2d4da80edbad0d7f58185d7487eaf7c6739fe86ae8cde383e1`. The original image, source manifest, selected tooling and capture receipts were retained and rechecked. The maintained runner/observer source was checked against original Git objects. Successful preceding host image builds and artifact comparisons establish their scoped host results, not successful guest startup. The input disk and VARS poststates were preserved separately, and no second guest was used to seek a pass. The existing startup gates remain unchanged: Rootd launch to final readiness at most 5 seconds, each readiness gap at most 1 second, final readiness to full caret at most 1 second, and all four native commands together at most 2 seconds. Those gates were not reached in this attempt. ## Tracking Related profiling work: [Integration #3](https://git.erikinkinen.fi/erix/integration/issues/3) and [PR #12](https://git.erikinkinen.fi/erix/integration/pulls/12). The scoped preceding host artifact correction is [#28](https://git.erikinkinen.fi/erix/integration/issues/28). This observation precedes shell readiness. Existing [filesystem scenario timeouts (#20)](https://git.erikinkinen.fi/erix/integration/issues/20) and [post-shell repeated-interrupt failure (#31)](https://git.erikinkinen.fi/erix/integration/issues/31) have different recorded phases; no shared cause is asserted. The next investigation should identify the missing startup progress boundary using the retained exact-source evidence while preserving the original failure and current deadlines.

erikinkinen added the

performance

bug

phase-6

labels

2026-09-12 22:00:10 +02:00

erikinkinen referenced this issue

2026-09-12 22:15:18 +02:00

[BUG] Startup collector accepts images without the required readiness and shell contract #34

~~erikinkinen referenced this issue 2026-09-12 22:17:56 +02:00~~

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

erikinkinen referenced this issue