search

matrix-org / synapse

Synapse: Matrix homeserver written in Python/Twisted.
https://matrix-org.github.io/synapse
Apache License 2.0
11.83k stars 2.13k forks source link

Synapse gets stuck after seeing `psycopg2.errors.ReadOnlySqlTransaction: cannot execute nextval() in a read-only transaction` #16490

Open MTRNord opened 1 year ago

MTRNord commented 1 year ago

https://github.com/matrix-org/synapse/blob/166ffc0f23419bc99d9597fe95deaae3bbee7caf/synapse/rest/health.py#L29-L31

Hi :)

It seems like the health endpoint is a little too simple. For example, I am getting with patroni (pg cluster) sometimes synapse in a state where it gets stuck in a read-only transaction state psycopg2.errors.ReadOnlySqlTransaction: cannot execute nextval() in a read-only transaction. Synapse never recovers until a restart from this, even when the database is already healthy for hours again. Meanwhile, however, my Kubernetes which could have easily restarted synapse by now thinks the server is healthy while all api endpoints fail.

Would it be possible to include fatal errors from the database in the evaluation of the health endpoint? Or are there other suggestions on how to solve this for someone hosting a synapse server?

dklimpel commented 1 year ago

Related to #11473

DMRobertson commented 1 year ago

As titled

Health endpoint doesn't reflect real health state

the issue sounds like a duplicate of #11473 as Dirk says.

cannot execute nextval() in a read-only transaction

This is new to me. I don't think Synapse has any logic for opening read-only transactions. (Searching for \.set_session\( yields only calls which set the autocommit flag.) So I would assume this is Synapse opening a connection expecting write privileges only to find that it has readonly privileges only. (In turn, I would assume this is because "Patroni" is doing some kind of failover or rebalancing which reconfigures an existing writeable postgres instance to be readonly.)

For that specific issue, I think the best we could do to help here is to explicitly create connections requesting a writeable session. There is some connection string syntax for this, which we could presumably invoke via psycopg2. It might be that case that raising an error at conn-creation time means the application is more likely to show signs of failure. But that still wouldn't be communicated via the healthcheck endpoint.

Being candid though, this seems like an unusual way to run postgres (and a niche failure mode); I don't think we're going to prioritise supporting it.

DMRobertson commented 1 year ago

sometimes synapse in a state where it gets stuck in a read-only transaction state psycopg2.errors.ReadOnlySqlTransaction: cannot execute nextval() in a read-only transaction

Also: logs, please.

MTRNord commented 1 year ago

sometimes synapse in a state where it gets stuck in a read-only transaction state psycopg2.errors.ReadOnlySqlTransaction: cannot execute nextval() in a read-only transaction

Also: logs, please.

A random excerpt (this happens basically on any INSERT I got 8h of this log :))

