fix(scheduler): downgrade routine EEXIST resync log, dedup hash_string

xce_core_push_events() WARNed on every JOBS_PUSH resync redelivery (sched_add_job rc=-EEXIST), which is the expected outcome under on_scheduler_join()'s full resync or the array-push dedup race (bug-1734/bug-1714) and flooded operational logs. Only that case now logs via a new DBG() macro (utils.h); any other add_rc (e.g. -ENOMEM) still WARNs. DBG is named to avoid colliding with the build's own -DDEBUG command-line define (debug/asan buildtypes). Also collapsed hash_string()'s duplicated djb2 loop to delegate to hash_block(), which already implements the same RUN_HASH loop. Logged as bug-1809 in .wolf/buglog.json. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01RLSNJhNoULvVcUhXEFafQC
2026-09-15 02:46:52 +00:00 · 2026-09-15 02:46:52 +00:00 · b7250c2ec6
commit b7250c2ec6
parent 868c6427c8
7 changed files with 115 additions and 19 deletions
--- a/.wolf/anatomy-index.json
+++ b/.wolf/anatomy-index.json
@ -1,13 +1,13 @@
 {
  "version": 1,
  "meta": {
-    "lastScanned": "2026-09-14T15:07:50.753Z",
-    "fileCount": 559,
+    "lastScanned": "2026-09-15T02:34:37.112Z",
+    "fileCount": 562,
    "hits": 0,
    "misses": 0,
-    "renderedHash": "fa0ccc6a5e22b9c3ea839f6af7edb6a4e2e0c854e5dbcfa8e3efa2923b5ff5da",
-    "storeUpdatedAt": "2026-09-14T15:07:50.761Z",
-    "rootHash": "2113d381173797cb"
+    "renderedHash": "54b2e66594a769b4176755032afcc65e9009684d6c9b649e2e021d28c2b7f11f",
+    "storeUpdatedAt": "2026-09-15T02:34:37.121Z",
+    "rootHash": "cda4e7e066f4e166"
  },
  "files": {
    ".agent-shell/transcripts/2026-08-11-11-39-59.md": {
@ -10237,6 +10237,33 @@
      "mtimeMs": 1789398458927.6282,
      "updatedAt": "2026-09-14T15:07:38.971Z",
      "source": "hook"
+    },
+    "src/include/utils.h": {
+      "description": "if !defined(_UTILS_H_)",
+      "tokens": 2810,
+      "hash": "403aa4d8df678a9b",
+      "size": 10558,
+      "mtimeMs": 1789439662648.9136,
+      "updatedAt": "2026-09-15T02:34:22.692Z",
+      "source": "hook"
+    },
+    "src/scheduler/src/core_events.c": {
+      "description": "include <errno.h>",
+      "tokens": 16287,
+      "hash": "658f318636cb3ead",
+      "size": 61075,
+      "mtimeMs": 1789439677074.2285,
+      "updatedAt": "2026-09-15T02:34:37.112Z",
+      "source": "hook"
+    },
+    "src/lib/utils.c": {
+      "description": "include <ctype.h>",
+      "tokens": 7015,
+      "hash": "41554dd9aaeadade",
+      "size": 26308,
+      "mtimeMs": 1789428659757.0122,
+      "updatedAt": "2026-09-14T23:30:59.805Z",
+      "source": "hook"
    }
  }
 }
--- a/.wolf/anatomy.md
+++ b/.wolf/anatomy.md
@ -1,7 +1,7 @@
 # anatomy.md

-> Auto-maintained by OpenWolf. Last scanned: 2026-09-14T15:07:50.753Z
-> Files: 559 tracked | Anatomy hits: 0 | Misses: 0
+> Auto-maintained by OpenWolf. Last scanned: 2026-09-15T02:34:37.112Z
+> Files: 562 tracked | Anatomy hits: 0 | Misses: 0

 ## ./

@ -887,11 +887,13 @@
 ## src/include/

 - `resreq.h` — if !defined(_RESREQ_H_) (~3310 tok)
+- `utils.h` — if !defined(_UTILS_H_) (~2810 tok)

 ## src/lib/

 - `misc.c` — include <errno.h> (~486 tok)
 - `resreq.c` — define _XOPEN_SOURCE 700 (~6663 tok)
+- `utils.c` — include <ctype.h> (~7015 tok)

 ## src/lib/testsuite/

@ -904,6 +906,7 @@

 ## src/scheduler/src/

+- `core_events.c` — include <errno.h> (~16287 tok)
 - `plugin.c` — include <errno.h> (~4554 tok)
 - `repl_break.c` — include <stdio.h> (~9921 tok)
 - `repl_info.c` — include <stdio.h> (~16226 tok)
--- a/.wolf/buglog.json
+++ b/.wolf/buglog.json
@ -21943,6 +21943,39 @@
      ],
      "occurrences": 1,
      "last_seen": "2026-09-14T15:50:00Z"
+    },
+    {
+      "id": "bug-1809",
+      "timestamp": "2026-09-14T16:20:00Z",
+      "error_message": "User-reported: live scheduler logs are flooded with WARN lines for every ordinary XCE_CORE_EVENT_JOBS_PUSH resync redelivery: \"xce_core_push_events JOBS_PUSH: sched_add_job failed for jobid <id> (rc=-17), merging state into existing tracked job instead of discarding\" (src/scheduler/src/core_events.c). rc=-17 is -EEXIST -- the expected, routine outcome of on_scheduler_join()'s full resync (bug-1734) or the array-push dedup race (bug-1714), already correctly handled by the bug-1734/bug-1738/bug-1739 merge logic in the same branch, not a functional defect.",
+      "file": "src/scheduler/src/core_events.c (XCE_CORE_EVENT_JOBS_PUSH duplicate-jobid merge branch, ~line 845)",
+      "root_cause": "Not a defect -- a UX/observability request. sched_add_job() (core.c) wraps key_add()->kvtab_add() (lib/kv.c), whose only failure modes for the core->jobs table (KVMGR_KEY_INT, no keyops->assign) are -EEXIST (duplicate jobid) or -ENOMEM (allocation failure). The EEXIST case is therefore the near-universal, routine shape of this branch under a reconnect/resync storm (confirmed live in bug-1714's own investigation: 700+ of these WARNs fired from a single 8-reconnect burst) -- WARN was the wrong level for an outcome the code already handles correctly by design; it was originally added at WARN by bug-1734's own fix pass without considering steady-state log volume under the reconnect-storm conditions that same session's investigation had just captured.",
+      "fix": "FIXED (2026-09-14). Split the single WARN call in the JOBS_PUSH EEXIST branch (core_events.c) on add_rc: when add_rc == -EEXIST, log via a new DBG(...) macro (utils.h, wraps tlog_debug() -- DEBUG level, silent by default, visible with -vvv) instead of WARN -- preserves the message (still valuable forensic evidence per bug-1734/bug-1714) without flooding default-verbosity operational logs. Any OTHER negative add_rc (e.g. -ENOMEM) still logs at WARN, since that would be a genuine anomaly, not a routine resync artifact. The new macro is named DBG, not DEBUG, matching the existing TRACE/INFO/WARN/ERROR one-line wrapper convention in utils.h: a first attempt to name it DEBUG(...) collided with the build's own bare -DDEBUG command-line define (src/meson.build, set for BOTH the debug and asan buildtypes -- confirmed via build warning \"DEBUG redefined ... this is the location of the previous definition <command-line>\" across every file that includes utils.h under either profile), so DBG was used instead per user decision after the tradeoff was surfaced. Verified: xce-build.sh scheduler debug --incremental and xce-build.sh scheduler asan --incremental both compile clean (zero DBG/DEBUG-redefinition warnings in either profile); full scheduler suite 77/77 Ok, zero regressions.",
+      "tags": [
+        "scheduler",
+        "logging",
+        "observability",
+        "core_events-c",
+        "jobs_push",
+        "sched_add_job",
+        "eexist",
+        "log-level",
+        "noise-reduction",
+        "not-a-defect",
+        "session-sibling-of-bug-1734",
+        "session-sibling-of-bug-1714",
+        "fixed",
+        "DBG-macro",
+        "utils-h"
+      ],
+      "related_bugs": [
+        "bug-1734",
+        "bug-1714",
+        "bug-1739",
+        "bug-1738"
+      ],
+      "occurrences": 1,
+      "last_seen": "2026-09-14T16:20:00Z"
    }
  ]
 }
--- a/.wolf/memory.md
+++ b/.wolf/memory.md
@ -4707,3 +4707,17 @@
 | 08:07 | Edited src/harness/testsuite/test_test_cli.c | added 1 condition(s) | ~86 |
 | 08:07 | Edited src/harness/testsuite/test_test_cli.c | added 1 condition(s) | ~95 |
 | 08:07 | Edited src/harness/testsuite/harness_test.c | modified that() | ~184 |
