SAR-150 Updating formatting. Attaching filter to handlers and not logger

src/ska/logging/transactions.py

@@ -9,6 +9,30 @@ from typing import Mapping, Text
 
 from ska.skuid.client import SkuidClient
 
+
+class TransactionIDTagsFilter(logging.Filter):
+    """Adds the transaction ID as a tag to the log
+    """
+
+    def __init__(self, transaction_id):
+        """Store the transaction ID and set up the filter
+
+        Parameters
+        ----------
+        transaction_id : [String]
+            A transaction ID
+        """
+        self.transaction_id = transaction_id
+
+    def filter(self, record):
+        if hasattr(record, "tags") and record.tags:
+            if "transaction_id" not in record.tags:
+                record.tags = f"{record.tags},transaction_id:{self.transaction_id}"
+        else:
+            record.tags = f"transaction_id:{self.transaction_id}"
+        return True
+
+
 class Transaction:
     """Transaction context handler.
 
@@ -34,24 +58,40 @@ class Transaction:
     def __init__(self, name, params, logger=None):
         if not isinstance(params, Mapping):
             raise TransactionParamsError("params must be dict-like (Mapping)")
+
         self.logger = logger
         if not logger:
             self.logger = logging.getLogger(__name__)
+
         self._name = name
         self._params = params
-        self.transaction_id = self._get_existing_transaction_id() or self._generate_new_id()
+        self.transaction_id = (
+            self._get_existing_transaction_id() or self._generate_new_id()
+        )
+        self.transaction_filter = TransactionIDTagsFilter(self.transaction_id)
+
 
     def __enter__(self):
+        handlers = set(self.logger.handlers + self.logger.parent.handlers)
+        for handler in handlers:
+            handler.addFilter(self.transaction_filter)
         params_json = json.dumps(self._params)
-        self.logger.info(f"Start transaction {self._name}, {self.transaction_id}, {params_json}")
+        self.logger.info(
+            f"Start transaction {self._name}, {self.transaction_id}, {params_json}"
+        )
         return self.transaction_id
 
     def __exit__(self, exc_type, exc_val, exc_tb):
         if exc_type:
-            self.logger.exception(f"Transaction application encountered exception executing "
-                                  f"{self._name}, {self.transaction_id}")
+            self.logger.exception(
+                f"Transaction application encountered exception executing "
+                f"{self._name}, {self.transaction_id}"
+            )
 
         self.logger.info(f"Exit transaction {self._name}, {self.transaction_id}")
+        handlers = set(self.logger.handlers + self.logger.parent.handlers)
+        for handler in handlers:
+            handler.removeFilter(self.transaction_filter)
 
         if exc_type:
             raise

tests/conftest.py

@@ -82,6 +82,7 @@ def recording_tags_logger():
 
     class MyFilter(logging.Filter):
         def filter(self, record):
+            if not hasattr(record, "tags"):
                 record.tags = "key1:value1,key2:value2"
             return True
 
@@ -95,16 +96,19 @@ def get_first_record_and_log_message(logger):
     log_message = recorder.logs[0]
     return record, log_message
 
+
 def get_last_record_and_log_message(logger):
     recorder = get_named_handler(logger, "recorder")
     record = recorder.records[-1]
     log_message = recorder.logs[-1]
     return record, log_message
 
+
 def get_all_record_logs(logger):
     recorder = get_named_handler(logger, "recorder")
     return recorder.logs
 
+
 def get_named_handler(logger, name):
     """Search up through logger hierarchy to find a handler with the specified name."""
     while logger:
@@ -127,5 +131,7 @@ def id_generator_stub(mocker):
             TransactionIdGeneratorStub.call_count += 1
             return TransactionIdGeneratorStub.last_id
 
-    mocker.patch('ska.logging.transactions.TransactionIdGenerator', TransactionIdGeneratorStub)
+    mocker.patch(
+        "ska.logging.transactions.TransactionIdGenerator", TransactionIdGeneratorStub
+    )
     yield TransactionIdGeneratorStub

tests/test_transactions.py

@@ -76,7 +76,9 @@ class TestTransactionIdGeneration:
 class TestTransactionLogging:
     """Tests for :class:`~ska.logging.transaction` related to logging."""
 
-    def test_name_and_id_and_params_in_context_handler(self, id_generator_stub, recording_logger):
+    def test_name_and_id_and_params_in_context_handler(
+        self, id_generator_stub, recording_logger
+    ):
         params = {"other": ["config", 1, 2, 3.0]}
         with transaction("name", params) as transaction_id:
             pass
@@ -94,18 +96,31 @@ class TestTransactionLogging:
         assert "name" in last_log_message
         assert transaction_id in last_log_message
 
-    def test_exception_logs_transaction_id_and_command(self, id_generator_stub, recording_logger):
+    def test_exception_logs_transaction_id_and_command(
+        self, id_generator_stub, recording_logger
+    ):
         params = {"other": ["config", 1, 2, 3.0]}
         with pytest.raises(RuntimeError):
             with transaction("name", params) as transaction_id:
                 raise RuntimeError("Something went wrong")
 
         record_logs = get_all_record_logs(recording_logger)
-        for log_msg in record_logs:
-            if "RuntimeError" in log_msg and transaction_id in log_msg and "name" in log_msg:
-                return
+        substrings = set(["RuntimeError", "name", transaction_id])
+        result = [True for log_msg in record_logs if substrings.issubset(log_msg)]
+        assert all(
+            result
+        ), f"Log messages not found in exception logs: {recording_logger}"
 
-        assert 0, f"Log messages not found in exception logs: {record_logs}"
+    def test_logging_in_context_handler(self, recording_tags_logger):
+        parameters = {}
+        with transaction("name", parameters, recording_tags_logger) as transaction_id:
+            recording_tags_logger.info("Some log inside the context")
+        records = get_all_record_logs(recording_tags_logger)
+        for record in records:
+            if "Some log inside the context" in record:
+                assert f"transaction_id:{transaction_id}" in record
+                return
+        assert 0, "Could not find transaction tag in messages: {records}"
 
 
 class TestTransactionIdGenerator: