LogReader binding

pauli_anttila · December 6, 2017, 4:09pm

Happy independence day to you too

I quickly checked the Tailer based implementation and it seems to be pretty clean

Couple of ideas/remarks:

Filepath could/should be configurable. Many of us, have configured separated log files (e.g. for different bindings). Binding could support both absolute and relative paths. Then also system logs could be monitored (at least if search patterns are also configurable).
There could be custom channel where also search pattern is configurable.
Trigger channel could be cleaner solution or both could be supported.

rule "Error event"
when
    Channel 'logreader:reader:reader1:error' triggered
then
    var message = receivedEvent.getEvent()
    logInfo("error occurred", "Error: {}", message)
end

LogTailerHandler logger has a paste typo (LoggerFactory.getLogger(LogReaderHandler.class))
Precompiled matchers could gain performance (might be that JVM do that anyway). No compile is done every time when line is received.
When TailerListenerAdapter receive Exception (handle exception method), should thing but to offline state?

If you are planned to make PR in someday, you could make PR with WIP tag immidiately, then it’s easier to give review comments directly from GitHub.

gitMiguel · December 6, 2017, 10:17pm

Thanks for the review and ideas.

Yes. Current idea is to have it configurable. Leaving it blank would default it to openhab.logdir. This would guarantee easy setup for beginners.
I’d say more than one.
What’s the advantage if trigger channels are used?
Good catch. I’ll fix this.
Think you are right about performace. I’ll look into this.
Imho this depends on exeception (See my earlier post about when to stop or log as warning).

I’ve been thinking about making a PR. I’m just a bit unsure this being ready enough to do so. Especially TailerListener having that bug as I mentioned earlier.

gitMiguel · December 7, 2017, 10:02am

New version available. Mostly for @sihui . Binding now goes offline only when there’s errors during initialization. In other cases errosr are directed to warn log and reading continues.

ralle · December 7, 2017, 3:17pm

I just tried your binding and it stumbled over the date format in my logs. Here’s the error along with the log line that caused the error:

(Line breaks inserted by me after pasting)

07-Dec-2017 16:11:52.971 [WARN ] [openhab.binding.logreader.handler.LogReaderHandler] - First line could not be read.
 Timestamp mismatch: 02-Dec-2017 08:28:37.185 [INFO ] [.module.script.internal.GenericScriptEngineFactory] - 
Activated scripting support for ECMAScript

gitMiguel · December 7, 2017, 3:25pm

Thanks Ralph for testing.

This binding needs the time to be in yyyy.mm.dd. For example 2017-12-07. Is there lots of people using different time formats?

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.