Couldn't see messages, then kick failed

[timokoesters]

Description

Something very weird happened in #conduit (but between two synapse users):

1. I couldn't see messages from one user, synapse logs showed this:
   Apr 02 21:53:12 matrix matrix-synapse[3871922]: 2022-04-02 19:53:12,495 - synapse.handlers.federation_event - 1415 - WARNING - _process_incoming_pdus_in_room_inner-56126-$UXuGlu7TKxSxiusMcp_RtAjVN0VgTg7bd911GwGU0Bg - While checking auth of <FrozenEventV3 event_id=$UXuGlu7TKxSxiusMcp_RtAjVN0VgTg7bd911GwGU0Bg, type=[m.room](http://m.room/).message, state_key=None, outlier=False> against auth_events: 403: During auth for event $UXuGlu7TKxSxiusMcp_RtAjVN0VgTg7bd911GwGU0Bg: found rejected event $Qb_j-UHGH_KdxjZ8-XOYsVgI-3ojjgCcV0py7G1kUHs in the state

2. I tried to kick the user, but got an error message along the lines of "could not find event $asdf". Unfortunately I don't have the exact message.

3. My server does not show a kick event. The user I tried to kick does not see the kick event. But a user from another hs can see it. I couldn't find anything about this in synapse logs

4. The user left the room themselves and rejoined. After that I could see their messages again

Steps to reproduce

• Unknown

Version information

My server: {"server_version":"1.55.2","python_version":"3.9.11"}
The server of the user I tried to kick: {"server_version":"1.53.0","python_version":"3.8.9"}

[squahtx]

Looking at matrix.org, $UXuGlu7TKxSxiusMcp_RtAjVN0VgTg7bd911GwGU0Bg is a regular m.room.message event and $Qb_j-UHGH_KdxjZ8-XOYsVgI-3ojjgCcV0py7G1kUHs is the m.room.member join event for the same user. Neither of these events are rejected on matrix.org.

Could you dig out the rejection_reason from the database?:

SELECT event_id,  FROM events WHERE event_id IN ('$UXuGlu7TKxSxiusMcp_RtAjVN0VgTg7bd911GwGU0Bg', '$Qb_j-UHGH_KdxjZ8-XOYsVgI-3ojjgCcV0py7G1kUHs');

Also are you running any modules that could reject events?

[timokoesters]

matrix=# SELECT event_id, rejection_reason  FROM events WHERE event_id IN ('$UXuGlu7TKxSxiusMcp_RtAjVN0VgTg7bd911GwGU0Bg', '$Qb_j-UHGH_KdxjZ8-XOYsVgI-3ojjgCcV0py7G1kUHs');                       
                   event_id                   | rejection_reason 
----------------------------------------------+------------------
 $Qb_j-UHGH_KdxjZ8-XOYsVgI-3ojjgCcV0py7G1kUHs | auth_error
 $UXuGlu7TKxSxiusMcp_RtAjVN0VgTg7bd911GwGU0Bg | auth_error

[squahtx]

Thanks for digging that out!

The rejected join event ($Qb_j-UHGH_KdxjZ8-XOYsVgI-3ojjgCcV0py7G1kUHs) has 4 auth events, one of which is a previous m.room.member join event:

timestamp	event id	type	sender	notes
2021-04-07 13:00:49 UTC	$iuIkrkm3NTRoW7rf4qKjpBcjCazBSNyrX8QYSg4Ln-4	m.room.member	the user in question	membership: join (???)
2021-04-07 12:43:35 UTC	$UfJ4H2SOR2X9yUQeJ6_Mm3Hl-lsn5nwTRQyFmc-iY3E	m.room.create	yourself
2021-11-13 11:45:59 UTC	$db0JUMoAMdztf3N7jQKyR019ypjW1uhcVyUBMu0ZPsg	m.room.power_levels	yourself
2022-03-30 11:32:49 UTC	$rM9dgJLh5aZuzMxMGaMGnW4XVUrLobrkMWKvBSzAfoM	m.room.join_rules	a moderator

The previous join event ($iuIkrkm3NTRoW7rf4qKjpBcjCazBSNyrX8QYSg4Ln-4) is from a year ago and has 3 auth events:

timestamp	event id	type	sender
2021-04-07 12:43:35 UTC	$UfJ4H2SOR2X9yUQeJ6_Mm3Hl-lsn5nwTRQyFmc-iY3E	m.room.create	yourself
2021-04-07 12:43:36 UTC	$VKIcskf0z3SkBkeJyzPa2IvB8-64g3Q4O4zdrQD2KjQ	m.room.power_levels	yourself
2021-04-07 12:43:36 UTC	$LqGoKWH6xTkllRooB4tjfqbViPCTEBuOfB_k8Dc-OJ8	m.room.join_rules	yourself

1. I'd be interested in finding the first event in the auth chain which is rejected. I suspect it's either the join ($Qb_j-UHGH_KdxjZ8-XOYsVgI-3ojjgCcV0py7G1kUHs) or the previous join ($iuIkrkm3NTRoW7rf4qKjpBcjCazBSNyrX8QYSg4Ln-4). Could you check which one it is?

2. If it turns out to be the recent join, could you also grep your homeserver logs for Qb_j-UHGH_KdxjZ8-XOYsVgI-3ojjgCcV0py7G1kUHs (watch out for the dollar sign if in regex mode)? There are 4 code paths which set the rejection reason to "auth_error" and they all log different messages:

   • "Rejecting %r because "
   • "While validating received event %r: "
   • "While checking auth of %r against auth_events: "
   • "Failed auth resolution for %r because "

   where "%r" will look like <FrozenEventV3 event_id=$Qb_j-UHGH_KdxjZ8-XOYsVgI-3ojjgCcV0py7G1kUHs, type=m.room.member, state_key=@..., outlier=...>

[richvdh]

this smells related to #9595 - which, as that issue says, is fixed for "new" events, but we have never done anything about cleaning up existing events.

[erikjohnston]

Are we happy to close this as a duplicate then?

[reivilibre]

Closing as duplicate of #9595.