diff --git a/CLAUDE.md b/CLAUDE.md index 4a2d7be6..d360f25b 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -87,7 +87,7 @@ Strong success criteria let you loop independently. Weak criteria ("make it work - `e2e/` — Playwright end-to-end suite (`@oxynote/e2e`, **pnpm**) plus the two docker-compose stacks it drives: the dev stack built from this repo, and the all-in-one image `docker/prod/` produces. Not shipped; it exercises the composed product through a real backend. Every file, script and make target belonging to one stack is named `dev` or `prod` — neither is the unnamed default. Details: [e2e/CLAUDE.md](e2e/CLAUDE.md). - `scripts/` — helpers the root Makefile calls. `run-quietly.sh` runs a build step with its output held back, replaying the log only if the step fails. - `docker/` — dev docker-compose stack, Caddyfile, `env/` (committed `*.example.env` templates; `make setup` copies them to the gitignored `*.local.env` files the compose stack reads, and `web.example.env` also to `web/.env` for the host dev server and electron builds), `demo/` (demo-data configs for mariadb/postgres). -- `docker/prod/` — the production all-in-one image: alpine-based Dockerfile (built via `make prod-build`; core comes from goreleaser), the image's Caddyfile (sibling of `docker/Caddyfile`), the TS launcher (`@oxynote/launcher`, **pnpm**) that validates the flat public `OXYNOTE_*` env, generates internal secrets, and supervises caddy + web + core + auth-realtime, plus the example compose deployment. Details: [docker/prod/CLAUDE.md](docker/prod/CLAUDE.md). +- `docker/prod/` — the production all-in-one image: alpine-based Dockerfile (built via `make prod-build`; core comes from goreleaser), the image's Caddyfile (sibling of `docker/Caddyfile`), the TS launcher (`@oxynote/launcher`, **pnpm**) that validates the flat public `OXYNOTE_*` env, generates internal secrets, and supervises caddy + web + core + auth-realtime, plus the example compose deployment and the local override `make prod-run` layers on it. Details: [docker/prod/CLAUDE.md](docker/prod/CLAUDE.md). **One `.gitignore`, and it lives at the repository root.** Components do not carry their own — a rule for a nested directory is written with its path (`e2e/test-results/`, `web/coverage/`), so every exclusion in the repository is readable in one file. The exception is `web/packages/lezer-promql/`, which is a vendored upstream fork and keeps the ignore file it ships with. @@ -107,7 +107,8 @@ make lint # fix lint/format/type issues in web, auth-realtime, core, datage make check-lint # the same gates, verification only make prod-build # goreleaser core binary + the all-in-one prod image -make prod-run # run the example prod compose against the local image +make prod-run # build the image + run the example compose on :8080, with + # a mailpit on :8025 so signup mail is readable make prod-stop # stop it # release-only, run by .github/workflows/release.yml on a tag: # make prod-publish RELEASE_VERSION=1.2.3 -> pushes :latest and :1.2.3 diff --git a/Makefile b/Makefile index c04ef1ac..a72663ef 100644 --- a/Makefile +++ b/Makefile @@ -10,6 +10,8 @@ PROD_BUILD_EXTRA ?= COMPOSE := docker-compose -p oxynote -f docker/docker-compose.dev.yaml E2E_DEV_COMPOSE := docker compose -f e2e/docker-compose.dev.yaml $(E2E_DEV_COMPOSE_EXTRA) E2E_PROD_COMPOSE := docker compose -f e2e/docker-compose.prod.yaml +PROD_COMPOSE := docker compose -f docker/prod/docker-compose.example.yaml \ + -f docker/prod/docker-compose.local.yaml # a tag names the stack an image belongs to. The e2e targets override these # to :e2e-dev and :e2e-prod so a run cannot replace the image `make start` @@ -165,14 +167,18 @@ prod-publish: -t ghcr.io/oxynote/oxynote:$(RELEASE_VERSION) \ --push . -# the example compose against the locally built image +# build the image, then run the example deployment against it on +# http://localhost:8080 (ctrl-c stops it). The local override adds the mail +# sink the example only describes in a comment: signup requires a verified +# address, so without it the verification link is only logged. Read the +# delivered mail at http://localhost:8025. .PHONY: prod-run -prod-run: - OXYNOTE_IMAGE_TAG=prod docker compose -f docker/prod/docker-compose.example.yaml up +prod-run: prod-build + OXYNOTE_IMAGE_TAG=$(PROD_IMAGE_TAG) $(PROD_COMPOSE) up .PHONY: prod-stop prod-stop: - docker compose -f docker/prod/docker-compose.example.yaml down + $(PROD_COMPOSE) down # changedetection.io generates its API key on first boot; start it alone and # copy the key into core.local.env before the rest of the stack (core reads diff --git a/docker/Caddyfile b/docker/Caddyfile index 2c7c126d..5b6d560b 100644 --- a/docker/Caddyfile +++ b/docker/Caddyfile @@ -3,6 +3,12 @@ # upstreams differ. Change the two files together. { admin off # disable the admin API + + # every served request is an INFO access log line, and nothing here + # reads them; warnings and errors still come through. + log { + level WARN + } } (common) { diff --git a/docker/docker-compose.dev.yaml b/docker/docker-compose.dev.yaml index bd728296..eaee68d3 100644 --- a/docker/docker-compose.dev.yaml +++ b/docker/docker-compose.dev.yaml @@ -112,6 +112,7 @@ services: max-file: "3" postgres: image: postgres:18.6-alpine + command: ["postgres", "-c", "log_checkpoints=off"] volumes: - postgres_data:/var/lib/postgresql - ./demo/postgres/init-demo-db.sh:/docker-entrypoint-initdb.d/init-demo-db.sh @@ -133,6 +134,7 @@ services: max-file: "3" mariadb: image: mariadb:12.3.2-noble + command: ["--log-warnings=1"] volumes: - mariadb_data:/var/lib/mysql - ./demo/mariadb/init-demo-db.sql:/docker-entrypoint-initdb.d/init-demo-db.sql @@ -161,6 +163,7 @@ services: environment: - MEILI_MASTER_KEY=devmasterkey - MEILI_ENV=development + - MEILI_LOG_LEVEL=WARN restart: unless-stopped logging: driver: local @@ -171,6 +174,8 @@ services: mailpit: container_name: mailpit image: axllent/mailpit:v1.31.0 + environment: + - MP_QUIET=true restart: unless-stopped logging: driver: local @@ -181,6 +186,7 @@ services: valkey: container_name: valkey image: valkey/valkey:9.1.1-alpine + command: ["valkey-server", "--loglevel", "warning"] volumes: - valkey_data:/data restart: unless-stopped @@ -240,6 +246,7 @@ services: environment: - GF_SECURITY_ADMIN_USER=admin - GF_SECURITY_ADMIN_PASSWORD=admin + - GF_LOG_LEVEL=error volumes: core_storage: diff --git a/docker/env/auth-realtime.example.env b/docker/env/auth-realtime.example.env index 6c555ee6..e29309e7 100644 --- a/docker/env/auth-realtime.example.env +++ b/docker/env/auth-realtime.example.env @@ -15,6 +15,11 @@ OXYNOTE_AUTH_REALTIME_VALKEY_DSN=redis://valkey:6379 # the listen address as host:port; empty binds all interfaces on 8081. OXYNOTE_AUTH_REALTIME_ADDRESS= +# observability +# the floor for everything the service writes, better-auth's and +# hocuspocus's lines included (DEBUG, INFO, WARN, ERROR); empty means INFO. +OXYNOTE_AUTH_REALTIME_LOG_LEVEL= + # public URLs (the caddy front door) OXYNOTE_AUTH_REALTIME_BETTER_AUTH_BASE_URL=http://localhost:8080/auth-realtime OXYNOTE_AUTH_REALTIME_BETTER_AUTH_COOKIE_DOMAIN=localhost diff --git a/docker/prod/CLAUDE.md b/docker/prod/CLAUDE.md index aa1bed9d..e4dbfc3b 100644 --- a/docker/prod/CLAUDE.md +++ b/docker/prod/CLAUDE.md @@ -13,7 +13,11 @@ tini. Postgres is the only required external service; valkey, an S3-compatible store, meilisearch, SMTP and changedetection.io are optional and external too — without a store, objects are kept on the data volume; `docker-compose.example.yaml` is the canonical deployment and `README.md` -the operator-facing reference. +the operator-facing reference. `docker-compose.local.yaml` is not part of +either: it is the override **`make prod-run`** layers on the example to +build the image and drive it from a browser here, adding the mailpit the +example only describes in a comment — signup requires a verified address, so +without a relay the verification link is never more than a log line. Build with **`make prod-build`** from the repository root: core's binary must come from goreleaser (never a plain `go build`), so the target @@ -79,6 +83,29 @@ also publish `ghcr.io/oxynote/core` from the `dockers_v2` block. `loadConfig` throws on it. - **Crash policy: die, don't restart.** Any child exit tears the rest down and exits the container nonzero; restarts belong to the container runtime. +- **Every line the container emits is a JSON record with a `service` + field** naming the process that wrote it — `launcher`, `core`, + `auth-realtime`, `web`, `caddy` — which is what the old `[core]`-style + tags said, in a form nothing has to parse back out of the text. +- **`service` is the only thing the launcher adds to a child's line.** + `childRecord` ([logging.ts](launcher/src/logging.ts)) merges the field + into the object a child already logged and changes nothing else: core's + and auth-realtime's `time`/`level`/`msg`, caddy's `ts` and `logger`, all + survive as their own keys. Stamping the launcher's level and timestamp on + top would report when the relay ran rather than when the event happened, + and rank a line the launcher never read. A line that is not a JSON object + — plain text, an array, a number — becomes `{msg, service}`, which is all + the launcher knows about it. `service` is written last, so the launcher's + answer wins over a child that claims a different one. +- **The launcher's own events go through pino** at a fixed info level, in + the shape core and auth-realtime emit (ISO `time`, uppercase `level`, + `msg`). They are the container's lifecycle, a dozen lines per boot, and + `OXYNOTE_LOG_LEVEL` lowers what the *services* write rather than whether + the container narrates its start. Both paths share one open stdout, so + records reach the stream in write order. +- **Each stream gets its own splitter**, since a line is only whole within + the stream it arrived on; `mute` drops what a child prints with no way to + switch it off (nitro's loopback listen banner). - **Supply chain**: every `FROM` is pinned by digest; caddy and tini are downloaded at pinned versions and checksum-verified. Caddy is Apache-2.0 (its LICENSE ships in the image at `/oxynote/licenses/caddy/`); the name diff --git a/docker/prod/Caddyfile b/docker/prod/Caddyfile index 4347ad52..dab7f232 100644 --- a/docker/prod/Caddyfile +++ b/docker/prod/Caddyfile @@ -4,6 +4,12 @@ # files together. { admin off # disable the admin API + + # every served request is an INFO access log line, and nothing here + # reads them; warnings and errors still come through. + log { + level WARN + } } (common) { diff --git a/docker/prod/README.md b/docker/prod/README.md index f2f3f119..cc4dde04 100644 --- a/docker/prod/README.md +++ b/docker/prod/README.md @@ -14,10 +14,12 @@ cp docker/prod/docker-compose.example.yaml my-deployment.yaml docker compose -f my-deployment.yaml up -d ``` -From a repository checkout, `make prod-build && make prod-run` -builds the image locally (goreleaser builds the core binary first — a bare -`docker build` is not supported) and runs the example as-is on -`http://localhost:8080`. +From a repository checkout, `make prod-run` builds the image locally +(goreleaser builds the core binary first — a bare `docker build` is not +supported) and runs this example on `http://localhost:8080`, with +`docker-compose.local.yaml` layered on top so signup mail lands in a mailpit +at `http://localhost:8025` instead of being logged. `make prod-stop` stops +it. The image serves plain HTTP on port **8080**. For a real domain, put a TLS-terminating proxy in front and set `OXYNOTE_PUBLIC_URL` to the public @@ -60,7 +62,9 @@ cleanly. An incomplete group fails the boot with the missing name. by client IP — disable it behind a proxy that hides the original IP and rate limit there instead), `OXYNOTE_MAX_DOCUMENT_HISTORY_ENTRIES`, `OXYNOTE_DOCUMENT_HISTORY_RETENTION` (Go duration, e.g. `2160h`), -`OXYNOTE_LOG_LEVEL` (`DEBUG`/`INFO`/`WARN`/`ERROR`), +`OXYNOTE_LOG_LEVEL` (`DEBUG`/`INFO`/`WARN`/`ERROR`; the floor for both core +and auth-realtime, `WARN` by default, so the container logs carry the +exceptions rather than the traffic), `OXYNOTE_TERMS_OF_SERVICE_URL`, `OXYNOTE_PRIVACY_POLICY_URL`. ## Secrets and the data volume diff --git a/docker/prod/docker-compose.example.yaml b/docker/prod/docker-compose.example.yaml index 586b626b..590d0a77 100644 --- a/docker/prod/docker-compose.example.yaml +++ b/docker/prod/docker-compose.example.yaml @@ -4,9 +4,10 @@ # put a TLS-terminating proxy in front for a real domain (the image itself # speaks plain HTTP on 8080). # -# `make prod-run` from the repository root uses this file as-is -# against a locally built image (tag :dev). The full variable reference -# lives in README.md next to this file. +# `make prod-run` from the repository root builds the image and runs this +# file against it, with docker-compose.local.yaml layered on top to add the +# mail sink a browser trial needs. The full variable reference lives in +# README.md next to this file. name: oxynote-prod @@ -45,6 +46,7 @@ services: postgres: image: postgres:18.6-alpine + command: ["postgres", "-c", "log_checkpoints=off"] environment: - POSTGRES_USER=oxynote - POSTGRES_PASSWORD=change-me-db @@ -63,6 +65,7 @@ services: environment: - MEILI_ENV=production - MEILI_MASTER_KEY=change-me-meili-key + - MEILI_LOG_LEVEL=WARN volumes: - meilisearch_data:/meili_data healthcheck: diff --git a/docker/prod/docker-compose.local.yaml b/docker/prod/docker-compose.local.yaml new file mode 100644 index 00000000..3c92c38a --- /dev/null +++ b/docker/prod/docker-compose.local.yaml @@ -0,0 +1,29 @@ +# what `make prod-run` layers on top of the example deployment so the image +# can be driven from a browser on this machine. It is not part of the +# deployment operators copy — docker-compose.example.yaml is that file, and +# it stays as documented. +# +# the one thing a local run cannot do without is mail: signup requires a +# verified address, so without a relay the verification link is only ever +# logged. This starts the mail sink the example already describes in a +# comment and points the image at it; the delivered mail is read at +# http://localhost:8025. + +name: oxynote-prod + +services: + oxynote: + environment: + - OXYNOTE_SMTP_DSN=smtp://mailpit:1025?tls=none + - OXYNOTE_EMAIL_FROM_ADDRESS=Oxynote + depends_on: + mailpit: + condition: service_started + + mailpit: + image: axllent/mailpit:v1.31.0 + environment: + - MP_QUIET=true + ports: + - "8025:8025" + restart: unless-stopped diff --git a/docker/prod/launcher/package.json b/docker/prod/launcher/package.json index 2828fb1a..acc62783 100644 --- a/docker/prod/launcher/package.json +++ b/docker/prod/launcher/package.json @@ -24,6 +24,7 @@ }, "dependencies": { "@sentry/node": "^10.71.0", + "pino": "^10.3.1", "zod": "^4.4.3" }, "devDependencies": { diff --git a/docker/prod/launcher/pnpm-lock.yaml b/docker/prod/launcher/pnpm-lock.yaml index abda2e0f..5d54658b 100644 --- a/docker/prod/launcher/pnpm-lock.yaml +++ b/docker/prod/launcher/pnpm-lock.yaml @@ -11,6 +11,9 @@ importers: '@sentry/node': specifier: ^10.71.0 version: 10.71.0(@opentelemetry/core@2.10.0(@opentelemetry/api@1.9.1)) + pino: + specifier: ^10.3.1 + version: 10.3.1 zod: specifier: ^4.4.3 version: 4.4.3 @@ -600,6 +603,9 @@ packages: cpu: [x64] os: [win32] + '@pinojs/redact@0.4.0': + resolution: {integrity: sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==} + '@rolldown/binding-android-arm-eabi@1.2.5': resolution: {integrity: sha512-DLe/i+l8ynIBY7XEQ191TeZvCoowIGa18R+dIV30GW7DiOtp74i/xX8hs8GUjW5ARV7VZuie3d6AumSmCwbeRA==} engines: {node: ^20.19.0 || >=22.12.0} @@ -905,6 +911,10 @@ packages: resolution: {integrity: sha512-LElXdjswlqjWrPpJFg1Fx4wpkOCxj1TDHlSV4PlaRxHGWko024xICaa97ZkMfs6DRKlCguiAI+rbXv5GWwXIkg==} hasBin: true + atomic-sleep@1.0.0: + resolution: {integrity: sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==} + engines: {node: '>=8.0.0'} + balanced-match@4.0.4: resolution: {integrity: sha512-BLrgEcRTwX2o6gGxGOCNyMvGSp35YofuYzw9h1IMTRmKqttAZZVU67bdb9Pr2vUHA8+j3i2tJfjO6C6+4myGTA==} engines: {node: 18 || 20 || >=22} @@ -1251,6 +1261,10 @@ packages: resolution: {integrity: sha512-4a+OsYv9UktOJKE+l1A4OufDgdRF9PifWj+tJnHURo/P+WOxpG4GzUFL9qCalmWauao6ogiG+QvnCovwPoyAWA==} engines: {node: '>=12.20.0'} + on-exit-leak-free@2.1.2: + resolution: {integrity: sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==} + engines: {node: '>=14.0.0'} + optionator@0.9.4: resolution: {integrity: sha512-6IpQ7mKUxRcZNLIObR0hz7lxsapSSIYNZJwXPGeF0mTVqGKFIXj1DQcMoT22S3ROcLyY/rz0PWaWZ9ayWmad9g==} engines: {node: '>= 0.8.0'} @@ -1288,6 +1302,16 @@ packages: resolution: {integrity: sha512-qcJu88Q2IWqJsDD529JKMdwGm/dvInW4HvQnRwiH9JtihJvzGOscDtHE3x1pBKeUOTysQ8kVmLnJ2kJu7yhcGA==} engines: {node: '>=12'} + pino-abstract-transport@3.0.0: + resolution: {integrity: sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==} + + pino-std-serializers@7.1.0: + resolution: {integrity: sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==} + + pino@10.3.1: + resolution: {integrity: sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg==} + hasBin: true + postcss@8.5.26: resolution: {integrity: sha512-u82N74LFzG8ca+dD8puPnplTXoGH4fTPpVGuIbt36G3qvNlkvfD0lEAZSxaly3KX8TS/L1A1gsCEmvKmBcVbkQ==} engines: {node: ^10 || ^12 || >=14} @@ -1301,10 +1325,23 @@ packages: engines: {node: '>=14'} hasBin: true + process-warning@5.1.0: + resolution: {integrity: sha512-jQSaVHsPgtyw60e1rQ/A+/ArPEj/S8pS/vFnyGa/gYFXrKk/6RuDkoqVDQ5NI5MmS01698ltlAk0NoDBNLujRw==} + punycode@2.3.1: resolution: {integrity: sha512-vYt7UD1U9Wg6138shLtLOvdAu+8DsC/ilFtEVHcH+wydcSpNE20AfSOduf6MkRFahL5FY7X1oU7nKVZFtfq8Fg==} engines: {node: '>=6'} + quick-format-unescaped@4.0.4: + resolution: {integrity: sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==} + + real-require@0.2.0: + resolution: {integrity: sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==} + engines: {node: '>= 12.13.0'} + + real-require@1.0.0: + resolution: {integrity: sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==} + require-in-the-middle@8.0.1: resolution: {integrity: sha512-QT7FVMXfWOYFbeRBF6nu+I6tr2Tf3u0q8RIEjNob/heKY/nh7drD/k7eeMFmSQgnTtCzLDcCu/XEnpW2wk4xCQ==} engines: {node: '>=9.3.0 || >=8.10.0 <9.0.0'} @@ -1317,6 +1354,10 @@ packages: engines: {node: ^20.19.0 || >=22.12.0} hasBin: true + safe-stable-stringify@2.5.0: + resolution: {integrity: sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==} + engines: {node: '>=10'} + semifies@1.0.0: resolution: {integrity: sha512-xXR3KGeoxTNWPD4aBvL5NUpMTT7WMANr3EWnaS190QVkY52lqqcVRD7Q05UVbBhiWDGWMlJEUam9m7uFFGVScw==} @@ -1340,6 +1381,9 @@ packages: resolution: {integrity: sha512-kCZr2V3ch9i00x8zXRhjUNVcjG9ijES5dDudkXvUVCT5QlJNQWElSJdZqyPemffHoLNUYwOcou0Fy+ojN0uHSQ==} engines: {node: '>= 18'} + sonic-boom@4.2.1: + resolution: {integrity: sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==} + source-map-js@1.2.1: resolution: {integrity: sha512-UXWMKhLOwVKb728IUtQPXxfYU+usdybtUrK/8uGE8CQMvrhOpwvzDBwj0QhSL7MQc7vIsISBG8VQ8+IDQxpfQA==} engines: {node: '>=0.10.0'} @@ -1348,6 +1392,10 @@ packages: resolution: {integrity: sha512-UjgapumWlbMhkBgzT7Ykc5YXUT46F0iKu8SGXq0bcwP5dz/h0Plj6enJqjz1Zbq2l5WaqYnrVbwWOWMyF3F47g==} engines: {node: '>=0.10.0'} + split2@4.2.0: + resolution: {integrity: sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==} + engines: {node: '>= 10.x'} + stackback@0.0.2: resolution: {integrity: sha512-1XMJE5fQo1jGH6Y/7ebnwPOBEkIEnT4QF32d5R1+VXdXveM0IBMJt8zfaxX1P3QhVwrYe+576+jkANtSS2mBbw==} @@ -1362,6 +1410,10 @@ packages: resolution: {integrity: sha512-qpCAvRl9stuOHveKsn7HncJRvv501qIacKzQlO/+Lwxc9+0q2wLyv4Dfvt80/DPn2pqOBsJdDiogXGR9+OvwRw==} engines: {node: '>=8'} + thread-stream@4.2.0: + resolution: {integrity: sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==} + engines: {node: '>=20'} + tinybench@2.9.0: resolution: {integrity: sha512-0+DUvqWMValLmha6lr4kD8iAMK1HzV0/aKnCtWb9v9641TnP/MFb7Pc2bxoxQjTXAErryXVgUOfv2YqNllqGeg==} @@ -1892,6 +1944,8 @@ snapshots: '@oxc-resolver/binding-win32-x64-msvc@11.24.2': optional: true + '@pinojs/redact@0.4.0': {} + '@rolldown/binding-android-arm-eabi@1.2.5': optional: true @@ -2196,6 +2250,8 @@ snapshots: astring@1.9.0: {} + atomic-sleep@1.0.0: {} + balanced-match@4.0.4: {} brace-expansion@5.0.9: @@ -2531,6 +2587,8 @@ snapshots: obug@2.1.4: {} + on-exit-leak-free@2.1.2: {} + optionator@0.9.4: dependencies: deep-is: 0.1.4 @@ -2604,6 +2662,26 @@ snapshots: picomatch@4.0.7: {} + pino-abstract-transport@3.0.0: + dependencies: + split2: 4.2.0 + + pino-std-serializers@7.1.0: {} + + pino@10.3.1: + dependencies: + '@pinojs/redact': 0.4.0 + atomic-sleep: 1.0.0 + on-exit-leak-free: 2.1.2 + pino-abstract-transport: 3.0.0 + pino-std-serializers: 7.1.0 + process-warning: 5.1.0 + quick-format-unescaped: 4.0.4 + real-require: 0.2.0 + safe-stable-stringify: 2.5.0 + sonic-boom: 4.2.1 + thread-stream: 4.2.0 + postcss@8.5.26: dependencies: nanoid: 3.3.18 @@ -2614,8 +2692,16 @@ snapshots: prettier@3.9.6: {} + process-warning@5.1.0: {} + punycode@2.3.1: {} + quick-format-unescaped@4.0.4: {} + + real-require@0.2.0: {} + + real-require@1.0.0: {} + require-in-the-middle@8.0.1: dependencies: debug: 4.4.3 @@ -2646,6 +2732,8 @@ snapshots: '@rolldown/binding-win32-arm64-msvc': 1.2.5 '@rolldown/binding-win32-x64-msvc': 1.2.5 + safe-stable-stringify@2.5.0: {} + semifies@1.0.0: {} semver@7.8.5: {} @@ -2660,10 +2748,16 @@ snapshots: smol-toml@1.8.0: {} + sonic-boom@4.2.1: + dependencies: + atomic-sleep: 1.0.0 + source-map-js@1.2.1: {} source-map@0.6.1: {} + split2@4.2.0: {} + stackback@0.0.2: {} std-env@4.2.0: {} @@ -2674,6 +2768,10 @@ snapshots: dependencies: has-flag: 4.0.0 + thread-stream@4.2.0: + dependencies: + real-require: 1.0.0 + tinybench@2.9.0: {} tinyexec@1.3.0: {} diff --git a/docker/prod/launcher/src/env.test.ts b/docker/prod/launcher/src/env.test.ts index 3a240608..369a2791 100644 --- a/docker/prod/launcher/src/env.test.ts +++ b/docker/prod/launcher/src/env.test.ts @@ -478,6 +478,12 @@ describe("loadConfig", () => { expect(config.logLevel).toBe("DEBUG") }) + it("defaults the log level to WARN", ({ expect }) => { + const config = loadConfig(completeEnv({})) + + expect(config.logLevel).toBe("WARN") + }) + it.for([ { name: "a word as a counter", diff --git a/docker/prod/launcher/src/env.ts b/docker/prod/launcher/src/env.ts index fedaa302..58240e8d 100644 --- a/docker/prod/launcher/src/env.ts +++ b/docker/prod/launcher/src/env.ts @@ -618,7 +618,10 @@ export function loadConfig(source: Record): Config { values.OXYNOTE_MAX_DOCUMENT_HISTORY_ENTRIES ?? "", documentHistoryRetention: values.OXYNOTE_DOCUMENT_HISTORY_RETENTION ?? "", - logLevel: values.OXYNOTE_LOG_LEVEL ?? "", + // core defaults to INFO on its own, which in this image means + // every request the front door serves ends up in `docker logs`. + // An operator wants the exceptions, not the traffic. + logLevel: values.OXYNOTE_LOG_LEVEL ?? "WARN", termsOfServiceUrl: values.OXYNOTE_TERMS_OF_SERVICE_URL ?? "", privacyPolicyUrl: values.OXYNOTE_PRIVACY_POLICY_URL ?? "", crashReportingDisabled: values.OXYNOTE_CRASH_REPORTING_DISABLED, diff --git a/docker/prod/launcher/src/index.ts b/docker/prod/launcher/src/index.ts index 13847ce8..f886caa4 100644 --- a/docker/prod/launcher/src/index.ts +++ b/docker/prod/launcher/src/index.ts @@ -3,9 +3,11 @@ import net from "node:net" import os from "node:os" import { join } from "node:path" import * as Sentry from "@sentry/node" +import { destination } from "pino" import { bakedLauncherSentryDsn, bakedSentryDsns } from "./baked.js" import { loadConfig, type Config } from "./env.js" import { checkLoopbackExposure } from "./loopback.js" +import { childRecord, createLogger } from "./logging.js" import { authRealtimePort, authRealtimeUrl, @@ -43,8 +45,14 @@ const crashReporter = createCrashReporter( // has to SIGKILL the whole container. const shutdownDeadlineMs = 55_000 -function log(line: string): void { - console.log(line) +// one open stdout for the launcher's own logger and for the children's +// relayed lines, so every record reaches the stream in write order rather +// than through two buffers. +const out = destination(1) +const log = createLogger("launcher", out) + +function logChildLine(name: string, line: string): void { + out.write(`${childRecord(name, line)}\n`) } function sleep(ms: number): Promise { @@ -110,7 +118,7 @@ async function shutdown(supervisor: Supervisor, code: number): Promise { shuttingDown = true const deadline = setTimeout(() => { - console.error("[launcher] shutdown deadline exceeded") + log.error("shutdown deadline exceeded") process.exit(1) }, shutdownDeadlineMs) @@ -123,8 +131,8 @@ async function shutdown(supervisor: Supervisor, code: number): Promise { function logEnabledFeatures(config: Config): void { const state = (enabled: boolean) => (enabled ? "on" : "off") - log( - `[launcher] search ${state(config.meilisearch !== undefined)}, ` + + log.info( + `search ${state(config.meilisearch !== undefined)}, ` + `email ${state(config.smtp !== undefined)}, ` + `github app ${state(config.githubApp !== undefined)}, ` + `slack app ${state(config.slackApp !== undefined)}, ` + @@ -142,18 +150,18 @@ async function main(): Promise { }) for (const name of report.generated) { - log(`[launcher] generated secret ${name}`) + log.info(`generated secret ${name}`) } if (report.fromVolume.length > 0) { - log( - `[launcher] using existing secrets: ${report.fromVolume.join(", ")}`, + log.info( + `using existing secrets: ${report.fromVolume.join(", ")}`, ) } if (report.fromEnv.length > 0) { - log( - `[launcher] secrets provided via environment: ${report.fromEnv.join(", ")}`, + log.info( + `secrets provided via environment: ${report.fromEnv.join(", ")}`, ) } @@ -171,10 +179,11 @@ async function main(): Promise { probe, sleep, log, + logChildLine, onUnexpectedExit(name, code) { const message = `${name} exited unexpectedly with code ${code}` - log(`[launcher] ${message}`) + log.error(message) // the child is gone, so whatever it would have reported // for itself is lost — an OOM kill leaves no other // trace at all. Reporting is awaited before the @@ -226,6 +235,13 @@ async function main(): Promise { readyUrl: `${webUrl}/login`, readyTimeoutMs: 60_000, stopGraceMs: 10_000, + // nitro's node-server entry announces the address it + // bound with a bare console.log and offers no way to + // silence it. That address is this container's + // loopback, not the one anyone reaches the app on, so + // it is dropped here and the launcher's own "up at" + // line — the public URL — is the one left standing. + mute: /^Listening on /, }, { name: "caddy", @@ -264,22 +280,18 @@ async function main(): Promise { ) } } catch (err) { - console.error( - `[launcher] ${err instanceof Error ? err.message : String(err)}`, - ) + log.error(err instanceof Error ? err.message : String(err)) await crashReporter.report(err) await supervisor.stopAll() process.exit(1) } - log(`[launcher] oxynote is up at ${config.publicOrigin}`) + log.info(`oxynote is up at ${config.publicOrigin}`) logEnabledFeatures(config) } main().catch((err: unknown) => { - console.error( - `[launcher] ${err instanceof Error ? err.message : String(err)}`, - ) + log.error(err instanceof Error ? err.message : String(err)) void crashReporter.report(err).then(() => { process.exit(1) }) diff --git a/docker/prod/launcher/src/logging.test.ts b/docker/prod/launcher/src/logging.test.ts index 90cda359..cb49c0ee 100644 --- a/docker/prod/launcher/src/logging.test.ts +++ b/docker/prod/launcher/src/logging.test.ts @@ -1,61 +1,185 @@ import { describe, it, vi } from "vitest" -import { createLinePrefixer } from "./logging.js" +import { childRecord, createLineSplitter, createLogger } from "./logging.js" -describe("createLinePrefixer", () => { - it("prefixes each complete line in a chunk", ({ expect }) => { - const write = vi.fn() - const prefixer = createLinePrefixer("[core]", write) +// a destination that keeps what pino wrote, parsed back into records. +function capture() { + const lines: string[] = [] - prefixer.data("first\nsecond\n") + return { + destination: { + write(chunk: string) { + lines.push(chunk) + }, + }, + records: () => + lines.map( + (line) => + JSON.parse(line) as Record< + string, + unknown + >, + ), + } +} - expect(write.mock.calls).toEqual([ - ["[core] first"], - ["[core] second"], +describe("createLogger", () => { + it("stamps every line with the service it was given", ({ expect }) => { + const written = capture() + + createLogger("launcher", written.destination).info( + "starting core", + ) + + expect(written.records()).toEqual([ + { + time: expect.stringMatching( + /^\d{4}-\d{2}-\d{2}T[\d:.]+Z$/, + ) as unknown, + level: "INFO", + service: "launcher", + msg: "starting core", + }, ]) }) + it("carries the level of each message it is given", ({ expect }) => { + const written = capture() + const log = createLogger("launcher", written.destination) + + log.info("up") + log.warn("exceeded its stop grace") + log.error("exited unexpectedly") + + expect(written.records().map((record) => record.level)).toEqual( + ["INFO", "WARN", "ERROR"], + ) + }) +}) + +describe("childRecord", () => { + it("passes a child's own JSON through, adding only the service", ({ + expect, + }) => { + const line = JSON.stringify({ + time: "2026-08-30T18:40:16.987Z", + level: "WARN", + msg: "github app integration is disabled", + version: "0.0.0", + }) + + expect(JSON.parse(childRecord("core", line))).toEqual({ + time: "2026-08-30T18:40:16.987Z", + level: "WARN", + msg: "github app integration is disabled", + version: "0.0.0", + service: "core", + }) + }) + + it("keeps the child's own level and time rather than restamping them", ({ + expect, + }) => { + const line = JSON.stringify({ + level: "warn", + ts: 1788112770.5264275, + logger: "admin", + msg: "admin endpoint disabled", + }) + + expect(JSON.parse(childRecord("caddy", line))).toEqual({ + level: "warn", + ts: 1788112770.5264275, + logger: "admin", + msg: "admin endpoint disabled", + service: "caddy", + }) + }) + + it("names the child itself when its line claims another service", ({ + expect, + }) => { + const line = JSON.stringify({ service: "elsewhere", msg: "hi" }) + + expect(JSON.parse(childRecord("web", line))).toEqual({ + service: "web", + msg: "hi", + }) + }) + + it.for([ + { name: "plain text", input: "listening on the socket" }, + { name: "a broken object", input: '{"msg":"unterminated' }, + { name: "an array", input: '["one","two"]' }, + { name: "a bare number", input: "42" }, + ])("carries $name as the message", ({ input }, { expect }) => { + expect(JSON.parse(childRecord("web", input))).toEqual({ + msg: input, + service: "web", + }) + }) +}) + +describe("createLineSplitter", () => { + it("emits each complete line in a chunk", ({ expect }) => { + const emit = vi.fn() + const splitter = createLineSplitter(emit) + + splitter.data("first\nsecond\n") + + expect(emit.mock.calls).toEqual([["first"], ["second"]]) + }) + it("holds a trailing fragment until its newline arrives", ({ expect, }) => { - const write = vi.fn() - const prefixer = createLinePrefixer("[web]", write) + const emit = vi.fn() + const splitter = createLineSplitter(emit) - prefixer.data("par") - expect(write).toHaveBeenCalledTimes(0) + splitter.data("par") + expect(emit).toHaveBeenCalledTimes(0) - prefixer.data("tial\nrest") + splitter.data("tial\nrest") - expect(write.mock.calls).toEqual([["[web] partial"]]) + expect(emit.mock.calls).toEqual([["partial"]]) + }) + + it("drops the lines mute matches and keeps the rest", ({ expect }) => { + const emit = vi.fn() + const splitter = createLineSplitter(emit, /^Listening on /) + + splitter.data("Listening on http://127.0.0.1:3000\nserving\n") + splitter.data("Listening on http://127.0.0.1:3000") + splitter.end() + + expect(emit.mock.calls).toEqual([["serving"]]) }) it("flushes the held fragment at stream end", ({ expect }) => { - const write = vi.fn() - const prefixer = createLinePrefixer("[auth-realtime]", write) + const emit = vi.fn() + const splitter = createLineSplitter(emit) - prefixer.data("no newline") - prefixer.end() + splitter.data("no newline") + splitter.end() - expect(write.mock.calls).toEqual([ - ["[auth-realtime] no newline"], - ]) + expect(emit.mock.calls).toEqual([["no newline"]]) }) it("ends quietly when nothing is buffered", ({ expect }) => { - const write = vi.fn() - const prefixer = createLinePrefixer("[caddy]", write) + const emit = vi.fn() + const splitter = createLineSplitter(emit) - prefixer.data("done\n") - prefixer.end() + splitter.data("done\n") + splitter.end() - expect(write).toHaveBeenCalledTimes(1) + expect(emit).toHaveBeenCalledTimes(1) }) it("reads buffer chunks the way streams deliver them", ({ expect }) => { - const write = vi.fn() - const prefixer = createLinePrefixer("[core]", write) + const emit = vi.fn() + const splitter = createLineSplitter(emit) - prefixer.data(Buffer.from("from a buffer\n")) + splitter.data(Buffer.from("from a buffer\n")) - expect(write.mock.calls).toEqual([["[core] from a buffer"]]) + expect(emit.mock.calls).toEqual([["from a buffer"]]) }) }) diff --git a/docker/prod/launcher/src/logging.ts b/docker/prod/launcher/src/logging.ts index 6d163ae2..b876230c 100644 --- a/docker/prod/launcher/src/logging.ts +++ b/docker/prod/launcher/src/logging.ts @@ -1,20 +1,104 @@ -export interface LinePrefixer { +import { pino, type DestinationStream } from "pino" + +// what the launcher logs its own events through: a message at one of three +// levels. +export interface Logger { + info(message: string): void + warn(message: string): void + error(message: string): void +} + +// createLogger builds the pino instance the launcher's own events go +// through, in the shape core and auth-realtime emit: an ISO timestamp, an +// uppercase level, the message under "msg", and the service field every +// record in the container stream carries. A child's output does not go +// through it — see childRecord, which adds that one field and touches +// nothing else. +// +// the level is fixed at info: the launcher's lines are the container's own +// lifecycle, a dozen per boot, and the "up at" line among them is the one an +// operator waits for — OXYNOTE_LOG_LEVEL lowers what the services +// themselves write, not whether the container narrates its start. +export function createLogger( + service: string, + destination: DestinationStream, +): Logger { + return pino( + { + level: "info", + base: { service }, + timestamp: pino.stdTimeFunctions.isoTime, + formatters: { + level: (label) => ({ + level: label.toUpperCase(), + }), + }, + }, + destination, + ) +} + +// childRecord renders one line of a child's output as one JSON record. +// +// a child that already logs JSON gets its object through as it wrote it, +// with one field added: service, naming the process the line came from. Its +// own level, time and fields are the ones that mean anything — stamping the +// launcher's on top would report when the relay ran rather than when the +// event happened, and rank a line the launcher never read. Anything else — +// a plain-text line, a JSON array, a bare number — becomes the msg of a +// record carrying only what the launcher does know: which child, and what +// it said. +// +// service is written last so it wins outright: the launcher is the one +// thing that knows for certain which process produced the line. +export function childRecord(service: string, line: string): string { + return JSON.stringify({ ...(asObject(line) ?? { msg: line }), service }) +} + +// asObject answers with the line's own fields when it is a JSON object, and +// undefined for everything else. Only an object can open with a brace, so +// the guard settles both questions at once: what it lets through parses to +// an object or not at all, and the try stays off every plain-text line a +// child writes — an array or a bare number never reaches it. +function asObject(line: string): Record | undefined { + if (!line.startsWith("{")) { + return undefined + } + + try { + return JSON.parse(line) as Record + } catch { + return undefined + } +} + +export interface LineSplitter { data(chunk: Buffer | string): void end(): void } -// createLinePrefixer buffers a child's raw output chunks and emits complete -// lines tagged with the child's name, so the four processes' logs stay -// tellable apart in the single container stream. A trailing fragment is -// held until its newline arrives and flushed at stream end, which keeps the -// last line of a crashing child — usually the one that matters — from -// being lost. -export function createLinePrefixer( - prefix: string, - write: (line: string) => void, -): LinePrefixer { +// createLineSplitter buffers a child's raw output chunks and hands over +// complete lines, so each becomes one log record rather than whatever +// happened to arrive in one read. A trailing fragment is held until its +// newline arrives and flushed at stream end, which keeps the last line of a +// crashing child — usually the one that matters — from being lost. +// +// mute drops the lines it matches. It is for output a child gives no way to +// switch off — see the web spec in index.ts. +export function createLineSplitter( + emit: (line: string) => void, + mute?: RegExp, +): LineSplitter { let buffer = "" + function take(line: string): void { + if (mute?.test(line)) { + return + } + + emit(line) + } + return { data(chunk) { buffer += chunk.toString() @@ -26,7 +110,7 @@ export function createLinePrefixer( break } - write(`${prefix} ${buffer.slice(0, newline)}`) + take(buffer.slice(0, newline)) buffer = buffer.slice(newline + 1) } }, @@ -36,7 +120,7 @@ export function createLinePrefixer( return } - write(`${prefix} ${buffer}`) + take(buffer) buffer = "" }, } diff --git a/docker/prod/launcher/src/mapping.test.ts b/docker/prod/launcher/src/mapping.test.ts index b0cd8780..f0a81093 100644 --- a/docker/prod/launcher/src/mapping.test.ts +++ b/docker/prod/launcher/src/mapping.test.ts @@ -145,6 +145,15 @@ describe("buildChildEnvs", () => { }) }) + it("gives core and auth-realtime the same log level", ({ expect }) => { + const envs = build(testConfig({ logLevel: "DEBUG" })) + + expect(envs.core.OXYNOTE_CORE_LOG_LEVEL).toBe("DEBUG") + expect(envs.authRealtime.OXYNOTE_AUTH_REALTIME_LOG_LEVEL).toBe( + "DEBUG", + ) + }) + it("hands each secret only to the component that needs it", ({ expect, }) => { diff --git a/docker/prod/launcher/src/mapping.ts b/docker/prod/launcher/src/mapping.ts index 7e38ca0d..42166cea 100644 --- a/docker/prod/launcher/src/mapping.ts +++ b/docker/prod/launcher/src/mapping.ts @@ -177,6 +177,7 @@ export function buildChildEnvs( config.maxOrganizationMembers, OXYNOTE_AUTH_REALTIME_RATE_LIMIT_DISABLED: config.rateLimitDisabled ? "true" : "false", + OXYNOTE_AUTH_REALTIME_LOG_LEVEL: config.logLevel, OXYNOTE_AUTH_REALTIME_BETTER_AUTH_GITHUB_CLIENT_ID: config.socialLogin.github?.clientId ?? "", OXYNOTE_AUTH_REALTIME_BETTER_AUTH_GITHUB_CLIENT_SECRET: diff --git a/docker/prod/launcher/src/supervisor.test.ts b/docker/prod/launcher/src/supervisor.test.ts index 4f94bad1..151c7405 100644 --- a/docker/prod/launcher/src/supervisor.test.ts +++ b/docker/prod/launcher/src/supervisor.test.ts @@ -74,7 +74,12 @@ function harness(childOptions: { exitOnTerm?: boolean } = {}) { const probe = vi .fn<(url: string) => Promise>() .mockResolvedValue(true) - const log = vi.fn<(line: string) => void>() + const log = { + info: vi.fn<(message: string) => void>(), + warn: vi.fn<(message: string) => void>(), + error: vi.fn<(message: string) => void>(), + } + const logChildLine = vi.fn<(name: string, line: string) => void>() const onUnexpectedExit = vi.fn<(name: string, code: number) => void>() const supervisor = createSupervisor({ @@ -82,10 +87,19 @@ function harness(childOptions: { exitOnTerm?: boolean } = {}) { probe, sleep: () => Promise.resolve(), log, + logChildLine, onUnexpectedExit, }) - return { children, spawn, probe, log, onUnexpectedExit, supervisor } + return { + children, + spawn, + probe, + log, + logChildLine, + onUnexpectedExit, + supervisor, + } } describe("createSupervisor", () => { @@ -121,9 +135,7 @@ describe("createSupervisor", () => { expect(h.probe).toHaveBeenCalledWith( "http://127.0.0.1:1/core", ) - expect(h.log).toHaveBeenCalledWith( - "[launcher] core is ready", - ) + expect(h.log.info).toHaveBeenCalledWith("core is ready") }) it("gives up when the child never becomes ready", async ({ @@ -161,7 +173,7 @@ describe("createSupervisor", () => { ) }) - it("tags the child's output with its name", async ({ + it("logs the child's output under the child's own name", async ({ expect, }) => { const h = harness() @@ -171,8 +183,10 @@ describe("createSupervisor", () => { h.children[0]?.stdout.emit("data", "hello\n") h.children[0]?.stderr.emit("data", "oops\n") - expect(h.log).toHaveBeenCalledWith("[core] hello") - expect(h.log).toHaveBeenCalledWith("[core] oops") + expect(h.logChildLine.mock.calls).toEqual([ + ["core", "hello"], + ["core", "oops"], + ]) }) it("reports an exit after readiness as unexpected", async ({ @@ -219,13 +233,15 @@ describe("createSupervisor", () => { await h.supervisor.stopAll() - const stops = h.log.mock.calls - .map(([line]) => line) - .filter((line) => line.includes("stopping")) + const stops = h.log.info.mock.calls + .map(([message]) => message) + .filter((message) => + message.includes("stopping"), + ) expect(stops).toEqual([ - "[launcher] stopping caddy", - "[launcher] stopping core", + "stopping caddy", + "stopping core", ]) expect(h.children[0]?.kill).toHaveBeenCalledWith( "SIGTERM", diff --git a/docker/prod/launcher/src/supervisor.ts b/docker/prod/launcher/src/supervisor.ts index d94b3948..1aee96a7 100644 --- a/docker/prod/launcher/src/supervisor.ts +++ b/docker/prod/launcher/src/supervisor.ts @@ -1,5 +1,5 @@ import type { ChildProcess } from "node:child_process" -import { createLinePrefixer } from "./logging.js" +import { createLineSplitter, type Logger } from "./logging.js" export interface ChildSpec { name: string @@ -14,6 +14,9 @@ export interface ChildSpec { readyTimeoutMs: number // how long a SIGTERM'd child may drain before SIGKILL. stopGraceMs: number + // output lines to drop, for what a child prints with no way to turn + // it off. + mute?: RegExp } export interface SupervisorDeps { @@ -25,7 +28,10 @@ export interface SupervisorDeps { // answers whether a GET to the URL returned 200. probe(url: string): Promise sleep(ms: number): Promise - log(line: string): void + // the supervisor's own events. + log: Logger + // relays one line a child wrote, under that child's name. + logChildLine(name: string, line: string): void // called when a child exits outside an initiated shutdown. onUnexpectedExit(name: string, code: number): void } @@ -52,24 +58,23 @@ export function createSupervisor(deps: SupervisorDeps): Supervisor { const children: Child[] = [] let stopping = false - function attachOutput(name: string, child: ChildProcess): void { + function attachOutput(spec: ChildSpec, child: ChildProcess): void { + // a splitter per stream, never one shared: a line is only ever + // whole within the stream it arrived on. for (const stream of [child.stdout, child.stderr]) { if (!stream) { continue } - const prefixer = createLinePrefixer( - `[${name}]`, - (line) => { - deps.log(line) - }, - ) + const splitter = createLineSplitter((line) => { + deps.logChildLine(spec.name, line) + }, spec.mute) stream.on("data", (chunk: Buffer) => { - prefixer.data(chunk) + splitter.data(chunk) }) stream.on("close", () => { - prefixer.end() + splitter.end() }) } } @@ -102,11 +107,11 @@ export function createSupervisor(deps: SupervisorDeps): Supervisor { } async function start(spec: ChildSpec): Promise { - deps.log(`[launcher] starting ${spec.name}`) + deps.log.info(`starting ${spec.name}`) const process = deps.spawn(spec.command, spec.args, spec.env) - attachOutput(spec.name, process) + attachOutput(spec, process) const exited = new Promise((resolve) => { process.once("exit", (code, signal) => { @@ -128,7 +133,7 @@ export function createSupervisor(deps: SupervisorDeps): Supervisor { await waitReady(child) - deps.log(`[launcher] ${spec.name} is ready`) + deps.log.info(`${spec.name} is ready`) } async function stopAll(): Promise { @@ -139,7 +144,7 @@ export function createSupervisor(deps: SupervisorDeps): Supervisor { continue } - deps.log(`[launcher] stopping ${child.spec.name}`) + deps.log.info(`stopping ${child.spec.name}`) child.process.kill("SIGTERM") const graceful = await Promise.race([ @@ -153,8 +158,8 @@ export function createSupervisor(deps: SupervisorDeps): Supervisor { continue } - deps.log( - `[launcher] ${child.spec.name} exceeded its stop grace, killing`, + deps.log.warn( + `${child.spec.name} exceeded its stop grace, killing`, ) child.process.kill("SIGKILL") diff --git a/docker/prod/launcher/src/test-helpers.ts b/docker/prod/launcher/src/test-helpers.ts index 75a4f4c7..acba7645 100644 --- a/docker/prod/launcher/src/test-helpers.ts +++ b/docker/prod/launcher/src/test-helpers.ts @@ -62,7 +62,7 @@ export function testConfig(overrides: Partial = {}): Config { rateLimitDisabled: false, maxDocumentHistoryEntries: "", documentHistoryRetention: "", - logLevel: "", + logLevel: "WARN", termsOfServiceUrl: "", privacyPolicyUrl: "", crashReportingDisabled: false, diff --git a/e2e/docker-compose.dev.yaml b/e2e/docker-compose.dev.yaml index b5fbc1c2..abbaea8e 100644 --- a/e2e/docker-compose.dev.yaml +++ b/e2e/docker-compose.dev.yaml @@ -133,6 +133,7 @@ services: postgres: image: postgres:18.6-alpine + command: ["postgres", "-c", "log_checkpoints=off"] environment: POSTGRES_USER: devuser POSTGRES_PASSWORD: devpass @@ -148,6 +149,7 @@ services: environment: - MEILI_MASTER_KEY=devmasterkey - MEILI_ENV=development + - MEILI_LOG_LEVEL=WARN healthcheck: test: ["CMD", "curl", "--fail", "http://localhost:7700/health"] interval: 5s @@ -158,5 +160,7 @@ services: # http port is published rather than proxied through caddy. mailpit: image: axllent/mailpit:v1.31.0 + environment: + - MP_QUIET=true ports: - "18025:8025" diff --git a/e2e/docker-compose.prod.yaml b/e2e/docker-compose.prod.yaml index dab0c136..e0196e66 100644 --- a/e2e/docker-compose.prod.yaml +++ b/e2e/docker-compose.prod.yaml @@ -79,6 +79,7 @@ services: postgres: image: postgres:18.6-alpine + command: ["postgres", "-c", "log_checkpoints=off"] environment: POSTGRES_USER: devuser POSTGRES_PASSWORD: devpass @@ -94,6 +95,7 @@ services: environment: - MEILI_MASTER_KEY=devmasterkey - MEILI_ENV=development + - MEILI_LOG_LEVEL=WARN healthcheck: test: ["CMD", "curl", "--fail", "http://localhost:7700/health"] interval: 5s @@ -105,5 +107,7 @@ services: # which routes nothing but the product. mailpit: image: axllent/mailpit:v1.31.0 + environment: + - MP_QUIET=true ports: - "19025:8025" diff --git a/server/auth-realtime/CLAUDE.md b/server/auth-realtime/CLAUDE.md index d3134a8e..abd8f4dd 100644 --- a/server/auth-realtime/CLAUDE.md +++ b/server/auth-realtime/CLAUDE.md @@ -57,6 +57,8 @@ src/ interface reporting.ts reported() / bestEffort(), the two ways a failure reaches sentry + logging.ts createLogger(level, destination): the pino logger + everything the service writes goes through headers.ts normalizing whatever shape a transport hands over auth.ts createAuth(deps) + the callbacks better-auth invokes hocuspocus.ts createHocuspocus(deps) / createDocumentHooks(deps) @@ -98,6 +100,32 @@ Rules that follow, and that a change must not erode: seeded, closing a direct connection). A `catch` that also builds a response stays written out, because neither helper can express that. +**Every line the service writes goes through +[logging.ts](src/logging.ts)**, which is **pino**, at the level +`OXYNOTE_AUTH_REALTIME_LOG_LEVEL` sets (`DEBUG`/`INFO`/`WARN`/`ERROR`, INFO +by default — the production image lowers it to WARN). It is configured to +emit what core's slog handler emits — an ISO `time`, an uppercase `level`, +the message under `msg`, and pino's default `pid`/`hostname` base dropped — +so a deployment's two services produce one log format rather than two. + +That includes the two libraries that would otherwise print on their own +terms: better-auth is given the matching level and a `log` callback, and +hocuspocus's Logger extension is routed to DEBUG, since a line per +connection, load, change and persist is a trace of the traffic rather than +something an operator needs. + +`createLogger` takes its destination as an argument because writing to +stdout is a side effect, so the sink belongs to `index.ts` like every other +one — it passes pino's `destination(1)`, and a test passes a stream it reads +back. `Logger` stays a four-method interface rather than pino's own type: +the service logs messages at levels and nothing more, and a narrow port is +what lets a suite hand over four `vi.fn()`s. + +**Nothing logs an address or a port.** The listen line says `listening` and +no more: inside a container the bound port is not the one anything reaches +the service on, so printing it only invites a wrong guess. Core's listen log +says the same thing for the same reason. + `src/sentry.ts` is the exception: node loads it through `--import` before the app graph exists, so it reads `process.env` directly and must not import anything of ours. Sentry's own docs call this file `instrument.js` — the name @@ -127,7 +155,9 @@ the same policy core applies to its own env — so nothing surfaces later as an what makes a required variable report as missing rather than empty. Adding a variable means adding it to the schema, to the `Env` interface, and -to `docker/env/auth-realtime.example.env`. +to `docker/env/auth-realtime.example.env`. One reaching the production image +also needs a line in the launcher's `mapping.ts`, which is where the public +`OXYNOTE_*` namespace is translated into each component's own. ## Formatting & TS diff --git a/server/auth-realtime/package.json b/server/auth-realtime/package.json index 03604124..e80b9fbd 100644 --- a/server/auth-realtime/package.json +++ b/server/auth-realtime/package.json @@ -57,6 +57,7 @@ "lowlight": "^3.3.0", "nanoid": "^6.0.1", "pg": "^8.23.0", + "pino": "^10.3.1", "redis": "^6.2.1", "yjs": "^13.6.32", "zod": "^4.4.3" diff --git a/server/auth-realtime/pnpm-lock.yaml b/server/auth-realtime/pnpm-lock.yaml index 34c3a952..5d6aa57c 100644 --- a/server/auth-realtime/pnpm-lock.yaml +++ b/server/auth-realtime/pnpm-lock.yaml @@ -109,6 +109,9 @@ importers: pg: specifier: ^8.23.0 version: 8.23.0 + pino: + specifier: ^10.3.1 + version: 10.3.1 redis: specifier: ^6.2.1 version: 6.2.1(@opentelemetry/api@1.9.1) @@ -1026,6 +1029,9 @@ packages: cpu: [x64] os: [win32] + '@pinojs/redact@0.4.0': + resolution: {integrity: sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==} + '@redis/bloom@6.2.1': resolution: {integrity: sha512-huQgNLaCIZfQ9SeLn4q9124uOUd8HbZDYHwwUzNcRgHqCHiHKl2dDxMqJCeWh8cMqZAoWuHR8XnWbDMIf+o7ag==} engines: {node: '>= 20.0.0'} @@ -1571,6 +1577,10 @@ packages: asynckit@0.4.0: resolution: {integrity: sha512-Oei9OH4tRh0YqU3GxhX79dM/mwVgvbZJaSNaRk+bshkj0S5cfHcgYakreBjrHwatXKbz+IoIdYLxrKim2MjW0Q==} + atomic-sleep@1.0.0: + resolution: {integrity: sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==} + engines: {node: '>=8.0.0'} + axios@1.19.0: resolution: {integrity: sha512-ht/iuYZXEjFxLH/Hkezgd7m6JKlHHXEUSneaDz8uZe1Gj5QZtCnpyDsckvAiEnT89OEbCLmnte4R4sn7P0EKFw==} @@ -2151,6 +2161,10 @@ packages: resolution: {integrity: sha512-4a+OsYv9UktOJKE+l1A4OufDgdRF9PifWj+tJnHURo/P+WOxpG4GzUFL9qCalmWauao6ogiG+QvnCovwPoyAWA==} engines: {node: '>=12.20.0'} + on-exit-leak-free@2.1.2: + resolution: {integrity: sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==} + engines: {node: '>=14.0.0'} + optionator@0.9.4: resolution: {integrity: sha512-6IpQ7mKUxRcZNLIObR0hz7lxsapSSIYNZJwXPGeF0mTVqGKFIXj1DQcMoT22S3ROcLyY/rz0PWaWZ9ayWmad9g==} engines: {node: '>= 0.8.0'} @@ -2228,6 +2242,16 @@ packages: resolution: {integrity: sha512-RvwwcruNjI1ncT5xRakeyS9Lf8lcItv34KD+aif+VH9kduAyfYBipGh12274xtenIPZ119/R9BdTBa8gAwSh0A==} engines: {node: '>=12'} + pino-abstract-transport@3.0.0: + resolution: {integrity: sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==} + + pino-std-serializers@7.1.0: + resolution: {integrity: sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==} + + pino@10.3.1: + resolution: {integrity: sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg==} + hasBin: true + postcss@8.5.26: resolution: {integrity: sha512-u82N74LFzG8ca+dD8puPnplTXoGH4fTPpVGuIbt36G3qvNlkvfD0lEAZSxaly3KX8TS/L1A1gsCEmvKmBcVbkQ==} engines: {node: ^10 || ^12 || >=14} @@ -2257,6 +2281,9 @@ packages: engines: {node: '>=14'} hasBin: true + process-warning@5.1.0: + resolution: {integrity: sha512-jQSaVHsPgtyw60e1rQ/A+/ArPEj/S8pS/vFnyGa/gYFXrKk/6RuDkoqVDQ5NI5MmS01698ltlAk0NoDBNLujRw==} + prosemirror-changeset@2.4.2: resolution: {integrity: sha512-ViYrjMSg3YFiXwIhKaluu+/mi3Yrxt6AR8ri14ulTaGcZtXO1CThl7A2gv79qx5fQnOw8woKwyBU2u+9PVCm3w==} @@ -2304,6 +2331,16 @@ packages: resolution: {integrity: sha512-vYt7UD1U9Wg6138shLtLOvdAu+8DsC/ilFtEVHcH+wydcSpNE20AfSOduf6MkRFahL5FY7X1oU7nKVZFtfq8Fg==} engines: {node: '>=6'} + quick-format-unescaped@4.0.4: + resolution: {integrity: sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==} + + real-require@0.2.0: + resolution: {integrity: sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==} + engines: {node: '>= 12.13.0'} + + real-require@1.0.0: + resolution: {integrity: sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==} + redis@6.2.1: resolution: {integrity: sha512-Z9VHtgYs48PiQC77X9O2Er8Hj4T+5BtFjT91/vi5Is1D04N72cA946ZslM1ImJw8ZctFBZWAVjM7S5wJNeHMpg==} engines: {node: '>= 20.0.0'} @@ -2326,6 +2363,10 @@ packages: rou3@0.9.2: resolution: {integrity: sha512-3SOzvaAg8rkHrXtRjpCvCvbyO5to9oOO27Z/XqHEYXfMRVSw/qMIVdmaOk9W2lcRLtR6dlqTjo9hDeJk70QBYQ==} + safe-stable-stringify@2.5.0: + resolution: {integrity: sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==} + engines: {node: '>=10'} + semifies@1.0.0: resolution: {integrity: sha512-xXR3KGeoxTNWPD4aBvL5NUpMTT7WMANr3EWnaS190QVkY52lqqcVRD7Q05UVbBhiWDGWMlJEUam9m7uFFGVScw==} @@ -2357,6 +2398,9 @@ packages: resolution: {integrity: sha512-kCZr2V3ch9i00x8zXRhjUNVcjG9ijES5dDudkXvUVCT5QlJNQWElSJdZqyPemffHoLNUYwOcou0Fy+ojN0uHSQ==} engines: {node: '>= 18'} + sonic-boom@4.2.1: + resolution: {integrity: sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==} + source-map-js@1.2.1: resolution: {integrity: sha512-UXWMKhLOwVKb728IUtQPXxfYU+usdybtUrK/8uGE8CQMvrhOpwvzDBwj0QhSL7MQc7vIsISBG8VQ8+IDQxpfQA==} engines: {node: '>=0.10.0'} @@ -2383,6 +2427,10 @@ packages: resolution: {integrity: sha512-qpCAvRl9stuOHveKsn7HncJRvv501qIacKzQlO/+Lwxc9+0q2wLyv4Dfvt80/DPn2pqOBsJdDiogXGR9+OvwRw==} engines: {node: '>=8'} + thread-stream@4.2.0: + resolution: {integrity: sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==} + engines: {node: '>=20'} + tinybench@2.9.0: resolution: {integrity: sha512-0+DUvqWMValLmha6lr4kD8iAMK1HzV0/aKnCtWb9v9641TnP/MFb7Pc2bxoxQjTXAErryXVgUOfv2YqNllqGeg==} @@ -3175,6 +3223,8 @@ snapshots: '@oxc-resolver/binding-win32-x64-msvc@11.24.2': optional: true + '@pinojs/redact@0.4.0': {} + '@redis/bloom@6.2.1(@redis/client@6.2.1(@opentelemetry/api@1.9.1))': dependencies: '@redis/client': 6.2.1(@opentelemetry/api@1.9.1) @@ -3740,6 +3790,8 @@ snapshots: asynckit@0.4.0: {} + atomic-sleep@1.0.0: {} + axios@1.19.0: dependencies: follow-redirects: 1.16.0 @@ -4282,6 +4334,8 @@ snapshots: obug@2.1.4: {} + on-exit-leak-free@2.1.2: {} + optionator@0.9.4: dependencies: deep-is: 0.1.4 @@ -4394,6 +4448,26 @@ snapshots: picomatch@4.0.5: {} + pino-abstract-transport@3.0.0: + dependencies: + split2: 4.2.0 + + pino-std-serializers@7.1.0: {} + + pino@10.3.1: + dependencies: + '@pinojs/redact': 0.4.0 + atomic-sleep: 1.0.0 + on-exit-leak-free: 2.1.2 + pino-abstract-transport: 3.0.0 + pino-std-serializers: 7.1.0 + process-warning: 5.1.0 + quick-format-unescaped: 4.0.4 + real-require: 0.2.0 + safe-stable-stringify: 2.5.0 + sonic-boom: 4.2.1 + thread-stream: 4.2.0 + postcss@8.5.26: dependencies: nanoid: 3.3.18 @@ -4414,6 +4488,8 @@ snapshots: prettier@3.9.6: {} + process-warning@5.1.0: {} + prosemirror-changeset@2.4.2: dependencies: prosemirror-transform: 1.12.0 @@ -4492,6 +4568,12 @@ snapshots: punycode@2.3.1: {} + quick-format-unescaped@4.0.4: {} + + real-require@0.2.0: {} + + real-require@1.0.0: {} + redis@6.2.1(@opentelemetry/api@1.9.1): dependencies: '@redis/bloom': 6.2.1(@redis/client@6.2.1(@opentelemetry/api@1.9.1)) @@ -4537,6 +4619,8 @@ snapshots: rou3@0.9.2: {} + safe-stable-stringify@2.5.0: {} + semifies@1.0.0: {} semver@7.7.2: {} @@ -4555,6 +4639,10 @@ snapshots: smol-toml@1.8.0: {} + sonic-boom@4.2.1: + dependencies: + atomic-sleep: 1.0.0 + source-map-js@1.2.1: {} source-map@0.6.1: {} @@ -4571,6 +4659,10 @@ snapshots: dependencies: has-flag: 4.0.0 + thread-stream@4.2.0: + dependencies: + real-require: 1.0.0 + tinybench@2.9.0: {} tinyexec@1.3.0: {} diff --git a/server/auth-realtime/src/auth.test.ts b/server/auth-realtime/src/auth.test.ts index 4ef9eb7f..643ff324 100644 --- a/server/auth-realtime/src/auth.test.ts +++ b/server/auth-realtime/src/auth.test.ts @@ -11,7 +11,13 @@ import { type SecondaryStorageClient, } from "./auth.js" import { createDatabase, type Store } from "./db.js" -import { stubCore, stubStore, testEnv, type StubCore } from "./test-helpers.js" +import { + stubCore, + stubLog, + stubStore, + testEnv, + type StubCore, +} from "./test-helpers.js" function stubRedis() { return { @@ -42,15 +48,17 @@ function buildAuth( ) { const real = createDatabase("postgresql://u:p@localhost/d") const core = overrides.core ?? stubCore() + const log = stubLog() const auth = createAuth({ env: overrides.env ?? testEnv(), store: overrides.store ?? stubStore(), dialect: real.dialect, redis: overrides.redis ?? stubRedis(), core, + log, }) - return { auth, core } + return { auth, core, log } } describe("authMethods", () => { @@ -431,6 +439,28 @@ describe("createAuth", () => { expect(auth.options.basePath).toBe("/api/auth") }) + it("takes better-auth's level from the configured one", ({ + expect, + }) => { + const { auth } = buildAuth({ + env: testEnv({ logLevel: "ERROR" }), + }) + + expect(auth.options.logger.level).toBe("error") + }) + + it("writes better-auth's own output through the service logger", ({ + expect, + }) => { + const { auth, log } = buildAuth() + + auth.options.logger.log("warn", "trusted origin missing") + + expect(log.warn.mock.calls).toEqual([ + ["better-auth: trusted origin missing"], + ]) + }) + it("keeps secondary storage when a redis client is given", ({ expect, }) => { @@ -454,6 +484,7 @@ describe("createAuth", () => { store: stubStore(), dialect: real.dialect, core: stubCore(), + log: stubLog(), }) expect(auth.options.secondaryStorage).toBeUndefined() diff --git a/server/auth-realtime/src/auth.ts b/server/auth-realtime/src/auth.ts index 3e573708..50a3b055 100644 --- a/server/auth-realtime/src/auth.ts +++ b/server/auth-realtime/src/auth.ts @@ -7,6 +7,7 @@ import type { PostgresDialect } from "kysely" import type { Store } from "./db.js" import type { CoreClient } from "./core.js" import type { Env, SocialProviderName } from "./env.js" +import type { Logger, LogLevel } from "./logging.js" import { reported } from "./reporting.js" export type AuthMethod = "email-password" | "google" | "github" | "slack" @@ -35,8 +36,20 @@ export interface AuthDeps { // better-auth with no secondary storage. redis?: SecondaryStorageClient core: CoreClient + log: Logger } +// better-auth's own level names, which are these lowercased. Passing it +// the matching one lets it drop a message before formatting it, and it +// resolves its extra "success" level to info before calling out. +const betterAuthLevels: Record = + { + DEBUG: "debug", + INFO: "info", + WARN: "warn", + ERROR: "error", + } + // the capability list served by /api/auth-config. Derived from the same // credentials that register the social providers, so the endpoint can // never disagree with what better-auth actually accepts. Email-password @@ -223,7 +236,14 @@ export function createSecondaryStorage(redis: SecondaryStorageClient) { } } -export function createAuth({ env, store, dialect, redis, core }: AuthDeps) { +export function createAuth({ + env, + store, + dialect, + redis, + core, + log, +}: AuthDeps) { const organizationHooks = createOrganizationHooks({ env, store, core }) function socialProvider(name: SocialProviderName) { @@ -248,6 +268,15 @@ export function createAuth({ env, store, dialect, redis, core }: AuthDeps) { // redirect URIs below). baseURL: env.authOrigin, basePath: "/api/auth", + // better-auth prints its own lines otherwise, on a level of + // its own; routed here they obey OXYNOTE_AUTH_REALTIME_LOG_LEVEL + // like everything else the service writes. + logger: { + level: betterAuthLevels[env.logLevel], + log: (level, message) => { + log[level](`better-auth: ${message}`) + }, + }, secret: env.betterAuthSecret, // the dialect instance alone leaves the CLI's schema generator // unable to tell which database it is talking to (instanceof diff --git a/server/auth-realtime/src/env.ts b/server/auth-realtime/src/env.ts index dd07f2be..7d13e227 100644 --- a/server/auth-realtime/src/env.ts +++ b/server/auth-realtime/src/env.ts @@ -1,5 +1,7 @@ import { z } from "zod" +import type { LogLevel } from "./logging.js" + export type SocialProviderName = "google" | "github" | "slack" export interface SocialProviderCredentials { @@ -39,6 +41,7 @@ export interface Env { maxOrganizations: number maxOrganizationMembers: number rateLimitEnabled: boolean + logLevel: LogLevel } // every URL here is one something dials or redirects a browser to, so the @@ -152,6 +155,13 @@ const schema = z // does not pass the original IP through — so it can be // switched off and left to whatever sits in front. OXYNOTE_AUTH_REALTIME_RATE_LIMIT_DISABLED: flag(false), + // the floor for everything this service writes, better-auth's + // and hocuspocus's output included. INFO matches core's own + // default; the production image lowers both to WARN. + OXYNOTE_AUTH_REALTIME_LOG_LEVEL: z + .enum(["DEBUG", "INFO", "WARN", "ERROR"]) + .optional() + .transform((value) => value ?? "INFO"), OXYNOTE_AUTH_REALTIME_BETTER_AUTH_GOOGLE_CLIENT_ID: z .string() .optional(), @@ -272,5 +282,6 @@ export function loadEnv(source: Record): Env { values.OXYNOTE_AUTH_REALTIME_MAX_ORGANIZATION_MEMBERS, rateLimitEnabled: !values.OXYNOTE_AUTH_REALTIME_RATE_LIMIT_DISABLED, + logLevel: values.OXYNOTE_AUTH_REALTIME_LOG_LEVEL, } } diff --git a/server/auth-realtime/src/hocuspocus.test.ts b/server/auth-realtime/src/hocuspocus.test.ts index 91975dd9..646621f1 100644 --- a/server/auth-realtime/src/hocuspocus.test.ts +++ b/server/auth-realtime/src/hocuspocus.test.ts @@ -8,7 +8,12 @@ import { type AuthSession, } from "./hocuspocus.js" import { replaceYdocContent, transformer } from "./ydocument.js" -import { fragmentXml, stubCore, type StubCore } from "./test-helpers.js" +import { + fragmentXml, + stubCore, + stubLog, + type StubCore, +} from "./test-helpers.js" type ConnectedDocument = Y.Doc & { broadcastStateless: Mock } @@ -677,10 +682,34 @@ describe("createDocumentHooks", () => { }) describe("createHocuspocus", () => { + it("sends the hocuspocus logger's per-connection lines out at DEBUG", ({ + expect, + }) => { + const log = stubLog() + const server = createHocuspocus({ + auth: stubAuth(), + core: stubCore(), + log, + }) + // the extension keeps its sink in its own configuration; the + // server exposes no other way to reach it. + const logger = server.configuration.extensions[0] as { + configuration: { log: (...args: unknown[]) => void } + } + + logger.configuration.log("onStoreDocument", "doc-1") + + expect(log.debug.mock.calls).toEqual([ + ["onStoreDocument doc-1"], + ]) + expect(log.info.mock.calls).toEqual([]) + }) + it("wires the document hooks onto the server", ({ expect }) => { const server = createHocuspocus({ auth: stubAuth(), core: stubCore(), + log: stubLog(), }) expect(typeof server.configuration.onAuthenticate).toBe( diff --git a/server/auth-realtime/src/hocuspocus.ts b/server/auth-realtime/src/hocuspocus.ts index 09398e0b..5b65a56c 100644 --- a/server/auth-realtime/src/hocuspocus.ts +++ b/server/auth-realtime/src/hocuspocus.ts @@ -3,6 +3,8 @@ import * as Y from "yjs" import { nanoid } from "nanoid" import { Hocuspocus } from "@hocuspocus/server" import { Logger } from "@hocuspocus/extension-logger" +// aliased because the extension above already claims the name Logger. +import type { Logger as ServiceLogger } from "./logging.js" import type { CoreClient } from "./core.js" import { toAxiosHeaders, toHeaders } from "./headers.js" import { bestEffort, reported } from "./reporting.js" @@ -329,9 +331,28 @@ export function createDocumentHooks({ auth, core }: DocumentHookDeps) { } } -export function createHocuspocus(deps: DocumentHookDeps): Hocuspocus { +export function createHocuspocus({ + log, + ...hooks +}: DocumentHookDeps & { log: ServiceLogger }): Hocuspocus { return new Hocuspocus({ - extensions: [new Logger()], - ...createDocumentHooks(deps), + // the extension writes a line per connection, load, change and + // persist. That is a trace of the traffic rather than + // something an operator needs to see, so it goes out at DEBUG + // instead of straight to stdout. + extensions: [ + new Logger({ + log: (...args: unknown[]) => { + log.debug( + args + .map((arg) => + String(arg), + ) + .join(" "), + ) + }, + }), + ], + ...createDocumentHooks(hooks), }) } diff --git a/server/auth-realtime/src/index.ts b/server/auth-realtime/src/index.ts index 0238b772..9bcb40be 100644 --- a/server/auth-realtime/src/index.ts +++ b/server/auth-realtime/src/index.ts @@ -2,11 +2,13 @@ import { serve } from "@hono/node-server" import { Hono } from "hono" import { createNodeWebSocket } from "@hono/node-ws" import { createClient } from "redis" +import { destination } from "pino" import { loadEnv } from "./env.js" import { createDatabase } from "./db.js" import { createCoreClient } from "./core.js" import { createAuth } from "./auth.js" import { createHocuspocus } from "./hocuspocus.js" +import { createLogger } from "./logging.js" import { createRoutes } from "./routes.js" import { bestEffort } from "./reporting.js" @@ -15,6 +17,7 @@ import { bestEffort } from "./reporting.js" // needs, which is what makes the rest of the service testable without a // database, a redis, or a port. const env = loadEnv(process.env) +const log = createLogger(env.logLevel, destination(1)) const database = createDatabase(env.databaseDSN) const { store, dialect } = database @@ -34,11 +37,12 @@ if (env.valkeyDsn) { await redis.connect() } -const auth = createAuth({ env, store, dialect, redis, core }) +const auth = createAuth({ env, store, dialect, redis, core, log }) const hocuspocus = createHocuspocus({ auth: { getSession: (input) => auth.api.getSession(input) }, core, + log, }) const app = new Hono() @@ -111,9 +115,10 @@ const server = serve( port: info.port, }) - console.log( - `Server is running on http://localhost:${info.port}`, - ) + // deliberately without the address: this is the port inside + // the container, which is not the one anything reaches the + // service on, and printing it only invites a wrong guess. + log.info("listening") }, ) nodeWs.injectWebSocket(server) @@ -126,7 +131,7 @@ const shutdownDeadlineMs = 15_000 // seconds, so exiting on the signal alone would drop that window of edits. async function shutdown() { const deadline = setTimeout(() => { - console.error("shutdown deadline exceeded") + log.error("shutdown deadline exceeded") process.exit(1) }, shutdownDeadlineMs) deadline.unref() diff --git a/server/auth-realtime/src/logging.test.ts b/server/auth-realtime/src/logging.test.ts new file mode 100644 index 00000000..53bff7c1 --- /dev/null +++ b/server/auth-realtime/src/logging.test.ts @@ -0,0 +1,78 @@ +import { describe, it } from "vitest" + +import { createLogger, type LogLevel } from "./logging.js" + +// a destination that keeps what pino wrote, parsed back into records. +function capture() { + const lines: string[] = [] + + return { + destination: { + write(chunk: string) { + lines.push(chunk) + }, + }, + records: () => + lines.map( + (line) => + JSON.parse(line) as Record< + string, + unknown + >, + ), + } +} + +const thresholdCases: { + name: string + level: LogLevel + expected: LogLevel[] +}[] = [ + { + name: "DEBUG", + level: "DEBUG", + expected: ["DEBUG", "INFO", "WARN", "ERROR"], + }, + { name: "INFO", level: "INFO", expected: ["INFO", "WARN", "ERROR"] }, + { name: "WARN", level: "WARN", expected: ["WARN", "ERROR"] }, + { name: "ERROR", level: "ERROR", expected: ["ERROR"] }, +] + +describe("createLogger", () => { + it.for(thresholdCases)( + "at $name emits that level and every level above it", + ({ level, expected }, { expect }) => { + const written = capture() + const log = createLogger(level, written.destination) + + log.debug("d") + log.info("i") + log.warn("w") + log.error("e") + + expect( + written.records().map((record) => record.level), + ).toEqual(expected) + }, + ) + + it("writes core's log shape: an ISO time, an upper-case level, a msg", ({ + expect, + }) => { + const written = capture() + + createLogger("INFO", written.destination).warn( + "cannot reach core", + ) + + expect(written.records()).toEqual([ + { + time: expect.stringMatching( + /^\d{4}-\d{2}-\d{2}T[\d:.]+Z$/, + ) as unknown, + level: "WARN", + msg: "cannot reach core", + }, + ]) + }) +}) diff --git a/server/auth-realtime/src/logging.ts b/server/auth-realtime/src/logging.ts new file mode 100644 index 00000000..ee41af95 --- /dev/null +++ b/server/auth-realtime/src/logging.ts @@ -0,0 +1,44 @@ +import { pino, type DestinationStream } from "pino" + +// the levels are core's slog levels, spelled the same way, so one +// OXYNOTE_LOG_LEVEL means the same thing on both sides of the deployment. +export type LogLevel = "DEBUG" | "INFO" | "WARN" | "ERROR" + +// what the service logs through, and all it needs: a message at one of four +// levels. It is the narrow port pino satisfies, so a test takes four +// vi.fn()s rather than standing up a logger to assert against. +export interface Logger { + debug(message: string): void + info(message: string): void + warn(message: string): void + error(message: string): void +} + +// createLogger builds the pino instance every line goes through, shaped to +// match what core's slog handler emits — an ISO timestamp, the level as an +// uppercase word, the message under "msg" — so one deployment's two +// services produce one log format rather than two. +// +// base is null because pino would otherwise stamp every line with a pid and +// a hostname, and neither says anything about a container running one +// process under an id docker assigned. destination is a parameter because +// writing to stdout is a side effect, and those belong to the composition +// root; a test passes a stream it can read back. +export function createLogger( + level: LogLevel, + destination: DestinationStream, +): Logger { + return pino( + { + level: level.toLowerCase(), + base: null, + timestamp: pino.stdTimeFunctions.isoTime, + formatters: { + level: (label) => ({ + level: label.toUpperCase(), + }), + }, + }, + destination, + ) +} diff --git a/server/auth-realtime/src/test-helpers.ts b/server/auth-realtime/src/test-helpers.ts index d2b18194..38d47118 100644 --- a/server/auth-realtime/src/test-helpers.ts +++ b/server/auth-realtime/src/test-helpers.ts @@ -3,6 +3,7 @@ import type * as Y from "yjs" import type { CoreClient } from "./core.js" import type { Store } from "./db.js" import type { Env } from "./env.js" +import type { Logger } from "./logging.js" export type StubStore = { [K in keyof Store]: Mock @@ -58,6 +59,21 @@ export function stubCore(): StubCore { } } +export type StubLogger = { + [K in keyof Logger]: Mock +} + +// a logger that records instead of writing, so a suite neither prints nor +// has to spy on the console to assert what a code path logged. +export function stubLog(): StubLogger { + return { + debug: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + } +} + // a complete, valid configuration. Tests override only the field under // test so an unrelated env change cannot quietly alter what they assert. export function testEnv(overrides: Partial = {}): Env { @@ -81,6 +97,7 @@ export function testEnv(overrides: Partial = {}): Env { maxOrganizations: 100, maxOrganizationMembers: 5, rateLimitEnabled: true, + logLevel: "INFO", ...overrides, } } diff --git a/server/core/internal/server/server.go b/server/core/internal/server/server.go index 56227ce4..2066b955 100644 --- a/server/core/internal/server/server.go +++ b/server/core/internal/server/server.go @@ -7,8 +7,6 @@ import ( "fmt" "log/slog" "net/http" - "net/url" - "strings" "sync" "time" @@ -237,7 +235,10 @@ func NewServer( // Listen starts listening for incoming connections. func (s *Server) Listen() { - s.log.Info("listening", slog.String("address", s.Address())) + // deliberately without the address: it is the one inside the + // container, which is not the one anything reaches the server on, so + // logging it only invites a wrong guess. + s.log.Info("listening") err := s.http.ListenAndServe() if !errors.Is(err, http.ErrServerClosed) { @@ -245,27 +246,6 @@ func (s *Server) Listen() { } } -// Address returns the address of the server. -func (s *Server) Address() string { - host := s.http.Addr - - // a host-less address binds all interfaces; localhost stands in for - // log readability. - if strings.HasPrefix(s.http.Addr, ":") { - host = "localhost" - if s.http.Addr != ":80" { - host += s.http.Addr // port can be random - } - } - - addr := &url.URL{ - Scheme: "http", - Host: host, - } - - return addr.String() -} - // Close performs clean up operations. func (s *Server) Close() error { if err := s.http.Shutdown(context.Background()); err != nil { diff --git a/server/core/internal/server/server_test.go b/server/core/internal/server/server_test.go index 5d65bd43..1fee42d1 100644 --- a/server/core/internal/server/server_test.go +++ b/server/core/internal/server/server_test.go @@ -299,40 +299,6 @@ func Test_Server_Listen(t *testing.T) { assert.NotContains(t, content2(), "cannot terminate gracefully") } -func Test_Server_Address(t *testing.T) { - t.Parallel() - - cc := map[string]struct { - Addr string - Result string - }{ - "Default HTTP port is omitted": { - Addr: ":80", - Result: "http://localhost", - }, - "Custom port is included": { - Addr: ":1234", - Result: "http://localhost:1234", - }, - "Host-qualified address is used verbatim": { - Addr: "127.0.0.1:8180", - Result: "http://127.0.0.1:8180", - }, - } - - for cn, c := range cc { - t.Run(cn, func(t *testing.T) { - t.Parallel() - - s := Server{ - http: &http.Server{Addr: c.Addr}, - } - - assert.Equal(t, c.Result, s.Address()) - }) - } -} - func Test_Server_Close(t *testing.T) { t.Parallel()