Zigbee lights turns back on after Astro-rule turned it off

Tags: #<Tag:0x00007f745e433f80> #<Tag:0x00007f745e433eb8> #<Tag:0x00007f745e433dc8>

I have these pair of rules:

rule "fasadlampa_rule_off"
when
    Item Test_item received command OFF
    or
    Channel 'astro:sun:local:rise#event' triggered START
then
   sendCommand(zigbee_device_0000000C_d0cf5efffec0c9b4_D0CF5EFFFEC0C9B4_1_dimmer, 0)
end

rule "windowlamps_rule_morning_off"
when
    Channel 'astro:sun:local:rise#event' triggered START
then
    sendCommand(Wallwart1, OFF)
    sendCommand(Wallwart2, OFF)
end

and would expect all the lights to go off when the sun rises. Unfortunately my events.log shows this:

2019-10-08 07:24:00.000 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDawn#event triggered END
2019-10-08 07:24:00.002 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered START
2019-10-08 07:24:00.035 [ome.event.ItemCommandEvent] - Item 'Wallwart1' received command OFF
2019-10-08 07:24:00.040 [nt.ItemStatePredictedEvent] - Wallwart1 predicted to become OFF
2019-10-08 07:24:00.041 [ome.event.ItemCommandEvent] - Item 'Wallwart2' received command OFF
2019-10-08 07:24:00.042 [vent.ItemStateChangedEvent] - Wallwart1 changed from ON to OFF
2019-10-08 07:24:00.042 [ome.event.ItemCommandEvent] - Item 'zigbee_device_0000000C_d0cf5efffec0c9b4_D0CF5EFFFEC0C9B4_1_dimmer' received command 0
2019-10-08 07:24:00.045 [nt.ItemStatePredictedEvent] - Wallwart2 predicted to become OFF
2019-10-08 07:24:00.047 [nt.ItemStatePredictedEvent] - zigbee_device_0000000C_d0cf5efffec0c9b4_D0CF5EFFFEC0C9B4_1_dimmer predicted to become 0
2019-10-08 07:24:00.048 [vent.ItemStateChangedEvent] - Wallwart2 changed from ON to OFF
2019-10-08 07:24:00.048 [vent.ItemStateChangedEvent] - zigbee_device_0000000C_d0cf5efffec0c9b4_D0CF5EFFFEC0C9B4_1_dimmer changed from 10 to 0
2019-10-08 07:24:22.384 [vent.ItemStateChangedEvent] - Wallwart2 changed from OFF to ON
2019-10-08 07:25:01.436 [vent.ItemStateChangedEvent] - Wallwart1 changed from OFF to ON

As you can see on the last two lines the lights turns back on for some reason. What causes it to go back on? Am I missing something fundamental in the rules programming?

My items file looks like this:

Group gFasadbelysning
Dimmer   FasadbelysningFramsidaColortemperature   "Color temperature"   (gFasadbelysning) {channel="zigbee:device:0000000C:d0cf5efffec0c9b4:D0CF5EFFFEC0C9B4_1_colortemperature"}
Dimmer   FasadbelysningFramsidaDimmer             "Level control"       (gFasadbelysning) {channel="zigbee:device:0000000C:d0cf5efffec0c9b4:D0CF5EFFFEC0C9B4_1_dimmer"}
DateTime RiseEnd "Sun rise" {channel="astro:sun:local:rise#end"}
DateTime SetEnd "Sun set" {channel="astro:sun:local:set#end"}
Switch   Wallwart1 "wallwart 1" {channel="zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer"}
Switch   Wallwart2 "wallwart 2" {channel="zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer"}

and my sitemap looks like this:

Group gFasadbelysning
Dimmer   FasadbelysningFramsidaColortemperature   "Color temperature"   (gFasadbelysning) {channel="zigbee:device:0000000C:d0cf5efffec0c9b4:D0CF5EFFFEC0C9B4_1_colortemperature"}
Dimmer   FasadbelysningFramsidaDimmer             "Level control"       (gFasadbelysning) {channel="zigbee:device:0000000C:d0cf5efffec0c9b4:D0CF5EFFFEC0C9B4_1_dimmer"}
DateTime RiseEnd "Sun rise" {channel="astro:sun:local:rise#end"}
DateTime SetEnd "Sun set" {channel="astro:sun:local:set#end"}
Switch   Wallwart1 "wallwart 1" {channel="zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer"}
Switch   Wallwart2 "wallwart 2" {channel="zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer"}

That’s twenty seconds later. What do they actually do, turn off then back on? Or the devices do nothing, and the log just reflects openHAB revising the state later when it finds out its prediction didn’t come true?

There are no ON commands logged, so it did not come from rule or UI

The physical devices does actually turn back on, and as you say there is nothing in the session log showing what caused this. The Openhab.log shows this at the same time:


