improved logging

python_app/orchestration/config_writer.py

@@ -4,6 +4,7 @@ from __future__ import annotations
 
 from contextlib import suppress
 import json
+import logging
 import os
 from pathlib import Path
 
@@ -16,6 +17,8 @@ from python_app.orchestration.preprocess_assets import (
 )
 from python_app.storage.npz_store import NpzStore
 
+logger = logging.getLogger(__name__)
+
 
 class ConfigWriter:
     """Write runtime artifacts consumed by C++ processes."""
@@ -39,6 +42,7 @@ class ConfigWriter:
             spec = PREPROCESS_ASSET_SPECS[key]
             asset = preprocess_asset_model(config, key)
             bundle_path = self._runtime_dir / spec.runtime_filename
+            logger.debug("Exporting preprocess bundle %s (set=%s) -> %s", key, asset.set_name, bundle_path)
             store.export_set_bundle(spec.set_kind, radar_key, asset.set_name, bundle_path)
             asset.bundle_path = str(bundle_path)
 
@@ -63,10 +67,12 @@ class ConfigWriter:
                 os.fsync(handle.fileno())
             os.replace(tmp_path, output_path)
         except Exception:
+            logger.exception("Failed to write run config to %s; removing temp file", output_path)
             # Never leave a half-written .tmp behind on a write/fsync failure.
             with suppress(OSError):
                 tmp_path.unlink()
             raise
+        logger.debug("Wrote run config to %s (%d bytes)", output_path, len(serialized))
         return output_path
 
 

python_app/orchestration/gui_session_state.py

@@ -61,4 +61,5 @@ class GuiSessionStateStore:
             encoding="utf-8",
         )
         temp_path.replace(self._path)
+        logger.debug("Wrote GUI session-state to %s", self._path)
         return self._path

python_app/orchestration/live_processing_config.py

@@ -4,8 +4,11 @@ from __future__ import annotations
 
 from dataclasses import dataclass
 import json
+import logging
 from pathlib import Path
 
+logger = logging.getLogger(__name__)
+
 
 @dataclass(slots=True)
 class ProcessingLiveConfig:
@@ -148,6 +151,12 @@ class ProcessingLiveConfigWriter:
 
     def write(self, config: ProcessingLiveConfig) -> Path:
         """Atomically write config by temp-file replace."""
+        # Hot path: rewritten on every live knob change, so keep this at DEBUG.
+        logger.debug(
+            "Writing live processing config (mode=%s) to %s",
+            config.processor_mode,
+            self._config_path,
+        )
         temp_path = self._config_path.with_suffix(self._config_path.suffix + ".tmp")
         temp_path.write_text(json.dumps(config.to_dict(), indent=2), encoding="utf-8")
         temp_path.replace(self._config_path)

python_app/orchestration/pipeline_metrics.py

@@ -15,8 +15,11 @@ from __future__ import annotations
 
 from collections import deque
 from dataclasses import dataclass
+import logging
 from typing import Callable, Iterable
 
+logger = logging.getLogger(__name__)
+
 
 @dataclass(frozen=True, slots=True)
 class MetricReport:
@@ -64,6 +67,7 @@ class PipelineMetrics:
         self._report_every = int(report_every)
         self._log_sink = log_sink
         self._buffers: dict[str, deque[int]] = {}
+        logger.debug("PipelineMetrics init: report_every=%d", self._report_every)
 
     def set_log_sink(self, log_sink: Callable[[str], None] | None) -> None:
         """Reassign the log sink (used when the GUI log appears after init)."""

python_app/orchestration/process_supervisor.py

@@ -4,6 +4,7 @@ from __future__ import annotations
 
 from dataclasses import dataclass
 import json
+import logging
 import os
 from pathlib import Path
 import shlex
@@ -14,11 +15,13 @@ import time
 from typing import Iterable
 from typing import Sequence
 
+logger = logging.getLogger(__name__)
+
 # Cap each child log so a long-lived daemon cannot fill the SD card. On reaching
 # the cap the current log is rolled to `{name}.{out,err}.log.prev` and a fresh
 # log opened (see `_roll_log_if_oversized`).
 _LOG_MAX_BYTES = 8 * 1024 * 1024
