diff --git a/python_app/generator_sweep/config.py b/python_app/generator_sweep/config.py index 3e43687..ed8f35a 100644 --- a/python_app/generator_sweep/config.py +++ b/python_app/generator_sweep/config.py @@ -3,6 +3,10 @@ from __future__ import annotations from dataclasses import dataclass +import logging + +logger = logging.getLogger(__name__) + @dataclass(slots=True, frozen=True) class GeneratorSweepConfig: @@ -85,8 +89,6 @@ def _validate_positive_float(value: float, label: str) -> None: def _resolve_log_level(value: str) -> int: """Normalize logging level name to ``logging`` module integer constant.""" - import logging - normalized = value.strip().upper() if not normalized: raise ValueError("generator_sweep.log_level must not be empty") @@ -179,6 +181,15 @@ def resolve_generator_sweep_config(model: GeneratorSweepConfig) -> ResolvedGener "generator_sweep.pwm_duty_cycle must be within (0, 1]", ) + logger.debug( + "Resolved generator sweep config: points=%d start=%dHz stop=%dHz loop=%s port=%d", + len(frequencies_hz), + frequencies_hz[0], + frequencies_hz[-1], + bool(model.loop), + int(model.port), + ) + return ResolvedGeneratorSweepConfig( log_level=log_level, serial=(model.serial.strip() or None) if isinstance(model.serial, str) else model.serial, diff --git a/python_app/generator_sweep/pwm.py b/python_app/generator_sweep/pwm.py index 67bb52d..619125a 100644 --- a/python_app/generator_sweep/pwm.py +++ b/python_app/generator_sweep/pwm.py @@ -3,8 +3,11 @@ from __future__ import annotations from dataclasses import dataclass, field +import logging from pathlib import Path +logger = logging.getLogger(__name__) + _PWM_CHANNEL_BY_PIN = { 12: 0, @@ -53,12 +56,14 @@ class HardwarePwmGate: self._pwm = HardwarePWM(pwm_channel=channel, hz=self.frequency_hz, chip=0) except Exception as exc: config_hint = _boot_config_hint() + logger.exception("Failed to initialize hardware PWM on GPIO%d (channel %d)", self.pin, channel) raise RuntimeError( "Failed to initialize Raspberry Pi hardware PWM. " f"Enable the PWM overlay in {config_hint} by adding " "'dtoverlay=pwm-2chan', then reboot the Raspberry Pi." ) from exc self._running = False + logger.info("Hardware PWM opened on GPIO%d at %d Hz", self.pin, self.frequency_hz) def enable(self) -> None: """Start PWM output when not already running.""" @@ -81,6 +86,8 @@ class HardwarePwmGate: def close(self) -> None: """Stop PWM and release runtime state.""" self.disable() + if self._pwm is not None: + logger.info("Hardware PWM closed on GPIO%d", self.pin) self._pwm = None diff --git a/python_app/generator_sweep/runner.py b/python_app/generator_sweep/runner.py index 529ad3b..ffdad82 100644 --- a/python_app/generator_sweep/runner.py +++ b/python_app/generator_sweep/runner.py @@ -45,11 +45,13 @@ class _MarkerOutputs: self._lines.open() self._is_open = True self.reset_to_idle() + logger.debug("Generator sweep marker GPIO lines opened") def close(self) -> None: """Release GPIO lines.""" self._is_open = False self._lines.close() + logger.debug("Generator sweep marker GPIO lines closed") def begin_sweep(self) -> None: """Raise sweep marker while preserving current step level.""" @@ -170,6 +172,7 @@ class GeneratorSweepRunner: self._markers.toggle_step() self._wait_for_generator_ready() self._emit_pwm_window() + logger.debug("Completed generator sweep pass over %d frequencies", len(self._config.frequencies_hz)) finally: self._pwm.disable() self._markers.end_sweep() diff --git a/python_app/gui/app_window.py b/python_app/gui/app_window.py index 1f4a490..d4c9602 100644 --- a/python_app/gui/app_window.py +++ b/python_app/gui/app_window.py @@ -12,13 +12,12 @@ from datetime import datetime import html import json import logging -from logging.handlers import RotatingFileHandler import os from pathlib import Path import sys import traceback -from PyQt6.QtCore import QTimer +from PyQt6.QtCore import QObject, QTimer, pyqtSignal from PyQt6.QtGui import QTextCursor from PyQt6.QtWidgets import QApplication, QMainWindow, QMessageBox @@ -40,12 +39,56 @@ from python_app.orchestration.pipeline_metrics import PipelineMetrics from python_app.orchestration.preprocess_assets import VISIBLE_PREPROCESS_ASSET_KEYS, preprocess_asset_model from python_app.orchestration.process_supervisor import ProcessSupervisor from python_app.orchestration.shm_reader import ShmRingReader +from python_app.logging_setup import ( + DEFAULT_LOG_LEVEL, + add_handler, + configure_logging, + get_logger, + set_log_level, +) from python_app.storage.npz_store import NpzStore from python_app.workflows.multi_radar_capture_workflow import MultiRadarSequentialCaptureSession from python_app.workflows.radar_config_variants import RadarConfigScanSummary, RadarConfigVariant from python_app.workflows.sequential_capture_workflow import SequentialCaptureSession +def _panel_extra(details: str | None, once_key: str | None) -> dict[str, object]: + """Carry GUI-panel-only fields (details block, once-key dedup) on a log record.""" + return {"panel_details": details, "panel_once_key": once_key} + + +class _PanelLogBridge(QObject): + """Marshals log records from any thread onto the GUI thread for panel rendering. + + A :class:`logging.Handler` can fire on a worker thread (readers, broadcaster), + but the log widget may only be touched on the GUI thread; emitting this queued + signal hands the record across safely (the GPIO-button pattern). + """ + + record = pyqtSignal(str, str, object, object) # display level, message, details, once_key + + +class _QtLogPanelHandler(logging.Handler): + """Logging handler that forwards application log records to the GUI log panel.""" + + def __init__(self, bridge: _PanelLogBridge) -> None: + super().__init__() + self._bridge = bridge + + def emit(self, record: logging.LogRecord) -> None: + """Forward one record to the panel bridge, mapping WARNING to the short 'WARN'.""" + try: + display_level = "WARN" if record.levelname == "WARNING" else record.levelname + self._bridge.record.emit( + display_level, + record.getMessage(), + getattr(record, "panel_details", None), + getattr(record, "panel_once_key", None), + ) + except Exception: # noqa: BLE001 - logging must never raise into the caller + self.handleError(record) + + class AppWindow( AppWindowUiMixin, AppWindowConfigMixin, @@ -64,7 +107,7 @@ class AppWindow( super().__init__() self._init_paths(project_root) - self._init_headless_logger() + self._init_logging() self._init_runtime_services() self._init_config_profile_state() self._init_reader_handles() @@ -85,39 +128,35 @@ class AppWindow( # Guards closeEvent against re-entrant teardown (e.g. a second signal). self._closing = False - def _init_headless_logger(self) -> None: - """Create a Python logger so headless WARN/ERROR reach journald and disk. + def _init_logging(self) -> None: + """Configure the application logger and the bridge that feeds the GUI panel. - In headless mode the in-app log only reaches an offscreen widget, so an - operator (or `journalctl`) would never see failures. We attach a stderr - StreamHandler (captured by journald) plus a small rotating file under - `runtime/logs`; in GUI mode no handler is attached and the logger stays - inert, preserving the visible log widget as the sole sink. + Installs the rotating-file (``runtime/logs/radar.log``) and stderr handlers on + the ``python_app`` logger so every module's logs — and the GUI's own ``_log*`` + calls — share one level-controlled, rotated pipeline. The verbosity floor starts + at the default and is replaced with the configured level once run_config loads; + the GUI panel is wired in once its widget exists (see ``_attach_log_panel``). """ - self._headless_logger: logging.Logger | None = None - if not self._is_truthy_env("RADAR_SYSTEM_HEADLESS"): + log_dir = self._project_root / "python_app/runtime/logs" + configure_logging(level=DEFAULT_LOG_LEVEL, log_dir=log_dir, console=True) + self._gui_logger = get_logger("gui") + self._log_panel_bridge = _PanelLogBridge() + self._log_panel_bridge.record.connect(self._on_log_record) + + def _attach_log_panel(self) -> None: + """Route application log records into the on-screen panel (widget now exists).""" + add_handler(_QtLogPanelHandler(self._log_panel_bridge)) + + def _on_log_record(self, level: str, text: str, details: object, once_key: object) -> None: + """Render one forwarded log record in the panel (always on the GUI thread).""" + if not hasattr(self, "_log_box"): return - logger = logging.getLogger("radar_system.gui") - logger.setLevel(logging.WARNING) - logger.propagate = False - logger.handlers.clear() - formatter = logging.Formatter( - fmt="%(asctime)s | %(levelname)-5s | %(message)s", - datefmt="%Y-%m-%d %H:%M:%S", + self._append_log_entry( + level, + text, + details=details if isinstance(details, str) else None, + once_key=once_key if isinstance(once_key, str) else None, ) - stream_handler = logging.StreamHandler(stream=sys.stderr) - stream_handler.setFormatter(formatter) - logger.addHandler(stream_handler) - # A rotating file keeps recent failures around after a journald restart. - with suppress(Exception): - log_dir = self._project_root / "python_app/runtime/logs" - log_dir.mkdir(parents=True, exist_ok=True) - file_handler = RotatingFileHandler( - log_dir / "gui.log", maxBytes=1_000_000, backupCount=3, encoding="utf-8" - ) - file_handler.setFormatter(formatter) - logger.addHandler(file_handler) - self._headless_logger = logger def _init_runtime_services(self) -> None: """Initialize long-lived service objects used by mixins.""" @@ -155,7 +194,12 @@ class AppWindow( return 50 def _init_config_profile_state(self) -> None: - """Resolve startup profile path, load active profile, and queue fallback notices.""" + """Resolve the startup profile path, load the active profile, and queue any + fallback notices for replay once the log panel exists. + + On failure to load a non-root profile, falls back to the root run_config.json; + a failure to load the root profile itself is fatal and re-raised. + """ active_profile_path = self._resolve_startup_profile_path() try: profile = GuiProfileModel.load_from_path(active_profile_path) @@ -172,6 +216,7 @@ class AppWindow( self._active_profile_path = active_profile_path self._defaults_config = profile.run_config.clone() + set_log_level(self._defaults_config.logging.level) if profile.gui is not None: self._gui_defaults = profile.gui else: @@ -277,8 +322,13 @@ class AppWindow( self._timer.timeout.connect(self._poll_rings) def _bootstrap_ui_runtime(self) -> None: - """Build UI and apply initial runtime-bound state after widgets exist.""" + """Build the UI and apply initial runtime-bound state once widgets exist. + + This is the first point at which the log panel is wired in, so it also + replays any startup entries buffered during the headless init phase. + """ self._build_ui() + self._attach_log_panel() self._flush_pending_startup_log_entries() self._log(f"Active config profile: {self._active_profile_path}") self._refresh_preprocess_summary_labels() @@ -293,6 +343,10 @@ class AppWindow( self._init_web_ui() if self._is_truthy_env("RADAR_SYSTEM_HEADLESS"): self._install_headless_watchdog() + self._log_debug( + f"Window bootstrap complete (mode={self._active_processing_mode}, " + f"ring poll interval={self._timer.interval()}ms)." + ) def _resolve_startup_profile_path(self) -> Path: """Resolve active profile path from session-state or root fallback path.""" @@ -373,6 +427,7 @@ class AppWindow( self._headless_watchdog.setInterval(2000) self._headless_watchdog.timeout.connect(self._headless_watchdog_tick) self._headless_watchdog.start() + self._log_debug("Headless watchdog armed (interval=2000ms).") def _headless_watchdog_tick(self) -> None: """Escalate any unexpected managed-process exit to a fatal headless restart.""" @@ -410,7 +465,11 @@ class AppWindow( return path.expanduser().resolve(strict=False) def _remember_active_profile_path(self, path: Path, *, startup: bool = False) -> None: - """Persist last successfully used config profile path.""" + """Persist the last successfully used config profile path to GUI session-state. + + A write failure is non-fatal: it is queued during startup or logged as a + warning afterwards, since it only affects which profile reopens next launch. + """ normalized_path = self._normalize_profile_path(path) self._active_profile_path = normalized_path try: @@ -434,19 +493,29 @@ class AppWindow( self._pending_startup_log_entries.append((level.upper(), text, details)) def _flush_pending_startup_log_entries(self) -> None: - """Flush startup log entries into the runtime log box after UI creation.""" - if not self._pending_startup_log_entries: - return + """Replay queued startup entries through the logger now that every sink exists. + Entries logged before the panel widget existed were buffered; routing them + through the logger here delivers them to the file/console and the panel at once. + """ + levels = {"WARN": logging.WARNING, "ERROR": logging.ERROR} for level, text, details in self._pending_startup_log_entries: - self._append_log_entry(level, text, details=details) + self._gui_logger.log(levels.get(level, logging.INFO), text, extra=_panel_extra(details, None)) self._pending_startup_log_entries.clear() def _apply_initial_radar_limits(self) -> None: - """Apply startup radar-limits strategy according to selected radar mode.""" + """Apply the startup radar-limits strategy according to the selected radar mode. + + In ``native`` mode the limits are queried from the connected device; otherwise + the UI is populated with no device-imposed limits. + """ if self._defaults_config.radar.driver_mode == "native": + self._log_debug("Querying radar limits from device (native driver mode).") self._refresh_radar_limits_from_device() return + self._log_debug( + f"Skipping device radar-limit query (driver mode={self._defaults_config.radar.driver_mode})." + ) self._apply_radar_limits_to_ui(None) @staticmethod @@ -483,6 +552,7 @@ class AppWindow( level_upper = level.upper() palette = { + "DEBUG": ("#6c7b8d", "#52627a", "#8a97a8"), "INFO": ("#1d5fbf", "#1f2937", "#526277"), "WARN": ("#9a5b00", "#5c4300", "#7a6640"), "ERROR": ("#c43d4d", "#6b1f2a", "#8b5d66"), @@ -513,26 +583,32 @@ class AppWindow( if level_upper == "ERROR" and hasattr(self, "_status_label"): self._status_label.setText("Status: error") - # In headless mode the offscreen widget above is invisible, so also mirror - # WARN/ERROR to the Python logger (stderr -> journald, plus rotating file) - # where an operator can actually observe failures. - headless_logger = getattr(self, "_headless_logger", None) - if headless_logger is not None and level_upper in {"WARN", "ERROR"}: - log_message = text if not details else f"{text}\n{details}" - log_level = logging.ERROR if level_upper == "ERROR" else logging.WARNING - headless_logger.log(log_level, log_message) + def _on_log_level_selected(self, level_text: str) -> None: + """Apply the chosen log level immediately (sub-level logs stop being generated). + + The value lives in run_config like any other field: it is recorded in the active + config here and saved with the config through the normal path — no separate write. + """ + level = level_text.strip().lower() + set_log_level(level) + self._defaults_config.logging.level = level + self._log(f"Log level set to {level.upper()}.") + + def _log_debug(self, text: str, *, once_key: str | None = None) -> None: + """Log a diagnostic message (emitted only while the level is DEBUG).""" + self._gui_logger.debug(text, extra=_panel_extra(None, once_key)) def _log(self, text: str, *, once_key: str | None = None) -> None: - """Append informational message to runtime log panel.""" - self._append_log_entry("INFO", text, once_key=once_key) + """Log an informational message to the panel, file, and console.""" + self._gui_logger.info(text, extra=_panel_extra(None, once_key)) def _log_warning(self, text: str, *, details: str | None = None, once_key: str | None = None) -> None: - """Append warning message to runtime log panel.""" - self._append_log_entry("WARN", text, details=details, once_key=once_key) + """Log a warning to the panel, file, and console.""" + self._gui_logger.warning(text, extra=_panel_extra(details, once_key)) def _log_error(self, text: str, *, details: str | None = None, once_key: str | None = None) -> None: - """Append error message to runtime log panel.""" - self._append_log_entry("ERROR", text, details=details, once_key=once_key) + """Log an error to the panel, file, and console.""" + self._gui_logger.error(text, extra=_panel_extra(details, once_key)) def _log_exception(self, context: str, exc: Exception, *, level: str = "ERROR") -> tuple[str, str]: """Log exception with detailed traceback and return `(message, details)`.""" @@ -624,13 +700,18 @@ class AppWindow( dialog.exec() def closeEvent(self, event) -> None: # noqa: N802 - """Ensure workers and dialogs are closed before window destruction.""" + """Tear down workers, readers, and dialogs before the window is destroyed. + + Guarded against re-entrancy so a second close signal (or a ``window.close()`` + after the event loop has already returned) does not run teardown twice. + """ if self._closing: # Re-entrant close (second signal, or window.close() after the event loop # already returned): teardown is in progress or done — do nothing more. super().closeEvent(event) return self._closing = True + self._log("Window closing; shutting down runtime.") try: # 0) Stop the web server first so a late request cannot start work. self._shutdown_web_ui() @@ -645,4 +726,5 @@ class AppWindow( if self._preprocess_dialog is not None: self._preprocess_dialog.close() finally: + self._log_debug("Window teardown finished.") super().closeEvent(event) diff --git a/python_app/gui/controllers/app_window_config/live_processing_mixin.py b/python_app/gui/controllers/app_window_config/live_processing_mixin.py index 4c26a9b..5233395 100644 --- a/python_app/gui/controllers/app_window_config/live_processing_mixin.py +++ b/python_app/gui/controllers/app_window_config/live_processing_mixin.py @@ -256,6 +256,12 @@ class AppWindowLiveProcessingMixin: for name, value in fields.items() if name not in {"history_command", "history_command_seq"} } + # Log only field names (not values) so remote edits are traceable + # without recording arbitrary client-supplied payloads. + self._log_debug( + f"Applying web live settings: fields={sorted(settings)}, " + f"history_command={history_command}." + ) self._suppress_live_settings_handler = True try: # processor_mode first: dual-sourced gpr_* fields route to the gpr or diff --git a/python_app/gui/controllers/app_window_config/profile_io_mixin.py b/python_app/gui/controllers/app_window_config/profile_io_mixin.py index 139f7e7..373338e 100644 --- a/python_app/gui/controllers/app_window_config/profile_io_mixin.py +++ b/python_app/gui/controllers/app_window_config/profile_io_mixin.py @@ -218,7 +218,16 @@ class AppWindowConfigProfileIOMixin: self._show_exception("Failed to load config profile", exc) def _apply_loaded_profile(self, profile: GuiProfileModel, profile_path: Path) -> None: - """Apply already parsed profile to GUI state without restarting the pipeline.""" + """Apply an already parsed profile to GUI state without restarting the pipeline. + + Repopulates every radar/processing/preprocess widget under signal blockers, + resizes history buffers, and refreshes derived state. The pipeline is left + untouched; callers handle user-facing logging and error reporting. + """ + self._log_debug( + f"Applying loaded profile: path={profile_path}, " + f"has_gui_state={profile.gui is not None}." + ) config = profile.run_config.clone() gui_state = profile.gui if profile.gui is not None else self._default_gui_state_for_config(config) self._defaults_config = config diff --git a/python_app/gui/controllers/app_window_config/state_builders.py b/python_app/gui/controllers/app_window_config/state_builders.py index 5dd9f6d..2b7c460 100644 --- a/python_app/gui/controllers/app_window_config/state_builders.py +++ b/python_app/gui/controllers/app_window_config/state_builders.py @@ -422,6 +422,7 @@ class AppWindowConfigStateBuildersMixin: config.runtime.settling_ms = int(self._settling_ms.text().strip()) config.runtime.processing_live_config_path = str(self._live_config_writer.path) + config.logging.level = self._log_level_combo.currentText().strip().lower() if config.is_matrix_radar: if config.is_multi_device and len(config.radar.multi_device.slave_serials) != 2: diff --git a/python_app/gui/controllers/app_window_pipeline_mixin.py b/python_app/gui/controllers/app_window_pipeline_mixin.py index 2128014..6edae98 100644 --- a/python_app/gui/controllers/app_window_pipeline_mixin.py +++ b/python_app/gui/controllers/app_window_pipeline_mixin.py @@ -304,16 +304,22 @@ class AppWindowPipelineMixin: self._log("All pipeline processes stopped") def _close_readers(self, *, keep_results: bool = False) -> None: - """Close active ring readers.""" + """Close active ring readers; keep the results reader when ``keep_results``.""" + closed = [] if self._raw_reader is not None: self._raw_reader.close() self._raw_reader = None + closed.append("raw") if self._pre_reader is not None: self._pre_reader.close() self._pre_reader = None + closed.append("preprocessed") if not keep_results and self._result_reader is not None: self._result_reader.close() self._result_reader = None + closed.append("results") + if closed: + self._log_debug(f"Closed ring readers: {', '.join(closed)}.") def _poll_rings(self) -> None: """Poll readers, ingest history, and trigger rendering.""" diff --git a/python_app/gui/controllers/app_window_preprocess_mixin.py b/python_app/gui/controllers/app_window_preprocess_mixin.py index b5b6082..ec435ec 100644 --- a/python_app/gui/controllers/app_window_preprocess_mixin.py +++ b/python_app/gui/controllers/app_window_preprocess_mixin.py @@ -58,7 +58,13 @@ class AppWindowPreprocessMixin: """Clear selected preprocess sets when radar-key-defining settings change.""" try: radar_key = self._radar_key_from_ui() - except Exception: + except Exception as exc: # noqa: BLE001 + # Radar fields can be mid-edit (empty/partial) while signals fire; the + # key cannot be computed yet, so skip until the inputs are valid again. + self._log_debug( + f"Skipping preprocess-selection reset; radar key unavailable: " + f"{type(exc).__name__}: {exc}" + ) return previous_radar_key = getattr(self, "_selected_preprocess_radar_key", radar_key) @@ -778,8 +784,11 @@ class AppWindowPreprocessMixin: ) def _cleanup_capture_session(self) -> None: - """Close and clear current capture session object.""" + """Close and clear the current capture session object.""" if self._capture_session is not None: + self._log_debug( + f"Closing capture session: kind={self._capture_session.kind}." + ) self._capture_session.close() self._capture_session = None self._update_capture_dialog_state() diff --git a/python_app/gui/controllers/app_window_ui_mixin.py b/python_app/gui/controllers/app_window_ui_mixin.py index b60cdd9..fe8dc22 100644 --- a/python_app/gui/controllers/app_window_ui_mixin.py +++ b/python_app/gui/controllers/app_window_ui_mixin.py @@ -33,6 +33,7 @@ from python_app.gui.controllers.sections import ( build_radar_group, build_switch_group, ) +from python_app.logging_setup import LOG_LEVELS class AppWindowUiMixin: @@ -178,6 +179,20 @@ class AppWindowUiMixin: self._log_toggle_button.setObjectName("sectionToggleButton") self._log_toggle_button.clicked.connect(lambda: self._toggle_log_panel()) + # Log-level selector: live verbosity control, persisted to run_config. + self._log_level_label = QLabel("Level", self._settings_panel) + self._log_level_label.setObjectName("hintLabel") + self._log_level_combo = QComboBox(self._settings_panel) + self._log_level_combo.setObjectName("logLevelCombo") + self._log_level_combo.addItems([name.capitalize() for name in LOG_LEVELS]) + self._log_level_combo.setToolTip("Logging verbosity — applied live and saved to run_config") + current_level = self._defaults_config.logging.level.capitalize() + current_index = self._log_level_combo.findText(current_level) + if current_index >= 0: + self._log_level_combo.setCurrentIndex(current_index) + # Connect AFTER seeding the value so reflecting the config does not save it back. + self._log_level_combo.currentTextChanged.connect(self._on_log_level_selected) + self._log_box = QTextEdit(self._settings_panel) self._log_box.setObjectName("runtimeLogBox") self._log_box.setReadOnly(True) @@ -196,6 +211,8 @@ class AppWindowUiMixin: header_layout.setSpacing(8) header_layout.addWidget(self._log_panel_title) header_layout.addStretch(1) + header_layout.addWidget(self._log_level_label) + header_layout.addWidget(self._log_level_combo) header_layout.addWidget(self._log_toggle_button) panel_layout.addWidget(header_row) diff --git a/python_app/gui/controllers/app_window_web_mixin.py b/python_app/gui/controllers/app_window_web_mixin.py index f209436..4ac30e6 100644 --- a/python_app/gui/controllers/app_window_web_mixin.py +++ b/python_app/gui/controllers/app_window_web_mixin.py @@ -198,6 +198,7 @@ class AppWindowWebMixin: with contextlib.suppress(Exception): server.stop() self._web_server = None + self._log("Web UI stopped.") self._web_controller = None @staticmethod diff --git a/python_app/gui/preprocess_dialog.py b/python_app/gui/preprocess_dialog.py index 3fc8c29..e9ec9d0 100644 --- a/python_app/gui/preprocess_dialog.py +++ b/python_app/gui/preprocess_dialog.py @@ -462,7 +462,12 @@ class PreprocessDialog(QDialog): ) def _ensure_preview_plots(self) -> bool: - """Create the amplitude+phase plot pair lazily on first successful capture.""" + """Lazily create the amplitude+phase plot pair and report whether it exists. + + Returns True once both plots are available. If construction fails (e.g. an + incompatible PyQtGraph/PyQt6 build), marks the preview permanently + unavailable so later captures fall back to the placeholder without retrying. + """ if self._amplitude_plot is not None and self._phase_plot is not None: return True if self._preview_plot_unavailable: @@ -474,6 +479,8 @@ class PreprocessDialog(QDialog): amplitude_plot = self._build_preview_axis("Magnitude", "dB") phase_plot = self._build_preview_axis("Phase", "deg") except Exception: + # Some PyQtGraph/PyQt6 combinations cannot build a PlotWidget here; + # latch the failure so we show the text placeholder instead of retrying. self._preview_plot_unavailable = True return False diff --git a/python_app/hardware_full/kamil_adc_service.py b/python_app/hardware_full/kamil_adc_service.py index 8aa3c32..3a58f9c 100644 --- a/python_app/hardware_full/kamil_adc_service.py +++ b/python_app/hardware_full/kamil_adc_service.py @@ -110,14 +110,18 @@ class KamilAdcTtyReader: daemon=True, ) self._thread.start() + logger.info("Kamil ADC TTY reader started on %s", self.tty_path) def close(self) -> None: """Stop the reader thread and close the TTY descriptor.""" + logger.debug("Stopping Kamil ADC TTY reader on %s", self.tty_path) self._stop_event.set() with self._mailbox_cv: self._mailbox_cv.notify_all() if self._thread is not None: self._thread.join(timeout=1.0) + if self._thread.is_alive(): + logger.warning("Kamil ADC reader thread did not stop within 1.0s") self._thread = None if self._fd is not None: try: @@ -180,7 +184,11 @@ class KamilAdcTtyReader: # ------------------------------------------------------------------ def _reader_loop(self) -> None: - """Drain TTY → parse frames → publish completed sweeps until stop.""" + """Drain the TTY, parse frames, and publish completed sweeps until stop. + + Runs on the background reader thread. Any exception is logged and stored + so the next :meth:`read_sweep` re-raises it on the consumer thread. + """ buffer = bytearray() try: if not self._skip_to_first_start_marker(buffer): @@ -191,6 +199,7 @@ class KamilAdcTtyReader: return self._publish_sweep(sweep) except Exception as exc: # noqa: BLE001 — surfaced to the consumer via read_sweep + logger.exception("Kamil ADC reader thread failed on %s", self.tty_path) self._publish_error(exc) def _skip_to_first_start_marker(self, buffer: bytearray) -> bool: @@ -335,12 +344,15 @@ class KamilAdcService: reader = KamilAdcTtyReader(self.config.radar.kamil_adc.tty_path) reader.open() self._reader = reader + logger.info("Kamil ADC service opened") except Exception: + logger.exception("Kamil ADC service failed to open; cleaning up") self.close() raise def close(self) -> None: """Stop the TTY reader and the external collector process.""" + logger.debug("Closing Kamil ADC service") if self._reader is not None: with suppress(Exception): self._reader.close() @@ -352,6 +364,9 @@ class KamilAdcService: self._validate_sweep(sweep) self._settings = sweep self._frequency_hz = None + logger.debug( + "Kamil ADC configured: frequency axis %s-%s Hz", sweep.start_hz, sweep.stop_hz + ) def read_device_limits(self) -> dict[str, float | int]: """Kamil ADC has no runtime-readable sweep limit API.""" @@ -374,6 +389,7 @@ class KamilAdcService: ) points = int(s21.size) if self._frequency_hz is None or self._frequency_hz.size != points: + logger.debug("Building Kamil ADC frequency axis for %d points", points) self._frequency_hz = self._build_frequency_axis(points) return SweepResult( x=self._frequency_hz.copy(), @@ -409,6 +425,7 @@ class KamilAdcService: self._process = None if process is None or process.poll() is not None: return + logger.info("Stopping Kamil ADC collector (pid=%d)", process.pid) with suppress(ProcessLookupError): os.killpg(process.pid, signal.SIGTERM) try: @@ -416,6 +433,9 @@ class KamilAdcService: return except subprocess.TimeoutExpired: pass + logger.warning( + "Kamil ADC collector (pid=%d) ignored SIGTERM; sending SIGKILL", process.pid + ) with suppress(ProcessLookupError): os.killpg(process.pid, signal.SIGKILL) process.wait(timeout=1.0) @@ -533,9 +553,16 @@ def _prepare_tty_path_for_collector(path: str) -> tuple[object, ...] | None: def apply_kamil_adc_laser_control(config: RunConfigModel) -> bool: - """Apply Kamil ADC laser settings exactly through the legacy device_main command sequence.""" + """Apply the configured laser settings through the legacy device_main command sequence. + + Connects to the laser controller, resets it, and applies either manual or + variation mode per ``radar.laser_control``. Returns `True` when settings were + applied, `False` when laser control is disabled. The controller is always + disconnected before returning. + """ laser = config.radar.laser_control if not laser.enabled: + logger.debug("Kamil ADC laser control disabled; skipping") return False _validate_laser_control_config(config) @@ -554,6 +581,7 @@ def apply_kamil_adc_laser_control(config: RunConfigModel) -> bool: controller.connect() controller.reset() mode = laser.mode.strip().lower() + logger.info("Applying Kamil ADC laser control in %s mode", mode) if mode == "manual": manual = laser.manual controller.set_manual_mode( diff --git a/python_app/hardware_full/laser_control/constants.py b/python_app/hardware_full/laser_control/constants.py index ac63179..f3b81fe 100644 --- a/python_app/hardware_full/laser_control/constants.py +++ b/python_app/hardware_full/laser_control/constants.py @@ -1,8 +1,7 @@ -""" -Constants for laser control module. +"""Constants for the laser control module. -Physical constraints, protocol parameters, and operational limits -extracted from original device_commands.py and device_conversion.py. +Physical constraints, protocol parameters, and operational limits for the +laser control board. """ # ---- Protocol constants diff --git a/python_app/hardware_full/laser_control/controller.py b/python_app/hardware_full/laser_control/controller.py index 60d3611..4220d87 100644 --- a/python_app/hardware_full/laser_control/controller.py +++ b/python_app/hardware_full/laser_control/controller.py @@ -362,8 +362,8 @@ class LaserController: if raw and len(raw) == 2: state = Protocol.decode_state(raw) if state != 0: - # Surface a device-reported non-OK STATE instead of silently treating - # a board-rejected command as success. (Returned to the caller too.) + # Surface a device-reported non-OK STATE instead of silently + # treating a board-rejected command as success. logger.warning( "Device returned non-OK STATE 0x%04x after command: %s", state, @@ -388,6 +388,6 @@ class LaserController: try: self.stop_task() except Exception: - pass + logger.warning("Failed to stop laser task on exit; closing port anyway", exc_info=True) self.disconnect() return False diff --git a/python_app/hardware_full/laser_control/conversions.py b/python_app/hardware_full/laser_control/conversions.py index a0eced7..ecfb2aa 100644 --- a/python_app/hardware_full/laser_control/conversions.py +++ b/python_app/hardware_full/laser_control/conversions.py @@ -1,10 +1,7 @@ -""" -Physical unit conversions for laser control module. +"""Physical unit conversions for the laser control module. -Converts between physical quantities (°C, mA, V) and -raw ADC/DAC integer values used by the device firmware. - -All formulas are taken directly from the original device_conversion.py. +Converts between physical quantities (°C, mA, V) and the raw ADC/DAC integer +values used by the device firmware, using the hardware's bridge/divider formulas. """ import math diff --git a/python_app/hardware_full/laser_control/protocol.py b/python_app/hardware_full/laser_control/protocol.py index 92f7c3b..482186f 100644 --- a/python_app/hardware_full/laser_control/protocol.py +++ b/python_app/hardware_full/laser_control/protocol.py @@ -1,11 +1,10 @@ -""" -Communication protocol for laser control module. +"""Communication protocol for the laser control module. -Encodes commands to bytes and decodes device responses. -Faithful re-implementation of the logic in device_commands.py, -refactored into a clean, testable class-based API. +Encodes commands to wire bytes, decodes device responses, and manages the +serial port connection to the laser control board. """ +import logging import struct from typing import Optional from enum import IntEnum @@ -38,6 +37,8 @@ from .exceptions import ( ProtocolError, ) +logger = logging.getLogger(__name__) + # Re-export enums so tests can import from protocol module class CommandCode(IntEnum): @@ -77,11 +78,11 @@ def _int_to_hex4(value: int) -> str: return f"{value:04x}" -def _flipfour(s: str) -> str: - """Swap two byte-pairs: 'aabb' → 'bbaa' (little-endian word).""" - if len(s) != 4: - raise ValueError(f"Expected 4-char hex string, got '{s}'") - return s[2:4] + s[0:2] +def _flipfour(hex_word: str) -> str: + """Swap the two byte-pairs of a 4-char hex word: 'aabb' -> 'bbaa' (little-endian).""" + if len(hex_word) != 4: + raise ValueError(f"Expected 4-char hex string, got '{hex_word}'") + return hex_word[2:4] + hex_word[0:2] def _xor_crc(words: list) -> str: @@ -183,7 +184,7 @@ class Protocol: # ---- Connection management def connect(self) -> None: - """Open the serial port. Auto-detects if port is None.""" + """Open the serial port. Auto-detects the device path when port is None.""" port = self._port_name or self._detect_port() try: self._serial = serial.Serial( @@ -192,13 +193,16 @@ class Protocol: timeout=SERIAL_TIMEOUT_SEC, ) except Exception as exc: + logger.error("Cannot open laser serial port '%s': %s", port, exc) raise CommunicationError( f"Cannot connect to port '{port}': {exc}" ) from exc + logger.debug("Laser serial port opened: %s @ %d baud", port, BAUDRATE) def disconnect(self) -> None: """Close the serial port if open.""" if self._serial and self._serial.is_open: + logger.debug("Closing laser serial port") self._serial.close() @property @@ -241,13 +245,14 @@ class Protocol: @staticmethod def calculate_crc(data: bytes) -> int: - """ - XOR CRC over all 16-bit words except the last two bytes (CRC field). - Mirrors the original CalculateCRC logic. + """Return the XOR CRC over all 16-bit words except word 0 and the CRC field. + + The command-code word (word 0) is excluded, matching the firmware's CRC + expectation. """ hex_str = data.hex() words = [hex_str[i:i+4] for i in range(0, len(hex_str), 4)] - # Skip word 0 (command code) per original firmware expectation + # Word 0 (command code) is excluded from the CRC. crc_words = words[1:] result = int(crc_words[0], 16) for w in crc_words[1:]: @@ -342,9 +347,8 @@ class Protocol: case TaskType.CHANGE_CURRENT_LD2: data += _flipfour(_int_to_hex4(current_ma_to_n(min_value))) # Word 3 data += _flipfour(_int_to_hex4(current_ma_to_n(max_value))) # Word 4 - # Word 5: current step encoded like LD1 and like min/max (current_ma_to_n), - # NOT int(step*100) — the latter was a copy/paste from temperature scaling - # and produced a different wire value than LD1 for the same physical step. + # Word 5: current step uses the same current_ma_to_n scaling as + # min/max (and as LD1) so equal physical steps map to equal wire values. data += _flipfour(_int_to_hex4(current_ma_to_n(step))) # Word 5 data += _flipfour(_int_to_hex4(int(time_step * 100))) # Word 6: Delta_Time_µs × 100 data += _flipfour(_int_to_hex4(temp_c_to_n(static_temp2))) # Word 7 diff --git a/python_app/hardware_full/librevna_driver/__init__.py b/python_app/hardware_full/librevna_driver/__init__.py index ecb75cd..d4fabca 100644 --- a/python_app/hardware_full/librevna_driver/__init__.py +++ b/python_app/hardware_full/librevna_driver/__init__.py @@ -10,7 +10,6 @@ from .enums import ( SweepScale, SyncMode, ) -from .logging_utils import DEFAULT_LOG_LEVEL, configure_logging from .exceptions import ( CRCError, DeviceDisconnectedError, @@ -39,7 +38,6 @@ from .models import ( __all__ = [ "CRCError", - "DEFAULT_LOG_LEVEL", "DeviceConfigVariant", "DeviceDisconnectedError", "DeviceInfo", @@ -55,7 +53,6 @@ __all__ = [ "PacketType", "ParseError", "ProtocolVersionMismatch", - "configure_logging", "SParameter", "StreamHandle", "SweepKind", diff --git a/python_app/hardware_full/librevna_driver/api/generator.py b/python_app/hardware_full/librevna_driver/api/generator.py index 9672838..e18a709 100644 --- a/python_app/hardware_full/librevna_driver/api/generator.py +++ b/python_app/hardware_full/librevna_driver/api/generator.py @@ -44,7 +44,18 @@ class GeneratorController: timeout_s: float, poll_interval_s: float, ) -> DeviceStatus: - """Wait until available lock flags report the generator is ready.""" + """Poll device status until the source/LO lock flags report the generator + is ready, then return that status. + + Polls every ``poll_interval_s`` seconds up to ``timeout_s`` total. Raises + ``TimeoutError`` if the locks do not assert in time and ``RuntimeError`` if + the connected hardware family exposes no lock telemetry. + """ + logger.info( + "Waiting for generator lock (timeout=%.2fs, poll_interval=%.2fs)", + timeout_s, + poll_interval_s, + ) deadline = time.monotonic() + timeout_s @@ -53,13 +64,19 @@ class GeneratorController: lock_values = [value for value in (status.source_locked, status.lo_locked) if value is not None] if lock_values: if all(lock_values): + logger.info("Generator locked (family=%s)", status.family.name) return status else: + logger.error( + "Generator lock telemetry unavailable for hardware family %s", + status.family.name, + ) raise RuntimeError( f"Generator lock telemetry is unavailable for hardware family {status.family.name}" ) remaining = deadline - time.monotonic() if remaining <= 0: + logger.warning("Timed out waiting for generator lock after %.2fs", timeout_s) raise TimeoutError("Timed out waiting for LibreVNA generator lock") time.sleep(min(poll_interval_s, remaining)) diff --git a/python_app/hardware_full/librevna_driver/logging_utils.py b/python_app/hardware_full/librevna_driver/logging_utils.py deleted file mode 100644 index 9e3e639..0000000 --- a/python_app/hardware_full/librevna_driver/logging_utils.py +++ /dev/null @@ -1,52 +0,0 @@ -"""Logging helpers for applications embedding ``librevna_driver``. - -The library uses standard ``logging`` module loggers under the -``librevna_driver`` namespace and never configures global logging implicitly. -Use :func:`configure_logging` in scripts/services when you want a convenient -default console setup. -""" - -from __future__ import annotations - -import logging - -_LOGGER_NAMESPACE = "librevna_driver" -_DEFAULT_FORMAT = ( - "%(asctime)s | %(levelname)-8s | %(name)s | %(message)s" -) -DEFAULT_LOG_LEVEL = "INFO" - - -def configure_logging( - level: int | str | None = None, - *, - fmt: str = _DEFAULT_FORMAT, - datefmt: str | None = "%Y-%m-%d %H:%M:%S", -) -> None: - """Configure package logger with one stream handler. - - This helper affects only the ``librevna_driver`` logger tree and is safe to - call repeatedly (previous handlers attached by this function are replaced). - When ``level`` is ``None``, :data:`DEFAULT_LOG_LEVEL` is used. - """ - - effective_level = level if level is not None else DEFAULT_LOG_LEVEL - - logger = logging.getLogger(_LOGGER_NAMESPACE) - logger.handlers.clear() - handler = logging.StreamHandler() - handler.setFormatter(logging.Formatter(fmt=fmt, datefmt=datefmt)) - logger.addHandler(handler) - logger.setLevel(_parse_level(effective_level)) - logger.propagate = False - - -def _parse_level(level: int | str) -> int: - """Parse numeric or textual log level into logging constant.""" - if isinstance(level, int): - return level - - normalized = level.strip().upper() - if normalized in logging.getLevelNamesMapping(): - return logging.getLevelNamesMapping()[normalized] - raise ValueError(f"Unknown logging level: {level!r}") diff --git a/python_app/hardware_full/librevna_driver/models.py b/python_app/hardware_full/librevna_driver/models.py index 8a0d56b..ebe0548 100644 --- a/python_app/hardware_full/librevna_driver/models.py +++ b/python_app/hardware_full/librevna_driver/models.py @@ -251,13 +251,14 @@ class SweepResult: return self.trace(parameter).imag def to_npz(self, path: str) -> None: - """Save result as NumPy `.npz` archive.""" + """Save the axis and all traces to a NumPy `.npz` archive at ``path``.""" data: dict[str, np.ndarray] = {self.x_label: self.x} data.update(self.traces) np.savez(path, **data) + logger.debug("Saved SweepResult to NPZ: %s (traces=%d)", path, len(self.traces)) def to_csv(self, path: str) -> None: - """Save result as CSV with `_real`/`_imag` columns.""" + """Save the axis and traces to CSV at ``path``, with `_real`/`_imag` columns.""" columns: list[np.ndarray] = [self.x] headers: list[str] = [self.x_label] for name, values in sorted(self.traces.items()): @@ -267,6 +268,7 @@ class SweepResult: headers.append(f"{name}_imag") matrix = np.column_stack(columns) np.savetxt(path, matrix, delimiter=",", header=",".join(headers), comments="") + logger.debug("Saved SweepResult to CSV: %s (traces=%d)", path, len(self.traces)) PacketPayload = Any diff --git a/python_app/hardware_full/librevna_multi_device_driver/controller.py b/python_app/hardware_full/librevna_multi_device_driver/controller.py index 648df35..ddbb0c9 100644 --- a/python_app/hardware_full/librevna_multi_device_driver/controller.py +++ b/python_app/hardware_full/librevna_multi_device_driver/controller.py @@ -6,6 +6,7 @@ from collections.abc import Iterator, Sequence from contextlib import suppress from dataclasses import replace from typing import Optional +import logging import threading import time @@ -23,6 +24,8 @@ from python_app.hardware_full.librevna_multi_device_driver.protocol import ( ) from python_app.hardware_full.librevna_multi_device_driver.transport import LibreVnaUsbBulkConnection +logger = logging.getLogger(__name__) + class MultiDeviceVnaController: """Coordinate one master LibreVNA and receiver slave LibreVNAs.""" @@ -46,6 +49,13 @@ class MultiDeviceVnaController: self._sweep_is_running = False self._is_closed = False + logger.info( + "Opening multi-device controller (master=%s, slaves=%s, sync=%s, external_ref=%s)", + master_serial_number, + list(slave_serial_numbers), + self._synchronization_enabled, + self._force_external_reference, + ) try: # Register each device the moment it opens so a partial open (e.g. a # slave that fails after the master is up) is fully released by close(). @@ -57,9 +67,12 @@ class MultiDeviceVnaController: self._slave_devices.append(connection) self._all_devices.append(connection) except Exception: + logger.exception("Failed to open multi-device controller; releasing devices") self.close() raise + logger.info("Multi-device controller ready (%d device(s) open)", len(self._all_devices)) + def __enter__(self) -> MultiDeviceVnaController: """Return this controller as a context manager resource.""" return self @@ -77,17 +90,20 @@ class MultiDeviceVnaController: if self._is_closed: return + logger.info("Closing multi-device controller (%d device(s))", len(self._all_devices)) self._is_closed = True with suppress(Exception): self._send_idle_to_all_devices() for device_connection in self._all_devices: with suppress(Exception): device_connection.close() + logger.debug("Multi-device controller closed") def stop_continuous_sweep(self) -> None: """Stop the currently running sweep without closing device transports.""" if self._is_closed: return + logger.info("Stopping continuous sweep") self._send_idle_to_all_devices() def configure_continuous_sweep( @@ -121,6 +137,7 @@ class MultiDeviceVnaController: and self._last_applied_sweep_configuration == sweep_configuration and self._last_master_stimulus_ports == stimulus_ports ): + logger.debug("Sweep configuration unchanged; keeping running sweep") return if self._sweep_is_running: @@ -131,6 +148,15 @@ class MultiDeviceVnaController: # so the new sweep starts on an empty queue. self._drain_all_received_packets() + logger.info( + "Configuring continuous sweep: %d points %d-%d Hz, ifbw=%d Hz, power=%.2f dBm, ports=%s", + sweep_configuration.points, + sweep_configuration.start_hz, + sweep_configuration.stop_hz, + sweep_configuration.if_bandwidth, + sweep_configuration.power_dbm, + stimulus_ports, + ) self._configure_sweep_on_all_devices( sweep_configuration, master_stimulus_ports=stimulus_ports, @@ -163,6 +189,7 @@ class MultiDeviceVnaController: datapoint_timeout_seconds=datapoint_timeout_seconds, ) except Exception: + logger.warning("Sweep cycle collection failed; idling all devices", exc_info=True) self._send_idle_to_all_devices() raise @@ -179,6 +206,10 @@ class MultiDeviceVnaController: timeout_seconds: float = 3.0, retry_count: int = 1, ) -> None: + """Send a packet and wait for its ACK, retrying up to ``retry_count`` times. + + Re-raises the last error if every attempt fails to acknowledge in time. + """ last_error: Exception | None = None for _attempt_index in range(retry_count + 1): device_connection.send_packet(packet_type, payload) @@ -187,6 +218,14 @@ class MultiDeviceVnaController: return except Exception as exc: # noqa: BLE001 last_error = exc + logger.debug( + "No ACK for packet type %s from %s (attempt %d/%d): %s", + packet_type, + device_connection.serial_number, + _attempt_index + 1, + retry_count + 1, + exc, + ) assert last_error is not None raise last_error @@ -199,6 +238,11 @@ class MultiDeviceVnaController: timeout_seconds: float = 3.0, retry_count: int = 1, ) -> None: + """Send a command and wait for its ACK, swallowing any failure. + + Used on best-effort paths (e.g. idling devices during shutdown) where a + non-responsive device must not abort the operation. + """ try: self._send_command_and_wait_for_acknowledgement( device_connection, @@ -208,9 +252,15 @@ class MultiDeviceVnaController: retry_count=retry_count, ) except Exception: - pass + logger.debug( + "Best-effort command type %s to %s failed; ignoring", + packet_type, + device_connection.serial_number, + ) def _send_idle_to_all_devices(self) -> None: + """Best-effort SET_IDLE to every device and mark the sweep as stopped.""" + logger.debug("Sending SET_IDLE to %d device(s)", len(self._all_devices)) # SET_IDLE is a one-shot stop command. The ACK may be delayed only by the # in-flight datapoint queue, which drains within a few hundred ms. A short, # single-shot timeout keeps recovery snappy when one device stops responding @@ -225,6 +275,12 @@ class MultiDeviceVnaController: self._sweep_is_running = False def _configure_reference_clocks(self) -> None: + """Apply ReferenceSettings to every device and mark the reference configured.""" + logger.debug( + "Configuring reference clocks on %d device(s) (external_ref=%s)", + len(self._all_devices), + self._force_external_reference, + ) for device_connection in self._all_devices: # 1 s ACK timeout plus one retry caps worst-case at ~2 s per device # so a stuck reference apply cannot stall recovery for minutes. @@ -245,6 +301,11 @@ class MultiDeviceVnaController: *, master_stimulus_ports: tuple[int, ...], ) -> None: + """Send SweepSettings to slaves then the master and mark the sweep running. + + The master is configured last so receivers are armed before the master + begins driving the synchronized trigger. + """ if self._master_device is None: raise RuntimeError("Master device is not open") @@ -270,8 +331,15 @@ class MultiDeviceVnaController: self._last_applied_sweep_configuration = replace(sweep_configuration) self._last_master_stimulus_ports = master_stimulus_ports self._sweep_is_running = True + logger.debug("Sweep settings applied to all devices; sweep running") def _drain_all_received_packets(self) -> None: + """Empty every device's received-packet queue, in parallel for 2+ devices. + + Concurrent draining keeps cross-device timing skew small so a hardware + cycle wrap cannot slip between per-device drains and desynchronize the + cycle counters. + """ # Drain every device queue in parallel rather than one after another: # serial drain leaves up to a few hundred microseconds of skew between # the master and slave drain moments, which is enough room for a @@ -299,6 +367,7 @@ class MultiDeviceVnaController: @staticmethod def _normalize_master_stimulus_ports(master_stimulus_ports: Sequence[int]) -> tuple[int, ...]: + """Validate and return master stimulus ports as a tuple of ints (ports 1/2 only).""" stimulus_ports = tuple(int(port) for port in master_stimulus_ports) if not stimulus_ports: raise ValueError("master_stimulus_ports must not be empty") diff --git a/python_app/hardware_full/librevna_multi_device_driver/cycle_collection.py b/python_app/hardware_full/librevna_multi_device_driver/cycle_collection.py index cb30d2b..1ff260c 100644 --- a/python_app/hardware_full/librevna_multi_device_driver/cycle_collection.py +++ b/python_app/hardware_full/librevna_multi_device_driver/cycle_collection.py @@ -3,6 +3,7 @@ from __future__ import annotations from collections.abc import Callable, Sequence +import logging import queue import threading import time @@ -21,6 +22,8 @@ from python_app.hardware_full.librevna_multi_device_driver.protocol import ( ) from python_app.hardware_full.librevna_multi_device_driver.transport import LibreVnaUsbBulkConnection +logger = logging.getLogger(__name__) + LIBREVNA_NATIVE_SWEEP_TIMEOUT_SECONDS = 1.5 # Hard upper bound on how long one full sweep cycle is allowed to take from @@ -93,6 +96,14 @@ def collect_complete_running_sweep_cycles( device_connection: LibreVnaUsbBulkConnection, handle_datapoint: Callable[[ParsedVnaDatapoint], bool], ) -> None: + """Read datapoints from one device until enough are consumed or a timeout fires. + + Runs on a worker thread. Each datapoint is offered to ``handle_datapoint``, + which returns whether it was consumed; only consumed datapoints count toward + progress and refresh the no-progress timeout. On any timeout or transport + error the error is recorded and ``stop_collection_requested`` is set so the + other collector threads also stop. + """ datapoints_received = 0 expected_datapoint_count = cycle_count * point_count loop_start_timestamp = time.monotonic() @@ -111,6 +122,13 @@ def collect_complete_running_sweep_cycles( now = time.monotonic() remaining_timeout_seconds = (last_consumed_timestamp + datapoint_timeout_seconds) - now if remaining_timeout_seconds <= 0: + logger.warning( + "No usable datapoints from %s for %.1fs (received %d/%d); aborting collection", + device_connection.serial_number, + datapoint_timeout_seconds, + datapoints_received, + expected_datapoint_count, + ) collection_errors.append( TimeoutError( f"No usable datapoints from {device_connection.serial_number} for " @@ -122,6 +140,12 @@ def collect_complete_running_sweep_cycles( return if not has_consumed_any_datapoint and (now - loop_start_timestamp) > cycle_start_guard_seconds: + logger.warning( + "Device %s streamed datapoints but never reached point_index=0 within %.1fs; " + "aborting collection", + device_connection.serial_number, + cycle_start_guard_seconds, + ) collection_errors.append( TimeoutError( f"Device {device_connection.serial_number} streamed datapoints but never " @@ -138,6 +162,14 @@ def collect_complete_running_sweep_cycles( # on for too long — this is the safety net the per-device timeout # cannot provide by itself. if (now - loop_start_timestamp) > _MAX_FULL_CYCLE_SECONDS: + logger.warning( + "Device %s did not finish a sweep cycle within %.1fs (received %d/%d); " + "aborting collection", + device_connection.serial_number, + _MAX_FULL_CYCLE_SECONDS, + datapoints_received, + expected_datapoint_count, + ) collection_errors.append( TimeoutError( f"Device {device_connection.serial_number} did not finish a sweep cycle " @@ -157,10 +189,20 @@ def collect_complete_running_sweep_cycles( return if isinstance(exc, queue.Empty): continue + logger.warning( + "Timed out receiving datapoint from %s; aborting collection: %s", + device_connection.serial_number, + exc, + ) collection_errors.append(exc) stop_collection_requested.set() return except Exception as exc: # noqa: BLE001 + logger.error( + "Error receiving datapoint from %s; aborting collection", + device_connection.serial_number, + exc_info=exc, + ) collection_errors.append(exc) stop_collection_requested.set() return @@ -182,6 +224,13 @@ def collect_complete_running_sweep_cycles( def build_cycle_tracking_handler( cycle_aware_handler: Callable[[ParsedVnaDatapoint, int], None], ) -> Callable[[ParsedVnaDatapoint], bool]: + """Wrap a cycle-aware handler with cross-device cycle tracking. + + Returns a per-datapoint handler that anchors cycle 0 on the first + ``point_index == 0`` seen, advances the cycle counter on each point-index + wrap, drops datapoints past ``cycle_count``, and reports whether each + datapoint was consumed. + """ # The controller restarts the sweep before every collection, so the # first packet each device emits is point 0 of a brand-new cycle 0. # Anchoring cycle 0 on the first observed point_index==0 — instead of @@ -198,6 +247,12 @@ def collect_complete_running_sweep_cycles( } def handle_datapoint(parsed_datapoint: ParsedVnaDatapoint) -> bool: + """Track the cycle index for one datapoint and dispatch it to the handler. + + Returns ``True`` when the datapoint was consumed (within ``cycle_count``) + and ``False`` when it was ignored (pre-sync straggler or past the last + requested cycle). + """ current_point_index = parsed_datapoint.point_index if not cycle_tracking_state["synchronized"]: @@ -221,6 +276,12 @@ def collect_complete_running_sweep_cycles( return handle_datapoint def handle_master_datapoint(parsed_datapoint: ParsedVnaDatapoint, cycle_index: int) -> None: + """Store the master device's frequency, reference, and reflection values. + + Records the sweep-point frequency and, per active master stimulus port, the + reference receiver value and the matching reflection (S11/S22) into the + cycle/point measurement buffers. + """ point_index = parsed_datapoint.point_index frequencies_hz[point_index] = parsed_datapoint.frequency_hz @@ -260,9 +321,16 @@ def collect_complete_running_sweep_cycles( ] = port_receiver_value def build_slave_datapoint_handler(slave_index: int) -> Callable[[ParsedVnaDatapoint], bool]: + """Build a cycle-tracking datapoint handler for the given slave device. + + The slave's two receivers map to ports ``2*slave_index + 3`` and ``+ 4``, + producing forward S-parameters (e.g. S3x/S4x) for each active master + stimulus port. + """ receiver_base_port = 2 * slave_index + 3 def handle_slave_datapoint(parsed_datapoint: ParsedVnaDatapoint, cycle_index: int) -> None: + """Store this slave's forward receiver values into the measurement buffers.""" point_index = parsed_datapoint.point_index for master_stimulus_port, stage_index in stage_by_master_port.items(): first_s_parameter_name = f"S{receiver_base_port}{master_stimulus_port}" @@ -303,6 +371,13 @@ def collect_complete_running_sweep_cycles( ) ) + logger.debug( + "Collecting %d sweep cycle(s) of %d points from %d device(s) (datapoint_timeout=%.1fs)", + cycle_count, + point_count, + len(all_device_connections), + datapoint_timeout_seconds, + ) for collection_thread in collection_threads: collection_thread.start() @@ -321,6 +396,10 @@ def collect_complete_running_sweep_cycles( collection_thread for collection_thread in collection_threads if collection_thread.is_alive() ] if stalled_threads: + logger.warning( + "Collector thread(s) still alive after join; requesting stop again: %s", + ", ".join(stalled_thread.name for stalled_thread in stalled_threads), + ) stop_collection_requested.set() # Give them one more short window in case they were just slow to react. secondary_deadline = time.monotonic() + 0.5 @@ -328,6 +407,10 @@ def collect_complete_running_sweep_cycles( stalled_thread.join(timeout=max(0.0, secondary_deadline - time.monotonic())) still_stalled = [stalled_thread for stalled_thread in stalled_threads if stalled_thread.is_alive()] if still_stalled: + logger.error( + "Collector thread(s) failed to stop within the join deadline: %s", + ", ".join(stalled_thread.name for stalled_thread in still_stalled), + ) collection_errors.append( RuntimeError( "Sweep collector thread(s) failed to stop within the join deadline: " @@ -339,11 +422,17 @@ def collect_complete_running_sweep_cycles( raise RuntimeError(f"Sweep collection failed: {collection_errors[0]}") from collection_errors[0] if slave_device_connections and min(datapoint_counts_by_device_serial.values(), default=0) == 0: + logger.error( + "No datapoints from at least one device; hardware trigger sync did not start " + "(per-device counts: %s)", + datapoint_counts_by_device_serial, + ) raise RuntimeError( "No datapoints received from at least one device; hardware trigger sync did not start. " "Check Trigger Out/In loop and 10 MHz reference wiring." ) + logger.debug("Sweep cycle collection complete (per-device counts: %s)", datapoint_counts_by_device_serial) return SweepMeasurementResult( frequencies_hz=frequencies_hz, s_parameters=calculate_last_cycle_s_parameters( diff --git a/python_app/hardware_full/librevna_multi_device_driver/transport.py b/python_app/hardware_full/librevna_multi_device_driver/transport.py index 4a175b5..d809f05 100644 --- a/python_app/hardware_full/librevna_multi_device_driver/transport.py +++ b/python_app/hardware_full/librevna_multi_device_driver/transport.py @@ -20,6 +20,11 @@ class LibreVnaUsbBulkConnection: """Minimal packet transport for one LibreVNA device.""" def __init__(self, serial_number: str) -> None: + """Open the USB transport for ``serial_number`` and start receiving packets. + + Raises ``ValueError`` when no serial number is supplied and propagates any + transport error raised while opening the device. + """ if not serial_number: raise ValueError("serial_number is required for multi-device acquisition") self.serial_number = serial_number @@ -32,10 +37,13 @@ class LibreVnaUsbBulkConnection: on_disconnect=self._on_disconnect, read_chunk_size=4096, ) + logger.debug("Opening LibreVNA USB connection (serial=%s)", serial_number) self._transport.connect(serial=serial_number, timeout_s=2.0) + logger.info("LibreVNA USB connection ready (serial=%s)", serial_number) def close(self) -> None: - """Close USB resources.""" + """Disconnect the underlying USB transport and release its resources.""" + logger.debug("Closing LibreVNA USB connection (serial=%s)", self.serial_number) self._transport.disconnect() def drain_received_packets(self) -> list[tuple[int, bytes]]: @@ -83,6 +91,11 @@ class LibreVnaUsbBulkConnection: raise RuntimeError(f"Device {self.serial_number} returned NACK") def _on_data(self, chunk: bytes) -> None: + """Decode a received USB chunk into frames and queue (type, payload) tuples. + + Any decode failure is recorded as the fatal transport error so the next + send/receive call surfaces it to the caller. + """ try: packets = self._scanner.feed(chunk) except Exception as exc: # noqa: BLE001 @@ -92,15 +105,18 @@ class LibreVnaUsbBulkConnection: self._received_packets.put((int(packet.type), bytes(packet.payload))) def _on_disconnect(self, exc: Exception) -> None: + """Record an asynchronous transport disconnect as the fatal error.""" self._set_fatal_error(exc) def _set_fatal_error(self, exc: Exception) -> None: + """Store the first fatal transport error and log it; later errors are ignored.""" with self._fatal_lock: if self._fatal_error is None: logger.error("LibreVNA USB transport failed for %s: %s", self.serial_number, exc) self._fatal_error = exc def _raise_if_failed(self) -> None: + """Re-raise the stored fatal transport error as ``RuntimeError`` if one exists.""" with self._fatal_lock: if self._fatal_error is None: return diff --git a/python_app/hardware_full/librevna_service.py b/python_app/hardware_full/librevna_service.py index 44f80e4..5e37225 100644 --- a/python_app/hardware_full/librevna_service.py +++ b/python_app/hardware_full/librevna_service.py @@ -34,6 +34,7 @@ class LibreVnaService: raise ValueError(f"Unsupported LibreVnaService backend mode: {self.backend_mode}") if mode == "mock": + logger.info("LibreVNA service using mock backend (mode=mock)") self._backend = MockLibreVnaBackend() self._using_mock_backend = True return @@ -44,6 +45,7 @@ class LibreVnaService: strict_protocol_version=self.strict_protocol_version, ) self._driver_available = True + logger.info("LibreVNA native backend initialized (serial=%s)", self.serial or "auto") except Exception as exc: # 'native' demands real hardware — never substitute synthetic data. if mode == "native": @@ -68,18 +70,24 @@ class LibreVnaService: return if self._backend is None: return + logger.debug("Opening LibreVNA backend (mock=%s)", self._using_mock_backend) self._backend.open() def close(self) -> None: """Close backend resources.""" if self._backend is None: return + logger.debug("Closing LibreVNA backend") self._backend.close() def configure(self, sweep: RadarSweepModel) -> None: """Apply sweep settings to active backend.""" if self._backend is None: raise RuntimeError("LibreVNA backend is not initialized") + logger.debug( + "Configuring LibreVNA sweep: %s-%s Hz, %s points", + sweep.start_hz, sweep.stop_hz, sweep.points, + ) self._backend.configure(sweep) def read_device_limits(self) -> dict[str, float | int]: diff --git a/python_app/hardware_full/multi_device_service.py b/python_app/hardware_full/multi_device_service.py index 6aacc63..e730a61 100644 --- a/python_app/hardware_full/multi_device_service.py +++ b/python_app/hardware_full/multi_device_service.py @@ -83,6 +83,10 @@ class MultiDeviceLibreVnaService: slave_serial_numbers=self.slave_serials, force_external_reference=self.force_external_reference, ) + logger.info( + "Multi-device controller opened (master=%s, slaves=%s)", + self.master_serial, self.slave_serials, + ) except Exception as exc: # Never silently latch to synthetic data: a deployed appliance must wait # for the real device, not record fakes. Synthetic data requires an @@ -180,6 +184,14 @@ class MultiDeviceLibreVnaService: if_bandwidth=int(round(float(sweep.if_bandwidth_hz))), power_dbm=float(sweep.power_dbm), ) + logger.debug( + "Multi-device configured: %s-%s Hz, %s points, IFBW=%s Hz, %s dBm", + self._sweep_configuration.start_hz, + self._sweep_configuration.stop_hz, + self._sweep_configuration.points, + self._sweep_configuration.if_bandwidth, + self._sweep_configuration.power_dbm, + ) def acquire_collection( self, diff --git a/python_app/hardware_full/single_radar_service.py b/python_app/hardware_full/single_radar_service.py index 3905c27..7ea0eca 100644 --- a/python_app/hardware_full/single_radar_service.py +++ b/python_app/hardware_full/single_radar_service.py @@ -2,6 +2,7 @@ from __future__ import annotations +import logging from typing import Protocol from python_app.hardware_full.kamil_adc_service import KamilAdcService @@ -10,6 +11,8 @@ from python_app.hardware_full.librevna_service import LibreVnaService from python_app.hardware_full.remote_compact_m_k209_service import RemoteCompactMK209Service from python_app.models.run_config_model import RadarSweepModel, RunConfigModel +logger = logging.getLogger(__name__) + class SingleRadarService(Protocol): """Common API used by single-radar workflows.""" @@ -39,6 +42,7 @@ def create_single_radar_service(config: RunConfigModel) -> SingleRadarService: ) model = config.radar.model or RunConfigModel.LIBREVNA_MODEL + logger.debug("Creating single-radar service for model=%s (driver_mode=%s)", model, config.radar.driver_mode) if model == RunConfigModel.LIBREVNA_MODEL: # Forward driver_mode (mirrors the matrix path): 'native' must require real # hardware and 'mock' must use the synthetic backend — never silently the wrong one. diff --git a/python_app/hardware_full/sn9000_service.py b/python_app/hardware_full/sn9000_service.py index 121b8ab..d14e612 100644 --- a/python_app/hardware_full/sn9000_service.py +++ b/python_app/hardware_full/sn9000_service.py @@ -79,6 +79,7 @@ class Sn9000Service: if self._instrument is not None: return + logger.info("Opening SN9000 VISA session: %s", self.resource) try: self._resource_manager = pyvisa.ResourceManager(self.visa_library) self._instrument = self._resource_manager.open_resource(self.resource) @@ -91,12 +92,14 @@ class Sn9000Service: if self._settings is not None: self._apply_configuration(self._settings) except Exception: + logger.exception("Failed to open SN9000 VISA session: %s", self.resource) self.close() raise def close(self) -> None: """Close VISA sessions.""" if self._instrument is not None: + logger.debug("Closing SN9000 VISA session") self._instrument.close() self._instrument = None if self._resource_manager is not None: @@ -114,6 +117,7 @@ class Sn9000Service: def recover(self) -> None: """Reopen the VISA session after a transient acquisition failure.""" + logger.warning("Recovering SN9000 VISA session (close, wait, reopen)") self.close() time.sleep(0.25) self.open() @@ -133,6 +137,10 @@ class Sn9000Service: self._validate_sweep(sweep) self._settings = sweep self._frequency_hz = None + logger.debug( + "Configuring SN9000 sweep: %s-%s Hz, %s points, IFBW=%s Hz, %s dBm", + sweep.start_hz, sweep.stop_hz, sweep.points, sweep.if_bandwidth_hz, sweep.power_dbm, + ) if self._instrument is None: return self._apply_configuration(sweep) @@ -210,6 +218,10 @@ class Sn9000Service: instrument.write("TRIG:SOUR BUS") self._expect_opc("*OPC?", context="SN9000 setup") self._frequency_hz = self._query_float32_array("SENS:FREQ:DATA?", int(sweep.points)) + logger.info( + "SN9000 configured: %d traces, %d points (%s-%s Hz)", + len(_S_PARAMETER_QUERY_ORDER), int(sweep.points), sweep.start_hz, sweep.stop_hz, + ) def _query_sweep_s_parameters(self, points: int) -> dict[str, np.ndarray]: instrument = self._require_instrument() diff --git a/python_app/logging_setup.py b/python_app/logging_setup.py new file mode 100644 index 0000000..718e2f5 --- /dev/null +++ b/python_app/logging_setup.py @@ -0,0 +1,127 @@ +"""Central logging configuration for the radar_system Python application. + +One package-level logger (``python_app``) owns the level, the rotating log file, +and the console stream, so every module's ``logging.getLogger(__name__)`` inherits +a single, consistently formatted, level-controlled pipeline. The GUI attaches its +own panel handler to the same logger (see :mod:`python_app.gui`), so the on-screen +log and the file stay in lock-step. + +The active level is chosen from the UI and persisted in ``run_config`` (the +``logging.level`` field); applying it here means a sub-threshold call — e.g. +``logger.debug(...)`` while the level is ``INFO`` — is never formatted or emitted, +so verbose logging costs nothing until it is turned on. +""" + +from __future__ import annotations + +import logging +import sys +from contextlib import suppress +from logging.handlers import RotatingFileHandler +from pathlib import Path + +# Root logger for the whole application package. Every module logs under it via +# ``logging.getLogger(__name__)`` (module names already start with "python_app"). +PACKAGE_LOGGER_NAME = "python_app" + +# Levels offered in the UI selector and accepted in run_config (coarsest last). +LOG_LEVELS: tuple[str, ...] = ("DEBUG", "INFO", "WARNING", "ERROR") +DEFAULT_LOG_LEVEL = "INFO" + +_LOG_FILENAME = "radar.log" +# 2 MiB per file across 6 generations caps the on-disk log at ~12 MiB so it can +# never fill an SD-card-backed Pi, while still retaining plenty of recent history. +_FILE_MAX_BYTES = 2 * 1024 * 1024 +_FILE_BACKUP_COUNT = 5 +_LOG_FORMAT = "%(asctime)s | %(levelname)-7s | %(name)s | %(message)s" +_DATE_FORMAT = "%Y-%m-%d %H:%M:%S" + +# Marker set on the handlers we install, so re-configuration can replace exactly +# our own handlers without disturbing any attached by the GUI or by tests. +_MANAGED_FLAG = "_radar_managed" + + +def coerce_level(value: object) -> int: + """Return a stdlib logging level int for a level name or number (default INFO).""" + if isinstance(value, bool): + return logging.INFO + if isinstance(value, int): + return value + resolved = logging.getLevelName(str(value).strip().upper()) + return resolved if isinstance(resolved, int) else logging.INFO + + +def normalize_level_name(value: object) -> str: + """Return a canonical UPPERCASE level name from the supported set (default INFO).""" + name = str(value).strip().upper() + return name if name in LOG_LEVELS else DEFAULT_LOG_LEVEL + + +def package_logger() -> logging.Logger: + """Return the application's root logger.""" + return logging.getLogger(PACKAGE_LOGGER_NAME) + + +def configure_logging( + *, + level: object = DEFAULT_LOG_LEVEL, + log_dir: Path | str | None = None, + console: bool = True, +) -> logging.Logger: + """Install the rotating-file and console handlers on the package logger. + + Idempotent: re-invoking replaces only the handlers this module installed, so + the level can be re-applied (or a log directory supplied later) without + duplicating sinks or dropping the GUI panel handler. + """ + logger = package_logger() + logger.setLevel(coerce_level(level)) + logger.propagate = False # we own the handlers — don't double-log through the root + + for handler in list(logger.handlers): + if getattr(handler, _MANAGED_FLAG, False): + logger.removeHandler(handler) + with suppress(Exception): + handler.close() + + formatter = logging.Formatter(_LOG_FORMAT, datefmt=_DATE_FORMAT) + + if console: + stream_handler = logging.StreamHandler(stream=sys.stderr) + stream_handler.setFormatter(formatter) + setattr(stream_handler, _MANAGED_FLAG, True) + logger.addHandler(stream_handler) + + if log_dir is not None: + try: + directory = Path(log_dir) + directory.mkdir(parents=True, exist_ok=True) + file_handler = RotatingFileHandler( + directory / _LOG_FILENAME, + maxBytes=_FILE_MAX_BYTES, + backupCount=_FILE_BACKUP_COUNT, + encoding="utf-8", + ) + file_handler.setFormatter(formatter) + setattr(file_handler, _MANAGED_FLAG, True) + logger.addHandler(file_handler) + except OSError: + logger.warning("Could not open log file in %s; logging to console only", log_dir) + + return logger + + +def set_log_level(level: object) -> None: + """Change the live application log level (UI selector / config reload).""" + package_logger().setLevel(coerce_level(level)) + + +def add_handler(handler: logging.Handler) -> None: + """Attach an extra sink (e.g. the GUI log panel) to the package logger.""" + setattr(handler, _MANAGED_FLAG, True) + package_logger().addHandler(handler) + + +def get_logger(name: str) -> logging.Logger: + """Return a child logger under the application root (e.g. ``get_logger("gui")``).""" + return logging.getLogger(f"{PACKAGE_LOGGER_NAME}.{name}") diff --git a/python_app/models/gui_profile_codec.py b/python_app/models/gui_profile_codec.py index 3e83d47..ded16d1 100644 --- a/python_app/models/gui_profile_codec.py +++ b/python_app/models/gui_profile_codec.py @@ -2,6 +2,7 @@ from __future__ import annotations +import logging from typing import Any from python_app.models.gui_profile_schema import ( @@ -18,6 +19,8 @@ from python_app.models.gui_profile_schema import ( ) from python_app.models.run_config_model import RunConfigModel +logger = logging.getLogger(__name__) + def _as_dict(value: Any, context: str) -> dict[str, Any]: """Validate payload node is object-like, treating missing values as empty object.""" @@ -74,6 +77,7 @@ def gui_profile_from_dict(payload: dict[str, Any]) -> GuiProfileModel: profile = GuiProfileModel(run_config=RunConfigModel.from_dict(payload), gui=None) gui_payload = payload.get("gui") if gui_payload is None: + logger.debug("Decoded GUI profile without a 'gui' section; UI state left unset") return profile gui_object = _as_dict(gui_payload, "gui") @@ -124,6 +128,7 @@ def gui_profile_from_dict(payload: dict[str, Any]) -> GuiProfileModel: and root_gpr_object.get("mode") in {"point", "extended"} ) if selected_mode == "gpr" and (legacy_algorithm_mode is not None or has_legacy_root_gpr_mode): + logger.debug("Migrating legacy GPR profile: rewriting selected_mode 'gpr' -> 'legacy_gpr'") selected_mode = "legacy_gpr" gpr_context = "gui.processing.gpr" @@ -495,6 +500,7 @@ def gui_profile_from_dict(payload: dict[str, Any]) -> GuiProfileModel: ) profile.gui = gui + logger.debug("Decoded GUI profile: selected_mode=%s", gui.processing.selected_mode) return profile diff --git a/python_app/models/gui_profile_schema.py b/python_app/models/gui_profile_schema.py index 01deb93..af7c17b 100644 --- a/python_app/models/gui_profile_schema.py +++ b/python_app/models/gui_profile_schema.py @@ -5,11 +5,14 @@ from __future__ import annotations from copy import deepcopy from dataclasses import dataclass, field import json +import logging from pathlib import Path from typing import Any from python_app.models.run_config_model import RunConfigModel +logger = logging.getLogger(__name__) + @dataclass(slots=True) class GuiSwitchStateModel: @@ -159,7 +162,11 @@ class GuiProfileModel: @classmethod def load_from_path(cls, path: Path) -> GuiProfileModel: - """Load JSON file from disk and decode into profile model.""" + """Load a JSON file from disk and decode it into a profile model. + + Raises ValueError when the file's JSON root is not an object. + """ + logger.debug("Loading GUI profile from %s", path) payload = json.loads(path.read_text(encoding="utf-8")) if not isinstance(payload, dict): raise ValueError(f"Config profile root must be JSON object: {path}") diff --git a/python_app/models/run_config_codec.py b/python_app/models/run_config_codec.py index 16967e9..196be07 100644 --- a/python_app/models/run_config_codec.py +++ b/python_app/models/run_config_codec.py @@ -2,9 +2,12 @@ from __future__ import annotations +import logging import math from typing import Any +from python_app.logging_setup import LOG_LEVELS + from python_app.models.run_config_schema import ( ComboModel, GprRxGeometryModel, @@ -21,6 +24,8 @@ from python_app.models.run_config_validation import ( validate_gpr_model, ) +logger = logging.getLogger(__name__) + def _as_dict(value: Any, context: str) -> dict[str, Any]: """Validate payload node is object-like, treating missing values as empty object.""" @@ -45,51 +50,47 @@ def _as_list(value: Any, context: str) -> list[Any]: def _read_str(payload: dict[str, Any], key: str, default: str) -> str: - """Return payload string, treating an explicit JSON `null` as missing. + """Return a payload string, treating an explicit JSON ``null`` as 'use default'. - `payload.get(key, default)` returns `None` when the key exists with value - `null`, which is then coerced into the literal string `"None"` by `str()`. + Keeping the default on ``null`` avoids coercing it to the literal string + ``"None"``. JSON arrays/objects reaching a scalar field are rejected as + ValueError to keep the config-error contract uniform. """ value = payload.get(key, default) if value is None: return default - # A JSON array/object reaching a scalar field is a config error, not a - # str() fallback; surface it as ValueError to keep the error contract uniform. if isinstance(value, (dict, list)): raise ValueError(f"{key} must be a JSON string") return str(value) def _read_int(payload: dict[str, Any], key: str, default: int) -> int: - """Return payload integer, treating an explicit JSON `null` as 'use default'. + """Return a payload integer, treating an explicit JSON ``null`` as 'use default'. - Without this, `int(payload.get(key, default))` raises TypeError on an - explicit `null`. JSON arrays/objects (and other non-numeric scalars) are - rejected as ValueError so malformed types share the config-error contract. + Accepts only a genuine JSON integer (not bool, not float, not numeric + string); silently truncating ``5.7`` or parsing ``"5"`` would hide a + malformed config. Mirrors ``gui_profile_codec._optional_int`` so the two + codecs agree. """ value = payload.get(key, default) if value is None: return default - # Accept only a genuine JSON integer (not bool, not float, not numeric string): - # silently truncating 5.7 or parsing "5" would hide a malformed config. Mirrors - # gui_profile_codec._optional_int so the two codecs agree. if isinstance(value, bool) or not isinstance(value, int): raise ValueError(f"{key} must be a JSON integer") return value def _read_float(payload: dict[str, Any], key: str, default: float) -> float: - """Return payload float, treating an explicit JSON `null` as 'use default'. + """Return a payload float, treating an explicit JSON ``null`` as 'use default'. - Rejects JSON arrays/objects (and other non-numeric scalars) as ValueError, - and rejects non-finite values (NaN/Infinity) at decode time so the C++ - pipeline never receives a value it cannot honor. + Accepts only a genuine JSON number (int/float, not bool, not numeric + string); parsing ``"1e9"`` would hide a malformed config. Non-finite values + (NaN/Infinity) are rejected at decode time so the C++ pipeline never receives + a value it cannot honor. Mirrors ``gui_profile_codec._optional_float``. """ value = payload.get(key, default) if value is None: return default - # Accept only a genuine JSON number (int/float, not bool, not numeric string): - # parsing "1e9" would hide a malformed config. Mirrors gui_profile_codec. if isinstance(value, bool) or not isinstance(value, (int, float)): raise ValueError(f"{key} must be a JSON number") result = float(value) @@ -99,11 +100,11 @@ def _read_float(payload: dict[str, Any], key: str, default: float) -> float: def _read_bool(payload: dict[str, Any], key: str, default: bool) -> bool: - """Return payload boolean, treating an explicit JSON `null` as 'use default'. + """Return a payload boolean, treating an explicit JSON ``null`` as 'use default'. - Plain `bool(payload.get(key, default))` would silently flip the default to - `False` on an explicit `null`; here `null` keeps the default instead. - Non-boolean JSON types are rejected as ValueError. + Keeping the default on ``null`` avoids the silent flip to ``False`` that a + plain ``bool(...)`` coercion would produce. Non-boolean JSON types are + rejected as ValueError. """ value = payload.get(key, default) if value is None: @@ -321,6 +322,14 @@ def run_config_from_dict(payload: dict[str, Any]) -> RunConfigModel: load_switch_payload(port1_payload, model.output_switch) load_switch_payload(port2_payload, model.input_switch) load_control_button_payload(control_button_payload, model.control_button) + + logging_payload = _as_dict(payload.get("logging"), "logging") + level = _read_str(logging_payload, "level", model.logging.level).strip().lower() + if level.upper() not in LOG_LEVELS: + valid = ", ".join(name.lower() for name in LOG_LEVELS) + raise ValueError(f"logging.level must be one of: {valid}") + model.logging.level = level + model.apply_device_model_constraints() runtime = model.runtime @@ -406,7 +415,7 @@ def run_config_from_dict(payload: dict[str, Any]) -> RunConfigModel: ) ) model.apply_device_model_constraints() - # Pass sweep= so #36 sweep bounds (points > 0, stop_hz >= start_hz) are validated + # Pass sweep= so the sweep bounds (points > 0, stop_hz > start_hz) are validated # on the config-load path instead of crashing the C++ acquisition process at boot. validate_gpr_model( model.gpr, @@ -437,6 +446,12 @@ def run_config_from_dict(payload: dict[str, Any]) -> RunConfigModel: input_positions=model.input_switch.positions, output_positions=model.output_switch.positions, ) + logger.debug( + "Decoded run config: radar.model=%s driver_mode=%s combos=%d", + model.radar.model, + model.radar.driver_mode, + len(model.combos), + ) return model @@ -540,6 +555,9 @@ def run_config_to_dict(model: RunConfigModel) -> dict[str, Any]: "debounce_ms": model.control_button.debounce_ms, "action": model.control_button.action, }, + "logging": { + "level": model.logging.level, + }, "run": { "settling_ms": model.runtime.settling_ms, "idle_sleep_ms": model.runtime.idle_sleep_ms, diff --git a/python_app/models/run_config_schema.py b/python_app/models/run_config_schema.py index 854ea22..5441f89 100644 --- a/python_app/models/run_config_schema.py +++ b/python_app/models/run_config_schema.py @@ -5,9 +5,12 @@ from __future__ import annotations from dataclasses import dataclass, field import hashlib import json +import logging from pathlib import Path from typing import Any +logger = logging.getLogger(__name__) + @dataclass(slots=True) class ComboModel: @@ -276,6 +279,18 @@ class GprModel: rx_geometry: list[GprRxGeometryModel] = field(default_factory=list) +@dataclass(slots=True) +class LoggingModel: + """Application logging settings shared by the GUI and headless daemon. + + ``level`` is the verbosity floor (one of DEBUG/INFO/WARNING/ERROR, case-insensitive); + it is chosen from the UI log-level selector, applied to the ``python_app`` logger at + startup, and persisted here so the same verbosity is restored on the next run. + """ + + level: str = "info" + + @dataclass(slots=True) class RunConfigModel: """Top-level runtime config model consumed by C++ processes and GUI.""" @@ -289,6 +304,7 @@ class RunConfigModel: gpr: GprModel = field(default_factory=GprModel) combos: list[ComboModel] = field(default_factory=list) control_button: ControlButtonModel = field(default_factory=ControlButtonModel) + logging: LoggingModel = field(default_factory=LoggingModel) LIBREVNA_MODEL = "librevna" LIBREVNA_MULTI_MODEL = "librevna_multi" @@ -427,7 +443,11 @@ class RunConfigModel: @classmethod def load_from_path(cls, path: Path) -> RunConfigModel: - """Load JSON file from disk and decode into model.""" + """Load a JSON file from disk and decode it into a model. + + Raises ValueError when the file's JSON root is not an object. + """ + logger.debug("Loading run config from %s", path) payload = json.loads(path.read_text(encoding="utf-8")) if not isinstance(payload, dict): raise ValueError(f"Config root must be JSON object: {path}") diff --git a/python_app/models/run_config_validation.py b/python_app/models/run_config_validation.py index adbcfad..c2ac04d 100644 --- a/python_app/models/run_config_validation.py +++ b/python_app/models/run_config_validation.py @@ -2,6 +2,7 @@ from __future__ import annotations +import logging from typing import Any from python_app.models.run_config_schema import ( @@ -13,6 +14,8 @@ from python_app.models.run_config_schema import ( SwitchModel, ) +logger = logging.getLogger(__name__) + # Wire-format bounds shared with the C++ pipeline. The ring header stores the # slot size as a uint32, and capacity * slot_size must address into a single # shared-memory mapping, so reject values the C++ side cannot represent. @@ -26,9 +29,10 @@ _MAX_COMBOS = 4096 def _require_int(payload: dict[str, Any], key: str, default: int) -> int: """Read a strict JSON integer, treating an explicit ``null`` as 'use default'. - Accept only a genuine JSON integer (not bool, not float, not numeric string): - silently truncating ``5.7`` or parsing ``"5"`` would hide a malformed config. - Mirrors ``run_config_codec._read_int`` so every config integer reads identically. + Accepts only a genuine JSON integer (not bool, not float, not numeric string), + because silently truncating ``5.7`` or parsing ``"5"`` would hide a malformed + config. Mirrors ``run_config_codec._read_int`` so every config integer reads + identically. """ value = payload.get(key, default) if value is None: # explicit JSON null -> use the default, never coerce @@ -63,7 +67,7 @@ def load_switch_payload( target: SwitchModel, ) -> None: """Populate switch model from payload preserving defaults for missing values.""" - # #53: scalar reads reject array/object JSON types as ValueError (not TypeError). + # Scalar reads reject array/object JSON types as ValueError (not TypeError). target.name = _require_str(payload, "name", target.name) target.driver_mode = _require_str(payload, "driver_mode", target.driver_mode) target.driver = _require_str(payload, "driver", target.driver) @@ -81,7 +85,7 @@ def load_control_button_payload( target: ControlButtonModel, ) -> None: """Populate control-button model from payload preserving defaults.""" - # #53: scalar reads reject array/object JSON types as ValueError (not TypeError). + # Scalar reads reject array/object JSON types as ValueError (not TypeError). target.enabled = _require_bool(payload, "enabled", target.enabled) target.gpio_chip = _require_str(payload, "gpio_chip", target.gpio_chip) target.pin = _require_int(payload, "pin", target.pin) @@ -92,38 +96,50 @@ def load_control_button_payload( def load_ring_payload(payload: dict[str, Any], target: RingEndpointModel) -> None: - """Populate ring endpoint model from payload preserving defaults.""" - # #53: scalar reads reject array/object JSON types as ValueError (not TypeError). + """Populate ring endpoint model from payload preserving defaults. + + Validates the resulting ring sizing before returning, so a bad config fails + here (on GUI save and at config load) instead of crashing the C++ ring + allocator at boot. + """ + # Scalar reads reject array/object JSON types as ValueError (not TypeError). target.name = _require_str(payload, "name", target.name) target.capacity = _require_int(payload, "capacity", target.capacity) target.slot_size_bytes = _require_int(payload, "slot_size_bytes", target.slot_size_bytes) - # #36: enforce ring sizing in Python so a bad config fails here (in GUI/save and - # at config load) instead of crashing the C++ ring allocator at boot. validate_ring_endpoint(target) def validate_ring_endpoint(ring: RingEndpointModel) -> None: - """Validate ring sizing against the constraints the C++ allocator requires.""" - field = ring.name or "ring" + """Validate ring sizing against the constraints the C++ allocator requires. + + Raises ValueError naming the offending ring when capacity or slot size is + non-positive, the slot size overflows the uint32 wire field, or the segment + would exceed the maximum single mapping. + """ + ring_name = ring.name or "ring" if ring.capacity <= 0: - raise ValueError(f"rings.{field}.capacity must be > 0") + raise ValueError(f"rings.{ring_name}.capacity must be > 0") if ring.slot_size_bytes <= 0: - raise ValueError(f"rings.{field}.slot_size_bytes must be > 0") + raise ValueError(f"rings.{ring_name}.slot_size_bytes must be > 0") if ring.slot_size_bytes > _UINT32_MAX: - raise ValueError(f"rings.{field}.slot_size_bytes exceeds the uint32 wire limit") + raise ValueError(f"rings.{ring_name}.slot_size_bytes exceeds the uint32 wire limit") # Overflow-safe: compare against the ceiling without ever forming the full - # product, so an attacker-sized capacity cannot wrap a fixed-width index. + # product, so an oversized capacity cannot wrap a fixed-width index. if ring.capacity > _RING_SEGMENT_MAX_BYTES // ring.slot_size_bytes: raise ValueError( - f"rings.{field} capacity * slot_size_bytes exceeds the maximum ring segment size" + f"rings.{ring_name} capacity * slot_size_bytes exceeds the maximum ring segment size" ) def validate_sweep_model(sweep: RadarSweepModel) -> None: - """Validate radar sweep bounds in Python so a bad sweep fails in the GUI/save - and at config load rather than aborting the C++ acquisition process at boot. + """Validate radar sweep bounds (point count and frequency span). + + Runs in Python so a bad sweep fails on GUI save and at config load rather + than aborting the C++ acquisition process at boot. Raises ValueError when + ``points`` is non-integral or non-positive, or when ``stop_hz`` does not + exceed ``start_hz``. """ - # #36: points must be a positive, integral count of frequency samples. + # points must be a positive, integral count of frequency samples. points = sweep.points if isinstance(points, bool) or not isinstance(points, int): raise ValueError("radar.sweep.points must be an integer") @@ -142,9 +158,11 @@ def validate_gpr_model( ) -> None: """Validate stable GPR config against current switch dimensions. - When ``sweep`` is supplied (load and GUI/save paths share this chokepoint), - its bounds are validated here too so #36 sweep failures surface alongside the - GPR checks instead of as a C++ boot crash. + Checks that the relative permittivity is positive and that every tx/rx + geometry entry indexes a valid, non-duplicate switch position. When ``sweep`` + is supplied (the load and GUI/save paths share this chokepoint), its bounds + are validated here too so sweep failures surface alongside the GPR checks + instead of as a C++ boot crash. """ if sweep is not None: validate_sweep_model(sweep) @@ -200,7 +218,12 @@ def validate_combos( def parse_combos_from_text(text: str) -> list[ComboModel]: - """Parse UI combos string in `input:output,input:output` format.""" + """Parse a UI combos string in ``input:output,input:output`` format. + + Returns an empty list for blank input. Raises ValueError (naming the + offending pair) on malformed syntax, empty sides, non-integer values, more + than ``_MAX_COMBOS`` entries, or a non-blank string that yields no combos. + """ cleaned = text.strip() if not cleaned: return [] @@ -213,13 +236,13 @@ def parse_combos_from_text(text: str) -> list[ComboModel]: if ":" not in pair: raise ValueError(f"Invalid combo syntax: {pair!r}. Expected input:output") - # #57: cap the combo count so a pathological string cannot expand into a - # list large enough to stall the GUI or the acquisition loop. + # Cap the combo count so a pathological string cannot expand into a list + # large enough to stall the GUI or the acquisition loop. if len(combos) >= _MAX_COMBOS: raise ValueError(f"Too many combos: limit is {_MAX_COMBOS}") input_text, output_text = (side.strip() for side in pair.split(":", 1)) - # #57: reject empty sides and re-raise non-integer values naming the pair/side. + # Reject empty sides and re-raise non-integer values naming the pair/side. if not input_text: raise ValueError(f"Invalid combo {pair!r}: input side is empty") if not output_text: @@ -236,4 +259,5 @@ def parse_combos_from_text(text: str) -> list[ComboModel]: if not combos: raise ValueError("No valid combos were provided") + logger.debug("Parsed %d combo(s) from UI text", len(combos)) return combos diff --git a/python_app/orchestration/config_writer.py b/python_app/orchestration/config_writer.py index 09d013b..42430b1 100644 --- a/python_app/orchestration/config_writer.py +++ b/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 diff --git a/python_app/orchestration/gui_session_state.py b/python_app/orchestration/gui_session_state.py index 7ac7b12..ca7de48 100644 --- a/python_app/orchestration/gui_session_state.py +++ b/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 diff --git a/python_app/orchestration/live_processing_config.py b/python_app/orchestration/live_processing_config.py index 9186964..55b3bb0 100644 --- a/python_app/orchestration/live_processing_config.py +++ b/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) diff --git a/python_app/orchestration/pipeline_metrics.py b/python_app/orchestration/pipeline_metrics.py index 8f4f1f0..b5e8ff2 100644 --- a/python_app/orchestration/pipeline_metrics.py +++ b/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).""" diff --git a/python_app/orchestration/process_supervisor.py b/python_app/orchestration/process_supervisor.py index 264ea5f..224d022 100644 --- a/python_app/orchestration/process_supervisor.py +++ b/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//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", diff --git a/python_app/orchestration/shm/ring_reader.py b/python_app/orchestration/shm/ring_reader.py index b8a3a94..6705c52 100644 --- a/python_app/orchestration/shm/ring_reader.py +++ b/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 diff --git a/python_app/orchestration/shm/ring_writer.py b/python_app/orchestration/shm/ring_writer.py index 4bbf6f9..d4386db 100644 --- a/python_app/orchestration/shm/ring_writer.py +++ b/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 diff --git a/python_app/scripts/convert_legacy_preprocess_sets.py b/python_app/scripts/convert_legacy_preprocess_sets.py index ba297ae..173a468 100644 --- a/python_app/scripts/convert_legacy_preprocess_sets.py +++ b/python_app/scripts/convert_legacy_preprocess_sets.py @@ -34,6 +34,7 @@ S21_ONLY_TARGET_KINDS = {"s21_calibration", "s21_reference"} def _build_parser() -> argparse.ArgumentParser: + """Return the argument parser for the legacy preprocess-set conversion CLI.""" parser = argparse.ArgumentParser( description=( "Convert old preprocess-set storage from a legacy python_app/data tree into the " @@ -59,6 +60,7 @@ def _build_parser() -> argparse.ArgumentParser: def _load_json(path: Path) -> dict[str, Any]: + """Read a JSON file and return its top-level object, rejecting non-object roots.""" payload = json.loads(path.read_text(encoding="utf-8")) if not isinstance(payload, dict): raise ValueError(f"JSON root must be object: {path}") @@ -66,6 +68,7 @@ def _load_json(path: Path) -> dict[str, Any]: def _read_combo_position(combo_payload: dict[str, Any], *, primary_key: str, alias_key: str) -> int: + """Return a switch position from a combo record, accepting the primary or alias key.""" if primary_key in combo_payload: return int(combo_payload[primary_key]) if alias_key in combo_payload: @@ -74,16 +77,23 @@ def _read_combo_position(combo_payload: dict[str, Any], *, primary_key: str, ali def _combo_suffix(input_pos: int, output_pos: int) -> str: + """Return the per-combo array-name suffix (e.g. ``i0_o1``) used in legacy NPZ keys.""" return f"i{input_pos}_o{output_pos}" def _load_array(arrays: Any, key: str, *, dtype: np.dtype[Any], label: str) -> np.ndarray: + """Return a flattened array of the given dtype from an NPZ mapping, by key.""" if key not in arrays: raise KeyError(f"Missing {label} array '{key}' in NPZ archive") return np.asarray(arrays[key], dtype=dtype).reshape(-1) def _load_legacy_collection(meta_path: Path, npz_path: Path, *, target_kind: str) -> SweepCollection: + """Build a SweepCollection from a legacy meta/NPZ pair for the given target kind. + + Reads per-combo frequency, S21 and (when present) S11 arrays. For S21-only target + kinds a missing S11 is filled with zeros; for any other kind a missing S11 is an error. + """ meta = _load_json(meta_path) combos_payload = meta.get("combos") if not isinstance(combos_payload, list): @@ -148,6 +158,11 @@ def _convert_one_set( meta_path: Path, overwrite: bool, ) -> None: + """Convert a single legacy set (meta + NPZ) and save it under the target kind. + + Raises if the companion NPZ is missing, or if the destination already exists and + ``overwrite`` is False. + """ set_name = meta_path.stem npz_path = meta_path.with_suffix(".npz") if not npz_path.exists(): @@ -168,6 +183,11 @@ def _convert_one_set( def main() -> int: + """Walk the legacy data tree, convert every recognized set, and print a summary. + + Returns 0 on full success, 1 if any set failed to convert, or 2 if no convertible + sets were found. + """ parser = _build_parser() args = parser.parse_args() diff --git a/python_app/scripts/convert_prog_libre_manual_to_vna_history.py b/python_app/scripts/convert_prog_libre_manual_to_vna_history.py index 57fc4f8..623db0c 100644 --- a/python_app/scripts/convert_prog_libre_manual_to_vna_history.py +++ b/python_app/scripts/convert_prog_libre_manual_to_vna_history.py @@ -13,10 +13,12 @@ import numpy as np def _real_imag_keys(trace_prefix: str) -> tuple[str, str]: + """Return the LibreVNA CSV column names for a trace's real and imaginary parts.""" return f"{trace_prefix}_Real", f"{trace_prefix}_Imaginary" def _load_complex_trace(csv_path: Path, trace_prefix: str) -> tuple[np.ndarray, np.ndarray]: + """Load one LibreVNA CSV and return its (frequency_hz, complex trace) arrays.""" real_key, imag_key = _real_imag_keys(trace_prefix) frequencies: list[float] = [] values: list[complex] = [] @@ -62,6 +64,7 @@ def _apply_one_port_osl( source_match: np.ndarray, reflection_tracking: np.ndarray, ) -> np.ndarray: + """Apply OSL one-port error correction to a measured S11 trace and return it.""" numerator = measured_trace - directivity denominator = reflection_tracking + (source_match * numerator) @@ -72,6 +75,7 @@ def _apply_one_port_osl( def _apply_through_calibration(measured_trace: np.ndarray, through_trace: np.ndarray) -> np.ndarray: + """Normalize a measured S21 trace by the through reference and return it.""" corrected = np.array(measured_trace, copy=True) stable_mask = np.abs(through_trace) > 1e-18 corrected[stable_mask] = measured_trace[stable_mask] / through_trace[stable_mask] @@ -79,15 +83,21 @@ def _apply_through_calibration(measured_trace: np.ndarray, through_trace: np.nda def _complex_to_points(values: np.ndarray) -> list[list[float]]: + """Return complex samples as ``[real, imag]`` pairs for JSON serialization.""" return [[float(value.real), float(value.imag)] for value in values] def _scan_file_sort_key(csv_path: Path) -> tuple[int, str]: + """Return a sort key ordering numeric scan filenames first, by integer value.""" stem = csv_path.stem return (int(stem), stem) if stem.isdigit() else (10**9, stem) def _load_scan_series(folder: Path, trace_prefix: str) -> tuple[np.ndarray, list[tuple[str, np.ndarray]]]: + """Load every numbered scan CSV in a folder and return (frequency_hz, named traces). + + All scans must share a common frequency axis; a mismatch raises ValueError. + """ scan_paths = [ path for path in sorted(folder.glob("*.csv"), key=_scan_file_sort_key) @@ -111,6 +121,7 @@ def _load_scan_series(folder: Path, trace_prefix: str) -> tuple[np.ndarray, list def _require_matching_frequency_axis(label: str, left: np.ndarray, right: np.ndarray) -> None: + """Raise ValueError (tagged with ``label``) unless two frequency axes match within tolerance.""" if not np.allclose(left, right, rtol=0.0, atol=1e-6): raise ValueError(f"{label} frequency axes do not match") @@ -127,6 +138,11 @@ def _build_history_payload( raw_record_count: int, preprocessed_record_count: int, ) -> dict[str, Any]: + """Assemble the vna-system history payload from paired sweep and calibrated scans. + + Pairs each sweep scan with its calibrated counterpart by order (names must match), + attaching the shared reference trace and sweep config to every history entry. + """ if len(sweep_scans) != len(calibrated_scans): raise ValueError("Sweep/calibrated scan counts do not match") @@ -168,15 +184,18 @@ def _build_history_payload( def _write_payload(output_path: Path, payload: dict[str, Any]) -> None: + """Write a payload as indented UTF-8 JSON, creating parent directories as needed.""" output_path.parent.mkdir(parents=True, exist_ok=True) output_path.write_text(json.dumps(payload, ensure_ascii=False, indent=2), encoding="utf-8") def _rmse(left: np.ndarray, right: np.ndarray) -> float: + """Return the root-mean-square magnitude difference between two complex traces.""" return float(np.sqrt(np.mean(np.abs(left - right) ** 2))) def _build_parser() -> argparse.ArgumentParser: + """Return the argument parser for the prog_libre-to-vna-history conversion CLI.""" parser = argparse.ArgumentParser( description="Convert manual LibreVNA S11/S21 CSV captures in prog_libre to vna history JSON.", ) @@ -232,6 +251,12 @@ def _build_parser() -> argparse.ArgumentParser: def main() -> None: + """Calibrate and convert the prog_libre S11/S21 CSV captures into history JSON files. + + Builds OSL coefficients for S11 and a through reference for S21, applies them to the + uncalibrated scans, writes raw and pre-calibrated history files for both channels, and + prints RMSE diagnostics against the supplied calibrated folder. + """ args = _build_parser().parse_args() calibration_dir = args.calibration_dir.expanduser().resolve() diff --git a/python_app/scripts/convert_snapshot_to_vna_history.py b/python_app/scripts/convert_snapshot_to_vna_history.py index d07ea23..21449a9 100644 --- a/python_app/scripts/convert_snapshot_to_vna_history.py +++ b/python_app/scripts/convert_snapshot_to_vna_history.py @@ -35,6 +35,7 @@ class CollectionRef: def _load_json(path: Path) -> dict[str, Any]: + """Read a JSON file and return its top-level object, rejecting non-object roots.""" payload = json.loads(path.read_text(encoding="utf-8")) if not isinstance(payload, dict): raise ValueError(f"JSON root must be object: {path}") @@ -42,17 +43,20 @@ def _load_json(path: Path) -> dict[str, Any]: def _collection_dirs(stage_dir: Path) -> list[Path]: + """Return the stage's collection subdirectories sorted by name (empty if absent).""" if not stage_dir.exists(): return [] return sorted([path for path in stage_dir.iterdir() if path.is_dir()], key=lambda path: path.name) def _parse_stage_index(name: str, fallback: int) -> int: + """Return the leading numeric prefix of a collection dir name, or ``fallback``.""" prefix = name.split("_", 1)[0] return int(prefix) if prefix.isdigit() else fallback def _pick_trace_meta(meta: dict[str, Any], input_index: int, output_index: int) -> dict[str, Any] | None: + """Return the trace record matching the given input/output switch indices, or None.""" traces = meta.get("traces", []) if not isinstance(traces, list): return None @@ -65,6 +69,7 @@ def _pick_trace_meta(meta: dict[str, Any], input_index: int, output_index: int) def _normalize_channel(channel: str) -> str: + """Return a lowercased channel name, accepting only ``s21`` or ``s11``.""" normalized = str(channel).strip().lower() if normalized not in {"s21", "s11"}: raise ValueError("channel must be either 's21' or 's11'") @@ -79,6 +84,11 @@ def _load_stage_records( output_index: int, channel: str, ) -> list[TraceRecord]: + """Load TraceRecords for one stage and one switch combo, for the given channel. + + Skips collections without a matching trace or array files; raises on shape mismatch + or non-finite samples. + """ stage_dir = snapshot_dir / stage records: list[TraceRecord] = [] @@ -145,6 +155,11 @@ def _load_stage_refs(snapshot_dir: Path, stage: str) -> list[CollectionRef]: def _index_by_collection_occurrence(records: list[TraceRecord]) -> tuple[dict[tuple[int, int], TraceRecord], list[tuple[int, int]]]: + """Key records by (collection_id, occurrence) and return the map plus original order. + + The occurrence counter disambiguates repeated collection ids, so raw and preprocessed + stages can be aligned slot-for-slot even when ids recur. + """ counters: defaultdict[int, int] = defaultdict(int) record_map: dict[tuple[int, int], TraceRecord] = {} order: list[tuple[int, int]] = [] @@ -158,6 +173,7 @@ def _index_by_collection_occurrence(records: list[TraceRecord]) -> tuple[dict[tu def _complex_to_points(values: np.ndarray) -> list[list[float]]: + """Return complex samples as ``[real, imag]`` pairs for JSON serialization.""" return [[float(v.real), float(v.imag)] for v in values] @@ -168,6 +184,12 @@ def _build_sweep_history( channel: str, primary_stage: str, ) -> list[dict[str, Any]]: + """Merge raw and preprocessed records into vna-system ``sweep_history`` entries. + + Iterates collections in the primary stage's order, pairing each with its counterpart + in the other stage; the raw samples become ``sweep_points`` and the preprocessed + samples ``calibrated_points`` (falling back to whichever stage is present). + """ raw_map, raw_order = _index_by_collection_occurrence(raw_records) pre_map, pre_order = _index_by_collection_occurrence(preprocessed_records) @@ -250,6 +272,7 @@ def _stage_alignment_warning(pre_refs: list[CollectionRef], result_refs: list[Co def _build_parser() -> argparse.ArgumentParser: + """Return the argument parser for the snapshot-to-vna-history conversion CLI.""" parser = argparse.ArgumentParser( description=( "Convert radar_system snapshot (numpy-directory-v1) to a vna_system-compatible " @@ -288,6 +311,12 @@ def _build_parser() -> argparse.ArgumentParser: def main() -> None: + """Convert one snapshot's chosen channel/combo into a vna-system history JSON file. + + Loads raw and preprocessed traces, builds the sweep history (optionally trimmed to the + last N sweeps), writes the output JSON, and prints a summary plus any stage-alignment + warning. + """ parser = _build_parser() args = parser.parse_args() channel = _normalize_channel(args.channel) diff --git a/python_app/scripts/k209_remote_server.py b/python_app/scripts/k209_remote_server.py index a1659d5..1a4dfb4 100644 --- a/python_app/scripts/k209_remote_server.py +++ b/python_app/scripts/k209_remote_server.py @@ -36,6 +36,7 @@ class K209RemoteRequestHandler(socketserver.StreamRequestHandler): """Handle one persistent K209 remote client connection.""" def setup(self) -> None: + """Disable Nagle and open the local K209 VISA session for this connection.""" super().setup() self.request.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) self.service = CompactMK209Service( @@ -47,12 +48,14 @@ class K209RemoteRequestHandler(socketserver.StreamRequestHandler): self.service.open() def finish(self) -> None: + """Close the K209 VISA session when the client disconnects.""" try: self.service.close() finally: super().finish() def handle(self) -> None: + """Serve command bytes from the client until EOF, reporting errors back inline.""" while True: command = self.rfile.read(1) if not command: @@ -74,12 +77,14 @@ class K209RemoteRequestHandler(socketserver.StreamRequestHandler): self.wfile.flush() def _handle_identity(self) -> None: + """Reply with the device identity string (length-prefixed UTF-8).""" payload = self.service.query_identity().encode("utf-8") self.wfile.write(STATUS_OK) send_u32(self.wfile, len(payload)) self.wfile.write(payload) def _handle_limits(self) -> None: + """Reply with the device frequency/IFBW/power/point limits as a packed struct.""" limits = self.service.read_device_limits() self.wfile.write(STATUS_OK) self.wfile.write( @@ -95,6 +100,7 @@ class K209RemoteRequestHandler(socketserver.StreamRequestHandler): ) def _handle_configure(self) -> None: + """Apply a sweep config from the client and reply with the frequency axis.""" start_hz, stop_hz, points, ifbw_hz, power_dbm = CONFIG_STRUCT.unpack( recv_exact(self.rfile, CONFIG_STRUCT.size) ) @@ -111,6 +117,7 @@ class K209RemoteRequestHandler(socketserver.StreamRequestHandler): send_float32_array(self.wfile, self.service.frequency_axis()) def _handle_acquire(self) -> None: + """Acquire one interleaved sweep and reply with the S11 and S21 arrays.""" sweep = self.service.acquire_interleaved() self.wfile.write(STATUS_OK) send_u32(self.wfile, int(sweep.frequency_hz.size)) @@ -124,12 +131,14 @@ class K209RemoteServer(socketserver.TCPServer): allow_reuse_address = True def __init__(self, server_address: tuple[str, int], resource: str, timeout_ms: int) -> None: + """Store the VISA resource and timeout used by each accepted connection.""" self.resource = resource self.timeout_ms = timeout_ms super().__init__(server_address, K209RemoteRequestHandler) def _parse_args() -> argparse.Namespace: + """Parse command-line options for the K209 remote server.""" parser = argparse.ArgumentParser(description="Serve a locally connected Compact-M K209 over TCP.") parser.add_argument("--host", default="0.0.0.0", help="Server bind address.") parser.add_argument("--port", type=int, default=DEFAULT_REMOTE_PORT, help="Server TCP port.") @@ -139,6 +148,7 @@ def _parse_args() -> argparse.Namespace: def main() -> int: + """Bind the K209 remote server and serve clients until interrupted.""" args = _parse_args() with K209RemoteServer((args.host, args.port), resource=args.resource, timeout_ms=args.timeout_ms) as server: print(f"K209 remote server listening on {args.host}:{args.port}") diff --git a/python_app/scripts/k209_remote_smoke_test.py b/python_app/scripts/k209_remote_smoke_test.py index ba52a98..80738f0 100644 --- a/python_app/scripts/k209_remote_smoke_test.py +++ b/python_app/scripts/k209_remote_smoke_test.py @@ -18,6 +18,7 @@ from python_app.models.run_config_model import RadarSweepModel def _parse_args() -> argparse.Namespace: + """Parse command-line options for the remote K209 smoke test.""" parser = argparse.ArgumentParser(description="Validate remote K209 connection and one sweep.") parser.add_argument("--host", default=DEFAULT_REMOTE_HOST, help="K209 remote server host.") parser.add_argument("--port", type=int, default=DEFAULT_REMOTE_PORT, help="K209 remote server port.") @@ -30,6 +31,11 @@ def _parse_args() -> argparse.Namespace: def main() -> int: + """Connect to a remote K209, run one sweep, and validate its shape and values. + + Raises on an unexpected point count, non-finite samples, or a non-monotonic frequency + axis; prints a one-line summary on success. + """ args = _parse_args() sweep = RadarSweepModel( start_hz=args.start_hz, diff --git a/python_app/scripts/k209_smoke_test.py b/python_app/scripts/k209_smoke_test.py index 26842d1..4137ba7 100644 --- a/python_app/scripts/k209_smoke_test.py +++ b/python_app/scripts/k209_smoke_test.py @@ -11,6 +11,7 @@ from python_app.models.run_config_model import RadarSweepModel def _parse_args() -> argparse.Namespace: + """Parse command-line options for the local K209 VISA smoke test.""" parser = argparse.ArgumentParser(description="Acquire one K209 sweep through VISA HiSLIP") parser.add_argument( "--resource", @@ -36,6 +37,7 @@ def _parse_args() -> argparse.Namespace: def _validate_result(result, expected_points: int) -> None: + """Raise RuntimeError unless the sweep has the expected point count, monotonic axis, and finite S11/S21.""" if result.x.shape != (expected_points,): raise RuntimeError(f"Unexpected frequency shape: {result.x.shape}") s11 = result.trace("s11") @@ -53,6 +55,11 @@ def _validate_result(result, expected_points: int) -> None: def main() -> int: + """Acquire one sweep from a locally connected K209 and validate it end to end. + + Opens the VISA session, configures the sweep, validates the result, checks the SCPI + error queue, and prints a summary; raises on any validation or SCPI failure. + """ args = _parse_args() sweep = RadarSweepModel( start_hz=args.start_hz, diff --git a/python_app/scripts/k209_sweep_benchmark.py b/python_app/scripts/k209_sweep_benchmark.py index 0c29ee2..10df26d 100644 --- a/python_app/scripts/k209_sweep_benchmark.py +++ b/python_app/scripts/k209_sweep_benchmark.py @@ -62,6 +62,7 @@ class BenchmarkResult: def _validate_config() -> None: + """Raise if any module-level benchmark constant is outside its valid range.""" if POINTS < 2: raise ValueError("POINTS must be >= 2") if WARMUP_SWEEPS < 0: @@ -77,6 +78,7 @@ def _validate_config() -> None: def _validate_interleaved(raw, expected_points: int) -> None: + """Raise unless a raw interleaved sweep has the expected shapes, monotonic axis, and finite values.""" if raw.frequency_hz.shape != (expected_points,): raise RuntimeError(f"Unexpected frequency shape: {raw.frequency_hz.shape}") if raw.s11_values.shape != (expected_points * 2,): @@ -94,6 +96,7 @@ def _validate_interleaved(raw, expected_points: int) -> None: def _validate_result(result, expected_points: int) -> None: + """Raise unless a converted SweepResult has the expected shapes and finite S11/S21.""" if result.x.shape != (expected_points,): raise RuntimeError(f"Unexpected frequency shape: {result.x.shape}") for name in ("s11", "s21"): @@ -105,12 +108,18 @@ def _validate_result(result, expected_points: int) -> None: def _percentile(values: list[float], percentile: float) -> float: + """Return the nearest-rank percentile (0..1) of ``values``.""" sorted_values = sorted(values) index = round((len(sorted_values) - 1) * percentile) return sorted_values[index] def _run_benchmark(service: CompactMK209Service, *, points: int, warmup: int, sweeps: int, convert: bool) -> BenchmarkResult: + """Time ``sweeps`` acquisitions after ``warmup`` warm-up sweeps and return their durations. + + When ``convert`` is True the timed path includes SweepResult construction; otherwise it + times the raw interleaved REAL32 acquisition. The first and last sweeps are validated. + """ acquire = service.acquire if convert else service.acquire_interleaved first = acquire() @@ -137,6 +146,7 @@ def _run_benchmark(service: CompactMK209Service, *, points: int, warmup: int, sw def _print_limits(limits: dict[str, float | int]) -> None: + """Print the device frequency/IFBW/power/point limits as a single human-readable line.""" print( "K209 limits: " f"frequency={limits['min_frequency_hz']:.0f}..{limits['max_frequency_hz']:.0f} Hz, " @@ -147,6 +157,7 @@ def _print_limits(limits: dict[str, float | int]) -> None: def main() -> int: + """Run the K209 sweep-acquisition benchmark and print timing/throughput statistics.""" _validate_config() sweep = RadarSweepModel( diff --git a/python_app/scripts/kamil_adc_raw_producer.py b/python_app/scripts/kamil_adc_raw_producer.py index b2a30aa..fc22178 100644 --- a/python_app/scripts/kamil_adc_raw_producer.py +++ b/python_app/scripts/kamil_adc_raw_producer.py @@ -94,6 +94,7 @@ def _open_radar_with_retry( logger.info("Kamil ADC opened after %d attempt(s).", attempt + 1) return True + logger.debug("Stop requested before the Kamil ADC became available.") return False @@ -116,6 +117,10 @@ def main() -> int: if not config.is_kamil_adc: raise RuntimeError("kamil_adc_raw_producer requires radar.model='kamil_adc'") config.ensure_combos() + logger.info( + "Kamil ADC raw producer starting: config=%s, combos=%d, continuous=%s", + args.config, len(config.combos), config.runtime.continuous, + ) raw_writer = ShmRingWriter( config.rings.raw.name, @@ -127,6 +132,10 @@ def main() -> int: config.rings.raw_tap.capacity, config.rings.raw_tap.slot_size_bytes, ) + logger.debug( + "Opened SHM ring writers: raw=%s, raw_tap=%s", + config.rings.raw.name, config.rings.raw_tap.name, + ) radar = KamilAdcService(config) input_switch = _switch_from_model(config.input_switch) output_switch = _switch_from_model(config.output_switch) diff --git a/python_app/scripts/matrix_raw_producer.py b/python_app/scripts/matrix_raw_producer.py index 409aadc..4d1960a 100644 --- a/python_app/scripts/matrix_raw_producer.py +++ b/python_app/scripts/matrix_raw_producer.py @@ -74,6 +74,7 @@ def _open_radar_with_retry( logger.info("Matrix radar opened after %d attempt(s).", attempt + 1) return radar + logger.debug("Stop requested before any matrix radar became available.") return None @@ -99,6 +100,10 @@ def main() -> int: "matrix_raw_producer requires a matrix-mode radar.model " "(librevna_multi or sn9000)" ) + logger.info( + "Matrix radar raw producer starting: config=%s, model=%s, continuous=%s", + args.config, config.radar.model, config.runtime.continuous, + ) raw_writer = ShmRingWriter( config.rings.raw.name, @@ -110,6 +115,10 @@ def main() -> int: config.rings.raw_tap.capacity, config.rings.raw_tap.slot_size_bytes, ) + logger.debug( + "Opened SHM ring writers: raw=%s, raw_tap=%s", + config.rings.raw.name, config.rings.raw_tap.name, + ) radar: MatrixRadarService | None = None try: diff --git a/python_app/scripts/sn9000_smoke_test.py b/python_app/scripts/sn9000_smoke_test.py index 892dfaa..b28f6d6 100644 --- a/python_app/scripts/sn9000_smoke_test.py +++ b/python_app/scripts/sn9000_smoke_test.py @@ -12,6 +12,7 @@ from python_app.models.run_config_model import RadarSweepModel, RunConfigModel def _parse_args() -> argparse.Namespace: + """Parse command-line options for the SN9000 VISA smoke test.""" parser = argparse.ArgumentParser(description="Acquire one SN9000 collection through VISA HiSLIP") parser.add_argument( "--host", @@ -40,6 +41,7 @@ def _parse_args() -> argparse.Namespace: def _validate_collection(collection: SweepCollection, expected_points: int) -> None: + """Raise unless a SN9000 collection has the expected traces, combos, shapes, and finite values.""" expected_traces = ( RunConfigModel.MULTI_DEVICE_INPUT_POSITIONS * RunConfigModel.MULTI_DEVICE_OUTPUT_POSITIONS ) @@ -82,6 +84,11 @@ def _validate_collection(collection: SweepCollection, expected_points: int) -> N def main() -> int: + """Acquire one SN9000 collection and validate it end to end. + + Opens the VISA session, configures the sweep, validates the collection, checks the SCPI + error queue, and prints a summary; raises on any validation or SCPI failure. + """ args = _parse_args() sweep = RadarSweepModel( start_hz=args.start_hz, diff --git a/python_app/storage/npz/paths.py b/python_app/storage/npz/paths.py index e11e0f6..8434b3e 100644 --- a/python_app/storage/npz/paths.py +++ b/python_app/storage/npz/paths.py @@ -21,11 +21,11 @@ def radar_key_from_config( if extra_serials: serial_parts.extend(str(value).strip() or "no_serial" for value in extra_serials) serial_part = "_".join(sanitize_path_component(value) for value in serial_parts) - start_token = _format_float_for_key(sweep_start_hz) - stop_token = _format_float_for_key(sweep_stop_hz) + start_token = format_float_for_key(sweep_start_hz) + stop_token = format_float_for_key(sweep_stop_hz) points_token = "adc" if model_name.strip().lower() == "kamil_adc" else str(int(sweep_points)) - ifbw_token = _format_float_for_key(ifbw_hz) - power_token = _format_float_for_key(power_dbm) + ifbw_token = format_float_for_key(ifbw_hz) + power_token = format_float_for_key(power_dbm) return ( f"{model_name}_{serial_part}" f"_st{start_token}_sp{stop_token}" @@ -51,8 +51,3 @@ def format_float_for_key(value: float) -> str: if abs(value - float(integer)) < 1e-6: return str(integer) return f"{value:.6f}".rstrip("0").rstrip(".") - - -def _format_float_for_key(value: float) -> str: - """Private alias preserved for internal compatibility.""" - return format_float_for_key(value) diff --git a/python_app/storage/npz/snapshot_numpy.py b/python_app/storage/npz/snapshot_numpy.py index 6476df3..41f7aef 100644 --- a/python_app/storage/npz/snapshot_numpy.py +++ b/python_app/storage/npz/snapshot_numpy.py @@ -3,6 +3,7 @@ from __future__ import annotations import json +import logging from pathlib import Path from typing import Any, TypeVar @@ -12,6 +13,8 @@ from python_app.models.dataset_model import ResultCollection, SweepCollection from python_app.storage.npz.paths import collection_dir_name, sanitize_path_component from python_app.storage.npz.serialize import serialize_result_collection, serialize_trace_collection +logger = logging.getLogger(__name__) + TCollection = TypeVar("TCollection") @@ -108,6 +111,7 @@ def select_aligned_histories( def save_trace_history_binary(stage_dir: Path, history: list[SweepCollection], magic: int) -> None: """Write binary trace history with lightweight metadata sidecars.""" stage_dir.mkdir(parents=True, exist_ok=True) + logger.debug("Writing %d binary trace collection(s) to %s", len(history), stage_dir) for index, collection in enumerate(history): binary_path = stage_dir / f"{index:04d}.bin" metadata_path = stage_dir / f"{index:04d}.json" @@ -130,6 +134,7 @@ def save_trace_history_binary(stage_dir: Path, history: list[SweepCollection], m def save_result_history_binary(stage_dir: Path, history: list[ResultCollection]) -> None: """Write binary processed-result history with metadata sidecars.""" stage_dir.mkdir(parents=True, exist_ok=True) + logger.debug("Writing %d binary result collection(s) to %s", len(history), stage_dir) for index, collection in enumerate(history): binary_path = stage_dir / f"{index:04d}.bin" metadata_path = stage_dir / f"{index:04d}.json" @@ -151,6 +156,7 @@ def save_result_history_binary(stage_dir: Path, history: list[ResultCollection]) def save_trace_history_numpy(stage_dir: Path, history: list[SweepCollection]) -> None: """Write raw/preprocessed collections as NumPy directory tree.""" stage_dir.mkdir(parents=True, exist_ok=True) + logger.debug("Writing %d NumPy trace collection(s) to %s", len(history), stage_dir) for index, collection in enumerate(history): collection_dir = stage_dir / collection_dir_name(index, collection.collection_id, collection.monotonic_ns) collection_dir.mkdir(parents=True, exist_ok=False) @@ -194,6 +200,7 @@ def save_trace_history_numpy(stage_dir: Path, history: list[SweepCollection]) -> def save_result_history_numpy(stage_dir: Path, history: list[ResultCollection]) -> None: """Write processed result collections as NumPy directory tree.""" stage_dir.mkdir(parents=True, exist_ok=True) + logger.debug("Writing %d NumPy result collection(s) to %s", len(history), stage_dir) for index, collection in enumerate(history): collection_dir = stage_dir / collection_dir_name(index, collection.collection_id, collection.monotonic_ns) collection_dir.mkdir(parents=True, exist_ok=False) diff --git a/python_app/storage/npz/store.py b/python_app/storage/npz/store.py index c8d2b4d..ce1f0c9 100644 --- a/python_app/storage/npz/store.py +++ b/python_app/storage/npz/store.py @@ -5,6 +5,7 @@ from __future__ import annotations from contextlib import suppress from datetime import datetime, timezone import json +import logging from pathlib import Path from typing import Any @@ -23,6 +24,8 @@ from python_app.storage.npz.snapshot_numpy import ( from python_app.storage.npz.vna_history_json import build_vna_history_payload from python_app.storage.store_api import StoreApi +logger = logging.getLogger(__name__) + class NpzStore(StoreApi): """Persist preprocess sets and runtime snapshots using NumPy files.""" @@ -31,6 +34,7 @@ class NpzStore(StoreApi): """Create store rooted at `root_dir`.""" self._root_dir = root_dir self._root_dir.mkdir(parents=True, exist_ok=True) + logger.debug("NpzStore rooted at %s", self._root_dir) @staticmethod def _vna_json_output_dir(output_root_dir: Path, output_stem: str) -> Path: @@ -85,10 +89,14 @@ class NpzStore(StoreApi): npz_tmp.replace(npz_path) meta_tmp.replace(meta_path) except BaseException: + logger.exception("Failed to save set %s/%s/%s; rolling back temp files", kind, radar_key, set_name) for tmp_path in (npz_tmp, meta_tmp): with suppress(OSError): tmp_path.unlink(missing_ok=True) raise + logger.info( + "Saved set %s/%s/%s (%d traces) to %s", kind, radar_key, set_name, len(combo_records), npz_path + ) def load_set(self, kind: str, radar_key: str, set_name: str) -> SweepCollection: """Load named preprocess set from NPZ representation.""" @@ -97,6 +105,7 @@ class NpzStore(StoreApi): meta_path = set_dir / f"{set_name}.json" if not npz_path.exists() or not meta_path.exists(): + logger.error("Missing set files for %s/%s/%s", kind, radar_key, set_name) raise FileNotFoundError(f"Missing set files for {kind}/{radar_key}/{set_name}") set_label = f"{kind}/{radar_key}/{set_name}" @@ -118,14 +127,17 @@ class NpzStore(StoreApi): ) ) - return SweepCollection( + collection = SweepCollection( collection_id=int(meta["collection_id"]), monotonic_ns=int(meta["monotonic_ns"]), traces=traces, capture_start_ns=int(meta.get("capture_start_ns", 0)), capture_end_ns=int(meta.get("capture_end_ns", 0)), ) + logger.debug("Loaded set %s (%d traces)", set_label, len(traces)) + return collection except (json.JSONDecodeError, KeyError, TypeError, ValueError) as exc: + logger.exception("Corrupted preprocess set %s", set_label) raise RuntimeError(f"Corrupted preprocess set {set_label}: {exc}") from exc def list_sets(self, kind: str, radar_key: str) -> list[str]: @@ -147,6 +159,7 @@ class NpzStore(StoreApi): collection = self.load_set(kind, radar_key, set_name) output_path.parent.mkdir(parents=True, exist_ok=True) output_path.write_bytes(serialize_trace_collection(collection, RAW_MAGIC)) + logger.info("Exported set %s/%s/%s bundle to %s", kind, radar_key, set_name, output_path) return output_path def save_runtime_snapshot( @@ -169,6 +182,7 @@ class NpzStore(StoreApi): save_trace_history_binary(snapshot_dir / "raw", raw_history[-last_n:], RAW_MAGIC) save_trace_history_binary(snapshot_dir / "preprocessed", preprocessed_history[-last_n:], PREPROC_MAGIC) save_result_history_binary(snapshot_dir / "results", result_history[-last_n:]) + logger.info("Saved binary runtime snapshot (last_n=%d) to %s", last_n, snapshot_dir) return snapshot_dir def save_runtime_snapshot_numpy( @@ -217,6 +231,14 @@ class NpzStore(StoreApi): selection_summary["result_count"] = len(selected_results) selection_summary["snapshot_stem"] = snapshot_stem selection_summary["snapshot_dir"] = str(snapshot_dir) + logger.info( + "Saved NumPy runtime snapshot to %s (raw=%d preprocessed=%d results=%d, anchor=%s)", + snapshot_dir, + len(selected_raw), + len(selected_preprocessed), + len(selected_results), + selection_summary.get("anchor_stage"), + ) return snapshot_dir, selection_summary def save_runtime_vna_history_json( @@ -281,6 +303,14 @@ class NpzStore(StoreApi): summary["output_stem"] = output_stem summary["output_dir"] = str(output_dir) summary["output_path"] = str(output_path) + logger.info( + "Saved VNA history JSON to %s (input=%d output=%d channel=%s sweeps=%d)", + output_path, + int(input_index), + int(output_index), + channel, + summary["sweep_count"], + ) return output_path, summary def save_runtime_vna_history_json_batch( @@ -320,6 +350,7 @@ class NpzStore(StoreApi): } ) if not combos: + logger.warning("No raw/preprocessed combos found in runtime history for VNA JSON batch export") raise ValueError("No matching raw/preprocessed traces were found in runtime history for any combo.") output_paths: list[Path] = [] @@ -361,6 +392,9 @@ class NpzStore(StoreApi): summary["output_stem"] = output_stem summary["output_dir"] = str(output_dir) summary["output_paths"] = [str(path) for path in output_paths] + logger.info( + "Saved %d VNA history JSON file(s) to %s (channel=%s)", len(output_paths), output_dir, channel + ) return output_paths, summary def _set_dir(self, kind: str, radar_key: str) -> Path: diff --git a/python_app/storage/npz/vna_history_json.py b/python_app/storage/npz/vna_history_json.py index a147b3e..955448c 100644 --- a/python_app/storage/npz/vna_history_json.py +++ b/python_app/storage/npz/vna_history_json.py @@ -5,12 +5,15 @@ from __future__ import annotations from collections import defaultdict from dataclasses import dataclass from datetime import datetime, timezone +import logging from typing import Any import numpy as np from python_app.models.dataset_model import ResultCollection, SweepCollection, TraceData +logger = logging.getLogger(__name__) + @dataclass(frozen=True) class TraceRecord: @@ -247,5 +250,18 @@ def build_vna_history_payload( alignment_warning = _stage_alignment_warning(preprocessed_history, result_history) if alignment_warning is not None: payload["alignment_warning"] = alignment_warning + logger.warning( + "VNA history export (input=%d output=%d): preprocessed/results stages not fully aligned", + input_index, + output_index, + ) + logger.debug( + "Built VNA history payload: input=%d output=%d raw=%d preprocessed=%d sweeps=%d", + input_index, + output_index, + len(raw_records), + len(preprocessed_records), + len(sweep_history), + ) return payload diff --git a/python_app/webui/app.py b/python_app/webui/app.py index 815050e..545cb90 100644 --- a/python_app/webui/app.py +++ b/python_app/webui/app.py @@ -10,6 +10,7 @@ static single-page frontend is mounted at ``/`` and the JSON/WS API under from __future__ import annotations from contextlib import asynccontextmanager +import logging from pathlib import Path from fastapi import FastAPI @@ -19,6 +20,8 @@ from python_app.webui.controller import WebController from python_app.webui.routes import router from python_app.webui.streaming import RingBroadcaster +logger = logging.getLogger(__name__) + _STATIC_DIR = Path(__file__).resolve().parent / "static" @@ -31,10 +34,12 @@ def create_app(controller: WebController) -> FastAPI: app.state.controller = controller app.state.broadcaster = broadcaster broadcaster.start() + logger.info("Web UI application started") try: yield finally: await broadcaster.stop() + logger.info("Web UI application stopped") app = FastAPI(title="Radar Web UI", lifespan=lifespan) app.include_router(router) diff --git a/python_app/webui/routes.py b/python_app/webui/routes.py index 715fded..a3aba98 100644 --- a/python_app/webui/routes.py +++ b/python_app/webui/routes.py @@ -10,12 +10,15 @@ from __future__ import annotations import asyncio import contextlib +import logging from fastapi import APIRouter, Body, HTTPException, Request, WebSocket, WebSocketDisconnect from python_app.webui.controller import WebController from python_app.webui.streaming import RingBroadcaster +logger = logging.getLogger(__name__) + router = APIRouter() @@ -30,6 +33,7 @@ async def get_status(request: Request) -> dict: @router.post("/api/start") async def post_start(request: Request) -> dict: + logger.info("Web UI request: start") controller = _controller(request) controller.start() return controller.status() @@ -37,6 +41,7 @@ async def post_start(request: Request) -> dict: @router.post("/api/single_capture") async def post_single_capture(request: Request) -> dict: + logger.info("Web UI request: single capture") controller = _controller(request) controller.single_capture() return controller.status() @@ -44,6 +49,7 @@ async def post_single_capture(request: Request) -> dict: @router.post("/api/stop") async def post_stop(request: Request) -> dict: + logger.info("Web UI request: stop") controller = _controller(request) controller.stop() return controller.status() @@ -51,6 +57,7 @@ async def post_stop(request: Request) -> dict: @router.post("/api/tmp_reference") async def post_tmp_reference(request: Request) -> dict: + logger.info("Web UI request: capture temporary reference") controller = _controller(request) controller.capture_tmp_reference() return controller.status() @@ -66,6 +73,7 @@ async def post_live_settings(request: Request, fields: dict = Body(default={})) try: return _controller(request).apply_live_settings(fields) except ValueError as exc: + logger.warning("Web UI rejected live settings update: %s", exc) raise HTTPException(status_code=400, detail=str(exc)) from exc @@ -76,11 +84,12 @@ async def ws(websocket: WebSocket) -> None: broadcaster: RingBroadcaster = websocket.app.state.broadcaster queue: asyncio.Queue[dict] = asyncio.Queue(maxsize=1) broadcaster.register(queue) + logger.info("Web UI client connected") try: while True: await websocket.send_json(await queue.get()) except WebSocketDisconnect: - pass + logger.info("Web UI client disconnected") finally: broadcaster.unregister(queue) with contextlib.suppress(Exception): diff --git a/python_app/webui/server.py b/python_app/webui/server.py index 0728753..4051482 100644 --- a/python_app/webui/server.py +++ b/python_app/webui/server.py @@ -30,6 +30,8 @@ class WebUiServer: def start(self) -> None: """Start serving on the background thread.""" + config = self._server.config + logger.info("Starting web UI server on %s:%s", config.host, config.port) self._thread.start() def is_alive(self) -> bool: @@ -49,5 +51,8 @@ class WebUiServer: def stop(self) -> None: """Ask uvicorn to exit and wait briefly for the thread to unwind.""" + logger.info("Stopping web UI server") self._server.should_exit = True self._thread.join(timeout=5.0) + if self._thread.is_alive(): + logger.warning("Web UI server thread did not stop within timeout") diff --git a/python_app/webui/streaming.py b/python_app/webui/streaming.py index 658ccd4..fda9b9a 100644 --- a/python_app/webui/streaming.py +++ b/python_app/webui/streaming.py @@ -37,16 +37,19 @@ class RingBroadcaster: def register(self, queue: asyncio.Queue[dict]) -> None: """Add a client queue to receive subsequent frames and status.""" self._clients.add(queue) + logger.debug("Registered web client queue (clients=%d)", len(self._clients)) def unregister(self, queue: asyncio.Queue[dict]) -> None: """Remove a client queue; safe to call more than once.""" self._clients.discard(queue) + logger.debug("Unregistered web client queue (clients=%d)", len(self._clients)) def start(self) -> None: """Launch the single polling task (idempotent).""" if self._task is None or self._task.done(): self._task = asyncio.create_task(self._run(), name="ring-broadcaster") self._task.add_done_callback(self._on_task_done) + logger.info("Ring broadcaster started") @staticmethod def _on_task_done(task: "asyncio.Task[None]") -> None: @@ -62,6 +65,7 @@ class RingBroadcaster: with contextlib.suppress(asyncio.CancelledError): await self._task self._task = None + logger.info("Ring broadcaster stopped") def _publish(self, message: dict) -> None: """Push a message to every client, dropping the oldest on a full queue.""" diff --git a/python_app/workflows/calibration_workflow.py b/python_app/workflows/calibration_workflow.py index 296de56..9a1b887 100644 --- a/python_app/workflows/calibration_workflow.py +++ b/python_app/workflows/calibration_workflow.py @@ -2,6 +2,8 @@ from __future__ import annotations +import logging + from python_app.models.dataset_model import SweepCollection from python_app.models.run_config_model import RunConfigModel from python_app.storage.npz_store import NpzStore @@ -10,6 +12,8 @@ from python_app.workflows.sequential_capture_workflow import ( SequentialCaptureSession, ) +logger = logging.getLogger(__name__) + def capture_calibration_set( config: RunConfigModel, @@ -19,6 +23,7 @@ def capture_calibration_set( median_sweep_count: int = DEFAULT_CALIBRATION_MEDIAN_SWEEP_COUNT, ) -> tuple[str, SweepCollection]: """Capture all switch combinations and persist them as calibration set.""" + logger.info("Starting one-shot calibration capture: set=%s", set_name) if config.is_matrix_radar: raise RuntimeError( "Matrix-radar S21 through calibration is not supported by this one-shot full-set helper. " diff --git a/python_app/workflows/kamil_adc_neutral_preprocess.py b/python_app/workflows/kamil_adc_neutral_preprocess.py index a6015cc..08171f5 100644 --- a/python_app/workflows/kamil_adc_neutral_preprocess.py +++ b/python_app/workflows/kamil_adc_neutral_preprocess.py @@ -2,6 +2,7 @@ from __future__ import annotations +import logging import time import numpy as np @@ -9,12 +10,19 @@ import numpy as np from python_app.models.dataset_model import ComboKey, SweepCollection, TraceData from python_app.models.run_config_model import ComboModel, RunConfigModel +logger = logging.getLogger(__name__) + def build_kamil_adc_neutral_s21_sets( config: RunConfigModel, point_count: int, ) -> tuple[SweepCollection, SweepCollection]: - """Build S21 calibration/reference collections that leave input S21 unchanged.""" + """Build neutral S21 calibration/reference collections for the Kamil ADC radar. + + The calibration uses unit S21 (1+0j) and the reference uses zero S21 across + every configured combo, so applying them in the preprocessing pipeline leaves + the input S21 unchanged. Returns the ``(calibration, reference)`` collections. + """ if not config.is_kamil_adc: raise ValueError("Neutral Kamil ADC sets require radar.model='kamil_adc'") @@ -47,6 +55,7 @@ def build_kamil_adc_neutral_s21_sets( s21_value=np.complex64(0.0 + 0.0j), monotonic_ns=now_ns, ) + logger.info("Built neutral Kamil ADC S21 sets: combos=%d points=%d", len(combos), points) return calibration, reference diff --git a/python_app/workflows/multi_radar_capture_workflow.py b/python_app/workflows/multi_radar_capture_workflow.py index b58d292..3f4b7ae 100644 --- a/python_app/workflows/multi_radar_capture_workflow.py +++ b/python_app/workflows/multi_radar_capture_workflow.py @@ -4,6 +4,7 @@ from __future__ import annotations from contextlib import suppress from dataclasses import dataclass +import logging import time import numpy as np @@ -23,6 +24,8 @@ from python_app.workflows.sequential_capture_workflow import ( select_trace_for_combo, ) +logger = logging.getLogger(__name__) + @dataclass(frozen=True, slots=True) class MultiRadarCaptureBatch: @@ -97,6 +100,15 @@ class MultiRadarSequentialCaptureSession: self._next_index = 0 self._opened = False + logger.info( + "Multi-radar capture session created: kind=%s set=%s combos=%d variants=%d matrix_radar=%s", + self._kind, + self._set_name, + len(self._combos), + len(self._radar_variants), + self._is_matrix_radar, + ) + if self._is_matrix_radar: self._radar: MatrixRadarService = create_matrix_radar_service(base_config) self._input_switch = None @@ -148,12 +160,17 @@ class MultiRadarSequentialCaptureSession: self._input_switch.open() if self._output_switch is not None: self._output_switch.open() + logger.info("Multi-radar capture session opened (kind=%s set=%s)", self._kind, self._set_name) except Exception: + logger.exception( + "Failed to open multi-radar capture session (kind=%s set=%s)", self._kind, self._set_name + ) self.close() raise def close(self) -> None: """Close all opened hardware resources.""" + was_open = self._opened with suppress(Exception): if self._output_switch is not None: self._output_switch.close() @@ -163,6 +180,8 @@ class MultiRadarSequentialCaptureSession: with suppress(Exception): self._radar.close() self._opened = False + if was_open: + logger.info("Multi-radar capture session closed (kind=%s set=%s)", self._kind, self._set_name) def state(self) -> SequentialCaptureState: """Return current progress snapshot.""" @@ -258,6 +277,14 @@ class MultiRadarSequentialCaptureSession: self._next_index = len(self._combos) else: self._next_index += 1 + logger.debug( + "Captured combo input=%d output=%d across %d variant(s) (%d/%d)", + combo.input, + combo.output, + len(variant_labels), + self._next_index, + len(self._combos), + ) return batch def undo_last_capture(self) -> MultiRadarCaptureBatch: @@ -336,6 +363,12 @@ class MultiRadarSequentialCaptureSession: trace_count=len(traces), ) ) + logger.info( + "Finalized multi-radar capture kind=%s set=%s into %d variant set(s)", + self._kind, + self._set_name, + len(saved_sets), + ) return saved_sets def _current_combo(self) -> ComboModel | None: diff --git a/python_app/workflows/radar_config_variants.py b/python_app/workflows/radar_config_variants.py index 6960108..a971051 100644 --- a/python_app/workflows/radar_config_variants.py +++ b/python_app/workflows/radar_config_variants.py @@ -4,11 +4,14 @@ from __future__ import annotations from dataclasses import dataclass import json +import logging from pathlib import Path from python_app.models.run_config_model import RunConfigModel from python_app.storage.npz_store import radar_key_from_config +logger = logging.getLogger(__name__) + _RADAR_SWEEP_KEYS = ( "start_hz", "stop_hz", @@ -59,6 +62,7 @@ def scan_radar_config_variants( directory = Path(normalized_path).expanduser() if not directory.exists(): + logger.warning("Radar config variant directory does not exist: %s", directory) return [], RadarConfigScanSummary( directory_path=str(directory), json_file_count=0, @@ -68,6 +72,7 @@ def scan_radar_config_variants( issues=(f"Directory does not exist: {directory}",), ) if not directory.is_dir(): + logger.warning("Radar config variant path is not a directory: %s", directory) return [], RadarConfigScanSummary( directory_path=str(directory), json_file_count=0, @@ -88,16 +93,30 @@ def scan_radar_config_variants( variant = _load_radar_config_variant(path, base_config=base_config) except Exception as exc: # noqa: BLE001 issues.append(f"{path.name}: {type(exc).__name__}: {exc}") + logger.warning("Skipping radar config variant %s: %s: %s", path.name, type(exc).__name__, exc) continue if variant.radar_key in seen_radar_keys: duplicate_variant_count += 1 issues.append( f"{path.name}: duplicate radar variant key {variant.radar_key}; keeping the first matching file only" ) + logger.warning( + "Skipping duplicate radar config variant %s (radar_key=%s already seen)", + path.name, + variant.radar_key, + ) continue seen_radar_keys.add(variant.radar_key) variants.append(variant) + logger.info( + "Scanned radar config variants in %s: json=%d valid=%d duplicates=%d", + directory, + len(json_paths), + len(variants), + duplicate_variant_count, + ) + return variants, RadarConfigScanSummary( directory_path=str(directory), json_file_count=len(json_paths), diff --git a/python_app/workflows/reference_workflow.py b/python_app/workflows/reference_workflow.py index 6785aee..aba4e5c 100644 --- a/python_app/workflows/reference_workflow.py +++ b/python_app/workflows/reference_workflow.py @@ -2,6 +2,8 @@ from __future__ import annotations +import logging + from python_app.models.dataset_model import SweepCollection from python_app.models.run_config_model import RunConfigModel from python_app.storage.npz_store import NpzStore @@ -10,6 +12,8 @@ from python_app.workflows.sequential_capture_workflow import ( SequentialCaptureSession, ) +logger = logging.getLogger(__name__) + def capture_reference_set( config: RunConfigModel, @@ -19,6 +23,7 @@ def capture_reference_set( median_sweep_count: int = DEFAULT_CALIBRATION_MEDIAN_SWEEP_COUNT, ) -> tuple[str, SweepCollection]: """Capture all switch combinations and persist them as reference set.""" + logger.info("Starting one-shot reference capture: set=%s", set_name) session = SequentialCaptureSession( config=config, kind="s21_reference", diff --git a/python_app/workflows/sequential_capture_workflow.py b/python_app/workflows/sequential_capture_workflow.py index 9a88a61..7e69df8 100644 --- a/python_app/workflows/sequential_capture_workflow.py +++ b/python_app/workflows/sequential_capture_workflow.py @@ -4,6 +4,7 @@ from __future__ import annotations from contextlib import suppress from dataclasses import dataclass +import logging import time import numpy as np @@ -15,13 +16,15 @@ from python_app.models.dataset_model import ComboKey, SweepCollection, TraceData from python_app.models.run_config_model import ComboModel, RunConfigModel from python_app.storage.npz_store import NpzStore, radar_key_from_config +logger = logging.getLogger(__name__) + MATRIX_RADAR_MANUAL_CAPTURE_KINDS = frozenset({"s21_calibration", "s11_open", "s11_short", "s11_load"}) DEFAULT_CALIBRATION_MEDIAN_SWEEP_COUNT = 5 @dataclass(slots=True) class SequentialCaptureState: - """Immutable view of sequential capture progress.""" + """Snapshot of sequential capture progress for the GUI/controller.""" kind: str set_name: str @@ -73,6 +76,15 @@ class SequentialCaptureSession: self._next_index = 0 self._opened = False + logger.info( + "Sequential capture session created: kind=%s set=%s combos=%d matrix_radar=%s median_sweeps=%d", + self._kind, + self._set_name, + len(self._combos), + self._is_matrix_radar, + self._median_sweep_count, + ) + if self._is_matrix_radar: self._radar: MatrixRadarService = create_matrix_radar_service(config) self._input_switch = None @@ -124,12 +136,15 @@ class SequentialCaptureSession: self._input_switch.open() if self._output_switch is not None: self._output_switch.open() + logger.info("Sequential capture session opened (kind=%s set=%s)", self._kind, self._set_name) except Exception: + logger.exception("Failed to open sequential capture session (kind=%s set=%s)", self._kind, self._set_name) self.close() raise def close(self) -> None: """Close all opened hardware resources.""" + was_open = self._opened with suppress(Exception): if self._output_switch is not None: self._output_switch.close() @@ -139,6 +154,8 @@ class SequentialCaptureSession: with suppress(Exception): self._radar.close() self._opened = False + if was_open: + logger.info("Sequential capture session closed (kind=%s set=%s)", self._kind, self._set_name) def state(self) -> SequentialCaptureState: """Return current progress snapshot.""" @@ -174,11 +191,13 @@ class SequentialCaptureSession: trace = combine_traces_via_median(per_sweep_traces) self._traces.append(trace) self._next_index += 1 + logger.debug("Captured matrix combo input=%d output=%d", combo.input, combo.output) return trace combined_collection = combine_collections_via_median(collections) self._traces.extend(combined_collection.traces) self._next_index = len(self._combos) + logger.info("Captured full matrix combo set (%d traces)", len(combined_collection.traces)) return combined_collection.traces[-1] if self._input_switch is None or self._output_switch is None: @@ -202,6 +221,13 @@ class SequentialCaptureSession: trace = combine_traces_via_median(sweep_traces) self._traces.append(trace) self._next_index += 1 + logger.debug( + "Captured combo input=%d output=%d (%d/%d)", + combo.input, + combo.output, + self._next_index, + len(self._combos), + ) return trace def undo_last_capture(self) -> TraceData: @@ -217,6 +243,7 @@ class SequentialCaptureSession: removed_trace = self._traces[-1] self._traces.clear() self._next_index = 0 + logger.info("Undid matrix combo set capture (kind=%s set=%s)", self._kind, self._set_name) return removed_trace expected_combo = self._combos[self._next_index - 1] @@ -228,6 +255,13 @@ class SequentialCaptureSession: raise RuntimeError("Capture session state is inconsistent; last trace does not match rewind combo") self._next_index -= 1 self._traces.pop() + logger.debug( + "Undid combo capture input=%d output=%d (%d/%d remaining)", + expected_combo.input, + expected_combo.output, + self._next_index, + len(self._combos), + ) return removed_trace def last_captured_trace(self) -> TraceData | None: @@ -265,6 +299,13 @@ class SequentialCaptureSession: extra_serials=self._config.radar_key_extra_parts() or None, ) store.save_set(self._kind, radar_key, self._set_name, collection) + logger.info( + "Finalized capture set kind=%s set=%s radar_key=%s traces=%d", + self._kind, + self._set_name, + radar_key, + len(collection.traces), + ) return radar_key, collection def _current_combo(self) -> ComboModel | None: