[BUG] Startup profiler mutation test can fail when timestamps do not advance #14

New issue

Open

opened 2026-09-12 09:37:27 +02:00 by erikinkinen · 0 comments

erikinkinen commented

2026-09-12 09:37:27 +02:00

Owner

Summary

The startup profiler's file-mutation fixture expects an immediate same-size
rewrite to advance filesystem timestamps. That assumption can make the fixture
fail before the Integration VM catalog runs. The failure appeared in the new
profiler's PR CI and is retained independently of passing local results.

Reproduction

At Integration 4416bcb2518b6d91b43cc7dfb8bbc8cde5e2840e, run
python3 -W error tests/startup_profile_test.py.

PR CI 1556,
integration job 19299, failed
FileAndCliTests.test_read_mutation_and_replacement_fail_with_descriptor_closed.
A separate local model that quantizes the reader's mtime/ctime identity fields
to whole seconds reproduces the same missing-exception assertion. The failing
runner's actual timestamp precision was not recorded, so this model establishes
the fixture assumption without claiming the runner's exact filesystem behavior.

Expected and actual behavior

Expected: the fixture deliberately supplies an observable metadata change or
path replacement, then checks rejection and descriptor cleanup independently
of host scheduling and timestamp resolution.

Actual: the same-size mutation branch writes different bytes and immediately
expects a changed file identity. CI reported ProfileError not raised and
FAILED (failures=1): 23 reporter tests passed and one failed. The preceding
37 collector and 21 unchanged-oracle tests passed. The helper step exited 1;
later VM acceptance did not run.

Environment and identity

Integration revision: 4416bcb2518b6d91b43cc7dfb8bbc8cde5e2840e.
Forgejo Docker host helper tests on Linux; no guest image or runtime
capability route is involved in this failing test.
Fixture inputs and output files are temporary caller-owned regular files.
Filesystem type, timestamp precision and Python patch version for the failed
process were not collected in its log.
Earlier local tests passed; no reliably failing frequency or earlier portable
version is established. The fixture is newly introduced at the stated head.

Evidence and prior checks

The complete CI log records the failure at 07:29:32 UTC on 2026-09-12. It contains
no compiler warnings; earlier helper error strings belong to intentional
negative fixtures. The coarse-timestamp model independently retains a red result.

Signed correction 7c1fe71b4f938029d0072919412f6bdce6db67d7 sets a distinct
mtime explicitly after the same-size
rewrite, preserves the path-replacement and descriptor-close assertions, and adds
a whole-second timestamp regression. All 25 reporter tests then pass with
warnings denied. The production reader's behavior is unchanged. Its documentation
clarifies the existing requirement to finish input writes before profiling:
metadata checks are not an atomic snapshot, and receipts bind the bytes read.
The correction's runs 1557/1558 passed the helper stage but were later cancelled
during partial VM catalogs. Their complete logs contain no test/compiler warnings.
Full replacement-head CI remains required; cancellation is not acceptance.

Tracking

Related profiler work: erix/integration#3. Audit: erix/integration#11.
Implementation review: erix/integration#12.

Retain the original CI failure and reproduce the fixture assumption.
Make mutation observable without sleeps or unchanged retries to green.
Preserve replacement/cleanup assertions and test coarse timestamp precision.
Publish the signed correction on the existing WIP pull request.
Review the correction's own complete CI results.

## Summary The startup profiler's file-mutation fixture expects an immediate same-size rewrite to advance filesystem timestamps. That assumption can make the fixture fail before the Integration VM catalog runs. The failure appeared in the new profiler's PR CI and is retained independently of passing local results. ## Reproduction At Integration `4416bcb2518b6d91b43cc7dfb8bbc8cde5e2840e`, run `python3 -W error tests/startup_profile_test.py`. [PR CI 1556](https://git.erikinkinen.fi/erix/integration/actions/runs/1556), integration job 19299, failed `FileAndCliTests.test_read_mutation_and_replacement_fail_with_descriptor_closed`. A separate local model that quantizes the reader's mtime/ctime identity fields to whole seconds reproduces the same missing-exception assertion. The failing runner's actual timestamp precision was not recorded, so this model establishes the fixture assumption without claiming the runner's exact filesystem behavior. ## Expected and actual behavior Expected: the fixture deliberately supplies an observable metadata change or path replacement, then checks rejection and descriptor cleanup independently of host scheduling and timestamp resolution. Actual: the same-size mutation branch writes different bytes and immediately expects a changed file identity. CI reported `ProfileError not raised` and `FAILED (failures=1)`: 23 reporter tests passed and one failed. The preceding 37 collector and 21 unchanged-oracle tests passed. The helper step exited 1; later VM acceptance did not run. ## Environment and identity - Integration revision: `4416bcb2518b6d91b43cc7dfb8bbc8cde5e2840e`. - Forgejo Docker host helper tests on Linux; no guest image or runtime capability route is involved in this failing test. - Fixture inputs and output files are temporary caller-owned regular files. Filesystem type, timestamp precision and Python patch version for the failed process were not collected in its log. - Earlier local tests passed; no reliably failing frequency or earlier portable version is established. The fixture is newly introduced at the stated head. ## Evidence and prior checks The complete CI log records the failure at 07:29:32 UTC on 2026-09-12. It contains no compiler warnings; earlier helper error strings belong to intentional negative fixtures. The coarse-timestamp model independently retains a red result. Signed correction `7c1fe71b4f938029d0072919412f6bdce6db67d7` sets a distinct mtime explicitly after the same-size rewrite, preserves the path-replacement and descriptor-close assertions, and adds a whole-second timestamp regression. All 25 reporter tests then pass with warnings denied. The production reader's behavior is unchanged. Its documentation clarifies the existing requirement to finish input writes before profiling: metadata checks are not an atomic snapshot, and receipts bind the bytes read. The correction's runs 1557/1558 passed the helper stage but were later cancelled during partial VM catalogs. Their complete logs contain no test/compiler warnings. Full replacement-head CI remains required; cancellation is not acceptance. ## Tracking Related profiler work: erix/integration#3. Audit: erix/integration#11. Implementation review: erix/integration#12. - [x] Retain the original CI failure and reproduce the fixture assumption. - [x] Make mutation observable without sleeps or unchanged retries to green. - [x] Preserve replacement/cleanup assertions and test coarse timestamp precision. - [x] Publish the signed correction on the existing WIP pull request. - [ ] Review the correction's own complete CI results.

erikinkinen added the

performance

bug

phase-6

labels

2026-09-12 09:37:27 +02:00

erikinkinen referenced this issue from a commit

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

test: Make profiler mutation checks independent of timestamp precision

~~erikinkinen referenced this issue 2026-09-12 09:46:11 +02:00~~

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

erikinkinen referenced this issue