From da858a1f3262375c26a2d0b07fe0a6fe746776b0 Mon Sep 17 00:00:00 2001
From: Richard van der Hoff <richard@matrix.org>
Date: Fri, 21 Apr 2023 10:04:52 +0100
Subject: [PATCH] Extend logging for outgoing pushes

---
 changelog.d/334.misc  |  1 +
 sygnal/apnspushkin.py | 27 ++++++++++++++++++---------
 sygnal/gcmpushkin.py  |  2 +-
 3 files changed, 20 insertions(+), 10 deletions(-)
 create mode 100644 changelog.d/334.misc

diff --git a/changelog.d/334.misc b/changelog.d/334.misc
new file mode 100644
index 00000000..13681a18
--- /dev/null
+++ b/changelog.d/334.misc
@@ -0,0 +1 @@
+Extend logging for outgoing pushes.
diff --git a/sygnal/apnspushkin.py b/sygnal/apnspushkin.py
index c3f18ac1..8a39cbe7 100644
--- a/sygnal/apnspushkin.py
+++ b/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)
diff --git a/sygnal/gcmpushkin.py b/sygnal/gcmpushkin.py
index f725b51f..0f92bff0 100644
--- a/sygnal/gcmpushkin.py
+++ b/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}