Skip to content
This repository was archived by the owner on Apr 26, 2024. It is now read-only.

Clean up some logging #6515

Merged
richvdh merged 1 commit into from
Dec 11, 2019
Merged

Clean up some logging #6515

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions changelog.d/6515.misc
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Clean up some logging when handling incoming events over federation.
37 changes: 19 additions & 18 deletions synapse/handlers/federation.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -182,7 +182,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)
Copy link
Copy Markdown
Member

@erikjohnston erikjohnston Dec 11, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why remove the prefixing? I find it quite useful to track how we're processing an event?

Copy link
Copy Markdown
Member Author

@richvdh richvdh Dec 11, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

because it's in the logcontext anyway.

Copy link
Copy Markdown
Member

@erikjohnston erikjohnston Dec 11, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, so it is. I had forgotten the log context isn't the generic request one. Carry on.

logger.info("handling received PDU: %s", pdu)

# We reprocess pdus when we have seen them only as outliers
existing = yield self.store.get_event(
Expand Down Expand Up @@ -278,9 +278,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)
)
Copy link
Copy Markdown
Member

@erikjohnston erikjohnston Dec 11, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd be tempted to not include e and rely on the exception chaining (raise Exception(..) from e).

(I assume we've checked that get_missing_events_for_pdu doesn't raise any expected exceptions.)

Copy link
Copy Markdown
Member Author

@richvdh richvdh Dec 11, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd be tempted to not include e and rely on the exception chaining (raise Exception(..) from e).

I tried that. It made for remarkably unreadable errors, not least because the exception chain is epic.

Exception chaining happens by default when you raise an exception from an except block, afaik

Copy link
Copy Markdown
Member Author

@richvdh richvdh Dec 11, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(I assume we've checked that get_missing_events_for_pdu doesn't raise any expected exceptions.)

well: first, I've looked at the places on_receive_pdu is called (ie, the places that might care that we turn one sort of exception into a generic Exception). There are two such places: _handle_queued_pdus, in which all exceptions are treated equally, and get_missing_events_for_pdu (again), which does treat FederationError with code=403 specially.

Then going down through get_missing_events_for_pdu, the only things which might raise a FederationError are federation_client.get_missing_events (which I'm 99% sure doesn't), and on_receive_pdu which, as discussed, filters out such exceptions. So I'm reasonably confident it's not possible for get_missing_events_for_pdu to raise a FederationError with code=403, and therefore this change shouldn't make any difference.


# Update the set of things we've seen after trying to
# fetch the missing stuff
Expand All @@ -292,14 +298,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.
Expand Down Expand Up @@ -344,6 +342,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()
Expand All @@ -364,10 +368,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)
Expand Down Expand Up @@ -611,8 +612,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,
)

Expand Down