From fbfe6de66b522446ed5c679840bc73a7fa74ee57 Mon Sep 17 00:00:00 2001 From: Utkarsh Bahuguna Date: Wed, 5 Aug 2026 22:17:03 +0530 Subject: [PATCH] feat(pathfinder): opt-in diagnostic logging for load_nvidia_dynamic_lib Adds a `cuda.pathfinder` logger, disabled by default, enabled by setting CUDA_PATHFINDER_LOG_LEVEL to a standard level name or an integer. `logging` is imported only when the variable is set. Importing it pulls in seven additional modules and measurably slows `import cuda.pathfinder`, which sits on the import hot path of every consumer, so the disabled path imports nothing and costs one module-global lookup plus an identity check (~5 ns) at each call site. No message string or `extra` dict is built when logging is off. Instruments the dynamic-library search only: each find step reports whether it matched, a successful load reports the resolved path and `found_via`, and the failure path emits the accumulated candidate list as structured fields. Records carry `pathfinder_*` fields so consumers can filter without parsing messages. The logger attaches a NullHandler, never calls basicConfig, and never touches the root logger. Invalid CUDA_PATHFINDER_LOG_LEVEL values warn once and leave logging disabled rather than raising. The environment variable is read once at import, matching the documented read-once policy of get_cuda_path_or_home(). Signed-off-by: Utkarsh Bahuguna --- .../_dynamic_libs/load_nvidia_dynamic_lib.py | 40 ++- .../pathfinder/_dynamic_libs/search_steps.py | 37 +++ .../cuda/pathfinder/_utils/diagnostic_log.py | 107 ++++++++ cuda_pathfinder/tests/test_diagnostic_log.py | 253 ++++++++++++++++++ 4 files changed, 431 insertions(+), 6 deletions(-) create mode 100644 cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py create mode 100644 cuda_pathfinder/tests/test_diagnostic_log.py diff --git a/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/load_nvidia_dynamic_lib.py b/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/load_nvidia_dynamic_lib.py index 53446107da3..66c76d8ea7d 100644 --- a/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/load_nvidia_dynamic_lib.py +++ b/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/load_nvidia_dynamic_lib.py @@ -35,6 +35,7 @@ parse_dynamic_lib_subprocess_payload, ) from cuda.pathfinder._dynamic_libs.supported_nvidia_libs import ALL_AVAILABLE_LIBNAMES +from cuda.pathfinder._utils.diagnostic_log import LOGGER, search_extra from cuda.pathfinder._utils.platform_aware import IS_WINDOWS if TYPE_CHECKING: @@ -162,11 +163,32 @@ def _try_ctk_root_canary(ctx: SearchContext) -> str | None: return None +def _log_resolved(loaded: LoadedDL, libname: str) -> LoadedDL: + """Log a successful resolution and return it unchanged.""" + if LOGGER is not None: + LOGGER.info( + "resolved %s to %s via %s", + libname, + loaded.abs_path, + loaded.found_via, + extra=search_extra( + libname, + pathfinder_abs_path=loaded.abs_path, + pathfinder_found_via=loaded.found_via, + pathfinder_was_already_loaded=loaded.was_already_loaded_from_elsewhere, + ), + ) + return loaded + + def _load_lib_no_cache(libname: str) -> LoadedDL: desc = LIB_DESCRIPTORS[libname] if libname in _DRIVER_ONLY_LIBNAMES: - return _load_driver_lib_no_cache(desc) + return _log_resolved(_load_driver_lib_no_cache(desc), libname) + + if LOGGER is not None: + LOGGER.debug("starting search for %s", libname, extra=search_extra(libname)) ctx = SearchContext(desc) @@ -179,24 +201,30 @@ def _load_lib_no_cache(libname: str) -> LoadedDL: loaded = LOADER.check_if_already_loaded_from_elsewhere(desc, find is not None) load_dependencies(desc, load_nvidia_dynamic_lib) if loaded is not None: - return loaded + return _log_resolved(loaded, libname) # Phase 3: Load from found path, or fall back to system search + late find. if find is not None: - return LOADER.load_with_abs_path(desc, find.abs_path, find.found_via) + return _log_resolved(LOADER.load_with_abs_path(desc, find.abs_path, find.found_via), libname) loaded = LOADER.load_with_system_search(desc) if loaded is not None: - return loaded + return _log_resolved(loaded, libname) + if LOGGER is not None: + LOGGER.debug( + "system search did not resolve %s; trying late find steps", + libname, + extra=search_extra(libname, pathfinder_step="load_with_system_search", pathfinder_matched=False), + ) find = run_find_steps(ctx, LATE_FIND_STEPS) if find is not None: - return LOADER.load_with_abs_path(desc, find.abs_path, find.found_via) + return _log_resolved(LOADER.load_with_abs_path(desc, find.abs_path, find.found_via), libname) if desc.ctk_root_canary_anchor_libnames: canary_abs_path = _try_ctk_root_canary(ctx) if canary_abs_path is not None: - return LOADER.load_with_abs_path(desc, canary_abs_path, "system-ctk-root") + return _log_resolved(LOADER.load_with_abs_path(desc, canary_abs_path, "system-ctk-root"), libname) ctx.raise_not_found() diff --git a/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/search_steps.py b/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/search_steps.py index 5901094fcaa..3d82f747ab5 100644 --- a/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/search_steps.py +++ b/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/search_steps.py @@ -28,6 +28,7 @@ from cuda.pathfinder._dynamic_libs.lib_descriptor import LibDescriptor from cuda.pathfinder._dynamic_libs.load_dl_common import DynamicLibNotFoundError from cuda.pathfinder._dynamic_libs.search_platform import PLATFORM, SearchPlatform +from cuda.pathfinder._utils.diagnostic_log import LOGGER, search_extra from cuda.pathfinder._utils.env_vars import get_cuda_path_or_home # --------------------------------------------------------------------------- @@ -63,6 +64,20 @@ def lib_searched_for(self) -> str: def raise_not_found(self) -> NoReturn: err = ", ".join(self.error_messages) att = "\n".join(self.attachments) + if LOGGER is not None: + # The exception below already carries this information, always on. + # Logging it too gives consumers the candidate list as structured + # fields rather than as text they would have to parse back out. + LOGGER.error( + "search failed for %s: no candidate matched", + self.lib_searched_for, + extra=search_extra( + self.libname, + pathfinder_searched_for=self.lib_searched_for, + pathfinder_error_messages=list(self.error_messages), + pathfinder_attachments=list(self.attachments), + ), + ) raise DynamicLibNotFoundError(f'Failure finding "{self.lib_searched_for}": {err}\n{att}') @@ -224,6 +239,28 @@ def run_find_steps(ctx: SearchContext, steps: tuple[FindStep, ...]) -> FindResul """Run find steps in order, returning the first hit.""" for step in steps: result = step(ctx) + if LOGGER is not None: + if result is None: + LOGGER.debug( + "step %s: no match for %s", + step.__name__, + ctx.lib_searched_for, + extra=search_extra(ctx.libname, pathfinder_step=step.__name__, pathfinder_matched=False), + ) + else: + LOGGER.debug( + "step %s: matched %s via %s", + step.__name__, + result.abs_path, + result.found_via, + extra=search_extra( + ctx.libname, + pathfinder_step=step.__name__, + pathfinder_matched=True, + pathfinder_abs_path=result.abs_path, + pathfinder_found_via=result.found_via, + ), + ) if result is not None: return result return None diff --git a/cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py b/cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py new file mode 100644 index 00000000000..d3777a71454 --- /dev/null +++ b/cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py @@ -0,0 +1,107 @@ +# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 + +"""Opt-in diagnostic logging for cuda.pathfinder. + +Disabled by default. Set ``CUDA_PATHFINDER_LOG_LEVEL`` to a standard level name +(``DEBUG``, ``INFO``, ``WARNING``, ``ERROR``, ``CRITICAL``) or to a numeric +level to enable it:: + + CUDA_PATHFINDER_LOG_LEVEL=DEBUG python -c "import cuda.pathfinder as p; p.load_nvidia_dynamic_lib('cudart')" + +Design notes +------------ +``logging`` is **not** imported unless the environment variable is set. Importing +it pulls in seven additional modules (``logging``, ``atexit``, ``string``, +``_string``, ``textwrap``, ``traceback``, ``_colorize``) and measurably slows +``import cuda.pathfinder``, which sits on the import hot path of every consumer. +Deferring the import keeps the disabled path free rather than merely cheap. + +Call sites guard on ``LOGGER is not None`` so that a disabled logger costs one +module-global lookup and an identity check, and so that no message string or +``extra`` dict is built when logging is off. + +The environment variable is read exactly once, at import. This matches +:func:`cuda.pathfinder._utils.env_vars.get_cuda_path_or_home`, which is +``functools.cache``-d and documents the same read-once policy. + +This module never configures the root logger, never calls ``basicConfig``, and +attaches only a ``NullHandler``. Consumers remain in full control of handlers +and formatting. +""" + +from __future__ import annotations + +import os +import warnings +from typing import TYPE_CHECKING, Any + +if TYPE_CHECKING: + import logging + +#: Environment variable that enables logging. Matches the existing +#: ``CUDA_PATHFINDER_*`` prefix used elsewhere in this package. +ENV_VAR_NAME = "CUDA_PATHFINDER_LOG_LEVEL" + +#: Logger name. Mirrors the import path so consumers can filter on it. +LOGGER_NAME = "cuda.pathfinder" + +_VALID_LEVEL_NAMES = ("CRITICAL", "ERROR", "WARNING", "INFO", "DEBUG") + + +def _resolve_level(raw: str) -> int | None: + """Map an environment-variable value to a logging level, or None if invalid.""" + import logging + + name = raw.strip().upper() + if name in _VALID_LEVEL_NAMES: + return int(getattr(logging, name)) + try: + return int(raw.strip()) + except ValueError: + return None + + +def _make_logger() -> logging.Logger | None: + """Build the package logger, or return None when logging is disabled. + + ``logging`` is imported only on the enabled path. + """ + raw = os.environ.get(ENV_VAR_NAME) + if not raw or not raw.strip(): + return None + + level = _resolve_level(raw) + if level is None: + warnings.warn( + f"{ENV_VAR_NAME}={raw!r} is not a valid logging level; " + f"expected one of {', '.join(_VALID_LEVEL_NAMES)} or an integer. " + "cuda.pathfinder logging stays disabled.", + UserWarning, + stacklevel=2, + ) + return None + + import logging + + logger = logging.getLogger(LOGGER_NAME) + # NullHandler keeps "No handlers could be found" quiet without imposing a + # destination; consumers attach their own handler if they want output. + logger.addHandler(logging.NullHandler()) + logger.setLevel(level) + return logger + + +#: The package logger, or ``None`` when logging is disabled. Guard every call +#: site with ``if LOGGER is not None:`` so the disabled path builds nothing. +LOGGER: logging.Logger | None = _make_logger() + + +def search_extra(libname: str, **fields: Any) -> dict[str, Any]: + """Build the ``extra`` mapping shared by pathfinder log records. + + Only ever called from inside a ``LOGGER is not None`` guard, so it costs + nothing when logging is disabled. Consumers can filter on these fields + instead of parsing the message text. + """ + return {"pathfinder_libname": libname, **fields} diff --git a/cuda_pathfinder/tests/test_diagnostic_log.py b/cuda_pathfinder/tests/test_diagnostic_log.py new file mode 100644 index 00000000000..4c97c2a2c3e --- /dev/null +++ b/cuda_pathfinder/tests/test_diagnostic_log.py @@ -0,0 +1,253 @@ +# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 + +"""Tests for opt-in diagnostic logging. + +All tests run without a GPU and without any NVIDIA library installed: the +search cascade is driven with a libname that cannot resolve, and the +enabled/disabled behaviour is exercised by reimporting the module under a +patched environment. +""" + +import importlib +import logging +import os +import sys +from unittest.mock import patch + +import pytest + +from cuda.pathfinder._dynamic_libs.lib_descriptor import LIB_DESCRIPTORS +from cuda.pathfinder._dynamic_libs.load_dl_common import DynamicLibNotFoundError +from cuda.pathfinder._utils import diagnostic_log + +ENV_VAR = diagnostic_log.ENV_VAR_NAME +LOGGER_NAME = diagnostic_log.LOGGER_NAME + + +def reload_with_env(value): + """Reimport diagnostic_log with ENV_VAR set to *value* (None to unset). + + Returns the freshly imported module. The module is restored afterwards by + the ``restore_diagnostic_log`` fixture. + """ + env = dict(os.environ) + env.pop(ENV_VAR, None) + if value is not None: + env[ENV_VAR] = value + with patch.dict(os.environ, env, clear=True): + return importlib.reload(diagnostic_log) + + +@pytest.fixture(autouse=True) +def restore_diagnostic_log(): + """Leave the module and the logger exactly as they were found.""" + logger = logging.getLogger(LOGGER_NAME) + saved = (logger.level, list(logger.handlers), logger.propagate) + yield + logger.setLevel(saved[0]) + logger.handlers[:] = saved[1] + logger.propagate = saved[2] + reload_with_env(None) + + +# --------------------------------------------------------------------------- +# enable / disable +# --------------------------------------------------------------------------- + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_logger_is_none_by_default(): + """Unset env var means no logger object at all, not merely a quiet one.""" + module = reload_with_env(None) + assert module.LOGGER is None + + +@pytest.mark.parametrize("value", ["", " "]) +@pytest.mark.agent_authored(model="claude-opus-5") +def test_empty_value_leaves_logging_disabled(value): + module = reload_with_env(value) + assert module.LOGGER is None + + +@pytest.mark.parametrize("value", ["DEBUG", "debug", " Debug ", "INFO", "WARNING", "ERROR", "CRITICAL"]) +@pytest.mark.agent_authored(model="claude-opus-5") +def test_env_var_enables_logger(value): + module = reload_with_env(value) + assert module.LOGGER is not None + assert module.LOGGER.name == LOGGER_NAME + assert module.LOGGER.level == getattr(logging, value.strip().upper()) + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_numeric_level_accepted(): + module = reload_with_env("10") + assert module.LOGGER is not None + assert module.LOGGER.level == logging.DEBUG + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_invalid_value_warns_once_and_stays_disabled(): + """An unusable value must not raise, and must not enable partial logging.""" + with pytest.warns(UserWarning, match=ENV_VAR) as record: + module = reload_with_env("VERBOSE") + assert module.LOGGER is None + assert len(record) == 1 + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_logging_not_imported_when_disabled(): + """The disabled path must not pay for `import logging`. + + Guard: this asserts the module does not import logging *itself*. pytest has + already imported logging, so the check is on the module's own behaviour. + """ + source = (diagnostic_log.__file__ or "").replace(".pyc", ".py") + with open(source) as f: + body = f.read() + # Every `import logging` must sit inside a function, never at module scope. + module_level_imports = [line for line in body.splitlines() if line.startswith(("import logging", "from logging"))] + assert module_level_imports == [], f"logging imported at module scope: {module_level_imports}" + + +# --------------------------------------------------------------------------- +# no side effects on the root logger +# --------------------------------------------------------------------------- + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_does_not_configure_root_logger(): + root = logging.getLogger() + before = (root.level, list(root.handlers)) + module = reload_with_env("DEBUG") + assert module.LOGGER is not None + assert root.level == before[0] + assert root.handlers == before[1] + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_attaches_only_a_null_handler(): + module = reload_with_env("DEBUG") + assert module.LOGGER is not None + assert any(isinstance(h, logging.NullHandler) for h in module.LOGGER.handlers) + assert all(isinstance(h, logging.NullHandler) for h in module.LOGGER.handlers) + + +# --------------------------------------------------------------------------- +# the search cascade emits records +# --------------------------------------------------------------------------- + + +def _reload_dependents(): + """Reload the modules that captured LOGGER at import time.""" + for name in ( + "cuda.pathfinder._dynamic_libs.search_steps", + "cuda.pathfinder._dynamic_libs.load_nvidia_dynamic_lib", + ): + if name in sys.modules: + importlib.reload(sys.modules[name]) + + +@pytest.fixture +def enabled_cascade(): + """Enable logging and rebind it into the search modules.""" + reload_with_env("DEBUG") + _reload_dependents() + yield + reload_with_env(None) + _reload_dependents() + + +def _unresolvable_context(): + """A SearchContext for a library that cannot be found anywhere.""" + from cuda.pathfinder._dynamic_libs import search_steps + + ctx = search_steps.SearchContext(LIB_DESCRIPTORS["cudart"]) + ctx.error_messages.append("no candidate in site-packages") + ctx.attachments.append("tried: /nonexistent/one\ntried: /nonexistent/two") + return search_steps, ctx + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_failed_lookup_logs_full_candidate_list(enabled_cascade, caplog): + """The failure path must carry the candidate list as structured fields.""" + search_steps, ctx = _unresolvable_context() + with caplog.at_level(logging.DEBUG, logger=LOGGER_NAME), pytest.raises(DynamicLibNotFoundError): + ctx.raise_not_found() + + errors = [r for r in caplog.records if r.levelno == logging.ERROR] + assert errors, "expected an ERROR record on the failure path" + record = errors[0] + assert record.pathfinder_libname == "cudart" + assert record.pathfinder_error_messages == ["no candidate in site-packages"] + assert "/nonexistent/one" in "\n".join(record.pathfinder_attachments) + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_step_outcomes_are_logged(enabled_cascade, caplog): + """Each find step reports whether it matched, with the step name attached.""" + search_steps, ctx = _unresolvable_context() + + def miss(_ctx): + return None + + def hit(_ctx): + return search_steps.FindResult("/opt/cuda/lib64/libcudart.so.12", "conda") + + with caplog.at_level(logging.DEBUG, logger=LOGGER_NAME): + result = search_steps.run_find_steps(ctx, (miss, hit)) + + assert result is not None + by_step = {r.pathfinder_step: r for r in caplog.records if hasattr(r, "pathfinder_step")} + assert by_step["miss"].pathfinder_matched is False + assert by_step["hit"].pathfinder_matched is True + assert by_step["hit"].pathfinder_abs_path == "/opt/cuda/lib64/libcudart.so.12" + assert by_step["hit"].pathfinder_found_via == "conda" + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_successful_resolution_logs_resolved_path(enabled_cascade, caplog): + """A resolved load emits the absolute path and how it was found.""" + from cuda.pathfinder._dynamic_libs import load_nvidia_dynamic_lib as mod + from cuda.pathfinder._dynamic_libs.load_dl_common import LoadedDL + + loaded = LoadedDL( + abs_path="/usr/lib/x86_64-linux-gnu/libcudart.so.12", + was_already_loaded_from_elsewhere=False, + _handle_uint=1234, + found_via="site-packages", + ) + with caplog.at_level(logging.DEBUG, logger=LOGGER_NAME): + returned = mod._log_resolved(loaded, "cudart") + + assert returned is loaded + infos = [r for r in caplog.records if r.levelno == logging.INFO] + assert infos, "expected an INFO record on the success path" + record = infos[0] + assert record.pathfinder_abs_path == "/usr/lib/x86_64-linux-gnu/libcudart.so.12" + assert record.pathfinder_found_via == "site-packages" + assert record.pathfinder_was_already_loaded is False + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_silent_when_disabled(caplog): + """With the env var unset, the same call sites emit nothing.""" + reload_with_env(None) + _reload_dependents() + from cuda.pathfinder._dynamic_libs import load_nvidia_dynamic_lib as mod + from cuda.pathfinder._dynamic_libs.load_dl_common import LoadedDL + + loaded = LoadedDL("/x/libcudart.so.12", False, 1, "conda") + with caplog.at_level(logging.DEBUG, logger=LOGGER_NAME): + mod._log_resolved(loaded, "cudart") + search_steps, ctx = _unresolvable_context() + with pytest.raises(DynamicLibNotFoundError): + ctx.raise_not_found() + + assert [r for r in caplog.records if r.name == LOGGER_NAME] == [] + + +@pytest.mark.agent_authored(model="claude-opus-5") +def test_search_extra_carries_libname(): + extra = diagnostic_log.search_extra("cudart", pathfinder_found_via="conda") + assert extra == {"pathfinder_libname": "cudart", "pathfinder_found_via": "conda"}