From 111ee64e36c68467fd07e1f435b16e3b02bf94d4 Mon Sep 17 00:00:00 2001 From: Alex Vandiver Date: Tue, 19 Oct 2021 23:52:23 +0000 Subject: [PATCH] push_notifications: Pass down the remote server and user-id for logs. This makes logging more consistent between FCM and APNs codepaths, and makes clear which user-ids are for local users, and which are opaque integers namespaced from some remote zulip server. --- zerver/lib/push_notifications.py | 41 +++++++++++++++++++++---- zerver/tests/test_push_notifications.py | 31 ++++++++++++++----- zilencer/views.py | 6 ++-- 3 files changed, 62 insertions(+), 16 deletions(-) diff --git a/zerver/lib/push_notifications.py b/zerver/lib/push_notifications.py index 1d388cbec8..fe3d8fa886 100644 --- a/zerver/lib/push_notifications.py +++ b/zerver/lib/push_notifications.py @@ -37,6 +37,7 @@ from zerver.models import ( get_display_recipient, get_user_profile_by_id, ) +from zilencer.models import RemoteZulipServer if TYPE_CHECKING: import aioapns @@ -130,7 +131,10 @@ APNS_MAX_RETRIES = 3 @statsd_increment("apple_push_notification") def send_apple_push_notification( - user_id: int, devices: Sequence[DeviceToken], payload_data: Dict[str, Any], remote: bool = False + user_id: int, + devices: Sequence[DeviceToken], + payload_data: Dict[str, Any], + remote: Optional[RemoteZulipServer] = None, ) -> None: if not devices: return @@ -155,7 +159,17 @@ def send_apple_push_notification( else: DeviceTokenClass = PushDeviceToken - logger.info("APNs: Sending notification for user %d to %d devices", user_id, len(devices)) + if remote: + logger.info( + "APNs: Sending notification for remote user %s:%d to %d devices", + remote.uuid, + user_id, + len(devices), + ) + else: + logger.info( + "APNs: Sending notification for local user %d to %d devices", user_id, len(devices) + ) payload_data = modernize_apns_payload(payload_data).copy() message = {**payload_data.pop("custom", {}), "aps": payload_data} for device in devices: @@ -228,11 +242,12 @@ def gcm_enabled() -> bool: # nocoverage return gcm_client is not None +# This is purely used in testing def send_android_push_notification_to_user( user_profile: UserProfile, data: Dict[str, Any], options: Dict[str, Any] ) -> None: devices = list(PushDeviceToken.objects.filter(user=user_profile, kind=PushDeviceToken.GCM)) - send_android_push_notification(devices, data, options) + send_android_push_notification(user_profile.id, devices, data, options) def parse_gcm_options(options: Dict[str, Any], data: Dict[str, Any]) -> str: @@ -282,10 +297,11 @@ def parse_gcm_options(options: Dict[str, Any], data: Dict[str, Any]) -> str: @statsd_increment("android_push_notification") def send_android_push_notification( + user_id: int, devices: Sequence[DeviceToken], data: Dict[str, Any], options: Dict[str, Any], - remote: bool = False, + remote: Optional[RemoteZulipServer] = None, ) -> None: """ Send a GCM message to the given devices. @@ -307,6 +323,17 @@ def send_android_push_notification( ) return + if remote: + logger.info( + "GCM: Sending notification for remote user %s:%d to %d devices", + remote.uuid, + user_id, + len(devices), + ) + else: + logger.info( + "GCM: Sending notification for local user %d to %d devices", user_id, len(devices) + ) reg_ids = [device.token for device in devices] priority = parse_gcm_options(options, data) try: @@ -876,7 +903,9 @@ def handle_remove_push_notification(user_profile_id: int, message_ids: List[int] PushDeviceToken.objects.filter(user=user_profile, kind=PushDeviceToken.APNS) ) if android_devices: - send_android_push_notification(android_devices, gcm_payload, gcm_options) + send_android_push_notification( + user_profile_id, android_devices, gcm_payload, gcm_options + ) if apple_devices: send_apple_push_notification(user_profile_id, apple_devices, apns_payload) @@ -989,4 +1018,4 @@ def handle_push_notification(user_profile_id: int, missed_message: Dict[str, Any len(apple_devices), ) send_apple_push_notification(user_profile.id, apple_devices, apns_payload) - send_android_push_notification(android_devices, gcm_payload, gcm_options) + send_android_push_notification(user_profile.id, android_devices, gcm_payload, gcm_options) diff --git a/zerver/tests/test_push_notifications.py b/zerver/tests/test_push_notifications.py index 13a09d485a..b50a69b3a8 100644 --- a/zerver/tests/test_push_notifications.py +++ b/zerver/tests/test_push_notifications.py @@ -1175,7 +1175,9 @@ class HandlePushNotificationTest(PushNotificationTest): handle_push_notification(self.user_profile.id, missed_message) mock_send_apple.assert_called_with(self.user_profile.id, apple_devices, {"apns": True}) - mock_send_android.assert_called_with(android_devices, {"gcm": True}, {}) + mock_send_android.assert_called_with( + self.user_profile.id, android_devices, {"gcm": True}, {} + ) mock_push_notifications.assert_called_once() def test_send_remove_notifications_to_bouncer(self) -> None: @@ -1245,6 +1247,7 @@ class HandlePushNotificationTest(PushNotificationTest): ) as mock_send_apple: handle_remove_push_notification(self.user_profile.id, [message.id]) mock_send_android.assert_called_with( + self.user_profile.id, android_devices, { "server": "testserver", @@ -1347,7 +1350,9 @@ class HandlePushNotificationTest(PushNotificationTest): handle_push_notification(self.user_profile.id, missed_message) mock_logger.assert_not_called() mock_send_apple.assert_called_with(self.user_profile.id, apple_devices, {"apns": True}) - mock_send_android.assert_called_with(android_devices, {"gcm": True}, {}) + mock_send_android.assert_called_with( + self.user_profile.id, android_devices, {"gcm": True}, {} + ) mock_push_notifications.assert_called_once() @mock.patch("zerver.lib.push_notifications.logger.info") @@ -2217,10 +2222,11 @@ class GCMSendTest(PushNotificationTest): data = self.get_gcm_data() with self.assertLogs("zerver.lib.push_notifications", level="INFO") as logger: send_android_push_notification_to_user(self.user_profile, data, {}) - self.assert_length(logger.output, 2) - log_msg1 = f"INFO:zerver.lib.push_notifications:GCM: Sent {1111} as {0}" - log_msg2 = f"INFO:zerver.lib.push_notifications:GCM: Sent {2222} as {1}" - self.assertEqual([log_msg1, log_msg2], logger.output) + self.assert_length(logger.output, 3) + log_msg1 = f"INFO:zerver.lib.push_notifications:GCM: Sending notification for local user {self.user_profile.id} to 2 devices" + log_msg2 = f"INFO:zerver.lib.push_notifications:GCM: Sent {1111} as {0}" + log_msg3 = f"INFO:zerver.lib.push_notifications:GCM: Sent {2222} as {1}" + self.assertEqual([log_msg1, log_msg2, log_msg3], logger.output) mock_warning.assert_not_called() def test_canonical_equal(self, mock_gcm: mock.MagicMock) -> None: @@ -2277,9 +2283,13 @@ class GCMSendTest(PushNotificationTest): with self.assertLogs("zerver.lib.push_notifications", level="INFO") as logger: send_android_push_notification_to_user(self.user_profile, data, {}) self.assertEqual( - f"INFO:zerver.lib.push_notifications:GCM: Got canonical ref {new_token}, dropping {old_token}", + f"INFO:zerver.lib.push_notifications:GCM: Sending notification for local user {self.user_profile.id} to 2 devices", logger.output[0], ) + self.assertEqual( + f"INFO:zerver.lib.push_notifications:GCM: Got canonical ref {new_token}, dropping {old_token}", + logger.output[1], + ) self.assertEqual(get_count("1111"), 0) self.assertEqual(get_count("2222"), 1) @@ -2300,7 +2310,12 @@ class GCMSendTest(PushNotificationTest): with self.assertLogs("zerver.lib.push_notifications", level="INFO") as logger: send_android_push_notification_to_user(self.user_profile, data, {}) self.assertEqual( - f"INFO:zerver.lib.push_notifications:GCM: Removing {token}", logger.output[0] + f"INFO:zerver.lib.push_notifications:GCM: Sending notification for local user {self.user_profile.id} to 2 devices", + logger.output[0], + ) + self.assertEqual( + f"INFO:zerver.lib.push_notifications:GCM: Removing {token}", + logger.output[1], ) self.assertEqual(get_count("1111"), 0) diff --git a/zilencer/views.py b/zilencer/views.py index 465a4cb353..353d311ca5 100644 --- a/zilencer/views.py +++ b/zilencer/views.py @@ -202,9 +202,11 @@ def remote_server_notify_push( len(apple_devices), ) - send_android_push_notification(android_devices, gcm_payload, gcm_options, remote=True) + send_android_push_notification( + user_id, android_devices, gcm_payload, gcm_options, remote=server + ) - send_apple_push_notification(user_id, apple_devices, apns_payload, remote=True) + send_apple_push_notification(user_id, apple_devices, apns_payload, remote=server) return json_success( {"total_android_devices": len(android_devices), "total_apple_devices": len(apple_devices)}