2019-10-08 07:24:00.037 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED15DE7: Command for channel zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer --> OFF [OnOffType]
2019-10-08 07:24:00.044 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED223A1: Command for channel zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer --> OFF [OnOffType]
2019-10-08 07:24:00.049 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - D0CF5EFFFEC0C9B4: Command for channel zigbee:device:0000000C:d0cf5efffec0c9b4:D0CF5EFFFEC0C9B4_1_dimmer --> 0 [PercentType]
2019-10-08 07:24:06.862 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - D0CF5EFFFEC0C9B4: Polling...
2019-10-08 07:24:06.863 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - D0CF5EFFFEC0C9B4: Polling zigbee:device:0000000C:d0cf5efffec0c9b4:D0CF5EFFFEC0C9B4_1_colortemperature
2019-10-08 07:24:14.864 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - D0CF5EFFFEC0C9B4: Polling zigbee:device:0000000C:d0cf5efffec0c9b4:D0CF5EFFFEC0C9B4_1_dimmer
2019-10-08 07:24:22.150 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED223A1: Polling...
2019-10-08 07:24:22.151 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED223A1: Polling zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer
2019-10-08 07:24:22.380 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 000D6FFFFED223A1: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Oct 08 07:24:22 CEST 2019]
2019-10-08 07:24:22.381 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 000D6FFFFED223A1: Channel zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer updated to 100
2019-10-08 07:24:22.382 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED223A1: Updating ZigBee channel state zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer to 100
2019-10-08 07:24:22.614 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 000D6FFFFED223A1: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Oct 08 07:24:22 CEST 2019]
2019-10-08 07:24:22.614 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 000D6FFFFED223A1: Channel zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer updated to 100
2019-10-08 07:24:22.614 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED223A1: Updating ZigBee channel state zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer to 100
2019-10-08 07:25:01.194 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED15DE7: Polling...
2019-10-08 07:25:01.195 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED15DE7: Polling zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer
2019-10-08 07:25:01.433 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 000D6FFFFED15DE7: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Oct 08 07:25:01 CEST 2019]
2019-10-08 07:25:01.433 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 000D6FFFFED15DE7: Channel zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer updated to 84
2019-10-08 07:25:01.433 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED15DE7: Updating ZigBee channel state zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer to 84
2019-10-08 07:25:01.711 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 000D6FFFFED15DE7: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=213, lastReportTime=Tue Oct 08 07:25:01 CEST 2019]
2019-10-08 07:25:01.711 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 000D6FFFFED15DE7: Channel zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer updated to 84
2019-10-08 07:25:01.712 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED15DE7: Updating ZigBee channel state zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer to 84

Funny enough I have a pair of rules for turning the lights on at sunset and then turning it off based on a cron-time at 23.00h and that works as expected.
@chris, can this be related to the zigbee binding?

Regards,
Henrik

Do they actually turn OFF and back ON or its that only in the logs?
Do you have any other rules involving these two items?

I have not been around at this time seing them going off and then on, but they are on when I look shortly after.
All rules involving Wallwart1 and 2 is:

rule "windowlamps_rule_morning_on"
when
    Time cron "0 0 5 1/1 * ? *"
then
    sendCommand(Wallwart1, ON)
    sendCommand(Wallwart2, ON)
end

rule "windowlamps_rule_morning_off"
when
    Channel 'astro:sun:local:rise#event' triggered START
then
    sendCommand(Wallwart1, OFF)
    sendCommand(Wallwart2, OFF)
end

rule "windowlamps_rule_evening_on"
when
    Channel 'astro:sun:local:set#event' triggered START
then
    sendCommand(Wallwart1, ON)
    sendCommand(Wallwart2, ON)
end

rule "windowlamps_rule_evening_off"
when
    Time cron "0 0 23 1/1 * ? *"
then
    sendCommand(Wallwart1, OFF)
    sendCommand(Wallwart2, OFF)
end

They all work fine except that the morning_off leavs it on (or something else forces it back on some 20s later)

Or they don’t even turn off in the first place and the binding updates the state of the item according to their actual state. And according to your DEBUG log that’s exactly what is happening.

Does that happen EVERY morning?

“predicted to become” usually means something is not connected and OH just assuming it should be ON/OFF

Check if everything what is needed is really online

That’s not quite true. The prediction comes from autoupdate, which is enabled for each Item by default.
autoupdate sees each command and predicts the likely effect on state, and issues a state update.
autoupdate is blind to whether any other bindings are also listening for commands, and acting on them.

But yes, the point here is that a log of state ON from an autoupdate prediction gives you absolutely no assurance that the target device is really ON at all. Or OFF in this case.

I note the offending Items are switch types, presumably linked to dimmer type channels, but I’d have thought that should still work.

interesting, I’ve thought differently.
Only time I see something like that in my log is when my mqtt broker is offline and OH triggers mqtt item. Other than that it’s always “item become ON” instead “item predicted to become ON”

Thanks for clarify

The openhab.log for the evening_off rule shows this:


