62 lines
4.9 KiB
Markdown
62 lines
4.9 KiB
Markdown
---
|
|
id: "bug-1924"
|
|
status: "fixed"
|
|
status_updated: "2026-10-08"
|
|
status_note: ""
|
|
component: "scheduler"
|
|
severity: "noise"
|
|
timestamp: "2026-10-08T09:30:37Z"
|
|
last_seen: "2026-10-08T09:30:37Z"
|
|
occurrences: 1
|
|
files: ["src/scheduler/testsuite/test_clock.c"]
|
|
tags: ["test", "flaky", "clock", "tlog"]
|
|
related: []
|
|
fix_commits: ["e56f27f9"]
|
|
gitea_issue: 349
|
|
gitea_synced_status: "fixed"
|
|
gitea_synced_hash: "03309e9ff280"
|
|
---
|
|
|
|
# bug-1924: scheduler core clock test fails when the test PID contains 1999 (tlog line includes getpid())
|
|
|
|
## Description
|
|
**Observed:** "scheduler core clock test" failed once in a full scheduler gate run (task 2.2 of scheduler-sim-decision-trace, 2026-10-08), then passed 5/5 on rerun:
|
|
```
|
|
../scheduler/testsuite/test_clock.c:351:test_tlog_format_shows_frozen_virtual_time_not_infotime:FAIL: formatted log line must NOT show info->time's wall-clock year while the virtual clock is frozen
|
|
15 Tests 1 Failures 0 Ignored
|
|
```
|
|
**Expected:** the test passes on every run. The formatter output is correct; only the assertion is too broad.
|
|
**Impact:** noise only. A random, rare failure of the scheduler suite (and of `/xce-build scheduler`) that has nothing to do with the change under test, costing a rerun and an investigation. No production effect.
|
|
**Found by:** spec task scheduler-sim-decision-trace 2.2 (full-suite gate run).
|
|
|
|
The test sets `info->time.year = 1999` and asserts `strstr(buff, "1999") == NULL` over the WHOLE formatted line. `xce_core_tlog_format()` (src/scheduler/src/core_clock.c:238-275) prints `[%5d]` with `getpid()` in that line, and the frozen virtual time (2033-05-18 03:33:20,000) is constant. So the assertion fails whenever the test process's PID contains the digits "1999" (e.g. 2619991). Confirmed by forcing such a PID (see Reproduction).
|
|
|
|
## Environment
|
|
- OS: no /etc/os-release; Docker container; NixOS kernel; kernel Linux 6.18.33 x86_64
|
|
- libc: glibc 2.42-47 (interpreter /nix/store/wb6rhpznjfczwlwx23zmdrrw74bayxw4-glibc-2.42-47/lib/ld-linux-x86-64.so.2)
|
|
- Toolchain: gcc (GCC) 15.2.0, meson 1.9.1
|
|
- Build: asan (xce.build)
|
|
- Code: scheduler-framework @ 54f9139e (first seen on the tree with task 2.2 uncommitted; test_clock.c and core_clock.c unchanged by it)
|
|
- Deployment: none (unit test binary `sched_core_clock_test`, meson suite `scheduler`, test name "scheduler core clock test")
|
|
|
|
## Reproduction
|
|
1. Build: `bash src/tools/xce-build.sh scheduler` (ASAN, `src/xce.build`).
|
|
2. `sh /home/claude/tmp/bug-1924/repro.sh src/xce.build/scheduler/testsuite` burns PIDs until the test binary runs under a PID containing "1999", then prints the result.
|
|
- Observed 2026-10-08: pid=2612000 PASS; pid=2619991 `test_tlog_format_shows_frozen_virtual_time_not_infotime: FAIL` (15 Tests 1 Failures).
|
|
- Frequency: deterministic for a PID containing "1999", otherwise never. Of the PIDs 1..4194304 (this host's `pid_max`), 2240 contain "1999" (0.053%); in the 2.0M-2.7M range the host was using, 0.034%. The original failure was one such unlucky run.
|
|
- Evidence: `/home/claude/tmp/bug-1924/` (`clock-pid1999.out`, the forced-PID run; `gate22-excerpt.log`, the original gate failure; `repro.sh`).
|
|
|
|
## Root cause
|
|
`test_tlog_format_shows_frozen_virtual_time_not_infotime` (src/scheduler/testsuite/test_clock.c) set `info->time.year = 1999` and asserted `strstr(buff, "1999") == NULL` over the whole formatted line. `xce_core_tlog_format()` (src/scheduler/src/core_clock.c:238-275) also writes `getpid()` into that line (`[%5d]`). With the virtual clock frozen, the timestamp is constant (2033-05-18 03:33:20,000 UTC, via `gmtime_r` in `ns_to_tlog_time`), so the only variable text is the PID. Any PID containing "1999" made the assertion fail although the formatter was correct. The defect was in the test, not the formatter; pre-existing since the test was added (scheduler-core task 4.5). Scope: the other tlog-format tests in test_clock.c assert specific substrings and do not search the whole line for a value the PID can contain.
|
|
|
|
## Fix
|
|
test_clock.c: the test now asserts the exact timestamp field, `TEST_ASSERT_EQUAL_STRING_LEN_MESSAGE("[2033-05-18 03:33:20,000] ", buff, 26, ...)`, instead of searching the whole line for "1999". That is both stricter (it pins the frozen virtual time) and independent of the PID. It still fails if the formatter prints `info->time` (1999-01-01), so it still catches the defect it was written for.
|
|
|
|
## Verification
|
|
- Test: `scheduler core clock test`, test_tlog_format_shows_frozen_virtual_time_not_infotime in src/scheduler/testsuite/test_clock.c. RED before the fix: forced with `/home/claude/tmp/bug-1924/repro.sh`, the old test FAILED under pid=2661999 (15 Tests 1 Failures). GREEN after: the fixed test PASSED under pid=2671999 (15 Tests 0 Failures), and passes in a normal run.
|
|
- Suites: `scheduler core clock test` OK on the branch build (asan, src/xce.build) after the cherry-pick; standalone run 15 Tests 0 Failures.
|
|
- Live: n/a, a test-only change with no production code touched.
|
|
|
|
## References
|
|
- Related: none
|
|
- Found by: .kiro/specs/scheduler-sim-decision-trace task 2.2 gate run
|