Question on logging in rules

Tags: #<Tag:0x00007f433d9d6e80> #<Tag:0x00007f433d9d6db8> #<Tag:0x00007f433d9d6cc8>
  • Platform information:
    • Hardware: Intel Core i7/16GB/256GB
    • OS: Windows 10 (1803)
    • Java Runtime Environment: Oracle 8u144
  • openHAB version:2.3
  • Issue of the topic: The documentation on logging from rules appears to not work
    This section

shows this:

logDebug("heating-control.rules", "Bedroom: Temperature: %1$.1f°C, Mode %2$s", Bedroom_Temp.state, Bedroom_Heater_Mode.state)

I tried it and it just printed exactly what I typed and not the actual values from the variable and/or items. I did a lot of searching to find alternative ways of doing and found a few.
Here is what I tried:

var humiditySetPoint = 55.0
rule "tooHumidInBasement"
when
    Time cron "0 0/1 * 1/1 * ? *"
then
    var Number humidityAverage = BS_DehumidIn_Humidity.averageSince(now.minusMinutes(60),"influxdb")
    var Number humidityNow = BS_DehumidIn_Humidity.state
    logInfo("basementDehumid.rules", "humidity set point: %1$.1f", humiditySetPoint)
    logInfo("basementDehumid.rules", "humidity set point: [{}]", humiditySetPoint)
    logInfo("basementDehumid.rules", "BS_DehumidIn_Humidity: Current: [{}]", BS_DehumidIn_Humidity.state)
    logInfo("basementDehumid.rules", "BS_DehumidIn_Humidity: Avg: [{}]",  humidityAverage)
    logInfo("basementDehumid.rules", "BS_DehumidIn_Humidity Again: Avg: " + humidityAverage)
    logInfo("basementDehumid.rules", String::format("Set point: %1$.2f%%", humiditySetPoint))
    logInfo("basementDehumid.rules", String::format("Current: %1$.2f%%", humidityNow.floatValue()))
    logInfo("basementDehumid.rules", String::format("Avg: %1$.2f%%", humidityAverage.floatValue()))
    
    if(humidityAverage > humiditySetPoint) {
        BS_DehumidPower_Power.send(ON)
    }
    else {
        if(humidityAverage < (humiditySetPoint - 5)) {
            BS_DehumidPower_Power.send(OFF)
        }
    }
end

and here are the results I got:

2018-09-09 16:24:46.246 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'basementDehumid.rules'
2018-09-09 16:25:00.188 [INFO ] [e.model.script.basementDehumid.rules] - humidity set point: %1$.1f
2018-09-09 16:25:00.189 [INFO ] [e.model.script.basementDehumid.rules] - humidity set point: [55.0]
2018-09-09 16:25:00.189 [INFO ] [e.model.script.basementDehumid.rules] - BS_DehumidIn_Humidity: Current: [55.9]
2018-09-09 16:25:00.190 [INFO ] [e.model.script.basementDehumid.rules] - BS_DehumidIn_Humidity: Avg: [50.56245053634353]
2018-09-09 16:25:00.191 [INFO ] [e.model.script.basementDehumid.rules] - BS_DehumidIn_Humidity Again: Avg: 50.56245053634353
2018-09-09 16:25:00.192 [INFO ] [e.model.script.basementDehumid.rules] - Set point: 55.00%
2018-09-09 16:25:00.193 [INFO ] [e.model.script.basementDehumid.rules] - Current: 55.90%
2018-09-09 16:25:00.193 [INFO ] [e.model.script.basementDehumid.rules] - Avg: 50.56%

As you can see the way documented in the rules section did not work at all. Two of the methods (string concatenation and squiggly braces worked but don’t allow setting precision). String::format allows setting the format, but is VERY picky about the type and the rules it uses make no sense to me (even after reading the documentation that I could find on them). I found that defining a local Number variable to hold the value allowed me to have a consistent method of getting the value I wanted.

So, does anybody use logging in rules? If so, how do you log the values of interesting things in rules. I have a way that works for me and is not horrible, so I am reasonably happy. Hopefully this provides the next person with things to try to get logging in rules to work.

Logging has changed significantly in openHAB 2.3, but the docs were never updated:

Now that you have a lot of experience with the new logging you may find the time and update the docs: :sunglasses:

Would be really great, thx.

Okay, I’ll find some time to update the documentation and submit a PR. Looking at the documentation on log4j2, it appears what is documented should work. This section shows that usage
https://logging.apache.org/log4j/2.x/manual/api.html

Not clear why it doesn’t work. There was another thread that had the same problem. So either everyone else manages to get their rules working without needing to log or there is something different about my setup.

No, there are a lot of recommendations in posts to use logging for debugging rules.

You need to find out :sunglasses:

Very much appreciated.

You could probably have just cast to Number. The result of all numeric calculations is stored in a BigDecimal which is a Number. DecimalType is also a Number so Number is a pretty safe type to use in Rules. And you can cast to Number using as instead of assigning the value to a new variable.

According to the Java String Formatter docs, it should work with BigDecimal. Does it work the same without the .floatValue? Unfortunately d/o/x only work with BigInteger so I think an .intValue would be required to use those with String::format.

Tons. I usually use old school string concatenation. In rare cases I’ll want to format a DateTime or floating point number in which case I’ll use String::format as you have. I never got the hang of using { } in my logs.

The vast majority of the time though such log statements are temporary in which case I don’t care about the precision of the value, or don’t involve floating point numbers.