Issues updating to 0.23/0.24 - DB migration fails

[TheForcer]

Hi there,

first up, I have been using Navidrome very successfully for a while now in Docker, mostly running version 0.22 on a Raspberry Pi 3B+ with music accessed via a SMB share. Now that setup has recently been migrated to a Pi 4 running Ubuntu 20, and has been working perfectly there as well.
I've been wanting to upgrade to 0.24/0.23 now, but when starting my docker-compose stack with the updated Docker Image, the DB migrations seem to fail and Navidrome does not start up.

These are trace logs from 0.22 -> 0.23. Same thing when updating to 0.24.

Attaching to navidrome
navidrome    |  _   _             _     _
navidrome    | | \ | |           (_)   | |
navidrome    | |  \| | __ ___   ___  __| |_ __ ___  _ __ ___   ___
navidrome    | | . ` |/ _` \ \ / / |/ _` | '__/ _ \| '_ ` _ \ / _ \
navidrome    | | |\  | (_| |\ V /| | (_| | | | (_) | | | | | |  __/
navidrome    | \_| \_/\__,_| \_/ |_|\__,_|_|  \___/|_| |_| |_|\___|
navidrome    |                            Version: 0.23.0 (2d1d992)
navidrome    | 
navidrome    | time="2020-07-10T12:35:07Z" level=debug msg="Loaded configuration" config="&conf.nd{ConfigFile:\"./navidrome.toml\", Port:\"4533\", MusicFolder:\"/music\", DataFolder:\"/data\", ScanInterval:\"1m\", DbPath:\"/data/navidrome.db?cache=shared&_busy_timeout=15000&_journal_mode=WAL&_foreign_keys=on\", LogLevel:\"trace\", SessionTimeout:\"30m\", BaseURL:\"\", UILoginBackgroundURL:\"https://source.unsplash.com/random/1600x900?music\", IgnoredArticles:\"The El La Los Las Le Les Os As O A\", IndexGroups:\"A B C D E F G H I J K L M N O P Q R S T U V W X-Z(XYZ) [Unknown]([)\", EnableTranscodingConfig:false, TranscodingCacheSize:\"400MB\", ImageCacheSize:\"100MB\", ProbeCommand:\"ffmpeg %s -f ffmetadata\", DevLogSourceLine:false, DevAutoCreateAdminPassword:\"\"}" file=./navidrome.toml
navidrome    | time="2020-07-10T12:35:07Z" level=debug msg="Opening DataBase" dbPath="/data/navidrome.db?cache=shared&_busy_timeout=15000&_journal_mode=WAL&_foreign_keys=on" driver=sqlite3
navidrome    | time="2020-07-10T12:35:07Z" level=error msg="Failed to apply new migrations" error="failed to run Go migration \"20200608153717_referential_integrity.go\": FOREIGN KEY constraint failed"

Since I didn't care much about the database, I decided to start fresh and use a new database. Thats when I discovered that Navidrome for some reason cannot initially read the Music on the file share. Using a migrated DB and a old version, I can play music with no problem. Starting fresh with any version gives me a read error on the music share.
I think this could be due to some technical issues with the mount, maybe similar to the issue described here #294 (comment)
In the end - To get the new version to work, I need to update my existing installation

The database itself is in a Docker volume on the Pi, so it should be unaffected by this issue. Do you have an idea why I am getting these migration errors?

Thanks in advance :)
Felix

[deluan]

Thanks for the report! Can you try with the attached version?

navidrome_v0.24.0-SNAPSHOT_Linux_arm64.tar.gz
navidrome_v0.24.0-SNAPSHOT_Linux_armv7.tar.gz

[TheForcer]

Sure, I ran the binary with the existing data paths to my data/music folder. Seems to be the same output.

root@SRV-Pi2:~/docker-compose/navidrome# ./navidrome -loglevel trace -datafolder /var/lib/docker/volumes/navidrome_data/_data/ -musicfolder /mnt/ts-221/multimedia/FLAC-Musik/

 _   _             _     _
| \ | |           (_)   | |
|  \| | __ ___   ___  __| |_ __ ___  _ __ ___   ___
| . ` |/ _` \ \ / / |/ _` | '__/ _ \| '_ ` _ \ / _ \
| |\  | (_| |\ V /| | (_| | | | (_) | | | | | |  __/
\_| \_/\__,_| \_/ |_|\__,_|_|  \___/|_| |_| |_|\___|
                 Version: v0.24.0-SNAPSHOT (f0ee52a)

DEBU[0000] Loaded configuration                          config="&conf.nd{ConfigFile:\"./navidrome.toml\", Port:\"4533\", MusicFolder:\"/mnt/ts-221/multimedia/FLAC-Musik/\", DataFolder:\"/var/lib/docker/volumes/navidrome_data/_data/\", ScanInterval:\"1m\", DbPath:\"/var/lib/docker/volumes/navidrome_data/_data/navidrome.db?cache=shared&_busy_timeout=15000&_journal_mode=WAL&_foreign_keys=on\", LogLevel:\"trace\", SessionTimeout:\"24h\", BaseURL:\"\", UILoginBackgroundURL:\"https://source.unsplash.com/random/1600x900?music\", IgnoredArticles:\"The El La Los Las Le Les Os As O A\", IndexGroups:\"A B C D E F G H I J K L M N O P Q R S T U V W X-Z(XYZ) [Unknown]([)\", EnableTranscodingConfig:false, TranscodingCacheSize:\"100MB\", ImageCacheSize:\"100MB\", ProbeCommand:\"ffmpeg %s -f ffmetadata\", CoverArtPriority:\"embedded, cover.*, folder.*, front.*\", DevLogSourceLine:false, DevAutoCreateAdminPassword:\"\"}" file=./navidrome.toml
DEBU[0000] Opening DataBase                              dbPath="/var/lib/docker/volumes/navidrome_data/_data/navidrome.db?cache=shared&_busy_timeout=15000&_journal_mode=WAL&_foreign_keys=on" driver=sqlite3
ERRO[0000] Failed to apply new migrations                error="failed to run Go migration \"20200608153717_referential_integrity.go\": FOREIGN KEY constraint failed"

[deluan]

Ok, can you try this?

navidrome_v0.24.0-SNAPSHOT_Linux_arm64.tar.gz
navidrome_v0.24.0-SNAPSHOT_Linux_armv7.tar.gz

[TheForcer]

Hi, the second versions seems to work fine, looks like the migrations were successful. Thanks!
Unfortunately still getting the access errors on my music library, but I guess thats on my end...

INFO[0000] Navidrome server is accepting requests        address=":4533"
TRAC[0002] SQL: `SELECT value FROM property WHERE id = ?`  args="['LastScan-/mnt/ts-221/multimedia/FLAC-Musik/']" elapsedTime="457.383µs" rowsAffected=1
DEBU[0002] Scanning folder                               folder=/mnt/ts-221/multimedia/FLAC-Musik/ lastModifiedSince="2020-07-12 12:41:51.841 +0200 CEST"
ERRO[0002] Error importing MediaFolder                   error="readdirent: interrupted system call" folder=/mnt/ts-221/multimedia/FLAC-Musik/
TRAC[0002] SQL: `UPDATE property SET value = ? WHERE id = ?`  args="['1594550969455','LastScan-/mnt/ts-221/multimedia/FLAC-Musik/']" elapsedTime="562.659µs" rowsAffected=1
ERRO[0002] Errors while scanning media. Please check the logs 
ERRO[0002] Error scanning media folder                   error="errors while scanning media" folder=/mnt/ts-221/multimedia/FLAC-Musik/

[deluan]

Thanks for helping fixing the migration issue. Regarding the access error, does it happen in the beginning of the scan, or it gets to import some files before failing?

[TheForcer]

I just found the underlying issue in a restic forum thread where someone also had problems with CIFS shares. It seems like with Go 1.14 some of the new asynchronous preemption stuff CIFS doesn't work really well, see here https://forum.restic.net/t/prune-fails-on-cifs-repo-using-go-1-14-build/2579

I added the GODEBUG=asyncpreemptoff=1 variable to my Docker compose file, and voila, works perfectly :)
Maybe that's worth a note as a workaround in the Docs?

[deluan]

Great finding! Awesome!! I'll add it to the docs. Maybe even making it default, if there's no bad side effects. Thanks a lot!

Will close this for now, but feel free to reopen if you find any related issue.

[deluan]

More info about the async preemption issue in Go 1.14: kubernetes/kubernetes#92521

Some projects are even skipping Go 1.14 to avoid this issue.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.