search

jellyfin / jellyfin-kodi

Jellyfin Plugin for Kodi
https://jellyfin.org
GNU General Public License v3.0
853 stars 113 forks source link

Library scan crashes RPi 4 1GB #350

Closed macearl closed 4 years ago

macearl commented 4 years ago

Describe the bug On a RPi 4 1GB with libreelec 9.2.3 a library scan with a largeish Library crashes kodi / the pi itself. The most entries it managed to scan where around 100

To Reproduce Set Up the addon as usual and start a scan for the library. It keeps consuming more and more RAM until it either crashes or freezes completely. (after consuming about 700-800MB of RAM)

The same library scans without a problem on a RPi 4 4GB and a few days ago with some fewer entries it also finished without error on a RPi 3b+

Logs Systemd journal:

Aug 05 23:01:19 Pi4-1GB-LibreElec kernel: Out of memory: Kill process 559 (kodi.bin
) score 758 or sacrifice child
Aug 05 23:01:19 Pi4-1GB-LibreElec kernel: Killed process 559 (kodi.bin) total-vm:13
24908kB, anon-rss:745436kB, file-rss:0kB, shmem-rss:0kB
Aug 05 23:01:19 Pi4-1GB-LibreElec kernel: oom_reaper: reaped process 559 (kodi.bin)
, now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Aug 05 23:01:20 Pi4-1GB-LibreElec kodi.sh[554]: Killed
Aug 05 23:01:20 Pi4-1GB-LibreElec systemd[1]: kodi.service: Main process exited, co
de=exited, status=137/n/a
Aug 05 23:01:20 Pi4-1GB-LibreElec systemd[1]: kodi.service: Failed with result 'exi
t-code'.
Aug 05 23:01:22 Pi4-1GB-LibreElec systemd[1]: kodi.service: Service RestartSec=2s e
xpired, scheduling restart.
Aug 05 23:01:22 Pi4-1GB-LibreElec systemd[1]: kodi.service: Scheduled restart job,
restart counter is at 1.
Aug 05 23:01:22 Pi4-1GB-LibreElec systemd[1]: Stopped Kodi Media Center.
Aug 05 23:01:22 Pi4-1GB-LibreElec systemd[1]: Starting Kodi Media Center...
Aug 05 23:01:22 Pi4-1GB-LibreElec systemd[1]: Started Kodi Media Center.

Kodi log (besides the metadata entries it just keeps repeating these messages) :

2020-08-05 23:01:15.424 T:2375865200   DEBUG: Thread JobWorker start, auto delete:
true
2020-08-05 23:01:15.815 T:2478216048   DEBUG: CAddonSettings[plugin.video.jellyfin]
: loading setting definitions
2020-08-05 23:01:15.815 T:2478216048   DEBUG: CAddonSettings[plugin.video.jellyfin]
: trying to load setting definitions from old format...
2020-08-05 23:01:15.831 T:2478216048   DEBUG: CAddonSettings[plugin.video.jellyfin]
: loading setting values
2020-08-05 23:01:15.831 T:2478216048   DEBUG: CSettingsManager: requested setting (
MinimumSetup) was not found.
2020-08-05 23:01:15.831 T:2478216048   DEBUG: CAddonSettings[plugin.video.jellyfin]
: failed to find definition for setting MinimumSetup. Creating a setting on-the-fly
...
2020-08-05 23:01:15.831 T:2478216048   DEBUG: CSettingsManager: requested setting (
MusicRescan) was not found.
2020-08-05 23:01:15.831 T:2478216048   DEBUG: CAddonSettings[plugin.video.jellyfin]
: failed to find definition for setting MusicRescan. Creating a setting on-the-fly.
..
2020-08-05 23:01:15.831 T:2478216048   DEBUG: CSettingsManager: requested setting (
SyncInstallRunDone) was not found.
2020-08-05 23:01:15.831 T:2478216048   DEBUG: CAddonSettings[plugin.video.jellyfin]
: failed to find definition for setting SyncInstallRunDone. Creating a setting on-t
he-fly...
2020-08-05 23:01:15.832 T:2478216048   DEBUG: CSettingsManager: requested setting (
groupedSets) was not found.
2020-08-05 23:01:15.832 T:2478216048   DEBUG: CAddonSettings[plugin.video.jellyfin]
: failed to find definition for setting groupedSets. Creating a setting on-the-fly.
..
2020-08-05 23:01:15.832 T:2478216048   DEBUG: CSettingsManager: requested setting (
platformDetected) was not found.
2020-08-05 23:01:15.832 T:2478216048   DEBUG: CAddonSettings[plugin.video.jellyfin]
: failed to find definition for setting platformDetected. Creating a setting on-the
-fly...
2020-08-05 23:01:15.975 T:2786272112   DEBUG: CAddonSettings[plugin.video.youtube]:
 loading setting definitions
2020-08-05 23:01:15.975 T:2786272112   DEBUG: CAddonSettings[plugin.video.youtube]:
 trying to load setting definitions from old format...
2020-08-05 23:01:15.985 T:2786272112   DEBUG: CAddonSettings[plugin.video.youtube]:
 loading setting values
2020-08-05 23:01:15.987 T:2786272112   DEBUG: CSettingsManager: requested setting (
youtube.api.enable) was not found.
2020-08-05 23:01:15.987 T:2786272112   DEBUG: CAddonSettings[plugin.video.youtube]:
 failed to find definition for setting youtube.api.enable. Creating a setting on-th
e-fly...
2020-08-05 23:01:15.987 T:2786272112   DEBUG: CSettingsManager: requested setting (
youtube.api.key.switch) was not found.
2020-08-05 23:01:15.988 T:2786272112   DEBUG: CAddonSettings[plugin.video.youtube]:
 failed to find definition for setting youtube.api.key.switch. Creating a setting o
n-the-fly...
2020-08-05 23:01:16.034 T:2617643888   DEBUG: CAddonSettings[plugin.video.youtube]:
 loading setting definitions
2020-08-05 23:01:16.034 T:2617643888   DEBUG: CAddonSettings[plugin.video.youtube]:
 trying to load setting definitions from old format...
2020-08-05 23:01:16.038 T:2617643888   DEBUG: CAddonSettings[plugin.video.youtube]:
 loading setting values
2020-08-05 23:01:16.040 T:2617643888   DEBUG: CSettingsManager: requested setting (
youtube.api.enable) was not found.
2020-08-05 23:01:16.040 T:2617643888   DEBUG: CAddonSettings[plugin.video.youtube]:
 failed to find definition for setting youtube.api.enable. Creating a setting on-th
e-fly...
2020-08-05 23:01:16.040 T:2617643888   DEBUG: CSettingsManager: requested setting (
youtube.api.key.switch) was not found.
2020-08-05 23:01:16.040 T:2617643888   DEBUG: CAddonSettings[plugin.video.youtube]:
 failed to find definition for setting youtube.api.key.switch. Creating a setting o
n-the-fly...
2020-08-05 23:01:16.043 T:2617643888   DEBUG: CAddonSettings[plugin.video.youtube]:
 loading setting definitions
2020-08-05 23:01:16.043 T:2617643888   DEBUG: CAddonSettings[plugin.video.youtube]:
 trying to load setting definitions from old format...
2020-08-05 23:01:16.046 T:2617643888   DEBUG: CAddonSettings[plugin.video.youtube]:
 loading setting values
2020-08-05 23:01:16.048 T:2617643888   DEBUG: CSettingsManager: requested setting (
youtube.api.enable) was not found.
2020-08-05 23:01:16.048 T:2617643888   DEBUG: CAddonSettings[plugin.video.youtube]:
 failed to find definition for setting youtube.api.enable. Creating a setting on-th
e-fly...
2020-08-05 23:01:16.048 T:2617643888   DEBUG: CSettingsManager: requested setting (
youtube.api.key.switch) was not found.
2020-08-05 23:01:16.048 T:2617643888   DEBUG: CAddonSettings[plugin.video.youtube]:
 failed to find definition for setting youtube.api.key.switch. Creating a setting o
n-the-fly...
2020-08-05 23:01:16.049 T:2617643888   DEBUG: [plugin.video.youtube] HTTPServer: Re
quest uri path |/ping|
2020-08-05 23:01:16.049 T:2617643888   DEBUG: [plugin.video.youtube] HTTPServer: Co
nnection from |127.0.0.1| Local range: |True|
2020-08-05 23:01:16.063 T:2786272112   DEBUG: [plugin.video.youtube] HTTPServer: Pi
ng |127.0.0.1:50152| |204|

System (please complete the following information):

mcarlton00 commented 4 years ago

It looks like you've activated debug logging on Kodi itself, but not the addon. Can you verify it's enabled in Add-ons -> Jellyfin -> Settings -> Advanced? Also have you noticed any difference depending on what media type you're syncing?

macearl commented 4 years ago

I've also set the logging level to debug in the jellyfin addon. But it just generated a ton of output containing the metadata of the movie it was syncing at the time (the log file is about 350mb). I'm on the road over the weekend so I don't have access to it right now but I can try and extract some additional entries from it on Sunday. Uploading or posting the whole thing is not really feasible due to the size. Is there anything in particular which would be helpful or could I just filter out some stuff to reduce the size? The metadata entries are probably not really relevant?

The entries it did manage to scan seem to be correct and complete, the available ram just runs out after some time.

I have only tried to sync movies yet. There are also about 4 TV shows with a 1 or 2 seasons each on this server. I'll try to only sync those first and see if it can manage it.

I've also tried to reduce the gpu_mem and lower the display resolution so that kodi can use almost the full GB of ram.

Later tonight or tomorrow I also have access to the RPi 3B+ again and can check if it can still complete a full scan on a clean install. As I also installed the 10.6.1 and 10.6.2 updates after it did its initial sync.

I'll also try to grab some logs from this scan.

macearl commented 4 years ago

I tried a fresh scan on an RPi 3B+ (the hostname was still set to RPi4-1GB-Libreelec as I've reused the sd card)

It crashed after a couple of entries, with debug logging enabled it took about 5-10 times longer to scan the same amount and crashed slightly later than without it.

https://sebsauvage.net/paste/?c8c78c39b010e654#b23evgg3tlw8Obaj6hd45mX/24FoImoaerYTHlJ+dOY

mcarlton00 commented 4 years ago

Your logs have a log of ERROR::jellyfin_kodi/jellyfin/ws_client.py:67 Handshake Status 502 in them, which seems to indicate an error talking to the server. But that's also related to websockets specifically, which doesn't matter during the bulk sync process.

I've been testing the last few days with a Pi 3B+ on libreelec and i haven't encountered any sync issues, so I'm not sure what the issue is

macearl commented 4 years ago

I poked around the code a bit and it seems, that the plugin just uses the builtin library sync function from kodi, correct? In this case this probably is more of an issue with kodi/the data the jellyfin server sends? Is there anything i could try on the server? I'm currently running the deb Package on another RPi 4GB through a NGINX reverse proxy (i have also tried accessing it directly, at least with local clients)

For now i have enabled Swap in Libreelec, which enables it to complete a scan. For this it starts to use up to 400MB of RAM and then starts to swap, it then peaks at about 450MB in both RAM and Swap. After about 5% of the scan the Swap starts to grow a bit more until it reaches about 530MB, at the same time RAM usage goes down to about 360MB. After that it mostly stays there until towards the end of the scan both values go back down and settle at around 200 each after the scan finished.

mcarlton00 commented 4 years ago

Not exactly. We're using our code to write directly to Kodi's database. Which is rather frowned upon by the Kodi team (fun fact). But I've never seen a crash from being out of memory before, and I used Emby for Kodi on Pis for years before the fork. I suppose if you were running the server and Kodi on the same Pi it would probably get memory starved, but especially just Kodi on a 1GB Pi4 it should be fine, considering my tests are on a Pi 3B+ have come back fine through:

Also oddly enough, swap usage on my 3B+ sits steady at 0 during the sync, with memory hovering around 200MB

macearl commented 4 years ago

I had some time, so i tried setting up a fresh jellyfin server, this time i chose the docker container and mounted my Media Directory into it read only. After setting everything up and waiting for the initial scan it shows the same behavior as the deb package.

Strange that it's only happening to me. Could things like non english characters be a problem? I have some Asian and Nordic Movies which use some special characters in their folder name. (But then this should probably only be a problem on the server, and not with a client, and seeing as even those 'special' characters are still UTF-8 this shouldn't really matter)

5hay commented 4 years ago

I seem to have the same issue you're describing @macearl but on a Fire TV Stick 4K (if I'm not mistaken it has 1.5 GB RAM). Latest Jellyfin 10.6.2 (official Docker image on Ubuntu 20.04 LTS). Installed Kodi and the Jellyfin Kodi addon yesterday (both latest stable versions) and during the initial sync it just crashes Kodi AND the Fire TV (good old unplugging power for it to restart). Big library, but not as big as @mcarlton00 's. I also have the Jellyfin plugin installed that helps with syncing.

mcarlton00 commented 4 years ago

Was this working properly for either of you on 10.5.5, or are you new users on 10.6.x?

macearl commented 4 years ago

I started using jellyfin with v10.5.5 everything seemed to work up to 10.6.0 with around ~700 movies and a few episodes.

I then updated to 10.6.1 and a day later to 10.6.2 as I saw 10.6.1 only a couple of days after its release. I then continued to copy over movies until the library reached ~1500 movies at this point I noticed the problems.

I also downgraded back to 10.6.0 which worked with around 700 movies to see if that fixes it but no luck. And if I understand correctly there where some breaking changes making a downgrade to 10.5.5 impossible. I'll try and read up some more on docker to see if I can install a clean 10.5.5 that way and see if this problem also exists pre 10.6

macearl commented 4 years ago

I did some more testing, with a fresh Jellyfin 10.5.5 Docker installation i am able to complete the scan without swap and a maximum ram usage of around 300MB

mcarlton00 commented 4 years ago

Thanks for confirming. Right now our guess is that this and #365 are the same underlying issue, which was a change in the upstream API from Jellyfin.

mcarlton00 commented 4 years ago

Can you try installing this zip file and see if the issue still exists?

Link

5hay commented 4 years ago

or are you new users on 10.6.x?

Yes.

Thank you for your update, I've tried the zip file. First by just updating the already installed version, but still crashed. Then I wiped everything in Kodi and installed your file but still a crash. It can't even get to 1% during the sync.

mcarlton00 commented 4 years ago

This is frustrating. Why can't I replicate this? It seems as though it should be failing consistently, especially if I'm on weaker hardware. We're missing something here.

Let's try going at this from a different angle.

macearl commented 4 years ago

I just tried your update, unfortunately the problem persists.

Steps done on RPi 4 1GB and RPi 3b+:

  1. freshly installed vanilla LibreELEC 9.2.4
  2. Installed addon through your provided zip file
  3. Set up addon with server url, username and password, no further changes
  4. Chose addon mode and selected only movies as a library to sync

Default sync settings:

On the RPi 4 1GB I also tried setting max items and download threads to 1 and try another scan, with the same result.

mcarlton00 commented 4 years ago

I don't particularly expect this to work, but can you try this version and see if it does anything different?

Also, what library types are you syncing?

macearl commented 4 years ago

I have set up 2 libraries on the jellyfin server "Movies" and "TV Shows" and I am currently only trying to sync the movie library.

I can't download the file at the moment as I'm redirected to a login page, perhaps it's not set to public?

mcarlton00 commented 4 years ago

Hmm, we'll try it this way plugin.video.jellyfin-py2.zip

macearl commented 4 years ago

The download worked, I had to modify the zip slightly for kodi to be able to install it as it found an invalid structure (I just removed some git specific files/folders and recreated the zip with all files in another directory of the same name as the zip file.

However still no luck, it crashes roughly after the same time.

mcarlton00 commented 4 years ago

How are you connecting to the server? Are you using a reverse proxy or base URL? Something is inconsistent here about why I can't replicate this. The only real issue I'm seeing in your logs is that websockets one, but I've never seen that mess with syncing.

macearl commented 4 years ago

I tried both.

My "normal" setup:

(with local devices I also tried connecting directly with the local ip and base url to make sure its not nginx that's causing the problems, i have not yet opened additional ports for direct external access)

My docker test setup:

xwiggen commented 4 years ago

The plugin crashes kodi on armhf, both 1Gb and 2Gb RAM (stable LibreElec). Workaround is creating swapfile, sync works after that without crashing. sudo fallocate -l 1G /swapfile mkswap /swapfile swapon /swapfile

mcarlton00 commented 4 years ago

It's confusing that I'm able to sync fine on a Pi 3, but macearl has reported that it failed for him. And I would expect the Pi 4 to have more power and be even more fine with syncing. I know the Pi 4 has a new processor, but imo that shouldn't be what the root issue is, as newer should be better at handling this. And then there's the issue of the FireTV, which afaik doesn't have the option of adding swap files.

We've had some strange localization issues come up from time to time, I'm wondering if that has an effect on performance here. Does anybody have Kodi set to a non-english language?

repomaa commented 4 years ago

I had the same issue, and managed to sync eventually by appending cma=64 to /flash/cmdline.txt and setting gpu_mem=256 in /flash/config.txt (you need to remount /flash with rw option: mount -o rw --remount /flash)

So this is most likely a memory leaking issue.

xwiggen commented 4 years ago

it's not a memleak.issuingsync; echo 3 > /proc/sys/vm/drop_caches before running out of memory clears cache and allows for syncing without swap/modifications.

mammo0 commented 4 years ago

Hello, I've got exactly the same problem with my Odroid N2+ running the latest CoreELEC. When doing a fresh sync (fresh install, etc.) I can watch how my 4GB RAM gets filled.

The suggestions of @repomaa or @xwiggen doesn't work in my case.

Sorry for not posting my Kodi log file. If I enable debug logging, the sync process does start, but is extremely slow. It takes around 3 minutes to sync 1 movie. I watched this process e.g. 1 hour but no errors were reported during that period. After that I canceled and disabled debug logging again. During a normal sync (without debug log enabled) I noticed that the first few movies are also synced slowly (10 - 20 seconds per movie). After about 3% of the sync process and 80% of RAM usage it suddenly speeds up (can't count how many movies per second). But there are still no errors in the (non debugging) log file.

My setup:

Both Kodi instances access the Jellyfin server behind its nginx reverse proxy on my LAN. No connection from WAN.

mammo0 commented 4 years ago

After writing the above, I disabled logging in the addon completely. And now the sync completes... There was still about 85% RAM usage (~3,3GB). After the initial sync finished, the RAM usage dropped back to about 30%. This is still much, but is OK for me.

mammo0 commented 4 years ago

I think that I found the cause of this bug. @macearl Can you please try this version of the plugin: plugin.video.jellyfin-0.6.2.2+py2.zip

This version is build upon my PR #410.

With this version the RAM usage on my Odroid N2+ during the initial sync was around 800MB. After the sync it went back to about 500MB.

macearl commented 4 years ago

didn't have that much time, but it still crashes for me. Tried it on 2 freshly set up SD Cards with different options for parallel items and download threads. It looks like it fails on multiples of the number of parallel requests so maybe it could be something with the cleanup after one batch finished?

I tried running it again with debug log enabled but it took too long and now i had to cancel the sync

mammo0 commented 4 years ago

Ok thanks for your feedback.

As I said just in my PR, a thread pool may be not needed for synchronization? This may also improve the performance on lower powered devices.

phyzical commented 4 years ago

just wanted to add some more data to the issue.

running a raspberry pi 2B rev 1.1 1gb, running osmc.

mine would crash at the letter A, i was watching it via htop and it was completely locking up as it ran out of ram.

if i gave it some swap it would make it further to B in tv shows and the scan would just fail instead of locking up. i also tried increase the swap to 4gb but then i started having the pi restart.

macearl commented 4 years ago

This should he fixed with https://github.com/jellyfin/jellyfin-kodi/pull/410

I'd probably close this issue now or should we wait for the fix to be included in the next release version?

oddstr13 commented 4 years ago

Closing as probable fix is merged. Reopen or create new issue if the problem persists after next release.

mcarlton00 commented 3 years ago

0.6.4 has been released, this should be fixed now once you update the addon.