Navidrome: Image caching breaks when a large number of releases are loaded

[arg274]

Hardware:

• OS: Raspbian (32-bit)
• Arch: armhf

Steps to reproduce the bug:

• Set the WebUI to display 72 elements per page
• Choose any album view (Was tested with "Random" and "All")
• Scroll page by page making sure that all the images on every page have finished loading (Usually requires a library large enough to reach that point, presumably a thousand or more releases)

At one point, the images will break, and will continue staying that way until a service restart. Only the images that had been cached beforehand will be visible. Affects the *sonic API as well. Disabling the image cache seems to circumvent the issue.

Excerpts from the log:

Aug 16 17:43:10 piserver navidrome[11286]: 2020/08/16 17:43:10 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Aug 16 17:43:11 piserver navidrome[11286]: 2020/08/16 17:43:11 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Aug 16 17:43:12 piserver navidrome[11286]: 2020/08/16 17:43:12 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Aug 16 17:43:13 piserver navidrome[11286]: 2020/08/16 17:43:13 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Aug 16 17:43:14 piserver navidrome[11286]: 2020/08/16 17:43:14 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s

Aug 16 17:41:20 piserver navidrome[11286]: time="2020-08-16T17:41:20+01:00" level=error msg="Error reading dir" error="open /mnt/extstorage/Music/Tom Waits/[1985] Rain Dogs [CD - MP3 - 320]: too many open files" path="/mnt/extstorage/Music/Tom Waits/[1985] Rain Dogs [CD - MP3 - 320]"
Aug 16 17:41:20 piserver navidrome[11286]: time="2020-08-16T17:41:20+01:00" level=error msg="Error loading directory tree" error="open /mnt/extstorage/Music/Tom Waits/[1985] Rain Dogs [CD - MP3 - 320]: too many open files"
Aug 16 17:41:20 piserver navidrome[11286]: time="2020-08-16T17:41:20+01:00" level=error msg="Error accessing image cache" error="open /home/pi/navdata/cache/images/l9ikgc_6rcbce240ca165c5724e902d373c3a9428: too many open files" path="/mnt/extstorage/Music/水曜日のカンパネラ/[2015] ジパング [CD - MP3 - 320]/07 - ライト兄弟.mp3" requestId=piserver/qzlNscJxQI-001686 size=300
Aug 16 17:41:20 piserver navidrome[11286]: time="2020-08-16T17:41:20+01:00" level=error msg="Error retrieving coverArt" error="open /home/pi/navdata/cache/images/l9ikgc_6rcbce240ca165c5724e902d373c3a9428: too many open files" id=81024fbec52d6bd514ef66efb9c416d4 requestId=piserver/qzlNscJxQI-001686

[deluan]

Seems that there is some sort of file descriptor leakage... This may be caused by the upstream https://github.com/djherbis/fscache library. Will do more investigation. For now the solution is what you did: turn off the cache with ImageCacheSize=0

[vs49688]

I just hit this on 0.37.0. Same problem, same fix.
Can be triggered in a few minutes navigating when using the Navidrome Kodi addon (it seems to load a LOT).

• OS: NixOS 20.09 (64-bit)
• Arch: x86_64

Nov 15 16:22:07 CADANCE navidrome[1482]: time="2020-11-15T16:22:07+10:00" level=error msg="Error accessing image cache" error="open /var/lib/navidrome/cache/images/ly8dnF_Mta29cf5e6e4753f65ada46c2596e1c3a0.key: too many open files" path="<sanitized>" requestId=CADANCE/bE2q8ud4Xx-003392 size=0
Nov 15 16:22:07 CADANCE navidrome[1482]: time="2020-11-15T16:22:07+10:00" level=error msg="Error retrieving coverArt" error="open /var/lib/navidrome/cache/images/ly8dnF_Mta29cf5e6e4753f65ada46c2596e1c3a0.key: too many open files" id=188003b3f59697bdbea2242fe65b024d requestId=CADANCE/bE2q8ud4Xx-003392
Nov 15 16:22:07 CADANCE navidrome[1482]: time="2020-11-15T16:22:07+10:00" level=warning msg="API: Failed response" error=0 message="Internal Error" requestId=CADANCE/bE2q8ud4Xx-003392
Nov 15 16:22:14 CADANCE navidrome[1482]: 2020/11/15 16:22:14 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 5ms
Nov 15 16:22:15 CADANCE navidrome[1482]: 2020/11/15 16:22:15 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 5ms
Nov 15 16:22:15 CADANCE navidrome[1482]: 2020/11/15 16:22:15 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 10ms
Nov 15 16:22:15 CADANCE navidrome[1482]: 2020/11/15 16:22:15 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 5ms
Nov 15 16:22:16 CADANCE navidrome[1482]: 2020/11/15 16:22:16 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 5ms
Nov 15 16:22:16 CADANCE navidrome[1482]: 2020/11/15 16:22:16 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 10ms
Nov 15 16:22:16 CADANCE navidrome[1482]: 2020/11/15 16:22:16 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 20ms
Nov 15 16:22:16 CADANCE navidrome[1482]: 2020/11/15 16:22:16 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 40ms
Nov 15 16:22:16 CADANCE navidrome[1482]: 2020/11/15 16:22:16 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 5ms
Nov 15 16:22:16 CADANCE navidrome[1482]: 2020/11/15 16:22:16 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 10ms
Nov 15 16:22:16 CADANCE navidrome[1482]: time="2020-11-15T16:22:16+10:00" level=error msg="Error accessing transcoding cache" error="open /var/lib/navidrome/cache/transcoding/lx3eyA30n90ef6d94ff90af744a4d39ae17d6cb1a: too many open files" id=1e1cf5e8ae79cacd28c11b57d2c45fe2 requestId=CADANCE/bE2q8ud4Xx-003397

[deluan]

Will investigate, thanks for reporting it.

[deluan]

Hey @vs49688 , can you try this build: https://github.com/deluan/navidrome/suites/1517769433/artifacts/26733088 ?

(Remember to reenable the Image Cache)

[vs49688]

Am testing now. Should probably also mention I woke up to more of the same (this is after updating to 0.38.0):

EDIT: This was with the image cache disabled.....

Nov 18 10:23:31 CADANCE navidrome[30464]: 2020/11/18 10:23:31 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 18 10:23:32 CADANCE navidrome[30464]: 2020/11/18 10:23:32 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 18 10:23:32 CADANCE navidrome[30464]: time="2020-11-18T10:23:32+10:00" level=error msg="Error reading dir" error="open /storage/SyncRoot/Music/music: too many open files" path=/storage/SyncRoot/Music/music
Nov 18 10:23:32 CADANCE navidrome[30464]: time="2020-11-18T10:23:32+10:00" level=error msg="Error loading directory tree" error="open /storage/SyncRoot/Music/music: too many open files"
Nov 18 10:23:32 CADANCE navidrome[30464]: time="2020-11-18T10:23:32+10:00" level=error msg="There were errors reading directories from filesystem" error="open /storage/SyncRoot/Music/music: too many open files"
Nov 18 10:23:32 CADANCE navidrome[30464]: time="2020-11-18T10:23:32+10:00" level=error msg="Scan was interrupted by error. See errors above" error="open /storage/SyncRoot/Music/music: too many open files"
Nov 18 10:23:32 CADANCE navidrome[30464]: time="2020-11-18T10:23:32+10:00" level=error msg="Error importing MediaFolder" error="open /storage/SyncRoot/Music/music: too many open files" folder=/storage/SyncRoot/Music/music
Nov 18 10:23:32 CADANCE navidrome[30464]: time="2020-11-18T10:23:32+10:00" level=error msg="Errors while scanning media. Please check the logs"
Nov 18 10:23:33 CADANCE navidrome[30464]: 2020/11/18 10:23:33 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 18 10:23:33 CADANCE navidrome[30464]: time="2020-11-18T10:23:33+10:00" level=warning msg="Pre-cache warmer is not available as ImageCache is DISABLED"
Nov 18 10:23:33 CADANCE navidrome[30464]: time="2020-11-18T10:23:33+10:00" level=error msg="scan error"

[vs49688]

Nope, still happens. Both with and without image cache. Full log attached.

EDIT: Seems email attachments are dropped: https://github.com/deluan/navidrome/files/5557147/navidrome.log.gz

[esiqveland]

Seeing the same navidrome 0.38.0 on arm64.
I am not certain of ulimit it is running with, but this is very probably a file descriptor leak, as it never recovers again after this starts happening.

[deluan]

Yes, this is definitely a file descriptor leaking. Can any of you guys try with version 0.36.0?

[esiqveland]

restarted .38.0 again now with debug logging and suddenly cant reproduce anymore.

deleted the caches/images folder and still can not reproduce.

[esiqveland]

My issue may not be the same.

See logs:

Nov 20 19:57:24 alarmpi navidrome[12027]: time="2020-11-20T19:57:24Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:26 alarmpi navidrome[12027]: time="2020-11-20T19:57:26Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:26 alarmpi navidrome[12027]: time="2020-11-20T19:57:26Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001217 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:26 alarmpi navidrome[12027]: time="2020-11-20T19:57:26Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:28 alarmpi navidrome[12027]: time="2020-11-20T19:57:28Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:28 alarmpi navidrome[12027]: time="2020-11-20T19:57:28Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001218 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:28 alarmpi navidrome[12027]: time="2020-11-20T19:57:28Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:30 alarmpi navidrome[12027]: time="2020-11-20T19:57:30Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:30 alarmpi navidrome[12027]: time="2020-11-20T19:57:30Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001219 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:30 alarmpi navidrome[12027]: time="2020-11-20T19:57:30Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:32 alarmpi navidrome[12027]: time="2020-11-20T19:57:32Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:32 alarmpi navidrome[12027]: time="2020-11-20T19:57:32Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001220 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:32 alarmpi navidrome[12027]: time="2020-11-20T19:57:32Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:34 alarmpi navidrome[12027]: time="2020-11-20T19:57:34Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:34 alarmpi navidrome[12027]: time="2020-11-20T19:57:34Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001221 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:34 alarmpi navidrome[12027]: time="2020-11-20T19:57:34Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:36 alarmpi navidrome[12027]: time="2020-11-20T19:57:36Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:36 alarmpi navidrome[12027]: time="2020-11-20T19:57:36Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001222 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:36 alarmpi navidrome[12027]: time="2020-11-20T19:57:36Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:38 alarmpi navidrome[12027]: time="2020-11-20T19:57:38Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:38 alarmpi navidrome[12027]: time="2020-11-20T19:57:38Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001223 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:38 alarmpi navidrome[12027]: time="2020-11-20T19:57:38Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:40 alarmpi navidrome[12027]: time="2020-11-20T19:57:40Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:40 alarmpi navidrome[12027]: time="2020-11-20T19:57:40Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001224 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:40 alarmpi navidrome[12027]: time="2020-11-20T19:57:40Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:42 alarmpi navidrome[12027]: time="2020-11-20T19:57:42Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:42 alarmpi navidrome[12027]: time="2020-11-20T19:57:42Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001225 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:42 alarmpi navidrome[12027]: time="2020-11-20T19:57:42Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:44 alarmpi navidrome[12027]: time="2020-11-20T19:57:44Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:44 alarmpi navidrome[12027]: time="2020-11-20T19:57:44Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001226 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:44 alarmpi navidrome[12027]: time="2020-11-20T19:57:44Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:46 alarmpi navidrome[12027]: time="2020-11-20T19:57:46Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:46 alarmpi navidrome[12027]: time="2020-11-20T19:57:46Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001227 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:46 alarmpi navidrome[12027]: time="2020-11-20T19:57:46Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:48 alarmpi navidrome[12027]: time="2020-11-20T19:57:48Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:48 alarmpi navidrome[12027]: 2020/11/20 19:57:48 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 5ms
Nov 20 19:57:48 alarmpi navidrome[12027]: time="2020-11-20T19:57:48Z" level=debug msg="New broker client" address=192.168.192.1 requestId=alarmpi/RXoAMNhVPr-001228 user=eivind userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36"
Nov 20 19:57:48 alarmpi navidrome[12027]: time="2020-11-20T19:57:48Z" level=debug msg="Client added to event broker" numClients=1
Nov 20 19:57:48 alarmpi navidrome[12027]: 2020/11/20 19:57:48 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 10ms
Nov 20 19:57:48 alarmpi navidrome[12027]: 2020/11/20 19:57:48 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 20ms
Nov 20 19:57:48 alarmpi navidrome[12027]: 2020/11/20 19:57:48 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 40ms
Nov 20 19:57:48 alarmpi navidrome[12027]: 2020/11/20 19:57:48 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 80ms
Nov 20 19:57:48 alarmpi navidrome[12027]: 2020/11/20 19:57:48 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 160ms
Nov 20 19:57:48 alarmpi navidrome[12027]: 2020/11/20 19:57:48 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 320ms
Nov 20 19:57:48 alarmpi navidrome[12027]: 2020/11/20 19:57:48 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 640ms
Nov 20 19:57:49 alarmpi navidrome[12027]: 2020/11/20 19:57:49 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:57:50 alarmpi navidrome[12027]: time="2020-11-20T19:57:50Z" level=debug msg="Removed client from event broker" numClients=0
Nov 20 19:57:50 alarmpi navidrome[12027]: 2020/11/20 19:57:50 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:57:51 alarmpi navidrome[12027]: 2020/11/20 19:57:51 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:57:52 alarmpi navidrome[12027]: 2020/11/20 19:57:52 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:57:53 alarmpi navidrome[12027]: 2020/11/20 19:57:53 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:57:54 alarmpi navidrome[12027]: 2020/11/20 19:57:54 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:57:55 alarmpi navidrome[12027]: 2020/11/20 19:57:55 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:57:56 alarmpi navidrome[12027]: 2020/11/20 19:57:56 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:57:57 alarmpi navidrome[12027]: 2020/11/20 19:57:57 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:57:58 alarmpi navidrome[12027]: 2020/11/20 19:57:58 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:57:59 alarmpi navidrome[12027]: 2020/11/20 19:57:59 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:58:00 alarmpi navidrome[12027]: 2020/11/20 19:58:00 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:58:01 alarmpi navidrome[12027]: 2020/11/20 19:58:01 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:58:02 alarmpi navidrome[12027]: 2020/11/20 19:58:02 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:58:03 alarmpi navidrome[12027]: 2020/11/20 19:58:03 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s
Nov 20 19:58:04 alarmpi navidrome[12027]: 2020/11/20 19:58:04 http: Accept error: accept tcp [::]:4533: accept4: too many open files; retrying in 1s

Notice how the web client keeps reconnecting.

[deluan]

Hummm, can you try disabling the Activity Panel with the config option DevActivityMenu=false? Also, I need confirmation this is happening in 0.36.1 and 0.37.0, if someone can try it, please

[vs49688]

Happens in 0.37.0. navidrome-0.37.0-cache.txt.gz.

Testing in 0.36.1 shortly.

This was reproduced by repeatedly hitting random and waiting for cover art to fail to load. When that didn't work, I switched to the Navidrome Kodi plugin. Navigating releases worked. Navigating artists (and failing to load the artist images) triggered it almost immediately.

Perhaps something isn't being closed upon failure?

[vs49688]

Also happens in 0.36.1. navidrome-0.36.1-cache.txt.gz

[deluan]

Thanks @vs49688! Is it too much to ask you to keep testing until you find the version it was last working? That would be extremely helpful, as I cannot seem to reproduce the issue here...

[deluan]

To rule out the upgrade to Go 1.15 (introduced in version 0.35.0), I've built the current version from master using Go 1.14. If any of you guys can test it, it would be very helpful. Thanks!

navidrome_v0.38.0-SNAPSHOT_Linux_arm64.tar.gz
navidrome_v0.38.0-SNAPSHOT_Linux_armv5.tar.gz
navidrome_v0.38.0-SNAPSHOT_Linux_armv6.tar.gz
navidrome_v0.38.0-SNAPSHOT_Linux_armv7.tar.gz
navidrome_v0.38.0-SNAPSHOT_Linux_i386.tar.gz
navidrome_v0.38.0-SNAPSHOT_Linux_x86_64.tar.gz

[vs49688]

Just tried it on this (with Go 1.14) and it still happens.
I seem to be able to reproduce it by navigating artists with the Kodi Navidrome plugin.

I could give you shell access if it'd help with debugging.

[vs49688]

Just reproduced it on 0.34.0

[deluan]

I could give you shell access if it'd help with debugging.

Thanks but I don't think that would help :(

0.34.0 only introduced UI changes, so the next logical candidate version (that introduced server changes) is 0.33.0, where the taglib extractor was introduced. I wonder if the taglib extractor is the code to blame here.... Can you please test version 0.38.0, but using Scanner.Extractor="ffmpeg"?

[vs49688]

Done, still happens.

Repro notes (personal):

• Open Kodi Plugin
• Navigate all artists (557), letting each default image load.
• Navigate and load 14 "random" pages of albums
• Triggered when it starts displaying a vertical rectangular image with a video camera in the centre for each album.

[vs49688]

I'm going to keep going back until I find one that's working, then I'll do a bisect on it. Probably won't get to this until tonight though.
Will report back.

[vs49688]

Well, that was several hours of my life I'll never get back. Bisected to 9f4f2f7381039b135b4bfe4595b03395d4625774.

EDIT: Should probably note that was done by cherry-picking 16397e08fcfc5368e2d6da635e6c4b10da3e96af as needed.

9f4f2f7381039b135b4bfe4595b03395d4625774 is the first bad commit
commit 9f4f2f7381039b135b4bfe4595b03395d4625774
Author: Deluan <[email protected]>
Date:   Fri Jul 24 13:30:27 2020 -0400

    Use new FileCache in cover service

 core/core_suite_test.go     | 18 ------------
 core/cover.go               | 72 +++++++++++++++++++--------------------------
 core/cover_test.go          | 27 +++++++----------
 core/file_caches.go         |  9 +++---
 core/file_caches_test.go    | 50 +++++++++++++++++++++++++++++--
 core/media_streamer.go      |  2 +-
 core/media_streamer_test.go |  3 +-
 7 files changed, 97 insertions(+), 84 deletions(-)

[deluan]

Hey @vs49688, really, really thanks for this. Are you in Discord? I'd like to chat about your finds.

[vs49688]

No worries. I'm not, but I could probably create an account. I see you have a matrix.org account, could we chat there?

[esiqveland]

If you enable pprof debugging, we can probably heap/threaddump and make these much simpler to debug:

https://golang.org/pkg/net/http/pprof/

[zoidy]

Hummm, can you try disabling the Activity Panal with the config option DevActivityMenu=false? Also, I need confirmation this is happening in 0.36.1 and 0.37.0, if someone can try it, please

I tried with the latest commit and I think the problem is indeed related to the activity panel. It may also be related to #640 since I also have that problem. I was able to reproduce the too many open files error like this:

• Compile the latest version
• Run two identical instances of the binary running on separate ports on the local LAN. The only difference is one has the DevActivityPanel=true setting.
• Open the Navidrome Album page and set the view to 72 (not sure this is important)
• Let both instances just sit there. The instance with the Activity Panel enabled has an error about every second related to http://<server>:<port>/app/api/events?jwt=<token> in the Network tab in the dev tools panel of the browser
• After about 30-45 minutes, the instance with DevActivityMenu=true stops responding and the "too many open files" error appears on the server

