VED-698 CRUD Splunk (#731)

* local_id

* vaccine_type

* pre-check body

* temp. revert

* _log_data_from_body

* _log_data_from_body II

* supplier

* cleanup, add tests

* smell

* log partial detail where available

* LF

* review cleanup

Author: JamesW1-NHS

backend/src/log_structure.py

@@ -6,13 +6,35 @@
 
 from log_firehose import FirehoseLogger
 
+from models.utils.validation_utils import get_vaccine_type
+
 logging.basicConfig()
 logger = logging.getLogger()
 logger.setLevel("INFO")
 
 
 firehose_logger = FirehoseLogger()
 
+def _log_data_from_body(event) -> dict:
+    log_data = {}
+    if event.get("body") is None:
+        return log_data
+    try:
+        imms = json.loads(event["body"])
+    except json.decoder.JSONDecodeError:
+        return log_data
+    try:
+        vaccine_type = get_vaccine_type(imms)
+        log_data["vaccine_type"] = vaccine_type
+    except Exception:
+        pass
+    try:
+        local_id = imms["identifier"][0]["value"] + "^" + imms["identifier"][0]["system"]
+        log_data["local_id"] = local_id
+    except Exception:
+        pass
+    return log_data
+
 
 def function_info(func):
     """This decorator prints the execution information for the decorated function."""
@@ -24,6 +46,7 @@ def wrapper(*args, **kwargs):
         headers = event.get("headers", {})
         correlation_id = headers.get("X-Correlation-ID", "X-Correlation-ID not passed")
         request_id = headers.get("X-Request-ID", "X-Request-ID not passed")
+        supplier_system = headers.get("SupplierSystem", "SupplierSystem not passed")
         actual_path = event.get("path", "Unknown")
         resource_path = event.get("requestContext", {}).get("resourcePath", "Unknown")
         logger.info(f"Starting {func.__name__} with X-Correlation-ID: {correlation_id} and X-Request-ID: {request_id}")
@@ -32,6 +55,7 @@ def wrapper(*args, **kwargs):
             "date_time": str(datetime.now()),
             "X-Correlation-ID": correlation_id,
             "X-Request-ID": request_id,
+            "supplier": supplier_system,
             "actual_path": actual_path,
             "resource_path": resource_path,
         }
@@ -43,6 +67,7 @@ def wrapper(*args, **kwargs):
             logger.info(f"Result:{result}")
             end = time.time()
             log_data["time_taken"] = f"{round(end - start, 5)}s"
+            log_data.update(_log_data_from_body(event))
             status = "500"
             status_code = "Exception"
             diagnostics = str()
@@ -78,6 +103,7 @@ def wrapper(*args, **kwargs):
             log_data["error"] = str(e)
             end = time.time()
             log_data["time_taken"] = f"{round(end - start, 5)}s"
+            log_data.update(_log_data_from_body(event))
             logger.exception(json.dumps(log_data))
             firehose_log["event"] = log_data
             firehose_logger.send_log(firehose_log)

backend/tests/test_log_structure_wrapper.py

@@ -8,6 +8,13 @@
 @patch('log_structure.logger')
 class TestFunctionInfoWrapper(unittest.TestCase):
 
+    def setUp(self):
+        self.redis_patcher = patch("models.utils.validation_utils.redis_client")
+        self.mock_redis_client = self.redis_patcher.start()
+
+    def tearDown(self):
+        patch.stopall()
+
     @staticmethod
     def mock_success_function(_event, _context):
         return "Success"
@@ -18,14 +25,23 @@ def mock_function_raises(_event, _context):
 
     def test_successful_execution(self, mock_logger, mock_firehose_logger):
         # Arrange
+        test_correlation = "test_correlation"
+        test_request = "test_request"
+        test_supplier = "test_supplier"
+        test_actual_path = "/test"
+        test_resource_path = "/test"
+
+        self.mock_redis_client.hget.return_value = "FLU"
         wrapped_function = function_info(self.mock_success_function)
         event = {
             'headers': {
-                'X-Correlation-ID': 'test_correlation',
-                'X-Request-ID': 'test_request'
+                'X-Correlation-ID': test_correlation,
+                'X-Request-ID': test_request,
+                'SupplierSystem': test_supplier
             },
-            'path': '/test',
-            'requestContext': {'resourcePath': '/test'}
+            'path': test_actual_path,
+            'requestContext': {'resourcePath': test_resource_path},
+            'body': "{\"identifier\": [{\"system\": \"http://test\", \"value\": \"12345\"}], \"protocolApplied\": [{\"targetDisease\": [{\"coding\": [{\"system\": \"http://snomed.info/sct\", \"code\": \"840539006\", \"display\": \"Disease caused by severe acute respiratory syndrome coronavirus 2\"}]}]}]}"
         }
 
         # Act
@@ -41,23 +57,37 @@ def test_successful_execution(self, mock_logger, mock_firehose_logger):
 
         self.assertIn('function_name', logged_info)
         self.assertIn('time_taken', logged_info)
