AI Implementation feature(1083): Environment Configuration and Logging Baseline (#2)

src/tenbackward/config.py

@@ -4,6 +4,8 @@ import os
 from dataclasses import dataclass, field
 from pathlib import Path
 from typing import Optional
+from urllib.parse import urlparse
+from zoneinfo import ZoneInfo, ZoneInfoNotFoundError
 
 from dotenv import dotenv_values, load_dotenv
 
@@ -11,27 +13,29 @@ from dotenv import dotenv_values, load_dotenv
 REQUIRED_KEYS = (
     "MASTODON_BASE_URL",
     "MASTODON_ACCESS_TOKEN",
+    "VISIBILITY",
     "SITE_URL",
     "HASHTAGS",
+    "THROWNBACK_PREFIX",
+    "MAX_RETRIES",
     "RUN_AT",
-)
-
-OPTIONAL_KEYS = (
-    "MASTODON_VISIBILITY",
-    "THROWBACK_PREFIX",
-    "RETRY_COUNT",
     "TZ",
 )
 
+OPTIONAL_KEYS: tuple[str, ...] = ()
+
 DEFAULTS = {
-    "MASTODON_VISIBILITY": "public",
-    "THROWBACK_PREFIX": "Throwback:",
-    "RETRY_COUNT": "3",
+    "VISIBILITY": "public",
+    "THROWNBACK_PREFIX": "Throwback:",
+    "MAX_RETRIES": "3",
     "TZ": "Europe/Berlin",
     "RUN_AT": "09:00",
 }
 
 
+ALLOWED_VISIBILITY = frozenset({"public", "unlisted"})
+
+
 class ConfigError(ValueError):
     """Raised when required configuration is missing or invalid."""
 
@@ -40,11 +44,11 @@ class ConfigError(ValueError):
 class Config:
     mastodon_base_url: str
     mastodon_access_token: str
-    mastodon_visibility: str
+    visibility: str
     site_url: str
     hashtags: str
     throwback_prefix: str
-    retry_count: int
+    max_retries: int
     run_at: str
     tz: str
     data_dir: Path = field(default_factory=lambda: Path("/app/data"))
@@ -104,11 +108,11 @@ def load_config(dotenv_path: Optional[Path] = None) -> Config:
     return Config(
         mastodon_base_url=merged["MASTODON_BASE_URL"],
         mastodon_access_token=merged["MASTODON_ACCESS_TOKEN"],
-        mastodon_visibility=merged["MASTODON_VISIBILITY"],
+        visibility=merged["VISIBILITY"],
         site_url=merged["SITE_URL"],
         hashtags=merged["HASHTAGS"],
-        throwback_prefix=merged["THROWBACK_PREFIX"],
-        retry_count=_parse_retry_count(merged["RETRY_COUNT"]),
+        throwback_prefix=merged["THROWNBACK_PREFIX"],
+        max_retries=_parse_max_retries(merged["MAX_RETRIES"]),
         run_at=merged["RUN_AT"],
         tz=merged["TZ"],
         data_dir=data_dir,
@@ -122,25 +126,47 @@ def apply_defaults(values: dict[str, str]) -> None:
 
 
 def validate_config(values: dict[str, str]) -> None:
-    missing = [k for k in REQUIRED_KEYS if not values.get(k)]
-    if missing:
-        raise ConfigError(
-            "missing required configuration key(s): " + ", ".join(missing)
-        )
+    errors: list[str] = []
+
+    for key in REQUIRED_KEYS:
+        raw = values.get(key, "")
+        if not raw:
+            errors.append(f"missing required configuration key: {key}")
 
     run_at = values.get("RUN_AT", "")
-    if not _is_valid_hhmm(run_at):
-        raise ConfigError(
-            f"RUN_AT={run_at!r} must be in HH:MM (24-hour) format"
+    if run_at and not _is_valid_hhmm(run_at):
+        errors.append(f"RUN_AT={run_at!r} must be in HH:MM (24-hour) format")
+
+    base_url = values.get("MASTODON_BASE_URL", "")
+    if base_url and not _is_valid_url(base_url):
+        errors.append(f"MASTODON_BASE_URL={base_url!r} must be a valid http(s) URL")
+
+    site_url = values.get("SITE_URL", "")
+    if site_url and not _is_valid_url(site_url):
+        errors.append(f"SITE_URL={site_url!r} must be a valid http(s) URL")
+
+    visibility = values.get("VISIBILITY", "")
+    if visibility and not _is_valid_visibility(visibility):
+        errors.append(
+            f"VISIBILITY={visibility!r} must be one of: {sorted(ALLOWED_VISIBILITY)}"
         )
 
-    try:
-        _parse_retry_count(values.get("RETRY_COUNT", ""))
-    except ConfigError as exc:
-        raise ConfigError(str(exc)) from exc
+    tz = values.get("TZ", "")
+    if tz and not _is_valid_tz(tz):
+        errors.append(f"TZ={tz!r} must be a valid IANA timezone")
+
+    max_retries = values.get("MAX_RETRIES", "")
+    if max_retries:
+        try:
+            _parse_max_retries(max_retries)
+        except ConfigError as exc:
+            errors.append(str(exc))
+
+    if errors:
+        raise ConfigError("; ".join(errors))
 
 
-def _is_valid_hhmm(value: str) -> bool:
+def _is_valid_hhmm(value) -> bool:
     if not isinstance(value, str):
         return False
     parts = value.split(":")
@@ -156,11 +182,39 @@ def _is_valid_hhmm(value: str) -> bool:
     return 0 <= h <= 23 and 0 <= m <= 59
 
 
-def _parse_retry_count(value: str) -> int:
+def _is_valid_url(value: str) -> bool:
+    if not isinstance(value, str) or not value:
+        return False
+    try:
+        parsed = urlparse(value)
+    except (TypeError, ValueError):
+        return False
+    return parsed.scheme in {"http", "https"} and bool(parsed.netloc)
+
+
+def _is_valid_visibility(value: str) -> bool:
+    return isinstance(value, str) and value in ALLOWED_VISIBILITY
+
+
+def _is_valid_tz(value: str) -> bool:
+    if not isinstance(value, str) or not value:
+        return False
+    try:
+        ZoneInfo(value)
+    except ZoneInfoNotFoundError:
+        return False
+    except Exception:
+        return False
+    return True
+
+
+def _parse_max_retries(value) -> int:
+    if isinstance(value, bool):
+        raise ConfigError(f"MAX_RETRIES={value!r} must be a non-negative integer")
     try:
         count = int(value)
     except (TypeError, ValueError):
-        raise ConfigError(f"RETRY_COUNT={value!r} must be a positive integer")
+        raise ConfigError(f"MAX_RETRIES={value!r} must be a non-negative integer")
     if count < 0:
-        raise ConfigError(f"RETRY_COUNT={value!r} must be >= 0")
+        raise ConfigError(f"MAX_RETRIES={value!r} must be >= 0")
     return count

src/tenbackward/logging_setup.py

@@ -0,0 +1,155 @@
+from __future__ import annotations
+
+import json
+import logging
+from datetime import datetime, timezone
+from typing import Any
+
+from .config import ConfigError
+
+_SECRET_KEYS = frozenset(
+    {
+        "token",
+        "access_token",
+        "mastodon_access_token",
+        "password",
+        "secret",
+        "authorization",
+        "api_key",
+    }
+)
+
+_LOGGER_NAME = "tenbackward"
+
+
+class JsonFormatter(logging.Formatter):
+    """Emit one JSON object per log record.
+
+    Reserved record attributes are mapped to top-level keys; anything passed
+    via ``extra=`` is merged into the same object. Keys whose name appears in
+    ``_SECRET_KEYS`` are redacted before formatting.
+    """
+
+    _RESERVED = {
+        "name",
+        "msg",
+        "args",
+        "levelname",
+        "levelno",
+        "pathname",
+        "filename",
+        "module",
+        "exc_info",
+        "exc_text",
+        "stack_info",
+        "lineno",
+        "funcName",
+        "created",
+        "msecs",
+        "relativeCreated",
+        "thread",
+        "threadName",
+        "processName",
+        "process",
+        "message",
+        "asctime",
+    }
+
+    def format(self, record: logging.LogRecord) -> str:  # noqa: A003
+        message = record.getMessage()
+        payload: dict[str, Any] = {
+            "ts": datetime.fromtimestamp(record.created, tz=timezone.utc).isoformat(),
+            "level": record.levelname,
+            "logger": record.name,
+            "message": message,
+        }
+
+        for key, value in record.__dict__.items():
+            if key in self._RESERVED or key.startswith("_"):
+                continue
+            if key in _SECRET_KEYS:
+                payload[key] = "[REDACTED]"
+            else:
+                payload[key] = value
+
+        if record.exc_info:
+            payload["exc_type"] = record.exc_info[0].__name__ if record.exc_info[0] else None
+
+        return json.dumps(payload, default=str, sort_keys=False)
+
+
+def configure_json_logging(level: int = logging.INFO) -> None:
+    """Install the JSON formatter on the root logger.
+
+    Idempotent: safe to call multiple times (replaces any existing handler).
+    """
+    handler = logging.StreamHandler()
+    handler.setFormatter(JsonFormatter())
+    handler.setLevel(level)
+
+    root = logging.getLogger()
+    root.setLevel(level)
+    for existing in list(root.handlers):
+        root.removeHandler(existing)
+    root.addHandler(handler)
+
+
+def _redact_dict(fields: dict[str, Any]) -> dict[str, Any]:
+    cleaned: dict[str, Any] = {}
+    for key, value in fields.items():
+        if key.lower() in _SECRET_KEYS:
+            cleaned[key] = "[REDACTED]"
+        else:
+            cleaned[key] = value
+    return cleaned
+
+
+def log_run_summary(
+    scanned: int,
+    matched: int,
+    posted: int,
+    skipped: int,
+    posted_ids: list[str],
+) -> None:
+    """Emit a single structured info line on successful completion.
+
+    A run with no matching posts is silent — no log line is emitted.
+    """
+    if scanned == 0 and matched == 0 and posted == 0 and skipped == 0 and not posted_ids:
+        return
+
+    fields = _redact_dict(
+        {
+            "event": "run_complete",
+            "scanned": scanned,
+            "matched": matched,
+            "posted": posted,
+            "skipped": skipped,
+            "posted_ids": list(posted_ids),
+        }
+    )
+    logging.getLogger(_LOGGER_NAME).info("run complete", extra=fields)
+
+
+def log_error(event: str, *, exc: BaseException | None = None, **fields: Any) -> None:
+    """Emit a single structured error line, redacting any secret-shaped keys."""
+    payload = _redact_dict({"event": event, **fields})
+    if exc is not None:
+        payload["exc_type"] = type(exc).__name__
+    logging.getLogger(_LOGGER_NAME).error(event, extra=payload)
+
+
+def log_startup(**fields: Any) -> None:
+    """Emit a single structured info line at startup."""
+    payload = _redact_dict({"event": "startup", **fields})
+    logging.getLogger(_LOGGER_NAME).info("startup", extra=payload)
+
+
+__all__ = [
+    "ConfigError",
+    "JsonFormatter",
+    "configure_json_logging",
+    "log_error",
+    "log_run_summary",
+    "log_startup",
+]

src/tenbackward/main.py

@@ -1,47 +1,116 @@
 from __future__ import annotations
 
-import logging
 import sys
+import time
+from typing import Iterable
 
 from . import __version__
-from .config import ConfigError, load_config
+from .config import Config, ConfigError, load_config
+from .logging_setup import (
+    configure_json_logging,
+    log_error,
+    log_run_summary,
+    log_startup,
+)
 from .state import load_posted, save_posted
 
 
-log = logging.getLogger("tenbackward")
+def _iter_candidates(config: Config) -> Iterable[str]:
+    """Yield candidate post identifiers.
+
+    This is the extension seam for the future blog-clone + matching
+    pipeline. Job 1083 leaves it empty so the silent-on-no-matches
+    contract is the default behaviour.
+    """
+    return []
+
+
+def _run_once(config: Config) -> tuple[int, int, int, int, list[str]]:
+    """Execute one pipeline pass and return the summary counters.
+
+    Returns ``(scanned, matched, posted, skipped, posted_ids)``.
+    """
+    already_posted = set(load_posted(config.data_dir).keys())
+
+    scanned = 0
+    matched = 0
+    posted = 0
+    skipped = 0
+    posted_ids: list[str] = []
+
+    state = load_posted(config.data_dir)
+
+    for candidate_id in _iter_candidates(config):
+        scanned += 1
+        matched += 1
+        if candidate_id in already_posted:
+            skipped += 1
+            continue
+        posted_ids.append(candidate_id)
+        state[candidate_id] = {"posted_at": _now_iso()}
+        posted += 1
+
+    if posted_ids:
+        save_posted(config.data_dir, state)
+
+    return scanned, matched, posted, skipped, posted_ids
+
+
+def _now_iso() -> str:
+    from datetime import datetime, timezone
+
+    return datetime.now(tz=timezone.utc).isoformat()
+
+
+def _run_with_retry(config: Config) -> tuple[int, int, int, int, list[str]] | None:
+    """Execute the pipeline with retries. Returns the summary counters on
+    success or ``None`` when the retry budget is exhausted."""
+    attempts = max(1, config.max_retries + 1)
+    last_exc: BaseException | None = None
+    for attempt in range(1, attempts + 1):
+        try:
+            return _run_once(config)
+        except Exception as exc:  # noqa: BLE001 — broad on purpose
+            last_exc = exc
+            log_error(
+                "pipeline_error",
+                exc=exc,
+                attempt=attempt,
+                max_attempts=attempts,
+            )
+            if attempt < attempts:
+                time.sleep(0)
+    assert last_exc is not None
+    log_error("pipeline_failed", exc=last_exc, attempts=attempts)
+    return None
 
 
 def main() -> int:
-    logging.basicConfig(
-        level=logging.INFO,
-        format="%(asctime)s %(levelname)s %(name)s: %(message)s",
-    )
+    configure_json_logging()
 
     try:
         config = load_config()
     except ConfigError as exc:
-        log.error("configuration error: %s", exc)
+        log_error("configuration_error", exc=exc)
         return 2
 
     config.data_dir.mkdir(parents=True, exist_ok=True)
 
-    state = load_posted(config.data_dir)
-    save_posted(config.data_dir, state)
-
-    log.info(
-        "10backward v%s ready (site=%s, run_at=%s, tz=%s, hashtags=%s, prefix=%r)",
-        __version__,
-        config.site_url,
-        config.run_at,
-        config.tz,
-        config.hashtags,
-        config.throwback_prefix,
+    log_startup(
+        version=__version__,
+        site_url=config.site_url,
+        run_at=config.run_at,
+        tz=config.tz,
+        hashtags=config.hashtags,
+        throwback_prefix=config.throwback_prefix,
     )
 
-    log.warning(
-        "post pipeline is not yet implemented; this run only validates the scaffold. "
-        "Future job will clone the blog and post a throwback via Mastodon.py."
-    )
+    result = _run_with_retry(config)
+    if result is None:
+        return 1
+
+    scanned, matched, posted, skipped, posted_ids = result
+    log_run_summary(scanned, matched, posted, skipped, posted_ids)
     return 0