diff --git a/signal_bot/__main__.py b/signal_bot/__main__.py index 4216ad7..4eb0f34 100644 --- a/signal_bot/__main__.py +++ b/signal_bot/__main__.py @@ -12,11 +12,10 @@ BIND_HOST/BIND_PORT whenever they live in .env -- which is where they live. from __future__ import annotations -import logging - import uvicorn from signal_bot.config_env import load_config +from signal_bot.logging_setup import configure as configure_logging from signal_bot.portcheck import PortInUseError, assert_port_free @@ -26,9 +25,7 @@ def main() -> None: # Before anything else: uvicorn only configures its own loggers, so # without this the bot's own log lines go to logging.lastResort and # anything below WARNING is thrown away. - logging.basicConfig( - level=config.log_level, format="%(asctime)s %(levelname)s %(name)s: %(message)s" - ) + configure_logging(config.log_level) try: assert_port_free(config.bind_host, config.bind_port) except PortInUseError as exc: diff --git a/signal_bot/dispatcher.py b/signal_bot/dispatcher.py index 4b6e9de..71e9ffc 100644 --- a/signal_bot/dispatcher.py +++ b/signal_bot/dispatcher.py @@ -10,6 +10,7 @@ from dataclasses import dataclass from typing import TYPE_CHECKING from signal_bot.counting import should_count, watched_group +from signal_bot.envelope_shape import shape_of from signal_bot.models import parse_envelope from signal_bot.registry import CommandContext, CommandRegistry from signal_bot.stats.recorder import record_message @@ -38,6 +39,10 @@ class Dispatcher: async def handle(self, frame: str) -> None: """Process one raw websocket frame end to end.""" + # Keys and types only, never values -- see envelope_shape. This is + # how "what does a frame with an attachment look like?" gets answered + # without a code change and a lucky moment. + logger.debug("envelope shape: %s", shape_of(frame)) message = parse_envelope(frame) if message is None: return diff --git a/signal_bot/envelope_shape.py b/signal_bot/envelope_shape.py new file mode 100644 index 0000000..a165080 --- /dev/null +++ b/signal_bot/envelope_shape.py @@ -0,0 +1,60 @@ +# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence. +"""Describing an envelope's *shape* without logging what anybody wrote. + +`DOCS-signal-envelopes.md` exists because the wire format is not obvious and +guessing at it has cost this repo 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 problem 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 the bot can now say it itself, at DEBUG. What it emits is keys and value +*types*, never values -- with a small allowlist for the handful of fields that +are format, not content: a MIME type and a groupInfo type say nothing about +anybody. Message bodies, names, numbers, uuids, quoted text and sticker ids +are all reduced to their type. + + LOG_LEVEL=DEBUG, then: journalctl --user -u signal-bot | grep 'envelope shape' +""" + +from __future__ import annotations + +import json +from typing import Final + +# Fields whose value is a wire-format fact rather than anything a person said. +SAFE_VALUES: Final = frozenset({"contentType", "type"}) + + +def _describe(value: object, key: str = "") -> str: + """Render one value as its shape.""" + if isinstance(value, dict): + inner = ", ".join(f"{k}: {_describe(v, k)}" for k, v in sorted(value.items())) + return "{" + inner + "}" + if isinstance(value, list): + if not value: + return "[]" + # One entry is enough to show the element shape; a photo album would + # otherwise print the same dict twenty times. + return f"[{_describe(value[0])} x{len(value)}]" + if key in SAFE_VALUES and isinstance(value, str): + return repr(value) + if value is None: + return "null" + return type(value).__name__ + + +def shape_of(raw: str | bytes) -> str: + """Describe a raw frame as keys and types, or say why it could not be. + + Args: + raw: The JSON frame exactly as received. + + Returns: + A one-line description safe to write to a log. + """ + try: + decoded = json.loads(raw) + except json.JSONDecodeError, UnicodeDecodeError: + return "" + return _describe(decoded) diff --git a/signal_bot/logging_setup.py b/signal_bot/logging_setup.py new file mode 100644 index 0000000..587d8c1 --- /dev/null +++ b/signal_bot/logging_setup.py @@ -0,0 +1,41 @@ +# 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) diff --git a/tests/test_envelope_shape.py b/tests/test_envelope_shape.py new file mode 100644 index 0000000..3f5bd41 --- /dev/null +++ b/tests/test_envelope_shape.py @@ -0,0 +1,78 @@ +# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence. +"""Describing a frame's shape without logging what anybody wrote.""" + +from __future__ import annotations + +import json + +from signal_bot.envelope_shape import shape_of +from tests.conftest import WATCHED_GROUP, envelope + +PRIVATE_BODY = "the actual message body" + + +def test_values_are_replaced_by_their_types() -> None: + """The whole point: a log line that cannot leak a message.""" + shape = shape_of(envelope(text=PRIVATE_BODY)) + assert PRIVATE_BODY not in shape + assert "message: str" in shape + + +def test_names_numbers_and_uuids_do_not_survive() -> None: + shape = shape_of(envelope(text="hi", sender=("ffcae71a-dcd1", "kuhy"))) + assert "ffcae71a" not in shape + assert "kuhy" not in shape + assert "+15555550123" not in shape + + +def test_quoted_text_does_not_survive() -> None: + shape = shape_of(envelope(text="hi", extra="quote")) + assert "..." not in shape + assert "quote: {author: str, id: int, text: str}" in shape + + +def test_the_group_id_is_a_type_but_its_kind_is_a_value() -> None: + """DELIVER vs UPDATE is wire format; the id identifies a conversation.""" + shape = shape_of(envelope(text="hi")) + assert WATCHED_GROUP not in shape + assert "groupId: str" in shape + assert "type: 'DELIVER'" in shape + + +def test_attachment_content_types_are_kept() -> None: + """The one thing this exists to answer, so it must survive redaction.""" + shape = shape_of(envelope(text=None, attachments=("image/jpeg", "video/mp4"))) + assert "contentType: 'image/jpeg'" in shape + assert "x2]" in shape + + +def test_an_album_is_summarised_not_repeated() -> None: + shape = shape_of(envelope(text=None, attachments=("image/jpeg",) * 20)) + assert "x20]" in shape + assert shape.count("contentType") == 1 + + +def test_an_empty_list_is_shown_as_empty() -> None: + assert shape_of(json.dumps({"envelope": {"members": []}})) == "{envelope: {members: []}}" + + +def test_null_is_distinguished_from_absent() -> None: + """A caption-less photo may send message: null rather than omitting it.""" + assert "message: null" in shape_of(json.dumps({"envelope": {"message": None}})) + + +def test_numbers_and_booleans_show_their_type() -> None: + frame = json.dumps({"envelope": {"timestamp": 1, "urgent": True, "score": 1.5}}) + assert shape_of(frame) == "{envelope: {score: float, timestamp: int, urgent: bool}}" + + +def test_an_unparseable_frame_says_so() -> None: + assert shape_of("not json") == "" + assert shape_of(b"\xff\xfe") == "" + + +def test_keys_are_sorted_so_two_frames_compare() -> None: + """Same shape, different key order, identical description.""" + first = json.dumps({"envelope": {"b": 1, "a": "x"}}) + second = json.dumps({"envelope": {"a": "x", "b": 1}}) + assert shape_of(first) == shape_of(second) diff --git a/tests/test_logging_setup.py b/tests/test_logging_setup.py new file mode 100644 index 0000000..0c16381 --- /dev/null +++ b/tests/test_logging_setup.py @@ -0,0 +1,48 @@ +# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence. +"""DEBUG that stays readable: the bot's own loggers, not its libraries'.""" + +from __future__ import annotations + +import logging + +import pytest + +from signal_bot.logging_setup import NOISY, NOISY_FLOOR, configure + + +@pytest.fixture(autouse=True) +def _restore_levels() -> None: + """Put every logger this module touches back, so tests stay independent.""" + root = logging.getLogger().level + before = {name: logging.getLogger(name).level for name in NOISY} + yield + logging.getLogger().setLevel(root) + for name, level in before.items(): + logging.getLogger(name).setLevel(level) + + +def test_the_bots_own_level_is_what_was_asked_for() -> None: + configure("DEBUG") + assert logging.getLogger("signal_bot.dispatcher").getEffectiveLevel() == logging.DEBUG + + +def test_debug_does_not_turn_on_the_noisy_libraries() -> None: + """httpcore logs both ends of every connection, every 30 seconds.""" + configure("DEBUG") + for name in NOISY: + assert logging.getLogger(name).level == NOISY_FLOOR + + +def test_the_floor_applies_at_info_too() -> None: + """httpx logged one "HTTP Request" line per listing poll, at INFO.""" + logging.getLogger("httpx").setLevel(logging.NOTSET) + configure("INFO") + assert logging.getLogger("httpx").level == NOISY_FLOOR + assert logging.getLogger("signal_bot").getEffectiveLevel() == logging.INFO + + +def test_warnings_from_a_noisy_library_still_get_through() -> None: + """The floor is a floor, not a gag: a real httpx warning is worth seeing.""" + configure("DEBUG") + assert logging.getLogger("httpx").isEnabledFor(logging.WARNING) + assert not logging.getLogger("httpx").isEnabledFor(logging.INFO)