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.
2021-10-19 23:52:23 +00:00 · 2021-10-19 23:52:23 +00:00 · 111ee64e36
parent 5bcd3c01cb
commit 111ee64e36
3 changed files with 62 additions and 16 deletions
--- 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)
--- 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)

--- 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)}