Openhab3 + cc2531 + zigbee binding - devices offline

lukasg · January 4, 2021, 10:55am

Thank you, Chris!
And sorry, but I am a little bit distressed, because it is working in general, but it is not working as it should all over

I will try to get on to the track of my problem with an network sniffer. Hopefully I will find out something…

hotte37 · January 4, 2021, 10:10pm

Hello chris, this is the problem i already have reported: “Problems with Zigbee binding since Openhab 2.5.10?”

https://community.openhab.org/t/problems-with-zigbee-binding-since-openhab-2-5-10/109574/15?u=hotte37

First all zigbee_routes and neighbours disappear, then the devices go offline after some time. The time depends on the refresh period.
When I restart only OpenHAB (systemctl stop openhab.service and systemctl start openhab.service), the devices are online again. After the Mesh period time the neighbors are filled again.
Even when i disable the CC2531 coordinator and enable it again using the Main UI, the devices are online again.

lukasg · January 5, 2021, 11:10am

Is there the same problem with other coordinaters than the cc2531?

chris · January 5, 2021, 11:20am

I don’t think it is the same issue as you have but even if it is, as I have already said, I don’t think this is a binding issue - the devices do not respond to requests from the binding - I am unable to force them

lukasg · January 5, 2021, 2:37pm

So now I have absolutely no idea what to do.

Feels like it is always a different behaviour.
Now all four Gledopto LED controllers are shown as offline, but I can control the LED stripes (on/off, dimmer). Sometimes the controllers are offline, but I can not control them.

This is a log while the conroller 00124B00222EEFC0 is shown as offline in the “things” section, but I can control the LED stripe:

2021-01-05 15:31:31.826 [WARN ] [o.internal.handler.SysteminfoHandler] - No information for channel sensors#fanSpeed with device index 0 :

2021-01-05 15:32:01.827 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EEFC0: Command for channel zigbee:device:ba1f317aca:00124b00222eefc0:00124B00222EEFC0_11_color --> ON [OnOffType]

2021-01-05 15:32:01.832 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00222EEFC0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B00222EEFC0 queueTime=0, state=WAITING, sendCnt=0, command=OnCommand [On/Off: 0000/0 -> 0661/11, cluster=0006, TID=--]]

2021-01-05 15:32:01.835 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3

2021-01-05 15:32:01.837 [DEBUG] [transaction.ZigBeeTransactionManager] - 0661/11: Sending ZigBeeTransaction [ieeeAddress=00124B00222EEFC0 queueTime=5, state=WAITING, sendCnt=0, command=OnCommand [On/Off: 0000/0 -> 0661/11, cluster=0006, TID=DE]]

2021-01-05 15:32:01.838 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2021-01-05 15:32:01.841 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0000/0 -> 0661/11, cluster=0006, TID=DE]

2021-01-05 15:32:01.842 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=222, commandId=1]

2021-01-05 15:32:01.844 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=0661/11, profile=0104, cluster=0006, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=74, rssi=--, lqi=--, payload=01 DE 01]

2021-01-05 15:32:01.845 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 61 06 0B 01 06 00 74 30 08 03 01 DE 01 D2, checksum=D2, error=false) 

2021-01-05 15:32:01.860 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2021-01-05 15:32:01.862 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DE state=TX_ACK

2021-01-05 15:32:01.864 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DE, state=TX_ACK, outstanding=1

2021-01-05 15:32:01.866 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0661, TID=DE, event=TX_ACK, state=TRANSMITTED

2021-01-05 15:32:01.884 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 C4 61 06 00 E5)

2021-01-05 15:32:01.885 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=45 C4, data=FE 03 45 C4 61 06 00 E5, checksum=E5, error=false

2021-01-05 15:32:01.887 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c4

2021-01-05 15:32:01.904 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 00 01 74 B2)

2021-01-05 15:32:01.906 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=SUCCESS(0), TransID=116)

2021-01-05 15:32:01.907 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DE state=RX_ACK

2021-01-05 15:32:01.908 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DE, state=RX_ACK, outstanding=1

2021-01-05 15:32:01.909 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 C4 61 06 00 E5)

2021-01-05 15:32:01.909 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0661, TID=DE, event=RX_ACK, state=ACKED

2021-01-05 15:32:01.912 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=45 C4, data=FE 03 45 C4 61 06 00 E5, checksum=E5, error=false

2021-01-05 15:32:01.914 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c4

2021-01-05 15:32:01.925 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_INCOMING_MSG (FE 19 44 81 00 00 06 00 61 06 0B 01 00 17 00 5F 74 B4 00 00 05 18 DE 0B 01 00 61 06 1D 8C)

2021-01-05 15:32:01.927 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=25, apiId=44 81, data=FE 19 44 81 00 00 06 00 61 06 0B 01 00 17 00 5F 74 B4 00 00 05 18 DE 0B 01 00 61 06 1D 8C, checksum=8C, error=false

2021-01-05 15:32:01.928 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4481

2021-01-05 15:32:01.930 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0661/11, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=18 DE 0B 01 00]

2021-01-05 15:32:01.931 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=222, commandId=11]

2021-01-05 15:32:01.933 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 0661/11 -> 0000/1, cluster=0006, TID=DE, commandIdentifier=1, statusCode=SUCCESS]

2021-01-05 15:32:01.935 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [On/Off: 0661/11 -> 0000/1, cluster=0006, TID=DE, commandIdentifier=1, statusCode=SUCCESS] 

2021-01-05 15:32:01.937 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B00222EEFC0 queueTime=105, state=COMPLETE, sendCnt=1, command=OnCommand [On/Off: 0000/0 -> 0661/11, cluster=0006, TID=DE]]

2021-01-05 15:32:01.940 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2021-01-05 15:32:01.942 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00222EEFC0: transactionComplete, state=COMPLETE, outstanding=0

2021-01-05 15:32:01.944 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3

2021-01-05 15:32:10.034 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EEFC0: Command for channel zigbee:device:ba1f317aca:00124b00222eefc0:00124B00222EEFC0_11_color --> OFF [OnOffType]

2021-01-05 15:32:10.037 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00222EEFC0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B00222EEFC0 queueTime=0, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0000/0 -> 0661/11, cluster=0006, TID=--]]

2021-01-05 15:32:10.039 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3

2021-01-05 15:32:10.041 [DEBUG] [transaction.ZigBeeTransactionManager] - 0661/11: Sending ZigBeeTransaction [ieeeAddress=00124B00222EEFC0 queueTime=3, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0000/0 -> 0661/11, cluster=0006, TID=DF]]

2021-01-05 15:32:10.042 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2021-01-05 15:32:10.044 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0000/0 -> 0661/11, cluster=0006, TID=DF]

2021-01-05 15:32:10.046 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=223, commandId=0]

2021-01-05 15:32:10.048 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=0661/11, profile=0104, cluster=0006, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=75, rssi=--, lqi=--, payload=01 DF 00]

2021-01-05 15:32:10.050 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 61 06 0B 01 06 00 75 30 08 03 01 DF 00 D3, checksum=D3, error=false) 

2021-01-05 15:32:10.064 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2021-01-05 15:32:10.066 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DF state=TX_ACK

2021-01-05 15:32:10.067 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DF, state=TX_ACK, outstanding=1

2021-01-05 15:32:10.069 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0661, TID=DF, event=TX_ACK, state=TRANSMITTED

2021-01-05 15:32:10.089 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 C4 61 06 00 E5)

2021-01-05 15:32:10.091 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=45 C4, data=FE 03 45 C4 61 06 00 E5, checksum=E5, error=false

2021-01-05 15:32:10.092 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c4

2021-01-05 15:32:10.109 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 00 01 75 B3)

2021-01-05 15:32:10.112 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=SUCCESS(0), TransID=117)

2021-01-05 15:32:10.113 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DF state=RX_ACK

2021-01-05 15:32:10.115 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DF, state=RX_ACK, outstanding=1

2021-01-05 15:32:10.116 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0661, TID=DF, event=RX_ACK, state=ACKED

2021-01-05 15:32:10.116 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 C4 61 06 00 E5)

2021-01-05 15:32:10.118 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=45 C4, data=FE 03 45 C4 61 06 00 E5, checksum=E5, error=false

2021-01-05 15:32:10.119 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c4

2021-01-05 15:32:10.130 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_INCOMING_MSG (FE 19 44 81 00 00 06 00 61 06 0B 01 00 1A 00 8A D8 B4 00 00 05 18 DF 0B 00 00 61 06 1D F8)

2021-01-05 15:32:10.132 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=25, apiId=44 81, data=FE 19 44 81 00 00 06 00 61 06 0B 01 00 1A 00 8A D8 B4 00 00 05 18 DF 0B 00 00 61 06 1D F8, checksum=F8, error=false

2021-01-05 15:32:10.133 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4481

2021-01-05 15:32:10.135 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0661/11, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=18 DF 0B 00 00]

2021-01-05 15:32:10.136 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=223, commandId=11]

2021-01-05 15:32:10.138 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 0661/11 -> 0000/1, cluster=0006, TID=DF, commandIdentifier=0, statusCode=SUCCESS]

2021-01-05 15:32:10.140 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [On/Off: 0661/11 -> 0000/1, cluster=0006, TID=DF, commandIdentifier=0, statusCode=SUCCESS] 

2021-01-05 15:32:10.142 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B00222EEFC0 queueTime=104, state=COMPLETE, sendCnt=1, command=OffCommand [On/Off: 0000/0 -> 0661/11, cluster=0006, TID=DF]]

2021-01-05 15:32:10.144 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2021-01-05 15:32:10.145 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00222EEFC0: transactionComplete, state=COMPLETE, outstanding=0

2021-01-05 15:32:10.147 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3

2021-01-05 15:32:31.857 [WARN ] [o.internal.handler.SysteminfoHandler] - No information for channel sensors#fanSpeed with device index 0 :

2021-01-05 15:33:31.887 [WARN ] [o.internal.handler.SysteminfoHandler] - No information for channel sensors#fanSpeed with device index 0 :

2021-01-05 15:34:31.919 [WARN ] [o.internal.handler.SysteminfoHandler] - No information for channel sensors#fanSpeed with device index 0 :

lukasg · January 14, 2021, 7:50am

Hello again,

after updating the “Mesh update period” of the CC2531EMK Coordinator-Thing to one week, there are no problems controlling my Zigbee-devices.
The Gledopto-controllers are shown as “offline”, but everything is working by now for 8630min (uptime of my RaspberryPi)

I will not change something. Never change a running system .

Thank you very much!

Greetings, Lukas

StefanH · February 23, 2021, 6:38pm

Hi,

can you provide more details. So, you changed the mesh update period AND still devices are shown as offline?

I’m testing an Ember Coordinator and see my 2 Routers and 1 End Devices being offline after the timeout of 1830s has reached (no clue where this value is defined). However, the sensor works fine.

During my tests with zigbee2mqtt I could see that the routers (CC2530+CC2591 with koenkk firmware) send data about every minute and my end device (a Xiaomi Door Window Sensor) about every hour.
This is what I see in the logs:

2021-02-23 19:04:59.547 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:3a4f49d56f:00158d0003121b0b' changed from OFFLINE to ONLINE
2021-02-23 19:04:59.549 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:3a4f49d56f:00158d0003121b0b in 1830 seconds
2021-02-23 19:20:34.988 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0003121B0B: Polling [zigbee:device:3a4f49d56f:00158d0003121b0b:00158D0003121B0B_1_switch] channels...
2021-02-23 19:35:29.553 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:3a4f49d56f:00158d0003121b0b
2021-02-23 19:35:29.558 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0003121B0B: Polling stopped
2021-02-23 19:35:29.563 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0003121B0B: Polling initialised at 1871140ms
2021-02-23 19:35:59.567 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:3a4f49d56f:00158d0003121b0b
2021-02-23 19:35:59.573 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:3a4f49d56f:00158d0003121b0b' changed from ONLINE to OFFLINE

Eagle1887 · March 13, 2021, 1:32pm

For those who may be usefull, check my post in a similar discussion regarding oh and cc2531 stick

[https://community.openhab.org/t/problems-with-zigbee-binding-since-openhab-2-5-10/109574/22?u=eagle1887](Problems with Zigbee binding since Openhab 2.5.10? - #22 by Eagle1887)

fuslwusl · November 9, 2021, 1:17pm

I have exactly the same problem. Since openHAB 2.5.12 my zigbee devices go offline after 1 or 2 days. Using SMaBiT (Bitron Video ZigBee USB Stick). With openHAB 2.5.10 it worked fine. Can anybody provide me the 2.5.10 zigbee jar files?