Item & group rules fail after zigbee light thing powered off/on

diablodale · August 23, 2020, 4:22pm

Hi all. My Zigbee light rule Member of x changed and Item x changed rules don’t run if the power to the light is disconnected and then reconnected (e.g. a physical power switch). The light can be turned off/on/dimmed. It is only the rules which don’t run.

I request some insight/advice as to the failure. I below provide a repro case and details.

I’m new to OH2 - migrating from SmartThings. I have experience writing SmartThings device handlers and I’m a professional dev. I read many posts about rules not running, but haven’t seen a post about rules not running after the Thing is power-cycled. There is a somewhat similar post at [SOLVED] Lights Rule - Group OFF - One Thing is offline

Setup

Openhab 2.5.7 via official Docker image openhab/openhab:latest-debian at commit 03e622c2efb8
Docker host is Ubuntu x86_64 v18.04.5 LTS, 8GB ram (showing 3.2GB free while all is running)
Java is that which is included in the above official Docker image. Docker logs for the container has an entry “Configuring Zulu JDK 8 unlimited strength cryptography policy”
Only one binding – Zigbee Binding with its coordinator Thing: ZigBee USB dongle (BV 2010/10) “Bitron Ember EM35x Coordinator”
Only one other Thing – Zigbee light: TRADFRI bulb E27 WS opal 980lm
Default OH2 ports of 8080 and 8443
OH2 docker user and group setup on host and mapped to docker with USER_ID and GROUP_ID as per install instructions
Zigbee usb controller device /dev/ttyUSB0 mapped successfully into Docker container with needed permissions

Repro

Setup openhab docker (I use a docker-compose for consistency and git tracking)
Add zigbee binding
Add Thing for the Zigbee usb controller
Connect power to the Zigbee light (the light should be on and shining)
Add Thing for the Zigbee light. Follow process provided by Ikea and OH2.
Light is successfully added as a Thing.
Collect the two channel IDs for the light: _dimmer and _colortemperature
Create openhab/conf/items/home.items to have some groups and two Dimmer Items; one for each channel. (file is below)
Use the Paper UI or Basic UI (with a quick sitemap) to verify control the light on/off/dimmer/temperature. This should work
Create openhab/conf/rules/home.rules to have rules that triggers on changes to the dimmer Item (not the color temp) and send command to the colortemp Item. My intention here is to make the light warmer as it is dimmer…and colder when it is brighter. (file is below)
Use the Paper UI or Basic UI and change only the brightness. When the brightness is changed, the color temperature of the light is changed by the rule. This should work
Remove power to the Zigbee light for 15 seconds.
Connect power to the Zigbee light.
Use the Paper UI or Basic UI to change only the light brightness.

Result

Light brightness is successfully changed.
Light color temperature is not changed.

Expected

Light brightness is successfully changed and color temperature is changed by the rule as was seen in step 11.

home.items

Group   gHome       "Home"                      <house>                 ["Building"]
Group   gGuestRoom  "Guest Room"                <parents_4_3>   (gHome) ["Room"]
Group   gLightTemp  "Lights with Temp"          <light>         (gHome) ["Lighting", "Switchable"]
Group:Switch:OR(ON, OFF)    gLight  "Lights"    <light>         (gHome) ["Lighting", "Switchable"]

// guest room devices
Dimmer  GuestRoom_Light     "Guest Light"       <light>         (gLight, gLightTemp, gGuestRoom)    ["Lighting"]        {channel="zigbee:device:01382AF5:000b57fffebd00f4:000B57FFFEBD00F4_1_dimmer"}
Dimmer  GuestRoom_LightTemp "Guest Light Temp"  <colorlight>    (gLight, gGuestRoom)                ["ColorLighting"]   {channel="zigbee:device:01382AF5:000b57fffebd00f4:000B57FFFEBD00F4_1_colortemperature"}

home.rules

rule "colortemp Member of"
when
    Member of gLightTemp changed
then
    logWarn("home.rules", "colortemp Memberof rule")
    if (triggeringItem.state == 0) {
        return
    }
    val targetName = triggeringItem.getName().concat("Temp")
    val itemVal = triggeringItem.state as Number
    val int targetVal = itemVal.intValue
    sendCommand(targetName, (100 - targetVal).toString)
end

rule "colortemp Item"
when
    Item GuestRoom_Light changed
then
    logWarn("home.rules", "colortemp Item rule")
end

Investigation with Logs and Console

The only way I can get the rules to work again is to stop and restart OpenHab2. So far I have found no other solution.

I turned on DEBUG for most of the event log categories and openhab/events.log grew by megabytes. I’m unable to discern good/bad things of interest in that bulk of DEBUG level data without experience with OH2. If anyone wants log data beyond the below, please tell me what you want and I’ll get it.

When the logs are at the default initial installation values, I did not see any unusual errors. However, I do see the absence of rules running.

The following log entries are taken by first stopping Openhab2. OH2 is not running.
Also, my Zigbee light is powered on and is physically shining at 99% brightness.

I might think that the issue is the Tradfri light doesn’t send OH2 a state update
after it successfully processes a received command. If that were true,
then the rules would not fire both before and after the light power-cycle.
That doesn’t match the seen behavior.

I might think the Tradfri never sends status updates and OH2 has some internal
code which assumes the Thing state was updated and then updates its internal
Item state. If that was true, then this internal OH2 assumption code
should run both before and after the light power-cycle.
That doesn’t match the seen behavior.

Keep in mind that the rule failures can be fixed by restarting OH2 docker restart openhab. Restarting it begins the scenario again like immediately below 16:04:54. But the rules will fail again if the light is power-cycled. Given the restart fix doesn’t include any change to the physical Tradfri light and the above two toughts, I don’t think the Tradfri is the source of the failure.

2020-08-23 16:04:54

I (re)start openhab2 with docker-compose up -d. Notice that the last ~6 entries of each log show the two rules from home.rules run and successfully use the discovered brightness of 99 to set the colortemp to 1. I don’t see anything unusual and this (to a newbie) is expected behavior.

openhab.log

2020-08-23 16:04:54.591 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
2020-08-23 16:04:54.628 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '52.5123592,13.4592311'.
2020-08-23 16:04:54.630 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en'.
2020-08-23 16:04:57.771 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.items'
2020-08-23 16:04:58.182 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.sitemap'
2020-08-23 16:04:59.702 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-08-23 16:05:00.439 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.rules'
2020-08-23 16:05:01.198 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://172.30.0.2:8080
2020-08-23 16:05:01.199 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://172.30.0.2:8443
2020-08-23 16:05:01.558 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2020-08-23 16:05:01.606 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
2020-08-23 16:05:01.666 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-08-23 16:05:07.678 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 000B57FFFEBD00F4: Starting ZigBee device discovery
2020-08-23 16:05:08.528 [WARN ] [se.smarthome.model.script.home.rules] - colortemp Item rule
2020-08-23 16:05:08.529 [WARN ] [se.smarthome.model.script.home.rules] - colortemp Memberof rule
2020-08-23 16:05:08.530 [WARN ] [se.smarthome.model.script.home.rules] - colortemp Item rule
2020-08-23 16:05:08.532 [WARN ] [se.smarthome.model.script.home.rules] - colortemp Memberof rule
2020-08-23 16:05:08.932 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 000B57FFFEBD00F4: Starting ZigBee device discovery

events.log

2020-08-23 16:05:01.844 [hingStatusInfoChangedEvent] - 'zigbee:device:01382AF5:000b57fffebd00f4' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2020-08-23 16:05:02.031 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:01382AF5' changed from UNINITIALIZED to INITIALIZING
2020-08-23 16:05:02.099 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:01382AF5' changed from INITIALIZING to UNKNOWN
2020-08-23 16:05:02.141 [hingStatusInfoChangedEvent] - 'zigbee:device:01382AF5:000b57fffebd00f4' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2020-08-23 16:05:02.145 [hingStatusInfoChangedEvent] - 'zigbee:device:01382AF5:000b57fffebd00f4' changed from INITIALIZING to UNKNOWN
2020-08-23 16:05:07.695 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_ember:01382AF5' has been updated.
2020-08-23 16:05:07.695 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:01382AF5' changed from UNKNOWN to ONLINE
2020-08-23 16:05:07.701 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:coordinator_ember:01382AF5 changed to UNKNOWN.
2020-08-23 16:05:08.453 [hingStatusInfoChangedEvent] - 'zigbee:device:01382AF5:000b57fffebd00f4' changed from UNKNOWN to ONLINE
2020-08-23 16:05:08.457 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:01382AF5:000b57fffebd00f4 changed to UNKNOWN.
2020-08-23 16:05:08.486 [vent.ItemStateChangedEvent] - GuestRoom_Light changed from NULL to 100
2020-08-23 16:05:08.487 [vent.ItemStateChangedEvent] - GuestRoom_LightTemp changed from NULL to 1
2020-08-23 16:05:08.488 [vent.ItemStateChangedEvent] - GuestRoom_Light changed from 100 to 99
2020-08-23 16:05:08.488 [GroupItemStateChangedEvent] - gLight changed from NULL to ON through GuestRoom_Light
2020-08-23 16:05:08.538 [ome.event.ItemCommandEvent] - Item 'GuestRoom_LightTemp' received command 1
2020-08-23 16:05:08.542 [nt.ItemStatePredictedEvent] - GuestRoom_LightTemp predicted to become 1
2020-08-23 16:05:08.550 [ome.event.ItemCommandEvent] - Item 'GuestRoom_LightTemp' received command 1
2020-08-23 16:05:08.554 [nt.ItemStatePredictedEvent] - GuestRoom_LightTemp predicted to become 1

2020-08-23 16:21:27

I use PaperUI/Control and successfully verify that UI shows my light brightness=99 and temp=1.

I click one time in the middle of the brightness slider and its value is 48%. My light physically decreases its brightness to 48% and it physically becomes warmer in color. The PaperUI slider for temperature now shows 52%. The physical behavior of the light, the PaperUI, and the logs all have expected behavior.

openhab.log

2020-08-23 16:21:27.146 [WARN ] [se.smarthome.model.script.home.rules] - colortemp Item rule
2020-08-23 16:21:27.151 [WARN ] [se.smarthome.model.script.home.rules] - colortemp Memberof rule

events.log

2020-08-23 16:21:26.059 [ome.event.ItemCommandEvent] - Item 'GuestRoom_Light' received command 48
2020-08-23 16:21:27.143 [vent.ItemStateChangedEvent] - GuestRoom_Light changed from 99 to 48
2020-08-23 16:21:27.155 [ome.event.ItemCommandEvent] - Item 'GuestRoom_LightTemp' received command 52
2020-08-23 16:21:27.156 [nt.ItemStatePredictedEvent] - GuestRoom_LightTemp predicted to become 52
2020-08-23 16:21:27.158 [vent.ItemStateChangedEvent] - GuestRoom_LightTemp changed from 1 to 52

2020-08-23 16:29:37

I remove power from the Zigbee light. Naturally, the light is physically not shining.

2020-08-23 16:29:55

18 seconds later, I return power to the Zigbee light. The light physically shines at a mid-level brightness and warmth. (I suspect it is shining at the the previous brightness=48 and color=52.) The light’s physical behavior is expected and the logs don’t have anything unusual (to a newbie).

openhab.log

no new entries

events.log

2020-08-23 16:29:56.966 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_ember:01382AF5' has been updated.
2020-08-23 16:29:59.067 [me.event.ThingUpdatedEvent] - Thing 'zigbee:device:01382AF5:000b57fffebd00f4' has been updated.

2020-08-23 16:40:05

In the PaperUI, I click on the brightness slider approximately 1/4 from the left. The brightness slider reacts and shows 21%. The light physically dimmed lower. Both of these are expected

The light did not physically become warmer.The temperature slider did not change in the PaperUI. The logs have an absence of activity of rules and the color temperature Item. Compare this lack of temperature change and log absence to the good activity above at 16:21:27.

openhab.log

no new entries

events.log

2020-08-23 16:40:08.542 [ome.event.ItemCommandEvent] - Item 'GuestRoom_Light' received command 21

2020-08-23 16:46:24

I again click in the PaperUI; this time on the brightness slider 3/4 from the left. The brightness slider reacts and shows 78%. The light physically became brighter. Both of these are expected

The light did not physically become colder.The temperature slider did not change in the PaperUI. The logs have an absence of activity of rules and the color temperature Item. Compare this lack of temperature change and log absence to the good activity above at 16:21:27.

openhab.log

no new entries

events.log

2020-08-23 16:46:24.905 [ome.event.ItemCommandEvent] - Item 'GuestRoom_Light' received command 78

OH2 Console

I used the OH2 console after the sequence documented in the above logs.

docker exec -it openhab /openhab/runtime/bin/client

openhab> items list
gGuestRoom (Type=GroupItem, Members=2, State=NULL, Label=Guest Room, Category=parents_4_3, Tags=[Room], Groups=[gHome])
gHome (Type=GroupItem, Members=3, State=NULL, Label=Home, Category=house, Tags=[Building])
GuestRoom_Light (Type=DimmerItem, State=48, Label=Guest Light, Category=light, Tags=[Lighting], Groups=[gLight, gLightTemp, gGuestRoom])
GuestRoom_LightTemp (Type=DimmerItem, State=52, Label=Guest Light Temp, Category=colorlight, Tags=[ColorLighting], Groups=[gLight, gGuestRoom])
gLight (Type=GroupItem, BaseType=SwitchItem, Members=2, State=ON, Label=Lights, Category=light, Tags=[Lighting, Switchable], Groups=[gHome])
gLightTemp (Type=GroupItem, Members=1, State=NULL, Label=Lights with Temp, Category=light, Tags=[Lighting, Switchable], Groups=[gHome])
openhab>

Notice the GuestRoom_LightTemp state=52. Its state is not being updated.
Also unusual is the GuestRoom_Light state=48. This is very unusual (to a newbie)
because the light’s physical brightness is successfully changing throughout this sequence.
However, that 48 value is the last known Item state before the physical power off/on at 16:29:37.

Guess at point of failure

Given all the above, I suspect there is some part of OH2/binding that does not recover when the Zigbee light is power-cycled.

OH2 receives the ui/api request to change brightness
Command to change the light is constructed (as seen in the logs)
Command is successfully sent using Zigbee protocol to the light
The light physically changes in response to the command

And then the failure

The internal OH2 state of the light is not changed. This is seen in the console items list output and the absence of a log entry GuestRoom_Light changed from.... While those two seem to be errant behaviors remember that the PaperUI/Control slider did react when I clicked on it.
Since that light’s Item state isn’t changed, it makes sense (to a newbie) that the rule doesn’t run…because from the rule engine’s perspective, the internal OH2 state never changed…therefore the when...changed rules do not run.

So why is the internal OH2 Item state not updated after a power-cycle of the Thing?

rossko57 · August 23, 2020, 4:41pm

You’ll probably be interested in this recent thread -