[darkeststar]

Not sure if this is related, but calls to /app/api/events appears to be consistently leaking a socket when the call gets cancelled. Which seems to be happening a decent amount when using the web client.

As an example, of a leak:

Number of file descriptors when the server is sitting idle:

$ sudo ls -l /proc/$(pidof navidrome)/fd | wc -l
257

Perform GET on app/api/event:

curl 'http://music.infosphere/app/api/events?jwt=<JWT_TOKEN>' \
  -H 'Connection: keep-alive' \
  -H 'Accept: text/event-stream' \
  -H 'Cache-Control: no-cache' \
  -H 'DNT: 1' \
  -H 'User-Agent: Mozilla/5.0 (X11; Fedora; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.198 Safari/537.36' \
  -H 'Referer: <REFERER>' \
  -H 'Accept-Language: en-US,en;q=0.9' \
  --compressed

While the call is running:

$ sudo ls -l /proc/$(pidof navidrome)/fd | wc -l
258

Using strace I can see what syscalls were made:

$ sudo strace -p $(pidof navidrome) -f --trace network
...
[pid 230876] accept4(14, {sa_family=AF_INET6, sin6_port=htons(44246), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_scope_id=0}, [112->28], SOCK_CLOEXEC|SOCK_NONBLOCK) = 312
[pid 230876] getsockname(312, {sa_family=AF_INET6, sin6_port=htons(4533), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_scope_id=0}, [112->28]) = 0
[pid 230876] setsockopt(312, SOL_TCP, TCP_NODELAY, [1], 4) = 0
...

Then after killing the curl command:

The number of open file descriptors never goes back down:

$ sudo ls -l /proc/$(pidof navidrome)/fd | wc -l
258

And the socket allocated in the accept4 call above (with file descriptor of 312) never gets closed:

$ sudo ls -l /proc/$(pidof navidrome)/fd/312
lrwx------. 1 navidrome navidrome 64 Nov 30 23:55 /proc/230861/fd/312 -> 'socket:[1061509]'

The strace output never show the above file descriptor getting cleaned up.

[deluan]

Hey @darkeststar, thanks for the detailed debugging! Yes, I can confirm that the Activity Panel is definitely add up to the issue, but it is not the main culprit. I'll release a new version today with the Activity Panel and the Image Cache disabled by default, that should alleviate the issue for new users, while I don't figure out the final solution for this issue

EDIT: This particular FD leakage was just fixed in a8c5fa6, and will be in the next release

[esiqveland]

I also think I had a old load balancer in front that did not play well with SSE. I think this caused numerous failed connections from some web clients, leaking connections much faster. I currently have no issues with caddy 2.2.0

[izaak]

I'll just say 'me too' and if there's anything I can do to help debug/test, I've got time. I'll be monitoring the open file descriptors closely, after disabling the image cache.

[jdaviescoates]

I noticed my images weren't loading anymore, and so came here to see if I could find out why, and I guess it's due to the fact image cache has been disabled by default.. how can I turn image caching back on to see if it still works on my system? Thanks!

[deluan]

Even with the Image Cache disabled, you should see the images. You can enable it with ImageCacheSize=100MB (100MB is the old default, but you can set it to any value greater than 0)

[jdaviescoates]

I do see some images, but strangely not some that I was seeing previously. And yeah I've actually already added that bit of code but didn't notice any difference.

[izaak]

I had encountered the file descriptor bug. Now I'm on 0.39.0 but I'm encountering strange behaviour with album art. Sometimes I restart Navidrome and some covers that worked before will disappear. To fix, I trigger a scan of a particular folder by updating the file times, and the cover comes back. Should I create a new issue, or is it related to this one?