Opening the music app fills the log indefinitely

[Tidschimon]

Hey there. I just re set-up my nextcloud on Version 19.0.4.2.
I did a occ files:scan --all to re-index all the files, afterwards I installed the music app and did a occ music:scan --all.
In the log messages there I could see all the folders being added, while it was adding I noticed that the app is importing everything, starting at '/', so I changed the root path afterwards to '/Music'.
Using the subsonic API with Dsub works perfectly, however, every time I open the music app in the web browser, I can only see a spinning circle and when I take a look into the log I notice its size is increasing extremely rapidly (~90MB/s) and appears to be growing until I restart the docker containers.
The log gets crowded with either a lot or very long messages. The error I could make out from it is something like

{
...
"method":"POST",
"url":"/apps/music/api/prepare_collection",
"message":{
  "Exception":"Error",
  "Message":"Undefined offset: 1 at /var/www/html/custom_apps/music/businesslayer/albumbusinesslayer.php#173",
  "Code":0,
  "Trace":[
    {
      "file":"/var/www/html/custom_apps/music/businesslayer/albumbusinesslayer.php",
      "line":173,
      "function":"onError",
      "class":"OC\\Log\\ErrorHandler",
      "type":"::",
      "args":[8,"Undefined offset: 1","/var/www/html/custom_apps/music/businesslayer/albumbusinesslayer.php",173
...

I've tried to re scan the library so far but no luck there. Looking at the source code it seems the php script cannot find the artist. Since some of the music files are quite old or even self-recorded there quite often is no "artist" that can be found online but I don't think that should be a problem. Did I find a bug there, or could it be a problem with my music collection only?

[paulijar]

Thanks for the report. This definitely seems like a bug, although not one which I would have seen or heard of before. Albums with no artist set should not cause any problems, but maybe there is something unusual in your server setup 🤔. But whatever the cause, the log file should not be spammed that rapidly.

[Tidschimon]

Just for the record: This setup has been working before with almost the same docker-compose file as attached. My setup is:
Hardware:

• Raspberry Pi 4
• Mirco SD card
• USB 3 externally powered hard drive
  File systems:
• EXT 4 (Micro SD Card)
• BTRFS (external hard drive)
  OS:
• Raspbian (latest and updated)
  Software stack:
• Docker
• Docker-compose compose.yml (saved as txt so I can upload it)

Next to the compose file I have an .env file with all the variables declared, among them one that mounts part of my external hard drive into the nextcloud container.
The only thing I changed since the setup was entirely working is that I added a password for the redis cache. That was also the reason why an update of the nextcloud image failed (which is not very nice).
For re setting up at first I "only" removed the nextclouddata and nextclouddb volumes, started the compose to let nextcloud initialize without my hard drive volumes mounted in. After that was done I restarted the compose with everything mounted and let nextcloud scan the files. This approach, however, didn't work for me, because I fiddled around with the appdata directory and so the music app didn't scan anything. So I did a second approach that I currently am still running and that I have the described issue with:

1. I moved the folder containing my nextcloud data outside of the directory mounted into the nextcloudcontainer
2. I deleted everything else that was left in said mounted folder (including the appdata directory and everything)
3. I removed the nextclouddata and nextclouddb volumes
4. I re-started the compose to let nextcloud initialize
5. I re-created an account for my user
6. Installed the music app
7. Logged in as the newly created user
8. Moved my previously moved files back into the mounted folder hence overwriting what nextcloud created there by default
9. Ran a files:scan on the user (which indexed all the files again)
10. Ran a music:scan for the user (which added everything there was)
11. Noticed that the music app was starting at '/' instead of '/Music'
12. Opened the settings via the browser and changed the path
13. Noticed the nextcloud.log file growing rapidly
14. Re-started the compose to see whether the growth stopped
15. Opened the music app in the browser again to see whether it starts growing again
    -> It did
    I hope these detailed steps help to maybe spot where I went in a wrong direction.
    From my point of view I don't think there is something wrong with how the stack is set up but maybe rather in the steps I took to get re-set-up

[paulijar]

Okay, thanks for the info. I'm busy this week with other things, but I try to spare a thought for this issue next week (or later).

[The1AndMany]

I ran into this problem as well, and I was able to do a bit of triage. I can't tell whether this is the same issue, but it's causing the same result of massive writes to nextcloud.log, in my case ~79MB/sec. Here are my findings:

• Everything was working fine from a fresh install, and the collection was loaded properly this morning. Things only started falling apart once I tried to refresh after creating a few playlists and using the Files app to move a non-music folder that ended up in my collection.
• It seems that the app is erroring out when trying to parse and display the collection. Part of the error message sent to nextcloud.log includes my entire JSON collection, rather than a filename to where that collection is stored on disk. This, along with the fact that it's throwing an error roughly 100 times/second, is the cause for the ridiculous logging.
• I confirmed the data increase rate by taking the last 500 lines of nextcloud.log using tail -500 and calculating the number of lines stamped with the same timecode, which goes down to the second. This came out to 100, so I used tail -100 to get a rough estimate of the size increase per second, which came out to ~79 MB, according to ls -sh.
• Even navigating away from the Music app, the errors keep coming. I was able to kill apache2, and my log stopped growing at 373 GB.
• My nextcloud data partition is roughly 2TB, sitting on a 4TB HDD. If I didn't know what was happening, I would have had 83 minutes to realize it and kill apache2 before the log file would have taken up all 4TB, or about 41 minutes for just the same partition. This is assuming no other data on the drive/partition. Given this, I would argue it'd be worth prioritizing this bug.

Below is a screenshot of my logging page in my Settings, loaded before I killed the server. I also included the results of ls -sh in the Nextcloud data directory, and a sample output from nextcloud.log. Please note that the sample output contains data of
my entire music collection. Hopefully someone who knows more than me can make good use of them!

sample_output.txt

[Pehu-ham]

I have noticed that if you delete one or more music files, the nextcloud.log keeps growing. Even after deleting the nextcloud (it's just for testing for me) and the database, the log file still grows.

[paulijar]

Okay, thanks all for the extra input. If anyone with this problem has more time than I do, you could try to comment out that error-emitting line music/businesslayer/albumbusinesslayer.php:173. This line is not actually necessary for anything that the web UI does; it is relevant only for the Shiva API which hasn't been used by the web UI for long time.

The call itself shouldn't be the root cause for the error, but it would be interesting to see, what happens when that line is removed. Maybe the logic breaks then somewhere else, and that could give us some new information. The very next line 174 may potentially be the next one with similar problem. If that happens, you could try to substitute that with $album->setNumberOfDisks(1);.

[Pehu-ham]

Unfortunately I cannot help you. I am a user only and have the Nextcloud on a shared provider. I only noticed it because my provider told me that he had to deactivate my account (memory overflow). Also I can't test it because I don't have access to the server.
best regards Peter

[paulijar]

Looking at the code closer, it seems that those code lines albumbusinesslayer.php:173 and :174 could refer to an invalid array index in case the DB contains an album row but the corresponding track rows are missing. This shouldn't normally happen, but maybe in some unexpected scenario it might be possible. However, I couldn't see anything getting logged when I artificially created such situation by modifying the DB directly. I don't know why was this, but maybe it could depend on some configuration of the cloud or PHP.

Also, I don't quite understand, why would the code refer to the same undefined offset over and over again. Each album ID should be used as the array index only once, but at least @The1AndMany´s screenshot shows that the same invalid offset 14700 has triggered the error many times during the same second.

Anyway, I now pushed an experimental fix to the master brach. If anyone with the problem would be able to download the file https://raw.githubusercontent.com/owncloud/music/master/businesslayer/albumbusinesslayer.php and substitute the corresponding file in the Music app release, I would be greatly interested to hear about the results.

[The1AndMany]

Looks like it's working now.

I renamed the old file to albumbusinesslayer.php.old and used wget to grab the new one, then used occ to re-enable the app. Loaded it in a browser and kept a close eye on the size of nextcloud.log. It was still growing, but not nearly as fast. After further inspection, it looks like it was caused by a misconfigured Joplin sync, and once I configured that to use a freshly-generated app password it stopped being an issue. No log messages from the music app, so I think it's safe to say this issue is solved, at least for me. Tested playlists, shuffle play, and general playback; no issues.

Thanks for the patch! Glad I could be of help.

[Tidschimon]

Also fixes it for me.
I also downloaded the file via wget and mounted it in inside my docker-compose.
I then opened the music app in the browser I don't get any growth on the log file and, what is even more, I do get the albums displayed in the browser. Before it was stuck in the loading animation.
Also no issues with playing the music.
This issue can also be closed from my side. Thanks a lot! 👍

[Pehu-ham]

Nice to read. But of course I hope that this will be changed by an update or new version for us users.

Peter

[Pehu-ham]

I have done it too. Thanks for that. So far there is no error message.

[paulijar]

The Music app v0.17.2 is now out, including the fix posted above a week ago.