diff --git a/server/app.py b/server/app.py index 4e79793..d5955e1 100644 --- a/server/app.py +++ b/server/app.py @@ -23,6 +23,20 @@ from server.slots import build_today from server.stats import build_history, check_milestones, compute_stats, MILESTONE_DEFS NO_STORE = {"Cache-Control": "no-store"} + + +def _configure_logging() -> None: + fmt = logging.Formatter("%(levelname)s: %(message)s") + server_log = logging.getLogger("server") + if not server_log.handlers: + handler = logging.StreamHandler() + handler.setFormatter(fmt) + server_log.addHandler(handler) + server_log.setLevel(logging.INFO) + server_log.propagate = False + + +_configure_logging() logger = logging.getLogger(__name__) diff --git a/server/push.py b/server/push.py index 78850a2..044b802 100644 --- a/server/push.py +++ b/server/push.py @@ -1,6 +1,7 @@ from __future__ import annotations import json +import logging from typing import Any import aiosqlite @@ -9,6 +10,8 @@ from pywebpush import WebPushException, webpush from server.db import utc_now_iso from server.settings import settings +logger = logging.getLogger(__name__) + async def save_subscription(db: aiosqlite.Connection, sub: dict[str, Any]) -> None: keys = sub.get("keys", {}) @@ -34,20 +37,42 @@ def _vapid_claims() -> dict[str, str]: return {"sub": settings.vapid_claims_email} +def _endpoint_label(endpoint: str) -> str: + return endpoint[:60] + ("..." if len(endpoint) > 60 else "") + + async def send_push( db: aiosqlite.Connection, payload: dict[str, Any], ) -> int: + tag = payload.get("tag", "?") + slot_id = payload.get("slot_id", "?") + if not settings.vapid_private_key or not settings.vapid_public_key: + logger.warning("Push skipped slot=%s tag=%s reason=vapid_not_configured", slot_id, tag) return 0 subs = await get_subscriptions(db) + if not subs: + logger.warning("Push skipped slot=%s tag=%s reason=no_subscriptions", slot_id, tag) + return 0 + sent = 0 + failed = 0 dead: list[str] = [] + logger.info( + "Push start slot=%s tag=%s subscriptions=%d title=%r", + slot_id, + tag, + len(subs), + payload.get("title"), + ) + for sub in subs: + endpoint = sub["endpoint"] subscription = { - "endpoint": sub["endpoint"], + "endpoint": endpoint, "keys": {"p256dh": sub["p256dh"], "auth": sub["auth"]}, } try: @@ -58,15 +83,42 @@ async def send_push( vapid_claims=_vapid_claims(), ) sent += 1 + logger.info("Push ok slot=%s endpoint=%s", slot_id, _endpoint_label(endpoint)) except WebPushException as exc: - if exc.response and exc.response.status_code in (404, 410): - dead.append(sub["endpoint"]) + status = exc.response.status_code if exc.response else None + if status in (404, 410): + dead.append(endpoint) + logger.info( + "Push dead slot=%s endpoint=%s status=%s", + slot_id, + _endpoint_label(endpoint), + status, + ) + else: + failed += 1 + logger.warning( + "Push failed slot=%s endpoint=%s status=%s error=%s", + slot_id, + _endpoint_label(endpoint), + status, + exc, + ) for endpoint in dead: await db.execute("DELETE FROM push_subscription WHERE endpoint = ?", (endpoint,)) if dead: await db.commit() + logger.info("Push removed %d dead subscription(s)", len(dead)) + logger.info( + "Push done slot=%s tag=%s sent=%d failed=%d dead=%d total=%d", + slot_id, + tag, + sent, + failed, + len(dead), + len(subs), + ) return sent diff --git a/server/scheduler.py b/server/scheduler.py index a21ca0f..0e73f5a 100644 --- a/server/scheduler.py +++ b/server/scheduler.py @@ -4,6 +4,7 @@ import asyncio import logging from datetime import datetime, timedelta +from apscheduler.events import EVENT_JOB_ERROR, EVENT_JOB_EXECUTED, EVENT_JOB_MISSED from apscheduler.schedulers.asyncio import AsyncIOScheduler from apscheduler.triggers.cron import CronTrigger from apscheduler.triggers.date import DateTrigger @@ -23,17 +24,21 @@ async def _remind_slot(slot_id: str) -> None: config = load_meds_config() tz = config.timezone day = today_str(tz) + logger.info("Reminder triggered slot=%s day=%s", slot_id, day) db = await get_db() try: logs = await get_log_for_day(db, day) if slot_id in logs and logs[slot_id]["status"] == "taken": + logger.info("Reminder skipped slot=%s day=%s reason=already_taken", slot_id, day) return slot = next((s for s in config.slots if s.id == slot_id), None) if not slot: + logger.warning("Reminder skipped slot=%s day=%s reason=unknown_slot", slot_id, day) return title = f"{slot.label} — Med-Time!" body = pick("reminder", label=slot.label, med=slot.meds[0].name if slot.meds else "Medis") - await send_slot_reminder(db, slot_id, title, body) + sent = await send_slot_reminder(db, slot_id, title, body) + logger.info("Reminder finished slot=%s day=%s sent=%d", slot_id, day, sent) finally: await db.close() @@ -61,12 +66,18 @@ async def _generate_daily_oracle() -> None: async def _evening_check() -> None: + logger.info("Evening check triggered") db = await get_db() try: marked = await mark_missed_for_overdue(db) + if not marked: + logger.info("Evening check done marked=0") + return + logger.info("Evening check marked missed slots=%s", ",".join(marked)) for slot_id in marked: body = pick("missed") - await send_slot_reminder(db, slot_id, "Verpasst?", body) + sent = await send_slot_reminder(db, slot_id, "Verpasst?", body) + logger.info("Evening reminder slot=%s sent=%d", slot_id, sent) finally: await db.close() @@ -102,10 +113,26 @@ async def schedule_snooze(slot_id: str, minutes: int) -> str: return until.isoformat() +def _scheduler_listener(event) -> None: + if event.code == EVENT_JOB_MISSED: + logger.warning( + "Scheduler job missed id=%s scheduled=%s", + event.job_id, + event.scheduled_run_time, + ) + elif event.code == EVENT_JOB_ERROR: + logger.exception("Scheduler job error id=%s", event.job_id) + elif event.code == EVENT_JOB_EXECUTED: + logger.info("Scheduler job executed id=%s", event.job_id) + + def start_scheduler() -> None: config = load_meds_config() tz = config.timezone + if not scheduler.running: + scheduler.add_listener(_scheduler_listener, EVENT_JOB_EXECUTED | EVENT_JOB_MISSED | EVENT_JOB_ERROR) + for slot in config.slots: h, m = slot.time.hour, slot.time.minute scheduler.add_job( @@ -115,6 +142,7 @@ def start_scheduler() -> None: id=f"remind-{slot.id}", replace_existing=True, ) + logger.info("Registered remind job slot=%s at %02d:%02d %s", slot.id, h, m, tz) scheduler.add_job( _evening_check, @@ -140,3 +168,5 @@ def start_scheduler() -> None: if not scheduler.running: scheduler.start() logger.info("Scheduler started for timezone %s", tz) + for job in scheduler.get_jobs(): + logger.info("Scheduler job id=%s next=%s", job.id, job.next_run_time)