Openhab3 + cc2531 + zigbee binding - devices offline

lukasg · December 28, 2020, 10:59am

Hello everybody,

I have two Innr LED Bulbs connected to openhab3 running on a Raspberry Pi 4 4GB with an CC2531.
It was very easy to pair them and control them via a HABPanel or Basic UI page.

But after a random time, both bulbs go offline.
Example from log:

2020-12-28 11:28:37.304 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ba1f317aca:847127fffe1736f4' changed from ONLINE to OFFLINE

After this the bulbs can not be controlled:

2020-12-28 11:27:54.183 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'LEDInnr1_LevelControl' received command ON
2020-12-28 11:27:54.185 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'LEDInnr1_LevelControl' predicted to become 0

Do you have any idea?

Thank you in advance!

Greetings,
Lukas

chris · December 28, 2020, 11:06am

As a matter of interest, if you restart OH, does it work again? I’m trying to establish if the issue is in the ZB network, or with the binding/OH.

The binding does also poll before setting the device offline, so it does seem to point to the fact that the devices were powered down, or somehow not working in the network.

lukasg · December 28, 2020, 12:02pm

Strange thing…after restarting openhab with:

[12:16:27] openhabian@openhab:~$ sudo systemctl stop openhab.service
Warning: The unit file, source configuration file or drop-ins of openhab.service changed on disk. Run ‘systemctl daemon-reload’ to reload units.
[12:17:06] openhabian@openhab:~$ sudo systemctl start openhab.service

the CC2531EMK Coordinator is in status UNKNOWN.

After restart of the RaspberryPi everything works by now. The coordinator and both bulbs are online and working as expected.

The problem was also with GLEDOPTO LED Controllers. Because of other reasons, I had to send them back.

chris · December 28, 2020, 1:28pm

If you can provide a debug log showing when the device goes offline I’ll take a look to see if I can see what is going on…

lukasg · December 28, 2020, 7:18pm

I set up debug logs like this in the console:
openhab> log:set DEBUG org.openhab.binding.zigbee
openhab> log:set DEBUG org.openhab.binding.zigbee.cc2531

Seems to be ok; s. screenshot.

Hopefully I did it right. I will provide a debug log, when the problem comes up again.

lukasg · December 30, 2020, 1:51pm

Since then, I had not the same problem again.

But now there are other issues. I have four new Gledopto 1ID LED controller. Nearly everything works as expected. But:
Every time I start the openHAB app on my tablet or smartphone and select the Basic UI, the LED-stripes controlled by the Gledopto-controllers are shown with the status “on”. But the stripes are off.

Then I turn the switch-button from “on” to “off” --> stripe is still off
Then I turn the switch-button from “off” to “on” --> stripe is going on
Then I turn the switch-button from “on” to “off” --> stripe is going off --> the right status is shown on the switch-button.
But when I turn the tablet to landscape mode, the switch shows status “on” again… with every Gledopto LED controller. The stripes are off.
Also the switch-button does not show the right color. All the time the switch is “green”, even if the switch is turned “off”.

Do you have any idea? Is there something wrong with the controllers?

Thank you in advance!

lukasg · December 30, 2020, 4:58pm

Got it!

In the item you have to add metadata “auto update” and click on “force auto update”.

lukasg · January 3, 2021, 6:34pm

Hello,

The four Gledopto devices are offline after some time…
Extract from events.log for device 00124b00222f9387:

2021-01-03 16:44:44.697 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ba1f317aca:00124b00222f9387' changed from ONLINE to OFFLINE

At same time here an extract from openhab.log for this device:

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:44.694 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:ba1f317aca:00124b00222f9387

Thank you in advance.

Greetings,
Lukas

chris · January 3, 2021, 6:38pm

Please provide the detailed log (as described in the binding docs) for at least 60 seconds before this event.

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.