java.io.IOException: Too many open files

JBS_Scotty · October 5, 2017, 2:22pm

I have exactly the same problem and it can be easily reproduced:

I have three charts in a sitemap
I use the basicui
As long as I do not refresch the site in a web browser - the performance is OK
As soon as I refresh the web view, the system goes down (CPU Usage by openhab > 90%) and does not respond any more
After a while I get ‘too many files open’ written to the log file

I have tested this behaiour on a Raspberry 3 and a Raspberry ZeroW

pi@MeteringPiZeroW:/var/lib/openhab2/tmp $ netstat -an | grep CLOSE_WAIT | wc -l
3526
pi@MeteringPiZeroW:/var/lib/openhab2/tmp $ ls -al | wc -l
55
pi@MeteringPiZeroW:/var/lib/openhab2/tmp $

pi@MeteringPi:/var/lib/openhab2/tmp $ netstat -an | grep CLOSE_WAIT | wc -l
1072
pi@MeteringPi:/var/lib/openhab2/tmp $ ls -al | wc -l
46
pi@MeteringPi:/var/lib/openhab2/tmp $

martinvw · October 5, 2017, 2:41pm

Please provide us with some output from the stackoverflow answer

JBS_Scotty · October 5, 2017, 3:01pm

Try this URI:
http://kulturnetz-drensteinfurt.de/Medien/Log4HABDebug.zip
Give me a short feedback that you have downloaded the zipped log file.
It contains the openhab2 log files with the exceptions thrown during infinite processing
Just search for ‘viele’ in the file.

grep "Zu viele" openhab.log

JBS_Scotty · October 5, 2017, 3:03pm

BTW:
On my linux development desktop machine - this problem does not occur

martinvw · October 5, 2017, 3:14pm

I downloaded. Maybe you could also provide the output of

use lsof -p pid to check what cause leak of file references;
use ulimit -n to see the limit of opened file references of a single process;
check any IO resources in your project,are they released in time?,Note that,File,Process,Socket(and Http connections) are all IO resources.

Although in this case the number of connections looks quite extreme, if you could create a Heap dump I might be able to pinpoint it. Please do that at a moment the number CLOSE_WAIT is at least 1000 preferably as high as you have seen it. It makes it easier to find a potential cause. How long does it take to collect this number of open connections?

JBS_Scotty · October 5, 2017, 3:28pm

pi@MeteringPi:/var/log/openhab2 $ sudo lsof -p 20147 | wc -l
2214
pi@MeteringPi:/var/log/openhab2 $ ulimit -n
65536
pi@MeteringPi:/var/log/openhab2 $

And lots of these lines
java 20147 openhab 2092u REG 179,2 43 247729 /var/lib/openhab2/tmp/imageio8931737582513179366.tmp
java 20147 openhab 2093u REG 179,2 43 247730 /var/lib/openhab2/tmp/imageio1396124037759319630.tmp
java 20147 openhab 2094u REG 179,2 43 247728 /var/lib/openhab2/tmp/imageio5819838373834152835.tmp
java 20147 openhab 2095u REG 179,2 43 247731 /var/lib/openhab2/tmp/imageio9089374638969299220.tmp
java 20147 openhab 2096u REG 179,2 43 247732 /var/lib/openhab2/tmp/imageio5140302089757248728.tmp
java 20147 openhab 2097u REG 179,2 43 247733 /var/lib/openhab2/tmp/imageio3900864253772793382.tmp
java 20147 openhab 2098u REG 179,2 43 247734 /var/lib/openhab2/tmp/imageio4205840447396376183.tmp
java 20147 openhab 2099u REG 179,2 43 247735 /var/lib/openhab2/tmp/imageio7159244966723304073.tmp
java 20147 openhab 2100u REG 179,2 43 247736 /var/lib/openhab2/tmp/imageio3823977621293419679.tmp
java 20147 openhab 2101u REG 179,2 43 247737 /var/lib/openhab2/tmp/imageio5104763224528198381.tmp
java 20147 openhab 2102u REG 179,2 43 247738 /var/lib/openhab2/tmp/imageio7943117347099773830.tmp
java 20147 openhab 2103u REG 179,2 28280 247594 /var/lib/openhab2/persistence/rrd4j/Consumption.rrd
java 20147 openhab 2104u REG 179,2 43 247677 /var/lib/openhab2/tmp/imageio2028556992348704553.tmp
java 20147 openhab 2105u REG 179,2 28280 247594 /var/lib/openhab2/persistence/rrd4j/Consumption.rrd
java 20147 openhab 2106u REG 179,2 28280 247594 /var/lib/openhab2/persistence/rrd4j/Consumption.rrd
java 20147 openhab 2107u REG 179,2 43 247740 /var/lib/openhab2/tmp/imageio4218212574218079016.tmp
java 20147 openhab 2108u REG 179,2 43 247739 /var/lib/openhab2/tmp/imageio1779322582842757726.tmp
java 20147 openhab 2109u REG 179,2 43 247741 /var/lib/openhab2/tmp/imageio1211665275807915698.tmp

JBS_Scotty · October 5, 2017, 3:29pm

I have to leave office right now
I’ll be back
Monday

martinvw · October 5, 2017, 3:36pm

I found a smoking gun for your case, your logging shows this:

2017-10-05 16:32:31.123 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:31.328 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:31.430 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:31.470 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:31.611 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:31.690 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.168 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:31.969 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.032 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.315 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.387 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.394 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.578 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.615 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.723 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.692 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.646 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.677 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.895 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.937 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:32.949 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.024 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.040 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.048 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.493 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.503 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.552 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.568 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.896 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.815 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.600 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.599 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.598 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.584 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.583 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:33.570 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.120 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.185 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.192 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.217 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.227 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.238 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.244 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.426 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.619 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.687 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.748 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.810 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.890 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.598 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.588 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.586 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.548 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.533 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.907 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:36.935 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.035 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.307 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.078 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.567 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.564 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.535 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.480 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.348 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.332 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.882 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.935 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.008 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.019 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.040 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.808 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.116 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.138 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.168 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.177 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.671 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.650 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.645 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.644 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:37.643 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.352 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.259 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.243 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.635 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.646 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.663 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.693 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.702 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.713 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.728 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.605 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.743 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.520 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.460 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.435 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.373 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.358 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.867 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.918 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.958 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.964 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:38.998 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.270 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.291 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.254 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.213 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.408 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.451 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.548 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.210 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.141 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.137 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.136 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.114 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.086 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.057 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.040 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.038 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.664 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.678 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.688 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.698 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.718 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.767 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.527 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.488 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.459 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.348 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.293 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:40.187 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:40.268 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:40.299 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:40.309 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:40.138 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.948 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.921 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.919 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.913 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.912 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.882 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
2017-10-05 16:32:39.839 [WARN ] [thome.ui.internal.chart.ChartServlet] - Illegal argument in chart: No Persistence service found.
...

And if you look at: https://github.com/eclipse/smarthome/blob/master/bundles/ui/org.eclipse.smarthome.ui/src/main/java/org/eclipse/smarthome/ui/internal/chart/ChartServlet.java#L278

It looks like a plausible place for those image to be left open

Kai · October 5, 2017, 5:04pm

Can you say in detail where you see a resource being left open? BufferedImage is not a Closable object, so I do not see where a resource leak can originate from that code…

martinvw · October 5, 2017, 5:16pm

Then the train stopped, so I had to stop looking, I’m expecting mildly that it could be somewhere inside the provider. I didn’t mean that I found it, just the combination of “imageio5104763224528198381.tmp” files and these log look like an interesting combination to me, I was about look into the builder used inside the provider but could not find the source quickly, so I will be looking at the decompiled one first

Edit: some typos

martinvw · October 5, 2017, 6:51pm

From https://github.com/eclipse/smarthome/blob/master/bundles/ui/org.eclipse.smarthome.ui/src/main/java/org/eclipse/smarthome/ui/internal/chart/ChartServlet.java#L280 I end up at the following code fragment in javax.imageio:

 public FileCacheImageOutputStream(OutputStream stream, File cacheDir)
     throws IOException {
	if (stream == null) {
		throw new IllegalArgumentException("stream == null!");
	}
	if ((cacheDir != null) && !(cacheDir.isDirectory())) {
		throw new IllegalArgumentException("Not a directory!");
	}
	this.stream = stream;
	if (cacheDir == null)
		this.cacheFile = Files.createTempFile("imageio", ".tmp").toFile();
	else
		this.cacheFile = Files.createTempFile(cacheDir.toPath(), "imageio", ".tmp")
							  .toFile();
	this.cache = new RandomAccessFile(cacheFile, "rw");

	this.closeAction = StreamCloser.createCloseAction(this);
	StreamCloser.addToQueue(closeAction);
}

martinvw · October 5, 2017, 7:20pm

Looking at it, I would say that it could maybe also be a consequence of an almost out-of-memory or other system problems. The code which I copied is part of the JDK so it should be rather unique if it gives problems, although I do not really like the part where the implementation states that it closes the images when the vm closes, so I prepared a PR: https://github.com/eclipse/smarthome/pull/4380