2019-10-07 23:00:00.016 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED15DE7: Command for channel zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer --> OFF [OnOffType]
2019-10-07 23:00:00.020 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED223A1: Command for channel zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer --> OFF [OnOffType]
2019-10-07 23:00:00.290 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 000D6FFFFED15DE7: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=false, lastReportTime=Mon Oct 07 23:00:00 CEST 2019]
2019-10-07 23:00:00.291 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 000D6FFFFED15DE7: Channel zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer updated to OFF
2019-10-07 23:00:00.291 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED15DE7: Updating ZigBee channel state zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer to OFF
2019-10-07 23:00:00.504 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 000D6FFFFED223A1: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=false, lastReportTime=Mon Oct 07 23:00:00 CEST 2019]
2019-10-07 23:00:00.504 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 000D6FFFFED223A1: Channel zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer updated to OFF
2019-10-07 23:00:00.505 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED223A1: Updating ZigBee channel state zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer to OFF
2019-10-07 23:00:06.239 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED223A1: Polling...
2019-10-07 23:00:06.240 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED223A1: Polling zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer
2019-10-07 23:00:06.554 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 000D6FFFFED223A1: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=false, lastReportTime=Mon Oct 07 23:00:06 CEST 2019]
2019-10-07 23:00:06.555 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 000D6FFFFED223A1: Channel zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer updated to OFF
2019-10-07 23:00:06.555 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED223A1: Updating ZigBee channel state zigbee:device:0000000C:000d6ffffed223a1:000D6FFFFED223A1_1_dimmer to OFF
2019-10-07 23:00:06.786 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 000D6FFFFED223A1: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Mon Oct 07 23:00:06 CEST 2019]
2019-10-07 23:00:09.423 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED15DE7: Polling...
2019-10-07 23:00:09.423 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED15DE7: Polling zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer
2019-10-07 23:00:09.654 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 000D6FFFFED15DE7: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=false, lastReportTime=Mon Oct 07 23:00:09 CEST 2019]
2019-10-07 23:00:09.654 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 000D6FFFFED15DE7: Channel zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer updated to OFF
2019-10-07 23:00:09.654 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6FFFFED15DE7: Updating ZigBee channel state zigbee:device:0000000C:000d6ffffed15de7:000D6FFFFED15DE7_1_dimmer to OFF
2019-10-07 23:00:09.884 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 000D6FFFFED15DE7: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=213, lastReportTime=Mon Oct 07 23:00:09 CEST 2019]

And that one I know is working…

In this log after the first two line you have the zigbee debug lines turning off the item. Not in your first log.
That is why I was asking if this happened EVERY mornings. It could be that your devices dropped off the zigbee network momemtarely this morning.

It is possible for bindings to veto autoupdate, on the basis that a timely real response is expected. (autoupdate is really just about speeding up the apparent response in the UI). Most binding’s don’t do that.

Bear in mind also that events.log normally only shows changes, so when two different actors issue updates with the same result only one change is seen.

In the case in point here, depending if that is all of the [debug] log, we don’t seem to get any update back from the zigbee binding for the morning OFF case.

The new evening log shows an immediate (200mS) unsolicited OFF response to the command. Good stuff.
The morning log shows no response until the routine poll comes along - and then it’s not what was expected.
It looks like the transmitted command just blackholes, maybe something has gone to sleep in the night.
System rebooted in the night? Auto backup?

It happened the two mornings that has passed since I created the rule, so 100% failure rate so far, but not much of a statistics…

I suggest you wake up before sunrise tomorrow and keep an eye on those lights to see if they ACTUALLY turn off and then back on of if it’s only a binding failure

Problem is that I just left for work/leaving kids at kindergarden by then… If nothing else I suppose I will have to wait for saturday…

You do realise you can add a test trigger to your switch-y rule, same as you already have to your dimmer-y rule?

I suspect it will work fine while you are watching it. The rule does the same thing, with the same timing, that the working evening-off rule does. Something else happens in the night, or something times out after hours of inactivity etc.

Test trigger as I did in fasadlampa_rule_off in the first post or something better?

A trigger is a trigger.

Out of interest, does that fasadalampa dimmer get involved in the evening events, or only morning? The debug logs suggest that two zigbee commands come from evening-off, and three from morning-off. Maybe that is the difference we seek.

From what I can see in the logs, the command is sent to turn it off, but the device still reports that it’s on. Unfortunately from the logging it’s not possible to see if the commands are really sent or not so I can’t confirm this.

One thing to note - why is the device being polled so often? Is that something you changed or was there a problem during the initialisation?

You also don’t say a) what the device is, or b) what binding version you’re running?

I don’t know why it’s being polled so often? I haven’t changed anything and I don’t believe I had any problems during initialisation. What polling rate would you expect?

The devices (Wallwart1 and Wallwart2) are IKEA TrĂĄdfri wall switches (art.no 903.561.66). The binding is binding-zigbee - 2.4.0.