Add structured logging and log analyzer

src/psd/__init__.py

@@ -8,6 +8,7 @@
 from .config import PSDConfig
 from .feature_flags import FLAGS, FeatureFlags, disable, enable
 from .graph import GraphConfig, find_optimal_path
+from .log_analyzer import LogStats, analyze_log, summarize_logs
 from .logging_utils import setup_logging
 
 setup_logging()
@@ -35,5 +36,8 @@
     "disable",
     "PSDTorch",
     "PSDTensorFlow",
+    "LogStats",
+    "analyze_log",
+    "summarize_logs",
     "__version__",
 ]

src/psd/graph.py

@@ -227,7 +227,11 @@ def find_optimal_path(
         return path
     finally:
         duration = perf_counter() - start_time
-        logger.info("find_optimal_path executed in %.6f seconds", duration)
+        logger.info(
+            "find_optimal_path executed in %.6f seconds",
+            duration,
+            extra={"duration": duration},
+        )
 
 
 __all__ = ["find_optimal_path", "GraphConfig"]

src/psd/log_analyzer.py

@@ -0,0 +1,61 @@
+from __future__ import annotations
+
+import json
+from dataclasses import dataclass
+from pathlib import Path
+
+
+@dataclass
+class LogStats:
+    """Summary statistics for a log file."""
+
+    error_count: int
+    avg_latency: float
+    latency_count: int
+
+
+def analyze_log(path: str | Path) -> LogStats:
+    """Summarise errors and latency metrics in a structured log file.
+
+    Parameters
+    ----------
+    path:
+        Path to a log file containing one JSON object per line.
+    """
+
+    p = Path(path)
+    errors = 0
+    latencies: list[float] = []
+    if not p.is_file():
+        return LogStats(0, 0.0, 0)
+    with p.open() as fh:
+        for line in fh:
+            try:
+                record = json.loads(line)
+            except json.JSONDecodeError:
+                continue
+            if record.get("level") == "ERROR":
+                errors += 1
+            if "duration" in record:
+                try:
+                    latencies.append(float(record["duration"]))
+                except (TypeError, ValueError):
+                    continue
+    avg = sum(latencies) / len(latencies) if latencies else 0.0
+    return LogStats(errors, avg, len(latencies))
+
+
+def summarize_logs(directory: str | Path = "logs") -> dict[str, LogStats]:
+    """Summarise all log files in ``directory``.
+
+    Returns a mapping of filename to :class:`LogStats`.
+    """
+
+    dir_path = Path(directory)
+    summaries: dict[str, LogStats] = {}
+    for file in dir_path.glob("*.log*"):
+        summaries[file.name] = analyze_log(file)
+    return summaries
+
+
+__all__ = ["LogStats", "analyze_log", "summarize_logs"]

src/psd/logging_utils.py

@@ -3,6 +3,7 @@
 import json
 import logging
 import logging.config
+from logging.handlers import RotatingFileHandler
 from pathlib import Path
 
 
@@ -16,16 +17,70 @@ def format(self, record: logging.LogRecord) -> str:  # pragma: no cover - trivia
             "name": record.name,
             "message": record.getMessage(),
         }
+        # Include extra attributes added via the ``extra`` argument
+        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",
+        }
+        for key, value in record.__dict__.items():
+            if key in reserved or key.startswith("_"):
+                continue
+            try:
+                json.dumps(value)
+                data[key] = value
+            except TypeError:  # pragma: no cover - non-serialisable extras
+                data[key] = str(value)
         if record.exc_info:
             data["exc_info"] = self.formatException(record.exc_info)
         return json.dumps(data)
 
 
 def setup_logging(config_path: str | Path | None = None) -> None:
-    """Load logging configuration from ``logging.ini`` if present."""
+    """Initialise structured logging with optional configuration file.
+
+    If ``config_path`` (or ``logging.ini``) is present, it will be loaded via
+    :func:`logging.config.fileConfig`.  Otherwise a sensible default
+    configuration with a rotating JSON log file and console output is
+    installed.
+    """
 
     path = Path(config_path or "logging.ini")
-    if not path.is_file():
+    if path.is_file():
+        Path("logs").mkdir(exist_ok=True)
+        logging.config.fileConfig(path, disable_existing_loggers=False)
+        return
+
+    root = logging.getLogger()
+    if root.handlers:  # pragma: no cover - defensive programming
         return
+    root.setLevel(logging.INFO)
     Path("logs").mkdir(exist_ok=True)
-    logging.config.fileConfig(path, disable_existing_loggers=False)
+
+    formatter = JsonFormatter()
+
+    file_handler = RotatingFileHandler("logs/psd.log", maxBytes=1_048_576, backupCount=3)
+    file_handler.setFormatter(formatter)
+    root.addHandler(file_handler)
+
+    console = logging.StreamHandler()
+    console.setFormatter(formatter)
+    root.addHandler(console)

tests/test_log_analyzer.py

@@ -0,0 +1,22 @@
+from __future__ import annotations
+
+import json
+from pathlib import Path
+
+import pytest
+
+from psd.log_analyzer import analyze_log
+
+
+def test_analyze_log(tmp_path: Path) -> None:
+    log_file = tmp_path / "psd.log"
+    records = [
+        {"time": "0", "level": "INFO", "name": "t", "message": "ok", "duration": 0.1},
+        {"time": "1", "level": "ERROR", "name": "t", "message": "fail"},
+        {"time": "2", "level": "INFO", "name": "t", "message": "ok", "duration": 0.3},
+    ]
+    log_file.write_text("\n".join(json.dumps(r) for r in records))
+    stats = analyze_log(log_file)
+    assert stats.error_count == 1
+    assert stats.latency_count == 2
+    assert stats.avg_latency == pytest.approx(0.2)