-# Per-process force-kill deadline used on stop (Fix #33: own deadline each).
+# Per-process force-kill deadline used on stop; each child gets its own window.
 _STOP_GRACE_SECONDS = 2.0
 
 
@@ -40,7 +43,7 @@ class ProcessExitReport:
 
     Log tails are not held in memory: they are read on demand from the child log
     files only while rendering an ERROR report, so the common clean-exit path on
-    every poll never pays for a 16KB read of two files (Fix #46).
+    every poll never pays for a 16KB read of two files.
     """
 
     name: str
@@ -110,9 +113,14 @@ class ProcessSupervisor:
         self._readiness_timeout_s = readiness_timeout_s
         self._processes: dict[str, ManagedProcess] = {}
         # Runtime pidfile lets us reap pipeline children left behind by a prior
-        # supervisor (crash/SIGKILL) independent of in-memory state (Fix #19).
+        # supervisor (crash/SIGKILL) independent of in-memory state.
         self._runtime_dir = self._project_root / "python_app/runtime"
         self._pidfile_path = self._runtime_dir / "supervisor_children.pids"
+        logger.debug(
+            "ProcessSupervisor init: root=%s readiness_timeout=%.1fs",
+            self._project_root,
+            self._readiness_timeout_s,
+        )
         self._reap_stale_children()
 
     def is_running(self) -> bool:
@@ -128,6 +136,11 @@ class ProcessSupervisor:
         if self.is_running():
             raise RuntimeError("Acquisition processes are already running")
 
+        logger.info(
+            "Starting pipeline from config %s (allow_clean_orchestrator_exit=%s)",
+            config_path,
+            allow_clean_orchestrator_exit,
+        )
         acquisition_command = self._acquisition_command(config_path)
         command_specs = {
             "data_processor": [
@@ -161,12 +174,15 @@ class ProcessSupervisor:
             )
             self._wait_until_ready(required_processes)
         except Exception:
+            logger.exception("Pipeline start failed; tearing down spawned processes")
             if processor_was_running:
                 self.stop()
             else:
                 self.stop_all()
             raise
 
+        logger.info("Pipeline started; live pids=%s", self.pids() or "none")
+
     def stop(self) -> None:
         """Stop acquisition-side processes, keep processor process intact."""
         self._stop_processes(["sweep_orchestrator", "data_preprocessor"])
@@ -194,6 +210,7 @@ class ProcessSupervisor:
         """
         existing = self._processes.get(name)
         if existing is not None and existing.handle.poll() is None:
+            logger.debug("Spawn skipped: `%s` already running (pid=%s)", name, existing.handle.pid)
             return
 
         logs_dir = self._project_root / "python_app/runtime/logs"
@@ -202,7 +219,7 @@ class ProcessSupervisor:
         stderr_path = logs_dir / f"{name}.err.log"
 
         # Roll any stale (uncollected) log to `.prev` before truncating so the
-        # previous run's diagnostics survive a respawn (Fix #29).
+        # previous run's diagnostics survive a respawn.
         self._roll_log_to_prev(stdout_path)
         self._roll_log_to_prev(stderr_path)
 
@@ -215,14 +232,14 @@ class ProcessSupervisor:
                 stdout=stdout_file,
                 stderr=stderr_file,
                 # Own session/process group so signalling the group on stop also
-                # reaches device-I/O grandchildren the producer may have spawned
-                # (Fix #33).
+                # reaches device-I/O grandchildren the producer may have spawned.
                 start_new_session=True,
             )
         except OSError as exc:
             stdout_file.close()
             stderr_file.close()
             command_text = shlex.join(command)
+            logger.error("Failed to spawn `%s`: %s: %s", name, type(exc).__name__, exc)
             raise RuntimeError(
                 f"Failed to spawn {name} with command `{command_text}` from `{self._project_root}`: "
                 f"{type(exc).__name__}: {exc}"
@@ -240,11 +257,13 @@ class ProcessSupervisor:
             stdout_path=stdout_path,
             stderr_path=stderr_path,
         )
+        logger.info("Spawned `%s` (pid=%d)", name, handle.pid)
         self._write_pidfile()
 
     def _acquisition_command(self, config_path: Path) -> list[str]:
         """Return acquisition producer command selected by radar.model."""
         radar_model = self._read_radar_model(config_path)
