diff --git a/main.py b/main.py index 4f6d664..1288b0e 100644 --- a/main.py +++ b/main.py @@ -29,7 +29,7 @@ from modules import packager from modules import processor from modules import scheduler from modules import tools -from modules.logger import get_logger, tail_log +from modules.logger import get_logger, configure_logging, tail_log log = get_logger(__name__) app = typer.Typer(add_completion=False, pretty_exceptions_show_locals=False) @@ -52,9 +52,12 @@ def main( status: bool = typer.Option(False, "--status", help="Print status summary and exit."), logs: bool = typer.Option(False, "--logs", help="Tail the log file and exit."), change_config: bool = typer.Option(False, "--config", help="Change a config value."), + debug: bool = typer.Option(False, "--debug", help="Show all debug output on the console."), ) -> None: global _master_password + configure_logging(debug=debug) + if setup: _run_setup() return @@ -139,8 +142,22 @@ def _start_service(run_now: bool = False) -> None: scheduler.start(sync, interval) + # Auto-run if this is the first sync ever, or the last one was overdue if run_now: scheduler.run_now(sync) + else: + last = database.get_last_sync_time() + if last is None: + log.info("No previous sync found — running immediately.") + scheduler.run_now(sync) + else: + elapsed_min = (datetime.now(timezone.utc) - last).total_seconds() / 60 + if elapsed_min >= interval: + log.info( + "Last sync was %.0f minute(s) ago (interval: %d min) — running immediately.", + elapsed_min, interval, + ) + scheduler.run_now(sync) log.info("MailRelay running. Press Ctrl+C to stop.") @@ -218,6 +235,8 @@ def _sync_cycle(conf: dict) -> None: except Exception as exc: log.error("Unexpected error in sync cycle: %s", exc, exc_info=True) summary["error"] = str(exc) + else: + database.record_sync_time() finally: summary["finished_at"] = datetime.now(timezone.utc).isoformat() _last_run = summary diff --git a/modules/database.py b/modules/database.py index e8ee070..f959105 100644 --- a/modules/database.py +++ b/modules/database.py @@ -2,8 +2,9 @@ import sqlite3 from contextlib import contextmanager +from datetime import datetime, timezone from pathlib import Path -from typing import Generator, Iterable +from typing import Generator, Iterable, Optional DB_PATH = Path(__file__).parent.parent / "data" / "mailrelay.db" @@ -48,6 +49,12 @@ def init_db() -> None: conn.execute(""" CREATE INDEX IF NOT EXISTS idx_state ON messages(state) """) + conn.execute(""" + CREATE TABLE IF NOT EXISTS metadata ( + key TEXT PRIMARY KEY, + value TEXT NOT NULL + ) + """) def is_known(message_id: str) -> bool: @@ -127,6 +134,28 @@ def get_pending_mboxes() -> list[dict]: return [{"mbox_path": path, "message_ids": ids} for path, ids in by_path.items()] +def get_last_sync_time() -> Optional[datetime]: + """Return the UTC timestamp of the last completed sync, or None.""" + with _db() as conn: + row = conn.execute( + "SELECT value FROM metadata WHERE key = 'last_sync_at'" + ).fetchone() + if not row: + return None + return datetime.fromisoformat(row["value"]).replace(tzinfo=timezone.utc) + + +def record_sync_time() -> None: + """Record that a sync cycle just completed.""" + now = datetime.now(timezone.utc).isoformat() + with _db() as conn: + conn.execute( + "INSERT INTO metadata (key, value) VALUES ('last_sync_at', ?) " + "ON CONFLICT(key) DO UPDATE SET value = excluded.value", + (now,), + ) + + def clear_pending_for_mbox(mbox_path: str) -> list[str]: """Remove pending state for a given MBOX (used on cleanup/re-process). diff --git a/modules/exporter.py b/modules/exporter.py index 9e2b719..1114a11 100644 --- a/modules/exporter.py +++ b/modules/exporter.py @@ -73,6 +73,8 @@ def run_export( out_dir = export_dir or EXPORT_DIR out_dir.mkdir(parents=True, exist_ok=True) + log.info("Starting Proton Mail export...") + try: binary = ensure_export_cli() except Exception as exc: diff --git a/modules/forwarder.py b/modules/forwarder.py index a34eab2..ec38809 100644 --- a/modules/forwarder.py +++ b/modules/forwarder.py @@ -47,6 +47,8 @@ def push_emails( if not emails: return [], [] + log.info("Starting IMAP push of %d email(s) to iCloud...", len(emails)) + succeeded: list[str] = [] failed: list[str] = [] @@ -70,8 +72,11 @@ def push_emails( if succeeded: mark_delivered(succeeded) - log.info("Marked %d message(s) as delivered.", len(succeeded)) + log.info( + "IMAP push complete — %d delivered, %d failed.", + len(succeeded), len(failed), + ) return succeeded, failed diff --git a/modules/logger.py b/modules/logger.py index c5352b5..62ab233 100644 --- a/modules/logger.py +++ b/modules/logger.py @@ -1,41 +1,76 @@ -"""Rotating log file setup for MailRelay.""" +"""Rotating log file and console setup for MailRelay. + +Two modes: + normal — console shows only user-facing INFO messages (sync, push, MBOX) + plus WARNING/ERROR from any logger + debug — console shows DEBUG from every logger with full context +""" import logging from logging.handlers import RotatingFileHandler from pathlib import Path LOG_PATH = Path(__file__).parent.parent / "data" / "mailrelay.log" -LOG_FORMAT = "%(asctime)s [%(levelname)-8s] %(name)s.%(funcName)s:%(lineno)d — %(message)s" MAX_BYTES = 5 * 1024 * 1024 # 5 MB BACKUP_COUNT = 3 +_NORMAL_FORMAT = "%(asctime)s [%(levelname)-8s] %(message)s" +_DEBUG_FORMAT = "%(asctime)s [%(levelname)-8s] %(name)s.%(funcName)s:%(lineno)d — %(message)s" + +# Loggers whose INFO messages are shown in normal (non-debug) mode +_USER_LOGGERS = frozenset({ + "__main__", + "modules.exporter", + "modules.forwarder", + "modules.packager", +}) + +# Third-party loggers silenced to WARNING in all modes +_SUPPRESS = ("apscheduler", "uvicorn", "fastapi", "asyncio", "multipart", "starlette") + + +class _UserFacingFilter(logging.Filter): + """Pass WARNING+ from any logger; INFO only from the user-visible set.""" + def filter(self, record: logging.LogRecord) -> bool: + if record.levelno >= logging.WARNING: + return True + return record.name in _USER_LOGGERS + def get_logger(name: str) -> logging.Logger: - """Return a named logger wired to the shared rotating file + stderr.""" - logger = logging.getLogger(name) + """Return a named logger that propagates to the root handler.""" + return logging.getLogger(name) - if logger.handlers: - return logger # already configured - logger.setLevel(logging.DEBUG) +def configure_logging(debug: bool = False) -> None: + """Set up root logger with file + console handlers. Call once at startup.""" + root = logging.getLogger() + root.setLevel(logging.DEBUG) + root.handlers.clear() - # Rotating file handler + # File handler — always full DEBUG detail LOG_PATH.parent.mkdir(parents=True, exist_ok=True) - file_handler = RotatingFileHandler( + fh = RotatingFileHandler( LOG_PATH, maxBytes=MAX_BYTES, backupCount=BACKUP_COUNT, encoding="utf-8" ) - file_handler.setLevel(logging.DEBUG) - file_handler.setFormatter(logging.Formatter(LOG_FORMAT)) + fh.setLevel(logging.DEBUG) + fh.setFormatter(logging.Formatter(_DEBUG_FORMAT)) + root.addHandler(fh) - # Console handler (all levels) - console_handler = logging.StreamHandler() - console_handler.setLevel(logging.DEBUG) - console_handler.setFormatter(logging.Formatter(LOG_FORMAT)) + # Console handler + ch = logging.StreamHandler() + if debug: + ch.setLevel(logging.DEBUG) + ch.setFormatter(logging.Formatter(_DEBUG_FORMAT)) + else: + ch.setLevel(logging.INFO) + ch.addFilter(_UserFacingFilter()) + ch.setFormatter(logging.Formatter(_NORMAL_FORMAT)) + root.addHandler(ch) - logger.addHandler(file_handler) - logger.addHandler(console_handler) - - return logger + # Silence noisy third-party loggers + for lib in _SUPPRESS: + logging.getLogger(lib).setLevel(logging.WARNING) def tail_log(lines: int = 50) -> str: @@ -43,5 +78,4 @@ def tail_log(lines: int = 50) -> str: if not LOG_PATH.exists(): return "(no log file yet)" text = LOG_PATH.read_text(encoding="utf-8") - all_lines = text.splitlines() - return "\n".join(all_lines[-lines:]) + return "\n".join(text.splitlines()[-lines:]) diff --git a/modules/packager.py b/modules/packager.py index 87d2658..7028bc2 100644 --- a/modules/packager.py +++ b/modules/packager.py @@ -54,6 +54,7 @@ def bundle_emails(emails: list[RichEmail]) -> Optional[str]: if not emails: return None + log.info("Converting %d email(s) to MBOX...", len(emails)) DOWNLOADS_DIR.mkdir(parents=True, exist_ok=True) timestamp = datetime.utcnow().strftime("%Y%m%dT%H%M%SZ") mbox_filename = f"mailrelay_{timestamp}.mbox"