LogReader binding

sihui · December 7, 2017, 4:11pm

Thx a lot, you are amazing.
But it looks like as long as this bug isn’t fixed it will become difficult to test any jar files in the /addons folder:

But I will try …

No. A different time format in the logs is very strange … Although I have my locale set to German, my time format is still 2017-12-07 17:06:04.112

gitMiguel · December 7, 2017, 4:28pm

Yeah, I’ve been reading that same topic and won’t upgrade untill all that is sorted out. Still running #1080.

Ok. Have you @ralle altered your logging settings to output a different time format? This would explain the bahvior. And can you give your platform specs also?

sihui · December 7, 2017, 9:45pm

Binding is running now without any issues since 5 hours (snapshot #1112), also the trace logs are being written.
Three thumbs up

gitMiguel · December 8, 2017, 5:44am

Good to hear! Any warnings in the logs from LogReader?

sihui · December 8, 2017, 7:27am

Nope, just the usual:

2017-12-08 08:25:10.925 [DEBUG] [g.logreader.handler.LogReaderHandler] - Last line: 2017-12-08 08:20:09.849
2017-12-08 08:25:10.929 [DEBUG] [g.logreader.handler.LogReaderHandler] - Total log lines: 2062. New lines since last read: 5
2017-12-08 08:25:10.932 [DEBUG] [g.logreader.handler.LogReaderHandler] - New warning lines: 0
2017-12-08 08:25:10.935 [DEBUG] [g.logreader.handler.LogReaderHandler] - New error lines: 0
2017-12-08 08:25:10.956 [TRACE] [g.logreader.handler.LogReaderHandler] - Parsing through log took 104 milliseconds

Still working fine now since 15 hours.

ralle · December 8, 2017, 10:36am

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.

gitMiguel · December 8, 2017, 10:53am

Glad you got it running.

I’ll add few lines about this to readme.

ralle · December 8, 2017, 12:19pm

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?

gitMiguel · December 8, 2017, 12:36pm

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?

ralle · December 8, 2017, 1:34pm

There’s only this message. Over and over again:

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) [?:?]

This is the version I’m running:

openhab> bundle:list | grep Log                                                                                                                                                    14:33:33
230 │ Active   │  80 │ 2.2.0.201712070953     │ LogReader Binding

gitMiguel · December 8, 2017, 2:30pm

The version is correct that’s for sure.

Do you mean that you have nothing else in your log? I need all lines. Not just the ones produced by LogReader.

AndersBN · December 8, 2017, 3:20pm

Hi Miika

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) [?:?]

gitMiguel · December 8, 2017, 3:38pm

Hello Anders,

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

ralle · December 8, 2017, 4:24pm

I will switch on DEBUG logging tonight and get you the relevant log lines.

pauli_anttila · December 8, 2017, 4:47pm

@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.

gitMiguel · December 8, 2017, 5:58pm

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?

ralle · December 8, 2017, 8:06pm

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

gitMiguel · December 8, 2017, 8:12pm

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?

Thanks for testing!

pauli_anttila · December 8, 2017, 9:15pm

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.

pauli_anttila · December 9, 2017, 9:59am

@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.