Synapse doesn't recongnize a user is in a room

[tleydxdy]

Description

User joins a room, timesout, the room never shows up (waited for weeks) for the user, the user is in the room according to other HSs.

Steps to reproduce

Error log:

[many more timeout]
2018-08-05 21:22:23,156 - synapse.crypto.keyclient - 55 - ERROR - POST-410614- User timeout caused connection failure.
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/synapse/crypto/keyclient.py", line 46, in fetch_server_key
    protocol = yield endpoint.connect(factory)
TimeoutError: User timeout caused connection failure.
2018-08-05 21:22:53,159 - synapse.crypto.keyclient - 55 - ERROR - POST-410614- User timeout caused connection failure.
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/synapse/crypto/keyclient.py", line 46, in fetch_server_key
    protocol = yield endpoint.connect(factory)
TimeoutError: User timeout caused connection failure.
2018-08-05 21:22:59,117 - synapse.storage.room - 215 - ERROR - POST-410614- store_room with room_id=!UcYsUzyxTGDxLBEvLz:matrix.org failed: duplicate key value violates unique constraint "rooms_pkey"
DETAIL:  Key (room_id)=(!UcYsUzyxTGDxLBEvLz:matrix.org) already exists.

2018-08-05 21:23:31,661 - synapse.storage.events - 191 - ERROR - None- IntegrityError, retrying.
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/synapse/storage/events.py", line 189, in f
    res = yield func(self, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/synapse/storage/events.py", line 443, in _persist_events
    new_forward_extremeties=new_forward_extremeties,
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/synapse/storage/_base.py", line 318, in runInteraction
    *args, **kwargs
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/synapse/storage/_base.py", line 368, in runWithConnection
    inner_func, *args, **kwargs
  File "/usr/lib/python2.7/dist-packages/twisted/python/threadpool.py", line 246, in inContext
    result = inContext.theWork()
  File "/usr/lib/python2.7/dist-packages/twisted/python/threadpool.py", line 262, in <lambda>
    inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
  File "/usr/lib/python2.7/dist-packages/twisted/enterprise/adbapi.py", line 307, in _runWithConnection
    compat.reraise(excValue, excTraceback)
  File "/usr/lib/python2.7/dist-packages/twisted/enterprise/adbapi.py", line 298, in _runWithConnection
    result = func(conn, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/synapse/storage/_base.py", line 364, in inner_func
    return func(conn, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/synapse/storage/_base.py", line 245, in _new_transaction
    r = func(txn, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/synapse/util/logutils.py", line 82, in wrapped
    return f(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/synapse/storage/events.py", line 756, in _persist_events_txn
    backfilled=backfilled,
  File "/usr/lib/python2.7/dist-packages/synapse/storage/events.py", line 1250, in _update_metadata_tables_txn
    txn, [event for event, _ in events_and_contexts]
  File "/usr/lib/python2.7/dist-packages/synapse/storage/signatures.py", line 110, in _store_event_reference_hashes_txn
    values=vals,
  File "/usr/lib/python2.7/dist-packages/synapse/storage/_base.py", line 487, in _simple_insert_many_txn
    txn.executemany(sql, vals)
  File "/usr/lib/python2.7/dist-packages/synapse/storage/_base.py", line 89, in executemany
    self._do_execute(self.txn.executemany, sql, *args)
  File "/usr/lib/python2.7/dist-packages/synapse/storage/_base.py", line 116, in _do_execute
    sql, *args
IntegrityError: duplicate key value violates unique constraint "event_reference_hashes_event_id_algorithm_key"
DETAIL:  Key (event_id, algorithm)=($143679705872209FGduw:matrix.org, sha256) already exists.

2018-08-05 21:23:34,259 - synapse.http.server - 101 - ERROR - POST-410614- Failed handle request via <function _async_render at 0x7f1886a7caa0>: <XForwardedForRequest at 0x7f18191957e8 method='POST' uri='/_matrix/client/r0/join/%23offtopic%3Amatrix.org?' clientproto='HTTP/1.0' site=8008>: Traceback (most recent call last):
Failure: twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <type 'exceptions.IndexError'>: tuple index out of range
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:651:_runCallbacks
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:1355:gotResult
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:1297:_inlineCallbacks
/usr/lib/python2.7/dist-packages/twisted/python/failure.py:389:throwExceptionIntoGenerator
--- <exception caught here> ---
/usr/lib/python2.7/dist-packages/synapse/storage/events.py:148:handle_queue_loop
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:1297:_inlineCallbacks
/usr/lib/python2.7/dist-packages/twisted/python/failure.py:389:throwExceptionIntoGenerator
/usr/lib/python2.7/dist-packages/synapse/storage/events.py:294:persisting_queue
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:1297:_inlineCallbacks
/usr/lib/python2.7/dist-packages/twisted/python/failure.py:389:throwExceptionIntoGenerator
/usr/lib/python2.7/dist-packages/synapse/storage/events.py:192:f
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:1297:_inlineCallbacks
/usr/lib/python2.7/dist-packages/twisted/python/failure.py:389:throwExceptionIntoGenerator
/usr/lib/python2.7/dist-packages/synapse/storage/events.py:443:_persist_events
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:1297:_inlineCallbacks
/usr/lib/python2.7/dist-packages/twisted/python/failure.py:389:throwExceptionIntoGenerator
/usr/lib/python2.7/dist-packages/synapse/storage/_base.py:318:runInteraction
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:1297:_inlineCallbacks
/usr/lib/python2.7/dist-packages/twisted/python/failure.py:389:throwExceptionIntoGenerator
/usr/lib/python2.7/dist-packages/synapse/storage/_base.py:368:runWithConnection
/usr/lib/python2.7/dist-packages/twisted/python/threadpool.py:246:inContext
/usr/lib/python2.7/dist-packages/twisted/python/threadpool.py:262:<lambda>
/usr/lib/python2.7/dist-packages/twisted/python/context.py:118:callWithContext
/usr/lib/python2.7/dist-packages/twisted/python/context.py:81:callWithContext
/usr/lib/python2.7/dist-packages/twisted/enterprise/adbapi.py:307:_runWithConnection
/usr/lib/python2.7/dist-packages/twisted/enterprise/adbapi.py:298:_runWithConnection
/usr/lib/python2.7/dist-packages/synapse/storage/_base.py:364:inner_func
/usr/lib/python2.7/dist-packages/synapse/storage/_base.py:245:_new_transaction
/usr/lib/python2.7/dist-packages/synapse/util/logutils.py:82:wrapped
/usr/lib/python2.7/dist-packages/synapse/storage/events.py:731:_persist_events_txn
/usr/lib/python2.7/dist-packages/synapse/storage/events.py:1069:_delete_existing_rows_txn
/usr/lib/python2.7/dist-packages/synapse/storage/_base.py:89:executemany
/usr/lib/python2.7/dist-packages/synapse/storage/_base.py:116:_do_execute
]]
2018-08-05 21:24:21,781 - synapse.crypto.keyclient - 55 - ERROR - POST-410614- User timeout caused connection failure.
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/synapse/crypto/keyclient.py", line 46, in fetch_server_key
    protocol = yield endpoint.connect(factory)
TimeoutError: User timeout caused connection failure.
2018-08-05 21:24:51,786 - synapse.crypto.keyclient - 55 - ERROR - POST-410614- User timeout caused connection failure.
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/synapse/crypto/keyclient.py", line 46, in fetch_server_key
    protocol = yield endpoint.connect(factory)
TimeoutError: User timeout caused connection failure.
[many more timeout]

Version information

• Homeserver: this problem also shows up for at least one other user from another HS

If not matrix.org:

• Version: 0.33.1, this problem happend a while back in 0.31 iirc
• Install method: apt
• Platform: debian 9 VM

[tleydxdy]

Likely related
I was using this script to clean out rooms.
https://github.com/xwiki-labs/synapse_scripts/blob/master/synapse_janitor.sql

[dhalucario]

I tried to join a room and it doesn't seem to work no matter what. Im gonna ask one of the admins if they can kick me from the room and I will try to rejoin, to see if that fixes it.

Version: 0.33.2
Install method: apt
Platform: Ubuntu 18.04.1 LTS

[dhalucario]

Getting kicked didn't work. It removed the user but I still can't join the room. I pretty much can join any other room on matrix.org

[aryasenna]

I faced the exact same problem, and I actually came because I am trying to join #offtopic, and got the same log with you (down to event_id of the authentication event).
If you see the error:

IntegrityError: duplicate key value violates unique constraint "event_reference_hashes_event_id_algorithm_key"
DETAIL:  Key (event_id, algorithm)=($143679705872209FGduw:matrix.org, sha256) already exists.

What I did was:

1. manually remove the above offending table value,
2. run the synapse_janitor
3. restart the server and tried to rejoin.

Still took some time (367 secs), but it finally works:

2018-08-25 15:27:06,618 - synapse.state - 471 - INFO - GET-1228- Resolving state for !UcYsUzyxTGDxLBEvLz:matrix.org with 0 groups
2018-08-25 15:27:06,619 - synapse.state - 471 - INFO - GET-1228- Resolving state for !UcYsUzyxTGDxLBEvLz:matrix.org with 0 groups
2018-08-25 15:27:06,662 - synapse.state - 471 - INFO - GET-1228- Resolving state for !UcYsUzyxTGDxLBEvLz:matrix.org with 0 groups
2018-08-25 15:27:06,667 - synapse.state - 471 - INFO - GET-1228- Resolving state for !UcYsUzyxTGDxLBEvLz:matrix.org with 0 groups
2018-08-25 15:27:06,852 - synapse.storage.events - 441 - INFO - persist_events-3- Calculating state delta for room !UcYsUzyxTGDxLBEvLz:matrix.org
2018-08-25 15:27:08,696 - synapse.util.async - 250 - INFO - POST-506- Releasing linearizer lock 'member' for key ('!UcYsUzyxTGDxLBEvLz:matrix.org',)
2018-08-25 15:27:08,697 - synapse.access.http.8008 - 139 - INFO - POST-506- 80.209.210.41 - 8008 - {@me:aryasenna.net} Processed request: 367.118sec (2.435sec, 0.150sec) (0.033sec/0.609sec/294) 65B 200 "POST /_matrix/client/r0/join/%23offtopic:matrix.org HTTP/1.1" "Mozilla/5.0" [159 dbevts]

By the way are you using PostgreSQL? then you need to also do some workaround to be able to join #offtopic since the room depth is high, the default Synapse psql schema doesn't accept it. (See #3214, also check your postgres log, to be sure).

[tleydxdy]

I'm pretty sure this is a bug

[richvdh]

sounds like the initial join failed. You should be able to retry.

possibly related: #6561, #5705.

I'm going to close this because it's quite old and it's not obvious what the actual problem was.