+        logger.debug("Selecting acquisition producer for radar.model=%s", radar_model)
         if radar_model in {"librevna_multi", "sn9000"}:
             return [
                 sys.executable,
@@ -286,7 +305,8 @@ class ProcessSupervisor:
             if process is None:
                 continue
             if process.handle.poll() is None:
-                # Signal the whole group so device-I/O grandchildren die too (Fix #33).
+                logger.info("Stopping `%s` (pid=%d): sending SIGTERM to group", name, process.handle.pid)
+                # Signal the whole group so device-I/O grandchildren die too.
                 self._signal_group(process.handle.pid, signal.SIGTERM)
 
         for name in ordered_names:
@@ -298,15 +318,20 @@ class ProcessSupervisor:
                 continue
 
             # Each process gets its own kill deadline so a slow shutdown of one
-            # cannot consume the grace window of the others (Fix #33).
+            # cannot consume the grace window of the others.
             try:
                 process.handle.wait(timeout=_STOP_GRACE_SECONDS)
             except subprocess.TimeoutExpired:
+                logger.warning(
+                    "`%s` did not exit within %.1fs of SIGTERM; sending SIGKILL",
+                    name,
+                    _STOP_GRACE_SECONDS,
+                )
                 self._signal_group(process.handle.pid, signal.SIGKILL)
                 try:
                     process.handle.wait(timeout=1.0)
                 except subprocess.TimeoutExpired:
-                    pass
+                    logger.error("`%s` still alive after SIGKILL", name)
             else:
                 # A negative code here is the SIGTERM we just sent (expected); only
                 # a positive self-exit during the grace window is worth noting.
@@ -330,7 +355,7 @@ class ProcessSupervisor:
 
     @staticmethod
     def _log_abnormal_stop_exit(process: ManagedProcess) -> None:
-        """Note a process that self-exited abnormally around stop time (Fix #33).
+        """Log a process that self-exited abnormally around stop time.
 
         Negative codes are signal-induced (e.g. the SIGTERM we send on stop) and
         are expected; only a non-zero self-exit is reported.
@@ -338,11 +363,7 @@ class ProcessSupervisor:
         return_code = process.handle.poll()
         if return_code is None or return_code <= 0:
             return
-        print(
-            f"process_supervisor: `{process.name}` exited abnormally with code "
-            f"{return_code} around stop",
-            file=sys.stderr,
-        )
+        logger.warning("`%s` exited abnormally with code %d around stop", process.name, return_code)
 
     def _drop_exited(self) -> None:
         """Remove exited process entries from internal map."""
@@ -367,11 +388,12 @@ class ProcessSupervisor:
         for name, process in self._processes.items():
             return_code = process.handle.poll()
             if return_code is None:
-                # Still running: enforce the size cap so logs never grow unbounded (Fix #16).
+                # Still running: enforce the size cap so logs never grow unbounded.
                 self._roll_log_if_oversized(process.stdout_path)
                 self._roll_log_if_oversized(process.stderr_path)
                 continue
 
+            logger.debug("Reaped `%s` with exit code %d", process.name, int(return_code))
             reports.append(
                 ProcessExitReport(
                     name=process.name,
@@ -394,6 +416,7 @@ class ProcessSupervisor:
     def _wait_until_ready(self, required_processes: Sequence[str]) -> None:
         """Wait until all required processes are alive or timeout/crash occurs."""
         deadline = time.monotonic() + self._readiness_timeout_s
+        logger.debug("Waiting for processes to become ready: %s", ", ".join(required_processes))
 
         while time.monotonic() < deadline:
             exit_reports = self.collect_exit_reports()
@@ -401,6 +424,7 @@ class ProcessSupervisor:
             if unexpected_reports:
                 raise RuntimeError("; ".join(report.format() for report in unexpected_reports))
             if all(self._is_alive(process_name) for process_name in required_processes):
+                logger.debug("All required processes ready")
                 return
             time.sleep(0.05)
 
@@ -420,7 +444,7 @@ class ProcessSupervisor:
 
     @staticmethod
     def _roll_log_to_prev(path: Path) -> None:
-        """Roll an existing log to `{path}.prev` before it is reopened (Fix #29).
+        """Roll an existing log to `{path}.prev` before it is reopened.
 
         Preserves a stale (exited, not-yet-reported) child's last output instead
         of truncating it when a fresh log is opened for a respawn.
@@ -435,7 +459,7 @@ class ProcessSupervisor:
 
     @staticmethod
     def _roll_log_if_oversized(path: Path) -> None:
-        """Bound a live child log to `_LOG_MAX_BYTES` so it cannot fill the SD card (Fix #16).
+        """Bound a live child log to `_LOG_MAX_BYTES` so it cannot fill the SD card.
 
         The child holds an open fd to this inode, so a rename would not redirect
         its writes. Instead keep one rolled generation via copy-to-`.prev` and
@@ -458,7 +482,7 @@ class ProcessSupervisor:
             pass
 
     def _write_pidfile(self) -> None:
-        """Persist live child PIDs so a later supervisor can reap them (Fix #19)."""
+        """Persist live child PIDs so a later supervisor can reap them."""
         try:
             self._runtime_dir.mkdir(parents=True, exist_ok=True)
             live_pids = [
@@ -472,7 +496,7 @@ class ProcessSupervisor:
             pass
 
     def _reap_stale_children(self) -> None:
-        """Kill pipeline children recorded by a prior supervisor instance (Fix #19).
+        """Kill pipeline children recorded by a prior supervisor instance.
 
         On a clean shutdown the pidfile is emptied; entries only remain when the
         previous supervisor died without stopping its children. We SIGKILL each
@@ -493,6 +517,7 @@ class ProcessSupervisor:
             # Guard against PID reuse: only reap if the process still looks like
             # one of our pipeline children before signalling its group.
             if self._is_stale_pipeline_pid(pid):
+                logger.warning("Reaping stale pipeline child from prior run (pid=%d)", pid)
                 self._signal_group(pid, signal.SIGKILL)
         try:
             self._pidfile_path.write_text("", encoding="utf-8")
@@ -503,7 +528,7 @@ class ProcessSupervisor:
         """Return whether `pid` still runs one of our pipeline binaries/scripts.
 
         Reads `/proc/<pid>/cmdline` so a recycled PID owned by an unrelated
-        process is never killed (Fix #19 safety guard).
+        process is never killed.
         """
         markers = (
             "build/bin/data_processor",

python_app/orchestration/shm/ring_reader.py

@@ -2,6 +2,7 @@
 
 from __future__ import annotations
 
+import logging
 import mmap
 from pathlib import Path
 import struct
@@ -16,6 +17,8 @@ from python_app.orchestration.shm.decoder import (
     decode_trace_collection,
 )
 
+logger = logging.getLogger(__name__)
+
 _HEADER_SIZE: Final[int] = 64
 _SLOT_HEADER_SIZE: Final[int] = 16
 _MAGIC: Final[bytes] = b"RDRRING2"
@@ -43,6 +46,12 @@ class ShmRingReader:
             # A fail-fast open (absent/incompatible ring) must not leak the fd/mapping.
             self.close()
             raise
+        logger.debug(
+            "Opened SHM ring reader %s (capacity=%d, slot_size=%d bytes)",
+            self._ring_name,
+            self.capacity,
+            self.slot_size_bytes,
+        )
 
     def close(self) -> None:
         """Close mmap and file handle."""
@@ -50,6 +59,7 @@ class ShmRingReader:
             self._mmap.close()
             self._mmap = None
         self._file.close()
+        logger.debug("Closed SHM ring reader %s", self._ring_name)
 
     def pop_payload(self) -> bytes | None:
         """Read next payload from ring, or `None` if no unread payload exists."""
@@ -68,6 +78,7 @@ class ShmRingReader:
         sequence = self._read_u64(slot_offset + 8)
         if sequence != read_seq + 1:
             # Producer overwrote this slot before we read it. Resync to latest.
+            logger.debug("Ring %s: slot lapped before read, resyncing to write_seq=%d", self._ring_name, write_seq)
             self._write_u64(32, write_seq)
             return None
 
@@ -75,6 +86,12 @@ class ShmRingReader:
         # Bound payload_size against the slot before slicing so a torn/garbage size
         # can never read out of the slot region; resync and skip on violation.
         if payload_size > self.slot_size_bytes:
+            logger.debug(
+                "Ring %s: payload_size %d exceeds slot %d, resyncing",
+                self._ring_name,
+                payload_size,
+                self.slot_size_bytes,
+            )
             self._write_u64(32, write_seq)
             return None
 
@@ -84,6 +101,7 @@ class ShmRingReader:
         # Re-read the slot sequence after the copy; if it changed, the producer
         # overwrote this slot mid-copy and the payload is torn — discard and resync.
         if self._read_u64(slot_offset + 8) != read_seq + 1:
+            logger.debug("Ring %s: slot overwritten mid-copy, discarding torn payload", self._ring_name)
             self._write_u64(32, write_seq)
             return None
 
@@ -158,6 +176,7 @@ class ShmRingReader:
             return 0
         dropped = int(write_seq - read_seq)
         self._write_u64(32, write_seq)
+        logger.debug("Ring %s: dropped %d unread payload(s)", self._ring_name, dropped)
         return dropped
 
     @property

python_app/orchestration/shm/ring_writer.py

@@ -2,12 +2,15 @@
 
 from __future__ import annotations
 
+import logging
 import mmap
 import os
 from pathlib import Path
 import struct
 from typing import Final
 
+logger = logging.getLogger(__name__)
+
 _HEADER_SIZE: Final[int] = 64
 _SLOT_HEADER_SIZE: Final[int] = 16
 _MAGIC: Final[bytes] = b"RDRRING2"
@@ -58,17 +61,26 @@ class ShmRingWriter:
             # Wrong-sized stale segment: drop it entirely and recreate, so the file
             # and any future mapping agree on geometry instead of being truncated
             # under a producer/consumer that still expects the old layout.
+            if not created:
+                logger.info("Ring %s: stale segment with wrong size, recreating", self._ring_name)
             self._file.truncate(self._mapped_size)
             created = True
 
         self._mmap = mmap.mmap(self._file.fileno(), self._mapped_size)
         if created:
             self._initialize_header()
+            logger.debug(
+                "Created SHM ring writer %s (capacity=%d, slot_size=%d bytes)",
+                self._ring_name,
+                self._capacity,
+                self._slot_size_bytes,
+            )
             return
 
         # Size matched but the header geometry/magic does not: the owner recreates
         # rather than diverge. Unlink and reopen as a brand-new ring.
         if not self._header_matches():
+            logger.warning("Ring %s: header/geometry mismatch on existing segment, recreating", self._ring_name)
             self._mmap.close()
             self._file.close()
             self._unlink_if_present()
@@ -77,6 +89,8 @@ class ShmRingWriter:
             self._file.truncate(self._mapped_size)
             self._mmap = mmap.mmap(self._file.fileno(), self._mapped_size)
             self._initialize_header()
+        else:
+            logger.debug("Reusing existing SHM ring writer %s", self._ring_name)
 
     def _unlink_if_present(self) -> None:
         """Remove the backing /dev/shm file if it exists (owner-only operation)."""
@@ -89,6 +103,7 @@ class ShmRingWriter:
         """Close mmap and file handle."""
         self._mmap.close()
         self._file.close()
+        logger.debug("Closed SHM ring writer %s", self._ring_name)
 
     def push(self, payload: bytes) -> bool:
         """Push one payload with overwrite-oldest semantics on overflow."""
@@ -98,6 +113,10 @@ class ShmRingWriter:
         write_seq = self._read_u64(24)
         read_seq = self._read_u64(32)
         if max(0, write_seq - read_seq) >= self._capacity:
+            # Ring full: the consumer is not keeping up, so the oldest unread slot is
+            # overwritten (overwrite-oldest). Logged at DEBUG to avoid flooding the
+            # log when a backlog persists across many pushes.
+            logger.debug("Ring %s: full, overwriting oldest unread slot", self._ring_name)
             # Advance the consumer cursor past the slot we are about to overwrite, but
             # re-read it first and move it only forward: a concurrent reader may have
             # already advanced it, and clobbering that backward would re-deliver an