LogReader binding

** Update2 **

Check post #144. This binding is now part of newest SNAPSHOT builds.

** Update **

Author and developer of this binding has changed. @pauli_anttila took the lead. Please check post #110 for updated info and new download links.

** Old post **

Hi all,

I’ve been developing a small binding for OH2 to automatically read openhab.log. Originally the idea came from this topic: Skript to read openhab logs. I don’t want to sit on my desktop all the time and watch logs so I created this binding to do it for me. If errors are found, Telegram action is used to notify me on my mobile phone (Example .rules file later in this post).

Now, few details about the binding. It reads through the log file and updates 7 different channels:

1. DateTime logRotated - Last time your log rotated.
2. DateTime lastRead - Last time when log was read by this binding
3. DateTime lastLine - Last log lines time stamp
4. Number warningLines - How many [WARN ] lines was found since last read
5. Number errorLines - How many [ERROR ] lines was found since last read
6. String lastWarningLine - Contents of last warning line
7. String lastErrorLine - Contents of last error line

It has one configuration options

1. Resfresh rate - How often to read. Defaults to 60. (At the time this is in seconds but I think would be better in minutes. What do you think?)

Binding picks log files path using system properties ${OPENHAB_LOGDIR}/openhab.log so it depends on default logging settings.

Attention! I’ve only tested on my OH2 server running version 2.2.0-SNAPSHOT (#1080) and installed through apt-get. If you are testing on some other platform and find it working or failing, please let me know.

You can configure everything through PaperUI. But I’ll provide my .items file if somebody likes to define items manually like I do :wink: .

Example logreader.items

DateTime logreaderLogRotated "Last Log Rotation [%1$tY.%1$tm.%1$te %1$tR]"  <time>  { channel="logreader:reader:reader1:logRotated" } 
DateTime logreaderLastRead   "Last Read [%1$tY.%1$tm.%1$te %1$tR]"          <time>  { channel="logreader:reader:reader1:lastRead" }
DateTime logreaderLastLine   "Last Line [%1$tY.%1$tm.%1$te %1$tR]"          <time>  { channel="logreader:reader:reader1:lastLine" }
Number   logreaderWarnings   "Warning lines [%d]"                           <alarm> { channel="logreader:reader:reader1:warningLines" }
Number   logreaderErrors     "Error lines [%d]"                             <alarm> { channel="logreader:reader:reader1:errorLines" }
String   logreaderLastWarningLine  "LastWarningLine [%s]"                           { channel="logreader:reader:reader1:lastWarningLine" }
String   logreaderLastErrorLine  "LastErrorLine [%s]"                               { channel="logreader:reader:reader1:lastErrorLine" }

Example logreader.rules

rule "LogReader"
	when
    	Item logreaderLastRead changed
	then
    	if (logreaderErrors.state > 0) {
			sendTelegram("YourBot", "LogReader alarm!\n\n" + logreaderErrors.state.toString + " Errors in log! Heres the last one:\n\n" + logreaderLastErrorLine.state.toString)
		}
  	end

Example logreader.things

logreader:reader:reader1[ refreshRate=60 ]

If you find this somehow useful and would like to test, download here and drop in your addons folder. Feedback and improvement ideas are always welcome!

/Miika

Edit #1

Fixed example rule to use logreaderLastRead as trigger instead of logreaderErrors. Now it triggers after every read and then checks if there are errors. With logreaderErrors there was a possibility to have same amount of errors between multiple reads --> channel would not update and the state stays the same --> rule doesn’t trigger.

Edit #2

New channels and configuration. Added more informative message to logreader.rules using new channel lastErrorLine.

9 Likes

It could be useful to have a channel with the contents of the last warning line and error line. It probably wouldn’t be too useful to put that on the sitemap but it might be useful to include in your Telegram message or to write a filter to not send the Telegram if it is a warning or error that you know you can ignore.

Just an idea. I’m unlikely to be someone who would use this binding but I’m glad you posted it. I hope others will find it useful and test it for you.

Thanks for the input @rlkoshak.

That is a good idea and I’ve been thinking it also. I’m not sure what part of the error line should be included. Particularly if somehow your log start to fill with errors. Do you know if a String item has a lenght limitation?

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

Did test on a snapshot manual install #1084.
After changing
if (logreaderErrors > 0) {
to
if (logreaderErrors.state > 0) {

it works like a charme. Thx!

1 Like

Glad to hear it’s working!

You are right about the rule example. Should have tested before posting :blush: I’ll correct my original post.

Any ideas or improvements pop to your mind?

Just realized that the refresh does not seem to work:

On first start it worked, though.
Don’t have time for further testing at the moment, will try to perform more tests the next days.
Could also be caused by the little buggy snapshots (since #1083)

Upps, why does it show “December”???

pi@raspberrypi3:~ $ date
Di 21. Nov 19:21:41 CET 2017

I have no problems with refresh. checked HABDroid, PaperUI and BasicUI.

I’ll do some digging about that month being wrong.

Edit Found the bug. In Java Calendar months start with 0 not 1. Forgot to make the -1. I’ll upload updated binding in a minute.

1 Like

Somewhere around 2G I think. You don’t have to worry about size.

1 Like

Does this default to /var/log/openhab2/openhab.log or to ${OPENHAB_LOGDIR}/openhab.log? The former is platform specific.

Defaults to /var/log/openhab2/openhab.log.

You have a good point here. I probably should use those environment variables?

I just gave it a try

openHABian 1.3
openHAB 2.1.0-1 (Release Build)

It seems to load, but it doesn’t refresh the items. I’m new to adding bindings manually so, that’s what I did:

  1. dropped the .jar into /srv/openhab2-addons/org.openhab.binding.logreader-2.2.0-SNAPSHOT.jar
  2. looked into the console bundle:list
    235 | Active | 80 | 2.2.0.201711211838 | LogReader Binding
  3. added the above logreader.items for a start

all I can see in the logs is this:

2017-11-23 07:40:07.884 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'logreader.items'
2017-11-23 07:40:07.930 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'logreader.items'
2017-11-23 07:40:07.985 [ItemChannelLinkAddedEvent ] - Link 'logreaderLogRotated-logreader:reader:reader1:logrotated' has been added.
2017-11-23 07:40:07.988 [ItemChannelLinkAddedEvent ] - Link 'logreaderLastRead-logreader:reader:reader1:lastread' has been added.
2017-11-23 07:40:07.991 [ItemChannelLinkAddedEvent ] - Link 'logreaderWarnings-logreader:reader:reader1:warninglines' has been added.
2017-11-23 07:40:07.994 [ItemChannelLinkAddedEvent ] - Link 'logreaderErrors-logreader:reader:reader1:errorlines' has been added.

and then → nothing happens.
In PaperUI the binding doesn’t show either:

Am I missing something?

Is that screenshot from PaperUI -> Addons? That is wrong place.

As you said you dropped the .jar into your addons folder and it shows in karaf. Thats good. Now go to PaperUI -> Configuration -> Things and click on the “+” button in upper section of the web page. Binding should be listed there.

all right, binding isn’t listed in the Addons > Bindings section, but as you pointed out in the Configuration > Bindings
So I Need to configure Things… As I like to have them in text configuration, I tried:
logreader.things

logreader:reader:reader1[ refreshrate="60" ]

now I get:

2017-11-23 08:18:53.656 [ItemStateChangedEvent     ] - logreaderLogRotated changed from NULL to 2017-09-22T13:12:32.000+0200
2017-11-23 08:18:53.665 [ItemStateChangedEvent     ] - logreaderLastRead changed from NULL to 2017-11-23T08:18:09.000+0100
2017-11-23 08:18:53.670 [ItemStateChangedEvent     ] - logreaderWarnings changed from NULL to 3
2017-11-23 08:18:53.673 [ItemStateChangedEvent     ] - logreaderErrors changed from NULL to 0

thanks!

1 Like

What I’d like to see in a binding like this:

  1. as noted above, the content of the last error / warning, which can then be sent to the notification
  2. the date of the last error / warning, so you can have rules on that
  3. a channel, if the logfile wasn’t changed for <<periodoftime>>, so you can have a rule saying: “Hey, your logfile isn’t filling since a day - have a look if somethings broken” (I do realize, if OH is down, the logreader will be down, too. But i had two instances of OH running and still no logfiles being written).
  4. as I’m used to configuring all kinds of periods in msec, I’m fine with refreshrates in msecs, minutes would be too broad I think

Thanks for the input Thomas.

This is absolutely in todo list. Would it be better to have separate channels for both types?

Same question here. Separate channels?

This sounds good. Just to keep it simple should this channel replace lastRead? As it is now, the lastRead channel maybe serves only as a debugger to show that the binging is running.

The refresh rate is in seconds, not in milliseconds.

One another thing came to my mind. Should the binding have enabled/disabled switch? I’m thinking of an situation where one is doing stuff with openHAB and at the same time karaf console is tailing logs. At that time you dont want your phone beebing log errors or warnings.

I’ll answer compacted… :grin:

  • Yes, as separate channels for warning and error
  • lastRead indicates the last time, the binding read, I’d like to have a lastItemTime channel, which tells the date of the last item
  • I know at present the period is in seconds. In my mind every binding uses msec for periods, so I suggested changing this to msec also
  • 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!

Thanks for your time!

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?

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?

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.

Hi @gitMiguel,

First of all, thanks for developing this binding. I think this can be useful for many people.

One remark I have (I haven’t tried this binding - so feedback only based on what I read in this thread). Add a channel for last ERROR, WARN, and also INFO. I would not excluded INFO. I know these are things you can typically ignore from the log. But with this channel, people could build rules (if “info-channel” contains a certain value => do stuff).

Hello @Dries,

You’re welcome. Nice to hear you like it!

Can’t really see how could INFO lines be useful at this stage. You do realize that there’s alot of those lines and only saving the last of them, imho, won’t do any good.

One posibility is to use somekind of include/exlude list (as mentioned earlier) to pick specific events from log and trigger a Switch channel. But I think almost all of those usefull INFO events are already state updates witch are triggerable through rules. Or do you have any specific use case in mind? I’d love to hear.

As a side note, the idea with this kind of list is to exclude unwanted line counts if the error/ warning is known and doesn’t somehow affect system functionality.