Mirror
/
zulip
mirror of https://github.com/zulip/zulip.git
1
0
Fork 0
Code Issues Projects Releases Wiki Activity

push notifications: Add a logger (default-off in tests). 

This should suppress some spammy logging output about push
notifications that we were seeing in a large number of unit tests.
This commit is contained in:
Tim Abbott 2018-11-27 09:45:45 -08:00
parent 38a6003472
commit 7b930124d9
3 changed files with 51 additions and 48 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

62
zerver/lib/push_notifications.py
View File

@ -33,6 +33,8 @@ from zerver.models import PushDeviceToken, Message, Recipient, UserProfile, \
receives_online_notifications, receives_stream_notifications, get_user_profile_by_id
from version import ZULIP_VERSION
logger = logging.getLogger(__name__)
if settings.ZILENCER_ENABLED:
from zilencer.models import RemotePushDeviceToken
else: # nocoverage -- Not convenient to add test for this.
@ -114,8 +116,8 @@ def send_apple_push_notification(user_id: int, devices: List[DeviceToken],
client = get_apns_client() # type: APNsClient
if client is None:
logging.debug("APNs: Dropping a notification because nothing configured. "
"Set PUSH_NOTIFICATION_BOUNCER_URL (or APNS_CERT_FILE).")
logger.debug("APNs: Dropping a notification because nothing configured. "
"Set PUSH_NOTIFICATION_BOUNCER_URL (or APNS_CERT_FILE).")
return
if remote:
@ -123,8 +125,8 @@ def send_apple_push_notification(user_id: int, devices: List[DeviceToken],
else:
DeviceTokenClass = PushDeviceToken
logging.info("APNs: Sending notification for user %d to %d devices",
user_id, len(devices))
logger.info("APNs: Sending notification for user %d to %d devices",
user_id, len(devices))
payload = APNsPayload(**modernize_apns_payload(payload_data))
expiration = int(time.time() + 24 * 3600)
retries_left = APNS_MAX_RETRIES
@ -138,8 +140,8 @@ def send_apple_push_notification(user_id: int, devices: List[DeviceToken],
try:
return client.get_notification_result(stream_id)
except HTTP20Error as e:
logging.warning("APNs: HTTP error sending for user %d to device %s: %s",
user_id, device.token, e.__class__.__name__)
logger.warning("APNs: HTTP error sending for user %d to device %s: %s",
user_id, device.token, e.__class__.__name__)
return None
result = attempt_send()
@ -154,16 +156,16 @@ def send_apple_push_notification(user_id: int, devices: List[DeviceToken],
# different format, as a tuple of the pair ("Unregistered", 12345132131).
result = result[0] # type: ignore # APNS API is inconsistent
if result == 'Success':
logging.info("APNs: Success sending for user %d to device %s",
user_id, device.token)
logger.info("APNs: Success sending for user %d to device %s",
user_id, device.token)
elif result in ["Unregistered", "BadDeviceToken", "DeviceTokenNotForTopic"]:
logging.info("APNs: Removing invalid/expired token %s (%s)" % (device.token, result))
logger.info("APNs: Removing invalid/expired token %s (%s)" % (device.token, result))
# We remove all entries for this token (There
# could be multiple for different Zulip servers).
DeviceTokenClass.objects.filter(token=device.token, kind=DeviceTokenClass.APNS).delete()
else:
logging.warning("APNs: Failed to send for user %d to device %s: %s",
user_id, device.token, result)
logger.warning("APNs: Failed to send for user %d to device %s: %s",
user_id, device.token, result)
#
# Sending to GCM, for Android
@ -186,8 +188,8 @@ def send_android_push_notification_to_user(user_profile: UserProfile, data: Dict
def send_android_push_notification(devices: List[DeviceToken], data: Dict[str, Any],
remote: bool=False) -> None:
if not gcm:
logging.debug("Skipping sending a GCM push notification since "
"PUSH_NOTIFICATION_BOUNCER_URL and ANDROID_GCM_API_KEY are both unset")
logger.debug("Skipping sending a GCM push notification since "
"PUSH_NOTIFICATION_BOUNCER_URL and ANDROID_GCM_API_KEY are both unset")
return
reg_ids = [device.token for device in devices]
@ -199,12 +201,12 @@ def send_android_push_notification(devices: List[DeviceToken], data: Dict[str, A
try:
res = gcm.json_request(registration_ids=reg_ids, data=data, retries=10)
except IOError as e:
logging.warning(str(e))
logger.warning(str(e))
return
if res and 'success' in res:
for reg_id, msg_id in res['success'].items():
logging.info("GCM: Sent %s as %s" % (reg_id, msg_id))
logger.info("GCM: Sent %s as %s" % (reg_id, msg_id))
# res.canonical will contain results when there are duplicate registrations for the same
# device. The "canonical" registration is the latest registration made by the device.
@ -213,21 +215,21 @@ def send_android_push_notification(devices: List[DeviceToken], data: Dict[str, A
for reg_id, new_reg_id in res['canonical'].items():
if reg_id == new_reg_id:
# I'm not sure if this should happen. In any case, not really actionable.
logging.warning("GCM: Got canonical ref but it already matches our ID %s!" % (reg_id,))
logger.warning("GCM: Got canonical ref but it already matches our ID %s!" % (reg_id,))
elif not DeviceTokenClass.objects.filter(token=new_reg_id,
kind=DeviceTokenClass.GCM).count():
# This case shouldn't happen; any time we get a canonical ref it should have been
# previously registered in our system.
#
# That said, recovery is easy: just update the current PDT object to use the new ID.
logging.warning(
logger.warning(
"GCM: Got canonical ref %s replacing %s but new ID not registered! Updating." %
(new_reg_id, reg_id))
DeviceTokenClass.objects.filter(
token=reg_id, kind=DeviceTokenClass.GCM).update(token=new_reg_id)
else:
# Since we know the new ID is registered in our system we can just drop the old one.
logging.info("GCM: Got canonical ref %s, dropping %s" % (new_reg_id, reg_id))
logger.info("GCM: Got canonical ref %s, dropping %s" % (new_reg_id, reg_id))
DeviceTokenClass.objects.filter(token=reg_id, kind=DeviceTokenClass.GCM).delete()
@ -235,13 +237,13 @@ def send_android_push_notification(devices: List[DeviceToken], data: Dict[str, A
for error, reg_ids in res['errors'].items():
if error in ['NotRegistered', 'InvalidRegistration']:
for reg_id in reg_ids:
logging.info("GCM: Removing %s" % (reg_id,))
logger.info("GCM: Removing %s" % (reg_id,))
# We remove all entries for this token (There
# could be multiple for different Zulip servers).
DeviceTokenClass.objects.filter(token=reg_id, kind=DeviceTokenClass.GCM).delete()
else:
for reg_id in reg_ids:
logging.warning("GCM: Delivery to %s failed: %s" % (reg_id, error))
logger.warning("GCM: Delivery to %s failed: %s" % (reg_id, error))
# python-gcm handles retrying of the unsent messages.
# Ref: https://github.com/geeknam/python-gcm/blob/master/gcm/gcm.py#L497
@ -354,8 +356,8 @@ def add_push_device_token(user_profile: UserProfile,
token_str: bytes,
kind: int,
ios_app_id: Optional[str]=None) -> None:
logging.info("Registering push device: %d %r %d %r",
user_profile.id, token_str, kind, ios_app_id)
logger.info("Registering push device: %d %r %d %r",
user_profile.id, token_str, kind, ios_app_id)
# If we're sending things to the push notification bouncer
# register this user with them here
@ -370,7 +372,7 @@ def add_push_device_token(user_profile: UserProfile,
if kind == PushDeviceToken.APNS:
post_data['ios_app_id'] = ios_app_id
logging.info("Sending new push device to bouncer: %r", post_data)
logger.info("Sending new push device to bouncer: %r", post_data)
# Calls zilencer.views.register_remote_push_device
send_to_push_bouncer('POST', 'register', post_data)
return
@ -431,9 +433,9 @@ def push_notifications_enabled() -> bool:
def initialize_push_notifications() -> None:
if not push_notifications_enabled():
logging.warning("Mobile push notifications are not configured.\n "
"See https://zulip.readthedocs.io/en/latest/"
"production/mobile-push-notifications.html")
logger.warning("Mobile push notifications are not configured.\n "
"See https://zulip.readthedocs.io/en/latest/"
"production/mobile-push-notifications.html")
def get_gcm_alert(message: Message) -> str:
"""
@ -615,7 +617,7 @@ def handle_remove_push_notification(user_profile_id: int, message_id: int) -> No
gcm_payload)
except requests.ConnectionError: # nocoverage
def failure_processor(event: Dict[str, Any]) -> None:
logging.warning(
logger.warning(
"Maximum retries exceeded for trigger:%s event:push_notification" % (
event['user_profile_id']))
return
@ -661,7 +663,7 @@ def handle_push_notification(user_profile_id: int, missed_message: Dict[str, Any
# queue for messages they haven't received if they're
# long-term idle; anything else is likely a bug.
if not user_profile.long_term_idle:
logging.error("Could not find UserMessage with message_id %s and user_id %s" % (
logger.error("Could not find UserMessage with message_id %s and user_id %s" % (
missed_message['message_id'], user_profile_id))
return
@ -669,7 +671,7 @@ def handle_push_notification(user_profile_id: int, missed_message: Dict[str, Any
apns_payload = get_apns_payload(user_profile, message)
gcm_payload = get_gcm_payload(user_profile, message)
logging.info("Sending push notification to user %s" % (user_profile_id,))
logger.info("Sending push notification to user %s" % (user_profile_id,))
if uses_notification_bouncer():
try:
@ -678,7 +680,7 @@ def handle_push_notification(user_profile_id: int, missed_message: Dict[str, Any
gcm_payload)
except requests.ConnectionError:
def failure_processor(event: Dict[str, Any]) -> None:
logging.warning(
logger.warning(
"Maximum retries exceeded for trigger:%s event:push_notification" % (
event['user_profile_id']))
retry_event('missedmessage_mobile_notifications', missed_message,

36
zerver/tests/test_push_notifications.py
View File

@ -370,8 +370,8 @@ class HandlePushNotificationTest(PushNotificationTest):
side_effect=self.bounce_request), \
mock.patch('zerver.lib.push_notifications.gcm') as mock_gcm, \
self.mock_apns() as mock_apns, \
mock.patch('logging.info') as mock_info, \
mock.patch('logging.warning'):
mock.patch('zerver.lib.push_notifications.logger.info') as mock_info, \
mock.patch('zerver.lib.push_notifications.logger.warning'):
apns_devices = [
(apn.b64_to_hex(device.token), device.ios_app_id, device.token)
for device in RemotePushDeviceToken.objects.filter(
@ -435,7 +435,7 @@ class HandlePushNotificationTest(PushNotificationTest):
side_effect=requests.ConnectionError), \
mock.patch('zerver.lib.queue.queue_json_publish',
side_effect=retry) as mock_retry, \
mock.patch('logging.warning') as mock_warn:
mock.patch('zerver.lib.push_notifications.logger.warning') as mock_warn:
gcm_devices = [
(apn.b64_to_hex(device.token), device.ios_app_id, device.token)
for device in RemotePushDeviceToken.objects.filter(
@ -595,7 +595,7 @@ class HandlePushNotificationTest(PushNotificationTest):
self.make_stream('public_stream')
message_id = self.send_stream_message("iago@zulip.com", "public_stream", "test")
missed_message = {'message_id': message_id}
with mock.patch('logging.error') as mock_logger:
with mock.patch('zerver.lib.push_notifications.logger.error') as mock_logger:
apn.handle_push_notification(self.user_profile.id, missed_message)
mock_logger.assert_called_with("Could not find UserMessage with "
"message_id %s and user_id %s" %
@ -637,7 +637,7 @@ class HandlePushNotificationTest(PushNotificationTest):
'.send_apple_push_notification') as mock_send_apple, \
mock.patch('zerver.lib.push_notifications'
'.send_android_push_notification') as mock_send_android, \
mock.patch('logging.error') as mock_logger:
mock.patch('zerver.lib.push_notifications.logger.error') as mock_logger:
apn.handle_push_notification(self.user_profile.id, missed_message)
mock_logger.assert_not_called()
mock_send_apple.assert_called_with(self.user_profile.id,
@ -668,7 +668,7 @@ class TestAPNs(PushNotificationTest):
def test_not_configured(self) -> None:
with mock.patch('zerver.lib.push_notifications.get_apns_client') as mock_get, \
mock.patch('zerver.lib.push_notifications.logging') as mock_logging:
mock.patch('zerver.lib.push_notifications.logger') as mock_logging:
mock_get.return_value = None
self.send()
mock_logging.debug.assert_called_once_with(
@ -683,7 +683,7 @@ class TestAPNs(PushNotificationTest):
def test_success(self) -> None:
with self.mock_apns() as mock_apns, \
mock.patch('zerver.lib.push_notifications.logging') as mock_logging:
mock.patch('zerver.lib.push_notifications.logger') as mock_logging:
mock_apns.get_notification_result.return_value = 'Success'
self.send()
mock_logging.warning.assert_not_called()
@ -695,7 +695,7 @@ class TestAPNs(PushNotificationTest):
def test_http_retry(self) -> None:
import hyper
with self.mock_apns() as mock_apns, \
mock.patch('zerver.lib.push_notifications.logging') as mock_logging:
mock.patch('zerver.lib.push_notifications.logger') as mock_logging:
mock_apns.get_notification_result.side_effect = itertools.chain(
[hyper.http20.exceptions.StreamResetError()],
itertools.repeat('Success'))
@ -711,7 +711,7 @@ class TestAPNs(PushNotificationTest):
def test_http_retry_eventually_fails(self) -> None:
import hyper
with self.mock_apns() as mock_apns, \
mock.patch('zerver.lib.push_notifications.logging') as mock_logging:
mock.patch('zerver.lib.push_notifications.logger') as mock_logging:
mock_apns.get_notification_result.side_effect = itertools.chain(
[hyper.http20.exceptions.StreamResetError()],
[hyper.http20.exceptions.StreamResetError()],
@ -1162,7 +1162,7 @@ class GCMTest(PushNotificationTest):
return data
class GCMNotSetTest(GCMTest):
@mock.patch('logging.debug')
@mock.patch('zerver.lib.push_notifications.logger.debug')
def test_gcm_is_none(self, mock_debug: mock.MagicMock) -> None:
apn.gcm = None
apn.send_android_push_notification_to_user(self.user_profile, {})
@ -1172,7 +1172,7 @@ class GCMNotSetTest(GCMTest):
class GCMIOErrorTest(GCMTest):
@mock.patch('zerver.lib.push_notifications.gcm.json_request')
@mock.patch('logging.warning')
@mock.patch('zerver.lib.push_notifications.logger.warning')
def test_json_request_raises_ioerror(self, mock_warn: mock.MagicMock,
mock_json_request: mock.MagicMock) -> None:
mock_json_request.side_effect = IOError('error')
@ -1180,8 +1180,8 @@ class GCMIOErrorTest(GCMTest):
mock_warn.assert_called_with('error')
class GCMSuccessTest(GCMTest):
@mock.patch('logging.warning')
@mock.patch('logging.info')
@mock.patch('zerver.lib.push_notifications.logger.warning')
@mock.patch('zerver.lib.push_notifications.logger.info')
@mock.patch('gcm.GCM.json_request')
def test_success(self, mock_send: mock.MagicMock, mock_info: mock.MagicMock,
mock_warning: mock.MagicMock) -> None:
@ -1198,7 +1198,7 @@ class GCMSuccessTest(GCMTest):
mock_warning.assert_not_called()
class GCMCanonicalTest(GCMTest):
@mock.patch('logging.warning')
@mock.patch('zerver.lib.push_notifications.logger.warning')
@mock.patch('gcm.GCM.json_request')
def test_equal(self, mock_send: mock.MagicMock, mock_warning: mock.MagicMock) -> None:
res = {}
@ -1210,7 +1210,7 @@ class GCMCanonicalTest(GCMTest):
mock_warning.assert_called_once_with("GCM: Got canonical ref but it "
"already matches our ID 1!")
@mock.patch('logging.warning')
@mock.patch('zerver.lib.push_notifications.logger.warning')
@mock.patch('gcm.GCM.json_request')
def test_pushdevice_not_present(self, mock_send: mock.MagicMock,
mock_warning: mock.MagicMock) -> None:
@ -1238,7 +1238,7 @@ class GCMCanonicalTest(GCMTest):
self.assertEqual(get_count(u'1111'), 0)
self.assertEqual(get_count(u'3333'), 1)
@mock.patch('logging.info')
@mock.patch('zerver.lib.push_notifications.logger.info')
@mock.patch('gcm.GCM.json_request')
def test_pushdevice_different(self, mock_send: mock.MagicMock,
mock_info: mock.MagicMock) -> None:
@ -1265,7 +1265,7 @@ class GCMCanonicalTest(GCMTest):
self.assertEqual(get_count(u'2222'), 1)
class GCMNotRegisteredTest(GCMTest):
@mock.patch('logging.info')
@mock.patch('zerver.lib.push_notifications.logger.info')
@mock.patch('gcm.GCM.json_request')
def test_not_registered(self, mock_send: mock.MagicMock, mock_info: mock.MagicMock) -> None:
res = {}
@ -1286,7 +1286,7 @@ class GCMNotRegisteredTest(GCMTest):
self.assertEqual(get_count(u'1111'), 0)
class GCMFailureTest(GCMTest):
@mock.patch('logging.warning')
@mock.patch('zerver.lib.push_notifications.logger.warning')
@mock.patch('gcm.GCM.json_request')
def test_failure(self, mock_send: mock.MagicMock, mock_warn: mock.MagicMock) -> None:
res = {}

1
zproject/test_settings.py
View File

@ -115,6 +115,7 @@ if not CASPER_TESTS:
set_loglevel('django.request', 'ERROR')
set_loglevel('fakeldap', 'ERROR')
set_loglevel('zulip.send_email', 'ERROR')
set_loglevel('zerver.lib.push_notifications', 'WARNING')
set_loglevel('zerver.lib.digest', 'ERROR')
set_loglevel('zerver.lib.email_mirror', 'ERROR')
set_loglevel('zerver.worker.queue_processors', 'WARNING')