diff --git a/sw-block/design/v3-observability.md b/sw-block/design/v3-observability.md new file mode 100644 index 000000000..2e9faab4d --- /dev/null +++ b/sw-block/design/v3-observability.md @@ -0,0 +1,518 @@ +# V3 Observability Design + +Date: 2026-04-13 +Status: design draft +Purpose: define logging, metrics, tracing, debugging, and alerting for sw-block + +## 1. Current State + +### 1.1 What exists + +| Component | Status | Location | +|-----------|--------|----------| +| Prometheus metrics | Partial | `blockvol/metrics.go`, volume server `/metrics` | +| Grafana dashboard | V1 draft | `monitoring/dashboards/block-overview.json` | +| glog logging | Active but unstructured | Throughout all Go code | +| pprof | Active | `net/http/pprof` on volume server debug port | +| Audit logging | None | — | +| Distributed tracing | None | — | +| Debug zip | None | — | +| Structured logging | None (plain text via glog) | — | + +### 1.2 Problems with current logging + +SeaweedFS (and sw-block) uses `glog` — Google's plain-text logger: + +``` +I0409 15:41:18.946772 volume_server_block.go:886 core [...]: event=replication.RebuildStarted mode=needs_rebuild ... +``` + +Issues: +- **Not structured**: key=value pairs embedded in free text, not machine-parseable +- **No channels**: replication, iSCSI, WAL, admin ops all go to the same log +- **No correlation**: no request ID or trace ID across nodes +- **No audit trail**: admin operations (create, delete, promote) are mixed with debug logs +- **Grep is the only query tool**: we spent hours in this session grep-ing for "sender not found" + +## 2. Structured Logging + +### 2.1 Channel model (from CockroachDB) + +Route logs by audience, not by severity: + +| Channel | Audience | What goes here | +|---------|----------|---------------| +| `OPS` | Operator | Volume lifecycle (create, delete, expand), config changes, server start/stop | +| `STORAGE` | Developer | WAL append, flush, SyncCache, extent I/O, crash recovery | +| `REPL` | Developer + Operator | Ship, barrier, catch-up, rebuild, probe, session start/complete/fail | +| `ISCSI` | Developer | Session login/logout, SCSI commands, connection events | +| `NVME` | Developer | NVMe-oF session, queue management, command processing | +| `AUDIT` | Security / Compliance | Admin mutations: who did what, when, result | +| `HEALTH` | Monitoring | Health score changes, scrub results, degraded/recovery events | + +### 2.2 Log format + +Use structured JSON for machine processing: + +```json +{ + "ts": "2026-04-09T15:41:18.946Z", + "level": "info", + "channel": "REPL", + "node": "10.0.0.3:18480", + "volume": "mydb", + "epoch": 2, + "msg": "rebuild session completed", + "replica": "10.0.0.1:18480", + "achieved_lsn": 284756, + "duration_ms": 2100, + "blocks_transferred": 262144 +} +``` + +Compare to current: +``` +I0409 15:41:18 block_rebuild_remote.go:145 remote rebuild: session 2 completed (achieved=284756) +``` + +The structured version is greppable, queryable (jq), and indexable (Loki/ELK). + +### 2.3 Implementation + +Use `zap` (Uber's structured logger) as the logging backend. SeaweedFS +already uses glog everywhere, so the migration is incremental: + +**Phase 1**: New block code uses zap directly +**Phase 2**: Wrapper that sends to both glog (for backward compat) and zap +**Phase 3**: Migrate existing glog calls in block code to zap channels + +```go +// Block logger initialization +var ( + opsLog = zap.L().Named("OPS") + storageLog = zap.L().Named("STORAGE") + replLog = zap.L().Named("REPL") + iscsiLog = zap.L().Named("ISCSI") + auditLog = zap.L().Named("AUDIT") + healthLog = zap.L().Named("HEALTH") +) + +// Usage: +replLog.Info("rebuild session completed", + zap.String("volume", "mydb"), + zap.String("replica", "10.0.0.1:18480"), + zap.Uint64("achieved_lsn", 284756), + zap.Duration("duration", 2100*time.Millisecond), + zap.Int("blocks", 262144), +) +``` + +### 2.4 Log levels + +| Level | When to use | Example | +|-------|-------------|---------| +| `DEBUG` | Internal detail, normally off | WAL entry encode/decode | +| `INFO` | Normal operation events | Volume created, rebuild completed | +| `WARN` | Abnormal but recoverable | Barrier failed, shipper degraded | +| `ERROR` | Requires attention | Crash recovery found CRC mismatch | +| `FATAL` | Cannot continue | Extent file corruption, unrecoverable | + +Rule from etcd: **choose level based on whether human intervention is needed.** INFO = no action. WARN = monitor. ERROR = investigate. FATAL = fix now. + +## 3. Distributed Tracing + +### 3.1 Why it matters + +This session's debugging workflow: scenario fails → grep primary log → grep replica log → manually correlate timestamps → find root cause. This took hours for each bug. + +With tracing, the same debug session becomes: + +``` +Open Jaeger UI → find trace for the rebuild session → see spans: + +Primary: handleReplicaProbeResult [0ms - 5ms] + └── applyCoreEvent(NeedsRebuildObserved) [1ms - 2ms] + └── installSession(SessionRebuild) [2ms - 3ms] + └── startTask → runRebuild [3ms - 10ms] + └── PlanRebuild [3ms - 4ms] + └── RebuildStarted → StartRebuildCommand [4ms - 5ms] + └── ExecutePendingRebuild [5ms - 6ms] + └── RemoteRebuildIO.TransferFullBase [6ms - 2100ms] + └── dial replica ctrl [6ms - 11ms] + └── send session control [11ms - 12ms] + └── read ack: accepted [12ms - 15ms] +Replica: handleSessionControl [12ms - 13ms] + └── StartRebuildSession [13ms - 14ms] + └── runBaseLaneClient [14ms - 2095ms] + └── dial rebuild server [14ms - 19ms] + └── receive 262144 blocks [19ms - 2090ms] + └── MarkBaseComplete [2090ms - 2091ms] + └── TryComplete → send ack [2091ms - 2095ms] +Primary: read ack: completed [2095ms - 2096ms] + └── OnRebuildCompleted [2096ms - 2100ms] +``` + +One view, both nodes, sub-millisecond timing for every step. + +### 3.2 Implementation + +Use OpenTelemetry with trace context propagation in the replication +wire protocol: + +```go +// Add trace context to WAL shipping frame header +type ShipFrame struct { + MsgType byte + TraceID [16]byte // OpenTelemetry trace ID (128-bit) + SpanID [8]byte // OpenTelemetry span ID (64-bit) + Payload []byte +} + +// On primary: start span, inject into frame +ctx, span := tracer.Start(ctx, "Ship") +frame.TraceID = span.SpanContext().TraceID() +frame.SpanID = span.SpanContext().SpanID() + +// On replica: extract from frame, continue trace +ctx = otel.ContextWithRemoteSpanContext(ctx, ...) +_, span := tracer.Start(ctx, "ReplicaApply") +``` + +### 3.3 What to trace + +| Path | Spans | +|------|-------| +| **Write** | SCSI Write → WriteLBA → WAL append → Ship → replica apply → ack | +| **SyncCache** | SCSI SyncCache → extent fsync → WAL fsync → barrier → replica fsync → ack | +| **Rebuild** | Probe → NeedsRebuild → StartRebuild → dial → session control → base transfer → completion | +| **Failover** | Master detects disconnect → lease expiry → promote → assignment delivery → new primary serves | + +### 3.4 Export + +Support multiple backends: +- **Jaeger**: for development/debugging +- **OTLP collector**: for production (routes to Grafana Tempo, Honeycomb, etc.) +- **Off**: no overhead when not needed (default) + +```bash +weed server -block \ + -otel.endpoint=jaeger:4317 \ + -otel.sample_rate=0.01 # 1% sampling in production +``` + +## 4. Metrics + +### 4.1 Must-have metrics + +#### Volume I/O + +```prometheus +# IOPS (counter — derive rate in Grafana) +sw_block_read_ops_total{volume="mydb"} +sw_block_write_ops_total{volume="mydb"} +sw_block_trim_ops_total{volume="mydb"} + +# Throughput +sw_block_read_bytes_total{volume="mydb"} +sw_block_write_bytes_total{volume="mydb"} + +# Latency (histogram — get p50/p99/p999 in Grafana) +sw_block_read_latency_seconds{volume="mydb"} +sw_block_write_latency_seconds{volume="mydb"} +# Buckets: 50us, 100us, 250us, 500us, 1ms, 2.5ms, 5ms, 10ms, 25ms, 50ms, 100ms + +# Queue depth +sw_block_pending_ops{volume="mydb",op="write"} +``` + +#### WAL + +```prometheus +sw_block_wal_entries_total{volume="mydb"} +sw_block_wal_bytes_written_total{volume="mydb"} +sw_block_wal_fsync_latency_seconds{volume="mydb"} +sw_block_wal_recycle_total{volume="mydb"} +sw_block_wal_head_lsn{volume="mydb"} +sw_block_wal_tail_lsn{volume="mydb"} +``` + +#### Replication + +```prometheus +sw_block_ship_latency_seconds{volume="mydb",replica="10.0.0.1"} +sw_block_ship_bytes_total{volume="mydb",replica="10.0.0.1"} +sw_block_replica_lag_lsn{volume="mydb",replica="10.0.0.1"} +sw_block_barrier_latency_seconds{volume="mydb"} +sw_block_barrier_success_total{volume="mydb"} +sw_block_barrier_failure_total{volume="mydb"} +``` + +#### Health / State + +```prometheus +sw_block_volume_mode{volume="mydb"} 1 +# 0=offline, 1=healthy, 2=degraded, 3=rebuilding, 4=needs_rebuild +sw_block_health_score{volume="mydb"} 1.0 +sw_block_replica_state{volume="mydb",replica="10.0.0.1"} 3 +# 0=disconnected, 1=connecting, 2=catching_up, 3=in_sync, 4=degraded, 5=needs_rebuild +``` + +#### Events + +```prometheus +sw_block_failover_total{volume="mydb"} +sw_block_rebuild_total{volume="mydb"} +sw_block_rebuild_duration_seconds{volume="mydb"} +sw_block_scrub_errors_total{volume="mydb"} +``` + +#### Capacity + +```prometheus +sw_block_volume_size_bytes{volume="mydb"} +sw_block_volume_used_bytes{volume="mydb"} +sw_block_snapshot_count{volume="mydb"} +sw_block_cluster_capacity_bytes +sw_block_cluster_used_bytes +``` + +#### iSCSI / NVMe + +```prometheus +sw_block_iscsi_sessions_active{portal="10.0.0.1:3260"} +sw_block_iscsi_login_total{portal="10.0.0.1:3260"} +sw_block_iscsi_command_total{portal="10.0.0.1:3260",opcode="write10"} +sw_block_nvme_connections_active{subsystem="mydb"} +``` + +### 4.2 What already exists vs what's needed + +| Metric category | Exists? | Where | +|-----------------|---------|-------| +| WAL entries, pressure | Yes | `blockvol/metrics.go` | +| Barrier latency | Yes | `wal_shipper.go` | +| Health score | Yes | `health_score.go` | +| Scrub errors | Yes | `scrub.go` | +| Role/epoch | Yes | heartbeat | +| **I/O IOPS/latency histogram** | **No** | Need to add in WriteLBA/ReadLBA | +| **Rebuild duration** | **No** | Need to add in recovery manager | +| **Replica lag LSN** | **Partial** | In heartbeat but not Prometheus | +| **iSCSI session count** | **No** | Need to add in iSCSI target | + +## 5. Debugging Tools + +### 5.1 Debug zip + +```bash +weed shell +> block.debug.zip -output=/tmp/debug.zip + +Collecting... + ✓ Volume status (3 volumes) + ✓ Server health (2 servers) + ✓ WAL status (head/tail/recycled per volume) + ✓ Replica state (shipper state, lag, last contact) + ✓ Recent events (last 100 failover/rebuild/degraded) + ✓ Goroutine dump (242 goroutines) + ✓ Heap profile (resident: 128MB, alloc: 89MB) + ✓ Logs (last 1h, all channels) + ✓ Metrics snapshot (last 5min counters) + +Written: /tmp/debug.zip (23MB) +``` + +Contents: +``` +debug-20260413-143000/ + cluster.json ← block.health output as JSON + volumes/ + mydb.json ← block.status output per volume + logs/ + node-10.0.0.1/ + ops.log ← last 1h, OPS channel + repl.log ← last 1h, REPL channel + storage.log ← last 1h, STORAGE channel + node-10.0.0.3/ + ops.log + repl.log + storage.log + profiles/ + goroutines.txt ← all goroutine stacks + heap.pb.gz ← Go heap profile (pprof format) + cpu-10s.pb.gz ← 10-second CPU profile + metrics/ + snapshot.json ← all Prometheus metrics at collection time + config/ + master.json ← master config + volume-server.json ← volume server config per node +``` + +### 5.2 Log merge + +```bash +# Merge logs from all nodes, sorted by timestamp +weed shell +> block.debug.merge-logs -dir=/tmp/debug-20260413/logs + +2026-04-09T15:41:18.946Z [node1] [REPL] rebuild session started replica=10.0.0.1 +2026-04-09T15:41:18.947Z [node2] [REPL] handleSessionControl start_rebuild session=2 +2026-04-09T15:41:18.948Z [node2] [STORAGE] base lane client starting addr=10.0.0.3:5260 +2026-04-09T15:41:20.950Z [node2] [STORAGE] base lane complete: 262144 blocks +2026-04-09T15:41:20.951Z [node1] [REPL] rebuild session completed achieved=284756 +``` + +One timeline, both nodes, channel-tagged. The exact view we needed during this session's debugging but had to build manually with grep. + +### 5.3 Live tail + +```bash +# Real-time log streaming filtered by channel and volume +weed shell +> block.debug.tail -channel=REPL -volume=mydb + +2026-04-13T14:30:01.123Z [INFO] ship entry lsn=284757 → 10.0.0.1 +2026-04-13T14:30:01.124Z [INFO] ship entry lsn=284758 → 10.0.0.1 +2026-04-13T14:30:02.000Z [WARN] barrier timeout target=284758 replica=10.0.0.1 +``` + +## 6. Audit Logging + +### 6.1 What to audit + +Every admin mutation that changes cluster state: + +| Operation | Logged fields | +|-----------|--------------| +| Volume create | actor, name, size, RF, durability mode | +| Volume delete | actor, name, size, snapshot count | +| Volume expand | actor, name, old_size, new_size | +| Manual promote | actor, volume, old_primary, new_primary, epoch | +| Snapshot create | actor, volume, snapshot_id | +| Snapshot delete | actor, volume, snapshot_id | +| Config change | actor, key, old_value, new_value | +| Server add/remove | actor, server_address | +| Rebuild trigger | actor (master/auto), volume, source, target | +| CHAP credential change | actor, portal, operation | + +### 6.2 Audit log format + +```json +{ + "ts": "2026-04-13T14:30:00.000Z", + "channel": "AUDIT", + "actor": "admin@10.0.0.100", + "operation": "volume.delete", + "target": "old-vol", + "details": { + "size_bytes": 53687091200, + "replica_factor": 2, + "snapshots_deleted": 3, + "epoch": 5 + }, + "result": "success" +} +``` + +### 6.3 Actor identification + +| Source | Actor format | +|--------|-------------| +| `weed shell` | `shell@{client_ip}` | +| REST API | `api@{client_ip}` or authenticated user | +| CSI driver | `csi@{node_name}` | +| Master auto-action | `master@{master_addr}` (e.g., auto-failover) | +| Primary auto-action | `primary@{vs_addr}` (e.g., auto-rebuild) | + +## 7. Alert Design + +### 7.1 Three tiers + +| Tier | Condition | Action | Example | +|------|-----------|--------|---------| +| **PAGE** | Data at risk | Wake someone | Volume offline (all replicas down), data corruption (CRC mismatch), split-brain detected | +| **TICKET** | Service degraded | Next business day | Volume degraded (one replica down >5min), rebuild stalled >10min, scrub errors, disk >85% | +| **LOG** | Informational | No action | Rebuild started/completed, failover event, snapshot created, config change | + +### 7.2 Anti-patterns to avoid + +| Anti-pattern | How to avoid | +|-------------|--------------| +| Same severity for everything | Use the three tiers above | +| Static thresholds on dynamic workloads | Alert on P99 change, not absolute value | +| Cascading alerts (1 OSD down → 10 alerts) | Group by volume/server in Alertmanager | +| No context in alerts | Include volume name, server, epoch, current state | +| Stale thresholds | Monthly alert audit: did this alert lead to action? | + +### 7.3 Recommended Prometheus rules + +```yaml +groups: + - name: sw-block-page + rules: + - alert: BlockVolumeOffline + expr: sw_block_volume_mode == 0 + for: 1m + labels: { severity: page } + annotations: + summary: "Volume {{ $labels.volume }} is OFFLINE" + action: "Check server connectivity. Run 'block.status {{ $labels.volume }}'" + + - alert: BlockDataCorruption + expr: sw_block_scrub_errors_total > 0 + labels: { severity: page } + annotations: + summary: "Volume {{ $labels.volume }} has {{ $value }} scrub errors" + action: "Run 'block.status {{ $labels.volume }}'. Check extent integrity." + + - name: sw-block-ticket + rules: + - alert: BlockVolumeDegraded + expr: sw_block_volume_mode == 2 + for: 5m + labels: { severity: ticket } + annotations: + summary: "Volume {{ $labels.volume }} degraded for >5min" + action: "Check replica state. Run 'block.status {{ $labels.volume }}'" + + - alert: BlockRebuildStalled + expr: sw_block_rebuild_duration_seconds > 600 + labels: { severity: ticket } + annotations: + summary: "Rebuild for {{ $labels.volume }} stalled ({{ $value | humanizeDuration }})" + + - alert: BlockCapacityHigh + expr: sw_block_cluster_used_bytes / sw_block_cluster_capacity_bytes > 0.85 + labels: { severity: ticket } + annotations: + summary: "Block cluster capacity at {{ $value | humanizePercentage }}" + + - alert: BlockWriteLatencyHigh + expr: histogram_quantile(0.99, rate(sw_block_write_latency_seconds_bucket[5m])) > 0.01 + for: 10m + labels: { severity: ticket } + annotations: + summary: "Volume {{ $labels.volume }} P99 write latency >10ms" + + - name: sw-block-log + rules: + - alert: BlockRebuildCompleted + expr: increase(sw_block_rebuild_total[5m]) > 0 + labels: { severity: log } + annotations: + summary: "Rebuild completed for {{ $labels.volume }}" +``` + +## 8. Implementation Priority + +| Priority | Feature | Effort | Impact | +|----------|---------|--------|--------| +| **P0** | I/O latency histogram in WriteLBA/ReadLBA | 50 lines | Perf visibility | +| **P0** | Rebuild duration metric | 20 lines | Recovery visibility | +| **P1** | Audit logging channel | 100 lines | Compliance, admin visibility | +| **P1** | Debug zip command | 200 lines | Debugging speed | +| **P1** | Alert rules template | 1 YAML file | Production monitoring | +| **P1** | Grafana dashboard update | Update JSON | Visual monitoring | +| **P2** | Structured logging (zap channels) | 300 lines migration | Log queryability | +| **P2** | Log merge tool | 80 lines | Multi-node debugging | +| **P3** | OpenTelemetry tracing | 500 lines | End-to-end latency analysis | +| **P3** | Trace context in replication protocol | Wire format change | Cross-node trace correlation |