Yes I have tweaked my logging config according to @Dimās post here. I have changed the time and date formatting now from dd-MMM-yyyy to yyyy-MM-dd and now it doesnāt complain anymore.
The binding runs now and updates its items, but every update interval it logs the following warning:
2017-12-08 13:14:42.627 [WARN ] [openhab.binding.logreader.handler.LogReaderHandler] - Exception occurred while parsing log: 1
java.lang.ArrayIndexOutOfBoundsException: 1
at org.openhab.binding.logreader.handler.LogReaderHandler.readLog(LogReaderHandler.java:211) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
Do you need a trace to find the root of the problem?
Trace logs are not needed but if you could provide whole log contents from past 10min (if you have default refreshRate of 60 seconds then past 5minutes is enough) so I can see the line what the binding tries to parse.
And what does bundle:list command in karaf console say? What is the version number of this binding?
2017-12-08 14:26:45.203 [WARN ] [openhab.binding.logreader.handler.LogReaderHandler] - Exception occurred while parsing log: 1
java.lang.ArrayIndexOutOfBoundsException: 1
at org.openhab.binding.logreader.handler.LogReaderHandler.readLog(LogReaderHandler.java:211) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2017-12-08 14:28:45.249 [WARN ] [openhab.binding.logreader.handler.LogReaderHandler] - Exception occurred while parsing log: 1
java.lang.ArrayIndexOutOfBoundsException: 1
at org.openhab.binding.logreader.handler.LogReaderHandler.readLog(LogReaderHandler.java:211) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2017-12-08 14:29:45.269 [WARN ] [openhab.binding.logreader.handler.LogReaderHandler] - Exception occurred while parsing log: 1
java.lang.ArrayIndexOutOfBoundsException: 1
at org.openhab.binding.logreader.handler.LogReaderHandler.readLog(LogReaderHandler.java:211) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2017-12-08 14:31:45.309 [WARN ] [openhab.binding.logreader.handler.LogReaderHandler] - Exception occurred while parsing log: 1
java.lang.ArrayIndexOutOfBoundsException: 1
at org.openhab.binding.logreader.handler.LogReaderHandler.readLog(LogReaderHandler.java:211) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
I have a similar issue in my log. Error occurs every ten minutes (refresh 300)
2017-12-08 16:09:02.212 [WARN ] [g.logreader.handler.LogReaderHandler] - Exception occurred while parsing log: 1
java.lang.ArrayIndexOutOfBoundsException: 1
at org.openhab.binding.logreader.handler.LogReaderHandler.readLog(LogReaderHandler.java:211) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
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) [?:?]
I have the same request to you as to Ralph. As you said it happens every 10 minutes then post your log contents from lets say 15 minutes. And remember to put logging level to DEBUG.
log:set DEBUG org.openhab.binding.logreader
Edit
@ralle You asked about TRACE logging and I said that I donāt need it. I somehow had the impression that you allready had DEBUG on. So please, debug log is what i need.
If thereās too much lines to post you can of course upload the for example pastebin.com
@gitMiguel, by quick analyse, brLastLine is empty when there is no new log items recognized since last scan, which then cause ArrayIndexOutOfBoundsException in line 211.
Again @pauli_anttila you are correct. This is something that I clearly didnāt think of. Always had in mind that at least some event would increase the line count. Strikes odd that in 5 minutes theres no new lines?
I switched on debugging and the warning didnāt appear since then. Maybe the reason is that the debugging itself created log entries that cause the bug NOT to trigger just as @pauli_anttila suggested?!
I tested again by switching off debug logging and instantly the warning returned
So this bug is now confirmed and Iāll fix it asap. Meanwhile you can increase the refresh rate even up to 10 minutes so the bug wont disturb you. Just out of curiosity how many bindings do you use since theres not much traffic in your log?
Thatās not odd at all. My āproductionā system, even itās pretty busy system (around 1000 items), I got only couple of lines per day (most of them are some INFO items from my rules).
Item state change events are not published to logs but only to console.
@gitMiguel This morning, I made some refactoring for Tailer based implementation. I included also fixed Tailer implementation which seems to work fine now. I completed Tailer based reader and implemented some new features like trigger channels, configurable search patterns and blacklisting features. If you want to take a look, codes can be found from my repo https://github.com/paulianttila/openhab2-addons/tree/logreader/addons/binding/org.openhab.binding.logreader.
If you want to make cooperation and can make PR to you repo.
I have one question though. If one is using default logging settings (like me at the time) all state updates are displayed also in the log. Tailer finds a warning and updates a string channel with warning line contents. On next read [WARN ] is found as a āfalse positiveā in that log line. Did you handle this or am I just blind?
In reader I have this covered with line.replace("[WARN ]", " "). And thereās a todo marking if someone finds a proper way to match only from specific part of the string.
State changes are direct to events.log by default. At least in OH 2.2 and canāt remember how this has been in older version. Additionally state changes should logged in INFO level not WARN level. Blacklisting feature could also be used to bypass unwanted lines.
Iāve been following your repo and can see that you made it much more better than I ever could. Iām quite sure that you should take the tailer part to your self and make a PR straight to OH. That would be a proper binding that really well covers all. And with those custom patterns you should be able to read any log you want.
Or what do you think @pauli_anttila? Also Iād like to hear what others has to say. Iām ready for proposals.
