search

matrix-org / synapse

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

Leaving room throws 500 internal error #7916

Closed nomelif closed 3 years ago

nomelif commented 4 years ago

Description

Synapse throws a 500 internal error when I try to leave a room.

Steps to reproduce

This is only broken for me with the postmarketOS offtopic channel for some reason. I have moved synapse twice via postgres dump. I don't know whether that has had an effect on the integrity of my data base. I was trying to leave the room in the first place because new messages stopped being received (into that specific room, other rooms work). They were being received for some time (months) after the second migration though.

What I expected: room is left successfully What happened: a 500 error is thrown, the room is not left.

I got a clear error from journalctl:

Jul 20 13:00:33 puppisnix synapse[5556]: synapse.access.http.8008: [OPTIONS-1160] - - 8008 - {None} Processed request: 0.003sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "OPTIONS /_matrix/client/r0/rooms/!VYsYJQNEpQSJlMMxiC%3Afam-ribbers.com/leave HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.7 Chrome/78.0.3904.130 Electron/7.3.0 Safari/537.36" [0 dbevts]
Jul 20 13:00:33 puppisnix synapse[5556]: synapse.http.server: [POST-1161] Failed handle request via 'RoomMembershipRestServlet': <XForwardedForRequest at 0x7f5484f090 method='POST' uri='/_matrix/client/r0/rooms/!VYsYJQNEpQSJlMMxiC%3Afam-ribbers.com/leave' clientproto='HTTP/1.0' site=8008>
Traceback (most recent call last):
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/http/server.py", line 228, in _async_render_wrapper
callback_return = await self._async_render(request)
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/http/server.py", line 399, in _async_render
callback_return = await raw_callback_return
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/rest/client/v1/room.py", line 746, in on_POST
content=event_content,
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/handlers/room_member.py", line 285, in update_membership
require_consent=require_consent,
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/handlers/room_member.py", line 501, in _update_membership
require_consent=require_consent,
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/handlers/room_member.py", line 198, in _local_membership_update
requester, event, context, extra_users=[target], ratelimit=ratelimit
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/util/metrics.py", line 73, in measured_func
r = await func(self, *args, **kwargs)
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/handlers/message.py", line 864, in handle_new_client_event
requester, event, context, ratelimit=ratelimit, extra_users=extra_users
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/handlers/message.py", line 1079, in persist_and_notify_client_event
event, context=context
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/storage/persist_events.py", line 149, in handle_queue_loop
ret = await per_item_callback(item)
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/storage/persist_events.py", line 259, in persisting_queue
item.events_and_contexts, backfilled=item.backfilled
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/storage/persist_events.py", line 324, in _persist_events
room_id, ev_ctx_rm, latest_event_ids
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/storage/persist_events.py", line 485, in _calculate_new_extremities
e_id for event in new_events for e_id in event.prev_event_ids()
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
result = result.throwExceptionIntoGenerator(g)
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
return g.throw(self.type, self.value, self.tb)
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py", line 333, in _get_prevs_before_rejected
"_get_prevs_before_rejected", _get_prevs_before_rejected_txn, chunk
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
result = result.throwExceptionIntoGenerator(g)
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
return g.throw(self.type, self.value, self.tb)
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/storage/database.py", line 525, in runInteraction
**kwargs
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
result = result.throwExceptionIntoGenerator(g)
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
return g.throw(self.type, self.value, self.tb)
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/storage/database.py", line 573, in runWithConnection
self._db_pool.runWithConnection(inner_func, *args, **kwargs)
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/threadpool.py", line 250, in inContext
result = inContext.theWork()
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/threadpool.py", line 266, in <lambda>
inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/context.py", line 122, in callWithContext
return self.currentContext().callWithContext(ctx, func, *args, **kw)
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/context.py", line 85, in callWithContext
return func(*args,**kw)
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 306, in _runWithConnection
compat.reraise(excValue, excTraceback)
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/compat.py", line 464, in reraise
raise exception.with_traceback(traceback)
File "/nix/store/6fpiyl8g17n47fk1b37ivq12874zrix3-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 297, in _runWithConnection
result = func(conn, *args, **kw)
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/storage/database.py", line 570, in inner_func
return func(conn, *args, **kwargs)
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/storage/database.py", line 416, in new_transaction
r = func(cursor, *args, **kwargs)
File "/nix/store/8vh43w13g29bkgjapwb0a6yg5rpc49iq-matrix-synapse-1.17.0/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py", line 326, in _get_prevs_before_rejected_txn
soft_failed = json.loads(metadata).get("soft_failed")
File "/nix/store/b7q8gw17aqxqqcvw3nqmw9pv4fx231iy-python3.7-simplejson-3.17.0/lib/python3.7/site-packages/simplejson/init.py", line 525, in loads
return _default_decoder.decode(s)
File "/nix/store/b7q8gw17aqxqqcvw3nqmw9pv4fx231iy-python3.7-simplejson-3.17.0/lib/python3.7/site-packages/simplejson/decoder.py", line 370, in decode
obj, end = self.raw_decode(s)
File "/nix/store/b7q8gw17aqxqqcvw3nqmw9pv4fx231iy-python3.7-simplejson-3.17.0/lib/python3.7/site-packages/simplejson/decoder.py", line 392, in raw_decode
raise TypeError("Input string must be text, not bytes")
TypeError: Input string must be text, not bytes

Version information

If not matrix.org:

$ curl http://localhost:8008/_synapse/admin/v1/server_version
{"server": {"name": "Synapse", "version": "1.17.0"}}

This was broken for the two previous matrix versions from nixpkgs as well. I hoped that the updates would fix it.

[chell@puppisnix:~]$ uname -a
Linux puppisnix 4.19.75 #1-NixOS SMP Thu Jan 1 00:00:01 UTC 1970 aarch64 GNU/Linux
clokep commented 4 years ago

This was broken for the two previous matrix versions from nixpkgs as well. I hoped that the updates would fix it.

Do you happen to know what those versions were?

