Improve callback failure logging to include service_id (#2301)

* Improve callback failure logging to include service_id

* Tweak message

---------

Co-authored-by: Jumana B <[email protected]>

app/celery/nightly_tasks.py

@@ -136,7 +136,7 @@ def timeout_notifications():
         if service_callback_api:
             signed_notification = create_delivery_status_callback_data(notification, service_callback_api)
             send_delivery_status_to_service.apply_async(
-                [str(notification.id), signed_notification],
+                [str(notification.id), signed_notification, notification.service_id],
                 queue=QueueNames.CALLBACKS,
             )
 

app/celery/service_callback_tasks.py

@@ -10,7 +10,7 @@
 
 @notify_celery.task(bind=True, name="send-delivery-status", max_retries=5, default_retry_delay=300)
 @statsd(namespace="tasks")
-def send_delivery_status_to_service(self, notification_id, signed_status_update):
+def send_delivery_status_to_service(self, notification_id, signed_status_update, service_id):
     status_update = signer_delivery_status.verify(signed_status_update)
 
     data = {
@@ -27,6 +27,7 @@ def send_delivery_status_to_service(self, notification_id, signed_status_update)
     }
     _send_data_to_service_callback_api(
         self,
+        service_id,
         data,
         status_update["service_callback_api_url"],
         status_update["service_callback_api_bearer_token"],
@@ -36,7 +37,7 @@ def send_delivery_status_to_service(self, notification_id, signed_status_update)
 
 @notify_celery.task(bind=True, name="send-complaint", max_retries=5, default_retry_delay=300)
 @statsd(namespace="tasks")
-def send_complaint_to_service(self, complaint_data):
+def send_complaint_to_service(self, complaint_data, service_id):
     complaint = signer_complaint.verify(complaint_data)
 
     data = {
@@ -49,17 +50,20 @@ def send_complaint_to_service(self, complaint_data):
 
     _send_data_to_service_callback_api(
         self,
+        service_id,
         data,
         complaint["service_callback_api_url"],
         complaint["service_callback_api_bearer_token"],
         "send_complaint_to_service",
     )
 
 
-def _send_data_to_service_callback_api(self, data, service_callback_url, token, function_name):
+def _send_data_to_service_callback_api(self, service_id, data, service_callback_url, token, function_name):
     notification_id = data["notification_id"] if "notification_id" in data else data["id"]
     try:
-        current_app.logger.info("{} sending {} to {}".format(function_name, notification_id, service_callback_url))
+        current_app.logger.info(
+            "{} sending {} to {} service: {}".format(function_name, notification_id, service_callback_url, service_id)
+        )
         response = request(
             method="POST",
             url=service_callback_url,
@@ -72,19 +76,19 @@ def _send_data_to_service_callback_api(self, data, service_callback_url, token,
         )
 
         current_app.logger.info(
-            f"{function_name} sending {notification_id} to {service_callback_url}, response {response.status_code}"
+            f"{function_name} sent {notification_id} to {service_callback_url} service: {service_id}, response {response.status_code}"
         )
 
         response.raise_for_status()
     except RequestException as e:
         current_app.logger.warning(
-            f"{function_name} request failed for notification_id: {notification_id} and url: {service_callback_url}. exc: {e}"
+            f"{function_name} request failed for notification_id: {notification_id} to url: {service_callback_url} service: {service_id} exc: {e}"
         )
         # Retry if the response status code is server-side or 429 (too many requests).
         if not isinstance(e, HTTPError) or e.response.status_code >= 500 or e.response.status_code == 429:
             try:
                 self.retry(queue=QueueNames.CALLBACKS_RETRY)
             except self.MaxRetriesExceededError:
                 current_app.logger.warning(
-                    "Retry: {function_name} has retried the max num of times for callback url {service_callback_url} and notification_id: {notification_id}"
+                    "Retry: {function_name} has retried the max num of times for callback url {service_callback_url} notification_id: {notification_id} service: {service_id}"
                 )

app/commands/support.py

@@ -117,7 +117,7 @@ def replay_service_callbacks(file_name, service_id):
             "service_callback_api_bearer_token": callback_api.bearer_token,
         }
         signed_status_update = signer_delivery_status.sign(data)
-        send_delivery_status_to_service.apply_async([str(n.id), signed_status_update], queue=QueueNames.CALLBACKS)
+        send_delivery_status_to_service.apply_async([str(n.id), signed_status_update, service_id], queue=QueueNames.CALLBACKS)
 
     print(
         "Replay service status for service: {}. Sent {} notification status updates to the queue".format(

app/notifications/callbacks.py

@@ -23,7 +23,9 @@ def _check_and_queue_callback_task(notification):
             return
 
         notification_data = create_delivery_status_callback_data(notification, service_callback_api)
-        send_delivery_status_to_service.apply_async([str(notification.id), notification_data], queue=QueueNames.CALLBACKS)
+        send_delivery_status_to_service.apply_async(
+            [str(notification.id), notification_data, notification.service_id], queue=QueueNames.CALLBACKS
+        )
 
 
 def create_delivery_status_callback_data(notification, service_callback_api):

app/notifications/notifications_ses_callback.py

@@ -206,4 +206,4 @@ def _check_and_queue_complaint_callback_task(complaint, notification, recipient)
     service_callback_api = get_service_complaint_callback_api_for_service(service_id=notification.service_id)
     if service_callback_api:
         complaint_data = create_complaint_callback_data(complaint, notification, service_callback_api, recipient)
-        send_complaint_to_service.apply_async([complaint_data], queue=QueueNames.CALLBACKS)
+        send_complaint_to_service.apply_async([complaint_data, notification.service_id], queue=QueueNames.CALLBACKS)

app/notifications/process_client_response.py

@@ -53,7 +53,7 @@ def _process_for_status(notification_status, client_name, provider_reference):
         if service_callback_api:
             signed_notification = create_delivery_status_callback_data(notification, service_callback_api)
             send_delivery_status_to_service.apply_async(
-                [str(notification.id), signed_notification],
+                [str(notification.id), signed_notification, notification.service_id],
                 queue=QueueNames.CALLBACKS,
             )
 

tests/app/celery/test_nightly_tasks.py

@@ -244,7 +244,7 @@ def test_timeout_notifications_sends_status_update_to_service(client, sample_tem
     timeout_notifications()
 
     signed_data = create_delivery_status_callback_data(notification, callback_api)
-    mocked.assert_called_once_with([str(notification.id), signed_data], queue=QueueNames.CALLBACKS)
+    mocked.assert_called_once_with([str(notification.id), signed_data, notification.service_id], queue=QueueNames.CALLBACKS)
 
 
 def test_send_daily_performance_stats_calls_does_not_send_if_inactive(client, mocker):

tests/app/celery/test_process_pinpoint_receipts_tasks.py

@@ -239,4 +239,6 @@ def test_process_pinpoint_results_calls_service_callback(sample_template, notify
         statsd_client.incr.assert_any_call("callback.pinpoint.delivered")
         updated_notification = get_notification_by_id(notification.id)
         signed_data = create_delivery_status_callback_data(updated_notification, callback_api)
-        mock_send_status.assert_called_once_with([str(notification.id), signed_data], queue="service-callbacks")
+        mock_send_status.assert_called_once_with(
+            [str(notification.id), signed_data, notification.service_id], queue="service-callbacks"
+        )

tests/app/celery/test_process_ses_receipts_tasks.py

@@ -121,7 +121,9 @@ def test_ses_callback_should_update_notification_status(notify_db, notify_db_ses
         statsd_client.incr.assert_any_call("callback.ses.delivered")
         updated_notification = Notification.query.get(notification.id)
         encrypted_data = create_delivery_status_callback_data(updated_notification, callback_api)
-        send_mock.assert_called_once_with([str(notification.id), encrypted_data], queue="service-callbacks")
+        send_mock.assert_called_once_with(
+            [str(notification.id), encrypted_data, notification.service_id], queue="service-callbacks"
+        )
 
 
 def test_ses_callback_dont_change_hard_bounce_status(sample_template, mocker):

tests/app/celery/test_process_sns_receipts_tasks.py

@@ -188,4 +188,4 @@ def test_process_sns_results_calls_service_callback(sample_template, notify_db_s
         statsd_client.incr.assert_any_call("callback.sns.delivered")
         updated_notification = get_notification_by_id(notification.id)
         signed_data = create_delivery_status_callback_data(updated_notification, callback_api)
-        send_mock.assert_called_once_with([str(notification.id), signed_data], queue="service-callbacks")
+        send_mock.assert_called_once_with([str(notification.id), signed_data, notification.service_id], queue="service-callbacks")

tests/app/celery/test_service_callback_tasks.py

@@ -37,7 +37,9 @@ def test_send_delivery_status_to_service_post_https_request_to_service_with_sign
     signed_status_update = _set_up_data_for_status_update(callback_api, notification)
     with requests_mock.Mocker() as request_mock:
         request_mock.post(callback_api.url, json={}, status_code=200)
-        send_delivery_status_to_service(notification.id, signed_status_update=signed_status_update)
+        send_delivery_status_to_service(
+            notification.id, signed_status_update=signed_status_update, service_id=notification.service_id
+        )
 
     mock_data = {
         "id": str(notification.id),
@@ -71,7 +73,7 @@ def test_send_complaint_to_service_posts_https_request_to_service_with_signed_da
         complaint_data = _set_up_data_for_complaint(callback_api, complaint, notification)
         with requests_mock.Mocker() as request_mock:
             request_mock.post(callback_api.url, json={}, status_code=200)
-            send_complaint_to_service(complaint_data)
+            send_complaint_to_service(complaint_data, notification.service_id)
 
         mock_data = {
             "notification_id": str(notification.id),
@@ -109,7 +111,7 @@ def test__send_data_to_service_callback_api_retries_if_request_returns_error_cod
     mocked = mocker.patch("app.celery.service_callback_tasks.send_delivery_status_to_service.retry")
     with requests_mock.Mocker() as request_mock:
         request_mock.post(callback_api.url, json={}, status_code=status_code)
-        send_delivery_status_to_service(notification.id, signed_status_update=signed_data)
+        send_delivery_status_to_service(notification.id, signed_status_update=signed_data, service_id=notification.service_id)
 
     assert mocked.call_count == 1
     assert mocked.call_args[1]["queue"] == "service-callbacks-retry"
@@ -134,7 +136,7 @@ def test__send_data_to_service_callback_api_does_not_retry_if_request_returns_40
     mocked = mocker.patch("app.celery.service_callback_tasks.send_delivery_status_to_service.retry")
     with requests_mock.Mocker() as request_mock:
         request_mock.post(callback_api.url, json={}, status_code=404)
-        send_delivery_status_to_service(notification.id, signed_status_update=signed_data)
+        send_delivery_status_to_service(notification.id, signed_status_update=signed_data, service_id=notification.service_id)
 
     assert mocked.call_count == 0
 
@@ -155,7 +157,7 @@ def test_send_delivery_status_to_service_succeeds_if_sent_at_is_none(notify_db_s
     mocked = mocker.patch("app.celery.service_callback_tasks.send_delivery_status_to_service.retry")
     with requests_mock.Mocker() as request_mock:
         request_mock.post(callback_api.url, json={}, status_code=404)
-        send_delivery_status_to_service(notification.id, signed_status_update=signed_data)
+        send_delivery_status_to_service(notification.id, signed_status_update=signed_data, service_id=notification.service_id)
 
     assert mocked.call_count == 0
 

tests/app/notifications/test_callbacks.py

@@ -86,7 +86,7 @@ def test_check_and_queue_callback_task_calls_delivery_task(
         _check_and_queue_callback_task(notification)
 
         mock_apply_async.assert_called_once_with(
-            [str(notification.id), create_delivery_status_callback_data(notification, callback_api)],
+            [str(notification.id), create_delivery_status_callback_data(notification, callback_api), notification.service_id],
             queue="service-callbacks",
         )