Freezing while scanning music library with Teufel Android App

1st Official Post

    Hi there.

    You'll find my log files here Http://ix.io/1gw3

    I'm running my RP3 with an external HDD. This had all my mp3 music. The HDD is source for the music library of my RP3. Everything is running smoothly.

    As speaker I have a Teufel Cinebar 52 THX. This is running with a Raumfeld Connector. Here the details on Teufel homepage.

    My problem is, that when I start the Teufel Raumfeld Android App and add the RP3 music Library as a new source, about 500 - 1000 songs are going to be scanned, before RP3 is hanging up. Memory is getting more and more low up to 40140 kb and CPU ist getting high up to 99 %.

    Anyone with an idea how RP3 and Teufel Raumfeld could work together?

    Edited once, last by JohnLocke (July 9, 2018 at 7:19 AM).

    I updated to Milhouse 9 #0708.

    Here the new log files.

    Http://ix.io/1gz2

    Http://ix.io/1gz3

    But problem still exists: I start the Teufel Raumfeld Android App and add the RP3 music Library as a new source, about 500 - 1000 songs are going to be scanned, before RP3 is hanging up. Memory is getting more and more low up to 40140 kb and CPU ist getting high up to 120 %.

    With #0708, does Kodi actually crash due to out of memory (it may take a while, up to 30 minutes or so)? Once Kodi restarts, post kodi.old.log and also the contents of "journalctl -a".

    It looks like the Teufel app is hammering on the Kodi webserver for information. Maybe this is causing a memory leak, or the Teufel is just flooding Kodi with requests.

    You could try enabling debug logging, and then also enabling JSON-RPC and Webserver component logging, and then start your Teufel and maybe we'll see what requests the Teufel is making to Kodi. Assuming Kodi restarts, upload kodi.old.log and "journalctl -a".

    It seems the Android addon is grinding it's way through your database using UPnP.

    What makes you think it runs out of memory - you've said "Memory is getting more and more low up to 40140 kb", how are you determining this?

    Unfortunately I can't see the journalctl log you posted to ix.io (the service is down at this time) but if Kodi is not restarting then it's probably not being killed by the out of memory process killer.

    From the kodi.old.log it looks like 1,111 UPnP items are processed in approximately 3 minutes. Then the "bing" screensaver starts. I don't see any further processing of any kind after that.

    It might be worth testing without any additional addons installed - start with a "clean" .kodi folder:

    1. systemctl stop kodi

    2. mv /storage/.kodi /storage/.kodi.bak

    3. reboot
    4. Add your music

    5. Run the Android addon

    Once you are done testing:

    1. systemctl stop kodi

    2. rm /storage/.kodi

    3. mv /storage/.kodi.bak /storage/.kodi

    4. reboot

    A clean test I will do tomorrow.

    In debug mode and when starting the Android app, I can see that the CPU is going up to the 260 %, and the Memory going down to about 40.000 kb. Than it is freezes and the RP3 is not reacting anymore, not to any input, also not the shown Memory or CPU is changing anymore.

    In the Android app I can see how many songs are indexed. At the same moment no more further songs are indexed. In this case it have been exactly 1.000 songs. But as described it is depends between about 400 and 1.000.

    I opened the journalctl now and it works.

    I recognized that in my last try i didn't activate the JSON-RPC.

    So now i did a new try with new logs. For that I deactivated the screensaver. But after about 700 songs the RP3 freezes again and the shown log / mem / CPU and clock didn't change anymore. Also the remote tool on my Laptop an my Android couldn't connect anymore to the RP3.

    After 105 minutes the RP3 didn't reboot by itself so that i reboot again by my own.

    journalctl

    Kodi.log

    Kodi.old.log

    And now last try, I formatted my SD card, installed a new libreelec via the LibreELEC USB-SD Creator. I updated to Milhouse #0710.

    I changed language and region, activated UPnP / DLNA and deactivated AirPlay and the screensaver.

    As you described I cleaned the Kodi folder via PuTTY. I activated the logs. I imported my external HDD to the music library (within that it also hangs up, why i have to do update my library one time).

    After that i started my Android Teufel App and scanned this music library as new source. After about 2 minutes 300 songs were scanned and the RP3 freezes again. It is shown "MEM 45592 / 767008 KB - FPS 33.7" "CPU: #0: 44% #1: 16% #2 7.7 % #3: 78% (CPU-KODI 68.92%).

    This time i didn't wait 30 minutes for a automatically restart. Should I?

    After manually restartig these are my logfiles (info: everytime restarting the RP3 i delete this source from the Android app, because otherwise it would freeze again very fast after restarting, so that it's not possible to get to the logfiles):

    Journal

    kodi.log

    because kodi.old.log is too big i uploaded it into my dropbox

    Are you using Yatse as well, because some of the JSON requests in your log look like the polling spam typical of Yatse. If you are using Yatse, please disable it while testing with your Tuefel, as they could be interacting with each depending on how badly the apps have been written. If you are not using Yatse then maybe the Tuefel app has the same design inefficiency as Yatse.

    In your kodi.old.log I can see (once I filter out the spam) that an app - presumably the Tuefel, maybe Yatse - is requesting song details in batches of 975 songs. It manages to request 16750 songs, then stops at 09:18:04.581- there are no further JSON requests (other than spam) which suggests the Tuefel is still working. Kodi doesn't appear to have crashed at this point as it is still processing the spam requests.

    Someone (Teufel? Yatse?) starts a music library scan at 09:20:21.511, which runs for several hours, finishing at 14:37:30.579.

    Then, at 16:30:24.536, there is a UPnP request (presumably from the Tuefel?) which seems to be requesting all songs - 49621 in total, in batches of 100. Kodi seems to responsd OK with the first 400 items, but then hangs when being asked to process the 5th batch. My guess is there is a serious memory leak (or scale issue) in Kodi's UPnP implementation, which is a highly experimental feature in Kodi 18.

    Please open a trac ticket on Kodi - TRAC and include the link to kodi.old.log - this will need the Kodi UPnP developer to investigate further.

    I did use Yatse and now removed it from my mobile smartphone. Indeed i used Kore for navigation.

    I did a new try. With shown clock i started importing with Teufel app at 4:25 PM. At 4:26 PM the shown clock and the logging information didn't change anymore. Because of that I thought it freezes again. Looking into my Teufel app it shows that 600 songs have been imported. Looking about 10 minutes later in Teufel app it's shows the resource of Kodi UPnP offline. Because of that i restarted the raspberry after 30 minutes, but didn't removed this resource from the Teufel app. After restarting Teufel was scanning again and raspberry freezes after some seconds at 04:56 pm again. Imported songs remained at 600 in Teufel app. I waited till Teufel shows the raspberry as offline, removed the resource from Teufel app, restarted again and created the following new logfiles:

    journalctl

    Kodi.log

    Kodi.old.log

    Quote from JohnLocke

    I did answer twice on Tuesday. Above you'll find one post from 6:29 pm and another one from 6:43 pm.

    Yes I saw those posts, but there's not much more I can add - the issue is with Kodi, specifically UPnP, and you've now done the best thing which is to open a trac ticket so that the relevant Kodi developer can take a look at it. Hopefully all the information you've provided in this thread (and in trac) will prove useful and result in a resolution eventually (can't say when that will happen, as UPnP is still a fairly experimental feature).