From b2e2f5a07892380475eb7b7a8fa2eaa8259bb6ab Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 16:41:26 -0700 Subject: [PATCH 01/16] Add extra tests --- .../unit/utilities/test_utilities_logs.py | 427 +++++++++++++++++- 1 file changed, 421 insertions(+), 6 deletions(-) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index 5ed3d4eca..adec91e90 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -1,5 +1,7 @@ -"""Test COMPASS Ordinance logging logic.""" +"""Test COMPASS Ordinance logging logic""" +import sys +import json import logging import asyncio from pathlib import Path @@ -7,12 +9,24 @@ import pytest from compass.services.provider import RunningAsyncServices -from compass.utilities.logs import LocationFileLog, LogListener +from compass.utilities.logs import ( + AddLocationFilter, + ExceptionOnlyFilter, + LocationFileLog, + LocationFilter, + LogListener, + NoLocationFilter, + _JsonExceptionFileHandler, + _JsonFormatter, + _LocalProcessQueueHandler, + _setup_logging_levels, + LOGGING_QUEUE, +) @pytest.mark.asyncio async def test_logs_sent_to_separate_files(tmp_path, service_base_class): - """Test that logs are correctly sent to individual files.""" + """Test that logs are correctly sent to individual files""" logger = logging.getLogger("ords") test_locations = ["a", "bc", "def", "ghij"] @@ -21,18 +35,18 @@ async def test_logs_sent_to_separate_files(tmp_path, service_base_class): assert not logger.handlers class AlwaysThreeService(TestService): - """Test service that returns ``3``.""" + """Test service that returns ``3``""" NUMBER = 3 LEN_SLEEP = 0.1 async def process_single(val): - """Call `AlwaysThreeService`.""" + """Call `AlwaysThreeService`""" logger.info(f"This location is {val!r}") return await AlwaysThreeService.call(len(val)) async def process_location_with_logs(listener, log_dir, location): - """Process location and record logs for tests.""" + """Process location and record logs for tests""" with LocationFileLog(listener, log_dir, location=location): logger.info("A generic test log") return await process_single(location) @@ -64,5 +78,406 @@ async def process_location_with_logs(listener, log_dir, location): assert f"This location is {loc!r}" in log_text +def test_no_location_filter(): + """Test NoLocationFilter correctly identifies records without location""" + filter_obj = NoLocationFilter() + + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + ) + assert filter_obj.filter(record) + + record.location = None + assert filter_obj.filter(record) + + record.location = "Task-42" + assert filter_obj.filter(record) + + record.location = "main" + assert filter_obj.filter(record) + + record.location = "El Paso Colorado" + assert not filter_obj.filter(record) + + +def test_location_filter(): + """Test LocationFilter correctly filters records by specific location""" + location = "El Paso Colorado" + filter_obj = LocationFilter(location) + + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + ) + record.location = location + assert filter_obj.filter(record) + + record.location = "Denver Colorado" + assert not filter_obj.filter(record) + + record_no_loc = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + ) + assert not filter_obj.filter(record_no_loc) + + record.location = None + assert not filter_obj.filter(record) + + +@pytest.mark.asyncio +async def test_add_location_filter_with_async_task(): + """Test AddLocationFilter adds location from async task name""" + filter_obj = AddLocationFilter() + + async def task_with_name(): + await asyncio.sleep(0) + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + ) + result = filter_obj.filter(record) + assert result + assert hasattr(record, "location") + assert record.location == "test_location" + return True + + task = asyncio.create_task(task_with_name(), name="test_location") + await task + + +def test_add_location_filter_without_async_task(): + """Test AddLocationFilter defaults to 'main' when no async task""" + filter_obj = AddLocationFilter() + + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + ) + result = filter_obj.filter(record) + assert result + assert hasattr(record, "location") + assert record.location == "main" + + +@pytest.mark.asyncio +async def test_add_location_filter_with_task_xx(): + """Test AddLocationFilter defaults to 'main' for Task-XX names""" + filter_obj = AddLocationFilter() + + async def task_with_generic_name(): + await asyncio.sleep(0) + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + ) + result = filter_obj.filter(record) + assert result + assert hasattr(record, "location") + assert record.location == "main" + return True + + task = asyncio.create_task(task_with_generic_name(), name="Task-42") + await task + + +def test_exception_only_filter(): + """Test ExceptionOnlyFilter only passes through exception records""" + filter_obj = ExceptionOnlyFilter() + + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + ) + assert not filter_obj.filter(record) + + try: + raise ValueError("test error") + except ValueError: + record.exc_info = sys.exc_info() + + assert filter_obj.filter(record) + + # TODO: Add a check that filter_obj does not capture normal records without exc_info + + +def test_json_formatter(): + """Test _JsonFormatter correctly formats log records to dictionaries""" + formatter = _JsonFormatter() + + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=42, + msg="test message", + args=(), + exc_info=None, + func="test_func", + ) + record.taskName = "test_task" + + result = formatter.format(record) + assert isinstance(result, dict) + assert result["message"] == "test message" + assert result["filename"] == "test.py" + assert result["funcName"] == "test_func" + assert result["taskName"] == "test_task" + assert result["lineno"] == 42 + assert result["exc_info"] is None + assert result["exc_text"] is None + assert "timestamp" in result + + +def test_json_formatter_with_exception(): + """Test _JsonFormatter correctly formats exception information""" + formatter = _JsonFormatter() + + record = logging.LogRecord( + name="test", + level=logging.ERROR, + pathname="test.py", + lineno=42, + msg="test error", + args=(), + exc_info=None, + func="test_func", + ) + record.taskName = "test_task" + + try: + raise ValueError("custom error message") + except ValueError: + record.exc_info = sys.exc_info() + + result = formatter.format(record) + assert isinstance(result, dict) + assert result["exc_info"] == "ValueError" + assert result["exc_text"] == "custom error message" + + +def test_json_formatter_truncates_long_messages(): + """Test _JsonFormatter truncates messages longer than 103 chars""" + formatter = _JsonFormatter() + + long_message = "a" * 200 + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=42, + msg=long_message, + args=(), + exc_info=None, + func="test_func", + ) + record.taskName = "test_task" + + result = formatter.format(record) + assert len(result["message"]) == 103 + assert result["message"] == "a" * 103 + + +def test_json_exception_file_handler_initialization(tmp_path): + """Test _JsonExceptionFileHandler initializes correctly""" + test_file = tmp_path / "test_exceptions.json" + + handler = _JsonExceptionFileHandler(test_file) + + assert handler.filename == test_file + assert test_file.exists() + + content = json.loads(test_file.read_text(encoding="utf-8")) + assert content == {} + + assert handler.level == logging.ERROR + assert any(isinstance(f, ExceptionOnlyFilter) for f in handler.filters) + + handler.close() + + +def test_json_exception_file_handler_emit(tmp_path): + """Test _JsonExceptionFileHandler correctly writes exceptions to JSON""" + test_file = tmp_path / "test_exceptions.json" + handler = _JsonExceptionFileHandler(test_file) + + record = logging.LogRecord( + name="test", + level=logging.ERROR, + pathname="test.py", + lineno=42, + msg="test error", + args=(), + exc_info=None, + func="test_func", + ) + record.taskName = "test_task" + record.module = "test_module" + + try: + raise ValueError("test exception") + except ValueError: + record.exc_info = sys.exc_info() + + handler.emit(record) + handler.close() + + content = json.loads(test_file.read_text(encoding="utf-8")) + assert "test_module" in content + assert "ValueError" in content["test_module"] + assert len(content["test_module"]["ValueError"]) == 1 + + entry = content["test_module"]["ValueError"][0] + assert entry["message"] == "test error" + assert entry["exc_text"] == "test exception" + assert entry["filename"] == "test.py" + assert entry["funcName"] == "test_func" + assert entry["lineno"] == 42 + + +def test_json_exception_file_handler_multiple_exceptions(tmp_path): + """Test _JsonExceptionFileHandler handles multiple exceptions""" + test_file = tmp_path / "test_exceptions.json" + handler = _JsonExceptionFileHandler(test_file) + + for i in range(3): + record = logging.LogRecord( + name="test", + level=logging.ERROR, + pathname="test.py", + lineno=i, + msg=f"error {i}", + args=(), + exc_info=None, + func="test_func", + ) + record.taskName = "test_task" + record.module = "test_module" + + try: + msg = f"exception {i}" + raise ValueError(msg) + except ValueError: + record.exc_info = sys.exc_info() + + handler.emit(record) + + handler.close() + + content = json.loads(test_file.read_text(encoding="utf-8")) + assert len(content["test_module"]["ValueError"]) == 3 + + +def test_setup_logging_levels(): + """Test _setup_logging_levels adds custom logging levels""" + _setup_logging_levels() + + assert hasattr(logging, "TRACE") + assert logging.TRACE == 5 + assert logging.getLevelName(logging.TRACE) == "TRACE" + + assert hasattr(logging, "DEBUG_TO_FILE") + assert logging.DEBUG_TO_FILE == 9 + assert logging.getLevelName(logging.DEBUG_TO_FILE) == "DEBUG_TO_FILE" + + logger = logging.getLogger("test_custom_levels") + assert hasattr(logger, "trace") + assert hasattr(logger, "debug_to_file") + assert callable(logger.trace) + assert callable(logger.debug_to_file) + + +def test_local_process_queue_handler_emit(): + """Test _LocalProcessQueueHandler correctly enqueues records""" + handler = _LocalProcessQueueHandler(LOGGING_QUEUE) + + while not LOGGING_QUEUE.empty(): + LOGGING_QUEUE.get() + + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="test.py", + lineno=42, + msg="test message", + args=(), + exc_info=None, + func="test_func", + ) + + handler.emit(record) + + assert not LOGGING_QUEUE.empty() + queued_record = LOGGING_QUEUE.get() + assert queued_record.msg == "test message" + + +def test_log_listener_context_manager(): + """Test LogListener as a context manager""" + logger_name = "test_listener_logger" + logger = logging.getLogger(logger_name) + + logger.handlers = [] + + with LogListener([logger_name], level="DEBUG") as listener: + assert len(logger.handlers) == 1 + assert listener._listener is not None + + assert len(logger.handlers) == 0 + + +@pytest.mark.asyncio +async def test_log_listener_async_context_manager(): + """Test LogListener as an async context manager""" + logger_name = "test_async_listener_logger" + logger = logging.getLogger(logger_name) + + logger.handlers = [] + + async with LogListener([logger_name], level="INFO") as listener: + assert len(logger.handlers) == 1 + assert listener._listener is not None + + assert len(logger.handlers) == 0 + + # TODO: Add case of logger emitting a record + + if __name__ == "__main__": pytest.main(["-q", "--show-capture=all", Path(__file__), "-rapP"]) From 1fbc58505e0166a9738bdc290c90b9bd9121a2ec Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 16:45:22 -0700 Subject: [PATCH 02/16] Enhance async log listener test to capture emitted log records --- .../unit/utilities/test_utilities_logs.py | 24 +++++++++++++++++-- 1 file changed, 22 insertions(+), 2 deletions(-) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index adec91e90..418c9ae21 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -474,9 +474,29 @@ async def test_log_listener_async_context_manager(): assert len(logger.handlers) == 1 assert listener._listener is not None - assert len(logger.handlers) == 0 + captured_records = [] + + class _CaptureHandler(logging.Handler): + def emit(self, record): + captured_records.append(record) + + capture_handler = _CaptureHandler(level=logging.INFO) + listener.addHandler(capture_handler) + + logger.info("async listener message") - # TODO: Add case of logger emitting a record + for _ in range(30): + if captured_records: + break + await asyncio.sleep(0.1) + + listener.removeHandler(capture_handler) + + assert captured_records + assert captured_records[0].msg == "async listener message" + assert getattr(captured_records[0], "location", None) == "main" + + assert len(logger.handlers) == 0 if __name__ == "__main__": From 20dd2a04c3e60913d244ac000a2d36aa222cf828 Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 16:47:10 -0700 Subject: [PATCH 03/16] Add check to exception filter for non-exception records --- tests/python/unit/utilities/test_utilities_logs.py | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index 418c9ae21..57812c5b5 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -233,8 +233,16 @@ def test_exception_only_filter(): record.exc_info = sys.exc_info() assert filter_obj.filter(record) - - # TODO: Add a check that filter_obj does not capture normal records without exc_info + non_exception_record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="plain", + args=(), + exc_info=None, + ) + assert not filter_obj.filter(non_exception_record) def test_json_formatter(): From ec99bbb369dddae90d4fff04e88c5db58daeb188 Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 16:51:13 -0700 Subject: [PATCH 04/16] Refactor log record creation in tests to use a factory function --- .../unit/utilities/test_utilities_logs.py | 168 ++++++------------ 1 file changed, 57 insertions(+), 111 deletions(-) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index 57812c5b5..b10ef6719 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -24,6 +24,35 @@ ) +@pytest.fixture +def log_record_factory(): + """Return a factory for creating base log records used in tests""" + + def _make( + *, + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + func=None, + ): + return logging.LogRecord( + name=name, + level=level, + pathname=pathname, + lineno=lineno, + msg=msg, + args=args, + exc_info=exc_info, + func=func, + ) + + return _make + + @pytest.mark.asyncio async def test_logs_sent_to_separate_files(tmp_path, service_base_class): """Test that logs are correctly sent to individual files""" @@ -78,19 +107,11 @@ async def process_location_with_logs(listener, log_dir, location): assert f"This location is {loc!r}" in log_text -def test_no_location_filter(): +def test_no_location_filter(log_record_factory): """Test NoLocationFilter correctly identifies records without location""" filter_obj = NoLocationFilter() - record = logging.LogRecord( - name="test", - level=logging.INFO, - pathname="", - lineno=0, - msg="test", - args=(), - exc_info=None, - ) + record = log_record_factory() assert filter_obj.filter(record) record.location = None @@ -106,35 +127,19 @@ def test_no_location_filter(): assert not filter_obj.filter(record) -def test_location_filter(): +def test_location_filter(log_record_factory): """Test LocationFilter correctly filters records by specific location""" location = "El Paso Colorado" filter_obj = LocationFilter(location) - record = logging.LogRecord( - name="test", - level=logging.INFO, - pathname="", - lineno=0, - msg="test", - args=(), - exc_info=None, - ) + record = log_record_factory() record.location = location assert filter_obj.filter(record) record.location = "Denver Colorado" assert not filter_obj.filter(record) - record_no_loc = logging.LogRecord( - name="test", - level=logging.INFO, - pathname="", - lineno=0, - msg="test", - args=(), - exc_info=None, - ) + record_no_loc = log_record_factory() assert not filter_obj.filter(record_no_loc) record.location = None @@ -142,21 +147,13 @@ def test_location_filter(): @pytest.mark.asyncio -async def test_add_location_filter_with_async_task(): +async def test_add_location_filter_with_async_task(log_record_factory): """Test AddLocationFilter adds location from async task name""" filter_obj = AddLocationFilter() async def task_with_name(): await asyncio.sleep(0) - record = logging.LogRecord( - name="test", - level=logging.INFO, - pathname="", - lineno=0, - msg="test", - args=(), - exc_info=None, - ) + record = log_record_factory() result = filter_obj.filter(record) assert result assert hasattr(record, "location") @@ -167,19 +164,11 @@ async def task_with_name(): await task -def test_add_location_filter_without_async_task(): +def test_add_location_filter_without_async_task(log_record_factory): """Test AddLocationFilter defaults to 'main' when no async task""" filter_obj = AddLocationFilter() - record = logging.LogRecord( - name="test", - level=logging.INFO, - pathname="", - lineno=0, - msg="test", - args=(), - exc_info=None, - ) + record = log_record_factory() result = filter_obj.filter(record) assert result assert hasattr(record, "location") @@ -187,21 +176,13 @@ def test_add_location_filter_without_async_task(): @pytest.mark.asyncio -async def test_add_location_filter_with_task_xx(): +async def test_add_location_filter_with_task_xx(log_record_factory): """Test AddLocationFilter defaults to 'main' for Task-XX names""" filter_obj = AddLocationFilter() async def task_with_generic_name(): await asyncio.sleep(0) - record = logging.LogRecord( - name="test", - level=logging.INFO, - pathname="", - lineno=0, - msg="test", - args=(), - exc_info=None, - ) + record = log_record_factory() result = filter_obj.filter(record) assert result assert hasattr(record, "location") @@ -212,19 +193,11 @@ async def task_with_generic_name(): await task -def test_exception_only_filter(): +def test_exception_only_filter(log_record_factory): """Test ExceptionOnlyFilter only passes through exception records""" filter_obj = ExceptionOnlyFilter() - record = logging.LogRecord( - name="test", - level=logging.INFO, - pathname="", - lineno=0, - msg="test", - args=(), - exc_info=None, - ) + record = log_record_factory() assert not filter_obj.filter(record) try: @@ -233,30 +206,18 @@ def test_exception_only_filter(): record.exc_info = sys.exc_info() assert filter_obj.filter(record) - non_exception_record = logging.LogRecord( - name="test", - level=logging.INFO, - pathname="", - lineno=0, - msg="plain", - args=(), - exc_info=None, - ) + non_exception_record = log_record_factory(msg="plain") assert not filter_obj.filter(non_exception_record) -def test_json_formatter(): +def test_json_formatter(log_record_factory): """Test _JsonFormatter correctly formats log records to dictionaries""" formatter = _JsonFormatter() - record = logging.LogRecord( - name="test", - level=logging.INFO, + record = log_record_factory( pathname="test.py", lineno=42, msg="test message", - args=(), - exc_info=None, func="test_func", ) record.taskName = "test_task" @@ -273,18 +234,15 @@ def test_json_formatter(): assert "timestamp" in result -def test_json_formatter_with_exception(): +def test_json_formatter_with_exception(log_record_factory): """Test _JsonFormatter correctly formats exception information""" formatter = _JsonFormatter() - record = logging.LogRecord( - name="test", + record = log_record_factory( level=logging.ERROR, pathname="test.py", lineno=42, msg="test error", - args=(), - exc_info=None, func="test_func", ) record.taskName = "test_task" @@ -300,19 +258,15 @@ def test_json_formatter_with_exception(): assert result["exc_text"] == "custom error message" -def test_json_formatter_truncates_long_messages(): +def test_json_formatter_truncates_long_messages(log_record_factory): """Test _JsonFormatter truncates messages longer than 103 chars""" formatter = _JsonFormatter() long_message = "a" * 200 - record = logging.LogRecord( - name="test", - level=logging.INFO, + record = log_record_factory( pathname="test.py", lineno=42, msg=long_message, - args=(), - exc_info=None, func="test_func", ) record.taskName = "test_task" @@ -340,19 +294,16 @@ def test_json_exception_file_handler_initialization(tmp_path): handler.close() -def test_json_exception_file_handler_emit(tmp_path): +def test_json_exception_file_handler_emit(tmp_path, log_record_factory): """Test _JsonExceptionFileHandler correctly writes exceptions to JSON""" test_file = tmp_path / "test_exceptions.json" handler = _JsonExceptionFileHandler(test_file) - record = logging.LogRecord( - name="test", + record = log_record_factory( level=logging.ERROR, pathname="test.py", lineno=42, msg="test error", - args=(), - exc_info=None, func="test_func", ) record.taskName = "test_task" @@ -379,20 +330,19 @@ def test_json_exception_file_handler_emit(tmp_path): assert entry["lineno"] == 42 -def test_json_exception_file_handler_multiple_exceptions(tmp_path): +def test_json_exception_file_handler_multiple_exceptions( + tmp_path, log_record_factory +): """Test _JsonExceptionFileHandler handles multiple exceptions""" test_file = tmp_path / "test_exceptions.json" handler = _JsonExceptionFileHandler(test_file) for i in range(3): - record = logging.LogRecord( - name="test", + record = log_record_factory( level=logging.ERROR, pathname="test.py", lineno=i, msg=f"error {i}", - args=(), - exc_info=None, func="test_func", ) record.taskName = "test_task" @@ -431,21 +381,17 @@ def test_setup_logging_levels(): assert callable(logger.debug_to_file) -def test_local_process_queue_handler_emit(): +def test_local_process_queue_handler_emit(log_record_factory): """Test _LocalProcessQueueHandler correctly enqueues records""" handler = _LocalProcessQueueHandler(LOGGING_QUEUE) while not LOGGING_QUEUE.empty(): LOGGING_QUEUE.get() - record = logging.LogRecord( - name="test", - level=logging.INFO, + record = log_record_factory( pathname="test.py", lineno=42, msg="test message", - args=(), - exc_info=None, func="test_func", ) From bfb4148619b120ca00e77f96894a221698ff7624 Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 16:53:10 -0700 Subject: [PATCH 05/16] Add helper fixture to attach ValueError exc_info to log records --- .../unit/utilities/test_utilities_logs.py | 49 +++++++++++-------- 1 file changed, 28 insertions(+), 21 deletions(-) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index b10ef6719..49a97844a 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -53,6 +53,19 @@ def _make( return _make +@pytest.fixture +def attach_value_error_exc_info(): + """Return a helper to attach ValueError exc_info to a log record""" + + def _attach(record, message): + try: + raise ValueError(message) + except ValueError: + record.exc_info = sys.exc_info() + + return _attach + + @pytest.mark.asyncio async def test_logs_sent_to_separate_files(tmp_path, service_base_class): """Test that logs are correctly sent to individual files""" @@ -193,17 +206,16 @@ async def task_with_generic_name(): await task -def test_exception_only_filter(log_record_factory): +def test_exception_only_filter( + log_record_factory, attach_value_error_exc_info +): """Test ExceptionOnlyFilter only passes through exception records""" filter_obj = ExceptionOnlyFilter() record = log_record_factory() assert not filter_obj.filter(record) - try: - raise ValueError("test error") - except ValueError: - record.exc_info = sys.exc_info() + attach_value_error_exc_info(record, "test error") assert filter_obj.filter(record) non_exception_record = log_record_factory(msg="plain") @@ -234,7 +246,9 @@ def test_json_formatter(log_record_factory): assert "timestamp" in result -def test_json_formatter_with_exception(log_record_factory): +def test_json_formatter_with_exception( + log_record_factory, attach_value_error_exc_info +): """Test _JsonFormatter correctly formats exception information""" formatter = _JsonFormatter() @@ -247,10 +261,7 @@ def test_json_formatter_with_exception(log_record_factory): ) record.taskName = "test_task" - try: - raise ValueError("custom error message") - except ValueError: - record.exc_info = sys.exc_info() + attach_value_error_exc_info(record, "custom error message") result = formatter.format(record) assert isinstance(result, dict) @@ -294,7 +305,9 @@ def test_json_exception_file_handler_initialization(tmp_path): handler.close() -def test_json_exception_file_handler_emit(tmp_path, log_record_factory): +def test_json_exception_file_handler_emit( + tmp_path, log_record_factory, attach_value_error_exc_info +): """Test _JsonExceptionFileHandler correctly writes exceptions to JSON""" test_file = tmp_path / "test_exceptions.json" handler = _JsonExceptionFileHandler(test_file) @@ -309,10 +322,7 @@ def test_json_exception_file_handler_emit(tmp_path, log_record_factory): record.taskName = "test_task" record.module = "test_module" - try: - raise ValueError("test exception") - except ValueError: - record.exc_info = sys.exc_info() + attach_value_error_exc_info(record, "test exception") handler.emit(record) handler.close() @@ -331,7 +341,7 @@ def test_json_exception_file_handler_emit(tmp_path, log_record_factory): def test_json_exception_file_handler_multiple_exceptions( - tmp_path, log_record_factory + tmp_path, log_record_factory, attach_value_error_exc_info ): """Test _JsonExceptionFileHandler handles multiple exceptions""" test_file = tmp_path / "test_exceptions.json" @@ -348,11 +358,8 @@ def test_json_exception_file_handler_multiple_exceptions( record.taskName = "test_task" record.module = "test_module" - try: - msg = f"exception {i}" - raise ValueError(msg) - except ValueError: - record.exc_info = sys.exc_info() + msg = f"exception {i}" + attach_value_error_exc_info(record, msg) handler.emit(record) From 3972ad58703dcd81992d1b98c7ef1a65203d3b36 Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 16:55:32 -0700 Subject: [PATCH 06/16] Refactor log record creation and exception handling in tests --- .../unit/utilities/test_utilities_logs.py | 126 ++++++++---------- 1 file changed, 55 insertions(+), 71 deletions(-) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index 49a97844a..6e30ae955 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -24,46 +24,38 @@ ) -@pytest.fixture -def log_record_factory(): - """Return a factory for creating base log records used in tests""" - - def _make( - *, - name="test", - level=logging.INFO, - pathname="", - lineno=0, - msg="test", - args=(), - exc_info=None, - func=None, - ): - return logging.LogRecord( - name=name, - level=level, - pathname=pathname, - lineno=lineno, - msg=msg, - args=args, - exc_info=exc_info, - func=func, - ) - - return _make - +def build_log_record( + *, + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + func=None, +): + """Create a base log record configured with common defaults""" + + return logging.LogRecord( + name=name, + level=level, + pathname=pathname, + lineno=lineno, + msg=msg, + args=args, + exc_info=exc_info, + func=func, + ) -@pytest.fixture -def attach_value_error_exc_info(): - """Return a helper to attach ValueError exc_info to a log record""" - def _attach(record, message): - try: - raise ValueError(message) - except ValueError: - record.exc_info = sys.exc_info() +def attach_value_error_exc_info(record, message): + """Attach ValueError exc_info to the provided log record""" - return _attach + try: + raise ValueError(message) + except ValueError: + record.exc_info = sys.exc_info() @pytest.mark.asyncio @@ -120,11 +112,11 @@ async def process_location_with_logs(listener, log_dir, location): assert f"This location is {loc!r}" in log_text -def test_no_location_filter(log_record_factory): +def test_no_location_filter(): """Test NoLocationFilter correctly identifies records without location""" filter_obj = NoLocationFilter() - record = log_record_factory() + record = build_log_record() assert filter_obj.filter(record) record.location = None @@ -140,19 +132,19 @@ def test_no_location_filter(log_record_factory): assert not filter_obj.filter(record) -def test_location_filter(log_record_factory): +def test_location_filter(): """Test LocationFilter correctly filters records by specific location""" location = "El Paso Colorado" filter_obj = LocationFilter(location) - record = log_record_factory() + record = build_log_record() record.location = location assert filter_obj.filter(record) record.location = "Denver Colorado" assert not filter_obj.filter(record) - record_no_loc = log_record_factory() + record_no_loc = build_log_record() assert not filter_obj.filter(record_no_loc) record.location = None @@ -160,13 +152,13 @@ def test_location_filter(log_record_factory): @pytest.mark.asyncio -async def test_add_location_filter_with_async_task(log_record_factory): +async def test_add_location_filter_with_async_task(): """Test AddLocationFilter adds location from async task name""" filter_obj = AddLocationFilter() async def task_with_name(): await asyncio.sleep(0) - record = log_record_factory() + record = build_log_record() result = filter_obj.filter(record) assert result assert hasattr(record, "location") @@ -177,11 +169,11 @@ async def task_with_name(): await task -def test_add_location_filter_without_async_task(log_record_factory): +def test_add_location_filter_without_async_task(): """Test AddLocationFilter defaults to 'main' when no async task""" filter_obj = AddLocationFilter() - record = log_record_factory() + record = build_log_record() result = filter_obj.filter(record) assert result assert hasattr(record, "location") @@ -189,13 +181,13 @@ def test_add_location_filter_without_async_task(log_record_factory): @pytest.mark.asyncio -async def test_add_location_filter_with_task_xx(log_record_factory): +async def test_add_location_filter_with_task_xx(): """Test AddLocationFilter defaults to 'main' for Task-XX names""" filter_obj = AddLocationFilter() async def task_with_generic_name(): await asyncio.sleep(0) - record = log_record_factory() + record = build_log_record() result = filter_obj.filter(record) assert result assert hasattr(record, "location") @@ -206,27 +198,25 @@ async def task_with_generic_name(): await task -def test_exception_only_filter( - log_record_factory, attach_value_error_exc_info -): +def test_exception_only_filter(): """Test ExceptionOnlyFilter only passes through exception records""" filter_obj = ExceptionOnlyFilter() - record = log_record_factory() + record = build_log_record() assert not filter_obj.filter(record) attach_value_error_exc_info(record, "test error") assert filter_obj.filter(record) - non_exception_record = log_record_factory(msg="plain") + non_exception_record = build_log_record(msg="plain") assert not filter_obj.filter(non_exception_record) -def test_json_formatter(log_record_factory): +def test_json_formatter(): """Test _JsonFormatter correctly formats log records to dictionaries""" formatter = _JsonFormatter() - record = log_record_factory( + record = build_log_record( pathname="test.py", lineno=42, msg="test message", @@ -246,13 +236,11 @@ def test_json_formatter(log_record_factory): assert "timestamp" in result -def test_json_formatter_with_exception( - log_record_factory, attach_value_error_exc_info -): +def test_json_formatter_with_exception(): """Test _JsonFormatter correctly formats exception information""" formatter = _JsonFormatter() - record = log_record_factory( + record = build_log_record( level=logging.ERROR, pathname="test.py", lineno=42, @@ -269,12 +257,12 @@ def test_json_formatter_with_exception( assert result["exc_text"] == "custom error message" -def test_json_formatter_truncates_long_messages(log_record_factory): +def test_json_formatter_truncates_long_messages(): """Test _JsonFormatter truncates messages longer than 103 chars""" formatter = _JsonFormatter() long_message = "a" * 200 - record = log_record_factory( + record = build_log_record( pathname="test.py", lineno=42, msg=long_message, @@ -305,14 +293,12 @@ def test_json_exception_file_handler_initialization(tmp_path): handler.close() -def test_json_exception_file_handler_emit( - tmp_path, log_record_factory, attach_value_error_exc_info -): +def test_json_exception_file_handler_emit(tmp_path): """Test _JsonExceptionFileHandler correctly writes exceptions to JSON""" test_file = tmp_path / "test_exceptions.json" handler = _JsonExceptionFileHandler(test_file) - record = log_record_factory( + record = build_log_record( level=logging.ERROR, pathname="test.py", lineno=42, @@ -340,15 +326,13 @@ def test_json_exception_file_handler_emit( assert entry["lineno"] == 42 -def test_json_exception_file_handler_multiple_exceptions( - tmp_path, log_record_factory, attach_value_error_exc_info -): +def test_json_exception_file_handler_multiple_exceptions(tmp_path): """Test _JsonExceptionFileHandler handles multiple exceptions""" test_file = tmp_path / "test_exceptions.json" handler = _JsonExceptionFileHandler(test_file) for i in range(3): - record = log_record_factory( + record = build_log_record( level=logging.ERROR, pathname="test.py", lineno=i, @@ -388,14 +372,14 @@ def test_setup_logging_levels(): assert callable(logger.debug_to_file) -def test_local_process_queue_handler_emit(log_record_factory): +def test_local_process_queue_handler_emit(): """Test _LocalProcessQueueHandler correctly enqueues records""" handler = _LocalProcessQueueHandler(LOGGING_QUEUE) while not LOGGING_QUEUE.empty(): LOGGING_QUEUE.get() - record = log_record_factory( + record = build_log_record( pathname="test.py", lineno=42, msg="test message", From 657079cfb485b2ef7d402a785cd18932dd8b6769 Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 16:57:09 -0700 Subject: [PATCH 07/16] Rename log record helper functions for clarity and consistency --- .../unit/utilities/test_utilities_logs.py | 40 +++++++++---------- 1 file changed, 20 insertions(+), 20 deletions(-) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index 6e30ae955..dcbbd71ab 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -24,7 +24,7 @@ ) -def build_log_record( +def _sample_log_record( *, name="test", level=logging.INFO, @@ -49,7 +49,7 @@ def build_log_record( ) -def attach_value_error_exc_info(record, message): +def _attach_value_error_exc_info(record, message): """Attach ValueError exc_info to the provided log record""" try: @@ -116,7 +116,7 @@ def test_no_location_filter(): """Test NoLocationFilter correctly identifies records without location""" filter_obj = NoLocationFilter() - record = build_log_record() + record = _sample_log_record() assert filter_obj.filter(record) record.location = None @@ -137,14 +137,14 @@ def test_location_filter(): location = "El Paso Colorado" filter_obj = LocationFilter(location) - record = build_log_record() + record = _sample_log_record() record.location = location assert filter_obj.filter(record) record.location = "Denver Colorado" assert not filter_obj.filter(record) - record_no_loc = build_log_record() + record_no_loc = _sample_log_record() assert not filter_obj.filter(record_no_loc) record.location = None @@ -158,7 +158,7 @@ async def test_add_location_filter_with_async_task(): async def task_with_name(): await asyncio.sleep(0) - record = build_log_record() + record = _sample_log_record() result = filter_obj.filter(record) assert result assert hasattr(record, "location") @@ -173,7 +173,7 @@ def test_add_location_filter_without_async_task(): """Test AddLocationFilter defaults to 'main' when no async task""" filter_obj = AddLocationFilter() - record = build_log_record() + record = _sample_log_record() result = filter_obj.filter(record) assert result assert hasattr(record, "location") @@ -187,7 +187,7 @@ async def test_add_location_filter_with_task_xx(): async def task_with_generic_name(): await asyncio.sleep(0) - record = build_log_record() + record = _sample_log_record() result = filter_obj.filter(record) assert result assert hasattr(record, "location") @@ -202,13 +202,13 @@ def test_exception_only_filter(): """Test ExceptionOnlyFilter only passes through exception records""" filter_obj = ExceptionOnlyFilter() - record = build_log_record() + record = _sample_log_record() assert not filter_obj.filter(record) - attach_value_error_exc_info(record, "test error") + _attach_value_error_exc_info(record, "test error") assert filter_obj.filter(record) - non_exception_record = build_log_record(msg="plain") + non_exception_record = _sample_log_record(msg="plain") assert not filter_obj.filter(non_exception_record) @@ -216,7 +216,7 @@ def test_json_formatter(): """Test _JsonFormatter correctly formats log records to dictionaries""" formatter = _JsonFormatter() - record = build_log_record( + record = _sample_log_record( pathname="test.py", lineno=42, msg="test message", @@ -240,7 +240,7 @@ def test_json_formatter_with_exception(): """Test _JsonFormatter correctly formats exception information""" formatter = _JsonFormatter() - record = build_log_record( + record = _sample_log_record( level=logging.ERROR, pathname="test.py", lineno=42, @@ -249,7 +249,7 @@ def test_json_formatter_with_exception(): ) record.taskName = "test_task" - attach_value_error_exc_info(record, "custom error message") + _attach_value_error_exc_info(record, "custom error message") result = formatter.format(record) assert isinstance(result, dict) @@ -262,7 +262,7 @@ def test_json_formatter_truncates_long_messages(): formatter = _JsonFormatter() long_message = "a" * 200 - record = build_log_record( + record = _sample_log_record( pathname="test.py", lineno=42, msg=long_message, @@ -298,7 +298,7 @@ def test_json_exception_file_handler_emit(tmp_path): test_file = tmp_path / "test_exceptions.json" handler = _JsonExceptionFileHandler(test_file) - record = build_log_record( + record = _sample_log_record( level=logging.ERROR, pathname="test.py", lineno=42, @@ -308,7 +308,7 @@ def test_json_exception_file_handler_emit(tmp_path): record.taskName = "test_task" record.module = "test_module" - attach_value_error_exc_info(record, "test exception") + _attach_value_error_exc_info(record, "test exception") handler.emit(record) handler.close() @@ -332,7 +332,7 @@ def test_json_exception_file_handler_multiple_exceptions(tmp_path): handler = _JsonExceptionFileHandler(test_file) for i in range(3): - record = build_log_record( + record = _sample_log_record( level=logging.ERROR, pathname="test.py", lineno=i, @@ -343,7 +343,7 @@ def test_json_exception_file_handler_multiple_exceptions(tmp_path): record.module = "test_module" msg = f"exception {i}" - attach_value_error_exc_info(record, msg) + _attach_value_error_exc_info(record, msg) handler.emit(record) @@ -379,7 +379,7 @@ def test_local_process_queue_handler_emit(): while not LOGGING_QUEUE.empty(): LOGGING_QUEUE.get() - record = build_log_record( + record = _sample_log_record( pathname="test.py", lineno=42, msg="test message", From af955756b1a47191b0caabf955b13f3deaaf51c1 Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 17:00:14 -0700 Subject: [PATCH 08/16] Added test_json_exception_file_handler_existing_file in test_utilities_logs.py to ensure _JsonExceptionFileHandler leaves pre-existing JSON content untouched while appending new exception entries. --- .../unit/utilities/test_utilities_logs.py | 55 +++++++++++++++++++ 1 file changed, 55 insertions(+) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index dcbbd71ab..b105f0b86 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -293,6 +293,61 @@ def test_json_exception_file_handler_initialization(tmp_path): handler.close() +def test_json_exception_file_handler_existing_file(tmp_path): + """Test existing JSON exception files remain intact upon init""" + test_file = tmp_path / "test_exceptions.json" + existing_content = { + "existing_module": { + "ValueError": [ + { + "timestamp": "existing", + "message": "existing error", + "exc_text": "existing exception", + "filename": "existing.py", + "funcName": "existing_func", + "taskName": "existing_task", + "lineno": 12, + } + ] + } + } + test_file.write_text( + json.dumps(existing_content, indent=4), encoding="utf-8" + ) + + handler = _JsonExceptionFileHandler(test_file) + + content_after_init = json.loads(test_file.read_text(encoding="utf-8")) + assert content_after_init == existing_content + + record = _sample_log_record( + level=logging.ERROR, + pathname="test.py", + lineno=10, + msg="new error", + func="test_func", + ) + record.taskName = "test_task" + record.module = "new_module" + + _attach_value_error_exc_info(record, "new exception") + + handler.emit(record) + handler.close() + + updated_content = json.loads(test_file.read_text(encoding="utf-8")) + assert ( + updated_content["existing_module"] + == existing_content["existing_module"] + ) + assert "new_module" in updated_content + assert "ValueError" in updated_content["new_module"] + new_entries = updated_content["new_module"]["ValueError"] + assert len(new_entries) == 1 + assert new_entries[0]["message"] == "new error" + assert new_entries[0]["exc_text"] == "new exception" + + def test_json_exception_file_handler_emit(tmp_path): """Test _JsonExceptionFileHandler correctly writes exceptions to JSON""" test_file = tmp_path / "test_exceptions.json" From abaef1985f67ce49f19a36ffabf0b88216e67000 Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 17:02:36 -0700 Subject: [PATCH 09/16] Added test_json_exception_file_handler_emit_type_error in test_utilities_logs.py to verify _JsonExceptionFileHandler.emit short-circuits cleanly when json.dumps raises TypeError, leaving the existing JSON file untouched. --- .../unit/utilities/test_utilities_logs.py | 29 +++++++++++++++++++ 1 file changed, 29 insertions(+) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index b105f0b86..ab5bad607 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -348,6 +348,35 @@ def test_json_exception_file_handler_existing_file(tmp_path): assert new_entries[0]["exc_text"] == "new exception" +def test_json_exception_file_handler_emit_type_error(tmp_path, monkeypatch): + """Test emit returns early when json.dumps raises TypeError""" + test_file = tmp_path / "test_exceptions.json" + handler = _JsonExceptionFileHandler(test_file) + original_content = test_file.read_text(encoding="utf-8") + + def _raise_type_error(*_, **__): + raise TypeError("cannot serialize") + + monkeypatch.setattr("compass.utilities.logs.json.dumps", _raise_type_error) + + record = _sample_log_record( + level=logging.ERROR, + pathname="test.py", + lineno=20, + msg="bad error", + func="test_func", + ) + record.taskName = "test_task" + record.module = "bad_module" + + _attach_value_error_exc_info(record, "bad exception") + + handler.emit(record) + handler.close() + + assert test_file.read_text(encoding="utf-8") == original_content + + def test_json_exception_file_handler_emit(tmp_path): """Test _JsonExceptionFileHandler correctly writes exceptions to JSON""" test_file = tmp_path / "test_exceptions.json" From e6a45e1cd7e363f9b33920f94558ca06a732bc9f Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 17:05:32 -0700 Subject: [PATCH 10/16] Added test_json_exception_file_handler_invalid_json to verify that _JsonExceptionFileHandler recovers gracefully when the file contains invalid JSON, replacing it with valid content for the new record --- .../unit/utilities/test_utilities_logs.py | 31 +++++++++++++++++++ 1 file changed, 31 insertions(+) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index ab5bad607..a1ae8f4f7 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -377,6 +377,37 @@ def _raise_type_error(*_, **__): assert test_file.read_text(encoding="utf-8") == original_content +def test_json_exception_file_handler_invalid_json(tmp_path): + """Test _JsonExceptionFileHandler handles invalid JSON gracefully""" + test_file = tmp_path / "test_exceptions.json" + test_file.write_text("not a valid json!", encoding="utf-8") + + handler = _JsonExceptionFileHandler(test_file) + + record = _sample_log_record( + level=logging.ERROR, + pathname="test.py", + lineno=30, + msg="error after invalid json", + func="test_func", + ) + record.taskName = "test_task" + record.module = "invalid_json_module" + + _attach_value_error_exc_info(record, "exception after invalid json") + + handler.emit(record) + handler.close() + + content = json.loads(test_file.read_text(encoding="utf-8")) + assert "invalid_json_module" in content + assert "ValueError" in content["invalid_json_module"] + entries = content["invalid_json_module"]["ValueError"] + assert len(entries) == 1 + assert entries[0]["message"] == "error after invalid json" + assert entries[0]["exc_text"] == "exception after invalid json" + + def test_json_exception_file_handler_emit(tmp_path): """Test _JsonExceptionFileHandler correctly writes exceptions to JSON""" test_file = tmp_path / "test_exceptions.json" From a7031a5f9fc22bf7843433f297cbe58a1245b882 Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 17:09:43 -0700 Subject: [PATCH 11/16] Updated test_location_file_log_async_context to match _JsonExceptionFileHandler behavior: the JSON output groups entries by module name. The test now checks the test_utilities_logs bucket, confirms the ValueError entry was recorded, and asserts the taskName matches the async task name. --- .../unit/utilities/test_utilities_logs.py | 41 +++++++++++++++++++ 1 file changed, 41 insertions(+) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index a1ae8f4f7..fcba48a4e 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -112,6 +112,47 @@ async def process_location_with_logs(listener, log_dir, location): assert f"This location is {loc!r}" in log_text +@pytest.mark.asyncio +async def test_location_file_log_async_context(tmp_path): + """Test async LocationFileLog context captures text and exception logs""" + + logger_name = "async_location_logger" + logger = logging.getLogger(logger_name) + logger.handlers = [] + + log_dir = tmp_path / "async_logs" + + async def _produce_logs(listener): + async with LocationFileLog(listener, log_dir, location="async_loc"): + logger.info("async info message") + try: + raise ValueError("async failure") + except ValueError: + logger.exception("async failure") + + async with LogListener([logger_name], level="INFO") as listener: + task = asyncio.create_task(_produce_logs(listener), name="async_loc") + await task + + text_log = log_dir / "async_loc.log" + json_log = log_dir / "async_loc exceptions.json" + assert text_log.exists() + assert json_log.exists() + + log_text = text_log.read_text(encoding="utf-8") + assert "async info message" in log_text + assert "async failure" in log_text + + json_content = json.loads(json_log.read_text(encoding="utf-8")) + assert "test_utilities_logs" in json_content + assert "ValueError" in json_content["test_utilities_logs"] + entries = json_content["test_utilities_logs"]["ValueError"] + assert len(entries) == 1 + assert entries[0]["message"] == "async failure" + assert entries[0]["exc_text"] == "async failure" + assert entries[0]["taskName"] == "async_loc" + + def test_no_location_filter(): """Test NoLocationFilter correctly identifies records without location""" filter_obj = NoLocationFilter() From 1a0973b3a705a16387504c3d4e52e97361ea7120 Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 17:12:50 -0700 Subject: [PATCH 12/16] Introduced ASYNC_EXIT_SLEEP_SECONDS on LocationFileLog (default 3) with a docstring in logs.py and replaced the hardcoded sleep values in __aexit__. --- compass/utilities/logs.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/compass/utilities/logs.py b/compass/utilities/logs.py index bf44332e3..e7dd6da71 100644 --- a/compass/utilities/logs.py +++ b/compass/utilities/logs.py @@ -242,6 +242,9 @@ class LocationFileLog: ) """Formatter used for text logs""" + ASYNC_EXIT_SLEEP_SECONDS = 3 + """Number of seconds to wait between async log flush checks""" + def __init__( self, listener, log_dir, location, level="INFO", max_teardown_time=30 ): @@ -361,8 +364,8 @@ async def __aexit__(self, exc_type, exc, tb): not LOGGING_QUEUE.empty() and (time.monotonic() - start_time) < self.max_teardown_time ): - await asyncio.sleep(3) - await asyncio.sleep(3) # Final recording + await asyncio.sleep(self.ASYNC_EXIT_SLEEP_SECONDS) + await asyncio.sleep(self.ASYNC_EXIT_SLEEP_SECONDS) # Final recording self.__exit__(exc_type, exc, tb) From 5041212953aa3c267f77f4b18aeb64e1f37c23c3 Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 17:12:57 -0700 Subject: [PATCH 13/16] In test_location_file_log_async_context, temporarily set LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = 0.01 (restored afterward) so the test completes quickly. --- tests/python/unit/utilities/test_utilities_logs.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index fcba48a4e..594a29d4d 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -116,6 +116,8 @@ async def process_location_with_logs(listener, log_dir, location): async def test_location_file_log_async_context(tmp_path): """Test async LocationFileLog context captures text and exception logs""" + original_sleep = LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS + LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = 0.01 logger_name = "async_location_logger" logger = logging.getLogger(logger_name) logger.handlers = [] @@ -152,6 +154,8 @@ async def _produce_logs(listener): assert entries[0]["exc_text"] == "async failure" assert entries[0]["taskName"] == "async_loc" + LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = original_sleep + def test_no_location_filter(): """Test NoLocationFilter correctly identifies records without location""" From bc2501406581de245c50c15e186bd7fa1ec4da2c Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 17:20:05 -0700 Subject: [PATCH 14/16] Add tests for empty handler --- .../unit/utilities/test_utilities_logs.py | 57 +++++++++++++++++++ 1 file changed, 57 insertions(+) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index 594a29d4d..3ea60f3c5 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -8,6 +8,7 @@ import pytest +from compass.exceptions import COMPASSValueError from compass.services.provider import RunningAsyncServices from compass.utilities.logs import ( AddLocationFilter, @@ -24,6 +25,18 @@ ) +class _DummyListener: + def __init__(self): + self.added_handlers = [] + self.removed_handlers = [] + + def addHandler(self, handler): # noqa: N802 + self.added_handlers.append(handler) + + def removeHandler(self, handler): # noqa: N802 + self.removed_handlers.append(handler) + + def _sample_log_record( *, name="test", @@ -157,6 +170,50 @@ async def _produce_logs(listener): LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = original_sleep +def test_location_file_log_breakdown_without_handler(tmp_path): + """Ensure handler teardown skips when handler is missing""" + + listener = _DummyListener() + log = LocationFileLog(listener, tmp_path, location="loc") + + log._break_down_handler() + log._remove_handler_from_listener() + + assert not listener.removed_handlers + + +def test_location_file_log_exception_breakdown_without_handler(tmp_path): + """Ensure exception handler teardown skips when handler missing""" + + listener = _DummyListener() + log = LocationFileLog(listener, tmp_path, location="loc") + + log._break_down_exception_handler() + log._remove_exception_handler_from_listener() + + assert not listener.removed_handlers + + +def test_location_file_log_add_handler_without_setup(tmp_path): + """Ensure add handler raises when handler not set up""" + + listener = _DummyListener() + log = LocationFileLog(listener, tmp_path, location="loc") + + with pytest.raises(COMPASSValueError): + log._add_handler_to_listener() + + +def test_location_file_log_add_exception_handler_without_setup(tmp_path): + """Ensure add exception handler raises when handler not set up""" + + listener = _DummyListener() + log = LocationFileLog(listener, tmp_path, location="loc") + + with pytest.raises(COMPASSValueError): + log._add_exception_handler_to_listener() + + def test_no_location_filter(): """Test NoLocationFilter correctly identifies records without location""" filter_obj = NoLocationFilter() From c71ffbce04da70a0bd16fc1f9bef4f1dbfa1f46a Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 17:22:00 -0700 Subject: [PATCH 15/16] Minor updates --- .../unit/utilities/test_utilities_logs.py | 86 +++++++++++-------- 1 file changed, 48 insertions(+), 38 deletions(-) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index 3ea60f3c5..3e8beb098 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -131,43 +131,48 @@ async def test_location_file_log_async_context(tmp_path): original_sleep = LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = 0.01 - logger_name = "async_location_logger" - logger = logging.getLogger(logger_name) - logger.handlers = [] - - log_dir = tmp_path / "async_logs" + try: + logger_name = "async_location_logger" + logger = logging.getLogger(logger_name) + logger.handlers = [] + + log_dir = tmp_path / "async_logs" + + async def _produce_logs(listener): + async with LocationFileLog( + listener, log_dir, location="async_loc" + ): + logger.info("async info message") + try: + raise ValueError("async failure") + except ValueError: + logger.exception("async failure") + + async with LogListener([logger_name], level="INFO") as listener: + task = asyncio.create_task( + _produce_logs(listener), name="async_loc" + ) + await task - async def _produce_logs(listener): - async with LocationFileLog(listener, log_dir, location="async_loc"): - logger.info("async info message") - try: - raise ValueError("async failure") - except ValueError: - logger.exception("async failure") + text_log = log_dir / "async_loc.log" + json_log = log_dir / "async_loc exceptions.json" + assert text_log.exists() + assert json_log.exists() - async with LogListener([logger_name], level="INFO") as listener: - task = asyncio.create_task(_produce_logs(listener), name="async_loc") - await task - - text_log = log_dir / "async_loc.log" - json_log = log_dir / "async_loc exceptions.json" - assert text_log.exists() - assert json_log.exists() - - log_text = text_log.read_text(encoding="utf-8") - assert "async info message" in log_text - assert "async failure" in log_text - - json_content = json.loads(json_log.read_text(encoding="utf-8")) - assert "test_utilities_logs" in json_content - assert "ValueError" in json_content["test_utilities_logs"] - entries = json_content["test_utilities_logs"]["ValueError"] - assert len(entries) == 1 - assert entries[0]["message"] == "async failure" - assert entries[0]["exc_text"] == "async failure" - assert entries[0]["taskName"] == "async_loc" + log_text = text_log.read_text(encoding="utf-8") + assert "async info message" in log_text + assert "async failure" in log_text - LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = original_sleep + json_content = json.loads(json_log.read_text(encoding="utf-8")) + assert "test_utilities_logs" in json_content + assert "ValueError" in json_content["test_utilities_logs"] + entries = json_content["test_utilities_logs"]["ValueError"] + assert len(entries) == 1 + assert entries[0]["message"] == "async failure" + assert entries[0]["exc_text"] == "async failure" + assert entries[0]["taskName"] == "async_loc" + finally: + LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = original_sleep def test_location_file_log_breakdown_without_handler(tmp_path): @@ -176,7 +181,7 @@ def test_location_file_log_breakdown_without_handler(tmp_path): listener = _DummyListener() log = LocationFileLog(listener, tmp_path, location="loc") - log._break_down_handler() + log._break_down_handler() # no AttributeError thrown log._remove_handler_from_listener() assert not listener.removed_handlers @@ -188,7 +193,7 @@ def test_location_file_log_exception_breakdown_without_handler(tmp_path): listener = _DummyListener() log = LocationFileLog(listener, tmp_path, location="loc") - log._break_down_exception_handler() + log._break_down_exception_handler() # no AttributeError thrown log._remove_exception_handler_from_listener() assert not listener.removed_handlers @@ -200,7 +205,9 @@ def test_location_file_log_add_handler_without_setup(tmp_path): listener = _DummyListener() log = LocationFileLog(listener, tmp_path, location="loc") - with pytest.raises(COMPASSValueError): + with pytest.raises( + COMPASSValueError, match="Must set up handler before listener!" + ): log._add_handler_to_listener() @@ -210,7 +217,10 @@ def test_location_file_log_add_exception_handler_without_setup(tmp_path): listener = _DummyListener() log = LocationFileLog(listener, tmp_path, location="loc") - with pytest.raises(COMPASSValueError): + with pytest.raises( + COMPASSValueError, + match="Must set up exception handler before listener!", + ): log._add_exception_handler_to_listener() From 31af7ef2a63501045f3edcb9c69b583ac28ea52f Mon Sep 17 00:00:00 2001 From: ppinchuk Date: Sat, 8 Nov 2025 17:23:54 -0700 Subject: [PATCH 16/16] Use module-level fixture --- .../unit/utilities/test_utilities_logs.py | 91 ++++++++++--------- 1 file changed, 47 insertions(+), 44 deletions(-) diff --git a/tests/python/unit/utilities/test_utilities_logs.py b/tests/python/unit/utilities/test_utilities_logs.py index 3e8beb098..23defee7c 100644 --- a/tests/python/unit/utilities/test_utilities_logs.py +++ b/tests/python/unit/utilities/test_utilities_logs.py @@ -25,6 +25,18 @@ ) +@pytest.fixture(autouse=True, scope="module") +def _speed_up_location_file_log_async_exit(): + """Speed up async LocationFileLog tests by shortening sleep""" + + original_sleep = LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS + LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = 0.01 + try: + yield + finally: + LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = original_sleep + + class _DummyListener: def __init__(self): self.added_handlers = [] @@ -129,50 +141,41 @@ async def process_location_with_logs(listener, log_dir, location): async def test_location_file_log_async_context(tmp_path): """Test async LocationFileLog context captures text and exception logs""" - original_sleep = LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS - LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = 0.01 - try: - logger_name = "async_location_logger" - logger = logging.getLogger(logger_name) - logger.handlers = [] - - log_dir = tmp_path / "async_logs" - - async def _produce_logs(listener): - async with LocationFileLog( - listener, log_dir, location="async_loc" - ): - logger.info("async info message") - try: - raise ValueError("async failure") - except ValueError: - logger.exception("async failure") - - async with LogListener([logger_name], level="INFO") as listener: - task = asyncio.create_task( - _produce_logs(listener), name="async_loc" - ) - await task - - text_log = log_dir / "async_loc.log" - json_log = log_dir / "async_loc exceptions.json" - assert text_log.exists() - assert json_log.exists() - - log_text = text_log.read_text(encoding="utf-8") - assert "async info message" in log_text - assert "async failure" in log_text - - json_content = json.loads(json_log.read_text(encoding="utf-8")) - assert "test_utilities_logs" in json_content - assert "ValueError" in json_content["test_utilities_logs"] - entries = json_content["test_utilities_logs"]["ValueError"] - assert len(entries) == 1 - assert entries[0]["message"] == "async failure" - assert entries[0]["exc_text"] == "async failure" - assert entries[0]["taskName"] == "async_loc" - finally: - LocationFileLog.ASYNC_EXIT_SLEEP_SECONDS = original_sleep + logger_name = "async_location_logger" + logger = logging.getLogger(logger_name) + logger.handlers = [] + + log_dir = tmp_path / "async_logs" + + async def _produce_logs(listener): + async with LocationFileLog(listener, log_dir, location="async_loc"): + logger.info("async info message") + try: + raise ValueError("async failure") + except ValueError: + logger.exception("async failure") + + async with LogListener([logger_name], level="INFO") as listener: + task = asyncio.create_task(_produce_logs(listener), name="async_loc") + await task + + text_log = log_dir / "async_loc.log" + json_log = log_dir / "async_loc exceptions.json" + assert text_log.exists() + assert json_log.exists() + + log_text = text_log.read_text(encoding="utf-8") + assert "async info message" in log_text + assert "async failure" in log_text + + json_content = json.loads(json_log.read_text(encoding="utf-8")) + assert "test_utilities_logs" in json_content + assert "ValueError" in json_content["test_utilities_logs"] + entries = json_content["test_utilities_logs"]["ValueError"] + assert len(entries) == 1 + assert entries[0]["message"] == "async failure" + assert entries[0]["exc_text"] == "async failure" + assert entries[0]["taskName"] == "async_loc" def test_location_file_log_breakdown_without_handler(tmp_path):