matrix-org / synapse

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

POST join from matrix bridge sometimes takes very long (> 30 sec.) #13461

Open hubermat opened 2 years ago

hubermat commented 2 years ago

Description

Hi,

Our own matrix bridge runs sometimes into long running join requests (> 30 sec.), which triggers a timeout on the bridge side. This is what the bridge executes:

return bridge.getIntent()._ensureJoined(roomAlias, false, undefined, true);

Typically this takes 0.03 sec.. But sometimes it takes a loooong time!

Here is the result from homeserver.log (filtered only for POST-9744812):

2022-08-04 00:25:26,333 - synapse.http.site - 362 - INFO - POST-9744812 - Connection from client lost before response was sent
2022-08-04 00:26:06,821 - synapse.handlers.message - 1275 - INFO - POST-9744812 - Not bothering to persist state event $0AvNQaCtErI11Pl4OvGPhfTJypW6eLzu9gSvEZ8-q6E duplicated by $L6xUQADxe6Va4rDMXgTgEDIqfdFNHXSWtf8SZl14Elw
2022-08-04 00:26:06,821 - synapse.http.server - 795 - WARNING - POST-9744812 - Not sending response to request <XForwardedForRequest at 0x7f03dced95e0 method='POST' uri='/_matrix/client/r0/join/%23ctg_12e8de3e-a2e9-40cb-a858-75ab7697d15e%3Achat.church.tools?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'>, already disconnected.
2022-08-04 00:26:06,822 - synapse.access.http.8008 - 450 - INFO - POST-9744812 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 70.490sec/-40.489sec (0.005sec, 0.003sec) (0.005sec/0.033sec/16) 0B 200! "POST /_matrix/client/r0/join/%23ctg_12e8de3e-a2e9-40cb-a858-75ab7697d15e%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [2 dbevts]

As you can see, connection from the bridge is closed after 30 seconds (timeout), the POST request in total takes 70 seconds.

What we notice, is that these long running join-requests sometimes occur in parallel with other similar join-request.

Here for example are three join requests from the bridge bot for three different rooms, all taking a long time and finishing at the same time! The above request POST-9744812 is one of them:

[comment: POST-9744698 send by bridge around 00:24:26 with a timeout of 30 seconds]
2022-08-04 00:24:56,314 - synapse.http.site - 362 - INFO - POST-9744698 - Connection from client lost before response was sent
[comment: POST-9744812 send by bridge around 00:24:56 with a timeout of 30 seconds]
2022-08-04 00:25:26,333 - synapse.http.site - 362 - INFO - POST-9744812 - Connection from client lost before response was sent
[comment: POST-9744966 send by bridge around 00:25:26 with a timeout of 30 seconds]
2022-08-04 00:25:56,353 - synapse.http.site - 362 - INFO - POST-9744966 - Connection from client lost before response was sent
2022-08-04 00:26:06,821 - synapse.handlers.message - 1275 - INFO - POST-9744812 - Not bothering to persist state event $0AvNQaCtErI11Pl4OvGPhfTJypW6eLzu9gSvEZ8-q6E duplicated by $L6xUQADxe6Va4rDMXgTgEDIqfdFNHXSWtf8SZl14Elw
2022-08-04 00:26:06,821 - synapse.http.server - 795 - WARNING - POST-9744812 - Not sending response to request <XForwardedForRequest at 0x7f03dced95e0 method='POST' uri='/_matrix/client/r0/join/%23ctg_12e8de3e-a2e9-40cb-a858-75ab7697d15e%3Achat.church.tools?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'>, already disconnected.
2022-08-04 00:26:06,822 - synapse.access.http.8008 - 450 - INFO - POST-9744812 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 70.490sec/-40.489sec (0.005sec, 0.003sec) (0.005sec/0.033sec/16) 0B 200! "POST /_matrix/client/r0/join/%23ctg_12e8de3e-a2e9-40cb-a858-75ab7697d15e%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [2 dbevts]
2022-08-04 00:26:06,823 - synapse.handlers.message - 1275 - INFO - POST-9744966 - Not bothering to persist state event $xNi9xZ4Q96OMkwCrBm5n3j1bmtQVUV5QTylIiBDJhFk duplicated by $kDwWpaBmP0SkjZUml9qwgd_5EQSfvrymtP5igwnAPKk
2022-08-04 00:26:06,823 - synapse.http.server - 795 - WARNING - POST-9744966 - Not sending response to request <XForwardedForRequest at 0x7f031128b8e0 method='POST' uri='/_matrix/client/r0/join/%23ctg_16365885-c9fd-495c-9f0c-36de0c5ca98b%3Achat.church.tools?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'>, already disconnected.
2022-08-04 00:26:06,823 - synapse.access.http.8008 - 450 - INFO - POST-9744966 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 40.472sec/-10.471sec (0.007sec, 0.001sec) (0.006sec/0.025sec/16) 0B 200! "POST /_matrix/client/r0/join/%23ctg_16365885-c9fd-495c-9f0c-36de0c5ca98b%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [3 dbevts]
2022-08-04 00:26:06,824 - synapse.handlers.message - 1275 - INFO - POST-9744698 - Not bothering to persist state event $YB-55YkNiNjBRRJidwEQsseTI7u-OhT2rMDyjL9cwgw duplicated by $lY_wX6HlN6-x9svkO_nk3Kz1GJ6Yx_c3S7qpmCOSWXI
2022-08-04 00:26:06,824 - synapse.http.server - 795 - WARNING - POST-9744698 - Not sending response to request <XForwardedForRequest at 0x7f0341c268e0 method='POST' uri='/_matrix/client/r0/join/%23ctg_067d4083-b340-450f-a765-b3ad3178eeb6%3Achat.church.tools?access_token=<redacted>' clientproto='HTTP/1.0' site='8008'>, already disconnected.
2022-08-04 00:26:06,824 - synapse.access.http.8008 - 450 - INFO - POST-9744698 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 100.510sec/-70.510sec (0.014sec, 0.003sec) (0.005sec/100.488sec/18) 0B 200! "POST /_matrix/client/r0/join/%23ctg_067d4083-b340-450f-a765-b3ad3178eeb6%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [1 dbevts]

Looks like there is something blocking in synapse (or the database, PostgreSQL in our case), then when the lock is released, all requests finish at the same time. Runtimes of the three requests above: 40, 70 and 100 seconds.

Here the POST join requests in the bigger context:

2022-08-04 00:24:21,693 - synapse.access.http.8008 - 450 - INFO - POST-9744593 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.043sec/0.000sec (0.005sec, 0.001sec) 
(0.003sec/0.021sec/17) 51B 200 "POST /_matrix/client/r0/join/%23cte_0d63e97a-9ed7-4ad5-8f94-9d61b8f0d8cb%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [5 dbevts]
2022-08-04 00:24:21,814 - synapse.access.http.8008 - 450 - INFO - POST-9744603 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.040sec/0.000sec (0.005sec, 0.001sec) 
(0.003sec/0.019sec/17) 51B 200 "POST /_matrix/client/r0/join/%23cte_3d0ec928-77fd-4311-b454-ed3f3994faa4%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [5 dbevts]
2022-08-04 00:24:21,915 - synapse.access.http.8008 - 450 - INFO - POST-9744613 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.025sec/0.000sec (0.005sec, 0.001sec) 
(0.003sec/0.013sec/16) 51B 200 "POST /_matrix/client/r0/join/%23cte_66aea0fc-bf8d-4e49-ae83-70c69bb31073%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [1 dbevts]
2022-08-04 00:24:22,017 - synapse.access.http.8008 - 450 - INFO - POST-9744623 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.024sec/0.000sec (0.003sec, 0.000sec) 
(0.002sec/0.012sec/16) 51B 200 "POST /_matrix/client/r0/join/%23cte_8b716325-0b3b-4817-bdcf-6f220d9d4a14%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [2 dbevts]
2022-08-04 00:24:22,170 - synapse.access.http.8008 - 450 - INFO - POST-9744637 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.047sec/0.000sec (0.004sec, 0.002sec) 
(0.003sec/0.015sec/16) 51B 200 "POST /_matrix/client/r0/join/%23cte_a341b1a5-7654-405e-997c-d44327840b07%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [11 dbevts]
2022-08-04 00:24:22,284 - synapse.access.http.8008 - 450 - INFO - POST-9744649 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.025sec/0.000sec (0.003sec, 0.001sec) 
(0.003sec/0.013sec/16) 51B 200 "POST /_matrix/client/r0/join/%23cte_bbc0a3bb-5e09-45b6-99ab-69c20b5c8417%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [1 dbevts]
2022-08-04 00:24:22,395 - synapse.access.http.8008 - 450 - INFO - POST-9744659 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.026sec/0.000sec (0.003sec, 0.001sec) 
(0.003sec/0.014sec/16) 51B 200 "POST /_matrix/client/r0/join/%23cte_f338935a-7c48-4695-9fd1-8303e3f8d1d9%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [1 dbevts]
2022-08-04 00:24:22,514 - synapse.access.http.8008 - 450 - INFO - POST-9744669 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.026sec/0.000sec (0.003sec, 0.001sec) 
(0.003sec/0.013sec/16) 51B 200 "POST /_matrix/client/r0/join/%23cte_f7920cfd-a719-4c57-a101-cf47d7779d85%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [1 dbevts]
2022-08-04 00:24:22,622 - synapse.access.http.8008 - 450 - INFO - POST-9744678 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.032sec/0.000sec (0.003sec, 0.001sec) 
(0.003sec/0.020sec/17) 51B 200 "POST /_matrix/client/r0/join/%23cte_42aaaefc-4da8-43d2-9679-2c3d32a99a66%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [1 dbevts]
2022-08-04 00:26:06,822 - synapse.access.http.8008 - 450 - INFO - POST-9744812 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 70.490sec/-40.489sec (0.005sec, 0.003se
c) (0.005sec/0.033sec/16) 0B 200! "POST /_matrix/client/r0/join/%23ctg_12e8de3e-a2e9-40cb-a858-75ab7697d15e%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [2 dbevts]
2022-08-04 00:26:06,823 - synapse.access.http.8008 - 450 - INFO - POST-9744966 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 40.472sec/-10.471sec (0.007sec, 0.001se
c) (0.006sec/0.025sec/16) 0B 200! "POST /_matrix/client/r0/join/%23ctg_16365885-c9fd-495c-9f0c-36de0c5ca98b%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [3 dbevts]
2022-08-04 00:26:06,824 - synapse.access.http.8008 - 450 - INFO - POST-9744698 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 100.510sec/-70.510sec (0.014sec, 0.003s
ec) (0.005sec/100.488sec/18) 0B 200! "POST /_matrix/client/r0/join/%23ctg_067d4083-b340-450f-a765-b3ad3178eeb6%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [1 dbevts]
2022-08-04 00:26:06,824 - synapse.access.http.8008 - 450 - INFO - POST-9745091 - 192.168.20.61 - 8008 - {@ctbot:chat.church.tools} Processed request: 10.451sec/0.002sec (0.006sec, 0.001sec)
 (0.006sec/0.022sec/16) 51B 200 "POST /_matrix/client/r0/join/%23ctg_258380d2-213c-4367-985b-6fc329b21d92%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [2 dbevts]
