SAR-149 Updated log message format. Added docs and samples to README. Added...

SAR-149 Updated log message format. Added docs and samples to README. Added tests. Updated transaction interface

README.md

@@ -132,10 +132,20 @@ The context handler logs to the root logger by default. Logs can be sent to a cu
 
 **Example ska formatted logs for successful transaction**
 
+Log message formats:
+
+- On Entry:
+  - Transaction [id]: Enter [name] with parameters [arguments]
+- On Exit:
+  - Transaction [id]: Exit [name]
+- On exception:
+  - Transaction [id]: Exception [name]
+    --Stacktrace--
+
 ```bash
 
-1|2020-09-15T11:01:20.380Z|INFO|MainThread|__enter__|transactions.py#46||Start transaction Scan, txn-T0001-20200914-00005, {"other": ["config", 1, 2, 3.0]}
-1|2020-09-15T11:01:20.381Z|INFO|MainThread|__exit__|transactions.py#54||Exit transaction Scan, txn-T0001-20200914-00005
+1|2020-09-15T11:01:20.380Z|INFO|MainThread|__enter__|transactions.py#46||Transaction [txn-T0001-20200914-00005]: Enter [Command] with parameters [{"other": ["config", 1, 2, 3.0]}]
+1|2020-09-15T11:01:20.381Z|INFO|MainThread|__exit__|transactions.py#54||Transaction [txn-T0001-20200914-00005]: Exit [Command]
 
 ```
 

src/ska/logging/transactions.py

@@ -9,63 +9,139 @@ from typing import Text
 
 from ska.skuid.client import SkuidClient
 
+
 class Transaction:
     """Transaction context handler.
 
      Provides:
      - Transaction ID:
-       - Re-use existing transaction ID, if available in `params["transaction_id"]`
+       - Re-use existing transaction ID, if available
        - If no transaction ID, or empty or None, then generate a new ID
-       - context handler returns the ID used
+       - context handler returns the transaction ID used
      - Log messages on entry, exit, and exception
 
-     .. Example::
+     .. Examples::
 
          def command(self, parameter_json):
              parameters = json.reads(parameter_json)
              with ska.logging.transaction('My Command', parameters) as transaction_id:
                  # ...
-                 pars['transaction_id'] = transaction_id
+                 parameters['transaction_id'] = transaction_id
+                 device.further_command(json.dumps(pars))
+                 # ...
+
+        def command(self, parameter_json):
+             parameters = json.reads(parameter_json)
+             with ska.logging.transaction('My Command', parameters, transaction_id = "123") as transaction_id:
+                 # ...
+                 parameters['transaction_id'] = transaction_id
                  device.further_command(json.dumps(pars))
                  # ...
 
+        def command(self, parameter_json):
+             parameters = json.reads(parameter_json)
+             parameters["txn_id_key"] = 123
+             with ska.logging.transaction('My Command', parameters, transaction_id_key = "txn_id_key") as transaction_id:
+                 # ...
+                 parameters['transaction_id'] = transaction_id
+                 device.further_command(json.dumps(pars))
+                 # ...
+
+     Log message formats:
+        On Entry:
+            Transaction [id]: Enter [name] with parameters [arguments]
+        On Exit:
+            Transaction [id]: Exit [name]
+        On exception:
+            Transaction [id]: Exception [name]
+            Stacktrace
      """
 
-    def __init__(self, name, **params):
-        # TODO: get the logger from the transaction logginh application without passing to 
-        # context handler see https://gitlab.com/ska-telescope/ska-logging/-/merge_requests/7#note_414359589
-        self.logger = logging.getLogger(__name__)
+    def __init__(
+        self,
+        name: str,
+        params: dict = {},
+        transaction_id: str = "",
+        transaction_id_key: str = "transaction_id",
+    ):
+        # Get the root logger
+        self.logger = logging.getLogger()
         self._name = name
         self._params = params
