"""Logging configuration for the sync service. Configures the root logger with a RotatingFileHandler (10 MB x 5, UTF-8) plus a console StreamHandler. The level and log path come from ``cfg.logging``. Every record written to the log file carries a cycle correlation id (``[cyc:xxxxxxxx]``): ``sync.service.cycle`` allocates one per pass via ``set_cycle_id`` and ``_CycleIdFilter`` injects it into each record, so every capture/apply/cleanup line of one pass -- and the matching ``SyncApplyRunLog.CycleID`` rows on SQL Server -- can be correlated with a single grep. Outside a cycle (fullsync, compare, startup) the field is ``-``. Log files are managed per-day: at startup any previously produced log (including the project's own ``sync.log`` and NSSM's ``nssm_*.log`` captures) is relocated into an ``Archive/`` subfolder next to the active log. Where a log lacks a timestamp, a ``-YYYY-MM-DD`` suffix is added (derived from its first log line, falling back to mtime) so historical files carry a date. The log root therefore only ever shows the current day's ``sync.log``. """ import contextvars import datetime import logging import logging.handlers import os import re import shutil _LOG_DATE_RE = re.compile(r"^(\d{4}-\d{2}-\d{2})") # Current cycle correlation id ("-" when not inside a service cycle). _cycle_id: contextvars.ContextVar[str] = contextvars.ContextVar( "sync_cycle_id", default="-" ) def set_cycle_id(cycle_id: str | None) -> None: """Set (or clear, with ``None``) the id stamped on every log record. Called by ``sync.service.cycle`` at the start/end of each pass. The same id is passed to ``usp_SyncApply`` so SQL-side ``SyncApplyRunLog`` rows can be joined back to the exact log lines of the cycle that produced them. """ _cycle_id.set(cycle_id or "-") class _CycleIdFilter(logging.Filter): """Inject the current cycle id into every record as ``record.cycle``. Attached to the handlers (not the logger) so records emitted through any module logger -- capture, cleanup, access_reader, ... -- are covered. """ def filter(self, record: logging.LogRecord) -> bool: # noqa: A003 record.cycle = _cycle_id.get() return True def _first_line_date(path: str) -> str | None: """Best-effort extraction of the first log line's YYYY-MM-DD date.""" try: with open(path, "r", encoding="utf-8", errors="replace") as f: for line in f: m = _LOG_DATE_RE.match(line) if m: return m.group(1) except OSError: pass return None def _archive_completed_logs(log_dir: str, active_name: str): """Move already-produced logs out of *log_dir* into *log_dir*/Archive. The active log (*active_name*) is left in place only when it belongs to the current day; an older ``sync.log`` is archived (with a ``-YYYY-MM-DD`` suffix) so a fresh one can be opened. NSSM's own ``nssm_*.log`` captures are timestamped already and are moved as-is. Moves are best-effort: files locked by another process (e.g. NSSM's live handles) are skipped. """ archive_dir = os.path.join(log_dir, "Archive") os.makedirs(archive_dir, exist_ok=True) today = datetime.date.today() for name in os.listdir(log_dir): src = os.path.join(log_dir, name) if not os.path.isfile(src): continue if name == "Archive": continue if not (name.endswith(".log") or ".log." in name): continue # Keep NSSM's live, currently-open handles in place. if name in ("nssm_stderr.log", "nssm_stdout.log"): continue if name == active_name: # Only archive the active log if it is from a previous day. log_date = _first_line_date(src) log_date = ( datetime.date.fromisoformat(log_date) if log_date else datetime.date.fromtimestamp(os.path.getmtime(src)) ) if log_date >= today: continue # today's log: keep appending new_name = f"sync-{log_date.strftime('%Y-%m-%d')}.log" else: new_name = name dst = os.path.join(archive_dir, new_name) if os.path.exists(dst): stem, ext = os.path.splitext(new_name) i = 2 while os.path.exists(os.path.join(archive_dir, f"{stem}({i}){ext}")): i += 1 dst = os.path.join(archive_dir, f"{stem}({i}){ext}") try: shutil.move(src, dst) except OSError: # Locked by another process (e.g. NSSM holding the file open). pass def setup_logging(cfg_dict: dict | None): """Configure root logging from the ``cfg.logging`` dict. ``cfg_dict`` is ``SyncConfig.logging`` (a dict or None). ``level`` is a logging-level name string (default ``"INFO"``); ``path`` is the log file path (default ``"sync.log"``). The parent directory is created if missing, and any previously produced logs are archived before the new handler opens. """ level = getattr(logging, (cfg_dict or {}).get("level", "INFO")) if cfg_dict else logging.INFO path = (cfg_dict or {}).get("path", "sync.log") log_dir = os.path.dirname(path) or "." os.makedirs(log_dir, exist_ok=True) # Archive everything from prior runs so the root only shows today's log. _archive_completed_logs(log_dir, os.path.basename(path)) # Idempotent: drop any handlers already attached to the root logger before # re-adding. setup_logging can be called from more than one entry point # (e.g. main.py and service.run), and the old code unconditionally # addHandler'd each time, stacking duplicate handlers so every log line was # written twice. Clearing first means repeated calls always yield exactly # one file handler + one console handler, regardless of caller. root = logging.getLogger() for old in list(root.handlers): root.removeHandler(old) try: old.close() except Exception: pass root.setLevel(level) cycle_filter = _CycleIdFilter() h = logging.handlers.RotatingFileHandler( path, maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8" ) h.addFilter(cycle_filter) h.setFormatter(logging.Formatter( "%(asctime)s %(levelname)s [%(name)s] [cyc:%(cycle)s] %(message)s" )) root.addHandler(h) sh = logging.StreamHandler() sh.addFilter(cycle_filter) # Console keeps the short format (fullsync/compare are interactive there). sh.setFormatter(logging.Formatter("%(levelname)s %(message)s")) root.addHandler(sh)