Refactor create_new_client_event to use a new parameter, state_event_ids, which accurately describes the usage with MSC2716 instead of abusing auth_event_ids

[MadLittleMods]

Refactor create_new_client_event to use a new parameter, state_event_ids, which accurately describes the usage with MSC2716 instead of abusing auth_event_ids.

Spawned from #10975 (comment)

Part of MSC2716

Dev notes

Relevant call stacks (MSC2716 -> create_new_client_event)

# For events
RoomBatchSendEventRestServlet.on_POST
handle_batch_of_events
persist_historical_events
create_event
create_new_client_event

# For `m.room.member` state events
RoomBatchSendEventRestServlet.on_POST
persist_state_events_at_start
update_membership
update_membership_locked
_local_membership_update
create_event
create_new_client_event

# For non `m.room.member` state events
RoomBatchSendEventRestServlet.on_POST
persist_state_events_at_start
create_and_send_nonmember_event
create_event
create_new_client_event

---

MSC2716 Complement tests are passing ✅

$ COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh TestImportHistoricalMessages
...
--- PASS: TestImportHistoricalMessages (21.11s)
    --- PASS: TestImportHistoricalMessages/parallel (7.37s)
        --- SKIP: TestImportHistoricalMessages/parallel/TODO:_Trying_to_send_insertion_event_with_same_`next_batch_id`_will_reject (0.00s)
        --- SKIP: TestImportHistoricalMessages/parallel/TODO:_What_happens_when_you_point_multiple_batches_at_the_same_insertion_event? (0.00s)
        --- PASS: TestImportHistoricalMessages/parallel/Federation (0.00s)
            --- PASS: TestImportHistoricalMessages/parallel/Federation/Historical_messages_are_visible_when_joining_on_federated_server_-_auto-generated_base_insertion_event (4.05s)
            --- PASS: TestImportHistoricalMessages/parallel/Federation/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event (4.57s)
            --- PASS: TestImportHistoricalMessages/parallel/Federation/Historical_messages_are_visible_when_already_joined_on_federated_server (5.56s)
            --- PASS: TestImportHistoricalMessages/parallel/Federation/When_messages_have_already_been_scrolled_back_through,_new_historical_messages_are_visible_in_next_scroll_back_on_federated_server (6.41s)
        --- PASS: TestImportHistoricalMessages/parallel/Existing_room_versions (0.00s)
            --- PASS: TestImportHistoricalMessages/parallel/Existing_room_versions/Not_allowed_to_redact_MSC2716_insertion,_batch,_marker_events (0.87s)
            --- PASS: TestImportHistoricalMessages/parallel/Existing_room_versions/Room_creator_can_send_MSC2716_events (0.95s)
        --- PASS: TestImportHistoricalMessages/parallel/Unrecognised_prev_event_ID_will_throw_an_error (1.43s)
        --- PASS: TestImportHistoricalMessages/parallel/Duplicate_next_batch_id_on_insertion_event_will_be_rejected (2.12s)
        --- PASS: TestImportHistoricalMessages/parallel/Normal_users_aren't_allowed_to_batch_send_historical_messages (2.26s)
        --- PASS: TestImportHistoricalMessages/parallel/Unrecognised_batch_id_will_throw_an_error (2.26s)
        --- PASS: TestImportHistoricalMessages/parallel/Batch_send_endpoint_only_returns_state_events_that_we_passed_in_via_state_events_at_start (2.72s)
        --- PASS: TestImportHistoricalMessages/parallel/Should_be_able_to_send_a_batch_without_any_state_events_at_start_-_user_already_joined_in_the_current_room_state (2.99s)
        --- PASS: TestImportHistoricalMessages/parallel/Should_be_able_to_batch_send_historical_messages_into_private_room (3.28s)
        --- PASS: TestImportHistoricalMessages/parallel/Historical_events_from_multiple_users_in_the_same_batch (3.34s)
        --- PASS: TestImportHistoricalMessages/parallel/Historical_events_resolve_in_the_correct_order (3.98s)
        --- PASS: TestImportHistoricalMessages/parallel/should_resolve_member_state_events_for_historical_events (4.00s)
        --- PASS: TestImportHistoricalMessages/parallel/Historical_events_from_batch_send_do_not_come_down_in_an_incremental_sync (4.12s)
PASS
ok  	github.com/matrix-org/complement/tests	23.012s

Dev notes

SYNAPSE_POSTGRES=1 SYNAPSE_TEST_LOG_LEVEL=INFO python -m twisted.trial tests.rest.client.test_room_batch

synapse/handlers/message.py -> create_event (by the create_new_client_event call)

        logger.info(
            "create_new_client_event %s event=%s state_group=%s",
            event.type,
            event.event_id,
            context._state_group,
        )

Before

After

create_new_client_event org.matrix.msc2716.insertion event=$y08_OT7wtMscqZbvauBvqWfXEjwM-hLX57_MT-71uNk state_group=7 create_new_client_event org.matrix.msc2716.insertion event=$3-4GMFlhZg6soJ5X3sZj8_hX2U7SrkFXn6TpKSBAZQ0 state_group=8 create_new_client_event m.room.message event=$JfDqQ6dWTMUrO7OC0K5MQhV0GiHIqGf6Ptzq-O74xQk state_group=8 create_new_client_event m.room.message event=$mKx6r9PikAI1GfmA6B-dV6AnzhOBJikfveKlk-HJTpY state_group=8 create_new_client_event m.room.message event=$32YuJxDCy8noF5q_Yb_wYm6-94taEjlRlNArpyrrmkM state_group=8 create_new_client_event org.matrix.msc2716.batch event=$I7GeKSYMTLNnoyWyWZTXFHVE9QmDWMFt1I-JzLsX83c state_group=8

same

Pull Request Checklist

• Pull request is based on the develop branch
• Pull request includes a changelog file. The entry should:
  • Be a short description of your change which makes sense to users. "Fixed a bug that prevented receiving messages from other servers." instead of "Moved X method from EventStore to EventWorkerStore.".
  • Use markdown where necessary, mostly for code blocks.
  • End with either a period (.) or an exclamation mark (!).
  • Start with a capital letter.
  • Feel free to credit yourself, by adding a sentence "Contributed by @github_username." or "Contributed by [Your Name]." to the end of the entry.
• Pull request includes a sign off
• Code style is correct
  (run the linters)

[MadLittleMods]

Making this comment more accurate

[MadLittleMods]

Added some nice context for why we're doing this that was only a PR review comment previously, #10975 (comment)

[MadLittleMods]

Making this comment more accurate

[MadLittleMods]

Since we are now using the new state_event_ids parameter to do all of the heavy lifting. I think we can remove any spots where we plumbed auth_event_ids just for MSC2716 things in https://github.com/matrix-org/synapse/pull/9247/files. This assumes that no one else started using those parameters outside of MSC2716 and I would need to check for sure while doing this removal. This includes the following functions:

• create_and_send_nonmember_event
• _local_membership_update
• update_membership
• update_membership_locked

We do need to keep prev_event_ids as that's still important and separate from the state/auth.

Should I do this as part of this PR or is it okay to split that out to another PR as a fast follow-up?

[richvdh]

I think it's fine to keep it separate.

[MadLittleMods]

Created #12304 to take care of this ⏩

[tulir]

It looks like batch sending is completely broken in 1.53, so would be nice to get this merged quickly :3

[MadLittleMods]

It looks like batch sending is completely broken in 1.53, so would be nice to get this merged quickly :3

-- @tulir, #12083 (comment)

What's broken about it?

This PR doesn't fix anything (just refactors a parameter differently)

Here are the Complement tests passing on v1.53.0 Synapse tag. The only thing broken is Complement itself which is being fixed in matrix-org/complement#324

$ cd complement
# checkout https://github.com/matrix-org/complement/pull/324
$ git checkout madlittlemods/fix-unrecognised-appservice-access-token

$ cd synapse
$ git checkout v1.53.0
$ COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh TestImportHistoricalMessages

--- PASS: TestImportHistoricalMessages (19.46s)
    --- PASS: TestImportHistoricalMessages/parallel (6.28s)
        --- SKIP: TestImportHistoricalMessages/parallel/TODO:_Trying_to_send_insertion_event_with_same_`next_batch_id`_will_reject (0.00s)
        --- SKIP: TestImportHistoricalMessages/parallel/TODO:_What_happens_when_you_point_multiple_batches_at_the_same_insertion_event? (0.00s)
        --- PASS: TestImportHistoricalMessages/parallel/Federation (0.00s)
            --- PASS: TestImportHistoricalMessages/parallel/Federation/Historical_messages_are_visible_when_joining_on_federated_server_-_auto-generated_base_insertion_event (4.12s)
            --- PASS: TestImportHistoricalMessages/parallel/Federation/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event (4.67s)
            --- PASS: TestImportHistoricalMessages/parallel/Federation/Historical_messages_are_visible_when_already_joined_on_federated_server (5.33s)
            --- PASS: TestImportHistoricalMessages/parallel/Federation/When_messages_have_already_been_scrolled_back_through,_new_historical_messages_are_visible_in_next_scroll_back_on_federated_server (5.38s)
        --- PASS: TestImportHistoricalMessages/parallel/Existing_room_versions (0.00s)
            --- PASS: TestImportHistoricalMessages/parallel/Existing_room_versions/Not_allowed_to_redact_MSC2716_insertion,_batch,_marker_events (0.82s)
            --- PASS: TestImportHistoricalMessages/parallel/Existing_room_versions/Room_creator_can_send_MSC2716_events (0.90s)
        --- PASS: TestImportHistoricalMessages/parallel/Unrecognised_prev_event_ID_will_throw_an_error (1.34s)
        --- PASS: TestImportHistoricalMessages/parallel/Duplicate_next_batch_id_on_insertion_event_will_be_rejected (1.94s)
        --- PASS: TestImportHistoricalMessages/parallel/Normal_users_aren't_allowed_to_batch_send_historical_messages (2.05s)
        --- PASS: TestImportHistoricalMessages/parallel/Unrecognised_batch_id_will_throw_an_error (2.06s)
        --- PASS: TestImportHistoricalMessages/parallel/Batch_send_endpoint_only_returns_state_events_that_we_passed_in_via_state_events_at_start (2.52s)
        --- PASS: TestImportHistoricalMessages/parallel/Should_be_able_to_send_a_batch_without_any_state_events_at_start_-_user_already_joined_in_the_current_room_state (2.79s)
        --- PASS: TestImportHistoricalMessages/parallel/Should_be_able_to_batch_send_historical_messages_into_private_room (3.07s)
        --- PASS: TestImportHistoricalMessages/parallel/Historical_events_from_multiple_users_in_the_same_batch (3.11s)
        --- PASS: TestImportHistoricalMessages/parallel/Historical_events_resolve_in_the_correct_order (3.57s)
        --- PASS: TestImportHistoricalMessages/parallel/should_resolve_member_state_events_for_historical_events (3.62s)
        --- PASS: TestImportHistoricalMessages/parallel/Historical_events_from_batch_send_do_not_come_down_in_an_incremental_sync (3.72s)
PASS
ok  	github.com/matrix-org/complement/tests	21.795s

[tulir]

It seems to always throw

AssertionError: Attempting to create a non-m.room.create event with no prev_events

Happened on 1.53, so I tested this branch and it worked, then I tried plain develop and it failed again

Maybe specific to event creation workers again? Did Complement ever get worker support?

[tulir]

Stack trace (I think this was from develop):

2022-02-28 22:09:26,425 - synapse.http.server - 100 - ERROR - POST-702 - Failed handle request via 'RoomBatchSendEventRestServlet': <XForwardedForRequest at 0x7f1cec068910 method='POST' uri='/_matrix/client/unstable/org.matrix.msc2716/rooms/%21luiLbOOYPPuupTkaHC:pc.mau.dev/batch_send?prev_event_id=$sOyl_xFS22jWSD0Tczo_fQ1c4aFc0vB809kYQj5tJ2c&user_id=@_tulir_whatsapp_<redacted>:pc.mau.dev&com.beeper.also_allow_user=@tulir:pc.mau.dev' clientproto='HTTP/1.1' site='8008'>
Traceback (most recent call last):
  File "synapse/http/server.py", line 269, in _async_render_wrapper
    callback_return = await self._async_render(request)
  File "synapse/http/server.py", line 471, in _async_render
    callback_return = await raw_callback_return
  File "synapse/rest/client/room_batch.py", line 148, in on_POST
    await self.room_batch_handler.persist_state_events_at_start(
  File "synapse/handlers/room_batch.py", line 240, in persist_state_events_at_start
    ) = await self.event_creation_handler.create_and_send_nonmember_event(
  File "synapse/handlers/message.py", line 857, in create_and_send_nonmember_event
    event, context = await self.create_event(
  File "synapse/handlers/message.py", line 611, in create_event
    event, context = await self.create_new_client_event(
  File "synapse/util/metrics.py", line 106, in measured_func
    r = await func(self, *args, **kwargs)
  File "synapse/handlers/message.py", line 977, in create_new_client_event
    assert (
AssertionError: Attempting to create a non-m.room.create event with no prev_events
2022-02-28 22:09:26,429 - synapse.access.http.8008 - 427 - INFO - POST-702 - 127.0.0.1 - 8008 - {@_tulir_whatsapp_<redacted>:pc.mau.dev} Processed request: 0.004sec/0.003sec (0.001sec, 0.000sec) (0.000sec/0.001sec/2) 55B 500 "POST /_matrix/client/unstable/org.matrix.msc2716/rooms/%21luiLbOOYPPuupTkaHC:pc.mau.dev/batch_send?prev_event_id=$sOyl_xFS22jWSD0Tczo_fQ1c4aFc0vB809kYQj5tJ2c&user_id=@_tulir_whatsapp_<redacted>:pc.mau.dev&com.beeper.also_allow_user=@tulir:pc.mau.dev HTTP/1.1" "mautrix-whatsapp/0.2.4+dev.3479e1cc mautrix-go/v0.10.11" [0 dbevts]

[tulir]

And of course a simple batch send with curl doesn't reproduce it, while the bridge does consistently on every attempt 🙃

[tulir]

Ah, I was able to reproduce it with curl by sending a non-member event in state_events_at_start. Happens on develop and 1.53.0, doesn't happen after merging this PR on top of develop. Doesn't happen on 1.52.0

Is non-member state events included in complement tests? I've stopped sending them from the bridge now (it only sent a dummy event as a workaround for #11188), but it should probably be tested (or rejected with a proper error, if it's not supposed to be allowed in state_events_at_start)

[MadLittleMods]

non-member event in state_events_at_start

😫 Ayee, that's one area I haven't really used yet.

Relevant code: synapse/handlers/room_batch.py#L232-L253

Feel free to create a separate issue to track this and will create a fix shortly.

[tulir]

Well the specific issue seems to go away with this PR. No idea why, but that's why I thought this was the fix. Anyway, I made #12110 for either adding tests or removing the branch.

[richvdh]

looks generally plausible to me, but I'm going to bump this over to @erikjohnston as I think he has more context here.

[richvdh]

was the previous omission of this a bug?

[richvdh]

(could we get rid of allow_no_prev_events and just allow there to be no prev events when state_event_ids is given?)

[MadLittleMods]

was the previous omission of this a bug?

Yes and seems to be why this PR fixes @tulir's issue, #12083 (comment)

(could we get rid of allow_no_prev_events and just allow there to be no prev events when state_event_ids is given?)

I'm leaning to no although technically yes probably.

The assertion nature of allow_no_prev_events disallowing the case for the majority of normal event sending cases is nice.

Also in our case, we only want the first event to have no prev_event_ids. The rest in the chain using state_event_ids should have prev_event_ids pointing at the event before it in the chain.

state_event_ids is really just used to derive auth_event_ids. Although I do see how they're related, auth_event_ids explicitly set by state_event_ids or derived from prev_event_ids in normal cases.

[erikjohnston]

For context: we see a fair few "can't create event with no prev events" errors already, so having an allow_no_prev_events flag should hopefully make it easier to reason about what is going on when investigating that issue.

[richvdh]

I think it's fine to keep it separate.

[erikjohnston]

(Side note: all these copies will be expensive for rooms with a lot of state, which will affect how quickly we can batch insert history.)

[MadLittleMods]

I'm not sure how exactly to side-step this.

state_event_ids is an ongoing list where we add to as we persist state_events_at_start. Then return the full list at the end.

And we state_event_ids.copy() to snapshot the state in the loop and pass it to the event creation functions. Otherwise, the signatures integrity checks go out of whack because we modified the list in place.

[MadLittleMods]

For reference on why we have to define state_event_ids here:

# Since each state event is marked as an outlier, the
# `EventContext.for_outlier()` won't have any `state_ids`
# set and therefore can't derive any state even though the
# prev_events are set. Also since the first event in the
# state chain is floating with no `prev_events`, it can't
# derive state from anywhere automatically. So we need to
# set some state explicitly.

[erikjohnston]

Ah. We probably don't actually want this behaviour, instead we want to only set the state for the insertion event and allow subsequent events to inherit the state from their prev event. When just sending messages this doesn't matter, but if we send state events in the batch then the current behaviour means that the state event won't become part of the state.

For example, if a user joins half way through the batch and they won't be able to send the message (assuming they weren't added as part of state_events_at_start).

I think its trivial to change, that we only set state_event_ids for the initial insertion event, i.e. when the prev_events are empty.

Or am I forgetting how this works yet again?

[MadLittleMods]

instead we want to only set the state for the insertion event and allow subsequent events to inherit the state from their prev event.

This is what currently is happening. And as far as I can tell, the comment explains it that way too.

For non-insertion events, we only use state_event_ids to derive auth_event_ids to set.

For insertion events, we set the state as state_event_ids

For example, if a user joins half way through the batch and they won't be able to send the message (assuming they weren't added as part of state_events_at_start).

It's not expected to have any state events in the batch of events (or at least processed to auth further messages). Any messages being sent should have m.room.member already in the state for that point in time where we are inserting at or added to state_events_at_start.

[erikjohnston]

I really don't know why I get confused about this every time. Ah well.

From the doc-comment:

We share the same state across the whole historical batch.

Ok, so I think is what is getting me. I think what you mean is that the state for the historical batch is all derived from the state at the insertion event? My reading of it was "all events in the batch have the same state", which is not true?

For non-insertion events, we only use state_event_ids to derive auth_event_ids to set.

Why do we need this for non-insertion events? Can't we just let the code derive it as normal from the state? That way the only special case is handling the insertion event.

It's not expected to have any state events in the batch of events (or at least processed to auth further messages). Any messages being sent should have m.room.member already in the state for that point in time where we are inserting at or added to state_events_at_start.

This means that the timeline will never see when a user joins/leaves, which may be fine for the Gitter use case, but we probably want to support it more generally than other use cases. I think we get this for free though, if we stop specifying the auth events directly.

[MadLittleMods]

Why do we need this for non-insertion events? Can't we just let the code derive it as normal from the state? That way the only special case is handling the insertion event.

Ahh, this does work and is a good simplification! Updated comments to be more nuanced here too ⏩

I also tried doing something similar for the state_events_at_start chain to avoid the copies but since each state event is an outlier which uses EventContext.for_outlier() and has no state_ids to derive from, we have to explicitly set the state for each and can't avoid it as far as I can tell. I also commented the code with these details.

Overall, more understanding of why things are the way they are from this prompt to change 👍

This means that the timeline will never see when a user joins/leaves, which may be fine for the Gitter use case, but we probably want to support it more generally than other use cases. I think we get this for free though, if we stop specifying the auth events directly.

The problem is that the events are persisted in reverse-chronological order so they have the correct stream_ordering while being backfilled which decrements.

As an example of why this fails, if we /batch_send -> events: [messageFromA, memberEventB, messageFromB], it will first try to persist messageFromB which will fail because memberEventB hasn't been processed yet.

[erikjohnston]

The problem is that the events are persisted in reverse-chronological order so they have the correct stream_ordering while being backfilled which decrements.

As an example of why this fails, if we /batch_send -> events: [messageFromA, memberEventB, messageFromB], it will first try to persist messageFromB which will fail because memberEventB hasn't been processed yet.

Oh yes, nyargh. I think we want to fix that, but not in this PR I guess. My hunch is that we want to try and persist the entire batch of events all in one go, rather than doing them one-by-one in reverse order.

[MadLittleMods]

For my own reference, here is a Complement test around adding state in the middle of the events batch (it fails for reason outlined above).

Complement test for "State in the middle of the events batch resolves for subsequent events"

t.Run("State in the middle of the events batch resolves for subsequent events", func(t *testing.T) {
	t.Parallel()

	roomID := as.CreateRoom(t, createPublicRoomOpts)
	alice.JoinRoom(t, roomID, nil)

	// Create the "live" event we are going to import our historical events next to
	eventIDsBefore := createMessagesInRoom(t, alice, roomID, 1, "eventIDsBefore")
	eventIdBefore := eventIDsBefore[0]
	timeAfterEventBefore := time.Now()

	events := createMessageEventsForBatchSendRequest([]string{virtualUserID}, timeAfterEventBefore, 1)

	// Add some events from Ricky who joined in the middle of the events batch
	virtualUserID2 := "@ricky:hs1"
	ensureVirtualUserRegistered(t, as, "ricky")
	events = append(
		events,
		createJoinStateEventsForBatchSendRequest([]string{virtualUserID2}, timeAfterEventBefore)...,
	)
	events = append(
		events,
		createMessageEventsForBatchSendRequest([]string{virtualUserID2}, timeAfterEventBefore, 1)...,
	)

	// Import a historical event
	batchSendHistoricalMessages(
		t,
		as,
		roomID,
		eventIdBefore,
		"",
		createJoinStateEventsForBatchSendRequest([]string{virtualUserID}, timeAfterEventBefore),
		events,
		// Status
		200,
	)
})

[MadLittleMods]

Thanks for the review @richvdh, @erikjohnston , and @tulir for trying it out 🦓