I think this is not the only problem which you are facing so maybe a heap-dump will give more insights.

Please also not limit yourself to a lot of these lines, but give me/us a text file with all of them, because to me they do not look the same

JBS_Scotty · October 9, 2017, 9:19am

I can provide now a clean ‘bug shot’, which can be downloaded here:

http://kulturnetz-drensteinfurt.de/Medien/Log4HABDebug_02.zip

It includes a readme describing how the error has been reproduced.

If you need additional information please give me some instructions what has to be dumped from the raspberry.

martinvw · October 9, 2017, 9:43am

That is interesting so its all about the non closed connections, because the number of graphs being left behind is really limited.

And you are running openHABian with the Zulu jdk?

Can others reproduce this easily?

I would really be interested in a heap dump but can’t find what tools are supported by zulu for that, can you validate whether this works: https://stackoverflow.com/questions/407612/how-to-get-a-thread-and-heap-dump-of-a-java-process-on-windows-thats-not-runnin

martinvw · October 9, 2017, 9:55am

Can you also run:

lsof -P
lsof -n

Whatever gets the real values of the ports instead http-alt I assume its just 8080 but its good to know for sure

JBS_Scotty · October 9, 2017, 10:43am

I’m Running a Zulu for PIZeroW

pi@MeteringPiZeroW:~ $ java -version
openjdk version "1.8.0_121"
OpenJDK Runtime Environment (Zulu Embedded 8.20.0.42-linux-aarch32hf) (build 1.8.0_121-b42)
OpenJDK Client VM (Zulu Embedded 8.20.0.42-linux-aarch32hf) (build 25.121-b42, mixed mode, Evaluation)

and a HotSpot for PI3

pi@MeteringPiRed:~ $ java -version
java version "1.8.0_65"
Java(TM) SE Runtime Environment (build 1.8.0_65-b17)
Java HotSpot(TM) Client VM (build 25.65-b01, mixed mode)

On both PIs the same behaviour. As soon as the Chrome Refresh is pressed the problem occurs.

Here are the Download Links for the PI3 Heaps:

http://kulturnetz-drensteinfurt.de/Medien/heap_01.bin
http://kulturnetz-drensteinfurt.de/Medien/heap_02.bin

JBS_Scotty · October 9, 2017, 10:48am

Here are the requested outputs:

http://kulturnetz-drensteinfurt.de/Medien/lsof_n.txt
http://kulturnetz-drensteinfurt.de/Medien/lsof_p.txt

martinvw · October 9, 2017, 11:01am

I’m having an hard time opening them, they also look really small. Can you validate that the processes uses only 10 MB?

JBS_Scotty · October 9, 2017, 11:06am

I got an exception during generating the heap dump:

Dumping heap to heap_03.bin ...
Exception in thread "main" java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at sun.tools.jmap.JMap.runTool(JMap.java:201)
        at sun.tools.jmap.JMap.main(JMap.java:130)
Caused by: java.lang.InternalError: Metadata does not appear to be polymorphic
        at sun.jvm.hotspot.types.basic.BasicTypeDataBase.findDynamicTypeForAddress(BasicTypeDataBase.java:278)
        at sun.jvm.hotspot.runtime.VirtualBaseConstructor.instantiateWrapperFor(VirtualBaseConstructor.java:102)
        at sun.jvm.hotspot.oops.Metadata.instantiateWrapperFor(Metadata.java:68)
        at sun.jvm.hotspot.memory.DictionaryEntry.klass(DictionaryEntry.java:71)
        at sun.jvm.hotspot.memory.Dictionary.classesDo(Dictionary.java:66)
        at sun.jvm.hotspot.memory.SystemDictionary.classesDo(SystemDictionary.java:190)
        at sun.jvm.hotspot.memory.SystemDictionary.allClassesDo(SystemDictionary.java:183)
        at sun.jvm.hotspot.utilities.HeapHprofBinWriter.writeClasses(HeapHprofBinWriter.java:954)
        at sun.jvm.hotspot.utilities.HeapHprofBinWriter.write(HeapHprofBinWriter.java:427)
        at sun.jvm.hotspot.tools.HeapDumper.run(HeapDumper.java:62)
        at sun.jvm.hotspot.tools.Tool.startInternal(Tool.java:260)
        at sun.jvm.hotspot.tools.Tool.start(Tool.java:223)
        at sun.jvm.hotspot.tools.Tool.execute(Tool.java:118)
        at sun.jvm.hotspot.tools.HeapDumper.main(HeapDumper.java:83)

martinvw · October 9, 2017, 11:08am

First result on Google:

Check the user which runs openhab vs the user you try to create the dump with