From 704bc8c4d3e2a4a73509f3230f78fe3589f4a632 Mon Sep 17 00:00:00 2001 From: Brandyn / Techy Date: Sun, 1 Nov 2026 19:53:05 -0600 Subject: [PATCH] Logging framework: logfmt events in our scripts, container labels + rotated json-file logs, Caddy JSON access logs; LOGGING.md Store-agnostic: journald + Docker logs are the only taps any collector (Alloy/Loki, VictoriaLogs, Netdata) needs. Co-Authored-By: Claude Fable 5.1 --- LOGGING.md | 84 ++++++++++++++++++++++++++++++++++++++++++ README.md | 1 + STATUS.md | 3 +- bin/dumpd.py | 42 ++++++++++++--------- bin/mtx-on-ready.sh | 2 +- bin/normalize-sweep.sh | 23 +++++++----- bin/vgdeband.sh | 17 +++++---- configure.py | 22 +++++++++-- deploy.sh | 2 +- docker-compose.yml | 32 ++++++++++++++++ 10 files changed, 186 insertions(+), 42 deletions(-) create mode 100644 LOGGING.md diff --git a/LOGGING.md b/LOGGING.md new file mode 100644 index 0000000..7471cf8 --- /dev/null +++ b/LOGGING.md @@ -0,0 +1,84 @@ +# Logging framework — store-agnostic + +Decided 2026-11-01. The log *store* (Grafana + Loki, VictoriaLogs, Netdata, …) is not chosen yet. Everything +upstream of it is fixed now, so the choice later is a collector config, not 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 `; 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 `; collectors read `/var/lib/docker/containers/*/*-json.log` and get the container **labels** below for free | + +Every collector on the shortlist reads both. Metrics are the same story: node_exporter / cAdvisor expose the +Prometheus text format that Alloy, vmagent and Netdata all scrape; MediaMTX (`metrics: yes`) and Caddy have +endpoints too, currently off. + +## 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-` | +| `infra` | mariadb, caddy TLS/ACME, container restarts, disk | host only | +| `deploy` | deploy.sh, dumpd `deploy_*`, 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_*`; +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. + +## Retention (when a store exists) + +14 days for everything; 90 for `auth` and `deploy`. Both Loki and VictoriaLogs do per-stream retention. + +## Wiring sketches (not deployed; pick one later) + +- **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 node_exporter, cAdvisor, MediaMTX `:9998/metrics`, Caddy `:2019/metrics` → Prometheus or + VictoriaMetrics, same Grafana. +- **VictoriaLogs**: single container, journald + docker via its agent or Vector; built-in UI behind the Caddy + forward-auth gate (`media-admins`). VictoriaMetrics beside it for metrics. +- **Netdata**: single container, host + container metrics and alerts (Discord) out of the box, journald viewer; + behind the Caddy gate. Weakest at log search. +- **ELK**: rejected — JVM heap and index disk on a box doing x264; our data is structured records (→ MariaDB) and a + single host's logs. diff --git a/README.md b/README.md index fdb9638..2765d8b 100644 --- a/README.md +++ b/README.md @@ -2,6 +2,7 @@ > **FRESH-INSTALL.md** = the ordered walkthrough from an empty box to a working stack and pipeline, manual steps included. > **HOSTNAME-CHANGE.md** = every place a hostname lives and how to rename a subdomain or move to a new base domain safely. +> **LOGGING.md** = log framework: journald + rotated Docker logs, container labels, logfmt events, categories; store (Loki/VictoriaLogs/Netdata) chosen later. > **UPCOMING.md** = what is still missing for a mil-sim community (gap list, techy's take, agreed direction: metadata DB, markers, watch app). **Hostnames** (all CNAMEs to the main host; one Discord login covers all of them): diff --git a/STATUS.md b/STATUS.md index 2e6c80d..26113fc 100644 --- a/STATUS.md +++ b/STATUS.md @@ -58,7 +58,8 @@ Source of truth: this repo, `techy/Media-Server-Setup` on the stack's own Gitea | Syncthing | clip intake, UI at `sync.` | UI behind Authentik + `media-admins`, own GUI auth off | live | | normalize sweep | editing standard, one copy per clip | live | | nftables | host firewall (22, 80/443, 1935, 2222, 3306, 8890/udp, 22000) | live | -| Caddy | TLS + routing for all hostnames | live | +| Caddy | TLS + routing for all hostnames; JSON access logs per site (identity headers kept, cookies/tokens dropped) | live (access logs: deploy pending) | +| Logging framework | rotated Docker logs + `vanguard.service/category` labels on every container; dumpd/sweep/vgdeband/deploy emit logfmt events (`LOGGING.md`); store not chosen (Loki vs VictoriaLogs vs Netdata) | **committed 2026-11-01, deploy pending** (recreates every container) | | Authentik (+Postgres, Redis) | Discord login, groups, guild-membership policy | live | | Jellyfin | watch page, SSO via Authentik, direct play only | live | | Vanguard Metadata plugin | seasons by tag, Discord names/avatars/events, feed, playback policy | **0.1.3 built** (flat `__<ts>` names, policy task, feed wording) — install pending; server has 0.1.0 or 0.1.2 | diff --git a/bin/dumpd.py b/bin/dumpd.py index 23d0c4e..5ba8a44 100755 --- a/bin/dumpd.py +++ b/bin/dumpd.py @@ -134,7 +134,7 @@ def quota_enforce_once(): try: folders = st("GET", "/rest/config/folders") except Exception as e: - print(f"{datetime.now(TZ):%F %T} quota: syncthing unreachable ({e})", flush=True); return + log("quota_unreachable", level="warn", error=e); return for f in folders: if not f["id"].startswith("clips-"): continue user = f["id"][len("clips-"):] @@ -144,12 +144,12 @@ def quota_enforce_once(): over = used > q; under = used < q * 0.9 if over and not f.get("paused"): try: st("POST", f"/rest/db/pause?folder={f['id']}"); paused[user] = {"at": datetime.now(TZ).isoformat(), "used_gb": round(used / 1e9, 1), "quota_gb": q / 1e9}; changed = True - except Exception as e: print(f"{datetime.now(TZ):%F %T} quota: pause {user} failed: {e}", flush=True); continue - print(f"{datetime.now(TZ):%F %T} quota: PAUSED clips-{user} ({used/1e9:.1f} GB > {q/1e9:.0f} GB)", flush=True) + except Exception as e: log("quota_pause_failed", level="error", user=user, error=e); continue + log("quota_paused", level="warn", user=user, folder=f"clips-{user}", used_gb=f"{used/1e9:.1f}", quota_gb=f"{q/1e9:.0f}") elif under and f.get("paused") and user in paused: try: st("POST", f"/rest/db/resume?folder={f['id']}"); paused.pop(user, None); changed = True - except Exception as e: print(f"{datetime.now(TZ):%F %T} quota: resume {user} failed: {e}", flush=True); continue - print(f"{datetime.now(TZ):%F %T} quota: resumed clips-{user} ({used/1e9:.1f} GB)", flush=True) + except Exception as e: log("quota_resume_failed", level="error", user=user, error=e); continue + log("quota_resumed", user=user, folder=f"clips-{user}", used_gb=f"{used/1e9:.1f}") if changed: try: QUOTA_STATE.parent.mkdir(exist_ok=True); QUOTA_STATE.write_text(json.dumps(paused, indent=2)) except OSError: pass @@ -157,7 +157,7 @@ def quota_enforce_once(): def quota_loop(): while True: try: quota_enforce_once() - except Exception as e: print(f"{datetime.now(TZ):%F %T} quota loop error: {e}", flush=True) + except Exception as e: log("quota_loop_error", level="error", error=e) _time.sleep(QUOTA_CHECK_S) def st_apikey(): @@ -247,7 +247,7 @@ def clips_setup(user, device_id, device_name=None): cur["devices"].append({"deviceID": device_id}) cur["type"] = "receiveonly"; cur["minDiskFree"] = spec["minDiskFree"] st("PUT", f"/rest/config/folders/{fid}", cur) - print(f"{datetime.now(TZ):%F %T} clips setup user={user} device={device_id[:7]}… folder={fid}", flush=True) + log("clips_setup", user=user, device=device_id[:7], folder=fid) return clips_status(user) DEPLOY_ENV = Path(os.environ.get("DEPLOY_ENV_FILE", "/etc/vanguard/deploy.env")) @@ -267,17 +267,25 @@ def run_deploy(reason): _deploy_lock["running"] = True def go(): try: - print(f"{datetime.now(TZ):%F %T} deploy: start ({reason})", flush=True) + log("deploy_start", reason=reason) r = subprocess.run(["/usr/local/bin/vanguard-deploy", "pull"], capture_output=True, text=True, timeout=1800) for line in (r.stdout + r.stderr).splitlines()[-40:]: print(f"deploy| {line}", flush=True) - print(f"{datetime.now(TZ):%F %T} deploy: exit {r.returncode}", flush=True) + log("deploy_exit", level=("info" if r.returncode == 0 else "error"), rc=r.returncode) except Exception as e: - print(f"{datetime.now(TZ):%F %T} deploy: error {e}", flush=True) + log("deploy_error", level="error", error=e) finally: _deploy_lock["running"] = False threading.Thread(target=go, daemon=True).start() return True +def log(event, level="info", **kv): + """One logfmt line per event (see LOGGING.md): ts= level= component=dumpd event= key=value ...""" + def q(v): + v = str(v) + return v if v and not re.search(r'[\s"=]', v) else '"' + v.replace("\\", "\\\\").replace('"', '\\"') + '"' + print(f"ts={datetime.now(TZ).isoformat(timespec='seconds')} level={level} component=dumpd event={event} " + + " ".join(f"{k}={q(v)}" for k, v in kv.items() if v is not None), flush=True) + def token_secret(): try: sec = TOKEN_SECRET_FILE.read_bytes().strip() @@ -394,7 +402,7 @@ class H(BaseHTTPRequestHandler): env = deploy_env(); secret = env.get("DEPLOY_WEBHOOK_SECRET", "") sig = self.headers.get("X-Gitea-Signature") or self.headers.get("X-Hub-Signature-256", "").replace("sha256=", "") if not secret or not sig or not hmac.compare_digest(hmac.new(secret.encode(), raw, hashlib.sha256).hexdigest(), sig): - print(f"{datetime.now(TZ):%F %T} deploy webhook: bad signature from {self.client_address[0]}", flush=True) + log("deploy_webhook_bad_signature", level="warn", ip=self.client_address[0]) return self._json(401, {"error": "bad signature"}) try: payload = json.loads(raw or b"{}") except json.JSONDecodeError: return self._json(400, {"error": "bad json"}) @@ -403,7 +411,7 @@ class H(BaseHTTPRequestHandler): if ref != f"refs/heads/{branch}": return self._json(200, {"ignored": f"ref {ref} is not {branch}"}) if env.get("DEPLOY_AUTO", "0") != "1": - print(f"{datetime.now(TZ):%F %T} deploy webhook: push {after} by {pusher} on {branch} — auto-deploy disabled (DEPLOY_AUTO=0)", flush=True) + log("deploy_webhook_push", rev=after, pusher=pusher, branch=branch, auto="0") return self._json(202, {"queued": False, "note": "auto-deploy disabled (DEPLOY_AUTO=0); run vanguard-deploy pull by hand"}) started = run_deploy(f"push {after} by {pusher}") return self._json(202, {"queued": started, "note": "deploy started" if started else "a deploy is already running"}) @@ -426,19 +434,19 @@ class H(BaseHTTPRequestHandler): # audio mirrors (<user>/<Title>.webrtc) are published by the hook inside the mediamtx container only if req.get("ip") in ("127.0.0.1", "::1") and re.fullmatch(r"[a-z0-9_.-]+/[a-z0-9_.-]+\.webrtc", path): return self._json(200, {"ok": True}) - print(f"{datetime.now(TZ):%F %T} mtx-auth DENY publish path={path} ip={req.get('ip')} (mirror paths are internal)", flush=True) + log("publish_deny", level="warn", stream=path, ip=req.get("ip"), reason="mirror paths are internal") return self._json(401, {"error": ".webrtc paths are reserved"}) cred = req.get("password") or req.get("token") or "" if cred.lower().startswith("bearer "): cred = cred[7:] if ":" in cred and "." in cred.split(":", 1)[1]: cred = cred.split(":", 1)[1] # "user:token" form user = verify_token(cred) if not user: - print(f"{datetime.now(TZ):%F %T} mtx-auth DENY publish path={path} ip={req.get('ip')} (bad/expired token)", flush=True) + log("publish_deny", level="warn", stream=path, ip=req.get("ip"), reason="bad or expired token") return self._json(401, {"error": "invalid or expired stream token"}) if not re.fullmatch(r"[a-z0-9_.-]+/[a-z0-9_.-]+", path) or not path.startswith(user + "/"): - print(f"{datetime.now(TZ):%F %T} mtx-auth DENY publish user={user} path={path} (not their prefix)", flush=True) + log("publish_deny", level="warn", user=user, stream=path, reason="not their prefix") return self._json(401, {"error": "path must be <your-username>/<Title>"}) - print(f"{datetime.now(TZ):%F %T} mtx-auth allow publish user={user} path={path} ip={req.get('ip')}", flush=True) + log("publish_allow", user=user, stream=path, ip=req.get("ip")) return self._json(200, {"ok": True}) if self.path.startswith("/me/clips"): who, _ = identity(self.headers) @@ -465,7 +473,7 @@ class H(BaseHTTPRequestHandler): moved, size = do_move(files, night) MARK.mkdir(exist_ok=True) (MARK / f"{night}-{tgt}.dumped").write_text(f"{datetime.now(TZ).isoformat()} by {u}\n") - print(f"{datetime.now(TZ):%F %T} dump night={night} user={tgt} by={u} files={moved} gb={size/1e9:.2f}", flush=True) + log("dump", night=night, user=tgt, by=u, files=moved, gb=f"{size/1e9:.2f}") self._json(200, {"night": night, "user": tgt, "moved": moved, "gb": round(size / 1e9, 2), "undo_until": (datetime.now(TZ) + timedelta(days=3)).strftime("%F")}) def log_message(self, *a): # quiet diff --git a/bin/mtx-on-ready.sh b/bin/mtx-on-ready.sh index 5fc0803..28d61f3 100755 --- a/bin/mtx-on-ready.sh +++ b/bin/mtx-on-ready.sh @@ -25,7 +25,7 @@ case "$tracks" in *"MPEG-4 Audio"*|*"MPEG-1 Audio"*|*G711*|*G722*|*LPCM*|*AC-3*) ;; *) exit 0 ;; # no (recognised) audio: nothing to mirror esac -echo "mirror: $MTX_PATH -> $MTX_PATH.webrtc (audio -> Opus)" +echo "event=mirror stream=$MTX_PATH target=$MTX_PATH.webrtc audio=opus" n=0 while [ $n -lt 10 ]; do # retry: the source may not be readable for the first second ffmpeg -nostdin -hide_banner -loglevel warning -fflags nobuffer -flags low_delay \ diff --git a/bin/normalize-sweep.sh b/bin/normalize-sweep.sh index 43cd9df..09aff87 100755 --- a/bin/normalize-sweep.sh +++ b/bin/normalize-sweep.sh @@ -36,7 +36,9 @@ MAX_W=2560; MAX_H=1440; MAX_FPS=60 exec 9>"${LOCK_FILE:-/run/lock/normalize-sweep.lock}" flock -n 9 || exit 0 -log() { echo "$(date '+%F %T') $*"; } +# logfmt (LOGGING.md): vglog <level> event=<verb> key=value ... values with spaces must arrive pre-quoted +vglog() { local lvl="$1"; shift; printf 'ts=%s level=%s component=sweep %s\n' "$(date -Is)" "$lvl" "$*"; } +log() { vglog info "msg=\"$*\""; } dur() { ffprobe -v error -show_entries format=duration -of csv=p=0 "$1" 2>/dev/null | cut -d. -f1; } # --- probe: prints "verdict reason" where verdict ∈ ok|remux|encode|skip ---------------------- @@ -87,10 +89,11 @@ find "$ROOT/streams" "$ROOT/clips" -type f \ ! -path '*/.src/*' ! -path '*/.stfolder/*' ! -path '*/.stversions/*' ! -name '*.part' -mmin +"$MINS_IDLE" -print0 2>/dev/null | while IFS= read -r -d '' src; do base="${src%.*}"; ext="${src##*.}" - live=0 + live=0; stream="" if [[ $(basename "$(dirname "$src")") == .live ]]; then live=1 titledir="$(dirname "$(dirname "$src")")" # streams/<user>/<Title> + stream="$(basename "$(dirname "$titledir")")/$(basename "$titledir")" # user/Title, the log correlation key base="$(dirname "$titledir")/$(basename "$titledir")__$(basename "${src%.*}")" # streams/<user>/<Title>__<ts> fi synced=0; stroot="" @@ -107,7 +110,7 @@ while IFS= read -r -d '' src; do if (( live )); then [[ $verdict == skip ]] && continue [[ $verdict == ok ]] && verdict=remux # must leave .live/ either way - out="$base.mp4"; [[ -e "$out" ]] && { log "exists $out (leaving $src)"; continue; } + out="$base.mp4"; [[ -e "$out" ]] && { vglog info "event=skip reason=exists file=\"$out\" src=\"$src\""; continue; } else case "$verdict" in ok|skip) continue ;; esac out="$base.mp4" @@ -118,7 +121,7 @@ while IFS= read -r -d '' src; do [[ -e "$out" ]] && continue fi tmp="$out.part" - log "$verdict $src ($reason)" + vglog info "event=verdict verdict=$verdict file=\"$src\" reason=\"$reason\" stream=\"$stream\"" tcargs=(); tcjson=""; band=0; deband=0 if (( live )); then # timecode: decode the overscan strip (server clock) or fall back to the server arrival time in the filename @@ -139,18 +142,18 @@ PYEOF if [[ -n ${TC_TIMECODE:-} ]]; then tcargs=(-timecode "$TC_TIMECODE" -metadata "creation_time=$TC_CREATION" -write_tmcd 1) tcjson="${TC_JSON:-}" - log "tc $src source=$TC_SOURCE timecode=$TC_TIMECODE" + vglog info "event=timecode file=\"$src\" stream=\"$stream\" source=$TC_SOURCE timecode=\"$TC_TIMECODE\"" fi # the band has done its job once decoded: remove it from the picture (re-encode with a crop) if [[ ${TC_SOURCE:-} == strip && ${TC_BAND:-0} -gt 0 ]]; then band=$TC_BAND; deband=1; verdict=encode; reason="remove ${band}px timecode band" - log "deband $src cropping ${band} rows (re-encode, timing preserved)" + vglog info "event=deband file=\"$src\" stream=\"$stream\" band_rows=$band" fi # opt-in gap filling: switch this stream from remux to a CFR re-encode when the holes add up to enough if (( FILL_GAPS_MS > 0 )) && [[ $verdict == remux && -n $tcjson ]]; then missing=$(python3 -c 'import json,sys; d=json.loads(sys.argv[1]); print(d.get("gaps",{}).get("total_missing_ms",0))' "$tcjson" 2>/dev/null || echo 0) if (( missing >= FILL_GAPS_MS )); then - verdict=encode; reason="fill-gaps ${missing}ms"; log "gaps $src ${missing} ms missing -> CFR re-encode (FILL_GAPS_MS=$FILL_GAPS_MS)" + verdict=encode; reason="fill-gaps ${missing}ms"; vglog info "event=fill_gaps file=\"$src\" stream=\"$stream\" missing_ms=$missing" fi fi fi @@ -189,7 +192,7 @@ PYEOF rm -f "$src" # band removal: the cropped file IS the recording; raw-with-band is not kept fi rmdir "$(dirname "$src")" "$titledir" 2>/dev/null || true # drop .live and the empty title folder - log "done $out"; continue + vglog info "event=published file=\"$out\" stream=\"$stream\" verdict=$verdict"; continue elif (( synced )); then rel_src="${src#"$stroot"/}"; rel_out="${out#"$stroot"/}" { echo "/$rel_out"; echo "/$rel_src"; } >> "$stroot/.stlocal" # ignore our output and the raw @@ -205,10 +208,10 @@ PYEOF mv -f "$tmp" "$out" fi chown 1000:1000 "$out" 2>/dev/null - log "done $out" + vglog info "event=done file=\"$out\" verdict=$verdict" else rm -f "$tmp" { echo "$(date '+%F %T') $verdict failed rc=$rc src_dur=${d1:-?} out_dur=${d2:-?} ($reason)"; } > "$base.normalize-failed.log" - log "FAILED $src (see $base.normalize-failed.log)" >&2 + vglog error "event=failed file=\"$src\" stream=\"$stream\" verdict=$verdict rc=$rc log=\"$base.normalize-failed.log\"" >&2 fi done diff --git a/bin/vgdeband.sh b/bin/vgdeband.sh index 9f8c03d..827a8c1 100755 --- a/bin/vgdeband.sh +++ b/bin/vgdeband.sh @@ -8,23 +8,24 @@ # -p IOSchedulingClass=idle /usr/local/bin/vgdeband.sh ; follow with journalctl -fu vgdeband set -uo pipefail ROOT="${MEDIA_ROOT:-/srv/media}" -log() { echo "$(date '+%F %T') $*"; } +vglog() { local lvl="$1"; shift; printf 'ts=%s level=%s component=vgdeband %s\n' "$(date -Is)" "$lvl" "$*"; } +log() { vglog info "msg=\"$*\""; } dur() { ffprobe -v error -show_entries format=duration -of csv=p=0 "$1" 2>/dev/null | cut -d. -f1; } if (( $# )); then files=("$@"); else mapfile -t files < <(find "$ROOT/streams" -mindepth 2 -maxdepth 2 -type f -name '*.mp4' | sort); fi for f in "${files[@]}"; do side="${f%.*}.json" - [[ -f $side ]] || { log "skip $f (no sidecar)"; continue; } + [[ -f $side ]] || { vglog info "event=skip reason=no_sidecar file=\"$f\""; continue; } read -r src removed tc ctime < <(python3 -c ' import json,sys; d=json.load(open(sys.argv[1])) print(d.get("source","none"), 1 if d.get("band_removed") else 0, d.get("timecode",""), d.get("timestamp",""))' "$side") - [[ $src == strip ]] || { log "skip $f (source=$src)"; continue; } - (( removed )) && { log "skip $f (band already removed)"; continue; } - fuser -s "$f" 2>/dev/null && { log "skip $f (in use)"; continue; } + [[ $src == strip ]] || { vglog info "event=skip reason=source_$src file=\"$f\""; continue; } + (( removed )) && { vglog info "event=skip reason=already_removed file=\"$f\""; continue; } + fuser -s "$f" 2>/dev/null && { vglog info "event=skip reason=in_use file=\"$f\""; continue; } w=$(ffprobe -v error -select_streams v:0 -show_entries stream=width -of csv=p=0 "$f") band=$(python3 /usr/local/bin/vgstrip.py band "$w") tmp="$f.part" tcargs=(); [[ -n $tc ]] && tcargs=(-timecode "$tc" -write_tmcd 1); [[ -n $ctime ]] && tcargs+=(-metadata "creation_time=$ctime") - log "deband $f (${w}px wide -> crop ${band} rows; tc=$tc)" + vglog info "event=deband file=\"$f\" width=$w band_rows=$band timecode=\"$tc\"" nice -n 15 ionice -c 3 ffmpeg -nostdin -hide_banner -loglevel error -y -i "$f" \ -map 0:v:0 -map '0:a?' \ -c:v libx264 -preset veryfast -crf 18 -maxrate 30M -bufsize 60M -pix_fmt yuv420p -profile:v high -threads "${ENCODE_THREADS:-2}" \ @@ -36,8 +37,8 @@ print(d.get("source","none"), 1 if d.get("band_removed") else 0, d.get("timecode python3 -c ' import json,sys; p=sys.argv[1]; d=json.load(open(p)); d["band_rows"]=int(sys.argv[2]); d["band_removed"]=True json.dump(d, open(p,"w"))' "$side" "$band"; chown 1000:1000 "$side" 2>/dev/null - log "done $f" + vglog info "event=done file=\"$f\"" else - rm -f "$tmp"; log "FAILED $f rc=$rc src_dur=${d1:-?} out_dur=${d2:-?} (file left untouched)" >&2 + rm -f "$tmp"; vglog error "event=failed file=\"$f\" rc=$rc src_dur=${d1:-?} out_dur=${d2:-?}" >&2 fi done diff --git a/configure.py b/configure.py index 1549d5a..187f5fd 100755 --- a/configure.py +++ b/configure.py @@ -133,6 +133,20 @@ def ask_name(kind, taken): return n # ------------------------------------------------------------------ writers +# Access log per site, JSON on stderr (docker logs). Identity headers Authentik injected are kept (who did what); +# cookies and tokens are dropped. See LOGGING.md. +CADDY_LOG = """ log { + output stderr + format filter { + wrap json + fields { + request>headers>Cookie delete + request>headers>Authorization delete + request>headers>X-Stream-Auth delete + } + } + } +""" AUTHENTIK_FORWARD_AUTH = """ # /logout on every gated host = sign out of the Discord login (domain-wide session) redir /logout /outpost.goauthentik.io/sign_out 302 # Authentik forward-auth (embedded outpost). Needs a Proxy Provider in Authentik — domain-level for the @@ -148,7 +162,7 @@ AUTHENTIK_FORWARD_AUTH = """ # /logout on every gated host = sign out of the Dis def gate(required_group=""): """Caddy lines: Authentik forward-auth, then deny unless X-Authentik-Groups contains required_group.""" - block = AUTHENTIK_FORWARD_AUTH + block = CADDY_LOG + AUTHENTIK_FORWARD_AUTH if required_group: g = re.escape(required_group) block += f""" @lacks_group not header_regexp X-Authentik-Groups (^|\\|){g}(\\||$) @@ -270,7 +284,7 @@ groups: {{http.request.header.X-Authentik-Groups}}" # vanguard:git {git_host} {{ encode zstd gzip - reverse_proxy 127.0.0.1:3000 +{CADDY_LOG} reverse_proxy 127.0.0.1:3000 }} """ if auth_host: @@ -278,7 +292,7 @@ groups: {{http.request.header.X-Authentik-Groups}}" # vanguard:auth {auth_host} {{ encode zstd gzip - reverse_proxy 127.0.0.1:9000 +{CADDY_LOG} reverse_proxy 127.0.0.1:9000 }} """ if watch_host: @@ -286,7 +300,7 @@ groups: {{http.request.header.X-Authentik-Groups}}" # vanguard:watch {watch_host} {{ encode zstd gzip - reverse_proxy 127.0.0.1:8096 +{CADDY_LOG} reverse_proxy 127.0.0.1:8096 }} """ Path("Caddyfile").write_text(f"""# vanguard:main diff --git a/deploy.sh b/deploy.sh index e3c5703..a587282 100755 --- a/deploy.sh +++ b/deploy.sh @@ -12,7 +12,7 @@ REPO="${DEPLOY_REPO_DIR:-/home/debian/vanguard-stream}"; BRANCH="${DEPLOY_BRANCH STATE=/var/lib/vanguard; mkdir -p "$STATE" 2>/dev/null || true LASTF="$STATE/deployed-rev"; PREVF="$STATE/previous-rev"; PENDING="$STATE/mediamtx-restart-pending" DRY="${VG_DRY:-0}"; OWNER=$(stat -c %U "$REPO" 2>/dev/null || echo debian) -log() { echo "$(date '+%F %T') deploy: $*"; } +log() { printf 'ts=%s level=info component=deploy msg="%s"\n' "$(date -Is)" "${*//\"/\\\"}"; } run() { log "\$ $*"; [[ $DRY == 1 ]] || "$@"; } asowner() { log "\$ (as $OWNER) $*"; [[ $DRY == 1 ]] || sudo -u "$OWNER" -H "$@"; } notify() { diff --git a/docker-compose.yml b/docker-compose.yml index ca3b5e8..451191e 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -1,5 +1,13 @@ +# Log framework (LOGGING.md): every container keeps rotated json-file logs and carries labels a collector can use as +# low-cardinality stream labels without parsing: vanguard.service / vanguard.category. +x-logging: &vglog + driver: json-file + options: { max-size: "50m", max-file: "5" } + services: mediamtx: + logging: *vglog + labels: { vanguard.service: mediamtx, vanguard.category: stream } image: bluenviron/mediamtx:latest-ffmpeg # alpine variant: has sh + wget for the is-live Discord hook container_name: mediamtx user: "1000:1000" # recordings owned by the debian user, so the archive pull can delete them @@ -22,6 +30,8 @@ services: restart: unless-stopped copyparty: + logging: *vglog + labels: { vanguard.service: copyparty, vanguard.category: media } image: copyparty/ac:latest container_name: copyparty ports: @@ -33,6 +43,8 @@ services: restart: unless-stopped syncthing: + logging: *vglog + labels: { vanguard.service: syncthing, vanguard.category: intake } image: syncthing/syncthing:latest container_name: syncthing environment: @@ -48,6 +60,8 @@ services: restart: unless-stopped caddy: + logging: *vglog + labels: { vanguard.service: caddy, vanguard.category: auth } image: caddy:latest container_name: caddy depends_on: [copyparty] @@ -64,6 +78,8 @@ services: # ---------------------------------------------------------------- identity (Authentik) authentik-db: + logging: *vglog + labels: { vanguard.service: authentik-db, vanguard.category: auth } image: docker.io/library/postgres:16-alpine container_name: authentik-db environment: @@ -81,6 +97,8 @@ services: restart: unless-stopped authentik-redis: + logging: *vglog + labels: { vanguard.service: authentik-redis, vanguard.category: auth } image: docker.io/library/redis:alpine container_name: authentik-redis command: --save 60 1 --loglevel warning @@ -94,6 +112,8 @@ services: restart: unless-stopped authentik-server: + logging: *vglog + labels: { vanguard.service: authentik-server, vanguard.category: auth } image: ghcr.io/goauthentik/server:${AUTHENTIK_TAG:-2025.8} container_name: authentik-server command: server @@ -118,6 +138,8 @@ services: restart: unless-stopped authentik-worker: + logging: *vglog + labels: { vanguard.service: authentik-worker, vanguard.category: auth } image: ghcr.io/goauthentik/server:${AUTHENTIK_TAG:-2025.8} container_name: authentik-worker command: worker @@ -133,6 +155,8 @@ services: # ---------------------------------------------------------------- watching (Jellyfin, direct play only) jellyfin: + logging: *vglog + labels: { vanguard.service: jellyfin, vanguard.category: media } image: jellyfin/jellyfin:latest container_name: jellyfin user: "1000:1000" @@ -150,6 +174,8 @@ services: # ---------------------------------------------------------------- database (for the Discord bot and friends) mariadb: + logging: *vglog + labels: { vanguard.service: mariadb, vanguard.category: infra } image: mariadb:11 container_name: mariadb network_mode: host # PUBLIC on 3306: host networking so the nftables input rules (db_allow / rate @@ -174,6 +200,8 @@ services: # ---------------------------------------------------------------- Discord bot (python; code lives in ./bot/app) discord-bot: + logging: *vglog + labels: { vanguard.service: discord-bot, vanguard.category: bot } build: ./bot container_name: discord-bot user: "1000:1000" @@ -208,6 +236,8 @@ services: # ---------------------------------------------------------------- Gitea + Actions runner gitea: + logging: *vglog + labels: { vanguard.service: gitea, vanguard.category: code } image: docker.gitea.com/gitea:1.24 container_name: gitea environment: @@ -253,6 +283,8 @@ services: restart: unless-stopped act_runner: + logging: *vglog + labels: { vanguard.service: act_runner, vanguard.category: deploy } image: docker.gitea.com/act_runner:latest container_name: act_runner environment: