Observability: metrics and logs

Two things tell you how a running instance is doing:

• Metrics — numbers over time: requests per second and their latency per route, the error rate, which search tier answers, how big the dictionary is, what an import is doing, how busy the Postgres pool is. They answer can it take my traffic? and why is it slow since yesterday?
• Logs — one line per event, every request included, on stdout. They answer what happened to this one request, with which error? (Logs below).

How the monitoring works

Three parts, each doing one job:

1. The server counts things as it runs and publishes the counters as a text page at /metrics. Open it in a browser and you see lines like http_requests_total{method="GET",route="/api/v1/search",status="200"} 1523. Nothing is stored here: it is the current value of every counter, and the page is off until METRICS_ENABLED=true.
2. Prometheus is a database for those numbers. Every 15 s it fetches (scrapes) that page, stamps the values with the time and keeps them, so "requests per second over the last hour" becomes a question it can answer. It has a small UI of its own (port 9090; the bundled stack publishes it on 3243) for ad-hoc queries in its query language, PromQL.
3. Grafana draws the graphs. It asks Prometheus for the numbers and shows them on dashboards; this repository ships one dashboard with the panels an operator needs, and Grafana loads it at start.

The server needs neither of the other two to run. Three ways to have them, from the least to the most work:

Enabling and scraping

METRICS_ENABLED=true
METRICS_PATH=/metrics

The endpoint lives outside both API surfaces (/api/v1, the admin prefixes): no authentication, no rate limit, Cache-Control: no-store, text/plain in the Prometheus text format. It is off by default. Behind the reverse proxy of deployment/reverse-proxy.md either do not route it at all (Prometheus scrapes the server's port directly, on the private network) or fence it like the admin prefixes:

location = /metrics { allow 10.0.0.0/8; deny all; proxy_pass http://vbh_server; }

@metrics path /metrics
handle @metrics {
	@scraper remote_ip 10.0.0.0/8
	handle @scraper {
		reverse_proxy 127.0.0.1:3010
	}
	respond 404
}

A scrape job:

scrape_configs:
  - job_name: vocab-bloom-hub
    scrape_interval: 15s
    static_configs:
      - targets: ['127.0.0.1:3010']

Prometheus + Grafana in Docker

A ready-made local stack ships next to the main compose file — optional, never part of the default stack. docker-compose.observability.yml is an overlay: a second compose file merged over the first, which adds two services and sets METRICS_ENABLED=true on the server. Start the instance with both files instead of one:

docker compose -f docker-compose.yml -f docker-compose.observability.yml up -d

That starts, on localhost only:

• Prometheus at http://localhost:3243 (PROMETHEUS_PORT), scraping the server's /metrics over the compose network every 15 s (observability/prometheus.yml; edit it if you change METRICS_PATH), keeping PROMETHEUS_RETENTION (15 days) of data in a named volume;
• Grafana at http://localhost:3244 (GRAFANA_PORT), log in with GRAFANA_ADMIN_USER / GRAFANA_ADMIN_PASSWORD (admin / admin unless set in .env). The Prometheus datasource and the Vocab Bloom Hub dashboard are provisioned from observability/grafana/ at start — request rate, error rate and p95 latency by route, search tiers, dictionary size, import/export progress, the Postgres pool, CPU / memory / event loop lag. The dashboard is a committed file (observability/grafana/dashboards/vocab-bloom-hub.json), versioned with the code.

Stopping is the mirror image — add the same -f flags to docker compose down; the named volumes prometheus-data and grafana-data keep the metric history and Grafana state across restarts.

An instance that does not run in this compose — the native start (yarn start, systemd, PM2) or a server on another machine — takes two steps instead of one:

1. Turn the metrics on in that instance's .env and restart it: METRICS_ENABLED=true. Check with curl localhost:3010/metrics.

2. Point Prometheus at it. In observability/prometheus.yml replace the target server:3010 with the instance's address — host.docker.internal:3010 for a server running on the Docker host itself, 10.0.0.5:3010 for another machine on the private network (never a public address, see above) — and start only the two monitoring services:

   docker compose -f docker-compose.yml -f docker-compose.observability.yml up -d prometheus grafana
   

Already running a Prometheus? Skip the compose file: add the instance to its scrape config and import observability/grafana/dashboards/vocab-bloom-hub.json into your Grafana.

COMPOSE_PROFILES=db DATABASE_URL= docker compose -f docker-compose.yml -f docker-compose.observability.yml up -d

Metrics

Process (prom-client defaults)

process_cpu_*, process_resident_memory_bytes, nodejs_heap_size_*, nodejs_eventloop_lag_seconds (and its percentiles), nodejs_gc_duration_seconds, nodejs_active_handles_total, … — the standard Node.js set, plus:

HTTP

Every request is timed by a middleware that runs before routing, so answers produced by the surface switches and plain 404s count too.

route is the route template (/api/v1/words/:word, /api/en/add/:entryType), never the raw path — paths are unbounded and would create a series per headword. A request that matched no route is labelled unmatched. The metrics endpoint itself is not counted.

Dictionary and search

The tier counter is the tuning signal for the search: a growing fuzzy share means users misspell more than the substring tiers catch, a large none share means the dictionary lacks what they look for.

A sustained waiting count on vbh_db_pool_connections means requests queue for a database connection: raise DB_POOL_SIZE (and mind the connection limit of a managed Postgres — see environment.md).

Useful queries

# request rate and error rate, per route
sum by (route) (rate(http_requests_total[5m]))
sum by (route) (rate(http_requests_total{status=~"5.."}[5m])) / sum by (route) (rate(http_requests_total[5m]))

# p95 latency of the public reads
histogram_quantile(0.95, sum by (le, route) (rate(http_request_duration_seconds_bucket{route=~"/api/v1/.*"}[5m])))

# how often the trigram tier saves a search
sum(rate(vbh_search_tier_hits_total{tier="fuzzy"}[1h])) / sum(rate(vbh_search_tier_hits_total[1h]))

# an import that is stuck: in progress for long with no progress change
vbh_dictionary_transfer_in_progress == 1 and changes(vbh_dictionary_transfer_progress_percent[10m]) == 0

Logs

The server writes its log to stdout, one line per event, and nothing else: where the lines end up is the process manager's business — docker compose logs -f server (Docker keeps them in /var/lib/docker/containers/…/*-json.log), journalctl -u vocab-bloom-hub-server under systemd, pm2's files. LOG_FORMAT picks their shape:

• json — the default with NODE_ENV=production, so in the Docker images: one JSON object per line, what a log collector reads without parsing rules;
• pretty — the default otherwise (yarn dev, the tests): the same lines rendered for a terminal, [10:00:01.234] INFO: [Bootstrap] Server listening on port 3010.

LOG_LEVEL is the minimum level, in Nest's names — verbose / debug / log / warn / error / fatal (pino's trace and info are accepted too); log by default, debug with NODE_ENV=development. Both are read at start: change them in .env and restart the server (docker compose up -d server recreates the container with the new environment).

What the lines look like

{"level":"info","time":"2026-08-30T10:00:01.234Z","pid":1,"hostname":"a1b2c3d4","context":"Bootstrap","msg":"Server listening on port 3010"}
{"level":"info","time":"2026-08-30T10:00:05.678Z","pid":1,"hostname":"a1b2c3d4","reqId":"6f1c2b3a-…","req":{"id":"6f1c2b3a-…","method":"GET","url":"/api/v1/words/run","remoteAddress":"203.0.113.7","userAgent":"curl/8.7.1"},"res":{"statusCode":200},"responseTime":12,"msg":"GET /api/v1/words/run 200 12ms"}
{"level":"error","time":"2026-08-30T10:00:09.012Z","pid":1,"hostname":"a1b2c3d4","reqId":"9c8d7e6f-…","context":"AllExceptionsFilter","statusCode":500,"err":{"type":"QueryFailedError","message":"…","stack":"QueryFailedError: …\n    at …"},"msg":"Unhandled exception on GET /api/en/words"}

The request id is a UUID generated per request and echoed in the X-Request-Id response header. An X-Request-Id that comes in — from the reverse proxy (header_up X-Request-Id {http.request.uuid} in Caddy, proxy_set_header X-Request-Id $request_id; in nginx) or from a client — is reused when it is 1–128 characters of A-Z a-z 0-9 . _ -, so the proxy's access log and the server's lines share one id; anything else is replaced.

Reading them

docker compose logs -f server                                  # as they come
docker compose logs --no-log-prefix server | jq -Rc 'fromjson? | select(.level == "error")'
docker compose logs --no-log-prefix server | jq -Rc 'fromjson? | select(.res.statusCode >= 500) | {time, msg, id: .req.id}'
docker compose logs --no-log-prefix server | jq -Rc 'fromjson? | select(.reqId == "6f1c2b3a-…")'   # everything of one request
docker compose logs --no-log-prefix server | jq -Rc 'fromjson? | select(.responseTime > 1000) | .msg'
journalctl -u vocab-bloom-hub-server -o cat | jq -Rc 'fromjson? | select(.level == "error")'   # native start under systemd

(jq -R … fromjson? skips the odd non-JSON line, such as a Node warning on stderr.)

Shipping them to a collector

Nothing in the images or the compose file: a collector reads what Docker already stores. The usual self-hosted setup is Grafana Loki with an agent on the Docker host — Grafana Alloy discovers the containers through the Docker socket, reads their stdout and pushes the lines to Loki:

discovery.docker "containers" {
  host = "unix:///var/run/docker.sock"
}

discovery.relabel "containers" {
  targets = discovery.docker.containers.targets
  rule {
    source_labels = ["__meta_docker_container_name"]
    regex         = "/(.*)"
    target_label  = "container"
  }
}

loki.source.docker "containers" {
  host       = "unix:///var/run/docker.sock"
  targets    = discovery.relabel.containers.output
  forward_to = [loki.write.default.receiver]
}

loki.write "default" {
  endpoint {
    url = "http://loki:3100/loki/api/v1/push"
  }
}

In Grafana the JSON fields become filters: {container="vocab-bloom-hub-server-1"} | json | level="error", … | json | res_statusCode >= 500, … | json | reqId="6f1c2b3a-…". The same lines suit any collector that reads container stdout (Promtail, Fluent Bit, Vector, Filebeat, the CloudWatch or Datadog agents), and Docker's own logging drivers send them straight from the daemon — awslogs, gelf, syslog, fluentd, or the Loki plugin — through a compose override or /etc/docker/daemon.json, again without touching this repository's files. A native start under systemd goes through journald, which every collector reads as well.

Not here yet

Traces (OpenTelemetry) are out of scope; the metrics can be re-exported through an OTel collector's Prometheus receiver.