Command execution delay/failing
Closed this issue · 11 comments
falmanna commented
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]]
cdjackson commented
Please provide the detailed debug log as per the binding documentation. I've reformatted your text so it's readable.
falmanna commented
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?
cdjackson commented
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.
falmanna commented
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?
cdjackson commented
You cannot use a later version of the library - please do not try as the binding will stop working. I will update the binding over the next few days to allow it to work with the latest version.
… On 24 Dec 2019, at 15:40, Feras Almannaa ***@***.***> wrote:
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
smarthome-0.log <https://github.com/openhab/org.openhab.binding.zigbee/files/3998654/smarthome-0.log>
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?
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub <#533?email_source=notifications&email_token=AAH6IQ2RK3RQRZUMLKKSF5DQ2IUONA5CNFSM4J64WRKKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEHTLP4Y#issuecomment-568768499>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAH6IQ65R2DU2THJMTZO4ELQ2IUONANCNFSM4J64WRKA>.
cdjackson commented
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.
falmanna commented
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
cdjackson commented
I've not updated the binding yet, so let's wait till this is completed.
falmanna commented
Sure, I am running ZSS 1.2.2 now and so far no problems.
cdjackson commented
But that’s very old and is totally meaningless now. Sorry, but as I said, we need to wait until the latest version is in use.
… On 26 Dec 2019, at 12:47, Feras Almannaa ***@***.***> wrote:
Sure, I am running ZSS 1.2.2 now and so far no problems.
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub <#533?email_source=notifications&email_token=AAH6IQ54G24RSOG6NJKINALQ2SRXLA5CNFSM4J64WRKKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEHVQ5XQ#issuecomment-569052894>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAH6IQ2QK2DAJZO6Y2SLZBLQ2SRXLANCNFSM4J64WRKA>.
cdjackson commented
Closing this as it's stale. If the issue still exists on the latest binding then please provide further information