Unhandled `get_state_ids_for_events` exception preventing sync

[begincalendar]

Description

Matrix clients can't sync after authenticating.

Steps to reproduce

I recently made some changes to the Docker (compose) networking setup surrounding my homeserver, but I don't know if that was a coincidence.

Everything seemed fine, but in one of my encrypted DMs I saw a Megolm decryption error when trying to send a message via Element (iOS). That seemed to be caused by 403 responses from the homeserver (I didn't dig into it at the time).

I tried to authenticate as the user on the receiving end of those DMs and that's when I discovered this issue.

I then logged out of another account and tried to reauthenticate, hitting the same issue.

Homeserver

A private personal homeserver

Synapse Version

1.128.0

Installation Method

Docker (matrixdotorg/synapse)

Database

Single Postgresql v16.0 instance

Workers

Single process

Platform

Docker container on Ubuntu 20.04

Configuration

No response

Relevant log output

2025-04-14T21:39:59.012499950Z 2025-04-14 21:39:59,011 - synapse.http.server - 146 - ERROR - GET-10662 - Failed handle request via 'SyncRestServlet': <XForwardedForRequest at 0x7f046fb382c0 method='GET' uri='/_matrix/client/v3/sync?filter=2&timeout=0&org.matrix.msc4222.use_state_after=true&set_presence=online&_cacheBuster=1744666798938' clientproto='HTTP/1.0' site='80'>
2025-04-14T21:39:59.012519773Z Traceback (most recent call last):
2025-04-14T21:39:59.012526194Z   File "/usr/local/lib/python3.12/site-packages/synapse/http/server.py", line 332, in _async_render_wrapper
2025-04-14T21:39:59.012530869Z     callback_return = await self._async_render(request)
2025-04-14T21:39:59.012535181Z   File "/usr/local/lib/python3.12/site-packages/synapse/http/server.py", line 544, in _async_render
2025-04-14T21:39:59.012539758Z     callback_return = await raw_callback_return
2025-04-14T21:39:59.012543865Z   File "/usr/local/lib/python3.12/site-packages/synapse/rest/client/sync.py", line 266, in on_GET
2025-04-14T21:39:59.012548304Z     sync_result = await self.sync_handler.wait_for_sync_for_user(
2025-04-14T21:39:59.012552371Z   File "/usr/local/lib/python3.12/site-packages/synapse/handlers/sync.py", line 440, in wait_for_sync_for_user
2025-04-14T21:39:59.012556575Z     res = await self.response_cache.wrap(
2025-04-14T21:39:59.012560395Z   File "/usr/local/lib/python3.12/site-packages/synapse/util/caches/response_cache.py", line 284, in wrap
2025-04-14T21:39:59.012564465Z     return await make_deferred_yieldable(result)
2025-04-14T21:39:59.012568124Z   File "/usr/local/lib/python3.12/site-packages/twisted/internet/defer.py", line 2010, in _inlineCallbacks
2025-04-14T21:39:59.012572136Z     result = context.run(
2025-04-14T21:39:59.012576252Z   File "/usr/local/lib/python3.12/site-packages/twisted/python/failure.py", line 549, in throwExceptionIntoGenerator
2025-04-14T21:39:59.012583877Z     return g.throw(self.value.with_traceback(self.tb))
2025-04-14T21:39:59.012587992Z   File "/usr/local/lib/python3.12/site-packages/synapse/util/caches/response_cache.py", line 265, in cb
2025-04-14T21:39:59.012593001Z     return await callback(*args, **kwargs)
2025-04-14T21:39:59.012602278Z   File "/usr/local/lib/python3.12/site-packages/synapse/handlers/sync.py", line 578, in _wait_for_sync_for_user
2025-04-14T21:39:59.012606354Z     ] = await self.current_sync_for_user(
2025-04-14T21:39:59.012610301Z   File "/usr/local/lib/python3.12/site-packages/synapse/handlers/sync.py", line 676, in current_sync_for_user
2025-04-14T21:39:59.012614262Z     ] = await self.generate_sync_result(
2025-04-14T21:39:59.012618077Z   File "/usr/local/lib/python3.12/site-packages/synapse/handlers/sync.py", line 1868, in generate_sync_result
2025-04-14T21:39:59.012622706Z     ) = await self._generate_sync_entry_for_rooms(sync_result_builder)
2025-04-14T21:39:59.012626670Z   File "/usr/local/lib/python3.12/site-packages/synapse/handlers/sync.py", line 2478, in _generate_sync_entry_for_rooms
2025-04-14T21:39:59.012630879Z     await concurrently_execute(handle_room_entries, room_entries, 10)
2025-04-14T21:39:59.012634780Z   File "/usr/local/lib/python3.12/site-packages/synapse/util/async_helpers.py", line 258, in concurrently_execute
2025-04-14T21:39:59.012638668Z     await yieldable_gather_results(
2025-04-14T21:39:59.012642601Z   File "/usr/local/lib/python3.12/site-packages/synapse/util/async_helpers.py", line 307, in yieldable_gather_results
2025-04-14T21:39:59.012654608Z     raise dfe.subFailure.value from None
2025-04-14T21:39:59.012658570Z   File "/usr/local/lib/python3.12/site-packages/twisted/internet/defer.py", line 2014, in _inlineCallbacks
2025-04-14T21:39:59.012662473Z     result = context.run(gen.send, result)
2025-04-14T21:39:59.012666296Z   File "/usr/local/lib/python3.12/site-packages/synapse/util/async_helpers.py", line 244, in _concurrently_execute_inner
2025-04-14T21:39:59.012671119Z     await maybe_awaitable(func(value))
2025-04-14T21:39:59.012676354Z   File "/usr/local/lib/python3.12/site-packages/synapse/handlers/sync.py", line 2467, in handle_room_entries
2025-04-14T21:39:59.012680444Z     await self._generate_room_entry(
2025-04-14T21:39:59.012684163Z   File "/usr/local/lib/python3.12/site-packages/synapse/handlers/sync.py", line 2978, in _generate_room_entry
2025-04-14T21:39:59.012687951Z     state = await self.compute_state_delta(
2025-04-14T21:39:59.012691639Z   File "/usr/local/lib/python3.12/site-packages/synapse/handlers/sync.py", line 1234, in compute_state_delta
2025-04-14T21:39:59.012695471Z     state_ids = await self._compute_state_delta_for_full_sync(
2025-04-14T21:39:59.012699271Z   File "/usr/local/lib/python3.12/site-packages/synapse/handlers/sync.py", line 1441, in _compute_state_delta_for_full_sync
2025-04-14T21:39:59.012703376Z     state_at_timeline_end = await self._state_storage_controller.get_state_ids_at(
2025-04-14T21:39:59.012707135Z   File "/usr/local/lib/python3.12/site-packages/synapse/storage/controllers/state.py", line 457, in get_state_ids_at
2025-04-14T21:39:59.012710834Z     state = await self.get_state_after_event(
2025-04-14T21:39:59.012714575Z   File "/usr/local/lib/python3.12/site-packages/synapse/storage/controllers/state.py", line 402, in get_state_after_event
2025-04-14T21:39:59.012719848Z     state_ids = await self.get_state_ids_for_event(
2025-04-14T21:39:59.012723572Z   File "/usr/local/lib/python3.12/site-packages/synapse/logging/opentracing.py", line 922, in _wrapper
2025-04-14T21:39:59.012728319Z     return await func(*args, **kwargs)
2025-04-14T21:39:59.012733656Z   File "/usr/local/lib/python3.12/site-packages/synapse/logging/opentracing.py", line 922, in _wrapper
2025-04-14T21:39:59.012737545Z     return await func(*args, **kwargs)
2025-04-14T21:39:59.012742522Z   File "/usr/local/lib/python3.12/site-packages/synapse/storage/controllers/state.py", line 376, in get_state_ids_for_event
2025-04-14T21:39:59.012746441Z     state_map = await self.get_state_ids_for_events(
2025-04-14T21:39:59.012750238Z   File "/usr/local/lib/python3.12/site-packages/synapse/logging/opentracing.py", line 922, in _wrapper
2025-04-14T21:39:59.012754314Z     return await func(*args, **kwargs)
2025-04-14T21:39:59.012758221Z   File "/usr/local/lib/python3.12/site-packages/synapse/logging/opentracing.py", line 922, in _wrapper
2025-04-14T21:39:59.012765047Z     return await func(*args, **kwargs)
2025-04-14T21:39:59.012768730Z   File "/usr/local/lib/python3.12/site-packages/synapse/storage/controllers/state.py", line 321, in get_state_ids_for_events
2025-04-14T21:39:59.012772649Z     return {event: event_to_state[event] for event in event_ids}
2025-04-14T21:39:59.012776448Z KeyError: '$REDACTED-REDACTED'

Anything else that would be useful to know?

No response

[begincalendar]

When the exception occurs here, this what my debug log shows each relevant variable is:

event_ids=['$REDACTED-REDACTED'], event_to_state={}, event_to_groups={}

I wondered how this is possible, given this check, but then I noticed this caching mechanism.

So perhaps there is a stale cache issue here?

[begincalendar]

I can see the relevant state event has no record in the events_json table. That's probably abnormal, right? So a borked state event is causing this exception. The exception-raising code is probably OK then, but it would be nice to avoid getting in this situation.

[begincalendar]

Haven't been able to reproduce this after manually cleaning out the borked event. Doesn't seem worth pursuing at this point, so closing.