async def _dispatch_notification_unlimited(self, n, device, context):
log = NotificationLoggerAdapter(logger,
{"request_id": context.request_id})
# The pushkey is kind of secret because you can use it to send push
# to someone.
# span_tags = {"pushkey": device.pushkey}
span_tags: Dict[str, int] = {}
with self.sygnal.tracer.start_span(
"apns_dispatch", tags=span_tags,
child_of=context.opentracing_span) as span_parent:
if n.event_id and not n.type:
payload = self._get_payload_event_id_only(n, device)
else:
payload = self._get_payload_full(n, device, log)
if payload is None:
# Nothing to do
span_parent.log_kv({logs.EVENT: "apns_no_payload"})
return
prio = 10
if n.prio == "low":
prio = 5
shaved_payload = apnstruncate.truncate(
payload, max_length=self.MAX_JSON_BODY_SIZE)
for retry_number in range(self.MAX_TRIES):
try:
log.debug("Trying")
span_tags = {"retry_num": retry_number}
with self.sygnal.tracer.start_span(
"apns_dispatch_try",
tags=span_tags,
child_of=span_parent) as span:
return await self._dispatch_request(
log, span, device, shaved_payload, prio)
except TemporaryNotificationDispatchException as exc:
retry_delay = self.RETRY_DELAY_BASE * (2**retry_number)
if exc.custom_retry_delay is not None:
retry_delay = exc.custom_retry_delay
log.warning(
"Temporary failure, will retry in %d seconds",
retry_delay,
exc_info=True,
)
span_parent.log_kv({
"event": "temporary_fail",
"retrying_in": retry_delay
})
if retry_number == self.MAX_TRIES - 1:
raise NotificationDispatchException(
"Retried too many times.") from exc
else:
await twisted_sleep(
retry_delay, twisted_reactor=self.sygnal.reactor)
async def _request_dispatch(
self,
n: Notification,
log: NotificationLoggerAdapter,
body: dict,
headers: Dict[AnyStr, List[AnyStr]],
pushkeys: List[str],
span: Span,
) -> Tuple[List[str], List[str]]:
poke_start_time = time.time()
failed = []
response, response_text = await self._perform_http_request(
body, headers)
RESPONSE_STATUS_CODES_COUNTER.labels(pushkin=self.name,
code=response.code).inc()
log.debug("GCM request took %f seconds", time.time() - poke_start_time)
span.set_tag(tags.HTTP_STATUS_CODE, response.code)
if 500 <= response.code < 600:
log.debug("%d from server, waiting to try again", response.code)
retry_after = None
for header_value in response.headers.getRawHeaders(b"retry-after",
default=[]):
retry_after = int(header_value)
span.log_kv({
"event": "gcm_retry_after",
"retry_after": retry_after
})
raise TemporaryNotificationDispatchException(
"GCM server error, hopefully temporary.",
custom_retry_delay=retry_after)
elif response.code == 400:
log.error(
"%d from server, we have sent something invalid! Error: %r",
response.code,
response_text,
)
# permanent failure: give up
raise NotificationDispatchException("Invalid request")
elif response.code == 401:
log.error("401 from server! Our API key is invalid? Error: %r",
response_text)
# permanent failure: give up
raise NotificationDispatchException("Not authorised to push")
elif response.code == 404:
# assume they're all failed
log.info("Reg IDs %r get 404 response; assuming unregistered",
pushkeys)
return pushkeys, []
elif 200 <= response.code < 300:
try:
resp_object = json_decoder.decode(response_text)
except ValueError:
raise NotificationDispatchException(
"Invalid JSON response from GCM.")
if "results" not in resp_object:
log.error(
"%d from server but response contained no 'results' key: %r",
response.code,
response_text,
)
if len(resp_object["results"]) < len(pushkeys):
log.error(
"Sent %d notifications but only got %d responses!",
len(n.devices),
len(resp_object["results"]),
)
span.log_kv({
logs.EVENT: "gcm_response_mismatch",
"num_devices": len(n.devices),
"num_results": len(resp_object["results"]),
})
# determine which pushkeys to retry or forget about
new_pushkeys = []
for i, result in enumerate(resp_object["results"]):
if "error" in result:
log.warning("Error for pushkey %s: %s", pushkeys[i],
result["error"])
span.set_tag("gcm_error", result["error"])
if result["error"] in BAD_PUSHKEY_FAILURE_CODES:
log.info(
"Reg ID %r has permanently failed with code %r: "
"rejecting upstream",
pushkeys[i],
result["error"],
)
failed.append(pushkeys[i])
elif result["error"] in BAD_MESSAGE_FAILURE_CODES:
log.info(
"Message for reg ID %r has permanently failed with code %r",
pushkeys[i],
result["error"],
)
else:
log.info(
"Reg ID %r has temporarily failed with code %r",
pushkeys[i],
result["error"],
)
new_pushkeys.append(pushkeys[i])
return failed, new_pushkeys
else:
raise NotificationDispatchException(
f"Unknown GCM response code {response.code}")
async def _handle_dispatch(
self,
root_span: Span,
request: Request,
log: NotificationLoggerAdapter,
notif: Notification,
context: NotificationContext,
) -> None:
"""
Actually handle the dispatch of notifications to devices, sequentially
for simplicity.
root_span: the OpenTracing span
request: the Twisted Web Request
log: the logger to use
notif: the notification to dispatch
context: the context of the notification
"""
try:
rejected = []
for d in notif.devices:
NOTIFS_RECEIVED_DEVICE_PUSH_COUNTER.inc()
appid = d.app_id
found_pushkins = self.find_pushkins(appid)
if len(found_pushkins) == 0:
log.warning("Got notification for unknown app ID %s",
appid)
rejected.append(d.pushkey)
continue
if len(found_pushkins) > 1:
log.warning("Got notification for an ambiguous app ID %s",
appid)
rejected.append(d.pushkey)
continue
pushkin = found_pushkins[0]
log.debug("Sending push to pushkin %s for app ID %s",
pushkin.name, appid)
NOTIFS_BY_PUSHKIN.labels(pushkin.name).inc()
result = await pushkin.dispatch_notification(notif, d, context)
if not isinstance(result, list):
raise TypeError("Pushkin should return list.")
rejected += result
request.write(json.dumps({"rejected": rejected}).encode())
if rejected:
log.info(
"Successfully delivered notifications with %d rejected pushkeys",
len(rejected),
)
except NotificationDispatchException:
request.setResponseCode(502)
log.warning("Failed to dispatch notification.", exc_info=True)
except Exception:
request.setResponseCode(500)
log.error("Exception whilst dispatching notification.",
exc_info=True)
finally:
if not request._disconnected:
request.finish()
PUSHGATEWAY_HTTP_RESPONSES_COUNTER.labels(code=request.code).inc()
root_span.set_tag(tags.HTTP_STATUS_CODE, request.code)
req_time = time.perf_counter() - context.start_time
if req_time > 0:
# can be negative as perf_counter() may not be monotonic
NOTIFY_HANDLE_HISTOGRAM.labels(
code=request.code).observe(req_time)
if not 200 <= request.code < 300:
root_span.set_tag(tags.ERROR, True)
root_span.finish()