async def _dispatch_notification_unlimited(
self, n: Notification, device: Device,
context: NotificationContext) -> List[str]:
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:
# Before we build the payload, check that the default_payload is not
# malformed and reject the pushkey if it is
default_payload = {}
if device.data:
default_payload = device.data.get("default_payload", {})
if not isinstance(default_payload, dict):
log.error(
"default_payload is malformed, this value must be a dict."
)
return [device.pushkey]
if n.event_id and not n.type:
payload: Optional[Dict[str,
Any]] = self._get_payload_event_id_only(
n, default_payload)
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:
span_tags = {"retry_num": retry_number}
with self.sygnal.tracer.start_span(
"apns_dispatch_try",
tags=span_tags,
child_of=span_parent) as span:
assert shaved_payload is not None
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:
await twisted_sleep(
retry_delay, twisted_reactor=self.sygnal.reactor)
raise NotificationDispatchException("Retried too many times.")
def _get_payload_full(
self, n: Notification, device: Device,
log: NotificationLoggerAdapter) -> Optional[Dict[str, Any]]:
"""
Constructs a payload for a notification.
Args:
n: The notification to construct a payload for.
device: Device information to which the constructed payload
will be sent.
log: A logger.
Returns:
The APNs payload as nested dicts.
"""
if not n.sender and not n.sender_display_name:
from_display = " "
elif n.sender_display_name is not None:
from_display = n.sender_display_name
elif n.sender is not None:
from_display = n.sender
from_display = from_display[0:self.MAX_FIELD_LENGTH]
loc_key = None
loc_args = None
if n.type == "m.room.message" or n.type == "m.room.encrypted":
room_display = None
if n.room_name:
room_display = n.room_name[0:self.MAX_FIELD_LENGTH]
elif n.room_alias:
room_display = n.room_alias[0:self.MAX_FIELD_LENGTH]
content_display = None
action_display = None
is_image = False
if n.content and "msgtype" in n.content and "body" in n.content:
if "body" in n.content:
if n.content["msgtype"] == "m.text":
content_display = n.content["body"]
elif n.content["msgtype"] == "m.emote":
action_display = n.content["body"]
else:
# fallback: 'body' should always be user-visible text
# in an m.room.message
content_display = n.content["body"]
if n.content["msgtype"] == "m.image":
is_image = True
if room_display:
if is_image:
loc_key = "IMAGE_FROM_USER_IN_ROOM"
loc_args = [from_display, content_display, room_display]
elif content_display:
loc_key = "MSG_FROM_USER_IN_ROOM_WITH_CONTENT"
loc_args = [from_display, room_display, content_display]
elif action_display:
loc_key = "ACTION_FROM_USER_IN_ROOM"
loc_args = [room_display, from_display, action_display]
else:
loc_key = "MSG_FROM_USER_IN_ROOM"
loc_args = [from_display, room_display]
else:
if is_image:
loc_key = "IMAGE_FROM_USER"
loc_args = [from_display, content_display]
elif content_display:
loc_key = "MSG_FROM_USER_WITH_CONTENT"
loc_args = [from_display, content_display]
elif action_display:
loc_key = "ACTION_FROM_USER"
loc_args = [from_display, action_display]
else:
loc_key = "MSG_FROM_USER"
loc_args = [from_display]
elif n.type == "m.call.invite":
is_video_call = False
# This detection works only for hs that uses WebRTC for calls
if n.content and "offer" in n.content and "sdp" in n.content[
"offer"]:
sdp = n.content["offer"]["sdp"]
if "m=video" in sdp:
is_video_call = True
if is_video_call:
loc_key = "VIDEO_CALL_FROM_USER"
else:
loc_key = "VOICE_CALL_FROM_USER"
loc_args = [from_display]
elif n.type == "m.room.member":
if n.user_is_target:
if n.membership == "invite":
if n.room_name:
loc_key = "USER_INVITE_TO_NAMED_ROOM"
loc_args = [
from_display,
n.room_name[0:self.MAX_FIELD_LENGTH],
]
elif n.room_alias:
loc_key = "USER_INVITE_TO_NAMED_ROOM"
loc_args = [
from_display,
n.room_alias[0:self.MAX_FIELD_LENGTH],
]
else:
loc_key = "USER_INVITE_TO_CHAT"
loc_args = [from_display]
elif n.type:
# A type of message was received that we don't know about
# but it was important enough for a push to have got to us
loc_key = "MSG_FROM_USER"
loc_args = [from_display]
badge = None
if n.counts.unread is not None:
badge = n.counts.unread
if n.counts.missed_calls is not None:
if badge is None:
badge = 0
badge += n.counts.missed_calls
if loc_key is None and badge is None:
log.info("Nothing to do for alert of type %s", n.type)
return None
payload = {}
if n.type and device.data:
payload = copy.deepcopy(device.data.get("default_payload", {}))
payload.setdefault("aps", {})
if loc_key:
payload["aps"].setdefault("alert", {})["loc-key"] = loc_key
if loc_args:
payload["aps"].setdefault("alert", {})["loc-args"] = loc_args
if badge is not None:
payload["aps"]["badge"] = badge
if loc_key and n.room_id:
payload["room_id"] = n.room_id
if loc_key and n.event_id:
payload["event_id"] = n.event_id
return payload
async def _dispatch_notification_unlimited(
self, n: Notification, device: Device,
context: NotificationContext) -> List[str]:
log = NotificationLoggerAdapter(logger,
{"request_id": context.request_id})
# `_dispatch_notification_unlimited` gets called once for each device in the
# `Notification` with a matching app ID. We do something a little dirty and
# perform all of our dispatches the first time we get called for a
# `Notification` and do nothing for the rest of the times we get called.
pushkeys = [
device.pushkey for device in n.devices
if self.handles_appid(device.app_id)
]
# `pushkeys` ought to never be empty here. At the very least it should contain
# `device`'s pushkey.
if pushkeys[0] != device.pushkey:
# We've already been asked to dispatch for this `Notification` and have
# previously sent out the notification to all devices.
return []
# The pushkey is kind of secret because you can use it to send push
# to someone.
# span_tags = {"pushkeys": pushkeys}
span_tags = {"gcm_num_devices": len(pushkeys)}
with self.sygnal.tracer.start_span(
"gcm_dispatch", tags=span_tags,
child_of=context.opentracing_span) as span_parent:
# TODO: Implement collapse_key to queue only one message per room.
failed: List[str] = []
data = GcmPushkin._build_data(n, device)
# Reject pushkey if default_payload is misconfigured
if data is None:
failed.append(device.pushkey)
headers = {
"User-Agent": ["sygnal"],
"Content-Type": ["application/json"],
"Authorization": ["key=%s" % (self.api_key, )],
}
body = self.base_request_body.copy()
body["data"] = data
body["priority"] = "normal" if n.prio == "low" else "high"
for retry_number in range(0, MAX_TRIES):
if len(pushkeys) == 1:
body["to"] = pushkeys[0]
else:
body["registration_ids"] = pushkeys
log.info("Sending (attempt %i) => %r", retry_number, pushkeys)
try:
span_tags = {"retry_num": retry_number}
with self.sygnal.tracer.start_span(
"gcm_dispatch_try",
tags=span_tags,
child_of=span_parent) as span:
new_failed, new_pushkeys = await self._request_dispatch(
n, log, body, headers, pushkeys, span)
pushkeys = new_pushkeys
failed += new_failed
if len(pushkeys) == 0:
break
except TemporaryNotificationDispatchException as exc:
retry_delay = 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
})
await twisted_sleep(retry_delay,
twisted_reactor=self.sygnal.reactor)
if len(pushkeys) > 0:
log.info("Gave up retrying reg IDs: %r", pushkeys)
# Count the number of failed devices.
span_parent.set_tag("gcm_num_failed", len(failed))
return failed
async def _dispatch_request(
self,
log: NotificationLoggerAdapter,
span: Span,
device: Device,
shaved_payload: Dict[str, Any],
prio: int,
) -> List[str]:
"""
Actually attempts to dispatch the notification once.
"""
# this is no good: APNs expects ID to be in their format
# so we can't just derive a
# notif_id = context.request_id + f"-{n.devices.index(device)}"
notif_id = str(uuid4())
log.info(f"Sending as APNs-ID {notif_id}")
span.set_tag("apns_id", notif_id)
device_token = base64.b64decode(device.pushkey).hex()
request = NotificationRequest(
device_token=device_token,
message=shaved_payload,
priority=prio,
notification_id=notif_id,
)
try:
with ACTIVE_REQUESTS_GAUGE.track_inprogress():
with SEND_TIME_HISTOGRAM.time():
response = await self._send_notification(request)
except aioapns.ConnectionError:
raise TemporaryNotificationDispatchException(
"aioapns Connection Failure")
code = int(response.status)
span.set_tag(tags.HTTP_STATUS_CODE, code)
RESPONSE_STATUS_CODES_COUNTER.labels(pushkin=self.name,
code=code).inc()
if response.is_successful:
return []
else:
# .description corresponds to the 'reason' response field
span.set_tag("apns_reason", response.description)
if (code, response.description) in self.TOKEN_ERRORS:
log.info(
"APNs token %s for pushkin %s was rejected: %d %s",
device_token,
self.name,
code,
response.description,
)
return [device.pushkey]
else:
if 500 <= code < 600:
raise TemporaryNotificationDispatchException(
f"{response.status} {response.description}")
else:
raise NotificationDispatchException(
f"{response.status} {response.description}")
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 _dispatch_notification_unlimited(self, n, device, context):
log = NotificationLoggerAdapter(logger,
{"request_id": context.request_id})
pushkeys = [
device.pushkey for device in n.devices
if device.app_id == self.name
]
# Resolve canonical IDs for all pushkeys
if pushkeys[0] != device.pushkey:
# Only send notifications once, to all devices at once.
return []
# The pushkey is kind of secret because you can use it to send push
# to someone.
# span_tags = {"pushkeys": pushkeys}
span_tags = {"gcm_num_devices": len(pushkeys)}
with self.sygnal.tracer.start_span(
"gcm_dispatch", tags=span_tags,
child_of=context.opentracing_span) as span_parent:
reg_id_mappings = await self.canonical_reg_id_store.get_canonical_ids(
pushkeys)
reg_id_mappings = {
reg_id: canonical_reg_id or reg_id
for (reg_id, canonical_reg_id) in reg_id_mappings.items()
}
inverse_reg_id_mappings = {
v: k
for (k, v) in reg_id_mappings.items()
}
data = GcmPushkin._build_data(n, device)
headers = {
b"User-Agent": ["sygnal"],
b"Content-Type": ["application/json"],
b"Authorization": ["key=%s" % (self.api_key, )],
}
# count the number of remapped registration IDs in the request
span_parent.set_tag(
"gcm_num_remapped_reg_ids_used",
[k != v for (k, v) in reg_id_mappings.items()].count(True),
)
# TODO: Implement collapse_key to queue only one message per room.
failed = []
body = self.base_request_body.copy()
body["data"] = data
body["priority"] = "normal" if n.prio == "low" else "high"
for retry_number in range(0, MAX_TRIES):
mapped_pushkeys = [reg_id_mappings[pk] for pk in pushkeys]
if len(pushkeys) == 1:
body["to"] = mapped_pushkeys[0]
else:
body["registration_ids"] = mapped_pushkeys
log.info("Sending (attempt %i) => %r", retry_number,
mapped_pushkeys)
try:
span_tags = {"retry_num": retry_number}
with self.sygnal.tracer.start_span(
"gcm_dispatch_try",
tags=span_tags,
child_of=span_parent) as span:
new_failed, new_pushkeys = await self._request_dispatch(
n, log, body, headers, mapped_pushkeys, span)
pushkeys = new_pushkeys
failed += [
inverse_reg_id_mappings[canonical_pk]
for canonical_pk in new_failed
]
if len(pushkeys) == 0:
break
except TemporaryNotificationDispatchException as exc:
retry_delay = 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
})
await twisted_sleep(retry_delay,
twisted_reactor=self.sygnal.reactor)
if len(pushkeys) > 0:
log.info("Gave up retrying reg IDs: %r", pushkeys)
# Count the number of failed devices.
span_parent.set_tag("gcm_num_failed", len(failed))
return failed
def _handle_request(self, request):
"""
Actually handle the request.
Args:
request (Request): The request, corresponding to a POST request.
Returns:
Either a str instance or NOT_DONE_YET.
"""
request_id = self._make_request_id()
header_dict = {
k.decode(): v[0].decode()
for k, v in request.requestHeaders.getAllRawHeaders()
}
# extract OpenTracing scope from the HTTP headers
span_ctx = self.sygnal.tracer.extract(Format.HTTP_HEADERS, header_dict)
span_tags = {
tags.SPAN_KIND: tags.SPAN_KIND_RPC_SERVER,
"request_id": request_id,
}
root_span = self.sygnal.tracer.start_span("pushgateway_v1_notify",
child_of=span_ctx,
tags=span_tags)
# if this is True, we will not close the root_span at the end of this
# function.
root_span_accounted_for = False
try:
context = NotificationContext(request_id, root_span,
time.perf_counter())
log = NotificationLoggerAdapter(logger, {"request_id": request_id})
try:
body = json.loads(request.content.read())
except Exception as exc:
msg = "Expected JSON request body"
log.warning(msg, exc_info=exc)
root_span.log_kv({logs.EVENT: "error", "error.object": exc})
request.setResponseCode(400)
return msg.encode()
if "notification" not in body or not isinstance(
body["notification"], dict):
msg = "Invalid notification: expecting object in 'notification' key"
log.warning(msg)
root_span.log_kv({logs.EVENT: "error", "message": msg})
request.setResponseCode(400)
return msg.encode()
try:
notif = Notification(body["notification"])
except InvalidNotificationException as e:
log.exception("Invalid notification")
request.setResponseCode(400)
root_span.log_kv({logs.EVENT: "error", "error.object": e})
return str(e).encode()
if notif.event_id is not None:
root_span.set_tag("event_id", notif.event_id)
# track whether the notification was passed with content
root_span.set_tag("has_content", notif.content is not None)
NOTIFS_RECEIVED_COUNTER.inc()
if len(notif.devices) == 0:
msg = "No devices in notification"
log.warning(msg)
request.setResponseCode(400)
return msg.encode()
root_span_accounted_for = True
ensureDeferred(
self._handle_dispatch(root_span, request, log, notif, context))
# we have to try and send the notifications first,
# so we can find out which ones to reject
return NOT_DONE_YET
except Exception as exc_val:
root_span.set_tag(tags.ERROR, True)
# [2] corresponds to the traceback
trace = traceback.format_tb(sys.exc_info()[2])
root_span.log_kv({
logs.EVENT: tags.ERROR,
logs.MESSAGE: str(exc_val),
logs.ERROR_OBJECT: exc_val,
logs.ERROR_KIND: type(exc_val),
logs.STACK: trace,
})
raise
finally:
if not root_span_accounted_for:
root_span.finish()
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 _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()
