Importing music through the web interface does not work and postgres enters deadlock
Hi, I'm facing the issue that the import of music through the web interface does not work. It does not matter if I choose a local music file or try to import from youtube.
The first two steps are successful and it shows that the file was uploaded, which is true because it shows up on the filesystem. If I click on "Finish Import" the redirection to the import badge takes place and there it stays forever on "pending".
Info about my setup:
- Docker
- Traefik Reverse Proxy with embedded and valid certificate
- Nginx as the frontend for funkwhale
- Funkwhale version 0.16.1
The log from the celeryworker shows nearly nothing (celerybeat is alsmost identical):
celery beat v4.1.1 (latentcall) is starting.
__ - ... __ - _
LocalTime -> 2018-08-20 12:39:11
Configuration ->
. broker -> redis://redis:6379/0
. loader -> celery.loaders.app.AppLoader
. scheduler -> celery.beat.PersistentScheduler
. db -> celerybeat-schedule
. logfile -> [stderr]@%INFO
. maxinterval -> 5.00 minutes (300s)
[2018-08-20 12:39:11,724: INFO/MainProcess] beat: Starting...
[2018-08-20 12:40:00,052: INFO/MainProcess] Scheduler: Sending due task federation.clean_music_cache (federation.clean_music_cache)
After the start of funkwhale (but before the import was executed), postgres entered a deadlock as you can see in the following log:
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.
The database cluster will be initialized with locale "en_US.utf8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".
Data page checksums are disabled.
fixing permissions on existing directory /var/lib/postgresql/data ... ok
creating subdirectories ... ok
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting dynamic shared memory implementation ... posix
creating configuration files ... ok
creating template1 database in /var/lib/postgresql/data/base/1 ... ok
initializing pg_authid ... ok
initializing dependencies ... ok
creating system views ... ok
loading system objects' descriptions ... ok
creating collations ... ok
creating conversions ... ok
creating dictionaries ... ok
setting privileges on built-in objects ... ok
creating information schema ... ok
loading PL/pgSQL server-side language ... ok
vacuuming database template1 ... ok
copying template1 to template0 ... ok
copying template1 to postgres ... ok
syncing data to disk ... ok
Success. You can now start the database server using:
postgres -D /var/lib/postgresql/data
or
pg_ctl -D /var/lib/postgresql/data -l logfile start
WARNING: enabling "trust" authentication for local connections
You can change this by editing pg_hba.conf or using the option -A, or
--auth-local and --auth-host, the next time you run initdb.
****************************************************
WARNING: No password has been set for the database.
This will allow anyone with access to the
Postgres port to access your database. In
Docker's default configuration, this is
effectively any other container on the same
system.
Use "-e POSTGRES_PASSWORD=password" to set
it in "docker run".
****************************************************
waiting for server to start....LOG: database system was shut down at 2018-08-20 12:18:45 UTC
LOG: MultiXact member wraparound protections are now enabled
LOG: autovacuum launcher started
LOG: database system is ready to accept connections
done
server started
ALTER ROLE
/usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
LOG: received fast shutdown request
waiting for server to shut down...LOG: aborting any active transactions
.LOG: autovacuum launcher shutting down
LOG: shutting down
LOG: database system is shut down
done
server stopped
PostgreSQL init process complete; ready for start up.
LOG: database system was shut down at 2018-08-20 12:18:48 UTC
LOG: MultiXact member wraparound protections are now enabled
LOG: autovacuum launcher started
LOG: database system is ready to accept connections
ERROR: deadlock detected
DETAIL: Process 100 waits for ShareLock on transaction 911; blocked by process 101.
Process 101 waits for ShareLock on transaction 913; blocked by process 100.
Process 100: INSERT INTO "dynamic_preferences_globalpreferencemodel" ("section", "name", "raw_value") VALUES ('instance', 'short_description', '') RETURNING "dynamic_preferences_globalpreferencemodel"."id"
Process 101: INSERT INTO "dynamic_preferences_globalpreferencemodel" ("section", "name", "raw_value") VALUES ('instance', 'nodeinfo_enabled', 'True') RETURNING "dynamic_preferences_globalpreferencemodel"."id"
HINT: See server log for query details.
CONTEXT: while inserting index tuple (0,9) in relation "dynamic_preferences_glob_section_name_f4a2439b_uniq"
STATEMENT: INSERT INTO "dynamic_preferences_globalpreferencemodel" ("section", "name", "raw_value") VALUES ('instance', 'short_description', '') RETURNING "dynamic_preferences_globalpreferencemodel"."id"
ERROR: duplicate key value violates unique constraint "dynamic_preferences_glob_section_name_f4a2439b_uniq"
DETAIL: Key (section, name)=(common, api_authentication_required) already exists.
STATEMENT: INSERT INTO "dynamic_preferences_globalpreferencemodel" ("section", "name", "raw_value") VALUES ('common', 'api_authentication_required', 'True') RETURNING "dynamic_preferences_globalpreferencemodel"."id"
After a few seconds the log of postgres changed to this:
LOG: database system was shut down at 2018-08-20 12:39:02 UTC
LOG: MultiXact member wraparound protections are now enabled
LOG: autovacuum launcher started
LOG: database system is ready to accept connections
And the log for redis:
1:C 20 Aug 12:39:06.770 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
_._
_.-``__ ''-._
_.-`` `. `_. ''-._ Redis 3.2.12 (00000000/0) 64 bit
.-`` .-```. ```\/ _.,_ ''-._
( ' , .-` | `, ) Running in standalone mode
|`-._`-...-` __...-.``-._|'` _.-'| Port: 6379
| `-._ `._ / _.-' | PID: 1
`-._ `-._ `-./ _.-' _.-'
|`-._`-._ `-.__.-' _.-'_.-'|
| `-._`-._ _.-'_.-' | http://redis.io
`-._ `-._`-.__.-'_.-' _.-'
|`-._`-._ `-.__.-' _.-'_.-'|
| `-._`-._ _.-'_.-' |
`-._ `-._`-.__.-'_.-' _.-'
`-._ `-.__.-' _.-'
`-._ _.-'
`-.__.-'
1:M 20 Aug 12:39:06.772 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
1:M 20 Aug 12:39:06.772 # Server started, Redis version 3.2.12
1:M 20 Aug 12:39:06.772 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
1:M 20 Aug 12:39:06.772 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with Redis. To fix this issue run the command 'echo never > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. Redis must be restarted after THP is disabled.
1:M 20 Aug 12:39:06.772 * DB loaded from disk: 0.000 seconds
1:M 20 Aug 12:39:06.772 * The server is now ready to accept connections on port 6379