MQTT / Logging in general

  • Platform information:
    • Hardware: DiskStation Docker
    • openHAB version: 2.5.3
  • Mosquitto Broker in another Docker container

I’ve setup my Openhab and it works so far nearly as expected.
Though I have an issue with logging and a shelly 2.5 via MQTT.

Issue1:
I’m getting lots of warnings in the log:
[WARN ] [hab.binding.mqtt.generic.ChannelState] - Command ‘off’ not supported by type ‘OnOffValue’: No enum constant org.eclipse.smarthome.core.library.types.OnOffType.off

I tried to solve that with Incoming Transformation of the channel belonging to the state of shelly.
This unfortunately did not stop the system from logging the warning.
I can not - or I do not want to set Tasmota on my shelly - change the message from the shelly, so how can I get rid of this message?

Issue 2:
To prevent spaming my log files I even tried to set the log level for this to ERROR but without success:

Logger                                             │ Level    
 ───────────────────────────────────────────────────┼──────    
 ROOT                                               │ WARN 
**hab.binding.mqtt.generic.ChannelState              │ ERROR**    
javax.jmdns                                        │ ERROR   
javax.mail                                         │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO                                                                              
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR                                                                     
org.apache.karaf.shell.ssh.SshUtils                │ ERROR                                                                           
org.apache.karaf.shell.support                     │ OFF                                                                                    
org.apache.sshd                                    │ ERROR                                                                                     
org.eclipse.lsp4j                                  │ OFF                                                                                             
org.eclipse.smarthome                              │ INFO                                                                                     
**org.eclipse.smarthome.script.TimerRules.rules      │ DEBUG**                                                                   
org.jupnp                                          │ ERROR                                                                                          
org.openhab                                        │ INFO                                                                                           
org.openhab.ui.paper                               │ WARN                                                                                    
org.openhab.ui.paper.internal                      │ INFO                                                                                   
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR                                                               
org.ops4j.pax.web.pax-web-runtime                  │ OFF                                                                                                    
smarthome.event                                    │ INFO                                                                                        
smarthome.event.InboxUpdatedEvent                  │ ERROR                                                                     
smarthome.event.ItemAddedEvent                     │ ERROR                                                                       
smarthome.event.ItemRemovedEvent                   │ ERROR                                                                    
smarthome.event.ItemStateEvent                     │ ERROR                                                                         
smarthome.event.ThingAddedEvent                    │ ERROR                                                                      
smarthome.event.ThingRemovedEvent                  │ ERROR                                                                   
smarthome.event.ThingStatusInfoEvent               │ ERROR

I even do not see any loggings of my rules (currently I tried only to enable one):
Rule file name: TimerRules.rules
logDebug(“TimerRules.rules”, “Begin BackyardLawnGrowIrrigationRule with value {}”, BackyardLawnGrowIrrigation.state)

What do I need to do to get the loggings?

Thanks in advance.
Joerg

What you’d want to do is to use a transformation that works, not try to hide the error.
But we do not know what you are doing now.

That is not a complete rule. Maybe you see an error message in your openhab.log when your rules file loads or is edited.

Well, yes. Hiding Warnings is not the solution. I only hate spamming log files.

Issue1:
I"ve installed Map Transformations, created an OnOff.map file with:
on=ON
off=OFF
Used trat in “mqtt Thing” channel of shell, incoming Transformation.
No changes in logging.
I do not have lots of mqtt msgs so i’ve checked with mqtt.fx and only the shelly reports lower case content.

Issue2:
All my rules work live a charm. Except trat i can not see the logs. Thats why i left out unnecessary code and provided only relevant snippets. It is not easy to write code and test without any debug tools, so the first rules where created in try and error mode.

Set up the transformation correctly. How did you apply it to your MQTT Thing? Did you install the Map transform?

It’s not spamming. It’s legitimately telling you that something is wrong and you need to fix it. Your Item is not updating or being commanded from the Shelly because the transform is not working.

The default log level of Rules is Info. logDebug won’t show up unless you drop the logging level for the Rules. To test that it works use logInfo. Also, make sure you are looking in openhab.log.

