diff --git a/src/ska/logging/transactions.py b/src/ska/logging/transactions.py index 670e53e73668ccebf20294b26beb82a6c041caa0..2b3639bce0d9fd1e5a757e45661b40330220ccb8 100644 --- a/src/ska/logging/transactions.py +++ b/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 @@ -90,4 +130,4 @@ class TransactionIdGenerator: class TransactionParamsError(TypeError): - """Invalid data type for transaction parameters.""" + """Invalid data type for transaction parameters.""" \ No newline at end of file diff --git a/tests/conftest.py b/tests/conftest.py index b87cc55d242b0afebe6ca344ecf9a96ccc87c37d..389f211869790fee8cfc693e114fdfeaee85798d 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -82,7 +82,8 @@ def recording_tags_logger(): class MyFilter(logging.Filter): def filter(self, record): - record.tags = "key1:value1,key2:value2" + if not hasattr(record, "tags"): + record.tags = "key1:value1,key2:value2" return True configure_logging(tags_filter=MyFilter, overrides=RECORDER_OVERRIDES) @@ -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 diff --git a/tests/test_transactions.py b/tests/test_transactions.py index 38e048ae43954b85350541ff7b01aef9d17fbe50..537b0d7221dbe245a0b024945f1dc22771eec304 100644 --- a/tests/test_transactions.py +++ b/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: