Exception: Attempting to state-resolve for room

[brandoncurtis]

Description

I have a long-running instance of Synapse that I've upgraded from the 0.1X days. Lately it has encountered an issue that makes it impossible to log in and renders the chat server unusable.

Steps to reproduce

• start up synapse
• do nothing; errors will appear in the log every five minutes
• try to log in; sync will fail and errors will appear in the log

Version information

• synapse v1.8.0
• installed with pipenv
• Ubuntu 18.04 in a VPS
• PostgreSQL db

Logs

(I'm using less -S to chop the excessively long lines)

2020-02-02 22:19:46,929 - synapse.access.https.8448 - 233 - INFO - PUT-335615- - - 8448 - Received request: PUT /_matrix/federation/v1/send/1580491672961/
2020-02-02 22:19:46,932 - synapse.federation.transport.server - 154 - INFO - PUT-335615- Request from matrix.org
2020-02-02 22:19:46,933 - synapse.federation.transport.server - 389 - INFO - PUT-335615- Received txn 1580491672961 from matrix.org. (PDUs: 0, EDUs: 1)
2020-02-02 22:19:46,947 - synapse.access.https.8448 - 302 - INFO - PUT-335615- - - 8448 - {matrix.org} Processed request: 0.017sec/0.000sec (0.008sec, 0.001sec) (0.003sec/0.008sec/5) 12B 200 "PUT /_matrix/federa
2020-02-02 22:19:47,075 - twisted - 172 - INFO - - Timing out client: IPv4Address(type='TCP', host='178.62.203.121', port=59918)
2020-02-02 22:19:49,022 - synapse.storage.TIME - 308 - INFO - - Total database time: 0.495% {add_device_change_to_streams(1): 0.254%, insert_linearized_receipt(1): 0.034%, set_received_txn_response(3): 0.031%}
2020-02-02 22:19:58,857 - synapse.storage.data_stores.main - 434 - INFO - generate_user_daily_visits-4358- Calling _generate_user_daily_visits
2020-02-02 22:19:58,945 - synapse.handlers.presence - 260 - INFO - persist_presence_changes-21793- Persisting 1 unpersisted presence updates
2020-02-02 22:19:59,021 - synapse.storage.TIME - 308 - INFO - - Total database time: 0.237% {get_latest_event_ids_and_hashes_in_room(1): 0.130%, _prune_old_user_ips(2): 0.028%, generate_user_daily_visits(1): 0.0
2020-02-02 22:19:59,837 - synapse.state - 495 - INFO - send_dummy_events_to_fill_extremities-4358- Resolving state for !cURbafjkfsMDVwdRDQ:matrix.org with 10 groups
2020-02-02 22:19:59,848 - synapse.state - 518 - INFO - send_dummy_events_to_fill_extremities-4358- Resolving conflicted state for '!cURbafjkfsMDVwdRDQ:matrix.org'
2020-02-02 22:20:00,059 - synapse.state.v1 - 79 - INFO - send_dummy_events_to_fill_extremities-4358- Asking for 9314/9314 conflicted events
2020-02-02 22:20:00,223 - synapse.metrics.background_process_metrics - 214 - ERROR - send_dummy_events_to_fill_extremities-4358- Background process 'send_dummy_events_to_fill_extremities' threw an exception
Traceback (most recent call last):
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {'$152231757428408OhOMC:matrix.org': {'event_id': '$152231757428408OhOMC:matrix.org', 'internal_metadata': '{"outlier":false,"stream_ordering":241758}', 'json': '{"auth_events":[["$1476538353540jx

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {'$15225858852051882xOqlo:matrix.org': _EventCacheEntry(event=<FrozenEvent event_id='$15225858852051882xOqlo:matrix.org', type='m.room.member', state_key='@freenode_belcher_:matrix.org'>, redacted

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {'$152029026420834dvIdM:tchncs.de': _EventCacheEntry(event=<FrozenEvent event_id='$152029026420834dvIdM:tchncs.de', type='m.room.member', state_key='@Milan:tchncs.de'>, redacted_event=None), '$154

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks

    result = g.send(result)
StopIteration: [<FrozenEvent event_id='$152029026420834dvIdM:tchncs.de', type='m.room.member', state_key='@Milan:tchncs.de'>, <FrozenEvent event_id='$1547639497149427qUwtd:matrix.org', type='m.room.member', stat

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {'$152029026420834dvIdM:tchncs.de': <FrozenEvent event_id='$152029026420834dvIdM:tchncs.de', type='m.room.member', state_key='@Milan:tchncs.de'>, '$1547639497149427qUwtd:matrix.org': <FrozenEvent 

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/synapse/metrics/background_process_metrics.py", line 212, in run
    return (yield result)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/synapse/handlers/message.py", line 1049, in _send_dummy_events_to_fill_extremities
    room_id, latest_event_ids=latest_event_ids
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/synapse/state/__init__.py", line 192, in get_current_users_in_room
    entry = yield self.resolve_state_groups_for_events(room_id, latest_event_ids)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/synapse/util/metrics.py", line 82, in measured_func
    r = yield func(self, *args, **kwargs)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/synapse/state/__init__.py", line 402, in resolve_state_groups_for_events
    state_res_store=StateResolutionStore(self.store),
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/synapse/state/__init__.py", line 525, in resolve_state_groups
    state_res_store=state_res_store,
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/home/brandon/repo/synapse/.venv/lib/python3.6/site-packages/synapse/state/v1.py", line 93, in resolve_events_with_store
    % (room_id, event.event_id, event.room_id,)
Exception: Attempting to state-resolve for room !cURbafjkfsMDVwdRDQ:matrix.org with event $15038575082050669IRCkf:matrix.org which is in !xPRJVyOhRymgpkarYZ:matrix.org

[richvdh]

yes, !cURbafjkfsMDVwdRDQ:matrix.org is broken thanks to some old events which shouldn't have been accepted. #6524 added some sanity checks which are now failing.

You can probably patch up your database with something like:

DELETE FROM state_groups_state sgs USING events e 
WHERE e.event_id=sgs.event_id AND e.room_id != sgs.room_id 
AND sgs.room_id= '!cURbafjkfsMDVwdRDQ:matrix.org';

(you may then need to restart synapse to flush the cache.)

[brandoncurtis]

That worked! Thanks!