Media-Server-Setup/LOGGING.md

# Logging framework

Decided 2026-11-01. The store was chosen, built and replaced on 2026-11-03: a VictoriaLogs stack went in
first and was torn out the same day for producing no dashboards, so the store is now **Elasticsearch with
Kibana**, served at the root of the `diag.BASE` host (Phase 13 in `CommunityDiscordMedia.md`). Logs arrive via
Filebeat, metrics via Metricbeat, into the same cluster so one dashboard can carry both. Everything upstream
of the store was fixed first, so the swap was a collector config rather than a code change.

## Where the lines come from (the only two taps a collector needs)

| Tap | Holds | Read with |
|---|---|---|
| **journald** | our systemd units: `dumpd`, `normalize-sweep`, `trash-purge`, `deploy-pending`, `vgdeband` (transient), `deploy.sh` output | `journalctl -u <unit>`; collectors: Alloy `loki.source.journal`, Vector `journald`, VictoriaLogs journald ingestion, Netdata's journal plugin |
| **Docker json-file logs** | every container (`docker-compose.yml`), rotated 5 × 50 MB each | `docker logs <name>`; collectors read `/var/lib/docker/containers/*/*-json.log` and get the container **labels** below for free |

Filebeat reads both: a docker autodiscover template per container (filestream + the container parser) and a
journald input for our units. Metrics are the same story: see the taps table below, all on loopback.

## Metrics taps (Prometheus text format, loopback only — Metricbeat scrapes them)

| endpoint | what | from |
|---|---|---|
| `http://127.0.0.1:9998/metrics` | MediaMTX: per path bytes/s, readers, publishers, WebRTC/HLS/RTMP/SRT sessions, dropped packets | MediaMTX `metrics: yes` |
| `http://127.0.0.1:2019/metrics` | Caddy: requests by host/status, durations, TLS | Caddy admin API (`servers { metrics }`) |
| `http://127.0.0.1:8080/metrics` | ours: the normalise queue, encode time, live stream count | `bin/dumpd.py` |

Host and per-container metrics (CPU, RAM, disk, network, block I/O, restarts) come from Metricbeat's `system`
and `docker` modules, not from an exporter — node_exporter and cAdvisor were removed when the Elastic stack
went in. None of these endpoints is reachable from outside: each binds loopback, the firewall opens none of
them, and Caddy routes no host to `/metrics` (every dumpd route there is an explicit path matcher).

### Our own metrics, and how to add one

MediaMTX answers "who is live" and Metricbeat answers "is the box busy". Neither can answer "is normalising
keeping up", because the sweep is a shell script on a timer. So the scripts keep counters and dumpd renders
them.

- `bin/vgmetrics.sh` is sourced by `normalize-sweep.sh` and `vgdeband.sh`. It accumulates `key value` lines in
  `/srv/media/.markers/metrics/<component>.counters` and keeps a `<component>.pid` file for as long as the
  script is executing. It renders nothing and serves nothing, so the scripts stay simple.
- `bin/dumpd.py` turns those files into Prometheus text on `GET /metrics`, adds gauges it can compute at
  scrape time, and asks the MediaMTX API for the live path list. `COUNTER_MAP` there is the single place that
  knows the metric names.

| metric | type | what it answers |
|---|---|---|
| `vanguard_media_pending{kind}` | gauge | finished recordings waiting to be normalised. **The capacity signal**: if this trends up across a night, CPU encoding is not keeping pace |
| `vanguard_media_pending_oldest_seconds` | gauge | how long the oldest one has waited |
| `vanguard_media_recording` | gauge | recordings MediaMTX is still writing (age under `MINS_IDLE`) |
| `vanguard_media_encoding_in_flight` | gauge | ffmpeg output files (`*.part`) open right now |
| `vanguard_media_running{component}` | gauge | 1 while the sweep or vgdeband is executing, by live pid, not a stale marker |
| `vanguard_media_jobs_total{component,verdict,outcome,kind}` | counter | remuxes and encodes finished, split by success and by stream vs clip |
| `vanguard_media_job_seconds_total{component,verdict,kind}` | counter | seconds spent in ffmpeg. Divide by the job count for mean encode time |
| `vanguard_media_runs_total{component}` | counter | script starts. Flat means the timer stopped |
| `vanguard_media_deband_total{component}` | counter | timecode bands cropped off |
| `vanguard_media_last_finish_timestamp_seconds{component}` | gauge | when it last finished |
| `vanguard_media_last_run_seconds{component}` | gauge | how long that run took |
| `vanguard_media_failed_files` | gauge | files parked with a `normalize-failed.log` |
| `vanguard_mediamtx_up` | gauge | did the MediaMTX API answer the scrape |
| `vanguard_streams_active` | gauge | streams publishing now, derived `.webrtc` mirrors excluded |
| `vanguard_streams_mirrors` | gauge | those mirrors, counted separately |
| `vanguard_stream_readers` | gauge | viewers attached across all paths |

To add a counter: pick a key of the form `name:label:label`, call `vgmet_add` with it, and add `name` to
`COUNTER_MAP` with the label names in the same order. Nothing else changes, and a key dumpd does not
recognise is ignored rather than breaking the scrape.

Three rules this design exists to keep. Metrics must never break a sweep, so every write is atomic and every
failure in the helper is silent, and a missing helper degrades to no-ops. A scrape must never disturb the
stack, so dumpd never takes the sweep's flock and the filesystem globs are depth-limited rather than walking
the media tree. And the counters live on disk rather than in the process, because the sweep exits between
runs.

Note for anyone editing `normalize-sweep.sh`: its file loop reads from a process substitution, not a pipe. A
pipe would put the loop in a subshell and every counter set inside it would be discarded on exit.

## Container labels (set in `docker-compose.yml`, `x-logging` anchor + `labels:`)

`vanguard.service` = the service name, `vanguard.category` = one of the categories below. A collector turns these
into stream labels without parsing a single line.

## Categories = the questions people ask

