diff --git a/deeplabcut/core/debug/__init__.py b/deeplabcut/core/debug/__init__.py new file mode 100644 index 000000000..bbc583fe0 --- /dev/null +++ b/deeplabcut/core/debug/__init__.py @@ -0,0 +1,46 @@ +# +# DeepLabCut Toolbox (deeplabcut.org) +# © A. & M.W. Mathis Labs +# https://github.com/DeepLabCut/DeepLabCut +# +# Please see AUTHORS for contributors. +# https://github.com/DeepLabCut/DeepLabCut/blob/main/AUTHORS +# +# Licensed under GNU Lesser General Public License v3.0 +# + +from collections.abc import Sequence + +from .debug_logger import ( + DLC_ALL_LIBS_SPECS, + DebugSection, + ExecutableSpec, + InMemoryDebugRecorder, + LibrarySpec, + RecordedLog, + build_debug_report, + collect_debug_sections, + collect_executable_summary, + collect_version_summary, + format_debug_report, + get_debug_recorder, + install_debug_recorder, + log_timing, +) + +__all__: Sequence[str] = ( + "DLC_ALL_LIBS_SPECS", + "ExecutableSpec", + "DebugSection", + "InMemoryDebugRecorder", + "LibrarySpec", + "RecordedLog", + "build_debug_report", + "collect_debug_sections", + "collect_executable_summary", + "collect_version_summary", + "format_debug_report", + "get_debug_recorder", + "install_debug_recorder", + "log_timing", +) diff --git a/deeplabcut/core/debug/_debug_utils.py b/deeplabcut/core/debug/_debug_utils.py new file mode 100644 index 000000000..95e8ef471 --- /dev/null +++ b/deeplabcut/core/debug/_debug_utils.py @@ -0,0 +1,87 @@ +# +# DeepLabCut Toolbox (deeplabcut.org) +# © A. & M.W. Mathis Labs +# https://github.com/DeepLabCut/DeepLabCut +# +# Please see AUTHORS for contributors. +# https://github.com/DeepLabCut/DeepLabCut/blob/main/AUTHORS +# +# Licensed under GNU Lesser General Public License v3.0 +# + +from __future__ import annotations + +import os +import shutil +import subprocess +from collections.abc import Sequence +from pathlib import Path + + +def _env_flag(name: str, default: bool = False) -> bool: + """Parse a boolean environment variable. + + Accepted truthy values: + 1, true, yes, on + + Accepted falsy values: + 0, false, no, off + """ + value = os.getenv(name) + if value is None: + return default + + value = value.strip().lower() + if value in {"1", "true", "yes", "on"}: + return True + if value in {"0", "false", "no", "off"}: + return False + return default + + +def _env_optional_float(name: str, default: float | None = None) -> float | None: + """Parse an optional float environment variable. + + Empty strings / unset values return ``default``. + Invalid values also fall back to ``default``. + """ + value = os.getenv(name) + if value is None: + return default + + value = value.strip() + if not value: + return default + + try: + return float(value) + except ValueError: + return default + + +def _which(command: str) -> str: + try: + resolved = shutil.which(command) + return str(Path(resolved).resolve()) if resolved else "not-found" + except Exception: + return "not-found" + + +def _command_version(command: str, version_args: Sequence[str] = ("-version",)) -> str: + try: + completed = subprocess.run( + [command, *version_args], + check=False, + capture_output=True, + text=True, + timeout=3, + ) + except Exception: + return "unavailable" + + text = (completed.stdout or completed.stderr or "").strip() + if not text: + return "unavailable" + + first_line = text.splitlines()[0].strip() + return first_line or "unavailable" diff --git a/deeplabcut/core/debug/debug_logger.py b/deeplabcut/core/debug/debug_logger.py new file mode 100644 index 000000000..44d2437a3 --- /dev/null +++ b/deeplabcut/core/debug/debug_logger.py @@ -0,0 +1,594 @@ +# +# DeepLabCut Toolbox (deeplabcut.org) +# © A. & M.W. Mathis Labs +# https://github.com/DeepLabCut/DeepLabCut +# +# Please see AUTHORS for contributors. +# https://github.com/DeepLabCut/DeepLabCut/blob/main/AUTHORS +# +# Licensed under GNU Lesser General Public License v3.0 +# + +from __future__ import annotations + +import logging +import platform +import sys +import threading +import traceback +from collections import deque +from collections.abc import Iterable +from contextlib import contextmanager +from dataclasses import dataclass +from datetime import datetime +from importlib import metadata +from pathlib import Path +from time import perf_counter_ns + +from ._debug_utils import ( + _command_version, + _env_flag, + _env_optional_float, + _which, +) + +_DEBUG_HANDLER_ATTR = "_dlc_debug_recorder" +LOG_QUEUE_MAXLEN = 1000 + +# NOTE @C-Achard 2026-05-13: we may want to centralize env vars in a config/settings module in the future +DLC_LOG_TIMING = _env_flag("DLC_LOG_TIMING", default=False) +DLC_LOG_TIMING_THRESHOLD_MS = _env_optional_float("DLC_LOG_TIMING_THRESHOLD_MS", default=None) + + +def reload_debug_settings_from_env() -> None: + """Reload debug/timing settings from environment variables.""" + global DLC_LOG_TIMING, DLC_LOG_TIMING_THRESHOLD_MS + + DLC_LOG_TIMING = _env_flag("DLC_LOG_TIMING", default=False) + DLC_LOG_TIMING_THRESHOLD_MS = _env_optional_float( + "DLC_LOG_TIMING_THRESHOLD_MS", + default=None, + ) + + +@contextmanager +def log_timing( + logger: logging.Logger, + label: str, + *, + level: int = logging.DEBUG, + threshold_ms: float | None = None, +): + """Lightweight scoped timer for debug instrumentation. + + Uses perf_counter_ns() for monotonic timing. + Logs only if logger is enabled for the requested level. + Optionally suppresses tiny timings below ``threshold_ms``. + """ + if not logger.isEnabledFor(level) or not DLC_LOG_TIMING: + yield + return + + effective_threshold_ms = threshold_ms if threshold_ms is not None else DLC_LOG_TIMING_THRESHOLD_MS + t0 = perf_counter_ns() + try: + yield + finally: + dt_ms = (perf_counter_ns() - t0) / 1e6 + if effective_threshold_ms is None or dt_ms >= effective_threshold_ms: + logger.log(level, "%s took %.3f ms", label, dt_ms) + + +@dataclass(frozen=True) +class RecordedLog: + created: float + level: str + logger_name: str + message: str + exc_text: str | None = None + + +class InMemoryDebugRecorder(logging.Handler): + """Lightweight, fail-open in-memory log recorder. + + Safety properties: + - bounded memory via deque(maxlen=...) + - no file/network I/O + - swallow-all-errors in emit() + - does not log from inside itself + - stores only small text snapshots + """ + + def __init__(self, *, capacity: int = LOG_QUEUE_MAXLEN, level: int = logging.DEBUG): + super().__init__(level=level) + self._records: deque[RecordedLog] = deque(maxlen=max(1, int(capacity))) + self._lock = threading.Lock() + self._dropped = 0 + + @property + def dropped_count(self) -> int: + return self._dropped + + def emit(self, record: logging.LogRecord) -> None: + try: + # Never call logging from here. + # Never inspect application objects. + msg = self._safe_message(record) + exc_text = self._safe_exception_text(record) + + snap = RecordedLog( + created=float(getattr(record, "created", 0.0) or 0.0), + level=str(getattr(record, "levelname", "UNKNOWN")), + logger_name=str(getattr(record, "name", "")), + message=msg, + exc_text=exc_text, + ) + + with self._lock: + self._records.append(snap) + + except Exception: + # Fail open: never let diagnostics interfere with runtime behavior. + try: + self._dropped += 1 + except Exception: + pass + + def clear(self) -> None: + try: + with self._lock: + self._records.clear() + self._dropped = 0 + except Exception: + pass + + def snapshot(self) -> list[RecordedLog]: + try: + with self._lock: + return list(self._records) + except Exception: + return [] + + def render_text(self, *, limit: int = 200) -> str: + lines: list[str] = [] + try: + records = self.snapshot()[-max(1, int(limit)) :] + if not records: + if self._dropped: + return f"[debug-recorder] no captured logs, {self._dropped} internal failures" + return "" + + base = records[0].created + for rec in records: + ts = datetime.fromtimestamp(rec.created).strftime("%H:%M:%S.%f")[:-3] + if DLC_LOG_TIMING: + rel_ms = (rec.created - base) * 1000.0 + lines.append(f"{ts} (+{rel_ms:8.1f} ms) | {rec.level:<8} | {rec.logger_name} | {rec.message}") + else: + lines.append(f"{ts} | {rec.level:<8} | {rec.logger_name} | {rec.message}") + if rec.exc_text: + lines.append(rec.exc_text.rstrip()) + + if self._dropped: + lines.append(f"[debug-recorder] dropped internal failures: {self._dropped}") + except Exception: + return "[debug-recorder] failed to render logs" + return "\n".join(lines) + + @staticmethod + def _safe_message(record: logging.LogRecord) -> str: + try: + return record.getMessage() + except Exception: + try: + return str(record.msg) + except Exception: + return "" + + @staticmethod + def _safe_exception_text(record: logging.LogRecord) -> str | None: + try: + if not record.exc_info: + return None + return "".join(traceback.format_exception(*record.exc_info)) + except Exception: + return "" + + +@dataclass(frozen=True) +class DebugSection: + title: str + items: dict[str, str] + + +def install_debug_recorder( + *, + logger_name: str = "deeplabcut", + capacity: int = LOG_QUEUE_MAXLEN, + handler_level: int = logging.INFO, + ensure_logger_level: int | None = None, +) -> InMemoryDebugRecorder: + """Attach a single in-memory recorder to the requested logger namespace. + + Idempotent: repeated calls return the same recorder. + + Parameters + ---------- + logger_name: + Logger namespace to attach the recorder to. + capacity: + Maximum number of captured records. By default, uses LOG_QUEUE_MAXLEN. + handler_level: + Minimum level stored by the recorder itself. + ensure_logger_level: + Controls whether to adjust the target logger level. + + - None: never modify the logger level + - int: lower the logger only if its effective level is more restrictive + """ + + root_logger = logging.getLogger(logger_name) + + existing = getattr(root_logger, _DEBUG_HANDLER_ATTR, None) + if isinstance(existing, InMemoryDebugRecorder): + return existing + + recorder = InMemoryDebugRecorder(capacity=capacity, level=handler_level) + recorder.set_name("deeplabcut-debug-recorder") + + # Important: + # - attach only to a DLC-owned logger namespace, not the global root logger + # - keep propagation unchanged + # - logger level adjustment, if any, is handled below; "auto" initializes + # an unset logger to ``handler_level`` rather than forcing DEBUG + root_logger.addHandler(recorder) + + if isinstance(ensure_logger_level, int): + # Only lower verbosity if explicitly requested. + if root_logger.getEffectiveLevel() > ensure_logger_level: + root_logger.setLevel(ensure_logger_level) + + setattr(root_logger, _DEBUG_HANDLER_ATTR, recorder) + return recorder + + +def get_debug_recorder(*, logger_name: str = "deeplabcut") -> InMemoryDebugRecorder | None: + logger = logging.getLogger(logger_name) + recorder = getattr(logger, _DEBUG_HANDLER_ATTR, None) + return recorder if isinstance(recorder, InMemoryDebugRecorder) else None + + +# -------------------------- +# Environment / version info +# -------------------------- + + +@dataclass(frozen=True) +class LibrarySpec: + """Small description of a library to report.""" + + key: str + dist_name: str | None = None + module_name: str | None = None + prefer_module_version: bool = False + + def resolved_dist_name(self) -> str: + return self.dist_name or self.key + + def resolved_module_name(self) -> str: + return self.module_name or self.key + + +DLC_CORE_LIBS: tuple[LibrarySpec, ...] = ( + LibrarySpec("deeplabcut"), + LibrarySpec("torch"), + LibrarySpec("torchvision"), + LibrarySpec("numpy"), + LibrarySpec("pandas"), + LibrarySpec("scipy"), + LibrarySpec("h5py"), + LibrarySpec("tables"), + LibrarySpec("opencv-python", dist_name="opencv-python", module_name="cv2", prefer_module_version=True), +) +DLC_GUI_LIBS: tuple[LibrarySpec, ...] = ( + LibrarySpec("PySide6"), + LibrarySpec("shiboken6"), + LibrarySpec("qtpy", dist_name="QtPy"), + LibrarySpec("qdarkstyle"), + LibrarySpec("napari"), + LibrarySpec("napari-deeplabcut", dist_name="napari-deeplabcut", module_name="napari_deeplabcut"), +) +DLC_TF_LIBS: tuple[LibrarySpec, ...] = ( + LibrarySpec("tensorflow"), + LibrarySpec("tf_keras", dist_name="tf-keras"), + LibrarySpec("tensorpack"), + LibrarySpec("tf_slim", dist_name="tf-slim"), +) +DLC_ALL_LIBS_SPECS: tuple[LibrarySpec, ...] = DLC_CORE_LIBS + DLC_GUI_LIBS + DLC_TF_LIBS + + +def _normalize_library_specs( + libraries: Iterable[LibrarySpec | str] | None, +) -> tuple[LibrarySpec, ...]: + if libraries is None: + return DLC_ALL_LIBS_SPECS + + normalized: list[LibrarySpec] = [] + for item in libraries: + if isinstance(item, LibrarySpec): + normalized.append(item) + else: + normalized.append(LibrarySpec(str(item))) + return tuple(normalized) + + +def _version(dist_name: str) -> str: + try: + return metadata.version(dist_name) + except Exception: + return "not-installed" + + +def _module_path(module_name: str) -> str: + try: + mod = __import__(module_name) + p = getattr(mod, "__file__", None) + return str(Path(p).resolve()) if p else "unknown" + except Exception: + return "unknown" + + +def _safe_tail(pathlike: object) -> str: + """Redact user-specific absolute paths. + + Keeps only the last 2 path components when possible. + """ + try: + p = Path(str(pathlike)) + parts = p.parts + if len(parts) >= 2: + return str(Path(*parts[-2:]).as_posix()) + return str(p.as_posix()) + except Exception: + return str(pathlike) + + +def _module_version(module_name: str) -> str: + try: + mod = __import__(module_name) + version = getattr(mod, "__version__", None) + if version: + return str(version) + return "unknown" + except Exception: + return "not-installed" + + +def collect_version_summary( + *, + libraries: Iterable[LibrarySpec | str] | None = None, + include_module_paths: bool = False, +) -> dict[str, str]: + specs = _normalize_library_specs(libraries) + summary: dict[str, str] = {} + + for spec in specs: + key = spec.key + module_name = spec.resolved_module_name() + + if spec.prefer_module_version: + version = _module_version(module_name) + if version in {"not-installed", "unknown"}: + version = _version(spec.resolved_dist_name()) + else: + version = _version(spec.resolved_dist_name()) + + summary[key] = version + + if include_module_paths: + summary[f"{key}_module_path"] = _safe_tail(_module_path(module_name)) + + return summary + + +@dataclass(frozen=True) +class ExecutableSpec: + """Small description of an external executable to report. + + Parameters + ---------- + key: + Label used in the output report. + command: + Executable name or absolute path to resolve. + version_args: + Arguments used to query the executable version. + """ + + key: str + command: str | None = None + version_args: tuple[str, ...] = ("-version",) + + def resolved_command(self) -> str: + return self.command or self.key + + +DEFAULT_EXECUTABLE_SPECS: tuple[ExecutableSpec, ...] = (ExecutableSpec("ffmpeg"),) + + +def _normalize_executable_specs( + executables: Iterable[ExecutableSpec | str] | None, +) -> tuple[ExecutableSpec, ...]: + if executables is None: + return DEFAULT_EXECUTABLE_SPECS + + normalized: list[ExecutableSpec] = [] + for item in executables: + if isinstance(item, ExecutableSpec): + normalized.append(item) + else: + normalized.append(ExecutableSpec(str(item))) + return tuple(normalized) + + +def collect_executable_summary( + *, + executables: Iterable[ExecutableSpec | str] | None = None, + include_paths: bool = True, +) -> dict[str, str]: + specs = _normalize_executable_specs(executables) + summary: dict[str, str] = {} + + for spec in specs: + key = spec.key + command = spec.resolved_command() + summary[key] = _command_version(command, spec.version_args) + if include_paths: + summary[f"{key}_path"] = _safe_tail(_which(command)) + + return summary + + +# -------------------------- +# Report formatting +# -------------------------- + + +def format_debug_report( + *, + sections: Iterable[DebugSection], + logs_text: str, +) -> str: + lines: list[str] = [] + + for section in sections: + lines.append(f"## {section.title}") + if section.items: + for k, v in section.items.items(): + lines.append(f"- {k}: {v}") + else: + lines.append("- ") + lines.append("") + + lines.append("## Recent logs") + lines.append("```text") + lines.append(logs_text or "") + lines.append("```") + + return "\n".join(lines) + + +def build_debug_report( + *, + recorder: InMemoryDebugRecorder | None, + libraries: Iterable[LibrarySpec | str] | None = None, + executables: Iterable[ExecutableSpec | str] | None = None, + include_module_paths: bool = False, + include_executable_paths: bool = True, + log_limit: int = 300, +) -> str: + logs_text = recorder.render_text(limit=log_limit) if recorder is not None else "" + + sections = collect_debug_sections( + libraries=libraries, + executables=executables, + include_module_paths=include_module_paths, + include_executable_paths=include_executable_paths, + ) + + return format_debug_report( + sections=sections, + logs_text=logs_text, + ) + + +def collect_runtime_summary() -> dict[str, str]: + return { + "python": sys.version.replace("\n", " "), + "platform": platform.platform(), + "executable": _safe_tail(sys.executable), + } + + +def _section_has_useful_values(items: dict[str, str]) -> bool: + for value in items.values(): + if value not in {"not-installed", "unknown", "not-found", "unavailable"}: + return True + return False + + +def collect_debug_sections( + *, + libraries: Iterable[LibrarySpec | str] | None = None, + executables: Iterable[ExecutableSpec | str] | None = None, + include_module_paths: bool = False, + include_executable_paths: bool = True, +) -> list[DebugSection]: + sections: list[DebugSection] = [] + + # Always include the runtime section first + sections.append( + DebugSection( + title="Runtime", + items=collect_runtime_summary(), + ) + ) + + # Default grouped report using your built-in constants + if libraries is None: + sections.append( + DebugSection( + title="DeepLabCut core libraries", + items=collect_version_summary( + libraries=DLC_CORE_LIBS, + include_module_paths=include_module_paths, + ), + ) + ) + + sections.append( + DebugSection( + title="GUI libraries", + items=collect_version_summary( + libraries=DLC_GUI_LIBS, + include_module_paths=include_module_paths, + ), + ) + ) + + tf_items = collect_version_summary( + libraries=DLC_TF_LIBS, + include_module_paths=include_module_paths, + ) + if tf_items and _section_has_useful_values(tf_items): + sections.append( + DebugSection( + title="TensorFlow libraries", + items=tf_items, + ) + ) + else: + # Custom input + sections.append( + DebugSection( + title="Libraries", + items=collect_version_summary( + libraries=libraries, + include_module_paths=include_module_paths, + ), + ) + ) + + exec_items = collect_executable_summary( + executables=executables, + include_paths=include_executable_paths, + ) + if exec_items: # report if unavailable + sections.append( + DebugSection( + title="External tools", + items=exec_items, + ), + ) + + return sections diff --git a/deeplabcut/gui/dialogs/__init__.py b/deeplabcut/gui/dialogs/__init__.py new file mode 100644 index 000000000..abf3848d7 --- /dev/null +++ b/deeplabcut/gui/dialogs/__init__.py @@ -0,0 +1,28 @@ +# +# DeepLabCut Toolbox (deeplabcut.org) +# © A. & M.W. Mathis Labs +# https://github.com/DeepLabCut/DeepLabCut +# +# Please see AUTHORS for contributors. +# https://github.com/DeepLabCut/DeepLabCut/blob/main/AUTHORS +# +# Licensed under GNU Lesser General Public License v3.0 +# + +from collections.abc import Sequence + +from .debug_dialog import ( + DebugTextDialog, + create_generate_debug_log_action, + make_issue_report_provider, + make_log_text_provider, + show_debug_report_dialog, +) + +__all__: Sequence[str] = ( + "DebugTextDialog", + "create_generate_debug_log_action", + "make_issue_report_provider", + "make_log_text_provider", + "show_debug_report_dialog", +) diff --git a/deeplabcut/gui/dialogs/debug_dialog.py b/deeplabcut/gui/dialogs/debug_dialog.py new file mode 100644 index 000000000..7c7c4a4c1 --- /dev/null +++ b/deeplabcut/gui/dialogs/debug_dialog.py @@ -0,0 +1,326 @@ +# +# DeepLabCut Toolbox (deeplabcut.org) +# © A. & M.W. Mathis Labs +# https://github.com/DeepLabCut/DeepLabCut +# +# Please see AUTHORS for contributors. +# https://github.com/DeepLabCut/DeepLabCut/blob/master/AUTHORS +# +# Licensed under GNU Lesser General Public License v3.0 +# + +from __future__ import annotations + +from collections.abc import Callable, Iterable +from typing import TYPE_CHECKING + +from PySide6 import QtGui +from PySide6.QtCore import Qt +from PySide6.QtGui import QAction, QFontDatabase, QKeySequence, QTextCursor +from PySide6.QtWidgets import ( + QApplication, + QDialog, + QHBoxLayout, + QLabel, + QPlainTextEdit, + QPushButton, + QVBoxLayout, + QWidget, +) + +from deeplabcut.core.debug import ( + ExecutableSpec, + InMemoryDebugRecorder, + LibrarySpec, + build_debug_report, + get_debug_recorder, + install_debug_recorder, +) + +if TYPE_CHECKING: + pass + + +def make_log_text_provider( + *, + recorder: InMemoryDebugRecorder | None, + limit: int = 300, +) -> Callable[[], str]: + """Return a callable that renders recent captured logs.""" + + def _provider() -> str: + if recorder is None: + return "" + return recorder.render_text(limit=limit) + + return _provider + + +def make_issue_report_provider( + *, + recorder: InMemoryDebugRecorder | None, + libraries: Iterable[LibrarySpec | str] | None = None, + executables: Iterable[ExecutableSpec | str] | None = None, + include_module_paths: bool = False, + include_executable_paths: bool = True, + log_limit: int = 300, +) -> Callable[[], str]: + """Return a callable that builds a full DLC debug report. + + ``libraries`` and ``executables`` are normalized to tuples so the returned + provider can be called repeatedly even if the caller passed a generator or + another one-shot iterable. + """ + libraries_snapshot = None if libraries is None else tuple(libraries) + executables_snapshot = None if executables is None else tuple(executables) + + def _provider() -> str: + return build_debug_report( + recorder=recorder, + libraries=libraries_snapshot, + executables=executables_snapshot, + include_module_paths=include_module_paths, + include_executable_paths=include_executable_paths, + log_limit=log_limit, + ) + + return _provider + + +class DebugTextDialog(QDialog): + """ + Minimal, application-agnostic debug text viewer. + + This widget only knows how to: + - fetch text from a callable + - display it read-only + - copy it to clipboard + - refresh it on demand + + It intentionally knows nothing about: + - recorder internals + - DLC main window internals + - environment/report formatting + """ + + def __init__( + self, + *, + title: str, + text_provider: Callable[[], str], + parent: QWidget | None = None, + initial_hint: str = "Read-only diagnostic output", + ) -> None: + super().__init__(parent=parent) + self.setWindowTitle(title) + self.setModal(False) + self.resize(950, 700) + + self._text_provider = text_provider + + self._build_ui(initial_hint=initial_hint) + # self.refresh_text() # showEvent triggers initial refresh, so this is redundant + + def update_content( + self, + *, + title: str | None = None, + text_provider: Callable[[], str] | None = None, + hint: str | None = None, + ) -> None: + """Update dialog metadata when reusing an existing instance.""" + if title is not None: + self.setWindowTitle(title) + if text_provider is not None: + self._text_provider = text_provider + if hint is not None: + self._hint_label.setText(hint) + + def _build_ui(self, *, initial_hint: str) -> None: + layout = QVBoxLayout(self) + + self._hint_label = QLabel(initial_hint, self) + self._hint_label.setTextInteractionFlags(Qt.TextSelectableByMouse) + layout.addWidget(self._hint_label) + + self._text_edit = QPlainTextEdit(self) + self._text_edit.setReadOnly(True) + self._text_edit.setLineWrapMode(QPlainTextEdit.NoWrap) + + # Use a fixed-width system font for logs / reports + font = QFontDatabase.systemFont(QFontDatabase.SystemFont.FixedFont) + self._text_edit.setFont(font) + + layout.addWidget(self._text_edit, stretch=1) + + button_row = QHBoxLayout() + + self._status_label = QLabel("", self) + self._status_label.setTextInteractionFlags(Qt.TextSelectableByMouse) + button_row.addWidget(self._status_label, stretch=1) + + self._refresh_btn = QPushButton("Refresh", self) + self._refresh_btn.clicked.connect(self.refresh_text) + button_row.addWidget(self._refresh_btn) + + self._copy_btn = QPushButton("Copy to clipboard", self) + self._copy_btn.clicked.connect(self.copy_to_clipboard) + button_row.addWidget(self._copy_btn) + + self._close_btn = QPushButton("Close", self) + self._close_btn.clicked.connect(self.close) + button_row.addWidget(self._close_btn) + + layout.addLayout(button_row) + + # Optional keyboard shortcut + copy_action = QAction(self) + copy_action.setShortcut(QKeySequence.StandardKey.Copy) + copy_action.triggered.connect(self.copy_to_clipboard) + self.addAction(copy_action) + + def refresh_text(self) -> None: + try: + QApplication.setOverrideCursor(Qt.WaitCursor) + text = self._text_provider() + except Exception as exc: + text = f"[debug-dialog] failed to build debug text\n\n{exc!r}" + finally: + QApplication.restoreOverrideCursor() + + self._text_edit.setPlainText(text or "") + self._text_edit.moveCursor(QTextCursor.MoveOperation.Start) + self._status_label.setText("") + + def copy_to_clipboard(self) -> None: + try: + text = self._text_edit.toPlainText() + QApplication.clipboard().setText(text) + self._status_label.setText("Copied to clipboard") + except Exception: + self._status_label.setText("Could not copy to clipboard") + + def showEvent(self, event: QtGui.QShowEvent) -> None: + """Refresh each time the dialog becomes visible.""" + super().showEvent(event) + self.refresh_text() + + +def _get_or_create_debug_dialog( + *, + parent: QWidget, + title: str, + text_provider: Callable[[], str], + text_hint: str, + attr_name: str = "_dlc_debug_dialog", +) -> DebugTextDialog: + """ + Reuse a single dialog instance attached to ``parent``. + + Storing the dialog on the main window avoids accidental garbage collection + and prevents opening a pile of duplicate windows. + """ + dlg = getattr(parent, attr_name, None) + if isinstance(dlg, DebugTextDialog): + dlg.update_content( + title=title, + text_provider=text_provider, + hint=text_hint, + ) + return dlg + + dlg = DebugTextDialog( + title=title, + text_provider=text_provider, + parent=parent, + initial_hint=text_hint, + ) + setattr(parent, attr_name, dlg) + return dlg + + +def show_debug_report_dialog( + *, + parent: QWidget, + recorder: InMemoryDebugRecorder | None = None, + logger_name: str = "deeplabcut", + libraries: Iterable[LibrarySpec | str] | None = None, + executables: Iterable[ExecutableSpec | str] | None = None, + include_module_paths: bool = False, + include_executable_paths: bool = True, + log_limit: int = 300, + dialog_attr_name: str = "_dlc_debug_dialog", +) -> DebugTextDialog: + """ + Open (or reuse) the full diagnostic report dialog. + + If ``recorder`` is not provided, this function tries to reuse an existing + recorder for the given logger namespace and installs one if missing. + """ + if recorder is None: + recorder = get_debug_recorder(logger_name=logger_name) + if recorder is None: + recorder = install_debug_recorder(logger_name=logger_name) + + provider = make_issue_report_provider( + recorder=recorder, + libraries=libraries, + executables=executables, + include_module_paths=include_module_paths, + include_executable_paths=include_executable_paths, + log_limit=log_limit, + ) + + dlg = _get_or_create_debug_dialog( + parent=parent, + title="DeepLabCut debug log", + text_provider=provider, + text_hint=("Diagnostic report for issue reporting. Use Refresh to update, then Copy to clipboard."), + attr_name=dialog_attr_name, + ) + # dlg.refresh_text() # redundant + dlg.show() + dlg.raise_() + dlg.activateWindow() + return dlg + + +def create_generate_debug_log_action( + *, + parent: QWidget, + recorder: InMemoryDebugRecorder | None = None, + logger_name: str = "deeplabcut", + libraries: Iterable[LibrarySpec | str] | None = None, + executables: Iterable[ExecutableSpec | str] | None = None, + include_module_paths: bool = False, + include_executable_paths: bool = True, + log_limit: int = 300, + text: str = "&Generate debug log...", + status_tip: str = "Generate a diagnostic report for troubleshooting", + dialog_attr_name: str = "_dlc_debug_dialog", +) -> QAction: + """ + Create a QAction that opens the DLC debug report dialog. + + Typical usage in ``MainWindow.create_actions``:: + + self.generateDebugLogAction = create_generate_debug_log_action(parent=self) + """ + action = QAction(text, parent) + action.setStatusTip(status_tip) + + def _open_dialog() -> None: + show_debug_report_dialog( + parent=parent, + recorder=recorder, + logger_name=logger_name, + libraries=libraries, + executables=executables, + include_module_paths=include_module_paths, + include_executable_paths=include_executable_paths, + log_limit=log_limit, + dialog_attr_name=dialog_attr_name, + ) + + action.triggered.connect(_open_dialog) + return action diff --git a/deeplabcut/gui/window.py b/deeplabcut/gui/window.py index 7e69ad5dd..faf4d05d1 100644 --- a/deeplabcut/gui/window.py +++ b/deeplabcut/gui/window.py @@ -35,8 +35,10 @@ import deeplabcut from deeplabcut import __version__ as DLC_VERSION from deeplabcut import auxiliaryfunctions, compat +from deeplabcut.core.debug import install_debug_recorder from deeplabcut.core.engine import Engine from deeplabcut.gui import BASE_DIR, components +from deeplabcut.gui.dialogs import create_generate_debug_log_action from deeplabcut.gui.tabs import ( AnalyzeVideos, CreateTrainingDataset, @@ -80,7 +82,8 @@ def __init__(self, app): self.screen_height = screen_size.height() self._closing = False - self.logger = logging.getLogger("GUI") + self.logger = logging.getLogger("deeplabcut.gui") + self.console_logger = logging.getLogger("deeplabcut.gui.console") self.config = None self.loaded = False @@ -108,6 +111,11 @@ def __init__(self, app): ) self._updater.finished.connect(self._on_update_check_finished) + # Debug recorder + self._debug_recorder = install_debug_recorder( + logger_name="deeplabcut", handler_level=logging.INFO, ensure_logger_level="auto" + ) + self.default_set() self._generate_welcome_page() @@ -129,7 +137,7 @@ def __init__(self, app): # create logger to also log to the console logging.basicConfig() - logging.getLogger("console").setLevel(logging.INFO) + self.console_logger.setLevel(logging.INFO) self._progress_bar = QtWidgets.QProgressBar() self._progress_bar.setMaximum(0) @@ -139,7 +147,7 @@ def __init__(self, app): def print_to_status_bar(self, text): self.status_bar.showMessage(text) self.status_bar.repaint() - logging.getLogger("console").info(text) + self.console_logger.info(text) @property def toolbar(self): @@ -627,6 +635,15 @@ def create_actions(self, names): self.check_updates = QAction("&Check for Updates...", self) self.check_updates.triggered.connect(lambda: self.check_for_updates(silent=False)) + self.buildDebugLogAction = create_generate_debug_log_action( + parent=self, + recorder=self._debug_recorder, + logger_name="deeplabcut", + include_module_paths=False, + include_executable_paths=True, + log_limit=1000, + ) + def create_menu_bar(self): menu_bar = self.menuBar() @@ -653,9 +670,11 @@ def create_menu_bar(self): help_menu = QMenu("&Help", self) menu_bar.addMenu(help_menu) help_menu.addAction(self.helpAction) - help_menu.adjustSize() + help_menu.addAction(self.buildDebugLogAction) + help_menu.addSeparator() help_menu.addAction(self.check_updates) help_menu.addAction(self.aboutAction) + help_menu.adjustSize() def update_menu_bar(self): self.file_menu.removeAction(self.newAction) diff --git a/tests/core/debug/test_debug_logger.py b/tests/core/debug/test_debug_logger.py new file mode 100644 index 000000000..c00a4566b --- /dev/null +++ b/tests/core/debug/test_debug_logger.py @@ -0,0 +1,483 @@ +from __future__ import annotations + +import logging +from uuid import uuid4 + +import pytest + +import deeplabcut.core.debug.debug_logger as debug_mod +from deeplabcut.core.debug import ( + DebugSection, + ExecutableSpec, + InMemoryDebugRecorder, + LibrarySpec, + build_debug_report, + collect_executable_summary, + collect_version_summary, + format_debug_report, + get_debug_recorder, + install_debug_recorder, + log_timing, +) + + +@pytest.fixture +def logger_name() -> str: + return f"deeplabcut.tests.debug.{uuid4()}" + + +@pytest.fixture +def clean_logger(logger_name: str): + """Create an isolated logger namespace and fully clean it afterwards.""" + logger = logging.getLogger(logger_name) + old_level = logger.level + old_propagate = logger.propagate + old_handlers = list(logger.handlers) + + logger.setLevel(logging.DEBUG) + logger.propagate = False + + yield logger + + for handler in list(logger.handlers): + logger.removeHandler(handler) + try: + handler.close() + except Exception: + pass + + for handler in old_handlers: + logger.addHandler(handler) + + logger.setLevel(old_level) + logger.propagate = old_propagate + + # Remove recorder marker installed by install_debug_recorder(). + logger.__dict__.pop("_dlc_debug_recorder", None) + + +def test_install_debug_recorder_is_idempotent(logger_name: str, clean_logger): + recorder1 = install_debug_recorder(logger_name=logger_name, capacity=10) + recorder2 = install_debug_recorder(logger_name=logger_name, capacity=99) + + assert recorder1 is recorder2 + assert isinstance(recorder1, InMemoryDebugRecorder) + assert get_debug_recorder(logger_name=logger_name) is recorder1 + + +def test_recorder_captures_messages_and_exceptions(logger_name: str, clean_logger): + logger = clean_logger + recorder = install_debug_recorder(logger_name=logger_name, capacity=10, handler_level=logging.DEBUG) + + logger.info("hello %s", "dlc") + try: + raise ValueError("boom") + except ValueError: + logger.exception("something failed") + + records = recorder.snapshot() + + assert len(records) == 2 + assert records[0].message == "hello dlc" + assert records[0].level == "INFO" + assert records[1].message == "something failed" + assert records[1].level == "ERROR" + assert records[1].exc_text is not None + assert "ValueError: boom" in records[1].exc_text + + +def test_recorder_is_bounded(logger_name: str, clean_logger): + logger = clean_logger + recorder = install_debug_recorder(logger_name=logger_name, capacity=2, handler_level=logging.DEBUG) + + logger.debug("first") + logger.debug("second") + logger.debug("third") + + messages = [rec.message for rec in recorder.snapshot()] + assert messages == ["second", "third"] + + +def test_render_text_contains_recent_messages(logger_name: str, clean_logger): + logger = clean_logger + recorder = install_debug_recorder(logger_name=logger_name, capacity=5) + + logger.warning("alpha") + logger.error("beta") + + text = recorder.render_text(limit=10) + + assert "WARNING" in text + assert "ERROR" in text + assert "alpha" in text + assert "beta" in text + assert logger_name in text + + +def test_clear_resets_records_and_drop_count(logger_name: str, clean_logger): + logger = clean_logger + recorder = install_debug_recorder(logger_name=logger_name, capacity=5) + + logger.info("before clear") + assert recorder.snapshot() + + recorder.clear() + + assert recorder.snapshot() == [] + assert recorder.dropped_count == 0 + assert recorder.render_text() == "" + + +def test_log_timing_emits_when_enabled( + monkeypatch: pytest.MonkeyPatch, + logger_name: str, + clean_logger, +): + logger = clean_logger + calls: list[tuple[int, str, tuple[object, ...]]] = [] + + wrapped = log_timing.__wrapped__ + + monkeypatch.setitem(wrapped.__globals__, "DLC_LOG_TIMING", True) + + ticks = iter([1_000_000_000, 1_005_000_000]) # 5.000 ms + monkeypatch.setitem(wrapped.__globals__, "perf_counter_ns", lambda: next(ticks)) + + monkeypatch.setattr(logger, "isEnabledFor", lambda level: True) + + def fake_log(level, msg, *args): + calls.append((level, msg, args)) + + monkeypatch.setattr(logger, "log", fake_log) + + with log_timing(logger, "tiny-step", threshold_ms=0.0): + pass + + assert calls == [ + (logging.DEBUG, "%s took %.3f ms", ("tiny-step", 5.0)), + ] + + +def test_log_timing_is_silent_when_disabled( + monkeypatch: pytest.MonkeyPatch, + logger_name: str, + clean_logger, +): + logger = clean_logger + calls: list[tuple[int, str, tuple[object, ...]]] = [] + + wrapped = log_timing.__wrapped__ + + monkeypatch.setitem(wrapped.__globals__, "DLC_LOG_TIMING", False) + monkeypatch.setattr(logger, "isEnabledFor", lambda level: True) + + def fake_log(level, msg, *args): + calls.append((level, msg, args)) + + monkeypatch.setattr(logger, "log", fake_log) + + with log_timing(logger, "should-not-appear", threshold_ms=0.0): + pass + + assert calls == [] + + +def test_log_timing_respects_threshold( + monkeypatch: pytest.MonkeyPatch, + logger_name: str, + clean_logger, +): + logger = clean_logger + calls: list[tuple[int, str, tuple[object, ...]]] = [] + + wrapped = log_timing.__wrapped__ + + monkeypatch.setitem(wrapped.__globals__, "DLC_LOG_TIMING", True) + + ticks = iter([1_000_000_000, 1_001_000_000]) # 1.000 ms + monkeypatch.setitem(wrapped.__globals__, "perf_counter_ns", lambda: next(ticks)) + + monkeypatch.setattr(logger, "isEnabledFor", lambda level: True) + + def fake_log(level, msg, *args): + calls.append((level, msg, args)) + + monkeypatch.setattr(logger, "log", fake_log) + + with log_timing(logger, "tiny-step", threshold_ms=2.0): + pass + + assert calls == [] + + +# ----------- Report building tests ----------- +def test_build_debug_report_includes_runtime_libraries_tools_and_recent_logs( + monkeypatch: pytest.MonkeyPatch, +): + recorder = InMemoryDebugRecorder(capacity=10, level=logging.DEBUG) + + record = logging.LogRecord( + name="deeplabcut.tests.debug", + level=logging.INFO, + pathname=__file__, + lineno=123, + msg="hello %s", + args=("report",), + exc_info=None, + ) + recorder.handle(record) + + monkeypatch.setattr( + debug_mod, + "collect_runtime_summary", + lambda: { + "python": "3.11.9", + "platform": "TestOS-1.0", + "executable": "bin/python", + }, + ) + + monkeypatch.setattr( + debug_mod, + "_version", + lambda dist_name: { + "alpha": "1.2.3", + "opencv-python": "9.9.9-dist", + }.get(dist_name, "not-installed"), + ) + + monkeypatch.setattr( + debug_mod, + "_module_version", + lambda module_name: { + "cv2": "4.10.0", + }.get(module_name, "not-installed"), + ) + + monkeypatch.setattr( + debug_mod, + "_module_path", + lambda module_name: { + "alpha": "/tmp/site-packages/alpha/__init__.py", + "cv2": "/tmp/site-packages/cv2/__init__.py", + }.get(module_name, "unknown"), + ) + + monkeypatch.setattr( + debug_mod, + "_command_version", + lambda command, version_args: { + "ffmpeg": "ffmpeg 6.1", + }.get(command, "unavailable"), + ) + + monkeypatch.setattr( + debug_mod, + "_which", + lambda command: { + "ffmpeg": "/usr/bin/ffmpeg", + }.get(command, "not-found"), + ) + + report = build_debug_report( + recorder=recorder, + libraries=( + LibrarySpec("alpha"), + LibrarySpec( + "opencv-python", + dist_name="opencv-python", + module_name="cv2", + prefer_module_version=True, + ), + ), + executables=(ExecutableSpec("ffmpeg"),), + include_module_paths=True, + include_executable_paths=True, + log_limit=20, + ) + + assert "## Runtime" in report + assert "- python: 3.11.9" in report + assert "- platform: TestOS-1.0" in report + assert "- executable: bin/python" in report + + assert "## Libraries" in report + assert "- alpha: 1.2.3" in report + assert "- opencv-python: 4.10.0" in report + assert "- alpha_module_path: alpha/__init__.py" in report + assert "- opencv-python_module_path: cv2/__init__.py" in report + + assert "## External tools" in report + assert "- ffmpeg: ffmpeg 6.1" in report + assert "- ffmpeg_path: bin/ffmpeg" in report + + assert "## Recent logs" in report + assert "deeplabcut.tests.debug" in report + assert "INFO" in report + assert "hello report" in report + assert "```text" in report + + +def test_build_debug_report_default_grouped_sections_and_skips_unavailable_tf( + monkeypatch: pytest.MonkeyPatch, +): + monkeypatch.setattr( + debug_mod, + "collect_runtime_summary", + lambda: { + "python": "3.12.0", + "platform": "GroupedTestOS", + "executable": "python", + }, + ) + + def fake_collect_version_summary(*, libraries=None, include_module_paths=False): + if libraries == debug_mod.DLC_CORE_LIBS: + return {"deeplabcut": "1.0.0", "numpy": "2.0.0"} + if libraries == debug_mod.DLC_GUI_LIBS: + return {"PySide6": "6.8.0"} + if libraries == debug_mod.DLC_TF_LIBS: + return { + "tensorflow": "not-installed", + "tf_keras": "not-installed", + "tensorpack": "unknown", + "tf_slim": "not-installed", + } + raise AssertionError("unexpected libraries input") + + monkeypatch.setattr(debug_mod, "collect_version_summary", fake_collect_version_summary) + + monkeypatch.setattr( + debug_mod, + "collect_executable_summary", + lambda *, executables=None, include_paths=True: { + "ffmpeg": "unavailable", + "ffmpeg_path": "not-found", + }, + ) + + report = build_debug_report( + recorder=None, + libraries=None, + executables=None, + ) + + assert "## Runtime" in report + assert "## DeepLabCut core libraries" in report + assert "- deeplabcut: 1.0.0" in report + assert "## GUI libraries" in report + assert "- PySide6: 6.8.0" in report + + # All TF values are unavailable/unknown, so the section should be omitted. + assert "## TensorFlow libraries" not in report + + # External tools should still be shown even when unavailable. + assert "## External tools" in report + assert "- ffmpeg: unavailable" in report + assert "- ffmpeg_path: not-found" in report + + assert "## Recent logs" in report + assert "" in report + + +def test_collect_version_summary_prefers_module_version_and_falls_back_to_distribution( + monkeypatch: pytest.MonkeyPatch, +): + monkeypatch.setattr( + debug_mod, + "_module_version", + lambda module_name: { + "cv2": "not-installed", + }.get(module_name, "unknown"), + ) + + monkeypatch.setattr( + debug_mod, + "_version", + lambda dist_name: { + "opencv-python": "4.9.0.80", + "missing-lib": "not-installed", + }.get(dist_name, "not-installed"), + ) + + summary = collect_version_summary( + libraries=( + LibrarySpec( + "opencv-python", + dist_name="opencv-python", + module_name="cv2", + prefer_module_version=True, + ), + LibrarySpec("missing-lib"), + ) + ) + + assert summary["opencv-python"] == "4.9.0.80" + assert summary["missing-lib"] == "not-installed" + + +def test_collect_executable_summary_reports_unavailable_tool_and_path( + monkeypatch: pytest.MonkeyPatch, +): + monkeypatch.setattr(debug_mod, "_command_version", lambda command, version_args: "unavailable") + monkeypatch.setattr(debug_mod, "_which", lambda command: "not-found") + + summary = collect_executable_summary( + executables=(ExecutableSpec("ghosttool"),), + include_paths=True, + ) + + assert summary == { + "ghosttool": "unavailable", + "ghosttool_path": "not-found", + } + + +def test_build_debug_report_uses_no_captured_logs_placeholder_for_empty_recorder( + monkeypatch: pytest.MonkeyPatch, +): + recorder = InMemoryDebugRecorder(capacity=5, level=logging.DEBUG) + + monkeypatch.setattr( + debug_mod, + "collect_runtime_summary", + lambda: { + "python": "3.11.0", + "platform": "EmptyLogsOS", + "executable": "python", + }, + ) + + monkeypatch.setattr( + debug_mod, + "collect_executable_summary", + lambda *, executables=None, include_paths=True: {}, + ) + + report = build_debug_report( + recorder=recorder, + libraries=(), + executables=(), + ) + + assert "## Runtime" in report + assert "## Libraries" in report + assert "- " in report + assert "## Recent logs" in report + assert "" in report + + +def test_format_debug_report_renders_empty_section_and_logs_block(): + text = format_debug_report( + sections=[ + DebugSection(title="Example", items={}), + ], + logs_text="line one\nline two", + ) + + assert "## Example" in text + assert "- " in text + assert "## Recent logs" in text + assert "```text" in text + assert "line one" in text + assert "line two" in text