docs(buglog): bug-1924 clock test fails when the test PID contains 1999

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-10-08 09:31:10 +00:00
parent 54f9139e77
commit 90d417bb1b
Signed by untrusted user: rshen
GPG key ID: 80533536B0EB651C
2 changed files with 81 additions and 0 deletions

View file

@ -17453,6 +17453,30 @@
"record": ".wolf/bugs/bug-1923.md",
"gitea_issue": 348,
"gitea_synced_status": "fixed"
},
{
"id": "bug-1924",
"status": "open",
"status_updated": "2026-10-08",
"status_note": "newly logged",
"component": "scheduler",
"severity": "noise",
"timestamp": "2026-10-08T09:30:37Z",
"last_seen": "2026-10-08T09:30:37Z",
"occurrences": 1,
"error_message": "scheduler core clock test fails when the test PID contains 1999 (tlog line includes getpid())\n\n**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:\n```\n../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\n15 Tests 1 Failures 0 Ignored\n```\n**Expected:** the test passes on every run. The formatter output is correct; only the assertion is too broad.\n**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.\n**Found by:** spec task scheduler-sim-decision-trace 2.2 (full-suite gate run).\n\nThe 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).",
"file": "src/scheduler/testsuite/test_clock.c",
"root_cause": "TODO: required for fixed/partial",
"fix": "TODO: required for fixed/partial\n\nVerification:\n- Test: TODO: name + file; RED before the fix, GREEN after\n- Suites: TODO: suite results and build profile\n- Live: TODO: soak/deploy run, or n/a and why",
"tags": [
"test",
"flaky",
"clock",
"tlog"
],
"related_bugs": [],
"fix_commits": [],
"record": ".wolf/bugs/bug-1924.md"
}
]
}

57
.wolf/bugs/bug-1924.md Normal file
View file

@ -0,0 +1,57 @@
---
id: "bug-1924"
status: "open"
status_updated: "2026-10-08"
status_note: "newly logged"
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: []
---
# 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
TODO: required for fixed/partial
## Fix
TODO: required for fixed/partial
## Verification
- Test: TODO: name + file; RED before the fix, GREEN after
- Suites: TODO: suite results and build profile
- Live: TODO: soak/deploy run, or n/a and why
## References
- Related: none