Handling logInfo when nothing happenend?

Setup, Configuration and Use Beginners
1

Hello Guys…
Maybe a silly question, but i was wondering how to handle logging in a more “pro” way…

Currently when i write a rule and makes something that should be logged for debugging later, let’s say:

rule "test"
   when Item test changed
        if condition1 < condition 2
       {
       sendCommand(light, ON)
       logInfo(Log, "Light turned on automatically")
    }
end

Then the log will be filled with “Light turned on automatically” everytime that item updates, is there a samrt way of handling this - or do i need to make an extra IF statement to see if the light is OFF and then only log if it changes state or something like this? - this can be pretty heavy to handle, since i then need a lot of etra IF statements for everything that i wanna log?

2

Hello Rasmus

In your example, you send always the command Light on. You can only log what you check.

if condition1 < condition2 && light.status == off

With this, you check your conditions and the light status.
Theortically the lights could be on, when the rule get triggered.

There are more log options than loginfo: logwarning and logdebug…

3

There are three approaches you can use going from the laziest to the most “professional”.

Which you choose is entirely up to you. A lot of times when you are dealing with one developer the most professional is way more work than is warranted.

#Lazyiest
Comment the logging statement out when you no longer need it but want to keep it around for later. When the time comes when you need it again remove the commenting statement to reenable it. Or just delete it and recreate it later if you need it.

#Slightly less lazy
Use the logging levels. For logging statement you may only care about when debugging problems use logDebug. For logging statements that are useful all of the time use logInfo. For problems that are not serious use logWarn and for problems that are serious use logError.

By default logInfo and above will only appear in the logs. If you move openHAB into debug logging mode the logDebugs will also appear in the log file (along with every other debug level log statement).

NOTE: changing the logging level requires an OH reboot unless you are tailing the logs in the karaf console where I think you can adjust the level on the fly.

#More professional
Come up with a log naming scheme that makes sense. For example “lighting”, “presence”, “alarm”, etc. All logging statements that are relevant to lighting should use “lighting” as the first argument to logX.

Apply use of the different logging levels as described above.

Now edit the logging config (see Taming OH 2 Logging and create a logger for each of your named loggers (i.e. “lighting”, “presence”, etc.). Now you can individually modify the logging level for each category of your rules by changing the logging levels. You can even shunt these logs into a separate file if desired.

Personally, I’m lazy. I pretty much just use logInfo and I either comment the logs out or delete them entirely when I’m done. This keeps my openhab.log pretty sparse and it only really reports warnings and errors or when a major sensor detected something (e.g. an external door opened, no one is home) or an actuator took some action (e.g. the light turned on because it is cloudy, the garage door was opened). As an example, in the past two hours there have been 7 entries in my openhab.log and three of those are errors contacting a webservice that stopped working for some reason.

I do use a sane naming scheme for my logging though so if I ever decide to go “professional” with it I’ll be ready. It also helps me segregate stuff out of openhab.log using grep.

4

Yes ok, that makes perfect sense… also I used the lazy method, but would like to prepare something more prof… I think I’ll start grouping them as the professional way and then later do the split up in files, that would be awesome…
But again, all things need to be hardcoded, there’s nothing easy to say only log when an item is changed or something, which makes sense since the log command is a line for it self… then I must accept that i get a log entry each time i receive updated telegrams from the KNX…

5

Unless you add additional logic (i.e. an if statement). The logger has no knowledge of nor cares a whit about the states of anything. If you only want the log to go out when the Item actually changes you need to code that yourself. I find that 99% of the time I’m already doing this sort of checking anyway so it ends up not being a burden.

6

Hello Rick… Ok then i understand, i thought that there were some kind of intelligence in the log statement - but it’s only a “command line” :slight_smile:

Just to be curious, you say you do that 99% of the time, only firing a rule when it’s nessecary? Does that mean you check allways if the light is off - and only then firing a on command?
Like i do it now, i fire an On or Off command everytime i receive updates on my sensors… this i a bit lazy i think, since i get a on or off signal every 5. minutes…

Can an item return it’s “Comment” for the logger?
Something like when using lambdas, i have an input item

Rick you does that in your example, but that’s the state you are logging - which only gives me the value of the parameter - but i don’t know which item is set for that?

logInfo(Heating, Valve.name + “Is set for” + Setpoint)?

This would be very usefull when dealing with Lambdas, so i know which item the lambda has processed?

8

First, let me say I had a shower thought this morning. You really shouldn’t be logging out state changes in your Items from Rules anyway. All the state changes and updates to Items are already logged in events.log.

Indeed. I pretty religiously only send a command to an Item if the command will cause that Item to change its state. There are a few exceptions to that. But, since I’m already checking I will just put the logging statement inside that if statement.

But this does beg the question of what exactly it is that I log.

  • I never log from my rules simple stuff that I can find somewhere else, e.g. events.log unless it is a temporary log I’m using to debug a problem.
  • I never log actions that make no actual change. For example if a rule decides it needs to turn on a light and the light is already on, nothing gets logged, again unless I’m debugging.
  • I only log when a rule is actually changing something.
  • I only have one log statement for each action/change.

By being very deliberate in what logs remain I have a very easy to read log file that allows me to follow and reconstruct the behavior of the rules easily without being overwhelmed by noise.

I don’t know what you mean by “Comment”. If you mean its label the answer is “no” for OH 1.x and “maybe” in OH 2. I noticed back when my Designer was working that there is a getLabel method on the Item class now. I don’t know if it works though.

If you mean the Item’s name then the answer is “yes”. MyItem.name

As you indicate, this is very handy for determining which Items are being worked on by a lambda or generic rule.