Kezdőlap Felfedezés Súgó
Regisztráció Bejelentkezés
lrosales
/
broad-announce
1
0
Másolás 0
Fájlok Problémák 0 Beolvasztási kérések 0 Wiki
Fa: f161122bbf
Branch-ok Tag-ek
broad-announce
/
M11_NATS_INVESTIGATION.md

M11_NATS_INVESTIGATION.md 12 KB
Előzmények Nyers

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)

"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:

{
  "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)

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

// 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

_, 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

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:

// 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:

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:

- 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:

# docker-compose.yml
nats:
  command: ["-js", "-sd", "/data", "-m", "8222", "-ms=5G"]  # explicit 5G cap

// 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?