| category | services / components | correlation key |
|---|---|---|
| `stream` | mediamtx (path ready/closed, recorder, WebRTC sessions, the on-ready hook's `event=mirror`), dumpd `publish_allow` / `publish_deny`, sweep `event=published` | `stream` = `user/Title` |
| `auth` | caddy access logs (status, `X-Authentik-Username`), authentik-server/worker events, gitea OIDC | `user` |
| `media` | sweep verdicts / timecode / deband / failed, vgdeband, jellyfin, copyparty | `file` |
| `intake` | syncthing (`folder.id`), dumpd `clips_setup`, `quota_*` | `folder` = `clips-<user>` |
| `infra` | mariadb, caddy TLS/ACME, container restarts, disk | host only |
| `deploy` | deploy.sh, dumpd `deploy_*`, `bot_deploy_*` and `bot_env_*` (the bot's CI posting a release bundle and its settings), act_runner | `rev` |
| `code`, `bot` | gitea, discord-bot | — |

## Labels vs fields

- **Labels** (low cardinality, what you filter by): `service`, `category`, `level`, `unit`. A dozen values each.
- **Fields** (parsed at query time, what you search in): `stream`, `user`, `file`, `folder`, `session`, `status`, `ip`, `event`.
  Thousands of values — fine as fields, ruinous as labels (Loki). VictoriaLogs indexes every word anyway.

## Our own line format: logfmt, one event per line

    ts=2026-11-01T19:52:14-06:00 level=info component=sweep event=published stream="techy2493/Vanguard_Training" file="/srv/media/streams/…" verdict=encode

- `ts` ISO-8601 with offset · `level` info|warn|error · `component` dumpd|sweep|vgdeband|deploy|on-ready · `event` a verb/noun in snake_case · then `key=value`, values with spaces or quotes double-quoted.
- Same key means the same thing everywhere: `stream` (user/Title), `user`, `file`, `folder`, `rev`, `ip`, `reason`.
- Implemented by: `log()` in `bin/dumpd.py`, `vglog` in `bin/normalize-sweep.sh` and `bin/vgdeband.sh`, `log()` in `deploy.sh` (`msg=` only), `bin/mtx-on-ready.sh` (MediaMTX prefixes its own path/time).

Events today: dumpd `publish_allow publish_deny dump clips_setup quota_paused quota_resumed quota_* deploy_* bot_deploy_start bot_deploy_exit bot_deploy_bad_signature bot_deploy_refused bot_env_applied bot_env_failed`;
sweep `verdict timecode deband fill_gaps published done failed skip`; vgdeband `deband done failed skip`; hook `mirror`.
A future alert script watches `level=error`, `event=failed`, `event=publish_deny` bursts, `event=quota_paused`, plus disk.

## Third-party formats a collector must parse

| source | format | stage |
|---|---|---|
| caddy | JSON (`logger`, `level`, `msg`; access logs: `request.*`, `status`, `request.headers.X-Authentik-Username`) | json |
| authentik | JSON (`event`, `user`, `action`) | json |
| syncthing | key=value after a `date time:` prefix (`folder.id=… log.pkg=model`) | logfmt |
| mediamtx | `YYYY/MM/DD HH:MM:SS LVL [component] [session|path x] message` | one regex → component, id, msg |
| jellyfin | `[HH:MM:SS.mmm] [LVL] [thread] Logger.Class: message` + stack-trace continuation lines | **multiline** (join lines not starting with `[`) then regex |
| gitea, mariadb, copyparty | plain text | level regex only |

## Caddy access logs

On for every site block (`CADDY_LOG` in `configure.py`): JSON to stderr; `Cookie`, `Authorization` and
`X-Stream-Auth` request headers are deleted before logging, the `X-Authentik-*` identity headers are kept — that is the
"who downloaded what" audit trail for the files host.

## Alerting: Kibana evaluates, we deliver

A basic Elastic licence allows only two connector types, `.index` and `.server-log`. Everything that leaves
the stack — webhook, Slack, email, PagerDuty — is Gold or above and refuses with
`403 Action type .webhook is disabled because your basic license does not support it`. So Kibana cannot talk
to Discord, and the pipeline is split:

    Kibana rule  --.index connector-->  vanguard-alerts  --vanguard-alerts.timer-->  Discord webhook

- **`observability/kibana-setup.py`** creates the connector ("Vanguard alert index") and the heartbeat
  rule. Run it once, *after* Elasticsearch security is on.
- **`vanguard-alerts` index** is the alert bus, pre-created by `configure.py` with `rule`, `level` and `kind`
  as keywords. Alerts are ordinary documents, so they are searchable in Discover next to the logs that caused
  them, and replayable after the fact.
- **`bin/vanguard-alerts.sh`** runs every minute, delivers anything newer than its cursor, and suppresses a
  repeat of the same rule within 15 minutes as a safety net. No webhook configured means journal-only and a
  non-zero exit, never a silent drop.
- **`bin/vanguard-deadman.sh`** watches both halves: a `kind=heartbeat` document arriving (Kibana still
  evaluating and writing) and `alerts.state` being fresh (something still delivering). Either half dying
  means no alarm can arrive, and nothing inside the stack could tell you.

### The rules themselves

`observability/kibana-alarms.py` creates them, so they are reviewable and reproducible rather than clicked in.
All of them repeat every **12 hours** while still true (`notify_when: onThrottleInterval`) and go silent when
the condition clears.

| Rule | Level | Fires when |
|---|---|---|
| Disk free below 15% | error | any real filesystem at ≥85% used. Pseudo filesystems are excluded by type, or every tmpfs would alarm forever |
| Memory free below 15% | warn | `system.memory.actual.used.pct` ≥ 0.85 |
| Discord bot not running | error | **no** metrics from the `discord-bot` container for 5 min (the one rule with a `<` comparator) |
| Discord bot unhealthy | error | the container healthcheck reports `unhealthy`, i.e. the bot's own `/health` says Discord is disconnected or the database does not answer |
| Recordings stuck waiting to be normalised | warn | `vanguard_media_pending_oldest_seconds` > 1 h |
| Normalise failures parked | warn | any file has a `normalize-failed.log` |

The two bot rules answer different questions and both are needed. "Not running" catches a stopped or
hard-crash-looping container. "Unhealthy" catches the worse case: the process is up, the port is open, and the
bot is doing nothing because its gateway or database is gone. That second one only works because the bot's
`/health` is exempt from its own identity middleware and returns 503 rather than 200 when degraded — a
healthcheck carries no Authentik headers, and a 200 with `discord_ready: false` would have made a dead bot
look healthy.

Elasticsearch, Kibana, Beat liveness and the disks are **not** here: that is the deadman's job, outside the
stack. Nothing that depends on Kibana can report that Kibana is dead, so duplicating those as rules would go
quiet in exactly the case that matters.

To add an alarm: author the rule in Kibana, point its action at the "Vanguard alert index" connector, and give
the document a `message` and a `level` of `warn` or `error`. Never set `kind: heartbeat` — that value is how
the delivery script recognises the heartbeat and keeps it out of Discord. Use "On status change" or a throttle
for real alarms; only the heartbeat should fire every interval.

## Retention

Set by `configure.py --apply`, so nothing here needs clicking and nothing grows without bound:

| What | How long | Set by |
|---|---|---|
| `filebeat-*`, `metricbeat-*` | `LOG_RETENTION_DAYS`, default 30 | a **delete phase injected into the Beats' own ILM policies**. They ship a rollover but no delete, so indices otherwise grow until the disk watermark turns them read-only — which the deadman reports but cannot undo |
| `vanguard-alerts` | `ALERT_RETENTION_DAYS`, default 90 | `vanguard-alerts.sh`, a `_delete_by_query` at most once every 6 h. A heartbeat document arrives every minute, so this index needs pruning more than it needs ILM |

The delete phase is *injected* rather than written whole, so whatever rollover the Beats chose is preserved
across upgrades. Keeping `auth` and `deploy` lines longer than the rest would mean separate indices and a
second ILM policy; not worth it unless an audit asks.

## As built (Phase 13)

| container | port | job |
|---|---|---|
| `elasticsearch` | 9200 | one store for **both** logs and metrics. 2 GB heap, single node, security off (loopback only) |
| `kibana` | 5601 | the single pane: Discover for logs, dashboards, alerting. Served at the root of `diag.BASE` |
| `filebeat` | — | container logs (autodiscover) + our journal units |
| `metricbeat` | — | host + Docker metrics (retires node_exporter and cAdvisor) + MediaMTX and Caddy Prometheus endpoints |

**Logs and metrics correlate because both Beats write the same fields into the same store.** That is what makes
one dashboard able to show a CPU spike next to the errors that caused it, rather than two dashboards side by
side:

| field | set by | use |
|---|---|---|
| `@timestamp` | both (ECS) | every panel shares the dashboard's time range |
| `host.name` | both | one box today, but the field is there |
| `container.name` | both | per-service metrics joined to that service's log lines |
| `service.name` | both, from the `vanguard.service` label | the name you actually think in |
| `vanguard.category` | both, from the label | filter a whole area at once: stream, media, auth, intake, deploy |

To get a dashboard that filters across both, make **one data view** spanning `filebeat-*,metricbeat-*` in
Kibana (Stack Management → Data Views). A single filter such as `service.name: mediamtx` then applies to the
metric panels and the log panel together. Metricbeat also ships its own system and Docker dashboards, which are
a good starting point to copy panels from.

Retention is one edit in Kibana rather than config: Stack Management → Index Lifecycle Policies → the beats
policy → add a delete phase. Doing it there rather than in a file keeps it adjustable without a redeploy.

### Old notes


(superseded 2026-11-03 — the Victoria/vmalert/Alertmanager shape, kept for the reasoning)

| container | port | job |
|---|---|---|
| `victorialogs` | 9428 | store, 30 d, `-http.pathPrefix=/logs` so Caddy passes the prefix through unchanged |
| `vector` | — | `docker_logs` + `journald` → VictoriaLogs (elasticsearch bulk). **Holds the Docker socket** |
| `victoriametrics` | 8428 | 90 d, scrapes the taps above (`observability/scrape.yml`) |
| `vmalert-metrics` | 8880 | `observability/alerts-metrics.yml` against VictoriaMetrics |
| `vmalert-logs` | 8881 | `observability/alerts-logs.yml` (LogsQL) against VictoriaLogs' stats endpoints |
| `alertmanager` | 9093 | groups, inhibits, posts to Discord (`webhook_url_file`, never in the config) |

Published only through `diag.BASE`, gated on `DIAG_REQUIRE_GROUP` (`media-admins`): `/logs`, `/metrics-db`,
`/alerts`, `/rules-metrics`, `/rules-logs`, and an index at `/`.

**The deadman** (`bin/vanguard-deadman.sh`, host timer, 5 min) is deliberately outside all of it: curl only, it
checks each component answers, that the always-firing `Watchdog` alert is still arriving through
vmalert → Alertmanager → dumpd `/heartbeat`, and the disks. It speaks on change, announces recovery once, and
with no webhook configured still logs and exits non-zero so `systemctl is-failed vanguard-deadman.service` is
a signal. Nothing inside the stack can report its own death; this can.

`ALERT_WEBHOOK_URL` in `.env` → `/etc/vanguard/alert-webhook` (0640 root:65534). Empty means log-only, which is
a working configuration, not an error: `configure.py` generates `observability/alertmanager.yml` with the
Discord notifier omitted, so nothing is half-configured and nothing fails to load.

## Gotchas this build produced (all fixed; here so they are not rediscovered)

- **`-http.pathPrefix` applies to EVERY endpoint, not just the UI.** With VictoriaLogs behind `/logs`, the
  ingestion path is `/logs/insert/elasticsearch/`, the health probe is `/logs/health` and the scrape is
  `/logs/metrics`. It rejects a write to the unprefixed path with a message naming the missing flag.
- **Every proxied UI needs its own prefix set**, or it loads at the sub-path and then fetches its assets from
  the domain root and renders broken. VictoriaMetrics and vmalert use `-http.pathPrefix`; Alertmanager uses
  `--web.route-prefix` plus `--web.external-url`. Setting those also moves their metrics and health paths.
- **Vector's `current_boot_only: false` is rejected on systemd 250–257.** Only the current boot is shipped;
  earlier entries are still on the host for `journalctl --boot=-1`.
- **A Caddy `respond` body is placeholder-expanded**, so `{...}` in CSS or JSON is eaten. Serve a page as a
  file and mount it, the way the gateway and dock pages are served, instead of inlining it. (The diag host no
  longer has such a page at all: Kibana occupies its root.)
- **Filebeat 9 removed the `container` input.** It is not deprecated-but-working: the config is refused per
  container with "Container input is deprecated. Use Filestream input with its container parser instead",
  and Filebeat then runs happily with zero harvesters and creates no index at all. Container logs go through
  `type: filestream` with `parsers: [container: ~]`, and every filestream input needs its own stable `id`.
  This is exactly the failure the deadman's "up but not shipping" check exists to catch.
- **`add_docker_metadata` should be told where the container id is.** Its path-sniffing default did not
  apply to our filestream paths, so the autodiscover template stamps `container.id` and the processor reads
  it via `match_fields: ["container.id"]`. Without the id there are no `container.labels.*`, and without
  those the `service.name` / `vanguard.category` promotion silently produces nothing.
- **A single node cannot place a replica**, so any beats index defaulting to one replica holds the cluster at
  yellow permanently. Both beats set `setup.template.settings.index.number_of_replicas: 0` with
  `setup.template.overwrite: true`; indices created before that need a one-time `_settings` call.
- **Kibana's Observability apps that check privileges cannot work with `xpack.security.enabled: false`.** The
  Infrastructure / Metrics app calls `api/infra/host/count` on every view and Elasticsearch answers
  `no handler found for uri [/_security/user/_has_privileges]`, surfaced as a red "error while fetching
  resource" banner. The fix is to turn security ON, not to avoid the app. Doing so normally adds a password
  prompt, which this stack forbids, so Kibana's **anonymous provider** signs every visitor in as one native
  user instead (`observability/kibana.yml`). Security being on is also what any future read-only tier needs.
- **Moving a setting from a container environment variable into a config file can break it.** `SERVER_BASEPATH: ""`
  was fine for years because the Kibana image drops empty env values, but `server.basePath: ""` in
  `kibana.yml` is a validation error (`must start with a slash, don't end with one`) and Kibana refuses to
  boot. When migrating env settings into a file, an empty value means "omit the key", not "set it to empty".
- **Metricbeat exits when Kibana is unreachable**, because `setup.dashboards.enabled: true` runs at startup.
  A Metricbeat restart loop is often a symptom of a Kibana problem, not a Metricbeat one.
- **Alerting rules created while security was off hold no API key** and stop working once it is on, until each
  rule is disabled and re-enabled. Create connectors and rules *after* security is on, not before.
- **Kibana's Observability charts group by `event.dataset`.** Beats do not set it, so without a processor
  every line lands in one "unknown" bucket and the Logs rate chart is useless. Filebeat now fills it from the
  container's `vanguard.service` label, or from `systemd.unit` for journald lines. `copy_fields` never
  overwrites an existing target, so listing several sources for one field means first match wins.
- **Metricbeat field shapes differ per module on purpose.** The MediaMTX and Caddy scrapes are untyped, so a
  value is at `prometheus.metrics.<name>` with labels at `prometheus.labels.*`. The dumpd scrape sets
  `use_types` and `rate_counters`, so a gauge is at `prometheus.<name>.value` and a counter has both
  `.counter` and `.rate`. Look for the right one before concluding a metric is missing.
- **`-r` and a non-CFR `-fps_mode` are mutually exclusive in ffmpeg.** It refuses the pair with
  "One of -r/-fpsmax was specified together a non-CFR -vsync/-fps_mode" and then fails with
  `Error opening output files: Invalid argument` — which looks like a path or permission problem and is not.
  Capping the frame rate means re-timing, so the cap forces CFR and passthrough has to lose.
- **`avg_frame_rate` alone is not a frame rate.** A looped or fragmented recording reported 95 fps for a
  30 fps source (`r_frame_rate=30/1`, `avg_frame_rate=3625/38`), which sent it down the fps-cap path and broke
  the encode. `r_frame_rate` alone is no better: it is a huge nominal value on genuine VFR. The sweep takes
  the **lower of the two**.
- **`configure.py --apply` cannot introduce a new host** — see HOSTNAME-CHANGE.md §D.

## Wiring sketches (the options that were weighed, kept so the decision is not re-argued)

- **Grafana + Loki**: `alloy` container with `loki.source.journal` + `loki.source.docker` (labels from the container
  labels above) → `loki` on loopback → `grafana` behind Authentik OIDC (third provider, like Jellyfin/Gitea).
  Metrics: Alloy scrapes the four taps above → Prometheus or VictoriaMetrics, same Grafana.
- **VictoriaLogs**: single container on `127.0.0.1:9428`, run with `-http.pathPrefix=/logs`; Vector
  ships journald and the Docker logs. Its built-in UI sits behind the Caddy forward-auth gate on `diag.BASE`
  (`media-admins`). VictoriaMetrics beside it would consume the four metric taps.
- **Netdata**: single container, host + container metrics and alerts (Discord) out of the box, journald viewer;
  behind the Caddy gate. Weakest at log search.
- **ELK** (chosen, and what is deployed): Elasticsearch with a pinned 2 GB heap, Kibana at the root of
  `diag.BASE`, Filebeat and Metricbeat shipping into the same cluster so one dashboard can carry logs and
  metrics together. The cost is the JVM heap and the index disk on a box that also runs x264; it was taken
  because every lighter option needed three or four more pieces to reach a usable dashboard.