-        self.transaction_id = self._get_new_or_existing_transaction_id()
+        self._transaction_id_key = transaction_id_key
+
+        self._transaction_id = (
+            transaction_id if self._is_valid_id(transaction_id) else ""
+        )
+
+        if not self._transaction_id:
+            self._transaction_id = self._get_from_params_or_generate_new_id()
+            self.logger.info(f"Generated transaction ID {self._transaction_id}")
+
+        if transaction_id and params.get(self._transaction_id_key):
+            self.logger.info(
+                f"Received 2 transaction IDs {transaction_id} and"
+                f" {params.get(transaction_id_key)}, using {self._transaction_id}"
+            )
 
     def __enter__(self):
         params_json = json.dumps(self._params)
-        self.logger.info(f"Start transaction {self._name}, {self.transaction_id}, {params_json}")
-        return self.transaction_id
+        self.logger.info(
+            f"Transaction [{self._transaction_id}]: Enter[{self._name}] "
+            f"with parameters[{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[{self._transaction_id}]: Exception[{self._name}]"
+            )
 
-        self.logger.info(f"Exit transaction {self._name}, {self.transaction_id}")
+        self.logger.info(f"Transaction[{self._transaction_id}]: Exit[{self._name}]")
 
         if exc_type:
             raise
 
-    def _get_new_or_existing_transaction_id(self):
-        transaction_id = self._params.get("transaction_id")
+    def _get_from_params_or_generate_new_id(self):
+        """Use the transaction_id_key to get the transaction ID from the parameters
+        or generate a new one if it's not there.
+
+        Returns
+        -------
+        [String]
+            [transaction ID]
+        """
+        transaction_id = self._params.get(self._transaction_id_key)
         if not self._is_valid_id(transaction_id):
             transaction_id = self._generate_new_id()
         return transaction_id
 
     def _is_valid_id(self, transaction_id):
+        """Check if the ID is valid
+
+        Parameters
+        ----------
+        transaction_id : [String]
+            [The transaction ID]
+
+        Returns
+        -------
+        [bool]
+            [Whether the ID is valid or not]
+        """
         if isinstance(transaction_id, Text) and transaction_id.strip():
             return True
         return False
 
     def _generate_new_id(self):
+        """Use TransactionIdGenerator to generate a new transaction ID
+
+        Returns
+        -------
+        [String]
+            [The newly generated transaction ID]
+        """
         id_generator = TransactionIdGenerator()
         return id_generator.next()
 

tests/conftest.py

@@ -95,6 +95,13 @@ def get_first_record_and_log_message(logger):
     log_message = recorder.logs[0]
     return record, log_message
 
+
+def get_second_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_last_record_and_log_message(logger):
     recorder = get_named_handler(logger, "recorder")
     record = recorder.records[-1]

tests/test_transactions.py

@@ -15,91 +15,134 @@ from tests.conftest import (
     get_first_record_and_log_message,
     get_last_record_and_log_message,
     get_all_record_logs,
+    get_second_record_and_log_message,
 )
 
 
 class TestTransactionIdGeneration:
     """Tests for :class:`~ska.logging.transaction` related to ID generation."""
 
-    def test_existing_valid_id_is_reused(self, id_generator_stub):
-        parameters = {"transaction_id": "abc1234", "other": "config"}
-        with transaction("name", **parameters) as transaction_id:
+    def test_preference_order(self, id_generator_stub):
+        parameters = {
+            "other": "config",
+            "transaction_id": "xyz123",
+            "other_transaction_id_key": "def789",
+        }
+        with transaction(
+            "name", parameters, transaction_id="abc1234"
+        ) as transaction_id:
+            assert transaction_id == "abc1234"
+
+        parameters = {
+            "other": "config",
+            "transaction_id": "xyz123",
+            "other_transaction_id_key": "def789",
+        }
+        with transaction(
+            "name", parameters, transaction_id_key="other_transaction_id_key"
+        ) as transaction_id:
+            assert transaction_id == "def789"
+
+        parameters = {
+            "other": "config",
+            "transaction_id": "xyz123",
+            "other_transaction_id_key": "def789",
+        }
+        with transaction(
+            "name",
+            parameters,
+            transaction_id="abc1234",
+            transaction_id_key="other_transaction_id_key",
+        ) as transaction_id:
             assert transaction_id == "abc1234"
 
     def test_new_id_generated_if_id_is_empty(self, id_generator_stub):
         parameters = {"transaction_id": "", "other": "config"}
-        with transaction("name", **parameters) as transaction_id:
+        with transaction("name", parameters) as transaction_id:
             assert transaction_id == id_generator_stub.last_id
 
     def test_new_id_generated_if_id_is_none(self, id_generator_stub):
         parameters = {"transaction_id": None, "other": "config"}
-        with transaction("name", **parameters) as transaction_id:
+        with transaction("name", parameters) as transaction_id:
             assert transaction_id == id_generator_stub.last_id
 
     def test_new_id_generated_if_id_is_only_white_space(self, id_generator_stub):
         parameters = {"transaction_id": "\t\n \r\n", "other": "config"}
-        with transaction("name", **parameters) as transaction_id:
+        with transaction("name", parameters) as transaction_id:
             assert transaction_id == id_generator_stub.last_id
 
     def test_new_id_generated_if_id_is_not_string_type(self, id_generator_stub):
         parameters = {"transaction_id": 1234.5, "other": "config"}
-        with transaction("name", **parameters) as transaction_id:
+        with transaction("name", parameters) as transaction_id:
             assert transaction_id == id_generator_stub.last_id
 
     def test_new_id_generated_if_id_is_not_present(self, id_generator_stub):
         parameters = {"other": "config"}
-        with transaction("name", **parameters) as transaction_id:
+        with transaction("name", parameters) as transaction_id:
             assert transaction_id == id_generator_stub.last_id
 
     def test_new_id_generated_if_params_empty(self, id_generator_stub):
         parameters = {}
-        with transaction("name", **parameters) as transaction_id:
+        with transaction("name", parameters) as transaction_id:
             assert transaction_id == id_generator_stub.last_id
 
     def test_id_provider_only_used_once_for_one_new_id(self, id_generator_stub):
         parameters = {}
-        with transaction("name", **parameters):
+        with transaction("name", parameters):
             assert id_generator_stub.call_count == 1
 
     def test_id_provider_not_used_for_existing_valid_id(self, id_generator_stub):
         parameters = {"transaction_id": "abc1234"}
-        with transaction("name", **parameters):
+        with transaction("name", parameters):
             assert id_generator_stub.call_count == 0
 
 
 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
+    ):
         parameters = {"other": ["config", 1, 2, 3.0]}
-        with transaction("name", **parameters) as transaction_id:
+        with transaction("name", parameters) as transaction_id:
             pass
         _, first_log_message = get_first_record_and_log_message(recording_logger)
+        _, second_log_message = get_second_record_and_log_message(recording_logger)
         _, last_log_message = get_last_record_and_log_message(recording_logger)
 
         # __enter__ log message
-        assert "Start transaction" in first_log_message
-        assert "name" in first_log_message
-        assert transaction_id in first_log_message
-        assert json.dumps(parameters) in first_log_message
+        assert "Generated transaction ID" in first_log_message
+        assert "Enter" in second_log_message
+        assert "name" in second_log_message
+        assert "other" in second_log_message
+        assert transaction_id in second_log_message
+        assert json.dumps(parameters) in second_log_message
 
         # __exit__ log message
-        assert "Exit transaction" in last_log_message
+        assert "Exit" in last_log_message
         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
+    ):
         parameters = {"other": ["config", 1, 2, 3.0]}
         with pytest.raises(RuntimeError):
-            with transaction("name", **parameters) as transaction_id:
+            with transaction("name", parameters) 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:
+            if (
+                "RuntimeError" in log_msg
+                and transaction_id in log_msg
+                and "name" in log_msg
+            ):
                 return
 
-        assert 0, f"RuntimeError and transaction tag not found in exception logs: {record_logs}"
+        assert (
+            0
+        ), f"RuntimeError and transaction tag not found in exception logs: {record_logs}"
 
 
 class TestTransactionIdGenerator: