Openhab3 + cc2531 + zigbee binding - devices offline

lukasg · January 3, 2021, 6:49pm

From openhab.log:

2021-01-03 16:43:00.604 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EEFC0: Polling stopped

2021-01-03 16:43:00.609 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EEFC0: Polling initialised at 7260993ms

2021-01-03 16:43:13.470 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222ef622

2021-01-03 16:43:13.472 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EF622: Polling stopped

2021-01-03 16:43:13.474 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EF622: Polling initialised at 7843230ms

2021-01-03 16:43:21.314 [WARN ] [o.internal.handler.SysteminfoHandler] - No information for channel sensors#fanSpeed with device index 0 :

2021-01-03 16:43:30.611 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222eefc0

2021-01-03 16:43:41.791 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222ef213

2021-01-03 16:43:41.795 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EF213: Polling stopped

2021-01-03 16:43:41.797 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EF213: Polling initialised at 7545304ms

2021-01-03 16:43:43.477 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222ef622

2021-01-03 16:44:11.799 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222ef213

2021-01-03 16:44:14.689 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222f9387

2021-01-03 16:44:14.691 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222F9387: Polling stopped

2021-01-03 16:44:14.693 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222F9387: Polling initialised at 7686656ms

2021-01-03 16:44:21.394 [WARN ] [o.internal.handler.SysteminfoHandler] - No information for channel sensors#fanSpeed with device index 0 :

2021-01-03 16:44:44.694 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222f9387

From events.log:

2021-01-03 16:43:27.993 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 519 to 511

2021-01-03 16:43:30.615 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘zigbee:device:ba1f317aca:00124b00222eefc0’ changed from ONLINE to OFFLINE

2021-01-03 16:43:31.002 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3367 to 3366

2021-01-03 16:43:31.009 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 62.3 to 61.8

2021-01-03 16:43:34.012 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_UsedPercent’ changed from 13.2 to 13.1

2021-01-03 16:43:34.019 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_AvailablePercent’ changed from 86.8 to 86.9

2021-01-03 16:43:34.021 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3366 to 3368

2021-01-03 16:43:34.026 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 61.8 to 63.8

2021-01-03 16:43:34.028 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 511 to 509

2021-01-03 16:43:37.043 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 63.8 to 63.3

2021-01-03 16:43:40.050 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_UsedPercent’ changed from 13.1 to 13.2

2021-01-03 16:43:40.061 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_AvailablePercent’ changed from 86.9 to 86.8

2021-01-03 16:43:40.063 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3368 to 3367

2021-01-03 16:43:40.071 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 63.3 to 62.3

2021-01-03 16:43:40.073 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 509 to 510

2021-01-03 16:43:43.081 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 62.3 to 62.8

2021-01-03 16:43:43.479 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘zigbee:device:ba1f317aca:00124b00222ef622’ changed from ONLINE to OFFLINE

2021-01-03 16:43:46.092 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_UsedPercent’ changed from 13.2 to 13.4

2021-01-03 16:43:46.108 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_AvailablePercent’ changed from 86.8 to 86.6

2021-01-03 16:43:46.117 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3367 to 3359

2021-01-03 16:43:46.119 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 62.8 to 64.3

2021-01-03 16:43:46.122 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 510 to 519

2021-01-03 16:43:49.112 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_UsedPercent’ changed from 13.4 to 13.1

2021-01-03 16:43:49.122 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_AvailablePercent’ changed from 86.6 to 86.9

2021-01-03 16:43:49.125 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3359 to 3368

2021-01-03 16:43:49.127 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 64.3 to 61.8

2021-01-03 16:43:49.129 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 519 to 510

2021-01-03 16:43:52.130 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_UsedPercent’ changed from 13.1 to 13.3

2021-01-03 16:43:52.142 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_AvailablePercent’ changed from 86.9 to 86.7

2021-01-03 16:43:52.145 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3368 to 3363

2021-01-03 16:43:52.149 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 510 to 514

2021-01-03 16:43:55.149 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_UsedPercent’ changed from 13.3 to 13.1

2021-01-03 16:43:55.157 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_AvailablePercent’ changed from 86.7 to 86.9

2021-01-03 16:43:55.158 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3363 to 3368

2021-01-03 16:43:55.164 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 61.8 to 63.8

2021-01-03 16:43:55.167 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 514 to 509

2021-01-03 16:43:58.179 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3368 to 3369

2021-01-03 16:43:58.185 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 63.8 to 61.8

2021-01-03 16:44:01.188 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_UsedPercent’ changed from 13.1 to 13.2

2021-01-03 16:44:01.203 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_AvailablePercent’ changed from 86.9 to 86.8

2021-01-03 16:44:01.208 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3369 to 3366

2021-01-03 16:44:01.210 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 61.8 to 62.8

2021-01-03 16:44:01.211 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 509 to 511

2021-01-03 16:44:04.207 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_UsedPercent’ changed from 13.2 to 13.1

2021-01-03 16:44:04.216 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_AvailablePercent’ changed from 86.8 to 86.9

2021-01-03 16:44:04.220 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3366 to 3368

2021-01-03 16:44:04.224 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 62.8 to 63.8

2021-01-03 16:44:04.227 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 511 to 509

2021-01-03 16:44:07.229 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_UsedPercent’ changed from 13.1 to 13.4

2021-01-03 16:44:07.238 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_AvailablePercent’ changed from 86.9 to 86.6

2021-01-03 16:44:07.243 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3368 to 3358

2021-01-03 16:44:07.251 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_CPUTemperature’ changed from 63.8 to 62.8

2021-01-03 16:44:07.254 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 509 to 519

2021-01-03 16:44:10.254 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_UsedPercent’ changed from 13.4 to 13.1

2021-01-03 16:44:10.265 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_AvailablePercent’ changed from 86.6 to 86.9

2021-01-03 16:44:10.268 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Available’ changed from 3358 to 3368

2021-01-03 16:44:10.272 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘Systeminfo_RAM_Used’ changed from 519 to 509

2021-01-03 16:44:11.801 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘zigbee:device:ba1f317aca:00124b00222ef213’ changed from ONLINE to OFFLINE

chris · January 3, 2021, 6:52pm

This looks correct - it just looks like the device isn’t responding. Without the fully information though, it’s still a little hard to be sure what’s happening, but it does seem that the device didn’t report, the binding seems to have polled and it looks like this failed, so the device was set OFFLINE. That is correct.

lukasg · January 3, 2021, 7:14pm

Thank you.

Any idea how to solve this problem? Is it a problem of the devices as itself? Which more information do you need?

Otherwise… I don´t know how to get it done.

The Innr bulbs also go offline, but long time later.

EDIT: Would it be better with an Zigbee 3.0 controller? The ones I use has only Zigbee 1.x.

chris · January 3, 2021, 7:53pm

Sorry - not really. A full debug log might help, but it seems from the information here that the device is not responding.

I doubt it would solve this problem - if the device isn’t responding (as it seems) then a new coordinator probably won’t help.

lukasg · January 3, 2021, 8:06pm

I thought this is the log which is needed…sorry.

Screenshot of logs I set up:

EDIT: Found out, that the controllers working, even if they are shown as offline.

Here the log after switching on an led stripe controlled by a Gledopto contoller:

> 2021-01-03 21:25:59.265 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 C4 A5 29 00 0E)
> 
> 2021-01-03 21:25:59.268 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=45 C4, data=FE 03 45 C4 A5 29 00 0E, checksum=0E, error=false
> 
> 2021-01-03 21:25:59.270 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c4
> 
> 2021-01-03 21:25:59.289 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_INCOMING_MSG (FE 1B 44 81 00 00 06 00 A5 29 03 01 00 37 00 CC 1F E1 00 00 07 18 9F 0A 00 00 10 01 A5 29 1D 59)
> 
> 2021-01-03 21:25:59.291 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=27, apiId=44 81, data=FE 1B 44 81 00 00 06 00 A5 29 03 01 00 37 00 CC 1F E1 00 00 07 18 9F 0A 00 00 10 01 A5 29 1D 59, checksum=59, error=false
> 
> 2021-01-03 21:25:59.293 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4481
> 
> 2021-01-03 21:25:59.296 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=29A5/3, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=18 9F 0A 00 00 10 01]
> 
> 2021-01-03 21:25:59.298 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=159, commandId=10]
> 
> 2021-01-03 21:25:59.300 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 29A5/3 -> 0000/1, cluster=0006, TID=9F, reports=[AttributeReport [attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=true]]]
> 
> 2021-01-03 21:25:59.303 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [On/Off: 29A5/3 -> 0000/1, cluster=0006, TID=9F, reports=[AttributeReport [attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=true]]] 
> 
> 2021-01-03 21:25:59.308 [DEBUG] [converter.ZigBeeConverterSwitchOnoff] - 7CB03EAA0A09812B: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Sun Jan 03 21:25:59 CET 2021, implemented=true]
> 
> 2021-01-03 21:25:59.312 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 7CB03EAA0A09812B: Channel zigbee:device:ba1f317aca:7cb03eaa0a09812b:7CB03EAA0A09812B_3_switch updated to ON
> 
> 2021-01-03 21:25:59.315 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A09812B: Updating ZigBee channel state zigbee:device:ba1f317aca:7cb03eaa0a09812b:7CB03EAA0A09812B_3_switch to ON
> 
> 2021-01-03 21:25:59.321 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:ba1f317aca:7cb03eaa0a09812b
> 
> 2021-01-03 21:25:59.324 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:ba1f317aca:7cb03eaa0a09812b
> 
> 2021-01-03 21:25:59.328 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:ba1f317aca:7cb03eaa0a09812b in 1830 seconds
> 
> 2021-01-03 21:26:10.010 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EEFC0: Command for channel zigbee:device:ba1f317aca:00124b00222eefc0:00124B00222EEFC0_11_color --> ON [OnOffType]
> 
> 2021-01-03 21:26:10.015 [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-03 21:26:10.017 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
> 
> 2021-01-03 21:26:10.020 [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=D4]]
> 
> 2021-01-03 21:26:10.022 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
> 
> 2021-01-03 21:26:10.024 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0000/0 -> 0661/11, cluster=0006, TID=D4]
> 
> 2021-01-03 21:26:10.026 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=212, commandId=1]
> 
> 2021-01-03 21:26:10.028 [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=2D, rssi=--, lqi=--, payload=01 D4 01]
> 
> 2021-01-03 21:26:10.030 [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 2D 30 08 03 01 D4 01 81, checksum=81, error=false) 
> 
> 2021-01-03 21:26:10.046 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
> 
> 2021-01-03 21:26:10.048 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D4 state=TX_ACK
> 
> 2021-01-03 21:26:10.051 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D4, state=TX_ACK, outstanding=1
> 
> 2021-01-03 21:26:10.055 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0661, TID=D4, event=TX_ACK, state=TRANSMITTED
> 
> 2021-01-03 21:26:10.070 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 C4 61 06 00 E5)
> 
> 2021-01-03 21:26:10.072 [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-03 21:26:10.074 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c4
> 
> 2021-01-03 21:26:10.091 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 00 01 2D EB)
> 
> 2021-01-03 21:26:10.093 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=SUCCESS(0), TransID=45)
> 
> 2021-01-03 21:26:10.094 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D4 state=RX_ACK
> 
> 2021-01-03 21:26:10.096 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D4, state=RX_ACK, outstanding=1
> 
> 2021-01-03 21:26:10.098 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 C4 61 06 00 E5)
> 
> 2021-01-03 21:26:10.098 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0661, TID=D4, event=RX_ACK, state=ACKED
> 
> 2021-01-03 21:26:10.100 [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-03 21:26:10.102 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c4
> 
> 2021-01-03 21:26:10.112 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_INCOMING_MSG (FE 19 44 81 00 00 06 00 61 06 0B 01 00 3C 00 BA A3 E1 00 00 05 18 D4 0B 01 00 61 06 1D CA)
> 
> 2021-01-03 21:26:10.114 [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 3C 00 BA A3 E1 00 00 05 18 D4 0B 01 00 61 06 1D CA, checksum=CA, error=false
> 
> 2021-01-03 21:26:10.116 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4481
> 
> 2021-01-03 21:26:10.119 [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 D4 0B 01 00]
> 
> 2021-01-03 21:26:10.121 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=212, commandId=11]
> 
> 2021-01-03 21:26:10.125 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 0661/11 -> 0000/1, cluster=0006, TID=D4, commandIdentifier=1, statusCode=SUCCESS]
> 
> 2021-01-03 21:26:10.128 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [On/Off: 0661/11 -> 0000/1, cluster=0006, TID=D4, commandIdentifier=1, statusCode=SUCCESS] 
> 
> 2021-01-03 21:26:10.132 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B00222EEFC0 queueTime=116, state=COMPLETE, sendCnt=1, command=OnCommand [On/Off: 0000/0 -> 0661/11, cluster=0006, TID=D4]]
> 
> 2021-01-03 21:26:10.135 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
> 
> 2021-01-03 21:26:10.137 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00222EEFC0: transactionComplete, state=COMPLETE, outstanding=0
> 
> 2021-01-03 21:26:10.139 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
> 
> ==> /var/log/openhab/events.log <==
> 
> 2021-01-03 21:26:09.992 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'GLEDOPTO03_Color' received command ON

chris · January 3, 2021, 8:35pm

Thanks - the logs look more compete here now. Can you also now provide this when the device goes OFFLINE (and for about 1 minute before).

lukasg · January 3, 2021, 8:42pm

Ok. I will do a reboot of the raspberry now and send a log when the devices go offline.
Thank you.

lukasg · January 4, 2021, 7:10am

Here it is…
from events.log:

2021-01-04 01:51:15.976 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ba1f317aca:00124b00222ef622' changed from ONLINE to OFFLINE

From openhab.log:

2021-01-04 01:50:54.823 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-01-04 01:50:54.824 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=1
2021-01-04 01:50:54.825 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=0, sleepy=0/3
2021-01-04 01:50:54.825 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=0, sleepy=0/3
2021-01-04 01:50:54.827 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A08B09E: Node SVC Discovery: NetworkAddressRequest returned null
2021-01-04 01:50:54.828 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A08B09E: Node SVC Discovery: NetworkAddressRequest failed after unicast and broadcast
2021-01-04 01:50:54.829 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A08B09E: Node SVC Discovery: request NWK_ADDRESS failed. Retry 3, wait 2169ms before retry.
2021-01-04 01:50:54.997 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222eefc0
2021-01-04 01:50:54.998 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EEFC0: Polling stopped
2021-01-04 01:50:55.000 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222EEFC0: Polling initialised at 7849949ms
2021-01-04 01:50:56.999 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A08B09E: Node SVC Discovery: running NWK_ADDRESS
2021-01-04 01:50:57.001 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A08B09E: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=7CB03EAA0A08B09E queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 1800/0, cluster=0000, TID=--, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]]
2021-01-04 01:50:57.002 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=1, sleepy=0/3
2021-01-04 01:50:57.003 [DEBUG] [transaction.ZigBeeTransactionManager] - 1800/0: Sending ZigBeeTransaction [ieeeAddress=7CB03EAA0A08B09E queueTime=3, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 1800/0, cluster=0000, TID=DD, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]]
2021-01-04 01:50:57.004 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 4 outstanding
2021-01-04 01:50:57.005 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> 1800/0, cluster=0000, TID=DD, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]
2021-01-04 01:50:57.007 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=1800/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=37, rssi=--, lqi=--, payload=DD 9E B0 08 0A AA 3E B0 7C 00 00]
2021-01-04 01:50:57.008 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 00 18 00 00 00 00 37 30 08 0B DD 9E B0 08 0A AA 3E B0 7C 00 00 85, checksum=85, error=false) 
2021-01-04 01:50:57.027 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-01-04 01:50:57.028 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DD state=TX_ACK
2021-01-04 01:50:57.029 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DD, state=TX_ACK, outstanding=4
2021-01-04 01:50:57.030 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=1800, TID=DD, event=TX_ACK, state=TRANSMITTED
2021-01-04 01:50:57.189 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CB03EAA0A09FE76 queueTime=16066, state=FAILED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> C403/0, cluster=0000, TID=D9, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:50:57.190 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-01-04 01:50:57.191 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A09FE76: transactionComplete, state=FAILED, outstanding=0
2021-01-04 01:50:57.191 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A09FE76: transactionComplete exceeded max retries 2
2021-01-04 01:50:57.193 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=7CB03EAA0A09FE76 queueTime=16070, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> C403/0, cluster=0000, TID=D9, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:50:57.194 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A09FE76: Node SVC Discovery: NetworkAddressRequest returned null
2021-01-04 01:50:57.194 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CB03EAA0A09FE76 queueTime=16071, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> C403/0, cluster=0000, TID=D9, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:50:57.195 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-01-04 01:50:57.196 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A09FE76: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-01-04 01:50:57.196 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=0, sleepy=0/3
2021-01-04 01:50:57.197 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=0, sleepy=0/3
2021-01-04 01:50:57.199 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:50:57.199 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=1, sleepy=0/3
2021-01-04 01:50:57.201 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=2, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=DE, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:50:57.201 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 4 outstanding
2021-01-04 01:50:57.202 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=DE, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]
2021-01-04 01:50:57.203 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=38, rssi=--, lqi=--, payload=DE 76 FE 09 0A AA 3E B0 7C 00 00]
2021-01-04 01:50:57.205 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FF FF 00 00 00 00 38 30 08 0B DE 76 FE 09 0A AA 3E B0 7C 00 00 36, checksum=36, error=false) 
2021-01-04 01:50:57.221 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-01-04 01:50:57.222 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DE state=TX_ACK
2021-01-04 01:50:57.223 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DE, state=TX_ACK, outstanding=4
2021-01-04 01:50:57.226 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFF, TID=DE, event=TX_ACK, state=TRANSMITTED
2021-01-04 01:50:58.817 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8031, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=DB, ieeeAddr=847127FFFE173A87, requestType=0, startIndex=0]]
2021-01-04 01:50:58.818 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-01-04 01:50:58.819 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=1
2021-01-04 01:50:58.819 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded max retries 1
2021-01-04 01:50:58.820 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=8034, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=DB, ieeeAddr=847127FFFE173A87, requestType=0, startIndex=0]]
2021-01-04 01:50:58.821 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 847127FFFE173A87: Node SVC Discovery: NetworkAddressRequest returned null
2021-01-04 01:50:58.822 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8035, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=DB, ieeeAddr=847127FFFE173A87, requestType=0, startIndex=0]]
2021-01-04 01:50:58.822 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-01-04 01:50:58.823 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 847127FFFE173A87: Node SVC Discovery: NetworkAddressRequest failed after unicast and broadcast
2021-01-04 01:50:58.823 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=1
2021-01-04 01:50:58.823 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 847127FFFE173A87: Node SVC Discovery: request NWK_ADDRESS failed. Retry 3, wait 6498ms before retry.
2021-01-04 01:50:58.824 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=0, sleepy=0/3
2021-01-04 01:50:58.825 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=0, sleepy=0/3
2021-01-04 01:51:02.239 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CB03EAA0A0872A3 queueTime=8034, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> BEF7/0, cluster=0000, TID=DC, ieeeAddr=7CB03EAA0A0872A3, requestType=0, startIndex=0]]
2021-01-04 01:51:02.240 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding
2021-01-04 01:51:02.241 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A0872A3: transactionComplete, state=FAILED, outstanding=0
2021-01-04 01:51:02.243 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A0872A3: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=7CB03EAA0A0872A3 queueTime=8038, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> BEF7/0, cluster=0000, TID=DC, ieeeAddr=7CB03EAA0A0872A3, requestType=0, startIndex=0]]
2021-01-04 01:51:02.244 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
2021-01-04 01:51:02.245 [DEBUG] [transaction.ZigBeeTransactionManager] - BEF7/0: Sending ZigBeeTransaction [ieeeAddress=7CB03EAA0A0872A3 queueTime=8041, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> BEF7/0, cluster=0000, TID=DC, ieeeAddr=7CB03EAA0A0872A3, requestType=0, startIndex=0]]
2021-01-04 01:51:02.246 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding
2021-01-04 01:51:02.248 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> BEF7/0, cluster=0000, TID=DC, ieeeAddr=7CB03EAA0A0872A3, requestType=0, startIndex=0]
2021-01-04 01:51:02.249 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=BEF7/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=39, rssi=--, lqi=--, payload=DC A3 72 08 0A AA 3E B0 7C 00 00]
2021-01-04 01:51:02.251 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 F7 BE 00 00 00 00 39 30 08 0B DC A3 72 08 0A AA 3E B0 7C 00 00 24, checksum=24, error=false) 
2021-01-04 01:51:02.271 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-01-04 01:51:02.272 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DC state=TX_ACK
2021-01-04 01:51:02.273 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DC, state=TX_ACK, outstanding=3
2021-01-04 01:51:02.276 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=BEF7, TID=DC, event=TX_ACK, state=TRANSMITTED
2021-01-04 01:51:03.040 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222f9387
2021-01-04 01:51:03.041 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222F9387: Polling stopped
2021-01-04 01:51:03.042 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00124B00222F9387: Polling initialised at 7893026ms
2021-01-04 01:51:05.031 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CB03EAA0A08B09E queueTime=8030, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 1800/0, cluster=0000, TID=DD, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]]
2021-01-04 01:51:05.032 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding
2021-01-04 01:51:05.032 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A08B09E: transactionComplete, state=FAILED, outstanding=0
2021-01-04 01:51:05.033 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A08B09E: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=7CB03EAA0A08B09E queueTime=8033, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 1800/0, cluster=0000, TID=DD, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]]
2021-01-04 01:51:05.034 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
2021-01-04 01:51:05.035 [DEBUG] [transaction.ZigBeeTransactionManager] - 1800/0: Sending ZigBeeTransaction [ieeeAddress=7CB03EAA0A08B09E queueTime=8035, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 1800/0, cluster=0000, TID=DD, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]]
2021-01-04 01:51:05.036 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding
2021-01-04 01:51:05.037 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> 1800/0, cluster=0000, TID=DD, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]
2021-01-04 01:51:05.038 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=1800/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3A, rssi=--, lqi=--, payload=DD 9E B0 08 0A AA 3E B0 7C 00 00]
2021-01-04 01:51:05.039 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 00 18 00 00 00 00 3A 30 08 0B DD 9E B0 08 0A AA 3E B0 7C 00 00 88, checksum=88, error=false) 
2021-01-04 01:51:05.058 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-01-04 01:51:05.059 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DD state=TX_ACK
2021-01-04 01:51:05.059 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DD, state=TX_ACK, outstanding=3
2021-01-04 01:51:05.060 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=1800, TID=DD, event=TX_ACK, state=TRANSMITTED
2021-01-04 01:51:05.224 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8026, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=DE, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:51:05.225 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding
2021-01-04 01:51:05.226 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=0
2021-01-04 01:51:05.226 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded max retries 1
2021-01-04 01:51:05.227 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=8029, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=DE, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:51:05.228 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A09FE76: Node SVC Discovery: NetworkAddressRequest returned null
2021-01-04 01:51:05.229 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A09FE76: Node SVC Discovery: NetworkAddressRequest failed after unicast and broadcast
2021-01-04 01:51:05.230 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8031, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=DE, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:51:05.230 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A09FE76: Node SVC Discovery: request NWK_ADDRESS failed. Retry 3, wait 2133ms before retry.
2021-01-04 01:51:05.231 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding
2021-01-04 01:51:05.231 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-01-04 01:51:05.232 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=0, sleepy=0/3
2021-01-04 01:51:05.233 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=0, sleepy=0/3
2021-01-04 01:51:05.322 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 847127FFFE173A87: Node SVC Discovery: running NWK_ADDRESS
2021-01-04 01:51:05.324 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 847127FFFE173A87: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=847127FFFE173A87 queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FB64/0, cluster=0000, TID=--, ieeeAddr=847127FFFE173A87, requestType=0, startIndex=0]]
2021-01-04 01:51:05.325 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
2021-01-04 01:51:05.326 [DEBUG] [transaction.ZigBeeTransactionManager] - FB64/0: Sending ZigBeeTransaction [ieeeAddress=847127FFFE173A87 queueTime=2, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FB64/0, cluster=0000, TID=DF, ieeeAddr=847127FFFE173A87, requestType=0, startIndex=0]]
2021-01-04 01:51:05.327 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding
2021-01-04 01:51:05.328 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FB64/0, cluster=0000, TID=DF, ieeeAddr=847127FFFE173A87, requestType=0, startIndex=0]
2021-01-04 01:51:05.329 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FB64/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3B, rssi=--, lqi=--, payload=DF 87 3A 17 FE FF 27 71 84 00 00]
2021-01-04 01:51:05.330 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 64 FB 00 00 00 00 3B 30 08 0B DF 87 3A 17 FE FF 27 71 84 00 00 01, checksum=01, error=false) 
2021-01-04 01:51:05.348 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-01-04 01:51:05.349 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DF state=TX_ACK
2021-01-04 01:51:05.350 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DF, state=TX_ACK, outstanding=3
2021-01-04 01:51:05.351 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FB64, TID=DF, event=TX_ACK, state=TRANSMITTED
2021-01-04 01:51:07.364 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A09FE76: Node SVC Discovery: running NWK_ADDRESS
2021-01-04 01:51:07.366 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A09FE76: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=7CB03EAA0A09FE76 queueTime=1, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> C403/0, cluster=0000, TID=--, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:51:07.367 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=1, sleepy=0/3
2021-01-04 01:51:07.368 [DEBUG] [transaction.ZigBeeTransactionManager] - C403/0: Sending ZigBeeTransaction [ieeeAddress=7CB03EAA0A09FE76 queueTime=3, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> C403/0, cluster=0000, TID=E0, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:51:07.369 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 4 outstanding
2021-01-04 01:51:07.370 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> C403/0, cluster=0000, TID=E0, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]
2021-01-04 01:51:07.371 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=C403/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3C, rssi=--, lqi=--, payload=E0 76 FE 09 0A AA 3E B0 7C 00 00]
2021-01-04 01:51:07.373 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 03 C4 00 00 00 00 3C 30 08 0B E0 76 FE 09 0A AA 3E B0 7C 00 00 CB, checksum=CB, error=false) 
2021-01-04 01:51:07.391 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-01-04 01:51:07.392 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=E0 state=TX_ACK
2021-01-04 01:51:07.393 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=E0, state=TX_ACK, outstanding=4
2021-01-04 01:51:07.396 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=C403, TID=E0, event=TX_ACK, state=TRANSMITTED
2021-01-04 01:51:10.277 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CB03EAA0A0872A3 queueTime=16072, state=FAILED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> BEF7/0, cluster=0000, TID=DC, ieeeAddr=7CB03EAA0A0872A3, requestType=0, startIndex=0]]
2021-01-04 01:51:10.278 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-01-04 01:51:10.279 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A0872A3: transactionComplete, state=FAILED, outstanding=0
2021-01-04 01:51:10.279 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A0872A3: transactionComplete exceeded max retries 2
2021-01-04 01:51:10.281 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=7CB03EAA0A0872A3 queueTime=16076, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> BEF7/0, cluster=0000, TID=DC, ieeeAddr=7CB03EAA0A0872A3, requestType=0, startIndex=0]]
2021-01-04 01:51:10.282 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A0872A3: Node SVC Discovery: NetworkAddressRequest returned null
2021-01-04 01:51:10.282 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CB03EAA0A0872A3 queueTime=16077, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> BEF7/0, cluster=0000, TID=DC, ieeeAddr=7CB03EAA0A0872A3, requestType=0, startIndex=0]]
2021-01-04 01:51:10.283 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-01-04 01:51:10.283 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A0872A3: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-01-04 01:51:10.284 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=0, sleepy=0/3
2021-01-04 01:51:10.285 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=0, sleepy=0/3
2021-01-04 01:51:10.286 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=7CB03EAA0A0872A3, requestType=0, startIndex=0]]
2021-01-04 01:51:10.287 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=1, sleepy=0/3
2021-01-04 01:51:10.288 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=2, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=E1, ieeeAddr=7CB03EAA0A0872A3, requestType=0, startIndex=0]]
2021-01-04 01:51:10.289 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 4 outstanding
2021-01-04 01:51:10.290 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=E1, ieeeAddr=7CB03EAA0A0872A3, requestType=0, startIndex=0]
2021-01-04 01:51:10.291 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3D, rssi=--, lqi=--, payload=E1 A3 72 08 0A AA 3E B0 7C 00 00]
2021-01-04 01:51:10.292 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FF FF 00 00 00 00 3D 30 08 0B E1 A3 72 08 0A AA 3E B0 7C 00 00 54, checksum=54, error=false) 
2021-01-04 01:51:10.308 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-01-04 01:51:10.309 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=E1 state=TX_ACK
2021-01-04 01:51:10.309 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=E1, state=TX_ACK, outstanding=4
2021-01-04 01:51:10.310 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFF, TID=E1, event=TX_ACK, state=TRANSMITTED
2021-01-04 01:51:13.061 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CB03EAA0A08B09E queueTime=16060, state=FAILED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 1800/0, cluster=0000, TID=DD, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]]
2021-01-04 01:51:13.062 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-01-04 01:51:13.063 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A08B09E: transactionComplete, state=FAILED, outstanding=0
2021-01-04 01:51:13.063 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A08B09E: transactionComplete exceeded max retries 2
2021-01-04 01:51:13.064 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=7CB03EAA0A08B09E queueTime=16064, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 1800/0, cluster=0000, TID=DD, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]]
2021-01-04 01:51:13.065 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A08B09E: Node SVC Discovery: NetworkAddressRequest returned null
2021-01-04 01:51:13.066 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CB03EAA0A08B09E queueTime=16065, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 1800/0, cluster=0000, TID=DD, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]]
2021-01-04 01:51:13.066 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-01-04 01:51:13.067 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A08B09E: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-01-04 01:51:13.068 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=0, sleepy=0/3
2021-01-04 01:51:13.068 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=0, sleepy=0/3
2021-01-04 01:51:13.070 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]]
2021-01-04 01:51:13.071 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=1, sleepy=0/3
2021-01-04 01:51:13.352 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=847127FFFE173A87 queueTime=8027, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FB64/0, cluster=0000, TID=DF, ieeeAddr=847127FFFE173A87, requestType=0, startIndex=0]]
2021-01-04 01:51:13.353 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding
2021-01-04 01:51:13.354 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 847127FFFE173A87: transactionComplete, state=FAILED, outstanding=0
2021-01-04 01:51:13.355 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 847127FFFE173A87: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=847127FFFE173A87 queueTime=8030, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FB64/0, cluster=0000, TID=DF, ieeeAddr=847127FFFE173A87, requestType=0, startIndex=0]]
2021-01-04 01:51:13.355 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=2, sleepy=0/3
2021-01-04 01:51:13.357 [DEBUG] [transaction.ZigBeeTransactionManager] - FB64/0: Sending ZigBeeTransaction [ieeeAddress=847127FFFE173A87 queueTime=8033, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FB64/0, cluster=0000, TID=DF, ieeeAddr=847127FFFE173A87, requestType=0, startIndex=0]]
2021-01-04 01:51:13.358 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding
2021-01-04 01:51:13.360 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FB64/0, cluster=0000, TID=DF, ieeeAddr=847127FFFE173A87, requestType=0, startIndex=0]
2021-01-04 01:51:13.361 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FB64/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3E, rssi=--, lqi=--, payload=DF 87 3A 17 FE FF 27 71 84 00 00]
2021-01-04 01:51:13.362 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 64 FB 00 00 00 00 3E 30 08 0B DF 87 3A 17 FE FF 27 71 84 00 00 04, checksum=04, error=false) 
2021-01-04 01:51:13.381 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-01-04 01:51:13.382 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DF state=TX_ACK
2021-01-04 01:51:13.382 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DF, state=TX_ACK, outstanding=3
2021-01-04 01:51:13.386 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FB64, TID=DF, event=TX_ACK, state=TRANSMITTED
2021-01-04 01:51:14.288 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=1, sleepy=0/3
2021-01-04 01:51:14.290 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=1220, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=E2, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]]
2021-01-04 01:51:14.291 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 4 outstanding
2021-01-04 01:51:14.292 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=E2, ieeeAddr=7CB03EAA0A08B09E, requestType=0, startIndex=0]
2021-01-04 01:51:14.293 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3F, rssi=--, lqi=--, payload=E2 9E B0 08 0A AA 3E B0 7C 00 00]
2021-01-04 01:51:14.294 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FF FF 00 00 00 00 3F 30 08 0B E2 9E B0 08 0A AA 3E B0 7C 00 00 AA, checksum=AA, error=false) 
2021-01-04 01:51:14.309 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-01-04 01:51:14.310 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=E2 state=TX_ACK
2021-01-04 01:51:14.311 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=E2, state=TX_ACK, outstanding=4
2021-01-04 01:51:14.312 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFF, TID=E2, event=TX_ACK, state=TRANSMITTED
2021-01-04 01:51:15.395 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CB03EAA0A09FE76 queueTime=8029, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> C403/0, cluster=0000, TID=E0, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:51:15.396 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-01-04 01:51:15.396 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A09FE76: transactionComplete, state=FAILED, outstanding=0
2021-01-04 01:51:15.398 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A09FE76: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=7CB03EAA0A09FE76 queueTime=8032, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> C403/0, cluster=0000, TID=E0, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:51:15.399 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=1, sleepy=0/3
2021-01-04 01:51:15.400 [DEBUG] [transaction.ZigBeeTransactionManager] - C403/0: Sending ZigBeeTransaction [ieeeAddress=7CB03EAA0A09FE76 queueTime=8035, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> C403/0, cluster=0000, TID=E0, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]]
2021-01-04 01:51:15.401 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 4 outstanding
2021-01-04 01:51:15.402 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> C403/0, cluster=0000, TID=E0, ieeeAddr=7CB03EAA0A09FE76, requestType=0, startIndex=0]
2021-01-04 01:51:15.404 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=C403/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=40, rssi=--, lqi=--, payload=E0 76 FE 09 0A AA 3E B0 7C 00 00]
2021-01-04 01:51:15.405 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 03 C4 00 00 00 00 40 30 08 0B E0 76 FE 09 0A AA 3E B0 7C 00 00 B7, checksum=B7, error=false) 
2021-01-04 01:51:15.424 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-01-04 01:51:15.426 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=E0 state=TX_ACK
2021-01-04 01:51:15.427 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=E0, state=TX_ACK, outstanding=4
2021-01-04 01:51:15.430 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=C403, TID=E0, event=TX_ACK, state=TRANSMITTED
2021-01-04 01:51:15.973 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222ef622

Thank you, Chris!

EDIT: For information, all zigbee devices are offline. None of them can be controlled via Basic UI or habPanel.

chris · January 4, 2021, 9:19am

Yes, that looks correct based on the logs. I’m not really sure what else I can add - I thought that this issue was that devices were incorrectly marked as offline?

The coordinator is unable to communicate with the devices, and the devices have not sent reports, so yes, they are offline.

lukasg · January 4, 2021, 9:52am

It is remarkable, that all Zigbee devices (Gledopto LED Controller for LED stripes, Osram smart plug, LED Innr bulb) are offline after some time.
Today in the morning I could not use any of the offline Zigbee-equipment (1x Osram smart plug, 4x Gledopto LED controllers for LED stripes, 2x Innr LED bulbs).

Do I have to change some settings of the coordinator-thing (baud rate? polling time? something like that) or other things (settings of a Zigbee thing attached)

?

It does not make sense to use openHAB when devices go offline and can not be used.

chris · January 4, 2021, 9:57am

The issue here is not with openHAB - there is something “wrong” in your network. Without more information, it’s very hard to know what is happening.

If baud rate was wrong, then the binding would not communicate with the dongle, so it is fine!

This only polls the device - the binding is polling, but the device doesn’t respond.

About the only way to know what is happening is with a network sniffer. Maybe the dongle has a problem, maybe the network is not a good mesh and is reliant on some device that has a poor link - I’m not really sure - sorry.

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?