Add --debug flag, dual-mode logging, and auto-run on startup

- logger.py: root-level handlers; normal mode shows only user-facing INFO
  (sync, export, push, MBOX) plus WARNING/ERROR; --debug shows all DEBUG
  with full context (module.func:line). Third-party loggers silenced to WARNING.
- main.py: add --debug CLI flag, call configure_logging() at startup,
  auto-trigger sync on first run or when last sync is overdue by the interval
- database.py: add metadata table with record_sync_time() / get_last_sync_time()
  so startup knows whether a sync is due; sync time recorded on success
- forwarder.py: INFO at push start and push complete with counts
- packager.py: INFO before MBOX conversion begins
- exporter.py: INFO when Proton Mail export starts

https://claude.ai/code/session_01KjaNo9RXevw6x1DjJD8mj6

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

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).
 

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:

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
 
 

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:])

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"