diff --git a/src/winml/modelkit/_warnings.py b/src/winml/modelkit/_warnings.py index 3c7297a12..b0fb520bd 100644 --- a/src/winml/modelkit/_warnings.py +++ b/src/winml/modelkit/_warnings.py @@ -101,73 +101,26 @@ def filter(self, record: logging.LogRecord) -> bool: ) # ========================================================================= - # py.warnings logger filters (for warnings routed via logging.captureWarnings) + # huggingface_hub: suppress the Windows "symlinks not supported" notice # ========================================================================= - - class _HFSymlinksInfoFilter(logging.Filter): - r"""Downgrade the huggingface_hub symlinks UserWarning from WARNING to INFO. - - On Windows without Developer Mode, huggingface_hub warns that symlinks - are unsupported and the cache will use copies instead. This is cosmetic — - the cache still works, just without deduplication. WARNING is misleading - here; INFO is the appropriate level. - - When warnings are routed via logging.captureWarnings(True), Python's - warnings.formatwarning() embeds the source filename in the log message - body ("path/to/huggingface_hub/file_download.py:1: UserWarning: ..."), - so we match against getMessage() rather than record.pathname (which - is always warnings.py in that path). - - Before (WARNING level, always visible): - [09:12:34] WARNING C:\\...\\huggingface_hub\\file_download.py:1: - UserWarning: `huggingface_hub` cache-system uses - symlinks by default to efficiently store - duplicated files but your machine does not - support them - - After (INFO level, only visible with --verbose or -v): - [09:12:34] INFO C:\\...\\huggingface_hub\\file_download.py:1: - UserWarning: `huggingface_hub` cache-system uses - symlinks by default to efficiently store - duplicated files but your machine does not - support them - """ - - def filter(self, record: logging.LogRecord) -> bool: - msg = record.getMessage() - if "symlinks" in msg and "huggingface_hub" in msg: - record.levelno = logging.INFO - record.levelname = "INFO" - return True - - logging.getLogger("py.warnings").addFilter(_HFSymlinksInfoFilter()) - - # Suppress the huggingface_hub symlinks warning at the Python warnings level - # so it is hidden even before captureWarnings(True) is activated in build.py. - # When captureWarnings(True) is active, _HFSymlinksInfoFilter above handles - # the same message for loggers that need it at INFO (e.g. with --verbose). + # On Windows without Developer Mode, huggingface_hub emits a UserWarning that + # its cache will use file copies instead of symlinks. This is cosmetic — the + # cache still works, just without deduplication. Drop it at the Python + # warnings layer so it is hidden in every verbosity mode; this also stops it + # before captureWarnings(True) (activated in build.py) could route it to the + # py.warnings logger. warnings.filterwarnings( "ignore", message=r".*huggingface_hub.*cache-system.*symlinks.*", category=UserWarning, ) - class _TasksManagerFilter(logging.Filter): - """Downgrade optimum TasksManager architecture-mismatch notice to INFO. - - optimum logs a WARNING when TasksManager selects a different Auto class - than the one in config.architectures (e.g. AutoModelForSequenceClassification - vs RobertaForSequenceClassification). This is expected behaviour for - WinML models and is purely informational. - """ - - def filter(self, record: logging.LogRecord) -> bool: - if "TasksManager returned" in record.getMessage(): - record.levelno = logging.INFO - record.levelname = "INFO" - return True - - logging.getLogger("optimum.exporters.tasks").addFilter(_TasksManagerFilter()) + # NOTE: optimum's informational WARNINGs (e.g. "TasksManager returned ...", + # "No model type passed for the task ...") are gated by the verbosity- + # conditional ERROR floor on the `optimum` logger in utils/logging.py + # (configure_logging): hidden by default, shown at -v/-vv. A demote-to-INFO + # filter here would only relabel a record after the root-level gate has + # already passed it through — it would not suppress anything — so none is used. class _TransformersWeightsFilter(logging.Filter): """Suppress the transformers "weights not used" notice. diff --git a/tests/unit/test_warnings_configure.py b/tests/unit/test_warnings_configure.py index c645e3fc7..4f04b7390 100644 --- a/tests/unit/test_warnings_configure.py +++ b/tests/unit/test_warnings_configure.py @@ -2,94 +2,71 @@ # Copyright (c) Microsoft Corporation. All rights reserved. # Licensed under the MIT License. # -------------------------------------------------------------------------- -"""Tests for _warnings._configure() filter behaviour.""" +"""Tests for _warnings._configure() suppression behaviour.""" from __future__ import annotations import logging import warnings -from typing import TYPE_CHECKING - - -if TYPE_CHECKING: - import pytest - - -def _get_hf_symlinks_filter() -> logging.Filter: - """Return the _HFSymlinksInfoFilter installed on the py.warnings logger.""" - logger = logging.getLogger("py.warnings") - matches = [f for f in logger.filters if type(f).__name__ == "_HFSymlinksInfoFilter"] - assert matches, "_HFSymlinksInfoFilter not found on py.warnings logger" - return matches[0] - - -def _emit_warning(message: str, filename: str) -> None: - """Emit a UserWarning through the real logging.captureWarnings path.""" - logging.captureWarnings(True) - try: - warnings.warn_explicit( - message=message, - category=UserWarning, - filename=filename, - lineno=1, - registry={}, # fresh registry — always route to showwarning - ) - finally: - logging.captureWarnings(False) - - -class TestHFSymlinksInfoFilter: - """_HFSymlinksInfoFilter downgrades huggingface_hub symlinks warnings to INFO.""" - - def test_filter_is_installed(self) -> None: - """_configure() installs _HFSymlinksInfoFilter on the py.warnings logger.""" - import winml.modelkit._warnings # noqa: F401 — triggers _configure() - - _get_hf_symlinks_filter() # asserts filter exists - - def test_downgrade_to_info(self, caplog: pytest.LogCaptureFixture) -> None: - """Warning from huggingface_hub containing 'symlinks' is downgraded to INFO.""" - import winml.modelkit._warnings # noqa: F401 - - with caplog.at_level(logging.DEBUG, logger="py.warnings"): - _emit_warning( - message=( - "`huggingface_hub` cache-system uses symlinks by default to" - " efficiently store duplicated files but your machine does not" - " support them" - ), - filename="C:/fake/huggingface_hub/file_download.py", - ) - - records = [r for r in caplog.records if "symlinks" in r.getMessage()] - assert records, "No matching record captured" - assert records[0].levelno == logging.INFO - assert records[0].levelname == "INFO" - - def test_unrelated_warning_unchanged(self, caplog: pytest.LogCaptureFixture) -> None: - """Records without 'symlinks' in message are not modified.""" - import winml.modelkit._warnings # noqa: F401 - - with caplog.at_level(logging.DEBUG, logger="py.warnings"): - _emit_warning( - message="Some other huggingface_hub warning without the keyword", - filename="C:/fake/huggingface_hub/file_download.py", - ) - - records = [r for r in caplog.records if "huggingface_hub" in r.getMessage()] - assert records, "No matching record captured" - assert records[0].levelno == logging.WARNING - - def test_symlinks_from_other_module_unchanged(self, caplog: pytest.LogCaptureFixture) -> None: - """A 'symlinks' warning not from huggingface_hub is not modified.""" - import winml.modelkit._warnings # noqa: F401 - - with caplog.at_level(logging.DEBUG, logger="py.warnings"): - _emit_warning( - message="symlinks are not supported on this platform", - filename="C:/fake/other_library/utils.py", - ) - - records = [r for r in caplog.records if "symlinks" in r.getMessage()] - assert records, "No matching record captured" - assert records[0].levelno == logging.WARNING + +import pytest + +from winml.modelkit._warnings import _configure + + +_HF_SYMLINKS_MESSAGE = ( + "`huggingface_hub` cache-system uses symlinks by default to efficiently" + " store duplicated files but your machine does not support them" +) + +# Loggers that _configure() attaches noise-suppression filters to. Calling +# _configure() repeatedly (as these tests do) would otherwise accumulate +# duplicate filter instances in global logging state. +_FILTERED_LOGGERS = ( + "diffusers.utils.import_utils", + "transformers.pipelines.base", + "transformers.models.auto.image_processing_auto", + "transformers.modeling_utils", +) + + +@pytest.fixture(autouse=True) +def _restore_logging_filters(): + """Snapshot and restore the filter lists of the loggers _configure() mutates.""" + saved = {name: list(logging.getLogger(name).filters) for name in _FILTERED_LOGGERS} + yield + for name, filters in saved.items(): + logging.getLogger(name).filters[:] = filters + + +class TestHFSymlinksSuppression: + """_configure() drops the huggingface_hub symlinks UserWarning at the warnings layer. + + The filter is a hard ``filterwarnings("ignore")`` rather than a demote-to-INFO + logging filter, so the warning never reaches the ``py.warnings`` logger and is + hidden in every verbosity mode. + """ + + def test_symlinks_warning_is_suppressed(self, monkeypatch: pytest.MonkeyPatch) -> None: + """The huggingface_hub symlinks UserWarning is ignored, not surfaced.""" + monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) + + with warnings.catch_warnings(record=True) as caught: + warnings.resetwarnings() + _configure() + warnings.warn(_HF_SYMLINKS_MESSAGE, UserWarning, stacklevel=2) + + assert not [w for w in caught if "symlinks" in str(w.message)] + + def test_unrelated_symlinks_warning_not_suppressed( + self, monkeypatch: pytest.MonkeyPatch + ) -> None: + """The ignore filter targets the HF message only; other warnings pass through.""" + monkeypatch.delenv("WINMLCLI_SHOW_ALL_WARNINGS", raising=False) + + with warnings.catch_warnings(record=True) as caught: + warnings.resetwarnings() + _configure() + warnings.warn("symlinks are unsupported on this platform", UserWarning, stacklevel=2) + + assert [w for w in caught if "symlinks" in str(w.message)] diff --git a/tests/unit/utils/test_logging.py b/tests/unit/utils/test_logging.py index c6ddb9a5c..bbce52e27 100644 --- a/tests/unit/utils/test_logging.py +++ b/tests/unit/utils/test_logging.py @@ -40,3 +40,17 @@ def test_library_loggers_follow_cli_level_when_verbose(verbosity, expected): # With -v/-vv the library loggers follow the CLI level so the detail is on demand. configure_logging(verbosity=verbosity) assert logging.getLogger("optimum").level == expected + + +def test_optimum_child_logger_gated_by_parent_floor(): + # The optimum "TasksManager returned ..." notice originates on the child logger + # optimum.exporters.tasks. With no demote filter, the parent ERROR floor must hide + # it by default and reveal it at -v (the floor follows the CLI level). This is what + # replaces the removed _TasksManagerFilter demote-to-INFO filter. + child = logging.getLogger("optimum.exporters.tasks") + + configure_logging(verbosity=0) + assert not child.isEnabledFor(logging.WARNING) + + configure_logging(verbosity=1) + assert child.isEnabledFor(logging.WARNING)