chore(buglog): bug-1864 fixed (0d3bb965); log bug-1865

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

.wolf/buglog.json

@@ -27770,7 +27770,7 @@
       "error_message": "OPEN, NOT FIXED, low priority. Every HA soak run logs 'ERROR [sched_init_resources] sched_init_resources add resource <name> failed' for EVERY configured resource (~33 lines), once per scheduler process, ~30s after it joined -- i.e. when a primary failover makes the scheduler re-join and the controller re-pushes its config (231/264/429 lines in 3 soak runs today). Scheduling is unaffected in those runs (all soaks PASS, replay parity 0 mismatches).",
       "file": "src/scheduler/src/scheduler.c",
       "root_cause": "sched_init_config() is written as a first-time initializer but runs on every config push (sched_apply_pending_config, including each rejoin's push). sched_init_resources() calls makeResource() for each config->resources[i], which fails when the name is already registered in core.resmgr (key_add of an existing key) and only logs. Consequences: (1) ERROR log noise on every rejoin; (2) latent: a rejoin/upgrade config push that CHANGES a resource definition (flags, valtype, order) never updates the scheduler's copy. Pre-existing -- the same call ran on the handler thread before bug-1846's deferral; not introduced by it. sched_init_queues() re-adding queues on each push is worth checking under the same lens.",