-        self.assertEqual(logged_info['X-Correlation-ID'], 'test_correlation')
-        self.assertEqual(logged_info['X-Request-ID'], 'test_request')
-        self.assertEqual(logged_info['actual_path'], '/test')
-        self.assertEqual(logged_info['resource_path'], '/test')
+        self.assertEqual(logged_info['X-Correlation-ID'], test_correlation)
+        self.assertEqual(logged_info['X-Request-ID'], test_request)
+        self.assertEqual(logged_info['supplier'], test_supplier)
+        self.assertEqual(logged_info['actual_path'], test_actual_path)
+        self.assertEqual(logged_info['resource_path'], test_resource_path)
+        self.assertEqual(logged_info['local_id'], '12345^http://test')
+        self.assertEqual(logged_info['vaccine_type'], 'FLU')
 
     def test_exception_handling(self, mock_logger, mock_firehose_logger):
+        # Arrange
+        test_correlation = "failed_test_correlation"
+        test_request = "failed_test_request"
+        test_supplier = "failed_test_supplier"
+        test_actual_path = "/failed_test"
+        test_resource_path = "/failed_test"
+
+        self.mock_redis_client.hget.return_value = "FLU"
 
         #Act
         decorated_function_raises = function_info(self.mock_function_raises)
 
         with self.assertRaises(ValueError):
             #Assert
             event = {'headers': {
-                'X-Correlation-ID': 'failed_test_correlation',
-                'X-Request-ID': 'failed_test_request'
+                'X-Correlation-ID': test_correlation,
+                'X-Request-ID': test_request,
+                'SupplierSystem': test_supplier
             },
-                'path': '/failed_test', 'requestContext': {'resourcePath': '/failed_test'}}
+                'path': test_actual_path, 'requestContext': {'resourcePath': test_resource_path},
+                'body': "{\"identifier\": [{\"system\": \"http://test\", \"value\": \"12345\"}], \"protocolApplied\": [{\"targetDisease\": [{\"coding\": [{\"system\": \"http://snomed.info/sct\", \"code\": \"840539006\", \"display\": \"Disease caused by severe acute respiratory syndrome coronavirus 2\"}]}]}]}"}
+
             context = {}
             decorated_function_raises(event, context)
 
@@ -70,8 +100,157 @@ def test_exception_handling(self, mock_logger, mock_firehose_logger):
 
         self.assertIn('function_name', logged_info)
         self.assertIn('time_taken', logged_info)
-        self.assertEqual(logged_info['X-Correlation-ID'], 'failed_test_correlation')
-        self.assertEqual(logged_info['X-Request-ID'], 'failed_test_request')
-        self.assertEqual(logged_info['actual_path'], '/failed_test')
-        self.assertEqual(logged_info['resource_path'], '/failed_test')
+        self.assertEqual(logged_info['X-Correlation-ID'], test_correlation)
+        self.assertEqual(logged_info['X-Request-ID'], test_request)
+        self.assertEqual(logged_info['supplier'], test_supplier)
+        self.assertEqual(logged_info['actual_path'], test_actual_path)
+        self.assertEqual(logged_info['resource_path'], test_resource_path)
         self.assertEqual(logged_info['error'], str(ValueError("Test error")))
