diff --git a/src/ska/logging/transactions.py b/src/ska/logging/transactions.py
index 100430bd6b85df2ed826c82558219304f1f107c1..3eee962bc7fc9b0eee8e6d9200704c41a1df0a74 100644
--- a/src/ska/logging/transactions.py
+++ b/src/ska/logging/transactions.py
@@ -1,6 +1,9 @@
# -*- 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
diff --git a/tests/conftest.py b/tests/conftest.py
new file mode 100644
index 0000000000000000000000000000000000000000..4c9967f00a223dc71ac69517d56339f18acab6cc
--- /dev/null
+++ b/tests/conftest.py
@@ -0,0 +1,122 @@
+"""
+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
diff --git a/tests/test_transactions.py b/tests/test_transactions.py
index 6b41f76f32feeef780858b59400b11d5eafc1793..05a31a7dfcd26b8c09aac0a331751c284acb4255 100644
--- a/tests/test_transactions.py
+++ b/tests/test_transactions.py
@@ -1,10 +1,13 @@
# -*- 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`."""