diff --git a/docker-compose.mill.yml b/docker-compose.mill.yml --- a/docker-compose.mill.yml +++ b/docker-compose.mill.yml @@ -16,6 +16,7 @@ environment: &mill-executor-env SPINDLE_ROLE: executor SPINDLE_SERVER_LISTEN_ADDR: 0.0.0.0:6555 + SPINDLE_SERVER_METRICS_LISTEN_ADDR: 0.0.0.0:9091 SPINDLE_SERVER_DB_PATH: /var/lib/spindle/spindle.db SPINDLE_SERVER_PLC_URL: https://plc.tngl.boltless.dev SPINDLE_SERVER_JETSTREAM_ENDPOINT: wss://jetstream.tngl.boltless.dev/subscribe @@ -39,6 +40,12 @@ SPINDLE_MICROVM_PIPELINES_DEBUG_SSH_HOST_KEY_PATH: /var/lib/spindle/debug_ssh_host_key # dials the mill container directly using ws SPINDLE_MILL_URL: ws://spindle:6555/mill + SPINDLE_TRACING_ENDPOINT: "${SPINDLE_TRACING_ENDPOINT:-}" + SPINDLE_TRACING_INSECURE: "${SPINDLE_TRACING_INSECURE:-false}" + SPINDLE_LOG_FORMAT: json + SPINDLE_LOGGING_ENDPOINT: "${SPINDLE_LOGGING_ENDPOINT:-}" + SPINDLE_LOGGING_INSECURE: "${SPINDLE_LOGGING_INSECURE:-false}" + SPINDLE_LOGGING_SERVICE_NAME: spindle devices: - /dev/vsock:/dev/vsock - /dev/kvm:/dev/kvm @@ -86,6 +93,12 @@ - spindle-artifacts:/var/lib/spindle/artifacts ports: !override - "127.0.0.1:2224:2224" + + prometheus: + command: + - --config.file=/etc/prometheus/prometheus.mill.yml + - --storage.tsdb.path=/prometheus + - --enable-feature=exemplar-storage mill-tokens: profiles: ["linux"] diff --git a/docker-compose.yml b/docker-compose.yml --- a/docker-compose.yml +++ b/docker-compose.yml @@ -172,6 +172,7 @@ environment: SPINDLE_SERVER_HOSTNAME: spindle.tngl.boltless.dev SPINDLE_SERVER_LISTEN_ADDR: 0.0.0.0:6555 + SPINDLE_SERVER_METRICS_LISTEN_ADDR: 0.0.0.0:9091 SPINDLE_SERVER_DB_PATH: /var/lib/spindle/spindle.db SPINDLE_SERVER_PLC_URL: https://plc.tngl.boltless.dev SPINDLE_SERVER_JETSTREAM_ENDPOINT: wss://jetstream.tngl.boltless.dev/subscribe @@ -189,6 +190,12 @@ SPINDLE_MICROVM_PIPELINES_DEBUG_SSH_ENABLED: true SPINDLE_MICROVM_PIPELINES_DEBUG_SSH_LISTEN_ADDR: 0.0.0.0:2223 SPINDLE_MICROVM_PIPELINES_DEBUG_SSH_GRACE_PERIOD: 10m + SPINDLE_TRACING_ENDPOINT: "${SPINDLE_TRACING_ENDPOINT:-}" + SPINDLE_TRACING_INSECURE: "${SPINDLE_TRACING_INSECURE:-false}" + SPINDLE_LOG_FORMAT: json + SPINDLE_LOGGING_ENDPOINT: "${SPINDLE_LOGGING_ENDPOINT:-}" + SPINDLE_LOGGING_INSECURE: "${SPINDLE_LOGGING_INSECURE:-false}" + SPINDLE_LOGGING_SERVICE_NAME: spindle # these two are required for cgroups, uncomment if testing # privileged: true # cgroup: host @@ -434,6 +441,63 @@ - zoekt.tngl.boltless.dev - pdsls.tngl.boltless.dev + prometheus: + image: prom/prometheus:v2.54.1 + profiles: ["observability"] + restart: unless-stopped + command: + - '--config.file=/etc/prometheus/prometheus.yml' + - '--storage.tsdb.path=/prometheus' + - '--enable-feature=exemplar-storage' + volumes: + - prometheus-data:/prometheus + - ./localinfra/observability/prometheus:/etc/prometheus:ro + ports: + - "127.0.0.1:9090:9090" + networks: [tngl] + + tempo: + image: grafana/tempo:2.5.0 + profiles: ["observability"] + restart: unless-stopped + command: ["-config.file=/etc/tempo/tempo.yml"] + volumes: + - ./localinfra/observability/tempo/tempo.yml:/etc/tempo/tempo.yml:ro + - tempo-data:/var/tempo + ports: + - "127.0.0.1:3200:3200" + networks: [tngl] + + loki: + image: grafana/loki:3.0.0 + profiles: ["observability"] + restart: unless-stopped + command: ["-config.file=/etc/loki/loki.yml"] + volumes: + - ./localinfra/observability/loki/loki.yml:/etc/loki/loki.yml:ro + - loki-data:/loki + ports: + - "127.0.0.1:3100:3100" + healthcheck: + test: ["CMD", "wget", "-qO-", "http://localhost:3100/ready"] + interval: 10s + timeout: 5s + retries: 3 + networks: [tngl] + + + + grafana: + image: grafana/grafana:11.2.0 + profiles: ["observability"] + restart: unless-stopped + volumes: + - grafana-data:/var/lib/grafana + - ./localinfra/observability/grafana/provisioning:/etc/grafana/provisioning:ro + ports: + - "127.0.0.1:3001:3000" + networks: [tngl] + volumes: caddy-data: postgres-data: @@ -451,6 +515,10 @@ go-mod-cache: appview-data: deliberi-data: + prometheus-data: + grafana-data: + tempo-data: + loki-data: networks: tngl: diff --git a/go.mod b/go.mod --- a/go.mod +++ b/go.mod @@ -38,6 +38,7 @@ github.com/djherbis/nio/v3 v3.0.1 github.com/docker/docker v28.2.2+incompatible github.com/dustin/go-humanize v1.0.1 + github.com/felixge/httpsnoop v1.0.4 github.com/gliderlabs/ssh v0.3.8 github.com/go-chi/chi/v5 v5.2.0 github.com/go-enry/go-enry/v2 v2.9.6 @@ -62,6 +63,7 @@ github.com/openbao/openbao/api/v2 v2.3.0 github.com/posthog/posthog-go v1.5.5 github.com/prometheus/client_golang v1.23.2 + github.com/prometheus/client_model v0.6.2 github.com/prometheus/procfs v0.19.2 github.com/redis/go-redis/v9 v9.7.3 github.com/resend/resend-go/v3 v3.5.0 @@ -78,6 +80,15 @@ github.com/yuin/goldmark-highlighting/v2 v2.0.0-20230729083705-37449abec8cc gitlab.com/staticnoise/goldmark-callout v0.0.0-20240609120641-6366b799e4ab go.abhg.dev/goldmark/mermaid v0.6.0 + go.opentelemetry.io/contrib/bridges/otelslog v0.18.0 + go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.65.0 + go.opentelemetry.io/otel v1.43.0 + go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp v0.19.0 + go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.43.0 + go.opentelemetry.io/otel/log v0.19.0 + go.opentelemetry.io/otel/sdk v1.43.0 + go.opentelemetry.io/otel/sdk/log v0.19.0 + go.opentelemetry.io/otel/trace v1.43.0 golang.org/x/crypto v0.51.0 golang.org/x/image v0.31.0 golang.org/x/net v0.55.0 @@ -139,6 +150,7 @@ github.com/bmatcuk/doublestar v1.3.4 // indirect github.com/casbin/govaluate v1.3.0 // indirect github.com/cenkalti/backoff/v4 v4.3.0 // indirect + github.com/cenkalti/backoff/v5 v5.0.3 // indirect github.com/cespare/xxhash/v2 v2.3.0 // indirect github.com/charmbracelet/colorprofile v0.4.1 // indirect github.com/charmbracelet/keygen v0.5.3 // indirect @@ -170,7 +182,6 @@ github.com/earthboundkid/versioninfo/v2 v2.24.1 // indirect github.com/emirpasic/gods v1.18.1 // indirect github.com/erikgeiser/coninput v0.0.0-20211004153227-1c3628e74d0f // indirect - github.com/felixge/httpsnoop v1.0.4 // indirect github.com/go-enry/go-oniguruma v1.2.1 // indirect github.com/go-git/gcfg v1.5.1-0.20230307220236-3a3c6141e376 // indirect github.com/go-git/go-billy/v5 v5.9.0 // indirect @@ -196,6 +207,7 @@ github.com/gorilla/securecookie v1.1.2 // indirect github.com/grafana/regexp v0.0.0-20240607082908-2cb410fa05da // indirect github.com/grpc-ecosystem/go-grpc-middleware v1.4.0 // indirect + github.com/grpc-ecosystem/grpc-gateway/v2 v2.28.0 // indirect github.com/hashicorp/errwrap v1.1.0 // indirect github.com/hashicorp/go-cleanhttp v0.5.2 // indirect github.com/hashicorp/go-multierror v1.1.1 // indirect @@ -271,7 +283,6 @@ github.com/pkg/errors v0.9.1 // indirect github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 // indirect github.com/polydawn/refmt v0.89.1-0.20221221234430-40501e09de1f // indirect - github.com/prometheus/client_model v0.6.2 // indirect github.com/prometheus/common v0.67.5 // indirect github.com/puzpuzpuz/xsync/v4 v4.2.0 // indirect github.com/rivo/uniseg v0.4.7 // indirect @@ -298,10 +309,9 @@ gitlab.com/yawning/tuplehash v0.0.0-20230713102510-df83abbf9a02 // indirect go.etcd.io/bbolt v1.4.0 // indirect go.opentelemetry.io/auto/sdk v1.2.1 // indirect - go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.65.0 // indirect - go.opentelemetry.io/otel v1.43.0 // indirect + go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.43.0 // indirect go.opentelemetry.io/otel/metric v1.43.0 // indirect - go.opentelemetry.io/otel/trace v1.43.0 // indirect + go.opentelemetry.io/proto/otlp v1.10.0 // indirect go.uber.org/atomic v1.11.0 // indirect go.uber.org/multierr v1.11.0 // indirect go.uber.org/zap v1.27.1 // indirect diff --git a/go.sum b/go.sum --- a/go.sum +++ b/go.sum @@ -862,20 +862,28 @@ go.etcd.io/bbolt v1.4.0/go.mod h1:AsD+OCi/qPN1giOX1aiLAha3o1U8rAz65bvN4j0sRuk= go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= +go.opentelemetry.io/contrib/bridges/otelslog v0.18.0 h1:hhPGP3zvvy1xWT9RTy970wlniSxFttBIsAK1gvMguJM= +go.opentelemetry.io/contrib/bridges/otelslog v0.18.0/go.mod h1:twJF7inoMza6kxMcF8JOdL3mPmtOZu7GEr34CUNE6Dg= go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.65.0 h1:7iP2uCb7sGddAr30RRS6xjKy7AZ2JtTOPA3oolgVSw8= go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.65.0/go.mod h1:c7hN3ddxs/z6q9xwvfLPk+UHlWRQyaeR1LdgfL/66l0= go.opentelemetry.io/otel v1.43.0 h1:mYIM03dnh5zfN7HautFE4ieIig9amkNANT+xcVxAj9I= go.opentelemetry.io/otel v1.43.0/go.mod h1:JuG+u74mvjvcm8vj8pI5XiHy1zDeoCS2LB1spIq7Ay0= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp v0.19.0 h1:HIBTQ3VO5aupLKjC90JgMqpezVXwFuq6Ryjn0/izoag= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp v0.19.0/go.mod h1:ji9vId85hMxqfvICA0Jt8JqEdrXaAkcpkI9HPXya0ro= go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.43.0 h1:88Y4s2C8oTui1LGM6bTWkw0ICGcOLCAI5l6zsD1j20k= go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.43.0/go.mod h1:Vl1/iaggsuRlrHf/hfPJPvVag77kKyvrLeD10kpMl+A= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.43.0 h1:3iZJKlCZufyRzPzlQhUIWVmfltrXuGyfjREgGP3UUjc= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.43.0/go.mod h1:/G+nUPfhq2e+qiXMGxMwumDrP5jtzU+mWN7/sjT2rak= +go.opentelemetry.io/otel/log v0.19.0 h1:KUZs/GOsw79TBBMfDWsXS+KZ4g2Ckzksd1ymzsIEbo4= +go.opentelemetry.io/otel/log v0.19.0/go.mod h1:5DQYeGmxVIr4n0/BcJvF4upsraHjg6vudJJpnkL6Ipk= go.opentelemetry.io/otel/metric v1.43.0 h1:d7638QeInOnuwOONPp4JAOGfbCEpYb+K6DVWvdxGzgM= go.opentelemetry.io/otel/metric v1.43.0/go.mod h1:RDnPtIxvqlgO8GRW18W6Z/4P462ldprJtfxHxyKd2PY= go.opentelemetry.io/otel/sdk v1.43.0 h1:pi5mE86i5rTeLXqoF/hhiBtUNcrAGHLKQdhg4h4V9Dg= go.opentelemetry.io/otel/sdk v1.43.0/go.mod h1:P+IkVU3iWukmiit/Yf9AWvpyRDlUeBaRg6Y+C58QHzg= -go.opentelemetry.io/otel/sdk/metric v1.40.0 h1:mtmdVqgQkeRxHgRv4qhyJduP3fYJRMX4AtAlbuWdCYw= -go.opentelemetry.io/otel/sdk/metric v1.40.0/go.mod h1:4Z2bGMf0KSK3uRjlczMOeMhKU2rhUqdWNoKcYrtcBPg= +go.opentelemetry.io/otel/sdk/log v0.19.0 h1:scYVLqT22D2gqXItnWiocLUKGH9yvkkeql5dBDiXyko= +go.opentelemetry.io/otel/sdk/log v0.19.0/go.mod h1:vFBowwXGLlW9AvpuF7bMgnNI95LiW10szrOdvzBHlAg= +go.opentelemetry.io/otel/sdk/metric v1.43.0 h1:S88dyqXjJkuBNLeMcVPRFXpRw2fuwdvfCGLEo89fDkw= +go.opentelemetry.io/otel/sdk/metric v1.43.0/go.mod h1:C/RJtwSEJ5hzTiUz5pXF1kILHStzb9zFlIEe85bhj6A= go.opentelemetry.io/otel/trace v1.43.0 h1:BkNrHpup+4k4w+ZZ86CZoHHEkohws8AY+WTX09nk+3A= go.opentelemetry.io/otel/trace v1.43.0/go.mod h1:/QJhyVBUUswCphDVxq+8mld+AvhXZLhe+8WVFxiFff0= go.opentelemetry.io/proto/otlp v1.10.0 h1:IQRWgT5srOCYfiWnpqUYz9CVmbO8bFmKcwYxpuCSL2g= diff --git a/localinfra/readme.md b/localinfra/readme.md --- a/localinfra/readme.md +++ b/localinfra/readme.md @@ -53,6 +53,38 @@ 6. AppView will be running on `127.0.0.1:3000` with two test users: `alice.pds.tngl.boltless.dev` and `bob.pds.tngl.boltless.dev`. Both with password `password`. `TANGLED_APPVIEW_HOST` must be a loopback IP with the mapped port (`127.0.0.1:3000`), not `localhost`: atproto's dev OAuth client requires a loopback IP for the redirect URI. If you remap the published appview port, update `TANGLED_APPVIEW_HOST` in `docker-compose.yml` to match. +## Observability + +Prometheus, Grafana, Tempo, and Loki are available through the optional `observability` profile. To run the standalone spindle with metrics, traces, and remote logs: + +```bash +SPINDLE_TRACING_ENDPOINT=tempo:4318 \ +SPINDLE_TRACING_INSECURE=true \ +SPINDLE_LOGGING_ENDPOINT=loki:3100 \ +SPINDLE_LOGGING_INSECURE=true \ +docker compose --profile linux --profile observability up +``` + +The endpoint values above are addresses on the Compose network. Leaving either endpoint empty disables that OTLP exporter; Prometheus metrics and JSON logs on stderr remain enabled. + +The profile exposes: + +- Grafana at , with the `Spindle Overview` dashboard and Prometheus, Tempo, and Loki datasources provisioned +- Prometheus at ; use `/targets` to verify the internal `spindle:9091/metrics` scrape +- Tempo at +- Loki at + +For mill mode, include both Compose files: + +```bash +SPINDLE_TRACING_ENDPOINT=tempo:4318 \ +SPINDLE_TRACING_INSECURE=true \ +SPINDLE_LOGGING_ENDPOINT=loki:3100 \ +SPINDLE_LOGGING_INSECURE=true \ +docker compose -f docker-compose.yml -f docker-compose.mill.yml --profile linux --profile observability up +``` + +The mill Prometheus configuration scrapes the mill host and all three executors. Grafana links metric exemplars to Tempo traces and trace IDs in Loki logs back to Tempo. ## Mill mode diff --git a/localinfra/spindle.Dockerfile b/localinfra/spindle.Dockerfile --- a/localinfra/spindle.Dockerfile +++ b/localinfra/spindle.Dockerfile @@ -18,8 +18,8 @@ COPY . . RUN --mount=type=cache,target=/go/cache \ --mount=type=cache,target=/go/mod \ - go build -tags libsqlite3 -o /out/spindle ./cmd/spindle && \ - go build -tags libsqlite3 -o /out/spindle-microvm-run ./cmd/spindle-microvm-run + go build -mod=mod -tags libsqlite3 -o /out/spindle ./cmd/spindle && \ + go build -mod=mod -tags libsqlite3 -o /out/spindle-microvm-run ./cmd/spindle-microvm-run FROM alpine:3.24 diff --git a/log/log.go b/log/log.go --- a/log/log.go +++ b/log/log.go @@ -2,22 +2,317 @@ import ( "context" + "errors" + "fmt" + "io" "log/slog" "os" "github.com/charmbracelet/log" + "go.opentelemetry.io/contrib/bridges/otelslog" + otellog "go.opentelemetry.io/otel/log" + "go.opentelemetry.io/otel/trace" ) -func NewHandler(name string) slog.Handler { - return log.NewWithOptions(os.Stderr, log.Options{ - ReportTimestamp: true, - Prefix: name, - Level: log.DebugLevel, +type handlerOperation struct { + attrs []slog.Attr + group string +} + +type namedHandler struct { + slog.Handler + name string + format string + writer io.Writer + hasTraceID bool + hasSpanID bool + operations []handlerOperation +} + +func (h *namedHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + hasTraceID := h.hasTraceID + hasSpanID := h.hasSpanID + for _, attr := range attrs { + switch attr.Key { + case "trace_id": + hasTraceID = true + case "span_id": + hasSpanID = true + } + } + operations := append(h.operations[:len(h.operations):len(h.operations)], handlerOperation{ + attrs: append([]slog.Attr(nil), attrs...), }) + return &namedHandler{ + Handler: h.Handler.WithAttrs(attrs), + name: h.name, + format: h.format, + writer: h.writer, + hasTraceID: hasTraceID, + hasSpanID: hasSpanID, + operations: operations, + } +} + +func (h *namedHandler) WithGroup(name string) slog.Handler { + operations := append(h.operations[:len(h.operations):len(h.operations)], handlerOperation{group: name}) + return &namedHandler{ + Handler: h.Handler.WithGroup(name), + name: h.name, + format: h.format, + writer: h.writer, + hasTraceID: h.hasTraceID, + hasSpanID: h.hasSpanID, + operations: operations, + } +} + +func (h *namedHandler) WithName(name string) slog.Handler { + next, err := newHandler(h.writer, name, h.format) + if err != nil { + return h + } + for _, operation := range h.operations { + if operation.group != "" { + next = next.WithGroup(operation.group) + } else { + next = next.WithAttrs(operation.attrs) + } + } + return next +} + +func (h *namedHandler) Handle(ctx context.Context, r slog.Record) error { + spanContext := trace.SpanContextFromContext(ctx) + if spanContext.IsValid() && spanContext.IsSampled() { + hasTraceID := h.hasTraceID + hasSpanID := h.hasSpanID + if !hasTraceID || !hasSpanID { + r.Attrs(func(a slog.Attr) bool { + if a.Key == "trace_id" { + hasTraceID = true + } + if a.Key == "span_id" { + hasSpanID = true + } + return !hasTraceID || !hasSpanID + }) + } + var attrs []slog.Attr + if !hasTraceID { + attrs = append(attrs, slog.String("trace_id", spanContext.TraceID().String())) + } + if !hasSpanID { + attrs = append(attrs, slog.String("span_id", spanContext.SpanID().String())) + } + if len(attrs) > 0 { + r.AddAttrs(attrs...) + } + } + return h.Handler.Handle(ctx, r) +} + +type fanoutHandler struct { + primary slog.Handler + others []slog.Handler +} + +func (h *fanoutHandler) Enabled(ctx context.Context, level slog.Level) bool { + if h.primary.Enabled(ctx, level) { + return true + } + for _, other := range h.others { + if other.Enabled(ctx, level) { + return true + } + } + return false +} + +func (h *fanoutHandler) Handle(ctx context.Context, r slog.Record) error { + var errs []error + if h.primary.Enabled(ctx, r.Level) { + if err := h.primary.Handle(ctx, r); err != nil { + errs = append(errs, err) + } + } + for _, other := range h.others { + if other.Enabled(ctx, r.Level) { + if err := other.Handle(ctx, r); err != nil { + errs = append(errs, err) + } + } + } + if len(errs) > 0 { + return errors.Join(errs...) + } + return nil +} + +func (h *fanoutHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + others := make([]slog.Handler, len(h.others)) + for i, other := range h.others { + others[i] = other.WithAttrs(attrs) + } + return &fanoutHandler{ + primary: h.primary.WithAttrs(attrs), + others: others, + } +} + +func (h *fanoutHandler) WithGroup(name string) slog.Handler { + others := make([]slog.Handler, len(h.others)) + for i, other := range h.others { + others[i] = other.WithGroup(name) + } + return &fanoutHandler{ + primary: h.primary.WithGroup(name), + others: others, + } +} + +func (h *fanoutHandler) WithName(name string) slog.Handler { + newPrimary := h.primary + if nh, ok := h.primary.(interface{ WithName(string) slog.Handler }); ok { + newPrimary = nh.WithName(name) + } + others := make([]slog.Handler, len(h.others)) + for i, other := range h.others { + if nh, ok := other.(interface{ WithName(string) slog.Handler }); ok { + others[i] = nh.WithName(name) + } else { + others[i] = other + } + } + return &fanoutHandler{ + primary: newPrimary, + others: others, + } +} + +func NewFanoutHandler(primary slog.Handler, others ...slog.Handler) slog.Handler { + var validOthers []slog.Handler + for _, other := range others { + if other != nil { + validOthers = append(validOthers, other) + } + } + if len(validOthers) == 0 { + return primary + } + return &fanoutHandler{ + primary: primary, + others: validOthers, + } +} + +type otelHandler struct { + slog.Handler + provider otellog.LoggerProvider + name string + operations []handlerOperation +} + +func (h *otelHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + operations := append(h.operations[:len(h.operations):len(h.operations)], handlerOperation{ + attrs: append([]slog.Attr(nil), attrs...), + }) + return &otelHandler{ + Handler: h.Handler.WithAttrs(attrs), + provider: h.provider, + name: h.name, + operations: operations, + } +} + +func (h *otelHandler) WithGroup(name string) slog.Handler { + operations := append(h.operations[:len(h.operations):len(h.operations)], handlerOperation{group: name}) + return &otelHandler{ + Handler: h.Handler.WithGroup(name), + provider: h.provider, + name: h.name, + operations: operations, + } +} + +func (h *otelHandler) WithName(newName string) slog.Handler { + var opts []otelslog.Option + if h.provider != nil { + opts = append(opts, otelslog.WithLoggerProvider(h.provider)) + } + var handler slog.Handler = otelslog.NewHandler(newName, opts...) + for _, operation := range h.operations { + if operation.group != "" { + handler = handler.WithGroup(operation.group) + } else { + handler = handler.WithAttrs(operation.attrs) + } + } + return &otelHandler{ + Handler: handler, + provider: h.provider, + name: newName, + operations: h.operations, + } +} + +func NewOtelHandler(provider otellog.LoggerProvider, name string) slog.Handler { + var opts []otelslog.Option + if provider != nil { + opts = append(opts, otelslog.WithLoggerProvider(provider)) + } + h := otelslog.NewHandler(name, opts...) + return &otelHandler{ + Handler: h, + provider: provider, + name: name, + } +} + +func newHandler(w io.Writer, name, format string) (slog.Handler, error) { + var handler slog.Handler + switch format { + case "", "text": + handler = log.NewWithOptions(w, log.Options{ + ReportTimestamp: true, + Prefix: name, + Level: log.DebugLevel, + }) + format = "text" + case "json": + handler = slog.NewJSONHandler(w, &slog.HandlerOptions{ + Level: slog.LevelDebug, + }).WithAttrs([]slog.Attr{slog.String("logger", name)}) + default: + return nil, fmt.Errorf("unknown log format %q", format) + } + return &namedHandler{ + Handler: handler, + name: name, + format: format, + writer: w, + }, nil +} + +func NewHandler(name string) slog.Handler { + handler, _ := newHandler(os.Stderr, name, "text") + return handler } func New(name string) *slog.Logger { return slog.New(NewHandler(name)) +} + +func NewWithFormat(name, format string) (*slog.Logger, error) { + return newWithFormatWriter(os.Stderr, name, format) +} + +func newWithFormatWriter(w io.Writer, name, format string) (*slog.Logger, error) { + handler, err := newHandler(w, name, format) + if err != nil { + return nil, err + } + return slog.New(handler), nil } func NewContext(ctx context.Context, name string) context.Context { @@ -49,17 +344,35 @@ // sublogger derives a new logger from an existing one by appending a suffix to its prefix. func SubLogger(base *slog.Logger, suffix string) *slog.Logger { - // try to get the underlying charmbracelet logger - if cl, ok := base.Handler().(*log.Logger); ok { - prefix := cl.GetPrefix() - if prefix != "" { - prefix = prefix + "/" + suffix - } else { - prefix = suffix - } - return slog.New(NewHandler(prefix)) + if base == nil { + return New(suffix) } - - // Fallback: no known handler type - return slog.New(NewHandler(suffix)) + if handler, ok := base.Handler().(*namedHandler); ok { + name := suffix + if handler.name != "" { + name = handler.name + "/" + suffix + } + return slog.New(handler.WithName(name)) + } + if fh, ok := base.Handler().(*fanoutHandler); ok { + var newName string + if ph, ok := fh.primary.(*namedHandler); ok { + if ph.name != "" { + newName = ph.name + "/" + suffix + } else { + newName = suffix + } + } else { + newName = suffix + } + return slog.New(fh.WithName(newName)) + } + if handler, ok := base.Handler().(*log.Logger); ok { + name := suffix + if handler.GetPrefix() != "" { + name = handler.GetPrefix() + "/" + suffix + } + return New(name) + } + return base.With("component", suffix) } diff --git a/log/log_test.go b/log/log_test.go new file mode 100644 --- /dev/null +++ b/log/log_test.go @@ -0,0 +1,383 @@ +package log + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "strings" + "testing" + + "go.opentelemetry.io/otel/trace" +) + +func TestNewWithFormatTextAndDefault(t *testing.T) { + for _, format := range []string{"", "text"} { + var buf bytes.Buffer + logger, err := newWithFormatWriter(&buf, "spindle", format) + if err != nil { + t.Fatal(err) + } + logger.Info("hello") + if got := buf.String(); !strings.Contains(got, "spindle") || !strings.Contains(got, "hello") { + t.Errorf("text log = %q", got) + } + } +} + +func TestNewWithFormatJSON(t *testing.T) { + var buf bytes.Buffer + logger, err := newWithFormatWriter(&buf, "spindle", "json") + if err != nil { + t.Fatal(err) + } + logger.Info("hello") + + var record map[string]any + if err := json.Unmarshal(buf.Bytes(), &record); err != nil { + t.Fatalf("parse json log: %v", err) + } + if record["logger"] != "spindle" || record["msg"] != "hello" { + t.Errorf("json log = %#v", record) + } +} + +func TestNewWithFormatRejectsUnknownFormat(t *testing.T) { + if _, err := NewWithFormat("spindle", "unknown"); err == nil { + t.Fatal("unknown format accepted") + } +} + +func TestSubLoggerPreservesJSON(t *testing.T) { + var buf bytes.Buffer + base, err := newWithFormatWriter(&buf, "spindle", "json") + if err != nil { + t.Fatal(err) + } + SubLogger(SubLogger(base, "mill"), "session").Info("connected") + + var record map[string]any + if err := json.Unmarshal(buf.Bytes(), &record); err != nil { + t.Fatalf("parse json log: %v", err) + } + if record["logger"] != "spindle/mill/session" { + t.Errorf("logger = %q", record["logger"]) + } + if strings.Count(buf.String(), `"logger"`) != 1 { + t.Errorf("duplicate logger fields in %s", buf.String()) + } +} + +func TestSubLoggerPreservesBoundAttributesAndGroups(t *testing.T) { + var buf bytes.Buffer + base, err := newWithFormatWriter(&buf, "spindle", "json") + if err != nil { + t.Fatal(err) + } + bound := base.With("request_id", "req-1").WithGroup("request").With("actor", "did:web:alice") + SubLogger(bound, "xrpc").Info("handled") + + var record map[string]any + if err := json.Unmarshal(buf.Bytes(), &record); err != nil { + t.Fatalf("parse json log: %v", err) + } + if record["logger"] != "spindle/xrpc" || record["request_id"] != "req-1" { + t.Errorf("json log = %#v", record) + } + group, ok := record["request"].(map[string]any) + if !ok || group["actor"] != "did:web:alice" { + t.Errorf("request group = %#v", record["request"]) + } +} + +func TestSubLoggerPreservesUnknownHandler(t *testing.T) { + var buf bytes.Buffer + base := slog.New(slog.NewJSONHandler(&buf, nil)) + SubLogger(base, "worker").Info("running") + + var record map[string]any + if err := json.Unmarshal(buf.Bytes(), &record); err != nil { + t.Fatalf("parse json log: %v", err) + } + if record["component"] != "worker" { + t.Errorf("component = %q", record["component"]) + } +} + +func TestTracingInLogHandler(t *testing.T) { + sampledSpanCtx := trace.NewSpanContext(trace.SpanContextConfig{ + TraceID: trace.TraceID{1}, + SpanID: trace.SpanID{2}, + TraceFlags: trace.FlagsSampled, + }) + unsampledSpanCtx := trace.NewSpanContext(trace.SpanContextConfig{ + TraceID: trace.TraceID{3}, + SpanID: trace.SpanID{4}, + TraceFlags: 0, + }) + + t.Run("sampled JSON", func(t *testing.T) { + var buf bytes.Buffer + logger, err := newWithFormatWriter(&buf, "spindle", "json") + if err != nil { + t.Fatal(err) + } + ctx := trace.ContextWithSpanContext(context.Background(), sampledSpanCtx) + logger.InfoContext(ctx, "hello") + + var record map[string]any + if err := json.Unmarshal(buf.Bytes(), &record); err != nil { + t.Fatalf("parse json log: %v", err) + } + if record["trace_id"] != sampledSpanCtx.TraceID().String() { + t.Errorf("trace_id = %v, want %v", record["trace_id"], sampledSpanCtx.TraceID().String()) + } + if record["span_id"] != sampledSpanCtx.SpanID().String() { + t.Errorf("span_id = %v, want %v", record["span_id"], sampledSpanCtx.SpanID().String()) + } + }) + + t.Run("sampled text", func(t *testing.T) { + var buf bytes.Buffer + logger, err := newWithFormatWriter(&buf, "spindle", "text") + if err != nil { + t.Fatal(err) + } + ctx := trace.ContextWithSpanContext(context.Background(), sampledSpanCtx) + logger.InfoContext(ctx, "hello") + got := buf.String() + if !strings.Contains(got, sampledSpanCtx.TraceID().String()) { + t.Errorf("text log missing trace_id: %q", got) + } + if !strings.Contains(got, sampledSpanCtx.SpanID().String()) { + t.Errorf("text log missing span_id: %q", got) + } + }) + + t.Run("unsampled JSON", func(t *testing.T) { + var buf bytes.Buffer + logger, err := newWithFormatWriter(&buf, "spindle", "json") + if err != nil { + t.Fatal(err) + } + ctx := trace.ContextWithSpanContext(context.Background(), unsampledSpanCtx) + logger.InfoContext(ctx, "hello") + + var record map[string]any + if err := json.Unmarshal(buf.Bytes(), &record); err != nil { + t.Fatalf("parse json log: %v", err) + } + if _, ok := record["trace_id"]; ok { + t.Errorf("unsampled log should not have trace_id") + } + if _, ok := record["span_id"]; ok { + t.Errorf("unsampled log should not have span_id") + } + }) + + t.Run("no context JSON", func(t *testing.T) { + var buf bytes.Buffer + logger, err := newWithFormatWriter(&buf, "spindle", "json") + if err != nil { + t.Fatal(err) + } + logger.Info("hello") + + var record map[string]any + if err := json.Unmarshal(buf.Bytes(), &record); err != nil { + t.Fatalf("parse json log: %v", err) + } + if _, ok := record["trace_id"]; ok { + t.Errorf("no-context log should not have trace_id") + } + if _, ok := record["span_id"]; ok { + t.Errorf("no-context log should not have span_id") + } + }) + + t.Run("prevent duplicate fields in record attributes", func(t *testing.T) { + var buf bytes.Buffer + logger, err := newWithFormatWriter(&buf, "spindle", "json") + if err != nil { + t.Fatal(err) + } + ctx := trace.ContextWithSpanContext(context.Background(), sampledSpanCtx) + logger.InfoContext(ctx, "hello", "trace_id", "custom-trace-id", "span_id", "custom-span-id") + + var record map[string]any + if err := json.Unmarshal(buf.Bytes(), &record); err != nil { + t.Fatalf("parse json log: %v", err) + } + if record["trace_id"] != "custom-trace-id" { + t.Errorf("trace_id = %v, want custom-trace-id", record["trace_id"]) + } + if record["span_id"] != "custom-span-id" { + t.Errorf("span_id = %v, want custom-span-id", record["span_id"]) + } + }) + + t.Run("prevent duplicate fields in WithAttrs", func(t *testing.T) { + var buf bytes.Buffer + logger, err := newWithFormatWriter(&buf, "spindle", "json") + if err != nil { + t.Fatal(err) + } + ctx := trace.ContextWithSpanContext(context.Background(), sampledSpanCtx) + logger.With("trace_id", "custom-trace-id", "span_id", "custom-span-id").InfoContext(ctx, "hello") + + var record map[string]any + if err := json.Unmarshal(buf.Bytes(), &record); err != nil { + t.Fatalf("parse json log: %v", err) + } + if record["trace_id"] != "custom-trace-id" { + t.Errorf("trace_id = %v, want custom-trace-id", record["trace_id"]) + } + if record["span_id"] != "custom-span-id" { + t.Errorf("span_id = %v, want custom-span-id", record["span_id"]) + } + }) +} + +type mockHandler struct { + records []slog.Record + attrs []slog.Attr + groups []string + name string + enabled bool +} + +func (m *mockHandler) Enabled(ctx context.Context, level slog.Level) bool { + return m.enabled +} + +func (m *mockHandler) Handle(ctx context.Context, r slog.Record) error { + m.records = append(m.records, r) + return nil +} + +func (m *mockHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &mockHandler{ + records: m.records, + attrs: append(m.attrs, attrs...), + groups: m.groups, + name: m.name, + enabled: m.enabled, + } +} + +func (m *mockHandler) WithGroup(name string) slog.Handler { + return &mockHandler{ + records: m.records, + attrs: m.attrs, + groups: append(m.groups, name), + name: m.name, + enabled: m.enabled, + } +} + +func (m *mockHandler) WithName(name string) slog.Handler { + return &mockHandler{ + records: m.records, + attrs: m.attrs, + groups: m.groups, + name: name, + enabled: m.enabled, + } +} + +func TestFanoutHandlerNoExtra(t *testing.T) { + primary := NewHandler("spindle") + handler := NewFanoutHandler(primary) + if handler != primary { + t.Error("NewFanoutHandler with no extra handlers should return the primary handler directly") + } +} + +func TestFanoutHandlerRouting(t *testing.T) { + primaryBuf := new(bytes.Buffer) + primary, err := newWithFormatWriter(primaryBuf, "primary", "json") + if err != nil { + t.Fatal(err) + } + + mock1 := &mockHandler{enabled: true} + mock2 := &mockHandler{enabled: false} + + fanout := NewFanoutHandler(primary.Handler(), mock1, mock2) + logger := slog.New(fanout) + + logger.Info("hello", "foo", "bar") + + if len(mock1.records) != 1 { + t.Errorf("mock1 got %d records, want 1", len(mock1.records)) + } else { + rec := mock1.records[0] + if rec.Message != "hello" { + t.Errorf("mock1 message = %q, want hello", rec.Message) + } + } + + if len(mock2.records) != 0 { + t.Errorf("mock2 got %d records, want 0", len(mock2.records)) + } + + if !strings.Contains(primaryBuf.String(), `"msg":"hello"`) { + t.Errorf("primaryBuf = %q, missing hello", primaryBuf.String()) + } +} + +func TestSubLoggerFanoutPropagation(t *testing.T) { + primaryBuf := new(bytes.Buffer) + primary, err := newWithFormatWriter(primaryBuf, "primary", "json") + if err != nil { + t.Fatal(err) + } + + mock := &mockHandler{enabled: true} + fanout := NewFanoutHandler(primary.Handler(), mock) + logger := slog.New(fanout) + + sub := SubLogger(logger, "sub") + sub.Info("test") + + if !strings.Contains(primaryBuf.String(), `"logger":"primary/sub"`) { + t.Errorf("primaryBuf = %q, missing logger primary/sub", primaryBuf.String()) + } + + if fanoutSub, ok := sub.Handler().(*fanoutHandler); ok { + if m, ok := fanoutSub.others[0].(*mockHandler); ok { + if m.name != "primary/sub" { + t.Errorf("mock name = %q, want primary/sub", m.name) + } + } else { + t.Error("fanoutSub others[0] is not *mockHandler") + } + } else { + t.Error("sub handler is not *fanoutHandler") + } +} + +func TestFanoutHandlerWithGroupAndAttrs(t *testing.T) { + primaryBuf := new(bytes.Buffer) + primary, err := newWithFormatWriter(primaryBuf, "primary", "json") + if err != nil { + t.Fatal(err) + } + + mock := &mockHandler{enabled: true} + fanout := NewFanoutHandler(primary.Handler(), mock) + logger := slog.New(fanout) + + logger.With("a", "b").WithGroup("g").Info("test") + + if fanoutSub, ok := logger.With("a", "b").WithGroup("g").Handler().(*fanoutHandler); ok { + if m, ok := fanoutSub.others[0].(*mockHandler); ok { + if len(m.attrs) != 1 || m.attrs[0].Key != "a" || m.attrs[0].Value.String() != "b" { + t.Errorf("mock attrs = %v, want [{a b}]", m.attrs) + } + if len(m.groups) != 1 || m.groups[0] != "g" { + t.Errorf("mock groups = %v, want [g]", m.groups) + } + } + } +} diff --git a/nix/gomod2nix.toml b/nix/gomod2nix.toml --- a/nix/gomod2nix.toml +++ b/nix/gomod2nix.toml @@ -211,6 +211,9 @@ [mod."github.com/cenkalti/backoff/v4"] version = "v4.3.0" hash = "sha256-wfVjNZsGG1WoNC5aL+kdcy6QXPgZo4THAevZ1787md8=" + [mod."github.com/cenkalti/backoff/v5"] + version = "v5.0.3" + hash = "sha256-bKq43PPD8RM6e7HePxHaO27traqm76bkvHcTVTQ+jeY=" [mod."github.com/cespare/xxhash/v2"] version = "v2.3.0" hash = "sha256-7hRlwSR+fos1kx4VZmJ/7snR7zHh8ZFKX+qqqqGcQpY=" @@ -458,6 +461,9 @@ [mod."github.com/grpc-ecosystem/go-grpc-middleware"] version = "v1.4.0" hash = "sha256-0UymBjkg41C9MPqkBLz/ZY9WbimZrabpJk+8C/X63h8=" + [mod."github.com/grpc-ecosystem/grpc-gateway/v2"] + version = "v2.28.0" + hash = "sha256-QeWb6jN6noeGPCzECgpUSb9YX9LzvKGwImEuX+A03gs=" [mod."github.com/hashicorp/errwrap"] version = "v1.1.0" hash = "sha256-6lwuMQOfBq+McrViN3maJTIeh4f8jbEqvLy2c9FvvFw=" @@ -858,18 +864,42 @@ [mod."go.opentelemetry.io/auto/sdk"] version = "v1.2.1" hash = "sha256-73bFYhnxNf4SfeQ52ebnwOWywdQbqc9lWawCcSgofvE=" + [mod."go.opentelemetry.io/contrib/bridges/otelslog"] + version = "v0.18.0" + hash = "sha256-m1iSWb89HFOPP1I8Zqb+p85ZMRrdlyAM9x6FjcW7DQ4=" [mod."go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"] version = "v0.65.0" hash = "sha256-fP/2TfGR6TcCH/ALHCAR2qHJlAJrCi8EU0OY1dRcf8U=" [mod."go.opentelemetry.io/otel"] version = "v1.43.0" hash = "sha256-oRemJUZhA7AzfUoBbRVA32u/XhMpipxLywHoJ1qsHBs=" + [mod."go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp"] + version = "v0.19.0" + hash = "sha256-fPT9B5yAIEXYVGBi5gcc7emErpKGUZzY46TV68wCWJ0=" + [mod."go.opentelemetry.io/otel/exporters/otlp/otlptrace"] + version = "v1.43.0" + hash = "sha256-caYRUaQ4DZGYtcUtH5kEkWXezDI4/vZRpUXpet3tQlg=" + [mod."go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp"] + version = "v1.43.0" + hash = "sha256-wvXfMOb3dIVtNDrsxO+wlH3BJwN70t3p0X2EV/ubPjQ=" + [mod."go.opentelemetry.io/otel/log"] + version = "v0.19.0" + hash = "sha256-bxaeA+aHA2VRrl4hfzomoadJyq34e6pzUvW9BLTtC/o=" [mod."go.opentelemetry.io/otel/metric"] version = "v1.43.0" hash = "sha256-iUfx5AvN2oiqlh2v8/oFa+2jm8RX4kbb6X1EOKRyPPw=" + [mod."go.opentelemetry.io/otel/sdk"] + version = "v1.43.0" + hash = "sha256-Z1uTuALNhRXStiDl0UvYh9+XE2hd9OYe/bxCSuR78uE=" + [mod."go.opentelemetry.io/otel/sdk/log"] + version = "v0.19.0" + hash = "sha256-mV2lp63Qi6THZYNmWEBo6puRFdslx3meMC+Sv7vs3iU=" [mod."go.opentelemetry.io/otel/trace"] version = "v1.43.0" hash = "sha256-LLx1PjBGzDwZ3//Gp14R1DCMlnMCzFxnGYqVUz5jTmk=" + [mod."go.opentelemetry.io/proto/otlp"] + version = "v1.10.0" + hash = "sha256-IEnbR38ucFLTcuC2FA+gRvZNq2loUqXgDskSqP3+LUM=" [mod."go.uber.org/atomic"] version = "v1.11.0" hash = "sha256-TyYws/cSPVqYNffFX0gbDml1bD4bBGcysrUWU7mHPIY=" diff --git a/spindle/ingester.go b/spindle/ingester.go --- a/spindle/ingester.go +++ b/spindle/ingester.go @@ -7,12 +7,14 @@ "errors" "fmt" - "tangled.org/core/api/tangled" - "tangled.org/core/spindle/db" - "tangled.org/core/tapc" - "github.com/bluesky-social/indigo/atproto/syntax" "github.com/bluesky-social/jetstream/pkg/models" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + "tangled.org/core/api/tangled" + "tangled.org/core/spindle/db" + "tangled.org/core/spindle/observability" + "tangled.org/core/tapc" ) type Ingester func(ctx context.Context, e *models.Event) error @@ -23,6 +25,24 @@ return nil } + ctx, span := observability.Tracer().Start(ctx, "jetstream.ingest") + defer span.End() + + if span.IsRecording() { + var attrs []attribute.KeyValue + if e.Did != "" { + attrs = append(attrs, attribute.String(observability.UserDIDKey, e.Did)) + } + if e.Commit != nil { + if e.Commit.Collection != "" { + attrs = append(attrs, attribute.String(observability.CollectionKey, e.Commit.Collection)) + } + if e.Commit.RKey != "" { + attrs = append(attrs, attribute.String(observability.RKeyKey, e.Commit.RKey)) + } + } + span.SetAttributes(attrs...) + } var err error switch e.Commit.Collection { case tangled.SpindleMemberNSID: @@ -42,7 +62,12 @@ } if err != nil { - s.l.Warn("failed to process message, skipping", "nsid", e.Commit.Collection, "did", e.Did, "rkey", e.Commit.RKey, "err", err) + s.l.WarnContext(ctx, "failed to process message, skipping", "nsid", e.Commit.Collection, "did", e.Did, "rkey", e.Commit.RKey, "err", err) + s.metrics.RecordEventIngestion("jetstream", "error") + span.SetStatus(codes.Error, "failed to process jetstream event") + } else { + s.metrics.RecordEventIngestion("jetstream", "success") + span.SetStatus(codes.Ok, "success") } return nil diff --git a/spindle/server.go b/spindle/server.go --- a/spindle/server.go +++ b/spindle/server.go @@ -22,6 +22,9 @@ "github.com/go-chi/chi/v5" "github.com/go-git/go-git/v5/plumbing/object" "github.com/hashicorp/go-version" + "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" "tangled.org/core/api/tangled" "tangled.org/core/eventconsumer" "tangled.org/core/eventconsumer/cursor" @@ -45,6 +48,7 @@ "tangled.org/core/spindle/mill" "tangled.org/core/spindle/mill/executor" "tangled.org/core/spindle/models" + "tangled.org/core/spindle/observability" "tangled.org/core/spindle/secrets" "tangled.org/core/spindle/xrpc" "tangled.org/core/tid" @@ -67,6 +71,7 @@ type executorClient interface { Connect(context.Context) Drain(context.Context) error + RegisterMetrics(*observability.Metrics) } type Spindle struct { @@ -77,8 +82,10 @@ e *rbac.Enforcer l *slog.Logger n *notifier.Notifier + metrics *observability.Metrics engs map[string]models.Engine jobWake chan struct{} + jobWorkers sync.WaitGroup cfg *config.Config ks *eventconsumer.Consumer res *idresolver.Resolver @@ -99,6 +106,11 @@ // New creates a new Spindle server with the provided configuration and engines. func New(ctx context.Context, cfg *config.Config, d *db.DB, engines map[string]models.Engine) (*Spindle, error) { logger := log.FromContext(ctx) + metrics := observability.GetMetrics(ctx) + if metrics == nil { + metrics = observability.NewMetrics() + ctx = observability.WithMetrics(ctx, metrics) + } n := notifier.New() lifecycleCtx, cancelLifecycle := context.WithCancel(context.WithoutCancel(ctx)) keepLifecycle := false @@ -120,6 +132,7 @@ db: d, l: logger, n: &n, + metrics: metrics, engs: engines, cfg: cfg, motd: defaultMotd, @@ -127,6 +140,7 @@ rootCancel: cancelLifecycle, jobWake: make(chan struct{}, 1), } + metrics.AttachDB(ctx, d) diskFallback := "" if cfg.Role == config.RoleStandalone { diskFallback = cfg.Server.LogDir @@ -343,9 +357,28 @@ } defer cancelRun() + _, err := observability.StartMetricsServer(runCtx, s.cfg.Server.MetricsListenAddr, s.l, s.metrics.Registry()) + if err != nil { + return fmt.Errorf("starting metrics listener: %w", err) + } + // only standalone runs the local queue. mill hosts place directly onto // executors, and executors only run jobs explicitly assigned by a mill - s.StartJobWorkers(runCtx) + workersCtx, cancelWorkers := context.WithCancel(runCtx) + s.StartJobWorkers(workersCtx) + defer func() { + cancelWorkers() + done := make(chan struct{}) + go func() { + s.jobWorkers.Wait() + close(done) + }() + select { + case <-done: + case <-time.After(5 * time.Second): + s.l.Warn("timed out waiting for job workers to stop") + } + }() var execDone chan struct{} if s.exec != nil { @@ -481,6 +514,39 @@ return fmt.Errorf("failed to load config: %w", err) } + shutdownTracing, err := observability.InitTracing(ctx, cfg.Tracing) + if err != nil { + return fmt.Errorf("failed to initialize tracing: %w", err) + } + defer func() { + shutdownCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + if err := shutdownTracing(shutdownCtx); err != nil { + log.FromContext(ctx).Error("failed to shut down tracing", "err", err) + } + }() + + otelHandler, shutdownLogging, err := observability.InitLogging(ctx, cfg.Logging) + if err != nil { + return fmt.Errorf("failed to initialize logging: %w", err) + } + defer func() { + shutdownCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + if err := shutdownLogging(shutdownCtx); err != nil { + log.FromContext(ctx).Error("failed to shut down logging", "err", err) + } + }() + + currentLogger := log.FromContext(ctx) + combinedHandler := log.NewFanoutHandler(currentLogger.Handler(), otelHandler) + combinedLogger := slog.New(combinedHandler) + slog.SetDefault(combinedLogger) + ctx = log.IntoContext(ctx, combinedLogger) + + metrics := observability.NewMetrics() + ctx = observability.WithMetrics(ctx, metrics) + if err := ensureGitVersion(); err != nil { return fmt.Errorf("ensuring git version: %w", err) } @@ -535,6 +601,7 @@ // notifier only exist after New, so attach them here m.Attach(s.DB(), s.Notifier()) s.mill = m + s.mill.RegisterMetrics(s.metrics) if err := m.RestoreState(); err != nil { return fmt.Errorf("restoring mill state: %w", err) } @@ -544,6 +611,7 @@ if err != nil { return err } + s.exec.RegisterMetrics(s.metrics) } return s.Start(ctx) @@ -551,24 +619,33 @@ func (s *Spindle) Router() http.Handler { mux := chi.NewRouter() + mux.Use(observability.HTTPMiddleware(s.metrics)) + if s.cfg.Tracing.Endpoint != "" { + mux.Use(observability.OTelRouteMiddleware) + } mux.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) { w.Write(s.GetMotdContent()) }) - if s.cfg.Role == config.RoleExecutor { + if s.cfg.Role != config.RoleExecutor { + mux.HandleFunc("/events", s.Events) + mux.HandleFunc("/logs/{knot}/{rkey}/{name}", s.Logs) + + if s.mill != nil { + mux.HandleFunc("/mill", s.mill.HandleExecutorConn) + } + + mux.Mount("/xrpc", s.XrpcRouter()) + } + + if s.cfg.Tracing.Endpoint == "" { return mux } - - mux.HandleFunc("/events", s.Events) - mux.HandleFunc("/logs/{knot}/{rkey}/{name}", s.Logs) - - // on a mill host, executors dial in here (plain ws, shared-secret auth) - if s.mill != nil { - mux.HandleFunc("/mill", s.mill.HandleExecutorConn) - } - - mux.Mount("/xrpc", s.XrpcRouter()) - return mux + return otelhttp.NewHandler( + mux, + "HTTP", + otelhttp.WithSpanNameFormatter(func(string, *http.Request) string { return "HTTP" }), + ) } func (s *Spindle) XrpcRouter() http.Handler { @@ -594,6 +671,22 @@ } func (s *Spindle) processKnotStream(ctx context.Context, src eventconsumer.Source, msg eventstream.Event) error { + ctx, span := observability.Tracer().Start(ctx, "knot.ingest") + defer span.End() + + metrics := s.metrics + err := s.processKnotStreamInner(ctx, src, msg) + if err != nil { + metrics.RecordEventIngestion("knot", "error") + span.SetStatus(codes.Error, "failed to process knot stream event") + } else { + metrics.RecordEventIngestion("knot", "success") + span.SetStatus(codes.Ok, "success") + } + return err +} + +func (s *Spindle) processKnotStreamInner(ctx context.Context, src eventconsumer.Source, msg eventstream.Event) error { l := log.FromContext(ctx).With("handler", "processKnotStream") l = l.With("src", src.Key(), "msg.Nsid", msg.Nsid, "msg.Rkey", msg.Rkey) if msg.Nsid == knotdb.RepoCollaboratorUpdateNSID { @@ -822,7 +915,7 @@ if err := s.db.CreatePipelineEvent(pipelineId.Rkey, tpl, s.n); err != nil { return models.PipelineId{}, fmt.Errorf("creating pipeline event: %w", err) } - err = s.processPipeline(repoDid, tpl, pipelineId, sourceRepo) + err = s.processPipeline(ctx, repoDid, tpl, pipelineId, sourceRepo) return pipelineId, err } @@ -1068,7 +1161,9 @@ func (s *Spindle) StartJobWorkers(ctx context.Context) { for range s.cfg.Server.MaxJobCount { + s.jobWorkers.Add(1) go func() { + defer s.jobWorkers.Done() for { job, err := s.db.DequeueJob(ctx) if err != nil { @@ -1083,6 +1178,7 @@ } continue } + s.metrics.RecordJobQueueActivity("dequeue") s.runJob(ctx, job) } }() @@ -1093,6 +1189,43 @@ pipelineId := models.PipelineId{ Knot: job.PipelineIdKnot, Rkey: job.PipelineIdRkey, + } + repoDID := job.RepoDid + if job.SourceRepo != nil && job.SourceRepo.RepoDid != nil && *job.SourceRepo.RepoDid != "" { + repoDID = *job.SourceRepo.RepoDid + } + + jobCtx := observability.ExtractFromTraceparentAndTracestate(ctx, job.Traceparent, job.Tracestate) + + jobCtx, span := observability.Tracer().Start(jobCtx, "job.run") + if span.IsRecording() { + attrs := []attribute.KeyValue{ + attribute.Int64(observability.JobIDKey, job.Id), + attribute.String(observability.PipelineIDKey, pipelineId.AtUri().String()), + } + if repoDID != "" { + attrs = append(attrs, attribute.String(observability.RepoDIDKey, repoDID)) + } + if job.RepoDid != "" && job.RepoDid != repoDID { + attrs = append(attrs, attribute.String(observability.TargetRepoDIDKey, job.RepoDid)) + } + span.SetAttributes(attrs...) + } + failed := false + defer func() { + if failed { + span.SetStatus(codes.Error, "job failed") + } else { + span.SetStatus(codes.Ok, "success") + } + span.End() + }() + + l := log.SubLogger(log.SubLogger(s.l, "job"), "engine").With( + "job_id", job.Id, + ) + if job.RepoDid != "" && job.RepoDid != repoDID { + l = l.With("target_repo_did", job.RepoDid) } pipelineEnv := models.PipelineEnvVarsForSource(job.Tpl.TriggerMetadata, pipelineId, job.SourceRepo) @@ -1116,6 +1249,7 @@ } eng, ok := s.engs[w.Engine] if !ok { + failed = true _ = s.db.StatusFailed(models.WorkflowId{ PipelineId: pipelineId, Name: w.Name, @@ -1125,6 +1259,7 @@ ewf, err := eng.InitWorkflow(*w, initTpl) if err != nil { + failed = true _ = s.db.StatusFailed(models.WorkflowId{ PipelineId: pipelineId, Name: w.Name, @@ -1139,7 +1274,7 @@ workflows[eng] = append(workflows[eng], *ewf) } - engine.StartWorkflows(log.SubLogger(s.l, "engine"), s.vault, s.cfg, s.stores, s.db, s.n, s.rootCtx, &models.Pipeline{ + engine.StartWorkflows(l, s.vault, s.cfg, s.stores, s.db, s.n, jobCtx, &models.Pipeline{ RepoDid: syntax.DID(job.RepoDid), Workflows: workflows, TrustedSource: trustedSource, @@ -1147,9 +1282,17 @@ } // enqueues the workflows in tpl. -func (s *Spindle) processPipeline(repoDid syntax.DID, tpl tangled.Pipeline, pipelineId models.PipelineId, sourceRepo *tangled.Pipeline_TriggerRepo) error { - err := s.db.EnqueueJob(s.rootCtx, repoDid.String(), pipelineId, sourceRepo, tpl) - if err != nil { +func (s *Spindle) processPipeline(ctx context.Context, repoDid syntax.DID, tpl tangled.Pipeline, pipelineId models.PipelineId, sourceRepo *tangled.Pipeline_TriggerRepo) error { + traceparent, tracestate := observability.InjectToTraceparentAndTracestate(ctx) + if err := s.db.EnqueueJob( + s.rootCtx, + repoDid.String(), + pipelineId, + sourceRepo, + tpl, + traceparent, + tracestate, + ); err != nil { return fmt.Errorf("failed to enqueue durable job: %w", err) } s.l.Info("pipeline enqueued successfully to db", "id", pipelineId) diff --git a/spindle/server_test.go b/spindle/server_test.go --- a/spindle/server_test.go +++ b/spindle/server_test.go @@ -14,6 +14,7 @@ "tangled.org/core/spindle/config" "tangled.org/core/spindle/db" "tangled.org/core/spindle/models" + "tangled.org/core/spindle/observability" ) func TestHasSkipCIPushOption(t *testing.T) { @@ -127,6 +128,8 @@ return ctx.Err() } } + +func (e *drainTestExecutor) RegisterMetrics(*observability.Metrics) {} func TestExecutorShutdownDrainsBeforeDisconnecting(t *testing.T) { exec := &drainTestExecutor{ diff --git a/spindle/tapclient.go b/spindle/tapclient.go --- a/spindle/tapclient.go +++ b/spindle/tapclient.go @@ -610,7 +610,7 @@ l.Error("failed resolving pipeline source repo", "err", err) return nil } - err = s.processPipeline(repo.RepoDid, tpl, pipelineId, sourceRepo) + err = s.processPipeline(ctx, repo.RepoDid, tpl, pipelineId, sourceRepo) if err != nil { // don't retry l.Error("failed processing pipeline", "err", err) diff --git a/cmd/spindle/main.go b/cmd/spindle/main.go --- a/cmd/spindle/main.go +++ b/cmd/spindle/main.go @@ -14,6 +14,7 @@ "time" "github.com/urfave/cli/v3" + tlog "tangled.org/core/log" "tangled.org/core/spindle" "tangled.org/core/spindle/db" @@ -32,7 +33,12 @@ DefaultCommand: "run", } - logger := tlog.New("spindle") + format := os.Getenv("SPINDLE_LOG_FORMAT") + logger, err := tlog.NewWithFormat("spindle", format) + if err != nil { + fmt.Fprintf(os.Stderr, "invalid log format: %v\n", err) + os.Exit(1) + } slog.SetDefault(logger) ctx := tlog.IntoContext(context.Background(), logger) diff --git a/cmd/spindle/main_test.go b/cmd/spindle/main_test.go new file mode 100644 --- /dev/null +++ b/cmd/spindle/main_test.go @@ -0,0 +1,48 @@ +package main + +import ( + "bytes" + "os" + "os/exec" + "strings" + "testing" +) + +func TestCLIInvalidLogFormat(t *testing.T) { + cmd := exec.Command(os.Args[0], "-test.run=TestHelperProcess") + cmd.Env = append(os.Environ(), "SPINDLE_LOG_FORMAT=invalid", "WANT_HELPER_PROCESS=1") + var stderr bytes.Buffer + cmd.Stderr = &stderr + err := cmd.Run() + + if err == nil { + t.Fatalf("expected command to fail, but it succeeded") + } + + exitErr, ok := err.(*exec.ExitError) + if !ok { + t.Fatalf("expected exit error, got %v", err) + } + if code := exitErr.ExitCode(); code != 1 { + t.Errorf("expected exit code 1, got %d", code) + } + + output := stderr.String() + if !strings.Contains(output, "invalid log format") { + t.Errorf("expected error message to contain 'invalid log format', got: %q", output) + } +} + +func TestHelperProcess(t *testing.T) { + if os.Getenv("WANT_HELPER_PROCESS") != "1" { + return + } + for i, arg := range os.Args { + if arg == "--" { + os.Args = append([]string{os.Args[0]}, os.Args[i+1:]...) + main() + return + } + } + main() +} diff --git a/nix/modules/spindle.nix b/nix/modules/spindle.nix --- a/nix/modules/spindle.nix +++ b/nix/modules/spindle.nix @@ -21,6 +21,12 @@ description = "Address to listen on"; }; + metricsListenAddr = mkOption { + type = types.str; + default = "127.0.0.1:9091"; + description = "Address for the metrics server to listen on"; + }; + dbPath = mkOption { type = types.path; default = "/var/lib/spindle/spindle.db"; @@ -341,6 +347,59 @@ example = "local"; description = "Optional cache upload URL used by live cache import paths."; }; + + }; + }; + + tracing = { + endpoint = mkOption { + type = types.str; + default = ""; + description = "OpenTelemetry collector endpoint (empty disables tracing)"; + }; + + serviceName = mkOption { + type = types.str; + default = "spindle"; + description = "OpenTelemetry service name"; + }; + + sampleRatio = mkOption { + type = types.number; + default = 1.0; + description = "Fraction of traces to sample"; + }; + + insecure = mkOption { + type = types.bool; + default = false; + description = "Use plaintext OTLP/HTTP"; + }; + }; + + logging = { + format = mkOption { + type = types.enum ["text" "json"]; + default = "text"; + description = "Local structured log format"; + }; + + endpoint = mkOption { + type = types.str; + default = ""; + description = "OpenTelemetry log collector endpoint (empty disables export)"; + }; + + serviceName = mkOption { + type = types.str; + default = "spindle"; + description = "OpenTelemetry log service name"; + }; + + insecure = mkOption { + type = types.bool; + default = false; + description = "Use plaintext OTLP/HTTP for logs"; }; }; @@ -544,6 +603,8 @@ localStateDirectories = mapAttrsToList (_: service: service.stateDirectory) localServices; localDbPaths = mapAttrsToList (_: service: toString service.server.dbPath) localServices; localRepoDirs = mapAttrsToList (_: service: toString service.server.repoDir) localServices; + metricsServices = filterAttrs (_: service: service.server.metricsListenAddr != "") localServices; + localMetricsListenAddrs = mapAttrsToList (_: service: service.server.metricsListenAddr) metricsServices; debugServices = filterAttrs (_: service: service.pipelines.microvm.debugSsh.enable) localServices; localDebugSshListenAddrs = mapAttrsToList (_: service: service.pipelines.microvm.debugSsh.listenAddr) debugServices; @@ -564,6 +625,7 @@ processEnvironment = instance: [ "SPINDLE_SERVER_LISTEN_ADDR=${instance.server.listenAddr}" + "SPINDLE_SERVER_METRICS_LISTEN_ADDR=${instance.server.metricsListenAddr}" "SPINDLE_SERVER_DB_PATH=${instance.server.dbPath}" "SPINDLE_SERVER_REPO_DIR=${instance.server.repoDir}" "SPINDLE_SERVER_HOSTNAME=${instance.server.hostname}" @@ -616,6 +678,14 @@ "SPINDLE_ARTIFACT_STORES_S3_REGION=${instance.artifactStores.s3.region}" "SPINDLE_MILL_ARTIFACT_STORE=${cfg.mill.artifactStore}" "SPINDLE_MILL_DRAIN_TIMEOUT=${toString cfg.mill.drainTimeout}s" + "SPINDLE_TRACING_ENDPOINT=${instance.tracing.endpoint}" + "SPINDLE_TRACING_SERVICE_NAME=${instance.tracing.serviceName}" + "SPINDLE_TRACING_SAMPLE_RATIO=${toString instance.tracing.sampleRatio}" + "SPINDLE_TRACING_INSECURE=${lib.boolToString instance.tracing.insecure}" + "SPINDLE_LOG_FORMAT=${instance.logging.format}" + "SPINDLE_LOGGING_ENDPOINT=${instance.logging.endpoint}" + "SPINDLE_LOGGING_SERVICE_NAME=${instance.logging.serviceName}" + "SPINDLE_LOGGING_INSECURE=${lib.boolToString instance.logging.insecure}" ]; connectionEnvironment = executor: [ @@ -811,6 +881,14 @@ { assertion = length localDebugSshListenAddrs == length (unique localDebugSshListenAddrs); message = "services.tangled.spindle.mill.executors must use different localService.pipelines.microvm.debugSsh.listenAddr values"; + } + { + assertion = length localMetricsListenAddrs == length (unique localMetricsListenAddrs); + message = "services.tangled.spindle.mill.executors must use different localService.server.metricsListenAddr values"; + } + { + assertion = !elem cfg.server.metricsListenAddr localMetricsListenAddrs; + message = "services.tangled.spindle.mill.executors must not use the main spindle's server.metricsListenAddr"; } { assertion = diff --git a/spindle/config/config.go b/spindle/config/config.go --- a/spindle/config/config.go +++ b/spindle/config/config.go @@ -3,6 +3,7 @@ import ( "context" "fmt" + "math" "time" "github.com/bluesky-social/indigo/atproto/syntax" @@ -12,6 +13,7 @@ type Server struct { ListenAddr string `env:"LISTEN_ADDR, default=0.0.0.0:6555"` + MetricsListenAddr string `env:"METRICS_LISTEN_ADDR, default=127.0.0.1:9091"` DBPath string `env:"DB_PATH, default=spindle.db"` RepoDir string `env:"REPO_DIR, default=repos"` Hostname string `env:"HOSTNAME, required"` @@ -151,6 +153,18 @@ DebugExecutorPort uint32 `env:"DEBUG_EXECUTOR_PORT, default=2223"` MaxJumpConnections int `env:"MAX_JUMP_CONNECTIONS, default=128"` } +type Tracing struct { + Endpoint string `env:"ENDPOINT"` + ServiceName string `env:"SERVICE_NAME, default=spindle"` + SampleRatio float64 `env:"SAMPLE_RATIO, default=1"` + Insecure bool `env:"INSECURE, default=false"` +} + +type Logging struct { + Endpoint string `env:"ENDPOINT"` + ServiceName string `env:"SERVICE_NAME, default=spindle"` + Insecure bool `env:"INSECURE, default=false"` +} type Config struct { Role Role `env:"SPINDLE_ROLE, default=standalone"` @@ -161,6 +175,8 @@ ArtifactStores ArtifactStores `env:",prefix=SPINDLE_ARTIFACT_STORES_"` LegacyS3 LegacyS3 `env:",prefix=SPINDLE_S3_"` Mill Mill `env:",prefix=SPINDLE_MILL_"` + Tracing Tracing `env:",prefix=SPINDLE_TRACING_"` + Logging Logging `env:",prefix=SPINDLE_LOGGING_"` } func (c *Config) validate() error { @@ -195,6 +211,15 @@ if c.Mill.MaxJumpConnections <= 0 { return fmt.Errorf("SPINDLE_MILL_MAX_JUMP_CONNECTIONS must be greater than zero") } + } + if math.IsNaN(c.Tracing.SampleRatio) || c.Tracing.SampleRatio < 0 || c.Tracing.SampleRatio > 1 { + return fmt.Errorf("SPINDLE_TRACING_SAMPLE_RATIO must be between 0 and 1 inclusive, got %f", c.Tracing.SampleRatio) + } + if c.Tracing.Endpoint != "" && c.Tracing.ServiceName == "" { + return fmt.Errorf("SPINDLE_TRACING_SERVICE_NAME must not be empty when tracing is enabled") + } + if c.Logging.Endpoint != "" && c.Logging.ServiceName == "" { + return fmt.Errorf("SPINDLE_LOGGING_SERVICE_NAME must not be empty when logging is enabled") } return nil } diff --git a/spindle/config/config_test.go b/spindle/config/config_test.go --- a/spindle/config/config_test.go +++ b/spindle/config/config_test.go @@ -110,3 +110,106 @@ t.Fatalf("max jump connections = %d, want 17", cfg.Mill.MaxJumpConnections) } } + +func TestLoadMetricsListenAddr(t *testing.T) { + t.Setenv("SPINDLE_SERVER_HOSTNAME", "spindle.example.com") + t.Setenv("SPINDLE_SERVER_OWNER", "did:web:spindle.example.com") + + cfg, err := Load(context.Background()) + if err != nil { + t.Fatal(err) + } + if cfg.Server.MetricsListenAddr != "127.0.0.1:9091" { + t.Errorf("default MetricsListenAddr = %q, want 127.0.0.1:9091", cfg.Server.MetricsListenAddr) + } + + t.Setenv("SPINDLE_SERVER_METRICS_LISTEN_ADDR", "0.0.0.0:9999") + cfg, err = Load(context.Background()) + if err != nil { + t.Fatal(err) + } + if cfg.Server.MetricsListenAddr != "0.0.0.0:9999" { + t.Errorf("overridden MetricsListenAddr = %q, want 0.0.0.0:9999", cfg.Server.MetricsListenAddr) + } +} + +func TestLoadTracingConfig(t *testing.T) { + t.Setenv("SPINDLE_SERVER_HOSTNAME", "spindle.example.com") + t.Setenv("SPINDLE_SERVER_OWNER", "did:web:spindle.example.com") + t.Setenv("SPINDLE_TRACING_ENDPOINT", "tempo:4318") + t.Setenv("SPINDLE_TRACING_SERVICE_NAME", "spindle-test") + t.Setenv("SPINDLE_TRACING_SAMPLE_RATIO", "0.5") + t.Setenv("SPINDLE_TRACING_INSECURE", "true") + + cfg, err := Load(context.Background()) + if err != nil { + t.Fatal(err) + } + + if cfg.Tracing.Endpoint != "tempo:4318" { + t.Errorf("Endpoint = %q, want tempo:4318", cfg.Tracing.Endpoint) + } + if cfg.Tracing.ServiceName != "spindle-test" { + t.Errorf("ServiceName = %q, want spindle-test", cfg.Tracing.ServiceName) + } + if cfg.Tracing.SampleRatio != 0.5 { + t.Errorf("SampleRatio = %f, want 0.5", cfg.Tracing.SampleRatio) + } + if !cfg.Tracing.Insecure { + t.Errorf("Insecure = %t, want true", cfg.Tracing.Insecure) + } +} + +func TestLoadTracingConfigValidation(t *testing.T) { + t.Setenv("SPINDLE_SERVER_HOSTNAME", "spindle.example.com") + t.Setenv("SPINDLE_SERVER_OWNER", "did:web:spindle.example.com") + + t.Setenv("SPINDLE_TRACING_SAMPLE_RATIO", "1.5") + if _, err := Load(context.Background()); err == nil { + t.Fatal("expected error for SampleRatio > 1") + } + + t.Setenv("SPINDLE_TRACING_SAMPLE_RATIO", "-0.1") + if _, err := Load(context.Background()); err == nil { + t.Fatal("expected error for SampleRatio < 0") + } + + t.Setenv("SPINDLE_TRACING_SAMPLE_RATIO", "NaN") + if _, err := Load(context.Background()); err == nil { + t.Fatal("expected error for NaN SampleRatio") + } +} + +func TestLoadLoggingConfig(t *testing.T) { + t.Setenv("SPINDLE_SERVER_HOSTNAME", "spindle.example.com") + t.Setenv("SPINDLE_SERVER_OWNER", "did:web:spindle.example.com") + t.Setenv("SPINDLE_LOGGING_ENDPOINT", "loki:4318") + t.Setenv("SPINDLE_LOGGING_SERVICE_NAME", "spindle-log-test") + t.Setenv("SPINDLE_LOGGING_INSECURE", "true") + + cfg, err := Load(context.Background()) + if err != nil { + t.Fatal(err) + } + + if cfg.Logging.Endpoint != "loki:4318" { + t.Errorf("Endpoint = %q, want loki:4318", cfg.Logging.Endpoint) + } + if cfg.Logging.ServiceName != "spindle-log-test" { + t.Errorf("ServiceName = %q, want spindle-log-test", cfg.Logging.ServiceName) + } + if !cfg.Logging.Insecure { + t.Errorf("Insecure = %t, want true", cfg.Logging.Insecure) + } +} + +func TestLoadLoggingConfigValidation(t *testing.T) { + t.Setenv("SPINDLE_SERVER_HOSTNAME", "spindle.example.com") + t.Setenv("SPINDLE_SERVER_OWNER", "did:web:spindle.example.com") + t.Setenv("SPINDLE_LOGGING_ENDPOINT", "loki:4318") + t.Setenv("SPINDLE_LOGGING_SERVICE_NAME", "") + + if _, err := Load(context.Background()); err == nil { + t.Fatal("expected error for empty ServiceName when logging endpoint is configured") + } +} diff --git a/spindle/db/db.go b/spindle/db/db.go --- a/spindle/db/db.go +++ b/spindle/db/db.go @@ -113,6 +113,8 @@ pipeline_id_rkey text not null, source_repo text, tpl text not null, + traceparent text not null default '', + tracestate text not null default '', created_at integer not null default (strftime('%s', 'now')) ); @@ -361,6 +363,27 @@ alter table mill_executors_new rename to mill_executors; `) return err + }); err != nil { + return err + } + + if err := orm.RunMigration(conn, logger, "jobs-trace-context", func(tx *sql.Tx) error { + for _, column := range []string{"traceparent", "tracestate"} { + var present int + if err := tx.QueryRow( + `select count(*) from pragma_table_info('jobs') where name = ?`, + column, + ).Scan(&present); err != nil { + return err + } + if present != 0 { + continue + } + if _, err := tx.Exec(`alter table jobs add column ` + column + ` text not null default ''`); err != nil { + return err + } + } + return nil }); err != nil { return err } diff --git a/spindle/db/jobs.go b/spindle/db/jobs.go --- a/spindle/db/jobs.go +++ b/spindle/db/jobs.go @@ -15,17 +15,19 @@ PipelineIdRkey string SourceRepo *tangled.Pipeline_TriggerRepo Tpl tangled.Pipeline + Traceparent string + Tracestate string } -func (d *DB) EnqueueJob(ctx context.Context, repoDid string, pipelineId models.PipelineId, sourceRepo *tangled.Pipeline_TriggerRepo, tpl tangled.Pipeline) error { +func (d *DB) EnqueueJob(ctx context.Context, repoDid string, pipelineId models.PipelineId, sourceRepo *tangled.Pipeline_TriggerRepo, tpl tangled.Pipeline, traceparent, tracestate string) error { tplJson, err := json.Marshal(tpl) if err != nil { return err } _, err = d.ExecContext(ctx, ` - insert into jobs (repo_did, pipeline_id_knot, pipeline_id_rkey, source_repo, tpl) - values (?, ?, ?, ?, ?) - `, repoDid, pipelineId.Knot, pipelineId.Rkey, string(sourceRepoJson(sourceRepo)), string(tplJson)) + insert into jobs (repo_did, pipeline_id_knot, pipeline_id_rkey, source_repo, tpl, traceparent, tracestate) + values (?, ?, ?, ?, ?, ?, ?) + `, repoDid, pipelineId.Knot, pipelineId.Rkey, string(sourceRepoJson(sourceRepo)), string(tplJson), traceparent, tracestate) return err } func (d *DB) DequeueJob(ctx context.Context) (*JobRow, error) { @@ -39,8 +41,8 @@ order by id asc limit 1 ) - returning id, repo_did, pipeline_id_knot, pipeline_id_rkey, source_repo, tpl - `).Scan(&row.Id, &row.RepoDid, &row.PipelineIdKnot, &row.PipelineIdRkey, &sourceRepoStr, &tplJson) + returning id, repo_did, pipeline_id_knot, pipeline_id_rkey, source_repo, tpl, traceparent, tracestate + `).Scan(&row.Id, &row.RepoDid, &row.PipelineIdKnot, &row.PipelineIdRkey, &sourceRepoStr, &tplJson, &row.Traceparent, &row.Tracestate) if err != nil { if err == sql.ErrNoRows { return nil, nil diff --git a/spindle/db/jobs_test.go b/spindle/db/jobs_test.go new file mode 100644 --- /dev/null +++ b/spindle/db/jobs_test.go @@ -0,0 +1,45 @@ +package db + +import ( + "context" + "path/filepath" + "testing" + + "tangled.org/core/api/tangled" + "tangled.org/core/spindle/models" +) + +func TestJobTraceContextSurvivesEnqueue(t *testing.T) { + ctx := context.Background() + database, err := Make(ctx, filepath.Join(t.TempDir(), "spindle.db")) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { database.Close() }) + + pipelineID := models.PipelineId{Knot: "knot.example.com", Rkey: "pipeline"} + const traceparent = "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01" + const tracestate = "vendor=value" + if err := database.EnqueueJob( + ctx, + "did:web:repo.example.com", + pipelineID, + &tangled.Pipeline_TriggerRepo{}, + tangled.Pipeline{}, + traceparent, + tracestate, + ); err != nil { + t.Fatal(err) + } + + job, err := database.DequeueJob(ctx) + if err != nil { + t.Fatal(err) + } + if job == nil { + t.Fatal("dequeued job is nil") + } + if job.Traceparent != traceparent || job.Tracestate != tracestate { + t.Fatalf("trace context = (%q, %q), want (%q, %q)", job.Traceparent, job.Tracestate, traceparent, tracestate) + } +} diff --git a/spindle/engine/engine.go b/spindle/engine/engine.go --- a/spindle/engine/engine.go +++ b/spindle/engine/engine.go @@ -12,11 +12,16 @@ "sync" "time" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/trace" + "strings" "tangled.org/core/notifier" "tangled.org/core/spindle/artifactstore" "tangled.org/core/spindle/config" "tangled.org/core/spindle/db" "tangled.org/core/spindle/models" + "tangled.org/core/spindle/observability" "tangled.org/core/spindle/secrets" ) @@ -76,6 +81,46 @@ // for engines that manage status updates outside StartWorkflows type RemoteStatusEngine interface { AuthorsRemoteStatus() +} + +type metricEngineNamer interface { + MetricEngineName() string +} + +func engineName(eng models.Engine) string { + if eng == nil { + return "unknown" + } + if named, ok := eng.(metricEngineNamer); ok { + return boundEngineName(named.MetricEngineName()) + } + name := strings.TrimPrefix(fmt.Sprintf("%T", eng), "*") + if idx := strings.Index(name, "."); idx != -1 { + name = name[:idx] + } + return boundEngineName(name) +} + +func boundEngineName(name string) string { + switch name { + case "dummy", "microvm", "nixery": + return name + default: + return "unknown" + } +} + +func workflowResult(ctx context.Context, err error) string { + if isCanceled(ctx) { + return "cancelled" + } + if errors.Is(err, ErrTimedOut) || errors.Is(ctx.Err(), context.DeadlineExceeded) { + return "timeout" + } + if err != nil { + return "failure" + } + return "success" } func reportWorkflowStatusError(l *slog.Logger, database *db.DB, n *notifier.Notifier, wid models.WorkflowId, err error) { @@ -149,11 +194,125 @@ } wg.Go(func() { + repoDID := w.RepoDID + if repoDID == "" && pipeline != nil { + repoDID = pipeline.RepoDid.String() + } + wl := l.With( + "owner_did", w.OwnerDID, + "repo_did", repoDID, + "pipeline_id", pipelineId.AtUri().String(), + "workflow_id", wid.String(), + ) + if st, err := db.GetStatus(wid); err == nil && models.StatusKind(st.Status).IsFinish() { l.Info("skipping finished workflow", "wid", wid, "status", st.Status) return } var err error + var wfCtx context.Context = ctx + engName := engineName(eng) + + // start span for workflow execution + var span trace.Span + wfCtx, span = observability.Tracer().Start(wfCtx, "workflow.run", trace.WithAttributes( + attribute.String(observability.WorkflowEngineKey, engName), + )) + if span.IsRecording() { + attrs := []attribute.KeyValue{ + attribute.String(observability.PipelineIDKey, pipelineId.AtUri().String()), + attribute.String(observability.WorkflowIDKey, wid.String()), + } + if w.OwnerDID != "" { + attrs = append(attrs, attribute.String(observability.OwnerDIDKey, w.OwnerDID)) + } + if repoDID != "" { + attrs = append(attrs, attribute.String(observability.RepoDIDKey, repoDID)) + } + span.SetAttributes(attrs...) + } + defer span.End() + + _, remoteStatus := eng.(RemoteStatusEngine) + metrics := observability.GetMetrics(ctx) + if !remoteStatus { + metrics.RecordWorkflowStart(engName) + } + startTime := time.Now() + result := "success" + + defer func() { + if err != nil { + span.SetStatus(codes.Error, "workflow failed") + } else if isCanceled(wfCtx) { + span.SetStatus(codes.Error, "workflow cancelled") + } else { + span.SetStatus(codes.Ok, "success") + } + + duration := time.Since(startTime) + resStr := result + if err != nil { + resStr = workflowResult(wfCtx, err) + } else if isCanceled(wfCtx) { + resStr = "cancelled" + } + + var cpuUsec, memoryCurrent, memoryPeak, swapCurrent, swapPeak, pidsCurrent, ioReadBytes, ioWriteBytes, ioReadOps, ioWriteOps, volumeAllocated uint64 + var cgroupAvailable, volumeAvailable bool + if reporter, ok := eng.(WorkflowResourceUsageReporter); ok { + if usage, ok := reporter.WorkflowResourceUsage(&w); ok { + cpuUsec = usage.CPUUsec + memoryCurrent = usage.MemoryCurrentBytes + memoryPeak = usage.MemoryPeakBytes + swapCurrent = usage.SwapCurrentBytes + swapPeak = usage.SwapPeakBytes + pidsCurrent = usage.PIDsCurrent + ioReadBytes = usage.IOReadBytes + ioWriteBytes = usage.IOWriteBytes + ioReadOps = usage.IOReadOps + ioWriteOps = usage.IOWriteOps + volumeAllocated = usage.VolumeAllocatedBytes + cgroupAvailable = usage.CgroupAvailable + volumeAvailable = usage.VolumeAvailable + } + } + + wl.InfoContext(wfCtx, "workflow finished", + "result", resStr, + "duration_seconds", duration.Seconds(), + "actual_cpu_usec", cpuUsec, + "actual_memory_current_bytes", memoryCurrent, + "actual_memory_peak_bytes", memoryPeak, + "actual_swap_current_bytes", swapCurrent, + "actual_swap_peak_bytes", swapPeak, + "actual_pids_current", pidsCurrent, + "actual_io_read_bytes", ioReadBytes, + "actual_io_write_bytes", ioWriteBytes, + "actual_io_read_ops", ioReadOps, + "actual_io_write_ops", ioWriteOps, + "actual_volume_allocated_bytes", volumeAllocated, + "actual_cgroup_available", cgroupAvailable, + "actual_volume_available", volumeAvailable, + ) + + if span.IsRecording() { + span.SetAttributes( + observability.ActualResourceAttrs( + cpuUsec, memoryCurrent, memoryPeak, swapCurrent, swapPeak, pidsCurrent, + ioReadBytes, ioWriteBytes, ioReadOps, ioWriteOps, volumeAllocated, + cgroupAvailable, volumeAvailable, + )..., + ) + } + + if remoteStatus { + return + } + + metrics.RecordWorkflowEnd(wfCtx, engName, resStr, duration) + }() + var wfLogger models.WorkflowLogger closeLog := func() {} if p, ok := eng.(workflowLoggerProvider); ok { @@ -176,10 +335,11 @@ defer closeLog() } - timeoutCtx, timeoutCancel := context.WithTimeout(ctx, workflowTimeout) + timeoutCtx, timeoutCancel := context.WithTimeout(wfCtx, workflowTimeout) defer timeoutCancel() - wfCtx, userCancel := context.WithCancelCause(timeoutCtx) + var userCancel context.CancelCauseFunc + wfCtx, userCancel = context.WithCancelCause(timeoutCtx) defer userCancel(nil) // allow wf context to be cancelled properly by manual cancel @@ -194,7 +354,6 @@ l.Info("waiting for slot", "wid", wid) slot := WorkflowSlot(NoopSlot{}) - _, remoteStatus := eng.(RemoteStatusEngine) var publishTerminalStatus func() destroyWorkflow := false slotAcquired := false @@ -228,7 +387,7 @@ } if !remoteStatus { - err := db.StatusRunning(wid, n) + err = db.StatusRunning(wid, n) if err != nil { l.Error("failed to set workflow status to running", "wid", wid, "err", err) return @@ -252,12 +411,50 @@ Write([]byte{0}) } - err = eng.RunStep(wfCtx, wid, &w, stepIdx, allSecrets, wfLogger) + if !remoteStatus { + metrics.RecordStepStart(engName) + } + stepStart := time.Now() + + var stepSpan trace.Span + var stepCtx context.Context + stepCtx, stepSpan = observability.Tracer().Start(wfCtx, "step.run") + if stepSpan.IsRecording() { + attrs := []attribute.KeyValue{ + attribute.String(observability.WorkflowEngineKey, engName), + attribute.String(observability.PipelineIDKey, pipelineId.AtUri().String()), + attribute.String(observability.WorkflowIDKey, wid.String()), + attribute.Int(observability.StepIndexKey, stepIdx), + attribute.String(observability.StepNameKey, step.Name()), + } + if w.OwnerDID != "" { + attrs = append(attrs, attribute.String(observability.OwnerDIDKey, w.OwnerDID)) + } + if repoDID != "" { + attrs = append(attrs, attribute.String(observability.RepoDIDKey, repoDID)) + } + stepSpan.SetAttributes(attrs...) + } + + err = eng.RunStep(stepCtx, wid, &w, stepIdx, allSecrets, wfLogger) if wfLogger != nil { wfLogger. ControlWriter(stepIdx, step, models.StepStatusEnd). Write([]byte{0}) + } + + stepResult := "success" + if err != nil { + stepResult = workflowResult(wfCtx, err) + stepSpan.SetStatus(codes.Error, "step failed") + } else { + stepSpan.SetStatus(codes.Ok, "success") + } + stepSpan.End() + + if !remoteStatus { + metrics.RecordStepEnd(stepCtx, engName, stepResult, time.Since(stepStart)) } if err != nil { diff --git a/spindle/engine/scheduler.go b/spindle/engine/scheduler.go --- a/spindle/engine/scheduler.go +++ b/spindle/engine/scheduler.go @@ -24,6 +24,9 @@ queue []*resourceWaiter[R] now func() time.Time // get time now, is a field for mocking agingThreshold time.Duration + + OnAcquire func(req R, allowed bool, reason string) + OnSnapshot func(budget, max, used R, queueLen int) } type resourceWaiter[R Resources[R]] struct { @@ -59,28 +62,50 @@ s.mu.Lock() if !req.Fits(s.budget) || !req.Fits(s.max) { s.mu.Unlock() + if s.OnAcquire != nil { + reason := "request_exceeds_budget" + if !req.Fits(s.max) { + reason = "request_exceeds_max" + } + s.OnAcquire(req, false, reason) + } return nil, fmt.Errorf("%w: request=%v budget=%v max=%v", ErrNoWorkflowSlots, req, s.budget, s.max) } // ignores the queue because it never blocks // only bypasses empty queues to prevent starvation if s.used.Add(req).Fits(s.budget) && (mode == NoWait || len(s.queue) == 0) { s.used = s.used.Add(req) + if s.OnAcquire != nil { + s.OnAcquire(req, true, "allowed_immediately") + } + if s.OnSnapshot != nil { + s.OnSnapshot(s.budget, s.max, s.used, len(s.queue)) + } s.mu.Unlock() return &resourceLease[R]{scheduler: s, req: req}, nil } if mode == NoWait { used := s.used s.mu.Unlock() + if s.OnAcquire != nil { + s.OnAcquire(req, false, "no_wait_slot_unavailable") + } return nil, fmt.Errorf("%w: request=%v used=%v budget=%v", ErrNoWorkflowSlots, req, used, s.budget) } waiter := &resourceWaiter[R]{req: req, ready: make(chan struct{}), enqueuedAt: s.now()} s.queue = append(s.queue, waiter) + if s.OnSnapshot != nil { + s.OnSnapshot(s.budget, s.max, s.used, len(s.queue)) + } s.schedule() s.mu.Unlock() select { case <-waiter.ready: + if s.OnAcquire != nil { + s.OnAcquire(req, true, "allowed_from_queue") + } return &resourceLease[R]{scheduler: s, req: req}, nil case <-ctx.Done(): s.mu.Lock() @@ -88,11 +113,20 @@ case <-waiter.ready: // undo committed resources, schedule already did that s.used = s.used.Sub(req) + if s.OnAcquire != nil { + s.OnAcquire(req, false, "context_done_after_ready") + } default: // still in queue, just remove s.remove(waiter) + if s.OnAcquire != nil { + s.OnAcquire(req, false, "context_done_in_queue") + } } s.schedule() + if s.OnSnapshot != nil { + s.OnSnapshot(s.budget, s.max, s.used, len(s.queue)) + } s.mu.Unlock() return nil, ctx.Err() } @@ -112,6 +146,9 @@ defer s.mu.Unlock() s.used = s.used.Sub(req) s.schedule() + if s.OnSnapshot != nil { + s.OnSnapshot(s.budget, s.max, s.used, len(s.queue)) + } } // start every waiter whose request fits. once a waiter is older than @@ -121,18 +158,23 @@ var reserved R now := s.now() i := 0 + changed := false for i < len(s.queue) { w := s.queue[i] if s.used.Add(reserved).Add(w.req).Fits(s.budget) { s.queue = slices.Delete(s.queue, i, i+1) s.used = s.used.Add(w.req) close(w.ready) + changed = true continue } if now.Sub(w.enqueuedAt) >= s.agingThreshold { reserved = reserved.Add(w.req) } i++ + } + if changed && s.OnSnapshot != nil { + s.OnSnapshot(s.budget, s.max, s.used, len(s.queue)) } } diff --git a/spindle/engine/usage.go b/spindle/engine/usage.go new file mode 100644 --- /dev/null +++ b/spindle/engine/usage.go @@ -0,0 +1,23 @@ +package engine + +import "tangled.org/core/spindle/models" + +type WorkflowResourceUsage struct { + CPUUsec uint64 + MemoryCurrentBytes uint64 + MemoryPeakBytes uint64 + SwapCurrentBytes uint64 + SwapPeakBytes uint64 + PIDsCurrent uint64 + IOReadBytes uint64 + IOWriteBytes uint64 + IOReadOps uint64 + IOWriteOps uint64 + VolumeAllocatedBytes uint64 + CgroupAvailable bool + VolumeAvailable bool +} + +type WorkflowResourceUsageReporter interface { + WorkflowResourceUsage(wf *models.Workflow) (WorkflowResourceUsage, bool) +} diff --git a/spindle/mill/engine.go b/spindle/mill/engine.go --- a/spindle/mill/engine.go +++ b/spindle/mill/engine.go @@ -28,6 +28,10 @@ func (e *Engine) AuthorsRemoteStatus() {} +func (e *Engine) MetricEngineName() string { + return e.name +} + func NewEngine(name string, mill *Mill) *Engine { return &Engine{name: name, mill: mill, l: mill.l.With("engine", "mill:"+name)} } diff --git a/spindle/mill/jump.go b/spindle/mill/jump.go --- a/spindle/mill/jump.go +++ b/spindle/mill/jump.go @@ -14,6 +14,7 @@ "github.com/gliderlabs/ssh" gossh "golang.org/x/crypto/ssh" + "tangled.org/core/spindle/observability" ) const ( @@ -59,9 +60,15 @@ return nil, fmt.Errorf("prepare jump host key: %w", err) } limiter := newJumpConnectionLimiter(maxConnections, maxJumpConnectionsPerIP) + limiter.metrics = m.metrics + m.metrics.RecordJumpLimit(int64(maxConnections)) srv := &ssh.Server{ PublicKeyHandler: func(ctx ssh.Context, _ ssh.PublicKey) bool { - return ctx.User() == "debug" + allowed := ctx.User() == "debug" + if !allowed { + m.metrics.RecordJumpRejection("unauthorized_user") + } + return allowed }, ConnCallback: func(ctx ssh.Context, conn net.Conn) net.Conn { if !limiter.acquire(conn.RemoteAddr()) { @@ -75,12 +82,18 @@ return conn }, LocalPortForwardingCallback: func(ctx ssh.Context, host string, port uint32) bool { - if port != executorPort || !m.hasLiveExecutor(host) { + if port != executorPort { + m.metrics.RecordJumpRejection("invalid_port") + return false + } + if !m.hasLiveExecutor(host) { + m.metrics.RecordJumpRejection("executor_unavailable") return false } ctx.Lock() defer ctx.Unlock() if opened, _ := ctx.Value(jumpRouteOpened).(bool); opened { + m.metrics.RecordJumpRejection("route_already_open") return false } ctx.SetValue(jumpRouteOpened, true) @@ -104,6 +117,7 @@ perIP map[string]int maxTotal int maxPerIP int + metrics *observability.Metrics } func newJumpConnectionLimiter(maxTotal, maxPerIP int) *jumpConnectionLimiter { @@ -118,11 +132,18 @@ host := jumpRemoteHost(addr) l.mu.Lock() defer l.mu.Unlock() - if l.total >= l.maxTotal || l.perIP[host] >= l.maxPerIP { + metrics := l.metrics + if l.total >= l.maxTotal { + metrics.RecordJumpRejection("max_total_reached") + return false + } + if l.perIP[host] >= l.maxPerIP { + metrics.RecordJumpRejection("max_per_ip_reached") return false } l.total++ l.perIP[host]++ + metrics.RecordJumpActive(int64(l.total)) return true } @@ -135,6 +156,7 @@ if l.perIP[host] == 0 { delete(l.perIP, host) } + l.metrics.RecordJumpActive(int64(l.total)) } func jumpRemoteHost(addr net.Addr) string { diff --git a/spindle/mill/mill.go b/spindle/mill/mill.go --- a/spindle/mill/mill.go +++ b/spindle/mill/mill.go @@ -13,10 +13,12 @@ "sync" "time" + "go.opentelemetry.io/otel/codes" "tangled.org/core/notifier" "tangled.org/core/spindle/db" "tangled.org/core/spindle/engine" "tangled.org/core/spindle/models" + "tangled.org/core/spindle/observability" "tangled.org/core/spindle/secrets" "tangled.org/core/tid" @@ -58,9 +60,9 @@ l *slog.Logger cfg Config - db *db.DB - n *notifier.Notifier - + db *db.DB + n *notifier.Notifier + metrics *observability.Metrics mu sync.Mutex sessions map[string]*millSession leases map[string]*RemoteLease @@ -170,6 +172,7 @@ } old.close() if old.disconnected { + m.metrics.RecordMillReconnect() m.l.Info("executor reconnected", "node", sess.nodeID) } else { m.l.Warn("replacing silent executor session", "node", sess.nodeID) @@ -345,8 +348,10 @@ max := m.cfg.MaxPending cur := m.pending m.mu.Unlock() + m.metrics.RecordMillPlacementAdmission(false, "max_pending_reached") return nil, fmt.Errorf("%w: mill has %d pending jobs (max %d)", engine.ErrNoWorkflowSlots, cur, max) } + m.metrics.RecordMillPlacementAdmission(true, "allowed") m.pending++ m.mu.Unlock() defer func() { @@ -357,6 +362,11 @@ for { if err := ctx.Err(); err != nil { + result := "cancelled" + if errors.Is(err, context.DeadlineExceeded) { + result = "timeout" + } + m.metrics.RecordMillPlacementResult(result) return nil, err } @@ -366,6 +376,7 @@ lease, err := m.bid(ctx, engineName, wid, wf) if err != nil { + m.metrics.RecordMillPlacementResult("error") return nil, err } if lease != nil { @@ -375,6 +386,7 @@ m.mu.Lock() delete(m.reservations, lease.id) m.mu.Unlock() + m.metrics.RecordMillPlacementResult("error") return nil, fmt.Errorf("persist reserved mill lease: %w", err) } m.mu.Lock() @@ -384,12 +396,18 @@ st.Lease = lease } m.mu.Unlock() + m.metrics.RecordMillPlacementResult("success") return &millSlot{fleet: m, lease: lease}, nil } // no executor available. wait for a change or ctx select { case <-ctx.Done(): + result := "cancelled" + if errors.Is(ctx.Err(), context.DeadlineExceeded) { + result = "timeout" + } + m.metrics.RecordMillPlacementResult(result) return nil, ctx.Err() case <-ch: } @@ -431,6 +449,19 @@ m.mu.Lock() m.reservations[leaseID] = lease m.mu.Unlock() + bidCtx, span := observability.Tracer().Start(bidCtx, "mill.placement.bid") + accepted := false + defer func() { + if accepted { + span.SetStatus(codes.Ok, "accepted") + } else { + span.SetStatus(codes.Error, "placement bid failed") + } + span.End() + }() + + traceparent, tracestate := observability.InjectToTraceparentAndTracestate(bidCtx) + msg := &millproto.Message{ReserveSeat: &millv1.ReserveSeat{ LeaseId: leaseID, TargetEngine: engineName, @@ -439,6 +470,8 @@ Knot: wid.Knot, Rkey: wid.Rkey, TtlSeconds: uint32(m.cfg.ReconnectGrace / time.Second), + Traceparent: traceparent, + Tracestate: tracestate, }} resp, err := sess.request(bidCtx, leaseID, msg) if err != nil { @@ -461,6 +494,7 @@ results <- bidResult{} return } + accepted = true results <- bidResult{sess: sess, lease: lease, rank: rank} } next := 0 @@ -607,21 +641,35 @@ return true } -func (m *Mill) commitAndWait(ctx context.Context, wf *models.Workflow, unlocked []secrets.UnlockedSecret) error { +func (m *Mill) commitAndWait(ctx context.Context, wf *models.Workflow, unlocked []secrets.UnlockedSecret) (err error) { st, ok := wf.Data.(*millWorkflowState) if !ok || st == nil || st.Lease == nil { return fmt.Errorf("mill workflow state missing lease") } lease := st.Lease + ctx, span := observability.Tracer().Start(ctx, "mill.commit") + defer func() { + if err != nil { + span.SetStatus(codes.Error, "commit failed") + } else { + span.SetStatus(codes.Ok, "success") + } + span.End() + }() + pbSecrets := make([]*millv1.Secret, len(unlocked)) for i, s := range unlocked { pbSecrets[i] = &millv1.Secret{Key: s.Key, Value: s.Value} } + traceparent, tracestate := observability.InjectToTraceparentAndTracestate(ctx) + commit := &millproto.Message{CommitLease: &millv1.CommitLease{ - LeaseId: lease.id, - Secrets: pbSecrets, + LeaseId: lease.id, + Secrets: pbSecrets, + Traceparent: traceparent, + Tracestate: tracestate, }} // commit retries ride reconnects, a reservation outlives one @@ -1184,3 +1232,53 @@ } return string(p), string(w), nil } + +func (m *Mill) RegisterMetrics(metrics *observability.Metrics) { + if metrics == nil { + return + } + m.metrics = metrics + metrics.RegisterMillGauges( + func() float64 { + m.mu.Lock() + defer m.mu.Unlock() + return float64(m.pending) + }, + func() float64 { + return float64(m.cfg.MaxPending) + }, + func() float64 { + m.mu.Lock() + defer m.mu.Unlock() + return float64(len(m.leases)) + }, + func() float64 { + m.mu.Lock() + defer m.mu.Unlock() + return float64(len(m.reservations)) + }, + func() float64 { + m.mu.Lock() + defer m.mu.Unlock() + active := 0 + for _, sess := range m.sessions { + if !sess.disconnected { + active++ + } + } + return float64(active) + }, + func() float64 { + m.mu.Lock() + defer m.mu.Unlock() + disconnected := 0 + for _, sess := range m.sessions { + if sess.disconnected { + disconnected++ + } + } + return float64(disconnected) + }, + ) +} + diff --git a/spindle/models/pipeline.go b/spindle/models/pipeline.go --- a/spindle/models/pipeline.go +++ b/spindle/models/pipeline.go @@ -29,4 +29,6 @@ Name string Data any Environment map[string]string + OwnerDID string + RepoDID string } diff --git a/spindle/observability/logging.go b/spindle/observability/logging.go new file mode 100644 --- /dev/null +++ b/spindle/observability/logging.go @@ -0,0 +1,60 @@ +package observability + +import ( + "context" + "fmt" + "log/slog" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp" + "go.opentelemetry.io/otel/log/global" + sdklog "go.opentelemetry.io/otel/sdk/log" + "go.opentelemetry.io/otel/sdk/resource" + corelog "tangled.org/core/log" + "tangled.org/core/spindle/config" +) + +func InitLogging(ctx context.Context, cfg config.Logging) (slog.Handler, func(context.Context) error, error) { + if cfg.Endpoint == "" { + return nil, func(context.Context) error { return nil }, nil + } + + opts := []otlploghttp.Option{ + otlploghttp.WithEndpoint(cfg.Endpoint), + otlploghttp.WithURLPath("/otlp/v1/logs"), + } + if cfg.Insecure { + opts = append(opts, otlploghttp.WithInsecure()) + } + + exporter, err := otlploghttp.New(ctx, opts...) + if err != nil { + return nil, nil, fmt.Errorf("creating OTLP log exporter: %w", err) + } + + res, err := resource.Merge( + resource.Default(), + resource.NewSchemaless(attribute.String("service.name", cfg.ServiceName)), + ) + if err != nil { + return nil, nil, fmt.Errorf("creating logging resource: %w", err) + } + + processor := sdklog.NewBatchProcessor(exporter) + provider := sdklog.NewLoggerProvider( + sdklog.WithProcessor(processor), + sdklog.WithResource(res), + ) + global.SetLoggerProvider(provider) + + otelH := corelog.NewOtelHandler(provider, cfg.ServiceName) + + shutdown := func(shutdownCtx context.Context) error { + if err := provider.Shutdown(shutdownCtx); err != nil { + return fmt.Errorf("shutting down logger provider: %w", err) + } + return nil + } + + return otelH, shutdown, nil +} diff --git a/spindle/observability/logging_test.go b/spindle/observability/logging_test.go new file mode 100644 --- /dev/null +++ b/spindle/observability/logging_test.go @@ -0,0 +1,83 @@ +package observability + +import ( + "context" + "log/slog" + "net/http" + "net/http/httptest" + "sync" + "testing" + "time" + + "tangled.org/core/spindle/config" +) + +func TestInitLoggingDisabled(t *testing.T) { + ctx := context.Background() + cfg := config.Logging{ + Endpoint: "", + } + + handler, shutdown, err := InitLogging(ctx, cfg) + if err != nil { + t.Fatalf("InitLogging returned error: %v", err) + } + if handler != nil { + t.Error("expected handler to be nil when logging is disabled") + } + if shutdown == nil { + t.Error("expected shutdown to be a no-op function, not nil") + } + if err := shutdown(ctx); err != nil { + t.Errorf("no-op shutdown returned error: %v", err) + } +} + +func TestInitLoggingEnabled(t *testing.T) { + var mu sync.Mutex + var logReceived bool + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path == "/otlp/v1/logs" { + mu.Lock() + logReceived = true + mu.Unlock() + w.WriteHeader(http.StatusOK) + } + })) + defer server.Close() + + ctx := context.Background() + endpoint := server.Listener.Addr().String() + + cfg := config.Logging{ + Endpoint: endpoint, + ServiceName: "spindle-test-service", + Insecure: true, + } + + handler, shutdown, err := InitLogging(ctx, cfg) + if err != nil { + t.Fatalf("InitLogging returned error: %v", err) + } + if handler == nil { + t.Fatal("expected handler to be non-nil when logging is enabled") + } + + logger := slog.New(handler) + logger.Info("hello from test log exporter") + + shutdownCtx, cancel := context.WithTimeout(context.Background(), 2*time.Second) + defer cancel() + if err := shutdown(shutdownCtx); err != nil { + t.Errorf("shutdown returned error: %v", err) + } + + mu.Lock() + received := logReceived + mu.Unlock() + + if !received { + t.Error("expected mock collector to receive the log request on /otlp/v1/logs") + } +} diff --git a/spindle/observability/metrics.go b/spindle/observability/metrics.go new file mode 100644 --- /dev/null +++ b/spindle/observability/metrics.go @@ -0,0 +1,1153 @@ +package observability + +import ( + "context" + "fmt" + "github.com/felixge/httpsnoop" + "github.com/go-chi/chi/v5" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/collectors" + "github.com/prometheus/client_golang/prometheus/promhttp" + "go.opentelemetry.io/otel/trace" + "log/slog" + "net" + "net/http" + "sync" + "tangled.org/core/spindle/db" + "time" +) + +type contextKey struct{} + +func WithMetrics(ctx context.Context, m *Metrics) context.Context { + return context.WithValue(ctx, contextKey{}, m) +} + +func GetMetrics(ctx context.Context) *Metrics { + if ctx == nil { + return nil + } + m, _ := ctx.Value(contextKey{}).(*Metrics) + return m +} + +type QuotaUsage struct { + Scope string + Resource string + Used float64 +} + +type QuotaSubjectCount struct { + Scope string + Resource string + Status string + Count int64 +} + +type QuotaSnapshot struct { + Usage []QuotaUsage + Subjects []QuotaSubjectCount +} + +type QuotaProvider func() QuotaSnapshot + +type quotaCollector struct { + m *Metrics + usageDesc *prometheus.Desc + subjectsDesc *prometheus.Desc +} + +func (c *quotaCollector) Describe(ch chan<- *prometheus.Desc) { + ch <- c.usageDesc + ch <- c.subjectsDesc +} + +func (c *quotaCollector) Collect(ch chan<- prometheus.Metric) { + if c.m == nil || c.m.quotaProvider == nil { + return + } + snap := c.m.quotaProvider() + + usage := make(map[[2]string]float64, len(snap.Usage)) + for _, u := range snap.Usage { + scope, ok := quotaScope(u.Scope) + if !ok { + continue + } + resource, ok := quotaResource(u.Resource) + if !ok { + continue + } + usage[[2]string{scope, resource}] += u.Used + } + for key, used := range usage { + ch <- prometheus.MustNewConstMetric(c.usageDesc, prometheus.GaugeValue, used, key[0], key[1]) + } + + subjects := make(map[[3]string]int64, len(snap.Subjects)) + for _, s := range snap.Subjects { + scope, ok := quotaScope(s.Scope) + if !ok { + continue + } + resource, ok := quotaResource(s.Resource) + if !ok { + continue + } + status, ok := quotaStatus(s.Status) + if !ok { + continue + } + subjects[[3]string{scope, resource, status}] += s.Count + } + for key, count := range subjects { + ch <- prometheus.MustNewConstMetric(c.subjectsDesc, prometheus.GaugeValue, float64(count), key[0], key[1], key[2]) + } +} + +type Metrics struct { + reg *prometheus.Registry + + httpRequests *prometheus.CounterVec + httpRequestDuration *prometheus.HistogramVec + httpInFlight prometheus.Gauge + + eventIngestion *prometheus.CounterVec + + jobQueueActivity *prometheus.CounterVec + + workflowsActive *prometheus.GaugeVec + workflowsTotal *prometheus.CounterVec + workflowDuration *prometheus.HistogramVec + + stepsActive *prometheus.GaugeVec + stepsTotal *prometheus.CounterVec + stepDuration *prometheus.HistogramVec + + poolMemory *prometheus.GaugeVec + poolVCPUs *prometheus.GaugeVec + poolDisk *prometheus.GaugeVec + poolQueueDepth prometheus.Gauge + poolAdmission *prometheus.CounterVec + + millPlacementAdmission *prometheus.CounterVec + millPlacementResults *prometheus.CounterVec + millReconnects prometheus.Counter + + jumpActive prometheus.Gauge + jumpMax prometheus.Gauge + jumpRejections *prometheus.CounterVec + + cacheUploads *prometheus.CounterVec + cacheUploadBytes *prometheus.CounterVec + + quotaDecisions *prometheus.CounterVec + quotaDefaultLimit *prometheus.GaugeVec + quotaWaitDepth *prometheus.GaugeVec + quotaWaitTime *prometheus.HistogramVec + quotaProvider QuotaProvider + clock clock + collectionFailures prometheus.Counter +} + +func NewMetrics() *Metrics { + return newMetricsWithClock(realClock{}) +} + +func newMetricsWithClock(clock clock) *Metrics { + reg := prometheus.NewRegistry() + reg.MustRegister( + collectors.NewGoCollector(), + collectors.NewProcessCollector(collectors.ProcessCollectorOpts{}), + collectors.NewBuildInfoCollector(), + ) + + m := &Metrics{ + reg: reg, + clock: clock, + + httpRequests: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_http_requests_total", + Help: "Total count of HTTP requests.", + }, []string{"method", "route", "status_code", "status_class"}), + + httpRequestDuration: prometheus.NewHistogramVec(prometheus.HistogramOpts{ + Name: "spindle_http_request_duration_seconds", + Help: "Duration of HTTP requests in seconds.", + Buckets: prometheus.DefBuckets, + }, []string{"method", "route", "status_code", "status_class"}), + + httpInFlight: prometheus.NewGauge(prometheus.GaugeOpts{ + Name: "spindle_http_requests_in_flight", + Help: "Current number of in-flight HTTP requests.", + }), + + eventIngestion: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_event_ingestion_outcomes_total", + Help: "Total number of ingested events by consumer and outcome status.", + }, []string{"consumer", "status"}), + + jobQueueActivity: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_job_queue_activity_total", + Help: "Total count of job queue operations.", + }, []string{"action"}), + + workflowsActive: prometheus.NewGaugeVec(prometheus.GaugeOpts{ + Name: "spindle_workflows_active", + Help: "Current number of active workflows by engine.", + }, []string{"engine"}), + + workflowsTotal: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_workflows_total", + Help: "Total number of completed workflows by engine and result.", + }, []string{"engine", "result"}), + + workflowDuration: prometheus.NewHistogramVec(prometheus.HistogramOpts{ + Name: "spindle_workflow_duration_seconds", + Help: "Duration of completed workflows by engine and result.", + Buckets: prometheus.DefBuckets, + }, []string{"engine", "result"}), + + stepsActive: prometheus.NewGaugeVec(prometheus.GaugeOpts{ + Name: "spindle_steps_active", + Help: "Current number of active steps by engine.", + }, []string{"engine"}), + + stepsTotal: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_steps_total", + Help: "Total number of completed steps by engine and status.", + }, []string{"engine", "status"}), + + stepDuration: prometheus.NewHistogramVec(prometheus.HistogramOpts{ + Name: "spindle_step_duration_seconds", + Help: "Duration of completed steps by engine and status.", + Buckets: prometheus.DefBuckets, + }, []string{"engine", "status"}), + + poolMemory: prometheus.NewGaugeVec(prometheus.GaugeOpts{ + Name: "spindle_engine_pool_memory_mib", + Help: "Local engine memory pool in MiB by state.", + }, []string{"state"}), + + poolVCPUs: prometheus.NewGaugeVec(prometheus.GaugeOpts{ + Name: "spindle_engine_pool_vcpus", + Help: "Local engine vCPU pool by state.", + }, []string{"state"}), + + poolDisk: prometheus.NewGaugeVec(prometheus.GaugeOpts{ + Name: "spindle_engine_pool_disk_mib", + Help: "Local engine disk pool in MiB by state.", + }, []string{"state"}), + + poolQueueDepth: prometheus.NewGauge(prometheus.GaugeOpts{ + Name: "spindle_engine_pool_queue_depth", + Help: "Current local engine resource scheduler queue depth.", + }), + + poolAdmission: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_engine_pool_admission_total", + Help: "Total count of local engine resource scheduler admissions, host capacity only.", + }, []string{"decision", "reason"}), + + millPlacementAdmission: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_mill_placement_admission_total", + Help: "Total count of mill placement admissions.", + }, []string{"status", "reason"}), + + millPlacementResults: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_mill_placement_results_total", + Help: "Total count of mill placement results.", + }, []string{"result"}), + + millReconnects: prometheus.NewCounter(prometheus.CounterOpts{ + Name: "spindle_mill_reconnects_total", + Help: "Total number of executor reconnects to the mill.", + }), + + jumpActive: prometheus.NewGauge(prometheus.GaugeOpts{ + Name: "spindle_jump_active_connections", + Help: "Current number of active debug jump connections.", + }), + + jumpMax: prometheus.NewGauge(prometheus.GaugeOpts{ + Name: "spindle_jump_max_connections", + Help: "Maximum number of debug jump connections allowed.", + }), + + jumpRejections: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_jump_rejections_total", + Help: "Total count of rejected debug jump connections.", + }, []string{"reason"}), + + cacheUploads: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_cache_uploads_total", + Help: "Total count of cache uploads.", + }, []string{"backend", "result"}), + + cacheUploadBytes: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_cache_upload_bytes_total", + Help: "Total bytes of cache uploads.", + }, []string{"backend", "result"}), + + quotaDecisions: prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "spindle_quota_decisions_total", + Help: "Total count of quota admission decisions by kind, resource, decision and reason.", + }, []string{"kind", "resource", "decision", "reason"}), + + quotaDefaultLimit: prometheus.NewGaugeVec(prometheus.GaugeOpts{ + Name: "spindle_quota_default_limit", + Help: "Configured default quota limit by scope and resource, in each resource's own unit. Zero means unlimited.", + }, []string{"scope", "resource"}), + + quotaWaitDepth: prometheus.NewGaugeVec(prometheus.GaugeOpts{ + Name: "spindle_quota_wait_depth", + Help: "Current number of requests waiting for quota by kind.", + }, []string{"kind"}), + + quotaWaitTime: prometheus.NewHistogramVec(prometheus.HistogramOpts{ + Name: "spindle_quota_wait_duration_seconds", + Help: "Time spent waiting for quota before a grant, by kind and the resource that was short.", + Buckets: prometheus.ExponentialBuckets(0.1, 3, 8), + }, []string{"kind", "resource"}), + collectionFailures: prometheus.NewCounter(prometheus.CounterOpts{ + Name: "spindle_collection_failures_total", + Help: "Total number of metric collection failures.", + }), + } + + reg.MustRegister( + m.httpRequests, + m.httpRequestDuration, + m.httpInFlight, + m.eventIngestion, + m.jobQueueActivity, + m.workflowsActive, + m.workflowsTotal, + m.workflowDuration, + m.stepsActive, + m.stepsTotal, + m.stepDuration, + m.poolMemory, + m.poolVCPUs, + m.poolDisk, + m.poolQueueDepth, + m.poolAdmission, + m.millPlacementAdmission, + m.millPlacementResults, + m.millReconnects, + m.jumpActive, + m.jumpMax, + m.jumpRejections, + m.cacheUploads, + m.cacheUploadBytes, + m.quotaDecisions, + m.quotaDefaultLimit, + m.quotaWaitDepth, + m.quotaWaitTime, + m.collectionFailures, + ) + + reg.MustRegister("aCollector{ + m: m, + usageDesc: prometheus.NewDesc( + "spindle_quota_usage", + "Current committed quota usage by scope and resource, in each resource's own unit.", + []string{"scope", "resource"}, nil, + ), + subjectsDesc: prometheus.NewDesc( + "spindle_quota_subjects", + "Current count of quota subjects by scope, resource and status.", + []string{"scope", "resource", "status"}, nil, + ), + }) + + return m +} + +func boundBackend(backend string) string { + switch backend { + case "http", "nix_store": + return backend + default: + return "unknown" + } +} + +func boundResult(result string) string { + switch result { + case "published", "quota_skipped", "failed": + return result + default: + return "unknown" + } +} + +// keep unbounded input out of metric labels +func quotaScope(scope string) (string, bool) { + switch scope { + case "user", "repo": + return scope, true + default: + return "unknown", false + } +} + +func quotaResource(resource string) (string, bool) { + switch resource { + case "cache_storage_bytes", "workflows", "vcpus", "memory_mib", "disk_mib": + return resource, true + default: + return "unknown", false + } +} + +func quotaStatus(status string) (string, bool) { + switch status { + case "unlimited", "under_limit", "near_limit", "at_limit", "over_limit": + return status, true + default: + return "unknown", false + } +} + +func quotaKind(kind string) (string, bool) { + switch kind { + case "workflow", "nix_cache", "generic_cache": + return kind, true + default: + return "unknown", false + } +} + +func quotaReason(reason string) (string, bool) { + switch reason { + case "allowed_immediately", "allowed_from_queue", "unlimited", "within_limit", + "user_limit", "repo_limit", "queued", "no_wait_slot_unavailable", + "context_done_in_queue", "context_done_after_ready", "store_error": + return reason, true + default: + return "unknown", false + } +} + +func enginePoolReason(reason string) (string, bool) { + switch reason { + case "allowed_immediately", "allowed_from_queue", "request_exceeds_budget", + "request_exceeds_max", "no_wait_slot_unavailable", "context_done_in_queue", + "context_done_after_ready": + return reason, true + default: + return "unknown", false + } +} + +func quotaDecision(allowed, temporary bool) string { + switch { + case allowed: + return "allowed" + case temporary: + return "deferred" + default: + return "rejected" + } +} + +func (m *Metrics) RecordCacheUpload(backend, result string) { + if m == nil { + return + } + backend = boundBackend(backend) + result = boundResult(result) + m.cacheUploads.WithLabelValues(backend, result).Inc() +} + +func (m *Metrics) RecordCacheUploadBytes(backend, result string, bytes int64) { + if m == nil || bytes < 0 { + return + } + backend = boundBackend(backend) + result = boundResult(result) + m.cacheUploadBytes.WithLabelValues(backend, result).Add(float64(bytes)) +} + +func (m *Metrics) RecordQuotaDecision(kind, resource string, allowed, temporary bool, reason string) { + if m == nil { + return + } + kind, _ = quotaKind(kind) + resource, _ = quotaResource(resource) + reason, _ = quotaReason(reason) + m.quotaDecisions.WithLabelValues(kind, resource, quotaDecision(allowed, temporary), reason).Inc() +} + +func (m *Metrics) SetQuotaWaitDepth(kind string, depth int64) { + if m == nil { + return + } + kind, _ = quotaKind(kind) + m.quotaWaitDepth.WithLabelValues(kind).Set(float64(depth)) +} + +func (m *Metrics) RecordQuotaWait(kind, resource string, d time.Duration) { + if m == nil || d < 0 { + return + } + kind, _ = quotaKind(kind) + resource, _ = quotaResource(resource) + m.quotaWaitTime.WithLabelValues(kind, resource).Observe(d.Seconds()) +} + +type clock interface { + Now() time.Time +} + +type realClock struct{} + +func (realClock) Now() time.Time { + return time.Now() +} + +type QuotaLoader func() (QuotaSnapshot, error) + +type cachedQuotaProvider struct { + mu sync.Mutex + loader QuotaLoader + clock clock + ttl time.Duration + lastSnap QuotaSnapshot + expiry time.Time + hasLast bool + onError func() +} + +func newCachedQuotaProvider(loader QuotaLoader, clock clock, ttl time.Duration) *cachedQuotaProvider { + return &cachedQuotaProvider{ + loader: loader, + clock: clock, + ttl: ttl, + } +} + +func cloneSnapshot(snap QuotaSnapshot) QuotaSnapshot { + var out QuotaSnapshot + if snap.Usage != nil { + out.Usage = make([]QuotaUsage, len(snap.Usage)) + copy(out.Usage, snap.Usage) + } + if snap.Subjects != nil { + out.Subjects = make([]QuotaSubjectCount, len(snap.Subjects)) + copy(out.Subjects, snap.Subjects) + } + return out +} + +func (c *cachedQuotaProvider) Get() QuotaSnapshot { + c.mu.Lock() + defer c.mu.Unlock() + + now := c.clock.Now() + if now.Before(c.expiry) { + if c.hasLast { + return cloneSnapshot(c.lastSnap) + } + return QuotaSnapshot{} + } + + snap, err := c.loader() + c.expiry = now.Add(c.ttl) + if err != nil { + if c.onError != nil { + c.onError() + } + slog.Error("failed to collect quota metrics snapshot", "err", err) + if c.hasLast { + return cloneSnapshot(c.lastSnap) + } + return QuotaSnapshot{} + } + c.lastSnap = cloneSnapshot(snap) + c.hasLast = true + return cloneSnapshot(c.lastSnap) +} + +func (m *Metrics) SetQuotaLoader(loader QuotaLoader) { + if m == nil { + return + } + if loader == nil { + m.quotaProvider = nil + return + } + cache := newCachedQuotaProvider(loader, m.clock, 1*time.Minute) + m.quotaProvider = cache.Get + cache.onError = m.collectionFailures.Inc +} + +func (m *Metrics) SetQuotaProvider(provider QuotaProvider) { + if m == nil { + return + } + if provider == nil { + m.quotaProvider = nil + return + } + m.SetQuotaLoader(func() (QuotaSnapshot, error) { + return provider(), nil + }) +} + +type QuotaObserver struct { + m *Metrics +} + +func (m *Metrics) QuotaObserver() *QuotaObserver { + return &QuotaObserver{m: m} +} + +func (o *QuotaObserver) RecordDecision(kind, resource string, allowed, temporary bool, reason string) { + o.m.RecordQuotaDecision(kind, resource, allowed, temporary, reason) +} + +func (o *QuotaObserver) SetWaitDepth(kind string, depth int64) { + o.m.SetQuotaWaitDepth(kind, depth) +} + +func (o *QuotaObserver) RecordWait(kind, resource string, d time.Duration) { + o.m.RecordQuotaWait(kind, resource, d) +} + +func (m *Metrics) Registry() *prometheus.Registry { + if m == nil { + return nil + } + return m.reg +} + +func (m *Metrics) RecordEventIngestion(consumer, status string) { + if m == nil { + return + } + m.eventIngestion.WithLabelValues(consumer, status).Inc() +} + +func (m *Metrics) RecordJobQueueActivity(action string) { + if m == nil { + return + } + m.jobQueueActivity.WithLabelValues(action).Inc() +} + +func (m *Metrics) SetQuotaDefaultLimit(scope, resource string, limit int64) { + if m == nil { + return + } + boundedScope, scopeOK := quotaScope(scope) + boundedResource, resourceOK := quotaResource(resource) + if !scopeOK || !resourceOK { + return + } + m.quotaDefaultLimit.WithLabelValues(boundedScope, boundedResource).Set(float64(limit)) +} + +func (m *Metrics) RecordWorkflowStart(engine string) { + if m == nil { + return + } + m.workflowsActive.WithLabelValues(engine).Inc() +} + +func observeWithExemplar(ctx context.Context, observer prometheus.Observer, val float64) { + spanContext := trace.SpanContextFromContext(ctx) + if spanContext.IsValid() && spanContext.IsSampled() { + if exemplarObserver, ok := observer.(prometheus.ExemplarObserver); ok { + exemplarObserver.ObserveWithExemplar( + val, + prometheus.Labels{"traceID": spanContext.TraceID().String()}, + ) + return + } + } + observer.Observe(val) +} + +func (m *Metrics) RecordWorkflowEnd(ctx context.Context, engine, result string, duration time.Duration) { + if m == nil { + return + } + m.workflowsActive.WithLabelValues(engine).Dec() + m.workflowsTotal.WithLabelValues(engine, result).Inc() + observer := m.workflowDuration.WithLabelValues(engine, result) + observeWithExemplar(ctx, observer, duration.Seconds()) +} + +func (m *Metrics) RecordStepStart(engine string) { + if m == nil { + return + } + m.stepsActive.WithLabelValues(engine).Inc() +} + +func (m *Metrics) RecordStepEnd(ctx context.Context, engine, status string, duration time.Duration) { + if m == nil { + return + } + m.stepsActive.WithLabelValues(engine).Dec() + m.stepsTotal.WithLabelValues(engine, status).Inc() + observer := m.stepDuration.WithLabelValues(engine, status) + observeWithExemplar(ctx, observer, duration.Seconds()) +} + +func (m *Metrics) RecordEnginePoolSnapshot( + usedMem, budgetMem, maxMem int64, + usedCPU, budgetCPU, maxCPU int64, + usedDisk, budgetDisk, maxDisk int64, + queueDepth int, +) { + if m == nil { + return + } + m.poolMemory.WithLabelValues("used").Set(float64(usedMem)) + m.poolMemory.WithLabelValues("limit").Set(float64(budgetMem)) + m.poolMemory.WithLabelValues("max_request").Set(float64(maxMem)) + + m.poolVCPUs.WithLabelValues("used").Set(float64(usedCPU)) + m.poolVCPUs.WithLabelValues("limit").Set(float64(budgetCPU)) + m.poolVCPUs.WithLabelValues("max_request").Set(float64(maxCPU)) + + m.poolDisk.WithLabelValues("used").Set(float64(usedDisk)) + m.poolDisk.WithLabelValues("limit").Set(float64(budgetDisk)) + m.poolDisk.WithLabelValues("max_request").Set(float64(maxDisk)) + + m.poolQueueDepth.Set(float64(queueDepth)) +} + +func (m *Metrics) RecordEnginePoolAdmission(allowed bool, reason string) { + if m == nil { + return + } + decision := "rejected" + if allowed { + decision = "allowed" + } + reason, _ = enginePoolReason(reason) + m.poolAdmission.WithLabelValues(decision, reason).Inc() +} + +func (m *Metrics) RegisterMillGauges( + pending, maxPending, leases, reservations, activeSessions, disconnectedSessions func() float64, +) { + if m == nil { + return + } + m.reg.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{ + Name: "spindle_mill_pending_jobs", + Help: "Current number of pending mill jobs.", + }, pending)) + m.reg.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{ + Name: "spindle_mill_max_pending_jobs", + Help: "Maximum number of pending mill jobs allowed.", + }, maxPending)) + m.reg.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{ + Name: "spindle_mill_leases_active", + Help: "Current number of active leases on the mill.", + }, leases)) + m.reg.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{ + Name: "spindle_mill_reservations_active", + Help: "Current number of seat reservations on the mill.", + }, reservations)) + m.reg.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{ + Name: "spindle_mill_active_sessions", + Help: "Current number of active executor sessions.", + }, activeSessions)) + m.reg.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{ + Name: "spindle_mill_disconnected_sessions", + Help: "Current number of disconnected executor sessions.", + }, disconnectedSessions)) +} + +func (m *Metrics) RecordMillPlacementAdmission(allowed bool, reason string) { + if m == nil { + return + } + status := "rejected" + if allowed { + status = "allowed" + } + m.millPlacementAdmission.WithLabelValues(status, reason).Inc() +} + +func (m *Metrics) RecordMillPlacementResult(result string) { + if m == nil { + return + } + m.millPlacementResults.WithLabelValues(result).Inc() +} + +func (m *Metrics) RecordMillReconnect() { + if m == nil { + return + } + m.millReconnects.Inc() +} + +func (m *Metrics) RegisterExecutorGauges(reservations, jobs, outboxBytes func() float64) { + if m == nil { + return + } + m.reg.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{ + Name: "spindle_executor_reservations_active", + Help: "Current number of seat reservations on the executor.", + }, reservations)) + m.reg.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{ + Name: "spindle_executor_jobs_active", + Help: "Current number of active jobs on the executor.", + }, jobs)) + m.reg.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{ + Name: "spindle_executor_outbox_bytes", + Help: "Current outbox size in bytes.", + }, outboxBytes)) +} + +func (m *Metrics) RecordJumpRejection(reason string) { + if m == nil { + return + } + m.jumpRejections.WithLabelValues(reason).Inc() +} + +func (m *Metrics) RecordJumpActive(total int64) { + if m == nil { + return + } + m.jumpActive.Set(float64(total)) +} + +func (m *Metrics) RecordJumpLimit(limit int64) { + if m == nil { + return + } + m.jumpMax.Set(float64(limit)) +} + +type dbCollector struct { + db *db.DB + queuedJobsDesc *prometheus.Desc + workflowStatusDesc *prometheus.Desc + collectionFailures prometheus.Counter + mu sync.RWMutex + queuedJobs int + hasQueuedJobs bool + workflowStatus map[string]int + + maxOpenDesc *prometheus.Desc + openDesc *prometheus.Desc + inUseDesc *prometheus.Desc + idleDesc *prometheus.Desc + waitCountDesc *prometheus.Desc + waitDurationDesc *prometheus.Desc + maxIdleClosedDesc *prometheus.Desc + maxLifetimeClosedDesc *prometheus.Desc +} + +func (c *dbCollector) Describe(ch chan<- *prometheus.Desc) { + ch <- c.queuedJobsDesc + ch <- c.workflowStatusDesc + ch <- c.maxOpenDesc + ch <- c.openDesc + ch <- c.inUseDesc + ch <- c.idleDesc + ch <- c.waitCountDesc + ch <- c.waitDurationDesc + ch <- c.maxIdleClosedDesc + ch <- c.maxLifetimeClosedDesc +} + +func (c *dbCollector) refresh(ctx context.Context) { + var queuedJobs int + if err := c.db.QueryRowContext(ctx, `SELECT COUNT(*) FROM jobs`).Scan(&queuedJobs); err != nil { + c.collectionFailures.Inc() + } else { + c.mu.Lock() + c.queuedJobs = queuedJobs + c.hasQueuedJobs = true + c.mu.Unlock() + } + + rows, err := c.db.QueryContext(ctx, ` + WITH latest AS ( + SELECT + json_extract(event, '$.status') AS status, + row_number() OVER ( + PARTITION BY + json_extract(event, '$.pipeline'), + json_extract(event, '$.workflow') + ORDER BY created DESC, rowid DESC + ) AS rank + FROM events + WHERE nsid = 'sh.tangled.pipeline.status' + ) + SELECT + CASE status + WHEN 'pending' THEN status + WHEN 'running' THEN status + WHEN 'failed' THEN status + WHEN 'timeout' THEN status + WHEN 'cancelled' THEN status + WHEN 'success' THEN status + ELSE 'unknown' + END AS bounded_status, + COUNT(*) + FROM latest + WHERE rank = 1 + GROUP BY bounded_status + `) + if err != nil { + c.collectionFailures.Inc() + return + } + defer rows.Close() + + statuses := make(map[string]int) + for rows.Next() { + var status string + var count int + if err := rows.Scan(&status, &count); err != nil { + c.collectionFailures.Inc() + return + } + statuses[boundWorkflowStatus(status)] = count + } + if err := rows.Err(); err != nil { + c.collectionFailures.Inc() + return + } + c.mu.Lock() + c.workflowStatus = statuses + c.mu.Unlock() +} + +func (c *dbCollector) run(ctx context.Context) { + c.refresh(ctx) + ticker := time.NewTicker(time.Minute) + defer ticker.Stop() + for { + select { + case <-ctx.Done(): + return + case <-ticker.C: + c.refresh(ctx) + } + } +} + +func (c *dbCollector) Collect(ch chan<- prometheus.Metric) { + if c.db == nil { + return + } + stats := c.db.Stats() + + ch <- prometheus.MustNewConstMetric(c.maxOpenDesc, prometheus.GaugeValue, float64(stats.MaxOpenConnections)) + ch <- prometheus.MustNewConstMetric(c.openDesc, prometheus.GaugeValue, float64(stats.OpenConnections)) + ch <- prometheus.MustNewConstMetric(c.inUseDesc, prometheus.GaugeValue, float64(stats.InUse)) + ch <- prometheus.MustNewConstMetric(c.idleDesc, prometheus.GaugeValue, float64(stats.Idle)) + ch <- prometheus.MustNewConstMetric(c.waitCountDesc, prometheus.CounterValue, float64(stats.WaitCount)) + ch <- prometheus.MustNewConstMetric(c.waitDurationDesc, prometheus.CounterValue, stats.WaitDuration.Seconds()) + ch <- prometheus.MustNewConstMetric(c.maxIdleClosedDesc, prometheus.CounterValue, float64(stats.MaxIdleClosed)) + ch <- prometheus.MustNewConstMetric(c.maxLifetimeClosedDesc, prometheus.CounterValue, float64(stats.MaxLifetimeClosed)) + + c.mu.RLock() + queuedJobs := c.queuedJobs + hasQueuedJobs := c.hasQueuedJobs + statuses := make(map[string]int, len(c.workflowStatus)) + for status, count := range c.workflowStatus { + statuses[status] = count + } + c.mu.RUnlock() + + if hasQueuedJobs { + ch <- prometheus.MustNewConstMetric(c.queuedJobsDesc, prometheus.GaugeValue, float64(queuedJobs)) + } + for status, count := range statuses { + ch <- prometheus.MustNewConstMetric(c.workflowStatusDesc, prometheus.GaugeValue, float64(count), status) + } +} + +func (m *Metrics) AttachDB(ctx context.Context, database *db.DB) { + if m == nil || database == nil { + return + } + coll := &dbCollector{ + db: database, + collectionFailures: m.collectionFailures, + queuedJobsDesc: prometheus.NewDesc( + "spindle_db_queued_jobs", + "Current number of queued jobs in database.", + nil, nil, + ), + workflowStatusDesc: prometheus.NewDesc( + "spindle_db_workflow_status_count", + "Current count of workflows in the database by status.", + []string{"status"}, nil, + ), + maxOpenDesc: prometheus.NewDesc( + "spindle_db_max_open_connections", + "Maximum number of open connections to the database.", + nil, nil, + ), + openDesc: prometheus.NewDesc( + "spindle_db_open_connections", + "The number of established connections both in use and idle.", + nil, nil, + ), + inUseDesc: prometheus.NewDesc( + "spindle_db_in_use_connections", + "The number of connections currently in use.", + nil, nil, + ), + idleDesc: prometheus.NewDesc( + "spindle_db_idle_connections", + "The number of idle connections.", + nil, nil, + ), + waitCountDesc: prometheus.NewDesc( + "spindle_db_wait_count", + "The total number of connections waited for.", + nil, nil, + ), + waitDurationDesc: prometheus.NewDesc( + "spindle_db_wait_duration_seconds", + "The total time blocked waiting for a connection.", + nil, nil, + ), + maxIdleClosedDesc: prometheus.NewDesc( + "spindle_db_max_idle_closed", + "The total number of connections closed due to SetMaxIdleConns.", + nil, nil, + ), + maxLifetimeClosedDesc: prometheus.NewDesc( + "spindle_db_max_lifetime_closed", + "The total number of connections closed due to SetConnMaxLifetime.", + nil, nil, + ), + workflowStatus: make(map[string]int), + } + m.reg.MustRegister(coll) + go coll.run(ctx) +} + +func StartMetricsServer(ctx context.Context, addr string, logger *slog.Logger, reg *prometheus.Registry) (*http.Server, error) { + if addr == "" { + return nil, nil + } + + ln, err := net.Listen("tcp", addr) + if err != nil { + return nil, fmt.Errorf("failed to bind metrics port %s: %w", addr, err) + } + + mux := http.NewServeMux() + mux.Handle("/metrics", promhttp.HandlerFor(reg, promhttp.HandlerOpts{EnableOpenMetrics: true})) + + srv := &http.Server{ + Addr: ln.Addr().String(), + Handler: mux, + ReadHeaderTimeout: 5 * time.Second, + } + + logger.Info("starting dedicated metrics listener", "address", srv.Addr) + + go func() { + if err := srv.Serve(ln); err != nil && err != http.ErrServerClosed { + logger.Error("metrics server error", "err", err) + } + }() + + go func() { + <-ctx.Done() + shutdownCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + _ = srv.Shutdown(shutdownCtx) + }() + + return srv, nil +} + +func boundMethod(m string) string { + switch m { + case "GET", "POST", "PUT", "DELETE", "PATCH", "HEAD", "OPTIONS": + return m + default: + return "UNKNOWN" + } +} + +func boundStatusCode(code int) string { + if code >= 100 && code < 600 { + return fmt.Sprintf("%d", code) + } + return "unknown" +} + +func getStatusClass(code int) string { + if code >= 100 && code < 200 { + return "1xx" + } else if code >= 200 && code < 300 { + return "2xx" + } else if code >= 300 && code < 400 { + return "3xx" + } else if code >= 400 && code < 500 { + return "4xx" + } else if code >= 500 && code < 600 { + return "5xx" + } + return "unknown" +} + +func boundWorkflowStatus(status string) string { + switch status { + case "pending", "running", "failed", "timeout", "cancelled", "success": + return status + default: + return "unknown" + } +} + +type recordedKey struct{} + +func HTTPMiddleware(m *Metrics) func(http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if m == nil { + next.ServeHTTP(w, r) + return + } + if r.Context().Value(recordedKey{}) != nil { + next.ServeHTTP(w, r) + return + } + r = r.WithContext(context.WithValue(r.Context(), recordedKey{}, true)) + + m.httpInFlight.Inc() + defer m.httpInFlight.Dec() + + captured := httpsnoop.CaptureMetrics(next, w, r) + + var route string + rctx := chi.RouteContext(r.Context()) + if rctx != nil { + route = rctx.RoutePattern() + } + if route == "" { + route = "unknown" + } + + method := boundMethod(r.Method) + statusCode := boundStatusCode(captured.Code) + statusClass := getStatusClass(captured.Code) + + m.httpRequests.WithLabelValues(method, route, statusCode, statusClass).Inc() + observer := m.httpRequestDuration.WithLabelValues(method, route, statusCode, statusClass) + observeWithExemplar(r.Context(), observer, captured.Duration.Seconds()) + }) + } +} diff --git a/spindle/observability/metrics_test.go b/spindle/observability/metrics_test.go new file mode 100644 --- /dev/null +++ b/spindle/observability/metrics_test.go @@ -0,0 +1,788 @@ +package observability + +import ( + "context" + "encoding/json" + "errors" + "net/http" + "net/http/httptest" + "os" + "regexp" + "strings" + "sync" + "sync/atomic" + "testing" + "time" + + "github.com/go-chi/chi/v5" + dto "github.com/prometheus/client_model/go" + "go.opentelemetry.io/otel" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" +) + +var forbiddenLabelValues = []string{ + "did:plc:123", + "did:web:alice", + "did:web:alice/repo1", + "res-abc", + "sha256:deadbeef", + "dial tcp 10.0.0.1:5432: connection refused", + "arbitrary", + "invalid_status", + "gpu_seconds", +} + +func gather(t *testing.T, m *Metrics) map[string]*dto.MetricFamily { + t.Helper() + families, err := m.Registry().Gather() + if err != nil { + t.Fatalf("gather: %v", err) + } + byName := make(map[string]*dto.MetricFamily, len(families)) + for _, f := range families { + byName[f.GetName()] = f + } + return byName +} + +func labelKeys(metric *dto.Metric) []string { + keys := make([]string, 0, len(metric.GetLabel())) + for _, lp := range metric.GetLabel() { + keys = append(keys, lp.GetName()) + } + return keys +} + +func labelValue(metric *dto.Metric, name string) string { + for _, lp := range metric.GetLabel() { + if lp.GetName() == name { + return lp.GetValue() + } + } + return "" +} + +func TestQuotaMetricsAreBounded(t *testing.T) { + m := NewMetrics() + if m == nil { + t.Fatal("failed to create metrics") + } + + m.SetQuotaProvider(func() QuotaSnapshot { + return QuotaSnapshot{ + Usage: []QuotaUsage{ + {Scope: "user", Resource: "cache_storage_bytes", Used: 5000}, + {Scope: "repo", Resource: "cache_storage_bytes", Used: 2000}, + {Scope: "user", Resource: "workflows", Used: 3}, + {Scope: "user", Resource: "vcpus", Used: 8}, + {Scope: "repo", Resource: "memory_mib", Used: 4096}, + {Scope: "repo", Resource: "disk_mib", Used: 20480}, + {Scope: "user", Resource: "workflows", Used: 2}, + {Scope: "did:plc:123", Resource: "cache_storage_bytes", Used: 9999}, + {Scope: "did:web:alice/repo1", Resource: "workflows", Used: 7}, + {Scope: "user", Resource: "gpu_seconds", Used: 1234}, + }, + Subjects: []QuotaSubjectCount{ + {Scope: "user", Resource: "cache_storage_bytes", Status: "under_limit", Count: 2}, + {Scope: "user", Resource: "cache_storage_bytes", Status: "at_limit", Count: 1}, + {Scope: "repo", Resource: "cache_storage_bytes", Status: "unlimited", Count: 5}, + {Scope: "user", Resource: "workflows", Status: "near_limit", Count: 1}, + {Scope: "repo", Resource: "memory_mib", Status: "over_limit", Count: 1}, + {Scope: "user", Resource: "cache_storage_bytes", Status: "invalid_status", Count: 42}, + {Scope: "did:plc:123", Resource: "cache_storage_bytes", Status: "under_limit", Count: 10}, + {Scope: "user", Resource: "gpu_seconds", Status: "under_limit", Count: 3}, + }, + } + }) + m.SetQuotaDefaultLimit("user", "workflows", 4) + m.SetQuotaDefaultLimit("did:web:alice", "gpu_seconds", 99) + + m.RecordQuotaDecision("nix_cache", "cache_storage_bytes", true, false, "within_limit") + m.RecordQuotaDecision("nix_cache", "cache_storage_bytes", false, false, "repo_limit") + m.RecordQuotaDecision("workflow", "workflows", false, true, "queued") + m.RecordQuotaDecision("workflow", "vcpus", true, false, "allowed_from_queue") + m.RecordQuotaDecision("did:web:alice", "gpu_seconds", false, false, "dial tcp 10.0.0.1:5432: connection refused") + m.RecordQuotaDecision("workflow", "workflows", false, false, "request_exceeds_budget") + + m.SetQuotaWaitDepth("workflow", 4) + m.SetQuotaWaitDepth("res-abc", 1) + m.RecordQuotaWait("workflow", "memory_mib", 3*time.Second) + m.RecordQuotaWait("sha256:deadbeef", "gpu_seconds", time.Second) + m.RecordQuotaWait("workflow", "memory_mib", -time.Second) + + families := gather(t, m) + + wantLabels := map[string][]string{ + "spindle_quota_usage": {"resource", "scope"}, + "spindle_quota_default_limit": {"resource", "scope"}, + "spindle_quota_subjects": {"resource", "scope", "status"}, + "spindle_quota_decisions_total": {"decision", "kind", "reason", "resource"}, + "spindle_quota_wait_depth": {"kind"}, + "spindle_quota_wait_duration_seconds": {"kind", "resource"}, + } + + allowed := map[string]map[string]bool{ + "scope": {"user": true, "repo": true}, + "resource": {"cache_storage_bytes": true, "workflows": true, "vcpus": true, "memory_mib": true, "disk_mib": true, "unknown": true}, + "status": {"unlimited": true, "under_limit": true, "near_limit": true, "at_limit": true, "over_limit": true}, + "kind": {"workflow": true, "nix_cache": true, "generic_cache": true, "unknown": true}, + "decision": {"allowed": true, "rejected": true, "deferred": true}, + "reason": { + "allowed_immediately": true, "allowed_from_queue": true, "unlimited": true, + "within_limit": true, "user_limit": true, "repo_limit": true, + "queued": true, "no_wait_slot_unavailable": true, + "context_done_in_queue": true, "context_done_after_ready": true, + "store_error": true, "unknown": true, + }, + } + + for name, want := range wantLabels { + f, ok := families[name] + if !ok { + t.Fatalf("missing quota metric family %s", name) + } + if len(f.GetMetric()) == 0 { + t.Fatalf("family %s emitted no series", name) + } + for _, metric := range f.GetMetric() { + keys := labelKeys(metric) + if strings.Join(keys, ",") != strings.Join(want, ",") { + t.Fatalf("family %s has labels %v, want %v", name, keys, want) + } + for _, lp := range metric.GetLabel() { + if !allowed[lp.GetName()][lp.GetValue()] { + t.Fatalf("family %s label %s has unbounded value %q", name, lp.GetName(), lp.GetValue()) + } + } + } + } + + for _, name := range []string{"spindle_quota_usage", "spindle_quota_subjects", "spindle_quota_default_limit"} { + for _, metric := range families[name].GetMetric() { + for _, lp := range metric.GetLabel() { + if lp.GetValue() == "unknown" { + t.Fatalf("family %s kept an unknown %s bucket", name, lp.GetName()) + } + } + } + } + + var sawUnknownDecision bool + for _, metric := range families["spindle_quota_decisions_total"].GetMetric() { + if labelValue(metric, "kind") == "unknown" { + sawUnknownDecision = true + if labelValue(metric, "resource") != "unknown" || labelValue(metric, "reason") != "unknown" { + t.Fatalf("unbounded decision kept a partially unbounded tuple: %v", metric.GetLabel()) + } + } + } + if !sawUnknownDecision { + t.Fatal("unbounded decision was dropped instead of counted as unknown") + } + + var workflowSeries int + for _, metric := range families["spindle_quota_usage"].GetMetric() { + if labelValue(metric, "scope") != "user" || labelValue(metric, "resource") != "workflows" { + continue + } + workflowSeries++ + if got := metric.GetGauge().GetValue(); got != 5 { + t.Fatalf("user workflow usage = %v, want 5", got) + } + } + if workflowSeries != 1 { + t.Fatalf("user workflow usage emitted %d series, want 1", workflowSeries) + } + + if got := len(families["spindle_quota_usage"].GetMetric()); got != 6 { + t.Fatalf("quota usage emitted %d series, want 6", got) + } + if got := len(families["spindle_quota_subjects"].GetMetric()); got != 5 { + t.Fatalf("quota subjects emitted %d series, want 5", got) + } + + var waits uint64 + for _, metric := range families["spindle_quota_wait_duration_seconds"].GetMetric() { + waits += metric.GetHistogram().GetSampleCount() + } + if waits != 2 { + t.Fatalf("observed %d quota waits, want 2", waits) + } + + for name, f := range families { + if !strings.HasPrefix(name, "spindle_quota_") { + continue + } + if _, ok := wantLabels[name]; !ok { + t.Fatalf("unexpected quota metric family %s", name) + } + if f.GetHelp() == "" { + t.Fatalf("family %s has no help text", name) + } + } +} + +func TestProvisionedDashboardMatchesEmittedQuotaMetrics(t *testing.T) { + const dashboardPath = "../../localinfra/observability/grafana/provisioning/dashboards/spindle.json" + + raw, err := os.ReadFile(dashboardPath) + if err != nil { + t.Fatalf("read dashboard: %v", err) + } + + var dashboard struct { + UID string `json:"uid"` + } + if err := json.Unmarshal(raw, &dashboard); err != nil { + t.Fatalf("parse dashboard: %v", err) + } + if dashboard.UID != "efv22ywqutn28f" { + t.Fatalf("dashboard uid = %q, provisioned uid is efv22ywqutn28f", dashboard.UID) + } + + m := NewMetrics() + m.SetQuotaProvider(func() QuotaSnapshot { + return QuotaSnapshot{ + Usage: []QuotaUsage{{Scope: "user", Resource: "cache_storage_bytes", Used: 1}}, + Subjects: []QuotaSubjectCount{{Scope: "user", Resource: "cache_storage_bytes", Status: "under_limit", Count: 1}}, + } + }) + m.SetQuotaDefaultLimit("user", "cache_storage_bytes", 1) + obs := m.QuotaObserver() + obs.RecordDecision("workflow", "workflows", true, false, "allowed_immediately") + obs.SetWaitDepth("workflow", 0) + obs.RecordWait("workflow", "memory_mib", time.Second) + m.RecordEnginePoolSnapshot(0, 1, 1, 0, 1, 1, 0, 1, 1, 0) + m.RecordEnginePoolAdmission(true, "allowed_immediately") + m.RecordCacheUpload("http", "published") + m.RecordCacheUploadBytes("http", "published", 1) + emitted := gather(t, m) + + referenced := regexp.MustCompile(`spindle_(?:quota|engine_pool|cache)_[a-z0-9_]+`).FindAllString(string(raw), -1) + if len(referenced) == 0 { + t.Fatal("dashboard references no quota or cache metrics") + } + for _, name := range referenced { + base := strings.TrimSuffix(name, "_bucket") + if _, ok := emitted[base]; !ok { + t.Fatalf("dashboard queries %s, which this package does not emit", name) + } + } +} + +func TestCacheUploadMetricsAreBounded(t *testing.T) { + m := NewMetrics() + + m.RecordCacheUpload("bad_backend", "bad_result") + m.RecordCacheUpload("http", "published") + m.RecordCacheUploadBytes("http", "published", 1024) + m.RecordCacheUploadBytes("http", "published", -500) + m.RecordCacheUploadBytes("nix_store", "quota_skipped", 2048) + m.RecordCacheUploadBytes("did:web:alice", "published", 2048) + + families := gather(t, m) + + for _, name := range []string{"spindle_cache_uploads_total", "spindle_cache_upload_bytes_total"} { + f, ok := families[name] + if !ok { + t.Fatalf("missing family %s", name) + } + for _, metric := range f.GetMetric() { + keys := labelKeys(metric) + if strings.Join(keys, ",") != "backend,result" { + t.Fatalf("family %s has labels %v, want [backend result]", name, keys) + } + backend := labelValue(metric, "backend") + if backend != "http" && backend != "nix_store" && backend != "unknown" { + t.Fatalf("family %s has unbounded backend %q", name, backend) + } + result := labelValue(metric, "result") + if result != "published" && result != "quota_skipped" && result != "failed" && result != "unknown" { + t.Fatalf("family %s has unbounded result %q", name, result) + } + } + } + + // negative byte counts are ignored + for _, metric := range families["spindle_cache_upload_bytes_total"].GetMetric() { + if labelValue(metric, "backend") == "http" && metric.GetCounter().GetValue() != 1024 { + t.Fatalf("http upload bytes = %v, want 1024", metric.GetCounter().GetValue()) + } + } +} + +// the cache-only quota families are gone, nothing may resurrect them +func TestObsoleteCacheQuotaFamiliesAreGone(t *testing.T) { + m := NewMetrics() + m.SetQuotaProvider(func() QuotaSnapshot { + return QuotaSnapshot{ + Usage: []QuotaUsage{{Scope: "user", Resource: "cache_storage_bytes", Used: 1}}, + Subjects: []QuotaSubjectCount{{Scope: "user", Resource: "cache_storage_bytes", Status: "under_limit", Count: 1}}, + } + }) + m.RecordQuotaDecision("nix_cache", "cache_storage_bytes", true, false, "within_limit") + + families := gather(t, m) + for _, name := range []string{ + "spindle_cache_quota_usage_bytes", + "spindle_cache_quota_subjects", + "spindle_cache_quota_decisions_total", + "spindle_quota_memory_mib", + "spindle_quota_vcpus", + "spindle_quota_disk_mib", + "spindle_quota_queue_depth", + } { + if _, ok := families[name]; ok { + t.Fatalf("obsolete metric family %s is still registered", name) + } + } +} + +// the local engine pool is physical capacity, both its levels and its +// admissions stay outside the quota namespace +func TestEnginePoolMetricsAreSeparateFromQuota(t *testing.T) { + m := NewMetrics() + m.RecordEnginePoolSnapshot(2048, 8192, 4096, 2, 8, 4, 10240, 40960, 20480, 3) + m.RecordEnginePoolAdmission(true, "allowed_immediately") + m.RecordEnginePoolAdmission(false, "request_exceeds_budget") + // a tenant quota reason is not a host capacity reason + m.RecordEnginePoolAdmission(false, "user_limit") + m.RecordEnginePoolAdmission(false, "did:web:alice") + + families := gather(t, m) + for _, name := range []string{ + "spindle_engine_pool_memory_mib", + "spindle_engine_pool_vcpus", + "spindle_engine_pool_disk_mib", + } { + f, ok := families[name] + if !ok { + t.Fatalf("missing family %s", name) + } + for _, metric := range f.GetMetric() { + keys := labelKeys(metric) + if strings.Join(keys, ",") != "state" { + t.Fatalf("family %s has labels %v, want [state]", name, keys) + } + state := labelValue(metric, "state") + if state != "used" && state != "limit" && state != "max_request" { + t.Fatalf("family %s has unbounded state %q", name, state) + } + } + } + + depth, ok := families["spindle_engine_pool_queue_depth"] + if !ok { + t.Fatal("missing family spindle_engine_pool_queue_depth") + } + if got := depth.GetMetric()[0].GetGauge().GetValue(); got != 3 { + t.Fatalf("engine pool queue depth = %v, want 3", got) + } + + admission, ok := families["spindle_engine_pool_admission_total"] + if !ok { + t.Fatal("missing family spindle_engine_pool_admission_total") + } + poolReasons := map[string]bool{ + "allowed_immediately": true, "allowed_from_queue": true, + "request_exceeds_budget": true, "request_exceeds_max": true, + "no_wait_slot_unavailable": true, "context_done_in_queue": true, + "context_done_after_ready": true, "unknown": true, + } + var unknownPoolReasons float64 + for _, metric := range admission.GetMetric() { + keys := labelKeys(metric) + if strings.Join(keys, ",") != "decision,reason" { + t.Fatalf("engine pool admission has labels %v, want [decision reason]", keys) + } + if decision := labelValue(metric, "decision"); decision != "allowed" && decision != "rejected" { + t.Fatalf("engine pool admission has unbounded decision %q", decision) + } + reason := labelValue(metric, "reason") + if !poolReasons[reason] { + t.Fatalf("engine pool admission has unbounded reason %q", reason) + } + if reason == "unknown" { + unknownPoolReasons += metric.GetCounter().GetValue() + } + } + if unknownPoolReasons != 2 { + t.Fatalf("counted %v unknown pool reasons, want 2", unknownPoolReasons) + } + + // host capacity admissions must never reach the tenant quota family + if _, ok := families["spindle_quota_decisions_total"]; ok { + t.Fatal("engine pool admissions leaked into spindle_quota_decisions_total") + } +} + +// the two reason vocabularies do not bleed into each other +func TestQuotaAndEnginePoolReasonsAreDisjointWhereTheyMustBe(t *testing.T) { + for _, reason := range []string{"request_exceeds_budget", "request_exceeds_max"} { + if _, ok := quotaReason(reason); ok { + t.Fatalf("host capacity reason %q is accepted as a quota reason", reason) + } + } + for _, reason := range []string{"user_limit", "repo_limit", "within_limit", "unlimited", "queued", "store_error"} { + if _, ok := enginePoolReason(reason); ok { + t.Fatalf("tenant quota reason %q is accepted as a host capacity reason", reason) + } + } +} + +// no forbidden identifier survives any bound function +func TestQuotaBoundFunctionsRejectIdentifiers(t *testing.T) { + for _, value := range forbiddenLabelValues { + if got, ok := quotaScope(value); ok || got != "unknown" { + t.Fatalf("quotaScope(%q) = %q, %v", value, got, ok) + } + if got, ok := quotaStatus(value); ok || got != "unknown" { + t.Fatalf("quotaStatus(%q) = %q, %v", value, got, ok) + } + if got, ok := enginePoolReason(value); ok || got != "unknown" { + t.Fatalf("enginePoolReason(%q) = %q, %v", value, got, ok) + } + if got, ok := quotaKind(value); ok || got != "unknown" { + t.Fatalf("quotaKind(%q) = %q, %v", value, got, ok) + } + if got, ok := quotaResource(value); ok || got != "unknown" { + t.Fatalf("quotaResource(%q) = %q, %v", value, got, ok) + } + if got, ok := quotaReason(value); ok || got != "unknown" { + t.Fatalf("quotaReason(%q) = %q, %v", value, got, ok) + } + } + + if got := quotaDecision(true, true); got != "allowed" { + t.Fatalf("allowed decision = %q", got) + } + if got := quotaDecision(false, true); got != "deferred" { + t.Fatalf("temporary denial = %q", got) + } + if got := quotaDecision(false, false); got != "rejected" { + t.Fatalf("permanent denial = %q", got) + } +} + +type mockClock struct { + mu sync.Mutex + t time.Time +} + +func (m *mockClock) Now() time.Time { + m.mu.Lock() + defer m.mu.Unlock() + return m.t +} + +func (m *mockClock) Advance(d time.Duration) { + m.mu.Lock() + defer m.mu.Unlock() + m.t = m.t.Add(d) +} + +func TestCachedQuotaProvider(t *testing.T) { + clk := &mockClock{t: time.Date(2026, 1, 1, 0, 0, 0, 0, time.UTC)} + + t.Run("first load", func(t *testing.T) { + var calls int32 + loader := func() (QuotaSnapshot, error) { + atomic.AddInt32(&calls, 1) + return QuotaSnapshot{ + Usage: []QuotaUsage{{Scope: "user", Resource: "vcpus", Used: 10}}, + }, nil + } + cache := newCachedQuotaProvider(loader, clk, 1*time.Minute) + snap := cache.Get() + if atomic.LoadInt32(&calls) != 1 { + t.Fatalf("expected 1 loader call, got %d", calls) + } + if len(snap.Usage) != 1 || snap.Usage[0].Used != 10 { + t.Fatalf("unexpected snapshot content: %v", snap) + } + }) + + t.Run("cache hit", func(t *testing.T) { + var calls int32 + loader := func() (QuotaSnapshot, error) { + atomic.AddInt32(&calls, 1) + return QuotaSnapshot{ + Usage: []QuotaUsage{{Scope: "user", Resource: "vcpus", Used: 10}}, + }, nil + } + cache := newCachedQuotaProvider(loader, clk, 1*time.Minute) + + cache.Get() + snap := cache.Get() + + if atomic.LoadInt32(&calls) != 1 { + t.Fatalf("expected exactly 1 loader call (first load), got %d", calls) + } + if len(snap.Usage) != 1 || snap.Usage[0].Used != 10 { + t.Fatalf("unexpected snapshot content: %v", snap) + } + }) + + t.Run("TTL expiry", func(t *testing.T) { + var calls int32 + loader := func() (QuotaSnapshot, error) { + atomic.AddInt32(&calls, 1) + return QuotaSnapshot{ + Usage: []QuotaUsage{{Scope: "user", Resource: "vcpus", Used: float64(atomic.LoadInt32(&calls) * 10)}}, + }, nil + } + cache := newCachedQuotaProvider(loader, clk, 1*time.Minute) + + snap1 := cache.Get() + if snap1.Usage[0].Used != 10 { + t.Fatalf("expected 10, got %g", snap1.Usage[0].Used) + } + + clk.Advance(59 * time.Second) + snap2 := cache.Get() + if snap2.Usage[0].Used != 10 { + t.Fatalf("expected cached 10, got %g", snap2.Usage[0].Used) + } + if atomic.LoadInt32(&calls) != 1 { + t.Fatalf("expected exactly 1 call, got %d", calls) + } + + clk.Advance(2 * time.Second) + snap3 := cache.Get() + if snap3.Usage[0].Used != 20 { + t.Fatalf("expected refreshed 20, got %g", snap3.Usage[0].Used) + } + if atomic.LoadInt32(&calls) != 2 { + t.Fatalf("expected exactly 2 calls, got %d", calls) + } + }) + + t.Run("concurrent miss coalescing", func(t *testing.T) { + var calls int32 + startChan := make(chan struct{}) + blockChan := make(chan struct{}) + + loader := func() (QuotaSnapshot, error) { + atomic.AddInt32(&calls, 1) + close(startChan) + <-blockChan + return QuotaSnapshot{ + Usage: []QuotaUsage{{Scope: "user", Resource: "vcpus", Used: 42}}, + }, nil + } + cache := newCachedQuotaProvider(loader, clk, 1*time.Minute) + + var wg sync.WaitGroup + const numCallers = 10 + results := make([]QuotaSnapshot, numCallers) + + for i := 0; i < numCallers; i++ { + wg.Add(1) + go func(idx int) { + defer wg.Done() + results[idx] = cache.Get() + }(i) + } + + <-startChan + time.Sleep(50 * time.Millisecond) + close(blockChan) + wg.Wait() + + if atomic.LoadInt32(&calls) != 1 { + t.Fatalf("expected concurrent scrapes to coalesce into exactly 1 loader call, got %d", calls) + } + + for idx, snap := range results { + if len(snap.Usage) != 1 || snap.Usage[0].Used != 42 { + t.Fatalf("caller %d got unexpected snapshot: %v", idx, snap) + } + } + }) + + t.Run("last-good preservation after error", func(t *testing.T) { + var calls int32 + var shouldFail int32 + + loader := func() (QuotaSnapshot, error) { + atomic.AddInt32(&calls, 1) + if atomic.LoadInt32(&shouldFail) == 1 { + return QuotaSnapshot{}, errors.New("database connection lost") + } + return QuotaSnapshot{ + Usage: []QuotaUsage{{Scope: "user", Resource: "vcpus", Used: 100}}, + }, nil + } + cache := newCachedQuotaProvider(loader, clk, 1*time.Minute) + + snap1 := cache.Get() + if len(snap1.Usage) != 1 || snap1.Usage[0].Used != 100 { + t.Fatalf("expected initial load success, got %v", snap1) + } + + atomic.StoreInt32(&shouldFail, 1) + clk.Advance(2 * time.Minute) + + snap2 := cache.Get() + if len(snap2.Usage) != 1 || snap2.Usage[0].Used != 100 { + t.Fatalf("expected last-good preservation, got %v", snap2) + } + + clk.Advance(2 * time.Minute) + snap3 := cache.Get() + if len(snap3.Usage) != 1 || snap3.Usage[0].Used != 100 { + t.Fatalf("expected last-good preservation on second failure, got %v", snap3) + } + + if atomic.LoadInt32(&calls) != 3 { + t.Fatalf("expected 3 load attempts, got %d", calls) + } + }) + + t.Run("cold error is cached until expiry", func(t *testing.T) { + var calls int32 + cache := newCachedQuotaProvider(func() (QuotaSnapshot, error) { + atomic.AddInt32(&calls, 1) + return QuotaSnapshot{}, errors.New("database unavailable") + }, clk, time.Minute) + + cache.Get() + cache.Get() + if got := atomic.LoadInt32(&calls); got != 1 { + t.Fatalf("cold failure loader calls = %d, want 1", got) + } + + clk.Advance(time.Minute) + cache.Get() + if got := atomic.LoadInt32(&calls); got != 2 { + t.Fatalf("loader calls at expiry = %d, want 2", got) + } + }) +} + +func BenchmarkRecordWorkflow(b *testing.B) { + m := NewMetrics() + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + m.RecordWorkflowStart("nixery") + m.RecordWorkflowEnd(context.Background(), "nixery", "success", 123*time.Millisecond) + } +} + +func BenchmarkRecordStep(b *testing.B) { + m := NewMetrics() + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + m.RecordStepStart("nixery") + m.RecordStepEnd(context.Background(), "nixery", "success", 45*time.Millisecond) + } +} + +func BenchmarkRecordQuotaDecision(b *testing.B) { + m := NewMetrics() + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + m.RecordQuotaDecision("workflow", "vcpus", true, false, "within_limit") + } +} + +func BenchmarkHTTPMiddleware(b *testing.B) { + m := NewMetrics() + handler := HTTPMiddleware(m)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + + req, err := http.NewRequest("GET", "/test", nil) + if err != nil { + b.Fatal(err) + } + rctx := chi.NewRouteContext() + rctx.RoutePatterns = []string{"/test"} + req = req.WithContext(context.WithValue(req.Context(), chi.RouteCtxKey, rctx)) + + w := httptest.NewRecorder() + + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + handler.ServeHTTP(w, req) + } +} +func TestRecordWorkflowEnd_Exemplar(t *testing.T) { + oldProvider := otel.GetTracerProvider() + recorder := tracetest.NewSpanRecorder() + provider := sdktrace.NewTracerProvider( + sdktrace.WithSpanProcessor(recorder), + sdktrace.WithSampler(sdktrace.AlwaysSample()), + ) + otel.SetTracerProvider(provider) + t.Cleanup(func() { + _ = provider.Shutdown(context.Background()) + otel.SetTracerProvider(oldProvider) + }) + + m := NewMetrics() + ctx, span := Tracer().Start(context.Background(), "test-workflow") + defer span.End() + + m.RecordWorkflowEnd(ctx, "nixery", "success", 123*time.Millisecond) + m.RecordStepEnd(ctx, "nixery", "success", 45*time.Millisecond) + + families, err := m.Registry().Gather() + if err != nil { + t.Fatal(err) + } + + findExemplar := func(name string) *dto.Exemplar { + for _, f := range families { + if f.GetName() == name { + for _, metric := range f.GetMetric() { + h := metric.GetHistogram() + if h == nil { + continue + } + for _, b := range h.GetBucket() { + if e := b.GetExemplar(); e != nil { + return e + } + } + } + } + } + return nil + } + + wfExemplar := findExemplar("spindle_workflow_duration_seconds") + if wfExemplar == nil { + t.Error("spindle_workflow_duration_seconds missing exemplar") + } else { + hasTraceID := false + for _, label := range wfExemplar.GetLabel() { + if label.GetName() == "traceID" && label.GetValue() == span.SpanContext().TraceID().String() { + hasTraceID = true + } + } + if !hasTraceID { + t.Errorf("workflow exemplar missing correct traceID, got label: %+v", wfExemplar.GetLabel()) + } + } + + stepExemplar := findExemplar("spindle_step_duration_seconds") + if stepExemplar == nil { + t.Error("spindle_step_duration_seconds missing exemplar") + } else { + hasTraceID := false + for _, label := range stepExemplar.GetLabel() { + if label.GetName() == "traceID" && label.GetValue() == span.SpanContext().TraceID().String() { + hasTraceID = true + } + } + if !hasTraceID { + t.Errorf("step exemplar missing correct traceID, got label: %+v", stepExemplar.GetLabel()) + } + } +} diff --git a/spindle/observability/tracing.go b/spindle/observability/tracing.go new file mode 100644 --- /dev/null +++ b/spindle/observability/tracing.go @@ -0,0 +1,162 @@ +package observability + +import ( + "context" + "fmt" + "net/http" + + "github.com/go-chi/chi/v5" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp" + "go.opentelemetry.io/otel/propagation" + "go.opentelemetry.io/otel/sdk/resource" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/trace" + "tangled.org/core/spindle/config" +) + +const ( + UserDIDKey = "tangled.user.did" + OwnerDIDKey = "tangled.owner.did" + RepoDIDKey = "tangled.repo.did" + TargetRepoDIDKey = "tangled.repo.target.did" + PipelineIDKey = "tangled.pipeline.id" + WorkflowIDKey = "tangled.workflow.id" + WorkflowEngineKey = "tangled.workflow.engine" + LeaseIDKey = "tangled.lease.id" + ExecutorNodeIDKey = "tangled.executor.node_id" + JobIDKey = "tangled.job.id" + RequestIDKey = "tangled.request.id" + CollectionKey = "atproto.collection" + RKeyKey = "atproto.rkey" + StepNameKey = "tangled.step.name" + StepIndexKey = "tangled.step.index" +) + +func InitTracing(ctx context.Context, cfg config.Tracing) (func(context.Context) error, error) { + otel.SetTextMapPropagator(propagation.TraceContext{}) + if cfg.Endpoint == "" { + return func(context.Context) error { return nil }, nil + } + + opts := []otlptracehttp.Option{otlptracehttp.WithEndpoint(cfg.Endpoint)} + if cfg.Insecure { + opts = append(opts, otlptracehttp.WithInsecure()) + } + exporter, err := otlptracehttp.New(ctx, opts...) + if err != nil { + return nil, fmt.Errorf("creating OTLP trace exporter: %w", err) + } + + res, err := resource.Merge( + resource.Default(), + resource.NewSchemaless(attribute.String("service.name", cfg.ServiceName)), + ) + if err != nil { + return nil, fmt.Errorf("creating tracing resource: %w", err) + } + + provider := sdktrace.NewTracerProvider( + sdktrace.WithBatcher(exporter), + sdktrace.WithResource(res), + sdktrace.WithSampler(sdktrace.ParentBased(sdktrace.TraceIDRatioBased(cfg.SampleRatio))), + ) + otel.SetTracerProvider(provider) + + return func(shutdownCtx context.Context) error { + if err := provider.Shutdown(shutdownCtx); err != nil { + return fmt.Errorf("shutting down tracer provider: %w", err) + } + return nil + }, nil +} + +func Tracer() trace.Tracer { + return otel.Tracer("tangled.org/core/spindle") +} + +func OTelRouteMiddleware(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + next.ServeHTTP(w, r) + + rctx := chi.RouteContext(r.Context()) + if rctx == nil { + return + } + pattern := rctx.RoutePattern() + if pattern == "" { + return + } + span := trace.SpanFromContext(r.Context()) + span.SetName("HTTP " + pattern) + span.SetAttributes(attribute.String("http.route", pattern)) + }) +} + +func InjectToTraceparentAndTracestate(ctx context.Context) (string, string) { + carrier := propagation.MapCarrier{} + propagation.TraceContext{}.Inject(ctx, carrier) + return carrier.Get("traceparent"), carrier.Get("tracestate") +} + +func ExtractFromTraceparentAndTracestate(ctx context.Context, traceparent, tracestate string) context.Context { + if traceparent == "" { + return ctx + } + carrier := propagation.MapCarrier{ + "traceparent": traceparent, + "tracestate": tracestate, + } + return propagation.TraceContext{}.Extract(ctx, carrier) +} + +const ( + ReqWorkflowsKey = "tangled.resource.requested.workflows" + ReqVCPUsKey = "tangled.resource.requested.vcpus" + ReqMemoryMiBKey = "tangled.resource.requested.memory_mib" + ReqDiskMiBKey = "tangled.resource.requested.disk_mib" + ReqCacheBytesKey = "tangled.resource.requested.cache_bytes" + + ActCPUUsecKey = "tangled.resource.actual.cpu_usec" + ActMemoryCurrentBytesKey = "tangled.resource.actual.memory_current_bytes" + ActMemoryPeakBytesKey = "tangled.resource.actual.memory_peak_bytes" + ActSwapCurrentBytesKey = "tangled.resource.actual.swap_current_bytes" + ActSwapPeakBytesKey = "tangled.resource.actual.swap_peak_bytes" + ActPIDsCurrentKey = "tangled.resource.actual.pids_current" + ActIOReadBytesKey = "tangled.resource.actual.io_read_bytes" + ActIOWriteBytesKey = "tangled.resource.actual.io_write_bytes" + ActIOReadOpsKey = "tangled.resource.actual.io_read_ops" + ActIOWriteOpsKey = "tangled.resource.actual.io_write_ops" + ActVolumeAllocatedBytesKey = "tangled.resource.actual.volume_allocated_bytes" + ActCgroupAvailableKey = "tangled.resource.actual.cgroup_available" + ActVolumeAvailableKey = "tangled.resource.actual.volume_available" +) + +func RequestedResourceAttrs(workflows, vcpus, memoryMiB, diskMiB, cacheBytes int64) []attribute.KeyValue { + return []attribute.KeyValue{ + attribute.Int64(ReqWorkflowsKey, workflows), + attribute.Int64(ReqVCPUsKey, vcpus), + attribute.Int64(ReqMemoryMiBKey, memoryMiB), + attribute.Int64(ReqDiskMiBKey, diskMiB), + attribute.Int64(ReqCacheBytesKey, cacheBytes), + } +} + +func ActualResourceAttrs(cpuUsec, memoryCurrent, memoryPeak, swapCurrent, swapPeak, pidsCurrent, ioReadBytes, ioWriteBytes, ioReadOps, ioWriteOps, volumeAllocated uint64, cgroupAvailable, volumeAvailable bool) []attribute.KeyValue { + return []attribute.KeyValue{ + attribute.Int64(ActCPUUsecKey, int64(cpuUsec)), + attribute.Int64(ActMemoryCurrentBytesKey, int64(memoryCurrent)), + attribute.Int64(ActMemoryPeakBytesKey, int64(memoryPeak)), + attribute.Int64(ActSwapCurrentBytesKey, int64(swapCurrent)), + attribute.Int64(ActSwapPeakBytesKey, int64(swapPeak)), + attribute.Int64(ActPIDsCurrentKey, int64(pidsCurrent)), + attribute.Int64(ActIOReadBytesKey, int64(ioReadBytes)), + attribute.Int64(ActIOWriteBytesKey, int64(ioWriteBytes)), + attribute.Int64(ActIOReadOpsKey, int64(ioReadOps)), + attribute.Int64(ActIOWriteOpsKey, int64(ioWriteOps)), + attribute.Int64(ActVolumeAllocatedBytesKey, int64(volumeAllocated)), + attribute.Bool(ActCgroupAvailableKey, cgroupAvailable), + attribute.Bool(ActVolumeAvailableKey, volumeAvailable), + } +} diff --git a/spindle/observability/tracing_test.go b/spindle/observability/tracing_test.go new file mode 100644 --- /dev/null +++ b/spindle/observability/tracing_test.go @@ -0,0 +1,100 @@ +package observability + +import ( + "context" + "net/http" + "net/http/httptest" + "testing" + + "github.com/go-chi/chi/v5" + "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + "go.opentelemetry.io/otel/trace" +) + +func TestTraceContextRoundTrip(t *testing.T) { + want := trace.NewSpanContext(trace.SpanContextConfig{ + TraceID: trace.TraceID{1}, + SpanID: trace.SpanID{2}, + TraceFlags: trace.FlagsSampled, + Remote: true, + }) + ctx := trace.ContextWithRemoteSpanContext(context.Background(), want) + + traceparent, tracestate := InjectToTraceparentAndTracestate(ctx) + if traceparent == "" { + t.Fatal("traceparent is empty") + } + + got := trace.SpanContextFromContext(ExtractFromTraceparentAndTracestate(context.Background(), traceparent, tracestate)) + if got.TraceID() != want.TraceID() || got.SpanID() != want.SpanID() || !got.IsSampled() || !got.IsRemote() { + t.Fatalf("span context = %v, want %v", got, want) + } +} + +func TestOTelRouteMiddlewareUsesRouteTemplate(t *testing.T) { + oldProvider := otel.GetTracerProvider() + recorder := tracetest.NewSpanRecorder() + provider := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(recorder)) + otel.SetTracerProvider(provider) + t.Cleanup(func() { + _ = provider.Shutdown(context.Background()) + otel.SetTracerProvider(oldProvider) + }) + + router := chi.NewRouter() + router.Use(OTelRouteMiddleware) + router.Get("/things/{id}", func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusNoContent) + }) + handler := otelhttp.NewHandler(router, "HTTP") + + request := httptest.NewRequest(http.MethodGet, "/things/raw-user-id", nil) + response := httptest.NewRecorder() + handler.ServeHTTP(response, request) + + spans := recorder.Ended() + if len(spans) != 1 { + t.Fatalf("ended spans = %d, want 1", len(spans)) + } + if got := spans[0].Name(); got != "HTTP /things/{id}" { + t.Fatalf("span name = %q, want route template", got) + } + for _, attr := range spans[0].Attributes() { + if attr.Key == attribute.Key("http.route") && attr.Value.AsString() == "/things/{id}" { + return + } + } + t.Fatal("http.route template attribute is missing") +} + +func TestTracingConstants(t *testing.T) { + tests := []struct { + got string + want string + }{ + {UserDIDKey, "tangled.user.did"}, + {OwnerDIDKey, "tangled.owner.did"}, + {RepoDIDKey, "tangled.repo.did"}, + {TargetRepoDIDKey, "tangled.repo.target.did"}, + {PipelineIDKey, "tangled.pipeline.id"}, + {WorkflowIDKey, "tangled.workflow.id"}, + {WorkflowEngineKey, "tangled.workflow.engine"}, + {LeaseIDKey, "tangled.lease.id"}, + {ExecutorNodeIDKey, "tangled.executor.node_id"}, + {JobIDKey, "tangled.job.id"}, + {RequestIDKey, "tangled.request.id"}, + {CollectionKey, "atproto.collection"}, + {RKeyKey, "atproto.rkey"}, + {StepNameKey, "tangled.step.name"}, + {StepIndexKey, "tangled.step.index"}, + } + for _, tc := range tests { + if tc.got != tc.want { + t.Errorf("got %q, want %q", tc.got, tc.want) + } + } +} diff --git a/spindle/xrpc/add_secret.go b/spindle/xrpc/add_secret.go --- a/spindle/xrpc/add_secret.go +++ b/spindle/xrpc/add_secret.go @@ -18,7 +18,7 @@ func (x *Xrpc) AddSecret(w http.ResponseWriter, r *http.Request) { l := x.Logger fail := func(e xrpcerr.XrpcError) { - l.Error("failed", "kind", e.Tag, "error", e.Message) + l.ErrorContext(r.Context(), "failed", "kind", e.Tag, "error", e.Message) writeError(w, e, http.StatusBadRequest) } @@ -72,7 +72,7 @@ repoDid := *repoRec.RepoDid if ok, err := x.Enforcer.IsSettingsAllowed(actorDid.String(), rbac.ThisServer, repoDid); !ok || err != nil { - l.Error("insufficient permissions", "did", actorDid.String()) + l.ErrorContext(r.Context(), "insufficient permissions", "did", actorDid.String()) writeError(w, xrpcerr.AccessControlError(actorDid.String()), http.StatusUnauthorized) return } @@ -86,7 +86,7 @@ } err = x.Vault.AddSecret(r.Context(), secret) if err != nil { - l.Error("failed to add secret to vault", "did", actorDid.String(), "err", err) + l.ErrorContext(r.Context(), "failed to add secret to vault", "did", actorDid.String(), "err", err) writeError(w, xrpcerr.GenericError(err), http.StatusInternalServerError) return } diff --git a/spindle/xrpc/ci_pipeline_describe_workflow_definition.go b/spindle/xrpc/ci_pipeline_describe_workflow_definition.go --- a/spindle/xrpc/ci_pipeline_describe_workflow_definition.go +++ b/spindle/xrpc/ci_pipeline_describe_workflow_definition.go @@ -9,7 +9,7 @@ func (x *Xrpc) DescribeWorkflowDefinition(w http.ResponseWriter, r *http.Request) { l := x.Logger fail := func(e xrpcerr.XrpcError) { - l.Error("failed", "kind", e.Tag, "error", e.Message) + l.ErrorContext(r.Context(), "failed", "kind", e.Tag, "error", e.Message) writeError(w, e, http.StatusBadRequest) } @@ -40,6 +40,6 @@ } if err := writeJson(w, http.StatusOK, out); err != nil { - l.Error("failed to write response", "err", err) + l.ErrorContext(r.Context(), "failed to write response", "err", err) } } diff --git a/spindle/xrpc/ci_pipeline_subscribe_logs.go b/spindle/xrpc/ci_pipeline_subscribe_logs.go --- a/spindle/xrpc/ci_pipeline_subscribe_logs.go +++ b/spindle/xrpc/ci_pipeline_subscribe_logs.go @@ -47,20 +47,20 @@ pipeline.String(), ).Scan(&eventJson) if err != nil { - l.Error("failed to find pipeline event", "err", err) + l.ErrorContext(r.Context(), "failed to find pipeline event", "err", err) writeJson(w, http.StatusNotFound, atclient.ErrorBody{Name: "NotFound", Message: fmt.Sprintf("pipeline not found: %s", pipeline.String())}) return } var tpl tangled.Pipeline if err := json.Unmarshal([]byte(eventJson), &tpl); err != nil { - l.Error("failed to unmarshal pipeline event", "err", err) + l.ErrorContext(r.Context(), "failed to unmarshal pipeline event", "err", err) writeJson(w, http.StatusInternalServerError, atclient.ErrorBody{Name: "InternalError", Message: "failed to parse pipeline event"}) return } if tpl.TriggerMetadata == nil || tpl.TriggerMetadata.Repo == nil { - l.Error("pipeline event trigger metadata is incomplete") + l.ErrorContext(r.Context(), "pipeline event trigger metadata is incomplete") writeJson(w, http.StatusInternalServerError, atclient.ErrorBody{Name: "InternalError", Message: "pipeline event trigger metadata is incomplete"}) return } @@ -86,7 +86,7 @@ conn, err := wsUpgrader.Upgrade(w, r, w.Header()) if err != nil { - l.Error("websocket upgrade failed", "err", err) + l.ErrorContext(r.Context(), "websocket upgrade failed", "err", err) return } defer conn.Close() @@ -111,7 +111,7 @@ } if err := conn.WriteControl(websocket.PingMessage, []byte{}, time.Now().Add(5*time.Second)); err != nil { - l.Warn("failed to ping client", "err", err) + l.WarnContext(r.Context(), "failed to ping client", "err", err) cancel() return } @@ -134,7 +134,7 @@ for { _, _, err := conn.ReadMessage() if err != nil { - l.Warn("failed to read message from client", "err", err) + l.WarnContext(r.Context(), "failed to read message from client", "err", err) cancel() return } @@ -167,7 +167,7 @@ lines, stop, err := logview.Follow(ctx, x.Db, x.ArtifactReader, x.Config.Server.LogDir, wid, isFinished) if err != nil { - l.Error("failed to follow workflow log", "workflow", wfName, "err", err) + l.ErrorContext(r.Context(), "failed to follow workflow log", "workflow", wfName, "err", err) return } defer stop() @@ -202,7 +202,7 @@ } if line.Err != nil { - l.Warn("error tailing log file", "workflow", wfName, "err", line.Err) + l.WarnContext(r.Context(), "error tailing log file", "workflow", wfName, "err", line.Err) return } @@ -274,19 +274,19 @@ wc, err := conn.NextWriter(websocket.BinaryMessage) if err != nil { - l.Error("failed to get next writer", "err", err) + l.ErrorContext(r.Context(), "failed to get next writer", "err", err) return } err = evt.Serialize(wc) if err != nil { - l.Error("failed to serialize event", "err", err) + l.ErrorContext(r.Context(), "failed to serialize event", "err", err) wc.Close() return } if err := wc.Close(); err != nil { - l.Warn("failed to flush-close event write", "err", err) + l.WarnContext(r.Context(), "failed to flush-close event write", "err", err) return } diff --git a/spindle/xrpc/ci_pipeline_trigger_pipeline.go b/spindle/xrpc/ci_pipeline_trigger_pipeline.go --- a/spindle/xrpc/ci_pipeline_trigger_pipeline.go +++ b/spindle/xrpc/ci_pipeline_trigger_pipeline.go @@ -17,10 +17,10 @@ func (x *Xrpc) TriggerPipeline(w http.ResponseWriter, r *http.Request) { l := x.Logger fail := func(e xrpcerr.XrpcError) { - l.Error("failed", "kind", e.Tag, "error", e.Message) + l.ErrorContext(r.Context(), "failed", "kind", e.Tag, "error", e.Message) writeError(w, e, http.StatusBadRequest) } - l.Debug("trigger pipeline") + l.DebugContext(r.Context(), "trigger pipeline") actorDid, ok := r.Context().Value(ActorDid).(syntax.DID) if !ok { @@ -123,7 +123,7 @@ if err := writeJson(w, http.StatusOK, tangled.CiTriggerPipeline_Output{ Pipeline: pipelineAt.String(), }); err != nil { - l.Error("failed to write response", "err", err) + l.ErrorContext(r.Context(), "failed to write response", "err", err) } } diff --git a/spindle/xrpc/ci_query_pipelines.go b/spindle/xrpc/ci_query_pipelines.go --- a/spindle/xrpc/ci_query_pipelines.go +++ b/spindle/xrpc/ci_query_pipelines.go @@ -12,7 +12,7 @@ func (x *Xrpc) HandleCiQueryPipelines(w http.ResponseWriter, r *http.Request) { l := x.Logger fail := func(e xrpcerr.XrpcError, status int) { - l.Error("failed", "kind", e.Tag, "error", e.Message) + l.ErrorContext(r.Context(), "failed", "kind", e.Tag, "error", e.Message) writeError(w, e, status) } @@ -56,7 +56,7 @@ func (x *Xrpc) HandleCiGetPipeline(w http.ResponseWriter, r *http.Request) { l := x.Logger fail := func(e xrpcerr.XrpcError, status int) { - l.Error("failed", "kind", e.Tag, "error", e.Message) + l.ErrorContext(r.Context(), "failed", "kind", e.Tag, "error", e.Message) writeError(w, e, status) } diff --git a/spindle/xrpc/list_secrets.go b/spindle/xrpc/list_secrets.go --- a/spindle/xrpc/list_secrets.go +++ b/spindle/xrpc/list_secrets.go @@ -18,7 +18,7 @@ func (x *Xrpc) ListSecrets(w http.ResponseWriter, r *http.Request) { l := x.Logger fail := func(e xrpcerr.XrpcError) { - l.Error("failed", "kind", e.Tag, "error", e.Message) + l.ErrorContext(r.Context(), "failed", "kind", e.Tag, "error", e.Message) writeError(w, e, http.StatusBadRequest) } @@ -67,14 +67,14 @@ repoDid := *repoRec.RepoDid if ok, err := x.Enforcer.IsSettingsAllowed(actorDid.String(), rbac.ThisServer, repoDid); !ok || err != nil { - l.Error("insufficient permissions", "did", actorDid.String()) + l.ErrorContext(r.Context(), "insufficient permissions", "did", actorDid.String()) writeError(w, xrpcerr.AccessControlError(actorDid.String()), http.StatusUnauthorized) return } ls, err := x.Vault.GetSecretsLocked(r.Context(), secrets.RepoIdentifier(repoDid)) if err != nil { - l.Error("failed to get secret from vault", "did", actorDid.String(), "err", err) + l.ErrorContext(r.Context(), "failed to get secret from vault", "did", actorDid.String(), "err", err) writeError(w, xrpcerr.GenericError(err), http.StatusInternalServerError) return } diff --git a/spindle/xrpc/owner.go b/spindle/xrpc/owner.go --- a/spindle/xrpc/owner.go +++ b/spindle/xrpc/owner.go @@ -21,7 +21,7 @@ w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(response); err != nil { - x.Logger.Error("failed to encode response", "error", err) + x.Logger.ErrorContext(r.Context(), "failed to encode response", "error", err) writeError(w, xrpcerr.NewXrpcError( xrpcerr.WithTag("InternalServerError"), xrpcerr.WithMessage("failed to encode response"), diff --git a/spindle/xrpc/pipeline_cancel_pipeline.go b/spindle/xrpc/pipeline_cancel_pipeline.go --- a/spindle/xrpc/pipeline_cancel_pipeline.go +++ b/spindle/xrpc/pipeline_cancel_pipeline.go @@ -15,10 +15,10 @@ func (x *Xrpc) CancelPipeline(w http.ResponseWriter, r *http.Request) { l := x.Logger fail := func(e xrpcerr.XrpcError) { - l.Error("failed", "kind", e.Tag, "error", e.Message) + l.ErrorContext(r.Context(), "failed", "kind", e.Tag, "error", e.Message) writeError(w, e, http.StatusBadRequest) } - l.Debug("cancel pipeline") + l.DebugContext(r.Context(), "cancel pipeline") actorDid, ok := r.Context().Value(ActorDid).(syntax.DID) if !ok { @@ -77,7 +77,7 @@ canceled := false defer func() { - l.Debug("canceled pipeline", "canceled", canceled) + l.DebugContext(r.Context(), "canceled pipeline", "canceled", canceled) }() for _, wName := range workflows { @@ -85,7 +85,7 @@ PipelineId: pipelineId, Name: wName, } - l.Debug("cancel pipeline", "wid", wid) + l.DebugContext(r.Context(), "cancel pipeline", "wid", wid) // dont cancel a workflow that already finished st, err := x.Db.GetStatus(wid) @@ -101,7 +101,7 @@ engine.CancelWorkflow(wid) for _, eng := range x.Engines { - l.Debug("destroying workflow", "wid", wid) + l.DebugContext(r.Context(), "destroying workflow", "wid", wid) if err := eng.DestroyWorkflow(r.Context(), wid); err != nil { fail(xrpcerr.GenericError(fmt.Errorf("failed to destroy workflow: %w", err))) return diff --git a/spindle/xrpc/remove_secret.go b/spindle/xrpc/remove_secret.go --- a/spindle/xrpc/remove_secret.go +++ b/spindle/xrpc/remove_secret.go @@ -17,7 +17,7 @@ func (x *Xrpc) RemoveSecret(w http.ResponseWriter, r *http.Request) { l := x.Logger fail := func(e xrpcerr.XrpcError) { - l.Error("failed", "kind", e.Tag, "error", e.Message) + l.ErrorContext(r.Context(), "failed", "kind", e.Tag, "error", e.Message) writeError(w, e, http.StatusBadRequest) } @@ -66,7 +66,7 @@ repoDid := *repoRec.RepoDid if ok, err := x.Enforcer.IsSettingsAllowed(actorDid.String(), rbac.ThisServer, repoDid); !ok || err != nil { - l.Error("insufficient permissions", "did", actorDid.String()) + l.ErrorContext(r.Context(), "insufficient permissions", "did", actorDid.String()) writeError(w, xrpcerr.AccessControlError(actorDid.String()), http.StatusUnauthorized) return } @@ -77,7 +77,7 @@ } err = x.Vault.RemoveSecret(r.Context(), secret) if err != nil { - l.Error("failed to remove secret from vault", "did", actorDid.String(), "err", err) + l.ErrorContext(r.Context(), "failed to remove secret from vault", "did", actorDid.String(), "err", err) writeError(w, xrpcerr.GenericError(err), http.StatusInternalServerError) return } diff --git a/localinfra/observability/loki/loki.yml b/localinfra/observability/loki/loki.yml new file mode 100644 --- /dev/null +++ b/localinfra/observability/loki/loki.yml @@ -0,0 +1,32 @@ +auth_enabled: false + +server: + http_listen_port: 3100 + grpc_listen_port: 9096 + +common: + instance_addr: 127.0.0.1 + path_prefix: /loki + storage: + filesystem: + chunks_directory: /loki/chunks + rules_directory: /loki/rules + replication_factor: 1 + ring: + kvstore: + store: inmemory + +schema_config: + configs: + - from: 2020-10-24 + store: tsdb + object_store: filesystem + schema: v13 + index: + prefix: index_ + period: 24h + +limits_config: + allow_structured_metadata: true + reject_old_samples: true + reject_old_samples_max_age: 168h diff --git a/localinfra/observability/prometheus/prometheus.mill.yml b/localinfra/observability/prometheus/prometheus.mill.yml new file mode 100644 --- /dev/null +++ b/localinfra/observability/prometheus/prometheus.mill.yml @@ -0,0 +1,12 @@ +global: + scrape_interval: 15s + evaluation_interval: 15s + +scrape_configs: + - job_name: 'spindle' + static_configs: + - targets: + - 'spindle:9091' + - 'spindle-executor-a:9091' + - 'spindle-executor-b:9091' + - 'spindle-executor-c:9091' diff --git a/localinfra/observability/prometheus/prometheus.yml b/localinfra/observability/prometheus/prometheus.yml new file mode 100644 --- /dev/null +++ b/localinfra/observability/prometheus/prometheus.yml @@ -0,0 +1,9 @@ +global: + scrape_interval: 15s + evaluation_interval: 15s + +scrape_configs: + - job_name: 'spindle' + static_configs: + - targets: + - 'spindle:9091' diff --git a/localinfra/observability/tempo/tempo.yml b/localinfra/observability/tempo/tempo.yml new file mode 100644 --- /dev/null +++ b/localinfra/observability/tempo/tempo.yml @@ -0,0 +1,23 @@ +server: + http_listen_port: 3200 + +distributor: + receivers: + otlp: + protocols: + http: + endpoint: 0.0.0.0:4318 + +ingester: + max_block_duration: 5m + +storage: + trace: + backend: local + wal: + path: /var/tempo/wal + local: + path: /var/tempo/blocks + +usage_report: + reporting_enabled: false diff --git a/spindle/engines/microvm/cgroup.go b/spindle/engines/microvm/cgroup.go --- a/spindle/engines/microvm/cgroup.go +++ b/spindle/engines/microvm/cgroup.go @@ -15,6 +15,7 @@ cgroups "github.com/containerd/cgroups/v3" "github.com/containerd/cgroups/v3/cgroup2" + "github.com/containerd/cgroups/v3/cgroup2/stats" "github.com/prometheus/procfs" ) @@ -197,6 +198,68 @@ return false } return metrics.MemoryEvents.OomKill > 0 +} + +type CgroupUsage struct { + CPU struct { + UsageUsec uint64 + } + Memory struct { + Usage uint64 + MaxUsage uint64 + SwapUsage uint64 + SwapMaxUsage uint64 + } + Pids struct { + Current uint64 + } + IO struct { + Rbytes uint64 + Wbytes uint64 + Rios uint64 + Wios uint64 + } +} + +func parseCgroupUsage(metrics *stats.Metrics) CgroupUsage { + if metrics == nil { + return CgroupUsage{} + } + var usage CgroupUsage + if metrics.CPU != nil { + usage.CPU.UsageUsec = metrics.CPU.UsageUsec + } + if metrics.Memory != nil { + usage.Memory.Usage = metrics.Memory.Usage + usage.Memory.MaxUsage = metrics.Memory.MaxUsage + usage.Memory.SwapUsage = metrics.Memory.SwapUsage + usage.Memory.SwapMaxUsage = metrics.Memory.SwapMaxUsage + } + if metrics.Pids != nil { + usage.Pids.Current = metrics.Pids.Current + } + if metrics.Io != nil { + for _, entry := range metrics.Io.Usage { + if entry != nil { + usage.IO.Rbytes += entry.Rbytes + usage.IO.Wbytes += entry.Wbytes + usage.IO.Rios += entry.Rios + usage.IO.Wios += entry.Wios + } + } + } + return usage +} + +func (h *CgroupHandle) Stat() (CgroupUsage, bool, error) { + if h == nil || h.manager == nil { + return CgroupUsage{}, false, nil + } + metrics, err := h.manager.Stat() + if err != nil { + return CgroupUsage{}, false, fmt.Errorf("cgroup stat: %w", err) + } + return parseCgroupUsage(metrics), true, nil } // probeRootSubtreeControl enables the domain controllers the engine needs diff --git a/spindle/engines/microvm/cgroup_other.go b/spindle/engines/microvm/cgroup_other.go --- a/spindle/engines/microvm/cgroup_other.go +++ b/spindle/engines/microvm/cgroup_other.go @@ -44,3 +44,28 @@ func (*CgroupHandle) OOMKilled() bool { return false } + +type CgroupUsage struct { + CPU struct { + UsageUsec uint64 + } + Memory struct { + Usage uint64 + MaxUsage uint64 + SwapUsage uint64 + SwapMaxUsage uint64 + } + Pids struct { + Current uint64 + } + IO struct { + Rbytes uint64 + Wbytes uint64 + Rios uint64 + Wios uint64 + } +} + +func (*CgroupHandle) Stat() (CgroupUsage, bool, error) { + return CgroupUsage{}, false, nil +} diff --git a/spindle/engines/microvm/cgroup_test.go b/spindle/engines/microvm/cgroup_test.go --- a/spindle/engines/microvm/cgroup_test.go +++ b/spindle/engines/microvm/cgroup_test.go @@ -8,6 +8,7 @@ "testing" cgroups "github.com/containerd/cgroups/v3" + "github.com/containerd/cgroups/v3/cgroup2/stats" ) func TestSanitizeCgroupName(t *testing.T) { @@ -96,5 +97,71 @@ } if r.Memory.Swap == nil || *r.Memory.Swap != 8*1024*1024 { t.Errorf("swap = %v, want %d bytes", r.Memory.Swap, 8*1024*1024) + } +} + +func TestParseCgroupUsage(t *testing.T) { + metrics := &stats.Metrics{ + CPU: &stats.CPUStat{ + UsageUsec: 12345, + }, + Memory: &stats.MemoryStat{ + Usage: 654321, + MaxUsage: 999999, + SwapUsage: 111111, + SwapMaxUsage: 222222, + }, + Pids: &stats.PidsStat{ + Current: 42, + }, + Io: &stats.IOStat{ + Usage: []*stats.IOEntry{ + { + Rbytes: 100, + Wbytes: 200, + Rios: 5, + Wios: 10, + }, + { + Rbytes: 50, + Wbytes: 80, + Rios: 2, + Wios: 4, + }, + }, + }, + } + + usage := parseCgroupUsage(metrics) + + if usage.CPU.UsageUsec != 12345 { + t.Errorf("CPU.UsageUsec = %d, want 12345", usage.CPU.UsageUsec) + } + if usage.Memory.Usage != 654321 { + t.Errorf("Memory.Usage = %d, want 654321", usage.Memory.Usage) + } + if usage.Memory.MaxUsage != 999999 { + t.Errorf("Memory.MaxUsage = %d, want 999999", usage.Memory.MaxUsage) + } + if usage.Memory.SwapUsage != 111111 { + t.Errorf("Memory.SwapUsage = %d, want 111111", usage.Memory.SwapUsage) + } + if usage.Memory.SwapMaxUsage != 222222 { + t.Errorf("Memory.SwapMaxUsage = %d, want 222222", usage.Memory.SwapMaxUsage) + } + if usage.Pids.Current != 42 { + t.Errorf("Pids.Current = %d, want 42", usage.Pids.Current) + } + if usage.IO.Rbytes != 150 { + t.Errorf("IO.Rbytes = %d, want 150", usage.IO.Rbytes) + } + if usage.IO.Wbytes != 280 { + t.Errorf("IO.Wbytes = %d, want 280", usage.IO.Wbytes) + } + if usage.IO.Rios != 7 { + t.Errorf("IO.Rios = %d, want 7", usage.IO.Rios) + } + if usage.IO.Wios != 14 { + t.Errorf("IO.Wios = %d, want 14", usage.IO.Wios) } } diff --git a/spindle/engines/microvm/cid_test.go b/spindle/engines/microvm/cid_test.go --- a/spindle/engines/microvm/cid_test.go +++ b/spindle/engines/microvm/cid_test.go @@ -1,3 +1,5 @@ +//go:build linux + package microvm import ( diff --git a/spindle/engines/microvm/engine.go b/spindle/engines/microvm/engine.go --- a/spindle/engines/microvm/engine.go +++ b/spindle/engines/microvm/engine.go @@ -28,6 +28,7 @@ "tangled.org/core/spindle/db" "tangled.org/core/spindle/engine" "tangled.org/core/spindle/models" + "tangled.org/core/spindle/observability" "tangled.org/core/spindle/secrets" ) @@ -102,6 +103,25 @@ cleanup: make(map[string][]cleanupFunc), debug: make(map[string]debugTarget), } + + metrics := observability.GetMetrics(ctx) + e.scheduler.OnSnapshot = func(budget, max, used Resources, queueLen int) { + metrics.RecordEnginePoolSnapshot( + used.MemoryMiB, budget.MemoryMiB, max.MemoryMiB, + used.VCPUs, budget.VCPUs, max.VCPUs, + used.DiskMiB, budget.DiskMiB, max.DiskMiB, + queueLen, + ) + } + e.scheduler.OnAcquire = func(_ Resources, allowed bool, reason string) { + metrics.RecordEnginePoolAdmission(allowed, reason) + } + metrics.RecordEnginePoolSnapshot( + 0, budget.MemoryMiB, max.MemoryMiB, + 0, budget.VCPUs, max.VCPUs, + 0, budget.DiskMiB, max.DiskMiB, + 0, + ) if cfg.MicroVMPipelines.DebugSSH.Enabled && cfg.MicroVMPipelines.DebugSSH.ListenAddr != "" { go e.serveDebugSSH(ctx) @@ -289,12 +309,14 @@ return err } state.ReadCache = readCache + stagingDir := filepath.Join(workDir, "upload-cache") uploadCache, err := StartUploadCacheProxy(ctx, cid, e.cfg.NixCache.UploadURL, upstreams, stagingDir, l) if err != nil { return err } state.UploadCache = uploadCache + dnsProxy, err := StartDNSProxy(ctx, cid, l) if err != nil { return err @@ -663,4 +685,20 @@ CPUQuotaPercent: cpuQuotaPercent, IOWeight: cfg.CgroupIOWeight, } +} + +func (e *Engine) WorkflowResourceUsage(wf *models.Workflow) (engine.WorkflowResourceUsage, bool) { + if wf == nil || wf.Data == nil { + return engine.WorkflowResourceUsage{}, false + } + state, ok := wf.Data.(*workflowState) + if !ok || state == nil { + return engine.WorkflowResourceUsage{}, false + } + state.resourceUsageMu.Lock() + defer state.resourceUsageMu.Unlock() + if !state.ResourceUsageAvailable || state.ResourceUsage == nil { + return engine.WorkflowResourceUsage{}, false + } + return *state.ResourceUsage, true } diff --git a/spindle/engines/microvm/qemu.go b/spindle/engines/microvm/qemu.go --- a/spindle/engines/microvm/qemu.go +++ b/spindle/engines/microvm/qemu.go @@ -18,6 +18,7 @@ "strconv" "strings" "sync" + "syscall" "time" "github.com/digitalocean/go-qemu/qmp" @@ -58,6 +59,7 @@ QMPPath string serialLogPath string workDir string + volumePaths map[string]string qmpSocketPath string @@ -153,9 +155,9 @@ } workDir := cfg.WorkDir - handle := &QEMUVMHandle{ - workDir: workDir, + workDir: workDir, + volumePaths: cfg.VolumePaths, } var ok bool @@ -367,6 +369,10 @@ } func (h *QEMUVMHandle) Close() error { + return h.close(nil) +} + +func (h *QEMUVMHandle) close(snapshot func()) error { if h == nil { return nil } @@ -388,6 +394,9 @@ _ = h.slirpCmd.Process.Kill() _ = h.slirpCmd.Wait() h.slirpCmd = nil + } + if snapshot != nil { + snapshot() } if h.qemuLogFile != nil { closeErr = errors.Join(closeErr, h.qemuLogFile.Close()) @@ -606,9 +615,9 @@ resolvPath = filepath.Join(workDir, "qemu-netns-resolv.conf") wrapperPath = filepath.Join(workDir, "qemu-netns-wrapper") - // the guest resolves through shuttle on 127.0.0.1. keep qemu's slirp DNS - // pointed at an unroutable local resolver inside this network namespace so - // direct guest queries to 10.0.3.3 don't bypass the shuttle dns policy. + // the guest resolves through shuttle on 127.0.0.1 + // keep slirp dns pointed at an unroutable resolver in this namespace so + // direct guest queries to 10.0.3.3 cannot bypass the shuttle policy if err := os.WriteFile(resolvPath, []byte("nameserver 127.0.0.1\n"), 0o644); err != nil { return "", "", "", fmt.Errorf("write qemu network namespace resolv.conf: %w", err) } @@ -789,4 +798,26 @@ case <-ticker.C: } } +} + +func (h *QEMUVMHandle) VolumeUsage() (map[string]int64, error) { + if h == nil { + return nil, nil + } + usages := make(map[string]int64) + var errs []error + for _, path := range h.volumePaths { + fi, err := os.Stat(path) + if err != nil { + errs = append(errs, fmt.Errorf("stat volume file %q: %w", path, err)) + continue + } + stat, ok := fi.Sys().(*syscall.Stat_t) + if !ok { + errs = append(errs, fmt.Errorf("stat volume file %q: sys is not syscall.Stat_t", path)) + continue + } + usages[path] = int64(stat.Blocks) * 512 + } + return usages, errors.Join(errs...) } diff --git a/spindle/engines/microvm/vm.go b/spindle/engines/microvm/vm.go --- a/spindle/engines/microvm/vm.go +++ b/spindle/engines/microvm/vm.go @@ -19,9 +19,11 @@ "regexp" "slices" "strings" + "sync" "sync/atomic" "time" + "tangled.org/core/spindle/engine" "tangled.org/core/spindle/models" ) @@ -148,6 +150,10 @@ OOMKilled() bool } +type VMResourceReporter interface { + VolumeUsage() (map[string]int64, error) +} + type VMConfig struct { Image ImageSpec CID uint32 @@ -177,6 +183,9 @@ WorkDir string NixOSToplevelCache nixosToplevelCacheStore StartedAt time.Time // when the VM booted, for the max-lifetime cap + ResourceUsage *engine.WorkflowResourceUsage + ResourceUsageAvailable bool + resourceUsageMu sync.Mutex } func (e *Engine) cleanupState(ctx context.Context, wid models.WorkflowId, state *workflowState) error { @@ -224,7 +233,7 @@ return nil } if vmExited(state.VM) { - return closeIO(&state.VM) + return e.closeVMWithUsage(wid, state) } var poweroffErr error @@ -235,11 +244,8 @@ poweredOff, poweroffErr = e.poweroffViaAgent(gracefulCtx, wid, state) cancel() - if poweredOff { - return closeIO(&state.VM) - } - if vmExited(state.VM) { - return closeIO(&state.VM) + if poweredOff || vmExited(state.VM) { + return e.closeVMWithUsage(wid, state) } } @@ -249,9 +255,21 @@ shutdownErr := state.VM.Shutdown(fallbackCtx) if shutdownErr != nil && !vmExited(state.VM) { e.l.Warn("microVM shutdown fallback failed", "workflow", wid, "error", shutdownErr) - return errors.Join(poweroffErr, shutdownErr, closeIO(&state.VM)) + return errors.Join(poweroffErr, shutdownErr, e.closeVMWithUsage(wid, state)) } + return e.closeVMWithUsage(wid, state) +} + +func (e *Engine) closeVMWithUsage(wid models.WorkflowId, state *workflowState) error { + if qvm, ok := state.VM.(*QEMUVMHandle); ok { + err := qvm.close(func() { + e.captureResourceUsage(wid, state) + }) + state.VM = nil + return err + } + e.captureResourceUsage(wid, state) return closeIO(&state.VM) } @@ -421,4 +439,72 @@ return errors.New("guest kernel panic"), true } return nil, false +} + +func (e *Engine) captureResourceUsage(wid models.WorkflowId, state *workflowState) { + if state == nil { + return + } + + state.resourceUsageMu.Lock() + defer state.resourceUsageMu.Unlock() + if state.ResourceUsageAvailable { + return + } + + var usage engine.WorkflowResourceUsage + + var cgroupErr error + var volumesErr error + var cgroupCaptured bool + var volumesCaptured bool + + if qvm, ok := state.VM.(*QEMUVMHandle); ok && qvm != nil { + cgroupUsage, ok, err := qvm.cgroup.Stat() + if err != nil { + cgroupErr = err + } else if ok { + cgroupCaptured = true + usage.CPUUsec = cgroupUsage.CPU.UsageUsec + usage.MemoryCurrentBytes = cgroupUsage.Memory.Usage + usage.MemoryPeakBytes = cgroupUsage.Memory.MaxUsage + usage.SwapCurrentBytes = cgroupUsage.Memory.SwapUsage + usage.SwapPeakBytes = cgroupUsage.Memory.SwapMaxUsage + usage.PIDsCurrent = cgroupUsage.Pids.Current + usage.IOReadBytes = cgroupUsage.IO.Rbytes + usage.IOWriteBytes = cgroupUsage.IO.Wbytes + usage.IOReadOps = cgroupUsage.IO.Rios + usage.IOWriteOps = cgroupUsage.IO.Wios + usage.CgroupAvailable = true + } + } + + if reporter, ok := state.VM.(VMResourceReporter); ok && reporter != nil { + volUsage, err := reporter.VolumeUsage() + if err != nil { + volumesErr = err + } + if len(volUsage) > 0 { + volumesCaptured = true + for _, allocated := range volUsage { + if allocated > 0 { + usage.VolumeAllocatedBytes += uint64(allocated) + } + } + usage.VolumeAvailable = err == nil + } + } + + if cgroupErr != nil || volumesErr != nil { + e.l.Warn("resource usage measurement failed", + "workflow_id", wid.String(), + "cgroup_error", cgroupErr, + "volumes_error", volumesErr, + ) + } + + if cgroupCaptured || volumesCaptured { + state.ResourceUsage = &usage + state.ResourceUsageAvailable = true + } } diff --git a/spindle/engines/microvm/vm_test.go b/spindle/engines/microvm/vm_test.go --- a/spindle/engines/microvm/vm_test.go +++ b/spindle/engines/microvm/vm_test.go @@ -1,9 +1,14 @@ +//go:build linux + package microvm import ( "context" + "crypto/rand" "errors" "log/slog" + "os" + "os/exec" "testing" "tangled.org/core/spindle/models" @@ -61,5 +66,111 @@ t.Fatal("expected vm handle to be closed") } }) + } +} + +func TestVolumeUsage(t *testing.T) { + tmpFile, err := os.CreateTemp("", "spindle-test-volume") + if err != nil { + t.Fatal(err) + } + defer os.Remove(tmpFile.Name()) + defer tmpFile.Close() + + data := make([]byte, 1024*1024) + if _, err := rand.Read(data); err != nil { + t.Fatal(err) + } + if _, err := tmpFile.Write(data); err != nil { + t.Fatal(err) + } + if err := tmpFile.Sync(); err != nil { + t.Fatal(err) + } + + h := &QEMUVMHandle{ + volumePaths: map[string]string{ + "vol1": tmpFile.Name(), + }, + } + + usages, err := h.VolumeUsage() + if err != nil { + t.Fatal(err) + } + + allocated, ok := usages[tmpFile.Name()] + if !ok { + t.Fatalf("expected path %q in usages, got %+v", tmpFile.Name(), usages) + } + + if allocated < 1024*1024 { + t.Errorf("expected at least 1MB allocated, got %d", allocated) + } +} + +func TestQEMUCloseSnapshotsAfterProcessExit(t *testing.T) { + cmd := exec.Command("sleep", "30") + if err := cmd.Start(); err != nil { + t.Fatal(err) + } + h := &QEMUVMHandle{ + Process: cmd.Process, + done: make(chan struct{}), + } + go func() { + err := cmd.Wait() + h.waitErrMu.Lock() + h.waitErr = err + h.waitErrMu.Unlock() + close(h.done) + }() + + var waitedDuringSnapshot bool + if err := h.close(func() { + select { + case <-h.done: + waitedDuringSnapshot = true + default: + } + }); err != nil { + t.Fatal(err) + } + if !waitedDuringSnapshot { + t.Fatal("resource snapshot ran before QEMU wait completed") + } +} + +func TestCaptureResourceUsageMarksPartialVolumeSnapshotUnavailable(t *testing.T) { + tmpFile, err := os.CreateTemp("", "spindle-test-volume") + if err != nil { + t.Fatal(err) + } + defer os.Remove(tmpFile.Name()) + defer tmpFile.Close() + if _, err := tmpFile.Write(make([]byte, 4096)); err != nil { + t.Fatal(err) + } + if err := tmpFile.Sync(); err != nil { + t.Fatal(err) + } + + state := &workflowState{VM: &QEMUVMHandle{ + volumePaths: map[string]string{ + "present": tmpFile.Name(), + "missing": tmpFile.Name() + "-missing", + }, + }} + e := &Engine{l: slog.New(slog.NewTextHandler(os.Stderr, nil))} + e.captureResourceUsage(models.WorkflowId{}, state) + + if !state.ResourceUsageAvailable || state.ResourceUsage == nil { + t.Fatal("partial resource snapshot was discarded") + } + if state.ResourceUsage.VolumeAvailable { + t.Fatal("partial volume snapshot marked available") + } + if state.ResourceUsage.VolumeAllocatedBytes == 0 { + t.Fatal("partial volume snapshot lost successful measurements") } } diff --git a/spindle/mill/executor/executor.go b/spindle/mill/executor/executor.go --- a/spindle/mill/executor/executor.go +++ b/spindle/mill/executor/executor.go @@ -5,17 +5,18 @@ "encoding/json" "errors" "fmt" + "log/slog" "maps" "net/http" "runtime" + "strings" "sync" "time" "github.com/bluesky-social/indigo/atproto/syntax" "github.com/gorilla/websocket" - "log/slog" - "strings" - + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/trace" "tangled.org/core/api/tangled" "tangled.org/core/netutil" "tangled.org/core/notifier" @@ -26,6 +27,7 @@ millproto "tangled.org/core/spindle/mill/proto" millv1 "tangled.org/core/spindle/mill/proto/gen" "tangled.org/core/spindle/models" + "tangled.org/core/spindle/observability" ) const ( @@ -73,6 +75,7 @@ snapshotMu sync.Mutex nextSeqno uint64 + lifecycleCtx context.Context jobsWG sync.WaitGroup } @@ -86,11 +89,12 @@ repoDid syntax.DID vault *memVault - committed bool - cancelled bool - cancel context.CancelFunc - ttlTimer *time.Timer - stopTail func() + committed bool + cancelled bool + cancel context.CancelFunc + ttlTimer *time.Timer + stopTail func() + traceParent trace.SpanContext } type messageEncoder interface { @@ -297,6 +301,7 @@ } } + func (e *Executor) sendReject(leaseID string, reason string, class millv1.RejectClass) { e.send(&millproto.Message{ReserveResult: &millv1.ReserveResult{ LeaseId: leaseID, @@ -322,6 +327,24 @@ } func (e *Executor) handleReserve(ctx context.Context, rs *millv1.ReserveSeat) { + parentCtx := e.lifecycleCtx + if parentCtx == nil { + parentCtx = ctx + } + if parentCtx == nil { + parentCtx = context.Background() + } + reserveCtx := observability.ExtractFromTraceparentAndTracestate(parentCtx, rs.GetTraceparent(), rs.GetTracestate()) + reserveCtx, span := observability.Tracer().Start(reserveCtx, "executor.assignment") + accepted := false + defer func() { + if accepted { + span.SetStatus(codes.Ok, "accepted") + } else { + span.SetStatus(codes.Error, "assignment rejected") + } + span.End() + }() reject := func(reason string, class millv1.RejectClass) { e.sendReject(rs.GetLeaseId(), reason, class) } @@ -379,7 +402,7 @@ } maps.Copy(wf.Environment, models.PipelineEnvVars(tpl.TriggerMetadata, pipelineId)) - slot, err := slotter.AcquireWorkflowSlot(ctx, wid, wf, engine.NoWait) + slot, err := slotter.AcquireWorkflowSlot(reserveCtx, wid, wf, engine.NoWait) if err != nil { class := millv1.RejectClass_REJECT_CLASS_INCOMPATIBLE if errors.Is(err, engine.ErrNoWorkflowSlots) { @@ -395,12 +418,13 @@ } res := &reservation{ - leaseID: rs.GetLeaseId(), - wid: wid, - realEngine: realEngine, - slot: slot, - wf: wf, - repoDid: repoDid, + leaseID: rs.GetLeaseId(), + wid: wid, + realEngine: realEngine, + slot: slot, + wf: wf, + repoDid: repoDid, + traceParent: trace.SpanContextFromContext(reserveCtx), } e.snapshotMu.Lock() @@ -423,6 +447,7 @@ LeaseId: rs.GetLeaseId(), Accepted: true, }}) + accepted = true e.pushSnapshotLocked() e.snapshotMu.Unlock() } @@ -445,7 +470,20 @@ res.ttlTimer.Stop() } - jobCtx, cancel := context.WithCancel(e.lifecycleCtx) + parentCtx := e.lifecycleCtx + if parentCtx == nil { + parentCtx = ctx + } + if parentCtx == nil { + parentCtx = context.Background() + } + if res.traceParent.IsValid() { + parentCtx = trace.ContextWithSpanContext(parentCtx, res.traceParent) + } + commitCtx := observability.ExtractFromTraceparentAndTracestate(parentCtx, cl.GetTraceparent(), cl.GetTracestate()) + runCtx, runSpan := observability.Tracer().Start(commitCtx, "executor.run") + + jobCtx, cancel := context.WithCancel(runCtx) res.cancel = cancel e.mu.Unlock() @@ -462,6 +500,7 @@ e.jobsWG.Add(1) go func() { defer e.jobsWG.Done() + defer runSpan.End() engine.StartWorkflows(e.l, vault, e.cfg, nil, e.db, e.n, jobCtx, pipeline, res.wid.PipelineId) }() @@ -671,4 +710,39 @@ out = append(out, label) } return out +} + +func (e *Executor) RegisterMetrics(metrics *observability.Metrics) { + if metrics == nil { + return + } + metrics.RegisterExecutorGauges( + func() float64 { + e.mu.Lock() + defer e.mu.Unlock() + reservations := 0 + for _, r := range e.active { + if !r.committed { + reservations++ + } + } + return float64(reservations) + }, + func() float64 { + e.mu.Lock() + defer e.mu.Unlock() + jobs := 0 + for _, r := range e.active { + if r.committed { + jobs++ + } + } + return float64(jobs) + }, + func() float64 { + e.eventMu.Lock() + defer e.eventMu.Unlock() + return float64(e.outboxBytes) + }, + ) } diff --git a/spindle/mill/executor/reserved.go b/spindle/mill/executor/reserved.go --- a/spindle/mill/executor/reserved.go +++ b/spindle/mill/executor/reserved.go @@ -3,6 +3,7 @@ import ( "context" "fmt" + "strings" "sync" "tangled.org/core/spindle/engine" @@ -22,6 +23,17 @@ return &reservedEngine{Engine: inner, slot: slot} } +func (e *reservedEngine) MetricEngineName() string { + if named, ok := e.Engine.(interface{ MetricEngineName() string }); ok { + return named.MetricEngineName() + } + name := strings.TrimPrefix(fmt.Sprintf("%T", e.Engine), "*") + if idx := strings.Index(name, "."); idx != -1 { + name = name[:idx] + } + return name +} + // hands back the pre-acquired slot exactly once, a second acquire would // double-count it func (e *reservedEngine) AcquireWorkflowSlot(ctx context.Context, wid models.WorkflowId, wf *models.Workflow, _ engine.AcquireMode) (engine.WorkflowSlot, error) { @@ -34,4 +46,12 @@ return nil, fmt.Errorf("reserved slot already consumed") } return slot, nil +} + +func (e *reservedEngine) WorkflowResourceUsage(wf *models.Workflow) (engine.WorkflowResourceUsage, bool) { + reporter, ok := e.Engine.(engine.WorkflowResourceUsageReporter) + if !ok { + return engine.WorkflowResourceUsage{}, false + } + return reporter.WorkflowResourceUsage(wf) } diff --git a/spindle/mill/proto/gen/mill.pb.go b/spindle/mill/proto/gen/mill.pb.go --- a/spindle/mill/proto/gen/mill.pb.go +++ b/spindle/mill/proto/gen/mill.pb.go @@ -423,6 +423,8 @@ Knot string `protobuf:"bytes,5,opt,name=knot,proto3" json:"knot,omitempty"` Rkey string `protobuf:"bytes,6,opt,name=rkey,proto3" json:"rkey,omitempty"` TtlSeconds uint32 `protobuf:"varint,7,opt,name=ttl_seconds,json=ttlSeconds,proto3" json:"ttl_seconds,omitempty"` + Traceparent string `protobuf:"bytes,8,opt,name=traceparent,proto3" json:"traceparent,omitempty"` + Tracestate string `protobuf:"bytes,9,opt,name=tracestate,proto3" json:"tracestate,omitempty"` unknownFields protoimpl.UnknownFields sizeCache protoimpl.SizeCache } @@ -504,6 +506,20 @@ return x.TtlSeconds } return 0 +} + +func (x *ReserveSeat) GetTraceparent() string { + if x != nil { + return x.Traceparent + } + return "" +} + +func (x *ReserveSeat) GetTracestate() string { + if x != nil { + return x.Tracestate + } + return "" } type ReserveResult struct { @@ -632,6 +648,8 @@ state protoimpl.MessageState `protogen:"open.v1"` LeaseId string `protobuf:"bytes,1,opt,name=lease_id,json=leaseId,proto3" json:"lease_id,omitempty"` Secrets []*Secret `protobuf:"bytes,2,rep,name=secrets,proto3" json:"secrets,omitempty"` + Traceparent string `protobuf:"bytes,3,opt,name=traceparent,proto3" json:"traceparent,omitempty"` + Tracestate string `protobuf:"bytes,4,opt,name=tracestate,proto3" json:"tracestate,omitempty"` unknownFields protoimpl.UnknownFields sizeCache protoimpl.SizeCache } @@ -678,6 +696,20 @@ return x.Secrets } return nil +} + +func (x *CommitLease) GetTraceparent() string { + if x != nil { + return x.Traceparent + } + return "" +} + +func (x *CommitLease) GetTracestate() string { + if x != nil { + return x.Tracestate + } + return "" } type Committed struct { @@ -1470,7 +1502,7 @@ "\x10active_lease_ids\x18\x03 \x03(\tR\x0eactiveLeaseIds\x1a_\n" + "\fEnginesEntry\x12\x10\n" + "\x03key\x18\x01 \x01(\tR\x03key\x129\n" + - "\x05value\x18\x02 \x01(\v2#.spindle.mill.v1.EngineAvailabilityR\x05value:\x028\x01\"\x80\x02\n" + + "\x05value\x18\x02 \x01(\v2#.spindle.mill.v1.EngineAvailabilityR\x05value:\x028\x01\"\xc2\x02\n" + "\vReserveSeat\x12\"\n" + "\blease_id\x18\x01 \x01(\tB\a\xbaH\x04r\x02\x10\x01R\aleaseId\x12,\n" + "\rtarget_engine\x18\x02 \x01(\tB\a\xbaH\x04r\x02\x10\x01R\ftargetEngine\x12*\n" + @@ -1479,7 +1511,11 @@ "\x04knot\x18\x05 \x01(\tR\x04knot\x12\x12\n" + "\x04rkey\x18\x06 \x01(\tR\x04rkey\x12\x1f\n" + "\vttl_seconds\x18\a \x01(\rR\n" + - "ttlSeconds\"\xbf\x01\n" + + "ttlSeconds\x12 \n" + + "\vtraceparent\x18\b \x01(\tR\vtraceparent\x12\x1e\n" + + "\n" + + "tracestate\x18\t \x01(\tR\n" + + "tracestate\"\xbf\x01\n" + "\rReserveResult\x12\"\n" + "\blease_id\x18\x01 \x01(\tB\a\xbaH\x04r\x02\x10\x01R\aleaseId\x12\x1a\n" + "\baccepted\x18\x02 \x01(\bR\baccepted\x12#\n" + @@ -1487,10 +1523,14 @@ "\freject_class\x18\x04 \x01(\x0e2\x1c.spindle.mill.v1.RejectClassB\b\xbaH\x05\x82\x01\x02\x10\x01R\vrejectClass\"0\n" + "\x06Secret\x12\x10\n" + "\x03key\x18\x01 \x01(\tR\x03key\x12\x14\n" + - "\x05value\x18\x02 \x01(\tR\x05value\"d\n" + + "\x05value\x18\x02 \x01(\tR\x05value\"\xa6\x01\n" + "\vCommitLease\x12\"\n" + "\blease_id\x18\x01 \x01(\tB\a\xbaH\x04r\x02\x10\x01R\aleaseId\x121\n" + - "\asecrets\x18\x02 \x03(\v2\x17.spindle.mill.v1.SecretR\asecrets\"/\n" + + "\asecrets\x18\x02 \x03(\v2\x17.spindle.mill.v1.SecretR\asecrets\x12 \n" + + "\vtraceparent\x18\x03 \x01(\tR\vtraceparent\x12\x1e\n" + + "\n" + + "tracestate\x18\x04 \x01(\tR\n" + + "tracestate\"/\n" + "\tCommitted\x12\"\n" + "\blease_id\x18\x01 \x01(\tB\a\xbaH\x04r\x02\x10\x01R\aleaseId\"2\n" + "\fReleaseLease\x12\"\n" + diff --git a/localinfra/observability/grafana/provisioning/dashboards/spindle.json b/localinfra/observability/grafana/provisioning/dashboards/spindle.json new file mode 100644 --- /dev/null +++ b/localinfra/observability/grafana/provisioning/dashboards/spindle.json @@ -0,0 +1,2525 @@ +{ + "annotations": { + "list": [ + { + "builtIn": 1, + "datasource": { + "type": "grafana", + "uid": "-- Grafana --" + }, + "enable": true, + "hide": true, + "name": "Annotations & Alerts", + "type": "dashboard" + } + ] + }, + "editable": true, + "fiscalYearStartMonth": 0, + "graphTooltip": 1, + "id": null, + "links": [], + "panels": [ + { + "collapsed": false, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 0 + }, + "id": 100, + "title": "System Status & Health", + "type": "row", + "panels": [] + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "mappings": [], + "thresholds": { + "mode": "absolute", + "steps": [ + { + "color": "red", + "value": null + }, + { + "color": "green", + "value": 1 + } + ] + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 4, + "w": 12, + "x": 0, + "y": 1 + }, + "id": 1, + "title": "Targets Up", + "description": "Indicates whether the Spindle instances are successfully scraped by Prometheus.", + "type": "stat", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "up{job=\"spindle\", instance=~\"$instance\"}", + "legendFormat": "{{instance}}", + "range": true, + "refId": "A" + } + ], + "options": { + "colorMode": "value", + "graphMode": "area", + "justifyMode": "auto", + "orientation": "auto", + "reduceOptions": { + "calcs": [ + "lastNotNull" + ], + "fields": "", + "values": false + }, + "textMode": "auto" + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "mappings": [], + "thresholds": { + "mode": "absolute", + "steps": [ + { + "color": "green", + "value": null + }, + { + "color": "yellow", + "value": 0.01 + }, + { + "color": "red", + "value": 0.05 + } + ] + }, + "unit": "percentunit", + "noValue": "No data" + }, + "overrides": [] + }, + "gridPos": { + "h": 4, + "w": 12, + "x": 12, + "y": 1 + }, + "id": 3, + "title": "5xx Error Ratio", + "description": "Ratio of HTTP 5xx errors to total HTTP requests.", + "type": "stat", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "(sum(rate(spindle_http_requests_total{job=\"spindle\", instance=~\"$instance\", route=~\"$route\", status_class=\"5xx\"}[$__rate_interval])) or (0 * sum(rate(spindle_http_requests_total{job=\"spindle\", instance=~\"$instance\", route=~\"$route\"}[$__rate_interval])))) / sum(rate(spindle_http_requests_total{job=\"spindle\", instance=~\"$instance\", route=~\"$route\"}[$__rate_interval]))", + "legendFormat": "5xx Error Ratio", + "range": true, + "refId": "A" + } + ], + "options": { + "colorMode": "value", + "graphMode": "area", + "justifyMode": "auto", + "orientation": "auto", + "reduceOptions": { + "calcs": [ + "lastNotNull" + ], + "fields": "", + "values": false + }, + "textMode": "auto" + } + }, + { + "collapsed": false, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 5 + }, + "id": 200, + "title": "HTTP Server API Performance", + "type": "row", + "panels": [] + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "reqps" + }, + "overrides": [ + { + "matcher": { + "id": "byFrameRefID", + "options": "B" + }, + "properties": [ + { + "id": "unit", + "value": "short" + } + ] + } + ] + }, + "gridPos": { + "h": 8, + "w": 12, + "x": 0, + "y": 6 + }, + "id": 10, + "title": "HTTP Request Rate & In-Flight", + "description": "Total count of HTTP requests per second split by method, route, and status class, and current in-flight requests.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_http_requests_total{job=\"spindle\", instance=~\"$instance\", route=~\"$route\"}[$__rate_interval])) by (route, method, status_class)", + "legendFormat": "{{method}} {{route}} ({{status_class}})", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_http_requests_in_flight{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "In-Flight Requests", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "s" + }, + "overrides": [] + }, + "gridPos": { + "h": 8, + "w": 12, + "x": 12, + "y": 6 + }, + "id": 11, + "title": "HTTP Request Latency Percentiles", + "description": "HTTP request latency percentiles (p50, p90, p99) across all endpoints.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "histogram_quantile(0.99, sum(rate(spindle_http_request_duration_seconds_bucket{job=\"spindle\", instance=~\"$instance\", route=~\"$route\"}[$__rate_interval])) by (le))", + "legendFormat": "p99", + "range": true, + "refId": "A", + "exemplar": true + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "histogram_quantile(0.90, sum(rate(spindle_http_request_duration_seconds_bucket{job=\"spindle\", instance=~\"$instance\", route=~\"$route\"}[$__rate_interval])) by (le))", + "legendFormat": "p90", + "range": true, + "refId": "B", + "exemplar": true + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "histogram_quantile(0.50, sum(rate(spindle_http_request_duration_seconds_bucket{job=\"spindle\", instance=~\"$instance\", route=~\"$route\"}[$__rate_interval])) by (le))", + "legendFormat": "p50", + "range": true, + "refId": "C", + "exemplar": true + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "collapsed": false, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 14 + }, + "id": 300, + "title": "Workflow & Step Execution", + "type": "row", + "panels": [] + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 8, + "x": 0, + "y": 15 + }, + "id": 13, + "title": "Active Workflows & Steps", + "description": "Current active workflow and step counts by engine type.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_workflows_active{job=\"spindle\", instance=~\"$instance\"}) by (engine)", + "legendFormat": "{{engine}} Active Workflows", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_steps_active{job=\"spindle\", instance=~\"$instance\"}) by (engine)", + "legendFormat": "{{engine}} Active Steps", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "pps" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 8, + "x": 8, + "y": 15 + }, + "id": 14, + "title": "Workflow & Step Completion Rates", + "description": "Rate of completed workflows and steps per second.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_workflows_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (engine, result)", + "legendFormat": "{{engine}} Completed: {{result}}", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_steps_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (engine, status)", + "legendFormat": "{{engine}} Step Completed: {{status}}", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "s" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 8, + "x": 16, + "y": 15 + }, + "id": 16, + "title": "Workflow & Step Latency & Durations", + "description": "Workflow and step execution duration percentiles and average durations.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "histogram_quantile(0.99, sum(rate(spindle_workflow_duration_seconds_bucket{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (le, engine))", + "legendFormat": "{{engine}} Workflow p99", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "histogram_quantile(0.90, sum(rate(spindle_workflow_duration_seconds_bucket{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (le, engine))", + "legendFormat": "{{engine}} Workflow p90", + "range": true, + "refId": "B" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "histogram_quantile(0.99, sum(rate(spindle_step_duration_seconds_bucket{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (le, engine))", + "legendFormat": "{{engine}} Step p99", + "range": true, + "refId": "C" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "histogram_quantile(0.90, sum(rate(spindle_step_duration_seconds_bucket{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (le, engine))", + "legendFormat": "{{engine}} Step p90", + "range": true, + "refId": "D" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_workflow_duration_seconds_sum{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) / sum(rate(spindle_workflow_duration_seconds_count{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval]))", + "legendFormat": "Avg Workflow Duration", + "range": true, + "refId": "E" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_step_duration_seconds_sum{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) / sum(rate(spindle_step_duration_seconds_count{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval]))", + "legendFormat": "Avg Step Duration", + "range": true, + "refId": "F" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "collapsed": false, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 22 + }, + "id": 400, + "title": "Ingestion, Queues, & Placement", + "type": "row", + "panels": [] + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "reqps" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 24, + "x": 0, + "y": 23 + }, + "id": 20, + "title": "Ingestion, Job Queues & Mill Placements", + "description": "Event ingestion rate, job queue activity rate, mill placement admission rate, and execution outcome rates.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_event_ingestion_outcomes_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (consumer, status)", + "legendFormat": "Consumer: {{consumer}} Status: {{status}}", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_job_queue_activity_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (action)", + "legendFormat": "Action: {{action}}", + "range": true, + "refId": "B" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_mill_placement_admission_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (status, reason)", + "legendFormat": "Admission: {{status}} ({{reason}})", + "range": true, + "refId": "C" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_mill_placement_results_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (result)", + "legendFormat": "Result: {{result}}", + "range": true, + "refId": "D" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "collapsed": false, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 30 + }, + "id": 500, + "title": "Admission Quotas & Decisions", + "type": "row", + "panels": [] + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "suffix: MiB" + }, + "overrides": [ + { + "matcher": { + "id": "byFrameRefID", + "options": "C" + }, + "properties": [ + { + "id": "unit", + "value": "short" + } + ] + }, + { + "matcher": { + "id": "byFrameRefID", + "options": "D" + }, + "properties": [ + { + "id": "unit", + "value": "short" + } + ] + } + ] + }, + "gridPos": { + "h": 7, + "w": 8, + "x": 0, + "y": 31 + }, + "id": 24, + "title": "Engine Resource Pool", + "description": "Physical scheduler pool of the local engine (used, limit, max_request). This is host capacity, not per-user or per-repository quota.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum by (state) (spindle_engine_pool_memory_mib{job=\"spindle\", instance=~\"$instance\", state=~\"used|limit\"})", + "legendFormat": "Memory {{state}}", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "max by (state) (spindle_engine_pool_memory_mib{job=\"spindle\", instance=~\"$instance\", state=\"max_request\"})", + "legendFormat": "Memory {{state}}", + "range": true, + "refId": "B" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum by (state) (spindle_engine_pool_vcpus{job=\"spindle\", instance=~\"$instance\", state=~\"used|limit\"})", + "legendFormat": "vCPUs {{state}}", + "range": true, + "refId": "C" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "max by (state) (spindle_engine_pool_vcpus{job=\"spindle\", instance=~\"$instance\", state=\"max_request\"})", + "legendFormat": "vCPUs {{state}}", + "range": true, + "refId": "D" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum by (state) (spindle_engine_pool_disk_mib{job=\"spindle\", instance=~\"$instance\", state=~\"used|limit\"})", + "legendFormat": "Disk {{state}}", + "range": true, + "refId": "E" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "max by (state) (spindle_engine_pool_disk_mib{job=\"spindle\", instance=~\"$instance\", state=\"max_request\"})", + "legendFormat": "Disk {{state}}", + "range": true, + "refId": "F" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "ops" + }, + "overrides": [ + { + "matcher": { + "id": "byFrameRefID", + "options": "B" + }, + "properties": [ + { + "id": "unit", + "value": "percentunit" + } + ] + } + ] + }, + "gridPos": { + "h": 7, + "w": 8, + "x": 8, + "y": 31 + }, + "id": 27, + "title": "Quota Decisions & Rejection Rate", + "description": "Rate of quota admission decisions by kind, resource, decision and reason, with the share of decisions that were not granted immediately.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_quota_decisions_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (kind, resource, decision, reason)", + "legendFormat": "{{kind}}/{{resource}} {{decision}} ({{reason}})", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "(sum(rate(spindle_quota_decisions_total{job=\"spindle\", instance=~\"$instance\", decision!=\"allowed\"}[$__rate_interval])) by (kind) or (sum(rate(spindle_quota_decisions_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (kind) * 0)) / clamp_min(sum(rate(spindle_quota_decisions_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (kind), 0.000001)", + "legendFormat": "Rejection rate: {{kind}}", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [ + { + "matcher": { + "id": "byFrameRefID", + "options": "B" + }, + "properties": [ + { + "id": "unit", + "value": "s" + } + ] + } + ] + }, + "gridPos": { + "h": 7, + "w": 8, + "x": 16, + "y": 31 + }, + "id": 28, + "title": "Quota Waits & Engine Pool Pressure", + "description": "Requests queued by the fair quota manager, the p95 time they wait before a grant, and the local engine scheduler queue and admission rate for comparison. Engine pool series are host capacity, not tenant quota.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_quota_wait_depth{job=\"spindle\", instance=~\"$instance\"}) by (kind)", + "legendFormat": "Waiting: {{kind}}", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "histogram_quantile(0.95, sum(rate(spindle_quota_wait_duration_seconds_bucket{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (le, kind, resource))", + "legendFormat": "p95 wait: {{kind}}/{{resource}}", + "range": true, + "refId": "B" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_engine_pool_queue_depth{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Engine pool queue", + "range": true, + "refId": "C" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_engine_pool_admission_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (decision, reason)", + "legendFormat": "Engine pool: {{decision}} ({{reason}})", + "range": true, + "refId": "D" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "collapsed": false, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 38 + }, + "id": 600, + "title": "Mill & Executor States", + "type": "row", + "panels": [] + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [ + { + "matcher": { + "id": "byFrameRefID", + "options": "C" + }, + "properties": [ + { + "id": "unit", + "value": "ops" + } + ] + } + ] + }, + "gridPos": { + "h": 7, + "w": 12, + "x": 0, + "y": 39 + }, + "id": 29, + "title": "Mill States & Sessions", + "description": "Mill executor sessions, job queue, limits, and lease/reservation occupancy. No data is displayed if the selected instance does not run in the Mill role.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_mill_active_sessions{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Active Sessions", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_mill_disconnected_sessions{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Disconnected Sessions", + "range": true, + "refId": "B" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_mill_reconnects_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval]))", + "legendFormat": "Reconnects Rate", + "range": true, + "refId": "C" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_mill_pending_jobs{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Pending Jobs", + "range": true, + "refId": "D" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_mill_max_pending_jobs{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Max Pending Jobs", + "range": true, + "refId": "E" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_mill_leases_active{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Active Leases", + "range": true, + "refId": "F" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_mill_reservations_active{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Active Seat Reservations", + "range": true, + "refId": "G" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 12, + "x": 12, + "y": 39 + }, + "id": 31, + "title": "Executor States & Buffers", + "description": "Executor active seat reservations, running jobs, and outbox buffer size in bytes. No data is displayed if the selected instance does not run in the Executor role.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_executor_reservations_active{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Reservations Active", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_executor_jobs_active{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Jobs Active", + "range": true, + "refId": "B" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_executor_outbox_bytes{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Outbox Bytes", + "range": true, + "refId": "C" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "collapsed": false, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 46 + }, + "id": 1000, + "title": "Quota Usage & Cache Uploads", + "type": "row", + "panels": [] + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "bytes" + }, + "overrides": [ + { + "matcher": { + "id": "byFrameRefID", + "options": "B" + }, + "properties": [ + { + "id": "unit", + "value": "short" + } + ] + } + ] + }, + "gridPos": { + "h": 7, + "w": 8, + "x": 0, + "y": 47 + }, + "id": 1001, + "title": "Cache Storage Quota Usage & Subjects", + "description": "Committed cache storage quota usage in bytes and count of quota subjects by scope and status.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_quota_usage{job=\"spindle\", instance=~\"$instance\", resource=\"cache_storage_bytes\"}) by (scope)", + "legendFormat": "Usage: {{scope}}", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_quota_subjects{job=\"spindle\", instance=~\"$instance\", resource=\"cache_storage_bytes\"}) by (scope, status)", + "legendFormat": "Subjects: {{scope}} ({{status}})", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 8, + "x": 8, + "y": 47 + }, + "id": 1002, + "title": "Workflow, vCPU, Memory & Disk Quota Usage", + "description": "Committed workflow, vCPU, memory (MiB) and disk (MiB) quota usage and subject counts by scope and resource.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_quota_usage{job=\"spindle\", instance=~\"$instance\", resource=~\"workflows|vcpus|memory_mib|disk_mib\"}) by (scope, resource)", + "legendFormat": "Usage: {{scope}} {{resource}}", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_quota_subjects{job=\"spindle\", instance=~\"$instance\", resource=~\"workflows|vcpus|memory_mib|disk_mib\"}) by (scope, resource, status)", + "legendFormat": "Subjects: {{scope}} {{resource}} ({{status}})", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 8, + "x": 16, + "y": 47 + }, + "id": 1003, + "title": "Cache Uploads (Count & Bytes)", + "description": "Rate of cache upload completions (outcome counts and throughput bytes/sec) by backend and result.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_cache_uploads_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (backend, result)", + "legendFormat": "Uploads: {{backend}} ({{result}})", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_cache_upload_bytes_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (backend, result)", + "legendFormat": "Bytes: {{backend}} ({{result}})", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "collapsed": true, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 54 + }, + "id": 700, + "title": "Database Connection Pool & Performance", + "type": "row", + "panels": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 6, + "x": 0, + "y": 54 + }, + "id": 28, + "title": "Database Connection Counts", + "description": "Database connection pool status (limits, open, in-use, idle connections).", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_db_max_open_connections{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Max Open", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_db_open_connections{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Open", + "range": true, + "refId": "B" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_db_in_use_connections{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "In Use", + "range": true, + "refId": "C" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_db_idle_connections{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Idle", + "range": true, + "refId": "D" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "ops" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 6, + "x": 6, + "y": 54 + }, + "id": 29, + "title": "Database Pool Rates & Failures", + "description": "Database pool operation rates, closed connection rates, and collection failures.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_db_wait_count{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval]))", + "legendFormat": "Wait Count Rate", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_db_max_idle_closed{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval]))", + "legendFormat": "Max Idle Closed Rate", + "range": true, + "refId": "B" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_db_max_lifetime_closed{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval]))", + "legendFormat": "Max Lifetime Closed Rate", + "range": true, + "refId": "C" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_collection_failures_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval]))", + "legendFormat": "Collection Failures Rate", + "range": true, + "refId": "D" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "s" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 6, + "x": 12, + "y": 54 + }, + "id": 30, + "title": "Average Database Wait Duration", + "description": "Average time spent blocked for each database connection wait.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_db_wait_duration_seconds{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) / sum(rate(spindle_db_wait_count{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval]))", + "legendFormat": "Average Wait Duration", + "range": true, + "refId": "A" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 6, + "x": 18, + "y": 54 + }, + "id": 31, + "title": "Database Workflow & Queue Counts", + "description": "Current workflow counts by status and jobs waiting in the durable database queue.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_db_workflow_status_count{job=\"spindle\", instance=~\"$instance\"}) by (status)", + "legendFormat": "{{status}}", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_db_queued_jobs{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "queued jobs", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + } + ] + }, + { + "collapsed": true, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 55 + }, + "id": 800, + "title": "Debug Jump System", + "type": "row", + "panels": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 12, + "x": 0, + "y": 62 + }, + "id": 32, + "title": "Debug Jump Connections", + "description": "Current active and maximum allowed debug jump connections.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_jump_active_connections{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Active Connections", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(spindle_jump_max_connections{job=\"spindle\", instance=~\"$instance\"})", + "legendFormat": "Max Limit", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "ops" + }, + "overrides": [] + }, + "gridPos": { + "h": 7, + "w": 12, + "x": 12, + "y": 62 + }, + "id": 33, + "title": "Debug Jump Rejections Rate", + "description": "Rate of rejected debug jump connections by rejection reason.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(spindle_jump_rejections_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (reason)", + "legendFormat": "Rejection: {{reason}}", + "range": true, + "refId": "A" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + } + ] + }, + { + "collapsed": true, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 56 + }, + "id": 900, + "title": "Go & Process Runtime", + "type": "row", + "panels": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 6, + "w": 8, + "x": 0, + "y": 70 + }, + "id": 7, + "title": "Process CPU Usage", + "description": "CPU usage in terms of cores utilized per instance.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(process_cpu_seconds_total{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (instance)", + "legendFormat": "{{instance}} CPU Cores", + "range": true, + "refId": "A" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "bytes" + }, + "overrides": [] + }, + "gridPos": { + "h": 6, + "w": 8, + "x": 8, + "y": 70 + }, + "id": 8, + "title": "Process Memory Usage", + "description": "Resident memory size (RSS) per instance.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(process_resident_memory_bytes{job=\"spindle\", instance=~\"$instance\"}) by (instance)", + "legendFormat": "{{instance}} Memory", + "range": true, + "refId": "A" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 6, + "w": 8, + "x": 16, + "y": 70 + }, + "id": 9, + "title": "Open File Descriptors", + "description": "Current and maximum allowed open file descriptors.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(process_open_fds{job=\"spindle\", instance=~\"$instance\"}) by (instance)", + "legendFormat": "{{instance}} Open FDs", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(process_max_fds{job=\"spindle\", instance=~\"$instance\"}) by (instance)", + "legendFormat": "{{instance}} Max FDs", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "short" + }, + "overrides": [] + }, + "gridPos": { + "h": 6, + "w": 8, + "x": 0, + "y": 76 + }, + "id": 34, + "title": "Go Concurrency", + "description": "Total number of active Go goroutines and OS threads.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(go_goroutines{job=\"spindle\", instance=~\"$instance\"}) by (instance)", + "legendFormat": "{{instance}} Goroutines", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(go_threads{job=\"spindle\", instance=~\"$instance\"}) by (instance)", + "legendFormat": "{{instance}} OS Threads", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "bytes" + }, + "overrides": [] + }, + "gridPos": { + "h": 6, + "w": 8, + "x": 8, + "y": 76 + }, + "id": 35, + "title": "Go Heap Memory", + "description": "Allocated heap bytes and active heap bytes currently in-use.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(go_memstats_alloc_bytes{job=\"spindle\", instance=~\"$instance\"}) by (instance)", + "legendFormat": "{{instance}} Heap Alloc", + "range": true, + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(go_memstats_heap_inuse_bytes{job=\"spindle\", instance=~\"$instance\"}) by (instance)", + "legendFormat": "{{instance}} Heap In-Use", + "range": true, + "refId": "B" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + }, + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "fieldConfig": { + "defaults": { + "custom": { + "drawStyle": "line", + "lineInterpolation": "smooth", + "hideFrom": { + "tooltip": false, + "viz": false, + "legend": false + } + }, + "unit": "ops" + }, + "overrides": [] + }, + "gridPos": { + "h": 6, + "w": 8, + "x": 16, + "y": 76 + }, + "id": 36, + "title": "Go GC Rate", + "description": "Rate of garbage collection cycles per second.", + "type": "timeseries", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "editorMode": "code", + "expr": "sum(rate(go_gc_duration_seconds_count{job=\"spindle\", instance=~\"$instance\"}[$__rate_interval])) by (instance)", + "legendFormat": "{{instance}} GC Rate", + "range": true, + "refId": "A" + } + ], + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "mode": "multi", + "sort": "none" + } + } + } + ] + }, + { + "collapsed": false, + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 57 + }, + "id": 1004, + "title": "Workflow Logs & Traces", + "type": "row", + "panels": [] + }, + { + "datasource": { + "type": "loki", + "uid": "loki" + }, + "gridPos": { + "h": 8, + "w": 12, + "x": 0, + "y": 58 + }, + "id": 1005, + "title": "Recent Workflow Lifecycle Logs", + "description": "Loki log stream for recent spindle workflow execution events.", + "type": "logs", + "targets": [ + { + "datasource": { + "type": "loki", + "uid": "loki" + }, + "editorMode": "code", + "expr": "{service_name=\"spindle\"} | workflow_id =~ \"$workflow_id\"", + "queryType": "range", + "refId": "A" + } + ], + "options": { + "showLabels": false, + "wrapLogMessage": true, + "enableLogDetails": true, + "showCommonLabels": false, + "showTime": true, + "sortOrder": "Descending" + } + }, + { + "datasource": { + "type": "loki", + "uid": "loki" + }, + "gridPos": { + "h": 8, + "w": 12, + "x": 12, + "y": 58 + }, + "id": 1006, + "title": "Recent Workflow Failures", + "description": "Completed spindle workflows whose result was not success.", + "type": "logs", + "targets": [ + { + "datasource": { + "type": "loki", + "uid": "loki" + }, + "editorMode": "code", + "expr": "{service_name=\"spindle\"} |= \"workflow finished\" | result != \"success\" | workflow_id =~ \"$workflow_id\"", + "queryType": "range", + "refId": "A" + } + ], + "options": { + "showLabels": false, + "wrapLogMessage": true, + "enableLogDetails": true, + "showCommonLabels": false, + "showTime": true, + "sortOrder": "Descending" + } + } + ], + "schemaVersion": 39, + "style": "dark", + "tags": [ + "spindle", + "production", + "operations" + ], + "templating": { + "list": [ + { + "current": {}, + "hide": 0, + "includeAll": false, + "label": "Datasource", + "multi": false, + "name": "datasource", + "options": [], + "query": "prometheus", + "refresh": 1, + "regex": "", + "skipUrlSync": false, + "type": "datasource" + }, + { + "allValue": "", + "current": { + "selected": true, + "value": [ + "$__all" + ], + "text": "All" + }, + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "definition": "label_values(up{job=\"spindle\"}, instance)", + "hide": 0, + "includeAll": true, + "label": "Instance", + "multi": true, + "name": "instance", + "options": [], + "query": { + "query": "label_values(up{job=\"spindle\"}, instance)", + "refId": "StandardVariableQuery" + }, + "refresh": 1, + "regex": "", + "skipUrlSync": false, + "sort": 1, + "type": "query" + }, + { + "allValue": "", + "current": { + "selected": true, + "value": [ + "$__all" + ], + "text": "All" + }, + "datasource": { + "type": "prometheus", + "uid": "$datasource" + }, + "definition": "label_values(spindle_http_requests_total{job=\"spindle\", instance=~\"$instance\"}, route)", + "hide": 0, + "includeAll": true, + "label": "Route", + "multi": true, + "name": "route", + "options": [], + "query": { + "query": "label_values(spindle_http_requests_total{job=\"spindle\", instance=~\"$instance\"}, route)", + "refId": "StandardVariableQuery" + }, + "refresh": 1, + "regex": "", + "skipUrlSync": false, + "sort": 1, + "type": "query" + }, + { + "current": { + "selected": true, + "text": ".*", + "value": ".*" + }, + "description": "regular expression matched against structured workflow_id metadata", + "hide": 0, + "label": "Workflow ID", + "name": "workflow_id", + "options": [], + "query": ".*", + "skipUrlSync": false, + "type": "textbox" + } + ] + }, + "time": { + "from": "now-1h", + "to": "now" + }, + "timepicker": { + "refresh_intervals": [ + "5s", + "10s", + "30s", + "1m", + "5m" + ] + }, + "timezone": "browser", + "title": "Spindle Overview", + "uid": "efv22ywqutn28f", + "version": 1, + "weekStart": "", + "refresh": "10s" +} diff --git a/localinfra/observability/grafana/provisioning/dashboards/spindle.yml b/localinfra/observability/grafana/provisioning/dashboards/spindle.yml new file mode 100644 --- /dev/null +++ b/localinfra/observability/grafana/provisioning/dashboards/spindle.yml @@ -0,0 +1,11 @@ +apiVersion: 1 + +providers: + - name: 'Spindle Dashboards' + orgId: 1 + folder: '' + type: file + disableDeletion: false + editable: true + options: + path: /etc/grafana/provisioning/dashboards diff --git a/localinfra/observability/grafana/provisioning/datasources/prometheus.yml b/localinfra/observability/grafana/provisioning/datasources/prometheus.yml new file mode 100644 --- /dev/null +++ b/localinfra/observability/grafana/provisioning/datasources/prometheus.yml @@ -0,0 +1,44 @@ +apiVersion: 1 + +datasources: + - name: Prometheus + type: prometheus + access: proxy + url: http://prometheus:9090 + isDefault: true + jsonData: + httpMethod: POST + exemplarTraceIdDestinations: + - name: traceID + datasourceUid: tempo + + - name: Tempo + type: tempo + access: proxy + url: http://tempo:3200 + uid: tempo + jsonData: + tracesToLogsV2: + datasourceUid: 'loki' + spanStartTimeShift: '-1h' + spanEndTimeShift: '1h' + tags: + - key: 'service.name' + filterByTraceID: true + filterBySpanID: false + customQuery: true + query: '{service_name="$${__span.tags["service.name"]}"} | trace_id="$${__trace.traceId}"' + + - name: Loki + type: loki + access: proxy + url: http://loki:3100 + uid: loki + jsonData: + derivedFields: + - datasourceUid: tempo + matcherRegex: 'trace_id' + matcherType: label + name: trace_id + urlDisplayLabel: 'View trace' + url: '$${__value.raw}' diff --git a/spindle/mill/proto/spindle/mill/v1/mill.proto b/spindle/mill/proto/spindle/mill/v1/mill.proto --- a/spindle/mill/proto/spindle/mill/v1/mill.proto +++ b/spindle/mill/proto/spindle/mill/v1/mill.proto @@ -47,6 +47,8 @@ string knot = 5; string rkey = 6; uint32 ttl_seconds = 7; + string traceparent = 8; + string tracestate = 9; } enum RejectClass { @@ -72,6 +74,8 @@ message CommitLease { string lease_id = 1 [(buf.validate.field).string.min_len = 1]; repeated Secret secrets = 2; + string traceparent = 3; + string tracestate = 4; } message Committed { @@ -184,4 +188,6 @@ EventBatch event_batch = 11; Ack ack = 12; LiveLog live_log = 13; + } +