unit tests, mock dynamodb, refactoring

Author: JamesW1-NHS

ack_backend/src/update_ack_file.py

@@ -66,6 +66,25 @@ def obtain_current_ack_content(temp_ack_file_key: str) -> StringIO:
     return accumulated_csv_content
 
 
+def handle_ingestion_complete(
+    temp_ack_file_key: str,
+    message_id: str,
+    supplier: str,
+    vaccine_type: str,
+    archive_ack_file_key: str,
+    file_key: str,
+) -> None:
+    """Handles processing where the complete file has been ingested"""
+    move_file(ACK_BUCKET_NAME, temp_ack_file_key, archive_ack_file_key)
+    move_file(SOURCE_BUCKET_NAME, f"processing/{file_key}", f"archive/{file_key}")
+    # Update the audit table and invoke the filename lambda with next file in the queue (if one exists)
+    change_audit_table_status_to_processed(file_key, message_id)
+    supplier_queue = f"{supplier}_{vaccine_type}"
+    next_queued_file_details = get_next_queued_file_details(supplier_queue)
+    if next_queued_file_details:
+        invoke_filename_lambda(next_queued_file_details["filename"], next_queued_file_details["message_id"])
+
+
 @upload_ack_file_logging_decorator
 def upload_ack_file(
     temp_ack_file_key: str,
@@ -89,16 +108,14 @@ def upload_ack_file(
     row_count_destination = get_row_count(ACK_BUCKET_NAME, temp_ack_file_key)
     # TODO: Should we check for > and if so what handling is required
     if row_count_destination == row_count_source:
-        move_file(ACK_BUCKET_NAME, temp_ack_file_key, archive_ack_file_key)
-        move_file(SOURCE_BUCKET_NAME, f"processing/{file_key}", f"archive/{file_key}")
-
-        # Update the audit table and invoke the filename lambda with next file in the queue (if one exists)
-        change_audit_table_status_to_processed(file_key, message_id)
-        supplier_queue = f"{supplier}_{vaccine_type}"
-        next_queued_file_details = get_next_queued_file_details(supplier_queue)
-        if next_queued_file_details:
-            invoke_filename_lambda(next_queued_file_details["filename"], next_queued_file_details["message_id"])
-
+        handle_ingestion_complete(
+            temp_ack_file_key,
+            message_id,
+            supplier,
+            vaccine_type,
+            archive_ack_file_key,
+            file_key,
+        )
         # Ingestion of this file is complete
         result = {
             "message_id": message_id,

ack_backend/tests/test_splunk_logging.py

@@ -5,7 +5,7 @@
 import json
 from io import StringIO
 from contextlib import ExitStack
-from moto import mock_s3
+from moto import mock_s3, mock_dynamodb
 from boto3 import client as boto3_client
 
 from tests.utils.values_for_ack_backend_tests import (
@@ -19,18 +19,21 @@
 from tests.utils.utils_for_ack_backend_tests import generate_event
 
 with patch.dict("os.environ", MOCK_ENVIRONMENT_DICT):
+    from clients import REGION_NAME
     from ack_processor import lambda_handler
 
 s3_client = boto3_client("s3")
+dynamodb_client = boto3_client("dynamodb", region_name=REGION_NAME)
 
 
-@patch.dict("os.environ", MOCK_ENVIRONMENT_DICT)
 @mock_s3
+@mock_dynamodb
+@patch.dict("os.environ", MOCK_ENVIRONMENT_DICT)
 class TestLoggingDecorators(unittest.TestCase):
     """Tests for the ack lambda logging decorators"""
 
     def setUp(self):
-        GenericSetUp(s3_client)
+        GenericSetUp(s3_client, None, dynamodb_client)
 
         # MOCK SOURCE FILE WITH 100 ROWS TO SIMULATE THE SCENARIO WHERE THE ACK FILE IS NO FULL.
         # TODO: Test all other scenarios.
@@ -59,8 +62,8 @@ def run(self, result=None):
             # Any uses of the logger in other files will confound the tests and should be patched here.
             patch("update_ack_file.logger"),
             # Time is incremented by 1.0 for each call to time.time for ease of testing.
-            # Range is set to a large number (100) due to many calls being made to time.time for some tests.
-            patch("logging_decorators.time.time", side_effect=[0.0 + i for i in range(100)]),
+            # Range is set to a large number (300) due to many calls being made to time.time for some tests.
+            patch("logging_decorators.time.time", side_effect=[0.0 + i for i in range(300)]),
         ]
 
         # Set up the ExitStack. Note that patches need to be explicitly started so that they will be applied even when
@@ -85,11 +88,16 @@ def extract_all_call_args_for_logger_error(self, mock_logger):
         """Extracts all arguments for logger.error."""
         return [args[0] for args, _ in mock_logger.error.call_args_list]
 
-    def expected_lambda_handler_logs(self, success: bool, number_of_rows, diagnostics=None):
+    def expected_lambda_handler_logs(self, success: bool, number_of_rows, ingestion_complete=False, diagnostics=None):
         """Returns the expected logs for the lambda handler function."""
         # Mocking of timings is such that the time taken is 2 seconds for each row, 
-        # plus 2 seconds for the handler if it succeeds (i.e. it calls update_ack_file) or 1 second if it doesn't
-        time_taken = f"{number_of_rows * 2 + 2}.0s" if success else f"{number_of_rows * 2 + 1}.0s"
+        # plus 2 seconds for the handler if it succeeds (i.e. it calls update_ack_file) or 1 second if it doesn't;
+        # plus an extra second if ingestion is complete
+        if success:
+            time_taken = f"{number_of_rows * 2 + 3}.0s" if ingestion_complete else f"{number_of_rows * 2 + 2}.0s"
+        else:
+            time_taken = f"{number_of_rows * 2 + 1}.0s"
+
         base_log = (
             ValidValues.lambda_handler_success_expected_log
             if success
@@ -139,7 +147,7 @@ def test_splunk_logging_missing_data(self):
             expected_first_logger_info_data = {**InvalidValues.Logging_with_no_values}
 
             expected_first_logger_error_data = self.expected_lambda_handler_logs(
-                success=False, number_of_rows=1, diagnostics="'NoneType' object has no attribute 'replace'"
+                success=False, number_of_rows=1, ingestion_complete=False, diagnostics="'NoneType' object has no attribute 'replace'"
             )
 
             first_logger_info_call_args = json.loads(self.extract_all_call_args_for_logger_info(mock_logger)[0])
@@ -305,6 +313,90 @@ def test_splunk_logging_multiple_with_diagnostics(
             ]
         )
 
+    def test_splunk_update_ack_file_not_logged(self):
+        self.maxDiff = None
+        """Tests that update_ack_file is not logged if we have sent acks for less than the whole file"""
+        # send 98 messages
+        messages = []
+        for i in range(1, 99):
+            message_value = "test" + str(i)
+            messages.append({"row_id": message_value})
+
+        with (
+            patch("logging_decorators.send_log_to_firehose") as mock_send_log_to_firehose,
+            patch("logging_decorators.logger") as mock_logger,
+            patch("update_ack_file.handle_ingestion_complete") as mock_handle_ingestion_complete,  # noqa: E999
+        ):
+            result = lambda_handler(generate_event(messages), context={})
+
+        self.assertEqual(result, EXPECTED_ACK_LAMBDA_RESPONSE_FOR_SUCCESS)
+
+        expected_secondlast_logger_info_data = {
+                **ValidValues.mock_message_expected_log_value,
+                "message_id": "test98",
+            }
+        expected_last_logger_info_data = self.expected_lambda_handler_logs(success=True, number_of_rows=98)
+
+        all_logger_info_call_args = self.extract_all_call_args_for_logger_info(mock_logger)
+        secondlast_logger_info_call_args = json.loads(all_logger_info_call_args[97])
+        last_logger_info_call_args = json.loads(all_logger_info_call_args[98])
+
+        self.assertEqual(secondlast_logger_info_call_args, expected_secondlast_logger_info_data)
+        self.assertEqual(last_logger_info_call_args, expected_last_logger_info_data)
+
+        mock_send_log_to_firehose.assert_has_calls(
+            [
+                call(secondlast_logger_info_call_args),
+                call(last_logger_info_call_args),
+            ]
+        )
+        mock_handle_ingestion_complete.assert_not_called()
+
+    def test_splunk_update_ack_file_logged(self):
+        """Tests that update_ack_file is logged if we have sent acks for the whole file"""
+        # send 99 messages
+        messages = []
+        for i in range(1, 100):
+            message_value = "test" + str(i)
+            messages.append({"row_id": message_value})
+
+        with (
+            patch("logging_decorators.send_log_to_firehose") as mock_send_log_to_firehose,
+            patch("logging_decorators.logger") as mock_logger,
+            patch("update_ack_file.handle_ingestion_complete") as mock_handle_ingestion_complete,  # noqa: E999
+        ):
+            result = lambda_handler(generate_event(messages), context={})
+
+        self.assertEqual(result, EXPECTED_ACK_LAMBDA_RESPONSE_FOR_SUCCESS)
+
+        expected_thirdlast_logger_info_data = {
+                **ValidValues.mock_message_expected_log_value,
+                "message_id": "test99",
+            }
+        expected_secondlast_logger_info_data = {
+                **ValidValues.upload_ack_file_expected_log,
+                "message_id": "test1",
+                "time_taken": "1.0s"
+            }
+        expected_last_logger_info_data = self.expected_lambda_handler_logs(success=True, number_of_rows=99, ingestion_complete=True)
+
+        all_logger_info_call_args = self.extract_all_call_args_for_logger_info(mock_logger)
+        thirdlast_logger_info_call_args = json.loads(all_logger_info_call_args[98])
+        secondlast_logger_info_call_args = json.loads(all_logger_info_call_args[99])
+        last_logger_info_call_args = json.loads(all_logger_info_call_args[100])
+        self.assertEqual(thirdlast_logger_info_call_args, expected_thirdlast_logger_info_data)
+        self.assertEqual(secondlast_logger_info_call_args, expected_secondlast_logger_info_data)
+        self.assertEqual(last_logger_info_call_args, expected_last_logger_info_data)
+
+        mock_send_log_to_firehose.assert_has_calls(
+            [
+                call(thirdlast_logger_info_call_args),
+                call(secondlast_logger_info_call_args),
+                call(last_logger_info_call_args),
+            ]
+        )
+        mock_handle_ingestion_complete.assert_called()
+
 
 if __name__ == "__main__":
     unittest.main()