+        self.assertEqual(logged_info['local_id'], '12345^http://test')
+        self.assertEqual(logged_info['vaccine_type'], 'FLU')
+
+    def test_body_missing(self, mock_logger, mock_firehose_logger):
+        # Arrange
+        test_correlation = "failed_test_correlation_body_missing"
+        test_request = "failed_test_request_body_missing"
+        test_supplier = "failed_test_supplier_body_missing"
+        test_actual_path = "/failed_test_body_missing"
+        test_resource_path = "/failed_test_body_missing"
+
+        wrapped_function = function_info(self.mock_success_function)
+        event = {
+            'headers': {
+                'X-Correlation-ID': test_correlation,
+                'X-Request-ID': test_request,
+                'SupplierSystem': test_supplier
+            },
+            'path': test_actual_path,
+            'requestContext': {'resourcePath': test_resource_path},
+        }
+
+        # Act
+        result = wrapped_function(event, {})
+
+        # Assert
+        args, kwargs = mock_logger.info.call_args
+        logged_info = json.loads(args[0])
+
+        self.assertEqual(logged_info['X-Correlation-ID'], test_correlation)
+        self.assertEqual(logged_info['X-Request-ID'], test_request)
+        self.assertEqual(logged_info['supplier'], test_supplier)
+        self.assertEqual(logged_info['actual_path'], test_actual_path)
+        self.assertEqual(logged_info['resource_path'], test_resource_path)
+        self.assertNotIn('local_id', logged_info)
+        self.assertNotIn('vaccine_type', logged_info)
+
+    def test_body_not_json(self, mock_logger, mock_firehose_logger):
+        # Arrange
+        test_correlation = "failed_test_correlation_body_not_json"
+        test_request = "failed_test_request_body_not_json"
+        test_supplier = "failed_test_supplier_body_not_json"
+        test_actual_path = "/failed_test_body_not_json"
+        test_resource_path = "/failed_test_body_not_json"
+
+        # Act
+        decorated_function_raises = function_info(self.mock_function_raises)
+
+        with self.assertRaises(ValueError):
+            #Assert
+            event = {'headers': {
+                'X-Correlation-ID': test_correlation,
+                'X-Request-ID': test_request,
+                'SupplierSystem': test_supplier
+            },
+                'path': test_actual_path, 'requestContext': {'resourcePath': test_resource_path},
+                'body': "invalid"}
+
+            context = {}
+            decorated_function_raises(event, context)
+
+        #Assert
+        args, kwargs = mock_logger.exception.call_args
+        logged_info = json.loads(args[0])
+
+        self.assertEqual(logged_info['X-Correlation-ID'], test_correlation)
+        self.assertEqual(logged_info['X-Request-ID'], test_request)
+        self.assertEqual(logged_info['supplier'], test_supplier)
+        self.assertEqual(logged_info['actual_path'], test_actual_path)
+        self.assertEqual(logged_info['resource_path'], test_resource_path)
+        self.assertNotIn('local_id', logged_info)
+        self.assertNotIn('vaccine_type', logged_info)
+
+    def test_body_invalid_identifier(self, mock_logger, mock_firehose_logger):
+        # Arrange
+        test_correlation = "failed_test_correlation_invalid_identifier"
+        test_request = "failed_test_request_invalid_identifier"
+        test_supplier = "failed_test_supplier_invalid_identifier"
+        test_actual_path = "/failed_test_invalid_identifier"
+        test_resource_path = "/failed_test_invalid_identifier"
+
+        self.mock_redis_client.hget.return_value = "FLU"
+
+        # Act
+        decorated_function_raises = function_info(self.mock_function_raises)
+
+        with self.assertRaises(ValueError):
+            #Assert
+            event = {'headers': {
+                'X-Correlation-ID': test_correlation,
+                'X-Request-ID': test_request,
+                'SupplierSystem': test_supplier
+            },
+                'path': test_actual_path, 'requestContext': {'resourcePath': test_resource_path},
+                'body': "{\"identifier\": [], \"protocolApplied\": [{\"targetDisease\": [{\"coding\": [{\"system\": \"http://snomed.info/sct\", \"code\": \"840539006\", \"display\": \"Disease caused by severe acute respiratory syndrome coronavirus 2\"}]}]}]}"}
+
+            context = {}
+            decorated_function_raises(event, context)
+
+        #Assert
+        args, kwargs = mock_logger.exception.call_args
+        logged_info = json.loads(args[0])
+
+        self.assertEqual(logged_info['X-Correlation-ID'], test_correlation)
+        self.assertEqual(logged_info['X-Request-ID'], test_request)
+        self.assertEqual(logged_info['supplier'], test_supplier)
+        self.assertEqual(logged_info['actual_path'], test_actual_path)
+        self.assertEqual(logged_info['resource_path'], test_resource_path)
+        self.assertNotIn('local_id', logged_info)
+        self.assertEqual(logged_info['vaccine_type'], 'FLU')
+
+    def test_body_invalid_protocol_applied(self, mock_logger, mock_firehose_logger):
+        # Arrange
+        test_correlation = "failed_test_correlation_invalid_protocol"
+        test_request = "failed_test_request_invalid_protocol"
+        test_supplier = "failed_test_supplier_invalid_protocol"
+        test_actual_path = "/failed_test_invalid_protocol"
+        test_resource_path = "/failed_test_invalid_protocol"
+
+        self.mock_redis_client.hget.return_value = "FLU"
+
+        # Act
+        decorated_function_raises = function_info(self.mock_function_raises)
+
+        with self.assertRaises(ValueError):
+            #Assert
+            event = {'headers': {
+                'X-Correlation-ID': test_correlation,
+                'X-Request-ID': test_request,
+                'SupplierSystem': test_supplier
+            },
+                'path': test_actual_path, 'requestContext': {'resourcePath': test_resource_path},
+                'body': "{\"identifier\": [{\"system\": \"http://test\", \"value\": \"12345\"}], \"protocolApplied\": []}"}
+
+            context = {}
+            decorated_function_raises(event, context)
+
+        #Assert
+        args, kwargs = mock_logger.exception.call_args
+        logged_info = json.loads(args[0])
+
+        self.assertEqual(logged_info['X-Correlation-ID'], test_correlation)
+        self.assertEqual(logged_info['X-Request-ID'], test_request)
+        self.assertEqual(logged_info['supplier'], test_supplier)
+        self.assertEqual(logged_info['actual_path'], test_actual_path)
+        self.assertEqual(logged_info['resource_path'], test_resource_path)
+        self.assertEqual(logged_info['local_id'], '12345^http://test')
+        self.assertNotIn('vaccine_type', logged_info)