Hide noisy CLI warnings by default - #1246
Conversation
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>
Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
xieofxie
left a comment
There was a problem hiding this comment.
Found two correctness issues in the new output handling: concurrent process-wide descriptor redirection can corrupt/hang the process, and broad OSError handling can silently lose reports.
Suppress warning-level native stderr and third-party progress by default while preserving verbose diagnostics. Harden fd redirection and Windows console handling so suppression fails open instead of crashing or corrupting output. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Move the expected test exception into a helper call so static analysis no longer treats the post-assertion handle check as unreachable. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Use a context-managed devnull handle for native stderr suppression and document the FileNotFoundError race when removing ONNX external data sidecars. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
KayMKM
left a comment
There was a problem hiding this comment.
Overall
The direction is right: native warning filtering, HF log suppression, and the Windows console handle repair are consolidated into native_stderr.py / logging.py / console.py, and the fd-redirect error paths are hardened. A few things should be addressed before merge.
1. Correctness
1.1 old_fd is closed before the reader thread finishes — fd-reuse cross-talk risk
src/winml/modelkit/utils/native_stderr.py
In suppress_native_warnings, the finally block does reader.join(timeout=_NATIVE_READER_JOIN_TIMEOUT_SECONDS) and then closes old_fd unconditionally. But _drain_filtered_native_stderr writes to exactly that old_fd. If the reader is still alive after the timeout, the fd number can be recycled and native stderr text may be written into an unrelated file/socket opened by another thread.
Suggestion: only close when the reader actually finished (leaking one fd is preferable), or make the thread own the close:
reader.join(timeout=_NATIVE_READER_JOIN_TIMEOUT_SECONDS)
if reader.is_alive():
logger.debug(...)
else:
_close_fd(old_fd)1.2 preserve_unclassified=False drops all Python-side stderr inside the window
_should_preserve_native_line discards every line without a [X: severity token. session.py uses preserve_unclassified=False around self.reset(), _restore_baseline() and session re-creation inside perf().
During that same window, Rich Live has a background refresh thread writing to stderr, and the logging StreamHandler is bound to fd 2. Those lines carry no severity token, so they are silently dropped — visible as dropped live-chart frames and lost log records.
Please scope the filtering so it cannot swallow our own output, or drop preserve_unclassified=False at these call sites.
1.3 suppress_third_party_progress mostly does not work
src/winml/modelkit/utils/logging.py
TQDM_DISABLEis not an environment variable tqdm reads. Verified against the pinned tqdm in this repo's venv:tqdm/std.pynever references it. Setting it is a no-op._disable_imported_tqdm_progress()only patches tqdm classes already present insys.modules. Inperf.pythe context manager is entered beforenormalize_model_arg(), at which pointhuggingface_hub/tqdmare typically not imported yet — so the download progress bars this is meant to hide are not hidden.HF_HUB_DISABLE_PROGRESS_BARS/huggingface_hub.utils.disable_progress_bars()is missing, and that is the actual switch for Hub download progress bars. (datasetsis handled,huggingface_hubis not.)
Also, globally rebinding tqdm.__init__ is not thread-safe and affects all threads and user code inside the window. Since huggingface_hub exposes an official disable_progress_bars(), prefer that over monkeypatching.
1.4 Library (non-CLI) code paths get an implicit behavior change
suppress_native_warnings() is added to analyze/runtime_checker/ep_checker.py, compiler/stages/compile.py, optim/pipes/graph.py, pattern/op_input_gen/op_input_gen.py, session/qairt/qairt_session.py, eval/mask_generation_evaluator.py and session/session.py — these are SDK-level, not CLI-level.
The gate _show_native_warnings_requested() reads the root logger's isEnabledFor(logging.INFO). When the package is used as a Python API, the root logger defaults to WARNING, so every InferenceSession creation will redirect process-wide fd 2, spawn a background thread, and silently discard ORT warnings. That is too invasive for library consumers.
Suggestion: make the switch explicit (an argument or a module-level setting) instead of implicitly deriving it from the root logger level.
1.5 _suppress_native_output now permanently rewrites the Win32 STD_OUTPUT_HANDLE
src/winml/modelkit/session/session.py
The original implementation only touched fd 1. The new code calls _set_win32_std_handle_to_current_fd(1) after restoring, which resets STD_OUTPUT_HANDLE to fd 1's osfhandle. If the two differed on entry (e.g. changed by an outer tool or pytest), this "restore" silently overwrites it.
The old capture_native_stderr saved old_w32 = GetStdHandle(...) and restored the exact value. That save/restore semantic was dropped — please keep it.
2. Design / maintainability
2.1 Private symbols imported across modules
Against the repo import convention:
session/session.pyimports_refresh_click_windows_console_stream,_restore_redirected_fd,_set_win32_std_handle_to_current_fdfromutils/native_stderr.pycommands/_live_chart.pyimports_SafeLivefromutils/console.py
Either promote them to public names or move them into the consuming module.
2.2 _refresh_click_windows_console_stream depends heavily on Click internals
It mutates click._winconsole.STDOUT_HANDLE / STDERR_HANDLE, reads click._compat._default_text_stdout, and _replace_click_console_handle walks an object graph (_text_stream, buffer, raw, wrapped, stream, _StreamWrapper__wrapped) writing .handle, with every failure swallowed by except Exception: pass.
A single Click minor upgrade can break this silently. Please add a version guard and a test that would actually fail if the mechanism stops working.
2.3 Newly added dead code
In native_stderr.py:
_is_native_warning_line— no callers_get_win32_stderr_handle— no callers_set_win32_stderr_to_current_fd— no callers_restore_win32_stderr_handle— only used by a test_restore_redirected_native_stderr_fd— a thin wrapper over_restore_redirected_fd(2, ...)with no added value
Please remove them.
2.4 SafeConsole and safe_console_print are redundant
Two mechanisms for the same behavior, plus display_console_report in perf.py defines yet another local print_ wrapper even though the console it receives is already a SafeConsole in most paths. Please converge on one. Note also that SafeConsole only overrides print — log, rule, print_exception, status are not covered.
2.5 _is_expected_windows_console_oserror message-parsing fallback is fragile
Parsing the exception text with re.search(r"Windows error:\s*(\d+)") depends on a non-localized message. winerror and errno already cover the realistic cases; please drop the regex branch.
2.6 native_fd_redirect_lock is held for the whole yield
_suppress_native_output wraps entire ort.InferenceSession(...) construction while holding the lock, and suppress_native_warnings does the same. The RLock makes same-thread nesting safe, but other threads that need a redirect will block for the full session-creation duration.
3. commands/_live_chart.py
3.1 _PLOTEXT_HORIZONTAL_OVERHEAD = 21 is a magic number
No explanation of where 21 comes from (y-axis label width?), and it will drift with plotext versions. Please document or derive it.
3.2 _pack_status_cells measures width with len()
Should use rich.cells.cell_len — the progress bar uses block characters and cells may contain wide characters, so len() miscounts display width.
3.3 Visual regression on wide terminals
The previous f"{pct_cell:<30}" / f"{cell:<28}" padding aligned columns across rows. The new a | b | c join has no padding, so on a wide terminal the rows no longer line up. Suggestion: keep the padding when there is enough width and only wrap on narrow terminals.
4. Scope creep / diff noise
4.1 onnx/persistence.py is unrelated to this PR
The "sidecar is locked, fall back to a uuid-suffixed name" change has nothing to do with hiding CLI warnings — please split it out. Also, the while True loop in _unique_external_data_location is pointless: a uuid4 collision is negligible, and the exists() check is itself TOCTOU-prone.
4.2 Unrelated reformatting
analyze/runtime_checker/ep_checker.py, commands/_pre_bench.py, onnx/persistence.py and pattern/op_input_gen/op_input_gen.py contain pure ruff format reflows. Among them, changing a Protocol method body from ... to pass is a regression (... is the idiomatic Protocol body), and op_input_gen.py gains a stray blank line. These bury the real changes — please land them separately.
4.3 Missing documentation
WINMLCLI_SHOW_ALL_WARNINGS now also controls native warning visibility, but the variable does not appear anywhere under docs/. Please document it in the perf command docs or the troubleshooting page.
5. Tests
5.1 test_third_party_progress_suppression_sets_tqdm_disable_env asserts an implementation detail
It only asserts the environment variable is set, not that progress output actually disappears — and the variable itself has no effect (see 1.3).
5.2 test_close_suppresses_native_warning_from_session_reset is the right pattern
Using capfd plus a real os.write(2, ...) is a genuine behavior assertion. Worth extending that style to the tqdm/progress tests.
5.3 Test doubles do not match the production signature
Several perf CLI tests replace suppress_native_warnings with mark_native_suppression(), which accepts no keyword arguments, while production code calls suppress_native_warnings(preserve_unclassified=False). It only passes today because PerfBenchmark is mocked out at those call sites. Please make the fake accept the same signature.
Blocking in my view: 1.1, 1.2, 1.3, 1.4, 1.5, 2.3. The rest are suggestions.
Restore the local monkeypatch inside the test body so the file-level resolve_device patch can tear down cleanly before later session tests run. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
KayMKM
left a comment
There was a problem hiding this comment.
Thanks for the fast turnaround — most of the previous round is addressed. Summary of where things stand.
Resolved
- fd-reuse cross-talk:
suppress_native_warningsnow only closesold_fdwhen the reader thread actually finished. Good. preserve_unclassified=Falseswallowing our own stderr: allsuppress_native_warnings(preserve_unclassified=False)call sites insession.pyare gone, replaced by_suppress_native_output()which only touches fd 1. Good.- Progress suppression: the ineffective
TQDM_DISABLEoverride and the globaltqdm.__init__monkeypatch are gone, replaced byHF_HUB_DISABLE_PROGRESS_BARSplus the officialhuggingface_hub.utils.disable_progress_bars(). Usingimport_moduleinstead ofsys.modules.getalso fixes the "not imported yet" gap. Good. - Library-path invasiveness:
enablednow defaults toFalse(opt-in), andcompiler/stages/compile.py,optim/pipes/graph.py,session/qairt/qairt_session.pyandeval/mask_generation_evaluator.pyare fully reverted. Good. - Win32 handle save/restore:
_suppress_native_outputnow capturesget_win32_std_handle(1)/get_win32_fd_handle(1)and restores the original value when they differ. Good. - Dead code removed, private cross-module imports replaced with public aliases,
_SafeLivepromoted toSafeLive, the message-parsing regex fallback dropped,cell_lenused instead oflen, the plotext overhead constant documented and covered bytest_live_chart_constants.py, the unrelatedpersistence.pysidecar change reverted, anddocs/commands/perf.mdupdated.
New regression (blocking, in my view)
perf.py now wraps the entire benchmark.run() in suppress_native_warnings(enabled=True):
with (
suppress_native_warnings(enabled=True),
suppress_huggingface_warning_logs(verbosity=verbose, quiet=quiet),
suppress_third_party_progress(verbosity=verbose, quiet=quiet),
):
result = benchmark.run()This is exactly what the previous revision's own test forbade — test_cli_does_not_wrap_entire_benchmark_in_native_stderr_redirect, whose docstring read "Perf CLI must not route Rich/report output through native stderr filtering". That test was deleted in this update rather than the constraint being kept.
Why it matters:
benchmark.run()covers_run_monitored_loop(RichLivewriting to stderr at 5 FPS) andprint_pre_bench_block. For the whole benchmark, fd 2 is a pipe drained by a background thread._drain_filtered_native_stderronly flushes on\n. Rich's cursor-control sequences (\x1b[?25l, cursor-up/erase-line, etc.) do not end with a newline, so they sit inpendinguntil the next newline arrives. Expect a flickering / misaligned live chart.- Verified locally: after
dup2-ing fd 2 onto a pipe,os.isatty(2)isFalsebutsys.stderr.isatty()still returnsTrue(CPython caches it on theFileIO). So Rich still believes it is on a terminal and keeps emitting the full ANSI sequence set — which lands straight in the line-buffered forwarding path above. test_run_does_not_redirect_native_stderr_around_model_load_or_uistill asserts thatPerfBenchmark.run()does not wrap model load / UI in suppression, but the CLI now wraps the whole thing from the outside, so that constraint no longer holds on the real code path.
Related: the new _NATIVE_PREFIX_SEVERITY_RE (^[A-Z][A-Z0-9_]*_(TRACE|DEBUG|INFO|WARNING|WARN|ERROR|ERR|FATAL)\b) now applies to all stderr content inside that window, including our own output, so the false-positive surface grew as well.
Suggestion: keep the suppression scoped to the native-heavy sections (device/EP resolution, ORT imports, session teardown) as the earlier revision did, and restore the deleted test.
New issue
analyze/runtime_checker/ep_checker.py — commit "Fix rules prefilter protocol stub" changed the _RulesPrefilterProtocol method body from ... to raise NotImplementedError. That class is a typing.Protocol; ... is the idiomatic and correct body for a protocol member. raise NotImplementedError makes type checkers treat it as a method with a default implementation rather than a pure stub. Please restore ... (the previous revision's pass was also wrong).
Still open from the last round
SafeConsoleandsafe_console_printstill coexist, anddisplay_console_reportadds a thirdprint_wrapper on top. Please converge on one.native_fd_redirect_lockis still held across the wholeyield— and now for the entire benchmark duration, which makes the contention window considerably longer.- The wide-terminal column alignment regression in
_render_status(padding dropped in favor of an unpaddeda | b | cjoin) is unchanged. - Unrelated reformatting is still in the diff: all of
commands/_pre_bench.py, the stray blank line inpattern/op_input_gen/op_input_gen.py, and theClassVarreflow inanalyze/runtime_checker/ep_checker.py.
## Summary - replace the pipe used by native warning suppression with a file-backed temporary spool - filter and replay preserved native diagnostics only after restoring stderr - retain fail-open behavior, Windows handle restoration, warning filtering, and bounded memory usage ## Root cause The warning filter introduced in #1246 redirected native stderr to a pipe. VitisAI can hang inside `ort.InferenceSession` when its compiler sees that pipe handle. The reader was draining correctly, so this was not the full-buffer deadlock fixed by #1223; changing the reader to defer replay still hung, which isolated the pipe handle itself as the trigger. A temporary file preserves warning filtering without pipe semantics or a finite producer buffer. With an empty VAIP cache and no VitisAI-specific bypass, `facebook/convnext-tiny-224` completed on VitisAI NPU in 144.1 seconds. Disabling warning filtering entirely completed the same workload in 145.1 seconds. ## Validation - `uv run --no-sync pytest tests/unit/utils/test_native_stderr.py tests/unit/commands/test_perf_cli.py -q --basetemp temp/pytest_tmp/native-warning-file-backed-final` (143 passed, 1 platform skip) - `uvx ruff check src/winml/modelkit/utils/native_stderr.py tests/unit/utils/test_native_stderr.py src/winml/modelkit/commands/perf.py tests/unit/commands/test_perf_cli.py` - cold-cache VitisAI NPU perf with warning filtering enabled: PASS in 144.1s
Summary
winml perfoutput while preserving errors.-v/-vvorWINMLCLI_SHOW_ALL_WARNINGS=1._ep_argandperfcommand imports lightweight.Validation
uv run ruff check --fix src\winml\modelkit\commands\perf.py src\winml\modelkit\commands\_live_chart.py src\winml\modelkit\utils\logging.py src\winml\modelkit\utils\native_stderr.py src\winml\modelkit\session\session.py src\winml\modelkit\commands\_ep_arg.py src\winml\modelkit\session\ep_device.py src\winml\modelkit\ep_path.py tests\unit\commands\test_perf_cli.py tests\unit\commands\test_ep_arg.py tests\unit\commands\test_ep_arg_imports.py tests\unit\session\test_perf_auto_reset.py tests\unit\session\test_ep_monitor.py tests\unit\utils\test_native_stderr.pyuv run pytest tests\unit\utils\test_logging.py tests\unit\utils\test_native_stderr.py tests\unit\commands\test_ep_arg.py tests\unit\commands\test_ep_arg_imports.py tests\unit\commands\test_perf_cli.py tests\unit\session\test_perf_auto_reset.py tests\unit\session\test_ep_monitor.py::TestLiveMonitorDisplay tests\unit\commands\test_live_chart_constants.py tests\unit\commands\test_inspect_cli.py::TestInspectFlagCombinations::test_default_inspection_suppresses_huggingface_warning_logs tests\unit\commands\test_inspect_cli.py::TestInspectFlagCombinations::test_default_inspection_restores_huggingface_warning_state -quv run winml perf -m facebook/convnext-tiny-224 --ep qnn@winml-catalog --op-tracing basic