-      "fix": "NOT FIXED. Candidate: on an existing name, update the registered xce_resource_t in place (or treat identical definitions as a no-op and log at DEBUG), mirroring core_events.c's core_upsert_* upsert posture for RESOURCES_PUSH; decide separately whether a changed definition needs picker/accounting refresh.",
+      "fix": "NOT FIXED. Candidate: on an existing name, update the registered xce_resource_t in place (or treat identical definitions as a no-op and log at DEBUG), mirroring core_events.c's core_upsert_* upsert posture for RESOURCES_PUSH; decide separately whether a changed definition needs picker/accounting refresh.\n\nUPDATE (2026-09-25): 2026-09-25: same defect also at the core CONFIG_PUSH path -- core_events.c core_apply_config_resources() calls makeResource() per pushed resource; makeResource_() (lib/resobj.c) returns NULL/EEXIST for any already-registered name and the caller logs ERROR 'core_apply_config_resources add resource <name> failed'. Seen as 33 ERROR lines in data/scheduler-replay-20260925-133708.replay (sim --sim-verify, b63bb581): the scheduler rejoined at 13:39:27 and the controller re-pushed CONFIG (plus WORKERS/JOB_PUSH) onto a core whose resources were already registered. Verify 0 mismatches, all 60 jobs DONE -- noise only in that run. A fix must cover both sites (sched_init_resources and core_apply_config_resources): identical definition -> no-op at DEBUG; changed definition -> decide update-in-place vs loud WARN.",
       "tags": [
         "scheduler",
         "config-push",
@@ -27971,6 +27971,52 @@
       "related_bugs": [],
       "occurrences": 1,
       "last_seen": "2026-09-25T13:07:56Z"
+    },
+    {
+      "id": "bug-1864",
+      "status": "fixed",
+      "status_updated": "2026-09-25",
+      "status_note": "0d3bb965",
+      "timestamp": "2026-09-25T14:26:45Z",
+      "error_message": "Standby controllers NACK in-order WAL catch-up entries (ae_reject_logmismatch, prevIdx one ahead of their log) ~576 times in a 45-min run (data/logs, 2026-09-25): e.g. ctrl-2 21:37:50.115 handled walCatchupEntry seq 258 (prevIdx=149) BEFORE seq 257 (prevIdx=148). With both standbys NACKing, the primary marks them catch-up, loses its write quorum and answers jobdispatch/join with E_XCE_NOT_READY (-10013) (ctrl-1 21:39:24.494); the scheduler client fails over (bug-1850), rejoins, and gets a JOBS_PUSH built from lagging committed state -> 'refusing resync state 0x1 ... existing job is RUN' WARNs for 14 jobs.",
+      "file": "src/lib/vtaskmgr.c,src/lib/dataq.c,src/lib/netio.c",
+      "root_cause": "vtaskmgr's dispatcher (pick_eligible_task -> dataq_deq(taskq, vtask_eligible)) evaluates each queued task's eligibility one item at a time while holding only the taskq lock; the per-endpoint busy flag it reads (endpoint_is_task_blocked) is cleared by the vcpu finishing the previous message WITHOUT that lock. Within one scan, task N (seq 257) is checked while the endpoint is still busy and skipped, the endpoint unblocks, and task N+1 (seq 258) for the SAME endpoint is then found eligible and dequeued first. endpoint_block_tasks gives mutual exclusion per endpoint but not FIFO order. Log proof (ctrl-2 21:37:50.113-.118): '04b650 not eligible' -> 'endpoint not blocked' -> '03cae0 eligible' in one scan; 03cae0=seq 258, 04b650=seq 257; tasks enqueued in arrival order by the single netio thread (vtask_handle_msg).",
+      "fix": "UPDATE (2026-09-25): Fix (uncommitted): dataq gains dataq_deq_ctx (per-scan matcher context); vtaskmgr's scan is now vtask_deq_eligible(taskq, is_blocked) with a per-scan set of endpoints found busy -- every later task of such an endpoint stays ineligible for the rest of that scan (overflow past 64 distinct busy endpoints makes all later IO tasks ineligible), so per-endpoint FIFO holds without taking any new lock (bug-1282 ABBA). Test lib/testsuite/test_vtask_order.c: is_blocked injected to flip ep busy->free mid-scan; reproduced the reorder (N+1 dequeued) before, NULL after; other-endpoint progress and FIFO/generic cases pass. Suites: lib 1/1, controller 5/5, worker 10/10, scheduler 87/87, harness 5/5. Reorder signature (reject prevIdx=K then accept K-1): user run 26 (-> 576 NACKs incl. cascades), pre-fix chaotic soaks 2 and 5.",
+      "tags": [
+        "lib",
+        "vtaskmgr",
+        "ordering",
+        "race",
+        "replication",
+        "ha",
+        "controller"
+      ],
+      "related_bugs": [],
+      "occurrences": 1,
+      "last_seen": "2026-09-25T14:26:45Z"
+    },
+    {
+      "id": "bug-1865",
+      "status": "open",
+      "status_updated": "2026-09-25",
+      "status_note": "HA closes a copied netio ep->fd (primary_ctrl_fd) that netio already closed -> closes the reused WAL fd",
+      "timestamp": "2026-09-25T14:43:27Z",
+      "error_message": "Standby's WAL fd closed out from under it at failover: chaotic HA soak 2026-09-25 (ha-chaos-o1), ctrl-3 at 14:39:55.574 'liveness poll: no primary activity for 11s -> failover' / 'primary_ctrl_fd RDHUP', and 3 ms later 'flusher fallback fdatasync FAILED (errno=9 Bad file descriptor) -- durable_lsn held at 90', then errno=22 EINVAL once the number was reused by a socket; 2305 fdatasync failures, durable_lsn stuck; soak still PASSed (counted as excluded bug924) but one round's jobsub failed EIO.",
+      "file": "src/controller/ha.c,src/controller/config_repl.c",
+      "root_cause": "config_repl.c:2192 stores the netio endpoint's raw fd (c->ha.primary_ctrl_fd = ep->fd) and ha_on_primary_ctrl_fd_rdhup (ha.c:8648, three branches) later close()s it directly. netio owns that socket and closes it on endpoint teardown, so by then the number may have been reused -- here by the standby's WAL segment (lowest free fd) -- and HA's close() closes the WAL instead. Double close / stale fd. Once a socket takes the number, WAL fdatasync gets EINVAL and pwrite could write WAL bytes into a socket.",
+      "fix": "",
+      "tags": [
+        "controller",
+        "ha",
+        "fd",
+        "double-close",
+        "persist",
+        "wal",
+        "durability"
+      ],
+      "related_bugs": [],
+      "occurrences": 1,
+      "last_seen": "2026-09-25T14:43:27Z"
     }
   ]
 }