mirror of
https://github.com/kuhyx/wake-alarm.git
synced 2026-11-10 19:27:02 +01:00
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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01EckWmyfetYq3Mi8MAnUudh
This commit is contained in:
parent
4286fcb019
commit
f5cfc3e452
@ -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.
|
||||
|
||||
51
wake_alarm/_correlation.py
Normal file
51
wake_alarm/_correlation.py
Normal file
@ -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))
|
||||
109
wake_alarm/_log_dedupe.py
Normal file
109
wake_alarm/_log_dedupe.py
Normal file
@ -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
|
||||
104
wake_alarm/_log_sink.py
Normal file
104
wake_alarm/_log_sink.py
Normal file
@ -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
|
||||
@ -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
|
||||
|
||||
@ -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()
|
||||
|
||||
43
wake_alarm/tests/test_correlation.py
Normal file
43
wake_alarm/tests/test_correlation.py
Normal file
@ -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"
|
||||
117
wake_alarm/tests/test_log_dedupe.py
Normal file
117
wake_alarm/tests/test_log_dedupe.py
Normal file
@ -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)
|
||||
110
wake_alarm/tests/test_log_sink.py
Normal file
110
wake_alarm/tests/test_log_sink.py
Normal file
@ -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"
|
||||
113
wake_alarm/tests/test_logging_setup.py
Normal file
113
wake_alarm/tests/test_logging_setup.py
Normal file
@ -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
|
||||
Loading…
Reference in New Issue
Block a user