Zigbee Telegesis stops working

Tags: #<Tag:0x00007f2fb1427650>

I have a Zigbee network with a lot (around 50 I think atm) IKEA bulbs / remotes and one Aqara Thermometer paired to a Telegesis USB stick running OpenHAB 2.5.0.M3 on a NUC. It runs fine, when it runs, but often (eg every 2-12h) just stops and goes OFFLINE (Communication Error). I have no idea why. When I restart OH (not boot the machine) it starts working again. I tried stop / starting the zigbee bundle and the telegesis bundle, but that did not help. The log when it happens looks like this:

2019-09-12 10:51:06.745 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:CD,833D,0123
2019-09-12 10:51:06.746 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:833D,0104,01,01,0008,07:b
 0,-48,FF
2019-09-12 10:51:06.746 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=33597, profileId=260, destinationEp=1, sourceEp=1, clusterId=8, messageData=08 62 0A 00 00 20 30, rssi=-72, lqi=255]
2019-09-12 10:51:06.950 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:02,000B57FFFEA59CE7,1490,034C,E2CE
2019-09-12 10:51:06.950 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisRouteRecordMessageEvent [hops=2, remoteAddress=000B57FFFEA59CE7, networkRoute=[5264, 844, 58062]]
2019-09-12 10:51:06.951 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:1490,0104,01,01,0008,07:$
 0,-48,FE
2019-09-12 10:51:06.951 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=5264, profileId=260, destinationEp=1, sourceEp=1, clusterId=8, messageData=08 24 0A 00 00 20 30, rssi=-72, lqi=254]
2019-09-12 10:51:07.159 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:NACK:DD
2019-09-12 10:51:07.159 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisNackMessageEvent [messageId=221]
2019-09-12 10:51:07.377 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:01,000B57FFFEA3BD9C,9864,E2CE
2019-09-12 10:51:07.377 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=000B57FFFEA3BD9C, networkRoute=[39012, 58062]]
2019-09-12 10:51:07.378 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:9864,0104,01,01,0008,07:+
 0,-49,FF
2019-09-12 10:51:07.378 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=39012, profileId=260, destinationEp=1, sourceEp=1, clusterId=8, messageData=08 2B 0A 00 00 20 30, rssi=-73, lqi=255]
2019-09-12 10:51:07.997 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:00,90FD9FFFFE2AC0E3,E2CE
2019-09-12 10:51:07.997 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisRouteRecordMessageEvent [hops=0, remoteAddress=90FD9FFFFE2AC0E3, networkRoute=[58062]]
2019-09-12 10:51:07.997 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:E2CE,0104,01,01,0008,07:>
 0,-49,FF
2019-09-12 10:51:07.998 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=58062, profileId=260, destinationEp=1, sourceEp=1, clusterId=8, messageData=08 3E 0A 00 00 20 30, rssi=-73, lqi=255]
2019-09-12 10:51:08.028 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2019-09-12 10:51:08.888 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=190221, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Power Configuration: 0/0 -> 30298/1, cluster=0001, TID=74, identifiers=[33]]]
2019-09-12 10:51:08.889 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 8 outstanding
2019-09-12 10:51:08.889 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE187C08: transactionComplete FAILED 0
2019-09-12 10:51:08.889 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE187C08: transactionComplete exceeded retries 2
2019-09-12 10:51:08.889 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=190222, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Power Configuration: 0/0 -> 30298/1, cluster=0001, TID=74, identifiers=[33]]]
2019-09-12 10:51:08.889 [DEBUG] [transaction.ZigBeeTransactionManager] - 30298/0: Sending ZigBeeTransaction [queueTime=8658, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 30298/0, cluster=0031, TID=8C, startIndex=0]]
2019-09-12 10:51:08.889 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 9 outstanding
2019-09-12 10:51:08.889 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 30298/0, cluster=0031, TID=8C, startIndex=0]
2019-09-12 10:51:08.889 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=30298/0, profile=0000, cluster=0031, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=FB, payload=00 00]
2019-09-12 10:51:08.890 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=30298, sourceEp=0, destEp=0, profileId=0, clusterId=49, messageData=00 00, messageId=null]
2019-09-12 10:51:09.220 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TELEGESIS Timer: Timeout 2
2019-09-12 10:51:09.220 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager transport state updated to OFFLINE
2019-09-12 10:51:09.221 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to OFFLINE
2019-09-12 10:51:09.221 [DEBUG] [gesis.internal.TelegesisFrameHandler] - Error: number of retries exceeded [3].
2019-09-12 10:51:09.264 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:NACK:E6
2019-09-12 10:51:09.264 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisNackMessageEvent [messageId=230]
2019-09-12 10:51:09.306 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=579733, state=COMPLETE, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=78, ieeeAddr=000B57FFFE993511, requestType=0, startIndex=0]]
2019-09-12 10:51:09.307 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 8 outstanding
2019-09-12 10:51:09.307 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 2
2019-09-12 10:51:09.307 [DEBUG] [transaction.ZigBeeTransactionManager] - 65535/0: Sending ZigBeeTransaction [queueTime=568807, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=8D, ieeeAddr=000B57FFFEBAC349, requestType=0, startIndex=0]]
2019-09-12 10:51:09.308 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 9 outstanding
2019-09-12 10:51:09.308 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=8D, ieeeAddr=000B57FFFEBAC349, requestType=0, startIndex=0]
2019-09-12 10:51:09.308 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65535/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=FC, payload=00 49 C3 BA FE FF 57 0B 00 00 00]
2019-09-12 10:51:09.309 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendMulticastCommand [radius=31, address=65535, sourceEp=0, destEp=0, profileId=0, clusterId=0, messageData=00 49 C3 BA FE FF 57 0B 00 00 00]
2019-09-12 10:51:09.936 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=8369, state=FAILED, sendCnt=1, command=NodeDescriptorRequest [0/0 -> 63550/0, cluster=0002, TID=7B, nwkAddrOfInterest=63550]]
2019-09-12 10:51:09.937 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 8 outstanding
2019-09-12 10:51:09.937 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE1A561E: transactionComplete FAILED 0
2019-09-12 10:51:09.937 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE1A561E: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=8370, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0/0 -> 63550/0, cluster=0002, TID=7B, nwkAddrOfInterest=63550]]
2019-09-12 10:51:10.225 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager shutdown: networkState=OFFLINE
2019-09-12 10:51:10.226 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to SHUTDOWN
2019-09-12 10:51:10.226 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - Network discovery task: shutdown
2019-09-12 10:51:10.227 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEA6BE7B: Node SVC Discovery: stopped
2019-09-12 10:51:10.227 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B3CFFFEF79681: Node SVC Discovery: stopped
2019-09-12 10:51:10.227 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEA6B222: Node SVC Discovery: stopped

or like this:

2019-09-12 07:22:35.518 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=29982/1, destinationAddress=0/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=08 45 0A 00 00 10 00]
2019-09-12 07:22:35.518 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=69, commandId=10]
2019-09-12 07:22:35.518 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 29982/1 -> 0/1, cluster=0006, TID=45, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
2019-09-12 07:22:35.519 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [On/Off: 29982/1 -> 0/1, cluster=0006, TID=45, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]] 
2019-09-12 07:22:35.645 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:B
2019-09-12 07:22:35.645 [DEBUG] [gesis.internal.TelegesisEventFactory] - Error creating instance of Telegesis event
java.lang.NullPointerException: null
2019-09-12 07:22:35.646 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX
2019-09-12 07:22:35.646 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=null, profileId=null, destinationEp=null, sourceEp=null, clusterId=null, messageData=null, rssi=null, lqi=null]
2019-09-12 07:22:35.646 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:01,000B57FFFE9A1310,293A
2019-09-12 07:22:35.646 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=000B57FFFE9A1310, networkRoute=[10554]]
2019-09-12 07:22:35.647 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:A52A,0104,01,0
2019-09-12 07:22:35.647 [DEBUG] [gesis.internal.TelegesisEventFactory] - Error creating instance of Telegesis event
java.lang.NullPointerException: null
2019-09-12 07:22:35.647 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=000B57FFFE9A1310, networkRoute=[10554]]
2019-09-12 07:22:35.647 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:02,000B57FFFE
2019-09-12 07:22:35.647 [DEBUG] [gesis.internal.TelegesisEventFactory] - Error creating instance of Telegesis event
java.lang.ArrayIndexOutOfBoundsException: null
2019-09-12 07:22:35.648 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:01,000B57FFFEA3BD9C,9864,0123
2019-09-12 07:22:35.648 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=000B57FFFEA3BD9C, networkRoute=[39012, 291]]
2019-09-12 07:22:35.648 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:2
2019-09-12 07:22:35.649 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=000B57FFFEA3BD9C, networkRoute=[39012, 291]]
2019-09-12 07:22:35.649 [DEBUG] [gesis.internal.TelegesisEventFactory] - Error creating instance of Telegesis event
java.lang.NullPointerException: null
2019-09-12 07:22:35.649 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:034
2019-09-12 07:22:35.649 [DEBUG] [gesis.internal.TelegesisEventFactory] - Error creating instance of Telegesis event
java.lang.NumberFormatException: For input string: "034"
	at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) ~[?:?]
	at java.lang.Integer.parseInt(Integer.java:580) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.telegesis.internal.protocol.TelegesisFrame.deserializeInt16(TelegesisFrame.java:198) ~[219:com.zsmartsystems.zigbee.dongle.telegesis:1.2.1]
	at com.zsmartsystems.zigbee.dongle.telegesis.internal.protocol.TelegesisReceiveMessageEvent.deserialize(TelegesisReceiveMessageEvent.java:161) ~[219:com.zsmartsystems.zigbee.dongle.telegesis:1.2.1]
	at com.zsmartsystems.zigbee.dongle.telegesis.internal.TelegesisEventFactory.getTelegesisFrame(TelegesisEventFactory.java:90) [219:com.zsmartsystems.zigbee.dongle.telegesis:1.2.1]
	at com.zsmartsystems.zigbee.dongle.telegesis.internal.TelegesisFrameHandler$1.run(TelegesisFrameHandler.java:185) [219:com.zsmartsystems.zigbee.dongle.telegesis:1.2.1]
2019-09-12 07:22:35.650 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:01,000B57FFFEA6852C,A1A8,0123
2019-09-12 07:22:35.650 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=000B57FFFEA6852C, networkRoute=[41384, 291]]
2019-09-12 07:22:35.650 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=000B57FFFEA6852C, networkRoute=[41384, 291]]
2019-09-12 07:22:35.650 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:4870,0104,01,01,0006,07:M
,
2019-09-12 07:22:35.650 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=18544, profileId=260, destinationEp=1, sourceEp=1, clusterId=6, messageData=08 4D 0A 00 00 10 00, rssi=null, lqi=null]
2019-09-12 07:22:35.651 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:01,000B57FFFEA6
2019-09-12 07:22:35.651 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=18544/1, destinationAddress=0/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=08 4D 0A 00 00 10 00]
2019-09-12 07:22:35.651 [DEBUG] [gesis.internal.TelegesisEventFactory] - Error creating instance of Telegesis event
java.lang.ArrayIndexOutOfBoundsException: null
2019-09-12 07:22:35.651 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=77, commandId=10]
2019-09-12 07:22:35.651 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:00,000B57FFFE
2019-09-12 07:22:35.651 [DEBUG] [gesis.internal.TelegesisEventFactory] - Error creating instance of Telegesis event
java.lang.ArrayIndexOutOfBoundsException: null
2019-09-12 07:22:35.651 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 18544/1 -> 0/1, cluster=0006, TID=4D, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
2019-09-12 07:22:35.652 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:9
2019-09-12 07:22:35.652 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [On/Off: 18544/1 -> 0/1, cluster=0006, TID=4D, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]] 
2019-09-12 07:22:35.652 [DEBUG] [gesis.internal.TelegesisEventFactory] - Error creating instance of Telegesis event
java.lang.NullPointerException: null
2019-09-12 07:22:35.809 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:A1A8,0104,01,01,0006,07:]


2019-09-12 07:22:35.809 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=41384, profileId=260, destinationEp=1, sourceEp=1, clusterId=6, messageData=08 5D 0A 00 00 0D 0D, rssi=null, lqi=null]
2019-09-12 07:22:35.810 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:833D,0104,
2019-09-12 07:22:35.810 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=41384/1, destinationAddress=0/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=08 5D 0A 00 00 0D 0D]
2019-09-12 07:22:35.810 [DEBUG] [gesis.internal.TelegesisEventFactory] - Error creating instance of Telegesis event
java.lang.NullPointerException: null
2019-09-12 07:22:35.810 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=93, commandId=10]
2019-09-12 07:22:35.810 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:01
2019-09-12 07:22:35.810 [DEBUG] [gesis.internal.TelegesisEventFactory] - Error creating instance of Telegesis event
java.lang.NullPointerException: null
2019-09-12 07:22:35.811 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:1490,0104,01,01,0006,07:a
SR:01,000B57FFFEA7DA8B,161F,A52A
2019-09-12 07:22:35.812 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=5264, profileId=260, destinationEp=1, sourceEp=1, clusterId=6, messageData=08 07 00 0D 0A 53 52, rssi=1, lqi=0]
2019-09-12 07:22:35.812 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:00,000B57FFFED7D5FD,E568
2019-09-12 07:22:35.812 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=5264/1, destinationAddress=0/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=08 07 00 0D 0A 53 52]
2019-09-12 07:22:35.812 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisRouteRecordMessageEvent [hops=0, remoteAddress=000B57FFFED7D5FD, networkRoute=[58728]]
2019-09-12 07:22:35.812 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=7, commandId=0]
2019-09-12 07:22:35.813 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:161F,0104,01,01,0006,07:^
,-46,FF
2019-09-12 07:22:35.813 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=5663, profileId=260, destinationEp=1, sourceEp=1, clusterId=6, messageData=08 5E 0A 00 00 10 00, rssi=-70, lqi=255]
2019-09-12 07:22:35.813 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesCommand [On/Off: 5264/1 -> 0/1, cluster=0006, TID=07, identifiers=[13, 10]]
2019-09-12 07:22:35.813 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesCommand [On/Off: 5264/1 -> 0/1, cluster=0006, TID=07, identifiers=[13, 10]] 
2019-09-12 07:22:35.813 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:E568,0104,01,01,0006,07:M
,-47,FF
2019-09-12 07:22:35.813 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=58728, profileId=260, destinationEp=1, sourceEp=1, clusterId=6, messageData=08 4D 0A 00 00 10 00, rssi=-71, lqi=255]
2019-09-12 07:22:35.814 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:01,90FD9FFFFE2AC0E3,E2CE,0123
2019-09-12 07:22:35.814 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=90FD9FFFFE2AC0E3, networkRoute=[58062, 291]]
2019-09-12 07:22:35.814 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisRouteRecordMessageEvent [hops=0, remoteAddress=000B57FFFED7D5FD, networkRoute=[58728]]
2019-09-12 07:22:35.814 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:E2CE,0104,01,01,0006,07:!
,-43,FF
2019-09-12 07:22:35.814 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=5663/1, destinationAddress=0/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=08 5E 0A 00 00 10 00]
2019-09-12 07:22:35.814 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=58062, profileId=260, destinationEp=1, sourceEp=1, clusterId=6, messageData=08 21 0A 00 00 10 00, rssi=-67, lqi=255]
2019-09-12 07:22:35.814 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=94, commandId=10]
2019-09-12 07:22:35.814 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 5663/1 -> 0/1, cluster=0006, TID=5E, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
2019-09-12 07:22:35.814 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [On/Off: 5663/1 -> 0/1, cluster=0006, TID=5E, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]] 
2019-09-12 07:22:35.815 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=58728/1, destinationAddress=0/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=08 4D 0A 00 00 10 00]
2019-09-12 07:22:35.815 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=77, commandId=10]
2019-09-12 07:22:35.815 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 58728/1 -> 0/1, cluster=0006, TID=4D, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
2019-09-12 07:22:35.815 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [On/Off: 58728/1 -> 0/1, cluster=0006, TID=4D, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]] 
2019-09-12 07:22:35.815 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=90FD9FFFFE2AC0E3, networkRoute=[58062, 291]]
2019-09-12 07:22:35.816 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=58062/1, destinationAddress=0/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=08 21 0A 00 00 10 00]
2019-09-12 07:22:35.816 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=33, commandId=10]
2019-09-12 07:22:35.816 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 58062/1 -> 0/1, cluster=0006, TID=21, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
2019-09-12 07:22:35.816 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [On/Off: 58062/1 -> 0/1, cluster=0006, TID=21, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]] 
2019-09-12 07:22:36.419 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2019-09-12 07:22:36.894 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:01,90FD9FFFFED5A477,FE14,B7B4
2019-09-12 07:22:36.895 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=90FD9FFFFED5A477, networkRoute=[65044, 47028]]
2019-09-12 07:22:36.895 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=90FD9FFFFED5A477, networkRoute=[65044, 47028]]
2019-09-12 07:22:36.895 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:FE14,0104,01,01,0300,08:#
a!r,-42,FF
2019-09-12 07:22:36.895 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=65044, profileId=260, destinationEp=1, sourceEp=1, clusterId=768, messageData=08 23 0A 07 00 21 72 01, rssi=-66, lqi=255]
2019-09-12 07:22:36.896 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=65044/1, destinationAddress=0/1, profile=0104, cluster=0300, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=08 23 0A 07 00 21 72 01]
2019-09-12 07:22:36.896 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=35, commandId=10]
2019-09-12 07:22:36.896 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Color Control: 65044/1 -> 0/1, cluster=0300, TID=23, reports=[Attribute Report: attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, attributeValue=370]]
2019-09-12 07:22:36.896 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [Color Control: 65044/1 -> 0/1, cluster=0300, TID=23, reports=[Attribute Report: attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, attributeValue=370]] 
2019-09-12 07:22:37.127 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SR:01,90FD9FFFFED5A477,FE14,B7B4
2019-09-12 07:22:37.127 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=90FD9FFFFED5A477, networkRoute=[65044, 47028]]
2019-09-12 07:22:37.128 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisRouteRecordMessageEvent [hops=1, remoteAddress=90FD9FFFFED5A477, networkRoute=[65044, 47028]]
2019-09-12 07:22:37.128 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:FE14,0104,01,01,0300,07:$
0,-46,FF
2019-09-12 07:22:37.128 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=65044, profileId=260, destinationEp=1, sourceEp=1, clusterId=768, messageData=08 24 0A 08 00 30 02, rssi=-70, lqi=255]
2019-09-12 07:22:37.128 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=65044/1, destinationAddress=0/1, profile=0104, cluster=0300, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=08 24 0A 08 00 30 02]
2019-09-12 07:22:37.128 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=36, commandId=10]
2019-09-12 07:22:37.129 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Color Control: 65044/1 -> 0/1, cluster=0300, TID=24, reports=[Attribute Report: attributeDataType=ENUMERATION_8_BIT, attributeIdentifier=8, attributeValue=2]]
2019-09-12 07:22:37.129 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [Color Control: 65044/1 -> 0/1, cluster=0300, TID=24, reports=[Attribute Report: attributeDataType=ENUMERATION_8_BIT, attributeIdentifier=8, attributeValue=2]] 
2019-09-12 07:22:37.420 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 2
2019-09-12 07:22:38.419 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TELEGESIS Timer: Timeout 2
2019-09-12 07:22:38.420 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager transport state updated to OFFLINE
2019-09-12 07:22:38.420 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to OFFLINE
2019-09-12 07:22:38.421 [DEBUG] [gesis.internal.TelegesisFrameHandler] - Error: number of retries exceeded [3].
2019-09-12 07:22:39.425 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager shutdown: networkState=OFFLINE

Any ideas? If you need more logs I would be happy to send them, as I don’t really have a clue if the actual problem happened here or before.

Probably it is related to the following issue -:

This bug means that once there are 3 retries, the device will go offline. The counter should be reset so that this is 3 retries in a row.

That, coupled with another bug in the binding means that the communications doesn’t restart -:

Both of these are waiting for people to update the PRs - once that’s done we can get this merged and hopefully it will resolve your issue.

Thanks a lot, I will try to survive until then. So this:

java.lang.NumberFormatException: For input string: "�,-4"
	at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) ~[?:?]
	at java.lang.Integer.parseInt(Integer.java:569) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.telegesis.internal.protocol.TelegesisFrame.deserializeInt16(TelegesisFrame.java:198) ~[219:com.zsmartsystems.zigbee.dongle.telegesis:1.2.1]
	at com.zsmartsystems.zigbee.dongle.telegesis.internal.protocol.TelegesisReceiveMessageEvent.deserialize(TelegesisReceiveMessageEvent.java:177) ~[219:com.zsmartsystems.zigbee.dongle.telegesis:1.2.1]
	at com.zsmartsystems.zigbee.dongle.telegesis.internal.TelegesisEventFactory.getTelegesisFrame(TelegesisEventFactory.java:90) [219:com.zsmartsystems.zigbee.dongle.telegesis:1.2.1]
	at com.zsmartsystems.zigbee.dongle.telegesis.internal.TelegesisFrameHandler$1.run(TelegesisFrameHandler.java:185) [219:com.zsmartsystems.zigbee.dongle.telegesis:1.2.1]

