Clean up some logging (#6515)

This just makes some of the logging easier to follow when things start going
wrong.

changelog.d/6515.misc

@@ -0,0 +1 @@
+Clean up some logging when handling incoming events over federation.

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,
             )