push_notifications: Log roundtrip time since worker decided to send.

Adds a log for the end-to-end latency from when the worker decided
to send push notifications & received a success response from bouncer.

Fixes part of #35368.

(cherry picked from commit c604ecb902)

zerver/lib/push_notifications.py

@@ -4,6 +4,7 @@ import asyncio
 import copy
 import logging
 import re
+import time
 from collections.abc import Mapping, Sequence
 from dataclasses import asdict, dataclass, field
 from email.headerregistry import Address
@@ -1528,6 +1529,7 @@ def send_push_notifications(
 
     # Send push notification
     try:
+        start_time = time.perf_counter()
         response_data: SendNotificationResponseData | SendNotificationRemoteResponseData
         if settings.ZILENCER_ENABLED:
             from zilencer.lib.push_notifications import send_e2ee_push_notifications
@@ -1543,6 +1545,7 @@ def send_push_notifications(
             }
             result = send_json_to_push_bouncer("POST", "push/e2ee/notify", post_data)
             response_data = send_notification_remote_response_data_adapter.validate_python(result)
+        send_push_notifications_latency = time.perf_counter() - start_time
     except (MissingRemoteRealmError, PushNotificationsDisallowedByBouncerError) as e:
         reason = e.reason if isinstance(e, PushNotificationsDisallowedByBouncerError) else e.msg
         logger.warning("Bouncer refused to send E2EE push notification: %s", reason)
@@ -1586,10 +1589,11 @@ def send_push_notifications(
     )
 
     logger.info(
-        "Sent E2EE mobile push notifications for user %s: %s via FCM, %s via APNs",
+        "Sent E2EE mobile push notifications for user %s: %s via FCM, %s via APNs in %.3fs",
         user_profile.id,
         android_successfully_sent_count,
         apple_successfully_sent_count,
+        send_push_notifications_latency,
     )
 
     if "realm_push_status" in response_data:

zerver/tests/test_e2ee_push_notifications.py

@@ -56,6 +56,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             self.mock_apns() as send_notification,
             self.assertLogs("zerver.lib.push_notifications", level="INFO") as zerver_logger,
             self.assertLogs("zilencer.lib.push_notifications", level="INFO") as zilencer_logger,
+            mock.patch("time.perf_counter", side_effect=[10.0, 15.0]),
         ):
             mock_fcm_messaging.send_each.return_value = self.make_fcm_success_response()
             send_notification.return_value.is_successful = True
@@ -87,7 +88,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             )
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs in 5.000s",
                 zerver_logger.output[3],
             )
 
@@ -153,6 +154,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             self.mock_apns() as send_notification,
             self.assertLogs("zerver.lib.push_notifications", level="INFO") as zerver_logger,
             self.assertLogs("zilencer.lib.push_notifications", level="INFO") as zilencer_logger,
+            mock.patch("time.perf_counter", side_effect=[10.5, 11.0]),
         ):
             mock_fcm_messaging.send_each.return_value = self.make_fcm_error_response(
                 UnregisteredError("Token expired")
@@ -187,7 +189,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             )
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 0 via FCM, 0 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 0 via FCM, 0 via APNs in 0.500s",
                 zerver_logger.output[4],
             )
 
@@ -218,6 +220,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             mock.patch("zilencer.lib.push_notifications.get_apns_context", return_value=None),
             self.assertLogs("zerver.lib.push_notifications", level="INFO") as zerver_logger,
             self.assertLogs("zilencer.lib.push_notifications", level="DEBUG") as zilencer_logger,
+            mock.patch("time.perf_counter", side_effect=[10.0, 12.0]),
         ):
             mock_fcm_messaging.send_each.return_value = self.make_fcm_error_response(
                 InternalError("fcm-error")
@@ -245,7 +248,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             )
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 0 via FCM, 0 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 0 via FCM, 0 via APNs in 2.000s",
                 zerver_logger.output[2],
             )
 
@@ -269,6 +272,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             ),
             self.assertLogs("zerver.lib.push_notifications", level="INFO") as zerver_logger,
             self.assertLogs("zilencer.lib.push_notifications", level="WARNING") as zilencer_logger,
+            mock.patch("time.perf_counter", side_effect=[10.0, 12.0]),
         ):
             mock_fcm_messaging.send_each.side_effect = InternalError("server error")
             handle_push_notification(hamlet.id, missed_message)
@@ -284,7 +288,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             )
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 0 via FCM, 1 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 0 via FCM, 1 via APNs in 2.000s",
                 zerver_logger.output[2],
             )
 