Don’t redact the code or logs. It never helps us and only results in more questions.

Yes, I did.

Basically you’re right. Warnings are like Info with a special character to me. Could lead to an issue but could also not. In this case I think it is spam, as no real useful information is inside of that log message.
No origin or hint from where it is coming. So basically useless only information of potential issue you’ll never find out without source code reading or having someone else who had the issue reported in the internet.

Fair enough. But for that I provided also my log:get output of Karaf. There it’s stated that for this Log everything, including DEBUG, should be logged.

Well yeah, I know that time of everyone is limited and basically its about not having log entries from my rules, so I try to focus on relevant information not bothering with too much useless info. BUT yes, I did not mention that my rules are working. Years, decades ago, I was a software developer as well, so I know how to write code, though the used languages (except Java) I’ve never used. Nethertheless I still get source code running even if it takes time.

That’s not quite true. It’s clearly to do with an MQTT binding channel, and clearly one that involves on/off.
I agree it is a shame it doesn’t say which channel, and leaves you to work it out.

How did you work it out? Meaning are you confident you are looking at the correct channel.

Okay, you have both a MAP transform and the Custom On/Off values set here.
From many other posts these do not play nice together - I think the MAP happens first, not sure, but then it will will fail the custom on/off lookup.

An important point is the Custom values affect both outgoing and incoming, and you do have a commandTopic set, so you are using outgoing.
Presumably you are happy that openHAB commands ON/OFF are published as “on”/“off” payloads?

If so, and if the incoming status payloads are also “on”/“off”, just do away with your MAP altogether and leave the Custom values.
Else, if you need different incoming and outgoing payloads, you will have to do separate transforms and remove the Custom on/off values.

When people have got in a mess with their logging before, the easiest escape has been to restore the whole default cfg file

1 Like

Yeah, basic origin info. I’ve checked listening with MQTT.fx on nearly every topic. There was one ESP8266 written by myself ages ago not monitored as I thought it was offline. With powering my swimming pool this device got power as well…
I’ve removed the MAP from Channel, now logging is quite!
Shame on me…

Hmm, I’ve checked the file.

log4j2.logger.org_eclipse_smarthome_script_timerrules_rules.level = DEBUG
log4j2.logger.org_eclipse_smarthome_script_timerrules_rules.name = org.eclipse.smarthome.script.TimerRules.rules

What is not very clear to me,do I need to use the filename after script:
log:set DEBUG org.eclipse.smarthome.script.TimerRules.rules
or the one which I use in the log statement (in this case both are the same):

var Timer irrigationLine1Timer = null
var Timer irrigationLine2Timer = null
var Timer irrigationLine3Timer = null

rule "BackyardLawnGrowIrrigationRule"
when
  Item BackyardLawnGrowIrrigation changed from OFF to ON
then
  logDebug("TimerRules.rules", "Begin BackyardLawnGrowIrrigationRule with value {}", BackyardLawnGrowIrrigation.state)
  if(irrigationLine1Timer === null) {
    Switchbox2Channel9.sendCommand(ON)
    var timeoutLine1 = (BackyardLawnIrrigationDurationPool.state as DecimalType).intValue
    irrigationLine1Timer = createTimer(now.plusMinutes(timeoutLine1)) [|
      Switchbox2Channel9.sendCommand(OFF)
      var isStillOn = (BackyardLawnGrowIrrigation.state == ON)
      if(isStillOn) {
        Switchbox2Channel10.sendCommand(ON)
        var timeoutLine2 = (BackyardLawnIrrigationDurationHut.state as DecimalType).intValue
        irrigationLine2Timer = createTimer(now.plusMinutes(timeoutLine2)) [|
          Switchbox2Channel10.sendCommand(OFF)
          var isStillOn2 = (BackyardLawnGrowIrrigation.state == ON)
          if(isStillOn2) {
            Cistern_Mains2.sendCommand(ON)
            var timeoutLine3 = (BackyardLawnIrrigationDurationStreet.state as DecimalType).intValue
            irrigationLine3Timer = createTimer(now.plusMinutes(timeoutLine3)) [|
	            Cistern_Mains2.sendCommand(OFF)	
              irrigationLine3Timer = null
              BackyardLawnGrowIrrigation.sendCommand(OFF)
            ]            
          }
          irrigationLine2Timer = null
        ]        
      }
      irrigationLine1Timer = null
    ]
  }
  logDebug("TimerRules.rules", "End BackyardLawnGrowIrrigationRule")
