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).

Stuck recordings: counts in Kibana, names in the logs, decisions on the host

Three layers on purpose, because each answers a different question and none of them needs a new web page.

• How bad is it, and is it getting worse — the gauges: vanguard_media_pending, vanguard_media_pending_oldest_seconds, vanguard_media_failed_files. A Lens dashboard over metricbeat-* shows the trend across a night, which is the thing a list never can.
• Which recordings — the sweep logs event=parked file= stream= log= once per run for every file a failure log is holding back, plus event=failed with ffmpeg's own stderr when it first breaks. Both land in filebeat-*, so a Discover search or a dashboard table names them and stays current. Names deliberately do NOT come from the metrics: a label per filename would wreck index cardinality for no gain.
• What to do about it — bin/vgstuck.sh on the host. It classifies every unpublished recording as parked (a failure log is blocking it, with the reason), published (an output already exists), waiting (nothing blocking it yet) or writing (still recording), then retry <match> clears the blocker so the sweep tries again and drop <match> moves it to trash/<today>/ for the same three-day undo as a dumped night. drop --all is refused.

A leftover <output>.mp4.part does not block anything — ffmpeg overwrites it with -y. It only wastes disk, and retry clears it.

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`
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"), the heartbeat rule, the data view, and the "Vanguard ops" landing dashboard plus the defaultRoute that makes diag.BASE open on it. Run it once, after Elasticsearch security is on. Name a step to run only that one: kibana-setup.py landing. Kibana deliberately stays at the root of that host. Moving it under /kibana would mean server.basePath plus rewriteBasePath, a Caddy handle that does not strip the prefix, and appending the prefix in both Beats' setup.kibana, this script, the alarm script and the deadman's status check — and a miss in the Beats one crash-loops Metricbeat, because it exits when Kibana is unreachable. defaultRoute buys the landing page without any of that.
• 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.