Front page displays errors

Zekovski

Hello,
Thank you for answering.

Here is what I got ...

raspberryraspberry:~$ systemctl status funkwhale-beat.service 
× funkwhale-beat.service - Funkwhale celery beat process
     Loaded: loaded (/etc/systemd/system/funkwhale-beat.service; disabled; preset: enabled)
     Active: failed (Result: exit-code) since Sun 2024-02-04 13:16:46 CET; 2 days ago
   Duration: 42.674s
    Process: 829 ExecStart=/srv/funkwhale/venv/bin/celery --app funkwhale_api.taskapp beat --loglevel INFO (code=exited, status=1/FAILURE)
   Main PID: 829 (code=exited, status=1/FAILURE)
        CPU: 20.795s

Feb 04 13:16:45 raspberry celery[829]: Configuration ->
Feb 04 13:16:45 raspberry celery[829]:     . broker -> redis://127.0.0.1:6379/0
Feb 04 13:16:45 raspberry celery[829]:     . loader -> celery.loaders.app.AppLoader
Feb 04 13:16:45 raspberry celery[829]:     . scheduler -> celery.beat.PersistentScheduler
Feb 04 13:16:45 raspberry celery[829]:     . db -> celerybeat-schedule
Feb 04 13:16:45 raspberry celery[829]:     . logfile -> [stderr]@%INFO
Feb 04 13:16:45 raspberry celery[829]:     . maxinterval -> 5.00 minutes (300s)
Feb 04 13:16:46 raspberry systemd[1]: funkwhale-beat.service: Main process exited, code=exited, status=1/FAILURE
Feb 04 13:16:46 raspberry systemd[1]: funkwhale-beat.service: Failed with result 'exit-code'.
Feb 04 13:16:46 raspberry systemd[1]: funkwhale-beat.service: Consumed 20.795s CPU time.
raspberryraspberry:~$ systemctl status funkwhale-server.service 
● funkwhale-server.service - Funkwhale application server
     Loaded: loaded (/etc/systemd/system/funkwhale-server.service; disabled; preset: enabled)
     Active: active (running) since Sun 2024-02-04 13:16:06 CET; 2 days ago
   Main PID: 830 (gunicorn)
     Status: "Gunicorn arbiter booted"
      Tasks: 12 (limit: 765)
        CPU: 27min 1.580s
     CGroup: /system.slice/funkwhale-server.service
             ├─830 /srv/funkwhale/venv/bin/python3 /srv/funkwhale/venv/bin/gunicorn config.asgi:application --workers 2 --worker-class uvicorn.workers.UvicornWorker --bind 127.0.0.1:5000
             ├─840 /srv/funkwhale/venv/bin/python3 /srv/funkwhale/venv/bin/gunicorn config.asgi:application --workers 2 --worker-class uvicorn.workers.UvicornWorker --bind 127.0.0.1:5000
             └─842 /srv/funkwhale/venv/bin/python3 /srv/funkwhale/venv/bin/gunicorn config.asgi:application --workers 2 --worker-class uvicorn.workers.UvicornWorker --bind 127.0.0.1:5000

Feb 06 20:13:03 raspberry gunicorn[842]:                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Feb 06 20:13:03 raspberry gunicorn[842]:   File "/srv/funkwhale/venv/lib/python3.11/site-packages/psycopg2/__init__.py", line 122, in connect
Feb 06 20:13:03 raspberry gunicorn[842]:     conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
Feb 06 20:13:03 raspberry gunicorn[842]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Feb 06 20:13:03 raspberry gunicorn[842]: django.db.utils.OperationalError: connection to server on socket "/var/run/postgresql/.s.PGSQL.5432" failed: FATAL:  the database system is in recovery mode
Feb 06 20:13:06 raspberry gunicorn[842]: [2024-02-06 19:13:06 +0000] [842] [INFO] connection closed
Feb 06 21:44:21 raspberry gunicorn[842]: [2024-02-06 20:44:21 +0000] [842] [INFO] ('5.183.104.47', 0) - "WebSocket /api/v1/activity" [accepted]
Feb 06 21:44:21 raspberry gunicorn[842]: [2024-02-06 20:44:21 +0000] [842] [INFO] connection open
Feb 06 21:44:24 raspberry gunicorn[842]: 2024-02-06 20:44:24,760 django.request WARNING  Method Not Allowed: /api/v1/subscriptions/all/
Feb 06 21:44:53 raspberry gunicorn[842]: [2024-02-06 20:44:53 +0000] [842] [INFO] connection closed

For your information, I followed this page : https://docs.funkwhale.audio/administrator/configuration/optimize.html after installation, and set CELERYD_CONCURRENCY=1. Maybe I should reset it to default to see if it works better.
I also tried --pool solo but it seems deprecated.

gcrk

Zekovski OperationalError: connection to server on socket "/var/run/postgresql/.s.PGSQL.5432" failed: FATAL: the database system is in recovery mode

Thats pretty clear, your database is out of service for some reason. I'd recommend to check its logs and try to solve the issue and restart Funkwhale afterwards.

Zekovski

That's strange because it sometimes works. I would have accused an access delay but OK.
I'll look into it, thank you.
How do I get access to detailed logs from the data base ? Right now I don't know what to correct exactly.

After restarting just now, the server status seems fine. But the beat service still fails, it says logfile is [stderr]@%INFO but I'm sorry, I don't know what it is.

And after displaying the front page I got this :

2024-02-07 10:07:32,744 django.request WARNING  Method Not Allowed: /api/v1/channels/
/srv/funkwhale/venv/lib/python3.11/site-packages/rest_framework/pagination.py:200: UnorderedObjectListWarning: Pagination may yield inconsistent results with an unordered object_list: <class 'funkwhale_api.playlists.models.Playlist'> PlaylistQuerySet.
   paginator = self.django_paginator_class(queryset, page_size)

But I have no channel nor playlist set up in the website or the db.

gcrk

Zekovski To get the database logs, run journalctl -u postgresql.

Zekovski After restarting just now, the server status seems fine. But the beat service still fails, it says logfile is [stderr]@%INFO but I’m sorry, I don’t know what it is.

Me neither, but more context of the message might help 🙂

The log message you sent isn't of any concern, it's just a warning. Please ignore it.

Zekovski

gcrk
OK thank you.

Postgresql journal doesn't show anything out of the ordinary.

Looking at funwhale-server I still get a bunch of these :

Feb 11 21:08:33 raspberry gunicorn[834]: django.db.utils.OperationalError: connection to server on socket "/var/run/postgresql/.s.PGSQL.5432" failed: FATAL:  the database system is not yet accepting connections
Feb 11 21:08:33 raspberry gunicorn[834]: DETAIL:  Consistent recovery state has not been yet reached.

The problem seems related to artists though. As I can't see them from my app, nor from the website apparently. Kinda random idea : Could this be because I have a "Various artists" artist attached to several albums but no track ?

gcrk

Zekovski The log message states quite clearly that postgres is not reachable, this has nothing to do with artists. If the database is not available, Funkwhale is unable to read or write data. It looks like the database got corrupted for some reason, but I cannot tell without having more details or log messages.

Zekovski

That's strange because I can still access my data and listen to my music.

Anyway, here is the result of journalctl -u postgresql :

-- Boot a5397e0236f44ccb968331152327105d --
Feb 04 13:16:03 raspi systemd[1]: Starting postgresql.service - PostgreSQL RDBMS...
Feb 04 13:16:03 raspi systemd[1]: Finished postgresql.service - PostgreSQL RDBMS.
Feb 11 18:14:41 raspi systemd[1]: postgresql.service: Deactivated successfully.
Feb 11 18:14:41 raspi systemd[1]: Stopped postgresql.service - PostgreSQL RDBMS.
-- Boot d31b070826e84cdda586895c8145c552 --
Feb 11 18:14:53 raspi systemd[1]: Starting postgresql.service - PostgreSQL RDBMS...
Feb 11 18:14:53 raspi systemd[1]: Finished postgresql.service - PostgreSQL RDBMS.
Feb 11 21:28:23 raspi systemd[1]: postgresql.service: Deactivated successfully.
Feb 11 21:28:23 raspi systemd[1]: Stopped postgresql.service - PostgreSQL RDBMS.
-- Boot a189b6a44ffe411982219c4f60cdbf7b --
Feb 11 21:28:35 raspi systemd[1]: Starting postgresql.service - PostgreSQL RDBMS...
Feb 11 21:28:35 raspi systemd[1]: Finished postgresql.service - PostgreSQL RDBMS.

And it goes back like this to the start with always the same messages. The status is active (exited).

Sorry if I'm slow thinking, I'm still learning how everything works together.

gcrk

Zekovski I am not a postgres expert, but maybe check /var/log as well? Is postgres also using the external disk to store its data?

Zekovski

No, postgresql is not using the external disk.

I just checked /var/log and indeed found a bunch of these :

2024-02-15 18:55:03.854 CET [743] LOG:  database system is ready to accept connections
2024-02-15 18:55:06.497 CET [743] LOG:  server process (PID 985) was terminated by signal 11: Segmentation fault
2024-02-15 18:55:06.497 CET [743] DETAIL:  Failed process was running: SELECT "music_album"."id", "music_album"."fid", "music_album"."mbid", "music_album"."uuid", "music_album"."from_activity_id", "music_album"."creation_date", "music_album"."body_text", "music_album"."title", "music_album"."artist_id", "music_album"."release_date", "music_album"."release_group_id", "music_album"."attachment_cover_id", "music_album"."type", "music_album"."attributed_to_id", "music_album"."description_id", COUNT("music_track"."id") AS "_tracks_count", (SELECT W0."id" FROM "music_upload" W0 INNER JOIN "music_track" W2 ON (W0."track_id" = W2."id") WHERE (W0."import_status" IN ('finished', 'skipped') AND W0."library_id" IN (SELECT V0."id" FROM "music_library" V0 INNER JOIN "federation_actor" V1 ON (V0."actor_id" = V1."id") WHERE ((V0."actor_id" = 1 AND V0."privacy_level" = 'me') OR (V1."domain_id" = 'musique.chezmwa.fr' AND V0."privacy_level" = 'instance') OR V0."privacy_level" = 'everyone' OR V0."id" IN (SELECT U0."target_id" FROM "federation_libraryfollow" U0 WHERE (U0."actor_id" = 1 AND U0."appr
2024-02-15 18:55:06.497 CET [743] LOG:  terminating any other active server processes
2024-02-15 18:55:06.502 CET [986] funkwhale@funkwhale FATAL:  the database system is in recovery mode
2024-02-15 18:55:06.510 CET [743] LOG:  all server processes terminated; reinitializing
2024-02-15 18:55:06.562 CET [990] LOG:  database system was interrupted; last known up at 2024-02-15 18:55:03 CET
2024-02-15 18:55:06.566 CET [993] funkwhale@funkwhale FATAL:  the database system is in recovery mode
2024-02-15 18:55:06.599 CET [995] funkwhale@funkwhale FATAL:  the database system is in recovery mode
2024-02-15 18:55:06.636 CET [998] funkwhale@funkwhale FATAL:  the database system is in recovery mode
2024-02-15 18:55:06.670 CET [1000] funkwhale@funkwhale FATAL:  the database system is in recovery mode
2024-02-15 18:55:06.675 CET [990] LOG:  database system was not properly shut down; automatic recovery in progress
2024-02-15 18:55:06.687 CET [990] LOG:  invalid record length at 0/F0A23C8: wanted 24, got 0
2024-02-15 18:55:06.687 CET [990] LOG:  redo is not required
2024-02-15 18:55:06.703 CET [1003] funkwhale@funkwhale FATAL:  the database system is not yet accepting connections
2024-02-15 18:55:06.703 CET [1003] funkwhale@funkwhale DETAIL:  Consistent recovery state has not been yet reached.
2024-02-15 18:55:06.721 CET [991] LOG:  checkpoint starting: end-of-recovery immediate wait
2024-02-15 18:55:06.743 CET [1005] funkwhale@funkwhale FATAL:  the database system is not yet accepting connections
2024-02-15 18:55:06.743 CET [1005] funkwhale@funkwhale DETAIL:  Consistent recovery state has not been yet reached.
2024-02-15 18:55:06.767 CET [991] LOG:  checkpoint complete: wrote 2 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.014 s, sync=0.005 s, total=0.052 s; sync files=3, longest=0.002 s, average=0.002 s; distance=0 kB, estimate=0 kB
2024-02-15 18:55:06.785 CET [743] LOG:  database system is ready to accept connections

I remember some SQL, so is there some way to find the issue directly inside the database maybe ?

gcrk

Zekovski I would try to restore the database from backup or contact postgresql community to get support.

Zekovski

OK thank you for your help so far.

I don't have a bakcup yet because it's brand new. Just one thing : Is it normal for this query in the logs to be this long ? Do you know if the logs cut the end or was it faulty in itself ?

gcrk

Zekovski Queries can be quite long since they are optimized for different things and I'd bet it was cut by the logging.