Is not something to be alarmed by?

No - probably not. The Telegesis “protocol” used to communicate between the stick and the binding is quite poor. It’s an ASCII based protocol, and there is no error checking. All that the libraries can do is trap errors and hope that the higher level systems will retry the message.

This is likely what led to the problem - these sorts of errors will happen occasionally, and the system should work fine with the occasional error. The problem is with the bug I referenced above, after 3 errors from the point the binding is started, the system will be put offline, and it should be 3 errors one after another.

Thanks a lot for the explanation. Is there a USB stick with a better protocol that you would recommend atm? Or is Telegesis still considered as one of the top options (USB Zigbee Stick)? Do you think the low baud rate of 19200 is a problem with lots of devices?

@chris is the expert but I am biased toward the Z-Wave Plus protocol. It is designed for long battery life, good range, device compatibility, and low interference. Security is also an option. Devices are region-specific due to various frequencies and more expensive than Zigbee.

I’ve migrated from Telegesis to an Ember EM3588-LR. It supports Zigbee 3.0, works with higher baud rates and doesn’t have issues with some devices (eg. Innr bulbs and plugs).

I think that’s also the option @chris recommends:

1 Like

As @weakfl stated, the Ember chipsets are best (IMHO), and the have the best support (both by the binding and their manufacturers). The EM35x mentioned by @weakfl is a good option, but there aren’t too many sticks readily available. There is the MeshConnect EM35x series from CEL that are generally easily available, but they have no firmware in them when purchased. There is also the HUSBZB-1 from GoControl (a combined ZigBee/ZWave stick available in the USA) that is also ok, but this has quite an old firmware and no bootloader. There is also a Bitron stick sold by Deutsche Telekom, but this requires custom drivers so is only usable on Linux…

Nearly all of the commercial users of the Z-Smart Systems libraries that perform all the low level ZigBee work are using Ember chipsets of various types, so it gets the most testing, and best support.

I would have no real hesitation recommending any of these if you can live with the relevant constraint. Plus or minus, they all work the same with the “same” firmware. However, this is an old product now, and I don’t think Silabs are still making them. Instead, they have a new range - the MightyGecko, or EFR32 range (same thing - different names). Again, this uses the “same” firmware as the EM35x series, so will work exactly the same with the binding.

I am looking at producing a stick with the EFR32 in it - hopefully at a similar cost to the existing CEL MeshConnect sticks. My goal is to solve a few problems that the existing sticks have - it will have a hardware reset (a potential problem with all current sticks that causes some people issues), and it should also allow me to support the sniffer function at the same time as being used as the coordinator (all current solutions require a second stick to act as a sniffer). It will also come programmed, and will include a bootloader so it can be updated, so it should get around all the issues we currently have with the various Ember sticks mentioned above.

Let’s see how I get on with this - I have some boards arriving in the next few days so there’s still a little work required to get this into a working state :sunglasses:.

Just for completeness - other options out there are the TI CC2531 dongles - these are low cost from China, but the firmware is not so good and I’ve been told by TI that it will not be updated. The Telegesis is still on my “recommended” list as it generally works fine, but it’s not going to be updated, and it’s not ZB3.0 compatible (I should also say that the Telegesis is actually the same as the CEL chips except the firmware, and the firmware can be reprogrammed with the standard Ember firmware). The ConBee is also semi popular, but not fully supported by the binding, and the last option is the XBee series which I believe works well, but again this is the same as the Ember chips with different firmware.

Anyway, I hope that rather long answer helps with your short question :slight_smile: .

2 Likes

I didn’t know that’s possible. Does it require a devkit?

Good question - I’m not 100% sure to be honest as it’s been a little while since I’ve done this. It has the same connector on the side as the CEL sticks, and can certainly be programmed with the devkit, but it may also have the standard bootloader, so it’s possible that it may be programmable using my console application in the Z-Smart System ZigBee repository.

Yay! Sign me up.

Ok, I had the same issue with my Telegesis ETRX357 Zigbee USB stick running on my RPI 3b+. All of my Zigbee switches and light bulbs quit responding today.

The log keeps repeating the following message:

“2019-09-13 12:30:07.674 [me.event.ThingUpdatedEvent] - Thing ‘zigbee:coordinator_telegesis:04000B6C’ has been updated.”

All of my items report in paper UI to be “ON LINE” yet are unresponsive.
In Paper UI I tried to disable the Zigbee Coordinator and restart it…to no avail. The same issue repeated the previous repeating message in the log.

As a last ditch effort I disabled the Zigbee controller in Paper UI then unplugged the USB controller from my Raspberry PI. After waiting about a minute I plugged it back in and restarted the Zigbee Coordinator in Paper UI and watched the log. It worked…went into discovery and detected all of my devices and it was all working again! I got lucky I guess.

I don’t know if this will help anyone…best wishes!

Mike Anderson

From what you’ve described, the issue looks different since you say everything is ONLINE. Maybe it’s better to start a new discussion.

This is perfectly normal - it means that there are updates still happening. You should look at the debug logs as explained in the binding documentation.

1 Like

Looks like :slight_smile:

ETRX357-LRS Serial/OTA Bootloader v01 b02

1. upload ebl
2. run
3. ebl info
BL >

But where can I get the right firmware?

I can probably provide it if you want to do this.

1 Like

That would be great, I’ll send you a PM…
I don’t use the stick atm, so worst case scenario I’ll have to send it to you for reprogramming, right? :stuck_out_tongue_winking_eye:

Yes - that’s fine. It should work fine with the bootloader and I’ve tested this many times in the past.

I would be very interested in if / how this works.

It definitely works - as above, I’ve done it many times…

I will try and find the firmware and write a short “how-to” at some point soon.