Federation automatic joins raise 403 on callee homeserver

[csuriano23]

Description

I have two federated homeservers, call them alpha and beta.

On both servers it is installed the synapse-auto-accept-invite plugin that triggers a join as a third-party rule each time a user is invited to a room.

When I create a room on alpha and then I invite an user of beta the rule is triggered, but it fails, below the stacktrace on beta homeserver (see also this issue):

2023-02-07 11:49:38 2023-02-07 10:49:38,629 - synapse.events.third_party_rules - 406 - ERROR - PUT-625 - Failed to run module API callback <bound method InviteAutoAccepter.on_new_event of <synapse_auto_accept_invite.InviteAutoAccepter object at 0xffff99f762b0>>: 403: You are not invited to this room.
2023-02-07 11:49:38 Traceback (most recent call last):
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/federation/federation_client.py", line 852, in _try_destination_list
2023-02-07 11:49:38     return await callback(destination)
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/federation/federation_client.py", line 962, in send_request
2023-02-07 11:49:38     ret = await self.transport_layer.make_membership_event(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/federation/transport/client.py", line 324, in make_membership_event
2023-02-07 11:49:38     return await self.client.get_json(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 1077, in get_json
2023-02-07 11:49:38     response = await self._send_request_with_optional_trailing_slash(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 406, in _send_request_with_optional_trailing_slash
2023-02-07 11:49:38     response = await self._send_request(request, **send_request_args)
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/http/matrixfederationclient.py", line 668, in _send_request
2023-02-07 11:49:38     raise exc
2023-02-07 11:49:38 synapse.api.errors.HttpResponseException: 403: Forbidden
2023-02-07 11:49:38 
2023-02-07 11:49:38 The above exception was the direct cause of the following exception:
2023-02-07 11:49:38 
2023-02-07 11:49:38 Traceback (most recent call last):
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/events/third_party_rules.py", line 404, in on_new_event
2023-02-07 11:49:38     await callback(event, state_events)
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse_auto_accept_invite/__init__.py", line 99, in on_new_event
2023-02-07 11:49:38     await self._api.update_room_membership(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/module_api/__init__.py", line 1063, in update_room_membership
2023-02-07 11:49:38     event_id, _ = await self._hs.get_room_member_handler().update_membership(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/handlers/room_member.py", line 597, in update_membership
2023-02-07 11:49:38     result = await self.update_membership_locked(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/handlers/room_member.py", line 965, in update_membership_locked
2023-02-07 11:49:38     remote_join_response = await self._remote_join(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/handlers/room_member.py", line 1747, in _remote_join
2023-02-07 11:49:38     event_id, stream_id = await self.federation_handler.do_invite_join(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation.py", line 574, in do_invite_join
2023-02-07 11:49:38     origin, event, room_version_obj = await self._make_and_verify_event(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation.py", line 1082, in _make_and_verify_event
2023-02-07 11:49:38     ) = await self.federation_client.make_membership_event(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/federation/federation_client.py", line 1014, in make_membership_event
2023-02-07 11:49:38     return await self._try_destination_list(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/federation/federation_client.py", line 894, in _try_destination_list
2023-02-07 11:49:38     raise synapse_error from e
2023-02-07 11:49:38 synapse.api.errors.ProxiedRequestError: 403: You are not invited to this room.

On alpha homeserver here is the stacktrace (I've patched the original code on /synapse/http/server.py:_async_render_wrapper, line ~315 in order to print this):

2023-02-07 11:49:38 Traceback (most recent call last):
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/http/server.py", line 307, in _async_render_wrapper
2023-02-07 11:49:38     callback_return = await self._async_render(request)
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/http/server.py", line 514, in _async_render
2023-02-07 11:49:38     callback_return = await raw_callback_return
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/federation/transport/server/_base.py", line 349, in new_func
2023-02-07 11:49:38     response = await func(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/federation/transport/server/federation.py", line 291, in on_GET
2023-02-07 11:49:38     result = await self.handler.on_make_join_request(
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/federation/federation_server.py", line 647, in on_make_join_request
2023-02-07 11:49:38     pdu = await self.handler.on_make_join_request(origin, room_id, user_id)
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation.py", line 952, in on_make_join_request
2023-02-07 11:49:38     await self._event_auth_handler.check_auth_rules_from_context(event)
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/handlers/event_auth.py", line 69, in check_auth_rules_from_context
2023-02-07 11:49:38     check_state_dependent_auth_rules(event, auth_events_by_id.values())
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/event_auth.py", line 304, in check_state_dependent_auth_rules
2023-02-07 11:49:38     _is_membership_change_allowed(event.room_version, event, auth_dict)
2023-02-07 11:49:38   File "/usr/local/lib/python3.9/site-packages/synapse/event_auth.py", line 649, in _is_membership_change_allowed
2023-02-07 11:49:38     raise AuthError(403, "You are not invited to this room.")
2023-02-07 11:49:38 synapse.api.errors.AuthError: 403: You are not invited to this room.

This is due to the fact that events received by the function /synapse/event_auth.py:_is_membership_change_allowed (arg auth_events) are these (once again patched version with more logging):

[{('m.room.power_levels', ''): <FrozenEventV3 event_id=$QBnOW4DH8asI1Sjbb4cEp1kGF1DHO3kOxBeuHilgfjs, type=m.room.power_levels, state_key=, outlier=False>, ('m.room.join_rules', ''): <FrozenEventV3 event_id=$jonFOBLPEwbG3oTctHGv8s-LYw7SW0s7bW5eXiKq3z0, type=m.room.join_rules, state_key=, outlier=False>, ('m.room.create', ''): <FrozenEventV3 event_id=$s6joCXpyxW38sPpSE6dWS_2A62Op39z71awJ0lZAU6U, type=m.room.create, state_key=, outlier=False>}]

When I manually accept from the beta client everything goes ok and the auth events logged are different (call from beta server is the same, I've compared the url):

[{('m.room.power_levels', ''): <FrozenEventV3 event_id=$QBnOW4DH8asI1Sjbb4cEp1kGF1DHO3kOxBeuHilgfjs, type=m.room.power_levels, state_key=, outlier=False>, ('m.room.join_rules', ''): <FrozenEventV3 event_id=$jonFOBLPEwbG3oTctHGv8s-LYw7SW0s7bW5eXiKq3z0, type=m.room.join_rules, state_key=, outlier=False>, ('m.room.member', '@betauser:beta.dbridge.dev'): <FrozenEventV3 event_id=$ym49hJLGIrVg094rFk2C0DdAfF1s92FNGevTfosF6I4, type=m.room.member, state_key=@betauser:beta.dbridge.dev, outlier=False>, ('m.room.create', ''): <FrozenEventV3 event_id=$s6joCXpyxW38sPpSE6dWS_2A62Op39z71awJ0lZAU6U, type=m.room.create, state_key=, outlier=False>}]

Even hardcoding a time.sleep(30) on the third-party rule doesn't seem to solve the issue. I've also tried patching the third party rule to retry N times with backoff factor, but still the same issue.

Is this inconsistent behavior on event storage a known issue?
If yes, has a fix already been planned?
Are there workaround possible?

Steps to reproduce

See description

Homeserver

local homeserver

Synapse Version

1.75.0

Installation Method

Docker (matrixdotorg/synapse)

Database

PostgreSQL, no separate servers, no porting, no restoring

Workers

Single process

Platform

See docker image matrixdotorg/synapse:v1.75.0

Configuration

Third party plugin:

modules:
  - module: synapse_auto_accept_invite.InviteAutoAccepter
    config:
      accept_invites_only_for_direct_messages: false

Relevant log output

See description

Anything else that would be useful to know?

No response