Sync current token may be ahead of event stream cache position using workers

[Fizzadar]

Based on my initial work investigating sync cache races in: #14154

Sync makes use of the event stream cache to determine whether a room has changed between the since & current tokens. This is then used to limit the number of rooms events are queried for in get_room_events_stream_for_rooms. After discovering the cache invalidation races above I added a quick log line for this: beeper/synapse@62497db (after beeper/synapse@5297155).

And it logs! Only a very small handful of occurrences over the last ~5 days and the position difference has so far been 1 every time. I suspect this may also occur against other stream caches but have not confirmed.

The worry here is if an event was sent within the gap it may be missed from an incremental sync which is especially bad because the user will never see or know about this event unless they re-init sync (or the client backfills it?).

One solution to this is to implement a waiting mechanism on StreamCache so a worker can wait for the cache to catch up with the current token for a given sync before fetching data. Because this is super rare and even when it happens it's a tiny position difference this would probably have negligable impact in sync performance and provide a shield against cache invalidation races over replication.

[Fizzadar]

Confirmed via the log change above, this is actually not that rare (😱). We have large bursts of these in sync workers:

Checking entity in DeviceInboxStreamChangeCache stream cache cache with
    current position 42696041 ahead of  the max stream cache position 42696040

There's even more in federation sender instances DeviceFederationOutboxStreamChangeCache, pretty much a constant flow of these:

Checking entity in DeviceFederationOutboxStreamChangeCache stream cache cache with
    current position 42696140 ahead of the max stream cache position 42696092

Finally the background work has a constant (1/s) flow of such errors on the _curr_state_delta_stream_cache cache, where in that case the cache often appears to be lagging significantly:

Checking entity in _curr_state_delta_stream_cache stream cache cache with
    current position 540123283 ahead of the max stream cache position 540123279

[Fizzadar]

Implemented wait-for fix option: #14269

[richvdh]

err, interesting. That doesn't sound good.

There's even more in federation sender instances DeviceFederationOutboxStreamChangeCache, pretty much a constant flow of these:

Checking entity in DeviceFederationOutboxStreamChangeCache stream cache cache with
    current position 42696140 ahead of the max stream cache position 42696092

This sounds very much like it could be the cause of #14251 and other device-list-tracking bugs we've been tearing our hair out over.

For those of us struggling to keep up at the back: are you able to explain the mechanics of this race? How does the "current position" come to be ahead of the "max stream cache position"?

I wasn't able to find where exactly you introduced these log lines - can you point me to a relevant diff?

[Fizzadar]

Diff for the logging code: #14239

Essentially it seems to boil down to:

• Something gets written to the database using a new token (get_next) out of an ID generator
• At that point, get_current_token will immediately point at that token
• But at that point the stream cache may not have yet been notified about the change, for one of two reasons:
  • no call to entity_has_changed is made after incrementing the token (only noticed this yesterday and made a provisional fix for events persisting in 9b5ef68), this would affect both workers and monlithic installs I believe
  • the replication lag time taken for the change to propagate from writer to other workers where they call entity_has_changed

Definitely seems likely this would trigger the device list issues as well.

[erikjohnston]

At that point, get_current_token will immediately point at that token

get_current_token should only return the new token when we've finished persisting that token (and it gets more complicated with multi-writer). So, as long as we poke the stream change cache at the same time as calling get_next (or advance in replication case) this should be fine.

I think part of the confusion here is that there is not a one-to-one mapping between stream caches and and stream ID generators. For example, the device inbox ID generator feeds into both DeviceInboxStreamChangeCache and DeviceFederationOutboxStreamChangeCache:

synapse/synapse/storage/databases/main/deviceinbox.py

Lines 688 to 698 in 8c94dd3

	async with self._device_inbox_id_gen.get_next() as stream_id:
	now_ms = self._clock.time_msec()
	await self.db_pool.runInteraction(
	"add_messages_to_device_inbox", add_messages_txn, now_ms, stream_id
	)
	for user_id in local_messages_by_user_then_device.keys():
	self._device_inbox_stream_cache.entity_has_changed(user_id, stream_id)
	for destination in remote_messages_by_destination.keys():
	self._device_federation_outbox_stream_cache.entity_has_changed(
	destination, stream_id
	)

So it's not unexpected if one xor the other stream change cache lags behind the current token.

---

Now, that's not to say there isn't a problem here. I'd be tempted for some of these stream caches to pass in the relevant stream ID generator, and then log if we are inserting a change with a lower stream ID than returned by get_current_token() (and maybe also get_current_token(instance_name) for multi writer streams). This may have some a false positive in process replication rows where we advance the ID gen and then update the stream change cache, e.g.:

synapse/synapse/storage/databases/main/deviceinbox.py

Lines 141 to 146 in 8c94dd3

	self._device_inbox_id_gen.advance(instance_name, token)
	for row in rows:
	if row.entity.startswith("@"):
	self._device_inbox_stream_cache.entity_has_changed(
	row.entity, token
	)

[Fizzadar]

I think I've been misunderstanding get_current_token - I was thinking it fetched it from the database but it's not it's the "known latest position" which is effectively the same as the waiting thing. Which makes this more confusing - how are we getting in a situation where the event ID generator has a token ahead of the events stream cache?

---

Re: device inbox I discovered this also where the two stream caches share one ID generator. My WIP PR #14286 addresses this by making sure both stream caches are always updated (to enable the waiting logic).