+| 16:16 | Session end: 6 writes across 3 files (SKILL.md, test_test_cli.c, harness_test.c) | 6 reads | ~7319 tok |
+
+## Session: 2026-09-14 16:16
+
+| Time | Action | File(s) | Outcome | ~Tokens |
+|------|--------|---------|---------|--------|
+| 16:22 | Edited src/include/utils.h | 3→5 lines | ~35 |
+| 16:22 | Edited src/scheduler/src/core_events.c | added 1 condition(s) | ~371 |
+| 16:22 | Edited src/scheduler/src/core_events.c | 1804 → 1809 | ~20 |
+| 16:23 | Edited src/include/utils.h | 5→3 lines | ~23 |
+| 16:24 | Edited src/scheduler/src/core_events.c | modified if() | ~347 |
+| 16:30 | Edited src/lib/utils.c | modified hash_string() | ~24 |
+| 19:34 | Edited src/include/utils.h | expanded (+6 lines) | ~113 |
+| 19:34 | Edited src/scheduler/src/core_events.c | DEBUG() → DBG() | ~325 |
--- a/src/include/utils.h
+++ b/src/include/utils.h
@ -141,6 +141,12 @@

 #define TRACE(...) tlog_debug3(__VA_ARGS__)

+/* Named DBG, not DEBUG -- DEBUG is a bare command-line macro (-DDEBUG,
+ * src/meson.build) defined for both the debug and asan buildtypes, so
+ * `#define DEBUG(...)` here would trigger a "DEBUG redefined" warning in
+ * every translation unit that includes this header under either profile. */
+#define DBG(...) tlog_debug(__VA_ARGS__)
+
 #define INFO(...) tlog_info(__VA_ARGS__)

 #define ERROR(...) tlog_error(__VA_ARGS__)
--- a/src/lib/utils.c
+++ b/src/lib/utils.c
@ -802,12 +802,5 @@ uint32_t hash_block(char* buf, size_t len)

 uint32_t hash_string(const char* key)
 {
-    uint32_t hc = 5381;
-    int      c;
-
-    while ((c = *key++)) {
-        hc = RUN_HASH(hc, c);
-    }
-
-    return hc;
+    return hash_block((char*)key, strlen(key));
 }
--- a/src/scheduler/src/core_events.c
+++ b/src/scheduler/src/core_events.c
@ -842,10 +842,30 @@ int xce_core_push_events(xce_sched_core_t* core, xce_core_event_t* events,
                     * fmt_jobid(), referenced at each other call site below),
                     * instead of a raw numeric jobid. */
                    fmt_jobid(jobidStr, sizeof(jobidStr), job->jobid);
-                    WARN("%s JOBS_PUSH: sched_add_job failed for jobid %s "
-                         "(rc=%d), merging state into existing tracked job "
-                         "instead of discarding",
-                         __func__, jobidStr, add_rc);
+
+                    /* bug-1809 follow-up: -EEXIST here is the expected,
+                     * routine shape of a resync redelivery (on_scheduler_
+                     * join()'s full resync, or the array-push dedup race
+                     * bug-1714 documents) -- not an anomaly -- so it is
+                     * logged at DBG (utils.h's tlog_debug() wrapper -- named
+                     * DBG rather than DEBUG to avoid colliding with the
+                     * build's own -DDEBUG command-line define) instead of
+                     * WARN, to stop it from flooding operational logs under
+                     * the reconnect-storm conditions bug-1734/bug-1714 both
+                     * captured live. Any OTHER negative add_rc (e.g. -ENOMEM
+                     * from key_add()'s allocation path) is a genuine anomaly
+                     * and still WARNs. */
+                    if (add_rc == -EEXIST) {
+                        DBG("%s JOBS_PUSH: sched_add_job failed for jobid %s "
+                            "(rc=%d), merging state into existing tracked "
+                            "job instead of discarding",
+                            __func__, jobidStr, add_rc);
+                    } else {
+                        WARN("%s JOBS_PUSH: sched_add_job failed for jobid %s "
+                             "(rc=%d), merging state into existing tracked "
+                             "job instead of discarding",
+                             __func__, jobidStr, add_rc);
+                    }

                    if ((existing != NULL) && (existing->state != job->state)) {
                        /* bug-1738: never let a resync redelivery regress an