signal-bot/signal_bot/logging_setup.py
Krzysztof kuhy Rudnicki 50f6a587c2 feat: the bot can describe an envelope without quoting anybody
DOCS-signal-envelopes.md exists because this wire format is not obvious
and guessing at it has cost real bugs -- the sticker read off the wrong
nesting level, and 0.0.3's !gekon shipping green on an assumption nobody
had checked against the live API. The recurring cost is that answering
"what does a frame with an attachment actually look like?" needed a code
change, a restart, and somebody sending one at the right moment.

So at DEBUG the dispatcher now logs each frame's *shape*: keys and value
types, never values. Two fields keep their values because they are wire
format rather than anything a person said -- a MIME type and a groupInfo
type. A message body, a name, a number, a uuid, quoted text and a
sticker id all come out as "str". An album collapses to one element and
a count instead of printing the same dict twenty times.

Verified against a live frame: the body, the quoted text, the uuid and
the phone number do not survive, and contentType does.

This also had to fix DEBUG being unusable. LOG_LEVEL=DEBUG set the root
logger, which turns on httpx, httpcore and asyncio; the bot polls a
group listing every 30 seconds, so the one interesting line arrived
buried and journald started dropping. Libraries are now held at WARNING
whatever the bot is set to -- at INFO httpx was already emitting an
"HTTP Request: GET ... 200 OK" line every thirty seconds, forever.
Measured on the running unit: 17 library lines per minute down to 2.

Two bugs in that setup found by its own tests rather than by review:
basicConfig is a documented no-op once the root logger has a handler, so
the level silently did not apply under pytest; and the floor belongs at
INFO too, not only below it.

A self-send does not produce a capturable attachment envelope, by the
way -- signal-cli emits no syncMessage for a send made over the same
connection. Two probe images returned HTTP 201 and no frame came back,
so the inbound shape still needs a human to post one.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_015d48t4qsQLBJnDwDeo2Nom
2026-08-30 19:29:06 +02:00

42 lines
1.8 KiB
Python

# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence.
"""Logging configuration, with the noisy libraries kept out of DEBUG.
``LOG_LEVEL=DEBUG`` exists to answer questions about the bot -- which frame
was ignored and why, what shape an envelope actually has. Setting the root
logger to DEBUG also turns on httpx, httpcore and asyncio, which between them
emit several lines per HTTP request. The bot polls a group listing every 30
seconds, so the one line worth reading arrives buried in hundreds that are
not, and journald rate-limiting then starts dropping messages.
So the libraries are held at WARNING whatever the bot is set to. A warning
from httpx is worth seeing; its per-request bookkeeping is not, at any level
-- at INFO it was already emitting a "HTTP Request: GET ... 200 OK" line
every thirty seconds, forever.
"""
from __future__ import annotations
import logging
from typing import Final
FORMAT: Final = "%(asctime)s %(levelname)s %(name)s: %(message)s"
# Every third-party logger that is chatty at DEBUG. httpcore is the worst
# offender by an order of magnitude: it logs both ends of every connection.
NOISY: Final = ("httpx", "httpcore", "asyncio", "websockets", "urllib3")
NOISY_FLOOR: Final = logging.WARNING
def configure(level: str) -> None:
"""Send the bot's logs to stderr at ``level``, muting the noisy libraries.
Args:
level: A logging level name, already validated by config_env.
"""
logging.basicConfig(level=level, format=FORMAT)
# Explicitly too: basicConfig is a documented no-op once the root logger
# already has a handler, which is the case under pytest and under some
# uvicorn arrangements. Without this the level silently does not apply.
logging.getLogger().setLevel(level)
for name in NOISY:
logging.getLogger(name).setLevel(NOISY_FLOOR)