zilencer: Add new LoggingCountStat mobile_pushes_forwarded.

This one counts actual successful deliveries.
This commit is contained in:
Mateusz Mandera 2023-10-28 02:01:22 +02:00 committed by Tim Abbott
parent b7117d51b2
commit 6819ecee92
5 changed files with 58 additions and 17 deletions

View File

@ -845,12 +845,27 @@ def get_count_stats(realm: Optional[Realm] = None) -> Dict[str, CountStat]:
if settings.ZILENCER_ENABLED: if settings.ZILENCER_ENABLED:
count_stats_.append( count_stats_.append(
# Tracks the number of push notifications requested to be sent
# by a remote server.
LoggingCountStat( LoggingCountStat(
"mobile_pushes_received::day", "mobile_pushes_received::day",
RemoteInstallationCount, RemoteInstallationCount,
CountStat.DAY, CountStat.DAY,
) )
) )
count_stats_.append(
# Tracks the number of push notifications successfully sent to mobile
# devices, as requested by the remote server. Therefore this should be
# less than or equal to mobile_pushes_received - with potential tiny offsets
# resulting from a request being *received* by the bouncer right before midnight,
# but *sent* to the mobile device right after midnight. This would cause the increments
# to happen to CountStat records for different days.
LoggingCountStat(
"mobile_pushes_forwarded::day",
RemoteInstallationCount,
CountStat.DAY,
)
)
return OrderedDict((stat.property, stat) for stat in count_stats_) return OrderedDict((stat.property, stat) for stat in count_stats_)

View File

@ -1442,8 +1442,10 @@ class TestLoggingCountStats(AnalyticsTestCase):
} }
now = timezone_now() now = timezone_now()
with time_machine.travel(now, tick=False), mock.patch( with time_machine.travel(now, tick=False), mock.patch(
"zilencer.views.send_android_push_notification" "zilencer.views.send_android_push_notification", return_value=1
), mock.patch("zilencer.views.send_apple_push_notification"), self.assertLogs( ), mock.patch(
"zilencer.views.send_apple_push_notification", return_value=1
), self.assertLogs(
"zilencer.views", level="INFO" "zilencer.views", level="INFO"
): ):
result = self.uuid_post( result = self.uuid_post(
@ -1455,13 +1457,17 @@ class TestLoggingCountStats(AnalyticsTestCase):
) )
self.assert_json_success(result) self.assert_json_success(result)
# There are 3 devices we created for the user, and the Count increment should # There are 3 devices we created for the user:
# match that number. # 1. The mobile_pushes_received increment should match that number.
# 2. mobile_pushes_forwarded only counts successful deliveries, and we've set up
# the mocks above to simulate 1 successful android and 1 successful apple delivery.
# Thus the increment should be just 2.
self.assertTableState( self.assertTableState(
RemoteInstallationCount, RemoteInstallationCount,
["property", "value", "subgroup", "server", "remote_id", "end_time"], ["property", "value", "subgroup", "server", "remote_id", "end_time"],
[ [
["mobile_pushes_received::day", 3, None, self.server, None, ceiling_to_day(now)], ["mobile_pushes_received::day", 3, None, self.server, None, ceiling_to_day(now)],
["mobile_pushes_forwarded::day", 2, None, self.server, None, ceiling_to_day(now)],
], ],
) )

View File

@ -218,9 +218,9 @@ def send_apple_push_notification(
devices: Sequence[DeviceToken], devices: Sequence[DeviceToken],
payload_data: Mapping[str, Any], payload_data: Mapping[str, Any],
remote: Optional["RemoteZulipServer"] = None, remote: Optional["RemoteZulipServer"] = None,
) -> None: ) -> int:
if not devices: if not devices:
return return 0
# We lazily do the APNS imports as part of optimizing Zulip's base # We lazily do the APNS imports as part of optimizing Zulip's base
# import time; since these are only needed in the push # import time; since these are only needed in the push
# notification queue worker, it's best to only import them in the # notification queue worker, it's best to only import them in the
@ -234,7 +234,7 @@ def send_apple_push_notification(
"APNs: Dropping a notification because nothing configured. " "APNs: Dropping a notification because nothing configured. "
"Set PUSH_NOTIFICATION_BOUNCER_URL (or APNS_CERT_FILE)." "Set PUSH_NOTIFICATION_BOUNCER_URL (or APNS_CERT_FILE)."
) )
return return 0
if remote: if remote:
assert settings.ZILENCER_ENABLED assert settings.ZILENCER_ENABLED
@ -275,6 +275,7 @@ def send_apple_push_notification(
results = apns_context.loop.run_until_complete(send_all_notifications()) results = apns_context.loop.run_until_complete(send_all_notifications())
successfully_sent_count = 0
for device, result in results: for device, result in results:
if isinstance(result, aioapns.exceptions.ConnectionError): if isinstance(result, aioapns.exceptions.ConnectionError):
logger.error( logger.error(
@ -290,6 +291,7 @@ def send_apple_push_notification(
exc_info=result, exc_info=result,
) )
elif result.is_successful: elif result.is_successful:
successfully_sent_count += 1
logger.info( logger.info(
"APNs: Success sending for user %s to device %s", user_identity, device.token "APNs: Success sending for user %s to device %s", user_identity, device.token
) )
@ -310,6 +312,8 @@ def send_apple_push_notification(
result.description, result.description,
) )
return successfully_sent_count
# #
# Sending to GCM, for Android # Sending to GCM, for Android
@ -411,7 +415,7 @@ def send_android_push_notification(
data: Dict[str, Any], data: Dict[str, Any],
options: Dict[str, Any], options: Dict[str, Any],
remote: Optional["RemoteZulipServer"] = None, remote: Optional["RemoteZulipServer"] = None,
) -> None: ) -> int:
""" """
Send a GCM message to the given devices. Send a GCM message to the given devices.
@ -424,13 +428,13 @@ def send_android_push_notification(
For details, see `parse_gcm_options`. For details, see `parse_gcm_options`.
""" """
if not devices: if not devices:
return return 0
if not gcm_client: if not gcm_client:
logger.debug( logger.debug(
"Skipping sending a GCM push notification since " "Skipping sending a GCM push notification since "
"PUSH_NOTIFICATION_BOUNCER_URL and ANDROID_GCM_API_KEY are both unset" "PUSH_NOTIFICATION_BOUNCER_URL and ANDROID_GCM_API_KEY are both unset"
) )
return return 0
if remote: if remote:
logger.info( logger.info(
@ -463,11 +467,13 @@ def send_android_push_notification(
) )
except OSError: except OSError:
logger.warning("Error while pushing to GCM", exc_info=True) logger.warning("Error while pushing to GCM", exc_info=True)
return return 0
successfully_sent_count = 0
if res and "success" in res: if res and "success" in res:
for reg_id, msg_id in res["success"].items(): for reg_id, msg_id in res["success"].items():
logger.info("GCM: Sent %s as %s", reg_id, msg_id) logger.info("GCM: Sent %s as %s", reg_id, msg_id)
successfully_sent_count = len(res["success"].keys())
if remote: if remote:
assert settings.ZILENCER_ENABLED assert settings.ZILENCER_ENABLED
@ -520,6 +526,8 @@ def send_android_push_notification(
for reg_id in reg_ids: for reg_id in reg_ids:
logger.warning("GCM: Delivery to %s failed: %s", reg_id, error) logger.warning("GCM: Delivery to %s failed: %s", reg_id, error)
return successfully_sent_count
# python-gcm handles retrying of the unsent messages. # python-gcm handles retrying of the unsent messages.
# Ref: https://github.com/geeknam/python-gcm/blob/master/gcm/gcm.py#L497 # Ref: https://github.com/geeknam/python-gcm/blob/master/gcm/gcm.py#L497

View File

@ -603,9 +603,9 @@ class PushBouncerNotificationTest(BouncerTestCase):
"gcm_options": {}, "gcm_options": {},
} }
with mock.patch( with mock.patch(
"zilencer.views.send_android_push_notification" "zilencer.views.send_android_push_notification", return_value=2
) as android_push, mock.patch( ) as android_push, mock.patch(
"zilencer.views.send_apple_push_notification" "zilencer.views.send_apple_push_notification", return_value=1
) as apple_push, self.assertLogs( ) as apple_push, self.assertLogs(
"zilencer.views", level="INFO" "zilencer.views", level="INFO"
) as logger: ) as logger:
@ -698,8 +698,10 @@ class PushBouncerNotificationTest(BouncerTestCase):
} }
time_received = time_sent + datetime.timedelta(seconds=1, milliseconds=234) time_received = time_sent + datetime.timedelta(seconds=1, milliseconds=234)
with time_machine.travel(time_received, tick=False), mock.patch( with time_machine.travel(time_received, tick=False), mock.patch(
"zilencer.views.send_android_push_notification" "zilencer.views.send_android_push_notification", return_value=1
), mock.patch("zilencer.views.send_apple_push_notification"), self.assertLogs( ), mock.patch(
"zilencer.views.send_apple_push_notification", return_value=1
), self.assertLogs(
"zilencer.views", level="INFO" "zilencer.views", level="INFO"
) as logger: ) as logger:
result = self.uuid_post( result = self.uuid_post(

View File

@ -429,7 +429,7 @@ def remote_server_notify_push(
# send_apple_push_notification. # send_apple_push_notification.
gcm_payload = truncate_payload(gcm_payload) gcm_payload = truncate_payload(gcm_payload)
send_android_push_notification( android_successfully_delivered = send_android_push_notification(
user_identity, android_devices, gcm_payload, gcm_options, remote=server user_identity, android_devices, gcm_payload, gcm_options, remote=server
) )
@ -437,7 +437,17 @@ def remote_server_notify_push(
apns_payload["custom"].get("zulip"), dict apns_payload["custom"].get("zulip"), dict
): ):
apns_payload["custom"]["zulip"] = truncate_payload(apns_payload["custom"]["zulip"]) apns_payload["custom"]["zulip"] = truncate_payload(apns_payload["custom"]["zulip"])
send_apple_push_notification(user_identity, apple_devices, apns_payload, remote=server) apple_successfully_delivered = send_apple_push_notification(
user_identity, apple_devices, apns_payload, remote=server
)
do_increment_logging_stat(
server,
COUNT_STATS["mobile_pushes_forwarded::day"],
None,
timezone_now(),
increment=android_successfully_delivered + apple_successfully_delivered,
)
return json_success( return json_success(
request, request,