Ran fix songs with current config. It ran to about 18,000 songs out of 186,000 songs and then i started seeing these messages in the docker container log:
1234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890
songkong:server unable to recreate default page:/.songkong/Reports/index.html: No file descriptors available
Robert
From Paul Taylor:
Thanks Robert, okay looks like something is using file descriptors and not releasing them
Not sure but may be related to artwork can you disabling Update artwork on the Basic tab please
–
Thank you so much for your help. I wanted to follow up and let you know that yes i did try your suggestion to uncheck the update artwork checkbox in the basic tab. I then re clicked on the fix songs button. Currently the fix songs routine has scanned
Songs loaded 30059 /186768
I currently see the following in the logs:
/opt/songkong/songkongremote8.sh: umask: line 1: illegal mode: 000
debuglogfile is:/songkong/Logs/songkong_debug%u-%g.log
userlogfile is:/songkong/Logs/songkong_user%u-%g.log
songkong:remote dbinit
songkong:remote started
Start Fixing Songs
No other error messages so far.
I will keep you posted on the fix songs progress.
Robert
Paul,
I wanted to follow up with you and let you know that i let the qnap sonkong docker container run for about a day and a half. After it ran about a day and a half, it produced the following message in the docker container log:
songkong:server unable to recreate default page:/.songkong/Reports/index.html: No file descriptors available. I am still searching for a resolution for this issue.
Robert
Note: Songkong docker container create code is as follows:
sudo docker create --name songkong
–restart=always
–net=lsio
-e PUID=0
-e PGID=0
-e TZ=“America/New_York”
-p 4567:4567
-v “/share/appdata/songkong”:/config
-v “/share/music/Music”:/music
-v “/share/music/library”:/library
songkong/songkong
Robert
The default ulimit (open files limit) on docker containers is quite low, you can increase by passing the ulimit parameter
I.e.
–ulimit nofile=20000:20000
Longer term I dont think SongKong should need these extra open files, so there is still a bug to fix here.
Paul,
I increased the soft and hardlimits to the following in the docker create code:
sudo docker create --name songkong
–privileged
–ulimit nofile=262144:262144
–restart=always
–net=lsio
-e PUID=0
-e PGID=0
-e TZ=“America/New_York”
-p 4567:4567
-v “/share/appdata/songkong”:/config
-v “/share/music/Music”:/music
-v “/share/music/library”:/library
songkong/songkong
After making that change and re-creating and re-running my docker containers, I no longer get that issue. I found the following articles very helpful:
Note: The article above mentioned that it might be good to run the container in privileged mode and referenced this article. I was not sure whether i should put the – privilege flag in the create code or not. I figured it could not hurt. After making the above changes and re-running a fix songs, I am happy to report that the fix song successfully completed. Can you let me know if the – privilege flag is needed?
Robert
I dont think it is needed, I think using privilege mode was an alternative to using ulimit as a parameter to docker.
I may have solved the issue of why more file descriptors are required
From https://jthink.atlassian.net/projects/SONGKONG/issues/SONGKONG-1950
Report sections are created in a way where we open filewriter in order to create top level album page, but then go off and create the sub pages before we actually write the top level page. So with this logic applied throughout we are opening filewriters too early, if we wait until children are created that may resolve the issue.
Fixed for next release.
Paul,
I stopped my songkong docker container, I deleted the docker container, i then download version 6.8 pro of Songkong and ran the following docker create code to create a new songkong docker container.
sudo docker create --name songkong
–ulimit nofile=262144:262144
–restart=always
–net=lsio
-e PUID=0
-e PGID=0
-e TZ=“America/New_York”
-p 4567:4567
-v “/share/appdata/songkong”:/songkong
-v “/share/music/Music”:/music
-v “/share/music/library”:/library
songkong/songkong
Songkong came up and i selected my music library folder and then selected the fix songs option on the menu. I proceeded through the submenus to select my preferences and then clicked start to start fixing music songs in my library:
Songkong scanned through and fixed around 85422 songs out of 302469 songs. I noticed after a while that the progress bar was not progressing.
so i viewed the songkong docker container log and saw the following messages:
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
songkong:server unable to recreate default page:/root/index.html: No file descriptors available
I ssh’d via putty into my server and did the following commands to see if i could see how many file descriptors were in use:
[admin@RSMediaServer ~]# ps aux | grep songkong
13719 admin S /sbin/tini /bin/sh -c /opt/songkong/songkongremote8.sh
13832 admin S ash /opt/songkong/songkongremote8.sh
13889 admin 13916340 S java -XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap -XX:MaxRAMFraction=2 -Dcom.mchange.v2.log.MLog=com.mchange.v2.log.jdk14logging.Jdk14MLog -Dorg.jboss.logging.provider=jdk -Djava.util.logging.config.class=com.jthink.songkong.logging.StandardLogging -jar lib/songkong-6.8.jar -r
25060 admin 964 S grep songkong
[admin@RSMediaServer ~]# lsof -p 13889 > songkong2.txt
The output of the songkong2.txt file indicated the following:
java 13889 admin *560r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *561r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *562r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *563r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *564r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *565r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *566r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *567r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *568w REG 253,0 1331633 1768426328 /songkong/Logs/songkong_debug0-0.log
java 13889 admin *569r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *570r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *571r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *572r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *573r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *574r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *575r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *576r REG 0,232 0 2618209526 /proc/1/cgroup
java 13889 admin *577r REG 0,232 0 2618209526 /proc/1/cgroup
I saw a ton of these lines
java 13889 admin *577r REG 0,232 0 2618209526 /proc/1/cgroup
with different *r numbers (4th column). The line that i noticed that was using a ton of file descriptors seemed to be the debug log. Can you determine why that log file is not releasing file descriptors?
Robert
PS: What steps do you recommend i take now to resolve this fix songs issue so that Songkong will scan my complete music collection?
Confused because this error would seem to only happen after creating a new report, and you are failing before get to this point. I’m running lsof on a standard linux machine and so far the bulk of open files are just links to cache files but the number of these are not increasing, it is consistent at about 350 file descriptors in use.
e.g (on Melco N100)
lr-x------ 1 root root 64 Jan 30 09:52 371 -> /mnt/app/share/log/SongKong/Database/EhCache/file/ArtistArtworkCache_64e9f1ef1e593fb741fdc9e97d5aa2a7cffe44cf/offheap-disk-store/ehcache-disk-store.data
And I can see only one file descriptor for songkong_debug0-0.log. Actually since songkong_debug0-0.log is one file I can’t see how you could have more than file descriptor open on it, are you sure there are multiple file descriptors for this file at the same time since it is not clear from your output.
In the meantime I will set up a test on an actual nas docker instance.
Oh I see now that I have reviewed the logs, once it started getting file descriptor errors it carried on, and then eventually gave up and tried to create report but then that failed with:
29/01/2020 11.46.40:EST:AbstractReport:createSectionFile:SEVERE: No file descriptors available
java.io.IOException: No file descriptors available
at java.io.UnixFileSystem.createFileExclusively(Native Method)
at java.io.File.createNewFile(File.java:1012)
at com.jthink.songkong.reports.AbstractReport.createSectionFile(AbstractReport.java:132)
at com.jthink.songkong.reports.AbstractReport.setupHeaderAndPages(AbstractReport.java:340)
at com.jthink.songkong.reports.FixSongsReport.setupHeaderAndPages(FixSongsReport.java:167)
at com.jthink.songkong.reports.FixSongsReport.configureReport(FixSongsReport.java:155)
at com.jthink.songkong.reports.FixSongsReportCreator.createBodyOfReport(FixSongsReportCreator.java:37)
at com.jthink.songkong.analyse.toplevelanalyzer.FixSongsController.start(FixSongsController.java:304)
at com.jthink.songkong.server.callback.ServerFixSongs$Task.run(ServerFixSongs.java:731)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
29/01/2020 11.46.40:EST:AbstractReport:outputErrors:WARNING: Report 2:start
29/01/2020 11.46.40:EST:AbstractReport:outputErrors:WARNING: Report 2:end
29/01/2020 11.46.40:EST:ServerFixSongs$Task:run:SEVERE: null
java.lang.NullPointerException
at java.io.FileOutputStream.<init>(FileOutputStream.java:203)
at com.jthink.songkong.reports.AbstractReport.getUTF8Writer(AbstractReport.java:185)
at com.jthink.songkong.reports.AbstractReport.outputErrors(AbstractReport.java:258)
at com.jthink.songkong.reports.FixSongsReportCreator.createBodyOfReport(FixSongsReportCreator.java:116)
at com.jthink.songkong.analyse.toplevelanalyzer.FixSongsController.start(FixSongsController.java:304)
at com.jthink.songkong.server.callback.ServerFixSongs$Task.run(ServerFixSongs.java:731)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
then the only thing that was running was the web progress monitor and that kept failing every time to update progress
29/01/2020 11.46.40:EST:CmdRemote:lambda$start$114:SEVERE: >>>>>/fixsongs.update_progress
But I still dont know what is using up the file descriptors in the first place.
Can you please email or upload this files so I can see what is listed, but also so I can see how many files are open so we know if using new limit or still limited by default 1024 docker limit
I have built a new docker image for SongKong 6.8 it will not fix the file descriptor problem, but it should now gracefully close down as soon as file descriptor limit is hit, and free up some (valid) file descriptors (used for caching) to allow a report to be generated.
Since I have so far been unable to replicate your issue would be grateful if you could give it a try.
Have a problem with my Qnap nas at the moment so I tried on Synology NAS, fixed a number of files without issue. But whilst running Fix Songs I sshed into the machine and monitored the number of fds open
It does continually increase but the majority are /proc/1/cgroup which doesnt seem to be anything to do with real files or sockets, only a docker thing.
Quickly get over the default ulimit if I include the cgroup lines (1024 but havent been able to confirm this is the limit set), but it finishes to completion without problem.
But if I strip out cgroup then the number of rows is about 400 which matches the number of files open when i ran on linux without docker.
You can use grep -v cgroup to strip out lines including cgroup
e.g
docker container exec ebe14e65cc86 lsof -p 8|grep -v cgroup|wc -l
So my qnap nas runs on arm32 so I have to use a different image, I started one from command line just using this minimal config and it worked ok
and my monitoring gave the same results, about 400 file descriptors open once /proc/1/cgroup was taken out.
Also the process id was 6, and on the qnap the process id was 9 so why is the process id of yours 13889 looking more like a regular linux process id ?
Are you running some sort of non-standard docker on the qnap, do you get same problem if you just create your docker instance from the ContainerStation wizard rather than from the command line ?
