Draft: Test that `/messages` works on remote homeserver and can be backfilled properly after many batches (MSC2716) #214

MadLittleMods · 2021-10-19T07:00:12Z

Test that /messages works on remote homeserver and can be backfilled properly after many batches

Part of MSC2716: matrix-org/matrix-spec-proposals#2716

Related to #212

Used while developing matrix-org/synapse#11114

Dev notes

	logrus.WithFields(logrus.Fields{
		"stack": string(debug.Stack()),
	}).Error("destroy stack")

var firstEvent gjson.Result
var lastEvent gjson.Result
if len(eventsJson) > 0 {
	firstEvent = eventsJson[0]
	lastEvent = eventsJson[len(eventsJson)-1]
}
logrus.WithFields(logrus.Fields{
	"events":     len(eventsJson),
	"firstEvent": fmt.Sprintf("%s (%s)", firstEvent.Get("event_id"), firstEvent.Get("type")),
	"lastEvent":  fmt.Sprintf("%s (%s)", lastEvent.Get("event_id"), lastEvent.Get("type")),
	"start":      gjson.GetBytes(messsageResBody, "start").Str,
	"end":        gjson.GetBytes(messsageResBody, "end").Str,
}).Error("Number of events from `/messages`")

tests/msc2716_test.go

internal/client/client.go

tests/msc2716_test.go

MadLittleMods · 2021-11-03T07:50:13Z

tests/msc2716_test.go

+	}
+
+	for {
+		if time.Since(start) > 200*c.SyncUntilTimeout {


This timeout is currently very large to accommodate the long ~20s /messages durations. We also have to make that request 11 times during the test which adds up very fast.

Synapse really has to chug for those requests 👹 and ideally wouldn't have to modify this at all.

I would need to look into optimizing Synapse to make this fast which we should probably do anyway as this is painfully slow.

This is currently set to a whopping 1000s by default

complement/internal/docker/deployment.go

Line 57 in 136fd60

SyncUntilTimeout: 5 * time.Second,

which seems excessive even given this.

@kegsay Sorry this wasn't clear as undrafting indicates "marked this pull request as ready for review" but I didn't assign you this one yet specifically because of this problem.

The test itself is good to go (timeout can be switched to normal and numBatches could be switched back to 11) and shipped but want to make it actually acceptable time-wise to run against Synapse before merging.

I used numBatches=2 during testing because it's much faster to see results while developing.

Thanks for the review pass though and I'll fix up these other spots ⏩

@MadLittleMods what is the status of this PR? It's still marked as a Draft.

#214 (comment)

Status is still the same as the last update in this thread. It's too slow on Synapse for me to be comfortable merging it yet.

In terms of optimizing Synapse to make this test viable to run time-wise, I'm a bit blocked on a race condition in some recent code, matrix-org/synapse#12394 (comment) -> matrix-org/synapse#12646

In terms of optimizing Synapse to make this test viable to run time-wise, I'm a bit blocked on a race condition in some recent code, matrix-org/synapse#12394 (comment) -> matrix-org/synapse#12646

Now matrix-org/synapse#12988 I think

Made progress on optimizing Synapse:

Saves 10s per /messages call: Fix have_seen_event cache not being invalidated synapse#13863

Still need to figure out Optimize backfill receiving to have less missing prev_event thrashing (scratch) synapse#13864

internal/client/client.go

kegsay · 2021-11-10T12:25:39Z

tests/msc2716_test.go

+			// could pick for other homeserver implementations so I just did 10+1 to
+			// make sure it also worked in that case.
+			//numBatches := 11
+			numBatches := 2


Lovely comment but then you seem to use 2. Why?

See:

I used numBatches=2 during testing because it's much faster to see results while developing.

#214 (comment)

Running this test against Synapse is extremely slow atm, #214 (comment)

TODO: Reminder to revert this to 11 before merge

tests/msc2716_test.go

kegsay · 2021-11-10T12:28:49Z

tests/msc2716_test.go

+			}
+
+			// Make sure we see the events at the very start of the message history
+			expectedEventIDs = append(expectedEventIDs, eventIDsBefore...)


So this is new -> old?

The order doesn't matter because it's just a list of expected ID's, expectedEventIDs

We also just use it in check off function (paginateUntilMessageCheckOff) which doesn't care about the order.

There is a similar variable in another test where order does matter but we call it expectedEventIDOrder

kegsay · 2021-11-10T12:35:09Z

tests/msc2716_test.go

+	}
+
+	for {
+		if time.Since(start) > 200*c.SyncUntilTimeout {


This is currently set to a whopping 1000s by default

complement/internal/docker/deployment.go

Line 57 in 136fd60

SyncUntilTimeout: 5 * time.Second,

which seems excessive even given this.

tests/msc2716_test.go

kegsay · 2021-11-10T12:38:22Z

tests/msc2716_test.go

+			actualEventIDList = append(actualEventIDList, eventID)
+
+			if _, keyExists := workingExpectedEventIDMap[eventID]; keyExists {
+				delete(workingExpectedEventIDMap, eventID)


So this function doesn't actually check the events are in the correct order, just that they exist?

Correct, just a checkoff function

kegsay · 2021-11-10T12:40:53Z

tests/msc2716_test.go

+		if !keyRes.Exists() {
+			t.Fatalf("missing key '%s'", wantKey)
+		}
+		if !keyRes.IsArray() {


Why not use JSONArrayEach?

complement/internal/match/json.go

Line 164 in 136fd60

func JSONArrayEach(wantKey string, fn func(gjson.Result) error) JSON {

It does these checks for you.

IIRC, I think it was because we can't break early with JSONArrayEach (can only break early if you throw an error which fails the test). JSONArrayEach could be refactored to have the item function return keepGoing, err but rather do that in another PR since it touches so many other tests.

Is the early return really a deal breaker? I don't think it'll affect runtime performance that much?

Updated to re-use JSONArrayEach. It's not so bad ⏩

See #214 (comment)

…till-works-with-many-batches

…ugging Split off from #214

tests/msc2716_test.go

…till-works-with-many-batches Conflicts: tests/msc2716_test.go

…ugging (#251) Split off from #214

…till-works-with-many-batches Conflicts: tests/msc2716_test.go

…ll-works-with-many-batches

kegsay · 2022-05-11T09:27:42Z

@MadLittleMods what is the status of this PR? It's still marked as a Draft.

tests/msc2716_test.go

Also includes `paginateUntilMessageCheckOff` from #214

…ll-works-with-many-batches

From #214 (comment)

Synapse changes: matrix-org/synapse#12718 Part of MSC2716: matrix-org/matrix-spec-proposals#2716 We're testing to make sure historical messages show up for a remote federated homeserver even when the homeserver is missing the part of the timeline where the marker events were sent and it paginates before they occurred to see if the history is available. Making sure the homeserver processes all of the markers from the current state instead of just when it sees them in the timeline. Sending marker events as state now so they are always able to be seen by homeservers (not lost in some timeline gap). Marker events should be sent with a unique `state_key` so that they can all resolve in the current state to easily be discovered. - If we re-use the same `state_key` (like `""`), then we would have to fetch previous snapshots of state up through time to find all of the marker events. This way we can avoid all of that. - Also avoids state resolution conflicts where only one of the marker events win As a homeserver, when we see new marker state, we know there is new history imported somewhere back in time and should process it to fetch the insertion event where the historical messages are and set it as an insertion extremity. This way we know where to backfill more messages when someone asks for scrollback. Also includes `paginateUntilMessageCheckOff` from #214

…ll-works-with-many-batches Conflicts: tests/msc2716_test.go

kegsay · 2022-09-20T09:31:15Z

Marked as stale; this PR will be closed in 7 days if there isn't any further progress. Please re-open when you get time. Long-lived branches are fine, but long-lived PRs like this always being in Draft is not fine.

…ll-works-with-many-batches

Fix #13856 Fix #13865 > Discovered while trying to make Synapse fast enough for [this MSC2716 test for importing many batches](matrix-org/complement#214 (comment)). As an example, disabling the `have_seen_event` cache saves 10 seconds for each `/messages` request in that MSC2716 Complement test because we're not making as many federation requests for `/state` (speeding up `have_seen_event` itself is related to #13625) > > But this will also make `/messages` faster in general so we can include it in the [faster `/messages` milestone](https://github.com/matrix-org/synapse/milestone/11). > > *-- #13856 ### The problem `_invalidate_caches_for_event` doesn't run in monolith mode which means we never even tried to clear the `have_seen_event` and other caches. And even in worker mode, it only runs on the workers, not the master (AFAICT). Additionally there was bug with the key being wrong so `_invalidate_caches_for_event` never invalidates the `have_seen_event` cache even when it does run. Because we were using the `@cachedList` wrong, it was putting items in the cache under keys like `((room_id, event_id),)` with a `set` in a `set` (ex. `(('!TnCIJPKzdQdUlIyXdQ:test', '$Iu0eqEBN7qcyF1S9B3oNB3I91v2o5YOgRNPwi_78s-k'),)`) and we we're trying to invalidate with just `(room_id, event_id)` which did nothing.

Split out from #214

MadLittleMods · 2022-10-04T23:20:51Z

tests/msc2716_test.go

+		// Since this will throw an error if they key does not exist,
+		// do this at the end of the loop. It's a valid scenario to be at the end
+		// of the room and have no more to paginate so we want the `return` when
+		// we've found all of the expected events to have a chance to run first.
+		messageResEnd = client.GetJSONFieldStr(t, messsageResBody, "end")


Split out to #489

…#489) As spec'd: > If no further events are available (either because we have reached the start of the timeline, or because the user does not have permission to see any more events), this property is omitted from the response. > > *-- https://spec.matrix.org/v1.1/client-server-api/#get_matrixclientv3roomsroomidmessages* Split out from #214 Previously, it would throw the following error and potentially we found all of the events within that last response to satisfy everything, ``` JSONFieldStr: key 'end' missing ```

Test that /messages can be backfilled properly after many batches

8099f47

MadLittleMods marked this pull request as draft October 19, 2021 07:00

MadLittleMods changed the title ~~Draft: Test that /messages works on remote homeserver and can be backfilled properly after many batches~~ Draft: Test that /messages works on remote homeserver and can be backfilled properly after many batches (MSC2716) Oct 20, 2021

Add message suffix to better distinguish messages

094c5f7

MadLittleMods mentioned this pull request Oct 21, 2021

Fix historical messages backfilling in random order on remote homeservers (MSC2716) matrix-org/synapse#11114

Merged

11 tasks

MadLittleMods commented Oct 28, 2021

View reviewed changes

tests/msc2716_test.go Outdated Show resolved Hide resolved

v4 room version

e30bcd4

MadLittleMods commented Nov 2, 2021

View reviewed changes

tests/msc2716_test.go Outdated Show resolved Hide resolved

MadLittleMods mentioned this pull request Nov 2, 2021

Ensure many batches are able to be imported (MSC2716) #212

Closed

MadLittleMods commented Nov 3, 2021

View reviewed changes

internal/client/client.go Outdated Show resolved Hide resolved

Make sure marker event is sent

1e333d6

MadLittleMods commented Nov 3, 2021

View reviewed changes

tests/msc2716_test.go Outdated Show resolved Hide resolved

Cleanup tests

2022b31

MadLittleMods commented Nov 3, 2021

View reviewed changes

Some test cleanup and comments

d325349

MadLittleMods changed the title ~~Draft: Test that /messages works on remote homeserver and can be backfilled properly after many batches (MSC2716)~~ Test that /messages works on remote homeserver and can be backfilled properly after many batches (MSC2716) Nov 3, 2021

MadLittleMods marked this pull request as ready for review November 3, 2021 07:53

MadLittleMods mentioned this pull request Nov 5, 2021

Allow events to be created with no prev_events (MSC2716) matrix-org/synapse#11243

Merged

4 tasks

kegsay approved these changes Nov 10, 2021

View reviewed changes

MadLittleMods changed the title ~~Test that /messages works on remote homeserver and can be backfilled properly after many batches (MSC2716)~~ Draft: Test that /messages works on remote homeserver and can be backfilled properly after many batches (MSC2716) Nov 10, 2021

MadLittleMods marked this pull request as draft November 11, 2021 01:12

MadLittleMods added 4 commits November 10, 2021 19:32

Delays not needed for test servers (get result ASAP)

2fe5180

See #214 (comment)

Fix typo

0604564

Merge branch 'master' into madlittlemods/test-backfill-and-messages-s…

83adbe2

…till-works-with-many-batches

Fix missing params after merge

4aba836

This was referenced Dec 2, 2021

Send marker events in all federation tests (MSC2716) #248

Merged

Add request query parameters to Complement request debug logs #250

Merged

MadLittleMods added a commit that referenced this pull request Dec 2, 2021

Add messageSuffix to more easily spot which message is which when deb…

959c3bb

…ugging Split off from #214

MadLittleMods mentioned this pull request Dec 2, 2021

Add messageSuffix to more easily spot which message is which when debugging (MSC2716) #251

Merged

MadLittleMods commented Dec 2, 2021

View reviewed changes

tests/msc2716_test.go Outdated Show resolved Hide resolved

Merge branch 'master' into madlittlemods/test-backfill-and-messages-s…

9b90429

…till-works-with-many-batches Conflicts: tests/msc2716_test.go

MadLittleMods added a commit that referenced this pull request Jan 13, 2022

Add messageSuffix to more easily spot which message is which when deb…

b638ca2

…ugging (#251) Split off from #214

MadLittleMods added 2 commits January 12, 2022 21:30

Merge branch 'master' into madlittlemods/test-backfill-and-messages-s…

677836b

…till-works-with-many-batches Conflicts: tests/msc2716_test.go

Merge branch 'main' into madlittlemods/test-backfill-and-messages-sti…

85eb7bd

…ll-works-with-many-batches

MadLittleMods commented May 12, 2022

View reviewed changes

tests/msc2716_test.go Outdated Show resolved Hide resolved

MadLittleMods added a commit that referenced this pull request May 12, 2022

Add test for multiple marker state

3b3d383

Also includes `paginateUntilMessageCheckOff` from #214

MadLittleMods mentioned this pull request May 12, 2022

Marker events as state - MSC2716 #371

Merged

Merge branch 'main' into madlittlemods/test-backfill-and-messages-sti…

3532821

…ll-works-with-many-batches

This was referenced May 13, 2022

Resync state after partial-state join matrix-org/synapse#12394

Merged

MSC2716 leftover todo tasks matrix-org/synapse#10737

Closed

MadLittleMods added a commit that referenced this pull request May 20, 2022

Remove vestigial timeout from testing in another PR

73c78cf

From #214 (comment)

Merge branch 'main' into madlittlemods/test-backfill-and-messages-sti…

1667e15

…ll-works-with-many-batches Conflicts: tests/msc2716_test.go

kegsay added the stale This issue or PR is old and may be closed soon label Sep 20, 2022

MadLittleMods added 2 commits September 20, 2022 17:41

Merge branch 'main' into madlittlemods/test-backfill-and-messages-sti…

0589546

…ll-works-with-many-batches

Update test name

606197a

MadLittleMods added 2 commits September 29, 2022 03:46

Changes and debugging

d679384

Mulitply timeout by the number of requests we expect

230c46e

MadLittleMods mentioned this pull request Sep 30, 2022

Optimize backfill receiving to have less missing prev_event thrashing (v2) matrix-org/synapse#13970

Closed

5 tasks

MadLittleMods added a commit that referenced this pull request Oct 4, 2022

Be tolerant of the the end key not existing in a /messages resposne

96d0a03

Split out from #214

MadLittleMods mentioned this pull request Oct 4, 2022

Be tolerant of the the end key not existing in a /messages response #489

Merged

MadLittleMods commented Oct 4, 2022

View reviewed changes

kegsay closed this Nov 18, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Draft: Test that `/messages` works on remote homeserver and can be backfilled properly after many batches (MSC2716) #214

Draft: Test that `/messages` works on remote homeserver and can be backfilled properly after many batches (MSC2716) #214

MadLittleMods commented Oct 19, 2021 •

edited

Loading

MadLittleMods Nov 3, 2021

kegsay Nov 10, 2021

MadLittleMods Nov 10, 2021 •

edited

Loading

MadLittleMods May 11, 2022 •

edited

Loading

MadLittleMods May 23, 2022 •

edited

Loading

richvdh Jun 9, 2022

MadLittleMods Sep 23, 2022

kegsay Nov 10, 2021

MadLittleMods Nov 11, 2021 •

edited

Loading

kegsay Nov 10, 2021

MadLittleMods Nov 11, 2021

kegsay Nov 10, 2021

kegsay Nov 10, 2021

MadLittleMods Nov 11, 2021

kegsay Nov 10, 2021

MadLittleMods Nov 11, 2021 •

edited

Loading

kegsay Dec 1, 2021

MadLittleMods Dec 2, 2021

kegsay commented May 11, 2022

kegsay commented Sep 20, 2022

MadLittleMods Oct 4, 2022

Draft: Test that /messages works on remote homeserver and can be backfilled properly after many batches (MSC2716) #214

Draft: Test that /messages works on remote homeserver and can be backfilled properly after many batches (MSC2716) #214

Conversation

MadLittleMods commented Oct 19, 2021 • edited Loading

Dev notes

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MadLittleMods Nov 10, 2021 • edited Loading

Choose a reason for hiding this comment

MadLittleMods May 11, 2022 • edited Loading

Choose a reason for hiding this comment

MadLittleMods May 23, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MadLittleMods Nov 11, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MadLittleMods Nov 11, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kegsay commented May 11, 2022

kegsay commented Sep 20, 2022

Choose a reason for hiding this comment

Draft: Test that `/messages` works on remote homeserver and can be backfilled properly after many batches (MSC2716) #214

Draft: Test that `/messages` works on remote homeserver and can be backfilled properly after many batches (MSC2716) #214

MadLittleMods commented Oct 19, 2021 •

edited

Loading

MadLittleMods Nov 10, 2021 •

edited

Loading

MadLittleMods May 11, 2022 •

edited

Loading

MadLittleMods May 23, 2022 •

edited

Loading

MadLittleMods Nov 11, 2021 •

edited

Loading

MadLittleMods Nov 11, 2021 •

edited

Loading