@@ -366,6 +370,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             ),
             self.assertLogs("zerver.lib.push_notifications", level="INFO") as zerver_logger,
             self.assertLogs("zilencer.lib.push_notifications", level="INFO") as zilencer_logger,
+            mock.patch("time.perf_counter", side_effect=[10.05, 12.10]),
         ):
             mock_fcm_messaging.send_each.return_value = self.make_fcm_success_response()
             send_notification.return_value.is_successful = True
@@ -397,7 +402,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             )
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs in 2.050s",
                 zerver_logger.output[3],
             )
 
@@ -564,6 +569,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             ),
             self.assertLogs("zerver.lib.push_notifications", level="INFO") as zerver_logger,
             self.assertLogs("zilencer.lib.push_notifications", level="INFO") as zilencer_logger,
+            mock.patch("time.perf_counter", side_effect=[10.0, 12.0]),
         ):
             mock_fcm_messaging_legacy.send_each.return_value = self.make_fcm_success_response(
                 for_legacy=True
@@ -608,7 +614,7 @@ class SendPushNotificationTest(E2EEPushNotificationTestCase):
             )
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs in 2.000s",
                 zerver_logger.output[7],
             )
 
@@ -716,6 +722,7 @@ class RemovePushNotificationTest(E2EEPushNotificationTestCase):
             self.mock_apns() as send_notification,
             self.assertLogs("zerver.lib.push_notifications", level="INFO") as zerver_logger,
             self.assertLogs("zilencer.lib.push_notifications", level="INFO"),
+            mock.patch("time.perf_counter", side_effect=[10.0, 12.0]),
         ):
             mock_fcm_messaging.send_each.return_value = self.make_fcm_success_response()
             send_notification.return_value.is_successful = True
@@ -730,7 +737,7 @@ class RemovePushNotificationTest(E2EEPushNotificationTestCase):
 
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs in 2.000s",
                 zerver_logger.output[2],
             )
 
@@ -759,6 +766,7 @@ class RemovePushNotificationTest(E2EEPushNotificationTestCase):
             ),
             self.assertLogs("zerver.lib.push_notifications", level="INFO") as zerver_logger,
             self.assertLogs("zilencer.lib.push_notifications", level="INFO"),
+            mock.patch("time.perf_counter", side_effect=[10.0, 12.0]),
         ):
             mock_fcm_messaging.send_each.return_value = self.make_fcm_success_response()
             send_notification.return_value.is_successful = True
@@ -773,7 +781,7 @@ class RemovePushNotificationTest(E2EEPushNotificationTestCase):
 
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs in 2.000s",
                 zerver_logger.output[2],
             )
 
@@ -891,6 +899,7 @@ class SendTestPushNotificationTest(E2EEPushNotificationTestCase):
             self.mock_apns() as send_notification,
             self.assertLogs("zilencer.lib.push_notifications", level="INFO"),
             self.assertLogs("zerver.lib.push_notifications", level="INFO") as zerver_logger,
+            mock.patch("time.perf_counter", side_effect=[10.0, 12.0, 13.0, 16.0]),
         ):
             mock_fcm_messaging.send_each.return_value = self.make_fcm_success_response()
             send_notification.return_value.is_successful = True
@@ -911,7 +920,7 @@ class SendTestPushNotificationTest(E2EEPushNotificationTestCase):
             )
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs in 2.000s",
                 zerver_logger.output[-1],
             )
 
@@ -931,7 +940,7 @@ class SendTestPushNotificationTest(E2EEPushNotificationTestCase):
             )
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 0 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 0 via APNs in 3.000s",
                 zerver_logger.output[-1],
             )
 
@@ -952,6 +961,7 @@ class SendTestPushNotificationTest(E2EEPushNotificationTestCase):
             ),
             self.assertLogs("zilencer.lib.push_notifications", level="INFO"),
             self.assertLogs("zerver.lib.push_notifications", level="INFO") as zerver_logger,
+            mock.patch("time.perf_counter", side_effect=[10.0, 12.0]),
         ):
             mock_fcm_messaging.send_each.return_value = self.make_fcm_success_response()
             send_notification.return_value.is_successful = True
@@ -972,7 +982,7 @@ class SendTestPushNotificationTest(E2EEPushNotificationTestCase):
             )
             self.assertEqual(
                 "INFO:zerver.lib.push_notifications:"
-                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs",
+                f"Sent E2EE mobile push notifications for user {hamlet.id}: 1 via FCM, 1 via APNs in 2.000s",
                 zerver_logger.output[-1],
             )