mirror of
https://mau.dev/maunium/synapse.git
synced 2024-12-14 22:53:52 +01:00
Add debug logs to figure out why an event was filtered (#14095)
Spawned while investigating https://github.com/matrix-org/synapse/issues/13944 This way we might get some more context whenever an `403 Forbidden - body: {"errcode":"M_FORBIDDEN","error":"You don't have permission to access that event."}` error is produced. `log_config.yaml` ```yaml loggers: synapse: level: INFO synapse.visibility: level: DEBUG ```
This commit is contained in:
parent
6fee2f49f3
commit
2c63cdcc3f
2 changed files with 32 additions and 1 deletions
1
changelog.d/14095.misc
Normal file
1
changelog.d/14095.misc
Normal file
|
@ -0,0 +1 @@
|
||||||
|
Add debug logs to figure out why an event was filtered out of the client response.
|
|
@ -84,7 +84,15 @@ async def filter_events_for_client(
|
||||||
"""
|
"""
|
||||||
# Filter out events that have been soft failed so that we don't relay them
|
# Filter out events that have been soft failed so that we don't relay them
|
||||||
# to clients.
|
# to clients.
|
||||||
|
events_before_filtering = events
|
||||||
events = [e for e in events if not e.internal_metadata.is_soft_failed()]
|
events = [e for e in events if not e.internal_metadata.is_soft_failed()]
|
||||||
|
if len(events_before_filtering) != len(events):
|
||||||
|
if logger.isEnabledFor(logging.DEBUG):
|
||||||
|
logger.debug(
|
||||||
|
"filter_events_for_client: Filtered out soft-failed events: Before=%s, After=%s",
|
||||||
|
[event.event_id for event in events_before_filtering],
|
||||||
|
[event.event_id for event in events],
|
||||||
|
)
|
||||||
|
|
||||||
types = (_HISTORY_VIS_KEY, (EventTypes.Member, user_id))
|
types = (_HISTORY_VIS_KEY, (EventTypes.Member, user_id))
|
||||||
|
|
||||||
|
@ -301,6 +309,10 @@ def _check_client_allowed_to_see_event(
|
||||||
_check_filter_send_to_client(event, clock, retention_policy, sender_ignored)
|
_check_filter_send_to_client(event, clock, retention_policy, sender_ignored)
|
||||||
== _CheckFilter.DENIED
|
== _CheckFilter.DENIED
|
||||||
):
|
):
|
||||||
|
logger.debug(
|
||||||
|
"_check_client_allowed_to_see_event(event=%s): Filtered out event because `_check_filter_send_to_client` returned `_CheckFilter.DENIED`",
|
||||||
|
event.event_id,
|
||||||
|
)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
if event.event_id in always_include_ids:
|
if event.event_id in always_include_ids:
|
||||||
|
@ -312,9 +324,17 @@ def _check_client_allowed_to_see_event(
|
||||||
# for out-of-band membership events (eg, incoming invites, or rejections of
|
# for out-of-band membership events (eg, incoming invites, or rejections of
|
||||||
# said invite) for the user themselves.
|
# said invite) for the user themselves.
|
||||||
if event.type == EventTypes.Member and event.state_key == user_id:
|
if event.type == EventTypes.Member and event.state_key == user_id:
|
||||||
logger.debug("Returning out-of-band-membership event %s", event)
|
logger.debug(
|
||||||
|
"_check_client_allowed_to_see_event(event=%s): Returning out-of-band-membership event %s",
|
||||||
|
event.event_id,
|
||||||
|
event,
|
||||||
|
)
|
||||||
return event
|
return event
|
||||||
|
|
||||||
|
logger.debug(
|
||||||
|
"_check_client_allowed_to_see_event(event=%s): Filtered out event because it's an outlier",
|
||||||
|
event.event_id,
|
||||||
|
)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
if state is None:
|
if state is None:
|
||||||
|
@ -337,11 +357,21 @@ def _check_client_allowed_to_see_event(
|
||||||
|
|
||||||
membership_result = _check_membership(user_id, event, visibility, state, is_peeking)
|
membership_result = _check_membership(user_id, event, visibility, state, is_peeking)
|
||||||
if not membership_result.allowed:
|
if not membership_result.allowed:
|
||||||
|
logger.debug(
|
||||||
|
"_check_client_allowed_to_see_event(event=%s): Filtered out event because the user can't see the event because of their membership, membership_result.allowed=%s membership_result.joined=%s",
|
||||||
|
event.event_id,
|
||||||
|
membership_result.allowed,
|
||||||
|
membership_result.joined,
|
||||||
|
)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
# If the sender has been erased and the user was not joined at the time, we
|
# If the sender has been erased and the user was not joined at the time, we
|
||||||
# must only return the redacted form.
|
# must only return the redacted form.
|
||||||
if sender_erased and not membership_result.joined:
|
if sender_erased and not membership_result.joined:
|
||||||
|
logger.debug(
|
||||||
|
"_check_client_allowed_to_see_event(event=%s): Returning pruned event because `sender_erased` and the user was not joined at the time",
|
||||||
|
event.event_id,
|
||||||
|
)
|
||||||
event = prune_event(event)
|
event = prune_event(event)
|
||||||
|
|
||||||
return event
|
return event
|
||||||
|
|
Loading…
Reference in a new issue