bambuddy/backend/app/utils/ffmpeg_output.py

"""Turning an ffmpeg subprocess's stderr into a log line worth reading (#2968).

ffmpeg opens every run with ~20 lines of version, build and library banner and
prints its diagnosis *last*. Truncating that from the front -- ``stderr[:200]``,
which is what most call sites did -- keeps the banner and throws the diagnosis
away. A reporter's H2D produced twelve of these, and every one of them read

    ffmpeg frame bytes capture failed (code 183): 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 --toolch

-- 200 characters that are identical on every install and say nothing about why
the capture failed. The exit code was the only usable byte in the whole line.

The banner-stripping summariser this module holds was written for #925 and
lived as a private helper in ``api/routes/camera.py``, where the streaming
endpoint used it. Ten other places log ffmpeg or ffprobe stderr -- snapshot
capture, last-frame extraction, the layer-timelapse stitch, the archive's MP4
conversion, external USB and RTSP capture and streaming, and timelapse
post-processing. Seven of them truncated from the front, two logged the whole
banner, and one already kept the tail. They all come here now, so they cannot
drift again.

Redaction is part of the summary rather than each caller's job. ffmpeg echoes
its input URL back in the ``Input #0`` line, so a camera password or a printer
access code reaches stderr on any failure; seven of those ten logged it
unmasked. A helper that redacts is one that cannot be called wrong.

Kept as a leaf module -- stdlib plus :mod:`core.logging_filters`, which is
itself stdlib-only -- so the services and the route can all reach it without
pulling a startup graph behind them.
"""

from __future__ import annotations

import asyncio
import contextlib
import logging

from backend.app.core.logging_filters import redact_url_credentials

logger = logging.getLogger(__name__)

# What ffmpeg prints before it has anything to say. Every line of the banner is
# either the version line or an indented continuation, and a real diagnostic is
# never indented this way, so the match is on the exact prefixes rather than on
# indentation alone -- ``  Duration: ...`` and ``    Stream #0:0 ...`` are
# indented too and are worth keeping.
_BANNER_PREFIXES = (
    "ffmpeg version ",
    "ffprobe version ",
    "  built with ",
    "  configuration:",
    "  libavutil ",
    "  libavcodec ",
    "  libavformat ",
    "  libavdevice ",
    "  libavfilter ",
    "  libswscale ",
    "  libswresample ",
    "  libpostproc ",
)

# How much of the tail to keep. ffmpeg's diagnosis is the last thing it writes,
# and ten lines is enough to carry the error plus the input analysis that
# explains it without letting a chatty decoder rotate the log file.
_MAX_LINES = 10

# And a ceiling on the whole thing. Ten lines is only a bound on the log record
# if the lines are a sane length, and ffmpeg quotes what the peer sent it back
# at us -- a printer's RTSP response is not something Bambuddy controls. Well
# above any real diagnosis, so this only ever trims a line that was already not
# going to be read.
_MAX_CHARACTERS = 2000

# What to log when the summary is empty. A failure whose stderr held nothing but
# the banner still deserves a line saying so -- ``failed: `` with an empty tail
# reads like a truncation bug rather than a printer that closed the connection.
NO_FFMPEG_OUTPUT = "no diagnostic output"


def summarize_ffmpeg_stderr(text: str | bytes | None) -> str:
    """Strip ffmpeg's boilerplate banner and keep the last lines that matter.

    Accepts raw ``bytes`` as well as ``str`` and decodes with ``errors=
    "replace"``: ffmpeg copies fragments of the stream into its error messages,
    so a bare ``.decode()`` at the call site can raise ``UnicodeDecodeError``
    while reporting an unrelated failure. Losing the diagnosis to a second
    exception is the one outcome worse than logging the banner.

    Returns ``""`` when there is nothing left after the banner, which is the
    signal the streaming endpoint uses to stay quiet. One-shot callers that log
    unconditionally should fall back to :data:`NO_FFMPEG_OUTPUT`.
    """
    if not text:
        return ""
    if isinstance(text, (bytes, bytearray)):
        text = text.decode(errors="replace")
    # Redaction runs on the whole string before anything is dropped: a
    # credentialed URL that straddles the cut would otherwise leave its tail in
    # the log with no ``@`` left for the pattern to anchor on.
    text = redact_url_credentials(text) or ""
    meaningful = [line for line in text.splitlines() if line.strip() and not line.startswith(_BANNER_PREFIXES)]
    summary = "\n".join(meaningful[-_MAX_LINES:])
    if len(summary) > _MAX_CHARACTERS:
        # From the end, for the same reason the whole module exists.
        summary = "..." + summary[-_MAX_CHARACTERS:]
    return summary


# ffmpeg's RTSP demuxer follows a server's 3xx Location by itself, with no
# option to refuse, and logs the first line below before it connects there.
# Only the configured address was ever checked, so a redirect ends the fetch:
# nothing fetched from the new destination is used. av_dump_format prints the
# second once the input is open, before ffmpeg writes any output.
_RTSP_REDIRECT_LOG = b"Redirecting to "
_INPUT_OPEN_LOG = b"Input #0, "
# Pinned: both lines are logged at "info".
FFMPEG_RTSP_LOGLEVEL = ("-loglevel", "info")
# Longest log line read before the input is open; ffmpeg's own are far shorter.
_MAX_LOG_LINE = 65536


def rtsp_log_event(line: bytes) -> str | None:
    """``"redirected"`` or ``"open"`` for the ffmpeg log line that says so."""
    if _RTSP_REDIRECT_LOG in line:
        return "redirected"
    if line.startswith(_INPUT_OPEN_LOG):
        return "open"
    return None


def refuse_rtsp_redirect(process: asyncio.subprocess.Process, line: bytes) -> None:
    """Stop an ffmpeg that reported following a redirect, saying where to."""
    target = line.split(_RTSP_REDIRECT_LOG, 1)[-1].split(b"\n", 1)[0].decode("utf-8", "replace").strip()
    logger.error(
        "RTSP camera redirected to %s; redirects are not followed, configure that address instead",
        (redact_url_credentials(target) or "")[:80],
    )
    with contextlib.suppress(ProcessLookupError):
        process.kill()


async def read_ffmpeg_log_until_open(process: asyncio.subprocess.Process) -> tuple[str, bytes]:
    """Read an RTSP ffmpeg's log up to the line saying its input is open.

    Returns ``("open", log)``; ``("redirected", log)`` after a redirect, with
    ffmpeg killed; or ``("ended", log)`` when ffmpeg stopped first.
    """
    assert process.stderr is not None
    log = b""
    while True:
        try:
            line = await process.stderr.readline()
        except ValueError:
            # A line past the reader's limit is no line of ffmpeg's own.
            with contextlib.suppress(ProcessLookupError):
                process.kill()
            return "ended", log
        if not line:
            return "ended", log
        log = (log + line)[-_MAX_LOG_LINE:]
        event = rtsp_log_event(line)
        if event == "redirected":
            refuse_rtsp_redirect(process, line)
            return event, log
        if event == "open":
            return event, log


async def watch_ffmpeg_log(process: asyncio.subprocess.Process) -> None:
    """Drain a streaming ffmpeg's log, so a full pipe never stalls it, and
    stop ffmpeg should it report a redirect after all."""
    assert process.stderr is not None
    tail = b""
    while chunk := await process.stderr.read(4096):
        window = tail + chunk
        if _RTSP_REDIRECT_LOG in window:
            refuse_rtsp_redirect(process, window[window.index(_RTSP_REDIRECT_LOG) :])
            return
        tail = window[-len(_RTSP_REDIRECT_LOG) :]