Command execution delay/failing
Closed this issue · 11 comments
Outline
I upgraded my openhab installation to 2.5 stable release recently, and I noticed a delay in executing the command for some switches I have. These same switches used to work without any problem before on 2.5M2 release.
One thing I noticed that might be related is, when I downgrade the ZSS dependency to version 1.2.1 on 2.5.0 stable installation, the problem disappeared, and when using 1.2.3 it comes back again. Not sure about 1.2.2
Configuration
Configuration | Description |
---|---|
Coordinator used | cc2531 |
openHAB version | 2.5.0M2 --> 2.5.0 Sable |
Hardware | Linux Device |
Memory | 2GB |
Java version | Java 8 |
Devices | 1 Way ON/OFF switch, the log is filtered for this specific device (000B57FFFEA1FBF2) |
Logs
The log is filtered to one device with this behavior (although I have multiple switches with the same behavior and some without each from a different brand), and shows the following operations.
1- I switched the device off, and it responded instantly
2- I switched it back on and it got the dealy I am describing
2019-12-24 08:20:42.749 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - Item 'zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch' received command OFF
2019-12-24 08:20:42.767 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch predicted to become OFF
2019-12-24 08:20:42.769 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch updated to OFF
2019-12-24 08:20:42.783 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch changed from ON to OFF
2019-12-24 08:20:42.788 [FINE ] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler handleCommand] - 000B57FFFEA1FBF2: Command for channel zigbee:device:39c27c24:000b57fffea1fbf2:000B57FFFEA1FBF2_16_switch --> OFF [OnOffType]
2019-12-24 08:20:42.792 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue addToQueue] - 000B57FFFEA1FBF2: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0/0 -> 26753/16, cluster=0006, TID=--]]
2019-12-24 08:20:42.915 [FINE ] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchOnoff attributeUpdated] - 000B57FFFEA1FBF2: ZigBee attribute reports ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclOnOffCluster@1a13d7c, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Tue Dec 24 08:20:42 GMT 2019]
2019-12-24 08:20:42.917 [FINE ] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter updateChannelState] - 000B57FFFEA1FBF2: Channel zigbee:device:39c27c24:000b57fffea1fbf2:000B57FFFEA1FBF2_16_switch updated to OFF
2019-12-24 08:20:42.920 [FINE ] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler setChannelState] - 000B57FFFEA1FBF2: Updating ZigBee channel state zigbee:device:39c27c24:000b57fffea1fbf2:000B57FFFEA1FBF2_16_switch to OFF
2019-12-24 08:20:42.925 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch updated to OFF
2019-12-24 08:20:42.955 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue addToQueue] - 000B57FFFEA1FBF2: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=DefaultResponse [On/Off: 0/0 -> 26753/16, cluster=0006, TID=F7, commandIdentifier=11, statusCode=UNSUP_GENERAL_COMMAND]]
2019-12-24 08:20:42.960 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete COMPLETE 1
2019-12-24 08:20:42.980 [FINE ] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchOnoff attributeUpdated] - 000B57FFFEA1FBF2: ZigBee attribute reports ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclOnOffCluster@1a13d7c, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Tue Dec 24 08:20:42 GMT 2019]
2019-12-24 08:20:42.982 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue addToQueue] - 000B57FFFEA1FBF2: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=DefaultResponse [On/Off: 0/0 -> 26753/16, cluster=0006, TID=1A, commandIdentifier=10, statusCode=SUCCESS]]
2019-12-24 08:20:42.983 [FINE ] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter updateChannelState] - 000B57FFFEA1FBF2: Channel zigbee:device:39c27c24:000b57fffea1fbf2:000B57FFFEA1FBF2_16_switch updated to OFF
2019-12-24 08:20:42.986 [FINE ] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler setChannelState] - 000B57FFFEA1FBF2: Updating ZigBee channel state zigbee:device:39c27c24:000b57fffea1fbf2:000B57FFFEA1FBF2_16_switch to OFF
2019-12-24 08:20:42.990 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch updated to OFF
2019-12-24 08:20:50.050 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - Item 'zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch' received command ON
2019-12-24 08:20:50.067 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch predicted to become ON
2019-12-24 08:20:50.069 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch updated to ON
2019-12-24 08:20:50.083 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch changed from OFF to ON
2019-12-24 08:20:50.092 [FINE ] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler handleCommand] - 000B57FFFEA1FBF2: Command for channel zigbee:device:39c27c24:000b57fffea1fbf2:000B57FFFEA1FBF2_16_switch --> ON [OnOffType]
2019-12-24 08:20:50.095 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue addToQueue] - 000B57FFFEA1FBF2: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=OnCommand [On/Off: 0/0 -> 26753/16, cluster=0006, TID=--]]
2019-12-24 08:20:52.803 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete FAILED 1
2019-12-24 08:20:52.805 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete exceeded retries 2
2019-12-24 08:20:52.970 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete FAILED 1
2019-12-24 08:20:52.972 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue addToQueue] - 000B57FFFEA1FBF2: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=10017, state=WAITING, sendCnt=1, command=DefaultResponse [On/Off: 0/0 -> 26753/16, cluster=0006, TID=F7, commandIdentifier=11, statusCode=UNSUP_GENERAL_COMMAND]]
2019-12-24 08:21:02.818 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete FAILED 1
2019-12-24 08:21:02.820 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue addToQueue] - 000B57FFFEA1FBF2: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=19838, state=WAITING, sendCnt=1, command=DefaultResponse [On/Off: 0/0 -> 26753/16, cluster=0006, TID=1A, commandIdentifier=10, statusCode=SUCCESS]]
2019-12-24 08:21:02.981 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete FAILED 1
2019-12-24 08:21:02.983 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete exceeded retries 2
2019-12-24 08:21:03.066 [FINE ] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchOnoff attributeUpdated] - 000B57FFFEA1FBF2: ZigBee attribute reports ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclOnOffCluster@1a13d7c, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Dec 24 08:21:03 GMT 2019]
2019-12-24 08:21:03.069 [FINE ] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter updateChannelState] - 000B57FFFEA1FBF2: Channel zigbee:device:39c27c24:000b57fffea1fbf2:000B57FFFEA1FBF2_16_switch updated to ON
2019-12-24 08:21:03.071 [FINE ] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler setChannelState] - 000B57FFFEA1FBF2: Updating ZigBee channel state zigbee:device:39c27c24:000b57fffea1fbf2:000B57FFFEA1FBF2_16_switch to ON
2019-12-24 08:21:03.075 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch updated to ON
2019-12-24 08:21:03.104 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue addToQueue] - 000B57FFFEA1FBF2: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=DefaultResponse [On/Off: 0/0 -> 26753/16, cluster=0006, TID=F8, commandIdentifier=11, statusCode=UNSUP_GENERAL_COMMAND]]
2019-12-24 08:21:03.108 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete COMPLETE 1
2019-12-24 08:21:03.127 [FINE ] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchOnoff attributeUpdated] - 000B57FFFEA1FBF2: ZigBee attribute reports ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclOnOffCluster@1a13d7c, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Dec 24 08:21:03 GMT 2019]
2019-12-24 08:21:03.130 [FINE ] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter updateChannelState] - 000B57FFFEA1FBF2: Channel zigbee:device:39c27c24:000b57fffea1fbf2:000B57FFFEA1FBF2_16_switch updated to ON
2019-12-24 08:21:03.131 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue addToQueue] - 000B57FFFEA1FBF2: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=DefaultResponse [On/Off: 0/0 -> 26753/16, cluster=0006, TID=1C, commandIdentifier=10, statusCode=SUCCESS]]
2019-12-24 08:21:03.132 [FINE ] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler setChannelState] - 000B57FFFEA1FBF2: Updating ZigBee channel state zigbee:device:39c27c24:000b57fffea1fbf2:000B57FFFEA1FBF2_16_switch to ON
2019-12-24 08:21:03.135 [INFO ] [org.eclipse.smarthome.io.monitor.internal.EventLogger receive] - zigbee_device_39c27c24_000b57fffea1fbf2_000B57FFFEA1FBF2_16_switch updated to ON
2019-12-24 08:21:12.831 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete FAILED 1
2019-12-24 08:21:12.832 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete exceeded retries 2
2019-12-24 08:21:13.118 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue transactionComplete] - 000B57FFFEA1FBF2: transactionComplete FAILED 1
2019-12-24 08:21:13.120 [FINE ] [com.zsmartsystems.zigbee.transaction.ZigBeeTransactionQueue addToQueue] - 000B57FFFEA1FBF2: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10016, state=WAITING, sendCnt=1, command=DefaultResponse [On/Off: 0/0 -> 26753/16, cluster=0006, TID=F8, commandIdentifier=11, statusCode=UNSUP_GENERAL_COMMAND]]
Please provide the detailed debug log as per the binding documentation. I've reformatted your text so it's readable.
Hi @cdjackson
It is the debug log as per the documentation, but I filtered it to a single device since I have many, and I showed exactly 2 operations. Do you need to look at the full log without filtering?
Yes, please don't filter logs - there is nothing here that shows what is happening. There's nothing from the TI driver and in all it's very limited as it doesn't show any commands being sent or received.
I attached the log file since it is a bit long. You can see from the log that:
The switch 00158D00022AE9A1 is working properly,
The switch 000B57FFFEA1FBF2 has the delay problem
I would like to mention that I tried the 1.2.2 ZSS version and it is working properly, it looks like something introduced in 1.2.3 that caused this problem. Should I try a later version?
I don't fundamentally see anything wrong. There are some issues that are fixed in the updated version so I suggest that we take another look then.
The log that I noticed is the following:
000B57FFFEA1FBF2: transactionComplete exceeded retries 2
000B57FFFEA1FBF2: transactionComplete FAILED 1
000B57FFFEA1FBF2: Added transaction to queue,
This only shows when I notice a delay happens, and it seems it is always around 10 sec
I've not updated the binding yet, so let's wait till this is completed.
Sure, I am running ZSS 1.2.2 now and so far no problems.
Closing this as it's stale. If the issue still exists on the latest binding then please provide further information