From 5bcd3c01cb2bba7ecbb3efb4a74ebdf9e2efdda1 Mon Sep 17 00:00:00 2001 From: Alex Vandiver Date: Tue, 19 Oct 2021 23:16:18 +0000 Subject: [PATCH] push_notifications: Add log line with user-id, UUID, and devices. Being able to determine how many distinct users are getting push notifications per remote host is useful, as is the distribution of device counts. This parallels the log line in handle_push_notification for push notifications from local realms, handled via the event queue. --- zerver/lib/push_notifications.py | 2 +- zerver/tests/test_push_notifications.py | 40 +++++++++++++++++++++---- zilencer/views.py | 10 +++++++ 3 files changed, 45 insertions(+), 7 deletions(-) diff --git a/zerver/lib/push_notifications.py b/zerver/lib/push_notifications.py index b8c144e011..1d388cbec8 100644 --- a/zerver/lib/push_notifications.py +++ b/zerver/lib/push_notifications.py @@ -983,7 +983,7 @@ def handle_push_notification(user_profile_id: int, missed_message: Dict[str, Any ) logger.info( - "Sending mobile push notifications for user %s: %s via FCM devices, %s via APNs devices", + "Sending mobile push notifications for local user %s: %s via FCM devices, %s via APNs devices", user_profile_id, len(android_devices), len(apple_devices), diff --git a/zerver/tests/test_push_notifications.py b/zerver/tests/test_push_notifications.py index ba818745b3..13a09d485a 100644 --- a/zerver/tests/test_push_notifications.py +++ b/zerver/tests/test_push_notifications.py @@ -300,7 +300,7 @@ class PushBouncerNotificationTest(BouncerTestCase): } with mock.patch("zilencer.views.send_android_push_notification"), mock.patch( "zilencer.views.send_apple_push_notification" - ): + ), self.assertLogs("zilencer.views", level="INFO") as logger: result = self.uuid_post( self.server_uuid, "/api/v1/remotes/push/notify", @@ -313,6 +313,14 @@ class PushBouncerNotificationTest(BouncerTestCase): {"result": "success", "msg": "", "total_android_devices": 2, "total_apple_devices": 1}, data, ) + self.assertEqual( + logger.output, + [ + "INFO:zilencer.views:" + f"Sending mobile push notifications for remote user 1234-abcd:{hamlet.id}: " + "2 via FCM devices, 1 via APNs devices" + ], + ) def test_remote_push_unregister_all(self) -> None: payload = self.get_generic_payload("register") @@ -868,7 +876,9 @@ class HandlePushNotificationTest(PushNotificationTest): "zerver.lib.push_notifications.gcm_client" ) as mock_gcm, self.mock_apns() as apns_context, self.assertLogs( "zerver.lib.push_notifications", level="INFO" - ) as logger: + ) as pn_logger, self.assertLogs( + "zilencer.views", level="INFO" + ) as views_logger: apns_devices = [ (b64_to_hex(device.token), device.ios_app_id, device.token) for device in RemotePushDeviceToken.objects.filter(kind=PushDeviceToken.APNS) @@ -885,16 +895,24 @@ class HandlePushNotificationTest(PushNotificationTest): ) apns_context.apns.send_notification.return_value.set_result(result) handle_push_notification(self.user_profile.id, missed_message) + self.assertEqual( + views_logger.output, + [ + "INFO:zilencer.views:" + f"Sending mobile push notifications for remote user 1234-abcd:{self.user_profile.id}: " + f"{len(gcm_devices)} via FCM devices, {len(apns_devices)} via APNs devices" + ], + ) for _, _, token in apns_devices: self.assertIn( "INFO:zerver.lib.push_notifications:" f"APNs: Success sending for user {self.user_profile.id} to device {token}", - logger.output, + pn_logger.output, ) for _, _, token in gcm_devices: self.assertIn( "INFO:zerver.lib.push_notifications:" f"GCM: Sent {token} as {message.id}", - logger.output, + pn_logger.output, ) @override_settings(PUSH_NOTIFICATION_BOUNCER_URL="https://push.zulip.org.example.com") @@ -918,7 +936,9 @@ class HandlePushNotificationTest(PushNotificationTest): "zerver.lib.push_notifications.gcm_client" ) as mock_gcm, self.mock_apns() as apns_context, self.assertLogs( "zerver.lib.push_notifications", level="INFO" - ) as logger: + ) as pn_logger, self.assertLogs( + "zilencer.views", level="INFO" + ) as views_logger: apns_devices = [ (b64_to_hex(device.token), device.ios_app_id, device.token) for device in RemotePushDeviceToken.objects.filter(kind=PushDeviceToken.APNS) @@ -936,11 +956,19 @@ class HandlePushNotificationTest(PushNotificationTest): ) apns_context.apns.send_notification.return_value.set_result(result) handle_push_notification(self.user_profile.id, missed_message) + self.assertEqual( + views_logger.output, + [ + "INFO:zilencer.views:" + f"Sending mobile push notifications for remote user 1234-abcd:{self.user_profile.id}: " + f"{len(gcm_devices)} via FCM devices, {len(apns_devices)} via APNs devices" + ], + ) for _, _, token in apns_devices: self.assertIn( "INFO:zerver.lib.push_notifications:" f"APNs: Removing invalid/expired token {token} (Unregistered)", - logger.output, + pn_logger.output, ) self.assertEqual( RemotePushDeviceToken.objects.filter(kind=PushDeviceToken.APNS).count(), 0 diff --git a/zilencer/views.py b/zilencer/views.py index 7851f8b7cd..465a4cb353 100644 --- a/zilencer/views.py +++ b/zilencer/views.py @@ -41,6 +41,8 @@ from zilencer.models import ( RemoteZulipServer, ) +logger = logging.getLogger(__name__) + def validate_entity(entity: Union[UserProfile, RemoteZulipServer]) -> RemoteZulipServer: if not isinstance(entity, RemoteZulipServer): @@ -192,6 +194,14 @@ def remote_server_notify_push( ) ) + logger.info( + "Sending mobile push notifications for remote user %s:%s: %s via FCM devices, %s via APNs devices", + server.uuid, + user_id, + len(android_devices), + len(apple_devices), + ) + send_android_push_notification(android_devices, gcm_payload, gcm_options, remote=True) send_apple_push_notification(user_id, apple_devices, apns_payload, remote=True)