Failed to acquire database snapshot for sync request

starsareintherose commented 1 year ago

Background information

Dendrite version or git SHA: 0.10.7
Monolith or Polylith?: Monolith
SQLite3 or Postgres?: Postgresql
Running in Docker?: no
go version: 1.19.4
Client used (if applicable): element

Description

What is the problem: log

Dec 09 23:44:25 helix dendrite[16324]: time="2022-12-09T15:44:25.820040149Z" level=info msg="Executing UpdateUserDailyVisits"
Dec 09 23:55:21 helix dendrite[16324]: time="2022-12-09T15:55:21.633855054Z" level=info msg="missing timeline limit, using default" req.id=1Z8Hw3aS1nKt req.method=POST req.path="/_matrix/client/r0/user/@malacology:matrix.malacology.net/filter" user_id="@malacology:matrix.malacology.net"
Dec 09 23:56:42 helix dendrite[16324]: time="2022-12-09T15:56:42.244262814Z" level=error msg="p.getJoinResponseForCompleteSync failed" device_id=oAFNo8cG error="pq: canceling statement due to user request" limit=20 req.id=GvdvwYhMSSAx req.method=GET req.path=/_matrix/client/r0/sync since=s0_0_0_0_0_0_0_0_0 timeout=0s user_id="@malacology:matrix.malacology.net"
Dec 09 23:56:42 helix dendrite[16324]: time="2022-12-09T15:56:42.245238884Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
Dec 09 23:56:42 helix dendrite[16324]: time="2022-12-09T15:56:42.245354403Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
Dec 09 23:56:42 helix dendrite[16324]: time="2022-12-09T15:56:42.245403723Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
Dec 09 23:56:42 helix dendrite[16324]: time="2022-12-09T15:56:42.245449304Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
Dec 09 23:56:42 helix dendrite[16324]: time="2022-12-09T15:56:42.245520601Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
Dec 09 23:56:42 helix dendrite[16324]: time="2022-12-09T15:56:42.245569103Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
Dec 09 23:56:42 helix dendrite[16324]: time="2022-12-09T15:56:42.245614437Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"

Who is affected: maybe caused by server migration
How is this bug manifesting: element reports: Unable to Connect to Homeserver
When did this first appear: last month

Steps to reproduce

list the steps
that reproduce the bug
using hyphens as bullet points

Undef-a commented 1 year ago

I'm also experiencing this one on v0.10.8. Seems to be relatively harmless unless you try to sync a new device. At that point the new sync hangs permanently.

As a result of this, I've also had device verification fail. Each device may see different icons and even when they don't the verification fails to sync properly.

Existing devices work fine otherwise.

starsareintherose commented 1 year ago

Not same. element reports: Unable to Connect to Homeserver

ca5ua1 commented 1 year ago

Have this issue, how to reproduce:

NixOS Unstable

Dendrite + PostgreSQL + Mautrix-telegram When using SQLite all works as it should. Here is my log (reverse order):


июн 11 22:23:29 Servicer01 mautrix-telegram[834031]: mautrix.errors.request.MForbidden: eventauth: sender "@telegrambot:DOMAIN" not in room
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     raise make_request_error(
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/api.py", line 256, in _send
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     resp_data, resp = await self._send(
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/api.py", line 401, in request
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     resp = await self.api.request(
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/client/api/events.py", line 450, in send_message_event
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     return await super().send_message_event(room_id, event_type, content, **kwargs)
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/appservice/api/intent.py", line 430, in send_message_event
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     return await __method(*args, **kwargs)
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/appservice/api/intent.py", line 141, in wrapper
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     return await self.send_message(room_id, content, **kwargs)
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/client/api/events.py", line 525, in send_text
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     await self.az.intent.send_notice(room_id, text=combined, html=combined_html)
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/bridge/matrix.py", line 525, in send_welcome_message
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     await self.send_welcome_message(room_id, inviter)
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/bridge/matrix.py", line 498, in accept_bot_invite
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     await self.accept_bot_invite(evt.room_id, inviter)
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/bridge/matrix.py", line 534, in int_handle_invite
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     await self.int_handle_invite(evt)
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/bridge/matrix.py", line 949, in int_handle_event
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:     await handler_func(event)
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]:   File "/nix/store/jwsnya4l6fysf0a4ndmlmp75j9nyw44s-python3.10-mautrix-0.18.8/lib/python3.10/site-packages/mautrix/appservice/as_handler.py", line 311, in try_handle
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]: Traceback (most recent call last):
июн 11 22:23:29 Servicer01 mautrix-telegram[834031]: [ERROR@mau.as] Exception in Matrix event handler
июн 11 22:23:28 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:28.985550232Z" level=info msg="Sent event to roomserver" event_id="$O0ay4I49K_Sp5WjOOBS2ysFg9WFTZIlhu7A12FD6iVY" req.id=Z7eYteiKioSO req.method=PUT req.path="/_matrix/client/v3/rooms/!LFiaiErOyp7Xx2eo:DOMAIN/send/m.room.message/mautri>
июн 11 22:23:28 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:28.985147070Z" level=warning msg="Stored soft-failed event" context=missing error="<nil>" event_id="$O0ay4I49K_Sp5WjOOBS2ysFg9WFTZIlhu7A12FD6iVY" kind=KindNew origin=DOMAIN room_id="!LFiaiErOyp7Xx2eo:DOMAIN" type=m.room.message
июн 11 22:23:28 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:28.622233223Z" level=warning msg="Error authing soft-failed event" context=missing error="eventauth: sender \"@telegrambot:DOMAIN\" not in room" event_id="$O0ay4I49K_Sp5WjOOBS2ysFg9WFTZIlhu7A12FD6iVY" kind=KindNew origin=DOMAIN room_>
июн 11 22:23:28 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:28.173947915Z" level=info msg="User joined room successfully" room_id="!LFiaiErOyp7Xx2eo:DOMAIN" servers="[]" user_id="@telegrambot:DOMAIN"
июн 11 22:23:28 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:28.145213629Z" level=warning msg="State reset detected (removing 1 events)" event_id="$heFAnID-1G3xNEMfuUibsuVzqZ9TcA1j77BaC4rffkw" new_latest="[$heFAnID-1G3xNEMfuUibsuVzqZ9TcA1j77BaC4rffkw $8YycrYdB87HRkKYjzsvuxl8CcF29Ye4huzUuunULuSs]>
июн 11 22:23:27 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:27.722610281Z" level=info msg="Fetching state" evType=m.room.power_levels req.id=pdTNLSp62l0C req.method=GET req.path="/_matrix/client/v3/rooms/!LFiaiErOyp7Xx2eo:DOMAIN/state/m.room.power_levels/" roomID="!LFiaiErOyp7Xx2eo:DOMAIN" st>
июн 11 22:23:26 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:26.949831608Z" level=info msg="User joined room successfully" room_id="!LFiaiErOyp7Xx2eo:DOMAIN" servers="[]" user_id="@telegrambot:DOMAIN"
июн 11 22:23:25 Servicer01 qemu-ga[870]: info: guest-ping called
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.484757540Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.484721303Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.484680854Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.484645838Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.484608364Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.484553145Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.484497267Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.484399341Z" level=error msg="Failed to acquire database snapshot for sync request" error="context canceled"
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.470622810Z" level=info msg=Responding backwards=true from=t1_9 limit=20 req.id=CzfYYd6ztPSw req.method=GET req.path="/_matrix/client/r0/rooms/!LFiaiErOyp7Xx2eo:DOMAIN/messages" return_end="" return_start=t1_9 to="" user_id="@ca:>
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.352998698Z" level=info msg="Fetched 1 events locally" backwards=true end="" req.id=CzfYYd6ztPSw req.method=GET req.path="/_matrix/client/r0/rooms/!LFiaiErOyp7Xx2eo:DOMAIN/messages" start=t1_9 user_id="@ca:DOMAIN"
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.079354476Z" level=info msg="User requested to room join" room_id="!LFiaiErOyp7Xx2eo:DOMAIN" servers="[]" user_id="@telegrambot:DOMAIN"
июн 11 22:23:25 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:25.075921213Z" level=info msg="User requested to room join" room_id="!LFiaiErOyp7Xx2eo:DOMAIN" servers="[]" user_id="@telegrambot:DOMAIN"
июн 11 22:23:18 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:23:18.920245509Z" level=info msg="Creating new room" req.id=hKE2lp8HqYoz req.method=POST req.path=/_matrix/client/r0/createRoom roomID="!LFiaiErOyp7Xx2eo:DOMAIN" roomVersion=9 userID="@ca:DOMAIN" user_id="@ca:DOMAIN"
июн 11 22:22:32 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:22:32.526394057Z" level=info msg="missing timeline limit, using default" req.id=7bFZIouJ8WTg req.method=POST req.path="/_matrix/client/r0/user/@ca:DOMAIN/filter" user_id="@ca:DOMAIN"
июн 11 22:22:31 Servicer01 dendrite-monolith-server[834037]: time="2023-06-11T19:22:31.200677357Z" level=info msg=PerformDeviceCreation device_id="<nil>" display_name=0xc003a43b50 localpart=ca req.id=ZtZv56wn2Tuo req.method=POST req.path=/_matrix/client/r0/login

niebloomj commented 6 months ago

Happing to me and keeps crashing my dendrite server

douglaz commented 4 months ago

It's happening to us too

matrix-org / dendrite