Extend logging for outgoing pushes

changelog.d/334.misc

@@ -0,0 +1 @@
+Extend logging for outgoing pushes.

sygnal/apnspushkin.py

@@ -228,18 +228,11 @@ async def _dispatch_request(
         device: Device,
         shaved_payload: Dict[str, Any],
         prio: int,
+        notif_id: str,
     ) -> 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()
@@ -344,8 +337,24 @@ async def _dispatch_notification_unlimited(
                         "apns_dispatch_try", tags=span_tags, child_of=span_parent
                     ) as span:
                         assert shaved_payload is not None
+
+                        # 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())
+                        # XXX: shouldn't we use the same notif_id for each retry?
+
+                        log.info(
+                            "Sending (attempt %i) => %s APNs-ID:%s room:%s, event:%s",
+                            retry_number,
+                            notif_id,
+                            device.pushkey,
+                            n.room_id,
+                            n.event_id,
+                        )
+
                         return await self._dispatch_request(
-                            log, span, device, shaved_payload, prio
+                            log, span, device, shaved_payload, prio, notif_id
                         )
                 except TemporaryNotificationDispatchException as exc:
                     retry_delay = self.RETRY_DELAY_BASE * (2**retry_number)

sygnal/gcmpushkin.py

@@ -376,7 +376,7 @@ async def _dispatch_notification_unlimited(
                 else:
                     body["registration_ids"] = pushkeys
 
-                log.info("Sending (attempt %i) => %r", retry_number, pushkeys)
+                log.info("Sending (attempt %i) => %r room:%s, event:%s", retry_number, pushkeys, n.room_id, n.event_id)
 
                 try:
                     span_tags = {"retry_num": retry_number}