Files
bambuddy/backend/tests/unit/test_ffmpeg_output_summary.py
T
maziggy d4477e9b71 Log ffmpeg's error instead of its build banner
ffmpeg opens every run with ~20 lines of version and build banner and prints
its diagnosis last, so the stderr[:200] eight of the nine call sites used kept
the banner and threw the error away. The reporter's twelve capture failures all
read "ffmpeg version 7.1.4 ... configuration: --prefix=/usr --extra-version=",
identical on every install; the exit code was the only usable byte.

The banner-stripping summariser written for #925 lived private to the camera
route. It now lives in backend/app/utils/ffmpeg_output.py and every ffmpeg and
ffprobe stderr goes through it. Two things the scattered copies also got wrong:
four logged the input URL unmasked, publishing a printer access code or camera
password, and four called a bare .decode() on bytes ffmpeg copies stream
fragments into.

-----

Delete the files a no-3MF archive owns, without taking a printer folder

Both delete paths derived the directory from file_path, which such an archive
does not have, so they removed nothing and logged it at ERROR under a SECURITY
banner. That was true when the archive was an empty row and stopped being true
once one could hold a timelapse and finish photos in <archive_dir>/<id>/ and an
uploaded source in archive/no_source/<id>/.

The two are cleaned up by different means, because <archive_dir>/<id> shares a
namespace with the per-printer folders: a normal archive lives at
<archive_dir>/<printer_id>/<timestamp>_<name>/, so archive/1 is printer 1's
folder and also the directory the shared helper hands archive id 1. Ids come
from unrelated sequences, so the first few archives collide with the printers
on every install, and an rmtree there takes every print that printer made --
measured on a scratch tree. no_source/<id> is a level deeper under a name no
printer id can take and is removed whole; the id-named directory gives up only
its photos subdirectory and the video the row records, then goes only if that
left it empty. The depth guard moves from one to two for the same reason: a
file_path that lost a path component could point the delete at a printer
folder, and no archive directory has been one level deep since the first
commit.

Hard delete had its own copy of these rules, which the helper's docstring says
it exists to prevent, and it had diverged -- it skipped the print-log thumbnail
cleanup whenever a guard tripped.

-----

Stop the RTSPS proxy leaving a handler behind at shutdown

asyncio.start_server keeps only a weak reference to the connection callback's
task, so a handler still awaiting its forwarders could be collected while
pending -- "Task was destroyed but it is pending!", at ERROR with a traceback
into camera.py, once every few hundred snapshots. Teardown had the matching
gap: server.close() leaves established connections running, so the close waited
on a handler that only finishes when the peer drops, and ffmpeg has already
been reaped by then.

Handlers are held for as long as they run and cancelled at shutdown, which is
Server.close_clients() by hand -- that landed in 3.13 and Bambuddy supports
3.10. Both the snapshot path and the streaming endpoint share the shutdown.
2026-08-29 08:51:33 +02:00

186 lines
8.1 KiB
Python

"""ffmpeg's diagnosis survives the log line, and its banner does not (#2968).
ffmpeg prints ~20 lines of version and build banner first and its actual error
last, so the ``stderr[:200]`` most call sites used kept the banner and dropped
the error. The reporter's H2D logged twelve capture failures that way; every
one of them was the same 200 characters of ``--prefix=/usr --extra-version=``
and none of them said why the capture failed.
#925 already solved this for the camera streaming endpoint. These tests cover
the shared module the other seven call sites now go through, and the two things
that were only ever true of the private copy: it takes bytes, and it masks
credentials for callers that never did.
"""
import inspect
import pytest
from backend.app.utils.ffmpeg_output import NO_FFMPEG_OUTPUT, summarize_ffmpeg_stderr
# Verbatim from the reporter's log, trimmed to the width the old truncation
# allowed through. The point of the fixture is that 200 characters of it carry
# no information at all.
_REAL_BANNER = """ffmpeg version 7.1.4-0+deb13u1 Copyright (c) 2000-2026 the FFmpeg developers
built with gcc 14 (Debian 14.2.0-19)
configuration: --prefix=/usr --extra-version=0+deb13u1 --toolchain=hardened --enable-gpl
libavutil 59. 39.100 / 59. 39.100
libavcodec 61. 19.101 / 61. 19.101
libavformat 61. 7.100 / 61. 7.100
libavdevice 61. 3.100 / 61. 3.100
libavfilter 10. 4.100 / 10. 4.100
libswscale 8. 3.100 / 8. 3.100
libswresample 5. 3.100 / 5. 3.100
libpostproc 58. 3.100 / 58. 3.100
"""
class TestTheDiagnosisSurvives:
def test_the_error_is_kept_and_the_banner_is_not(self):
"""The whole point: the last line, not the first 200 characters."""
stderr = _REAL_BANNER + "[rtsp @ 0x5f] method DESCRIBE failed: 401 Unauthorized\n"
result = summarize_ffmpeg_stderr(stderr)
assert "method DESCRIBE failed: 401 Unauthorized" in result
assert "ffmpeg version" not in result
assert "--prefix=/usr" not in result
def test_the_old_truncation_would_have_kept_none_of_it(self):
"""Guards the claim the fix rests on rather than asserting it in prose:
200 characters from the front of a real failure is banner only."""
stderr = _REAL_BANNER + "[rtsp @ 0x5f] method DESCRIBE failed: 401 Unauthorized\n"
assert "DESCRIBE" not in stderr[:200]
def test_input_analysis_is_kept(self):
"""Indented, but not banner. ``Duration:`` and ``Stream #0:0`` explain
the error above them and are the reason the match is on exact prefixes
rather than on leading whitespace."""
stderr = _REAL_BANNER + (
"Input #0, rtsp, from 'rtsp://192.0.2.1:322/streaming/live/1':\n"
" Duration: N/A, start: 0.000000, bitrate: N/A\n"
" Stream #0:0: Video: h264, yuv420p, 1920x1080\n"
"Output file is empty, nothing was encoded\n"
)
result = summarize_ffmpeg_stderr(stderr)
assert "Duration: N/A" in result
assert "Stream #0:0: Video: h264" in result
assert "Output file is empty" in result
def test_only_the_last_lines_are_kept(self):
"""A chatty decoder must not rotate the log file on one failure."""
stderr = _REAL_BANNER + "\n".join(f"error line {i}" for i in range(40))
lines = summarize_ffmpeg_stderr(stderr).splitlines()
assert len(lines) == 10
assert lines[-1] == "error line 39"
def test_a_banner_only_failure_says_so(self):
"""Empty, so the caller substitutes a phrase. ``failed: `` with nothing
after it reads like a truncation bug rather than a silent printer."""
assert summarize_ffmpeg_stderr(_REAL_BANNER) == ""
assert (summarize_ffmpeg_stderr(_REAL_BANNER) or NO_FFMPEG_OUTPUT) == NO_FFMPEG_OUTPUT
class TestWhatTheCallSitesUsedToGetWrong:
def test_bytes_are_accepted(self):
"""Every call site held bytes and decoded them itself."""
assert "Connection refused" in summarize_ffmpeg_stderr(b"rtsp://192.0.2.1: Connection refused\n")
def test_undecodable_bytes_do_not_raise(self):
"""ffmpeg copies stream fragments into its messages, so a bare
``.decode()`` could raise UnicodeDecodeError while reporting an
unrelated failure -- losing the diagnosis to a second exception."""
result = summarize_ffmpeg_stderr(b"\xff\xfe broken input\nInvalid data found\n")
assert "Invalid data found" in result
def test_the_access_code_is_masked(self):
"""ffmpeg echoes its input URL back, and four of the call sites logged
it unmasked. The mask is part of the summary so it cannot be skipped."""
stderr = b"Error opening input file rtsp://bblp:12345678@192.0.2.1:322/streaming/live/1.\n"
result = summarize_ffmpeg_stderr(stderr)
assert "12345678" not in result
assert "[REDACTED]" in result
# Host and user survive, or the line stops being useful for diagnosis.
assert "192.0.2.1:322" in result
assert "bblp" in result
def test_a_credential_masked_before_the_cut_not_after(self):
"""Truncating first would leave a URL with no ``@`` for the pattern to
anchor on, and the secret in the log."""
stderr = "\n".join(f"noise {i}" for i in range(30))
stderr += "\nOpening rtsp://user:hunter2@192.0.2.1:322/live and 40 more characters of tail\n"
result = summarize_ffmpeg_stderr(stderr)
assert "hunter2" not in result
@pytest.mark.parametrize("empty", ["", None, b""])
def test_nothing_in_nothing_out(self, empty):
assert summarize_ffmpeg_stderr(empty) == ""
def test_a_single_enormous_line_is_bounded(self):
"""Ten lines only bounds the record if the lines are sane, and ffmpeg
quotes back what the peer sent it. The tail is what is kept."""
stderr = _REAL_BANNER + "x" * 50_000 + " Connection refused\n"
result = summarize_ffmpeg_stderr(stderr)
assert len(result) < 2_100
assert result.endswith("Connection refused")
assert result.startswith("...")
def test_an_ordinary_diagnosis_is_never_trimmed(self):
"""The ceiling must not be reachable by real ffmpeg output."""
stderr = _REAL_BANNER + "\n".join(f"[rtsp @ 0x5f] error line {i}" for i in range(10))
assert not summarize_ffmpeg_stderr(stderr).startswith("...")
class TestEveryCallSiteGoesThroughIt:
"""The defect was seven copies of the same truncation, not one bad line.
Asserted against the source because the alternative -- driving all seven
subprocesses -- tests ffmpeg, and because the failure mode being guarded is
somebody adding an eighth.
"""
@pytest.mark.parametrize(
"module_path",
[
"backend.app.services.camera",
"backend.app.services.external_camera",
"backend.app.services.layer_timelapse",
"backend.app.services.timelapse_processor",
"backend.app.services.archive",
"backend.app.api.routes.camera",
],
)
def test_no_module_truncates_stderr_by_hand(self, module_path):
import importlib
source = inspect.getsource(importlib.import_module(module_path))
for lineno, raw in enumerate(source.splitlines(), 1):
# Comments discuss the defect by name -- this file's own fix notes
# do -- so only what executes is checked.
line = raw.split("#", 1)[0]
if "stderr" not in line:
continue
assert "stderr.decode()[:" not in line, f"{module_path}:{lineno} truncates stderr from the front"
assert "stderr_text[:" not in line, f"{module_path}:{lineno} truncates stderr from the front"
assert 'stderr.decode(errors="replace")[:' not in line, (
f"{module_path}:{lineno} truncates stderr from the front"
)
# A bare decode is the other half of the defect: it can raise
# UnicodeDecodeError while reporting an unrelated failure, and it
# leaves the input URL's credentials unmasked.
assert "stderr.decode()" not in line, f"{module_path}:{lineno} decodes stderr by hand"