We have messed a bit with JSON stuff recently (see #7674).

anoadragon453 commented 4 years ago

Looks like the relevant code lines have been changed (after v1.17.0): https://github.com/matrix-org/synapse/commit/f460da6031d01b2b271ded097ed6be65fd1b24f9#diff-5a0797e349006661a23d6b420d7735d1

clokep commented 4 years ago

@anoadragon453 Ah, yeah I wonder if something came in as the wrong data type ("I have moved synapse twice via postgres dump. I don't know whether that has had an effect on the integrity of my data base.") If so, that PR should fix it.

anoadragon453 commented 4 years ago

@nomelif Please let us know if this issue is resolved in the next Synapse release. You may also try running on the latest develop branch (but it is not recommended for a production instance).

nomelif commented 4 years ago

This was broken for the two previous matrix versions from nixpkgs as well. I hoped that the updates would fix it.

Do you happen to know what those versions were?

We have messed a bit with JSON stuff recently (see #7674).

Looking at the git blame for nixpkgs, the previous version they distributed was 1.16.1 and the one before was 1.15.2.

nomelif commented 4 years ago

@nomelif Please let us know if this issue is resolved in the next Synapse release. You may also try running on the latest develop branch (but it is not recommended for a production instance).

I'll let you know. I don't want to mess around with multiple versions of synapse if the case happens to be that my db is flaky, tho.

nomelif commented 4 years ago

@anoadragon453 Ah, yeah I wonder if something came in as the wrong data type ("I have moved synapse twice via postgres dump. I don't know whether that has had an effect on the integrity of my data base.") If so, that PR should fix it.

I wonder if I could see what postgres returns somehow.

nomelif commented 4 years ago

Have updated my synapse to 1.18.0 (as it landed in nixpkgs-stable) but this is still broken.

nomelif commented 4 years ago

From journalctl:

Aug 01 11:36:17 puppisnix synapse[21688]: synapse.access.http.8008: [OPTIONS-196] - - 8008 - {None} Processed request: 0.002sec/-0.000sec (0.004sec, 0.000sec) (0.000sec/0.000sec/0) 0B 204 "OPTIONS /_matrix/client/r0/rooms/!VYsYJQNEpQSJlMMxiC%3Afam-ribbers.com/leave HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.2 Chrome/83.0.4103.94 Electron/9.0.2 Safari/537.36" [0 dbevts]
Aug 01 11:36:18 puppisnix synapse[21688]: root: [persist_events-3] Tried to decode 'None' as JSON and failed
Aug 01 11:36:18 puppisnix synapse[21688]: synapse.http.server: [POST-197] Failed handle request via 'RoomMembershipRestServlet': <XForwardedForRequest at 0x7f5abc3890 method='POST' uri='/_matrix/client/r0/rooms/!VYsYJQNEpQSJlMMxiC%3Afam-ribbers.com/leave' clientproto='HTTP/1.0' site=8008>
                                          Traceback (most recent call last):
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/http/server.py", line 228, in _async_render_wrapper
                                              callback_return = await self._async_render(request)
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/http/server.py", line 399, in _async_render
                                              callback_return = await raw_callback_return
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/rest/client/v1/room.py", line 747, in on_POST
                                              content=event_content,
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/handlers/room_member.py", line 285, in update_membership
                                              require_consent=require_consent,
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/handlers/room_member.py", line 501, in _update_membership
                                              require_consent=require_consent,
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/handlers/room_member.py", line 198, in _local_membership_update
                                              requester, event, context, extra_users=[target], ratelimit=ratelimit
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/util/metrics.py", line 73, in measured_func
                                              r = await func(self, *args, **kwargs)
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/handlers/message.py", line 878, in handle_new_client_event
                                              requester, event, context, ratelimit=ratelimit, extra_users=extra_users
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/handlers/message.py", line 1094, in persist_and_notify_client_event
                                              event, context=context
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/persist_events.py", line 148, in handle_queue_loop
                                              ret = await per_item_callback(item)
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/persist_events.py", line 258, in persisting_queue
                                              item.events_and_contexts, backfilled=item.backfilled
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/persist_events.py", line 323, in _persist_events
                                              room_id, ev_ctx_rm, latest_event_ids
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/persist_events.py", line 484, in _calculate_new_extremities
                                              e_id for event in new_events for e_id in event.prev_event_ids()
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
                                              result = result.throwExceptionIntoGenerator(g)
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
                                              return g.throw(self.type, self.value, self.tb)
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py", line 306, in _get_prevs_before_rejected
                                              "_get_prevs_before_rejected", _get_prevs_before_rejected_txn, chunk
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
                                              result = result.throwExceptionIntoGenerator(g)
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
                                              return g.throw(self.type, self.value, self.tb)
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/database.py", line 525, in runInteraction
                                              **kwargs
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
                                              result = result.throwExceptionIntoGenerator(g)
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
                                              return g.throw(self.type, self.value, self.tb)
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/database.py", line 573, in runWithConnection
                                              self._db_pool.runWithConnection(inner_func, *args, **kwargs)
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/threadpool.py", line 250, in inContext
                                              result = inContext.theWork()
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/threadpool.py", line 266, in <lambda>
                                              inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/context.py", line 122, in callWithContext
                                              return self.currentContext().callWithContext(ctx, func, *args, **kw)
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/context.py", line 85, in callWithContext
                                              return func(*args,**kw)
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 306, in _runWithConnection
                                              compat.reraise(excValue, excTraceback)
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/python/compat.py", line 464, in reraise
                                              raise exception.with_traceback(traceback)
                                            File "/nix/store/vkjhkf40njamh7h257dcw1vy9963g95g-python3.7-Twisted-20.3.0/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 297, in _runWithConnection
                                              result = func(conn, *args, **kw)
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/database.py", line 570, in inner_func
                                              return func(conn, *args, **kwargs)
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/database.py", line 416, in new_transaction
                                              r = func(cursor, *args, **kwargs)
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py", line 299, in _get_prevs_before_rejected_txn
                                              soft_failed = db_to_json(metadata).get("soft_failed")
                                            File "/nix/store/nkj4rasgvnf0ix9nzvw3zpmy5n7zwbvr-matrix-synapse-1.18.0/lib/python3.7/site-packages/synapse/storage/_base.py", line 109, in db_to_json
                                              return json.loads(db_content)
                                            File "/nix/store/87yihjqc6hyjc0vm41y554grgdrg9l92-python3.7-simplejson-3.17.0/lib/python3.7/site-packages/simplejson/__init__.py", line 525, in loads
                                              return _default_decoder.decode(s)
                                            File "/nix/store/87yihjqc6hyjc0vm41y554grgdrg9l92-python3.7-simplejson-3.17.0/lib/python3.7/site-packages/simplejson/decoder.py", line 370, in decode
                                              obj, end = self.raw_decode(s)
                                            File "/nix/store/87yihjqc6hyjc0vm41y554grgdrg9l92-python3.7-simplejson-3.17.0/lib/python3.7/site-packages/simplejson/decoder.py", line 392, in raw_decode
                                              raise TypeError("Input string must be text, not bytes")
                                          TypeError: Input string must be text, not bytes
Aug 01 11:36:18 puppisnix synapse[21688]: synapse.access.http.8008: [POST-197] - - 8008 - {@fsmnarmosta:puppisrausku.dy.fi} Processed request: 0.164sec/0.001sec (0.037sec, 0.000sec) (0.011sec/0.014sec/5) 55B 500 "POST /_matrix/client/r0/rooms/!VYsYJQNEpQSJlMMxiC%3Afam-ribbers.com/leave HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.2 Chrome/83.0.4103.94 Electron/9.0.2 Safari/537.36" [0 dbevts]
Aug 01 11:36:18 puppisnix synapse[21688]: synapse.logging.context: [POST-197] Re-starting finished log context POST-197
nomelif commented 4 years ago

If my db is the problem, would there be a way to see that by messing with psql directly?

auscompgeek commented 4 years ago

This log message in particular seems interesting:

root: [persist_events-3] Tried to decode 'None' as JSON and failed

As it turns out, the TypeError message from simplejson is extremely misleading and actually means whatever was passed in here was not a str or bytes (not necessarily that a bytes was passed).

So my hypothesis is that at least one row in the event_json table has NULL in the internal_metadata column.

erikjohnston commented 4 years ago

@nomelif can you check to see if there are any NULLs in your DB? SELECT * FROM event_json WHERE internal_metadata IS NULL LIMIT 5?

nomelif commented 4 years ago

No nulls:

synapse=> SELECT COUNT(*) FROM event_json WHERE internal_metadata IS NULL;
 count 
-------
     0
(1 row)
nomelif commented 4 years ago

Stronger statement: there is no column with nulls in that table

synapse=> SELECT * FROM event_json  WHERE event_id IS NULL;
 event_id | room_id | internal_metadata | json | format_version 
----------+---------+-------------------+------+----------------
(0 rows)

synapse=> SELECT * FROM event_json  WHERE room_id IS NULL;
 event_id | room_id | internal_metadata | json | format_version 
----------+---------+-------------------+------+----------------
(0 rows)

synapse=> SELECT * FROM event_json  WHERE internal_metadata IS NULL;
 event_id | room_id | internal_metadata | json | format_version 
----------+---------+-------------------+------+----------------
(0 rows)

synapse=> SELECT * FROM event_json  WHERE json IS NULL;
 event_id | room_id | internal_metadata | json | format_version 
----------+---------+-------------------+------+----------------
(0 rows)

synapse=> SELECT * FROM event_json  WHERE format_version IS NULL;
 event_id | room_id | internal_metadata | json | format_version 
----------+---------+-------------------+------+----------------
(0 rows)
erikjohnston commented 4 years ago

Interesting. Can you try: SELECT DISTINCT pg_typeof(internal_metadata) FROM event_json ;?

nomelif commented 4 years ago

Only text

synapse=> SELECT DISTINCT pg_typeof(internal_metadata) FROM event_json ;
 pg_typeof 
-----------
 text
(1 row)
nomelif commented 4 years ago

For some reason trying to join a room also fails. I haven't managed to get a good error yet tho.

erikjohnston commented 4 years ago

Hmm, the last thing I can think of trying is SELECT * FROM event_json WHERE internal_metadata NOT LIKE '{%' LIMIT 5;

nomelif commented 4 years ago 
synapse=> SELECT * FROM event_json WHERE internal_metadata NOT LIKE '{%' LIMIT 5;
 event_id | room_id | internal_metadata | json | format_version 
----------+---------+-------------------+------+----------------
(0 rows)
nomelif commented 4 years ago

Would there be a way to figure out the exact request synapse is making?

erikjohnston commented 4 years ago

You could turn up logging for SQL temporarily, though its very very verbose:

    synapse.storage.txn:
        level: DEBUG

    synapse.storage.SQL:
        level: DEBUG
nomelif commented 4 years ago

I have installed the thing through nix and configured it statelessly. I don't really have writable config files

nomelif commented 4 years ago

I'll try to figure out if I can catch the queries on the postgres side

auscompgeek commented 4 years ago

I have installed the thing through nix and configured it statelessly. I don't really have writable config files

Can't you change the log config in your nix config?

ptman commented 4 years ago

should be possible: https://nixos.org/nixos/options.html#services.matrix-synapse.logconfig

PC-Admin commented 4 years ago

Quite frustrating when you're trying to clear your client out a bit and you just encounter this over and over:

Screenshot from 2020-09-21 04-56-28

I assume it's the same error mentioned here.

richvdh commented 4 years ago

I assume it's the same error mentioned here.

this is likely to be a bad assumption. Please open a new issue and share the server logs.

richvdh commented 4 years ago

@nomelif are you still seeing this problem? there's likely little we can do to help unless you are able to adjust your logging settings.

clokep commented 3 years ago

Closing this due to lack of response.

nomelif commented 3 years ago

Sorry, I admit I forgot about this until the issue was closed. I managed (I think) to put the debug flags on. Trying to leave the room leaves this log in systemd

-- Logs begin at Mon 2020-11-16 12:05:23 EET, end at Tue 2020-12-22 10:20:19 EET. --
Dec 22 10:19:30 puppisnix synapse[32293]: synapse.crypto.keyring: [PUT-221] Requesting keys dict_items([('mayeul.net', {'ed25519:a_jkYf': 1608625170959})]) from notary server matrix.org
Dec 22 10:19:31 puppisnix synapse[32293]: synapse.http.matrixfederationclient: [PUT-221] {POST-O-279} [matrix.org] Completed request: 200 OK in 0.70 secs - POST matrix://matrix.org/_matrix/key/v2/query
Dec 22 10:19:31 puppisnix synapse[32293]: synapse.federation.transport.server: [PUT-221] Received txn 1607951656782 from mayeul.net. (PDUs: 0, EDUs: 1)
Dec 22 10:19:31 puppisnix synapse[32293]: synapse.access.http.8008: [GET-220] - - 8008 - {@fsmnarmosta:puppisrausku.dy.fi} Processed request: 13.936sec/-0.000sec (0.017sec, 0.000sec) (0.000sec/0.000sec/0) 513B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s814721_6263844_0_562080_21865_19_9105_529823_1 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.7 Chrome/83.0.4103.122 Electron/9.3.0 Safari/537.36" [0 dbevts]
Dec 22 10:19:31 puppisnix synapse[32293]: synapse.access.http.8008: [PUT-221] - - 8008 - {mayeul.net} Processed request: 0.879sec/-0.000sec (0.032sec, 0.001sec) (0.014sec/0.125sec/10) 11B 200 "PUT /_matrix/federation/v1/send/1607951656782 HTTP/1.0" "Synapse/1.23.0" [0 dbevts]
Dec 22 10:19:32 puppisnix synapse[32293]: synapse.federation.transport.server: [PUT-224] Received txn 1608582897445 from aasg.name. (PDUs: 0, EDUs: 1)
Dec 22 10:19:32 puppisnix synapse[32293]: synapse.access.http.8008: [PUT-224] - - 8008 - {aasg.name} Processed request: 0.022sec/-0.000sec (0.013sec, 0.000sec) (0.004sec/0.006sec/4) 11B 200 "PUT /_matrix/federation/v1/send/1608582897445 HTTP/1.0" "Synapse/1.23.0" [0 dbevts]
Dec 22 10:19:35 puppisnix synapse[32293]: synapse.http.federation.matrix_federation_agent: [federation_transaction_transmission_loop-197] Failed to connect to lukebentleyfox.net:8448: User timeout caused connection failure.
Dec 22 10:19:35 puppisnix synapse[32293]: synapse.http.matrixfederationclient: [federation_transaction_transmission_loop-197] {PUT-O-145} [lukebentleyfox.net] Request failed: PUT matrix://lukebentleyfox.net/_matrix/federation/v1/send/1608624606359: TimeoutError('')
Dec 22 10:19:38 puppisnix synapse[32293]: synapse.federation.transport.server: [PUT-225] Received txn 1601307097746 from matrix.vsund.de. (PDUs: 0, EDUs: 1)
Dec 22 10:19:38 puppisnix synapse[32293]: synapse.access.http.8008: [GET-223] - - 8008 - {@fsmnarmosta:puppisrausku.dy.fi} Processed request: 6.943sec/-0.000sec (0.012sec, 0.004sec) (0.000sec/0.000sec/0) 496B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s814721_6263845_0_562080_21865_19_9105_529823_1 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.7 Chrome/83.0.4103.122 Electron/9.3.0 Safari/537.36" [0 dbevts]
Dec 22 10:19:38 puppisnix synapse[32293]: synapse.access.http.8008: [PUT-225] - - 8008 - {matrix.vsund.de} Processed request: 0.144sec/-0.000sec (0.016sec, 0.001sec) (0.008sec/0.108sec/7) 11B 200 "PUT /_matrix/federation/v1/send/1601307097746 HTTP/1.0" "Synapse/1.19.2" [0 dbevts]
Dec 22 10:19:41 puppisnix synapse[32293]: synapse.federation.transport.server: [PUT-228] Received txn 1606163701091 from strahlungsfrei.de. (PDUs: 0, EDUs: 1)
Dec 22 10:19:41 puppisnix synapse[32293]: synapse.access.http.8008: [GET-227] - - 8008 - {@fsmnarmosta:puppisrausku.dy.fi} Processed request: 2.729sec/-0.000sec (0.011sec, 0.003sec) (0.000sec/0.000sec/0) 519B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s814721_6263846_0_562080_21865_19_9105_529823_1 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.7 Chrome/83.0.4103.122 Electron/9.3.0 Safari/537.36" [0 dbevts]
Dec 22 10:19:41 puppisnix synapse[32293]: synapse.access.http.8008: [PUT-228] - - 8008 - {strahlungsfrei.de} Processed request: 0.127sec/-0.000sec (0.018sec, 0.000sec) (0.004sec/0.098sec/3) 11B 200 "PUT /_matrix/federation/v1/send/1606163701091 HTTP/1.0" "Synapse/1.22.1" [0 dbevts]
Dec 22 10:19:44 puppisnix synapse[32293]: synapse.http.federation.well_known_resolver: [federation_transaction_transmission_loop-308] Fetching https://ajay.app/.well-known/matrix/server
Dec 22 10:19:44 puppisnix synapse[32293]: synapse.http.federation.well_known_resolver: [federation_transaction_transmission_loop-308] Response from .well-known: {'m.server': 'matrix.ajay.app:443'}
Dec 22 10:19:49 puppisnix synapse[32293]: synapse.federation.transport.server: [PUT-231] Received txn 1605327531949 from infotrode.cloud. (PDUs: 0, EDUs: 1)
Dec 22 10:19:49 puppisnix synapse[32293]: synapse.access.http.8008: [GET-230] - - 8008 - {@fsmnarmosta:puppisrausku.dy.fi} Processed request: 7.258sec/-0.000sec (0.010sec, 0.002sec) (0.000sec/0.000sec/0) 494B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s814721_6263847_0_562080_21865_19_9105_529823_1 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.7 Chrome/83.0.4103.122 Electron/9.3.0 Safari/537.36" [0 dbevts]
Dec 22 10:19:49 puppisnix synapse[32293]: synapse.access.http.8008: [PUT-231] - - 8008 - {infotrode.cloud} Processed request: 0.054sec/-0.000sec (0.014sec, 0.000sec) (0.003sec/0.025sec/3) 11B 200 "PUT /_matrix/federation/v1/send/1605327531949 HTTP/1.0" "Synapse/1.19.1" [0 dbevts]
Dec 22 10:19:50 puppisnix synapse[32293]: synapse.handlers.presence: [persist_presence_changes-7] Persisting 2 unpersisted presence updates
Dec 22 10:19:50 puppisnix synapse[32293]: synapse.http.matrixfederationclient: [federation_transaction_transmission_loop-7] {PUT-O-13} [samli.ch] Request failed: PUT matrix://samli.ch/_matrix/federation/v1/send/1608624606227: RequestTransmissionFailed:[Error([('SSL routines', 'tls_process_server_certificate', 'certificate verify failed')])]
Dec 22 10:19:51 puppisnix synapse[32293]: synapse.federation.transport.server: [PUT-234] Received txn 1601307097916 from matrix.vsund.de. (PDUs: 0, EDUs: 1)
Dec 22 10:19:51 puppisnix synapse[32293]: synapse.access.http.8008: [GET-233] - - 8008 - {@fsmnarmosta:puppisrausku.dy.fi} Processed request: 1.817sec/-0.000sec (0.015sec, 0.000sec) (0.000sec/0.000sec/0) 790B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s814721_6263848_0_562080_21865_19_9105_529823_1 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.7 Chrome/83.0.4103.122 Electron/9.3.0 Safari/537.36" [0 dbevts]
Dec 22 10:19:51 puppisnix synapse[32293]: synapse.access.http.8008: [PUT-234] - - 8008 - {matrix.vsund.de} Processed request: 0.055sec/-0.000sec (0.014sec, 0.001sec) (0.004sec/0.024sec/3) 11B 200 "PUT /_matrix/federation/v1/send/1601307097916 HTTP/1.0" "Synapse/1.19.2" [0 dbevts]
Dec 22 10:19:57 puppisnix synapse[32293]: synapse.http.federation.matrix_federation_agent: [federation_transaction_transmission_loop-181] Failed to connect to kueckieben.de:8448: User timeout caused connection failure.
Dec 22 10:19:57 puppisnix synapse[32293]: synapse.http.matrixfederationclient: [federation_transaction_transmission_loop-181] {PUT-O-134} [kueckieben.de] Request failed: PUT matrix://kueckieben.de/_matrix/federation/v1/send/1608624606348: TimeoutError('')
Dec 22 10:20:01 puppisnix synapse[32293]: synapse.federation.transport.server: [PUT-237] Received txn 1608030687256 from matrix.lowsamplingrate.eu. (PDUs: 0, EDUs: 1)
Dec 22 10:20:01 puppisnix synapse[32293]: synapse.access.http.8008: [GET-236] - - 8008 - {@fsmnarmosta:puppisrausku.dy.fi} Processed request: 10.736sec/-0.000sec (0.014sec, 0.000sec) (0.000sec/0.000sec/0) 506B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s814721_6263851_0_562080_21865_19_9105_529823_1 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.7 Chrome/83.0.4103.122 Electron/9.3.0 Safari/537.36" [0 dbevts]
Dec 22 10:20:01 puppisnix synapse[32293]: synapse.access.http.8008: [PUT-237] - - 8008 - {matrix.lowsamplingrate.eu} Processed request: 0.041sec/-0.000sec (0.015sec, 0.000sec) (0.004sec/0.009sec/3) 11B 200 "PUT /_matrix/federation/v1/send/1608030687256 HTTP/1.0" "Synapse/1.23.0" [0 dbevts]
Dec 22 10:20:05 puppisnix synapse[32293]: synapse.storage.databases.main.event_push_actions: [event_push_action_stream_orderings-0] Searching for stream ordering 1 month ago
Dec 22 10:20:05 puppisnix synapse[32293]: synapse.storage.databases.main.event_push_actions: [event_push_action_stream_orderings-0] Found stream ordering 1 month ago: it's 810743
Dec 22 10:20:05 puppisnix synapse[32293]: synapse.storage.databases.main.event_push_actions: [event_push_action_stream_orderings-0] Searching for stream ordering 1 day ago
Dec 22 10:20:05 puppisnix synapse[32293]: synapse.storage.databases.main.event_push_actions: [event_push_action_stream_orderings-0] Found stream ordering 1 day ago: it's 814548
Dec 22 10:20:05 puppisnix synapse[32293]: synapse.metrics: [] Collecting gc 1
Dec 22 10:20:14 puppisnix synapse[32293]: synapse.federation.transport.server: [PUT-240] Received txn 1607951656782 from mayeul.net. (PDUs: 0, EDUs: 1)
Dec 22 10:20:14 puppisnix synapse[32293]: synapse.access.http.8008: [PUT-240] - - 8008 - {mayeul.net} Processed request: 0.016sec/-0.000sec (0.009sec, 0.000sec) (0.003sec/0.004sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1607951656782 HTTP/1.0" "Synapse/1.23.0" [0 dbevts]
Dec 22 10:20:17 puppisnix synapse[32293]: root: [persist_events-3] Tried to decode 'None' as JSON and failed
Dec 22 10:20:17 puppisnix synapse[32293]: synapse.http.server: [POST-242] Failed handle request via 'RoomMembershipRestServlet': <XForwardedForRequest at 0x7f75e7b610 method='POST' uri='/_matrix/client/r0/rooms/!VYsYJQNEpQSJlMMxiC%3Afam-ribbers.com/leave' clientproto='HTTP/1.0' site=8008>
                                          Traceback (most recent call last):
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/persist_events.py", line 150, in handle_queue_loop
                                              ret = await per_item_callback(item)
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/persist_events.py", line 302, in persisting_queue
                                              return await self._persist_events(
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/persist_events.py", line 395, in _persist_events
                                              new_latest_event_ids = await self._calculate_new_extremities(
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/persist_events.py", line 558, in _calculate_new_extremities
                                              existing_prevs = await self.persist_events_store._get_prevs_before_rejected(
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/databases/main/events.py", line 295, in _get_prevs_before_rejected
                                              await self.db_pool.runInteraction(
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/database.py", line 632, in runInteraction
                                              result = await self.runWithConnection(
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/database.py", line 712, in runWithConnection
                                              return await make_deferred_yieldable(
                                            File "/nix/store/1pdgwjk10n49l2vd2yhv9njmp77hi0k9-python3.8-Twisted-20.3.0/lib/python3.8/site-packages/twisted/python/threadpool.py", line 250, in inContext
                                              result = inContext.theWork()
                                            File "/nix/store/1pdgwjk10n49l2vd2yhv9njmp77hi0k9-python3.8-Twisted-20.3.0/lib/python3.8/site-packages/twisted/python/threadpool.py", line 266, in <lambda>
                                              inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
                                            File "/nix/store/1pdgwjk10n49l2vd2yhv9njmp77hi0k9-python3.8-Twisted-20.3.0/lib/python3.8/site-packages/twisted/python/context.py", line 122, in callWithContext
                                              return self.currentContext().callWithContext(ctx, func, *args, **kw)
                                            File "/nix/store/1pdgwjk10n49l2vd2yhv9njmp77hi0k9-python3.8-Twisted-20.3.0/lib/python3.8/site-packages/twisted/python/context.py", line 85, in callWithContext
                                              return func(*args,**kw)
                                            File "/nix/store/1pdgwjk10n49l2vd2yhv9njmp77hi0k9-python3.8-Twisted-20.3.0/lib/python3.8/site-packages/twisted/enterprise/adbapi.py", line 306, in _runWithConnection
                                              compat.reraise(excValue, excTraceback)
                                            File "/nix/store/1pdgwjk10n49l2vd2yhv9njmp77hi0k9-python3.8-Twisted-20.3.0/lib/python3.8/site-packages/twisted/python/compat.py", line 464, in reraise
                                              raise exception.with_traceback(traceback)
                                            File "/nix/store/1pdgwjk10n49l2vd2yhv9njmp77hi0k9-python3.8-Twisted-20.3.0/lib/python3.8/site-packages/twisted/enterprise/adbapi.py", line 297, in _runWithConnection
                                              result = func(conn, *args, **kw)
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/database.py", line 707, in inner_func
                                              return func(db_conn, *args, **kwargs)
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/database.py", line 510, in new_transaction
                                              r = func(cursor, *args, **kwargs)
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/databases/main/events.py", line 289, in _get_prevs_before_rejected_txn
                                              soft_failed = db_to_json(metadata).get("soft_failed")
                                            File "/nix/store/dyhnjkhwhk3z1br3amlqb4wwyyljk2yn-matrix-synapse-1.24.0/lib/python3.8/site-packages/synapse/storage/_base.py", line 109, in db_to_json
                                              return json_decoder.decode(db_content)
                                            File "/nix/store/y986xn8838q7k9cr6zqq5j7cciaamry0-python3-3.8.5/lib/python3.8/json/decoder.py", line 337, in decode
                                              obj, end = self.raw_decode(s, idx=_w(s, 0).end())
                                          TypeError: expected string or bytes-like object
Dec 22 10:20:17 puppisnix synapse[32293]: synapse.access.http.8008: [POST-242] - - 8008 - {@fsmnarmosta:puppisrausku.dy.fi} Processed request: 0.171sec/-0.000sec (0.033sec, 0.000sec) (0.006sec/0.015sec/6) 55B 500 "POST /_matrix/client/r0/rooms/!VYsYJQNEpQSJlMMxiC%3Afam-ribbers.com/leave HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.7 Chrome/83.0.4103.122 Electron/9.3.0 Safari/537.36" [0 dbevts]

I admit I am not sure if I configured the thing correctly. I took the default log settings file and appended the few lines given by @erikjohnston 

version: 1

# In systemd's journal, loglevel is implicitly stored, so let's omit it
# from the message text.
formatters:
    journal_fmt:
        format: '%(name)s: [%(request)s] %(message)s'

filters:
    context:
        (): synapse.util.logcontext.LoggingContextFilter
        request: ""

handlers:
    journal:
        class: systemd.journal.JournalHandler
        formatter: journal_fmt
        filters: [context]
        SYSLOG_IDENTIFIER: synapse

root:
    level: INFO
    handlers: [journal]

disable_existing_loggers: False

synapse.storage.txn:
    level: DEBUG

synapse.storage.SQL:
    level: DEBUG
richvdh commented 3 years ago 
synapse.storage.txn:
   level: DEBUG

synapse.storage.SQL:
   level: DEBUG

these should be under a loggers key. Take a look at the default log config: https://github.com/matrix-org/synapse/blob/master/docs/sample_log_config.yaml#L46

nomelif commented 3 years ago

In the time between @richvdh 's last message, I tried to get rid of the rooms in the hopes of re-joining them. I used a command of the kind:

curl -XPOST 'http://localhost:8008/_synapse/admin/v1/rooms/!VYsYJQNEpQSJlMMxiC:fam-ribbers.com/delete' -d '{"purge": true, "force_purge": true}' -H 'Authorization: Bearer <snip>'
{"errcode":"M_UNKNOWN","error":"Users are still joined to this room"}

This managed to hide the room from element, but it is in a state where I can not re-join it.

I added the logger lines and tried to capture joining it:

-- Logs begin at Sun 2021-02-14 23:29:24 EET, end at Mon 2021-03-15 13:59:04 EET. --
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_prune_old_user_ips-a2a2} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_update_client_ips_batch-a2a3}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_prune_old_user_ips-a2a2} (1613390261830,)
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_update_client_ips_batch-a2a3} 0.002103 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_prune_old_user_ips-a2a2} 0.003092 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_prune_old_user_ips-a2a2} 0.011414 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_destination_retry_timings-a2a4}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_destination_retry_timings-a2a4} SELECT destination, failure_ts, retry_last_ts, retry_interval FROM destinations WHERE destination = ?
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_destination_retry_timings-a2a4} ['stokedmind.net']
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_destination_retry_timings-a2a4} 0.001037 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_destination_retry_timings-a2a4} 0.004890 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_received_txn_response-a2a5}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_received_txn_response-a2a5} SELECT transaction_id, origin, ts, response_code, response_json, has_been_referenced FROM received_transactions WHERE transaction_id = ? AND origin = ?
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_received_txn_response-a2a5} ['1615736547271', 'stokedmind.net']
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_received_txn_response-a2a5} 0.001000 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_received_txn_response-a2a5} 0.004875 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {set_received_txn_response-a2a6}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {set_received_txn_response-a2a6} INSERT INTO received_transactions (transaction_id, origin, response_code, response_json, ts) VALUES(?, ?, ?, ?, ?)
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {set_received_txn_response-a2a6} ('1615736547271', 'stokedmind.net', 200, <memory at 0x7f7c94c700>, 1615809466429)
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {set_received_txn_response-a2a6} 0.000866 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {set_received_txn_response-a2a6} 0.005070 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_prune_old_user_ips-a2a7}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_prune_old_user_ips-a2a7} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_prune_old_user_ips-a2a7} (1613390266830,)
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_update_client_ips_batch-a2a8}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_update_client_ips_batch-a2a8} 0.002631 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_prune_old_user_ips-a2a7} 0.004254 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:46+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_prune_old_user_ips-a2a7} 0.010539 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:51+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_prune_old_user_ips-a2a9}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:51+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_prune_old_user_ips-a2a9} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:51+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_prune_old_user_ips-a2a9} (1613390271830,)
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:51+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_update_client_ips_batch-a2aa}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:51+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_update_client_ips_batch-a2aa} 0.002053 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:51+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_prune_old_user_ips-a2a9} 0.003769 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:51+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_prune_old_user_ips-a2a9} 0.007998 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:56+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_prune_old_user_ips-a2ab}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:56+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_prune_old_user_ips-a2ab} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:56+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_prune_old_user_ips-a2ab} (1613390276830,)
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:56+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_update_client_ips_batch-a2ac}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:56+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_update_client_ips_batch-a2ac} 0.001198 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:56+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_prune_old_user_ips-a2ab} 0.002737 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:57:56+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_prune_old_user_ips-a2ab} 0.008071 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_cleanup_old_transaction_ids-a2ad}
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_cleanup_old_transaction_ids-a2ad} DELETE FROM event_txn_id WHERE inserted_ts < ?
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_cleanup_old_transaction_ids-a2ad} (1615723081777,)
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_cleanup_old_transaction_ids-a2ad} 0.001480 sec
Mar 15 13:58:01 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_cleanup_old_transaction_ids-a2ad} 0.007672 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_censor_redactions_fetch-a2ae}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_censor_redactions_fetch-a2ae} SELECT redactions.event_id, redacts FROM redactions LEFT JOIN events AS original_event ON ( redacts = original_event.event_id ) WHERE NOT have_censored AND redactions.received_ts <= ? ORDER BY redactions.received_ts ASC LIMIT ?
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_censor_redactions_fetch-a2ae} (1615809481779, 100)
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_censor_redactions_fetch-a2ae} 0.001045 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_censor_redactions_fetch-a2ae} 0.005017 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_update_censor_txn-a2af}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_update_censor_txn-a2af} 0.000789 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_prune_old_user_ips-a2b0}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_prune_old_user_ips-a2b0} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_prune_old_user_ips-a2b0} (1613390281829,)
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_update_client_ips_batch-a2b1}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_update_client_ips_batch-a2b1} 0.001608 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_prune_old_user_ips-a2b0} 0.004008 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:01+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_prune_old_user_ips-a2b0} 0.009960 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {delete_old_ui_auth_sessions-a2b2}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {delete_old_ui_auth_sessions-a2b2} SELECT session_id FROM ui_auth_sessions WHERE creation_time <= ?
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {delete_old_ui_auth_sessions-a2b2} [1615636682073]
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {delete_old_ui_auth_sessions-a2b2} 0.000873 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {delete_old_ui_auth_sessions-a2b2} 0.005824 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_user_ids_requiring_device_list_resync-a2b3}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_user_ids_requiring_device_list_resync-a2b3} SELECT user_id FROM device_lists_remote_resync
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_user_ids_requiring_device_list_resync-a2b3} 0.001134 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_user_ids_requiring_device_list_resync-a2b3} 0.003989 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_destination_retry_timings-a2b4}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_destination_retry_timings-a2b4} SELECT destination, failure_ts, retry_last_ts, retry_interval FROM destinations WHERE destination = ?
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_destination_retry_timings-a2b4} ['puhoy.net']
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_remote_profile_cache_entries_that_expire-a2b5}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_remote_profile_cache_entries_that_expire-a2b5} SELECT user_id, displayname, avatar_url FROM remote_profile_cache WHERE last_check < ?
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_remote_profile_cache_entries_that_expire-a2b5} (1615723082092,)
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_destination_retry_timings-a2b4} 0.002863 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_remote_profile_cache_entries_that_expire-a2b5} 0.001198 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_destination_retry_timings-a2b4} 0.007566 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_remote_profile_cache_entries_that_expire-a2b5} 0.009141 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_destination_retry_timings-a2b6}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_destination_retry_timings-a2b6} SELECT destination, failure_ts, retry_last_ts, retry_interval FROM destinations WHERE destination = ?
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_destination_retry_timings-a2b6} ['netzgemeinde.eu']
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_rooms_with_many_extremities-a2b7}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_rooms_with_many_extremities-a2b7} SELECT room_id FROM event_forward_extremities WHERE 1=1 GROUP BY room_id HAVING count(*) > ? ORDER BY count(*) DESC LIMIT ?
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_rooms_with_many_extremities-a2b7} [10, 5]
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_destination_retry_timings-a2b6} 0.003088 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_rooms_with_many_extremities-a2b7} 0.002812 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_destination_retry_timings-a2b6} 0.008862 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_rooms_with_many_extremities-a2b7} 0.007415 sec
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {update_presence-a2b8}
Mar 15 13:58:02 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {update_presence-a2b8} INSERT INTO presence_stream (currently_active, last_active_ts, last_federation_update_ts, last_user_sync_ts, state, status_msg, stream_id, user_id) VALUES(?, ?, ?, ?, ?, ?, ?, ?)
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {update_presence-a2b8} ((True, 1615809460700, 1615809416966, 1615809460702, 'online', None, 7421682, '@fsmnarmosta:puppisrausku.dy.fi'), (True, 1615809419570, 1615809426366, 0, 'online', None, 7421683, '@wowaname:matrix.heldscal.la'), (True, 1615809444876, 1615809445700, 0, 'online', None, 7421684, '@cat:maunium.net'), (True, 1615808540040, 1615809466427, 0, 'online', None, 7421685, '@reyawn:stokedmind.net'), (True, 1615809268367, 1615809431200, 0, 'online', None, 7421686, '@mayeul:mayeul.net'))
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {update_presence-a2b8} 0.002430 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {update_presence-a2b8} DELETE FROM presence_stream WHERE stream_id < ? AND user_id = ANY(?)
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {update_presence-a2b8} [7421686, ['@fsmnarmosta:puppisrausku.dy.fi', '@wowaname:matrix.heldscal.la', '@cat:maunium.net', '@reyawn:stokedmind.net', '@mayeul:mayeul.net']]
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {update_presence-a2b8} 0.002013 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {update_presence-a2b8} 0.013407 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {update_cached_last_access_time-a2b9}
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {update_cached_last_access_time-a2b9} UPDATE remote_media_cache SET last_access_ts = ? WHERE media_origin = ? AND media_id = ?
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {update_cached_last_access_time-a2b9} <generator object MediaRepositoryStore.update_cached_last_access_time.<locals>.update_cache_txn.<locals>.<genexpr> at 0x7f7cf2f120>
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {update_cached_last_access_time-a2b9} 0.000055 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {update_cached_last_access_time-a2b9} UPDATE local_media_repository SET last_access_ts = ? WHERE media_id = ?
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {update_cached_last_access_time-a2b9} <generator object MediaRepositoryStore.update_cached_last_access_time.<locals>.update_cache_txn.<locals>.<genexpr> at 0x7f7cf2f120>
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {update_cached_last_access_time-a2b9} 0.000049 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {update_cached_last_access_time-a2b9} 0.008919 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {generate_user_daily_visits-a2ba}
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {generate_user_daily_visits-a2ba} INSERT INTO user_daily_visits (user_id, device_id, timestamp, user_agent) SELECT u.user_id, u.device_id, ?, MAX(u.user_agent) FROM user_ips AS u LEFT JOIN ( SELECT user_id, device_id, timestamp FROM user_daily_visits WHERE timestamp = ? ) udv ON u.user_id = udv.user_id AND u.device_id=udv.device_id INNER JOIN users ON users.name=u.user_id WHERE last_seen > ? AND last_seen <= ? AND udv.timestamp IS NULL AND users.is_guest=0 AND users.appservice_id IS NULL GROUP BY u.user_id, u.device_id
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {generate_user_daily_visits-a2ba} (1615766400000, 1615766400000, 1615809182350, 1615809482351)
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {generate_user_daily_visits-a2ba} 0.003039 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:02+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {generate_user_daily_visits-a2ba} 0.008140 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_prev_events_for_room-a2bb}
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_prev_events_for_room-a2bb} SELECT e.event_id FROM event_forward_extremities AS f INNER JOIN events AS e USING (event_id) WHERE f.room_id = ? ORDER BY e.depth DESC LIMIT 10
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_prev_events_for_room-a2bb} ('!ZPbDMeSXDwjIJrdCvo:fam-ribbers.com',)
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_prev_events_for_room-a2bb} 0.001795 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_prev_events_for_room-a2bb} 0.005581 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_profile_displayname-a2bc}
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_profile_displayname-a2bc} SELECT displayname FROM profiles WHERE user_id = ?
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_profile_displayname-a2bc} ['fsmnarmosta']
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_profile_displayname-a2bc} 0.000856 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_profile_displayname-a2bc} 0.004191 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_profile_avatar_url-a2bd}
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_profile_avatar_url-a2bd} SELECT avatar_url FROM profiles WHERE user_id = ?
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_profile_avatar_url-a2bd} ['fsmnarmosta']
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_profile_avatar_url-a2bd} 0.000819 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_profile_avatar_url-a2bd} 0.004219 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {clean_room_for_join-a2be}
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {clean_room_for_join-a2be} DELETE FROM event_forward_extremities WHERE room_id = ?
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {clean_room_for_join-a2be} ('!ZPbDMeSXDwjIJrdCvo:fam-ribbers.com',)
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {clean_room_for_join-a2be} 0.000911 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:04+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {clean_room_for_join-a2be} 0.003999 sec
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:06+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_prune_old_user_ips-a2bf}
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:06+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_prune_old_user_ips-a2bf} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:06+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_prune_old_user_ips-a2bf} (1613390286829,)
Mar 15 13:58:06 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:06+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_update_client_ips_batch-a2c0}
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:06+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_update_client_ips_batch-a2c0} 0.001374 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:06+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_prune_old_user_ips-a2bf} 0.003115 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:06+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_prune_old_user_ips-a2bf} 0.009870 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_received_txn_response-a2c1}
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_received_txn_response-a2c1} SELECT transaction_id, origin, ts, response_code, response_json, has_been_referenced FROM received_transactions WHERE transaction_id = ? AND origin = ?
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_received_txn_response-a2c1} ['1615631899809', 'envs.net']
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_received_txn_response-a2c1} 0.000797 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_received_txn_response-a2c1} 0.004003 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_load_next_mult_id-a2c2}
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_load_next_mult_id-a2c2} SELECT nextval(?) FROM generate_series(1, ?)
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_load_next_mult_id-a2c2} ('receipts_sequence', 1)
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_load_next_mult_id-a2c2} 0.000686 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_load_next_mult_id-a2c2} 0.003248 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {insert_linearized_receipt-a2c3}
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {insert_linearized_receipt-a2c3} SELECT stream_ordering, received_ts FROM events WHERE event_id = ?
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {insert_linearized_receipt-a2c3} ['$rh0-Vfi3m4BSxLP2pYBIYANtiNLdcfMiznUWSO_mThU']
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {insert_linearized_receipt-a2c3} 0.000763 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {insert_linearized_receipt-a2c3} SELECT stream_ordering, event_id FROM events INNER JOIN receipts_linearized as r USING (event_id, room_id) WHERE r.room_id = ? AND r.receipt_type = ? AND r.user_id = ?
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {insert_linearized_receipt-a2c3} ('!UbCmIlGTHNIgIRZcpt:nheko.im', 'm.read', '@creme:envs.net')
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {insert_linearized_receipt-a2c3} 0.001260 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {insert_linearized_receipt-a2c3} INSERT INTO receipts_linearized (room_id, receipt_type, user_id, stream_id, event_id, data) VALUES (?, ?, ?, ?, ?, ?) ON CONFLICT (room_id, receipt_type, user_id) DO UPDATE SET stream_id=EXCLUDED.stream_id, event_id=EXCLUDED.event_id, data=EXCLUDED.data
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {insert_linearized_receipt-a2c3} ['!UbCmIlGTHNIgIRZcpt:nheko.im', 'm.read', '@creme:envs.net', 713242, '$rh0-Vfi3m4BSxLP2pYBIYANtiNLdcfMiznUWSO_mThU', '{"ts":1615808984042}']
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {insert_linearized_receipt-a2c3} 0.000804 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {insert_linearized_receipt-a2c3} DELETE FROM event_push_actions  WHERE user_id = ? AND room_id = ? AND  stream_ordering <= ? AND ((stream_ordering < ? AND highlight = 1) or highlight = 0)
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {insert_linearized_receipt-a2c3} ('@creme:envs.net', '!UbCmIlGTHNIgIRZcpt:nheko.im', 865470, 856691)
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {insert_linearized_receipt-a2c3} 0.001162 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {insert_linearized_receipt-a2c3} DELETE FROM event_push_summary WHERE room_id = ? AND user_id = ? AND stream_ordering <= ?
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {insert_linearized_receipt-a2c3} ('!UbCmIlGTHNIgIRZcpt:nheko.im', '@creme:envs.net', 865470)
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {insert_linearized_receipt-a2c3} 0.000886 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {insert_linearized_receipt-a2c3} 0.019686 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {MultiWriterIdGenerator._update_table-a2c4}
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {MultiWriterIdGenerator._update_table-a2c4} INSERT INTO stream_positions (stream_name, instance_name, stream_id) VALUES (?, ?, ?) ON CONFLICT (stream_name, instance_name) DO UPDATE SET stream_id = GREATEST(stream_positions.stream_id, EXCLUDED.stream_id)
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {MultiWriterIdGenerator._update_table-a2c4} ('receipts', 'master', (713242,))
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {MultiWriterIdGenerator._update_table-a2c4} 0.001206 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {MultiWriterIdGenerator._update_table-a2c4} 0.003814 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {insert_graph_receipt-a2c5}
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {insert_graph_receipt-a2c5} DELETE FROM receipts_graph WHERE room_id = ? AND receipt_type = ? AND user_id = ?
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {insert_graph_receipt-a2c5} ['!UbCmIlGTHNIgIRZcpt:nheko.im', 'm.read', '@creme:envs.net']
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {insert_graph_receipt-a2c5} 0.000999 sec
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {insert_graph_receipt-a2c5} INSERT INTO receipts_graph (room_id, receipt_type, user_id, event_ids, data) VALUES(?, ?, ?, ?, ?)
Mar 15 13:58:08 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {insert_graph_receipt-a2c5} ('!UbCmIlGTHNIgIRZcpt:nheko.im', 'm.read', '@creme:envs.net', '["$rh0-Vfi3m4BSxLP2pYBIYANtiNLdcfMiznUWSO_mThU"]', '{"ts":1615808984042}')
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {insert_graph_receipt-a2c5} 0.000697 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {insert_graph_receipt-a2c5} 0.008489 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_get_linearized_receipts_for_rooms-a2c6}
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_get_linearized_receipts_for_rooms-a2c6} SELECT * FROM receipts_linearized WHERE stream_id > ? AND stream_id <= ? AND room_id = ANY(?)
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_get_linearized_receipts_for_rooms-a2c6} [713241, 713242, ['!UbCmIlGTHNIgIRZcpt:nheko.im']]
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {set_received_txn_response-a2c7}
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {set_received_txn_response-a2c7} INSERT INTO received_transactions (transaction_id, origin, response_code, response_json, ts) VALUES(?, ?, ?, ?, ?)
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {set_received_txn_response-a2c7} ('1615631899809', 'envs.net', 200, <memory at 0x7f7c94c700>, 1615809488183)
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_get_linearized_receipts_for_rooms-a2c6} 0.004382 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {set_received_txn_response-a2c7} 0.002203 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_get_linearized_receipts_for_rooms-a2c6} 0.010038 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:08+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {set_received_txn_response-a2c7} 0.020924 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_prune_old_user_ips-a2c8}
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_prune_old_user_ips-a2c8} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_prune_old_user_ips-a2c8} (1613390291830,)
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_update_client_ips_batch-a2c9}
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_update_client_ips_batch-a2c9} 0.001371 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_prune_old_user_ips-a2c8} 0.003284 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_prune_old_user_ips-a2c8} 0.010704 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_received_txn_response-a2ca}
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_received_txn_response-a2ca} SELECT transaction_id, origin, ts, response_code, response_json, has_been_referenced FROM received_transactions WHERE transaction_id = ? AND origin = ?
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_received_txn_response-a2ca} ['1615017244810', 'gnugen.ch']
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_received_txn_response-a2ca} 0.000989 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_received_txn_response-a2ca} 0.005173 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {update_presence-a2cb}
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {update_presence-a2cb} INSERT INTO presence_stream (currently_active, last_active_ts, last_federation_update_ts, last_user_sync_ts, state, status_msg, stream_id, user_id) VALUES(?, ?, ?, ?, ?, ?, ?, ?)
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {update_presence-a2cb} ((False, 1615809490705, 1615809491860, 0, 'unavailable', None, 7421687, '@afontain:gnugen.ch'),)
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {update_presence-a2cb} 0.000883 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {update_presence-a2cb} DELETE FROM presence_stream WHERE stream_id < ? AND user_id = ANY(?)
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {update_presence-a2cb} [7421687, ['@afontain:gnugen.ch']]
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {update_presence-a2cb} 0.000797 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {update_presence-a2cb} 0.008554 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {set_received_txn_response-a2cc}
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {set_received_txn_response-a2cc} INSERT INTO received_transactions (transaction_id, origin, response_code, response_json, ts) VALUES(?, ?, ?, ?, ?)
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {set_received_txn_response-a2cc} ('1615017244810', 'gnugen.ch', 200, <memory at 0x7f7c94c700>, 1615809491879)
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {set_received_txn_response-a2cc} 0.000838 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {set_received_txn_response-a2cc} 0.005265 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_received_txn_response-a2cd}
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_received_txn_response-a2cd} SELECT transaction_id, origin, ts, response_code, response_json, has_been_referenced FROM received_transactions WHERE transaction_id = ? AND origin = ?
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_received_txn_response-a2cd} ['1615017245452', 'gnugen.ch']
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_received_txn_response-a2cd} 0.000806 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_received_txn_response-a2cd} 0.003550 sec
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {update_presence-a2ce}
Mar 15 13:58:11 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {update_presence-a2ce} INSERT INTO presence_stream (currently_active, last_active_ts, last_federation_update_ts, last_user_sync_ts, state, status_msg, stream_id, user_id) VALUES(?, ?, ?, ?, ?, ?, ?, ?)
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {update_presence-a2ce} ((True, 1615809488940, 1615809491957, 0, 'online', None, 7421688, '@afontain:gnugen.ch'),)
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {update_presence-a2ce} 0.000794 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {update_presence-a2ce} DELETE FROM presence_stream WHERE stream_id < ? AND user_id = ANY(?)
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {update_presence-a2ce} [7421688, ['@afontain:gnugen.ch']]
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {update_presence-a2ce} 0.000796 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {update_presence-a2ce} 0.026562 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {set_received_txn_response-a2cf}
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {set_received_txn_response-a2cf} INSERT INTO received_transactions (transaction_id, origin, response_code, response_json, ts) VALUES(?, ?, ?, ?, ?)
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {set_received_txn_response-a2cf} ('1615017245452', 'gnugen.ch', 200, <memory at 0x7f7c94c100>, 1615809491994)
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:11+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {set_received_txn_response-a2cf} 0.000709 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:12+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {set_received_txn_response-a2cf} 0.011589 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:15+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_received_txn_response-a2d0}
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:15+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_received_txn_response-a2d0} SELECT transaction_id, origin, ts, response_code, response_json, has_been_referenced FROM received_transactions WHERE transaction_id = ? AND origin = ?
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:15+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_received_txn_response-a2d0} ['1614292490945', 'synapse.vpzom.click']
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:15+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_received_txn_response-a2d0} 0.000812 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:15+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_received_txn_response-a2d0} 0.005095 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:15+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {set_received_txn_response-a2d1}
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:15+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {set_received_txn_response-a2d1} INSERT INTO received_transactions (transaction_id, origin, response_code, response_json, ts) VALUES(?, ?, ?, ?, ?)
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:15+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {set_received_txn_response-a2d1} ('1614292490945', 'synapse.vpzom.click', 200, <memory at 0x7f7c94c700>, 1615809495993)
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:15+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {set_received_txn_response-a2d1} 0.000774 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:15+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {set_received_txn_response-a2d1} 0.004358 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_prune_old_user_ips-a2d2}
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_prune_old_user_ips-a2d2} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_prune_old_user_ips-a2d2} (1613390296830,)
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_update_client_ips_batch-a2d3}
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_update_client_ips_batch-a2d3} 0.001382 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {_prune_old_user_ips-a2d2} 0.003128 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {_prune_old_user_ips-a2d2} 0.009052 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_received_txn_response-a2d4}
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_received_txn_response-a2d4} SELECT transaction_id, origin, ts, response_code, response_json, has_been_referenced FROM received_transactions WHERE transaction_id = ? AND origin = ?
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_received_txn_response-a2d4} ['1613656402997', 'brixit.nl']
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_received_txn_response-a2d4} 0.019908 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_received_txn_response-a2d4} 0.024336 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_room_version-a2d5}
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_room_version-a2d5} SELECT room_version FROM rooms WHERE room_id = ?
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_room_version-a2d5} ['!VYsYJQNEpQSJlMMxiC:fam-ribbers.com']
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_room_version-a2d5} 0.000800 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_room_version-a2d5} 0.004876 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_current_state_ids-a2d6}
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_current_state_ids-a2d6} SELECT type, state_key, event_id FROM current_state_events WHERE room_id = ?
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_current_state_ids-a2d6} ('!VYsYJQNEpQSJlMMxiC:fam-ribbers.com',)
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_current_state_ids-a2d6} 0.000947 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_current_state_ids-a2d6} 0.004766 sec
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {do_fetch-a2d7}
Mar 15 13:58:16 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {do_fetch-a2d7} SELECT e.event_id, e.stream_ordering, ej.internal_metadata, ej.json, ej.format_version, r.room_version, rej.reason FROM events AS e JOIN event_json AS ej USING (event_id) LEFT JOIN rooms r ON r.room_id = e.room_id LEFT JOIN rejections as rej USING (event_id) WHERE e.event_id = ANY(?)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {do_fetch-a2d7} [['$tzT5e0HCfAMuV_rbqlO5Fvq-eM_4fWwz0eHUqyislxM']]
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {do_fetch-a2d7} 0.013087 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {do_fetch-a2d7} SELECT event_id, redacts FROM redactions WHERE redacts = ANY(?)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {do_fetch-a2d7} [['$tzT5e0HCfAMuV_rbqlO5Fvq-eM_4fWwz0eHUqyislxM']]
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {do_fetch-a2d7} 0.000704 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {do_fetch-a2d7} 0.019484 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {set_received_txn_response-a2d8}
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {set_received_txn_response-a2d8} INSERT INTO received_transactions (transaction_id, origin, response_code, response_json, ts) VALUES(?, ?, ?, ?, ?)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {set_received_txn_response-a2d8} ('1613656402997', 'brixit.nl', 200, <memory at 0x7f7c94ce80>, 1615809496976)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {set_received_txn_response-a2d8} 0.000865 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:16+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {set_received_txn_response-a2d8} 0.005144 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_received_txn_response-a2d9}
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_received_txn_response-a2d9} SELECT transaction_id, origin, ts, response_code, response_json, has_been_referenced FROM received_transactions WHERE transaction_id = ? AND origin = ?
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_received_txn_response-a2d9} ['1613656403019', 'brixit.nl']
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_received_txn_response-a2d9} 0.001109 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_received_txn_response-a2d9} 0.005091 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_presence_for_users-a2da}
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_presence_for_users-a2da} SELECT user_id, state, last_active_ts, last_federation_update_ts, last_user_sync_ts, status_msg, currently_active FROM presence_stream WHERE user_id = ANY(?)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_presence_for_users-a2da} [['@martijn:brixit.nl']]
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_presence_for_users-a2da} 0.001297 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_presence_for_users-a2da} 0.004981 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {update_presence-a2db}
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {update_presence-a2db} INSERT INTO presence_stream (currently_active, last_active_ts, last_federation_update_ts, last_user_sync_ts, state, status_msg, stream_id, user_id) VALUES(?, ?, ?, ?, ?, ?, ?, ?)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {update_presence-a2db} ((True, 1615809482350, 1615809497266, 0, 'online', None, 7421689, '@martijn:brixit.nl'),)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {update_presence-a2db} 0.000822 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {update_presence-a2db} DELETE FROM presence_stream WHERE stream_id < ? AND user_id = ANY(?)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {update_presence-a2db} [7421689, ['@martijn:brixit.nl']]
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {update_presence-a2db} 0.000722 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {update_presence-a2db} 0.006599 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_rooms_for_user_with_stream_ordering-a2dc}
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_rooms_for_user_with_stream_ordering-a2dc} SELECT room_id, e.instance_name, e.stream_ordering FROM current_state_events AS c INNER JOIN events AS e USING (room_id, event_id) WHERE c.type = 'm.room.member' AND state_key = ? AND c.membership = ?
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {get_rooms_for_user_with_stream_ordering-a2dc} ('@martijn:brixit.nl', 'join')
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {get_rooms_for_user_with_stream_ordering-a2dc} 0.002376 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {get_rooms_for_user_with_stream_ordering-a2dc} 0.005312 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {set_received_txn_response-a2dd}
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {set_received_txn_response-a2dd} INSERT INTO received_transactions (transaction_id, origin, response_code, response_json, ts) VALUES(?, ?, ?, ?, ?)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {set_received_txn_response-a2dd} ('1613656403019', 'brixit.nl', 200, <memory at 0x7f7c94c4c0>, 1615809497288)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL time] {set_received_txn_response-a2dd} 0.003145 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:17+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN END] {set_received_txn_response-a2dd} 0.009352 sec
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {_prune_old_user_ips-a2de}
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {_prune_old_user_ips-a2de} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL values] {_prune_old_user_ips-a2de} (1613390321783,)
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.txn:[TXN START] {get_user_ids_requiring_device_list_resync-a2df}
Mar 15 13:58:41 puppisnix homeserver[32152]: logging during logging: 2021-03-15T13:58:41+0200 [stderr#error] ERROR:twisted:DEBUG:synapse.storage.SQL:[SQL] {get_user_ids_requiring_device_list_resync-a2df} SELECT user_id FROM device_lists_remote_resync

I am starting to ponder the benefits of simply nuking postgres and reinstalling everything. It seems fairly clear that there is some broken lingering state which I have myself partly amplified while trying to fix it.

richvdh commented 3 years ago

sorry for the slow response time here.

I added the logger lines and tried to capture joining it:

A couple of things here. Firstly, I'm afraid it's not complete - although it shows the DEBUG lines now, it no longer shows the original error, so we can't tell what operation you were trying to do.

Secondly:

logging during logging: ... [stderr#error] ERROR:twisted:

This suggests that you have directed log output to stderr. This isn't a great idea because, by default, stderr is redirected to the logs - so you get a loop. The loop gets caught, but the resultant logging is very unclear. You can suppress the redirection of stderr with a --no-redirect-stdio commandline option, but it would probably be better to update your log config to send the logging direct to where you want it. (https://github.com/matrix-org/synapse/issues/6550 covers this rather confusing behaviour.)

In summary: it looks like your log config is somewhat bogus. If you upload the config file here, we might be able to offer advice as to what is wrong with it.

nomelif commented 3 years ago

I am afraid I have re-installed matrix with a wiped postgres. It works with the same configuration as before, so I am inclined to believe that something went awry while migrating it. Thank you for your time and sorry for wasting it.

richvdh commented 3 years ago

never mind, if it works now we'll consider that a win :)