From 12ed3dd6cbecfb42aedb85796a60be66babbec1e Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" Date: Tue, 28 Jul 2026 19:02:25 +0800 Subject: [PATCH 1/8] Hide benign ORT native warnings --- src/winml/modelkit/session/session.py | 64 +++++++++++++++------------ src/winml/modelkit/utils/logging.py | 41 +++++++++++++++++ tests/unit/utils/test_logging.py | 40 +++++++++++++++++ 3 files changed, 116 insertions(+), 29 deletions(-) diff --git a/src/winml/modelkit/session/session.py b/src/winml/modelkit/session/session.py index 52f4e301d..33d65e5e3 100644 --- a/src/winml/modelkit/session/session.py +++ b/src/winml/modelkit/session/session.py @@ -19,6 +19,7 @@ from ..core.onnx_utils import get_io_config from ..onnx import is_compiled_onnx +from ..utils.logging import suppress_noisy_ort_native_warnings from .ep_device import ( WinMLEPMonitorMismatch, expand_ep_name, @@ -353,7 +354,8 @@ def __init__( session_option_entries=self._active_session_option_entries, provider_options=self._provider_options, ) - self._session = ort.InferenceSession(self._onnx_path, sess_options=so) + with suppress_noisy_ort_native_warnings(): + self._session = ort.InferenceSession(self._onnx_path, sess_options=so) self._running_model_path = self._onnx_path _dev = self._ep_device.device logger.info( @@ -387,17 +389,18 @@ def compile(self) -> None: if not self._persist_jit: try: - session = ort.InferenceSession( - str(self._onnx_path), - sess_options=_build_session_options( - self._ep_device, - self._ep_config, - None, - self._session_options_factory, - session_option_entries=self._active_session_option_entries, - provider_options=self._provider_options, - ), - ) + with suppress_noisy_ort_native_warnings(): + session = ort.InferenceSession( + str(self._onnx_path), + sess_options=_build_session_options( + self._ep_device, + self._ep_config, + None, + self._session_options_factory, + session_option_entries=self._active_session_option_entries, + provider_options=self._provider_options, + ), + ) except Exception as e: self._state = SessionState.ERROR self._last_error = e @@ -468,7 +471,7 @@ def compile(self) -> None: session_option_entries=self._active_session_option_entries, provider_options=self._provider_options, ) - with _suppress_native_output(compile_log): + with _suppress_native_output(compile_log), suppress_noisy_ort_native_warnings(): session = ort.InferenceSession(str(model_path), sess_options=runtime_so) actual_providers = session.get_providers() @@ -859,17 +862,18 @@ def _restore_baseline() -> Exception | None: return None try: - self._session = ort.InferenceSession( - active_model_path, - sess_options=_build_session_options( - self._ep_device, - self._ep_config, - None, - self._session_options_factory, - session_option_entries=saved_sess_entries, - provider_options=saved_prov, - ), - ) + with suppress_noisy_ort_native_warnings(): + self._session = ort.InferenceSession( + active_model_path, + sess_options=_build_session_options( + self._ep_device, + self._ep_config, + None, + self._session_options_factory, + session_option_entries=saved_sess_entries, + provider_options=saved_prov, + ), + ) except Exception as error: self._session = None self._state = SessionState.ERROR @@ -893,7 +897,8 @@ def _restore_baseline() -> Exception | None: session_option_entries=desired_sess_entries, provider_options=new_prov, ) - self._session = ort.InferenceSession(active_model_path, sess_options=so) + with suppress_noisy_ort_native_warnings(): + self._session = ort.InferenceSession(active_model_path, sess_options=so) self._provider_options = new_prov self._active_session_option_entries = desired_sess_entries self._running_model_path = active_model_path @@ -1247,10 +1252,11 @@ def is_compatible( self._session_options_factory, ) sess_options.log_severity_level = 4 # Suppress ORT logs during probe - ort.InferenceSession( - test_model.SerializeToString(), - sess_options=sess_options, - ) + with suppress_noisy_ort_native_warnings(): + ort.InferenceSession( + test_model.SerializeToString(), + sess_options=sess_options, + ) return True except Exception: return False diff --git a/src/winml/modelkit/utils/logging.py b/src/winml/modelkit/utils/logging.py index 53d2e314b..4a3210c1b 100644 --- a/src/winml/modelkit/utils/logging.py +++ b/src/winml/modelkit/utils/logging.py @@ -29,6 +29,7 @@ import logging import os import sys +import tempfile from contextlib import contextmanager from typing import TYPE_CHECKING @@ -63,6 +64,11 @@ "transformers", ) _HUGGINGFACE_VERBOSITY_ENVS = ("TRANSFORMERS_VERBOSITY", "HF_HUB_VERBOSITY") +_NOISY_ORT_NATIVE_WARNING_MARKERS = ( + b"onnxruntime::VerifyEachNodeIsAssignedToAnEp", + b"Some nodes were not assigned to the preferred execution providers", + b"Rerunning with verbose output on a non-minimal build will show node assignments", +) def configure_logging( @@ -158,6 +164,41 @@ def suppress_huggingface_warning_logs( logging.getLogger(name).setLevel(level) +@contextmanager +def suppress_noisy_ort_native_warnings() -> "Iterator[None]": + """Hide known-benign ORT native stderr warnings while preserving other output.""" + if env_flag_enabled("WINMLCLI_SHOW_ALL_WARNINGS"): + yield + return + + old_stderr = os.dup(2) + try: + with tempfile.TemporaryFile() as captured_stderr: + os.dup2(captured_stderr.fileno(), 2) + try: + yield + finally: + os.dup2(old_stderr, 2) + captured_stderr.seek(0) + _write_all(old_stderr, _filter_noisy_ort_native_stderr(captured_stderr.read())) + finally: + os.close(old_stderr) + + +def _filter_noisy_ort_native_stderr(data: bytes) -> bytes: + return b"".join( + line + for line in data.splitlines(keepends=True) + if not any(marker in line for marker in _NOISY_ORT_NATIVE_WARNING_MARKERS) + ) + + +def _write_all(fd: int, data: bytes) -> None: + while data: + written = os.write(fd, data) + data = data[written:] + + def _normalize_verbosity(verbosity: int, verbose: bool) -> int: # Backward compat: bool verbose -> int, also handles count passthrough. if verbose and verbosity == 0: diff --git a/tests/unit/utils/test_logging.py b/tests/unit/utils/test_logging.py index a1313e274..97b99f4f3 100644 --- a/tests/unit/utils/test_logging.py +++ b/tests/unit/utils/test_logging.py @@ -16,6 +16,7 @@ _NOISY_LIBRARY_LOGGERS, configure_logging, suppress_huggingface_warning_logs, + suppress_noisy_ort_native_warnings, ) @@ -254,6 +255,45 @@ def test_huggingface_warning_context_restores_imported_library_verbosity(monkeyp assert hub_state.level == logging.INFO +def test_suppress_noisy_ort_native_warnings_filters_node_assignment_noise(capfd): + noisy_warning = ( + "2026-07-28 18:23:19.8172425 [W:onnxruntime:, session_state.cc:1327 " + "onnxruntime::VerifyEachNodeIsAssignedToAnEp] Some nodes were not assigned " + "to the preferred execution providers which may or may not have an negative " + "impact on performance. e.g. ORT explicitly assigns shape related ops to CPU " + "to improve perf.\n" + ) + useful_warning = ( + "2026-07-28 18:23:19.8172425 [W:onnxruntime:, qnn_backend_manager.cc:2026 " + "onnxruntime::qnn::QnnBackendManager::ExtractBackendProfilingInfo] " + "Won't output any profiling.\n" + ) + + with suppress_noisy_ort_native_warnings(): + os.write(2, noisy_warning.encode()) + os.write(2, useful_warning.encode()) + + stderr = capfd.readouterr().err + assert "VerifyEachNodeIsAssignedToAnEp" not in stderr + assert "Some nodes were not assigned" not in stderr + assert "QnnBackendManager::ExtractBackendProfilingInfo" in stderr + + +def test_show_all_warnings_env_reveals_noisy_ort_native_warnings(monkeypatch, capfd): + monkeypatch.setenv("WINMLCLI_SHOW_ALL_WARNINGS", "1") + noisy_warning = ( + "2026-07-28 18:23:19.8337349 [W:onnxruntime:, session_state.cc:1329 " + "onnxruntime::VerifyEachNodeIsAssignedToAnEp] Rerunning with verbose output " + "on a non-minimal build will show node assignments.\n" + ) + + with suppress_noisy_ort_native_warnings(): + os.write(2, noisy_warning.encode()) + + stderr = capfd.readouterr().err + assert "VerifyEachNodeIsAssignedToAnEp" in stderr + + def _install_fake_huggingface_logging( monkeypatch: pytest.MonkeyPatch, package_name: str, From f3b2bf82d5fa297835987b66ff97b9c87b883bbf Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" Date: Tue, 28 Jul 2026 19:08:50 +0800 Subject: [PATCH 2/8] Show native ORT warnings in verbose mode --- src/winml/modelkit/utils/logging.py | 8 +++++++- tests/unit/utils/test_logging.py | 16 ++++++++++++++++ 2 files changed, 23 insertions(+), 1 deletion(-) diff --git a/src/winml/modelkit/utils/logging.py b/src/winml/modelkit/utils/logging.py index 4a3210c1b..1317ecd6f 100644 --- a/src/winml/modelkit/utils/logging.py +++ b/src/winml/modelkit/utils/logging.py @@ -167,7 +167,7 @@ def suppress_huggingface_warning_logs( @contextmanager def suppress_noisy_ort_native_warnings() -> "Iterator[None]": """Hide known-benign ORT native stderr warnings while preserving other output.""" - if env_flag_enabled("WINMLCLI_SHOW_ALL_WARNINGS"): + if _show_all_warnings_requested(): yield return @@ -185,6 +185,12 @@ def suppress_noisy_ort_native_warnings() -> "Iterator[None]": os.close(old_stderr) +def _show_all_warnings_requested() -> bool: + return env_flag_enabled("WINMLCLI_SHOW_ALL_WARNINGS") or logging.getLogger().isEnabledFor( + logging.INFO + ) + + def _filter_noisy_ort_native_stderr(data: bytes) -> bytes: return b"".join( line diff --git a/tests/unit/utils/test_logging.py b/tests/unit/utils/test_logging.py index 97b99f4f3..b47c8e473 100644 --- a/tests/unit/utils/test_logging.py +++ b/tests/unit/utils/test_logging.py @@ -294,6 +294,22 @@ def test_show_all_warnings_env_reveals_noisy_ort_native_warnings(monkeypatch, ca assert "VerifyEachNodeIsAssignedToAnEp" in stderr +def test_verbose_logging_reveals_noisy_ort_native_warnings(monkeypatch, capfd): + monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) + configure_logging(verbosity=1) + noisy_warning = ( + "2026-07-28 18:23:19.8337349 [W:onnxruntime:, session_state.cc:1329 " + "onnxruntime::VerifyEachNodeIsAssignedToAnEp] Rerunning with verbose output " + "on a non-minimal build will show node assignments.\n" + ) + + with suppress_noisy_ort_native_warnings(): + os.write(2, noisy_warning.encode()) + + stderr = capfd.readouterr().err + assert "VerifyEachNodeIsAssignedToAnEp" in stderr + + def _install_fake_huggingface_logging( monkeypatch: pytest.MonkeyPatch, package_name: str, From 8aca08c78d550b800bc85cfb7484f2055562fa0f Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" Date: Tue, 28 Jul 2026 19:16:59 +0800 Subject: [PATCH 3/8] Cover Win32 native stderr filtering --- tests/unit/utils/test_logging.py | 51 ++++++++++++++++++++++++++++++++ 1 file changed, 51 insertions(+) diff --git a/tests/unit/utils/test_logging.py b/tests/unit/utils/test_logging.py index b47c8e473..50b9db882 100644 --- a/tests/unit/utils/test_logging.py +++ b/tests/unit/utils/test_logging.py @@ -4,6 +4,8 @@ # -------------------------------------------------------------------------- """Unit tests for configure_logging — third-party logger noise control.""" +import ctypes +import ctypes.wintypes import logging import os import sys @@ -310,6 +312,55 @@ def test_verbose_logging_reveals_noisy_ort_native_warnings(monkeypatch, capfd): assert "VerifyEachNodeIsAssignedToAnEp" in stderr +@pytest.mark.skipif(sys.platform != "win32", reason="Win32 native stderr only") +def test_suppress_noisy_ort_native_warnings_filters_win32_std_error_handle(capfd): + noisy_warning = ( + b"2026-07-28 18:23:19.8172425 [W:onnxruntime:, session_state.cc:1327 " + b"onnxruntime::VerifyEachNodeIsAssignedToAnEp] Some nodes were not assigned " + b"to the preferred execution providers.\n" + ) + useful_warning = ( + b"2026-07-28 18:23:19.8172425 [W:onnxruntime:, qnn_backend_manager.cc:2026 " + b"onnxruntime::qnn::QnnBackendManager::ExtractBackendProfilingInfo] " + b"Won't output any profiling.\n" + ) + + with suppress_noisy_ort_native_warnings(): + _write_win32_stderr(noisy_warning) + _write_win32_stderr(useful_warning) + + stderr = capfd.readouterr().err + assert "VerifyEachNodeIsAssignedToAnEp" not in stderr + assert "QnnBackendManager::ExtractBackendProfilingInfo" in stderr + + +def _write_win32_stderr(data: bytes) -> None: + k32 = ctypes.WinDLL("kernel32", use_last_error=True) + k32.GetStdHandle.argtypes = [ctypes.wintypes.DWORD] + k32.GetStdHandle.restype = ctypes.wintypes.HANDLE + k32.WriteFile.argtypes = [ + ctypes.wintypes.HANDLE, + ctypes.wintypes.LPCVOID, + ctypes.wintypes.DWORD, + ctypes.POINTER(ctypes.wintypes.DWORD), + ctypes.wintypes.LPVOID, + ] + k32.WriteFile.restype = ctypes.wintypes.BOOL + + std_error_handle = ctypes.wintypes.DWORD(0xFFFFFFF4) + written = ctypes.wintypes.DWORD(0) + buffer = ctypes.create_string_buffer(data) + ok = k32.WriteFile( + k32.GetStdHandle(std_error_handle), + buffer, + len(data), + ctypes.byref(written), + None, + ) + assert ok + assert written.value == len(data) + + def _install_fake_huggingface_logging( monkeypatch: pytest.MonkeyPatch, package_name: str, From 66233703d5c7e11118bf679cd359b6b9af1b9163 Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" Date: Wed, 29 Jul 2026 15:37:10 +0800 Subject: [PATCH 4/8] Use generic native warning suppression --- src/winml/modelkit/session/session.py | 14 +-- src/winml/modelkit/utils/logging.py | 47 ---------- src/winml/modelkit/utils/native_stderr.py | 71 ++++++++++++++ tests/unit/utils/test_logging.py | 107 ---------------------- tests/unit/utils/test_native_stderr.py | 87 ++++++++++++++++++ 5 files changed, 165 insertions(+), 161 deletions(-) diff --git a/src/winml/modelkit/session/session.py b/src/winml/modelkit/session/session.py index 33d65e5e3..2801bc189 100644 --- a/src/winml/modelkit/session/session.py +++ b/src/winml/modelkit/session/session.py @@ -19,7 +19,7 @@ from ..core.onnx_utils import get_io_config from ..onnx import is_compiled_onnx -from ..utils.logging import suppress_noisy_ort_native_warnings +from ..utils.native_stderr import suppress_native_warnings from .ep_device import ( WinMLEPMonitorMismatch, expand_ep_name, @@ -354,7 +354,7 @@ def __init__( session_option_entries=self._active_session_option_entries, provider_options=self._provider_options, ) - with suppress_noisy_ort_native_warnings(): + with suppress_native_warnings(): self._session = ort.InferenceSession(self._onnx_path, sess_options=so) self._running_model_path = self._onnx_path _dev = self._ep_device.device @@ -389,7 +389,7 @@ def compile(self) -> None: if not self._persist_jit: try: - with suppress_noisy_ort_native_warnings(): + with suppress_native_warnings(): session = ort.InferenceSession( str(self._onnx_path), sess_options=_build_session_options( @@ -471,7 +471,7 @@ def compile(self) -> None: session_option_entries=self._active_session_option_entries, provider_options=self._provider_options, ) - with _suppress_native_output(compile_log), suppress_noisy_ort_native_warnings(): + with _suppress_native_output(compile_log), suppress_native_warnings(): session = ort.InferenceSession(str(model_path), sess_options=runtime_so) actual_providers = session.get_providers() @@ -862,7 +862,7 @@ def _restore_baseline() -> Exception | None: return None try: - with suppress_noisy_ort_native_warnings(): + with suppress_native_warnings(): self._session = ort.InferenceSession( active_model_path, sess_options=_build_session_options( @@ -897,7 +897,7 @@ def _restore_baseline() -> Exception | None: session_option_entries=desired_sess_entries, provider_options=new_prov, ) - with suppress_noisy_ort_native_warnings(): + with suppress_native_warnings(): self._session = ort.InferenceSession(active_model_path, sess_options=so) self._provider_options = new_prov self._active_session_option_entries = desired_sess_entries @@ -1252,7 +1252,7 @@ def is_compatible( self._session_options_factory, ) sess_options.log_severity_level = 4 # Suppress ORT logs during probe - with suppress_noisy_ort_native_warnings(): + with suppress_native_warnings(): ort.InferenceSession( test_model.SerializeToString(), sess_options=sess_options, diff --git a/src/winml/modelkit/utils/logging.py b/src/winml/modelkit/utils/logging.py index 1317ecd6f..53d2e314b 100644 --- a/src/winml/modelkit/utils/logging.py +++ b/src/winml/modelkit/utils/logging.py @@ -29,7 +29,6 @@ import logging import os import sys -import tempfile from contextlib import contextmanager from typing import TYPE_CHECKING @@ -64,11 +63,6 @@ "transformers", ) _HUGGINGFACE_VERBOSITY_ENVS = ("TRANSFORMERS_VERBOSITY", "HF_HUB_VERBOSITY") -_NOISY_ORT_NATIVE_WARNING_MARKERS = ( - b"onnxruntime::VerifyEachNodeIsAssignedToAnEp", - b"Some nodes were not assigned to the preferred execution providers", - b"Rerunning with verbose output on a non-minimal build will show node assignments", -) def configure_logging( @@ -164,47 +158,6 @@ def suppress_huggingface_warning_logs( logging.getLogger(name).setLevel(level) -@contextmanager -def suppress_noisy_ort_native_warnings() -> "Iterator[None]": - """Hide known-benign ORT native stderr warnings while preserving other output.""" - if _show_all_warnings_requested(): - yield - return - - old_stderr = os.dup(2) - try: - with tempfile.TemporaryFile() as captured_stderr: - os.dup2(captured_stderr.fileno(), 2) - try: - yield - finally: - os.dup2(old_stderr, 2) - captured_stderr.seek(0) - _write_all(old_stderr, _filter_noisy_ort_native_stderr(captured_stderr.read())) - finally: - os.close(old_stderr) - - -def _show_all_warnings_requested() -> bool: - return env_flag_enabled("WINMLCLI_SHOW_ALL_WARNINGS") or logging.getLogger().isEnabledFor( - logging.INFO - ) - - -def _filter_noisy_ort_native_stderr(data: bytes) -> bytes: - return b"".join( - line - for line in data.splitlines(keepends=True) - if not any(marker in line for marker in _NOISY_ORT_NATIVE_WARNING_MARKERS) - ) - - -def _write_all(fd: int, data: bytes) -> None: - while data: - written = os.write(fd, data) - data = data[written:] - - def _normalize_verbosity(verbosity: int, verbose: bool) -> int: # Backward compat: bool verbose -> int, also handles count passthrough. if verbose and verbosity == 0: diff --git a/src/winml/modelkit/utils/native_stderr.py b/src/winml/modelkit/utils/native_stderr.py index 7e175e25e..bb4e7bff2 100644 --- a/src/winml/modelkit/utils/native_stderr.py +++ b/src/winml/modelkit/utils/native_stderr.py @@ -20,16 +20,20 @@ import os import re import sys +import tempfile import threading from contextlib import contextmanager from typing import TYPE_CHECKING +from .._env import env_flag_enabled + if TYPE_CHECKING: from collections.abc import Iterator logger = logging.getLogger(__name__) +_NATIVE_WARNING_LINE_RE = re.compile(rb"\[[Ww]:") # --------------------------------------------------------------------------- # Win32 kernel32 (configured once) @@ -127,3 +131,70 @@ def _drain() -> None: line = _ansi_re.sub("", raw).strip() if line: logger.log(level, "[ORT] %s", line) + + +@contextmanager +def suppress_native_warnings(*, enabled: bool = True) -> Iterator[None]: + """Hide native warning lines while preserving native errors and diagnostics. + + Native ORT/QNN diagnostics use severity tokens such as ``[W:...]`` and + ``[E:...]``. Normal CLI output hides warning-level native chatter; ``-v`` / + ``-vv`` or ``WINMLCLI_SHOW_ALL_WARNINGS=1`` leaves stderr untouched. + """ + if not enabled or _show_native_warnings_requested(): + yield + return + + old_fd = os.dup(2) + old_w32 = _get_win32_stderr_handle() + try: + with tempfile.TemporaryFile() as captured: + os.dup2(captured.fileno(), 2) + _set_win32_stderr_to_current_fd() + try: + yield + finally: + os.dup2(old_fd, 2) + _restore_win32_stderr_handle(old_w32) + captured.seek(0) + _write_all(old_fd, _filter_native_warning_stderr(captured.read())) + finally: + os.close(old_fd) + + +def _show_native_warnings_requested() -> bool: + return env_flag_enabled("WINMLCLI_SHOW_ALL_WARNINGS") or logging.getLogger().isEnabledFor( + logging.INFO + ) + + +def _filter_native_warning_stderr(data: bytes) -> bytes: + return b"".join( + line for line in data.splitlines(keepends=True) if not _is_native_warning_line(line) + ) + + +def _is_native_warning_line(line: bytes) -> bool: + return bool(_NATIVE_WARNING_LINE_RE.search(line)) + + +def _get_win32_stderr_handle() -> object | None: + if sys.platform != "win32": + return None + return _k32.GetStdHandle(_STD_ERROR_HANDLE) + + +def _set_win32_stderr_to_current_fd() -> None: + if sys.platform == "win32": + _k32.SetStdHandle(_STD_ERROR_HANDLE, msvcrt.get_osfhandle(2)) + + +def _restore_win32_stderr_handle(handle: object | None) -> None: + if sys.platform == "win32" and handle is not None: + _k32.SetStdHandle(_STD_ERROR_HANDLE, handle) + + +def _write_all(fd: int, data: bytes) -> None: + while data: + written = os.write(fd, data) + data = data[written:] diff --git a/tests/unit/utils/test_logging.py b/tests/unit/utils/test_logging.py index 50b9db882..a1313e274 100644 --- a/tests/unit/utils/test_logging.py +++ b/tests/unit/utils/test_logging.py @@ -4,8 +4,6 @@ # -------------------------------------------------------------------------- """Unit tests for configure_logging — third-party logger noise control.""" -import ctypes -import ctypes.wintypes import logging import os import sys @@ -18,7 +16,6 @@ _NOISY_LIBRARY_LOGGERS, configure_logging, suppress_huggingface_warning_logs, - suppress_noisy_ort_native_warnings, ) @@ -257,110 +254,6 @@ def test_huggingface_warning_context_restores_imported_library_verbosity(monkeyp assert hub_state.level == logging.INFO -def test_suppress_noisy_ort_native_warnings_filters_node_assignment_noise(capfd): - noisy_warning = ( - "2026-07-28 18:23:19.8172425 [W:onnxruntime:, session_state.cc:1327 " - "onnxruntime::VerifyEachNodeIsAssignedToAnEp] Some nodes were not assigned " - "to the preferred execution providers which may or may not have an negative " - "impact on performance. e.g. ORT explicitly assigns shape related ops to CPU " - "to improve perf.\n" - ) - useful_warning = ( - "2026-07-28 18:23:19.8172425 [W:onnxruntime:, qnn_backend_manager.cc:2026 " - "onnxruntime::qnn::QnnBackendManager::ExtractBackendProfilingInfo] " - "Won't output any profiling.\n" - ) - - with suppress_noisy_ort_native_warnings(): - os.write(2, noisy_warning.encode()) - os.write(2, useful_warning.encode()) - - stderr = capfd.readouterr().err - assert "VerifyEachNodeIsAssignedToAnEp" not in stderr - assert "Some nodes were not assigned" not in stderr - assert "QnnBackendManager::ExtractBackendProfilingInfo" in stderr - - -def test_show_all_warnings_env_reveals_noisy_ort_native_warnings(monkeypatch, capfd): - monkeypatch.setenv("WINMLCLI_SHOW_ALL_WARNINGS", "1") - noisy_warning = ( - "2026-07-28 18:23:19.8337349 [W:onnxruntime:, session_state.cc:1329 " - "onnxruntime::VerifyEachNodeIsAssignedToAnEp] Rerunning with verbose output " - "on a non-minimal build will show node assignments.\n" - ) - - with suppress_noisy_ort_native_warnings(): - os.write(2, noisy_warning.encode()) - - stderr = capfd.readouterr().err - assert "VerifyEachNodeIsAssignedToAnEp" in stderr - - -def test_verbose_logging_reveals_noisy_ort_native_warnings(monkeypatch, capfd): - monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) - configure_logging(verbosity=1) - noisy_warning = ( - "2026-07-28 18:23:19.8337349 [W:onnxruntime:, session_state.cc:1329 " - "onnxruntime::VerifyEachNodeIsAssignedToAnEp] Rerunning with verbose output " - "on a non-minimal build will show node assignments.\n" - ) - - with suppress_noisy_ort_native_warnings(): - os.write(2, noisy_warning.encode()) - - stderr = capfd.readouterr().err - assert "VerifyEachNodeIsAssignedToAnEp" in stderr - - -@pytest.mark.skipif(sys.platform != "win32", reason="Win32 native stderr only") -def test_suppress_noisy_ort_native_warnings_filters_win32_std_error_handle(capfd): - noisy_warning = ( - b"2026-07-28 18:23:19.8172425 [W:onnxruntime:, session_state.cc:1327 " - b"onnxruntime::VerifyEachNodeIsAssignedToAnEp] Some nodes were not assigned " - b"to the preferred execution providers.\n" - ) - useful_warning = ( - b"2026-07-28 18:23:19.8172425 [W:onnxruntime:, qnn_backend_manager.cc:2026 " - b"onnxruntime::qnn::QnnBackendManager::ExtractBackendProfilingInfo] " - b"Won't output any profiling.\n" - ) - - with suppress_noisy_ort_native_warnings(): - _write_win32_stderr(noisy_warning) - _write_win32_stderr(useful_warning) - - stderr = capfd.readouterr().err - assert "VerifyEachNodeIsAssignedToAnEp" not in stderr - assert "QnnBackendManager::ExtractBackendProfilingInfo" in stderr - - -def _write_win32_stderr(data: bytes) -> None: - k32 = ctypes.WinDLL("kernel32", use_last_error=True) - k32.GetStdHandle.argtypes = [ctypes.wintypes.DWORD] - k32.GetStdHandle.restype = ctypes.wintypes.HANDLE - k32.WriteFile.argtypes = [ - ctypes.wintypes.HANDLE, - ctypes.wintypes.LPCVOID, - ctypes.wintypes.DWORD, - ctypes.POINTER(ctypes.wintypes.DWORD), - ctypes.wintypes.LPVOID, - ] - k32.WriteFile.restype = ctypes.wintypes.BOOL - - std_error_handle = ctypes.wintypes.DWORD(0xFFFFFFF4) - written = ctypes.wintypes.DWORD(0) - buffer = ctypes.create_string_buffer(data) - ok = k32.WriteFile( - k32.GetStdHandle(std_error_handle), - buffer, - len(data), - ctypes.byref(written), - None, - ) - assert ok - assert written.value == len(data) - - def _install_fake_huggingface_logging( monkeypatch: pytest.MonkeyPatch, package_name: str, diff --git a/tests/unit/utils/test_native_stderr.py b/tests/unit/utils/test_native_stderr.py index de1dc3141..292e8469b 100644 --- a/tests/unit/utils/test_native_stderr.py +++ b/tests/unit/utils/test_native_stderr.py @@ -12,12 +12,21 @@ import pytest +from winml.modelkit.utils import native_stderr as native_stderr_module from winml.modelkit.utils.native_stderr import ( capture_native_stderr, suppress_native_stderr, ) +@pytest.fixture(autouse=True) +def _restore_root_logger_level(): + root = logging.getLogger() + level = root.level + yield + root.setLevel(level) + + class TestSuppressNativeStderr: """Tests for suppress_native_stderr (devnull-based).""" @@ -120,3 +129,81 @@ def test_no_deadlock_on_large_output(self, caplog): # a no-op. Either way the point is that the loop above did not deadlock. if sys.platform == "win32": assert any("partitioning subgraph" in r.message for r in caplog.records) + + +class TestSuppressNativeWarnings: + """Tests for warning-only native stderr suppression.""" + + def test_filters_native_warning_lines_and_preserves_errors(self, monkeypatch, capfd): + monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) + logging.getLogger().setLevel(logging.WARNING) + + with native_stderr_module.suppress_native_warnings(): + os.write(2, b"2026 [W:custom-native:, file.cc:1 WarningFunc] noisy warning\n") + os.write(2, b"2026 [E:onnxruntime:, qnn_backend.cc:2 ErrorFunc] useful error\n") + os.write(2, b"plain diagnostic\n") + + stderr = capfd.readouterr().err + assert "noisy warning" not in stderr + assert "useful error" in stderr + assert "plain diagnostic" in stderr + + def test_verbose_logging_leaves_native_warnings_visible(self, monkeypatch, capfd): + monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) + logging.getLogger().setLevel(logging.INFO) + + with native_stderr_module.suppress_native_warnings(): + os.write(2, b"2026 [W:custom-native:, file.cc:1 WarningFunc] visible warning\n") + + assert "visible warning" in capfd.readouterr().err + + def test_show_all_warnings_env_leaves_native_warnings_visible(self, monkeypatch, capfd): + monkeypatch.setenv("WINMLCLI_SHOW_ALL_WARNINGS", "1") + logging.getLogger().setLevel(logging.WARNING) + + with native_stderr_module.suppress_native_warnings(): + os.write(2, b"2026 [W:custom-native:, file.cc:1 WarningFunc] env warning\n") + + assert "env warning" in capfd.readouterr().err + + @pytest.mark.skipif(sys.platform != "win32", reason="Win32 native stderr only") + def test_filters_win32_std_error_handle_warning(self, monkeypatch, capfd): + monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) + logging.getLogger().setLevel(logging.WARNING) + + with native_stderr_module.suppress_native_warnings(): + _write_win32_stderr(b"2026 [W:custom-native:, file.cc:1 WarningFunc] win32 warning\n") + _write_win32_stderr(b"2026 [E:custom-native:, file.cc:2 ErrorFunc] win32 error\n") + + stderr = capfd.readouterr().err + assert "win32 warning" not in stderr + assert "win32 error" in stderr + + +def _write_win32_stderr(data: bytes) -> None: + import ctypes.wintypes + + k32 = ctypes.WinDLL("kernel32", use_last_error=True) + k32.GetStdHandle.argtypes = [ctypes.wintypes.DWORD] + k32.GetStdHandle.restype = ctypes.wintypes.HANDLE + k32.WriteFile.argtypes = [ + ctypes.wintypes.HANDLE, + ctypes.wintypes.LPCVOID, + ctypes.wintypes.DWORD, + ctypes.POINTER(ctypes.wintypes.DWORD), + ctypes.wintypes.LPVOID, + ] + k32.WriteFile.restype = ctypes.wintypes.BOOL + + std_error_handle = ctypes.wintypes.DWORD(0xFFFFFFF4) + written = ctypes.wintypes.DWORD(0) + buffer = ctypes.create_string_buffer(data) + ok = k32.WriteFile( + k32.GetStdHandle(std_error_handle), + buffer, + len(data), + ctypes.byref(written), + None, + ) + assert ok + assert written.value == len(data) From 7bd7d996f01b3310304175b7bf2fdc56add5491b Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" Date: Wed, 29 Jul 2026 15:46:25 +0800 Subject: [PATCH 5/8] Apply native warning suppression broadly --- .../analyze/runtime_checker/ep_checker.py | 20 ++--- src/winml/modelkit/compiler/stages/compile.py | 4 +- .../eval/mask_generation_evaluator.py | 26 +++--- src/winml/modelkit/optim/pipes/graph.py | 8 +- .../pattern/op_input_gen/op_input_gen.py | 13 +-- .../modelkit/session/qairt/qairt_session.py | 4 +- src/winml/modelkit/utils/native_stderr.py | 68 +++++++++++----- tests/unit/utils/test_native_stderr.py | 79 +++++++++++++++++++ 8 files changed, 168 insertions(+), 54 deletions(-) diff --git a/src/winml/modelkit/analyze/runtime_checker/ep_checker.py b/src/winml/modelkit/analyze/runtime_checker/ep_checker.py index 94ab82d42..efd6b9ccc 100644 --- a/src/winml/modelkit/analyze/runtime_checker/ep_checker.py +++ b/src/winml/modelkit/analyze/runtime_checker/ep_checker.py @@ -11,6 +11,8 @@ import onnx import onnxruntime as ort +from ...utils.native_stderr import suppress_native_warnings + if TYPE_CHECKING: from collections.abc import Sequence @@ -31,8 +33,7 @@ class _RulesPrefilterProtocol(Protocol): def build_skip_check_result_for_rules_all_nodes_compile_run_pass( self, onnx_model: onnx.ModelProto, - ) -> dict[str, Any] | None: - ... + ) -> dict[str, Any] | None: ... class EPChecker: @@ -46,9 +47,7 @@ class EPChecker: # EP/device combinations that are known to leak resources/state across many # sequential checks inside a single worker process. Running each case in an # isolated process avoids "first case passes, later cases fail" behavior. - EPS_REQUIRING_CASE_ISOLATION_BY_DEVICE: ClassVar[ - dict[str, set[ort.OrtHardwareDeviceType]] - ] = { + EPS_REQUIRING_CASE_ISOLATION_BY_DEVICE: ClassVar[dict[str, set[ort.OrtHardwareDeviceType]]] = { "OpenVINOExecutionProvider": {ort.OrtHardwareDeviceType.NPU}, } @@ -176,11 +175,12 @@ def check_run( input_args: dict[str, Any], ) -> dict[str, Any]: """Test model execution with execution provider.""" - session = ort.InferenceSession( - path_or_bytes, - self._get_sess_options(), - provider_options=self._provider_options, - ) + with suppress_native_warnings(): + session = ort.InferenceSession( + path_or_bytes, + self._get_sess_options(), + provider_options=self._provider_options, + ) # inputs = self._generate_inputs(session) graph_input_names = {inp.name for inp in session.get_inputs()} inputs = {k: v for k, v in input_args.items() if k in graph_input_names} diff --git a/src/winml/modelkit/compiler/stages/compile.py b/src/winml/modelkit/compiler/stages/compile.py index d877867ea..781fe2814 100644 --- a/src/winml/modelkit/compiler/stages/compile.py +++ b/src/winml/modelkit/compiler/stages/compile.py @@ -25,6 +25,7 @@ resolve_device, ) from ...utils.constants import ORT_SESSION_COMPILER +from ...utils.native_stderr import suppress_native_warnings from ..configs import WinMLCompileConfig from .base import BaseStage @@ -173,7 +174,8 @@ def _compile_shared_context(self, context: CompileContext) -> None: if context.use_inference_session: session_options.add_session_config_entry("ep.context_file_path", str(ctx_path)) - session = ort.InferenceSession(str(model_path), sess_options=session_options) + with suppress_native_warnings(): + session = ort.InferenceSession(str(model_path), sess_options=session_options) try: context.session = session context.log(f"Actual providers: {session.get_providers()}") diff --git a/src/winml/modelkit/eval/mask_generation_evaluator.py b/src/winml/modelkit/eval/mask_generation_evaluator.py index 0f5684f9e..c73b30c5d 100644 --- a/src/winml/modelkit/eval/mask_generation_evaluator.py +++ b/src/winml/modelkit/eval/mask_generation_evaluator.py @@ -44,6 +44,7 @@ import numpy as np +from ..utils.native_stderr import suppress_native_warnings from .base_evaluator import WinMLEvaluator @@ -294,18 +295,19 @@ def _load_sessions(self) -> tuple[Any, Any]: sess_opts = ort.SessionOptions() sess_opts.graph_optimization_level = ort.GraphOptimizationLevel.ORT_DISABLE_ALL - enc = ort.InferenceSession( - paths[self._ENCODER_ROLE], - sess_options=sess_opts, - providers=providers, - provider_options=provider_options, - ) - dec = ort.InferenceSession( - paths[self._DECODER_ROLE], - sess_options=sess_opts, - providers=providers, - provider_options=provider_options, - ) + with suppress_native_warnings(): + enc = ort.InferenceSession( + paths[self._ENCODER_ROLE], + sess_options=sess_opts, + providers=providers, + provider_options=provider_options, + ) + dec = ort.InferenceSession( + paths[self._DECODER_ROLE], + sess_options=sess_opts, + providers=providers, + provider_options=provider_options, + ) logger.info(" encoder providers: %s", enc.get_providers()) logger.info(" decoder providers: %s", dec.get_providers()) return enc, dec diff --git a/src/winml/modelkit/optim/pipes/graph.py b/src/winml/modelkit/optim/pipes/graph.py index 853cdb9ee..cd0e7e184 100644 --- a/src/winml/modelkit/optim/pipes/graph.py +++ b/src/winml/modelkit/optim/pipes/graph.py @@ -20,6 +20,7 @@ from typing import TYPE_CHECKING, Any, ClassVar from ...onnx import load_onnx, save_onnx +from ...utils.native_stderr import suppress_native_warnings from .base import BasePipe, OptimizationError, PipeConfig, caps_dict @@ -568,9 +569,10 @@ def process(self, model: onnx.ModelProto, config: ORTGraphPipeConfig) -> onnx.Mo # Create session to trigger optimization try: - _ = ort.InferenceSession( - str(input_file), sess_opts, providers=["CPUExecutionProvider"] - ) + with suppress_native_warnings(): + _ = ort.InferenceSession( + str(input_file), sess_opts, providers=["CPUExecutionProvider"] + ) except Exception as e: raise OptimizationError( f"ONNX Runtime optimization failed: {e}", diff --git a/src/winml/modelkit/pattern/op_input_gen/op_input_gen.py b/src/winml/modelkit/pattern/op_input_gen/op_input_gen.py index d3d975463..c2aadf9c1 100644 --- a/src/winml/modelkit/pattern/op_input_gen/op_input_gen.py +++ b/src/winml/modelkit/pattern/op_input_gen/op_input_gen.py @@ -21,6 +21,7 @@ from onnx.defs import OpSchema from ...onnx import ONNXDomain, SupportedONNXType +from ...utils.native_stderr import suppress_native_warnings from ...utils.result_sanitizer import sanitize_check_result_payload from ..utils import get_op_input_properties from .qdq_gen import QDQGenerator @@ -1542,6 +1543,7 @@ def check_on_ep( isolate_case_execution = ep_checker.needs_case_isolation() with ResilientRunner(capture_output=capture_output, timeout_sec=60) as runner: + def _run_ep_check( fn: Callable[[Any, Any], dict[str, Any]], model_bytes: bytes, @@ -1663,9 +1665,7 @@ def _dry_run_result() -> dict[str, Any]: f"all<{compile_count['all']}>" f"{Style.RESET_ALL}" ) - if ( - not compile_success and save_failed_model - ) or save_model: + if (not compile_success and save_failed_model) or save_model: if save_dir is None: save_dir = ( Path(model_output_dir) @@ -1918,9 +1918,10 @@ def _run_op_on_cpu(self, kwargs: dict[str, Any], tags: dict[str, Any]) -> Any: model = self._create_model(kwargs, is_constant_map, output_dtypes, qdq_types=qdq_types) # Create inference session - sess = ort.InferenceSession( - model.SerializeToString(), - ) + with suppress_native_warnings(): + sess = ort.InferenceSession( + model.SerializeToString(), + ) input_dict = {k: v for k, v in kwargs.items() if k not in self.op_attribute_names} input_dict = self.create_input_dict(input_dict, qdq_types=qdq_types) diff --git a/src/winml/modelkit/session/qairt/qairt_session.py b/src/winml/modelkit/session/qairt/qairt_session.py index 5fb280151..0ab80ac8c 100644 --- a/src/winml/modelkit/session/qairt/qairt_session.py +++ b/src/winml/modelkit/session/qairt/qairt_session.py @@ -13,6 +13,7 @@ from pathlib import Path from typing import TYPE_CHECKING, Any +from ...utils.native_stderr import suppress_native_warnings from ...utils.python_env import ensure_venv from .. import EPDeviceTarget, WinMLEPDevice, WinMLEPRegistry, resolve_device from ..session import SessionState, WinMLSession @@ -255,7 +256,8 @@ def _create_inference_session(self) -> None: None, self._session_options_factory, ) - self._session = ort.InferenceSession(str(self._ctx_path), sess_options=sess_options) + with suppress_native_warnings(): + self._session = ort.InferenceSession(str(self._ctx_path), sess_options=sess_options) # Record the loaded model only after the session is successfully # created, so a failed load leaves running_model_path unset. self._running_model_path = self._ctx_path diff --git a/src/winml/modelkit/utils/native_stderr.py b/src/winml/modelkit/utils/native_stderr.py index bb4e7bff2..738524f30 100644 --- a/src/winml/modelkit/utils/native_stderr.py +++ b/src/winml/modelkit/utils/native_stderr.py @@ -2,16 +2,18 @@ # Copyright (c) Microsoft Corporation. All rights reserved. # Licensed under the MIT License. # -------------------------------------------------------------------------- -"""Redirect native stderr written by ORT / QNN on Windows. +"""Redirect/filter native stderr written by ORT / QNN. ORT's native code writes diagnostics (e.g. "Init provider bridge failed.") directly to fd 2 / Win32 STD_ERROR_HANDLE, bypassing Python logging. -Two context managers are provided: +Three context managers are provided: * ``suppress_native_stderr`` - discard to devnull (startup noise) * ``capture_native_stderr`` - capture via pipe and re-log (compilation output) +* ``suppress_native_warnings`` - hide warning lines, replay everything else -Both are no-ops on non-Windows. +The first two are no-ops on non-Windows. ``suppress_native_warnings`` works via +fd 2 on all platforms and also keeps the Win32 stderr handle in sync on Windows. """ from __future__ import annotations @@ -20,7 +22,6 @@ import os import re import sys -import tempfile import threading from contextlib import contextmanager from typing import TYPE_CHECKING @@ -33,7 +34,7 @@ logger = logging.getLogger(__name__) -_NATIVE_WARNING_LINE_RE = re.compile(rb"\[[Ww]:") +_NATIVE_SEVERITY_TOKEN_RE = re.compile(rb"\[([A-Za-z]):") # --------------------------------------------------------------------------- # Win32 kernel32 (configured once) @@ -145,19 +146,26 @@ def suppress_native_warnings(*, enabled: bool = True) -> Iterator[None]: yield return + read_fd, write_fd = os.pipe() old_fd = os.dup(2) old_w32 = _get_win32_stderr_handle() + reader = threading.Thread( + target=_drain_filtered_native_stderr, + args=(read_fd, old_fd), + name="suppress-native-warnings", + daemon=True, + ) try: - with tempfile.TemporaryFile() as captured: - os.dup2(captured.fileno(), 2) - _set_win32_stderr_to_current_fd() - try: - yield - finally: - os.dup2(old_fd, 2) - _restore_win32_stderr_handle(old_w32) - captured.seek(0) - _write_all(old_fd, _filter_native_warning_stderr(captured.read())) + os.dup2(write_fd, 2) + os.close(write_fd) + _set_win32_stderr_to_current_fd() + reader.start() + try: + yield + finally: + os.dup2(old_fd, 2) + _restore_win32_stderr_handle(old_w32) + reader.join() finally: os.close(old_fd) @@ -168,14 +176,32 @@ def _show_native_warnings_requested() -> bool: ) -def _filter_native_warning_stderr(data: bytes) -> bytes: - return b"".join( - line for line in data.splitlines(keepends=True) if not _is_native_warning_line(line) - ) +def _drain_filtered_native_stderr(read_fd: int, target_fd: int) -> None: + pending = b"" + try: + while chunk := os.read(read_fd, 4096): + pending += chunk + while b"\n" in pending: + line, pending = pending.split(b"\n", 1) + _write_non_warning_line(target_fd, line + b"\n") + if pending: + _write_non_warning_line(target_fd, pending) + except OSError: + pass + finally: + os.close(read_fd) + + +def _write_non_warning_line(fd: int, line: bytes) -> None: + if not _is_native_warning_line(line): + _write_all(fd, line) def _is_native_warning_line(line: bytes) -> bool: - return bool(_NATIVE_WARNING_LINE_RE.search(line)) + match = _NATIVE_SEVERITY_TOKEN_RE.search(line) + if match is None: + return False + return match.group(1).lower() == b"w" def _get_win32_stderr_handle() -> object | None: @@ -190,7 +216,7 @@ def _set_win32_stderr_to_current_fd() -> None: def _restore_win32_stderr_handle(handle: object | None) -> None: - if sys.platform == "win32" and handle is not None: + if sys.platform == "win32": _k32.SetStdHandle(_STD_ERROR_HANDLE, handle) diff --git a/tests/unit/utils/test_native_stderr.py b/tests/unit/utils/test_native_stderr.py index 292e8469b..39b9b1a3c 100644 --- a/tests/unit/utils/test_native_stderr.py +++ b/tests/unit/utils/test_native_stderr.py @@ -148,6 +148,18 @@ def test_filters_native_warning_lines_and_preserves_errors(self, monkeypatch, ca assert "useful error" in stderr assert "plain diagnostic" in stderr + def test_preserves_error_lines_that_reference_warning_tokens(self, monkeypatch, capfd): + monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) + logging.getLogger().setLevel(logging.WARNING) + + with native_stderr_module.suppress_native_warnings(): + os.write( + 2, + b"2026 [E:onnxruntime:, qnn.cc:2 ErrorFunc] failed after previous [W:note]\n", + ) + + assert "failed after previous [W:note]" in capfd.readouterr().err + def test_verbose_logging_leaves_native_warnings_visible(self, monkeypatch, capfd): monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) logging.getLogger().setLevel(logging.INFO) @@ -179,6 +191,64 @@ def test_filters_win32_std_error_handle_warning(self, monkeypatch, capfd): assert "win32 warning" not in stderr assert "win32 error" in stderr + @pytest.mark.skipif(sys.platform != "win32", reason="Win32 native stderr only") + def test_restores_win32_std_error_handle_after_exception(self, monkeypatch): + monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) + logging.getLogger().setLevel(logging.WARNING) + + before = _get_win32_stderr_handle() + with ( + pytest.raises(RuntimeError, match="boom"), + native_stderr_module.suppress_native_warnings(), + ): + raise RuntimeError("boom") + + assert _get_win32_stderr_handle() == before + + def test_restore_win32_std_error_handle_accepts_null_handle(self, monkeypatch): + calls = [] + std_error_handle = object() + + class FakeKernel32: + def __init__(self) -> None: + self.SetStdHandle = self._set_std_handle + + def _set_std_handle(self, handle_kind: object, handle: object | None) -> bool: + calls.append((handle_kind, handle)) + return True + + monkeypatch.setattr(native_stderr_module.sys, "platform", "win32") + monkeypatch.setattr(native_stderr_module, "_k32", FakeKernel32(), raising=False) + monkeypatch.setattr( + native_stderr_module, + "_STD_ERROR_HANDLE", + std_error_handle, + raising=False, + ) + + native_stderr_module._restore_win32_stderr_handle(None) + + assert calls == [(std_error_handle, None)] + + @pytest.mark.timeout(30) + def test_no_deadlock_on_large_warning_output(self, monkeypatch, capfd): + monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) + logging.getLogger().setLevel(logging.WARNING) + warning_line = b"2026 [W:custom-native:, file.cc:1 WarningFunc] noisy warning\n" + error_line = b"2026 [E:custom-native:, file.cc:2 ErrorFunc] useful error\n" + written = 0 + + with native_stderr_module.suppress_native_warnings(): + for _ in range(20000): + os.write(2, warning_line) + written += len(warning_line) + os.write(2, error_line) + + assert written > 64 * 1024 + stderr = capfd.readouterr().err + assert "noisy warning" not in stderr + assert "useful error" in stderr + def _write_win32_stderr(data: bytes) -> None: import ctypes.wintypes @@ -207,3 +277,12 @@ def _write_win32_stderr(data: bytes) -> None: ) assert ok assert written.value == len(data) + + +def _get_win32_stderr_handle() -> int: + import ctypes.wintypes + + k32 = ctypes.WinDLL("kernel32", use_last_error=True) + k32.GetStdHandle.argtypes = [ctypes.wintypes.DWORD] + k32.GetStdHandle.restype = ctypes.wintypes.HANDLE + return k32.GetStdHandle(ctypes.wintypes.DWORD(0xFFFFFFF4)) From acebf38fcdd43688a93b70442dedfc6fa758be4a Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" Date: Wed, 29 Jul 2026 17:25:33 +0800 Subject: [PATCH 6/8] Hide noisy perf warnings by default Suppress native warning-level diagnostics and Hugging Face warning chatter in normal CLI output while preserving verbose diagnostics. Avoid import-time ORT startup warnings and repair Windows console handles after native stream redirection. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- src/winml/modelkit/commands/_ep_arg.py | 2 +- src/winml/modelkit/commands/_live_chart.py | 54 ++++- src/winml/modelkit/commands/perf.py | 24 +- src/winml/modelkit/ep_path.py | 16 +- src/winml/modelkit/session/ep_device.py | 17 +- src/winml/modelkit/session/session.py | 37 ++- src/winml/modelkit/utils/logging.py | 17 +- src/winml/modelkit/utils/native_stderr.py | 138 +++++++++-- tests/unit/commands/test_ep_arg.py | 2 +- tests/unit/commands/test_ep_arg_imports.py | 36 +++ tests/unit/commands/test_perf_cli.py | 261 +++++++++++++++++++++ tests/unit/session/test_ep_monitor.py | 55 +++++ tests/unit/session/test_perf_auto_reset.py | 140 ++++++++++- tests/unit/utils/test_native_stderr.py | 93 ++++++-- 14 files changed, 811 insertions(+), 81 deletions(-) create mode 100644 tests/unit/commands/test_ep_arg_imports.py diff --git a/src/winml/modelkit/commands/_ep_arg.py b/src/winml/modelkit/commands/_ep_arg.py index d5309c393..409e88d31 100644 --- a/src/winml/modelkit/commands/_ep_arg.py +++ b/src/winml/modelkit/commands/_ep_arg.py @@ -17,7 +17,7 @@ import click -from ..session import VALID_SOURCE_TAGS +from ..ep_path import VALID_SOURCE_TAGS def split_ep_at_source(value: str) -> tuple[str, str | None]: diff --git a/src/winml/modelkit/commands/_live_chart.py b/src/winml/modelkit/commands/_live_chart.py index d46fcaa15..cf91931aa 100644 --- a/src/winml/modelkit/commands/_live_chart.py +++ b/src/winml/modelkit/commands/_live_chart.py @@ -25,6 +25,9 @@ # Display refresh rate (frames per second) _REFRESH_FPS = 5 +_PANEL_HORIZONTAL_OVERHEAD = 4 +_PLOTEXT_HORIZONTAL_OVERHEAD = 21 +_MIN_CHART_WIDTH = 20 class _OmittedDeviceKind: @@ -97,9 +100,43 @@ def __init__( self._chart_height = chart_height self._poll_interval_s = poll_interval_ms / 1000.0 self._live: Any = None + self._console: Console | None = None # Track the last rendered panel for transient=False final display self._last_panel: Any = None + def _panel_content_width(self) -> int | None: + """Return the Rich panel content width available in the current console.""" + width = getattr(self._console, "width", None) + if not isinstance(width, int) or width <= _PANEL_HORIZONTAL_OVERHEAD: + return None + return width - _PANEL_HORIZONTAL_OVERHEAD + + def _effective_chart_width(self) -> int: + """Clamp plotext's canvas width so its full output fits in the panel.""" + content_width = self._panel_content_width() + if content_width is None: + return self._chart_width + available_chart_width = content_width - _PLOTEXT_HORIZONTAL_OVERHEAD + return min(self._chart_width, max(_MIN_CHART_WIDTH, available_chart_width)) + + def _pack_status_cells(self, cells: list[str]) -> list[str]: + """Pack status cells into as few panel-safe lines as possible.""" + if not cells: + return [] + max_width = self._panel_content_width() + separator = " | " + lines: list[str] = [] + current = f" {cells[0]}" + for cell in cells[1:]: + candidate = f"{current}{separator}{cell}" + if max_width is not None and len(candidate) > max_width: + lines.append(current) + current = f" {cell}" + else: + current = candidate + lines.append(current) + return lines + def _resolved_device_label(self) -> str: """Return the display label for the requested or resolved device.""" return self._adapter_label if self._show_adapter else self._device @@ -125,9 +162,10 @@ def _aggregate_gpu_label(self) -> str: def __enter__(self) -> LiveMonitorDisplay: from rich.live import Live + self._console = Console(stderr=True) self._live = Live( refresh_per_second=_REFRESH_FPS, - console=Console(stderr=True), + console=self._console, transient=False, # Keep last frame visible in scrollback ) self._live.__enter__() @@ -279,7 +317,7 @@ def _render_chart( plt.xlim(x_min, x_max) plt.xlabel("Time (s)") - plt.plotsize(self._chart_width, self._chart_height) + plt.plotsize(self._effective_chart_width(), self._chart_height) from rich.console import Group from rich.text import Text @@ -358,7 +396,9 @@ def _render_status( # Row 1: Progress pct_cell = f"{bar} {pct:.0%}" - row1 = f" {pct_cell:<30}| {progress} | Device: {self._resolved_device_label()}" + row1_lines = self._pack_status_cells( + [pct_cell, progress, f"Device: {self._resolved_device_label()}"] + ) # Row 2: Compute (unified now/avg format across all three) adapter_label_text = self._selected_adapter_label() @@ -369,19 +409,19 @@ def _render_status( row2_cells = [cpu_cell, gpu_cell] if self._show_adapter: row2_cells.insert(0, adapter_cell) - row2 = " " + "| ".join(f"{cell:<28}" for cell in row2_cells) + row2_lines = self._pack_status_cells(row2_cells) # Row 3: Memory ram_cell = f"Sys Mem: {ram_mb:.0f} MB" mem_cell = f"Device Mem: {memory_local_mb:.0f}/{memory_shared_mb:.0f} MB (local/shared)" - row3 = f" {ram_cell:<24}| {mem_cell}" + row3_lines = self._pack_status_cells([ram_cell, mem_cell]) # Row 4: Inference lat_cell = f"Latency: {latency_ms:.2f} ms" thr_cell = f"Throughput: ~{throughput:.0f} smp/s" - row4 = f" {lat_cell:<24}| {thr_cell}" + row4_lines = self._pack_status_cells([lat_cell, thr_cell]) - return f"{row1}\n{row2}\n{row3}\n{row4}" + return "\n".join([*row1_lines, *row2_lines, *row3_lines, *row4_lines]) def print_final_snapshot( self, diff --git a/src/winml/modelkit/commands/perf.py b/src/winml/modelkit/commands/perf.py index d618b2370..b2d4d7b3a 100644 --- a/src/winml/modelkit/commands/perf.py +++ b/src/winml/modelkit/commands/perf.py @@ -33,10 +33,10 @@ from ..utils import cli as cli_utils from ..utils.constants import ACCELERATOR_DEVICE_TYPES, EPName, EPNameOrAlias -from ..utils.logging import configure_logging +from ..utils.logging import configure_logging, suppress_huggingface_warning_logs from ..utils.model_input import ModelInputKind, classify_model_input +from ..utils.native_stderr import suppress_native_warnings from ._ep_arg import EpAtSourceParamType -from ._live_chart import LiveMonitorDisplay from ._pre_bench import print_pre_bench_block @@ -1968,6 +1968,8 @@ def _run_monitored_loop( duration_sec: float | None = None, ) -> None: """Run the benchmark iteration loop with live hardware monitoring.""" + from ._live_chart import LiveMonitorDisplay + # In duration mode the display and the loop share one benchmark-phase clock # so the progress bar tracks the same budget the loop stops on. clock = _BenchmarkClock() if duration_sec is not None else None @@ -2660,6 +2662,11 @@ def perf( if not model: raise click.UsageError("A model is required via -m/--model.") + # Merge top-level -v/-q with subcommand-level flags before any model + # resolution that can touch Hugging Face Hub and emit warning records. + verbose, quiet = cli_utils.resolve_verbosity(ctx, verbose, quiet) + configure_logging(verbosity=verbose, quiet=quiet) + # Hub-hosted ONNX (e.g. ``onnx-community/sam3-tracker-ONNX/onnx/...``) # is downloaded once and treated as a local .onnx path thereafter. # Must run BEFORE the ``Path(hf_model).suffix == ".onnx"`` check below @@ -2667,7 +2674,8 @@ def perf( # ``normalize_model_arg`` returns ``str | None`` per its signature; # the ``or model`` keeps the narrowed ``str`` type for downstream use. try: - hf_model: str = cli_utils.normalize_model_arg(model) or model + with suppress_huggingface_warning_logs(verbosity=verbose, quiet=quiet): + hf_model: str = cli_utils.normalize_model_arg(model) or model except Exception as e: raise click.ClickException(f"Failed to resolve Hub-hosted ONNX path {model!r}: {e}") from e model = hf_model @@ -2715,10 +2723,6 @@ def perf( elif "execution_provider" in cc: ep = (cc["execution_provider"], None) - # Merge top-level -v/-q with subcommand-level flags so either position works. - verbose, quiet = cli_utils.resolve_verbosity(ctx, verbose, quiet) - configure_logging(verbosity=verbose, quiet=quiet) - # Runtime EP provider options (e.g. QNN htp_performance_mode) forwarded to # the inference session for both HF model IDs and ONNX file inputs. ep_provider_options = cli_utils.parse_ep_options(ep_options) @@ -3040,7 +3044,11 @@ def perf( console.print(f"[dim]Loading model:[/dim] {hf_model}") benchmark = PerfBenchmark(config) - result = benchmark.run() + with ( + suppress_huggingface_warning_logs(verbosity=verbose, quiet=quiet), + suppress_native_warnings(), + ): + result = benchmark.run() # Composite models (e.g. CLIP/SigLIP dual-encoders) have no single ORT # session; each sub-model is benchmarked individually and reported as diff --git a/src/winml/modelkit/ep_path.py b/src/winml/modelkit/ep_path.py index 81691d582..e4d844aae 100644 --- a/src/winml/modelkit/ep_path.py +++ b/src/winml/modelkit/ep_path.py @@ -52,7 +52,7 @@ from importlib import metadata from pathlib import Path from types import MappingProxyType -from typing import Any +from typing import Any, Final from packaging.version import InvalidVersion, Version @@ -60,6 +60,20 @@ logger = logging.getLogger(__name__) +# Canonical EPSource origin tags accepted by ``--ep @`` and +# ``EPDeviceTarget(source=...)``. +VALID_SOURCE_TAGS: Final[frozenset[str]] = frozenset( + { + "bundled", + "pypi", + "nuget", + "msix", + "winml-catalog", + "directory", + } +) + + # --------------------------------------------------------------------------- # Canonical EP metadata registry. # --------------------------------------------------------------------------- diff --git a/src/winml/modelkit/session/ep_device.py b/src/winml/modelkit/session/ep_device.py index a51a3f68e..8eb3fd667 100644 --- a/src/winml/modelkit/session/ep_device.py +++ b/src/winml/modelkit/session/ep_device.py @@ -38,6 +38,7 @@ import onnxruntime as ort +from ..ep_path import VALID_SOURCE_TAGS from ..utils.constants import ( DEVICE_PRIORITY, EP_ALIASES, @@ -243,24 +244,14 @@ def ep_short_or_none(ep_full: str) -> str | None: # These three closed sets are the canonical authority used by # EPDeviceTarget.__post_init__ for construction-time validation. # - VALID_DEVICES: the 3 device categories ORT enumerates. -# - VALID_SOURCE_TAGS: the canonical EPSource origin tags. See -# docs/design/session/3_design_classes.md §4. +# - VALID_SOURCE_TAGS: the canonical EPSource origin tags, imported from +# ep_path.py so lightweight CLI parsers can validate source-qualified EPs +# without importing this ORT-bound module. # - known_ep_short_names(): derived from EP_ALIASES (no hardcoded list, # per CLAUDE.md cardinal rule #1). VALID_DEVICES: Final[frozenset[str]] = frozenset(DEVICE_PRIORITY) -VALID_SOURCE_TAGS: Final[frozenset[str]] = frozenset( - { - "bundled", - "pypi", - "nuget", - "msix", - "winml-catalog", - "directory", - } -) - def known_ep_short_names() -> frozenset[str]: """Set of EP short names registered in the public alias map. diff --git a/src/winml/modelkit/session/session.py b/src/winml/modelkit/session/session.py index 2801bc189..db3b44d0e 100644 --- a/src/winml/modelkit/session/session.py +++ b/src/winml/modelkit/session/session.py @@ -19,7 +19,11 @@ from ..core.onnx_utils import get_io_config from ..onnx import is_compiled_onnx -from ..utils.native_stderr import suppress_native_warnings +from ..utils.native_stderr import ( + _refresh_click_windows_console_stream, + _set_win32_std_handle_to_current_fd, + suppress_native_warnings, +) from .ep_device import ( WinMLEPMonitorMismatch, expand_ep_name, @@ -57,11 +61,14 @@ def _suppress_native_output(log_path: str | Path | None = None) -> Iterator[None old_stdout = os.dup(1) os.dup2(fd, 1) os.close(fd) + _set_win32_std_handle_to_current_fd(1) try: yield finally: os.dup2(old_stdout, 1) os.close(old_stdout) + _set_win32_std_handle_to_current_fd(1) + _refresh_click_windows_console_stream(1) class SessionState(Enum): @@ -354,7 +361,7 @@ def __init__( session_option_entries=self._active_session_option_entries, provider_options=self._provider_options, ) - with suppress_native_warnings(): + with _suppress_native_output(), suppress_native_warnings(preserve_unclassified=False): self._session = ort.InferenceSession(self._onnx_path, sess_options=so) self._running_model_path = self._onnx_path _dev = self._ep_device.device @@ -389,7 +396,10 @@ def compile(self) -> None: if not self._persist_jit: try: - with suppress_native_warnings(): + with ( + _suppress_native_output(), + suppress_native_warnings(preserve_unclassified=False), + ): session = ort.InferenceSession( str(self._onnx_path), sess_options=_build_session_options( @@ -471,7 +481,10 @@ def compile(self) -> None: session_option_entries=self._active_session_option_entries, provider_options=self._provider_options, ) - with _suppress_native_output(compile_log), suppress_native_warnings(): + with ( + _suppress_native_output(compile_log), + suppress_native_warnings(preserve_unclassified=False), + ): session = ort.InferenceSession(str(model_path), sess_options=runtime_so) actual_providers = session.get_providers() @@ -837,9 +850,7 @@ def perf( or self._session is None ) if had_baseline_session and _session_rebuilt: - logger.warning( - "auto-resetting compiled session to apply monitor session/provider options" - ) + logger.info("auto-resetting compiled session to apply monitor session/provider options") self.reset() stats = PerfStats(warmup=warmup) @@ -862,7 +873,10 @@ def _restore_baseline() -> Exception | None: return None try: - with suppress_native_warnings(): + with ( + _suppress_native_output(), + suppress_native_warnings(preserve_unclassified=False), + ): self._session = ort.InferenceSession( active_model_path, sess_options=_build_session_options( @@ -897,7 +911,10 @@ def _restore_baseline() -> Exception | None: session_option_entries=desired_sess_entries, provider_options=new_prov, ) - with suppress_native_warnings(): + with ( + _suppress_native_output(), + suppress_native_warnings(preserve_unclassified=False), + ): self._session = ort.InferenceSession(active_model_path, sess_options=so) self._provider_options = new_prov self._active_session_option_entries = desired_sess_entries @@ -1252,7 +1269,7 @@ def is_compatible( self._session_options_factory, ) sess_options.log_severity_level = 4 # Suppress ORT logs during probe - with suppress_native_warnings(): + with _suppress_native_output(), suppress_native_warnings(preserve_unclassified=False): ort.InferenceSession( test_model.SerializeToString(), sess_options=sess_options, diff --git a/src/winml/modelkit/utils/logging.py b/src/winml/modelkit/utils/logging.py index 53d2e314b..8cec7dd59 100644 --- a/src/winml/modelkit/utils/logging.py +++ b/src/winml/modelkit/utils/logging.py @@ -29,6 +29,7 @@ import logging import os import sys +import warnings from contextlib import contextmanager from typing import TYPE_CHECKING @@ -63,6 +64,7 @@ "transformers", ) _HUGGINGFACE_VERBOSITY_ENVS = ("TRANSFORMERS_VERBOSITY", "HF_HUB_VERBOSITY") +_HUGGINGFACE_WARNING_MODULE_RE = r"(huggingface_hub|transformers)(\.|$).*" def configure_logging( @@ -126,11 +128,12 @@ def suppress_huggingface_warning_logs( *, verbose: bool = False, ) -> "Iterator[None]": - """Temporarily hide Hugging Face warning chatter for an inspect operation.""" + """Temporarily hide Hugging Face warning chatter for model loading.""" verbosity = _normalize_verbosity(verbosity, verbose) log_level = _cli_log_level(verbosity, quiet) show_all_warnings = env_flag_enabled("WINMLCLI_SHOW_ALL_WARNINGS") huggingface_level = log_level if verbosity > 0 or show_all_warnings else logging.ERROR + hide_python_warnings = verbosity == 0 and not show_all_warnings saved_logger_levels = { name: logging.getLogger(name).level for name in _HUGGINGFACE_WARNING_LOGGERS @@ -146,7 +149,17 @@ def suppress_huggingface_warning_logs( for env_name in _HUGGINGFACE_VERBOSITY_ENVS: os.environ[env_name] = library_verbosity _sync_imported_huggingface_verbosity(huggingface_level) - yield + if hide_python_warnings: + with warnings.catch_warnings(): + for category in (FutureWarning, DeprecationWarning, UserWarning): + warnings.filterwarnings( + "ignore", + category=category, + module=_HUGGINGFACE_WARNING_MODULE_RE, + ) + yield + else: + yield finally: for env_name, value in saved_env.items(): if value is None: diff --git a/src/winml/modelkit/utils/native_stderr.py b/src/winml/modelkit/utils/native_stderr.py index 738524f30..614c8f84a 100644 --- a/src/winml/modelkit/utils/native_stderr.py +++ b/src/winml/modelkit/utils/native_stderr.py @@ -49,6 +49,7 @@ _k32.GetStdHandle.restype = ctypes.wintypes.HANDLE _k32.SetStdHandle.argtypes = [ctypes.wintypes.DWORD, ctypes.wintypes.HANDLE] _k32.SetStdHandle.restype = ctypes.wintypes.BOOL + _STD_OUTPUT_HANDLE = ctypes.wintypes.DWORD(0xFFFFFFF5) _STD_ERROR_HANDLE = ctypes.wintypes.DWORD(0xFFFFFFF4) @@ -68,17 +69,17 @@ def suppress_native_stderr(*, enabled: bool = True) -> Iterator[None]: return old_fd = os.dup(2) - old_w32 = _k32.GetStdHandle(_STD_ERROR_HANDLE) devnull = os.open(os.devnull, os.O_WRONLY) os.dup2(devnull, 2) os.close(devnull) - _k32.SetStdHandle(_STD_ERROR_HANDLE, msvcrt.get_osfhandle(2)) + _set_win32_std_handle_to_current_fd(2) try: yield finally: os.dup2(old_fd, 2) os.close(old_fd) - _k32.SetStdHandle(_STD_ERROR_HANDLE, old_w32) + _set_win32_std_handle_to_current_fd(2) + _refresh_click_windows_console_stream(2) @contextmanager @@ -112,10 +113,9 @@ def _drain() -> None: reader = threading.Thread(target=_drain, name="capture-native-stderr", daemon=True) old_fd = os.dup(2) - old_w32 = _k32.GetStdHandle(_STD_ERROR_HANDLE) os.dup2(write_fd, 2) os.close(write_fd) - _k32.SetStdHandle(_STD_ERROR_HANDLE, msvcrt.get_osfhandle(2)) + _set_win32_std_handle_to_current_fd(2) reader.start() try: yield @@ -124,7 +124,8 @@ def _drain() -> None: # signals EOF to the reader thread so it can finish and close the read end. os.dup2(old_fd, 2) os.close(old_fd) - _k32.SetStdHandle(_STD_ERROR_HANDLE, old_w32) + _set_win32_std_handle_to_current_fd(2) + _refresh_click_windows_console_stream(2) reader.join() # Re-emit each captured line through Python logging. _ansi_re = re.compile(r"\x1b\[[0-9;]*m") @@ -135,7 +136,11 @@ def _drain() -> None: @contextmanager -def suppress_native_warnings(*, enabled: bool = True) -> Iterator[None]: +def suppress_native_warnings( + *, + enabled: bool = True, + preserve_unclassified: bool = True, +) -> Iterator[None]: """Hide native warning lines while preserving native errors and diagnostics. Native ORT/QNN diagnostics use severity tokens such as ``[W:...]`` and @@ -148,23 +153,23 @@ def suppress_native_warnings(*, enabled: bool = True) -> Iterator[None]: read_fd, write_fd = os.pipe() old_fd = os.dup(2) - old_w32 = _get_win32_stderr_handle() reader = threading.Thread( target=_drain_filtered_native_stderr, - args=(read_fd, old_fd), + args=(read_fd, old_fd, preserve_unclassified), name="suppress-native-warnings", daemon=True, ) try: os.dup2(write_fd, 2) os.close(write_fd) - _set_win32_stderr_to_current_fd() + _set_win32_std_handle_to_current_fd(2) reader.start() try: yield finally: os.dup2(old_fd, 2) - _restore_win32_stderr_handle(old_w32) + _set_win32_std_handle_to_current_fd(2) + _refresh_click_windows_console_stream(2) reader.join() finally: os.close(old_fd) @@ -176,27 +181,38 @@ def _show_native_warnings_requested() -> bool: ) -def _drain_filtered_native_stderr(read_fd: int, target_fd: int) -> None: +def _drain_filtered_native_stderr( + read_fd: int, + target_fd: int, + preserve_unclassified: bool, +) -> None: pending = b"" try: while chunk := os.read(read_fd, 4096): pending += chunk while b"\n" in pending: line, pending = pending.split(b"\n", 1) - _write_non_warning_line(target_fd, line + b"\n") + _write_non_warning_line(target_fd, line + b"\n", preserve_unclassified) if pending: - _write_non_warning_line(target_fd, pending) + _write_non_warning_line(target_fd, pending, preserve_unclassified) except OSError: pass finally: os.close(read_fd) -def _write_non_warning_line(fd: int, line: bytes) -> None: - if not _is_native_warning_line(line): +def _write_non_warning_line(fd: int, line: bytes, preserve_unclassified: bool) -> None: + if _should_preserve_native_line(line, preserve_unclassified): _write_all(fd, line) +def _should_preserve_native_line(line: bytes, preserve_unclassified: bool) -> bool: + match = _NATIVE_SEVERITY_TOKEN_RE.search(line) + if match is None: + return preserve_unclassified + return match.group(1).lower() != b"w" + + def _is_native_warning_line(line: bytes) -> bool: match = _NATIVE_SEVERITY_TOKEN_RE.search(line) if match is None: @@ -211,8 +227,19 @@ def _get_win32_stderr_handle() -> object | None: def _set_win32_stderr_to_current_fd() -> None: - if sys.platform == "win32": - _k32.SetStdHandle(_STD_ERROR_HANDLE, msvcrt.get_osfhandle(2)) + _set_win32_std_handle_to_current_fd(2) + + +def _set_win32_std_handle_to_current_fd(fd: int) -> None: + if sys.platform != "win32": + return + if fd == 1: + std_handle = _STD_OUTPUT_HANDLE + elif fd == 2: + std_handle = _STD_ERROR_HANDLE + else: + return + _k32.SetStdHandle(std_handle, msvcrt.get_osfhandle(fd)) def _restore_win32_stderr_handle(handle: object | None) -> None: @@ -220,6 +247,81 @@ def _restore_win32_stderr_handle(handle: object | None) -> None: _k32.SetStdHandle(_STD_ERROR_HANDLE, handle) +def _refresh_click_windows_console_stream(fd: int) -> None: + """Refresh Click's cached Windows console writer after fd redirection. + + Click caches ``STDOUT_HANDLE`` / ``STDERR_HANDLE`` at import time and may + cache ConsoleStream instances keyed by ``sys.stdout`` / ``sys.stderr``. + ``os.dup2`` closes the original OS handle, so those cached writers must be + repointed at the restored fd handle to avoid ``Windows error: 6`` later. + """ + if sys.platform != "win32": + return + try: + import click._compat as click_compat + import click._winconsole as click_winconsole + except ImportError: + return + + try: + handle = msvcrt.get_osfhandle(fd) + except OSError: + return + + if fd == 1: + click_winconsole.STDOUT_HANDLE = handle + getters = ( + click_compat.get_text_stdout, + getattr(click_compat, "_default_text_stdout", None), + ) + elif fd == 2: + click_winconsole.STDERR_HANDLE = handle + getters = ( + click_compat.get_text_stderr, + getattr(click_compat, "_default_text_stderr", None), + ) + else: + return + + seen: set[int] = set() + for getter in getters: + if getter is None: + continue + try: + stream = getter() + except Exception: + continue + _replace_click_console_handle(stream, handle, seen) + + +def _replace_click_console_handle(obj: object, handle: object, seen: set[int]) -> None: + ident = id(obj) + if ident in seen: + return + seen.add(ident) + + if hasattr(obj, "handle"): + try: + obj.handle = handle + except Exception: + pass + + for attr in ( + "_text_stream", + "buffer", + "raw", + "wrapped", + "stream", + "_StreamWrapper__wrapped", + ): + try: + child = getattr(obj, attr) + except Exception: + continue + if child is not None and child is not obj: + _replace_click_console_handle(child, handle, seen) + + def _write_all(fd: int, data: bytes) -> None: while data: written = os.write(fd, data) diff --git a/tests/unit/commands/test_ep_arg.py b/tests/unit/commands/test_ep_arg.py index 3ebaf0e33..6e6ed57d5 100644 --- a/tests/unit/commands/test_ep_arg.py +++ b/tests/unit/commands/test_ep_arg.py @@ -25,7 +25,7 @@ import pytest -from winml.modelkit.session import VALID_SOURCE_TAGS +from winml.modelkit.ep_path import VALID_SOURCE_TAGS # --------------------------------------------------------------------------- diff --git a/tests/unit/commands/test_ep_arg_imports.py b/tests/unit/commands/test_ep_arg_imports.py new file mode 100644 index 000000000..f0fc9f211 --- /dev/null +++ b/tests/unit/commands/test_ep_arg_imports.py @@ -0,0 +1,36 @@ +# ------------------------------------------------------------------------- +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. +# -------------------------------------------------------------------------- +"""Import-boundary tests for the ``--ep [@]`` parser.""" + +from __future__ import annotations + +import subprocess +import sys + + +def test_ep_arg_import_does_not_import_onnxruntime() -> None: + """The parser is used while Click loads commands, before warning filters run.""" + code = "import sys; import winml.modelkit.commands._ep_arg; print('onnxruntime' in sys.modules)" + result = subprocess.run( # noqa: S603 - fixed interpreter and inline test code + [sys.executable, "-c", code], + check=True, + capture_output=True, + text=True, + ) + + assert result.stdout.strip() == "False" + + +def test_perf_command_import_does_not_import_onnxruntime() -> None: + """Click imports command modules before entering the command body.""" + code = "import sys; import winml.modelkit.commands.perf; print('onnxruntime' in sys.modules)" + result = subprocess.run( # noqa: S603 - fixed interpreter and inline test code + [sys.executable, "-c", code], + check=True, + capture_output=True, + text=True, + ) + + assert result.stdout.strip() == "False" diff --git a/tests/unit/commands/test_perf_cli.py b/tests/unit/commands/test_perf_cli.py index bc4d38c0d..448c8e8e6 100644 --- a/tests/unit/commands/test_perf_cli.py +++ b/tests/unit/commands/test_perf_cli.py @@ -11,7 +11,10 @@ from __future__ import annotations import json +import logging +import os import re +import warnings from io import StringIO from pathlib import Path from typing import ClassVar @@ -441,6 +444,74 @@ def capture_config(config: BenchmarkConfig) -> MagicMock: assert "Benchmarking ONNX" in result.output assert captured["config"].shape_config == {"input_ids": [1, 128]} + def test_cli_onnx_hub_resolution_suppresses_huggingface_warnings_by_default( + self, runner: CliRunner, tmp_path: Path, caplog: pytest.LogCaptureFixture + ) -> None: + """Default perf output hides Hugging Face warnings from Hub ONNX resolution.""" + resolved = tmp_path / "model.onnx" + resolved.write_bytes(b"fake onnx") + + def resolve_with_warning(model: str) -> str: + logging.getLogger("huggingface_hub.utils._http").warning( + "Warning: You are sending unauthenticated requests to the HF Hub." + ) + return str(resolved) + + with ( + patch( + "winml.modelkit.commands.perf.cli_utils.normalize_model_arg", + side_effect=resolve_with_warning, + ), + patch("winml.modelkit.commands.perf.PerfBenchmark") as mock_perf, + patch("winml.modelkit.commands.perf.display_console_report"), + patch("winml.modelkit.commands.perf.write_json_report"), + ): + mock_perf.return_value.run.return_value = MagicMock() + caplog.clear() + result = runner.invoke( + perf, + ["-m", "org/repo/path/model.onnx", "-o", str(tmp_path / "out.json")], + obj={}, + ) + + assert result.exit_code == 0, result.output + assert "Benchmarking ONNX" in result.output + assert "unauthenticated requests" not in result.output + assert not any("unauthenticated requests" in record.message for record in caplog.records) + + def test_cli_onnx_hub_resolution_reveals_huggingface_warnings_when_verbose( + self, runner: CliRunner, tmp_path: Path, caplog: pytest.LogCaptureFixture + ) -> None: + """Verbose perf output keeps Hub ONNX resolution warnings visible.""" + resolved = tmp_path / "model.onnx" + resolved.write_bytes(b"fake onnx") + + def resolve_with_warning(model: str) -> str: + logging.getLogger("huggingface_hub.utils._http").warning( + "Warning: You are sending unauthenticated requests to the HF Hub." + ) + return str(resolved) + + with ( + patch( + "winml.modelkit.commands.perf.cli_utils.normalize_model_arg", + side_effect=resolve_with_warning, + ), + patch("winml.modelkit.commands.perf.PerfBenchmark") as mock_perf, + patch("winml.modelkit.commands.perf.display_console_report"), + patch("winml.modelkit.commands.perf.write_json_report"), + ): + mock_perf.return_value.run.return_value = MagicMock() + caplog.clear() + result = runner.invoke( + perf, + ["-m", "org/repo/path/model.onnx", "-v", "-o", str(tmp_path / "out.json")], + obj={}, + ) + + assert result.exit_code == 0, result.output + assert any("unauthenticated requests" in record.message for record in caplog.records) + def test_cli_hf_forwards_export_overrides(self, runner: CliRunner, tmp_path: Path) -> None: """HF perf builds should pass export-related CLI overrides into BenchmarkConfig.""" input_specs = tmp_path / "inputs.json" @@ -493,6 +564,196 @@ def capture_config(config: BenchmarkConfig) -> MagicMock: assert export_override["input_tensors"][0].name == "pixel_values" assert export_override["input_tensors"][0].shape == ("batch", 3, 224, 224) + def test_cli_hf_suppresses_huggingface_warning_logs_by_default( + self, runner: CliRunner, tmp_path: Path, caplog: pytest.LogCaptureFixture + ) -> None: + """Default perf output hides Hugging Face warning chatter during model load.""" + + def emit_huggingface_warnings() -> MagicMock: + logging.getLogger("huggingface_hub.utils._http").warning( + "Warning: You are sending unauthenticated requests to the HF Hub." + ) + logging.getLogger("transformers").warning("`Siglip2ImageProcessorFast` is deprecated.") + return MagicMock() + + with ( + patch("winml.modelkit.commands.perf.PerfBenchmark") as mock_perf, + patch("winml.modelkit.commands.perf.display_console_report"), + patch("winml.modelkit.commands.perf.write_json_report"), + ): + mock_perf.return_value.run.side_effect = emit_huggingface_warnings + caplog.clear() + result = runner.invoke( + perf, + ["-m", "microsoft/resnet-50", "-o", str(tmp_path / "out.json")], + obj={}, + ) + + assert result.exit_code == 0, result.output + assert "Loading model" in result.output + assert "unauthenticated requests" not in result.output + assert "Siglip2ImageProcessorFast" not in result.output + assert not any("unauthenticated requests" in record.message for record in caplog.records) + assert not any("Siglip2ImageProcessorFast" in record.message for record in caplog.records) + + def test_cli_hf_suppresses_huggingface_python_warnings_by_default( + self, runner: CliRunner, tmp_path: Path + ) -> None: + """Default perf output hides Hugging Face warnings.warn chatter during model load.""" + + def emit_huggingface_warning() -> MagicMock: + warnings.warn_explicit( + "Warning: You are sending unauthenticated requests to the HF Hub.", + UserWarning, + filename="huggingface_hub/utils/_http.py", + lineno=1, + module="huggingface_hub.utils._http", + ) + return MagicMock() + + with ( + patch("winml.modelkit.commands.perf.PerfBenchmark") as mock_perf, + patch("winml.modelkit.commands.perf.display_console_report"), + patch("winml.modelkit.commands.perf.write_json_report"), + ): + mock_perf.return_value.run.side_effect = emit_huggingface_warning + with warnings.catch_warnings(record=True) as records: + warnings.simplefilter("always") + result = runner.invoke( + perf, + ["-m", "microsoft/resnet-50", "-o", str(tmp_path / "out.json")], + obj={}, + ) + + assert result.exit_code == 0, result.output + assert not any("unauthenticated requests" in str(record.message) for record in records) + + def test_cli_hf_suppresses_native_warning_logs_by_default( + self, runner: CliRunner, tmp_path: Path, capfd: pytest.CaptureFixture[str] + ) -> None: + """Default perf output hides native ORT warning-level stderr during model load.""" + + def emit_native_warning() -> MagicMock: + os.write( + 2, + b"2026 [W:onnxruntime:Default, onnxruntime_pybind_module.cc:44 " + b"onnxruntime::python::CreateOrtEnv] Init provider bridge failed.\n", + ) + os.write( + 2, + b"2026 [E:onnxruntime:Default, onnxruntime_pybind_module.cc:45 " + b"onnxruntime::python::CreateOrtEnv] real native error.\n", + ) + return MagicMock() + + with ( + patch("winml.modelkit.commands.perf.PerfBenchmark") as mock_perf, + patch("winml.modelkit.commands.perf.display_console_report"), + patch("winml.modelkit.commands.perf.write_json_report"), + ): + mock_perf.return_value.run.side_effect = emit_native_warning + result = runner.invoke( + perf, + ["-m", "microsoft/resnet-50", "-o", str(tmp_path / "out.json")], + obj={}, + ) + + fd_stderr = capfd.readouterr().err + assert result.exit_code == 0, result.output + assert "Loading model" in result.output + assert "Init provider bridge failed" not in result.output + assert "Init provider bridge failed" not in fd_stderr + assert "real native error" in fd_stderr + + def test_cli_hf_reveals_huggingface_warning_logs_when_verbose( + self, runner: CliRunner, tmp_path: Path, caplog: pytest.LogCaptureFixture + ) -> None: + """Verbose perf output keeps Hugging Face warning chatter visible.""" + + def emit_huggingface_warnings() -> MagicMock: + logging.getLogger("huggingface_hub.utils._http").warning( + "Warning: You are sending unauthenticated requests to the HF Hub." + ) + logging.getLogger("transformers").warning("`Siglip2ImageProcessorFast` is deprecated.") + return MagicMock() + + with ( + patch("winml.modelkit.commands.perf.PerfBenchmark") as mock_perf, + patch("winml.modelkit.commands.perf.display_console_report"), + patch("winml.modelkit.commands.perf.write_json_report"), + ): + mock_perf.return_value.run.side_effect = emit_huggingface_warnings + caplog.clear() + result = runner.invoke( + perf, + ["-m", "microsoft/resnet-50", "-v", "-o", str(tmp_path / "out.json")], + obj={}, + ) + + assert result.exit_code == 0, result.output + assert any("unauthenticated requests" in record.message for record in caplog.records) + assert any("Siglip2ImageProcessorFast" in record.message for record in caplog.records) + + def test_cli_hf_reveals_huggingface_python_warnings_when_verbose( + self, runner: CliRunner, tmp_path: Path + ) -> None: + """Verbose perf output keeps Hugging Face warnings.warn chatter visible.""" + + def emit_huggingface_warning() -> MagicMock: + warnings.warn_explicit( + "Warning: You are sending unauthenticated requests to the HF Hub.", + UserWarning, + filename="huggingface_hub/utils/_http.py", + lineno=1, + module="huggingface_hub.utils._http", + ) + return MagicMock() + + with ( + patch("winml.modelkit.commands.perf.PerfBenchmark") as mock_perf, + patch("winml.modelkit.commands.perf.display_console_report"), + patch("winml.modelkit.commands.perf.write_json_report"), + ): + mock_perf.return_value.run.side_effect = emit_huggingface_warning + with warnings.catch_warnings(record=True) as records: + warnings.simplefilter("always") + result = runner.invoke( + perf, + ["-m", "microsoft/resnet-50", "-v", "-o", str(tmp_path / "out.json")], + obj={}, + ) + + assert result.exit_code == 0, result.output + assert any("unauthenticated requests" in str(record.message) for record in records) + + def test_cli_hf_reveals_native_warning_logs_when_verbose( + self, runner: CliRunner, tmp_path: Path, capfd: pytest.CaptureFixture[str] + ) -> None: + """Verbose perf output keeps native ORT warning-level stderr visible.""" + + def emit_native_warning() -> MagicMock: + os.write( + 2, + b"2026 [W:onnxruntime:Default, onnxruntime_pybind_module.cc:44 " + b"onnxruntime::python::CreateOrtEnv] Init provider bridge failed.\n", + ) + return MagicMock() + + with ( + patch("winml.modelkit.commands.perf.PerfBenchmark") as mock_perf, + patch("winml.modelkit.commands.perf.display_console_report"), + patch("winml.modelkit.commands.perf.write_json_report"), + ): + mock_perf.return_value.run.side_effect = emit_native_warning + result = runner.invoke( + perf, + ["-m", "microsoft/resnet-50", "-v", "-o", str(tmp_path / "out.json")], + obj={}, + ) + + assert result.exit_code == 0, result.output + assert "Init provider bridge failed" in capfd.readouterr().err + def test_cli_onnx_warns_ignored_build_flags(self, runner: CliRunner, tmp_path: Path) -> None: """Build-pipeline flags are no-ops for a pre-built ONNX with skip_build, so the CLI surfaces a warning naming the flags the user set.""" diff --git a/tests/unit/session/test_ep_monitor.py b/tests/unit/session/test_ep_monitor.py index e693caa57..e4fce6a07 100644 --- a/tests/unit/session/test_ep_monitor.py +++ b/tests/unit/session/test_ep_monitor.py @@ -10,10 +10,12 @@ import sys import threading import time +from io import StringIO from pathlib import Path from unittest.mock import MagicMock, patch import pytest +from rich.console import Console from winml.modelkit.session import PerfStats, VitisAIMonitor, WinMLEPMonitor @@ -1881,6 +1883,59 @@ def test_duration_mode_warmup_progress_scales_by_warmup(self): assert "] 50%" in status assert "Time:" not in status + def test_render_chart_fits_narrow_console_panel(self): + from winml.modelkit.commands._live_chart import LiveMonitorDisplay + + console = Console(file=StringIO(), width=80, force_terminal=False) + display = LiveMonitorDisplay( + total_iterations=10, + warmup=0, + model_id="test", + device="npu", + chart_width=120, + ) + display._console = console + + renderable = display._render_chart( + util_samples=[10.0, 30.0, 50.0], + cpu_samples=[2.0, 4.0, 6.0], + gpu_samples=[1.0, 2.0, 3.0], + ) + + panel_content_width = console.width - 4 + chart_lines = [line.plain for line in renderable.renderables[1:]] + assert max(len(line) for line in chart_lines) <= panel_content_width + + def test_render_status_fits_narrow_console_panel(self): + from winml.modelkit.commands._live_chart import LiveMonitorDisplay + + console = Console(file=StringIO(), width=60, force_terminal=False) + display = LiveMonitorDisplay( + total_iterations=10, + warmup=0, + model_id="test", + device="gpu", + ) + display._console = console + + status = display._render_status( + iteration=1, + latency_ms=10.0, + util_samples=[80.0, 90.0], + cpu_pct=15.0, + cpu_samples=[10.0, 15.0], + gpu_pct=42.5, + gpu_samples=[40.0, 45.0], + memory_local_mb=36.0, + memory_shared_mb=60.0, + ram_mb=1377.0, + ) + + panel_content_width = console.width - 4 + assert "GPU (selected): 90.0%/85.0%" in status + assert "GPU (aggregate): 45.0%/42.5%" in status + assert max(len(line) for line in status.splitlines()) <= panel_content_width + # ============================================================================ # GPU utilization aggregation (hardware-independent) diff --git a/tests/unit/session/test_perf_auto_reset.py b/tests/unit/session/test_perf_auto_reset.py index 84314fdc5..9bb4c2002 100644 --- a/tests/unit/session/test_perf_auto_reset.py +++ b/tests/unit/session/test_perf_auto_reset.py @@ -7,6 +7,8 @@ from __future__ import annotations import logging +import os +from unittest.mock import MagicMock import onnxruntime as ort @@ -36,7 +38,7 @@ def _make_cpu_session(model_path): def test_auto_reset_fires_when_options_contributed(caplog): """If session is already compiled AND monitor contributes provider_options, - session.perf().__enter__ auto-resets with a WARNING log. + session.perf().__enter__ auto-resets with verbose-only diagnostic logging. """ from winml.modelkit.session.monitor.ep_monitor import WinMLEPMonitor from winml.modelkit.session.session import WinMLSession @@ -69,20 +71,146 @@ def get_provider_options(self): assert session._session is not None pre_session = session._session - with caplog.at_level(logging.WARNING), session.perf(monitor=_ContributingMonitor()): + with caplog.at_level(logging.INFO), session.perf(monitor=_ContributingMonitor()): pass # NFR-3: the verbatim phrase MUST appear as a substring of the log. expected = "auto-resetting compiled session to apply monitor session/provider options" - warnings = [r.message for r in caplog.records if r.levelname == "WARNING"] - assert any(expected in m for m in warnings), ( - f"NFR-3 verbatim phrase not in WARNING records. expected substring: " - f"{expected!r}; got: {warnings}" + info_messages = [r.message for r in caplog.records if r.levelno == logging.INFO] + assert any(expected in m for m in info_messages), ( + f"NFR-3 verbatim phrase not in INFO records. expected substring: " + f"{expected!r}; got: {info_messages}" ) + assert not any(expected in r.message for r in caplog.records if r.levelno >= logging.WARNING) # Old session object was dropped assert session._session is None or session._session is not pre_session +def test_eager_session_creation_suppresses_native_stdout(monkeypatch, capfd): + """Native QNN compiler stdout must not leak during eager InferenceSession creation.""" + from winml.modelkit.session import session as session_module + from winml.modelkit.session.session import WinMLSession + + from .conftest import make_stub_winml_ep_device + + class _FakeOrtSession: + def get_providers(self): + return ["CPUExecutionProvider"] + + def _fake_inference_session(*_args, **_kwargs): + os.write(1, b"native compiler progress should be hidden\n") + return _FakeOrtSession() + + cpu_dev = _get_real_cpu_ort_device() + cpu_ep_device = make_stub_winml_ep_device(cpu_dev, "CPUExecutionProvider") + + monkeypatch.setattr(session_module.ort, "InferenceSession", _fake_inference_session) + + WinMLSession(get_minimal_onnx_model_path(), ep_device=cpu_ep_device) + + assert "native compiler progress" not in capfd.readouterr().out + + +def test_native_stdout_suppression_refreshes_click_handle(monkeypatch): + """Restoring fd 1 must repair Click's cached Windows console handle.""" + from winml.modelkit.session import session as session_module + + calls = [] + monkeypatch.setattr(session_module, "_refresh_click_windows_console_stream", calls.append) + + with session_module._suppress_native_output(): + pass + + assert calls == [1] + + +def test_auto_reset_suppresses_native_stdout(monkeypatch, capfd): + """Monitor-triggered session rebuild/restore also suppresses native stdout.""" + from winml.modelkit.session import session as session_module + from winml.modelkit.session.monitor.ep_monitor import WinMLEPMonitor + from winml.modelkit.session.session import WinMLSession + + from .conftest import make_stub_winml_ep_device + + class _ContributingMonitor(WinMLEPMonitor): + @classmethod + def is_available(cls): + return True + + def __enter__(self): + return self + + def __exit__(self, *a): + pass + + def to_dict(self): + return {"ep": "test"} + + def get_provider_options(self): + return {"some_key": "1"} + + def _fake_inference_session(*_args, **_kwargs): + os.write(1, b"native compiler progress should be hidden\n") + return MagicMock() + + cpu_dev = _get_real_cpu_ort_device() + cpu_ep_device = make_stub_winml_ep_device(cpu_dev, "CPUExecutionProvider") + session = WinMLSession(get_minimal_onnx_model_path(), ep_device=cpu_ep_device) + session.compile() + + monkeypatch.setattr(session_module.ort, "InferenceSession", _fake_inference_session) + + with session.perf(monitor=_ContributingMonitor()): + pass + + assert "native compiler progress" not in capfd.readouterr().out + + +def test_auto_reset_suppresses_unclassified_native_stderr(monkeypatch, capfd): + """Monitor-triggered session rebuild hides native diagnostics without severity tokens.""" + from winml.modelkit.session import session as session_module + from winml.modelkit.session.monitor.ep_monitor import WinMLEPMonitor + from winml.modelkit.session.session import WinMLSession + + from .conftest import make_stub_winml_ep_device + + class _ContributingMonitor(WinMLEPMonitor): + @classmethod + def is_available(cls): + return True + + def __enter__(self): + return self + + def __exit__(self, *a): + pass + + def to_dict(self): + return {"ep": "test"} + + def get_provider_options(self): + return {"some_key": "1"} + + def _fake_inference_session(*_args, **_kwargs): + os.write(2, b"DSP_INFO UNSUPPORTED_KEY: 49\n") + os.write(2, b"2026 [E:custom-native:, file.cc:2 ErrorFunc] useful error\n") + return MagicMock() + + cpu_dev = _get_real_cpu_ort_device() + cpu_ep_device = make_stub_winml_ep_device(cpu_dev, "CPUExecutionProvider") + session = WinMLSession(get_minimal_onnx_model_path(), ep_device=cpu_ep_device) + session.compile() + + monkeypatch.setattr(session_module.ort, "InferenceSession", _fake_inference_session) + + with session.perf(monitor=_ContributingMonitor()): + pass + + stderr = capfd.readouterr().err + assert "DSP_INFO" not in stderr + assert "useful error" in stderr + + def test_no_auto_reset_when_monitor_empty(): """If monitor contributes NO options, no reset occurs.""" from winml.modelkit.session.monitor.ep_monitor import NullEPMonitor diff --git a/tests/unit/utils/test_native_stderr.py b/tests/unit/utils/test_native_stderr.py index 39b9b1a3c..0f658f9f5 100644 --- a/tests/unit/utils/test_native_stderr.py +++ b/tests/unit/utils/test_native_stderr.py @@ -47,19 +47,10 @@ def test_disabled_leaves_native_stderr_visible(self, capfd): assert "visible when disabled" in capfd.readouterr().err @pytest.mark.skipif(sys.platform != "win32", reason="Win32 only") - def test_win32_std_error_handle_restored(self): - import ctypes.wintypes - - k32 = ctypes.WinDLL("kernel32", use_last_error=True) - k32.GetStdHandle.argtypes = [ctypes.wintypes.DWORD] - k32.GetStdHandle.restype = ctypes.wintypes.HANDLE - std_error_handle = ctypes.wintypes.DWORD(0xFFFFFFF4) - - before = k32.GetStdHandle(std_error_handle) + def test_win32_std_error_handle_usable_after_restore(self): with suppress_native_stderr(): pass - after = k32.GetStdHandle(std_error_handle) - assert before == after, "STD_ERROR_HANDLE not restored" + _write_win32_stderr(b"after restore\n") @pytest.mark.skipif(sys.platform == "win32", reason="Non-Windows only") def test_noop_on_non_windows(self, capfd): @@ -160,6 +151,18 @@ def test_preserves_error_lines_that_reference_warning_tokens(self, monkeypatch, assert "failed after previous [W:note]" in capfd.readouterr().err + def test_can_filter_unclassified_native_diagnostics(self, monkeypatch, capfd): + monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) + logging.getLogger().setLevel(logging.WARNING) + + with native_stderr_module.suppress_native_warnings(preserve_unclassified=False): + os.write(2, b"DSP_INFO UNSUPPORTED_KEY: 49\n") + os.write(2, b"2026 [E:custom-native:, file.cc:2 ErrorFunc] useful error\n") + + stderr = capfd.readouterr().err + assert "DSP_INFO" not in stderr + assert "useful error" in stderr + def test_verbose_logging_leaves_native_warnings_visible(self, monkeypatch, capfd): monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) logging.getLogger().setLevel(logging.INFO) @@ -192,18 +195,17 @@ def test_filters_win32_std_error_handle_warning(self, monkeypatch, capfd): assert "win32 error" in stderr @pytest.mark.skipif(sys.platform != "win32", reason="Win32 native stderr only") - def test_restores_win32_std_error_handle_after_exception(self, monkeypatch): + def test_win32_std_error_handle_usable_after_exception(self, monkeypatch): monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) logging.getLogger().setLevel(logging.WARNING) - before = _get_win32_stderr_handle() with ( pytest.raises(RuntimeError, match="boom"), native_stderr_module.suppress_native_warnings(), ): raise RuntimeError("boom") - assert _get_win32_stderr_handle() == before + _write_win32_stderr(b"after exception\n") def test_restore_win32_std_error_handle_accepts_null_handle(self, monkeypatch): calls = [] @@ -230,6 +232,69 @@ def _set_std_handle(self, handle_kind: object, handle: object | None) -> bool: assert calls == [(std_error_handle, None)] + @pytest.mark.skipif(sys.platform != "win32", reason="Click Win32 console only") + def test_refreshes_click_console_handle_cache(self, monkeypatch): + import click._compat as click_compat + import click._winconsole as click_winconsole + + class FakeRaw: + handle = 1 + + class FakeBuffer: + raw = FakeRaw() + + class FakeText: + buffer = FakeBuffer() + + class FakeConsoleStream: + _text_stream = FakeText() + + stream = FakeConsoleStream() + + monkeypatch.setattr(click_compat, "get_text_stderr", lambda: stream) + monkeypatch.setattr(click_winconsole, "STDERR_HANDLE", 1) + monkeypatch.setattr(native_stderr_module.msvcrt, "get_osfhandle", lambda fd: 12345) + + native_stderr_module._refresh_click_windows_console_stream(2) + + assert click_winconsole.STDERR_HANDLE == 12345 + assert stream._text_stream.buffer.raw.handle == 12345 + + @pytest.mark.skipif(sys.platform != "win32", reason="Click Win32 console only") + def test_refreshes_click_default_console_handle_cache(self, monkeypatch): + import click._compat as click_compat + import click._winconsole as click_winconsole + + class FakeRaw: + def __init__(self) -> None: + self.handle = 1 + + class FakeBuffer: + def __init__(self) -> None: + self.raw = FakeRaw() + + class FakeText: + def __init__(self) -> None: + self.buffer = FakeBuffer() + + class FakeConsoleStream: + def __init__(self) -> None: + self._text_stream = FakeText() + + uncached_stream = FakeConsoleStream() + default_cached_stream = FakeConsoleStream() + + monkeypatch.setattr(click_compat, "get_text_stderr", lambda: uncached_stream) + monkeypatch.setattr(click_compat, "_default_text_stderr", lambda: default_cached_stream) + monkeypatch.setattr(click_winconsole, "STDERR_HANDLE", 1) + monkeypatch.setattr(native_stderr_module.msvcrt, "get_osfhandle", lambda fd: 12345) + + native_stderr_module._refresh_click_windows_console_stream(2) + + assert click_winconsole.STDERR_HANDLE == 12345 + assert uncached_stream._text_stream.buffer.raw.handle == 12345 + assert default_cached_stream._text_stream.buffer.raw.handle == 12345 + @pytest.mark.timeout(30) def test_no_deadlock_on_large_warning_output(self, monkeypatch, capfd): monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) From 767c66c3938db8ca0b83253dca843fb5cd9bf9fa Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" Date: Wed, 29 Jul 2026 17:44:54 +0800 Subject: [PATCH 7/8] Fix CI after warning suppression updates Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- src/winml/modelkit/session/__init__.py | 3 +-- src/winml/modelkit/utils/native_stderr.py | 4 ++-- tests/unit/commands/test_perf_module.py | 2 +- 3 files changed, 4 insertions(+), 5 deletions(-) diff --git a/src/winml/modelkit/session/__init__.py b/src/winml/modelkit/session/__init__.py index 9acef048c..39d7f4180 100644 --- a/src/winml/modelkit/session/__init__.py +++ b/src/winml/modelkit/session/__init__.py @@ -4,14 +4,13 @@ # -------------------------------------------------------------------------- """WinMLSession - ONNX Runtime session manager with WinML EP integration.""" -from ..ep_path import DirectorySource, EPEntry +from ..ep_path import VALID_SOURCE_TAGS, DirectorySource, EPEntry from .ep_device import ( DEVICE_TO_DEVICE_TYPE, DEVICE_TYPE_TO_DEVICE, EP_DEVICE_SPECS, VALID_DEVICES, VALID_EPS, - VALID_SOURCE_TAGS, DeviceNotFound, EPDeviceSpec, EPDeviceTarget, diff --git a/src/winml/modelkit/utils/native_stderr.py b/src/winml/modelkit/utils/native_stderr.py index 614c8f84a..561a54003 100644 --- a/src/winml/modelkit/utils/native_stderr.py +++ b/src/winml/modelkit/utils/native_stderr.py @@ -24,7 +24,7 @@ import sys import threading from contextlib import contextmanager -from typing import TYPE_CHECKING +from typing import TYPE_CHECKING, cast from .._env import env_flag_enabled @@ -223,7 +223,7 @@ def _is_native_warning_line(line: bytes) -> bool: def _get_win32_stderr_handle() -> object | None: if sys.platform != "win32": return None - return _k32.GetStdHandle(_STD_ERROR_HANDLE) + return cast("object", _k32.GetStdHandle(_STD_ERROR_HANDLE)) def _set_win32_stderr_to_current_fd() -> None: diff --git a/tests/unit/commands/test_perf_module.py b/tests/unit/commands/test_perf_module.py index 2931c4f12..47f07a316 100644 --- a/tests/unit/commands/test_perf_module.py +++ b/tests/unit/commands/test_perf_module.py @@ -499,7 +499,7 @@ def test_run_monitored_loop_forwards_explicit_none_device_kind_to_live_display(s fake_display.__enter__.return_value = fake_display with patch( - "winml.modelkit.commands.perf.LiveMonitorDisplay", + "winml.modelkit.commands._live_chart.LiveMonitorDisplay", return_value=fake_display, ) as mock_display: _run_monitored_loop( From f60588c3ecb7984ae5e1a445d7a94d21ad5c119f Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" Date: Wed, 29 Jul 2026 18:36:01 +0800 Subject: [PATCH 8/8] Handle Windows console write failures in perf output Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- src/winml/modelkit/commands/_live_chart.py | 10 +++--- src/winml/modelkit/commands/_pre_bench.py | 18 ++++------ src/winml/modelkit/commands/perf.py | 41 ++++++++++++---------- src/winml/modelkit/utils/console.py | 19 ++++++++++ tests/unit/commands/test_perf_cli.py | 33 +++++++++++++++++ tests/unit/commands/test_pre_bench.py | 34 ++++++++++++++++++ 6 files changed, 120 insertions(+), 35 deletions(-) diff --git a/src/winml/modelkit/commands/_live_chart.py b/src/winml/modelkit/commands/_live_chart.py index cf91931aa..0ea6e2b51 100644 --- a/src/winml/modelkit/commands/_live_chart.py +++ b/src/winml/modelkit/commands/_live_chart.py @@ -13,10 +13,10 @@ import time from typing import Any, Final -from rich.console import Console from rich.panel import Panel from ..session.monitor.hw_monitor import adapter_label +from ..utils.console import SafeConsole, _SafeLive from ..utils.constants import ACCELERATOR_DEVICE_TYPES @@ -100,7 +100,7 @@ def __init__( self._chart_height = chart_height self._poll_interval_s = poll_interval_ms / 1000.0 self._live: Any = None - self._console: Console | None = None + self._console: SafeConsole | None = None # Track the last rendered panel for transient=False final display self._last_panel: Any = None @@ -160,10 +160,8 @@ def _aggregate_gpu_label(self) -> str: return label def __enter__(self) -> LiveMonitorDisplay: - from rich.live import Live - - self._console = Console(stderr=True) - self._live = Live( + self._console = SafeConsole(stderr=True) + self._live = _SafeLive( refresh_per_second=_REFRESH_FPS, console=self._console, transient=False, # Keep last frame visible in scrollback diff --git a/src/winml/modelkit/commands/_pre_bench.py b/src/winml/modelkit/commands/_pre_bench.py index 726450545..ed65cb90f 100644 --- a/src/winml/modelkit/commands/_pre_bench.py +++ b/src/winml/modelkit/commands/_pre_bench.py @@ -18,6 +18,8 @@ from rich.panel import Panel from rich.text import Text +from ..utils.console import safe_console_print + if TYPE_CHECKING: from collections.abc import Sequence @@ -89,17 +91,13 @@ def print_pre_bench_block( model_lines: list[Text] = [] if model_id: model_lines.append( - _labeled_line( - "Model:", f"[bold cyan]{model_id}[/bold cyan] [dim](HF)[/dim]" - ) + _labeled_line("Model:", f"[bold cyan]{model_id}[/bold cyan] [dim](HF)[/dim]") ) if cached_onnx_path: model_lines.append(_labeled_line("ONNX:", f"[dim]{cached_onnx_path}[/dim]")) elif onnx_file: model_lines.append( - _labeled_line( - "Model:", f"[bold cyan]{onnx_file}[/bold cyan] [dim](local)[/dim]" - ) + _labeled_line("Model:", f"[bold cyan]{onnx_file}[/bold cyan] [dim](local)[/dim]") ) if task: @@ -112,7 +110,7 @@ def print_pre_bench_block( model_lines.extend(_io_lines("Outputs:", outputs)) if model_lines: - console.print(Panel(Group(*model_lines), title="Model", expand=True)) + safe_console_print(console, Panel(Group(*model_lines), title="Model", expand=True)) # --- Device panel: resolved device + EP + DLL ------------------------- hw_suffix = f" [dim]({hardware_name})[/dim]" if hardware_name else "" @@ -126,7 +124,7 @@ def print_pre_bench_block( _labeled_line("EP:", ep_line), _labeled_line("EP DLL:", f"[dim]{dll_display}[/dim]"), ] - console.print(Panel(Group(*device_lines), title="Device", expand=True)) + safe_console_print(console, Panel(Group(*device_lines), title="Device", expand=True)) def _labeled_line(label: str, value_markup: str) -> Text: @@ -147,9 +145,7 @@ def _io_lines( name_width = max((len(name) for name, _, _ in specs), default=0) out: list[Text] = [] for i, (name, dtype, shape) in enumerate(specs): - prefix = ( - f"{label:<{_LABEL_WIDTH}}" if i == 0 else " " * _LABEL_WIDTH - ) + prefix = f"{label:<{_LABEL_WIDTH}}" if i == 0 else " " * _LABEL_WIDTH shape_str = "[" + ", ".join(str(d) for d in shape) + "]" dtype_suffix = f" [dim]{dtype}[/dim]" if dtype else "" out.append( diff --git a/src/winml/modelkit/commands/perf.py b/src/winml/modelkit/commands/perf.py index 735ac022c..ab955f392 100644 --- a/src/winml/modelkit/commands/perf.py +++ b/src/winml/modelkit/commands/perf.py @@ -32,6 +32,7 @@ from rich.table import Table from ..utils import cli as cli_utils +from ..utils.console import SafeConsole, safe_console_print from ..utils.constants import ACCELERATOR_DEVICE_TYPES, EPName, EPNameOrAlias from ..utils.logging import configure_logging, suppress_huggingface_warning_logs from ..utils.model_input import ModelInputKind, classify_model_input @@ -866,7 +867,7 @@ def _run_single(self) -> BenchmarkResult: } assert self._ep_device is not None pre_bench_kwargs = _pre_bench_kwargs_from_ep_device(self._ep_device, **pre_bench_common) - print_pre_bench_block(Console(stderr=True), **pre_bench_kwargs) + print_pre_bench_block(SafeConsole(stderr=True), **pre_bench_kwargs) # [3] Run benchmark if self.config.duration is not None: @@ -1649,9 +1650,13 @@ def display_console_report(result: BenchmarkResult, console: Console) -> None: even though they no longer render to stdout — the data model is unchanged, only the console rendering was pruned. """ + + def print_(*objects: Any, **kwargs: Any) -> None: + safe_console_print(console, *objects, **kwargs) + # Latency table - console.print() - console.print("[bold]Latency (ms)[/bold]") + print_() + print_("[bold]Latency (ms)[/bold]") table = Table(show_header=True, header_style="bold cyan") for col in ["Avg", "P50", "P90", "P95", "P99", "Min", "Max", "Std"]: @@ -1668,24 +1673,24 @@ def display_console_report(result: BenchmarkResult, console: Console) -> None: f"{result.std_ms:.2f}", ) - console.print(table) + print_(table) if result.warmup_mean_ms > 0: - console.print( + print_( f" [dim]Warmup: {result.warmup_mean_ms:.2f} ms avg " f"(first {result.config.warmup} iterations)[/dim]" ) # Throughput - console.print() + print_() throughput_line = f"[bold]Throughput:[/bold] {result.samples_per_sec:.2f} samples/sec" if result.effective_batch_size != 1: throughput_line += f" [dim](batch {result.effective_batch_size})[/dim]" - console.print(throughput_line) + print_(throughput_line) # Flag when the requested batch couldn't be honored so a static-batch model # doesn't look like it silently ran the requested batch. if result.config.batch_size != result.effective_batch_size: - console.print( + print_( f" [yellow]Note:[/yellow] requested batch {result.config.batch_size} " f"could not be applied (model has a static batch of " f"{result.effective_batch_size})." @@ -1693,8 +1698,8 @@ def display_console_report(result: BenchmarkResult, console: Console) -> None: # Hardware section (only when monitoring was active) if result.hw_monitor: - console.print() - console.print("[bold]Hardware (during benchmark)[/bold]") + print_() + print_("[bold]Hardware (during benchmark)[/bold]") cpu = result.hw_monitor.get("cpu", {}) ram = result.hw_monitor.get("ram", {}) # ``hw_monitor["gpu"]`` is aggregate GPU telemetry. Selected-adapter @@ -1705,23 +1710,23 @@ def display_console_report(result: BenchmarkResult, console: Console) -> None: device_kind = result.hw_monitor.get("device_kind") if device_kind in ACCELERATOR_DEVICE_TYPES: adapter = result.hw_monitor.get("adapter") or result.hw_monitor.get(device_kind, {}) - console.print( + print_( f" {device_kind.upper()}: {adapter.get('mean_pct', 0):.1f}% avg, " f"{adapter.get('peak_pct', 0):.1f}% peak | " f"CPU: {cpu.get('mean_pct', 0):.1f}% avg | " f"RAM: {ram.get('used_mb', 0):.0f} MB" ) else: - console.print( + print_( f" CPU: {cpu.get('mean_pct', 0):.1f}% avg | RAM: {ram.get('used_mb', 0):.0f} MB" ) # Memory section (only when --memory is enabled) if result.memory_profile: mem = result.memory_profile - console.print() - console.print("[bold]Memory:[/bold]") - console.print( + print_() + print_("[bold]Memory:[/bold]") + print_( f" RAM: {mem['rss_after_inference_mb']:.1f} MB -> " f"model load: {mem['rss_model_load_delta_mb']:+.1f} MB | " f"inference: {mem['rss_inference_delta_mb']:+.1f} MB | " @@ -1730,7 +1735,7 @@ def display_console_report(result: BenchmarkResult, console: Console) -> None: vram_local = mem.get("vram_local_after_inference_mb", 0) vram_shared = mem.get("vram_shared_after_inference_mb", 0) if vram_local > 0 or vram_shared > 0: - console.print( + print_( f" VRAM: {vram_local:.1f}/{vram_shared:.1f} MB (local/shared) -> " f"model load: {mem['vram_local_model_load_delta_mb']:+.1f}/" f"{mem['vram_shared_model_load_delta_mb']:+.1f} MB | " @@ -1740,7 +1745,7 @@ def display_console_report(result: BenchmarkResult, console: Console) -> None: f"{mem['vram_shared_total_delta_mb']:+.1f} MB" ) - console.print() + print_() def write_json_report(result: BenchmarkResult, output_path: Path) -> None: @@ -2726,7 +2731,7 @@ def perf( ep_provider_options = cli_utils.parse_ep_options(ep_options) json_mode = output_format == "json" - console = Console(stderr=True) if json_mode else Console() + console = SafeConsole(stderr=True) if json_mode else SafeConsole() # ========================================================================= # GENAI RUNTIME: benchmark an onnxruntime-genai bundle folder diff --git a/src/winml/modelkit/utils/console.py b/src/winml/modelkit/utils/console.py index e83293d9b..2b5b0f1e4 100644 --- a/src/winml/modelkit/utils/console.py +++ b/src/winml/modelkit/utils/console.py @@ -51,6 +51,25 @@ def get_console() -> Console: return Console(stderr=True) +class SafeConsole(Console): + """Rich Console variant that does not fail commands on Windows console write errors.""" + + def print(self, *objects: Any, **kwargs: Any) -> None: + """Print objects, ignoring Windows console handle/mode write errors.""" + try: + super().print(*objects, **kwargs) + except OSError: + logger.debug("Ignoring OSError from Console.print", exc_info=True) + + +def safe_console_print(console: Console, *objects: Any, **kwargs: Any) -> None: + """Print to Rich console, ignoring Windows console handle/mode write errors.""" + try: + console.print(*objects, **kwargs) + except OSError: + logger.debug("Ignoring OSError from Console.print", exc_info=True) + + # ══════════════════════════════════════════════════════════════════════════ # SHARED FORMATTING # ══════════════════════════════════════════════════════════════════════════ diff --git a/tests/unit/commands/test_perf_cli.py b/tests/unit/commands/test_perf_cli.py index 448c8e8e6..495274ee4 100644 --- a/tests/unit/commands/test_perf_cli.py +++ b/tests/unit/commands/test_perf_cli.py @@ -1745,6 +1745,18 @@ def test_cli_closes_benchmark_after_success( class TestDisplayConsoleReport: + class _FailingConsoleFile: + encoding = "utf-8" + + def write(self, _text: str) -> int: + raise OSError(1, "Incorrect function") + + def flush(self) -> None: + pass + + def isatty(self) -> bool: + return True + def test_prefers_adapter_block_over_gpu_aggregate(self) -> None: result = BenchmarkResult( config=BenchmarkConfig(model_id="microsoft/resnet-50", warmup=1), @@ -1788,6 +1800,27 @@ def test_prefers_adapter_block_over_gpu_aggregate(self) -> None: assert "GPU: 91.2% avg, 98.8% peak" in out assert "GPU: 1.1% avg, 2.2% peak" not in out + def test_ignores_windows_console_write_oserror(self) -> None: + result = BenchmarkResult( + config=BenchmarkConfig(model_id="microsoft/resnet-50", warmup=1), + mean_ms=10.0, + min_ms=9.0, + max_ms=11.0, + p50_ms=10.0, + p90_ms=10.5, + p95_ms=10.8, + p99_ms=11.0, + std_ms=0.5, + warmup_mean_ms=12.0, + samples_per_sec=100.0, + effective_batch_size=1, + actual_device="gpu", + actual_task="image-classification", + ) + console = Console(file=self._FailingConsoleFile(), width=120, force_terminal=False) + + display_console_report(result, console) + class TestPerfSubmodel: """--submodel narrows a composite model to a single sub-component.""" diff --git a/tests/unit/commands/test_pre_bench.py b/tests/unit/commands/test_pre_bench.py index 95b0d402f..d9867c629 100644 --- a/tests/unit/commands/test_pre_bench.py +++ b/tests/unit/commands/test_pre_bench.py @@ -14,6 +14,19 @@ from winml.modelkit.commands._pre_bench import print_pre_bench_block +class _FailingConsoleFile: + encoding = "utf-8" + + def write(self, _text: str) -> int: + raise OSError(1, "Incorrect function") + + def flush(self) -> None: + pass + + def isatty(self) -> bool: + return True + + _PLUGIN_DLL = ( r"C:\Users\zhengte\BYOM\ModelKits\winml\x64\Release" r"\onnxruntime_providers_openvino_plugin.dll" @@ -72,6 +85,27 @@ def test_hf_block_shows_model_id(): assert "convnext.onnx" in out +def test_hf_block_ignores_windows_console_write_oserror(): + console = Console(file=_FailingConsoleFile(), width=120, force_terminal=False) + + print_pre_bench_block( + console, + model_id="facebook/convnext-base-224", + task="image-classification", + opset=17, + inputs=[("pixel_values", "float32", (1, 3, 224, 224))], + outputs=[("logits", "float32", (1, 1000))], + cached_onnx_path=r"C:\Users\u\.cache\winml\artifacts\convnext.onnx", + onnx_file=None, + device="npu", + hardware_name="NPU Compute Accelerator Device", + ep="qnn", + ep_source="pypi", + ep_version="2.29.0", + ep_dll_path=r"C:\Users\u\onnxruntime_providers_qnn.dll", + ) + + def test_hf_block_shows_inputs_and_outputs(): out = _render_hf() assert "pixel_values" in out