From a994ec712d8724fff8ce39865f255381abfe30d4 Mon Sep 17 00:00:00 2001 From: Garrett Allen <98648590+Gerrrt@users.noreply.github.com> Date: Fri, 4 Sep 2026 23:11:27 +0000 Subject: [PATCH] fix(backup): stop shipping the archives back through the log pipeline (#286) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `backup-volumes.sh` archives each volume with `docker run ... tar -czf -`, so the gzip stream IS that container's stdout. The json-file driver records stdout whether or not anyone reads it, and Alloy's `loki.source.docker` tails every container on the socket — so `make backup` sent its own output back into Loki as log lines. Measured on 2026-08-29: 765 MB across three volumes in about three minutes, 2.7 MiB/s against a 950 B/s baseline, 5,500 lines a second against three. Loki's RSS tracked it minute for minute up to 1015 MiB, which is what set its `mem_limit` in #114. Roughly three days of the estate's real logs per run, and it recurred on the backup timers — 577 MiB on 09-04. It also quietly undid `archive_one()`'s own argument. That function encrypts with age precisely so the plaintext never touches this disk; the *compressed* plaintext was landing in `loki-data`, which is not encrypted, and staying for the 30-day retention. Fixed at source: `--log-driver none` on the runs whose stdout is a data stream, so Docker discards it rather than Alloy filtering it later. Nothing reads `docker logs` on a container the shell is already piping. Second line of defence in `docker.alloy`: containers labelled `homelab.logs=off` are dropped before Alloy opens a log stream, for the next ad-hoc `docker run` that forgets. NOT filtered on the compose project, which #286 proposed and which would have broken collection. That label is empty for every container on `oracle` — `wiki`, `db` and the agent are all plain `docker run` (scripts/deploy-agent.sh) — so "drop what has no project label" would have silently stopped collecting logs for the one service in this estate anybody uses. Checked against `container_last_seen` on both hosts first. Opt-out is weaker than the allow-list #286 wanted and the gap is written down rather than papered over: a throwaway container setting neither flag is still tailed. Bounding that is a per-stream ingestion limit in Loki, which trades a flood for silently dropped lines and is a separate decision. `loki`'s `mem_limit` is deliberately unchanged. Every measurement behind it still includes the flood; a fortnight without one does not exist until 2026-09-18. The comment says so and says what to re-derive from. Co-Authored-By: Claude Opus 5 --- docs/roadmap.md | 35 +++++++++++++++------ scripts/backup-volumes.sh | 20 +++++++++++- scripts/restore-volumes.sh | 13 ++++++-- stacks/observability/alloy/docker.alloy | 42 ++++++++++++++++++++++++- stacks/observability/compose.yaml | 18 ++++++++--- 5 files changed, 108 insertions(+), 20 deletions(-) diff --git a/docs/roadmap.md b/docs/roadmap.md index d69f554..33b2261 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -165,16 +165,31 @@ issues intact. Nothing was summarised away. byte ceiling on the TSDB, which is at a measurable steady state at day 28 of 30. - **[#286](https://github.com/Gerrrt/HomeLab/issues/286) Alloy tails the backup - archiver's tar stream into Loki.** Found while sizing #114, and it is the - reason `loki`'s ceiling is 1536M rather than about 512M. - `discovery.docker` has no filter, so it tails every container on the socket - rather than this stack's seven — and `backup-volumes.sh` writes each volume's - gzip stream to a container's stdout. One `make backup` put 765 MB of binary - through the log pipeline in three minutes, roughly three days of the estate's - real logs, and `loki-data` is not encrypted where the archives deliberately - are. Filter on the compose project label; the archiver should also get - `logging: driver: none`. Until then #114's largest number is sized around - this rather than around Loki. + archiver's tar stream into Loki.** Done 2026-09-04. Found while sizing #114, + and it is the reason `loki`'s ceiling is 1536M rather than about 512M: + `backup-volumes.sh` writes each volume's gzip stream to a container's stdout + and `discovery.docker` tails every container on the socket, so one + `make backup` put 765 MB of binary through the log pipeline in three minutes + — roughly three days of the estate's real logs, into a `loki-data` volume + that is not encrypted where the archives deliberately are. + + **The fix this entry proposed would have broken log collection.** Filtering + on `__meta_docker_container_label_com_docker_compose_project` and dropping + what does not carry it reads as the tidy answer, but that label is empty for + every container on `oracle` — `wiki`, `db` and the agent itself are all plain + `docker run` — so it would have silently stopped collecting logs for the one + service in this estate anybody uses. Checked against `container_last_seen` + across both hosts before writing any of it. What landed instead is + `--log-driver none` on the archiver runs, so Docker discards the stream at + source, plus an opt-out label (`homelab.logs=off`) that Alloy drops on before + opening a stream at all. + + Opt-out is a weaker guarantee than the allow-list this entry wanted, and the + gap is named rather than papered over: a future throwaway container that sets + neither flag is still tailed. Bounding *that* is a per-stream ingestion limit + in Loki, which trades a flood for silently dropped lines and is its own + decision. `loki`'s `mem_limit` is unchanged until a fortnight without the + flood exists to re-derive from — 2026-09-18. - **[#249](https://github.com/Gerrrt/HomeLab/issues/249) Scrape the UPS self-test schedule.** [#93](https://github.com/Gerrrt/HomeLab/issues/93) left `mjolnir` testing itself every fortnight and nothing able to see that it does. diff --git a/scripts/backup-volumes.sh b/scripts/backup-volumes.sh index 620aa83..dbc54a4 100755 --- a/scripts/backup-volumes.sh +++ b/scripts/backup-volumes.sh @@ -516,9 +516,26 @@ archive_one() { # # errexit is lifted for the pipeline because BOTH statuses are needed, and # `rc=$?` afterwards would clobber PIPESTATUS. + # --log-driver none, and it is load-bearing rather than tidiness. This + # container's stdout IS the gzip stream, the json-file driver records stdout + # whether or not anyone reads it, and Alloy's loki.source.docker tails every + # container on the socket — so this line used to ship each archive back into + # Loki as log lines. Measured on 2026-08-29: 765 MB across three volumes in + # about three minutes, 2.7 MiB/s against a 950 B/s baseline, which took loki's + # RSS to 1015 MiB and is the whole reason its mem_limit is 1536M (#286, #114). + # + # It also undid this function's own argument. The comment above says the + # plaintext never touches this disk; the *compressed* plaintext was landing in + # the loki-data volume, which is not encrypted, and staying there for the + # 30-day retention. + # + # `none` rather than a size cap: there is no volume of this that is useful. + # The stream is binary, nothing reads `docker logs` on a container the shell + # is already piping, and a cap would only change how much of it arrives. set +e docker run --rm --network none --read-only \ --security-opt no-new-privileges \ + --log-driver none --label homelab.logs=off \ -v "${PROJECT}_${vol}:/data:ro" \ "${TAR_IMAGE}" \ tar --numeric-owner -czf - -C /data . \ @@ -736,7 +753,8 @@ docker image inspect "${TAR_IMAGE}" >/dev/null 2>&1 || { info "sizing ${#VOLUMES[@]} volume(s)" total_kb=0 for v in "${VOLUMES[@]}"; do - kb="$(docker run --rm --network none -v "${PROJECT}_${v}:/data:ro" "${TAR_IMAGE}" \ + kb="$(docker run --rm --network none --log-driver none --label homelab.logs=off \ + -v "${PROJECT}_${v}:/data:ro" "${TAR_IMAGE}" \ du -sk /data | awk '{print $1}')" total_kb=$((total_kb + kb)) done diff --git a/scripts/restore-volumes.sh b/scripts/restore-volumes.sh index df00726..b2fca6f 100755 --- a/scripts/restore-volumes.sh +++ b/scripts/restore-volumes.sh @@ -252,7 +252,8 @@ printf ' %-32s %14s %14s\n' "volume" "live now" "in the set" for v in "${TARGETS[@]}"; do live="?" if docker volume inspect "${PROJECT}_${v}" >/dev/null 2>&1; then - kb="$(docker run --rm --network none -v "${PROJECT}_${v}:/data:ro" "${ARCHIVER}" du -sk /data | awk '{print $1}')" + kb="$(docker run --rm --network none --log-driver none --label homelab.logs=off \ + -v "${PROJECT}_${v}:/data:ro" "${ARCHIVER}" du -sk /data | awk '{print $1}')" live="$(human $((kb * 1024)))" else live="does not exist" @@ -312,7 +313,11 @@ if ((SAFETY)); then snapped=() for v in "${TARGETS[@]}"; do docker volume inspect "${PROJECT}_${v}" >/dev/null 2>&1 || continue + # --log-driver none for the reason archive_one() in backup-volumes.sh + # spells out: stdout here is the gzip stream, and without this it is shipped + # into Loki as log lines (#286). docker run --rm --network none --read-only --security-opt no-new-privileges \ + --log-driver none --label homelab.logs=off \ -v "${PROJECT}_${v}:/data:ro" "${ARCHIVER}" \ tar --numeric-owner -czf - -C /data . 2>/dev/null \ | age --recipient "${AGE_RECIPIENT}" --output "${SNAP_DIR}/${v}.tar.gz.age" @@ -359,7 +364,8 @@ for v in "${TARGETS[@]}"; do # Extracted as root, with --numeric-owner, so tar can put back the uids the # services run as (65534, 10001, 472) rather than remapping them. age --decrypt -i "${AGE_IDENTITY}" "${SET_DIR}/${v}.tar.gz.age" \ - | docker run --rm -i --network none -v "${PROJECT}_${v}:/data" "${ARCHIVER}" \ + | docker run --rm -i --network none --log-driver none --label homelab.logs=off \ + -v "${PROJECT}_${v}:/data" "${ARCHIVER}" \ sh -c 'set -e; cd /data && find . -mindepth 1 -delete && tar --numeric-owner -xzf - -C /data' done @@ -370,7 +376,8 @@ printf '\n' for v in "${TARGETS[@]}"; do want="${EXPECT_UID[$v]:-}" [[ -n ${want} ]] || continue - got="$(docker run --rm --network none -v "${PROJECT}_${v}:/data:ro" "${ARCHIVER}" \ + got="$(docker run --rm --network none --log-driver none --label homelab.logs=off \ + -v "${PROJECT}_${v}:/data:ro" "${ARCHIVER}" \ stat -c '%u' /data/. 2>/dev/null || echo '?')" if [[ ${got} == "${want}" ]]; then green "${v}: owned by uid ${got}, as ${VOL_SERVICE[$v]} expects" diff --git a/stacks/observability/alloy/docker.alloy b/stacks/observability/alloy/docker.alloy index cca8bc1..f527edd 100644 --- a/stacks/observability/alloy/docker.alloy +++ b/stacks/observability/alloy/docker.alloy @@ -58,6 +58,46 @@ discovery.docker "dockerlogs" { host = "unix:///var/run/docker.sock" } +// Ephemeral containers opt out of log collection with `homelab.logs=off`, and +// this drops them before Alloy ever opens their log stream. +// +// It exists because `make backup` was shipping its own archives back through +// here. backup-volumes.sh runs `tar -czf -` in a container, so the gzip stream +// IS that container's stdout; the json-file driver records stdout regardless of +// who is reading, and this component discovers every container on the socket +// rather than one stack's. 765 MB of binary arrived as log lines in three +// minutes on 2026-08-29 — 2.7 MiB/s against a 950 B/s baseline — which took +// loki's RSS to 1015 MiB and set its mem_limit (#286, #114). +// +// Those runs now also pass `--log-driver none`, which is the real fix: Docker +// discards the stream at source and there is nothing left to tail. This rule is +// the second line, for the next ad-hoc `docker run` that forgets. +// +// NOT filtered on the compose project, which is the obvious-looking form and is +// wrong here. `__meta_docker_container_label_com_docker_compose_project` is +// empty for every container on `oracle` — `wiki`, `db` and the agent itself are +// all plain `docker run` (see scripts/deploy-agent.sh) — so "drop what has no +// project label" would silently stop collecting logs for the one service in +// this estate that a person actually uses. Verified against +// container_last_seen across both hosts before writing this. An allow-list of +// known-good names is the same trap one step further on: it fails closed on a +// host nobody remembered to add. +// +// Opt-out rather than opt-in is a real weakness and worth naming: a future +// throwaway container that sets neither flag still gets tailed. What bounds +// that case is not this rule — it is a per-stream ingestion limit in Loki, +// which is a separate decision because it trades a flood for silently dropped +// lines. Recorded on #286 rather than done here. +discovery.relabel "dockerlogs_targets" { + targets = discovery.docker.dockerlogs.targets + + rule { + source_labels = ["__meta_docker_container_label_homelab_logs"] + regex = "off" + action = "drop" + } +} + discovery.relabel "dockerlogs" { targets = [] @@ -70,7 +110,7 @@ discovery.relabel "dockerlogs" { loki.source.docker "default" { host = "unix:///var/run/docker.sock" - targets = discovery.docker.dockerlogs.targets + targets = discovery.relabel.dockerlogs_targets.output labels = {"platform" = "docker", "log_type" = "docker"} relabel_rules = discovery.relabel.dockerlogs.rules forward_to = [loki.process.dockerlogs_filter.receiver] diff --git a/stacks/observability/compose.yaml b/stacks/observability/compose.yaml index f5b932c..58b33de 100644 --- a/stacks/observability/compose.yaml +++ b/stacks/observability/compose.yaml @@ -162,8 +162,14 @@ x-service-defaults: &service-defaults # to start with, on a 152 MiB peak from a six-hour window. Fourteen days # inverts that — it is the riskiest of the seven to bound. # -# When #286 lands, re-derive this from a fortnight without the flood; it should -# fall to roughly 512M. Move the number and this paragraph together. +# #286 landed on 2026-09-04: the archiver runs with `--log-driver none`, so +# Docker discards the stream at source, and Alloy drops any container labelled +# `homelab.logs=off` before opening its log stream. The number here has +# deliberately NOT been moved yet — every measurement above still includes the +# flood, and a fortnight without it does not exist until 2026-09-18. Re-derive +# then, from `max_over_time(container_memory_rss{name="loki"}[14d])`; on the +# nine quiet days in this window that peaked at 107-128 MiB, so expect roughly +# 512M. Move the number and this paragraph together. # # NO SWAP, DELIBERATELY. `memswap_limit` equals `mem_limit` on every service, # which sets `memory.swap.max` to 0. Left unset it defaults to 2x mem_limit, @@ -341,9 +347,11 @@ services: # is the same fact twice: loki has by far the widest dynamic range here, # 93 MiB median against a peak eleven times that. That peak is the 2026-08-29 # ingest flood explained above, it belongs to #286 rather than to Loki, and - # it recurs — 577 MiB as recently as 09-04. Sized to clear it rather than - # to clip it, because a log store OOM-killed mid-flood takes the record of - # the flood with it. + # it recurred until #286 was fixed on 2026-09-04 — 577 MiB as recently as + # that morning. Sized to clear it rather than to clip it, because a log + # store OOM-killed mid-flood takes the record of the flood with it. The + # cause is gone; the number stays until a fortnight of data without it + # exists to re-derive from. See the block above `services:`. mem_limit: 1536m memswap_limit: 1536m command: -config.file=/etc/loki/loki-config.yaml