refactor(logs): homogeneous logging with LOG_LEVEL debug mode

.env.example

@@ -19,3 +19,8 @@ PYRO_ENGINE_VERSION=latest
 # Stuck-PTZ detector (auto-reboots a PTZ camera that stops rotating during patrol).
 # Enabled by default. Set to "false" to disable.
 ENABLE_STUCK_DETECTOR=true
+
+# Log verbosity for both services: DEBUG, INFO, WARNING, ERROR.
+# INFO keeps one summary line per inference round and per patrol cycle;
+# DEBUG adds per-pose captures, raw predictions and HTTP access logs.
+LOG_LEVEL=INFO

.github/workflows/tests.yml

@@ -44,6 +44,9 @@ jobs:
         run: |
           uv run coverage run -m pytest tests/
           uv run coverage xml
+
+      - name: Run camera API tests
+        run: uv run --project pyro_camera_api --locked --with pytest pytest pyro_camera_api/tests
       - name: Upload coverage artifact
         uses: actions/upload-artifact@v4
         with:

CLAUDE.md

@@ -91,7 +91,15 @@ Day is determined by IR-channel analysis (`is_day_time(strategy="ir")`): if `max
 
 ### Environment Variables (`.env`)
 
-Key vars used at runtime: `LAT`, `LON`, `API_URL`, `API_TOKEN`, `CAM_USER`, `CAM_PWD`, `MEDIAMTX_SERVER_IP`, `ROUTER_IP`, `ROUTER_USER`, `ROUTER_PASSWORD`, `ENABLE_ROUTER_REBOOT`.
+Key vars used at runtime: `LAT`, `LON`, `API_URL`, `API_TOKEN`, `CAM_USER`, `CAM_PWD`, `MEDIAMTX_SERVER_IP`, `ROUTER_IP`, `ROUTER_USER`, `ROUTER_PASSWORD`, `ENABLE_ROUTER_REBOOT`, `LOG_LEVEL`.
+
+### Logging
+
+Both services configure logging only from their entrypoint (`src/run.py` calls `pyroengine.logs.setup_logging`, `pyro_camera_api/pyro_camera_api/main.py` calls `core.logging.setup_logging`), sharing the format `%(asctime)s [%(levelname)s] %(name)s: %(message)s` and reading `LOG_LEVEL`. Library modules must never call `logging.basicConfig`.
+
+Convention: camera-scoped messages start with `[cam_id]`, use `%`-style lazy args, and INFO is reserved for events an operator should see (one summary per inference round and per patrol cycle, detections, alerts, failures). Per-pose and per-frame detail belongs at DEBUG.
+
+The engine container healthcheck reads the freshness of the heartbeat file (`--heartbeat-file`, default `data/heartbeat`), so it is independent of log level and log wording. The file is deleted at startup and touched only on real progress (successful capture, night sleep, autofocus on a responsive camera): an engine that captures nothing goes unhealthy after the 10 min window.
 
 ### Legacy direct-camera module
 

README.md

@@ -116,10 +116,16 @@ CAM_USER=my_dummy_login
 CAM_PWD=my_dummy_pwd
 MEDIAMTX_SERVER_IP=1.2.3.4
 PYRO_ENGINE_VERSION=latest
+LOG_LEVEL=INFO
 ```
 
 `PYRO_ENGINE_VERSION` controls which Docker image tag is pulled for both services (defaults to `latest` if unset).
 
+`LOG_LEVEL` sets the verbosity of both services (defaults to `INFO`). At `INFO` a quiet patrol
+round is one summary line per camera cycle and one per inference round; detections, alerts and
+failures are always reported. Set `LOG_LEVEL=DEBUG` to also get per-pose captures, raw model
+predictions, ffmpeg output and HTTP access logs.
+
 ### Data directory
 
 A `./data` directory is expected with at least:

docker-compose.yml

@@ -13,6 +13,7 @@ services:
       CAM_PWD: ${CAM_PWD}
       MEDIAMTX_SERVER_IP: ${MEDIAMTX_SERVER_IP}
       ENABLE_STUCK_DETECTOR: ${ENABLE_STUCK_DETECTOR:-true}
+      LOG_LEVEL: ${LOG_LEVEL:-INFO}
     volumes:
       - ./data:/usr/src/app/data
     restart: always
@@ -39,20 +40,25 @@ services:
       API_URL: ${API_URL}
       CAM_USER: ${CAM_USER}
       CAM_PWD: ${CAM_PWD}
+      LOG_LEVEL: ${LOG_LEVEL:-INFO}
     volumes:
       - ./data:/usr/src/app/data
-    command: >
-      sh -c '
-        truncate -s 0 engine.log &&
-        python run.py 2>&1 | tee -a engine.log
-      '
+    # The json-file driver below is the single rotated log sink; nothing reads a log
+    # file inside the container anymore.
+    command: python run.py
     restart: always
     network_mode: host
     healthcheck:
-      test: ["CMD-SHELL", "grep -q 'confidence\\|Nighttime detected' engine.log || exit 1"]
+      # Liveness comes from the heartbeat file, touched only on real progress (a
+      # successful capture, night sleep, autofocus on a responsive camera), so a blind
+      # engine goes unhealthy while LOG_LEVEL changes cannot affect the verdict.
+      # 10 min tolerates the slowest legitimate gaps (hourly autofocus with unreachable
+      # cameras at 2 min each, long alert-cache flushes on a slow uplink).
+      test: ["CMD-SHELL", "[ -n \"$$(find data/heartbeat -mmin -10 2>/dev/null)\" ] || exit 1"]
       interval: 30s
       retries: 3
-      start_period: 20s
+      # Covers the first-boot model download plus the camera API and first-frame waits.
+      start_period: 300s
       timeout: 5s
     logging:
       driver: json-file

pyro-predictor/pyro_predictor/predictor.py

@@ -34,7 +34,9 @@ class Predictor:
         nb_consecutive_frames: sliding-window size for temporal smoothing
         frame_size: if set, resize each frame to (H, W) before inference
         cam_ids: list of camera IDs to pre-initialise state for
-        verbose: if False, suppress all informational log output (default True)
+        verbose: if False, informational output is downgraded to DEBUG so nothing is emitted at
+            INFO (default True). Unlike previous versions this no longer mutates a global logger
+            level, so it cannot silence an unrelated part of the host application.
         kwargs: forwarded to Classifier
 
     Examples:
@@ -186,13 +188,14 @@ def predict(
                 preds = preds[(preds[:, 2] - preds[:, 0]) < self.max_bbox_size, :]
                 preds = np.reshape(preds, (-1, 5))
 
-        if self.verbose:
-            logger.info(f"pred for {cam_key} : {preds}")
+        logger.debug("[%s] Raw predictions: %s", cam_key, preds)
         conf = self._update_states(frame, preds, cam_key)
 
-        if self.verbose:
-            device_str = f"Camera '{cam_id}' - " if isinstance(cam_id, str) else ""
-            pred_str = "Wildfire detected" if conf > self.conf_thresh else "No wildfire"
-            logger.info(f"{device_str}{pred_str} (confidence: {conf:.2%})")
+        # A detection is worth an INFO line, a quiet frame is not. verbose=False keeps the
+        # caller's INFO stream clean without touching any global logger level.
+        if conf > self.conf_thresh and self.verbose:
+            logger.info("[%s] Wildfire detected (confidence: %.2f%%)", cam_key, conf * 100)
+        else:
+            logger.debug("[%s] Wildfire=%s (confidence: %.2f%%)", cam_key, conf > self.conf_thresh, conf * 100)
 
         return float(conf)

pyro-predictor/pyro_predictor/vision.py

@@ -25,7 +25,6 @@
 MODEL_SLUG = MODEL_REPO_ID.split("/", 1)[1]
 MODEL_CACHE_SUBDIR = "models"
 
-logging.basicConfig(format="%(asctime)s | %(levelname)s: %(message)s", level=logging.INFO, force=True)
 logger = logging.getLogger(__name__)
 
 
@@ -52,8 +51,9 @@ def __init__(
         verbose=True,
     ) -> None:
         self.verbose = verbose
-        if not verbose:
-            logger.setLevel(logging.WARNING)
+        # verbose=False downgrades the setup chatter to DEBUG so nothing reaches the caller's
+        # INFO stream, without mutating this module's logger level for the whole process.
+        info = logger.info if verbose else logger.debug
 
         if model_path:
             if not pathlib.Path(model_path).is_file():
@@ -64,7 +64,7 @@ def __init__(
         else:
             if format == "ncnn":
                 if not self.is_arm_architecture():
-                    logger.info("NCNN format is optimized for arm architecture only, switching to onnx is recommended")
+                    info("NCNN format is optimized for arm architecture only, switching to onnx is recommended")
                 model = MODEL_NAME
                 self.format = "ncnn"
             elif format == "onnx":
@@ -85,20 +85,20 @@ def __init__(
                     for entry in cache_root.iterdir():
                         if entry.name != MODEL_SLUG:
                             shutil.rmtree(entry, ignore_errors=True)
-                            logger.info(f"Removed stale model cache: {entry}")
+                            info(f"Removed stale model cache: {entry}")
                 legacy_archive = pathlib.Path(model_folder) / model
                 legacy_extract = pathlib.Path(model_folder) / model.replace(".tar.gz", "")
                 if legacy_archive.is_file():
                     legacy_archive.unlink()
-                    logger.info(f"Removed legacy model archive: {legacy_archive}")
+                    info(f"Removed legacy model archive: {legacy_archive}")
                 if legacy_extract.is_dir():
                     shutil.rmtree(legacy_extract, ignore_errors=True)
-                    logger.info(f"Removed legacy model extract dir: {legacy_extract}")
+                    info(f"Removed legacy model extract dir: {legacy_extract}")
 
-                logger.info(f"Downloading model from {MODEL_REPO_ID}/{model} ...")
+                info(f"Downloading model from {MODEL_REPO_ID}/{model} ...")
                 model_cache.mkdir(exist_ok=True, parents=True)
                 hf_hub_download(repo_id=MODEL_REPO_ID, filename=model, local_dir=str(model_cache))
-                logger.info("Model downloaded!")
+                info("Model downloaded!")
 
             # Extract archive
             if model_path.endswith(".tar.gz"):
@@ -108,7 +108,7 @@ def __init__(
                     pathlib.Path(extract_path).mkdir(parents=True, exist_ok=True)
                     with tarfile.open(model_path, "r:gz") as tar:
                         tar.extractall(extract_path)
-                    logger.info(f"Extracted model to: {extract_path}")
+                    info(f"Extracted model to: {extract_path}")
                 model_path = extract_path
 
         if self.format == "ncnn":
@@ -122,16 +122,16 @@ def __init__(
                 available_providers = onnxruntime.get_available_providers()
                 if "CUDAExecutionProvider" in available_providers:
                     providers = ["CUDAExecutionProvider", "CPUExecutionProvider"]
-                    logger.info("CUDA is available — using CUDAExecutionProvider for ONNX inference")
+                    info("CUDA is available — using CUDAExecutionProvider for ONNX inference")
                 else:
                     providers = ["CPUExecutionProvider"]
-                    logger.info("Using CPUExecutionProvider for ONNX inference")
+                    info("Using CPUExecutionProvider for ONNX inference")
                 self.ort_session = onnxruntime.InferenceSession(onnx_file, providers=providers)
 
             except Exception as e:
                 raise RuntimeError(f"Failed to load the ONNX model from {model_path}: {e!s}") from e
 
-            logger.info(f"ONNX model loaded successfully from {model_path}")
+            info(f"ONNX model loaded successfully from {model_path}")
 
         self.imgsz = imgsz
         self.conf = conf
@@ -231,7 +231,7 @@ def __call__(self, pil_img: Image.Image, occlusion_bboxes: dict | None = None) -
         pred = pred[(pred[:, 2] - pred[:, 0]) < self.max_bbox_size, :]
         pred = np.reshape(pred, (-1, 5))
 
-        logger.info(f"Model original pred : {pred}")
+        logger.debug("Model original pred: %s", pred)
 
         # Remove prediction in bbox occlusion mask
         if len(occlusion_bboxes):

pyro_camera_api/pyro_camera_api/api/routes_stream.py

@@ -27,6 +27,7 @@
     log_ffmpeg_output,
     stop_any_running_stream,
 )
+from pyro_camera_api.utils.redact import redact_url
 from pyro_camera_api.utils.time_utils import update_command_time
 
 router = APIRouter()
@@ -124,7 +125,7 @@ def start_stream(camera_ip: str, request: Request):
                 )
 
                 workers[camera_ip] = Pipeline(decoder=decoder, encoder=encoder)
-                logger.info("[%s] start pipeline, rtsp %s, srt %s", camera_ip, input_url, output_url)
+                logger.info("[%s] Start pipeline, rtsp %s, srt %s", camera_ip, redact_url(input_url), output_url)
                 decoder.start()
                 encoder.start()
 
@@ -136,7 +137,8 @@ def start_stream(camera_ip: str, request: Request):
 
             # restream mode
             cmd = build_ffmpeg_restream_cmd(input_url=input_url, output_url=output_url)
-            logger.info("[%s] Running ffmpeg command, %s", camera_ip, " ".join(cmd))
+            logger.info("[%s] Starting ffmpeg restream to %s", camera_ip, output_url)
+            logger.debug("[%s] ffmpeg command: %s", camera_ip, " ".join(redact_url(part) for part in cmd))
             proc = subprocess.Popen(cmd, stdout=subprocess.DEVNULL, stderr=subprocess.PIPE)
             procs[camera_ip] = proc
             threading.Thread(target=log_ffmpeg_output, args=(proc, camera_ip), daemon=True).start()

pyro_camera_api/pyro_camera_api/camera/adapters/linovision.py

@@ -520,11 +520,11 @@ def reboot_camera(self) -> bool:
         return self._handle_response(resp, "Reboot requested") is not None
 
     def get_auto_focus(self):
-        logger.warning("Auto focus retrieval not implemented for Linovision")
+        logger.debug("Auto focus retrieval not implemented for Linovision")
         return
 
     def set_auto_focus(self, disable: bool):
-        logger.warning("Auto focus setting not implemented for Linovision (disable=%s)", disable)
+        logger.debug("Auto focus setting not implemented for Linovision (disable=%s)", disable)
         return
 
     def _zoom_to_raw(self, zoom: int) -> int:
@@ -568,16 +568,16 @@ def focus_finder(
         _ = save_images
         _ = retry_depth
         _ = should_abort
-        logger.warning("Focus finder not implemented for Linovision")
+        logger.debug("Focus finder not implemented for Linovision")
         return self.focus_position if self.focus_position is not None else -1
 
     def set_manual_focus(self, position: int):
         self.focus_position = position
-        logger.warning("Manual focus not implemented for Linovision yet (position=%s)", position)
+        logger.debug("Manual focus not implemented for Linovision yet (position=%s)", position)
         return
 
     def get_focus_level(self):
-        logger.warning("Focus level not implemented for Linovision yet")
+        logger.debug("Focus level not implemented for Linovision yet")
         return
 
     def disable_ptz_osd(self):

pyro_camera_api/pyro_camera_api/camera/adapters/mock.py

@@ -64,7 +64,7 @@ def _ensure_image(self) -> None:
             resp = requests.get(self.image_url, timeout=5)
             resp.raise_for_status()
             self._cached_image = Image.open(BytesIO(resp.content)).convert("RGB")
-            logger.info("MockCamera %s cached image, size=%s", self.camera_id, self._cached_image.size)
+            logger.debug("MockCamera %s cached image, size=%s", self.camera_id, self._cached_image.size)
         except Exception as exc:
             logger.error("MockCamera %s failed to download image: %s", self.camera_id, exc)
             self._cached_image = None
@@ -109,7 +109,7 @@ def get_azimuth(self) -> Optional[float]:
 
     def set_manual_focus(self, position: int) -> None:
         self.focus_position = position
-        logger.info("MockCamera %s set_manual_focus(%s) (no op)", self.camera_id, position)
+        logger.debug("MockCamera %s set_manual_focus(%s) (no op)", self.camera_id, position)
 
     def focus_finder(
         self,
@@ -124,23 +124,23 @@ def focus_finder(
             raise FocusAbortedError
         if self.focus_position is None:
             self.focus_position = 720
-        logger.info("MockCamera %s focus_finder -> %s (fake)", self.camera_id, self.focus_position)
+        logger.debug("MockCamera %s focus_finder -> %s (fake)", self.camera_id, self.focus_position)
         return int(self.focus_position)
 
     # ------------------------------------------------------------------
     # Extra helpers to satisfy existing routes (no op)
     # ------------------------------------------------------------------
 
     def set_auto_focus(self, disable: bool):
-        logger.info("MockCamera %s set_auto_focus(disable=%s) (no op)", self.camera_id, disable)
+        logger.debug("MockCamera %s set_auto_focus(disable=%s) (no op)", self.camera_id, disable)
         return {"status": "ok", "disable": disable}
 
     def get_focus_level(self):
         focus = self.focus_position if self.focus_position is not None else 720
         zoom = 0
-        logger.info("MockCamera %s get_focus_level -> focus=%s zoom=%s (fake)", self.camera_id, focus, zoom)
+        logger.debug("MockCamera %s get_focus_level -> focus=%s zoom=%s (fake)", self.camera_id, focus, zoom)
         return {"focus": focus, "zoom": zoom}
 
     def start_zoom_focus(self, position: int):
-        logger.info("MockCamera %s start_zoom_focus(%s) (no op)", self.camera_id, position)
+        logger.debug("MockCamera %s start_zoom_focus(%s) (no op)", self.camera_id, position)
         return {"status": "ok", "position": position}

pyro_camera_api/pyro_camera_api/camera/adapters/rest.py

@@ -8,7 +8,6 @@
 
 import base64
 import logging
-import re
 from io import BytesIO
 from typing import Any, Dict, Optional
 from urllib.parse import urlparse
@@ -17,13 +16,12 @@
 from PIL import Image
 
 from pyro_camera_api.camera.base import BaseCamera
+from pyro_camera_api.utils.redact import redact_url
 
 logger = logging.getLogger(__name__)
 
 # Header names whose values must never be logged in clear.
 _SENSITIVE_HEADERS = {"authorization", "x-api-key", "api-key", "apikey", "token"}
-# Query parameters whose values must never be logged in clear.
-_SENSITIVE_QUERY = re.compile(r"(token|access_token|api_?key|pwd|password)=([^&]+)", re.IGNORECASE)
 
 
 class RestSnapshotCamera(BaseCamera):
@@ -72,8 +70,8 @@ def _redact_headers(headers: Dict[str, str]) -> Dict[str, str]:
 
     @staticmethod
     def _redact_url(url: str) -> str:
-        """Mask credential-like query parameters for safe logging."""
-        return _SENSITIVE_QUERY.sub(r"\1=***", url)
+        """Mask userinfo and credential-like query parameters for safe logging."""
+        return redact_url(url)
 
     def _safe_headers(self) -> Dict[str, str]:
         """Return headers with sensitive values removed (for cross-origin fetches)."""

pyro_camera_api/pyro_camera_api/camera/adapters/rtsp.py

@@ -15,21 +15,11 @@
 from PIL import Image
 
 from pyro_camera_api.camera.base import BaseCamera
+from pyro_camera_api.utils.redact import redact_url as _safe_url
 
 logger = logging.getLogger(__name__)
 
 
-def _safe_url(u: str) -> str:
-    try:
-        if "://" in u and "@" in u:
-            scheme, rest = u.split("://", 1)
-            after_at = rest.split("@", 1)[1]
-            return f"{scheme}://***:***@{after_at}"
-    except Exception as exc:
-        logger.debug("Could not redact credentials from URL: %s", exc)
-    return u
-
-
 class RTSPCamera(BaseCamera):
     """RTSP camera that grabs one frame via ffmpeg with a hard timeout, returns a Pillow Image."""