2023-10-15T20:45:09+02:00   2023-10-15 18:45:09,845 - synapse.access.http.8083 - 465 - INFO - PUT-50238- 135.181.89.181 - 8083 - {matrix.akselmo.dev} Processed request: 0.020sec/0.001sec (0.008sec, 0.000sec) (0.001sec/0.005sec/2) 55B 500 "PUT /_matrix/federation/v1/send/1697223622203 HTTP/1.1" "Synapse/1.94.0" [0 dbevts]
2023-10-15T20:45:09+02:00   
2023-10-15T20:45:09+02:00   psycopg2.errors.ReadOnlySqlTransaction: cannot execute INSERT in a read-only transaction
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return func(sql, *args, **kwargs)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 473, in _do_execute
2023-10-15T20:45:09+02:00       self._do_execute(self.txn.execute, sql, parameters)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 421, in execute
2023-10-15T20:45:09+02:00       txn.execute(sql, list(allvalues.values()))
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1438, in simple_upsert_txn_native_upsert
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return self.simple_upsert_txn_native_upsert(
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1298, in simple_upsert_txn
2023-10-15T20:45:09+02:00           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       r = func(cursor, *args, **kwargs)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 762, in new_transaction
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return func(db_conn, *args, **kwargs)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1022, in inner_func
2023-10-15T20:45:09+02:00                ^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       result = func(conn, *args, **kw)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return func(*args, **kw)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 82, in callWithContext
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return self.currentContext().callWithContext(ctx, func, *args, **kw)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 117, in callWithContext
2023-10-15T20:45:09+02:00                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
2023-10-15T20:45:09+02:00                ^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       result = inContext.theWork()  # type: ignore[attr-defined]
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 244, in inContext
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return await make_deferred_yieldable(
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1029, in runWithConnection
2023-10-15T20:45:09+02:00                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       result = await self.runWithConnection(
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 900, in _runInteraction
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return g.throw(self.type, self.value, self.tb)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
2023-10-15T20:45:09+02:00                ^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       result = context.run(
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/internet/defer.py", line 1993, in _inlineCallbacks
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return await delay_cancellation(_runInteraction())
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 934, in runInteraction
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return await self.runInteraction(
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1249, in simple_upsert
2023-10-15T20:45:09+02:00       await self.db_pool.simple_upsert(
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/transactions.py", line 152, in set_received_txn_response
2023-10-15T20:45:09+02:00       await self.store.set_received_txn_response(
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/federation/persistence.py", line 62, in set_response
2023-10-15T20:45:09+02:00       await self.transaction_actions.set_response(origin, transaction, 200, response)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/federation/federation_server.py", line 403, in _handle_incoming_transaction
2023-10-15T20:45:09+02:00                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       result = await self._handle_incoming_transaction(
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/federation/federation_server.py", line 351, in _on_incoming_transaction_inner
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return await callback(*args, **kwargs)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/util/caches/response_cache.py", line 258, in cb
2023-10-15T20:45:09+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       return g.throw(self.type, self.value, self.tb)
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
2023-10-15T20:45:09+02:00                ^^^^^^^^^^^^
2023-10-15T20:45:09+02:00       result = context.run(
2023-10-15T20:45:09+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/internet/defer.py", line 1993, in _inlineCallbacks
2023-10-15T20:45:09+02:00   Traceback (most recent call last):
2023-10-15T20:45:09+02:00   2023-10-15 18:45:09,843 - synapse.http.server - 140 - ERROR - PUT-50238- Failed handle request via 'FederationSendServlet': <XForwardedForRequest at 0xffff8454e7d0 method='PUT' uri='/_matrix/federation/v1/send/1697223622203' clientproto='HTTP/1.1' site='8083'>
2023-10-15T20:45:09+02:00   2023-10-15 18:45:09,827 - synapse.federation.transport.server.federation - 105 - INFO - PUT-50238-- Received txn 1697223622203 from matrix.akselmo.dev. (PDUs: 0, EDUs: 1)
2023-10-15T20:45:03+02:00   
2023-10-15T20:45:03+02:00   psycopg2.errors.FeatureNotSupported: cannot access temporary or unlogged relations during recovery
2023-10-15T20:45:03+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       return func(sql, *args, **kwargs)
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 473, in _do_execute
2023-10-15T20:45:03+02:00       self._do_execute(self.txn.execute, sql, parameters)
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 421, in execute
2023-10-15T20:45:03+02:00       txn.execute(delete_sql, (self._clock.time_msec() - _LOCK_TIMEOUT_MS,))
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/lock.py", line 328, in reap_stale_read_write_locks_txn
2023-10-15T20:45:03+02:00           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       r = func(cursor, *args, **kwargs)
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 762, in new_transaction
2023-10-15T20:45:03+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       return func(db_conn, *args, **kwargs)
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1022, in inner_func
2023-10-15T20:45:03+02:00                ^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       result = func(conn, *args, **kw)
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
2023-10-15T20:45:03+02:00              ^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       return func(*args, **kw)
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 82, in callWithContext
2023-10-15T20:45:03+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       return self.currentContext().callWithContext(ctx, func, *args, **kw)
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 117, in callWithContext
2023-10-15T20:45:03+02:00                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
2023-10-15T20:45:03+02:00                ^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       result = inContext.theWork()  # type: ignore[attr-defined]
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 244, in inContext
2023-10-15T20:45:03+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       return await make_deferred_yieldable(
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1029, in runWithConnection
2023-10-15T20:45:03+02:00                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       result = await self.runWithConnection(
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 900, in _runInteraction
2023-10-15T20:45:03+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       return g.throw(self.type, self.value, self.tb)
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
2023-10-15T20:45:03+02:00                ^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       result = context.run(
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/internet/defer.py", line 1993, in _inlineCallbacks
2023-10-15T20:45:03+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       return await delay_cancellation(_runInteraction())
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 934, in runInteraction
2023-10-15T20:45:03+02:00       await self.db_pool.runInteraction(
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/lock.py", line 332, in _reap_stale_read_write_locks
2023-10-15T20:45:03+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:45:03+02:00       return await func(*args, **kwargs)
2023-10-15T20:45:03+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/metrics/background_process_metrics.py", line 245, in run
2023-10-15T20:45:03+02:00   Traceback (most recent call last):
2023-10-15T20:45:03+02:00   2023-10-15 18:45:03,675 - synapse.metrics.background_process_metrics - 247 - ERROR - _reap_stale_read_write_locks-9852- Background process '_reap_stale_read_write_locks' threw an exception
2023-10-15T20:44:58+02:00   2023-10-15 18:44:58,046 - synapse.util.caches.lrucache - 210 - INFO - LruCache._expire_old_entries-3954- Dropped 2 items from caches
2023-10-15T20:44:52+02:00   2023-10-15 18:44:52,364 - twisted - 275 - INFO - sentinel- Timing out client: IPv6Address(type='TCP', host='::ffff:10.245.1.254', port=43076, flowInfo=0, scopeID=0)
2023-10-15T20:44:51+02:00   
2023-10-15T20:44:51+02:00   psycopg2.errors.FeatureNotSupported: cannot access temporary or unlogged relations during recovery
2023-10-15T20:44:51+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       return func(sql, *args, **kwargs)
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 473, in _do_execute
2023-10-15T20:44:51+02:00       self._do_execute(self.txn.execute, sql, parameters)
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 421, in execute
2023-10-15T20:44:51+02:00       txn.execute(delete_sql, (self._clock.time_msec() - _LOCK_TIMEOUT_MS,))
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/lock.py", line 328, in reap_stale_read_write_locks_txn
2023-10-15T20:44:51+02:00           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       r = func(cursor, *args, **kwargs)
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 762, in new_transaction
2023-10-15T20:44:51+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       return func(db_conn, *args, **kwargs)
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1022, in inner_func
2023-10-15T20:44:51+02:00                ^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       result = func(conn, *args, **kw)
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
2023-10-15T20:44:51+02:00              ^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       return func(*args, **kw)
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 82, in callWithContext
2023-10-15T20:44:51+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       return self.currentContext().callWithContext(ctx, func, *args, **kw)
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 117, in callWithContext
2023-10-15T20:44:51+02:00                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
2023-10-15T20:44:51+02:00                ^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       result = inContext.theWork()  # type: ignore[attr-defined]
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 244, in inContext
2023-10-15T20:44:51+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       return await make_deferred_yieldable(
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1029, in runWithConnection
2023-10-15T20:44:51+02:00                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       result = await self.runWithConnection(
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 900, in _runInteraction
2023-10-15T20:44:51+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       return g.throw(self.type, self.value, self.tb)
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
2023-10-15T20:44:51+02:00                ^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       result = context.run(
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/internet/defer.py", line 1993, in _inlineCallbacks
2023-10-15T20:44:51+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       return await delay_cancellation(_runInteraction())
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 934, in runInteraction
2023-10-15T20:44:51+02:00       await self.db_pool.runInteraction(
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/lock.py", line 332, in _reap_stale_read_write_locks
2023-10-15T20:44:51+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:51+02:00       return await func(*args, **kwargs)
2023-10-15T20:44:51+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/metrics/background_process_metrics.py", line 245, in run
2023-10-15T20:44:51+02:00   Traceback (most recent call last):
2023-10-15T20:44:51+02:00   2023-10-15 18:44:51,674 - synapse.metrics.background_process_metrics - 247 - ERROR - _reap_stale_read_write_locks-9851- Background process '_reap_stale_read_write_locks' threw an exception
2023-10-15T20:44:44+02:00   2023-10-15 18:44:44,815 - synapse.access.http.8083 - 465 - INFO - PUT-50231- 88.129.114.162 - 8083 - {None} Processed request: 1.851sec/0.001sec (0.000sec, 0.003sec) (0.000sec/0.000sec/0) 191B 401 "PUT /_matrix/federation/v1/send/1696716943177 HTTP/1.1" "Synapse/1.93.0" [0 dbevts]
2023-10-15T20:44:44+02:00   2023-10-15 18:44:44,814 - synapse.http.server - 124 - INFO - PUT-50231- <XForwardedForRequest at 0xffff8440f150 method='PUT' uri='/_matrix/federation/v1/send/1696716943177' clientproto='HTTP/1.1' site='8083'> SynapseError: 401 - Failed to find any key to satisfy: _FetchKeyRequest(server_name='matrix.aroy-art.com', minimum_valid_until_ts=1697395482963, key_ids=['ed25519:a_WdaT'])
2023-10-15T20:44:44+02:00   2023-10-15 18:44:44,812 - synapse.federation.transport.server._base - 312 - WARNING - PUT-50231- authenticate_request failed: 401: Failed to find any key to satisfy: _FetchKeyRequest(server_name='matrix.aroy-art.com', minimum_valid_until_ts=1697395482963, key_ids=['ed25519:a_WdaT'])
2023-10-15T20:44:44+02:00   
2023-10-15T20:44:44+02:00   psycopg2.errors.ReadOnlySqlTransaction: cannot execute INSERT in a read-only transaction
2023-10-15T20:44:44+02:00       cur.execute(b''.join(parts))
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/psycopg2/extras.py", line 1299, in execute_values
2023-10-15T20:44:44+02:00                                   ^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       lambda the_sql, the_values: execute_values(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 413, in <lambda>
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return func(sql, *args, **kwargs)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 473, in _do_execute
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return self._do_execute(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 410, in execute_values
2023-10-15T20:44:44+02:00       txn.execute_values(sql, args, fetch=False)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1596, in simple_upsert_many_txn_native_upsert
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return self.simple_upsert_many_txn_native_upsert(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1498, in simple_upsert_many_txn
2023-10-15T20:44:44+02:00       self.db_pool.simple_upsert_many_txn(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/keys.py", line 63, in store_server_keys_response_txn
2023-10-15T20:44:44+02:00           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       r = func(cursor, *args, **kwargs)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 762, in new_transaction
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return func(db_conn, *args, **kwargs)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1022, in inner_func
2023-10-15T20:44:44+02:00                ^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       result = func(conn, *args, **kw)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return func(*args, **kw)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 82, in callWithContext
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return self.currentContext().callWithContext(ctx, func, *args, **kw)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 117, in callWithContext
2023-10-15T20:44:44+02:00                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
2023-10-15T20:44:44+02:00                ^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       result = inContext.theWork()  # type: ignore[attr-defined]
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 244, in inContext
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return await make_deferred_yieldable(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1029, in runWithConnection
2023-10-15T20:44:44+02:00                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       result = await self.runWithConnection(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 900, in _runInteraction
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return g.throw(self.type, self.value, self.tb)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
2023-10-15T20:44:44+02:00                ^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       result = context.run(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/internet/defer.py", line 1993, in _inlineCallbacks
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return await delay_cancellation(_runInteraction())
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 934, in runInteraction
2023-10-15T20:44:44+02:00       await self.db_pool.runInteraction(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/keys.py", line 118, in store_server_keys_response
2023-10-15T20:44:44+02:00       await self.store.store_server_keys_response(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/crypto/keyring.py", line 594, in process_v2_response
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return await self.process_v2_response(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/crypto/keyring.py", line 898, in get_server_verify_keys_v2_direct
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       keys = await self.get_server_verify_keys_v2_direct(server_name)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/crypto/keyring.py", line 841, in get_keys
2023-10-15T20:44:44+02:00   Traceback (most recent call last):
2023-10-15T20:44:44+02:00   2023-10-15 18:44:44,810 - synapse.crypto.keyring - 846 - ERROR - ServerKeyFetcher-0- Error getting keys from matrix.aroy-art.com
2023-10-15T20:44:44+02:00   2023-10-15 18:44:44,802 - synapse.http.matrixfederationclient - 348 - INFO - ServerKeyFetcher-0- {GET-O-106} [matrix.aroy-art.com] Completed request: 200 OK in 0.32 secs, got 321 bytes - GET matrix-federation://matrix.aroy-art.com/_matrix/key/v2/server
2023-10-15T20:44:44+02:00   2023-10-15 18:44:44,607 - synapse.http.federation.well_known_resolver - 190 - INFO - ServerKeyFetcher-0-- Response from .well-known: {'m.server': 'matrix.aroy-art.com:443'}
2023-10-15T20:44:44+02:00   2023-10-15 18:44:44,487 - synapse.http.federation.well_known_resolver - 253 - INFO - ServerKeyFetcher-0-- Fetching https://matrix.aroy-art.com/.well-known/matrix/server
2023-10-15T20:44:44+02:00   
2023-10-15T20:44:44+02:00   psycopg2.errors.ReadOnlySqlTransaction: cannot execute INSERT in a read-only transaction
2023-10-15T20:44:44+02:00       cur.execute(b''.join(parts))
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/psycopg2/extras.py", line 1299, in execute_values
2023-10-15T20:44:44+02:00                                   ^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       lambda the_sql, the_values: execute_values(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 413, in <lambda>
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return func(sql, *args, **kwargs)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 473, in _do_execute
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return self._do_execute(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 410, in execute_values
2023-10-15T20:44:44+02:00       txn.execute_values(sql, args, fetch=False)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1596, in simple_upsert_many_txn_native_upsert
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return self.simple_upsert_many_txn_native_upsert(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1498, in simple_upsert_many_txn
2023-10-15T20:44:44+02:00       self.db_pool.simple_upsert_many_txn(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/keys.py", line 63, in store_server_keys_response_txn
2023-10-15T20:44:44+02:00           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       r = func(cursor, *args, **kwargs)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 762, in new_transaction
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return func(db_conn, *args, **kwargs)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1022, in inner_func
2023-10-15T20:44:44+02:00                ^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       result = func(conn, *args, **kw)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return func(*args, **kw)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 82, in callWithContext
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return self.currentContext().callWithContext(ctx, func, *args, **kw)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 117, in callWithContext
2023-10-15T20:44:44+02:00                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
2023-10-15T20:44:44+02:00                ^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       result = inContext.theWork()  # type: ignore[attr-defined]
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 244, in inContext
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return await make_deferred_yieldable(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1029, in runWithConnection
2023-10-15T20:44:44+02:00                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       result = await self.runWithConnection(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 900, in _runInteraction
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return g.throw(self.type, self.value, self.tb)
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
2023-10-15T20:44:44+02:00                ^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       result = context.run(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/internet/defer.py", line 1993, in _inlineCallbacks
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return await delay_cancellation(_runInteraction())
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 934, in runInteraction
2023-10-15T20:44:44+02:00       await self.db_pool.runInteraction(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/keys.py", line 118, in store_server_keys_response
2023-10-15T20:44:44+02:00       await self.store.store_server_keys_response(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/crypto/keyring.py", line 594, in process_v2_response
2023-10-15T20:44:44+02:00                            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       processed_response = await self.process_v2_response(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/crypto/keyring.py", line 724, in get_server_verify_key_v2_indirect
2023-10-15T20:44:44+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:44+02:00       return await self.get_server_verify_key_v2_indirect(
2023-10-15T20:44:44+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/crypto/keyring.py", line 621, in get_key
2023-10-15T20:44:44+02:00   Traceback (most recent call last):
2023-10-15T20:44:44+02:00   2023-10-15 18:44:44,479 - synapse.crypto.keyring - 629 - ERROR - PerspectivesKeyFetcher-92- Unable to get key from 'matrix.org': ReadOnlySqlTransaction cannot execute INSERT in a read-only transaction
2023-10-15T20:44:44+02:00   2023-10-15 18:44:44,468 - synapse.http.matrixfederationclient - 348 - INFO - PerspectivesKeyFetcher-92- {POST-O-105} [matrix.org] Completed request: 200 OK in 1.50 secs, got 458 bytes - POST matrix-federation://matrix.org/_matrix/key/v2/query
2023-10-15T20:44:43+02:00   2023-10-15 18:44:43,044 - synapse.http.federation.well_known_resolver - 190 - INFO - PerspectivesKeyFetcher-92-- Response from .well-known: {'m.server': 'matrix-federation.matrix.org:443'}
2023-10-15T20:44:42+02:00   2023-10-15 18:44:42,970 - synapse.http.federation.well_known_resolver - 253 - INFO - PerspectivesKeyFetcher-92-- Fetching https://matrix.org/.well-known/matrix/server
2023-10-15T20:44:42+02:00   2023-10-15 18:44:42,968 - synapse.crypto.keyring - 670 - INFO - PerspectivesKeyFetcher-92- Requesting keys [_FetchKeyRequest(server_name='matrix.aroy-art.com', minimum_valid_until_ts=1697395482963, key_ids=['ed25519:a_WdaT'])] from notary server matrix.org
2023-10-15T20:44:39+02:00   
2023-10-15T20:44:39+02:00   psycopg2.errors.FeatureNotSupported: cannot access temporary or unlogged relations during recovery
2023-10-15T20:44:39+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       return func(sql, *args, **kwargs)
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 473, in _do_execute
2023-10-15T20:44:39+02:00       self._do_execute(self.txn.execute, sql, parameters)
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 421, in execute
2023-10-15T20:44:39+02:00       txn.execute(delete_sql, (self._clock.time_msec() - _LOCK_TIMEOUT_MS,))
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/lock.py", line 328, in reap_stale_read_write_locks_txn
2023-10-15T20:44:39+02:00           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       r = func(cursor, *args, **kwargs)
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 762, in new_transaction
2023-10-15T20:44:39+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       return func(db_conn, *args, **kwargs)
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1022, in inner_func
2023-10-15T20:44:39+02:00                ^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       result = func(conn, *args, **kw)
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
2023-10-15T20:44:39+02:00              ^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       return func(*args, **kw)
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 82, in callWithContext
2023-10-15T20:44:39+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       return self.currentContext().callWithContext(ctx, func, *args, **kw)
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 117, in callWithContext
2023-10-15T20:44:39+02:00                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
2023-10-15T20:44:39+02:00                ^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       result = inContext.theWork()  # type: ignore[attr-defined]
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 244, in inContext
2023-10-15T20:44:39+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       return await make_deferred_yieldable(
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1029, in runWithConnection
2023-10-15T20:44:39+02:00                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       result = await self.runWithConnection(
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 900, in _runInteraction
2023-10-15T20:44:39+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       return g.throw(self.type, self.value, self.tb)
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
2023-10-15T20:44:39+02:00                ^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       result = context.run(
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/internet/defer.py", line 1993, in _inlineCallbacks
2023-10-15T20:44:39+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       return await delay_cancellation(_runInteraction())
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 934, in runInteraction
2023-10-15T20:44:39+02:00       await self.db_pool.runInteraction(
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/lock.py", line 332, in _reap_stale_read_write_locks
2023-10-15T20:44:39+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:39+02:00       return await func(*args, **kwargs)
2023-10-15T20:44:39+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/metrics/background_process_metrics.py", line 245, in run
2023-10-15T20:44:39+02:00   Traceback (most recent call last):
2023-10-15T20:44:39+02:00   2023-10-15 18:44:39,675 - synapse.metrics.background_process_metrics - 247 - ERROR - _reap_stale_read_write_locks-9850- Background process '_reap_stale_read_write_locks' threw an exception
2023-10-15T20:44:28+02:00   2023-10-15 18:44:28,047 - synapse.util.caches.lrucache - 210 - INFO - LruCache._expire_old_entries-3953- Dropped 17 items from caches
2023-10-15T20:44:27+02:00   
2023-10-15T20:44:27+02:00   psycopg2.errors.FeatureNotSupported: cannot access temporary or unlogged relations during recovery
2023-10-15T20:44:27+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       return func(sql, *args, **kwargs)
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 473, in _do_execute
2023-10-15T20:44:27+02:00       self._do_execute(self.txn.execute, sql, parameters)
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 421, in execute
2023-10-15T20:44:27+02:00       txn.execute(delete_sql, (self._clock.time_msec() - _LOCK_TIMEOUT_MS,))
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/lock.py", line 328, in reap_stale_read_write_locks_txn
2023-10-15T20:44:27+02:00           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       r = func(cursor, *args, **kwargs)
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 762, in new_transaction
2023-10-15T20:44:27+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       return func(db_conn, *args, **kwargs)
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1022, in inner_func
2023-10-15T20:44:27+02:00                ^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       result = func(conn, *args, **kw)
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
2023-10-15T20:44:27+02:00              ^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       return func(*args, **kw)
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 82, in callWithContext
2023-10-15T20:44:27+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       return self.currentContext().callWithContext(ctx, func, *args, **kw)
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 117, in callWithContext
2023-10-15T20:44:27+02:00                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
2023-10-15T20:44:27+02:00                ^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       result = inContext.theWork()  # type: ignore[attr-defined]
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 244, in inContext
2023-10-15T20:44:27+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       return await make_deferred_yieldable(
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1029, in runWithConnection
2023-10-15T20:44:27+02:00                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       result = await self.runWithConnection(
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 900, in _runInteraction
2023-10-15T20:44:27+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       return g.throw(self.type, self.value, self.tb)
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
2023-10-15T20:44:27+02:00                ^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       result = context.run(
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/internet/defer.py", line 1993, in _inlineCallbacks
2023-10-15T20:44:27+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       return await delay_cancellation(_runInteraction())
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 934, in runInteraction
2023-10-15T20:44:27+02:00       await self.db_pool.runInteraction(
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/lock.py", line 332, in _reap_stale_read_write_locks
2023-10-15T20:44:27+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:27+02:00       return await func(*args, **kwargs)
2023-10-15T20:44:27+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/metrics/background_process_metrics.py", line 245, in run
2023-10-15T20:44:27+02:00   Traceback (most recent call last):
2023-10-15T20:44:27+02:00   2023-10-15 18:44:27,674 - synapse.metrics.background_process_metrics - 247 - ERROR - _reap_stale_read_write_locks-9849- Background process '_reap_stale_read_write_locks' threw an exception
2023-10-15T20:44:15+02:00   
2023-10-15T20:44:15+02:00   psycopg2.errors.FeatureNotSupported: cannot access temporary or unlogged relations during recovery
2023-10-15T20:44:15+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       return func(sql, *args, **kwargs)
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 473, in _do_execute
2023-10-15T20:44:15+02:00       self._do_execute(self.txn.execute, sql, parameters)
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 421, in execute
2023-10-15T20:44:15+02:00       txn.execute(delete_sql, (self._clock.time_msec() - _LOCK_TIMEOUT_MS,))
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/lock.py", line 328, in reap_stale_read_write_locks_txn
2023-10-15T20:44:15+02:00           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       r = func(cursor, *args, **kwargs)
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 762, in new_transaction
2023-10-15T20:44:15+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       return func(db_conn, *args, **kwargs)
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1022, in inner_func
2023-10-15T20:44:15+02:00                ^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       result = func(conn, *args, **kw)
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
2023-10-15T20:44:15+02:00              ^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       return func(*args, **kw)
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 82, in callWithContext
2023-10-15T20:44:15+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       return self.currentContext().callWithContext(ctx, func, *args, **kw)
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 117, in callWithContext
2023-10-15T20:44:15+02:00                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
2023-10-15T20:44:15+02:00                ^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       result = inContext.theWork()  # type: ignore[attr-defined]
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 244, in inContext
2023-10-15T20:44:15+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       return await make_deferred_yieldable(
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1029, in runWithConnection
2023-10-15T20:44:15+02:00                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       result = await self.runWithConnection(
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 900, in _runInteraction
2023-10-15T20:44:15+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       return g.throw(self.type, self.value, self.tb)
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
2023-10-15T20:44:15+02:00                ^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       result = context.run(
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/twisted/internet/defer.py", line 1993, in _inlineCallbacks
2023-10-15T20:44:15+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       return await delay_cancellation(_runInteraction())
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 934, in runInteraction
2023-10-15T20:44:15+02:00       await self.db_pool.runInteraction(
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/lock.py", line 332, in _reap_stale_read_write_locks
2023-10-15T20:44:15+02:00              ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-15T20:44:15+02:00       return await func(*args, **kwargs)
2023-10-15T20:44:15+02:00     File "/usr/local/lib/python3.11/site-packages/synapse/metrics/background_process_metrics.py", line 245, in run
2023-10-15T20:44:15+02:00   Traceback (most recent call last):
2023-10-15T20:44:15+02:00   2023-10-15 18:44:15,675 - synapse.metrics.background_process_metrics - 247 - ERROR - _reap_stale_read_write_locks-9848- Background process '_reap_stale_read_write_locks' threw an exception

To bring this some context of what I believe happened:

  1. For reasons patroni failed over
  2. Patroni updated the kubernetes service annotations
  3. The kubernetes IP failed over too
  4. Kubernetes did either not or not successfully terminate connections
  5. Synapse got stuck on the old connection to the old postgres
  6. Synapse didnt try to reconnect.

I didnt verify if this is the reality. But this is my theory based on how patroni/postgres-operator in kubernetes does failover. There is currently no bouncer in between. I am relying purely on kubernetes services for failover routing here.

Not sure if it adds much context but its a kubernetes 1.28 kubeadm based with cilium as the network stack and postgres-operator for the database (it uses patroni for failover)

Also I guess that patroni sets standby into recovery mode? Not sure how exactly pg/patroni does this. But from what I read online read-only/standby mode is reflected as recovery mode to consumers. But correct me if thats wrong please.