diff --git a/.env.example b/.env.example index a40d4113..4c1b5f69 100644 --- a/.env.example +++ b/.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 diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 14928a6c..d9a5302e 100644 --- a/.github/workflows/tests.yml +++ b/.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: diff --git a/CLAUDE.md b/CLAUDE.md index ba9f8a5d..aedd577b 100644 --- a/CLAUDE.md +++ b/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 diff --git a/README.md b/README.md index 41d396b6..d285ef09 100644 --- a/README.md +++ b/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: diff --git a/docker-compose.yml b/docker-compose.yml index 28bd1265..e0e30ecc 100644 --- a/docker-compose.yml +++ b/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 diff --git a/pyro-predictor/pyro_predictor/predictor.py b/pyro-predictor/pyro_predictor/predictor.py index b4c4cc23..bb80804b 100644 --- a/pyro-predictor/pyro_predictor/predictor.py +++ b/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) diff --git a/pyro-predictor/pyro_predictor/vision.py b/pyro-predictor/pyro_predictor/vision.py index 0ff66cc5..9df5014b 100644 --- a/pyro-predictor/pyro_predictor/vision.py +++ b/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): diff --git a/pyro_camera_api/pyro_camera_api/api/routes_stream.py b/pyro_camera_api/pyro_camera_api/api/routes_stream.py index c94ffc2f..60cd0fce 100644 --- a/pyro_camera_api/pyro_camera_api/api/routes_stream.py +++ b/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() diff --git a/pyro_camera_api/pyro_camera_api/camera/adapters/linovision.py b/pyro_camera_api/pyro_camera_api/camera/adapters/linovision.py index 1ee3a615..3318f08c 100644 --- a/pyro_camera_api/pyro_camera_api/camera/adapters/linovision.py +++ b/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): diff --git a/pyro_camera_api/pyro_camera_api/camera/adapters/mock.py b/pyro_camera_api/pyro_camera_api/camera/adapters/mock.py index 7f048b84..51331111 100644 --- a/pyro_camera_api/pyro_camera_api/camera/adapters/mock.py +++ b/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,7 +124,7 @@ 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) # ------------------------------------------------------------------ @@ -132,15 +132,15 @@ def focus_finder( # ------------------------------------------------------------------ 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} diff --git a/pyro_camera_api/pyro_camera_api/camera/adapters/rest.py b/pyro_camera_api/pyro_camera_api/camera/adapters/rest.py index 7df1bf46..810274bf 100644 --- a/pyro_camera_api/pyro_camera_api/camera/adapters/rest.py +++ b/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).""" diff --git a/pyro_camera_api/pyro_camera_api/camera/adapters/rtsp.py b/pyro_camera_api/pyro_camera_api/camera/adapters/rtsp.py index 6557b848..b36f8fd6 100644 --- a/pyro_camera_api/pyro_camera_api/camera/adapters/rtsp.py +++ b/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.""" diff --git a/pyro_camera_api/pyro_camera_api/camera/adapters/url.py b/pyro_camera_api/pyro_camera_api/camera/adapters/url.py index b064a9ba..318789aa 100644 --- a/pyro_camera_api/pyro_camera_api/camera/adapters/url.py +++ b/pyro_camera_api/pyro_camera_api/camera/adapters/url.py @@ -7,7 +7,6 @@ from __future__ import annotations import logging -import re from io import BytesIO from typing import Optional, Tuple from urllib.parse import urlparse, urlunparse @@ -17,6 +16,7 @@ from requests.auth import HTTPDigestAuth from pyro_camera_api.camera.base import BaseCamera +from pyro_camera_api.utils.redact import redact_url logger = logging.getLogger(__name__) @@ -40,14 +40,7 @@ def _redact(url: str) -> str: """ Mask credentials in URL for safe logging. """ - parsed = urlparse(url) - # Drop user info from netloc - netloc = parsed.netloc.split("@")[-1] - cleaned = parsed._replace(netloc=netloc) - redacted = urlunparse(cleaned) - # Mask query credentials - redacted = re.sub(r"(usr|user|username)=([^&]+)", r"\1=***", redacted, flags=re.IGNORECASE) - return re.sub(r"(pwd|pass|password)=([^&]+)", r"\1=***", redacted, flags=re.IGNORECASE) + return redact_url(url) @staticmethod def _strip_credentials(parsed) -> Tuple[str, Optional[Tuple[str, str]]]: diff --git a/pyro_camera_api/pyro_camera_api/camera/patrol.py b/pyro_camera_api/pyro_camera_api/camera/patrol.py index 90f0f8db..b3605b58 100644 --- a/pyro_camera_api/pyro_camera_api/camera/patrol.py +++ b/pyro_camera_api/pyro_camera_api/camera/patrol.py @@ -87,6 +87,8 @@ def patrol_loop(camera_ip: str, stop_flag: threading.Event) -> None: continue start_time = time.time() + captured = 0 + failed = 0 for pose in poses: if stop_flag.is_set() or is_camera_streaming(camera_ip): @@ -94,15 +96,20 @@ def patrol_loop(camera_ip: str, stop_flag: threading.Event) -> None: try: cam.move_camera("ToPos", idx=pose, speed=50) - logger.info("[%s] Moving to pose %s", camera_ip, pose) + logger.debug("[%s] Moved to pose %s", camera_ip, pose) time.sleep(1.5) image = cam.capture() if image: cam.last_images[pose] = image - logger.info("[%s] Stored image for pose %s", camera_ip, pose) + captured += 1 + logger.debug("[%s] Stored image for pose %s", camera_ip, pose) + else: + failed += 1 + logger.debug("[%s] Capture returned no image for pose %s", camera_ip, pose) except Exception as exc: + failed += 1 logger.error("[%s] Error at pose %s: %s", camera_ip, pose, exc) continue @@ -113,19 +120,27 @@ def patrol_loop(camera_ip: str, stop_flag: threading.Event) -> None: try: cam.move_camera("ToPos", idx=poses[0], speed=50) - logger.info("[%s] Returned to pose 0", camera_ip) + logger.debug("[%s] Returned to pose %s", camera_ip, poses[0]) except Exception as exc: - logger.warning("[%s] Failed to return to pose 0: %s", camera_ip, exc) + logger.warning("[%s] Failed to return to first pose: %s", camera_ip, exc) if getattr(cam, "focus_position", None) is not None: try: if cam.focus_position is not None: cam.set_manual_focus(cam.focus_position) - logger.info("[%s] Restored manual focus to %s", camera_ip, cam.focus_position) + logger.debug("[%s] Restored manual focus to %s", camera_ip, cam.focus_position) except Exception as exc: logger.warning("[%s] Failed to restore focus: %s", camera_ip, exc) elapsed = time.time() - start_time + logger.info( + "[%s] Patrol cycle: captured=%d/%d failed=%d duration=%.1fs", + camera_ip, + captured, + len(poses), + failed, + elapsed, + ) sleep_time = max(0.0, 30.0 - elapsed) stop_flag.wait(sleep_time) @@ -145,10 +160,10 @@ def static_loop(camera_ip: str, stop_flag: threading.Event) -> None: while not stop_flag.is_set(): now = time.time() - # skip window + # skip window: entering it is already logged once, so stay quiet while it lasts if now < SKIP_UNTIL[camera_ip]: left = int(SKIP_UNTIL[camera_ip] - now) - logger.warning("[%s] Skipped for %ds due to previous failures", camera_ip, left) + logger.debug("[%s] Skipped for %ds due to previous failures", camera_ip, left) else: try: # capture with internal timeout handled by RTSP or URL adapters @@ -160,15 +175,23 @@ def static_loop(camera_ip: str, stop_flag: threading.Event) -> None: if opened_at: settle_until = opened_at + 1.0 - if image and now >= settle_until: + if image and now < settle_until: + # The capture worked, the frame is just too close to the reconnect to + # trust: discard it without counting a failure. + logger.debug("[%s] Discarding frame captured during settle window", camera_ip) + elif image: cam.last_images[-1] = image - logger.info("[%s] Updated static image (pose -1)", camera_ip) + # Steady state is silent, only the recovery is worth an INFO line. + if FAILURE_COUNT[camera_ip]: + logger.info("[%s] Capture recovered after %d failures", camera_ip, FAILURE_COUNT[camera_ip]) + else: + logger.debug("[%s] Updated static image (pose -1)", camera_ip) # success reset failure counter and clear skip FAILURE_COUNT[camera_ip] = 0 SKIP_UNTIL[camera_ip] = 0.0 else: FAILURE_COUNT[camera_ip] += 1 - logger.error( + logger.warning( "[%s] Capture returned no image, failures=%d", camera_ip, FAILURE_COUNT[camera_ip], @@ -179,7 +202,7 @@ def static_loop(camera_ip: str, stop_flag: threading.Event) -> None: except Exception as exc: FAILURE_COUNT[camera_ip] += 1 - logger.error( + logger.warning( "[%s] Error capturing static image: %s, failures=%d", camera_ip, exc, diff --git a/pyro_camera_api/pyro_camera_api/camera/registry.py b/pyro_camera_api/pyro_camera_api/camera/registry.py index 6ad42515..35ec2326 100644 --- a/pyro_camera_api/pyro_camera_api/camera/registry.py +++ b/pyro_camera_api/pyro_camera_api/camera/registry.py @@ -45,8 +45,7 @@ def repl(match: re.Match[str]) -> str: return _ENV_PLACEHOLDER.sub(repl, value) -logger = logging.getLogger("CameraRegistry") -logger.setLevel(logging.INFO) +logger = logging.getLogger(__name__) # Global registry of camera objects, keyed by camera id CAMERA_REGISTRY: Dict[str, BaseCamera] = {} diff --git a/pyro_camera_api/pyro_camera_api/core/logging.py b/pyro_camera_api/pyro_camera_api/core/logging.py index b69f7d27..cb73e40f 100644 --- a/pyro_camera_api/pyro_camera_api/core/logging.py +++ b/pyro_camera_api/pyro_camera_api/core/logging.py @@ -10,6 +10,8 @@ import os import sys +from pyro_camera_api.utils.redact import RedactSecretsFilter + def setup_logging() -> None: """ @@ -23,17 +25,36 @@ def setup_logging() -> None: level_name = os.getenv("LOG_LEVEL", "INFO").upper() level = getattr(logging, level_name, logging.INFO) - # Avoid duplicate handlers (FastAPI reload) - for handler in logging.root.handlers[:]: - logging.root.removeHandler(handler) - + # force=True clears existing handlers (FastAPI reload, uvicorn own config) + handler = logging.StreamHandler(sys.stdout) + # Credentials are scrubbed at the handler so lines relayed from subprocesses + # (ffmpeg stderr) and third-party loggers are covered too, not only our own calls. + handler.addFilter(RedactSecretsFilter()) logging.basicConfig( level=level, format="%(asctime)s [%(levelname)s] %(name)s: %(message)s", - handlers=[logging.StreamHandler(sys.stdout)], + handlers=[handler], + force=True, ) - # Reduce noise from external libraries - logging.getLogger("urllib3").setLevel(logging.WARNING) - logging.getLogger("PIL").setLevel(logging.WARNING) - logging.getLogger("ffmpeg").setLevel(logging.WARNING) + # Reduce noise from external libraries. Never below the configured level: a child logger + # level is not re-checked against the root one, so WARNING here would leak warnings + # through an ERROR root. + noisy_level = max(level, logging.WARNING) + logging.getLogger("urllib3").setLevel(noisy_level) + logging.getLogger("PIL").setLevel(noisy_level) + logging.getLogger("ffmpeg").setLevel(noisy_level) + + # Uvicorn installs its own handlers with propagate=False and an explicit INFO level, so its + # startup and access lines would keep a timestamp-less format of their own and stay visible + # even at LOG_LEVEL=ERROR. Hand them to the root handler and reset their level to NOTSET so + # they inherit the configured one. + for name in ("uvicorn", "uvicorn.error", "uvicorn.access"): + uvicorn_logger = logging.getLogger(name) + uvicorn_logger.handlers.clear() + uvicorn_logger.propagate = True + uvicorn_logger.setLevel(logging.NOTSET) + + # The engine polls capture endpoints every few seconds; one access line per request + # drowns the log, so keep them for debug runs only. + logging.getLogger("uvicorn.access").setLevel(logging.DEBUG if level <= logging.DEBUG else noisy_level) diff --git a/pyro_camera_api/pyro_camera_api/services/anonymizer_rtsp.py b/pyro_camera_api/pyro_camera_api/services/anonymizer_rtsp.py index e729d1dc..090c48c4 100644 --- a/pyro_camera_api/pyro_camera_api/services/anonymizer_rtsp.py +++ b/pyro_camera_api/pyro_camera_api/services/anonymizer_rtsp.py @@ -213,7 +213,7 @@ def log_ffmpeg_stderr(proc: subprocess.Popen[bytes], name: str) -> None: for line in iter(proc.stderr.readline, b""): if not line: break - logger.info("[%s] %s", name, line.decode(errors="ignore").rstrip()) + logger.debug("[ffmpeg %s] %s", name, line.decode(errors="ignore").rstrip()) class FPSMeter: @@ -236,7 +236,7 @@ def tick(self, n: int = 1) -> None: inst = self._count / dt self._ema = inst if self._ema is None else 0.9 * self._ema + 0.1 * inst if now - self._last_log >= self._log_every: - logger.info("FPS %s, current %.2f, smoothed %.2f", self.name, inst, self._ema or inst) + logger.debug("FPS %s, current %.2f, smoothed %.2f", self.name, inst, self._ema or inst) self._last_log = now self._t0 = now self._count = 0 diff --git a/pyro_camera_api/pyro_camera_api/services/stream.py b/pyro_camera_api/pyro_camera_api/services/stream.py index b31284ba..5518bb2b 100644 --- a/pyro_camera_api/pyro_camera_api/services/stream.py +++ b/pyro_camera_api/pyro_camera_api/services/stream.py @@ -122,7 +122,7 @@ def log_ffmpeg_output(proc: subprocess.Popen, camera_id: str) -> None: for line in iter(proc.stderr.readline, b""): if not line: break - logger.info("[ffmpeg %s] %s", camera_id, line.decode(errors="ignore").rstrip()) + logger.debug("[ffmpeg %s] %s", camera_id, line.decode(errors="ignore").rstrip()) def build_ffmpeg_restream_cmd(input_url: str, output_url: str) -> list[str]: diff --git a/pyro_camera_api/pyro_camera_api/utils/redact.py b/pyro_camera_api/pyro_camera_api/utils/redact.py new file mode 100644 index 00000000..a165931e --- /dev/null +++ b/pyro_camera_api/pyro_camera_api/utils/redact.py @@ -0,0 +1,70 @@ +# Copyright (C) 2022-2026, Pyronear. + +# This program is licensed under the Apache License 2.0. +# See LICENSE or go to for full license details. + + +from __future__ import annotations + +import logging +import re +from urllib.parse import urlsplit, urlunsplit + +__all__ = ["RedactSecretsFilter", "redact_text", "redact_url"] + +# scheme:// then a run of non-space/non-slash characters ending in "@": the greedy "*" +# reaches the LAST "@" of the run, so a password containing "@" is fully masked, and a +# "@" later in the path (after a "/") never matches. +_USERINFO = re.compile(r"(\w[\w+.-]*://)[^\s/]*@") + +# Credential-like key=value pairs in query strings, MediaMTX streamid forms +# ("#!::u=user,p=pass,m=publish") and ffmpeg command lines. "u"/"p" are kept for the +# streamid form; the lookbehind keeps them from matching inside longer words. +_SENSITIVE_KV = re.compile( + r"(? str: + """Mask URL userinfo and credential-like key=value pairs anywhere in a string.""" + return _SENSITIVE_KV.sub(r"\1=***", _USERINFO.sub(r"\1***:***@", text)) + + +def redact_url(url: str) -> str: + """Mask the userinfo part and credential-like query parameters of a URL. + + The userinfo is parsed instead of split on "@": a password may itself contain "@" (only + the last one delimits the host), and a path may contain "@" while the URL carries no + credentials at all. + + Values that are not a scheme://host URL still get key=value masking, so this is safe to + map over a whole command line. + """ + try: + parts = urlsplit(url) + if "@" in parts.netloc: + host = parts.netloc.rpartition("@")[2] + url = urlunsplit((parts.scheme, f"***:***@{host}", parts.path, parts.query, parts.fragment)) + except ValueError: + # Unparsable, so never echo it back: it may still hold credentials. + return "***" + return _SENSITIVE_KV.sub(r"\1=***", url) + + +class RedactSecretsFilter(logging.Filter): + """Scrub credentials from every record at the handler, whatever the source. + + Per-call redaction cannot cover lines relayed from subprocesses (ffmpeg echoes the + full input URL on its own stderr) or third-party loggers, so the last line of defense + sits on the handler itself. + """ + + def filter(self, record: logging.LogRecord) -> bool: + msg = record.getMessage() + redacted = redact_text(msg) + if redacted != msg: + record.msg = redacted + record.args = None + return True diff --git a/pyro_camera_api/tests/test_redact.py b/pyro_camera_api/tests/test_redact.py new file mode 100644 index 00000000..38728df5 --- /dev/null +++ b/pyro_camera_api/tests/test_redact.py @@ -0,0 +1,97 @@ +# Copyright (C) 2022-2026, Pyronear. + +# This program is licensed under the Apache License 2.0. +# See LICENSE or go to for full license details. + +import logging + +import pytest + +from pyro_camera_api.utils.redact import RedactSecretsFilter, redact_text, redact_url + + +@pytest.mark.parametrize( + ("url", "expected"), + [ + # Plain credentials + ("rtsp://admin:secret@10.0.0.1:554/h264", "rtsp://***:***@10.0.0.1:554/h264"), + # A "@" inside the password must not end up in the output: only the last "@" + # delimits the host, so splitting on the first one leaks the rest of the password. + ("rtsp://admin:p@ssword@10.0.0.1/live", "rtsp://***:***@10.0.0.1/live"), + ("rtsp://admin:@@@@10.0.0.1/live", "rtsp://***:***@10.0.0.1/live"), + # User only, no password + ("rtsp://admin@10.0.0.1/live", "rtsp://***:***@10.0.0.1/live"), + # Query string is preserved + ("http://user:pwd@cam/snap.cgi?channel=1", "http://***:***@cam/snap.cgi?channel=1"), + ], +) +def test_redact_url_masks_credentials(url, expected): + assert redact_url(url) == expected + + +@pytest.mark.parametrize( + "url", + [ + # No credentials at all: must be returned untouched + "rtsp://10.0.0.1:554/h264", + "srt://1.2.3.4:8890?streamid=publish:cam", + # "@" in the path is not userinfo, the URL must not be mangled + "rtsp://10.0.0.1/live@2", + "http://cam/snap@2x.jpg", + ], +) +def test_redact_url_leaves_credential_free_urls_intact(url): + assert redact_url(url) == url + + +@pytest.mark.parametrize("arg", ["-i", "-f", "mpegts", "-rtsp_transport", "tcp", "1500k"]) +def test_redact_url_leaves_plain_arguments_intact(arg): + """redact_url is mapped over whole ffmpeg command lines, so non-URL args must pass through.""" + assert redact_url(arg) == arg + + +def test_redact_url_never_echoes_password_fragments(): + """Guard against any future split-based regression leaking part of the password.""" + redacted = redact_url("rtsp://admin:sup3r@S3cret!@10.0.0.1/live") + assert "sup3r" not in redacted + assert "S3cret" not in redacted + assert "10.0.0.1" in redacted + + +@pytest.mark.parametrize( + ("url", "leak"), + [ + # MediaMTX streamid auth form: the publish password must never reach the logs. + ("srt://1.2.3.4:8890?streamid=#!::u=pyro,p=S3cret,m=publish", "S3cret"), + ("srt://1.2.3.4:8890?passphrase=S3cret", "S3cret"), + ("http://cam/snap.cgi?usr=admin&pwd=S3cret", "S3cret"), + ("http://cam/snap.cgi?token=abc123", "abc123"), + ], +) +def test_redact_url_masks_credential_parameters(url, leak): + redacted = redact_url(url) + assert leak not in redacted + assert "***" in redacted + + +def test_redact_text_masks_urls_in_free_text(): + """ffmpeg echoes its input URL on stderr; the handler filter must scrub relayed lines.""" + line = "Input #0, rtsp, from 'rtsp://admin:S3cret@10.0.0.1:554/h264_2':" + redacted = redact_text(line) + assert "S3cret" not in redacted + assert "10.0.0.1" in redacted + + +def test_filter_scrubs_records_with_args(): + record = logging.LogRecord( + "any", + logging.INFO, + __file__, + 1, + "[%s] Start pipeline, rtsp %s", + ("10.0.0.1", "rtsp://a:pw@10.0.0.1/live"), + None, + ) + assert RedactSecretsFilter().filter(record) is True + assert "pw" not in record.getMessage() + assert "[10.0.0.1] Start pipeline" in record.getMessage() diff --git a/pyroengine/core.py b/pyroengine/core.py index 92744a63..ea1afb09 100644 --- a/pyroengine/core.py +++ b/pyroengine/core.py @@ -27,7 +27,6 @@ urllib3.disable_warnings(urllib3.exceptions.InsecureRequestWarning) -logging.basicConfig(format="%(asctime)s | %(levelname)s: %(message)s", level=logging.INFO, force=True) logger = logging.getLogger(__name__) @@ -76,23 +75,27 @@ def __init__( engine: Engine, camera_data: Dict[str, Dict[str, Any]], pyro_camera_api_url: str, + heartbeat_file: Optional[str] = None, ) -> None: self.engine = engine self.camera_data = camera_data self.is_day = True self.last_autofocus: Optional[datetime] = None + # Touched on every loop so container liveness does not depend on log content. + self.heartbeat_file = Path(heartbeat_file) if heartbeat_file else None # Wait for the camera API to be available + logger.info("Waiting for Pyro Camera API at %s", pyro_camera_api_url) time.sleep(self.API_INITIAL_WAIT) while True: try: - logger.info("Waiting for Pyro Camera API") self.camera_api_client = PyroCameraAPIClient(pyro_camera_api_url) _ = self.camera_api_client.get_stream_status() logger.info("Pyro Camera API client ready") break except Exception as e: - logger.error(f"API not ready: {e}") + # Expected while the camera API container is still booting. + logger.warning("Camera API not ready yet, retrying in %ds: %s", self.API_RETRY_DELAY, e) time.sleep(self.API_RETRY_DELAY) # Optional startup actions, do not fail hard @@ -100,17 +103,18 @@ def __init__( try: self.camera_api_client.start_patrol(ip) except Exception as e: - logger.warning(f"Could not start patrol on {ip} at startup, continuing: {e}") + logger.warning("[%s] Could not start patrol at startup, continuing: %s", ip, e) # Wait and then loop until inference passes once + logger.info("Waiting for cameras (%d configured)", len(self.camera_data)) time.sleep(self.POST_READY_WAIT) while True: try: - logger.info("Waiting for cameras") self.inference_loop() break except Exception as e: - logger.error(f"Inference failed: {e}") + # Cameras may not have produced a first frame yet, keep waiting. + logger.warning("First inference pass failed, retrying in %ds: %s", self.API_RETRY_DELAY, e) time.sleep(self.API_RETRY_DELAY) def focus_finder(self) -> None: @@ -130,15 +134,18 @@ def focus_finder(self) -> None: continue pose = poses[-1] if self._safe_get_latest_image(ip, pose) is not None: + # The camera answers, so the 2 min per-camera optimization timeout + # must not read as a dead engine. + self._write_heartbeat() try: self.camera_api_client.stop_patrol(ip) time.sleep(0.5) self.camera_api_client.run_focus_optimization(ip) - logger.info(f"Autofocus completed for {ip}") + logger.info("[%s] Autofocus completed", ip) self.camera_api_client.start_patrol(ip) self.last_autofocus = now - except Exception as e: - logger.error(f"[Failed to run hourly focus finder on camera {ip}: {e}") + except Exception: + logger.exception("[%s] Failed to run hourly focus finder", ip) def _any_stream_active(self) -> bool: """ @@ -166,7 +173,7 @@ def _any_stream_active(self) -> bool: return False except Exception as e: - logger.error(f"Could not fetch stream status: {e}") + logger.error("Could not fetch stream status: %s", e) return False def _safe_get_latest_image(self, ip: str, pose: int) -> Optional[Image.Image]: @@ -175,7 +182,7 @@ def _safe_get_latest_image(self, ip: str, pose: int) -> Optional[Image.Image]: except UnidentifiedImageError: return None except Exception as e: - logger.error(f"Error getting image for {ip} pose {pose}: {e}") + logger.error("[%s] Could not get image for pose %s: %s", ip, pose, e) return None def inference_loop(self) -> None: @@ -188,44 +195,79 @@ def inference_loop(self) -> None: logger.info("Stream detected, skipping inference on all cameras") return + start_ts = time.time() + analyzed = 0 + failed = 0 + positive = 0 + max_conf = 0.0 + for ip, cam in self.camera_data.items(): camera_name = cam["name"] + is_ptz = cam.get("type") == "ptz" + # Static cameras expose a single frame under the conventional pose -1. + poses = cam.get("poses", []) if is_ptz else [-1] - if cam.get("type") == "ptz": - for pose in cam.get("poses", []): - if self._any_stream_active(): - logger.info("Stream turned on during loop, stopping inference immediately") - return - try: - cam_id = f"{ip}_{pose}" - frame = self._safe_get_latest_image(ip, pose) - if frame is not None: - logger.info(f"Captured image for {ip}, pose {pose}") - self.is_day = is_day_time(None, frame, "ir") - self.engine.predict(frame, cam_id) - except requests.HTTPError as e: - logger.error( - f"HTTP error for {camera_name}, pose {pose}: " - f"{e.response.text if e.response is not None else e}" - ) - except Exception as e: - logger.error(f"Error for {camera_name}, pose {pose}: {e}") - - else: + for pose in poses: if self._any_stream_active(): logger.info("Stream turned on during loop, stopping inference immediately") return + + cam_id = f"{ip}_{pose}" if is_ptz else ip try: - cam_id = ip - frame = self._safe_get_latest_image(ip, -1) - if frame is not None: - logger.info(f"Captured image for {ip}") - self.is_day = is_day_time(None, frame, "ir") - self.engine.predict(frame, cam_id) + frame = self._safe_get_latest_image(ip, pose) + if frame is None: + failed += 1 + continue + logger.debug("[%s] Captured image from %s", cam_id, camera_name) + # Written only on real progress, so an engine that captures nothing + # goes stale and the healthcheck reports it instead of a fresh file. + self._write_heartbeat() + self.is_day = is_day_time(None, frame, "ir") + conf = float(self.engine.predict(frame, cam_id)) + analyzed += 1 + max_conf = max(max_conf, conf) + # The predictor applies hysteresis (0.8x threshold while an event is + # ongoing), so read its verdict instead of re-deriving the threshold: + # the summary must not say "quiet" while alerts are being staged. + if self.engine._states[cam_id]["ongoing"]: + positive += 1 except requests.HTTPError as e: - logger.error(f"HTTP error for {camera_name}: {e.response.text if e.response is not None else e}") - except Exception as e: - logger.error(f"Error for {camera_name}: {e}") + failed += 1 + body = e.response.text if e.response is not None else e + logger.error("[%s] HTTP error from %s: %s", cam_id, camera_name, body) + except Exception: + failed += 1 + logger.exception("[%s] Inference failed on %s", cam_id, camera_name) + + logger.info( + "Inference round: analyzed=%d failed=%d positive=%d max_confidence=%.2f duration=%.1fs", + analyzed, + failed, + positive, + max_conf, + time.time() - start_ts, + ) + + def _write_heartbeat(self) -> None: + """Refresh the heartbeat file used by the container healthcheck. + + A failure here must not stop detection, so it is reported and execution continues. + """ + if self.heartbeat_file is None: + return + try: + self.heartbeat_file.write_text(datetime.now().isoformat()) + except OSError as e: + logger.warning("Could not write heartbeat file %s: %s", self.heartbeat_file, e) + + def _sleep_with_heartbeat(self, duration: float, step: float = 60.0) -> None: + """Sleep in steps, refreshing the heartbeat, so the long night sleep stays healthy.""" + remaining = duration + while remaining > 0: + self._write_heartbeat() + chunk = min(step, remaining) + time.sleep(chunk) + remaining -= chunk def check_and_restart_patrol(self) -> None: """ @@ -234,7 +276,7 @@ def check_and_restart_patrol(self) -> None: try: stream_status = self.camera_api_client.get_stream_status() except Exception as e: - logger.error(f"Could not check if stream is running: {e}") + logger.error("Could not check if stream is running: %s", e) return active_pipelines = stream_status.get("active_pipelines") or [] @@ -245,9 +287,9 @@ def check_and_restart_patrol(self) -> None: patrol_status = self.camera_api_client.get_patrol_status(ip) if not patrol_status.get("patrol_running", False): self.camera_api_client.start_patrol(ip) - logger.info(f"Patrol restarted on camera {ip}") + logger.info("[%s] Patrol restarted", ip) except Exception as e: - logger.error(f"Could not check or restart patrol on camera {ip}: {e}") + logger.error("[%s] Could not check or restart patrol: %s", ip, e) def main_loop(self, period: int, send_alerts: bool = True) -> None: """ @@ -272,36 +314,34 @@ def main_loop(self, period: int, send_alerts: bool = True) -> None: patrol_status = self.camera_api_client.get_patrol_status(ip) if not patrol_status.get("patrol_running", True): self.camera_api_client.stop_patrol(ip) - logger.info(f"Stopped patrol for camera {ip} due to night") + logger.info("[%s] Patrol stopped for the night", ip) except Exception as e: - logger.error(f"Failed to stop patrol on camera {ip}: {e}") + logger.error("[%s] Failed to stop patrol: %s", ip, e) logger.info("Nighttime detected by at least one camera, sleeping for 1 hour") - time.sleep(3600) + self._sleep_with_heartbeat(3600) try: ip = next(iter(self.camera_data.keys())) frame = self.camera_api_client.capture_image(ip) self.is_day = is_day_time(None, frame, "ir") - logger.info(f"Re checked day and night using camera {ip}, result is_day={self.is_day}") + logger.info("[%s] Re checked day and night, is_day=%s", ip, self.is_day) if self.is_day: logger.info("Day detected, restarting patrols") self.check_and_restart_patrol() time.sleep(30) - logger.info("Patrols restarted successfully, waiting 30 seconds before next check") except Exception as e: - logger.error(f"Failed to check day and night after sleep: {e}") + logger.error("Failed to check day and night after sleep: %s", e) self.is_day = False else: if len(self.engine._alerts) and send_alerts: try: self.engine._process_alerts() - except Exception as e: - logger.error(f"Error processing alerts: {e}") + except Exception: + logger.exception("Error processing alerts") else: - logger.info("Run focus finder") self.focus_finder() self.check_and_restart_patrol() @@ -309,5 +349,7 @@ def main_loop(self, period: int, send_alerts: bool = True) -> None: loop_time = time.time() - start_ts sleep_time = max(period - loop_time, 0) - logger.info(f"Loop run under {loop_time:.2f} seconds, sleeping for {sleep_time:.2f} seconds") + logger.debug("Loop ran in %.2fs, sleeping for %.2fs", loop_time, sleep_time) + # Plain sleep: liveness during the day comes from successful captures, so a + # blind engine must go stale here rather than keep the heartbeat fresh. time.sleep(sleep_time) diff --git a/pyroengine/engine.py b/pyroengine/engine.py index c4440138..3919a456 100644 --- a/pyroengine/engine.py +++ b/pyroengine/engine.py @@ -28,7 +28,6 @@ # Client errors worth retrying later; every other 4xx is a permanent rejection of the payload. RETRYABLE_STATUS = frozenset({408, 425, 429}) -logging.basicConfig(format="%(asctime)s | %(levelname)s: %(message)s", level=logging.INFO, force=True) logger = logging.getLogger(__name__) # Context crop kept in RAM instead of the full-resolution frame. The region keeps a wide field of @@ -82,9 +81,9 @@ def heartbeat_with_timeout(api_instance: Any, cam_id: str, timeout: int = 1) -> try: api_instance.heartbeat(cam_id) except TimeoutError: - logger.warning(f"Heartbeat check timed out for {cam_id}") + logger.warning("[%s] Heartbeat check timed out", cam_id) except RequestsConnectionError: - logger.warning(f"Unable to reach the pyro-api with {cam_id}") + logger.warning("[%s] Unable to reach the pyro-api", cam_id) finally: signal.alarm(0) @@ -272,12 +271,12 @@ def predict( or time.time() - self._states[cam_key]["last_image_sent"] > self.send_last_image_period ): # send image periodically - logger.info(f"Uploading periodical image for cam {cam_id}") + logger.info("[%s] Uploading periodical image", cam_id) self._states[cam_key]["last_image_sent"] = time.time() ip = cam_id.split("_")[0] if ip in self.api_client: response = self.api_client[ip].update_last_image(encoded_bytes) - logger.info(response.text) + logger.debug("[%s] Periodical image response: %s", cam_id, response.text) # Send one pose image per day at 12:00 if isinstance(self.cam_creds, dict) and cam_id in self.cam_creds: @@ -288,17 +287,17 @@ def predict( _, pose_id = self.cam_creds[cam_id] ip = cam_id.split("_")[0] if ip in self.api_client: - logger.info(f"Uploading daily pose image for cam {cam_id} (pose {pose_id})") + logger.info("[%s] Uploading daily pose image (pose %s)", cam_id, pose_id) self._states[cam_key]["last_pose_image_sent"] = now response = self.api_client[ip].update_pose_image(pose_id, encoded_bytes) - logger.info(response.text) + logger.debug("[%s] Daily pose image response: %s", cam_id, response.text) # Update occlusion masks from API if ( self._states[cam_key]["last_bbox_mask_fetch"] is None or time.time() - self._states[cam_key]["last_bbox_mask_fetch"] > self.last_bbox_mask_fetch_period ): - logger.info(f"Update occlusion masks for cam {cam_key}") + logger.debug("[%s] Updating occlusion masks", cam_key) self._states[cam_key]["last_bbox_mask_fetch"] = time.time() if isinstance(cam_id, str) and isinstance(self.cam_creds, dict) and cam_id in self.cam_creds: _, pose_id = self.cam_creds[cam_id] @@ -314,9 +313,10 @@ def predict( coords = tuple(float(c) for c in mask_str.split(",")) bbox_mask_dict[str(mask_entry["id"])] = coords self.occlusion_masks[cam_key] = bbox_mask_dict - logger.info(f"Downloaded occlusion masks for cam {cam_key}: {bbox_mask_dict}") + logger.info("[%s] Downloaded %d occlusion masks", cam_key, len(bbox_mask_dict)) + logger.debug("[%s] Occlusion masks: %s", cam_key, bbox_mask_dict) except RequestException as e: - logger.warning(f"Failed to fetch occlusion masks for cam {cam_key} (pose {pose_id}): {e}") + logger.warning("[%s] Failed to fetch occlusion masks (pose %s): %s", cam_key, pose_id, e) # Inference with ONNX if fake_pred is None: @@ -332,7 +332,7 @@ def predict( preds = preds[(preds[:, 2] - preds[:, 0]) < self.max_bbox_size, :] preds = np.reshape(preds, (-1, 5)) - logger.info(f"pred for {cam_key} : {preds}") + logger.debug("[%s] Raw predictions: %s", cam_key, preds) # Store only a compact JPEG region around the detections so _process_alerts can crop at # full resolution without keeping the whole original frame in RAM. During an ongoing alert, # also cover the frozen fire locations so carried-forward / backfilled crops are cut from the @@ -347,10 +347,11 @@ def predict( if self.save_captured_frames: self._local_backup(frame, cam_id, is_alert=False, encoded_bytes=encoded_bytes) - # Log analysis result - 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%})") + # Log analysis result: a detection is always worth an INFO line, a quiet frame is not. + if conf > self.conf_thresh: + logger.info("[%s] Wildfire detected (confidence: %.2f%%)", cam_key, conf * 100) + else: + logger.debug("[%s] No wildfire (confidence: %.2f%%)", cam_key, conf * 100) # Alert (use ongoing so hysteresis-relaxed threshold keeps staging frames during a dip) if self._states[cam_key]["ongoing"] and len(self.api_client) > 0 and isinstance(cam_id, str): @@ -678,7 +679,7 @@ def _process_alerts(self) -> None: # try to upload the oldest element frame_info = self._alerts[0] cam_id = frame_info["cam_id"] - logger.info(f"Camera '{cam_id}' - Sending alert from {frame_info['ts']}...") + logger.info("[%s] Sending alert from %s", cam_id, frame_info["ts"]) # Save alert on device if self.save_detections_frames: @@ -695,7 +696,7 @@ def _process_alerts(self) -> None: jpeg_bytes = frame_info.get("jpeg_bytes") if jpeg_bytes is None: # The full frame is no longer kept in RAM, so there is nothing to re-encode. - logger.warning(f"Camera '{cam_id}' - skipping alert without encoded frame") + logger.warning("[%s] Skipping alert without encoded frame", cam_id) self._alerts.popleft() continue bboxes = [tuple(bboxe) for bboxe in bboxes] @@ -721,22 +722,20 @@ def _process_alerts(self) -> None: raise RequestException( f"success {response.status_code} without a detection id: {response.text}" ) from None - logger.info(f"Camera '{cam_id}' - alert sent") + logger.info("[%s] Alert sent, %d remaining in cache", cam_id, len(self._alerts) - 1) else: # Rejected for good: keeping the alert would only replay the same failure # and block the whole queue behind it. - logger.error(f"Camera '{cam_id}' - alert rejected ({response.status_code}): {response.text}") + logger.error("[%s] Alert rejected (%s): %s", cam_id, response.status_code, response.text) self._alerts.popleft() except ValueError as e: # The client refused to serialize the payload, so a retry cannot help either. - logger.error(f"Camera '{cam_id}' - invalid alert payload, dropping it") - logger.error(e) + logger.error("[%s] Invalid alert payload, dropping it: %s", cam_id, e) self._alerts.popleft() except (KeyError, RequestException) as e: - logger.error(f"Camera '{cam_id}' - unable to upload cache") - logger.error(e) + logger.error("[%s] Unable to upload cache: %s", cam_id, e) break def _local_backup( diff --git a/pyroengine/logs.py b/pyroengine/logs.py new file mode 100644 index 00000000..303d146f --- /dev/null +++ b/pyroengine/logs.py @@ -0,0 +1,39 @@ +# Copyright (C) 2022-2026, Pyronear. + +# This program is licensed under the Apache License 2.0. +# See LICENSE or go to for full license details. + + +import logging +import os +import sys + +__all__ = ["setup_logging"] + + +def setup_logging() -> None: + """ + Configure application wide logging. + + Priority: + - LOG_LEVEL environment variable + - default INFO + + Only entrypoints should call this: library modules must not configure the root logger. + """ + level_name = os.getenv("LOG_LEVEL", "INFO").upper() + level = getattr(logging, level_name, logging.INFO) + + logging.basicConfig( + level=level, + format="%(asctime)s [%(levelname)s] %(name)s: %(message)s", + handlers=[logging.StreamHandler(sys.stdout)], + force=True, + ) + + # Reduce noise from external libraries. Never below the configured level: a child logger + # level is not re-checked against the root one, so WARNING here would leak warnings + # through an ERROR root. + noisy_level = max(level, logging.WARNING) + logging.getLogger("urllib3").setLevel(noisy_level) + logging.getLogger("PIL").setLevel(noisy_level) diff --git a/pyroengine/sensors.py b/pyroengine/sensors.py index 9c43e342..8c747623 100644 --- a/pyroengine/sensors.py +++ b/pyroengine/sensors.py @@ -18,8 +18,6 @@ __all__ = ["ReolinkCamera"] urllib3.disable_warnings(urllib3.exceptions.InsecureRequestWarning) -# Configure logging -logging.basicConfig(level=logging.DEBUG) logger = logging.getLogger(__name__) diff --git a/src/capture_and_save.py b/src/capture_and_save.py index 21c841a7..784f4367 100644 --- a/src/capture_and_save.py +++ b/src/capture_and_save.py @@ -12,8 +12,13 @@ import numpy as np from dotenv import load_dotenv +from pyroengine.logs import setup_logging from pyroengine.sensors import ReolinkCamera +# Standalone script: nothing else configures logging, without this the INFO output +# from pyroengine.sensors is silently dropped. +setup_logging() + def main(): """ diff --git a/src/control_reolink_cam.py b/src/control_reolink_cam.py index 0406b86a..c9a93eb5 100644 --- a/src/control_reolink_cam.py +++ b/src/control_reolink_cam.py @@ -8,8 +8,13 @@ from dotenv import load_dotenv +from pyroengine.logs import setup_logging from pyroengine.sensors import ReolinkCamera +# Standalone script: nothing else configures logging, without this the INFO output +# from pyroengine.sensors is silently dropped. +setup_logging() + def main(): """ diff --git a/src/focus_finder.py b/src/focus_finder.py index 914f196f..9917851b 100644 --- a/src/focus_finder.py +++ b/src/focus_finder.py @@ -8,8 +8,13 @@ import sys from pathlib import Path +from pyroengine.logs import setup_logging from pyroengine.sensors import ReolinkCamera +# Standalone script: nothing else configures logging, without this the INFO output +# from pyroengine.sensors is silently dropped. +setup_logging() + # ---------------------------------------------------------------------- # Main loop diff --git a/src/run.py b/src/run.py index 55cabdf4..1f62ea68 100644 --- a/src/run.py +++ b/src/run.py @@ -16,18 +16,23 @@ from pyroengine import SystemController from pyroengine.engine import Engine +from pyroengine.logs import setup_logging urllib3.disable_warnings(urllib3.exceptions.InsecureRequestWarning) -logging.basicConfig(format="%(asctime)s | %(levelname)s: %(message)s", level=logging.INFO, force=True) logger = logging.getLogger(__name__) def main(args): - print(args) - # .env loading load_dotenv(".env") + + setup_logging() + logger.info("Starting engine with %s", vars(args)) + # The heartbeat lives on the persisted data mount: a stale file from a previous run + # must not report this boot as healthy before the first real capture. + if args.heartbeat_file: + pathlib.Path(args.heartbeat_file).unlink(missing_ok=True) api_url = os.environ.get("API_URL") assert isinstance(api_url, str) cam_user = os.environ.get("CAM_USER") @@ -83,7 +88,12 @@ def main(args): save_detections_frames=args.save_detections_frames, ) - sys_controller = SystemController(engine, camera_data, args.pyro_camera_api_url) + sys_controller = SystemController( + engine, + camera_data, + args.pyro_camera_api_url, + heartbeat_file=args.heartbeat_file, + ) sys_controller.main_loop(args.period, args.send_alerts) @@ -103,6 +113,12 @@ def main(args): parser.add_argument("--pyro_camera_api_url", type=str, default="http://127.0.0.1:8081", help="Camera api url") parser.add_argument("--creds", type=str, default="data/credentials.json", help="Camera credentials") parser.add_argument("--cache", type=str, default="./data", help="Cache folder") + parser.add_argument( + "--heartbeat-file", + type=str, + default="data/heartbeat", + help="File refreshed on every loop, used by the container healthcheck", + ) parser.add_argument( "--frame-size", type=tuple, diff --git a/src/setup_positions.py b/src/setup_positions.py index 62f61530..4020d667 100644 --- a/src/setup_positions.py +++ b/src/setup_positions.py @@ -13,8 +13,13 @@ import numpy as np from dotenv import load_dotenv +from pyroengine.logs import setup_logging from pyroengine.sensors import ReolinkCamera +# Standalone script: nothing else configures logging, without this the INFO output +# from pyroengine.sensors is silently dropped. +setup_logging() + def main(): """ diff --git a/src/sweep_focus_and_capture.py b/src/sweep_focus_and_capture.py index 9b70d7e4..6aff878a 100644 --- a/src/sweep_focus_and_capture.py +++ b/src/sweep_focus_and_capture.py @@ -11,8 +11,13 @@ from dotenv import load_dotenv +from pyroengine.logs import setup_logging from pyroengine.sensors import ReolinkCamera +# Standalone script: nothing else configures logging, without this the INFO output +# from pyroengine.sensors is silently dropped. +setup_logging() + # Load credentials from .env file load_dotenv() CAM_USER = os.getenv("CAM_USER", "admin") diff --git a/tests/test_core.py b/tests/test_core.py index fc322dab..063164a6 100644 --- a/tests/test_core.py +++ b/tests/test_core.py @@ -1,4 +1,6 @@ +import logging import pathlib +from collections import defaultdict from datetime import datetime from unittest.mock import MagicMock, patch @@ -19,7 +21,10 @@ def fast_sleep(monkeypatch): @pytest.fixture def mock_engine(): engine = MagicMock() - engine.predict.return_value = None + engine.predict.return_value = 0.0 + engine.conf_thresh = 0.25 + # The summary reads the predictor's per-camera verdict, not the raw confidence. + engine._states = defaultdict(lambda: {"ongoing": False}) return engine @@ -80,6 +85,42 @@ def test_inference_loop_triggers_predict(mock_client_class, mock_engine, mock_ca mock_client.get_latest_image.assert_called() +@patch("pyroengine.core.PyroCameraAPIClient") +def test_inference_loop_quiet_round_logs_single_line(mock_client_class, mock_engine, mock_camera_data, caplog): + """A round with no detection reports one INFO summary, not one line per pose.""" + mock_client = mock_client_class.return_value + mock_client.get_latest_image.return_value = Image.new("RGB", (100, 100), (255, 200, 200)) + mock_client.get_stream_status.return_value = {"active_streams": 0} + + controller = SystemController(mock_engine, mock_camera_data, "http://fake.url") + + with caplog.at_level(logging.INFO, logger="pyroengine.core"): + controller.inference_loop() + + info_lines = [r.getMessage() for r in caplog.records if r.levelno == logging.INFO] + assert len(info_lines) == 1 + assert "analyzed=2" in info_lines[0] + assert "positive=0" in info_lines[0] + assert "max_confidence" in info_lines[0] + + +@patch("pyroengine.core.PyroCameraAPIClient") +def test_inference_loop_summary_counts_failures(mock_client_class, mock_engine, mock_camera_data, caplog): + """Poses that fail to capture are reported in the round summary.""" + mock_client = mock_client_class.return_value + mock_client.get_latest_image.side_effect = Exception("camera down") + mock_client.get_stream_status.return_value = {"active_streams": 0} + + controller = SystemController(mock_engine, mock_camera_data, "http://fake.url") + + with caplog.at_level(logging.INFO, logger="pyroengine.core"): + controller.inference_loop() + + summary = [r.getMessage() for r in caplog.records if r.levelno == logging.INFO][-1] + assert "analyzed=0" in summary + assert "failed=2" in summary + + @patch("pyroengine.core.PyroCameraAPIClient") def test_inference_loop_handles_http_error(mock_client_class, mock_engine, mock_camera_data): mock_client = mock_client_class.return_value @@ -111,6 +152,71 @@ def test_inference_loop_handles_generic_error(mock_client_class, mock_engine, mo assert not mock_engine.predict.called +@patch("pyroengine.core.PyroCameraAPIClient") +def test_heartbeat_file_is_written(mock_client_class, mock_engine, mock_camera_data, tmp_path): + """The healthcheck relies on this file, so it must be refreshed independently of log level.""" + mock_client = mock_client_class.return_value + mock_client.get_latest_image.return_value = Image.new("RGB", (100, 100), (255, 200, 200)) + mock_client.get_stream_status.return_value = {"active_streams": 0} + heartbeat = tmp_path / "heartbeat" + + controller = SystemController(mock_engine, mock_camera_data, "http://fake.url", heartbeat_file=str(heartbeat)) + heartbeat.unlink(missing_ok=True) + + controller.inference_loop() + + assert heartbeat.exists() + assert heartbeat.read_text() + + +@patch("pyroengine.core.PyroCameraAPIClient") +def test_heartbeat_not_written_when_no_capture_succeeds(mock_client_class, mock_engine, mock_camera_data, tmp_path): + """A blind engine must go stale so the healthcheck reports it, not stay fresh.""" + mock_client = mock_client_class.return_value + mock_client.get_latest_image.return_value = None + mock_client.get_stream_status.return_value = {"active_streams": 0} + heartbeat = tmp_path / "heartbeat" + + controller = SystemController(mock_engine, mock_camera_data, "http://fake.url", heartbeat_file=str(heartbeat)) + heartbeat.unlink(missing_ok=True) + + controller.inference_loop() + + assert not heartbeat.exists() + + +@patch("pyroengine.core.PyroCameraAPIClient") +def test_summary_counts_ongoing_events_as_positive(mock_client_class, mock_engine, mock_camera_data, caplog): + """The positive count follows the predictor's hysteresis verdict, not the raw threshold.""" + mock_client = mock_client_class.return_value + mock_client.get_latest_image.return_value = Image.new("RGB", (100, 100), (255, 200, 200)) + mock_client.get_stream_status.return_value = {"active_streams": 0} + # Ongoing event whose confidence dipped below conf_thresh: still a positive. + mock_engine.predict.return_value = 0.22 + mock_engine._states = defaultdict(lambda: {"ongoing": True}) + + controller = SystemController(mock_engine, mock_camera_data, "http://fake.url") + + with caplog.at_level(logging.INFO, logger="pyroengine.core"): + controller.inference_loop() + + summary = [r.getMessage() for r in caplog.records if r.levelno == logging.INFO][-1] + assert "positive=2" in summary + + +@patch("pyroengine.core.PyroCameraAPIClient") +def test_heartbeat_write_failure_does_not_raise(mock_client_class, mock_engine, mock_camera_data, tmp_path): + """A broken heartbeat path must not stop detection.""" + mock_client = mock_client_class.return_value + mock_client.get_stream_status.return_value = {"active_streams": 0} + unwritable = tmp_path / "missing_dir" / "heartbeat" + + controller = SystemController(mock_engine, mock_camera_data, "http://fake.url", heartbeat_file=str(unwritable)) + + controller._write_heartbeat() # must not raise + assert not unwritable.exists() + + @patch("pyroengine.core.PyroCameraAPIClient") def test_inference_loop_skips_when_stream_active(mock_client_class, mock_engine, mock_camera_data): mock_client = mock_client_class.return_value diff --git a/tests/test_predictor.py b/tests/test_predictor.py index a82e2ac9..0f08a727 100644 --- a/tests/test_predictor.py +++ b/tests/test_predictor.py @@ -57,25 +57,50 @@ def test_predictor_fake_pred(mock_wildfire_image): assert isinstance(out, float) -def test_predictor_verbose_false_no_logs(mock_wildfire_image, caplog): - """verbose=False suppresses pyro_predictor log output.""" - predictor = Predictor(nb_consecutive_frames=2, verbose=False) +def test_predictor_quiet_frame_no_info_logs(mock_wildfire_image, caplog): + """A frame with no detection stays out of INFO, so a quiet round is silent.""" + predictor = Predictor(nb_consecutive_frames=2) with caplog.at_level(logging.INFO, logger="pyro_predictor"): - predictor.predict(mock_wildfire_image) + predictor.predict(mock_wildfire_image, fake_pred=np.empty((0,))) assert caplog.records == [] -def test_predictor_verbose_true_emits_logs(mock_wildfire_image, caplog): - """verbose=True (default) emits INFO logs.""" - predictor = Predictor(nb_consecutive_frames=2, verbose=True) +def test_predictor_detection_emits_info_log(mock_wildfire_image, caplog): + """A detection is always reported at INFO.""" + predictor = Predictor(nb_consecutive_frames=2) + fake = np.array([[0.1, 0.1, 0.2, 0.2, 0.9], [0.3, 0.3, 0.4, 0.4, 0.8]]).T with caplog.at_level(logging.INFO, logger="pyro_predictor"): - predictor.predict(mock_wildfire_image) - assert any(r.levelno == logging.INFO for r in caplog.records) + predictor.predict(mock_wildfire_image, cam_id="cam_a", fake_pred=fake) + assert any(r.levelno == logging.INFO and "cam_a" in r.getMessage() for r in caplog.records) -def test_classifier_verbose_false_no_logs(tmpdir_factory, caplog): - """Classifier verbose=False suppresses log output during init.""" - folder = str(tmpdir_factory.mktemp("cls_cache")) +def test_predictor_verbose_false_emits_no_info(mock_wildfire_image, caplog): + """verbose=False keeps the caller's INFO stream clean, even on a detection.""" + predictor = Predictor(nb_consecutive_frames=2, verbose=False) + fake = np.array([[0.1, 0.1, 0.2, 0.2, 0.9], [0.3, 0.3, 0.4, 0.4, 0.8]]).T with caplog.at_level(logging.INFO, logger="pyro_predictor"): - Classifier(model_folder=folder, format="onnx", verbose=False) + predictor.predict(mock_wildfire_image, cam_id="cam_a", fake_pred=fake) assert caplog.records == [] + + +def test_verbose_false_does_not_mutate_logger_levels(): + """verbose=False must stay local to the instance, never touch a shared logger level.""" + before = logging.getLogger("pyro_predictor.vision").level + Predictor(nb_consecutive_frames=2, verbose=False) + assert logging.getLogger("pyro_predictor.vision").level == before + + +def test_predictor_frame_details_at_debug(mock_wildfire_image, caplog): + """Per-frame details remain available when DEBUG is enabled.""" + predictor = Predictor(nb_consecutive_frames=2) + with caplog.at_level(logging.DEBUG, logger="pyro_predictor"): + predictor.predict(mock_wildfire_image, fake_pred=np.empty((0,))) + assert any(r.levelno == logging.DEBUG for r in caplog.records) + + +def test_classifier_does_not_configure_root_logger(tmpdir_factory): + """Importing/constructing the library must not install root handlers.""" + folder = str(tmpdir_factory.mktemp("cls_cache")) + root_handlers = list(logging.root.handlers) + Classifier(model_folder=folder, format="onnx", verbose=False) + assert logging.root.handlers == root_handlers