diff --git a/README.md b/README.md index 8221d0f4e6ba31f577277f2994a23cf192003507..788b6ca05d15de743d1c9b188bc50309fbad6401 100644 --- a/README.md +++ b/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] ``` diff --git a/src/ska/logging/transactions.py b/src/ska/logging/transactions.py index 5a1bbd4d334b159648db0f34cab7fe62aa1385a4..5a5e163304eb2cfacca96af515b6fe4cb9fee038 100644 --- a/src/ska/logging/transactions.py +++ b/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() diff --git a/tests/conftest.py b/tests/conftest.py index b87cc55d242b0afebe6ca344ecf9a96ccc87c37d..d33216e557c5fc9766017f07da0be9226674e59a 100644 --- a/tests/conftest.py +++ b/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] diff --git a/tests/test_transactions.py b/tests/test_transactions.py index e29b5c6c42cbed9034ffb422d17d9196e6137abf..6e459521196da7764383c9e66108d196858870af 100644 --- a/tests/test_transactions.py +++ b/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: