From d66d68f9177d3addc32f6ab02458e3620f5ffc1f Mon Sep 17 00:00:00 2001
From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com>
Date: Tue, 3 May 2022 16:32:40 +0100
Subject: [PATCH] Add extra debug logging to federation sender (#12614)

... in order to debug some problems we've been having with certain events not
being sent when expected.
---
 changelog.d/12614.misc                |  1 +
 synapse/federation/sender/__init__.py | 20 ++++++++++++++++++--
 2 files changed, 19 insertions(+), 2 deletions(-)
 create mode 100644 changelog.d/12614.misc

diff --git a/changelog.d/12614.misc b/changelog.d/12614.misc
new file mode 100644
index 000000000000..79022df127d0
--- /dev/null
+++ b/changelog.d/12614.misc
@@ -0,0 +1 @@
+Add extra debug logging to federation sender.
diff --git a/synapse/federation/sender/__init__.py b/synapse/federation/sender/__init__.py
index d795b7b26bcc..6d2f46318bea 100644
--- a/synapse/federation/sender/__init__.py
+++ b/synapse/federation/sender/__init__.py
@@ -343,9 +343,16 @@ async def _process_event_queue_loop(self) -> None:
                     last_token, self._last_poked_id, limit=100
                 )
 
-                logger.debug("Handling %s -> %s", last_token, next_token)
+                logger.debug(
+                    "Handling %i -> %i: %i events to send (current id %i)",
+                    last_token,
+                    next_token,
+                    len(events),
+                    self._last_poked_id,
+                )
 
                 if not events and next_token >= self._last_poked_id:
+                    logger.debug("All events processed")
                     break
 
                 async def handle_event(event: EventBase) -> None:
@@ -353,6 +360,7 @@ async def handle_event(event: EventBase) -> None:
                     send_on_behalf_of = event.internal_metadata.get_send_on_behalf_of()
                     is_mine = self.is_mine_id(event.sender)
                     if not is_mine and send_on_behalf_of is None:
+                        logger.debug("Not sending remote-origin event %s", event)
                         return
 
                     # We also want to not send out-of-band membership events.
@@ -389,12 +397,16 @@ async def handle_event(event: EventBase) -> None:
                     # above).
                     #
                     if event.internal_metadata.is_out_of_band_membership():
+                        logger.debug("Not sending OOB membership event %s", event)
                         return
 
                     # Finally, there are some other events that we should not send out
                     # until someone asks for them. They are explicitly flagged as such
                     # with `proactively_send: False`.
                     if not event.internal_metadata.should_proactively_send():
+                        logger.debug(
+                            "Not sending event with proactively_send=false: %s", event
+                        )
                         return
 
                     destinations: Optional[Set[str]] = None
@@ -458,7 +470,10 @@ async def handle_event(event: EventBase) -> None:
                             "federation_sender"
                         ).observe((now - ts) / 1000)
 
-                async def handle_room_events(events: Iterable[EventBase]) -> None:
+                async def handle_room_events(events: List[EventBase]) -> None:
+                    logger.debug(
+                        "Handling %i events in room %s", len(events), events[0].room_id
+                    )
                     with Measure(self.clock, "handle_room_events"):
                         for event in events:
                             await handle_event(event)
@@ -477,6 +492,7 @@ async def handle_room_events(events: Iterable[EventBase]) -> None:
                     )
                 )
 
+                logger.debug("Successfully handled up to %i", next_token)
                 await self.store.update_federation_out_pos("events", next_token)
 
                 if events: