SAR-150 Added tests that fail when using threads. Marked as xfail

src/ska/logging/transactions.py

@@ -18,8 +18,7 @@ class TransactionIDTagsFilter(logging.Filter):
     """
 
     def __init__(self, *args, **kwargs):
-        """Override logging.Filter.__init__ to keep track of the transaction ID and callstack
-        """
+        """Override logging.Filter.__init__ to keep track of the transaction ID and callstack"""
         self.transaction_id = kwargs.pop("transaction_id", None)
         self.callstack = kwargs.pop("call_stack", None)
         super(TransactionIDTagsFilter, self).__init__(*args, **kwargs)
@@ -182,7 +181,9 @@ class Transaction:
 
     def __exit__(self, exc_type, exc_val, exc_tb):
         if exc_type:
-            self.logger.exception(f"Transaction[{self._transaction_id}]: Exception[{self._name}]")
+            self.logger.exception(
+                f"Transaction[{self._transaction_id}]: Exception[{self._name}] marker[{self._random_marker}]"
+            )
 
         self.logger.info(
             f"Transaction[{self._transaction_id}]: Exit[{self._name}] "

tests/conftest.py

@@ -131,6 +131,12 @@ def get_all_record_logs(logger):
     return recorder.logs
 
 
+def clear_logger_logs(logger):
+    recorder = get_named_handler(logger, "recorder")
+    recorder.logs = []
+    recorder.records = []
+
+
 def get_named_handler(logger, name):
     """Search up through logger hierarchy to find a handler with the specified name."""
     while logger:

tests/test_transactions_threaded.py

+"""Tests for the logging transactions module focusing on threads"""
+import pytest
+
+from threading import Thread
+
+from ska.logging import transaction
+from tests.conftest import get_all_record_logs, clear_logger_logs
+
+
+class ThreadingLogsGenerator:
+    """Generate logs by spawning a number of threads and logging in them
+    Some uses the transaction context and some not.
+    """
+    def __init__(self, logger=None, pass_logger=False):
+        self.logger = logger
+        self.pass_logger = pass_logger
+
+    def thread_with_transaction_exception(self, thread_index):
+        if self.pass_logger:
+            try:
+                with transaction(f"Transaction thread [{thread_index}]", logger=self.logger):
+                    self.logger.info(
+                        f"Transaction thread in transaction [{thread_index}], in transaction"
+                    )
+                    raise RuntimeError("An exception has occurred")
+            except RuntimeError:
+                pass
+        else:
+            try:
+                with transaction(f"Transaction thread [{thread_index}]"):
+                    self.logger.info(
+                        f"Transaction thread in transaction [{thread_index}], in transaction"
+                    )
+                    raise RuntimeError("An exception has occurred")
+            except RuntimeError:
+                pass
+
+    def thread_with_transaction(self, thread_index):
+        if self.pass_logger:
+            with transaction(f"Transaction thread [{thread_index}]", logger=self.logger):
+                self.logger.info(f"Transaction thread [{thread_index}], in transaction")
+            self.logger.info(f"Thread log [{thread_index}], no transaction")
+        else:
+            with transaction(f"Transaction thread [{thread_index}]"):
+                self.logger.info(f"Transaction thread [{thread_index}], in transaction")
+            self.logger.info(f"Thread log [{thread_index}], no transaction")
+
+    def thread_without_transaction(self, thread_index):
+        self.logger.info(f"Thread log [{thread_index}], no transaction")
+
+    def get_logs(self):
+        clear_logger_logs(self.logger)
+        test_threads = []
+        for thread_index in range(10):
+            thread_in_transaction = Thread(
+                target=self.thread_with_transaction, args=(thread_index,)
+            )
+            thread_no_transaction = Thread(
+                target=self.thread_without_transaction, args=(thread_index,)
+            )
+            thread_exception = Thread(
+                target=self.thread_with_transaction_exception, args=(thread_index,)
+            )
+            test_threads.append(thread_in_transaction)
+            test_threads.append(thread_no_transaction)
+            test_threads.append(thread_exception)
+
+        for t in test_threads:
+            t.start()
+        for t in test_threads:
+            t.join()
+
+        return get_all_record_logs(self.logger)
+
+
+@pytest.fixture
+def threaded_logs_local_logger(ensures_tags_logger):
+    tlg = ThreadingLogsGenerator(logger=ensures_tags_logger, pass_logger=True)
+    return tlg.get_logs()
+
+
+@pytest.fixture
+def threaded_logs_global_logger(ensures_tags_logger):
+    tlg = ThreadingLogsGenerator(logger=ensures_tags_logger, pass_logger=False)
+    return tlg.get_logs()
+
+
+class TestThreadScenarios:
+    @pytest.mark.xfail
+    def test_logs_outside_transaction_has_no_transaction_ids(
+        self, threaded_logs_global_logger, threaded_logs_local_logger
+    ):
+        all_logs = threaded_logs_global_logger + threaded_logs_local_logger
+        outside_transaction_logs = [log for log in all_logs if "no transaction" in log]
+        assert outside_transaction_logs
+        for log in outside_transaction_logs:
+            assert "transaction_id:txn" not in log, f"transaction_id should not be in log {log}"
+
+    @pytest.mark.xfail
+    def test_no_duplicate_transaction_ids(self, threaded_logs_local_logger):
+        all_logs = threaded_logs_local_logger
+        transaction_logs = [log for log in all_logs if "Transaction thread" in log]
+        assert transaction_logs
+        for log in transaction_logs:
+            assert "transaction_id" in log, f"Expected transaction_id in {log}"
+            assert log.count("transaction_id") == 1, f"Only expected one transaction_id in {log}"
+
+    def test_internal_log_has_transaction_id(self, threaded_logs_local_logger):
+        all_logs = threaded_logs_local_logger
+        internal_logs = [log for log in all_logs if "in transaction" in log]
+        assert internal_logs
+        for log in internal_logs:
+            assert "transaction_id" in log
+
+    def test_internal_log_has_no_transaction_id(self, threaded_logs_global_logger):
+        all_logs = threaded_logs_global_logger
+        internal_logs = [log for log in all_logs if "in transaction" in log]
+        assert internal_logs
+        for log in internal_logs:
+            assert "transaction_id" not in log
+
+    def test_enter_exit_exception_matches(
+        self, threaded_logs_global_logger, threaded_logs_local_logger
+    ):
+        all_logs = threaded_logs_global_logger + threaded_logs_local_logger
+        enter_exit_logs = []
+        enter_exit_logs += [log for log in all_logs if "Enter[" in log]
+        enter_exit_logs += [log for log in all_logs if "Exit[" in log]
+        assert enter_exit_logs
+        assert len(enter_exit_logs) % 2 == 0
+
+        # Group enter exit by marker
+        markers = {}
+        for log in enter_exit_logs:
+            marker = log[-6:-1]
+            assert marker.isdigit()
+            markers.setdefault(marker, []).append(log)
+        assert markers
+
+        for key, log_pair in markers.items():
+            assert len(log_pair) == 2
+            assert "Enter" in log_pair[0]
+            assert "Exit" in log_pair[1]
+            assert log_pair[0].endswith(f"[{key}]")
+            assert log_pair[1].endswith(f"[{key}]")
+
+        exception_logs = [log for log in all_logs if "RuntimeError" in log]
+        for log in exception_logs:
+            marker_start = log.index("marker[")
+            marker = log[marker_start + 7 : marker_start + 12]
+            assert marker.isdigit()
+            assert marker in markers, "An exception marker has no match with a start/end log"
+            markers[marker].append(log)
+
+        # There is an equal number test transactions that has exceptions to those that do not
+        count_exceptions = 0
+        count_no_exceptions = 0
+        for key, logs in markers.items():
+            if len(logs) == 2:
+                count_no_exceptions += 1
+            if len(logs) == 3:
+                count_exceptions += 1
+        assert count_no_exceptions != 0
+        assert count_no_exceptions == count_exceptions