Describe the bug with a clear and concise deion of what the bug is. <p dir

[bug] Notifications not loading about gotosocial HOT 12 CLOSED

lily-bit-0 commented on June 12, 2024

[bug] Notifications not loading

from gotosocial.

Comments (12)

tsmethurst commented on June 12, 2024 1

Ah, thank you for the detailed investigation and writeup! What strange behavior! I wonder if the account aliases are causing an infinite loop of GET statements or something like that, I'll have a look :) in the meantime, glad to hear your instance is usable again!

from gotosocial.

tsmethurst commented on June 12, 2024

Hi, judging from the logs the issue is that the database query is taking a really long time, so your client hangs up the request and then you get the context canceled issue. Could you tell me which database backend you're using (sqlite vs postgres)? And are you on 0.15.0-rc2 now, or still on 0.15.0-rc1?

from gotosocial.

lily-bit-0 commented on June 12, 2024

I use sqlite and I’ve upgraded to 0.15.0-rc2 on the day it released.

from gotosocial.

tsmethurst commented on June 12, 2024

Hmm okay, it might be worth running a manual analyze and vacuum on the database as described here just to make sure everything is in order; it's possible that the analyze step from updating to 0.15.0-rc1 got interrupted or something.

from gotosocial.

lily-bit-0 commented on June 12, 2024

I did that and it looked like this, I don’t know what it’s supposed to look like but I guess nothing out of the ordinary happened:

sqlite> PRAGMA analysis_limit=0; ANALYZE;
0
sqlite> VACUUM;
sqlite>

Afterwards notifications still didn’t load. Then I upgraded to 0.15.0 and it didn’t make a difference either, the log when loading notifications still looks the same.

from gotosocial.

tsmethurst commented on June 12, 2024

Alright, thanks for trying. Do you have any issues loading other things on your account, like loading the federated timeline or loading your list of followers/following, that sort of thing? Is there anything particularly unusual about your filesystem setup, or the location where your database files are stored, ie., are you storing them on a different drive or anything like that? Also, do you see anything in your logs that looks like SLOW QUERY when you're making these requests? Just trying to narrow things down.

from gotosocial.

lily-bit-0 commented on June 12, 2024

Most things load quickly but the local and federated timelines (that I don’t usually use) take around 16 seconds to load on both accounts, and my main account’s following list loads quickly but the follower list also fails to load (even though I don’t have many followers and follow a lot more people), resulting in similar log lines as the notification issue with a latency of one minute in the final line and those two error lines. This is again just an idea but maybe the followers being affected also hints at the cause being the failed move attempt.

All GTS stuff is in /gotosocial which is on a MicroSD on a Raspberry Pi 3 B+. It also has a USB HDD but nothing from GTS is on it right now.

When I grep for SLOW there are quite a few lines with SLOW DATABASE QUERY, about 50-300 per day. These lines appear when I open the local and federated timelines that take 16 seconds but they don’t appear when I open notifications or the follower list.

from gotosocial.

tsmethurst commented on June 12, 2024

Ah, microsd is not really suitable for running databases on. Moving at least your sqlite database files over to a decent USB drive should clear it up. I don't think the move is related tbh. At least, I don't see how it could be. Could you try moving your sqlite db files over to the USB drive instead and have gotosocial access them from there?

from gotosocial.

tsmethurst commented on June 12, 2024

(funnily enough we recently added a line to the docs about running gts on single board computers, and call out microsd specifically: https://docs.gotosocial.org/en/latest/getting_started/#single-board-computers)

from gotosocial.

lily-bit-0 commented on June 12, 2024

I moved /gotosocial to the HDD and now the local and federated timelines take about 12 seconds to load, so it made a difference there, but notifications and followers still don’t load and the log looks the same.

I also changed my swappiness from 60 to 10 as the docs suggest but it didn’t make a difference.

In case this helps, here is another pair of logs for notifications and followers with log-level set to debug and log-db-queries to true:

timestamp="12/04/2024 18:24:02.874" func=server.glob..func1.Logger.func13.1 level=INFO latency="363.225µs" userAgent="Mozilla/5.0 (X11; Linux x86_64; rv:124.0) Gecko/20100101 Firefox/124.0" method=OPTIONS statusCode=204 path=/api/v1/notifications clientIP=138.199.6.196 requestID=7a41zmwe04000ydmhkv0 msg="No Content: wrote 0B"
timestamp="12/04/2024 18:25:03.005" func=typeutils.(*Converter).AccountToAPIAccountPublic level=ERROR requestID=qp41zmwe04000hze94gg msg="error(s) populating account, will continue: PopulateAccount: error populating account avatar: context canceled\nPopulateAccount: error populating moved to account: context canceled"
timestamp="12/04/2024 18:25:03.005" func=typeutils.(*Converter).AccountToAPIAccountPublic level=ERROR requestID=qp41zmwe04000hze94gg msg="error converting account movedTo: AccountToAPIAccountPublic: error getting last posted: context canceled"
timestamp="12/04/2024 18:25:03.124" func=typeutils.(*Converter).AccountToAPIAccountPublic level=ERROR requestID=qp41zmwe04000hze94gg msg="error(s) populating account, will continue: PopulateAccount: error populating account avatar: context canceled\nPopulateAccount: error populating account header: context canceled\nPopulateAccount: error populating account emojis: context canceled\nPopulateAccount: error populating account settings: context canceled"
timestamp="12/04/2024 18:25:03.125" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HTJSCY8KP6V9SZAVCW2CHF59 because it couldn't be converted to its api representation: NotificationToapi: error converting status to api: statusToFrontend: error converting status author: AccountToAPIAccountPublic: error getting last posted: context canceled"
timestamp="12/04/2024 18:25:03.126" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HTGAG2WZ5A2GPQ4R8JWHXAV0 because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HK00GBRND3JP24FYHDB3T8CK visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.127" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HTEE5YNVRB6C9E4RKK8HF7DA because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HTEE5WR7MM4Z3021CTNXY4C7 visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.127" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HTCM3ZRGNY3TNBXYZJZ714JP because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HNBRW8F27BCZCWC8EHMJA5WT visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.128" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HSXWX06YG7RTVRPHHDW6FKMT because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HJVCYTD8MQY05TZZ46HRH0GV visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.128" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HRYBGSBV0S73C0865P3H2VEY because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HRYBGQGH8D9SHJ81KV2HBC39 visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.129" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HRPN097NHGQWMEHM1266NAHE because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HK01JQRCEZHFWBMZB33VCB9R visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.130" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HRJFSNK2EYT3DKG3FA4Q46AB because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HK00GBRND3JP24FYHDB3T8CK visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.131" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HQA63SD932J6PNJ5676QXFZM because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HQ67DZKG46PY56YDJG7VCRDQ visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.131" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HPV5W4B5JMEEQQSVP8EXM2KS because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HMBSJ83MQB80Z1RWGE3ZP2EH visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.132" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HPV5VHVYKBYANEB62AFFXE3R because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HMBSJ83MQB80Z1RWGE3ZP2EH visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.133" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HPDD0620AJGCJWBJYTWQ311Q because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HJVJHSNVN3GJNQT6VTY47F8Q visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.133" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HPCXBWW3QE26HJSBENY7PH0E because of an error checking notification visibility: isAccountVisibleTo: error checking account 01H4G70SKP1HK4Z9KRT7H6Y116 visibility: isAccountVisible: db error getting user for account 01H4G70SKP1HK4Z9KRT7H6Y116: context canceled"
timestamp="12/04/2024 18:25:03.134" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HPCXBFPW78KQ8R048B08QWWC because of an error checking notification visibility: isAccountVisibleTo: error checking account 01H4G70SKP1HK4Z9KRT7H6Y116 visibility: isAccountVisible: db error getting user for account 01H4G70SKP1HK4Z9KRT7H6Y116: context canceled"
timestamp="12/04/2024 18:25:03.135" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HP6NMRFMTQV9J9AHP7Q5RC85 because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HJVJHSNVN3GJNQT6VTY47F8Q visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.136" func=timeline.(*Processor).NotificationsGet level=DEBUG requestID=qp41zmwe04000hze94gg msg="skipping notification 01HP3PMGDRJYPE9CY1M155AC7F because of an error checking notification visibility: isAccountVisibleTo: error checking account 01HNBRW8F27BCZCWC8EHMJA5WT visibility: isAccountVisible: db error getting user for account 01FX0XAZ0XFMCPPJC19NB3VW0Y: context canceled"
timestamp="12/04/2024 18:25:03.142" func=server.glob..func1.Logger.func13.1 level=INFO latency="1m0.136378746s" userAgent="Mozilla/5.0 (X11; Linux x86_64; rv:124.0) Gecko/20100101 Firefox/124.0" method=GET statusCode=200 path=/api/v1/notifications clientIP=138.199.6.196 requestID=qp41zmwe04000hze94gg msg="OK: wrote 4.00kiB"

timestamp="12/04/2024 18:13:01.364" func=server.glob..func1.Logger.func13.1 level=INFO latency="141.196µs" userAgent="Mozilla/5.0 (X11; Linux x86_64; rv:124.0) Gecko/20100101 Firefox/124.0" method=OPTIONS statusCode=204 path=/api/v1/accounts/01FX0XAZ0XFMCPPJC19NB3VW0Y/followers clientIP=138.199.6.196 requestID=6hr1bmwe04001ftsgd0g msg="No Content: wrote 0B"
timestamp="12/04/2024 18:14:01.490" func=typeutils.(*Converter).AccountToAPIAccountPublic level=ERROR requestID=p5r1bmwe040004fzqfdg msg="error(s) populating account, will continue: PopulateAccount: error populating account header: context canceled\nPopulateAccount: error populating moved to account: context canceled"
timestamp="12/04/2024 18:14:01.490" func=typeutils.(*Converter).AccountToAPIAccountPublic level=ERROR requestID=p5r1bmwe040004fzqfdg msg="error converting account movedTo: AccountToAPIAccountPublic: error getting last posted: context canceled"
timestamp="12/04/2024 18:14:02.423" func=util.WriteResponseBytes level=ERROR requestID=p5r1bmwe040004fzqfdg msg="error writing: write tcp 127.0.0.1:8081->127.0.0.1:59966: i/o timeout"
timestamp="12/04/2024 18:14:02.423" func=server.glob..func1.Logger.func13.1 level=INFO latency="1m0.93417337s" userAgent="Mozilla/5.0 (X11; Linux x86_64; rv:124.0) Gecko/20100101 Firefox/124.0" method=GET statusCode=200 path=/api/v1/accounts/01FX0XAZ0XFMCPPJC19NB3VW0Y/followers clientIP=138.199.6.196 requestID=p5r1bmwe040004fzqfdg msg="OK: wrote 4.00kiB"

(Note that I removed log lines that looked unrelated because of different client IPs for example)

from gotosocial.

tsmethurst commented on June 12, 2024

Hiya, I think the context canceled log lines indicate that it's still taking forever to get things out of the DB for some reason. Could you describe the USB drive that the db is now sitting on? I suspect it might also not be suitable for having a database on. Most people I know that succeed in running GtS on a raspberry pi plug a portable SSD into the USB port of the rpi (the usb 3 port that is, iirc).

from gotosocial.

lily-bit-0 commented on June 12, 2024

It’s a regular Seagate IronWolf connected via an Inateck SATA to USB 3.0 adapter that has its own power supply. The Raspberry Pi is a model 3 B+ that unfortunately only has USB 2.0, so I thought an SSD wouldn’t really make a difference. I guess it could be time to upgrade to a better SBC + SSD but I don’t mind if it’s just a little slow and it has been working well enough until now.

I did a little experiment to check if better hardware would fix the issue by copying the GtS directory over to my desktop PC with its M.2 NVMe SSD. I didn’t set it up fully, I just replaced the binary with the AMD64 version, ran it and used curl commands I copied from Semaphore using Firefox network developer tools to query the GtS API on localhost.

It worked and lowered the latency of local and federated timelines down to 350 ms, but notifications and followers still didn’t work and returned the same log messages as above. In this setup without a reverse proxy in front of GtS, the notification and follower queries didn’t time out after one minute anymore and the log lines only appeared when I cancelled the curl command. So I left the command running for longer to see if it would work eventually, but after about 8 minutes of querying for notifications or followers GtS just crashes. I then temporarily changed the log-level to trace and saw that as soon as I query notifications or followers, the log gets spammed with tons of stuff every few milliseconds until I stop the query or it crashes. I guess that means that notifications and followers not loading is not a hardware issue?

I was about to send what I’ve written until this point but then I took a closer look at the trace log spam and noticed that it’s all about my two previous Fedi accounts, the one I tried to move from and the one I then moved back to when moving to GtS didn’t work. I also remembered that I put both of these accounts into my GtS account aliases when I tried to move, but some time later I removed the aliases. So I tried adding the account aliases back again, and that actually fixed it! Now I can even remove the aliases once again and notifications and followers still load, with a latency of only 400 ms on the Raspberry Pi.

I went through the logs to create a timeline of what happened:

2024-04-03 22:19:32 I add account aliases
2024-04-04 15:04 I start multiple failing attempts to move my Misskey account to GtS
2024-04-04 15:30:38 I try moving it to my old Mastodon account instead which worked
2024-04-05 10:48:35 notifications break
2024-04-07 18:07:12 I remove account aliases

Unless I read the logs wrong it looks like notifications broke two days before I removed the account aliases, so I’m pretty sure I removed them to see if it would fix notifications, which it didn’t. But that also means that removing the aliases didn’t cause the issue, so it’s unexpected that adding them back fixed it. The first failed notification query happened the morning after the move, which I believe was the first time I’ve newly loaded a client after the move attempts, so that could mean that it broke some time between that morning and the previous day’s move attempts.

I’ll close this now since my notifications and followers work again but I’d be happy to provide logs or anything else if needed, I have log files of the crashes and traces that I did on my desktop and I still have a copy of the GtS directory from before fixing the issue.

Thanks for your help!

from gotosocial.

[bug] Notifications not loading about gotosocial HOT 12 CLOSED

Comments (12)

Related Issues (20)

Recommend Projects

React

Vue.js

Typescript

TensorFlow

Django

Laravel

D3

Recommend Topics

javascript

web

server

Machine learning

Visualization

Game

Recommend Org

Facebook

Microsoft

Google

Alibaba

D3

Tencent