2022-08-04 00:26:06,988 - synapse.access.http.8008 - 450 - INFO - POST-9745158 - 192.168.20.61 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.032sec/0.000sec (0.003sec, 0.001sec) 
(0.003sec/0.017sec/16) 51B 200 "POST /_matrix/client/r0/join/%23ctg_5159917e-27ea-42d0-b963-3e6e643e9da8%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [2 dbevts]
2022-08-04 00:26:07,550 - synapse.access.http.8008 - 450 - INFO - POST-9745220 - 192.168.20.61 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.037sec/0.000sec (0.003sec, 0.001sec) 
(0.003sec/0.018sec/16) 51B 200 "POST /_matrix/client/r0/join/%23ctg_53e1c190-7522-43b9-be6b-dda944a14951%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [3 dbevts]
2022-08-04 00:26:07,786 - synapse.access.http.8008 - 450 - INFO - POST-9745248 - 192.168.20.61 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.024sec/0.000sec (0.006sec, 0.001sec) 
(0.002sec/0.012sec/16) 51B 200 "POST /_matrix/client/r0/join/%23ctg_6aa63134-e708-4e0c-882e-f81b1bad164d%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [2 dbevts]

We have activated prometheus metrics on our synapse server, but could not find anything abnormal when these delays occured.

Steps to reproduce

Homeserver

https://chat.church.tools/

Synapse Version

{"server_version":"1.63.1","python_version":"3.8.10"}

Installation Method

Debian packages from packages.matrix.org

Platform

Ubuntu 18.04

PostgreSQL Version

postgres (PostgreSQL) 10.20 (Ubuntu 10.20-0ubuntu0.18.04.1)

Relevant log output

see description above

Anything else that would be useful to know?

No response

r1bnc commented 2 years ago

I also seem to get a lot of these messages and the synapse times out (goes down):

matrix-synapse[613379]: 2022-08-05 05:03:42,560 - synapse.http.server - 795 - WARNING - PUT-20973 - Not sending response to request <XForwardedForRequest at 0x7f47ad9cb430 method='PUT' uri='/_matrix/federation/v1/send/1659445109176' clientproto='HTTP/1.0' site='8048'>, already disconnected.
...
matrix-synapse[613379]: 2022-08-05 05:03:42,608 - synapse.http.server - 795 - WARNING - PUT-20975 - Not sending response to request <XForwardedForRequest at 0x7f47e2aa0d90 method='PUT' uri='/_matrix/federation/v1/send/1659578924069' clientproto='HTTP/1.0' site='8048'>, already disconnected.
...
scrubbed

I am using the ansible docker image for matrix.

UPDATE: Fixed mine by deleting a large room on synapse admin.

UPDATE: After updating matrix and postgre, the issue is back.

anoadragon453 commented 2 years ago

Thank you for the detailed report.

Do you see a pattern with these slow joins occurring for either local room joins (where a user from your homeserver is already in the room) or remote room joins (where your homeserver is joining this room for the first time)?

We're currently actively working on making both cases faster - see these milestones: https://github.com/matrix-org/synapse/milestone/8, https://github.com/matrix-org/synapse/milestone/10

I'll pass your report on to the people working on the issue directly in case it's helpful, but my suggestion would be to try again once some of the above work lands in a released version of Synapse. You can follow the milestones and our changelog for updates.

richvdh commented 2 years ago

Looks like there is something blocking in synapse (or the database, PostgreSQL in our case), then when the lock is released, all requests finish at the same time.

yes, all requests to join the same room will be de-duplicated: only one such request will actually do any work. One of the requests (the first one to arrive) will actually have done the work: it should show significantly higher DB/CPU time (and lots more log lines). If you can find that request, and share the logs for it, we can begin to find out why it was so slow.

hubermat commented 2 years ago

@richvdh: the three join requests in the example of my original post above are from the bridge bot for three different rooms (!), all taking a long time and finishing at the same time. So your explanation (de-duplication, because of join request for the same room) does not apply here.

hubermat commented 2 years ago

@anoadragon453

Do you see a pattern with these slow joins occurring for either local room joins (where a user from your homeserver is already in the room) or remote room joins (where your homeserver is joining this room for the first time)?

These slow joins appear for local rooms on our homeserver. We manage the rooms via a matrix-bridge-based admin tool. Rooms are created by a central admin bot, and in subsequent runs of the admin tool, the central admin bot updates the rooms (adds/removed members, adjusts power levels etc.).

The slow joins appear (sometimes) when this bridge function is called: bridge.getIntent()._ensureJoined(roomAlias, false, undefined, true);

It makes sure, that the central admin bot is currently a member of the room, before it does other things with the room. The bot should always be already in the room, as the bot created the room and added himself in the first place. But _ensureJoined seems to do POST /join anyway, and this sometimes blocks for no apparent reason.

hubermat commented 2 years ago

And sorry for the long "timeout" in this thread, I had been on vacation šŸ˜

hubermat commented 1 year ago

Any ideas on this? This is still happening for uns on a regular basis (several times per day).

reivilibre commented 1 year ago

I know this isn't necessarily convenient, but it'd probably help to use some more tools to see what's going on.

  1. Metrics (with our Grafana dashboard in contrib/grafana) ā€” https://matrix-org.github.io/synapse/latest/usage/administration/understanding_synapse_through_grafana_graphs.html ā€” some of the graphs in the dashboard will point to where time is going ā€” e.g. see the Database and Per-block Metrics sections. If you can get some graphs that line up to a problem, there are likely clues there.
  2. Tracing (this is much less user-friendly and more of a development tool, so probably try metrics first) ā€” https://matrix-org.github.io/synapse/latest/opentracing.html#setting-up-opentracing ā€” this should let you search for a long-running request and see
  3. If you suspect the database is holding things up, running SELECT * FROM pg_stat_activity WHERE state!='idle'; on the Postgres database can be useful to see what current connections are up to, including timings. (beware the output of this query may contain sensitive user data).
squahtx commented 1 year ago

When "/join"ing a room, there are two "lock"s.

The first ensures that an application service can only do one /join at a time. The second ensures that a room can only process one /join from any user at a time. We're aware of slow local room joins for large rooms.

That is, if one or more local users were to join a large local room, those joins would be queued one after the other. In the meantime, if the bridge were to /join that room, it would have to wait behind those users. Any additional /joins the bridge does would have to wait behind the /join for that big slow room too.

2022-08-04 00:26:06,822 - synapse.access.http.8008 - 450 - INFO - POST-9744812 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 70.490sec/-40.489sec (0.005sec, 0.003se
c) (0.005sec/0.033sec/16) 0B 200! "POST /_matrix/client/r0/join/%23ctg_12e8de3e-a2e9-40cb-a858-75ab7697d15e%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [2 dbevts]
2022-08-04 00:26:06,823 - synapse.access.http.8008 - 450 - INFO - POST-9744966 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 40.472sec/-10.471sec (0.007sec, 0.001se
c) (0.006sec/0.025sec/16) 0B 200! "POST /_matrix/client/r0/join/%23ctg_16365885-c9fd-495c-9f0c-36de0c5ca98b%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [3 dbevts]
2022-08-04 00:26:06,824 - synapse.access.http.8008 - 450 - INFO - POST-9744698 - 192.168.20.60 - 8008 - {@ctbot:chat.church.tools} Processed request: 100.510sec/-70.510sec (0.014sec, 0.003s
ec) (0.005sec/100.488sec/18) 0B 200! "POST /_matrix/client/r0/join/%23ctg_067d4083-b340-450f-a765-b3ad3178eeb6%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [1 dbevts]
2022-08-04 00:26:06,824 - synapse.access.http.8008 - 450 - INFO - POST-9745091 - 192.168.20.61 - 8008 - {@ctbot:chat.church.tools} Processed request: 10.451sec/0.002sec (0.006sec, 0.001sec)
 (0.006sec/0.022sec/16) 51B 200 "POST /_matrix/client/r0/join/%23ctg_258380d2-213c-4367-985b-6fc329b21d92%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "-" [2 dbevts]

Going by these logs, it's the /join to #ctg_067d4083-b340-450f-a765-b3ad3178eeb6:chat.church.tools that is held up behind other users. I'd expect it to be one of the larger rooms on your homeserver. Could you check how big the room is?

squahtx commented 1 year ago

Probably due to https://github.com/matrix-org/synapse/issues/13965

hubermat commented 1 year ago

@squahtx I checked todays homeserver.log and found several occurrences of long running joins (each around 80 seconds), that led to gateway timeouts on the side of your bridge.

I checked two of those and had a look at the rooms, in both cases the room hat only one member, the bridge-user @chatbot that created the room in the first place, and for which the join now took very long, although the user was already in the room.

Here the complete log regarding on of those rooms, with the long running join (blocking other operation) near the beginning of the log:

2022-12-16 09:58:37,992 - synapse.access.http.8008 - 450 - INFO - GET-4821848 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.004sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.001sec/3) 3500B 200 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/state HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:58:38,025 - synapse.access.http.8008 - 450 - INFO - PUT-4821849 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.027sec/0.002sec (0.003sec, 0.000sec) (0.000sec/0.004sec/3) 59B 200 "PUT /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/state/m.room.avatar/ HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:58:38,038 - synapse.access.http.8008 - 450 - INFO - GET-4821851 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.007sec/0.001sec (0.001sec, 0.000sec) (0.002sec/0.002sec/3) 3808B 200 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/state HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:58:38,045 - synapse.access.http.8008 - 450 - INFO - GET-4821853 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.003sec/0.000sec (0.000sec, 0.000sec) (0.001sec/0.001sec/3) 388B 200 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/members HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:56,726 - synapse.http.server - 795 - WARNING - POST-4821579 - Not sending response to request <XForwardedForRequest at 0x7faf0b7e1520 method='POST' uri='/_matrix/client/v3/join/!bGitvSgjvnaVLPhMVy%3Achat.church.tools' clientproto='HTTP/1.0' site='8008'>, already disconnected.
2022-12-16 09:59:56,726 - synapse.access.http.8008 - 450 - INFO - POST-4821579 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 81.790sec/-51.790sec (0.013sec, 0.000sec) (0.002sec/81.777sec/11) 0B 200! "POST /_matrix/client/v3/join/!bGitvSgjvnaVLPhMVy%3Achat.church.tools HTTP/1.0" "-" [2 dbevts]
2022-12-16 09:59:56,775 - synapse.http.server - 795 - WARNING - POST-4821857 - Not sending response to request <XForwardedForRequest at 0x7faf1c4a94c0 method='POST' uri='/_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite' clientproto='HTTP/1.0' site='8008'>, already disconnected.
2022-12-16 09:59:56,777 - synapse.access.http.8008 - 450 - INFO - POST-4821857 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 78.723sec/-48.712sec (0.002sec, 0.001sec) (0.001sec/0.010sec/10) 0B 200! "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [7 dbevts]
2022-12-16 09:59:56,849 - synapse.http.server - 795 - WARNING - POST-4822738 - Not sending response to request <XForwardedForRequest at 0x7faeb4318490 method='POST' uri='/_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite' clientproto='HTTP/1.0' site='8008'>, already disconnected.
2022-12-16 09:59:56,850 - synapse.access.http.8008 - 450 - INFO - POST-4822738 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 48.778sec/-18.756sec (0.004sec, 0.003sec) (0.016sec/0.017sec/12) 0B 200! "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:56,916 - synapse.access.http.8008 - 450 - INFO - POST-4823663 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 18.819sec/0.001sec (0.005sec, 0.001sec) (0.006sec/0.018sec/12) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:56,977 - synapse.access.http.8008 - 450 - INFO - POST-4824402 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.051sec/0.002sec (0.007sec, 0.000sec) (0.005sec/0.013sec/14) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,042 - synapse.access.http.8008 - 450 - INFO - POST-4824403 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.057sec/0.002sec (0.006sec, 0.000sec) (0.004sec/0.016sec/14) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,100 - synapse.access.http.8008 - 450 - INFO - POST-4824405 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.049sec/0.002sec (0.002sec, 0.002sec) (0.004sec/0.013sec/12) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,168 - synapse.access.http.8008 - 450 - INFO - POST-4824406 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.058sec/0.002sec (0.006sec, 0.000sec) (0.007sec/0.015sec/12) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,256 - synapse.access.http.8008 - 450 - INFO - POST-4824408 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.075sec/0.002sec (0.005sec, 0.002sec) (0.006sec/0.018sec/14) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,322 - synapse.access.http.8008 - 450 - INFO - POST-4824409 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.056sec/0.001sec (0.004sec, 0.000sec) (0.005sec/0.014sec/12) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,391 - synapse.access.http.8008 - 450 - INFO - POST-4824410 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.061sec/0.001sec (0.004sec, 0.001sec) (0.006sec/0.014sec/14) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,477 - synapse.access.http.8008 - 450 - INFO - POST-4824411 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.079sec/0.001sec (0.004sec, 0.001sec) (0.006sec/0.016sec/12) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,542 - synapse.access.http.8008 - 450 - INFO - POST-4824414 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.057sec/0.001sec (0.006sec, 0.000sec) (0.006sec/0.015sec/12) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,611 - synapse.access.http.8008 - 450 - INFO - POST-4824415 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.061sec/0.001sec (0.002sec, 0.002sec) (0.008sec/0.012sec/14) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,669 - synapse.access.http.8008 - 450 - INFO - POST-4824416 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.050sec/0.002sec (0.004sec, 0.001sec) (0.004sec/0.015sec/12) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,733 - synapse.access.http.8008 - 450 - INFO - POST-4824417 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.054sec/0.002sec (0.004sec, 0.001sec) (0.004sec/0.014sec/14) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,806 - synapse.access.http.8008 - 450 - INFO - POST-4824419 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.067sec/0.002sec (0.004sec, 0.001sec) (0.006sec/0.016sec/14) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,872 - synapse.access.http.8008 - 450 - INFO - POST-4824421 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.056sec/0.002sec (0.006sec, 0.001sec) (0.006sec/0.015sec/12) 2B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/invite HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:57,899 - synapse.access.http.8008 - 450 - INFO - GET-4824424 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.018sec/0.001sec (0.001sec, 0.000sec) (0.001sec/0.006sec/3) 12880B 200 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/state HTTP/1.0" "-" [1 dbevts]
2022-12-16 09:59:57,908 - synapse.access.http.8008 - 450 - INFO - GET-4824426 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.004sec/0.002sec (0.001sec, 0.000sec) (0.001sec/0.002sec/3) 9438B 200 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/members HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:58,007 - synapse.access.http.8008 - 450 - INFO - GET-4824446 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.003sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.002sec/2) 361B 200 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/state/m.room.power_levels/ HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:58,057 - synapse.access.http.8008 - 450 - INFO - PUT-4824447 - 192.168.20.62 - 8008 - {@ctbot:chat.church.tools} Processed request: 0.047sec/0.001sec (0.008sec, 0.000sec) (0.001sec/0.007sec/6) 59B 200 "PUT /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/state/m.room.power_levels/ HTTP/1.0" "-" [0 dbevts]
2022-12-16 09:59:59,389 - synapse.handlers.sync - 691 - INFO - GET-4824624 - Failed to find any events in room !bGitvSgjvnaVLPhMVy:chat.church.tools at RoomStreamToken(topological=None, stream=5080720, instance_map=frozendict.frozendict({}))
2022-12-16 09:59:59,653 - synapse.http.server - 167 - INFO - GET-4824635 - <XForwardedForRequest at 0x7fae858ab550 method='GET' uri='/_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/event/%24gSPCGNjDzg3iBctZgX2feLSpJIukdQHnr9j9iBzQmFA' clientproto='HTTP/1.0' site='8008'> SynapseError: 404 - Event not found.
2022-12-16 09:59:59,654 - synapse.access.http.8008 - 450 - INFO - GET-4824635 - 192.168.20.61 - 8008 - {@ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools} Processed request: 0.003sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.001sec/1) 52B 404 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/event/%24gSPCGNjDzg3iBctZgX2feLSpJIukdQHnr9j9iBzQmFA HTTP/1.0" "Dart/2.18 (dart:io)" [0 dbevts]
2022-12-16 09:59:59,801 - synapse.http.server - 167 - INFO - GET-4824642 - <XForwardedForRequest at 0x7fae985314f0 method='GET' uri='/_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/state/m.room.member/%40ctbot%3Achat.church.tools' clientproto='HTTP/1.0' site='8008'> SynapseError: 403 - User @ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools not in room !bGitvSgjvnaVLPhMVy:chat.church.tools, and room previews are disabled
2022-12-16 09:59:59,802 - synapse.access.http.8008 - 450 - INFO - GET-4824642 - 192.168.20.61 - 8008 - {@ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools} Processed request: 0.003sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.001sec/2) 181B 403 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/state/m.room.member/%40ctbot%3Achat.church.tools HTTP/1.0" "Dart/2.18 (dart:io)" [0 dbevts]
2022-12-16 10:01:04,054 - synapse.handlers.sync - 691 - INFO - GET-4827422 - Failed to find any events in room !bGitvSgjvnaVLPhMVy:chat.church.tools at RoomStreamToken(topological=None, stream=5053006, instance_map=frozendict.frozendict({}))
2022-12-16 10:01:08,355 - synapse.access.http.8008 - 450 - INFO - POST-4827507 - 192.168.20.61 - 8008 - {@ct_9e245d45-4a11-44de-ac6c-a66a4e1903e7:chat.church.tools} Processed request: 0.043sec/0.004sec (0.005sec, 0.001sec) (0.002sec/0.009sec/11) 51B 200 "POST /_matrix/client/r0/join/!bGitvSgjvnaVLPhMVy%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [0 dbevts]
2022-12-16 10:01:08,408 - synapse.access.http.8008 - 450 - INFO - POST-4827508 - 192.168.20.61 - 8008 - {@ct_9e245d45-4a11-44de-ac6c-a66a4e1903e7:chat.church.tools} Processed request: 0.075sec/0.003sec (0.007sec, 0.000sec) (0.007sec/0.033sec/11) 51B 200 "POST /_matrix/client/r0/join/!bGitvSgjvnaVLPhMVy%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [0 dbevts]
2022-12-16 10:01:39,674 - synapse.access.http.8008 - 450 - INFO - GET-4828548 - 192.168.20.61 - 8008 - {@ct_9e245d45-4a11-44de-ac6c-a66a4e1903e7:chat.church.tools} Processed request: 0.009sec/0.001sec (0.003sec, 0.000sec) (0.001sec/0.004sec/3) 4007B 200 "GET /_matrix/client/r0/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/messages?limit=30&dir=b&from=t11-5092290_183295263_79680_13265048_9920345_7632_5761_535564_0&access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [0 dbevts]
2022-12-16 10:01:42,635 - synapse.access.http.8008 - 450 - INFO - PUT-4828637 - 192.168.20.61 - 8008 - {@ct_9e245d45-4a11-44de-ac6c-a66a4e1903e7:chat.church.tools} Processed request: 0.002sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.000sec/1) 2B 200 "PUT /_matrix/client/r0/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/typing/%40ct_9e245d45-4a11-44de-ac6c-a66a4e1903e7%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [0 dbevts]
2022-12-16 10:20:01,245 - synapse.access.http.8008 - 450 - INFO - POST-4861378 - 192.168.20.62 - 8008 - {@ct_3e173fce-22b6-472d-a2d3-f35284904552:chat.church.tools} Processed request: 0.088sec/0.003sec (0.009sec, 0.001sec) (0.003sec/0.014sec/15) 51B 200 "POST /_matrix/client/r0/join/!bGitvSgjvnaVLPhMVy%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [15 dbevts]
2022-12-16 10:20:37,832 - synapse.access.http.8008 - 450 - INFO - GET-4862804 - 192.168.20.62 - 8008 - {@ct_3e173fce-22b6-472d-a2d3-f35284904552:chat.church.tools} Processed request: 0.006sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.003sec/3) 4598B 200 "GET /_matrix/client/r0/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/messages?limit=30&dir=b&from=t12-5092291_183301114_80563_13265751_9920912_7632_5761_535618_0&access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [0 dbevts]
2022-12-16 10:37:46,534 - synapse.http.server - 167 - INFO - GET-4893264 - <XForwardedForRequest at 0x7faeb39a49d0 method='GET' uri='/_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/members?' clientproto='HTTP/1.0' site='8008'> SynapseError: 403 - User @ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools not in room !bGitvSgjvnaVLPhMVy:chat.church.tools, and room previews are disabled
2022-12-16 10:37:46,535 - synapse.access.http.8008 - 450 - INFO - GET-4893264 - 192.168.20.62 - 8008 - {@ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools} Processed request: 0.005sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.001sec/2) 181B 403 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/members? HTTP/1.0" "Dart/2.18 (dart:io)" [1 dbevts]
2022-12-16 10:37:47,019 - synapse.http.server - 167 - INFO - GET-4893266 - <XForwardedForRequest at 0x7faeaa395250 method='GET' uri='/_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/members?' clientproto='HTTP/1.0' site='8008'> SynapseError: 403 - User @ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools not in room !bGitvSgjvnaVLPhMVy:chat.church.tools, and room previews are disabled
2022-12-16 10:37:47,020 - synapse.access.http.8008 - 450 - INFO - GET-4893266 - 192.168.20.62 - 8008 - {@ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools} Processed request: 0.007sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.003sec/2) 181B 403 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/members? HTTP/1.0" "Dart/2.18 (dart:io)" [0 dbevts]
2022-12-16 10:37:52,878 - synapse.access.http.8008 - 450 - INFO - POST-4893449 - 192.168.20.62 - 8008 - {@ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools} Processed request: 0.082sec/0.002sec (0.007sec, 0.002sec) (0.004sec/0.023sec/18) 51B 200 "POST /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/join HTTP/1.0" "Dart/2.18 (dart:io)" [8 dbevts]
2022-12-16 10:37:53,125 - synapse.access.http.8008 - 450 - INFO - GET-4893458 - 192.168.20.62 - 8008 - {@ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools} Processed request: 0.009sec/0.002sec (0.002sec, 0.000sec) (0.001sec/0.005sec/3) 10983B 200 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/members? HTTP/1.0" "Dart/2.18 (dart:io)" [0 dbevts]
2022-12-16 10:37:53,130 - synapse.access.http.8008 - 450 - INFO - GET-4893459 - 192.168.20.61 - 8008 - {@ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools} Processed request: 0.013sec/0.002sec (0.002sec, 0.000sec) (0.002sec/0.005sec/3) 10983B 200 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/members? HTTP/1.0" "Dart/2.18 (dart:io)" [0 dbevts]
2022-12-16 10:37:53,250 - synapse.access.http.8008 - 450 - INFO - GET-4893488 - 192.168.20.61 - 8008 - {@ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools} Processed request: 0.005sec/0.001sec (0.001sec, 0.000sec) (0.001sec/0.002sec/3) 10983B 200 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/members? HTTP/1.0" "Dart/2.18 (dart:io)" [0 dbevts]
2022-12-16 10:37:53,252 - synapse.access.http.8008 - 450 - INFO - GET-4893487 - 192.168.20.62 - 8008 - {@ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools} Processed request: 0.006sec/0.003sec (0.000sec, 0.000sec) (0.001sec/0.003sec/3) 10983B 200 "GET /_matrix/client/v3/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/members? HTTP/1.0" "Dart/2.18 (dart:io)" [0 dbevts]
2022-12-16 10:53:32,644 - synapse.handlers.sync - 691 - INFO - GET-4933638 - Failed to find any events in room !bGitvSgjvnaVLPhMVy:chat.church.tools at RoomStreamToken(topological=None, stream=5044421, instance_map=frozendict.frozendict({}))
2022-12-16 10:53:33,788 - synapse.access.http.8008 - 450 - INFO - POST-4933718 - 192.168.20.60 - 8008 - {@ct_4d52df64-3f0c-45a2-b9fc-1cd5e8e0dace:chat.church.tools} Processed request: 0.106sec/0.003sec (0.006sec, 0.002sec) (0.006sec/0.031sec/17) 51B 200 "POST /_matrix/client/r0/join/!bGitvSgjvnaVLPhMVy%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [8 dbevts]
2022-12-16 10:53:35,076 - synapse.access.http.8008 - 450 - INFO - GET-4933836 - 192.168.20.60 - 8008 - {@ct_4d52df64-3f0c-45a2-b9fc-1cd5e8e0dace:chat.church.tools} Processed request: 0.006sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.003sec/3) 5580B 200 "GET /_matrix/client/r0/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/messages?limit=30&dir=b&from=t14-5092293_183311979_82023_13266784_9921815_7633_5761_535693_0&access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [0 dbevts]
2022-12-16 10:53:38,010 - synapse.access.http.8008 - 450 - INFO - PUT-4934018 - 192.168.20.60 - 8008 - {@ct_4d52df64-3f0c-45a2-b9fc-1cd5e8e0dace:chat.church.tools} Processed request: 0.002sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.001sec/1) 2B 200 "PUT /_matrix/client/r0/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/typing/%40ct_4d52df64-3f0c-45a2-b9fc-1cd5e8e0dace%3Achat.church.tools?access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [0 dbevts]
2022-12-16 11:00:59,106 - synapse.access.http.8008 - 450 - INFO - GET-4948150 - 192.168.20.60 - 8008 - {@ct_a30d229a-4ec3-4619-8ab7-002acccb95be:chat.church.tools} Processed request: 0.016sec/0.000sec (0.005sec, 0.000sec) (0.001sec/0.011sec/5) 5157B 200 "GET /_matrix/client/r0/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/messages?limit=30&dir=b&from=s5092292_183314291_82258_13266919_9921927_7633_5761_535704_0&access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [0 dbevts]
2022-12-16 11:01:48,698 - synapse.access.http.8008 - 450 - INFO - GET-4949542 - 192.168.20.60 - 8008 - {@ct_9e245d45-4a11-44de-ac6c-a66a4e1903e7:chat.church.tools} Processed request: 0.008sec/0.001sec (0.002sec, 0.000sec) (0.001sec/0.003sec/3) 5160B 200 "GET /_matrix/client/r0/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/messages?limit=30&dir=b&from=t13-5092292_183314617_82283_13266937_9921943_7633_5761_535707_0&access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [0 dbevts]
2022-12-16 12:00:28,469 - synapse.handlers.sync - 691 - INFO - GET-5055913 - Failed to find any events in room !bGitvSgjvnaVLPhMVy:chat.church.tools at RoomStreamToken(topological=None, stream=5091767, instance_map=frozendict.frozendict({}))
2022-12-16 12:06:24,234 - synapse.access.http.8008 - 450 - INFO - GET-5074935 - 192.168.20.62 - 8008 - {@ct_9e245d45-4a11-44de-ac6c-a66a4e1903e7:chat.church.tools} Processed request: 0.034sec/0.000sec (0.004sec, 0.001sec) (0.004sec/0.018sec/5) 5160B 200 "GET /_matrix/client/r0/rooms/!bGitvSgjvnaVLPhMVy%3Achat.church.tools/messages?limit=30&dir=b&from=t13-5092292_183314617_82283_13266937_9921943_7633_5761_535707_0&access_token=<redacted> HTTP/1.0" "okhttp/4.9.2" [12 dbevts]

What puzzles me: how can "Failed to find any events in room !bGitvSgjvnaVLPhMVy" happen, right in the middle of other operations?

squahtx commented 1 year ago

@squahtx I checked todays homeserver.log and found several occurrences of long running joins (each around 80 seconds), that led to gateway timeouts on the side of your bridge.

I checked two of those and had a look at the rooms, in both cases the room hat only one member, the bridge-user @chatbot that created the room in the first place, and for which the join now took very long, although the user was already in the room.

Just to confirm, were the rooms you checked the ones which took the very longest out of the entire group of joins? In any case, I strongly suspect the bot, or other users on the server, are hitting cases where https://github.com/matrix-org/synapse/issues/13965 shows up. The slow cases that I know of are:

It's hard to say more without tracing set up.

If possible, I would avoid calling /join when already joined to rooms for now. GET /_matrix/client/v3/rooms/{roomId}/state/m.room.member/%40ctbot%3Achat.church.tools will allow the bot's current membership to be retrieved.

What puzzles me: how can "Failed to find any events in room !bGitvSgjvnaVLPhMVy" happen, right in the middle of other operations?

There can be multiple requests being processed at the same time, so their log messages are interleaved. Searching for "GET-4933638", for example, will yield all log lines from that request.

hubermat commented 1 year ago

@squahtx Yes, the rooms I checked are the ones with the longest running joins in the group of joins. I am pretty sure that the room size is not the problem here.

The @ctbot creates more or less all rooms on our homeserver and manages all memberships within those rooms for the users (keeps the room memberships up to date). Therefore the @ctbot has several thousand joins...

If possible, I would avoid calling /join when already joined to rooms for now. GET /_matrix/client/v3/rooms/{roomId}/state/m.room.member/%40ctbot%3Achat.church.tools will allow the bot's current membership to be retrieved.

I will try this, thank you!

H-Shay commented 1 year ago

Was this issue resolved or does it still persist?

hubermat commented 1 year ago

I am still struggling with the Matrix-AppService-Bridge SDK. I changed my calls to /join for the @ctbot, but I now realized, that the bridge SDK also internally calls _ensureJoined() quite frequently, leading to multiple joins from the @ctbot. After reading the code I found a bridge option dontJoin, which prevents this behaviour. I am now testing this. Tomorrow I will know whether it has an effect or not.

To give you an impression, our bridge handles ~15.000 room updates (members in/out, avatar check, ...) per day, during this around 20 locks occur during @ctbot joins. We will see if this drops to 0 now.

hubermat commented 1 year ago

For us the issue is no longer pressing, as we now could prevent the calls to /join for the @ctbot. However, in synapse the issue with room joins for users which are in maaaany rooms (in our case the @ctbot is in around 40.000 rooms) still persists. The db lock (?) / timeout happens from time to time with room joins from these "heavy" users, and should be resolved in synapse.