SAR-149 WIP Add first transaction logging test

And add missing `conftest.py`

src/ska/logging/transactions.py

 # -*- coding: utf-8 -*-
 
 """This module provides the transaction logging mechanism."""
+import json
+import logging
+
 from typing import Mapping, Text
 
 
@@ -33,7 +36,11 @@ class transaction:
         self._params = params
 
     def __enter__(self):
-        return self._get_new_or_existing_transaction_id()
+        transaction_id = self._get_new_or_existing_transaction_id()
+        params_json = json.dumps(self._params)
+        # Question:  should we have a user provided logger instead of using root?
+        logging.info(f"Start transaction {self._name}, {transaction_id}, {params_json}")
+        return transaction_id
 
     def __exit__(self, exc_type, exc_val, exc_tb):
         pass

tests/conftest.py

+"""
+A module defining pytest fixtures for testing ska.logging.
+"""
+import logging
+
+import pytest
+
+from ska.logging import configure_logging
+
+
+@pytest.fixture
+def reset_logging():
+    """Cleanup logging module's state after each test (at least try to)."""
+    yield
+    manager = logging.root.manager
+    manager.disabled = logging.NOTSET
+    for logger in list(manager.loggerDict.values()) + [logging.root]:
+        if isinstance(logger, logging.Logger):
+            logger.setLevel(logging.NOTSET)
+            logger.propagate = True
+            logger.disabled = False
+            logger.filters.clear()
+            handlers = logger.handlers.copy()
+            for handler in handlers:
+                # Copied from `logging.shutdown`.
+                try:
+                    handler.acquire()
+                    handler.flush()
+                    handler.close()
+                except (OSError, ValueError):
+                    pass
+                finally:
+                    handler.release()
+                logger.removeHandler(handler)
+
+
+class AppendHandler(logging.Handler):
+    """Handler that keeps a history of the records and formatted log messages."""
+
+    def __init__(self, *args, **kwargs):
+        super().__init__(*args, **kwargs)
+        self.logs = []
+        self.records = []
+
+    def emit(self, record):
+        self.records.append(record)
+        self.logs.append(self.format(record))
+
+
+"""Override configuration for recording loggers"""
+RECORDER_OVERRIDES = {
+    "handlers": {"recorder": {"()": AppendHandler, "formatter": "default"}},
+    "root": {"handlers": ["console", "recorder"]},
+}
+
+
+@pytest.fixture
+def default_logger():
+    """Return user logger instance with default configuration."""
+    configure_logging()
+    yield logging.getLogger("ska.test.app")
+
+
+@pytest.fixture
+def recording_logger():
+    """Return user logger, including a recording handler.
+
+    The additional handler has the name "recorder".  It uses the default formatter,
+    and stores all formatted output strings as a list in its `logs` attribute.
+    It also keeps a list of the raw log records in its `records` attribute.
+
+    Note:  we use this instead of pytest's `caplog` fixture because we cannot change
+    the formatter that it uses.
+    """
+    configure_logging(overrides=RECORDER_OVERRIDES)
+    yield logging.getLogger("ska.logger")
+
+
+@pytest.fixture
+def recording_tags_logger():
+    """Return user logger like :func:`recording_logger`, but including tags filter."""
+
+    class MyFilter(logging.Filter):
+        def filter(self, record):
+            record.tags = "key1:value1,key2:value2"
+            return True
+
+    configure_logging(tags_filter=MyFilter, overrides=RECORDER_OVERRIDES)
+    yield logging.getLogger("ska.logger")
+
+
+def get_first_record_and_log_message(logger):
+    recorder = get_named_handler(logger, "recorder")
+    record = recorder.records[0]
+    log_message = recorder.logs[0]
+    return record, log_message
+
+
+def get_named_handler(logger, name):
+    """Search up through logger hierarchy to find a handler with the specified name."""
+    while logger:
+        for handler in logger.handlers:
+            if handler.name == name:
+                return handler
+        logger = logger.parent
+
+
+@pytest.fixture
+def id_provider_stub(mocker):
+    """Replace the standard transactions.IdProviderService with a simple stub implementation."""
+
+    class IdProviderStub:
+        last_id = "NOT SET"
+        call_count = 0
+
+        def generate_new_id(self):
+            IdProviderStub.last_id = "XYZ-789"
+            IdProviderStub.call_count += 1
+            return IdProviderStub.last_id
+
+    mocker.patch('ska.logging.transactions.IdProviderService', IdProviderStub)
+    yield IdProviderStub

tests/test_transactions.py

 # -*- coding: utf-8 -*-
 
 """Tests for the logging transactions module."""
+import json
+
 import pytest
 
 from ska.logging import transaction
 from ska.logging.transactions import TransactionParamsError
+from tests.conftest import get_first_record_and_log_message
 
 
 class TestTransactionIdGeneration:
@@ -65,6 +68,15 @@ class TestTransactionIdGeneration:
 class TestTransactionLogging:
     """Tests for :class:`~ska.logging.transaction` related to logging."""
 
+    def test_name_and_id_and_params_json_logged_on_entry(self, id_provider_stub, recording_logger):
+        params = {"other": ["config", 1, 2, 3.0]}
+        with transaction("name", params) as transaction_id:
+            pass
+        _, log_message = get_first_record_and_log_message(recording_logger)
+        assert "name" in log_message
+        assert transaction_id in log_message
+        assert json.dumps(params) in log_message
+
 
 class TestIdProviderService:
     """Tests for :class:`~ska.logging.transactions.IdProviderService`."""