From 79c5a0cbda07eded59f7c7c35d980ad930784383 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Thu, 8 Oct 2026 09:51:13 +0000 Subject: [PATCH] docs(buglog): bug-1924 fixed (e56f27f9) Co-Authored-By: Claude Opus 5.5 (1M context) --- .wolf/buglog.json | 12 +++++++----- .wolf/bugs/bug-1924.md | 16 +++++++++------- 2 files changed, 16 insertions(+), 12 deletions(-) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index bd2aed33..5a5bdfa0 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -17456,9 +17456,9 @@ }, { "id": "bug-1924", - "status": "open", + "status": "fixed", "status_updated": "2026-10-08", - "status_note": "newly logged", + "status_note": "", "component": "scheduler", "severity": "noise", "timestamp": "2026-10-08T09:30:37Z", @@ -17466,8 +17466,8 @@ "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", + "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.\n\nVerification:\n- 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.\n- Suites: `scheduler core clock test` OK on the branch build (asan, src/xce.build) after the cherry-pick; standalone run 15 Tests 0 Failures.\n- Live: n/a, a test-only change with no production code touched.", "tags": [ "test", "flaky", @@ -17475,7 +17475,9 @@ "tlog" ], "related_bugs": [], - "fix_commits": [], + "fix_commits": [ + "e56f27f9" + ], "record": ".wolf/bugs/bug-1924.md", "gitea_issue": 349, "gitea_synced_status": "open" diff --git a/.wolf/bugs/bug-1924.md b/.wolf/bugs/bug-1924.md index 322b0367..ef9dc5fa 100644 --- a/.wolf/bugs/bug-1924.md +++ b/.wolf/bugs/bug-1924.md @@ -1,8 +1,8 @@ --- id: "bug-1924" -status: "open" +status: "fixed" status_updated: "2026-10-08" -status_note: "newly logged" +status_note: "" component: "scheduler" severity: "noise" timestamp: "2026-10-08T09:30:37Z" @@ -11,6 +11,7 @@ occurrences: 1 files: ["src/scheduler/testsuite/test_clock.c"] tags: ["test", "flaky", "clock", "tlog"] related: [] +fix_commits: ["e56f27f9"] gitea_issue: 349 gitea_synced_status: "open" gitea_synced_hash: "c620260c5a09" @@ -46,15 +47,16 @@ The test sets `info->time.year = 1999` and asserts `strstr(buff, "1999") == NULL - 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 +`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 -TODO: required for fixed/partial +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: 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 +- 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