Determining the source of sendCommand

Setup, Configuration and Use Runtime
, ,
1

I’ve run into quite a strange problem. I have a light controlled by an Aeotec zwave dimmer. In the past, I was using mqtt to send a command to the dimmer to turn the light on at 4pm every weekday. This was done via python script executed via the system crontab (RPi3 OH2) owned by the openhab user. This worked just fine, but recently, I’ve changed that task and included it in a rule that executes at 4pm everyday, but the light should only turn on when the luminance reaches a certain level (luminance is monitored by an Aeotec multi sensor). I’m finding that the light turns on every weekday at 4pm in spite of the luminance constraint. I have a log statement in the rule where the sendCommand is executed and it is logged every time the sendCommand is called. I also have log statements within the rule where the luminance level is checked and they are not logged, except on weekends, when the light does not mysteriously turn on at 4pm. I’m at a loss as to why this happening. I cron task has been removed. The device has been rebooted a few times since the change, so nothing should be cached.

Is there something like a stack trace that could tell me what the source of a sendCommand is? I’ve tried looking in the Karaf console, but nothing there seems relevant.

All tips appreciated, thanks

2

Since you are using log statements already, you should be able to see where it doesn’t work.
If you want us to help more that that, you should post your rule.

3

You might be able to put the events logger into trace level and perhaps there will be more information. I don’t really know. Given this is zwave, check your association groups. You may have zwave devices sending commands directly to each other bypassing OH entirely.

Beyond that, we will need to see the rules and items to make sure there isn’t something subtle going on

4

I also have an Aeotec Multisensor and use the luminance reading in rules to gate whether or not other Aeotec devices (switches/dimmers) are activated or not. All zwave attached via an z-stick gen 5 to OH 2.3 on Rpi3. Assuming this is parallel (only one OH instance attached to all devices), I would check the following:

  1. Your dimmer has a setting that controls what happens when it receives an ON command. It can be either come on at the last operative setting OR come on at full brightness. Unless you are retaining the last AUTOMATED operative brightness level in your rule code and using that for your sendCommand argument OR sending an explicit brightness level in your rule (e.g. sendCommand(70) ), the fact that humans might actually adjust the brightness is a possible behavioral hole.

  2. Some piece of your rule logic is preventing the luminance levels from even being checked. This is suggested by your statement that the logging for those is NOT appearing except on weekends. Some outer logic in the rule is blocking access to the luminance checking block – likely a virtual switch used as a global control variable which is being set elsewhere in your rules network – likely in multiple places, one of which is CRON-controlled thus yielding the DOW/TOD “misbehavior”.

  3. Probably NOT the case here, but in general with this type of setup you have to check for NULL as value of luminance and deal with that explicitly.

Side-note: Those Aeotec multisensors do have a tendence to burn through battery sets pretty quickly (4 x AAA). You have to monitor them closely. Using name-brand batteries, I get 40-50 days out of a set. A good place to invest in rechargeables. I read the luminance every 15 minutes to set a DARKNESS gating virtual variable AND the multisensor is in my kitchen where it gets the highest amount of motion activations per day in my house.

5

Sorry, it took so log for me to respond. Here is the rule I use to turn on the light:

 rule "Check luminance"
when    
Item Inside_Luminance changed
then
var Number start_time = 15

 if(light_status.state.toString == "OFF"){
     if(Season_Name.state.toString == "SUMMER" || Season_Name.state.toString ==  "SPRING"){
        start_time = 16
    }
   
    if(now.getHourOfDay >= start_time) {
        if(luminance_check_started.state == 0 || luminance_check_started.state == NULL){
            var hourtime = start_time - 12
            var current_status = "Check started at: " + hourtime.toString + ":00 PM, waiting for 0 luminance..."
            executeCommandLine("/home/openhab/picode/ldr/set_luminance_start.py " + current_status)
            luminance_check_started.postUpdate(1)
        }

        var Number luminance_level = Inside_Luminance.state as DecimalType
        
        if( luminance_level <= 35 && DeskLight_Switch.state == OFF){
            logInfo("luminance", "DeskLight ON")
            logInfo("luminance", luminance_level.toString)
            DeskLight_Switch.sendCommand(ON)
        }
        if(Inside_Luminance.state == 0 && (ZPorch_Switch.state == OFF || 
            ZGarage_Switch.state == OFF)){
            ZPorch_Switch.sendCommand(ON)
            ZGarage_Switch.sendCommand(ON)
            PatioLight_Switch.sendCommand(ON)
            
            var String next_start = "Lights off when luminance '>' 0 next morning'...'"

            executeCommandLine("/home/openhab/picode/ldr/set_light_status.py " + next_start)
            executeCommandLine("/home/openhab/picode/ldr/side-level.py")
            luminance_check_started.postUpdate(0)
        }
    }
}
end

As you can see, the rule is called every time there is a change in the luminance level, as detected by the multi sensor.

    light_status

is an Item that is updated as outside lights toggle their state (OFF in the morning when luminance is > 0, ON by this rule, when luminance reaches 0)

The morning rule listed later.

Given the season, the rest of the rule will execute only if the current hour is past 3pm or 4pm. Once this threshold is met, the rest of the rule executes and updates the sitemap, and the Item

luminance_check_started

is updated to act as a guard to prevent multiple executions of execCommandLine. The luminance level is then checked and if the luminance level in is <= 35 AND the desk light is off, then the desk light will be turned ON.

Here is where the problem lies. If the light is on as a result of this rule, those log messages should appear in the log. But, today for example, here is what was in the log:

2018-06-12 16:00:02.183 [INFO ] [pse.smarthome.model.script.Desklight] - Received Command
2018-06-12 16:00:11.178 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/home/openhab/picode/ldr/set_luminance_start.py Check started at: 4:00 PM, waiting for 0 luminance...'

As you can see, the Desklight got a "Received Command at 4:02, but the logging statements did not precede it. I have a logInfo statement in switch’s ‘received command’ rule. Today was an overcast day, so the luminance level was below 35, but even on sunny days, that light comes on at 4pm, except, of course, on the weekends. I don’t account for the day anywhere in the rule, so the discrepancy is strange.

I hope I’ve explained things well enough for someone to offer some insight. The rule for the desk lights ‘received command’ is simply:

rule "Adjust Desk lamp"
when 
Item DeskLight_Switch received command
then
logInfo("Desklight", "Received Command")
if(receivedCommand == OFF){
	Desk_Dimmer.sendCommand(OFF)
	DeskLight_Switch.postUpdate(OFF)
}
else{
	Desk_Dimmer.sendCommand(ON)
	DeskLight_Switch.postUpdate(ON)
}
end

Here is the morning rule:

rule "Morning luminance check"
when 
Item Inside_Luminance changed from 0
then

logInfo("Luminance", Inside_Luminance.state.toString)

if(light_status.state.toString == "ON"){
var start_time = 15

if(Season_Name.state.toString == "SUMMER" || Season_Name.state.toString == "SPRING"){
        start_time = 16
}

var hourtime = start_time - 12
var next_start = "Luminance check starting at: " + hourtime.toString + ":00 PM"
executeCommandLine("/home/openhab/picode/ldr/set_morning_light_status.py " + next_start)

ZPorch_Switch.sendCommand(OFF)
ZGarage_Switch.sendCommand(OFF)
}
end

I have one Time rule that turns on the light at 6:45 am during the work week:

     rule "Turn on desk light during the work week at 6:45"
     when
      Time cron "0 45 6 ? * MON-FRI *"
     then
     logInfo("Desklight", "DeskLight morning ON command sent")
     DeskLight_Switch.sendCommand(ON)
    end

There are two other rules where the desk light gets sendCommand(ON), but those are both via two wall mote, and I can’t imagine those going rogue.

Someone mentioned turning on trace, I’ll have to look that up, as I’m not sure how to do that and I’ll get back with results.

Thanks for the help

6

You need to look at the events.log and the debug level logs of what ever binding is linked to Desklamp_Switch around 16:00 to see what is issuing the command to the item.