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?
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:
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?
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.
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”
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?
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
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.
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.