mirror of https://github.com/zulip/zulip.git
zilencer: Log how long the remote server delayed the push notification.
This commit is contained in:
Alex Vandiver
Tim Abbott
parent
fd6091ad17
commit
4cef665e98
|
|
@ -11,6 +11,7 @@ from urllib import parse
|
|||
import aioapns
|
||||
import orjson
|
||||
import responses
|
||||
import time_machine
|
||||
from django.conf import settings
|
||||
from django.db import transaction
|
||||
from django.db.models import F, Q
|
||||
|
|
@ -428,6 +429,68 @@ class PushBouncerNotificationTest(BouncerTestCase):
|
|||
remote=server,
|
||||
)
|
||||
|
||||
def test_old_timestamp_format(self) -> None:
|
||||
hamlet = self.example_user("hamlet")
|
||||
RemotePushDeviceToken.objects.create(
|
||||
kind=RemotePushDeviceToken.GCM,
|
||||
token=hex_to_b64("aaaaaa"),
|
||||
user_id=hamlet.id,
|
||||
server=RemoteZulipServer.objects.get(uuid=self.server_uuid),
|
||||
)
|
||||
|
||||
time_sent = now().replace(microsecond=0)
|
||||
with time_machine.travel(time_sent):
|
||||
message = Message(
|
||||
sender=hamlet,
|
||||
recipient=self.example_user("othello").recipient,
|
||||
realm_id=hamlet.realm_id,
|
||||
content="This is test content",
|
||||
rendered_content="This is test content",
|
||||
date_sent=now(),
|
||||
sending_client=get_client("test"),
|
||||
)
|
||||
message.set_topic_name("Test topic")
|
||||
message.save()
|
||||
gcm_payload, gcm_options = get_message_payload_gcm(hamlet, message)
|
||||
apns_payload = get_message_payload_apns(
|
||||
hamlet, message, NotificationTriggers.DIRECT_MESSAGE
|
||||
)
|
||||
|
||||
# Reconfigure like old versions, which had integer-granularity
|
||||
# timestamps, and only in the GCM payload.
|
||||
self.assertIsNotNone(gcm_payload.get("time"))
|
||||
gcm_payload["time"] = int(gcm_payload["time"])
|
||||
self.assertEqual(gcm_payload["time"], int(time_sent.timestamp()))
|
||||
self.assertIsNotNone(apns_payload["custom"]["zulip"].get("time"))
|
||||
del apns_payload["custom"]["zulip"]["time"]
|
||||
|
||||
payload = {
|
||||
"user_id": hamlet.id,
|
||||
"user_uuid": str(hamlet.uuid),
|
||||
"gcm_payload": gcm_payload,
|
||||
"apns_payload": apns_payload,
|
||||
"gcm_options": gcm_options,
|
||||
}
|
||||
time_recieved = time_sent + datetime.timedelta(seconds=1, milliseconds=234)
|
||||
with time_machine.travel(time_recieved, tick=False), 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",
|
||||
payload,
|
||||
content_type="application/json",
|
||||
)
|
||||
self.assert_json_success(result)
|
||||
self.assertEqual(
|
||||
logger.output[0],
|
||||
"INFO:zilencer.views:"
|
||||
f"Remote queuing latency for 6cde5f7a-1f7e-4978-9716-49f69ebfc9fe:<id:{hamlet.id}><uuid:{hamlet.uuid}> "
|
||||
"is 1 seconds",
|
||||
)
|
||||
|
||||
def test_remote_push_unregister_all(self) -> None:
|
||||
payload = self.get_generic_payload("register")
|
||||
|
||||
|
|
@ -1087,6 +1150,8 @@ class HandlePushNotificationTest(PushNotificationTest):
|
|||
self.setup_apns_tokens()
|
||||
self.setup_gcm_tokens()
|
||||
|
||||
time_sent = now()
|
||||
with time_machine.travel(time_sent, tick=False):
|
||||
message = self.get_message(
|
||||
Recipient.PERSONAL,
|
||||
type_id=self.personal_recipient_user.id,
|
||||
|
|
@ -1097,11 +1162,12 @@ class HandlePushNotificationTest(PushNotificationTest):
|
|||
message=message,
|
||||
)
|
||||
|
||||
time_recieved = time_sent + datetime.timedelta(seconds=1, milliseconds=234)
|
||||
missed_message = {
|
||||
"message_id": message.id,
|
||||
"trigger": NotificationTriggers.DIRECT_MESSAGE,
|
||||
}
|
||||
with mock.patch(
|
||||
with time_machine.travel(time_recieved, tick=False), mock.patch(
|
||||
"zerver.lib.push_notifications.gcm_client"
|
||||
) as mock_gcm, self.mock_apns() as (apns_context, send_notification), self.assertLogs(
|
||||
"zerver.lib.push_notifications", level="INFO"
|
||||
|
|
@ -1124,9 +1190,12 @@ class HandlePushNotificationTest(PushNotificationTest):
|
|||
self.assertEqual(
|
||||
views_logger.output,
|
||||
[
|
||||
"INFO:zilencer.views:"
|
||||
f"Remote queuing latency for 6cde5f7a-1f7e-4978-9716-49f69ebfc9fe:<id:{self.user_profile.id}><uuid:{self.user_profile.uuid}> "
|
||||
"is 1.234 seconds",
|
||||
"INFO:zilencer.views:"
|
||||
f"Sending mobile push notifications for remote user 6cde5f7a-1f7e-4978-9716-49f69ebfc9fe:<id:{self.user_profile.id}><uuid:{self.user_profile.uuid}>: "
|
||||
f"{len(gcm_devices)} via FCM devices, {len(apns_devices)} via APNs devices"
|
||||
f"{len(gcm_devices)} via FCM devices, {len(apns_devices)} via APNs devices",
|
||||
],
|
||||
)
|
||||
for _, _, token in apns_devices:
|
||||
|
|
@ -1148,6 +1217,8 @@ class HandlePushNotificationTest(PushNotificationTest):
|
|||
self.setup_apns_tokens()
|
||||
self.setup_gcm_tokens()
|
||||
|
||||
time_sent = now()
|
||||
with time_machine.travel(time_sent, tick=False):
|
||||
message = self.get_message(
|
||||
Recipient.PERSONAL,
|
||||
type_id=self.personal_recipient_user.id,
|
||||
|
|
@ -1158,11 +1229,12 @@ class HandlePushNotificationTest(PushNotificationTest):
|
|||
message=message,
|
||||
)
|
||||
|
||||
time_recieved = time_sent + datetime.timedelta(seconds=1, milliseconds=234)
|
||||
missed_message = {
|
||||
"message_id": message.id,
|
||||
"trigger": NotificationTriggers.DIRECT_MESSAGE,
|
||||
}
|
||||
with mock.patch(
|
||||
with time_machine.travel(time_recieved, tick=False), mock.patch(
|
||||
"zerver.lib.push_notifications.gcm_client"
|
||||
) as mock_gcm, self.mock_apns() as (apns_context, send_notification), self.assertLogs(
|
||||
"zerver.lib.push_notifications", level="INFO"
|
||||
|
|
@ -1184,9 +1256,12 @@ class HandlePushNotificationTest(PushNotificationTest):
|
|||
self.assertEqual(
|
||||
views_logger.output,
|
||||
[
|
||||
"INFO:zilencer.views:"
|
||||
f"Remote queuing latency for 6cde5f7a-1f7e-4978-9716-49f69ebfc9fe:<id:{self.user_profile.id}><uuid:{self.user_profile.uuid}> "
|
||||
"is 1.234 seconds",
|
||||
"INFO:zilencer.views:"
|
||||
f"Sending mobile push notifications for remote user 6cde5f7a-1f7e-4978-9716-49f69ebfc9fe:<id:{self.user_profile.id}><uuid:{self.user_profile.uuid}>: "
|
||||
f"{len(gcm_devices)} via FCM devices, {len(apns_devices)} via APNs devices"
|
||||
f"{len(gcm_devices)} via FCM devices, {len(apns_devices)} via APNs devices",
|
||||
],
|
||||
)
|
||||
for _, _, token in apns_devices:
|
||||
|
|
|
|||
|
|
@ -1,7 +1,7 @@
|
|||
import datetime
|
||||
import logging
|
||||
from collections import Counter
|
||||
from typing import Any, Dict, List, Optional, Type, TypeVar
|
||||
from typing import Any, Dict, List, Optional, Type, TypeVar, Union
|
||||
from uuid import UUID
|
||||
|
||||
import orjson
|
||||
|
|
@ -317,6 +317,25 @@ def remote_server_notify_push(
|
|||
if apple_devices and user_id is not None and user_uuid is not None:
|
||||
apple_devices = delete_duplicate_registrations(apple_devices, server.id, user_id, user_uuid)
|
||||
|
||||
remote_queue_latency: Optional[str] = None
|
||||
sent_time: Optional[Union[float, int]] = gcm_payload.get(
|
||||
"time", apns_payload["custom"]["zulip"].get("time")
|
||||
)
|
||||
if sent_time is not None:
|
||||
if isinstance(sent_time, int):
|
||||
# The 'time' field only used to have whole-integer
|
||||
# granularity, so if so we only report with
|
||||
# whole-second granularity
|
||||
remote_queue_latency = str(int(timezone_now().timestamp()) - sent_time)
|
||||
else:
|
||||
remote_queue_latency = f"{timezone_now().timestamp() - sent_time:.3f}"
|
||||
logger.info(
|
||||
"Remote queuing latency for %s:%s is %s seconds",
|
||||
server.uuid,
|
||||
user_identity,
|
||||
remote_queue_latency,
|
||||
)
|
||||
|
||||
logger.info(
|
||||
"Sending mobile push notifications for remote user %s:%s: %s via FCM devices, %s via APNs devices",
|
||||
server.uuid,
|
||||
|
|
|
|||
Loading…
Reference in New Issue