diff --git a/tests/logging/test_exceptions.py b/tests/logging/test_exceptions.py index bf69d46..49d1c71 100644 --- a/tests/logging/test_exceptions.py +++ b/tests/logging/test_exceptions.py @@ -3,8 +3,12 @@ import pytest from daqpytools.logging.exceptions import ( + ERSEnvError, + ERSInitError, + LoggerConfigurationError, LoggerHandlerError, LoggerSetupError, + ProtobufFormatError, ) @@ -23,3 +27,25 @@ def test_exceptions(): assert str(exc_info.value) == ( "Constructing test_logger failed as: \nThe test made me do it :(" ) + + +def test_configuration_and_ers_related_exceptions() -> None: + config_path = "tests/logging/log_format.ini" + with pytest.raises(LoggerConfigurationError) as exc_info: + raise LoggerConfigurationError(config_path, "bad section") + assert f"Configuration file '{config_path}'" in str(exc_info.value) + assert "bad section" in str(exc_info.value) + + with pytest.raises(ERSEnvError) as exc_info: + raise ERSEnvError("DUNEDAQ_ERS_ERROR") + assert str(exc_info.value) == "The environment variable DUNEDAQ_ERS_ERROR is empty" + + with pytest.raises(ERSInitError) as exc_info: + raise ERSInitError("host:30092", "ers_stream") + assert "address='host:30092'" in str(exc_info.value) + assert "topic='ers_stream'" in str(exc_info.value) + + with pytest.raises(ProtobufFormatError) as exc_info: + raise ProtobufFormatError("protobufstream(bad)") + assert "protobufstream URLs must be formatted (url:port)." in str(exc_info.value) + assert "protobufstream(bad)" in str(exc_info.value) diff --git a/tests/logging/test_filters.py b/tests/logging/test_filters.py new file mode 100644 index 0000000..9bc6a0e --- /dev/null +++ b/tests/logging/test_filters.py @@ -0,0 +1,134 @@ +import logging +import uuid +from collections.abc import Iterator +from unittest.mock import MagicMock + +import pytest + +from daqpytools.logging.filters import ( + HandleIDFilter, + ThrottleFilter, + add_filter, + add_throttle_filter, + get_filter_spec, +) +from daqpytools.logging.handlerconf import HandlerType + + +def _record(level: int = logging.INFO) -> logging.LogRecord: + return logging.LogRecord( + name="test.filters", + level=level, + pathname="", + lineno=42, + msg="message", + args=(), + exc_info=None, + ) + + +@pytest.fixture +def clean_logger() -> Iterator[logging.Logger]: + name = f"test.filters.{uuid.uuid4()}" + logger = logging.getLogger(name) + logger.handlers = [] + logger.filters = [] + logger.propagate = False + logger.setLevel(logging.DEBUG) + yield logger + for handler in logger.handlers[:]: + logger.removeHandler(handler) + logger.filters = [] + logging.root.manager.loggerDict.pop(name, None) + + +def test_get_filter_spec_registry_lookup() -> None: + assert get_filter_spec(HandlerType.Throttle) is not None + assert get_filter_spec(HandlerType.Rich) is None + + +def test_add_filter_uses_default_fallback_from_spec( + clean_logger: logging.Logger, +) -> None: + add_filter(clean_logger, HandlerType.Throttle, fallback_handlers=None) + + assert len(clean_logger.filters) == 1 + logger_filter = clean_logger.filters[0] + assert isinstance(logger_filter, ThrottleFilter) + assert logger_filter.fallback_handlers == {HandlerType.Throttle} + + +def test_add_filter_uses_explicit_fallback_and_extras( + clean_logger: logging.Logger, +) -> None: + add_filter( + clean_logger, + HandlerType.Throttle, + fallback_handlers={HandlerType.Unknown}, + initial_treshold=7, + time_limit=11, + ) + + logger_filter = clean_logger.filters[0] + assert isinstance(logger_filter, ThrottleFilter) + assert logger_filter.fallback_handlers == {HandlerType.Unknown} + assert logger_filter.initial_threshold == 7 + assert logger_filter.time_limit == 11 + + +def test_add_throttle_filter_delegates_to_add_filter( + clean_logger: logging.Logger, + monkeypatch: pytest.MonkeyPatch, +) -> None: + add_filter_mock = MagicMock() + monkeypatch.setattr("daqpytools.logging.filters.add_filter", add_filter_mock) + + add_throttle_filter(clean_logger, fallback_handlers={HandlerType.Throttle}) + + add_filter_mock.assert_called_once_with( + clean_logger, + HandlerType.Throttle, + {HandlerType.Throttle}, + ) + + +def test_handleid_filter_matches_with_fallback_when_record_handlers_missing() -> None: + logger_filter = HandleIDFilter( + handler_id=HandlerType.Rich, + fallback_handlers={HandlerType.Rich}, + ) + + assert logger_filter.filter(_record()) is True + + +def test_handleid_filter_rejects_when_no_allowed_handlers() -> None: + logger_filter = HandleIDFilter( + handler_id=HandlerType.Rich, + fallback_handlers={HandlerType.Rich}, + ) + record = _record() + record.handlers = None + + assert logger_filter.filter(record) is False + + +def test_throttle_filter_passthrough_when_throttle_not_allowed() -> None: + logger_filter = ThrottleFilter( + fallback_handlers={HandlerType.Rich}, + initial_threshold=1, + time_limit=60, + ) + + assert logger_filter.filter(_record(level=logging.ERROR)) is True + + +def test_throttle_filter_suppresses_after_initial_threshold() -> None: + logger_filter = ThrottleFilter( + fallback_handlers={HandlerType.Throttle}, + initial_threshold=1, + time_limit=60, + ) + record = _record(level=logging.ERROR) + + assert logger_filter.filter(record) is True + assert logger_filter.filter(record) is False diff --git a/tests/logging/test_handlerconf.py b/tests/logging/test_handlerconf.py new file mode 100644 index 0000000..7681f77 --- /dev/null +++ b/tests/logging/test_handlerconf.py @@ -0,0 +1,215 @@ +import logging +import uuid +from typing import ClassVar +from unittest.mock import MagicMock + +import pytest + +from daqpytools.apps import logging_demonstrator as demo +from daqpytools.logging.exceptions import ERSEnvError, ProtobufFormatError +from daqpytools.logging.handlerconf import ( + ERSPyLogHandlerConf, + HandlerType, + LogHandlerConf, + ProtobufConf, + StreamType, +) +from daqpytools.logging.levels import level_to_ers_var + + +def test_handlertype_from_string_case_insensitive() -> None: + assert HandlerType.from_string("RiCh") == HandlerType.Rich + + +def test_handlertype_from_string_unknown_returns_none() -> None: + assert HandlerType.from_string("definitely_unknown") is None + + +def test_protobufconf_get_string_formats_url_port() -> None: + conf = ProtobufConf(url="host", port=1234) + assert conf.get_string() == "host:1234" + + +def test_loghandlerconf_ers_property_raises_before_init() -> None: + conf = LogHandlerConf(init_ers=False) + with pytest.raises(AttributeError, match="ERS stream not initialised"): + _ = conf.ERS + + +def test_loghandlerconf_init_ers_stream_sets_structure( + monkeypatch: pytest.MonkeyPatch, +) -> None: + fake_oks = {"DUNEDAQ_ERS_ERROR": ERSPyLogHandlerConf(handlers=[HandlerType.Rich])} + monkeypatch.setattr( + LogHandlerConf, "_get_oks_conf", staticmethod(lambda: fake_oks) + ) + + conf = LogHandlerConf(init_ers=False) + conf.init_ers_stream() + + assert conf.ERS["ers_handlers"] == fake_oks + assert conf.ERS["stream"] == StreamType.ERS + + +def test_loghandlerconf_post_init_calls_init_when_flag_true( + monkeypatch: pytest.MonkeyPatch, +) -> None: + fake_oks = {"DUNEDAQ_ERS_ERROR": ERSPyLogHandlerConf(handlers=[HandlerType.Rich])} + monkeypatch.setattr(LogHandlerConf, "_get_oks_conf", staticmethod(lambda: fake_oks)) + + conf = LogHandlerConf(init_ers=True) + assert conf.ERS["ers_handlers"] == fake_oks + + +def test_get_base_returns_copy_not_original_reference() -> None: + base_one = LogHandlerConf.get_base() + base_two = LogHandlerConf.get_base() + + base_one.add(HandlerType.Unknown) + + assert HandlerType.Unknown in base_one + assert HandlerType.Unknown not in base_two + + +def test_convert_str_to_handlertype_ignores_erstrace() -> None: + handler, protobuf_conf = LogHandlerConf._convert_str_to_handlertype("erstrace") + assert handler is None + assert protobuf_conf is None + + +def test_convert_str_to_handlertype_regular_handler() -> None: + handler, protobuf_conf = LogHandlerConf._convert_str_to_handlertype("throttle") + assert handler == HandlerType.Throttle + assert protobuf_conf is None + + +def test_convert_str_to_handlertype_parses_protobuf_with_url_port() -> None: + handler, protobuf_conf = LogHandlerConf._convert_str_to_handlertype( + "protobufstream(monkafka.cern.ch:30092)" + ) + assert handler == HandlerType.Protobufstream + assert protobuf_conf == ProtobufConf(url="monkafka.cern.ch", port=30092) + + +def test_convert_str_to_handlertype_invalid_protobuf_format_raises() -> None: + with pytest.raises(ProtobufFormatError): + LogHandlerConf._convert_str_to_handlertype("protobufstream(bad-format)") + + +def test_make_ers_handler_conf_raises_when_env_missing( + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.setattr("os.getenv", lambda _: None) + with pytest.raises(ERSEnvError): + LogHandlerConf._make_ers_handler_conf("DUNEDAQ_ERS_ERROR") + + +def test_make_ers_handler_conf_parses_multiple_handlers( + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.setattr( + "os.getenv", + lambda _: "erstrace, throttle, lstdout, protobufstream(host:1234)", + ) + + conf = LogHandlerConf._make_ers_handler_conf("DUNEDAQ_ERS_ERROR") + + assert HandlerType.Throttle in conf.handlers + assert HandlerType.Lstdout in conf.handlers + assert conf.protobufconf == ProtobufConf(url="host", port=1234) + + +def test_get_oks_conf_builds_mapping_for_all_ers_level_vars( + monkeypatch: pytest.MonkeyPatch, +) -> None: + calls: list[str] = [] + + def _fake_make(level_var: str) -> ERSPyLogHandlerConf: + calls.append(level_var) + return ERSPyLogHandlerConf(handlers=[HandlerType.Rich]) + + monkeypatch.setattr( + LogHandlerConf, "_make_ers_handler_conf", staticmethod(_fake_make) + ) + + conf = LogHandlerConf._get_oks_conf() + + assert set(calls) == set(level_to_ers_var.values()) + assert set(conf.keys()) == set(level_to_ers_var.values()) + + +# demonstrator test_* parity integrated into handlerconf tests + +def test_demo_test_handlerconf_runs_ers_flow_and_restores( + monkeypatch: pytest.MonkeyPatch, +) -> None: + logger = MagicMock(spec=logging.Logger) + + class FakeHC: + Base: ClassVar[dict] = { + "handlers": {HandlerType.Stream}, + "stream": StreamType.BASE, + } + Opmon: ClassVar[dict] = { + "handlers": {HandlerType.Rich}, + "stream": StreamType.OPMON, + } + + def __init__(self, init_ers: bool = False) -> None: + self._ers = { + "ers_handlers": { + "DUNEDAQ_ERS_ERROR": ERSPyLogHandlerConf( + handlers=[HandlerType.Rich] + ), + }, + "stream": StreamType.ERS, + } + if init_ers: + self.init_ers_stream() + + @property + def ERS(self) -> dict: # noqa: N802 + return self._ers + + def init_ers_stream(self) -> None: + return None + + monkeypatch.setattr(demo, "LogHandlerConf", FakeHC) + + demo.test_handlerconf(logger) + + logger.warning.assert_called() + logger.info.assert_called() + + +def test_demo_test_ers_handler_configuration_calls_setup_and_logs( + monkeypatch: pytest.MonkeyPatch, +) -> None: + logger_name = f"demo.ers.{uuid.uuid4()}" + logger = logging.getLogger(logger_name) + logger.handlers = [] + logger.filters = [] + logger.propagate = False + + get_logger_mock = MagicMock(return_value=logger) + setup_mock = MagicMock() + + class FakeHC: + def __init__(self, init_ers: bool = False) -> None: + assert init_ers is True + self._ers = {"stream": StreamType.ERS, "ers_handlers": {}} + + @property + def ERS(self) -> dict: # noqa: N802 + return self._ers + + monkeypatch.setattr(demo, "get_daq_logger", get_logger_mock) + monkeypatch.setattr(demo, "setup_daq_ers_logger", setup_mock) + monkeypatch.setattr(demo, "LogHandlerConf", FakeHC) + + demo.test_ers_handler_configuration("INFO") + + get_logger_mock.assert_called_once() + setup_mock.assert_called_once_with(logger, "session_temp") + + logging.root.manager.loggerDict.pop(logger_name, None) diff --git a/tests/logging/test_handlers.py b/tests/logging/test_handlers.py new file mode 100644 index 0000000..0b2284f --- /dev/null +++ b/tests/logging/test_handlers.py @@ -0,0 +1,529 @@ +import logging +import uuid +from collections.abc import Iterator +from unittest.mock import MagicMock, call + +import pytest + +from daqpytools.apps import logging_demonstrator as demo +from daqpytools.logging import handlers as handlers_mod +from daqpytools.logging.exceptions import ERSInitError, LoggerHandlerError +from daqpytools.logging.filters import HandleIDFilter +from daqpytools.logging.formatter import LoggingFormatter +from daqpytools.logging.handlerconf import HandlerType +from daqpytools.logging.rich_handler import FormattedRichHandler + + +@pytest.fixture +def clean_logger() -> Iterator[logging.Logger]: + name = f"test.handlers.{uuid.uuid4()}" + logger = logging.getLogger(name) + logger.handlers = [] + logger.filters = [] + logger.propagate = False + logger.setLevel(logging.DEBUG) + yield logger + for handler in logger.handlers[:]: + logger.removeHandler(handler) + try: + handler.close() + except Exception as e: + # Handler already closed or does not support close + del e + logger.filters = [] + logging.root.manager.loggerDict.pop(name, None) + + +@pytest.fixture +def parent_child_loggers() -> Iterator[tuple[logging.Logger, logging.Logger]]: + parent_name = f"test.handlers.parent.{uuid.uuid4()}" + child_name = f"{parent_name}.child" + + parent = logging.getLogger(parent_name) + child = logging.getLogger(child_name) + + parent.handlers = [] + parent.filters = [] + parent.propagate = False + parent.setLevel(logging.DEBUG) + + child.handlers = [] + child.filters = [] + child.propagate = True + child.setLevel(logging.DEBUG) + + yield parent, child + + for logger in [child, parent]: + for handler in logger.handlers[:]: + logger.removeHandler(handler) + try: + handler.close() + except Exception as e: + # Handler already closed or does not support close + del e + logger.filters = [] + logging.root.manager.loggerDict.pop(logger.name, None) + + +def test_logger_has_handler_non_logger_returns_false() -> None: + assert handlers_mod.logger_has_handler(MagicMock(), logging.StreamHandler) is False + + +def test_logger_has_handler_matches_non_stream_type( + clean_logger: logging.Logger, +) -> None: + handler = logging.NullHandler() + clean_logger.addHandler(handler) + assert ( + handlers_mod.logger_has_handler(clean_logger, logging.NullHandler) + is True + ) + + +def test_logger_has_handler_matches_stream_by_target_stream( + clean_logger: logging.Logger, +) -> None: + stdout_handler = logging.StreamHandler( + handlers_mod.STDOUT_HANDLER_SPEC.target_stream + ) + clean_logger.addHandler(stdout_handler) + + assert ( + handlers_mod.logger_has_handler( + clean_logger, + logging.StreamHandler, + target_stream=handlers_mod.STDOUT_HANDLER_SPEC.target_stream, + ) + is True + ) + assert ( + handlers_mod.logger_has_handler( + clean_logger, + logging.StreamHandler, + target_stream=handlers_mod.STDERR_HANDLER_SPEC.target_stream, + ) + is False + ) + + +def test_logger_has_filter_detects_filter_type(clean_logger: logging.Logger) -> None: + clean_logger.addFilter(logging.Filter("named.filter")) + assert handlers_mod.logger_has_filter(clean_logger, logging.Filter) is True + + +def test_ancestors_have_handlers_returns_false_when_disabled( + parent_child_loggers: tuple[logging.Logger, logging.Logger], +) -> None: + _, child = parent_child_loggers + assert ( + handlers_mod.ancestors_have_handlers(child, False, logging.NullHandler) + is False + ) + + +def test_ancestors_have_handlers_rejects_root_logger() -> None: + with pytest.raises(ValueError, match="root logger"): + handlers_mod.ancestors_have_handlers( + logging.getLogger(), + True, + logging.NullHandler, + ) + + +def test_ancestors_have_handlers_requires_target_for_streamhandler( + clean_logger: logging.Logger, +) -> None: + with pytest.raises(ValueError, match="target_stream must be specified"): + handlers_mod.ancestors_have_handlers( + clean_logger, + True, + logging.StreamHandler, + ) + + +def test_ancestors_have_handlers_rejects_target_for_non_stream( + clean_logger: logging.Logger, +) -> None: + with pytest.raises(ValueError, match="target_stream can only be specified"): + handlers_mod.ancestors_have_handlers( + clean_logger, + True, + logging.NullHandler, + target_stream=handlers_mod.STDOUT_HANDLER_SPEC.target_stream, + ) + + +def test_ancestors_have_handlers_detects_parent_handler( + parent_child_loggers: tuple[logging.Logger, logging.Logger], +) -> None: + parent, child = parent_child_loggers + parent.addHandler(logging.NullHandler()) + + assert ( + handlers_mod.ancestors_have_handlers(child, True, logging.NullHandler) + is True + ) + + +def test_check_parent_handlers_raises_loggerhandlererror( + parent_child_loggers: tuple[logging.Logger, logging.Logger], +) -> None: + parent, child = parent_child_loggers + parent.addHandler(logging.NullHandler()) + + with pytest.raises(LoggerHandlerError): + handlers_mod.check_parent_handlers(child, True, logging.NullHandler) + + +def test_logger_or_ancestors_have_handler_checks_local_then_parent( + parent_child_loggers: tuple[logging.Logger, logging.Logger], +) -> None: + parent, child = parent_child_loggers + assert ( + handlers_mod.logger_or_ancestors_have_handler( + child, True, logging.NullHandler + ) + is False + ) + + parent.addHandler(logging.NullHandler()) + assert ( + handlers_mod.logger_or_ancestors_have_handler( + child, True, logging.NullHandler + ) + is True + ) + + +def test_get_handler_specs_returns_expected_specs() -> None: + assert len(handlers_mod.get_handler_specs(HandlerType.Rich)) == 1 + assert len(handlers_mod.get_handler_specs(HandlerType.Lstdout)) == 1 + assert len(handlers_mod.get_handler_specs(HandlerType.Lstderr)) == 1 + assert len(handlers_mod.get_handler_specs(HandlerType.Stream)) == 2 + assert len(handlers_mod.get_handler_specs(HandlerType.File)) == 1 + assert len(handlers_mod.get_handler_specs(HandlerType.Protobufstream)) == 1 + + +def test_build_rich_handler_uses_get_width_when_missing( + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.setattr(handlers_mod, "get_width", lambda: 111) + handler = handlers_mod._build_rich_handler() + assert isinstance(handler, FormattedRichHandler) + assert handler.console.width == 111 + + +def test_build_stdout_handler_sets_formatter() -> None: + handler = handlers_mod._build_stdout_handler() + assert isinstance(handler, logging.StreamHandler) + assert handler.stream is handlers_mod.STDOUT_HANDLER_SPEC.target_stream + assert isinstance(handler.formatter, LoggingFormatter) + + +def test_build_stderr_handler_sets_level_and_formatter() -> None: + handler = handlers_mod._build_stderr_handler() + assert isinstance(handler, logging.StreamHandler) + assert handler.stream is handlers_mod.STDERR_HANDLER_SPEC.target_stream + assert handler.level == logging.ERROR + assert isinstance(handler.formatter, LoggingFormatter) + + +def test_build_file_handler_requires_path() -> None: + with pytest.raises(ValueError, match="path is required"): + handlers_mod._build_file_handler() + + +def test_build_file_handler_creates_handler_with_formatter( + tmp_path: pytest.TempPathFactory, +) -> None: + file_path = tmp_path / "test.log" + handler = handlers_mod._build_file_handler(path=str(file_path)) + assert isinstance(handler, logging.FileHandler) + assert isinstance(handler.formatter, LoggingFormatter) + handler.close() + + +def test_build_erskafka_handler_wraps_exception( + monkeypatch: pytest.MonkeyPatch, +) -> None: + def _raise(*args: object, **kwargs: object) -> None: + del args, kwargs + raise RuntimeError("boom") + + monkeypatch.setattr(handlers_mod, "ERSKafkaLogHandler", _raise) + with pytest.raises(ERSInitError): + handlers_mod._build_erskafka_handler(session_name="s1") + + +def test_build_erskafka_handler_success_passes_arguments( + monkeypatch: pytest.MonkeyPatch, +) -> None: + class FakeKafkaHandler: + def __init__(self, **kwargs: object) -> None: + self.kwargs = kwargs + + monkeypatch.setattr(handlers_mod, "ERSKafkaLogHandler", FakeKafkaHandler) + handler = handlers_mod._build_erskafka_handler( + session_name="session_x", + topic="topic_x", + address="addr_x", + ers_app_name="app_x", + ) + + assert isinstance(handler, FakeKafkaHandler) + assert handler.kwargs["session"] == "session_x" + assert handler.kwargs["kafka_address"] == "addr_x" + assert handler.kwargs["kafka_topic"] == "topic_x" + assert handler.kwargs["app_name"] == "app_x" + + +def test_add_handler_adds_single_spec_and_handleidfilter( + clean_logger: logging.Logger, +) -> None: + handlers_mod.add_handler(clean_logger, HandlerType.Rich, use_parent_handlers=True) + + assert len(clean_logger.handlers) == 1 + assert isinstance(clean_logger.handlers[0], FormattedRichHandler) + assert any( + isinstance(logger_filter, HandleIDFilter) + for logger_filter in clean_logger.handlers[0].filters + ) + + +def test_add_handler_skips_when_matching_handler_exists( + clean_logger: logging.Logger, +) -> None: + handlers_mod.add_handler(clean_logger, HandlerType.Rich, use_parent_handlers=True) + handlers_mod.add_handler(clean_logger, HandlerType.Rich, use_parent_handlers=True) + assert len(clean_logger.handlers) == 1 + + +def test_add_handler_skips_when_parent_has_handler( + parent_child_loggers: tuple[logging.Logger, logging.Logger], +) -> None: + parent, child = parent_child_loggers + handlers_mod.add_handler(parent, HandlerType.Rich, use_parent_handlers=True) + handlers_mod.add_handler(child, HandlerType.Rich, use_parent_handlers=True) + + assert len(parent.handlers) == 1 + assert len(child.handlers) == 0 + + +def test_add_handler_accepts_string_type(clean_logger: logging.Logger) -> None: + handlers_mod.add_handler(clean_logger, "rich", use_parent_handlers=True) + assert len(clean_logger.handlers) == 1 + + +def test_add_handler_unknown_string_does_nothing(clean_logger: logging.Logger) -> None: + handlers_mod.add_handler(clean_logger, "unknown_type", use_parent_handlers=True) + assert len(clean_logger.handlers) == 0 + + +def test_add_handler_uses_explicit_fallback_override( + clean_logger: logging.Logger, +) -> None: + override = {HandlerType.Unknown} + handlers_mod.add_handler( + clean_logger, + HandlerType.Rich, + use_parent_handlers=True, + fallback_handler=override, + ) + + handler_filter = next( + logger_filter + for logger_filter in clean_logger.handlers[0].filters + if isinstance(logger_filter, HandleIDFilter) + ) + assert handler_filter.fallback_handlers == override + + +def test_add_handler_for_stream_adds_stdout_and_stderr( + clean_logger: logging.Logger, +) -> None: + handlers_mod.add_handler(clean_logger, HandlerType.Stream, use_parent_handlers=True) + stream_handlers = [ + handler + for handler in clean_logger.handlers + if isinstance(handler, logging.StreamHandler) + ] + assert len(stream_handlers) == 2 + + +def test_add_handlers_from_types_stream_deduplicates( + clean_logger: logging.Logger, +) -> None: + handlers_mod.add_handlers_from_types( + clean_logger, + {HandlerType.Stream, HandlerType.Lstdout, HandlerType.Lstderr}, + use_parent_handlers=True, + fallback_handlers={HandlerType.Stream}, + ) + stream_handlers = [ + handler + for handler in clean_logger.handlers + if isinstance(handler, logging.StreamHandler) + ] + assert len(stream_handlers) == 2 + + +def test_add_handlers_from_types_routes_to_filter_spec( + clean_logger: logging.Logger, + monkeypatch: pytest.MonkeyPatch, +) -> None: + add_filter_mock = MagicMock() + monkeypatch.setattr(handlers_mod, "add_filter", add_filter_mock) + + handlers_mod.add_handlers_from_types( + clean_logger, + {HandlerType.Throttle}, + use_parent_handlers=True, + fallback_handlers={HandlerType.Throttle}, + ) + + add_filter_mock.assert_called_once() + + +def test_add_handlers_from_types_no_duplicate_filter( + clean_logger: logging.Logger, + monkeypatch: pytest.MonkeyPatch, +) -> None: + clean_logger.addFilter(MagicMock(spec=handlers_mod.get_filter_spec(HandlerType.Throttle).filter_class)) + add_filter_mock = MagicMock() + monkeypatch.setattr(handlers_mod, "add_filter", add_filter_mock) + + handlers_mod.add_handlers_from_types( + clean_logger, + {HandlerType.Throttle}, + use_parent_handlers=True, + fallback_handlers={HandlerType.Throttle}, + ) + + add_filter_mock.assert_not_called() + + +# demonstrator test_* parity integrated into handlers tests + +def test_demo_test_main_functions_emits_expected_levels() -> None: + logger = MagicMock(spec=logging.Logger) + + demo.test_main_functions(logger) + + logger.debug.assert_called_once() + assert logger.info.call_count >= 2 + assert logger.warning.call_count >= 2 + logger.error.assert_called_once() + logger.critical.assert_called_once() + + +def test_demo_test_child_logger_builds_child_and_logs( + monkeypatch: pytest.MonkeyPatch, + tmp_path: pytest.TempPathFactory, +) -> None: + child_logger = MagicMock(spec=logging.Logger) + get_logger_mock = MagicMock(return_value=child_logger) + monkeypatch.setattr(demo, "get_daq_logger", get_logger_mock) + + demo.test_child_logger( + logger_name="parent.logger", + log_level="INFO", + disable_logger_inheritance=True, + rich_handler=True, + file_handler_path=str(tmp_path / "demo.log"), + stream_handlers=True, + ) + + get_logger_mock.assert_called_once_with( + logger_name="parent.logger.child", + log_level="INFO", + use_parent_handlers=False, + rich_handler=True, + file_handler_path=str(tmp_path / "demo.log"), + stream_handlers=True, + ) + child_logger.debug.assert_called_once() + child_logger.info.assert_called() + child_logger.warning.assert_called() + child_logger.error.assert_called_once() + child_logger.critical.assert_called_once() + + +def test_demo_test_throttle_uses_throttle_extra_and_sleep( + monkeypatch: pytest.MonkeyPatch, +) -> None: + logger = MagicMock(spec=logging.Logger) + sleep_mock = MagicMock() + monkeypatch.setattr(demo.time, "sleep", sleep_mock) + + demo.test_throttle(logger) + + sleep_mock.assert_called_once_with(31) + logger.warning.assert_called_once_with("Sleeping for 30 seconds") + assert logger.info.call_count == 1050 + + first_call_kwargs = logger.info.call_args_list[0].kwargs + assert first_call_kwargs["extra"]["handlers"] == [ + HandlerType.Rich, + HandlerType.Throttle, + ] + + +def test_demo_test_handlertypes_routes_expected_extras() -> None: + logger = MagicMock(spec=logging.Logger) + + demo.test_handlertypes(logger) + + critical_calls = logger.critical.call_args_list + assert any( + c.kwargs.get("extra", {}).get("handlers") == [HandlerType.Rich] + for c in critical_calls + ) + assert any( + c.kwargs.get("extra", {}).get("handlers") == [HandlerType.File] + for c in critical_calls + ) + assert any( + c.kwargs.get("extra", {}).get("handlers") == [HandlerType.Lstdout] + for c in critical_calls + ) + assert any( + c.kwargs.get("extra", {}).get("handlers") == [HandlerType.Throttle] + for c in critical_calls + ) + assert any( + c.kwargs.get("extra", {}).get("handlers") + == [HandlerType.Rich, HandlerType.Protobufstream] + for c in critical_calls + ) + + +def test_demo_test_fallback_handlers_calls_add_handler( + monkeypatch: pytest.MonkeyPatch, +) -> None: + logger = MagicMock(spec=logging.Logger) + get_logger_mock = MagicMock(return_value=logger) + add_handler_mock = MagicMock() + + monkeypatch.setattr(demo, "get_daq_logger", get_logger_mock) + monkeypatch.setattr(demo, "add_handler", add_handler_mock) + + demo.test_fallback_handlers("DEBUG") + + get_logger_mock.assert_called_once_with( + logger_name="fallback_logger", + log_level="DEBUG", + stream_handlers=False, + rich_handler=True, + ) + add_handler_mock.assert_has_calls( + [ + call(logger, HandlerType.Lstdout, True), + call( + logger, + HandlerType.Lstderr, + True, + fallback_handler={HandlerType.Unknown}, + ), + ] + ) diff --git a/tests/logging/test_logger.py b/tests/logging/test_logger.py index ce7db56..a7c8995 100644 --- a/tests/logging/test_logger.py +++ b/tests/logging/test_logger.py @@ -4,9 +4,19 @@ import pytest +from daqpytools.logging import logger as logger_mod from daqpytools.logging.exceptions import LoggerSetupError +from daqpytools.logging.handlerconf import ( + ERSPyLogHandlerConf, + HandlerType, + ProtobufConf, +) from daqpytools.logging.handlers import logger_or_ancestors_have_handler -from daqpytools.logging.logger import get_daq_logger, setup_root_logger +from daqpytools.logging.logger import ( + get_daq_logger, + setup_daq_ers_logger, + setup_root_logger, +) test_logger_name = "test_logger" test_logger_child_name = f"{test_logger_name}.child" @@ -225,3 +235,63 @@ def test_logger_parent_walk_handles_mock_logger_cycle(): logger_or_ancestors_have_handler(fake_logger, True, logging.NullHandler) is False ) + + +def test_setup_daq_ers_logger_uses_single_protobuf_config( + monkeypatch: pytest.MonkeyPatch, +) -> None: + logger = logging.getLogger(f"test.logger.ers.{id(object())}") + add_handlers_mock = MagicMock() + monkeypatch.setattr(logger_mod, "add_handlers_from_types", add_handlers_mock) + + oks_conf = { + "DUNEDAQ_ERS_ERROR": ERSPyLogHandlerConf( + handlers=[HandlerType.Rich, HandlerType.Protobufstream], + protobufconf=ProtobufConf(url="host-a", port=30092), + ), + "DUNEDAQ_ERS_WARNING": ERSPyLogHandlerConf( + handlers=[HandlerType.Throttle], + protobufconf=ProtobufConf(url="host-a", port=30092), + ), + } + monkeypatch.setattr( + logger_mod.LogHandlerConf, + "_get_oks_conf", + staticmethod(lambda: oks_conf), + ) + + setup_daq_ers_logger(logger, ers_kafka_session="session-a", ers_app_name="app-a") + + add_handlers_mock.assert_called_once_with( + logger, + {HandlerType.Rich, HandlerType.Protobufstream, HandlerType.Throttle}, + use_parent_handlers=True, + fallback_handlers={HandlerType.Unknown}, + session_name="session-a", + ers_app_name="app-a", + address="host-a:30092", + ) + + +def test_setup_daq_ers_logger_rejects_multiple_protobuf_configs( + monkeypatch: pytest.MonkeyPatch, +) -> None: + logger = logging.getLogger(f"test.logger.ers.multi.{id(object())}") + oks_conf = { + "DUNEDAQ_ERS_ERROR": ERSPyLogHandlerConf( + handlers=[HandlerType.Protobufstream], + protobufconf=ProtobufConf(url="host-a", port=30092), + ), + "DUNEDAQ_ERS_WARNING": ERSPyLogHandlerConf( + handlers=[HandlerType.Protobufstream], + protobufconf=ProtobufConf(url="host-b", port=30093), + ), + } + monkeypatch.setattr( + logger_mod.LogHandlerConf, + "_get_oks_conf", + staticmethod(lambda: oks_conf), + ) + + with pytest.raises(ValueError, match="Multiple protobufstream"): + setup_daq_ers_logger(logger, ers_kafka_session="session-a") diff --git a/tests/logging/test_routing.py b/tests/logging/test_routing.py new file mode 100644 index 0000000..1ebb818 --- /dev/null +++ b/tests/logging/test_routing.py @@ -0,0 +1,166 @@ +import logging + +from daqpytools.logging.handlerconf import ERSPyLogHandlerConf, HandlerType, StreamType +from daqpytools.logging.routing import ( + AllowedHandlersStrategy, + DefaultAllowedHandlerStrategy, + ERSAllowedHandlersStrategy, + StreamAwareAllowedHandlersStrategy, +) + + +class _StrategyForHelper(AllowedHandlersStrategy): + def resolve( + self, + record: logging.LogRecord, + fallback_handlers: set[object], + ) -> set[object] | None: + del record, fallback_handlers + return None + + +def _record(level: int = logging.INFO) -> logging.LogRecord: + return logging.LogRecord( + name="test.routing", + level=level, + pathname="", + lineno=10, + msg="message", + args=(), + exc_info=None, + ) + + +def test_safe_return_set_filters_out_none() -> None: + strategy = _StrategyForHelper() + assert strategy.safe_return_set({None, HandlerType.Rich}) == {HandlerType.Rich} + + +def test_safe_return_set_returns_empty_set_when_all_none() -> None: + strategy = _StrategyForHelper() + assert strategy.safe_return_set({None}) == set() + + +def test_default_strategy_uses_record_handlers_when_present() -> None: + strategy = DefaultAllowedHandlerStrategy() + record = _record() + record.handlers = {HandlerType.Rich, None} + + assert strategy.resolve(record, {HandlerType.File}) == {HandlerType.Rich} + + +def test_default_strategy_uses_fallback_when_handlers_missing() -> None: + strategy = DefaultAllowedHandlerStrategy() + record = _record() + + assert strategy.resolve(record, {HandlerType.File}) == {HandlerType.File} + + +def test_default_strategy_returns_none_when_handlers_attr_is_none() -> None: + strategy = DefaultAllowedHandlerStrategy() + record = _record() + record.handlers = None + + assert strategy.resolve(record, {HandlerType.File}) is None + + +def test_ers_strategy_returns_none_when_level_not_mapped() -> None: + strategy = ERSAllowedHandlersStrategy() + record = _record(level=25) + record.stream = StreamType.ERS + record.ers_handlers = {} + + assert strategy.resolve(record, set()) is None + + +def test_ers_strategy_returns_none_without_ers_handlers() -> None: + strategy = ERSAllowedHandlersStrategy() + record = _record(level=logging.ERROR) + record.stream = StreamType.ERS + + assert strategy.resolve(record, set()) is None + + +def test_ers_strategy_returns_none_when_level_conf_missing() -> None: + strategy = ERSAllowedHandlersStrategy() + record = _record(level=logging.ERROR) + record.stream = StreamType.ERS + record.ers_handlers = { + "DUNEDAQ_ERS_WARNING": ERSPyLogHandlerConf(handlers=[HandlerType.Rich]) + } + + assert strategy.resolve(record, set()) is None + + +def test_ers_strategy_returns_handler_set_when_valid() -> None: + strategy = ERSAllowedHandlersStrategy() + record = _record(level=logging.ERROR) + record.stream = StreamType.ERS + record.ers_handlers = { + "DUNEDAQ_ERS_ERROR": ERSPyLogHandlerConf( + handlers=[HandlerType.Throttle, None], + ) + } + + assert strategy.resolve(record, set()) == {HandlerType.Throttle} + + +class _FakeDefault: + def __init__(self) -> None: + self.called = False + + def resolve( + self, + record: logging.LogRecord, + fallback_handlers: set[object], + ) -> set[object] | None: + del record, fallback_handlers + self.called = True + return {HandlerType.File} + + +class _FakeERS: + def __init__(self) -> None: + self.called = False + + def resolve( + self, + record: logging.LogRecord, + fallback_handlers: set[object], + ) -> set[object] | None: + del record, fallback_handlers + self.called = True + return {HandlerType.Throttle} + + +def test_streamaware_uses_ers_strategy_for_ers_stream() -> None: + default = _FakeDefault() + ers = _FakeERS() + strategy = StreamAwareAllowedHandlersStrategy( + default_strategy=default, ers_strategy=ers + ) + + record = _record(level=logging.ERROR) + record.stream = StreamType.ERS + + result = strategy.resolve(record, {HandlerType.Rich}) + + assert result == {HandlerType.Throttle} + assert ers.called is True + assert default.called is False + + +def test_streamaware_uses_default_strategy_for_non_ers_stream() -> None: + default = _FakeDefault() + ers = _FakeERS() + strategy = StreamAwareAllowedHandlersStrategy( + default_strategy=default, ers_strategy=ers + ) + + record = _record(level=logging.INFO) + + result = strategy.resolve(record, {HandlerType.Rich}) + + assert result == {HandlerType.File} + assert default.called is True + assert ers.called is False diff --git a/tests/logging/test_specs.py b/tests/logging/test_specs.py new file mode 100644 index 0000000..74a57b5 --- /dev/null +++ b/tests/logging/test_specs.py @@ -0,0 +1,95 @@ +import logging +from dataclasses import FrozenInstanceError + +import pytest + +from daqpytools.logging.specs import FilterSpec, HandlerSpec + + +def _handler_factory(**kwargs: object) -> logging.Handler: + del kwargs + return logging.NullHandler() + + +def _filter_factory( + fallback_handlers: set[object], extras: dict[str, object] +) -> logging.Filter: + del fallback_handlers, extras + return logging.Filter() + + +def test_handlerspec_is_frozen() -> None: + spec = HandlerSpec( + alias="rich", + handler_class=logging.NullHandler, + factory=_handler_factory, + fallback_types=("rich",), + ) + + with pytest.raises(FrozenInstanceError): + spec.alias = "stream" + + +def test_handlerspec_stores_target_stream_optional() -> None: + spec_without = HandlerSpec( + alias="a", + handler_class=logging.NullHandler, + factory=_handler_factory, + fallback_types=("a",), + ) + assert spec_without.target_stream is None + + stream = object() + spec_with = HandlerSpec( + alias="b", + handler_class=logging.StreamHandler, + factory=_handler_factory, + fallback_types=("b",), + target_stream=stream, + ) + assert spec_with.target_stream is stream + + +def test_handlerspec_factory_signature_compatible() -> None: + spec = HandlerSpec( + alias="rich", + handler_class=logging.NullHandler, + factory=_handler_factory, + fallback_types=("rich",), + ) + handler = spec.factory(width=120) + assert isinstance(handler, logging.NullHandler) + + +def test_filterspec_is_frozen() -> None: + spec = FilterSpec( + alias="throttle", + filter_class=logging.Filter, + factory=_filter_factory, + ) + + with pytest.raises(FrozenInstanceError): + spec.alias = "x" + + +def test_filterspec_defaults_fallback_types_to_empty_tuple() -> None: + spec = FilterSpec( + alias="throttle", + filter_class=logging.Filter, + factory=_filter_factory, + ) + assert spec.fallback_types == () + + +def test_filterspec_accepts_factory_and_alias() -> None: + spec = FilterSpec( + alias="throttle", + filter_class=logging.Filter, + factory=_filter_factory, + fallback_types=("throttle",), + ) + + assert spec.alias == "throttle" + assert spec.filter_class is logging.Filter + assert spec.fallback_types == ("throttle",) + assert isinstance(spec.factory(set(), {}), logging.Filter)