Эх сурвалжийг харах

M11 NATS investigation: root cause + fix plan

The M11 conditional-ship finding (2-min re-verify 2026-06-16
14:48 EDT) traced to NATS JetStream hitting its server-level
max_storage cap (5.46 GiB default) because ALERTS stream's 24h
retention allowed 6.1 GiB of test data to accumulate.

Server is in 'limit exceeded' state, rejecting new publishes.
The 10-min soak was a false positive because the receive-rate
metric (ba_ingestd_alerts_received_total) only counts gRPC
receive, not NATS publish success.

Fix plan in three layers:
  Short-term (M11 unblock):
    - ALERTS max_age: 24h -> 1h
    - ALERTS max_bytes: 1G (with DiscardOld)
    - DELIVERIES/DLQ max_bytes: 100M / 10M
    - docker-compose: explicit -ms=5G on NATS
    - Restart NATS to apply
  Medium-term (recurrence prevention):
    - Add ba_ingestd_nats_publish_total{result=ok} counter
    - Update m11_smoke to assert publish rate
    - Add NATS storage PromQL alert (>80%)
  Long-term (M12):
    - W2: 3-broker NATS JetStream cluster, R=3 streams
    - W6: dashboards + alertmanager for NATS resources

Host disk is 6.5G free, so 5G cap is the safe ceiling.
Luis Rosales 1 сар өмнө
parent
commit
fafba39e6c
1 өөрчлөгдсөн 300 нэмэгдсэн , 0 устгасан
  1. 300 0
      M11_NATS_INVESTIGATION.md

+ 300 - 0
M11_NATS_INVESTIGATION.md

@@ -0,0 +1,300 @@
+# M11 NATS JetStream Investigation
+
+**Date:** 2026-06-16
+**Investigator:** OpenClaw
+**Status:** Root cause identified, fix proposed
+**Severity:** Critical (blocks M11 ship, blocks M12 W1)
+
+---
+
+## TL;DR
+
+NATS JetStream server is in **"resource limits exceeded"** state because the default server-level `max_storage` cap (5.46 GiB) is exceeded by the streams holding 6.1 GB of historical test data. New publishes are being rejected. The 10-min M11 soak was a false positive — `ba_ingestd_alerts_received_total` measures gRPC receive, not NATS publish success, so a broken publish path looks like a working system.
+
+**Single-line fix:** Lower the stream `max_age` from 24h to 1h (and add a `max_bytes` safety cap) so streams self-trim well before the server cap is reached. Plus explicitly raise the server's `max_storage` flag for safety.
+
+---
+
+## Investigation timeline
+
+| Time | Finding |
+|---|---|
+| 12:37 EDT | 10-min M11 soak at 9.5k/s — looks green, but rate metric hides publish failures |
+| 12:48 EDT | 2-min re-verification: rate collapses from 9.7k/s → 0/s at 2m mark |
+| 14:48 EDT | NATS logs: `[ERR] JetStream resource limits exceeded for server` every 10s |
+| 14:48 EDT | ingestd logs: `nats publish` returning `context canceled` |
+| 15:35 EDT (this doc) | Confirmed: server `max_storage: 5.46 GiB` exceeded by `bytes: 6.1 GiB` in streams |
+
+---
+
+## Evidence
+
+### Server-level state (from `/varz`)
+
+```json
+"jetstream": {
+  "config": {
+    "max_memory": 12493725696,        // 12.5 GB (≈90% of 15.5GiB cgroup limit)
+    "max_storage": 5858774016,        // 5.46 GiB ← THE BUG
+    "store_dir": "/data/jetstream"
+  },
+  "stats": {
+    "memory": 0,
+    "storage": 6534853971,            // 6.08 GiB ← EXCEEDS max_storage
+    "reserved_memory": "1.8e19",
+    "reserved_storage": "1.8e19"
+  }
+}
+```
+
+### Stream-level state (from on-disk `meta.inf`)
+
+**ALERTS stream:**
+```json
+{
+  "name": "ALERTS",
+  "subjects": ["alerts.>"],
+  "retention": "limits",
+  "max_msgs": -1,                    // unlimited
+  "max_bytes": -1,                   // unlimited
+  "max_age": 86400000000000,         // 24h (in nanoseconds)
+  "storage": "file",
+  "num_replicas": 1
+}
+```
+
+**State:** 11,387,410 messages, 6.1 GB, first message 2026-06-15T20:49, last 2026-06-15T22:54.
+
+### Stream creation code (`internal/broker/broker.go`)
+
+```go
+streams := []struct {
+    name     string
+    subjects []string
+    age      time.Duration
+}{
+    {"ALERTS", []string{"alerts.>"}, 24 * time.Hour},       // 24h ← too long
+    {"DELIVERIES", []string{"deliveries.>"}, 1 * time.Hour}, // 1h (OK)
+    {"DLQ", []string{"dlq.>"}, 7 * 24 * time.Hour},          // 7d (probably also too long)
+}
+```
+
+The code DOES set `MaxAge` correctly. The bug is that 24h retention for ALERTS, combined with the default `max_storage` of 5.46 GiB, means any sustained 6k/s+ test load fills the storage within a few hours.
+
+### NATS logs (from `docker logs broad-announce-nats-1`)
+
+```
+[ERR] JetStream resource limits exceeded for server
+[ERR] JetStream resource limits exceeded for server
+... (every 10s)
+```
+
+### Host disk (parres)
+
+```
+/dev/mapper/pve-root   37G   29G  6.5G  82% /
+```
+
+NATS volume: 6.1 GB used of the 6.5 GB free on `/`. **There's no headroom.**
+
+---
+
+## Root cause
+
+NATS 2.10's default `max_storage` is auto-calculated to a percentage of available disk space (5.46 GiB in this case). The ALERTS stream's 24h retention allows messages to accumulate until they exceed the cap. Once exceeded:
+
+1. NATS enters "limit exceeded" state
+2. New publishes are **rejected** (returns error to ingestd)
+3. The 6.1 GB of already-stored messages are **kept** (the limit is soft — it caps new writes, not existing data)
+4. ingestd's `nats.Publish` call returns `context canceled`
+5. The gRPC stream propagates the error to the loadgen
+6. Loadgens close their streams
+7. The `ba_ingestd_alerts_received_total` rate drops to 0
+8. The smoke concludes the system is broken
+
+**The 10-min M11 soak was a false positive because the rate metric (`alerts_received_total`) only counts gRPC receive, not successful publish. The 6k/s for 10 minutes looked healthy, but the publish path was actually broken the whole time — and 2 minutes wasn't long enough for the storage to fill past the cap until AFTER the test window.**
+
+Wait, that's backwards — 2 min re-verify DID show the failure. The 10-min soak DIDN'T show the failure. So the publish path was working for 10 min but failed in 2 min. That means:
+
+- The 10-min soak was BEFORE the test run that hit the cap
+- The 2-min re-verify was AFTER, when storage was already near the cap
+- The remaining storage ran out at 2 min
+
+Actually re-reading: the 10-min soak was yesterday 2026-06-15 20:49 → 22:54, and the storage was already at 6.1 GB at the end. So the cap was hit during the soak, but the receive rate metric kept going because ingestd kept receiving from loadgens (gRPC is decoupled from publish).
+
+Then the 2-min re-verification today, with cap already exceeded, failed within 2 min because the storage was full from the start.
+
+**The 10-min soak's "green" status is itself the false positive — the publish path was failing intermittently throughout, but the metric only showed receive rate.**
+
+---
+
+## Why this wasn't caught earlier
+
+1. **The smoke only asserts on receive rate**, not publish success. The receive path is decoupled from the publish path (gRPC receive → ingestd → NATS publish), so a broken publish looks like a working receive.
+
+2. **No publish-failure metric** in ingestd. There's no `ba_ingestd_nats_publish_total{result="error"}` counter. We can't even tell after the fact how many publishes failed.
+
+3. **Storage monitoring gap.** 6.1 GB of data accumulated over 2 hours of testing and nobody noticed. The PromQL targets don't include NATS storage usage.
+
+4. **No alerts on NATS resource-limit errors.** The `[ERR] JetStream resource limits exceeded` log line is silent unless someone watches the logs.
+
+5. **The 24h retention was set without checking disk capacity.** M0-era code, written when there was no production data. Should have been tuned for the actual disk budget.
+
+---
+
+## Proposed fix
+
+### Short-term (M11 ship-blocker)
+
+**1. Lower ALERTS retention to 1h** in `internal/broker/broker.go`
+
+```go
+// Before:
+{"ALERTS", []string{"alerts.>"}, 24 * time.Hour},
+
+// After:
+{"ALERTS", []string{"alerts.>"}, 1 * time.Hour},
+```
+
+**Why 1h is enough:** routerd is the only consumer, and it processes messages in real-time. Once a message is acked by routerd, it doesn't need to be in the stream anymore. The 1h window is a safety net for slow consumers, not a hard requirement.
+
+**2. Add `max_bytes` to ALERTS** as a hard cap
+
+```go
+_, err := c.js.CreateOrUpdateStream(ctx, jetstream.StreamConfig{
+    Name:         s.name,
+    Subjects:     s.subjects,
+    MaxAge:       s.age,
+    MaxBytes:     1 << 30, // 1 GiB hard cap
+    Storage:      jetstream.FileStorage,
+    Discard:      jetstream.DiscardOld, // drop oldest when MaxBytes hit
+})
+```
+
+`DiscardOld` ensures we never block the producer — old messages get dropped, new ones flow through.
+
+**3. Bump server `max_storage` flag** in `docker-compose.yml`
+
+```yaml
+nats:
+  image: nats:2.10-alpine
+  command: ["-js", "-sd", "/data", "-m", "8222", "-ms=10G"]
+  #                               new flag: ^^^^ 10 GiB cap
+```
+
+`10G` is well under the 37G disk minus headroom for OS + Docker layers.
+
+**4. Reduce DLQ retention from 7d to 1h** (or 24h)
+
+DLQ messages are operational artifacts. The 7d window is excessive for a dev box. Recommend 1h for dev, 24h for prod.
+
+**5. Restart NATS** to apply the new server limit, then re-run M11 smoke.
+
+### Medium-term (M11 follow-up)
+
+**1. Add a publish-success counter to ingestd:**
+
+```go
+// In ingestd's nats.Publish wrapper
+var natsPublishTotal = promauto.NewCounterVec(prometheus.CounterOpts{
+    Name: "ba_ingestd_nats_publish_total",
+    Help: "NATS publish attempts by result",
+}, []string{"result"})  // ok, error, timeout
+
+func (p *natsPublisher) Publish(ctx, subject, data) error {
+    _, err := p.js.PublishAsync(subject, data)
+    if err != nil {
+        natsPublishTotal.WithLabelValues("error").Inc()
+        return err
+    }
+    natsPublishTotal.WithLabelValues("ok").Inc()
+    return nil
+}
+```
+
+**2. Update M11 smoke to assert on publish success:**
+
+```python
+def assert_publish_ok(target_rate, tolerance, window_seconds=30):
+    q = f'rate(ba_ingestd_nats_publish_total{{result="ok"}}[{window_seconds}s])'
+    rate = float(prom_query(q))
+    if rate < target_rate * (1 - tolerance):
+        fail_(f"NATS publish rate {rate:.0f}/s < target {target_rate}/s")
+    pass_(f"NATS publish rate {rate:.0f}/s ≥ {target_rate}/s")
+```
+
+**3. Add NATS storage PromQL alert:**
+
+```yaml
+- alert: NatsJetStreamStorageHigh
+  expr: (jetstream_stats_storage / jetstream_config_max_storage) > 0.80
+  for: 5m
+  annotations:
+    summary: "NATS JetStream storage > 80% of max_storage"
+```
+
+### Long-term (M12, per the plan)
+
+- **W2: Multi-broker NATS cluster** (3 brokers, R=3 streams) — raises the storage ceiling by 3x and provides single-broker-loss resilience
+- **W6: Observability** — proper dashboards + alertmanager rules for NATS resource usage
+
+---
+
+## Verification plan (after fix)
+
+1. Apply code changes
+2. Restart NATS: `docker compose restart nats`
+3. Verify streams come up with new config (check `meta.inf` on disk)
+4. Run M11 smoke at 6k/s × 10 min — should now publish-clean for 10 min
+5. Run with `--duration 30m` to confirm streams self-trim and storage stays under cap
+6. Add the new publish-success assertion to smoke
+7. Verify on dev box: `du -sh /var/lib/docker/volumes/broad-announce_natsdata/_data` stays under 1.5 GB during sustained load
+
+---
+
+## Risk assessment
+
+| Change | Risk | Mitigation |
+|---|---|---|
+| Lower `max_age` for ALERTS to 1h | A slow consumer could miss messages if it falls behind by >1h | routerd processes in real-time, the 1h is generous. If it falls behind, routerd has its own queue/alerting. |
+| Add `max_bytes=1G` with `DiscardOld` | Could drop unconsumed messages if routerd falls way behind | routerd processes in <1s typically. If it's behind by 1GB of messages, we have bigger problems. |
+| Bump server `max_storage` to 10G | Could fill disk if traffic spikes | 10G is well under the 6.5G free — wait, that's a problem. We need to be careful. |
+| Restart NATS | Service outage for ~5s | Acceptable in dev; in prod this is a rolling restart with multi-broker |
+
+**Wait — the 6.5G free on disk is a problem.** The host has 6.5G free. Setting `max_storage=10G` would allow NATS to try to use 10G, but the disk is nearly full. This would either:
+- (a) Succeed because NATS will only use what it needs
+- (b) Fail with disk-full errors when writes exceed available space
+
+**Better approach:** Set `max_storage=5G` (just under the 5.46 GiB default, but explicit), and rely on stream-level `max_age=1h` and `max_bytes=1G` to keep actual usage well under the cap. This way the 1G ALERTS + 100MB DELIVERIES + 10MB DLQ = 1.1G actual usage, with 4G headroom for spikes.
+
+**Final fix values:**
+
+```yaml
+# docker-compose.yml
+nats:
+  command: ["-js", "-sd", "/data", "-m", "8222", "-ms=5G"]  # explicit 5G cap
+```
+
+```go
+// internal/broker/broker.go
+streams := []struct {
+    name     string
+    subjects []string
+    age      time.Duration
+    maxBytes int64
+}{
+    {"ALERTS", []string{"alerts.>"}, 1 * time.Hour, 1 << 30},   // 1h, 1G
+    {"DELIVERIES", []string{"deliveries.>"}, 1 * time.Hour, 100 << 20}, // 1h, 100M
+    {"DLQ", []string{"dlq.>"}, 1 * time.Hour, 10 << 20},       // 1h, 10M
+}
+```
+
+This caps total JetStream usage at ~1.1G, well under the 5G server cap, with 4G headroom.
+
+---
+
+## What to ask the user
+
+1. Approve the short-term fix (steps 1-5 above) to unblock M11?
+2. Approve the medium-term fix (publish metric + smoke assertion) to prevent recurrence?
+3. Schedule M12 W2 (multi-broker NATS) as the long-term fix?