LogReader binding

New version is now uploaded and as usual you can find it in post#1

I added new thing type LogTailer witch uses org.apache.commons.io.input.Tailer. It is only there for my own testing purposes. While testing I encountered a bug that stops the tailing and start reading log file from beginning. Work in progress to get tailer patched. You can ignore this and use LogReader as usual.

P.S Trying to write a proper readme to github. Have anything that should be covered?

Unfortunately it stops now with:

05-Dez-2017 09:44:11.359 [DEBUG] [org.openhab.binding.logreader                     ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.logreader.internal.LogReaderHandlerFactory, component.id=14, service.id=123, service.bundleid=10, service.scope=bundle} - org.openhab.binding.logreader
05-Dez-2017 09:44:11.398 [DEBUG] [org.openhab.binding.logreader                     ] - BundleEvent STARTING - org.openhab.binding.logreader
05-Dez-2017 09:44:11.403 [DEBUG] [org.openhab.binding.logreader                     ] - BundleEvent STARTED - org.openhab.binding.logreader
05-Dez-2017 09:44:11.444 [DEBUG] [org.openhab.binding.logreader                     ] - BundleEvent [unknown:512] - org.openhab.binding.logreader
05-Dez-2017 09:47:43.347 [DEBUG] [openhab.binding.logreader.handler.LogReaderHandler] - Initializing LogReader
05-Dez-2017 09:47:47.990 [TRACE] [openhab.binding.logreader.handler.LogReaderHandler] - Log lines at first read: 89
05-Dez-2017 09:47:47.993 [TRACE] [openhab.binding.logreader.handler.LogReaderHandler] - First log read took 14 milliseconds
05-Dez-2017 09:47:47.996 [TRACE] [openhab.binding.logreader.handler.LogReaderHandler] - Log rotated: 2017-12-05 09:44:12.875
05-Dez-2017 09:52:52.257 [DEBUG] [openhab.binding.logreader.handler.LogReaderHandler] - Last line: 2017-12-05 09:50:34.881
05-Dez-2017 09:52:52.259 [DEBUG] [openhab.binding.logreader.handler.LogReaderHandler] - Total log lines: 241. New lines since last read: 152
05-Dez-2017 09:52:52.278 [DEBUG] [openhab.binding.logreader.handler.LogReaderHandler] - New warning lines: 21
05-Dez-2017 09:52:52.281 [DEBUG] [openhab.binding.logreader.handler.LogReaderHandler] - New error lines: 0
05-Dez-2017 09:52:52.305 [TRACE] [openhab.binding.logreader.handler.LogReaderHandler] - Parsing through log took 167 milliseconds
05-Dez-2017 09:57:53.371 [DEBUG] [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:202) ~[?:?]
	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) [?:?]
05-Dez-2017 09:57:53.419 [TRACE] [openhab.binding.logreader.handler.LogReaderHandler] - Parsing through log took 83 milliseconds

Looks like you have only included log lines generated by LogReader. Can you paste your whole log between that same time frame?

Nope, did not save them.
Since upgrading to #1112, the binding does not produce trace logs anymore.
Will stop using the binding for now until the openHAB snapshot gets a little bit more stable again.

The last output I can provide for now:
openHAB started at 08:38, binding stopped working at 09:07 (last read), events.log at that time:

2017-12-06 09:07:30.218 [ome.event.ItemCommandEvent] - Item 'Shading_Shutter_LivingWest_Autoshade' received command OFF
2017-12-06 09:07:33.959 [vent.ItemStateChangedEvent] - logreaderLastWarningLine changed from 2017-12-06 08:57:34.102  [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@1b389ce' takes more than 5000ms. to 
2017-12-06 09:07:33.972 [hingStatusInfoChangedEvent] - 'logreader:reader:reader1' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR): 1
2017-12-06 09:07:33.993 [vent.ItemStateChangedEvent] - logreaderLastRead changed from 2017-12-06T09:02:32.932+0100 to 2017-12-06T09:07:33.962+0100

logreader.things:

logreader:reader:reader1 [ refreshRate=300 ]

openhab.log:

2017-12-06 08:42:20.891 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'logreader.things'

although it was set to TRACE.

@gitMiguel, have you published your source codes to GitHub? More eyes will always find bugs fasten.

You have done great work and I’m also very interest in this binding, but there are many of us, which doesn’t install any 3rd party bindings without seeing the source codes (and even build version from the source codes). I’m in no way to blame you for anything, but when you whole house is controlled via openHAB, you just need to be extreamily careful.

4 Likes

@sihui, That’s all right. Hope to get you back testing asap. You provide very valuable information and it’s easy for me to enhance the binding based on that.

Errors are captured and binding immediately set to offline rather than outputting warning lines to log. “Unparseable” lines is one thing to cause this. This could be handled differently but imho the binding is there to capture warnings and not to produce more of them. I think there’s two ways to resolve this. One is to not immediately put binding state to offline and stop reading but to direct these to warnin log and let the binding continue reading in the next loop. The second is to try to cover all different log outputs and handle them correctly. The latter is what I’m after.

@pauli_anttila, thise are some wise words and I agree. I have to admit that I havn’t thought it this way while developing and distributing this. I saw your posting in IoT Matketplace topic and I second all of your comments. I asked similar questions in here: Developing and distributing own bindings. Hoped to get some guidance how to handle these things in future.

And yes, source code can be found at github. github.com/gitMiguel Please have a look there. Help is always appreciated!

PS Happy independence day! Finns rule :smile:

Happy independence day to you too :blush:

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

Couple of ideas/remarks:

  1. 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).
  2. There could be custom channel where also search pattern is configurable.
  3. 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
  1. LogTailerHandler logger has a paste typo (LoggerFactory.getLogger(LogReaderHandler.class))
  2. Precompiled matchers could gain performance (might be that JVM do that anyway). No compile is done every time when line is received.
  3. 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.

Thanks for the review and ideas.

  1. Yes. Current idea is to have it configurable. Leaving it blank would default it to openhab.logdir. This would guarantee easy setup for beginners.

  2. I’d say more than one.

  3. What’s the advantage if trigger channels are used?

  4. Good catch. I’ll fix this.

  5. Think you are right about performace. I’ll look into this.

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

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.

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

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?

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

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?

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

1 Like

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

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.

1 Like

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.

Glad you got it running.

I’ll add few lines about this to readme.

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?