ExportXMLWordPrintableJSON

    • Type: Bug
    • Resolution: Fixed
    • Priority: Major - P3
    • 9.1.0-rc0, 9.1.0-rc1024
    • Affects Version/s: None
    • Component/s: None
    • None
    • Server Security
    • Fully Compatible
    • ALL
    • Server Security 2026-09-25, Server Security 2026-10-09
    • None
    • None
    • None
    • None
    • None
    • None
    • None

      Claude Overview

      What the logs show (disagg_pali_chaos_key_long bug hunt runs 29 and 32)

      • Every 13436 is a read: a find on chaos_items by _id with secondaryPreferred and maxTimeMS: 2000, rejected by d20093 with "node is not in primary or recovering state". That is the workload's secondaryRead op. The harness counts all ops, reads included, in its outage detector and labels the result "write outage".
      • Timing: d20093 was the primary killed by evt-039 (run 29) / evt-034 (run 32). The errors start as soon as the restarted d20093 is listening and still in STARTUP2 (19:09:56 in run 29, 19:07:24 in run 32). In run 32 they end right when d20093 logs "Accepting reads" (19:08:59). d20092 became primary and stayed primary throughout.
      • Why they cluster: the error rate jumps from ~50/s to ~500/s exactly when the workload rotates into the read-heavy-secondary profile (47% secondary reads). In run 32, the big outages turn into the "long tail" of 1–2-op outages at the next rotation, to ddl-heavy (4%). So the ticket's triage question 3 has an answer: the tail is the same thing at a lower read rate.

      How the reads reached a node that wasn't ready

      1. Server: the disagg replSetGetStatus reports every non-primary member as SECONDARY, whatever its real state (replication_coordinator_disagg_storage.cpp:2148).
      2. Workload: resolveSecondaryConn (chaos_workload.js:53-55) picks whichever member reports stateStr === "SECONDARY" and sends the find there without checking. When its own hello check correctly sees the node isn't a secondary, it asks the primary, is told "SECONDARY", and tries again.
      3. Connection leak: each attempt opens a new connection that is never closed. d20093's "Connection accepted" count per second matches its 13436 count almost exactly, and its connection count reached 10,667.

      Why the harness called them "unexplained"

      The outage window for an event is its injection time + 30 s, extended from restoredAtMs or by a 240 s recovery allowance.

      • When the deferred restart fails, chaos_controller.js:689 breaks out of the loop before restoredAtMs is recorded (:709).
      • recoveryAttempted (chaos_metrics.js:99) doesn't count deferredRestartError, so no recovery allowance applies either.

      So the window closed at injection + 30 s. The first "unexplained" outage opens 0.6 s after that in run 29 and 0.4 s after in run 32, while the deferred restart was still running.

      A harness crash in run 29

      The standby's replica-set address is a Python partition proxy (20094 → 20093). Each proxied connection uses 6 file descriptors, and 10,667 leaked connections × 6 = 64,002, just over the 64,000 limit. At 19:10:29.6 the proxy crashed with OSError: [Errno 24] Too many open files. That closed every connection at once and ended the run 29 outage cluster. The proxy address stayed dead for the rest of the run.

      Suggested fixes (not implemented)

      • Workload: check hello.secondary on the candidate before using it, close replaced connections, and track secondary-read failures separately from write outages.
      • Controller: stamp restoredAtMs or apply the recovery allowance when a deferred restart fails.
      • Proxy: handle EMFILE in _on_accept instead of crashing.
      • Server (small, separate ticket): make replSetGetStatus report the peer's real state.

      Other notes

      • Cause vs. symptom: the underlying trigger is the node failing to reach SECONDARY, which SERVER-135303 already covers (closed as a duplicate of SERVER-135292). This ticket is a harness side effect of that.
      • Current master hides it, for the wrong reason: the SERVER-135382 cooldown filter uses the last event's end time. In run 29 that is 994704 ms into the run, because evt-039 never got a restoredAtMs. All these outages start after it, so master would log them as cooldown outages instead of failing on them.

      Not investigated:

        - Why d20092 wasn't seen as primary in the post-chaos checks (it never stepped down). That belongs to SERVER-135303.
        - Why the 5 s STARTUP2 wait ran 82 s. The loop only checks its deadline between calls, and my guess is one of its calls blocked on the half-started node.
        - The single 20 ms outage in run 29 (7 failed ops, error 515 ConnectionClosedByPeer, at 1,231,932 ms into the run).

      Human Summary

      This ticket will handle harness improvements. The trigger is covered by the tickets linked in SERVER-135303. This ticket should:

      • close the connection in resolveSecondaryConn and check hello on the chosen node,
      • handle EMFILE in the proxy,
      • and extend the event window when a deferred restart fails

            Assignee:
            Sam Frank
            Reporter:
            Sam Frank
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: