diff --git a/CHANGELOG.md b/CHANGELOG.md index 799fbceb6..7f7d25d0f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,11 +14,14 @@ and this project adheres to - 🐛(frontend) reduce PostHog volume from web vitals and opt_in spam #2701 - ✨(backend) expose the attachment max size in the config endpoint #2577 - ✨(frontend) warn before uploading an attachment over the size limit #2577 +- ✨(collaboration) add opt-in prometheus metrics to yhub, server and worker, + protected by a bearer token - ✨(collaboration) report yhub errors to sentry, configured through `SENTRY_*` - ✨(backend) add opt-in prometheus metrics on `/metrics`, protected by a bearer token -- ✨(helm) add a dedicated ingress for the prometheus metrics +- ✨(helm) add a dedicated ingress for the prometheus metrics of the backend + and of yhub - ✨(backend) add a service generating cached RS256 JWT tokens - ✨(backend) publish the JWT public key on a JWKS endpoint - 🔧(dev) generate the JWT signing key when bootstrapping the dev stack diff --git a/documentation/env.md b/documentation/env.md index 758ea29d3..bc87a0d2d 100644 --- a/documentation/env.md +++ b/documentation/env.md @@ -199,6 +199,10 @@ documents what each of them changes. | SENTRY_RELEASE | Release the events are reported under. Detected by the SDK when unset | | | SENTRY_TRACES_SAMPLE_RATE | Share of the traces sent to Sentry, between `0` and `1` | 0 | | SENTRY_PROFILES_SAMPLE_RATE | Share of the sampled traces that are also profiled, between `0` and `1`. The native profiler is only loaded above `0` | 0 | +| PROMETHEUS_METRICS_ENABLED | Set to "true" to serve the prometheus metrics of the process, server or worker, on a port of their own. See the "Metrics" section of `src/yhub-server/README.md` | false | +| PROMETHEUS_API_KEY | Bearer token required by the metrics listener. Required when the metrics are enabled: starting without it is an error. Can be read from a file with PROMETHEUS_API_KEY_FILE | | +| PROMETHEUS_METRICS_PORT | Port the metrics are served on | 9464 | +| PROMETHEUS_METRICS_PATH | Path the metrics are served on, and the only one answered | /metrics | | SOFT_MIGRATION | Set to "true" to seed a room from the legacy Django/S3 document store the first time it is opened | false | | LEGACY_S3_ENDPOINT_URL | Required by SOFT_MIGRATION, endpoint of the legacy media bucket, without a path | | | LEGACY_S3_ACCESS_KEY_ID | Required by SOFT_MIGRATION, read access to that bucket (or LEGACY_S3_ACCESS_KEY_ID_FILE) | | diff --git a/documentation/metrics.md b/documentation/metrics.md index ce90ae078..6ba516782 100644 --- a/documentation/metrics.md +++ b/documentation/metrics.md @@ -1,4 +1,12 @@ -# Prometheus metrics of the backend +# Prometheus metrics + +This page is about the backend. The collaboration server (yhub) has metrics of +its own, served the same way — a bearer token, outside of what the ingress of +the application publishes — and documented in the "Metrics" section of +`src/yhub-server/README.md`. The [Helm section](#kubernetes-helm-chart) below +covers both. + +## Backend The backend ships an **opt-in** instrumentation, [django-prometheus](https://github.com/django-commons/django-prometheus). It is @@ -117,6 +125,30 @@ ingressMetrics: `ingressMetrics` routes the exact path `/metrics` of that host to the backend and nothing else. Its host has to be in `DJANGO_ALLOWED_HOSTS`. +With yhub, the same ingress also publishes the server and the worker, each on an +exact path of its own: + +```yaml +yhub: + envVars: + PROMETHEUS_API_KEY: # the worker inherits it + secretKeyRef: + name: yhub + key: PROMETHEUS_API_KEY + metrics: + enabled: true # /metrics/yhub and /metrics/yhub-worker +``` + +| Path | Served by | +|---|---| +| `/metrics` | backend | +| `/metrics/yhub` | yhub server (websockets, authorizations, backend calls) | +| `/metrics/yhub-worker` | yhub worker (compactions), when `yhub.worker.enabled` | + +That is three scrape jobs on one host, differing by `metrics_path`. What is said +above about [several replicas](#several-replicas-behind-one-address) applies to +each of them: yhub labels its samples with `hostname` too. + The celery worker receives `backend.envVars` too. It serves no request, so its metrics are never read: turn them off there with `backend.celery.envVars.PROMETHEUS_METRICS_ENABLED: "False"`. diff --git a/src/helm/impress/README.md b/src/helm/impress/README.md index 3e54eb902..e7bda10f1 100644 --- a/src/helm/impress/README.md +++ b/src/helm/impress/README.md @@ -66,10 +66,10 @@ | `ingressAdmin.tls.secretName` | Secret name for TLS config | `nil` | | `ingressAdmin.tls.additional[].secretName` | Secret name for additional TLS config | | | `ingressAdmin.tls.additional[].hosts[]` | Hosts for additional TLS config | | -| `ingressMetrics.enabled` | whether to enable the Ingress publishing the Prometheus metrics of the backend (requires PROMETHEUS_METRICS_ENABLED and PROMETHEUS_API_KEY in backend.envVars) | `false` | +| `ingressMetrics.enabled` | whether to enable the Ingress publishing the Prometheus metrics of the backend (requires PROMETHEUS_METRICS_ENABLED and PROMETHEUS_API_KEY in backend.envVars) and, with yhub.metrics.enabled, those of yhub | `false` | | `ingressMetrics.className` | IngressClass to use for the Ingress | `nil` | | `ingressMetrics.host` | Host for the Ingress. Use a host of its own, and add it to DJANGO_ALLOWED_HOSTS | `metrics.impress.example.com` | -| `ingressMetrics.path` | Path to use for the Ingress, matched exactly | `/metrics` | +| `ingressMetrics.path` | Path of the backend metrics, matched exactly. The yhub ones are published at yhub.metrics.path and yhub.metrics.workerPath | `/metrics` | | `ingressMetrics.hosts` | Additional host to configure for the Ingress | `[]` | | `ingressMetrics.tls.enabled` | Whether to enable TLS for the Ingress | `true` | | `ingressMetrics.tls.secretName` | Secret name for TLS config | `nil` | @@ -360,6 +360,10 @@ | `yhub.command` | Override the yhub container command | `[]` | | `yhub.args` | Override the yhub container args | `[]` | | `yhub.replicas` | Amount of yhub replicas | `3` | +| `yhub.metrics.enabled` | Serve the prometheus metrics of yhub on a port of their own, in the server and in the worker. Requires PROMETHEUS_API_KEY in yhub.envVars | `false` | +| `yhub.metrics.port` | Port the metrics are served on. Added to the yhub Service, and to a Service of its own for the worker | `9464` | +| `yhub.metrics.path` | Path the server serves its metrics on, which is the path ingressMetrics publishes them at | `/metrics/yhub` | +| `yhub.metrics.workerPath` | Path the worker serves its metrics on, which is the path ingressMetrics publishes them at | `/metrics/yhub-worker` | | `yhub.worker.enabled` | Deploy the worker apart from the server, each scaling on its own | `false` | | `yhub.worker.replicas` | Amount of yhub worker replicas | `1` | | `yhub.worker.resources` | Resource requirements for the yhub worker container, the server ones when empty | `{}` | diff --git a/src/helm/impress/templates/_helpers.tpl b/src/helm/impress/templates/_helpers.tpl index b3e39c267..98026bd9c 100644 --- a/src/helm/impress/templates/_helpers.tpl +++ b/src/helm/impress/templates/_helpers.tpl @@ -349,3 +349,59 @@ data: .dockerconfigjson: {{ template "impress.secret.dockerconfigjson.data" .imageCredentials }} {{- end -}} {{- end }} + +{{/* +Environment serving the prometheus metrics of a yhub pod on a port of its own. +The bearer token (PROMETHEUS_API_KEY) is not set here: it is a secret, given +through `yhub.envVars`, which the worker inherits. + +Requires a dict with "root" (top level scope) and "path" (where to serve them) +*/}} +{{- define "impress.yhub.metrics.env" -}} +{{- if .root.Values.yhub.metrics.enabled }} +- name: PROMETHEUS_METRICS_ENABLED + value: "true" +- name: PROMETHEUS_METRICS_PORT + value: {{ .root.Values.yhub.metrics.port | quote }} +- name: PROMETHEUS_METRICS_PATH + value: {{ .path | quote }} +{{- end }} +{{- end }} + +{{/* +One exact path of the metrics ingress. + +Requires a dict with "root", "path", "service" and "port" +*/}} +{{- define "impress.ingressMetrics.path" -}} +- path: {{ .path | quote }} + {{- if semverCompare ">=1.18-0" .root.Capabilities.KubeVersion.GitVersion }} + pathType: Exact + {{- end }} + backend: + {{- if semverCompare ">=1.19-0" .root.Capabilities.KubeVersion.GitVersion }} + service: + name: {{ .service }} + port: + number: {{ .port }} + {{- else }} + serviceName: {{ .service }} + servicePort: {{ .port }} + {{- end }} +{{- end }} + +{{/* +Every path of the metrics ingress: the backend, and the two halves of yhub when +their metrics are enabled. Distinct exact paths on one host, so that one ingress +and one address filter cover them all without rewriting anything — each service +is told to serve its metrics on the path it is published at. +*/}} +{{- define "impress.ingressMetrics.paths" -}} +{{ include "impress.ingressMetrics.path" (dict "root" . "path" .Values.ingressMetrics.path "service" (include "impress.backend.fullname" .) "port" .Values.backend.service.port) }} +{{- if and .Values.yhub.enabled .Values.yhub.metrics.enabled }} +{{ include "impress.ingressMetrics.path" (dict "root" . "path" .Values.yhub.metrics.path "service" (include "impress.yhub.fullname" .) "port" .Values.yhub.metrics.port) }} +{{- if .Values.yhub.worker.enabled }} +{{ include "impress.ingressMetrics.path" (dict "root" . "path" .Values.yhub.metrics.workerPath "service" (printf "%s-metrics" (include "impress.yhub.worker.fullname" .)) "port" .Values.yhub.metrics.port) }} +{{- end }} +{{- end }} +{{- end }} diff --git a/src/helm/impress/templates/ingress_metrics.yaml b/src/helm/impress/templates/ingress_metrics.yaml index d5a0f5fd7..e8dcee478 100644 --- a/src/helm/impress/templates/ingress_metrics.yaml +++ b/src/helm/impress/templates/ingress_metrics.yaml @@ -1,6 +1,7 @@ {{- /* -Publishes the Prometheus metrics of the backend (PROMETHEUS_METRICS_ENABLED) and -nothing else: one exact path, on a host of its own. The main ingress sends every +Publishes the Prometheus metrics of the backend (PROMETHEUS_METRICS_ENABLED), and +those of yhub with `yhub.metrics.enabled`, and nothing else: exact paths, on a +host of its own. The main ingress sends every path but /api and /external_api to the frontend, so without this one the metrics are not reachable from outside the cluster. Restrict who may call it with the annotations of your ingress controller; the bearer token is the second lock. @@ -53,38 +54,12 @@ spec: - host: {{ .Values.ingressMetrics.host | quote }} http: paths: - - path: {{ .Values.ingressMetrics.path | quote }} - {{- if semverCompare ">=1.18-0" $.Capabilities.KubeVersion.GitVersion }} - pathType: Exact - {{- end }} - backend: - {{- if semverCompare ">=1.19-0" $.Capabilities.KubeVersion.GitVersion }} - service: - name: {{ include "impress.backend.fullname" . }} - port: - number: {{ .Values.backend.service.port }} - {{- else }} - serviceName: {{ include "impress.backend.fullname" . }} - servicePort: {{ .Values.backend.service.port }} - {{- end }} + {{- include "impress.ingressMetrics.paths" . | nindent 10 }} {{- end }} {{- range .Values.ingressMetrics.hosts }} - host: {{ . | quote }} http: paths: - - path: {{ $.Values.ingressMetrics.path | quote }} - {{- if semverCompare ">=1.18-0" $.Capabilities.KubeVersion.GitVersion }} - pathType: Exact - {{- end }} - backend: - {{- if semverCompare ">=1.19-0" $.Capabilities.KubeVersion.GitVersion }} - service: - name: {{ include "impress.backend.fullname" $ }} - port: - number: {{ $.Values.backend.service.port }} - {{- else }} - serviceName: {{ include "impress.backend.fullname" $ }} - servicePort: {{ $.Values.backend.service.port }} - {{- end }} + {{- include "impress.ingressMetrics.paths" $ | nindent 10 }} {{- end }} {{- end }} diff --git a/src/helm/impress/templates/yhub_deployment.yaml b/src/helm/impress/templates/yhub_deployment.yaml index cdaf3da09..671d88cca 100644 --- a/src/helm/impress/templates/yhub_deployment.yaml +++ b/src/helm/impress/templates/yhub_deployment.yaml @@ -55,13 +55,15 @@ spec: {{- toYaml . | nindent 12 }} {{- end }} {{- $roleEnv := include "impress.yhub.roleEnv" (dict "root" . "role" "server") }} - {{- if or $envVars .Values.jwtKeys.enabled $roleEnv }} + {{- $metricsEnv := include "impress.yhub.metrics.env" (dict "root" . "path" .Values.yhub.metrics.path) }} + {{- if or $envVars .Values.jwtKeys.enabled $roleEnv $metricsEnv }} env: {{- $envVars | indent 12 }} {{- if .Values.jwtKeys.enabled }} {{- include "impress.jwtKeys.yhubEnv" . | nindent 12 }} {{- end }} {{- $roleEnv | indent 12 }} + {{- $metricsEnv | nindent 12 }} {{- end }} {{- if .Values.yhub.envFrom }} envFrom: @@ -75,6 +77,11 @@ spec: - name: http containerPort: {{ .Values.yhub.service.targetPort }} protocol: TCP + {{- if .Values.yhub.metrics.enabled }} + - name: metrics + containerPort: {{ .Values.yhub.metrics.port }} + protocol: TCP + {{- end }} {{- if .Values.yhub.probes.liveness }} livenessProbe: {{- include "impress.probes.abstract" (merge .Values.yhub.probes.liveness (dict "targetPort" .Values.yhub.service.targetPort )) | nindent 12 }} diff --git a/src/helm/impress/templates/yhub_svc.yaml b/src/helm/impress/templates/yhub_svc.yaml index 12f0577ec..84b748293 100644 --- a/src/helm/impress/templates/yhub_svc.yaml +++ b/src/helm/impress/templates/yhub_svc.yaml @@ -17,6 +17,12 @@ spec: targetPort: {{ .Values.yhub.service.targetPort }} protocol: TCP name: http + {{- if .Values.yhub.metrics.enabled }} + - port: {{ .Values.yhub.metrics.port }} + targetPort: metrics + protocol: TCP + name: metrics + {{- end }} selector: {{- include "impress.common.selectorLabels" (list . $component) | nindent 4 }} {{- end }} diff --git a/src/helm/impress/templates/yhub_worker_deployment.yaml b/src/helm/impress/templates/yhub_worker_deployment.yaml index 0da9a6e7d..f0e1e624d 100644 --- a/src/helm/impress/templates/yhub_worker_deployment.yaml +++ b/src/helm/impress/templates/yhub_worker_deployment.yaml @@ -64,13 +64,15 @@ spec: {{- toYaml . | nindent 12 }} {{- end }} {{- $roleEnv := include "impress.yhub.roleEnv" (dict "root" . "role" "worker") }} - {{- if or $envVars .Values.jwtKeys.enabled $roleEnv }} + {{- $metricsEnv := include "impress.yhub.metrics.env" (dict "root" . "path" .Values.yhub.metrics.workerPath) }} + {{- if or $envVars .Values.jwtKeys.enabled $roleEnv $metricsEnv }} env: {{- $envVars | indent 12 }} {{- if .Values.jwtKeys.enabled }} {{- include "impress.jwtKeys.yhubEnv" . | nindent 12 }} {{- end }} {{- $roleEnv | indent 12 }} + {{- $metricsEnv | nindent 12 }} {{- end }} {{- if .Values.yhub.envFrom }} envFrom: @@ -80,6 +82,13 @@ spec: securityContext: {{- toYaml . | nindent 12 }} {{- end }} + {{- if .Values.yhub.metrics.enabled }} + # the only port a worker binds: it serves no route and no websocket + ports: + - name: metrics + containerPort: {{ .Values.yhub.metrics.port }} + protocol: TCP + {{- end }} {{- with ($worker.resources | default .Values.yhub.resources) }} resources: {{- toYaml . | nindent 12 }} diff --git a/src/helm/impress/templates/yhub_worker_metrics_svc.yaml b/src/helm/impress/templates/yhub_worker_metrics_svc.yaml new file mode 100644 index 000000000..c2752d217 --- /dev/null +++ b/src/helm/impress/templates/yhub_worker_metrics_svc.yaml @@ -0,0 +1,22 @@ +{{- if and .Values.yhub.enabled .Values.yhub.worker.enabled .Values.yhub.metrics.enabled -}} +{{- $fullName := include "impress.yhub.worker.fullname" . -}} +{{- $component := "yhub-worker" -}} +# The worker serves nothing but its metrics, so this Service only exists with +# them: it is what the metrics ingress routes to. +apiVersion: v1 +kind: Service +metadata: + name: {{ $fullName }}-metrics + namespace: {{ .Release.Namespace | quote }} + labels: + {{- include "impress.common.labels" (list . $component) | nindent 4 }} +spec: + type: ClusterIP + ports: + - port: {{ .Values.yhub.metrics.port }} + targetPort: metrics + protocol: TCP + name: metrics + selector: + {{- include "impress.common.selectorLabels" (list . $component) | nindent 4 }} +{{- end }} diff --git a/src/helm/impress/values.yaml b/src/helm/impress/values.yaml index e9096b8cc..e432772ab 100644 --- a/src/helm/impress/values.yaml +++ b/src/helm/impress/values.yaml @@ -186,10 +186,10 @@ ingressAdmin: secretName: null additional: [] -## @param ingressMetrics.enabled whether to enable the Ingress publishing the Prometheus metrics of the backend (requires PROMETHEUS_METRICS_ENABLED and PROMETHEUS_API_KEY in backend.envVars) +## @param ingressMetrics.enabled whether to enable the Ingress publishing the Prometheus metrics of the backend (requires PROMETHEUS_METRICS_ENABLED and PROMETHEUS_API_KEY in backend.envVars) and, with yhub.metrics.enabled, those of yhub ## @param ingressMetrics.className IngressClass to use for the Ingress ## @param ingressMetrics.host Host for the Ingress. Use a host of its own, and add it to DJANGO_ALLOWED_HOSTS -## @param ingressMetrics.path Path to use for the Ingress, matched exactly +## @param ingressMetrics.path Path of the backend metrics, matched exactly. The yhub ones are published at yhub.metrics.path and yhub.metrics.workerPath ingressMetrics: enabled: false className: null @@ -998,6 +998,16 @@ yhub: ## deployed apart, see below. replicas: 3 + ## @param yhub.metrics.enabled Serve the prometheus metrics of yhub on a port of their own, in the server and in the worker. Requires PROMETHEUS_API_KEY in yhub.envVars + ## @param yhub.metrics.port Port the metrics are served on. Added to the yhub Service, and to a Service of its own for the worker + ## @param yhub.metrics.path Path the server serves its metrics on, which is the path ingressMetrics publishes them at + ## @param yhub.metrics.workerPath Path the worker serves its metrics on, which is the path ingressMetrics publishes them at + metrics: + enabled: false + port: 9464 + path: /metrics/yhub + workerPath: /metrics/yhub-worker + ## @param yhub.worker.enabled Deploy the worker apart from the server, each scaling on its own ## @param yhub.worker.replicas Amount of yhub worker replicas ## @param yhub.worker.resources Resource requirements for the yhub worker container, the server ones when empty diff --git a/src/yhub-server/README.md b/src/yhub-server/README.md index e88ecae24..45074fcb5 100644 --- a/src/yhub-server/README.md +++ b/src/yhub-server/README.md @@ -391,6 +391,52 @@ made *versioned*, so what is exercised is what a deployment runs rather than a simpler case. Watch it with `mc ls --versions --recursive impress/yhub-storage` from an `mc` container on the stack's network. +## Metrics (Prometheus) + +Off by default. With `PROMETHEUS_METRICS_ENABLED=true` every process — the +server and the worker alike — serves its metrics on a port of its own: + +| Variable | Default | What it changes | +| -------- | ------- | --------------- | +| `PROMETHEUS_METRICS_ENABLED` | `false` | `true` to collect the runtime metrics and start the listener | +| `PROMETHEUS_API_KEY` | — | Bearer token a scraper has to present (or `…_FILE`). **Required** when enabled: starting without it is an error | +| `PROMETHEUS_METRICS_PORT` | `9464` | Port of the listener | +| `PROMETHEUS_METRICS_PATH` | `/metrics` | Path it answers on, and the only one | + +The listener is not yhub's server. The worker role binds no port, so a route +under `/collaboration/` would leave the persistence half without metrics; and +what is under `/collaboration/` is what an ingress publishes. It answers `GET` +on that one path to `Authorization: Bearer `, compared in +constant time, and `401` to anything else — the contract of the backend's +`/metrics` (`documentation/metrics.md`). The path is configurable so that one +ingress can publish the backend, the server and the worker side by side on +distinct exact paths, without rewriting anything. + +What is measured, every sample labelled with the `hostname` and the `role` of +the process, and **never** with a document or a user: + +| Metric | Labels | What it tells | +| ------ | ------ | ------------- | +| `yhub_ws_connections`, `yhub_rooms` | | Websockets, and documents with at least one, on this replica | +| `yhub_auth_duration_seconds` | `phase` (`authenticate`, `authorize`), `endpoint`, `result` (`ok`, `denied`, `unavailable`, `error`) | What admitting a caller costs — backend calls and legacy seed included. It runs on every websocket upgrade, recheck, REST call and fallback poll | +| `yhub_backend_request_duration_seconds` | `route` (`users_me`, `document`, `accesses_me`, `content_updated`), `status` (http status, `timeout`, `error`) | The calls made to the Docs backend | +| `yhub_backend_requests_inflight` | `route` | Backend calls not answered yet: what piles up when the backend slows down | +| `yhub_worker_pending_tasks` | | Compactions waiting on the redis queue. One queue for the whole deployment: read it with `max`, never `sum` | +| `yhub_worker_task_duration_seconds` | `result` (`ok`, `error`) | Duration of the compactions | +| `yhub_worker_tasks_inflight` | | Compactions running, out of `YHUB_TASK_CONCURRENCY` | +| `yhub_doc_updates_total` | | Compactions that found new content, i.e. `content-updated` notifications | +| `yhub_seed_duration_seconds` | `result` (`seeded`, `empty`, `failed`) | Soft migrations, from the S3 read to the stream write | +| `yhub_seeds_inflight`, `yhub_seed_rejected_total` | | Soft migrations running, and refused because the replica was at its maximum | +| `nodejs_*`, `process_*` | | The node runtime. `nodejs_eventloop_lag_seconds` is the one to watch: one thread serves every socket of a replica | + +`yhub_ws_connections` and `yhub_rooms` are read off yhub's own bookkeeping of +its subscriptions (`stream.subs`), which is not a published API: a yhub upgrade +that renames it turns both into zeros rather than failing anything. + +Not measured, because yhub has no hook for it: messages and bytes per +connection, and close codes. Read those off the ingress controller and the +valkey exporter. + ## Error reporting (Sentry) `src/sentry.ts` is preloaded by the start command diff --git a/src/yhub-server/__tests__/config.spec.ts b/src/yhub-server/__tests__/config.spec.ts index 9717acccc..b53270a4c 100644 --- a/src/yhub-server/__tests__/config.spec.ts +++ b/src/yhub-server/__tests__/config.spec.ts @@ -119,3 +119,49 @@ describe('PORT', () => { expect((await load()).PORT).toBe(4000); }); }); + +describe('PROMETHEUS_METRICS_*', () => { + beforeEach(() => { + for (const key of [ + 'PROMETHEUS_METRICS_ENABLED', + 'PROMETHEUS_API_KEY', + 'PROMETHEUS_API_KEY_FILE', + 'PROMETHEUS_METRICS_PORT', + 'PROMETHEUS_METRICS_PATH', + ]) { + vi.stubEnv(key, ''); + } + }); + + it('is off by default, and then asks for no key', async () => { + const config = await load(); + expect(config.PROMETHEUS_METRICS_ENABLED).toBe(false); + expect(config.PROMETHEUS_METRICS_PORT).toBe(9464); + expect(config.PROMETHEUS_METRICS_PATH).toBe('/metrics'); + }); + + it('refuses to start enabled without a key: the metrics would be public', async () => { + vi.stubEnv('PROMETHEUS_METRICS_ENABLED', 'true'); + await expect(load()).rejects.toThrow( + 'PROMETHEUS_METRICS_ENABLED requires PROMETHEUS_API_KEY to be set', + ); + }); + + it('starts enabled with a key', async () => { + vi.stubEnv('PROMETHEUS_METRICS_ENABLED', 'true'); + vi.stubEnv('PROMETHEUS_API_KEY', 'a-key'); + vi.stubEnv('PROMETHEUS_METRICS_PORT', '9500'); + vi.stubEnv('PROMETHEUS_METRICS_PATH', '/metrics/yhub'); + const config = await load(); + expect(config.PROMETHEUS_METRICS_ENABLED).toBe(true); + expect(config.PROMETHEUS_METRICS_PORT).toBe(9500); + expect(config.PROMETHEUS_METRICS_PATH).toBe('/metrics/yhub'); + }); + + it('refuses a path that is not one', async () => { + vi.stubEnv('PROMETHEUS_METRICS_PATH', 'metrics'); + await expect(load()).rejects.toThrow( + 'PROMETHEUS_METRICS_PATH must start with "/" (got "metrics")', + ); + }); +}); diff --git a/src/yhub-server/__tests__/metrics.spec.ts b/src/yhub-server/__tests__/metrics.spec.ts new file mode 100644 index 000000000..4f35f6999 --- /dev/null +++ b/src/yhub-server/__tests__/metrics.spec.ts @@ -0,0 +1,350 @@ +// metrics.ts — the metric helpers and the http listener, tested without yhub: +// the helpers are plain functions over the registry, and the listener's handler +// is driven through a real `node:http` server on a port of the system's choosing. + +import type { AddressInfo } from 'node:net'; +import { createServer } from 'node:http'; +import type { Server } from 'node:http'; + +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; + +const API_KEY = 'test-prometheus-api-key'; + +const load = () => import('../src/metrics.js'); + +beforeEach(() => { + vi.unstubAllEnvs(); + vi.resetModules(); + vi.stubEnv('PROMETHEUS_METRICS_ENABLED', 'true'); + vi.stubEnv('PROMETHEUS_API_KEY', API_KEY); + vi.stubEnv('PROMETHEUS_API_KEY_FILE', ''); + vi.stubEnv('PROMETHEUS_METRICS_PATH', ''); + vi.stubEnv('PROMETHEUS_METRICS_PORT', ''); + vi.stubEnv('YHUB_ROLE', ''); +}); + +describe('labels', () => { + it('never lets the caller choose an endpoint label', async () => { + const { endpointLabel } = await load(); + expect(endpointLabel('ws')).toBe('ws'); + expect(endpointLabel('reset-connections')).toBe('reset-connections'); + expect(endpointLabel('made-up-by-the-caller')).toBe('other'); + expect(endpointLabel('')).toBe('other'); + expect(endpointLabel(undefined)).toBe('other'); + }); + + it('names a backend route without the document id', async () => { + const { backendRouteLabel } = await load(); + const docid = '7c0f6f4e-2b0e-4a57-9f0a-3f6f2f0d1e11'; + expect(backendRouteLabel('/api/v1.0/users/me/')).toBe('users_me'); + expect(backendRouteLabel(`/api/v1.0/documents/${docid}/`)).toBe('document'); + expect(backendRouteLabel(`/api/v1.0/documents/${docid}/accesses/me/`)).toBe( + 'accesses_me', + ); + expect( + backendRouteLabel(`/api/v1.0/documents/${docid}/content-updated/`), + ).toBe('content_updated'); + expect(backendRouteLabel('/api/v1.0/something/else/')).toBe('other'); + }); + + it('tells the replicas and the roles apart', async () => { + vi.stubEnv('YHUB_ROLE', 'worker'); + const { registry, docUpdatesTotal } = await load(); + docUpdatesTotal.inc(); + expect(await registry.metrics()).toMatch( + /yhub_doc_updates_total\{hostname="[^"]+",role="worker"\} 1/, + ); + }); +}); + +describe('timedAuth', () => { + const resultsOf = async () => { + const { authDuration } = await load(); + const { values } = await authDuration.get(); + return values + .filter(({ metricName }) => metricName?.endsWith('_count')) + .map( + ({ labels }) => `${labels.phase}:${labels.endpoint}:${labels.result}`, + ); + }; + const failure = (status?: number) => + Object.assign(new Error('boom'), status == null ? {} : { status }); + + it('passes the answer through and counts it as ok', async () => { + const { timedAuth } = await load(); + const timed = timedAuth( + 'authenticate', + (endpoint: string) => endpoint, + async (endpoint: string) => ({ userid: `on ${endpoint}` }), + ); + + await expect(timed('ws')).resolves.toEqual({ userid: 'on ws' }); + expect(await resultsOf()).toEqual(['authenticate:ws:ok']); + }); + + it('reads the endpoint and calls the callback before the first await', async () => { + const { timedAuth } = await load(); + const order: string[] = []; + const timed = timedAuth( + 'authenticate', + () => { + order.push('endpoint'); + return 'ws'; + }, + async () => { + order.push('callback'); + return null; + }, + ); + + const pending = timed(); + // nothing has been awaited yet: a uws request is still valid here + expect(order).toEqual(['endpoint', 'callback']); + await pending; + }); + + it('counts a null answer of authorize as a denial, not of authenticate', async () => { + const { timedAuth } = await load(); + await timedAuth( + 'authorize', + () => 'ydoc', + async () => null, + )(); + await timedAuth( + 'authenticate', + () => 'ydoc', + async () => null, + )(); + + expect(await resultsOf()).toEqual([ + 'authorize:ydoc:denied', + 'authenticate:ydoc:ok', + ]); + }); + + it.each([ + [401, 'denied'], + [403, 'denied'], + [503, 'unavailable'], + [500, 'error'], + [undefined, 'error'], + ])('rethrows a %s and counts it as %s', async (status, result) => { + const { timedAuth } = await load(); + const err = failure(status); + const timed = timedAuth( + 'authorize', + () => 'ws', + async () => { + throw err; + }, + ); + + await expect(timed()).rejects.toBe(err); + expect(await resultsOf()).toEqual([`authorize:ws:${result}`]); + }); +}); + +describe('timedBackendRequest', () => { + const samples = async () => { + const { backendRequestDuration, backendRequestsInflight } = await load(); + const duration = await backendRequestDuration.get(); + const inflight = await backendRequestsInflight.get(); + return { + counted: duration.values + .filter(({ metricName }) => metricName?.endsWith('_count')) + .map(({ labels }) => `${labels.route}:${labels.status}`), + inflight: inflight.values.map(({ value }) => value), + }; + }; + + it('counts the answer under its route and status, and is in flight meanwhile', async () => { + const { timedBackendRequest } = await load(); + let during: number[] = []; + + const res = await timedBackendRequest('/api/v1.0/users/me/', async () => { + during = (await samples()).inflight; + return new Response('{}', { status: 403 }); + }); + + expect(res.status).toBe(403); + expect(during).toEqual([1]); + expect(await samples()).toEqual({ + counted: ['users_me:403'], + inflight: [0], + }); + }); + + it('counts a call that never got an answer as an error', async () => { + const { timedBackendRequest } = await load(); + const err = new Error('connect ECONNREFUSED'); + + await expect( + timedBackendRequest('/api/v1.0/users/me/', async () => { + throw err; + }), + ).rejects.toBe(err); + + expect(await samples()).toEqual({ + counted: ['users_me:error'], + inflight: [0], + }); + }); +}); + +describe('timedBackendRequest timeouts', () => { + it('tells a call that was given up on from one that failed', async () => { + const { backendRequestDuration, timedBackendRequest } = await load(); + // what `AbortSignal.timeout` aborts a fetch with + const err = new DOMException('The operation timed out', 'TimeoutError'); + + await expect( + timedBackendRequest('/api/v1.0/users/me/', async () => { + throw err; + }), + ).rejects.toBe(err); + + const { values } = await backendRequestDuration.get(); + expect( + values + .filter(({ metricName }) => metricName?.endsWith('_count')) + .map(({ labels }) => `${labels.route}:${labels.status}`), + ).toEqual(['users_me:timeout']); + }); +}); + +describe('the metrics listener', () => { + let server: Server | undefined; + + const listen = async (): Promise => { + const { handleMetricsRequest } = await load(); + server = createServer((req, res) => { + void handleMetricsRequest(req, res); + }); + await new Promise((resolve) => + server?.listen(0, '127.0.0.1', resolve), + ); + return `http://127.0.0.1:${(server.address() as AddressInfo).port}`; + }; + + afterEach(async () => { + await new Promise((resolve) => + server ? server.close(resolve) : resolve(null), + ); + server = undefined; + }); + + // no trailing-space case: http strips the whitespace around a header value, + // so it reaches the server as the exact key + it.each([ + undefined, + '', + 'Bearer', + 'Bearer ', + 'Bearer wrong-key', + `bearer ${API_KEY}`, + `Token ${API_KEY}`, + API_KEY, + 'Bearer clé-non-ascii', + ])('refuses "%s"', async (authorization) => { + const url = await listen(); + + const res = await fetch(`${url}/metrics`, { + headers: authorization == null ? {} : { authorization }, + }); + + expect(res.status).toBe(401); + expect(res.headers.get('www-authenticate')).toBe('Bearer realm="metrics"'); + expect(await res.text()).toBe('Unauthorized'); + }); + + it('serves the metrics to the right key', async () => { + const url = await listen(); + const { docUpdatesTotal } = await load(); + docUpdatesTotal.inc(3); + + const res = await fetch(`${url}/metrics?ignored=1`, { + headers: { authorization: `Bearer ${API_KEY}` }, + }); + + expect(res.status).toBe(200); + expect(res.headers.get('content-type')).toContain('text/plain'); + expect(await res.text()).toMatch(/yhub_doc_updates_total\{[^}]*\} 3/); + }); + + it('serves nothing else, key or not', async () => { + const url = await listen(); + const headers = { authorization: `Bearer ${API_KEY}` }; + + for (const path of ['/', '/metrics/', '/collaboration/metrics/v1']) { + expect((await fetch(`${url}${path}`, { headers })).status).toBe(404); + } + expect( + (await fetch(`${url}/metrics`, { method: 'POST', headers })).status, + ).toBe(405); + // without the key, the method is not even looked at + expect((await fetch(`${url}/metrics`, { method: 'POST' })).status).toBe( + 401, + ); + }); + + it('serves them where PROMETHEUS_METRICS_PATH says', async () => { + vi.stubEnv('PROMETHEUS_METRICS_PATH', '/metrics/yhub-worker'); + const url = await listen(); + const headers = { authorization: `Bearer ${API_KEY}` }; + + expect( + (await fetch(`${url}/metrics/yhub-worker`, { headers })).status, + ).toBe(200); + expect((await fetch(`${url}/metrics`, { headers })).status).toBe(404); + }); +}); + +describe('startMetricsServer', () => { + it('reports what it reads off yhub, by role', async () => { + // a port of the system's choosing cannot be asked for: intEnv wants >= 1 + vi.stubEnv('PROMETHEUS_METRICS_PORT', '19464'); + const { registry, startMetricsServer } = await load(); + const yhub = { + stream: { + subs: new Map([ + ['room-a', { subs: new Set([1, 2]) }], + ['room-b', { subs: new Set([3]) }], + ]), + getPendingTasksSize: async () => 7, + }, + }; + + const server = await startMetricsServer(yhub as never); + try { + const text = await registry.metrics(); + expect(text).toMatch(/yhub_rooms\{[^}]*\} 2/); + expect(text).toMatch(/yhub_ws_connections\{[^}]*\} 3/); + expect(text).toMatch(/yhub_worker_pending_tasks\{[^}]*\} 7/); + // the node runtime collectors are on + expect(text).toContain('nodejs_eventloop_lag_seconds'); + } finally { + await new Promise((resolve) => server.close(resolve)); + } + }); + + it('survives a yhub that no longer exposes its subscriptions, and a redis that blinks', async () => { + vi.stubEnv('PROMETHEUS_METRICS_PORT', '19465'); + const { registry, startMetricsServer } = await load(); + const yhub = { + stream: { + getPendingTasksSize: async () => { + throw new Error('redis is gone'); + }, + }, + }; + + const server = await startMetricsServer(yhub as never); + try { + const text = await registry.metrics(); + expect(text).toMatch(/yhub_rooms\{[^}]*\} 0/); + expect(text).toMatch(/yhub_ws_connections\{[^}]*\} 0/); + } finally { + await new Promise((resolve) => server.close(resolve)); + } + }); +}); diff --git a/src/yhub-server/package.json b/src/yhub-server/package.json index ae7b306bb..99c594b8d 100644 --- a/src/yhub-server/package.json +++ b/src/yhub-server/package.json @@ -18,7 +18,8 @@ "@sentry/profiling-node": "10.70.0", "@y/hub": "0.9.0", "@y/y": "14.0.0-rc.25", - "jose": "6.2.8" + "jose": "6.2.8", + "prom-client": "15.1.3" }, "devDependencies": { "@eslint/js": "10.0.1", diff --git a/src/yhub-server/src/backend.ts b/src/yhub-server/src/backend.ts index fa8793a65..900f5af74 100644 --- a/src/yhub-server/src/backend.ts +++ b/src/yhub-server/src/backend.ts @@ -35,6 +35,7 @@ import { Y_PROVIDER_API_KEY, YHUB_JWT_PRIVATE_KEY, } from './config.js'; +import { timedBackendRequest } from './metrics.js'; // The shape of the backend payload a caller name resolves to. export interface BackendUser { @@ -117,17 +118,19 @@ export const backendFetch = async ( path: string, { cookie, origin }: { cookie?: string; origin?: string }, ): Promise => { - const res = await fetch(`${COLLABORATION_BACKEND_BASE_URL}${path}`, { - headers: { - // an anonymous caller may have no session at all; `cookie: undefined` would - // reach the backend as the literal string "undefined" - ...(cookie ? { cookie } : {}), - // a same-origin request carries no `Origin` — forwarded when there is one, omitted - // rather than sent empty, which is not a value the header is allowed to take - ...(origin ? { origin } : {}), - 'X-Y-Provider-Key': Y_PROVIDER_API_KEY, - }, - }); + const res = await timedBackendRequest(path, () => + fetch(`${COLLABORATION_BACKEND_BASE_URL}${path}`, { + headers: { + // an anonymous caller may have no session at all; `cookie: undefined` would + // reach the backend as the literal string "undefined" + ...(cookie ? { cookie } : {}), + // a same-origin request carries no `Origin` — forwarded when there is one, omitted + // rather than sent empty, which is not a value the header is allowed to take + ...(origin ? { origin } : {}), + 'X-Y-Provider-Key': Y_PROVIDER_API_KEY, + }, + }), + ); if (!res.ok) { const err: Error & { status?: number } = new Error( `Failed to fetch ${path}: ${res.status}`, @@ -143,13 +146,14 @@ export const backendFetch = async ( export const touchDocument = async (docid: string): Promise => { if (backendSigningKey == null) return; try { - const res = await fetch( - `${COLLABORATION_BACKEND_BASE_URL}/api/v1.0/documents/${docid}/content-updated/`, - { + const path = `/api/v1.0/documents/${docid}/content-updated/`; + const token = await getBackendToken(); + const res = await timedBackendRequest(path, () => + fetch(`${COLLABORATION_BACKEND_BASE_URL}${path}`, { method: 'POST', - headers: { authorization: `Bearer ${await getBackendToken()}` }, + headers: { authorization: `Bearer ${token}` }, signal: AbortSignal.timeout(BACKEND_NOTIFY_TIMEOUT_MS), - }, + }), ); if (!res.ok) { touchLog.warn( diff --git a/src/yhub-server/src/config.ts b/src/yhub-server/src/config.ts index 737e8915b..4a6de4467 100644 --- a/src/yhub-server/src/config.ts +++ b/src/yhub-server/src/config.ts @@ -183,3 +183,28 @@ export const SENTRY_PROFILES_SAMPLE_RATE = rateEnv( 'SENTRY_PROFILES_SAMPLE_RATE', 0, ); + +// Prometheus metrics, served by `metrics.ts` on a port of their own: the worker +// binds no port at all, and the routes under /collaboration/ are the ones an +// ingress publishes. Off by default. +export const PROMETHEUS_METRICS_ENABLED = + process.env.PROMETHEUS_METRICS_ENABLED === 'true'; +// The bearer token a scraper has to present, the same contract as the backend's +// /metrics. There is no running without it: an unset key would publish the +// metrics to whoever reaches the port, so it is a startup error instead. +export const PROMETHEUS_API_KEY = secret('PROMETHEUS_API_KEY', ''); +if (PROMETHEUS_METRICS_ENABLED && !PROMETHEUS_API_KEY) { + throw new Error( + 'PROMETHEUS_METRICS_ENABLED requires PROMETHEUS_API_KEY to be set', + ); +} +export const PROMETHEUS_METRICS_PORT = intEnv('PROMETHEUS_METRICS_PORT', 9464); +// Configurable so that one ingress can publish the server, the worker and the +// backend side by side on distinct exact paths, without rewriting anything. +export const PROMETHEUS_METRICS_PATH = + process.env.PROMETHEUS_METRICS_PATH || '/metrics'; +if (!PROMETHEUS_METRICS_PATH.startsWith('/')) { + throw new Error( + `PROMETHEUS_METRICS_PATH must start with "/" (got "${PROMETHEUS_METRICS_PATH}")`, + ); +} diff --git a/src/yhub-server/src/metrics.ts b/src/yhub-server/src/metrics.ts new file mode 100644 index 000000000..375962cd2 --- /dev/null +++ b/src/yhub-server/src/metrics.ts @@ -0,0 +1,340 @@ +/** + * Prometheus metrics of this process, and the http listener that serves them. + * + * The listener is separate from yhub's own server on purpose. The worker role + * binds no port, so a route under /collaboration/ would leave the persistence + * half — the one a load test most needs to see — without metrics; and what is + * under /collaboration/ is what an ingress publishes. It answers `GET` on + * PROMETHEUS_METRICS_PATH and nothing else, to a caller presenting + * PROMETHEUS_API_KEY as a bearer token: the contract of the backend's /metrics. + * + * The metrics are defined whether or not they are served — an increment costs + * nothing worth a branch at every call site. What is only done when they are + * enabled is what has a cost of its own: the node runtime collectors and the + * listener (`startMetricsServer`). + * + * No label ever carries a document or a user: a label value is a time series, + * and there are as many of those as there are documents. + */ +import { timingSafeEqual } from 'node:crypto'; +import type { IncomingMessage, Server, ServerResponse } from 'node:http'; +import { createServer } from 'node:http'; +import { hostname } from 'node:os'; + +import { + Counter, + Gauge, + Histogram, + Registry, + collectDefaultMetrics, +} from 'prom-client'; + +import { + PROMETHEUS_API_KEY, + PROMETHEUS_METRICS_PATH, + PROMETHEUS_METRICS_PORT, + ROLE, + RUNS_SERVER, + RUNS_WORKER, +} from './config.js'; +import type { YHub } from './yhub.js'; + +export const registry = new Registry(); +// A scrape that goes through a load balancer is answered by a different replica +// each time: the hostname keeps their series apart, so that a counter never +// jumps from the numbers of one replica to those of another. +registry.setDefaultLabels({ hostname: hostname(), role: ROLE }); + +// Upgrades and backend calls answer in milliseconds when all is well and in +// tens of seconds when the backend is drowning; both ends have to be readable. +const LATENCY_BUCKETS = [ + 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, +]; +// A compaction merges a whole document: seconds are common, minutes happen. +const TASK_BUCKETS = [0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, 300]; + +export const authDuration = new Histogram({ + name: 'yhub_auth_duration_seconds', + help: 'Time spent authenticating a caller or authorizing it on a document, backend calls and legacy seed included', + labelNames: ['phase', 'endpoint', 'result'] as const, + buckets: LATENCY_BUCKETS, + registers: [registry], +}); + +export const backendRequestDuration = new Histogram({ + name: 'yhub_backend_request_duration_seconds', + help: 'Duration of the calls made to the Docs backend', + labelNames: ['route', 'status'] as const, + buckets: LATENCY_BUCKETS, + registers: [registry], +}); + +export const backendRequestsInflight = new Gauge({ + name: 'yhub_backend_requests_inflight', + help: 'Calls to the Docs backend that have not been answered yet', + labelNames: ['route'] as const, + registers: [registry], +}); + +export const workerTaskDuration = new Histogram({ + name: 'yhub_worker_task_duration_seconds', + help: 'Duration of the compaction tasks run by this worker', + labelNames: ['result'] as const, + buckets: TASK_BUCKETS, + registers: [registry], +}); + +export const workerTasksInflight = new Gauge({ + name: 'yhub_worker_tasks_inflight', + help: 'Compaction tasks this worker is running', + registers: [registry], +}); + +export const docUpdatesTotal = new Counter({ + name: 'yhub_doc_updates_total', + help: 'Compactions that found new content to persist', + registers: [registry], +}); + +export const seedDuration = new Histogram({ + name: 'yhub_seed_duration_seconds', + help: 'Duration of the soft migrations of a legacy document, from the S3 read to the stream write', + labelNames: ['result'] as const, + buckets: LATENCY_BUCKETS, + registers: [registry], +}); + +export const seedsInflight = new Gauge({ + name: 'yhub_seeds_inflight', + help: 'Soft migrations this replica is running', + registers: [registry], +}); + +export const seedRejectedTotal = new Counter({ + name: 'yhub_seed_rejected_total', + help: 'Soft migrations refused because this replica was already running its maximum', + registers: [registry], +}); + +// The routes of yhub, ours included. The label is read off the url of the +// request, which is the caller's to choose: anything else is one bucket. +const KNOWN_ENDPOINTS = new Set([ + 'ws', + 'ydoc', + 'activity', + 'changeset', + 'rollback', + 'prune', + 'ping', + 'ready', + 'jwks', + 'reset-connections', + 'migrate', + 'create-ydoc', + 'restore-ydoc', + 'reset-ydoc', +]); +export const endpointLabel = (endpoint: string | undefined): string => + endpoint != null && KNOWN_ENDPOINTS.has(endpoint) ? endpoint : 'other'; + +// What a backend path is called in a label: never the path, which holds the +// document id. +export const backendRouteLabel = (path: string): string => { + if (path.endsWith('/users/me/')) return 'users_me'; + if (path.endsWith('/accesses/me/')) return 'accesses_me'; + if (path.endsWith('/content-updated/')) return 'content_updated'; + if (/\/documents\/[^/]+\/$/.test(path)) return 'document'; + return 'other'; +}; + +const errStatus = (err: unknown): number | undefined => + typeof err === 'object' && + err !== null && + 'status' in err && + typeof (err as { status: unknown }).status === 'number' + ? (err as { status: number }).status + : undefined; + +/** + * Time one of the two callbacks of the auth plugin, without changing what it + * returns or throws. + * + * ok it answered, and granted something + * denied it answered no: `null` from `authorize`, a 401/403 thrown + * unavailable it could not answer (503): the backend, or the legacy store + * error anything else + * + * `endpointOf` and the callback are both called before the first await: the + * request yhub hands to `authenticate` is only valid synchronously. + */ +export const timedAuth = + ( + phase: 'authenticate' | 'authorize', + endpointOf: (...args: Args) => string | undefined, + callback: (...args: Args) => Promise, + ) => + async (...args: Args): Promise => { + const endpoint = endpointLabel(endpointOf(...args)); + const end = authDuration.startTimer({ phase, endpoint }); + try { + const result = await callback(...args); + end({ + result: phase === 'authorize' && result == null ? 'denied' : 'ok', + }); + return result; + } catch (err) { + const status = errStatus(err); + end({ + result: + status === 401 || status === 403 + ? 'denied' + : status === 503 + ? 'unavailable' + : 'error', + }); + throw err; + } + }; + +/** + * Time a call to the backend. `status` is the http status, `timeout` when the + * call was given up on, `error` when it never got an answer. + */ +export const timedBackendRequest = async ( + path: string, + request: () => Promise, +): Promise => { + const route = backendRouteLabel(path); + const end = backendRequestDuration.startTimer({ route }); + backendRequestsInflight.inc({ route }); + try { + const res = await request(); + end({ status: String(res.status) }); + return res; + } catch (err) { + // what `AbortSignal.timeout` aborts with: a backend that is up but too slow + // is not the same finding as one that cannot be reached + const timedOut = err instanceof Error && err.name === 'TimeoutError'; + end({ status: timedOut ? 'timeout' : 'error' }); + throw err; + } finally { + backendRequestsInflight.dec({ route }); + } +}; + +// What is only known by asking yhub, asked at scrape time. +const registerYhubGauges = (yhub: YHub): void => { + if (RUNS_SERVER) { + // `stream.subs` is yhub's own bookkeeping of who listens to which room on + // this replica — not a published API, and read defensively for that reason: + // a yhub that renames it costs two gauges, not the process. + const rooms = (): Map }> | undefined => { + const subs = (yhub.stream as unknown as { subs?: unknown }).subs; + return subs instanceof Map ? subs : undefined; + }; + new Gauge({ + name: 'yhub_rooms', + help: 'Documents with at least one websocket connection on this replica', + registers: [registry], + collect() { + this.set(rooms()?.size ?? 0); + }, + }); + new Gauge({ + name: 'yhub_ws_connections', + help: 'Websocket connections subscribed to a document on this replica', + registers: [registry], + collect() { + let connections = 0; + for (const room of rooms()?.values() ?? []) { + connections += room.subs?.size ?? 0; + } + this.set(connections); + }, + }); + } + if (RUNS_WORKER) { + new Gauge({ + name: 'yhub_worker_pending_tasks', + // one queue for the whole deployment: every worker reports the same + // number, which is to be read with max(), never summed + help: 'Compaction tasks waiting on the redis queue, for the whole deployment (use max, not sum)', + registers: [registry], + async collect() { + try { + this.set(await yhub.stream.getPendingTasksSize()); + } catch { + // a scrape must not fail because redis blinked + } + }, + }); + } +}; + +const isAuthorized = (req: IncomingMessage): boolean => { + if (!PROMETHEUS_API_KEY) return false; + const presented = Buffer.from(req.headers.authorization ?? ''); + const expected = Buffer.from(`Bearer ${PROMETHEUS_API_KEY}`); + // timingSafeEqual refuses buffers of different lengths, and the length of the + // key is not what is being protected + return ( + presented.length === expected.length && timingSafeEqual(presented, expected) + ); +}; + +export const handleMetricsRequest = async ( + req: IncomingMessage, + res: ServerResponse, +): Promise => { + const path = (req.url ?? '').split('?')[0]; + if (path !== PROMETHEUS_METRICS_PATH) { + res.writeHead(404, { 'content-type': 'text/plain' }).end('Not Found'); + return; + } + // before the method: what an unauthenticated caller learns is that there is + // a lock, not what is behind it + if (!isAuthorized(req)) { + res + .writeHead(401, { + 'content-type': 'text/plain', + 'www-authenticate': 'Bearer realm="metrics"', + }) + .end('Unauthorized'); + return; + } + if (req.method !== 'GET' && req.method !== 'HEAD') { + res + .writeHead(405, { 'content-type': 'text/plain', allow: 'GET, HEAD' }) + .end('Method Not Allowed'); + return; + } + try { + const body = await registry.metrics(); + res.writeHead(200, { 'content-type': registry.contentType }).end(body); + } catch { + res + .writeHead(500, { 'content-type': 'text/plain' }) + .end('Internal Server Error'); + } +}; + +/** + * Start collecting the runtime metrics and serving everything. Only called when + * PROMETHEUS_METRICS_ENABLED is set, which `config.ts` refuses without a key. + */ +export const startMetricsServer = (yhub: YHub): Promise => { + // event loop lag, heap, gc, cpu: one node thread serves every socket of this + // replica, and its lag is the first thing to move when it saturates + collectDefaultMetrics({ register: registry }); + registerYhubGauges(yhub); + + const server = createServer((req, res) => { + void handleMetricsRequest(req, res); + }); + // it must never be what keeps a stopping process alive + server.unref(); + return new Promise((resolve, reject) => { + server.once('error', reject); + server.listen(PROMETHEUS_METRICS_PORT, () => resolve(server)); + }); +}; diff --git a/src/yhub-server/src/migration.ts b/src/yhub-server/src/migration.ts index 848bf9e6a..1f682e309 100644 --- a/src/yhub-server/src/migration.ts +++ b/src/yhub-server/src/migration.ts @@ -31,6 +31,7 @@ import { logger } from '@y/hub'; import * as Y from '@y/y'; import { secret } from './env.js'; +import { seedDuration, seedRejectedTotal, seedsInflight } from './metrics.js'; import type { DocRef, YHub } from './yhub.js'; export const SOFT_MIGRATION = process.env.SOFT_MIGRATION === 'true'; @@ -425,9 +426,13 @@ const migrate = async (yhub: YHub, docRef: DocRef): Promise => { 'too many concurrent soft migrations', ); err.noCache = true; + seedRejectedTotal.inc(); throw err; } activeSeeds++; + seedsInflight.inc(); + const endSeed = seedDuration.startTimer(); + let seedResult: 'seeded' | 'empty' | 'failed' = 'failed'; try { const start = Date.now(); const update = await fetchLegacyDoc(docRef.docid); @@ -436,6 +441,7 @@ const migrate = async (yhub: YHub, docRef: DocRef): Promise => { { event: 'seed.empty', docid: docRef.docid }, 'no legacy s3 object; room starts empty', ); + seedResult = 'empty'; return 'empty'; } // Decode before writing anything: a legacy object that is not a valid @@ -482,9 +488,12 @@ const migrate = async (yhub: YHub, docRef: DocRef): Promise => { }, 'seeded legacy doc from s3', ); + seedResult = 'seeded'; return 'exists'; } finally { activeSeeds--; + seedsInflight.dec(); + endSeed({ result: seedResult }); } } finally { if (acquired != null) { diff --git a/src/yhub-server/src/server.ts b/src/yhub-server/src/server.ts index 1a35b174d..7922255aa 100644 --- a/src/yhub-server/src/server.ts +++ b/src/yhub-server/src/server.ts @@ -20,6 +20,9 @@ import { ORG, PORT, POSTGRES, + PROMETHEUS_METRICS_ENABLED, + PROMETHEUS_METRICS_PATH, + PROMETHEUS_METRICS_PORT, REDIS, REDIS_PREFIX, ROLE, @@ -37,6 +40,13 @@ import { YHUB_S3_SECRET_ACCESS_KEY, allowedOrigins, } from './config.js'; +import { + docUpdatesTotal, + startMetricsServer, + timedAuth, + workerTaskDuration, + workerTasksInflight, +} from './metrics.js'; // legacy Django/S3 document store — see migration.ts and README.md import { SOFT_MIGRATION, @@ -294,12 +304,49 @@ const auth = createAuthPlugin({ }), }); +// The same plugin, timed from the outside: what a connection costs is these two +// callbacks — the backend calls they make, and the legacy seed — and wrapping +// them here leaves the policy above exactly as it reads. `authorize` is generic +// over the scope it is asked about, which a wrapper cannot carry: hence the cast +// back to the type it was given. +const timedAuthPlugin = createAuthPlugin({ + authenticate: timedAuth( + 'authenticate', + // `/collaboration/{name}/{version}/...` → index 2, as `authenticate` reads it + (req) => req.getUrl().split('/')[2], + (req) => auth.authenticate(req), + ), + authorize: timedAuth( + 'authorize', + (_scope, _resourceId, user) => user?.endpoint, + (...args: Parameters) => auth.authorize(...args), + ) as typeof auth.authorize, +}); + // `docUpdate` is the worker event for "this compaction found new content": the // task returns before it when it has nothing to persist, so the awareness-only // traffic of someone merely opening a document never reaches it. Since yhub // 0.5.0 it is handed the room of the task alongside the merged document. const workerEvents = { + taskStart: () => { + workerTasksInflight.inc(); + }, + // yhub reports the duration in milliseconds + taskComplete: ({ + duration, + error, + }: { + duration: number; + error: Error | null; + }) => { + workerTasksInflight.dec(); + workerTaskDuration.observe( + { result: error == null ? 'ok' : 'error' }, + duration / 1000, + ); + }, docUpdate: ({ docRef }: { docRef: DocRef }) => { + docUpdatesTotal.inc(); // Django knows the documents of this org, on the main branch, by their uuid if ( docRef.org !== ORG || @@ -423,7 +470,7 @@ const yhub: YHub = (await createYHub({ server: RUNS_SERVER ? { port: PORT, - auth, + auth: timedAuthPlugin, api, apiPrefix: API_PREFIX, // What a browser may reach this server from, applied by yhub to the websocket upgrade @@ -439,6 +486,10 @@ const yhub: YHub = (await createYHub({ : null, })) as YHub; +if (PROMETHEUS_METRICS_ENABLED) { + await startMetricsServer(yhub); +} + // What this process was configured to be, in one line: yhub's own startup log // reports neither the role nor the stream settings, and every one of them is an // environment variable a deployment can get wrong. The two timings are read @@ -455,6 +506,10 @@ logger.info( // postgres — a bucket with `s3Writes` false is one that is only read s3Bucket: YHUB_S3_BUCKET_NAME ?? null, s3Writes: S3_PERSISTENCE, + // where the metrics are served, null when they are not + metrics: PROMETHEUS_METRICS_ENABLED + ? `:${PROMETHEUS_METRICS_PORT}${PROMETHEUS_METRICS_PATH}` + : null, taskDebounceMs: yhub.stream.taskDebounce, minMessageLifetimeMs: yhub.stream.minMessageLifetime, }, diff --git a/src/yhub-server/yarn.lock b/src/yhub-server/yarn.lock index c5363c708..fe1416ee0 100644 --- a/src/yhub-server/yarn.lock +++ b/src/yhub-server/yarn.lock @@ -488,7 +488,7 @@ dependencies: "@opentelemetry/api" "^1.3.0" -"@opentelemetry/api@^1.3.0", "@opentelemetry/api@^1.9.1": +"@opentelemetry/api@^1.3.0", "@opentelemetry/api@^1.4.0", "@opentelemetry/api@^1.9.1": version "1.9.1" resolved "https://registry.yarnpkg.com/@opentelemetry/api/-/api-1.9.1.tgz#c1b0346de336ba55af2d5a7970882037baedec05" integrity sha512-gLyJlPHPZYdAk1JENA9LeHejZe1Ti77/pTeFm/nMXmQH/HFZlcS/O2XJB+L8fkbrNSqhdtlvjBVjxwUYanNH5Q== @@ -1111,6 +1111,11 @@ binary-extensions@^2.0.0: resolved "https://registry.yarnpkg.com/binary-extensions/-/binary-extensions-2.3.0.tgz#f6e14a97858d327252200242d4ccfe522c445522" integrity sha512-Ceh+7ox5qe7LJuLHoY0feh3pHuUDHAcRUeyL2VYghZwfpkNIy/+8Ocg0a3UuSoYzavmylwuLWQOf3hl0jjMMIw== +bintrees@1.0.2: + version "1.0.2" + resolved "https://registry.yarnpkg.com/bintrees/-/bintrees-1.0.2.tgz#49f896d6e858a4a499df85c38fb399b9aff840f8" + integrity sha512-VOMgTMwjAaUG580SXn3LacVgjurrbMme7ZZNYGSSV7mmtY6QQRh0Eg3pwIcntQ77DErK1L0NxkbetjcoXzVwKw== + block-stream2@^2.1.0: version "2.1.0" resolved "https://registry.yarnpkg.com/block-stream2/-/block-stream2-2.1.0.tgz#ac0c5ef4298b3857796e05be8ebed72196fa054b" @@ -1853,6 +1858,14 @@ process-warning@^5.0.0: resolved "https://registry.yarnpkg.com/process-warning/-/process-warning-5.1.0.tgz#0ea094b18b610f594243efc585e20f2dbee555dc" integrity sha512-jQSaVHsPgtyw60e1rQ/A+/ArPEj/S8pS/vFnyGa/gYFXrKk/6RuDkoqVDQ5NI5MmS01698ltlAk0NoDBNLujRw== +prom-client@15.1.3: + version "15.1.3" + resolved "https://registry.yarnpkg.com/prom-client/-/prom-client-15.1.3.tgz#69fa8de93a88bc9783173db5f758dc1c69fa8fc2" + integrity sha512-6ZiOBfCywsD4k1BN9IX0uZhF+tJkV8q8llP64G5Hajs4JOeVLPCwpPVcpXy3BwYiUGgyJzsJJQeOIv7+hDSq8g== + dependencies: + "@opentelemetry/api" "^1.4.0" + tdigest "^0.1.1" + pstree.remy@^1.1.8: version "1.1.8" resolved "https://registry.yarnpkg.com/pstree.remy/-/pstree.remy-1.1.8.tgz#c242224f4a67c21f686839bbdb4ac282b8373d3a" @@ -2089,6 +2102,13 @@ supports-color@^5.5.0: dependencies: has-flag "^3.0.0" +tdigest@^0.1.1: + version "0.1.3" + resolved "https://registry.yarnpkg.com/tdigest/-/tdigest-0.1.3.tgz#831a1fd531f207127ab75d054d4c6c6dedab3ac7" + integrity sha512-zbRt+lT+/H4fRItHshczHErVCQnitJk8MfMT24MqFJf3YL7SJJPqGIGeuOdvxXxM/AHFzKBl7WoyaYwqO9s3Kw== + dependencies: + bintrees "1.0.2" + thread-stream@^4.0.0: version "4.2.0" resolved "https://registry.yarnpkg.com/thread-stream/-/thread-stream-4.2.0.tgz#054063e93baab22363d05b784d6c7e439230cac7"