end

rule "BackyardLawnGrowIrrigationRuleStop"
when
  Item BackyardLawnGrowIrrigation changed from ON to OFF
then
  logDebug("TimerRules.rules", "Begin BackyardLawnGrowIrrigationRuleStop with value {}", BackyardLawnGrowIrrigation.state)
  Switchbox2Channel9.sendCommand(OFF)
  Switchbox2Channel10.sendCommand(OFF)
  Cistern_Mains2.sendCommand(OFF)
  irrigationLine1Timer = null
  irrigationLine2Timer = null
  irrigationLine3Timer = null
  logDebug("TimerRules.rules", "End BackyardLawnGrowIrrigationRuleStop")
end

Yes, I could use cancel of timers in my manualTurnOff rule…

Oh Jesus…

Finally I’ve crossed checked the namespace…

Switching from:

log:set DEBUG org.eclipse.smarthome.script.TimerRules.rules

to

log:set DEBUG org.eclipse.smarthome.model.script

I’ll get every message from my rules.

Changing this then to:
log:set DEBUG org.eclipse.smarthome.model.script.TimerRules.rules

I do get only the ones from this specific rule (I deleted the entry for all rules manually in cfg file before executing above statement).

Only open question for now,do I need to use filename oder logger name in logDebug statement

A more appropriate way would be a simple state machine:

// define global vars at top of file
var Timer tIrrigation = null
var int iCount = 0

rule "Backyard lawn irrigation"
when
    Item BackyardLawnGrowIrrigation changed
then
    if(previousState == NULL) return;
    logDebug("irrigation", "Backyard lawn irrigation rule started with {}",BackyardLawnGrowIrrigation.state)
    if(BackyardLawnGrowIrrigation.state == ON) {
        logDebug("irrigation", "start irrigation")
        tIrrigation?.cancel
        iCount = 0
        tIrrigation = createTimer(now, [|
            iCount ++
            logDebug("irrigation", "Step {}",iCount)
            switch (iCount) {
                case 1 : {
                    logDebug("irrigation", "Start Pool irrigation with {} Minutes",(BackyardLawnIrrigationDurationPool.state as DecimalType).intValue)
                    Switchbox2Channel9.sendCommand(ON)
                    tIrrigation.reschedule(now.plusMinutes((BackyardLawnIrrigationDurationPool.state as DecimalType).intValue))
                }
                case 2 : {
                    logDebug("irrigation", "Stop Pool irrigation")
                    logDebug("irrigation", "Start Hut irrigation with {} Minutes",(BackyardLawnIrrigationDurationHut.state as DecimalType).intValue)
                    Switchbox2Channel9.sendCommand(OFF)
                    Switchbox2Channel10.sendCommand(ON)
                    tIrrigation.reschedule(now.plusMinutes((BackyardLawnIrrigationDurationHut.state as DecimalType).intValue))
                }
                case 3 : {
                    logDebug("irrigation", "Stop Hut irrigation")
                    logDebug("irrigation", "Start Street irrigation with {} Minutes",(BackyardLawnIrrigationDurationStreet.state as DecimalType).intValue)
                    Switchbox2Channel10.sendCommand(OFF)
                    Cistern_Mains2.sendCommand(ON)
                    tIrrigation.reschedule(now.plusMinutes((BackyardLawnIrrigationDurationStreet.state as DecimalType).intValue))
                }
                default: {
                    logDebug("irrigation", "Stop Street irrigation")
                    Cistern_Mains2.sendCommand(OFF)
                    BackyardLawnGrowIrrigation.postUpdate(OFF)
                    tIrrigation = null
                }
            }
        ])
    } else if(BackyardLawnGrowIrrigation.state == OFF){
        logDebug("irrigation", "stop irrigation")
        tIrrigation?.cancel
        tIrrigation = null
        Switchbox2Channel9.sendCommand(OFF)
        Switchbox2Channel10.sendCommand(OFF)
        Cistern_Mains2.sendCommand(OFF)
    }
    logDebug("irrigation", "Backyard lawn irrigation rule ends")
end

If using other Itemnames the code could be even shorter:

Group gIrrigationTime
Group gIrrigationValve
Number IrrigationTime_1 "Pool [%0.f mins]" (gIrrigationTime)
Switch IrrigiationValve_1 "Pool [%s]" (gIrrigationVale)
Number IrrigationTime_2 "Hut [%0.f mins]" (gIrrigationTime)
Switch IrrigiationValve_2 "Hut [%s]" (gIrrigationVale)
Number IrrigationTime_3 "Street [%0.f mins]" (gIrrigationTime)
Switch IrrigiationValve_3 "Street [%s]" (gIrrigationVale)

with this rule:

// define global vars at top of file
var Timer tIrrigation = null
var Number nCount = 0

rule "Backyard lawn irrigation"
when
    Item BackyardLawnGrowIrrigation changed
then
    if(previousState == NULL) return;
    logDebug("irrigation", "Backyard lawn irrigation rule started with {}",BackyardLawnGrowIrrigation.state)
    if(BackyardLawnGrowIrrigation.state == ON) {
        logDebug("irrigation", "start irrigation")
        tIrrigation?.cancel
        nCount = 0
        tIrrigation = createTimer(now, [|
            nCount = nCount + 1
            logDebug("irrigation", "Step {}",nCount)
            gIrrigationValve.members.filter[i|i.state == ON].forEach[v|
                logDebug("irrigation","Switch off Valve {}",v.name)
                v.sendCommand(OFF)]
            if(nCount < 4) {
                logDebug("irrigation","Switch on Valve {}",gIrrigationValve.members.filter[i|i.name.contains(nCount.toString)].head.name)
                gIrrigationValve.members.filter[i|i.name.contains(nCount.toString)].head.sendCommand(ON)
                tIrrigation.reschedule(now.plusMinutes((gIrrigationTimer.members.filter[i|i.name.contains(nCount.toString)].head.state as DecimalType).intValue))
            } else {
                tIrrigation = null
            }
        ])
    } else if(BackyardLawnGrowIrrigation.state == OFF){
        logDebug("irrigation", "stop irrigation")
        tIrrigation?.cancel
        tIrrigation = null
        gIrrigationValve.members.filter[i|i.state == ON].forEach[v|
            logDebug("irrigation","Switch off Valve {}",v.name)
            v.sendCommand(OFF)
        ]
    }
    logDebug("irrigation", "Backyard lawn irrigation rule ends")
end
2 Likes

Hi,

I actually like both approaches, though I need to make myself more familiar with lanbda’s…
As I said I’ve left developing way before Lambda was even in someone’s mind.

The second approach is cool, I do understand it nearly but I need to introduce some new Items and link them to the channel. Could be done but this solution currently is only for the grouth of my lawn (newly seeded). So I need to have this sequence for about 6 to 8 weeks.Then I am going to switch to another irrigation method and then I will definitely consider this approach.

Many thanks for sharing this as I would never have thought about that and learned some new cool ways using lambda/functional programming.

I’m not entirely sure I understand the question. The first argument to the logDebug et. al. statements gets appended to org.eclipse.smarthome.model.script and therefore becomes the name of that logger. So, if you want to put all the logs statements with “Timer.rules” into their own log file, see Log4j2 Sample Config and create a new logger and appender configure using org.eclipse.smarthome.model.script.Timer.rules for the logger.blah.name property.

Yes that was I am after. The first argument of the logYYY statements is used as the logger “name”. The file name of rule can be then what ever.

Then this thread is sorted out. Thanks a lot to all of you.