From f5cfc3e452aff28252595a9f7b5a98987d3253c8 Mon Sep 17 00:00:00 2001 From: Krzysztof kuhy Rudnicki Date: Wed, 26 Aug 2026 23:00:08 +0200 Subject: [PATCH] Phase 1: structured JSONL logging with cross-process dedupe Adds the diagnostic substrate the rest of the hardening work builds on. A 6am failure should be reconstructable afterwards instead of re-debugged. Two sinks, deliberately. stderr -> journal is unchanged. Alongside it, one JSON object per line in ~/.local/state/wake_alarm/events.jsonl, so a morning can be replayed with jq. The hard constraint is that _trigger is a fresh process every 60 seconds, so an in-memory rate limiter would reset on every tick and suppress nothing. _log_dedupe therefore persists the last emitted fingerprint to disk and flushes a suppressed_repeats count onto the next distinct record. Verified across separate processes: 4 invocations logging the same routine event produce 1 record plus an accurate count of 3. That is what satisfies the standing "do not raise the level of _sync's degraded-read paths" rule by construction, rather than by keeping levels artificially low and losing the signal. The correlation id is derived, never generated: both halves compute wake-YYYYMMDD-HHMM from the resolved alarm instant, so the PC and the phone agree with no handshake and no uuid exchange -- which matters precisely when sync is down. Logging never raises. An unwritable sink degrades to journal-only. _alarm.py and _sync.py keep the default component= for now; tagging them means splitting them for the 250-line gate, which belongs in the phases that actually restructure those files. 389 tests pass, 100% branch coverage held. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01EckWmyfetYq3Mi8MAnUudh --- wake_alarm/_constants.py | 10 +++ wake_alarm/_correlation.py | 51 +++++++++++ wake_alarm/_log_dedupe.py | 109 +++++++++++++++++++++++ wake_alarm/_log_sink.py | 104 ++++++++++++++++++++++ wake_alarm/_logging_setup.py | 92 +++++++++++++++++-- wake_alarm/_trigger.py | 2 +- wake_alarm/tests/test_correlation.py | 43 +++++++++ wake_alarm/tests/test_log_dedupe.py | 117 +++++++++++++++++++++++++ wake_alarm/tests/test_log_sink.py | 110 +++++++++++++++++++++++ wake_alarm/tests/test_logging_setup.py | 113 ++++++++++++++++++++++++ 10 files changed, 743 insertions(+), 8 deletions(-) create mode 100644 wake_alarm/_correlation.py create mode 100644 wake_alarm/_log_dedupe.py create mode 100644 wake_alarm/_log_sink.py create mode 100644 wake_alarm/tests/test_correlation.py create mode 100644 wake_alarm/tests/test_log_dedupe.py create mode 100644 wake_alarm/tests/test_log_sink.py create mode 100644 wake_alarm/tests/test_logging_setup.py diff --git a/wake_alarm/_constants.py b/wake_alarm/_constants.py index 7e42db3..554da72 100644 --- a/wake_alarm/_constants.py +++ b/wake_alarm/_constants.py @@ -92,6 +92,16 @@ SYNC_TOKEN_FALLBACK_FILES: tuple[Path, ...] = ( # Where a successful read is cached, so a network blip can't cost a wake-up. ALARM_CACHE_FILE: Path = Path.home() / ".config" / "wake_alarm" / "alarm_cache.json" +# Structured logs live under XDG state, not .config: they are churning runtime +# data, not configuration. The JSONL file is additive -- the journal keeps +# receiving the same records via stderr. +LOG_STATE_DIR: Path = Path.home() / ".local" / "state" / "wake_alarm" +LOG_JSONL_FILE: Path = LOG_STATE_DIR / "events.jsonl" + +# Fingerprint of the last emitted event, so consecutive duplicates can be +# suppressed across separate per-minute trigger processes. +LOG_DEDUPE_FILE: Path = LOG_STATE_DIR / "last_event.json" + # The phone's path to its published alarm. Deliberately the *same* logical # path on both backends — Firebase's namespace mirrors the repo layout — so # only the transport changes, never the parse. diff --git a/wake_alarm/_correlation.py b/wake_alarm/_correlation.py new file mode 100644 index 0000000..47f0bb3 --- /dev/null +++ b/wake_alarm/_correlation.py @@ -0,0 +1,51 @@ +"""Derive the identifier that joins one morning's PC and phone log lines. + +The id is **derived, never generated**: both halves compute it independently +from the resolved alarm instant, so no handshake, no uuid exchange and no +network round-trip is involved. That matters because the two devices must +still agree when sync is down -- which is exactly when the logs are worth +reading. + +Local time, matching ``_trigger``'s local-time basis (``_state.py`` keys by +UTC, which is a separate known mismatch tracked in the hardening plan). +""" + +from __future__ import annotations + +from typing import TYPE_CHECKING + +if TYPE_CHECKING: + from datetime import datetime + +# ``wake-YYYYMMDD-HHMM``. Stable across processes and across devices. +_CORRELATION_FORMAT = "wake-%Y%m%d-%H%M" + + +def correlation_id(fire_time: datetime) -> str: + """Build the correlation id for the alarm firing at *fire_time*. + + Args: + fire_time: The resolved local fire instant for today's alarm. + + Returns: + A string of the form ``wake-20260826-0700``. + """ + return fire_time.strftime(_CORRELATION_FORMAT) + + +def correlation_id_for(hour: int, minute: int, *, now: datetime) -> str: + """Build the correlation id from an ``(hour, minute)`` alarm on *now*'s date. + + Convenience for callers that hold the synced alarm rather than a resolved + datetime. The date comes from *now*, so a caller must pass the date the + alarm belongs to, not merely the current instant. + + Args: + hour: Alarm hour, 0-23. + minute: Alarm minute, 0-59. + now: Any datetime on the alarm's local date. + + Returns: + The correlation id string. + """ + return correlation_id(now.replace(hour=hour, minute=minute)) diff --git a/wake_alarm/_log_dedupe.py b/wake_alarm/_log_dedupe.py new file mode 100644 index 0000000..81fb693 --- /dev/null +++ b/wake_alarm/_log_dedupe.py @@ -0,0 +1,109 @@ +"""Suppress consecutive identical events across *separate processes*. + +``_trigger`` is a fresh process every 60 seconds, so an in-memory rate limiter +would reset on every tick and suppress nothing. The fingerprint of the last +emitted event therefore lives on disk. + +This is what lets the routine paths log at all without producing 1440 identical +journal lines a day, and it satisfies the standing "do not raise the level of +_sync's degraded-read paths" rule *by construction* rather than by keeping +levels artificially low. When a run of duplicates finally breaks, the next +distinct record carries ``suppressed_repeats`` so nothing is silently lost. +""" + +from __future__ import annotations + +import hashlib +import json +import logging +from typing import TYPE_CHECKING + +if TYPE_CHECKING: + from pathlib import Path + +# Records carrying this attribute participate in dedupe; others always pass. +DEDUPE_ATTR = "dedupe_key" +REPEATS_FIELD = "suppressed_repeats" + + +def _fingerprint(key: str, level: int) -> str: + """Hash the dedupe key and level into a short stable digest. + + Args: + key: Caller-supplied dedupe key. + level: Numeric log level. + + Returns: + A hex digest identifying this event shape. + """ + return hashlib.sha256(f"{level}:{key}".encode()).hexdigest()[:16] + + +class DedupeFilter(logging.Filter): + """Drop a record whose dedupe key matches the previously emitted one.""" + + def __init__(self, state_file: Path) -> None: + """Initialise the filter. + + Args: + state_file: Where the last-emitted fingerprint is persisted. + """ + super().__init__() + self._state_file = state_file + + def _read(self) -> tuple[str, int]: + """Read the stored fingerprint and repeat count. + + Returns: + The fingerprint and how many duplicates have been suppressed. + """ + try: + raw = json.loads(self._state_file.read_text(encoding="utf-8")) + except (OSError, ValueError): + return "", 0 + if not isinstance(raw, dict): + return "", 0 + digest = raw.get("digest") + count = raw.get("count") + if not isinstance(digest, str) or not isinstance(count, int): + return "", 0 + return digest, count + + def _write(self, digest: str, count: int) -> None: + """Persist the fingerprint and repeat count, ignoring IO errors. + + Args: + digest: Fingerprint of the last emitted record. + count: Number of duplicates suppressed since it was emitted. + """ + try: + self._state_file.parent.mkdir(parents=True, exist_ok=True) + self._state_file.write_text( + json.dumps({"digest": digest, "count": count}), + encoding="utf-8", + ) + except OSError: + # Logging must never be the thing that breaks the alarm. + pass + + def filter(self, record: logging.LogRecord) -> bool: + """Decide whether *record* should be emitted. + + Args: + record: The candidate record. + + Returns: + True to emit, False to suppress as a duplicate. + """ + key = getattr(record, DEDUPE_ATTR, None) + if not isinstance(key, str): + return True + digest = _fingerprint(key, record.levelno) + previous, count = self._read() + if digest == previous: + self._write(digest, count + 1) + return False + if count: + setattr(record, REPEATS_FIELD, count) + self._write(digest, 0) + return True diff --git a/wake_alarm/_log_sink.py b/wake_alarm/_log_sink.py new file mode 100644 index 0000000..9b61a69 --- /dev/null +++ b/wake_alarm/_log_sink.py @@ -0,0 +1,104 @@ +"""JSONL log sink: machine-readable events alongside the human journal. + +The journal (stderr -> systemd) stays exactly as it was; this is *additive*. +Every record is one JSON object on one line, so a failed wake-up can be +reconstructed with ``jq`` instead of re-derived by hand: + + jq 'select(.corr == "wake-20260826-0700")' ~/.local/state/wake_alarm/events.jsonl + +Extra keyword arguments passed to a logging call via ``extra={"fields": {...}}`` +are merged into the record, so callers add structure without a bespoke API. +""" + +from __future__ import annotations + +import json +import logging +from logging.handlers import RotatingFileHandler +from typing import TYPE_CHECKING, Any + +if TYPE_CHECKING: + from pathlib import Path + +# Attribute names ``logging`` sets on every record; anything else in __dict__ +# came from the caller's ``extra=`` and belongs in the payload. +_RESERVED = frozenset( + { + "args", + "asctime", + "created", + "exc_info", + "exc_text", + "filename", + "funcName", + "levelname", + "levelno", + "lineno", + "message", + "module", + "msecs", + "msg", + "name", + "pathname", + "process", + "processName", + "relativeCreated", + "stack_info", + "taskName", + "thread", + "threadName", + }, +) + +MAX_BYTES = 5 * 1024 * 1024 +BACKUP_COUNT = 5 + + +class JsonlFormatter(logging.Formatter): + """Render a log record as a single-line JSON object.""" + + def format(self, record: logging.LogRecord) -> str: + """Serialise *record* as compact JSON. + + Args: + record: The record to render. + + Returns: + One line of JSON, no trailing newline. + """ + payload: dict[str, Any] = { + "ts": self.formatTime(record, "%Y-%m-%dT%H:%M:%S%z"), + "level": record.levelname, + "logger": record.name, + "msg": record.getMessage(), + } + payload.update( + { + key: value + for key, value in record.__dict__.items() + if key not in _RESERVED and not key.startswith("_") + }, + ) + if record.exc_info: + payload["exc"] = self.formatException(record.exc_info) + return json.dumps(payload, default=repr, sort_keys=True) + + +def build_handler(path: Path) -> RotatingFileHandler: + """Create the rotating JSONL handler writing to *path*. + + Args: + path: Destination file; its parent is created if absent. + + Returns: + A configured handler, ready to attach to the root logger. + """ + path.parent.mkdir(parents=True, exist_ok=True) + handler = RotatingFileHandler( + path, + maxBytes=MAX_BYTES, + backupCount=BACKUP_COUNT, + encoding="utf-8", + ) + handler.setFormatter(JsonlFormatter()) + return handler diff --git a/wake_alarm/_logging_setup.py b/wake_alarm/_logging_setup.py index d7b4ea0..231d1c8 100644 --- a/wake_alarm/_logging_setup.py +++ b/wake_alarm/_logging_setup.py @@ -1,13 +1,91 @@ -"""Logging configuration for the wake_alarm entry point.""" +"""Logging configuration for the wake_alarm entry points. + +Two sinks, deliberately: + +* **stderr -> journal** -- unchanged, human-readable, what ``journalctl`` shows. +* **JSONL file** -- machine-readable, greppable with ``jq``, so a failed + wake-up can be reconstructed after the fact instead of re-debugged. + +The JSONL handler carries a cross-process dedupe filter (see ``_log_dedupe``) +because ``_trigger`` runs as a fresh process every minute; without it, "log +everywhere" would mean 1440 identical lines a day. + +Configuration never raises: a logging failure must not be the reason an alarm +does not go off. +""" from __future__ import annotations import logging +from wake_alarm._constants import LOG_DEDUPE_FILE, LOG_JSONL_FILE +from wake_alarm._log_dedupe import DedupeFilter +from wake_alarm._log_sink import build_handler -def configure_logging() -> None: - """Configure root logging with the standard daemon format and level.""" - logging.basicConfig( - level=logging.INFO, - format="%(asctime)s %(name)s %(levelname)s %(message)s", - ) +_STDERR_FORMAT = "%(asctime)s %(name)s %(levelname)s %(message)s" + +# Marks the handler we own, so a second call is a no-op rather than a +# duplicate sink (main() runs once per process, but --demo and tests re-enter). +_HANDLER_FLAG = "_wake_alarm_jsonl" + + +def _already_attached(root: logging.Logger) -> bool: + """Report whether the JSONL handler is already installed. + + Args: + root: The root logger to inspect. + + Returns: + True if a previous call already attached the handler. + """ + return any(getattr(h, _HANDLER_FLAG, False) for h in root.handlers) + + +def configure_logging(*, component: str = "wake_alarm") -> None: + """Configure the daemon log format plus the structured JSONL sink. + + Args: + component: Name recorded on every JSONL record, identifying which + entry point emitted it (``alarm``, ``trigger``, ``sync``). + """ + logging.basicConfig(level=logging.INFO, format=_STDERR_FORMAT) + root = logging.getLogger() + if _already_attached(root): + return + try: + handler = build_handler(LOG_JSONL_FILE) + except OSError: + # No structured log is survivable; a crash here is not. + logging.getLogger(__name__).info( + "structured log unavailable; journal only", + ) + return + handler.addFilter(DedupeFilter(LOG_DEDUPE_FILE)) + handler.addFilter(_ComponentFilter(component)) + setattr(handler, _HANDLER_FLAG, True) + root.addHandler(handler) + + +class _ComponentFilter(logging.Filter): + """Stamp every record with the entry point that produced it.""" + + def __init__(self, component: str) -> None: + """Initialise the filter. + + Args: + component: Value to set on each record. + """ + super().__init__() + self._component = component + + def filter(self, record: logging.LogRecord) -> bool: + """Attach the component name to *record*. + + Args: + record: The record being emitted. + + Returns: + Always True; this filter annotates rather than excludes. + """ + record.component = self._component + return True diff --git a/wake_alarm/_trigger.py b/wake_alarm/_trigger.py index 56d0957..ec618bf 100644 --- a/wake_alarm/_trigger.py +++ b/wake_alarm/_trigger.py @@ -164,7 +164,7 @@ def _parse_args(argv: list[str]) -> argparse.Namespace: def main() -> None: """Entry point for one timer tick.""" - configure_logging() + configure_logging(component="trigger") args = _parse_args(sys.argv[1:]) now = _now() diff --git a/wake_alarm/tests/test_correlation.py b/wake_alarm/tests/test_correlation.py new file mode 100644 index 0000000..65ea7e5 --- /dev/null +++ b/wake_alarm/tests/test_correlation.py @@ -0,0 +1,43 @@ +"""Tests for the derived correlation id.""" + +from __future__ import annotations + +from datetime import datetime + +from wake_alarm._correlation import correlation_id, correlation_id_for + + +def _local(year: int, month: int, day: int, hour: int, minute: int) -> datetime: + """Build an aware local datetime, matching the idiom in test_trigger.py.""" + return datetime(year, month, day, hour, minute, tzinfo=None).astimezone() + + +def test_correlation_id_formats_local_instant() -> None: + """The id encodes the local date and the alarm's wall-clock time.""" + assert correlation_id(_local(2026, 8, 26, 7, 0)) == "wake-20260826-0700" + + +def test_correlation_id_pads_single_digits() -> None: + """Single-digit months, days, hours and minutes are zero padded.""" + assert correlation_id(_local(2026, 1, 2, 3, 4)) == "wake-20260102-0304" + + +def test_correlation_id_is_stable_for_the_same_instant() -> None: + """Two independent computations agree, which is the whole point.""" + moment = _local(2026, 12, 31, 23, 59) + assert correlation_id(moment) == correlation_id(moment) + + +def test_correlation_id_for_uses_the_date_of_now() -> None: + """The (hour, minute) form takes its date from the supplied instant.""" + assert ( + correlation_id_for(7, 30, now=_local(2026, 8, 26, 22, 15)) + == "wake-20260826-0730" + ) + + +def test_correlation_id_for_ignores_the_time_of_now() -> None: + """Only *now*'s date matters; its own time is replaced.""" + early = correlation_id_for(6, 0, now=_local(2026, 8, 26, 1, 2)) + late = correlation_id_for(6, 0, now=_local(2026, 8, 26, 23, 58)) + assert early == late == "wake-20260826-0600" diff --git a/wake_alarm/tests/test_log_dedupe.py b/wake_alarm/tests/test_log_dedupe.py new file mode 100644 index 0000000..4c5ac01 --- /dev/null +++ b/wake_alarm/tests/test_log_dedupe.py @@ -0,0 +1,117 @@ +"""Tests for cross-process consecutive-event suppression.""" + +from __future__ import annotations + +import json +import logging +from typing import TYPE_CHECKING + +import pytest + +from wake_alarm._log_dedupe import REPEATS_FIELD, DedupeFilter + +if TYPE_CHECKING: + from pathlib import Path + + +def _record( + msg: str, *, key: str | None = None, level: int = logging.INFO +) -> logging.LogRecord: + """Build a log record, optionally carrying a dedupe key.""" + record = logging.LogRecord("t", level, __file__, 1, msg, None, None) + if key is not None: + record.dedupe_key = key + return record + + +def test_record_without_key_always_passes(tmp_path: Path) -> None: + """Only records that opt in are ever suppressed.""" + dedupe = DedupeFilter(tmp_path / "s.json") + assert dedupe.filter(_record("a")) is True + assert dedupe.filter(_record("a")) is True + + +def test_non_string_key_passes(tmp_path: Path) -> None: + """A malformed key is ignored rather than crashing the logger.""" + dedupe = DedupeFilter(tmp_path / "s.json") + record = _record("a") + record.dedupe_key = 42 + assert dedupe.filter(record) is True + + +def test_first_record_passes_and_duplicate_is_suppressed(tmp_path: Path) -> None: + """The first of a run is emitted; the rest are dropped.""" + dedupe = DedupeFilter(tmp_path / "s.json") + assert dedupe.filter(_record("a", key="idle")) is True + assert dedupe.filter(_record("a", key="idle")) is False + + +def test_distinct_key_passes_and_carries_the_count(tmp_path: Path) -> None: + """Breaking a run surfaces how many duplicates were suppressed.""" + dedupe = DedupeFilter(tmp_path / "s.json") + dedupe.filter(_record("a", key="idle")) + for _ in range(3): + dedupe.filter(_record("a", key="idle")) + record = _record("b", key="fired") + assert dedupe.filter(record) is True + assert getattr(record, REPEATS_FIELD) == 3 + + +def test_no_count_attached_when_nothing_was_suppressed(tmp_path: Path) -> None: + """A clean transition does not add a zero-valued field.""" + dedupe = DedupeFilter(tmp_path / "s.json") + dedupe.filter(_record("a", key="one")) + record = _record("b", key="two") + assert dedupe.filter(record) is True + assert not hasattr(record, REPEATS_FIELD) + + +def test_same_key_at_a_different_level_is_not_a_duplicate(tmp_path: Path) -> None: + """Level is part of the fingerprint: an escalation must not be swallowed.""" + dedupe = DedupeFilter(tmp_path / "s.json") + assert dedupe.filter(_record("a", key="k")) is True + assert dedupe.filter(_record("a", key="k", level=logging.WARNING)) is True + + +def test_state_persists_across_filter_instances(tmp_path: Path) -> None: + """A fresh process (new filter, same file) still suppresses the duplicate.""" + state = tmp_path / "s.json" + assert DedupeFilter(state).filter(_record("a", key="idle")) is True + assert DedupeFilter(state).filter(_record("a", key="idle")) is False + + +@pytest.mark.parametrize( + "payload", ["not json", '"a string"', '{"digest": 1}', '{"count": "x"}'] +) +def test_corrupt_state_is_treated_as_empty(tmp_path: Path, payload: str) -> None: + """A damaged state file must not suppress a record or raise.""" + state = tmp_path / "s.json" + state.write_text(payload, encoding="utf-8") + assert DedupeFilter(state).filter(_record("a", key="idle")) is True + + +def test_missing_state_file_is_treated_as_empty(tmp_path: Path) -> None: + """A first-ever run has no state file and must still emit.""" + assert DedupeFilter(tmp_path / "absent.json").filter(_record("a", key="k")) is True + + +def test_unwritable_state_does_not_raise(tmp_path: Path) -> None: + """Logging must never be the thing that breaks the alarm.""" + state = tmp_path / "sub" / "s.json" + state.parent.mkdir() + state.parent.chmod(0o500) + try: + assert DedupeFilter(state).filter(_record("a", key="k")) is True + finally: + state.parent.chmod(0o700) + + +def test_state_file_records_the_digest_and_count(tmp_path: Path) -> None: + """The persisted shape is what a later process expects to read.""" + state = tmp_path / "s.json" + dedupe = DedupeFilter(state) + dedupe.filter(_record("a", key="idle")) + dedupe.filter(_record("a", key="idle")) + stored = json.loads(state.read_text(encoding="utf-8")) + assert stored["count"] == 1 + assert isinstance(stored["digest"], str) diff --git a/wake_alarm/tests/test_log_sink.py b/wake_alarm/tests/test_log_sink.py new file mode 100644 index 0000000..1cb5e14 --- /dev/null +++ b/wake_alarm/tests/test_log_sink.py @@ -0,0 +1,110 @@ +"""Tests for the JSONL log sink.""" + +from __future__ import annotations + +import json +import logging +import sys +from typing import TYPE_CHECKING + +from wake_alarm._log_sink import BACKUP_COUNT, MAX_BYTES, JsonlFormatter, build_handler + +if TYPE_CHECKING: + from pathlib import Path + + +def _record(msg: str = "hello", *, level: int = logging.INFO) -> logging.LogRecord: + """Build a plain log record.""" + return logging.LogRecord("wake_alarm.t", level, __file__, 7, msg, None, None) + + +def test_format_emits_single_line_json() -> None: + """One record renders as exactly one parseable JSON line.""" + rendered = JsonlFormatter().format(_record()) + assert "\n" not in rendered + assert json.loads(rendered)["msg"] == "hello" + + +def test_format_includes_core_fields() -> None: + """Level, logger and timestamp are always present.""" + payload = json.loads(JsonlFormatter().format(_record(level=logging.WARNING))) + assert payload["level"] == "WARNING" + assert payload["logger"] == "wake_alarm.t" + assert payload["ts"] + + +def test_format_interpolates_arguments() -> None: + """``%s`` style arguments are rendered, not left raw.""" + record = logging.LogRecord("t", logging.INFO, __file__, 1, "hi %s", ("bob",), None) + assert json.loads(JsonlFormatter().format(record))["msg"] == "hi bob" + + +def test_format_merges_extra_fields() -> None: + """Caller supplied ``extra=`` keys become top-level payload fields.""" + record = _record() + record.corr = "wake-20260826-0700" + assert json.loads(JsonlFormatter().format(record))["corr"] == "wake-20260826-0700" + + +def test_format_skips_private_attributes() -> None: + """Underscore-prefixed attributes stay out of the payload.""" + record = _record() + record._hidden = "no" + assert "_hidden" not in json.loads(JsonlFormatter().format(record)) + + +def test_format_renders_unserialisable_values() -> None: + """A value JSON cannot encode falls back to repr instead of raising.""" + record = _record() + record.thing = object() + assert "object" in json.loads(JsonlFormatter().format(record))["thing"] + + +def test_format_includes_exception_text() -> None: + """An exc_info record carries the traceback under ``exc``.""" + + def _raise() -> None: + msg = "boom" + raise ValueError(msg) + + try: + _raise() + except ValueError: + record = logging.LogRecord( + "t", + logging.ERROR, + __file__, + 1, + "failed", + None, + sys.exc_info(), + ) + assert "ValueError" in json.loads(JsonlFormatter().format(record))["exc"] + + +def test_build_handler_creates_parent_directory(tmp_path: Path) -> None: + """The state directory is created on demand.""" + target = tmp_path / "deep" / "nested" / "events.jsonl" + build_handler(target).close() + assert target.parent.is_dir() + + +def test_build_handler_is_configured_for_rotation(tmp_path: Path) -> None: + """Rotation bounds are applied so the log cannot grow without limit.""" + handler = build_handler(tmp_path / "e.jsonl") + try: + assert handler.maxBytes == MAX_BYTES + assert handler.backupCount == BACKUP_COUNT + finally: + handler.close() + + +def test_handler_writes_a_parseable_line(tmp_path: Path) -> None: + """End to end: emitting through the handler yields valid JSONL.""" + target = tmp_path / "e.jsonl" + handler = build_handler(target) + try: + handler.emit(_record("written")) + finally: + handler.close() + assert json.loads(target.read_text(encoding="utf-8").strip())["msg"] == "written" diff --git a/wake_alarm/tests/test_logging_setup.py b/wake_alarm/tests/test_logging_setup.py new file mode 100644 index 0000000..a037906 --- /dev/null +++ b/wake_alarm/tests/test_logging_setup.py @@ -0,0 +1,113 @@ +"""Tests for wiring the journal and JSONL sinks together.""" + +from __future__ import annotations + +import json +import logging +from typing import TYPE_CHECKING + +import pytest + +from wake_alarm import _logging_setup +from wake_alarm._logging_setup import configure_logging + +if TYPE_CHECKING: + from collections.abc import Iterator + from pathlib import Path + + +@pytest.fixture(autouse=True) +def log_dir(tmp_path: Path, monkeypatch: pytest.MonkeyPatch) -> Iterator[Path]: + """Point the sink at a temp dir and restore root handlers afterwards. + + Without this a test would attach a real handler to the process-wide root + logger and write into the developer's own state directory. + """ + monkeypatch.setattr(_logging_setup, "LOG_JSONL_FILE", tmp_path / "events.jsonl") + monkeypatch.setattr(_logging_setup, "LOG_DEDUPE_FILE", tmp_path / "last.json") + root = logging.getLogger() + original = list(root.handlers) + # pytest's logging plugin pins the root level; basicConfig() cannot lower + # it once handlers exist, so INFO records would be filtered before reaching + # our sink. Force it, and restore afterwards. + original_level = root.level + root.setLevel(logging.INFO) + # Another module's test may already have installed our handler on the + # process-wide root logger, which would make configure_logging() a no-op + # here. Detach any such handler so each test starts from a clean root. + stashed = [h for h in original if getattr(h, "_wake_alarm_jsonl", False)] + for handler in stashed: + root.removeHandler(handler) + yield tmp_path + root.setLevel(original_level) + for handler in stashed: + root.addHandler(handler) + for handler in list(root.handlers): + if handler not in original: + handler.close() + root.removeHandler(handler) + + +def _flush() -> None: + """Flush root handlers so the JSONL file reflects what was emitted.""" + for handler in logging.getLogger().handlers: + handler.flush() + + +def test_configure_attaches_the_jsonl_handler() -> None: + """A structured handler is installed alongside the stderr one.""" + before = len(logging.getLogger().handlers) + configure_logging(component="alarm") + assert len(logging.getLogger().handlers) > before + + +def test_records_reach_the_jsonl_file(log_dir: Path) -> None: + """An ordinary log call lands in the structured file.""" + configure_logging(component="alarm") + logging.getLogger("wake_alarm.t").warning("ALARM TRIGGERED") + _flush() + written = (log_dir / "events.jsonl").read_text(encoding="utf-8") + assert json.loads(written.strip())["msg"] == "ALARM TRIGGERED" + + +def test_component_is_stamped_on_every_record(log_dir: Path) -> None: + """Records identify which entry point produced them.""" + configure_logging(component="trigger") + logging.getLogger("wake_alarm.t").info("tick") + _flush() + payload = json.loads((log_dir / "events.jsonl").read_text().strip()) + assert payload["component"] == "trigger" + + +def test_second_call_does_not_duplicate_the_handler() -> None: + """Re-entry (``--demo``, tests) must not double every line.""" + configure_logging(component="alarm") + count = len(logging.getLogger().handlers) + configure_logging(component="alarm") + assert len(logging.getLogger().handlers) == count + + +def test_dedupe_filter_is_active(log_dir: Path) -> None: + """Consecutive identical routine events collapse to one line.""" + configure_logging(component="trigger") + log = logging.getLogger("wake_alarm.t") + for _ in range(4): + log.info("idle", extra={"dedupe_key": "idle"}) + _flush() + lines = (log_dir / "events.jsonl").read_text().strip().splitlines() + assert len(lines) == 1 + + +def test_unwritable_destination_degrades_to_journal_only( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """A failing sink must not stop the alarm from running.""" + + def _boom(_path: Path) -> None: + msg = "read-only" + raise OSError(msg) + + monkeypatch.setattr(_logging_setup, "build_handler", _boom) + before = len(logging.getLogger().handlers) + configure_logging(component="alarm") + assert len(logging.getLogger().handlers) == before