From fbfe6de66b522446ed5c679840bc73a7fa74ee57 Mon Sep 17 00:00:00 2001 From: Utkarsh Bahuguna Date: Wed, 5 Aug 2026 22:17:03 +0530 Subject: [PATCH 1/5] 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"} From 6c5b0cc35ecc8aea1e9cf5aa5f2c2817e2349152 Mon Sep 17 00:00:00 2001 From: Utkarsh Bahuguna Date: Fri, 25 Sep 2026 15:37:09 +0530 Subject: [PATCH 2/5] test(pathfinder): bind the logger by attribute instead of reloading modules The cascade fixture reloaded search_steps and load_nvidia_dynamic_lib to pick up a LOGGER enabled after import. A reload rebinds everything the module defines, including FindResult, so any test module that imported FindResult beforehand held a different class object than the one the reloaded search_steps returned. Dataclass equality compares classes, so those assertions failed on values that print identically, and which tests broke depended on execution order. The consumers bind LOGGER by value at import, so setting that one attribute through monkeypatch is enough and leaves no state behind. test_silent_when_ disabled asserts the disabled default rather than reloading into it. Against current main this fixes 13 failures in test_search_steps.py and test_windows_nsight.py; on the original base it was 2 in test_load_nvidia_dynamic_lib_using_mocker.py. CI never ran on this PR, so it was never reported. Signed-off-by: Utkarsh Bahuguna --- cuda_pathfinder/tests/test_diagnostic_log.py | 41 ++++++++++---------- 1 file changed, 21 insertions(+), 20 deletions(-) diff --git a/cuda_pathfinder/tests/test_diagnostic_log.py b/cuda_pathfinder/tests/test_diagnostic_log.py index 4c97c2a2c3e..34b48866d2b 100644 --- a/cuda_pathfinder/tests/test_diagnostic_log.py +++ b/cuda_pathfinder/tests/test_diagnostic_log.py @@ -12,7 +12,6 @@ import importlib import logging import os -import sys from unittest.mock import patch import pytest @@ -138,24 +137,23 @@ def test_attaches_only_a_null_handler(): # --------------------------------------------------------------------------- -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 enabled_cascade(monkeypatch): + """Enable logging and rebind it into the search modules. + + The consumers bind LOGGER by value at import, so the fixture sets that one + attribute on each of them rather than reloading them. Reloading would also + rebind their classes, and a module that imported FindResult before the + reload then holds a different class object than the one the reloaded + search_steps returns, so equality between the two fails and unrelated test + modules break depending on execution order. + """ + from cuda.pathfinder._dynamic_libs import load_nvidia_dynamic_lib, search_steps + + logger = reload_with_env("DEBUG").LOGGER + assert logger is not None, "logging should be enabled under a valid level" + for consumer in (search_steps, load_nvidia_dynamic_lib): + monkeypatch.setattr(consumer, "LOGGER", logger) def _unresolvable_context(): @@ -232,9 +230,12 @@ def test_successful_resolution_logs_resolved_path(enabled_cascade, caplog): @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 import search_steps as steps + + # Disabled is the default, so assert it rather than reloading into it. + assert reload_with_env(None).LOGGER is None + assert mod.LOGGER is None and steps.LOGGER is None from cuda.pathfinder._dynamic_libs.load_dl_common import LoadedDL loaded = LoadedDL("/x/libcudart.so.12", False, 1, "conda") From 99559acb093fcd4a40bf8bd4e72bc77a041d8394 Mon Sep 17 00:00:00 2001 From: Utkarsh Bahuguna Date: Thu, 1 Oct 2026 16:11:08 +0530 Subject: [PATCH 3/5] refactor(pathfinder): reduce logging to one INFO record per load Signed-off-by: Utkarsh Bahuguna --- .../_dynamic_libs/load_nvidia_dynamic_lib.py | 46 +--- .../pathfinder/_dynamic_libs/search_steps.py | 37 --- .../cuda/pathfinder/_utils/diagnostic_log.py | 90 +------ cuda_pathfinder/tests/test_diagnostic_log.py | 242 ++++-------------- 4 files changed, 81 insertions(+), 334 deletions(-) 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 b965921ac52..98cd3c28e80 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,7 +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.diagnostic_log import LOGGER from cuda.pathfinder._utils.platform_aware import IS_WINDOWS if TYPE_CHECKING: @@ -163,32 +163,11 @@ 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 _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)) + return _load_driver_lib_no_cache(desc) ctx = SearchContext(desc) @@ -199,30 +178,24 @@ def _load_lib_no_cache(libname: str) -> LoadedDL: loaded = LOADER.check_if_already_loaded_from_elsewhere(desc) load_dependencies(desc, load_nvidia_dynamic_lib) if loaded is not None: - return _log_resolved(loaded, libname) + return loaded # Phase 3: Load from found path, or fall back to system search + late find. if find is not None: - return _log_resolved(LOADER.load_with_abs_path(desc, find.abs_path, find.found_via), libname) + return LOADER.load_with_abs_path(desc, find.abs_path, find.found_via) loaded = LOADER.load_with_system_search(desc) if loaded is not None: - 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), - ) + return loaded find = run_find_steps(ctx, LATE_FIND_STEPS) if find is not None: - return _log_resolved(LOADER.load_with_abs_path(desc, find.abs_path, find.found_via), libname) + return LOADER.load_with_abs_path(desc, find.abs_path, find.found_via) if desc.ctk_root_canary_anchor_libnames: canary_abs_path = _try_ctk_root_canary(ctx) if canary_abs_path is not None: - return _log_resolved(LOADER.load_with_abs_path(desc, canary_abs_path, "system-ctk-root"), libname) + return LOADER.load_with_abs_path(desc, canary_abs_path, "system-ctk-root") ctx.raise_not_found() @@ -355,4 +328,7 @@ def load_nvidia_dynamic_lib(libname: str) -> LoadedDL: f"Library name {libname!r} is known but not available on {_PLATFORM_NAME}. " f"Supported names on {_PLATFORM_NAME}: {sorted(ALL_AVAILABLE_LIBNAMES)}" ) - return _load_lib_no_cache(libname) + loaded = _load_lib_no_cache(libname) + if LOGGER is not None: + LOGGER.info("loaded %s from %s (found via %s)", libname, loaded.abs_path, loaded.found_via) + return loaded diff --git a/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/search_steps.py b/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/search_steps.py index e068c00c967..80779f72ae2 100644 --- a/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/search_steps.py +++ b/cuda_pathfinder/cuda/pathfinder/_dynamic_libs/search_steps.py @@ -28,7 +28,6 @@ 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 from cuda.pathfinder._utils.path_sort import numeric_aware_path_sort_key @@ -65,20 +64,6 @@ 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}') @@ -292,28 +277,6 @@ 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 index d3777a71454..8d1274b1884 100644 --- a/cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py +++ b/cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py @@ -1,107 +1,45 @@ # SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. # SPDX-License-Identifier: Apache-2.0 -"""Opt-in diagnostic logging for cuda.pathfinder. +"""Opt-in logging of where :func:`load_nvidia_dynamic_lib` found each library. -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. +Disabled by default. Set ``CUDA_PATHFINDER_LOG_LEVEL`` to a level name (e.g. +``INFO``) or number to enable it. ``logging`` is only imported when the variable +is set, and the root logger is never configured. """ from __future__ import annotations import os import warnings -from typing import TYPE_CHECKING, Any +from typing import TYPE_CHECKING 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 +_LEVEL_NAMES = ("CRITICAL", "ERROR", "WARNING", "INFO", "DEBUG") 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(): + raw = os.environ.get(ENV_VAR_NAME, "").strip() + if not raw: return None - level = _resolve_level(raw) + import logging + + name = raw.upper() + level = int(raw) if raw.isdigit() else getattr(logging, name) if name in _LEVEL_NAMES else None 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, - ) + warnings.warn(f"{ENV_VAR_NAME}={raw!r} is not a valid logging level; logging stays disabled.", 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. +#: ``None`` when logging is disabled, so call sites can skip all work. 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 index 34b48866d2b..bce1059dcd2 100644 --- a/cuda_pathfinder/tests/test_diagnostic_log.py +++ b/cuda_pathfinder/tests/test_diagnostic_log.py @@ -1,13 +1,7 @@ # 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. -""" +"""Tests for opt-in logging in load_nvidia_dynamic_lib. No GPU or NVIDIA library needed.""" import importlib import logging @@ -16,22 +10,18 @@ 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._dynamic_libs import load_nvidia_dynamic_lib as mod +from cuda.pathfinder._dynamic_libs.load_dl_common import DynamicLibNotFoundError, LoadedDL from cuda.pathfinder._utils import diagnostic_log ENV_VAR = diagnostic_log.ENV_VAR_NAME LOGGER_NAME = diagnostic_log.LOGGER_NAME +LOADED = LoadedDL("/opt/cuda/lib64/libcudart.so.12", False, 1234, "CUDA_PATH") 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) + """Reimport diagnostic_log with ENV_VAR set to *value* (None to unset).""" + env = {k: v for k, v in os.environ.items() if k != ENV_VAR} if value is not None: env[ENV_VAR] = value with patch.dict(os.environ, env, clear=True): @@ -40,215 +30,95 @@ def reload_with_env(value): @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) + saved = (logger.level, list(logger.handlers)) 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.parametrize("value", [None, "", " "]) @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()) +def test_disabled_by_default(value): + assert reload_with_env(value).LOGGER is None +@pytest.mark.parametrize(("value", "level"), [("INFO", logging.INFO), (" debug ", logging.DEBUG), ("10", 10)]) @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 +def test_env_var_enables_logger(value, level): + logger = reload_with_env(value).LOGGER + assert logger is not None + assert logger.name == LOGGER_NAME + assert logger.level == level + assert all(isinstance(h, logging.NullHandler) for h in logger.handlers) @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 -# --------------------------------------------------------------------------- +def test_invalid_value_warns_and_stays_disabled(): + with pytest.warns(UserWarning, match=ENV_VAR): + assert reload_with_env("VERBOSE").LOGGER is None @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] + reload_with_env("DEBUG") + assert (root.level, root.handlers) == before @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 test_logging_not_imported_at_module_scope(): + with open(diagnostic_log.__file__) as f: + lines = f.read().splitlines() + assert not [line for line in lines if line.startswith(("import logging", "from logging"))] @pytest.fixture -def enabled_cascade(monkeypatch): - """Enable logging and rebind it into the search modules. - - The consumers bind LOGGER by value at import, so the fixture sets that one - attribute on each of them rather than reloading them. Reloading would also - rebind their classes, and a module that imported FindResult before the - reload then holds a different class object than the one the reloaded - search_steps returns, so equality between the two fails and unrelated test - modules break depending on execution order. - """ - from cuda.pathfinder._dynamic_libs import load_nvidia_dynamic_lib, search_steps +def load_cudart(monkeypatch): + """Call load_nvidia_dynamic_lib('cudart') with the search stubbed out.""" - logger = reload_with_env("DEBUG").LOGGER - assert logger is not None, "logging should be enabled under a valid level" - for consumer in (search_steps, load_nvidia_dynamic_lib): - monkeypatch.setattr(consumer, "LOGGER", logger) + def call(logger, result=LOADED): + monkeypatch.setattr(mod, "LOGGER", logger) + def fake_load(_libname): + if isinstance(result, Exception): + raise result + return result -def _unresolvable_context(): - """A SearchContext for a library that cannot be found anywhere.""" - from cuda.pathfinder._dynamic_libs import search_steps + monkeypatch.setattr(mod, "_load_lib_no_cache", fake_load) + mod.load_nvidia_dynamic_lib.cache_clear() + try: + return mod.load_nvidia_dynamic_lib("cudart") + finally: + mod.load_nvidia_dynamic_lib.cache_clear() - 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 + return call @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() +def test_successful_load_logs_one_info_record(load_cudart, caplog): + logger = reload_with_env("INFO").LOGGER + with caplog.at_level(logging.INFO, logger=LOGGER_NAME): + assert load_cudart(logger) is LOADED - 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) + records = [r for r in caplog.records if r.name == LOGGER_NAME] + assert len(records) == 1 + assert records[0].levelno == logging.INFO + assert records[0].getMessage() == "loaded cudart from /opt/cuda/lib64/libcudart.so.12 (found via CUDA_PATH)" @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 +def test_failed_load_logs_nothing(load_cudart, caplog): + logger = reload_with_env("DEBUG").LOGGER + with caplog.at_level(logging.DEBUG, logger=LOGGER_NAME), pytest.raises(DynamicLibNotFoundError): + load_cudart(logger, DynamicLibNotFoundError("not found")) + assert [r for r in caplog.records if r.name == LOGGER_NAME] == [] @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.""" - from cuda.pathfinder._dynamic_libs import load_nvidia_dynamic_lib as mod - from cuda.pathfinder._dynamic_libs import search_steps as steps - - # Disabled is the default, so assert it rather than reloading into it. - assert reload_with_env(None).LOGGER is None - assert mod.LOGGER is None and steps.LOGGER is None - from cuda.pathfinder._dynamic_libs.load_dl_common import LoadedDL - - loaded = LoadedDL("/x/libcudart.so.12", False, 1, "conda") +def test_silent_when_disabled(load_cudart, caplog): 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 load_cudart(None) is LOADED 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"} From 4c9b60e403c1bbc2e478e3819da781c4ca46415a Mon Sep 17 00:00:00 2001 From: Utkarsh Bahuguna Date: Fri, 30 Oct 2026 14:38:25 +0530 Subject: [PATCH 4/5] docs(pathfinder): mention CUDA_PATHFINDER_LOG_LEVEL in load_nvidia_dynamic_lib Signed-off-by: Utkarsh Bahuguna --- .../cuda/pathfinder/_dynamic_libs/load_nvidia_dynamic_lib.py | 3 +++ 1 file changed, 3 insertions(+) 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 98cd3c28e80..e4a101e163d 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 @@ -313,6 +313,9 @@ def load_nvidia_dynamic_lib(libname: str) -> LoadedDL: The search is performed **per library**. There is currently no mechanism to guarantee that multiple libraries are all resolved from the same location. + Set ``CUDA_PATHFINDER_LOG_LEVEL=INFO`` to log where each library was + found (``abs_path`` and ``found_via``) to the ``cuda.pathfinder`` logger. + """ pointer_size_bits = struct.calcsize("P") * 8 if pointer_size_bits != 64: From 7c79f2519d0cda3ca8ac6108e874529e3b8ef8d8 Mon Sep 17 00:00:00 2001 From: Utkarsh Bahuguna Date: Fri, 6 Nov 2026 14:11:52 +0530 Subject: [PATCH 5/5] test(pathfinder): mark diagnostic log tests thread-unsafe; parse only decimal levels Signed-off-by: Utkarsh Bahuguna --- cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py | 2 +- cuda_pathfinder/tests/test_diagnostic_log.py | 7 +++++-- 2 files changed, 6 insertions(+), 3 deletions(-) diff --git a/cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py b/cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py index 8d1274b1884..7c9a362a338 100644 --- a/cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py +++ b/cuda_pathfinder/cuda/pathfinder/_utils/diagnostic_log.py @@ -30,7 +30,7 @@ def _make_logger() -> logging.Logger | None: import logging name = raw.upper() - level = int(raw) if raw.isdigit() else getattr(logging, name) if name in _LEVEL_NAMES else None + level = int(raw) if raw.isdecimal() else getattr(logging, name) if name in _LEVEL_NAMES else None if level is None: warnings.warn(f"{ENV_VAR_NAME}={raw!r} is not a valid logging level; logging stays disabled.", stacklevel=2) return None diff --git a/cuda_pathfinder/tests/test_diagnostic_log.py b/cuda_pathfinder/tests/test_diagnostic_log.py index bce1059dcd2..58ee11cd4af 100644 --- a/cuda_pathfinder/tests/test_diagnostic_log.py +++ b/cuda_pathfinder/tests/test_diagnostic_log.py @@ -14,6 +14,8 @@ from cuda.pathfinder._dynamic_libs.load_dl_common import DynamicLibNotFoundError, LoadedDL from cuda.pathfinder._utils import diagnostic_log +pytestmark = pytest.mark.thread_unsafe(reason="reloads diagnostic_log under a patched os.environ") + ENV_VAR = diagnostic_log.ENV_VAR_NAME LOGGER_NAME = diagnostic_log.LOGGER_NAME LOADED = LoadedDL("/opt/cuda/lib64/libcudart.so.12", False, 1234, "CUDA_PATH") @@ -54,10 +56,11 @@ def test_env_var_enables_logger(value, level): assert all(isinstance(h, logging.NullHandler) for h in logger.handlers) +@pytest.mark.parametrize("value", ["VERBOSE", "\u00b2"]) # superscript two: isdigit() but not int()-parsable @pytest.mark.agent_authored(model="claude-opus-5") -def test_invalid_value_warns_and_stays_disabled(): +def test_invalid_value_warns_and_stays_disabled(value): with pytest.warns(UserWarning, match=ENV_VAR): - assert reload_with_env("VERBOSE").LOGGER is None + assert reload_with_env(value).LOGGER is None @pytest.mark.agent_authored(model="claude-opus-5")