From 7c429f92d6935a3e9e0140fdd82801edc43b66b8 Mon Sep 17 00:00:00 2001
From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com>
Date: Wed, 11 Dec 2019 14:32:25 +0000
Subject: [PATCH] Clean up some logging (#6515)

This just makes some of the logging easier to follow when things start going
wrong.
---
 changelog.d/6515.misc          |  1 +
 synapse/handlers/federation.py | 37 +++++++++++++++++-----------------
 2 files changed, 20 insertions(+), 18 deletions(-)
 create mode 100644 changelog.d/6515.misc

diff --git a/changelog.d/6515.misc b/changelog.d/6515.misc
new file mode 100644
index 000000000000..a9c303ed1ca2
--- /dev/null
+++ b/changelog.d/6515.misc
@@ -0,0 +1 @@
+Clean up some logging when handling incoming events over federation.
diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py
index 8f3c9d770243..cf9c46d02758 100644
--- a/synapse/handlers/federation.py
+++ b/synapse/handlers/federation.py
@@ -183,7 +183,7 @@ def on_receive_pdu(self, origin, pdu, sent_to_us_directly=False):
         room_id = pdu.room_id
         event_id = pdu.event_id
 
-        logger.info("[%s %s] handling received PDU: %s", room_id, event_id, pdu)
+        logger.info("handling received PDU: %s", pdu)
 
         # We reprocess pdus when we have seen them only as outliers
         existing = yield self.store.get_event(
@@ -279,9 +279,15 @@ def on_receive_pdu(self, origin, pdu, sent_to_us_directly=False):
                             len(missing_prevs),
                         )
 
-                        yield self._get_missing_events_for_pdu(
-                            origin, pdu, prevs, min_depth
-                        )
+                        try:
+                            yield self._get_missing_events_for_pdu(
+                                origin, pdu, prevs, min_depth
+                            )
+                        except Exception as e:
+                            raise Exception(
+                                "Error fetching missing prev_events for %s: %s"
+                                % (event_id, e)
+                            )
 
                         # Update the set of things we've seen after trying to
                         # fetch the missing stuff
@@ -293,14 +299,6 @@ def on_receive_pdu(self, origin, pdu, sent_to_us_directly=False):
                                 room_id,
                                 event_id,
                             )
-                elif missing_prevs:
-                    logger.info(
-                        "[%s %s] Not recursively fetching %d missing prev_events: %s",
-                        room_id,
-                        event_id,
-                        len(missing_prevs),
-                        shortstr(missing_prevs),
-                    )
 
             if prevs - seen:
                 # We've still not been able to get all of the prev_events for this event.
@@ -345,6 +343,12 @@ def on_receive_pdu(self, origin, pdu, sent_to_us_directly=False):
                         affected=pdu.event_id,
                     )
 
+                logger.info(
+                    "Event %s is missing prev_events: calculating state for a "
+                    "backwards extremity",
+                    event_id,
+                )
+
                 # Calculate the state after each of the previous events, and
                 # resolve them to find the correct state at the current event.
                 auth_chains = set()
@@ -365,10 +369,7 @@ def on_receive_pdu(self, origin, pdu, sent_to_us_directly=False):
                     # know about
                     for p in prevs - seen:
                         logger.info(
-                            "[%s %s] Requesting state at missing prev_event %s",
-                            room_id,
-                            event_id,
-                            p,
+                            "Requesting state at missing prev_event %s", event_id,
                         )
 
                         room_version = yield self.store.get_room_version(room_id)
@@ -612,8 +613,8 @@ def _get_state_for_room(self, destination, room_id, event_id):
         failed_to_fetch = desired_events - event_map.keys()
         if failed_to_fetch:
             logger.warning(
-                "Failed to fetch missing state/auth events for %s: %s",
-                room_id,
+                "Failed to fetch missing state/auth events for %s %s",
+                event_id,
                 failed_to_fetch,
             )