LogReader binding

[gitMiguel (Miika Jukka)]

Hi @ganesh.ingle,

Thanks for the interest and I’m appy to hear more of your thoughts.

This binding is very useful, but we need to be careful on system resources needed for running regular expressions on continuous log stream.

You are absolutely right about resources. I’d like to know how big openhab logs can grow with and without default settings. Ofcourse rotation helps to keep them in reasonable size.

I need to do a re-assessment on performance. I think it should a openhab distro level feature.

I didn’t quite catch you here. You want to reuse your old code somehow? And what do you mean by distro level feature?

[kevin]

This sounds like a great addition to OpenHAB. Can I suggest adding a list of opt out items? To put it another way, report all errors apart from “this list.”
In my case I have a couple of Wemo switches that spit random meaningless errors into the log which I’m not interested in. Trying to turn these off the conventional way stopped them from working at all so I just ignore them. I also get a bucketload of delay errors which again are pointless after every reboot.
Adding a disable channel for when OpenHAB is being worked on is also a good idea.

[gitMiguel (Miika Jukka)]

Hi @kevin,

As you can see I mentioned this earlier when Rich proposed this feature.

Binding is based on regural expressions so an include/exlude list would be quite easy to implement.

So this is in the todo list

About the on/off switch. Should it be directly in the binding or better leaving it for rules to handle when to send notifications?

Thanks for joining the conversation.
/Miika

[kevin]

As I haven’t been able to trial the binding yet, but will next week, excuse anything that doesn’t make sense.
My suggestion is to have a disable binding channel that defaults to off, assuming the binding is dealing with the notifications itself. If a rule handles the onward notifications then the rule can just read a simple ON/OFF item and a disable function isn’t needed.
I’m particularly keen for the disable reporting of certain errors feature in your todo list, I have 2 OpenHAB systems that take between 8 and 10 minutes each to restart and issue several pointless rule delayed by 5000ms errors when they reboot. so I’m keen not to add to this

[gitMiguel (Miika Jukka)]

Binding itself doesn’t send any notifications and I’m quite sure I’ll leave it this way. It just updates a set of channels. After that it’s up to the user to decide what action or notification service to use. Like I’m using Telegram.

[Dries]

Hi @gitMiguel,

Some bindings post some usefull information in the openhab.log as info. Examples:

2017-11-10 00:28:30.889 [INFO ] [ternal.discovery.ConnectSDKDiscovery] - Device removed: {"modelName":"LG Smart TV","lastConnected":1510255439,"lastKnownIPAddress":"192.168.3.20","id":"0548fff0-0576-403f-a0fc-e9f4f218b9f4","services":{},"lastDetection":1510255439,"friendlyName":"TV Living"}

If I could create a rule that is triggered when the INFO_Message (your channel) is changed, and then something like “if contains Device removed”, I could do stuff with that message.

Displaying the INFO_Message on a sitemap would indeed be useless, since that information would change too often.

And yes, this rule would be triggered a lot (but not that often match the conditions in the if-statement).

I’m not sure if it would impact system resources. Users that don’t care about this information, don’t need to bind this channel to an item (or build a rule).

[binderth (Thomas Binder)]

@gitMiguel

lastRead indicates the last time, the binding read, I’d like to have a lastItemTime channel, which tells the date of the last item

Understood. Suppose we have these two channels implemented in the binding. By evaluating these two timestamps in a rule, could it be enough for a “Hey, somethings wrong in logging”-trigger?

yes, this is more than sufficient for a quick check: (if lastItemTime > 12hours)

@gitMiguel

Ok. I’m leaving it as is for now. I’ll write some trace logging to measure read and parsing times to see what would be lowest reasonable refresh rate. Of course this depends on log sizes. Can you put debug logging on to see counted log rows?

Hmm. Debugging on or not, the logrotate is configured to 10MB logsize in Standard. That means roughly 85.000 up to 100.000 lines depending on how much info is present per one line.

@gitMiguel

If you have the last error/warning date I assume the notification will be but on every error, but every hour/day or so. At least I would configure my rule that way to avoid flooding. But yes if the “I’m testing” switch is ready enough, it would be a help!

There’s nothing ready for this switch. Think I’ll drop the idea for now. Leaving it to rules sounds better because then every user has control over what to notify and when.

Experienced users would easily add one item “debug=true/false” and drop notifications on that item’s state, I guess! so you could just leave it as this.

[binderth (Thomas Binder)]

regarding the discussion on INFO items and stuff:
I’m strongly opposed on this one. Why? simply because it would a) kill OH2 on one-chip-Hardware like Raspberry PIs or PINE64s and the like. and b) that’s not the purpose of a logfile at all.

A logfile just brings some kind of overview on the state of an application. If you need for some reason INFO on how a certain piece in your application is acting => get that piece of application do that for you. The only thing a logfile can do more than an application, is if that application isn’t working properly - hence the need for ERROR or some softer WARNING notifications.

So, for the above examples: If the LG Smart TV binding INFOs, that the TV was removed: this should be implemented as a channel in the binding itself - then we can do something in a rule on this action, not via the very costly detour of analyzing a logfile.
Second: If you really want to have items based on a file like a logfile, you need to adress them properly. how would you do that in a cycle of say 60sec? You could have dozens of INFOs while the analyzing waits. If you needed some realtime action - you need cycles of mere msecs -> that yould even bring some bigger Hardware on the brink of failing.

That being said: Please stick to ERRORs and WARNINGs - If there are any, you need to have a closer look into the logfiles/application anyways. For INFOs - goto the binding itself.

[gitMiguel (Miika Jukka)]

You have very good points here and i totally agree. Leaving INFO out helps keeping this not so “resourcehungry”

That being said: Please stick to ERRORs and WARNINGs - If there are any, you need to have a closer look into the logfiles/application anyways. For INFOs - goto the binding itself.

+1 To this. This binding is going handle only errors and warnings.

[Confectrician (Jerome Luckenbach)]

I agree with @binderth in that INFO Topic.

For this usecase a binding can provide trigger channels, which will then get fired when an event (like the disconnect) takes place.

[Dries]

@binderth

this should be implemented as a channel in the binding itself - then we can do something in a rule on this action, not via the very costly detour of analyzing a logfile.

Okay, I got your point. I didn’t think it would impact system resources that much, but I’m probably underestimating this. I withdraw my request.

[binderth (Thomas Binder)]

@Dries

Okay, I got your point. I didn’t think it would impact system resources that much, but I’m probably underestimating this. I withdraw my request.

hehe - yes, just imagine with 80.000+ lines, you’ll propably get as much INFO-items…

[gitMiguel (Miika Jukka)]

As an example here’s my log “stats”. Don’t wonder those huge warning and error line counts because I’m testing the new modbus binding at the same time. Modbus openHAB2 binding available for alpha testing

13:20:01.997 [DEBUG] [ng.logreader.handler.LogReaderHandler] - Log rotated: 2017-11-12 20:09:49.028  
13:20:03.334 [DEBUG] [ng.logreader.handler.LogReaderHandler] - Last line: 2017-11-24 13:20:02.226
13:20:03.335 [DEBUG] [ng.logreader.handler.LogReaderHandler] - Total log lines: 83929. New lines since last read: 83929
13:20:03.336 [DEBUG] [ng.logreader.handler.LogReaderHandler] - New warning lines: 25843
13:20:03.365 [DEBUG] [ng.logreader.handler.LogReaderHandler] - New error lines: 890

[gitMiguel (Miika Jukka)]

I uploaded a slightly updated binding few minutes ago. You can find the download link in post #1. Also check out the fix I made to logreader.rules file

Now the first read, when binding is initialized, is done with LineNumberReader and it only counts the lines and doesn’t parse anything. After this BufferedReader does the reading as usual and channels start to update. There’s also 2 different “timers” added to measure execution times. You can see these result in the log by switching log level to trace in karaf.

log:set TRACE org.openhab.binding.logreader

Have to keep in mind that there might me other factors that affect these times but I think it points the way. I would really much like too see what times you get with RPis version 2 and 3. For comparison, here’s some times I got from my OH2 server (Amd AthlonX2 5000+ / 8gb ram / old hdd):

14:54:38.470 [TRACE] [ng.logreader.handler.LogReaderHandler] - Log lines at first read: 84618
14:54:38.472 [TRACE] [ng.logreader.handler.LogReaderHandler] - First log read took 155 milliseconds
...
14:55:38.610 [DEBUG] [ng.logreader.handler.LogReaderHandler] - Total log lines: 84621. New lines since last read: 3
14:55:38.620 [TRACE] [ng.logreader.handler.LogReaderHandler] - Parsing through log took 146 milliseconds
...
14:56:38.764 [DEBUG] [ng.logreader.handler.LogReaderHandler] - Total log lines: 84627. New lines since last read: 6
14:56:38.774 [TRACE] [ng.logreader.handler.LogReaderHandler] - Parsing through log took 144 milliseconds

Before someone starts to wonder I have to say that I’m quite beginner in java and learning on the way and there might be better and faster methods to achieve this.

Hey @Benjy, can you give me some tips how to use this ${OPENHAB_LOGDIR} in my binding?

[gitMiguel (Miika Jukka)]

I can see that you really have done your homework. And i want to do mine also. I’d like to hear those rough estimates of yours!

I’m running my system in home enviroment but as you said it is not a toy. Of course not as critical as your systems but has to work 24/7 and even when you’re away you have know if something happens.

Really looking forward to this.
/Miika

[Benjy (Ben Clark)]

I’m afraid I don’t know how you’d access it in Java. But I’d guess the first place you could try is the openhab.logdir property.

[gitMiguel (Miika Jukka)]

Thanks anyway. Didn’t even think it could be listed in system properties. I’ll check it. Do you know anyone who could answear this question?

[sihui]

Today I had the time to test again, using Bundle-Version: 2.2.0.201711241250.

Basically it works, I get notifications about warn and error messages.
But the refresh interval does not work: after changing the interval the status gets updated once, then it stops, regardless of what I put in there (I tried 60 seconds, 300 seconds, 5 seconds).

[gitMiguel (Miika Jukka)]

Can you give me TRACE logs?

[sihui]

Sure, but not before Friday evening, I am traveling.