diff --git a/.wolf/buglog.json b/.wolf/buglog.json index d9bd2762..d69c50e8 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -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" } ] } diff --git a/.wolf/bugs/bug-1924.md b/.wolf/bugs/bug-1924.md new file mode 100644 index 00000000..06e3f8f1 --- /dev/null +++ b/.wolf/bugs/bug-1924.md @@ -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