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

Add fields to better debug where events are being soft_failed #10168

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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/10168.misc
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Add extra logging fields to better debug where events are being soft failed.
21 changes: 18 additions & 3 deletions synapse/handlers/federation.py
Original file line number Diff line number Diff line change
Expand Up @@ -2425,7 +2425,11 @@ async def _persist_auth_tree(
)

async def _check_for_soft_fail(
self, event: EventBase, state: Optional[Iterable[EventBase]], backfilled: bool
self,
event: EventBase,
state: Optional[Iterable[EventBase]],
backfilled: bool,
origin: str,
) -> None:
"""Checks if we should soft fail the event; if so, marks the event as
such.
Expand All @@ -2434,6 +2438,7 @@ async def _check_for_soft_fail(
event
state: The state at the event if we don't have all the event's prev events
backfilled: Whether the event is from backfill
origin: The host the event originates from.
"""
# For new (non-backfilled and non-outlier) events we check if the event
# passes auth based on the current state. If it doesn't then we
Expand Down Expand Up @@ -2503,7 +2508,17 @@ async def _check_for_soft_fail(
try:
event_auth.check(room_version_obj, event, auth_events=current_auth_events)
except AuthError as e:
logger.warning("Soft-failing %r because %s", event, e)
logger.warning(
"Soft-failing %r (from %s) because %s",
event,
e,
origin,
extra={
"room_id": event.room_id,
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Useful to know where the bad events are being sent

"mxid": event.sender,
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Useful to know who is sending the bad events

"hs": origin,
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Useful to log which homeserver is sending all of the bad events

},
Copy link
Contributor Author

@MadLittleMods MadLittleMods Jun 12, 2021

Choose a reason for hiding this comment

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

For another example of extra, see tests/logging/test_terse_json.py#L64-L74 which adds extra fields to the structured logging objects.

"The fourth keyword argument is extra which can be used to pass a dictionary which is used to populate the __dict__ of the LogRecord", https://docs.python.org/3/library/logging.html#logging.Logger.debug

)
soft_failed_event_counter.inc()
event.internal_metadata.soft_failed = True

Expand Down Expand Up @@ -2616,7 +2631,7 @@ async def _check_event_auth(
context.rejected = RejectedReason.AUTH_ERROR

if not context.rejected:
await self._check_for_soft_fail(event, state, backfilled)
await self._check_for_soft_fail(event, state, backfilled, origin=origin)

if event.type == EventTypes.GuestAccess and not context.rejected:
await self.maybe_kick_guest_users(event)
Expand Down