[SOLVED] Zigbee Error Can't connect to devices

LuigiTheHunter · March 17, 2019, 6:17pm

I did not had a symlink, until now. Thats the reason why I had to change the Port after nearly every restart. But now the stick seems to be “online”, but all other zigbee devices are “unknown”.

This is what happens when I try to turn a Lamp on:

2019-03-17 19:00:32.510 [ome.event.ItemCommandEvent] - Item 'ls_livingroom' received command ON

2019-03-17 19:00:32.528 [nt.ItemStatePredictedEvent] - ls_livingroom predicted to become NULL

also I got this:

2019-03-17 19:36:20.519 [WARN ] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED2DB77: Polling aborted due to exception 

java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@da64cc rejected from java.util.concurrent.ScheduledThreadPoolExecutor@14f68f7[Shutting down, pool size = 3, active threads = 3, queued tasks = 0, completed tasks = 257]

	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063) ~[?:?]

	at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830) ~[?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(ScheduledThreadPoolExecutor.java:326) ~[?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(ScheduledThreadPoolExecutor.java:533) ~[?:?]

	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.scheduleTask(ZigBeeNetworkManager.java:559) ~[193:com.zsmartsystems.zigbee:1.1.6]

	at com.zsmartsystems.zigbee.transaction.ZigBeeTransaction.sendTransaction(ZigBeeTransaction.java:69) ~[193:com.zsmartsystems.zigbee:1.1.6]

	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.sendTransaction(ZigBeeNetworkManager.java:1439) ~[193:com.zsmartsystems.zigbee:1.1.6]

	at com.zsmartsystems.zigbee.ZigBeeNode.sendTransaction(ZigBeeNode.java:775) ~[193:com.zsmartsystems.zigbee:1.1.6]

	at com.zsmartsystems.zigbee.ZigBeeEndpoint.sendTransaction(ZigBeeEndpoint.java:501) ~[193:com.zsmartsystems.zigbee:1.1.6]

	at com.zsmartsystems.zigbee.zcl.ZclCluster.send(ZclCluster.java:158) ~[193:com.zsmartsystems.zigbee:1.1.6]

	at com.zsmartsystems.zigbee.zcl.ZclCluster.read(ZclCluster.java:174) ~[193:com.zsmartsystems.zigbee:1.1.6]

	at com.zsmartsystems.zigbee.zcl.ZclCluster.read(ZclCluster.java:184) ~[193:com.zsmartsystems.zigbee:1.1.6]

	at com.zsmartsystems.zigbee.zcl.ZclCluster.readSync(ZclCluster.java:233) ~[193:com.zsmartsystems.zigbee:1.1.6]

	at com.zsmartsystems.zigbee.zcl.clusters.ZclOnOffCluster.getOnOff(ZclOnOffCluster.java:136) ~[193:com.zsmartsystems.zigbee:1.1.6]

	at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel.handleRefresh(ZigBeeConverterSwitchLevel.java:127) ~[229:org.openhab.binding.zigbee:2.4.0]

	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$2.run(ZigBeeThingHandler.java:443) [229:org.openhab.binding.zigbee:2.4.0]

	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]

	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]

	at java.lang.Thread.run(Thread.java:748) [?:?]

And this
2019-03-17 19:57:48.855 [ERROR] [converter.ZigBeeConverterSwitchOnoff] - 001788010670E695: Error 0xffff setting client binding

EDIT:
I also have this issue now:
Initializing handler for thing 'zigbee:device:ba690b37:90fd9ffffe3497ef' takes more than 5000ms.

Also this was filled all the time before the issue:

But is always empty now…

Is there any way to fix this, without having to add all the zigbee devices again? Thanks in advance!

H102 · March 17, 2019, 7:55pm

Is openhab still a member of the tty group?

LuigiTheHunter · March 17, 2019, 8:01pm

Thanks for the quick answer, yes and of the dialout group aswell.

H102 · March 17, 2019, 8:04pm

If you switch on simple mode does OH auto discover all the devices? Note, that if you use files for all items you may end up with duplicates when turning on simple mode.

LuigiTheHunter · March 17, 2019, 8:07pm

Sorry but what is simple mode?

H102 · March 17, 2019, 8:11pm

In PaperUI, Configuration > System > Item Linking > Simple Mode

LuigiTheHunter · March 18, 2019, 7:12pm

When I turn that on literally nothing happens.

chris · March 19, 2019, 8:02am

This happens during shutdown - we probably need to trap and ignore the exception.

As it states, there was an error setting the bind. This is probably a timeout, but without a debug log, it’s pretty hard to say. This will be retried next time the binding starts. If it persists, please provide the log.

Please provide a debug log.

LuigiTheHunter · March 19, 2019, 7:07pm

Like this?:

tail -f /var/log/openhab2/openhab.log /var/log/openhab2/events.log
zigbee
2019-03-19 20:07:03.907 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:03.908 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-19 20:07:05.356 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 0: Node SVC Discovery: NetworkAddressRequest returned null

2019-03-19 20:07:05.357 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001936ACE6: Node SVC Discovery: request NWK_ADDRESS failed. Retry 3, wait 6528ms before retry.

2019-03-19 20:07:05.359 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ReadAttributesCommand [On/Off: 0/0 -> 23270/1, cluster=0006, TID=18, identifiers=[0]]

2019-03-19 20:07:05.365 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ManagementLqiRequest [0/0 -> 52957/0, cluster=0031, TID=19, startIndex=0]

2019-03-19 20:07:05.368 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update

2019-03-19 20:07:05.370 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 7CB03EAA0A01CE94

2019-03-19 20:07:05.371 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A01CE94: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.373 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A01CE94: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.375 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A01CE94: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.376 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 00124B001936ACE6

2019-03-19 20:07:05.378 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001936ACE6: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.379 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001936ACE6: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.381 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001936ACE6: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.383 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 000B57FFFED9D2F1

2019-03-19 20:07:05.384 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFED9D2F1: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.386 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFED9D2F1: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.387 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFED9D2F1: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.389 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 90FD9FFFFED59076

2019-03-19 20:07:05.391 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED59076: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.392 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED59076: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.394 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED59076: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS]

2019-03-19 20:07:05.396 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 7CB03EAA00AD38A7

2019-03-19 20:07:05.397 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA00AD38A7: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.399 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA00AD38A7: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.401 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA00AD38A7: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.404 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 90FD9FFFFE8EEDE7

2019-03-19 20:07:05.406 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE8EEDE7: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.407 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE8EEDE7: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.409 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE8EEDE7: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.419 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 90FD9FFFFE3497EF

2019-03-19 20:07:05.421 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE3497EF: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.422 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE3497EF: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.424 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE3497EF: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS]

2019-03-19 20:07:05.425 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 90FD9FFFFED343B8

2019-03-19 20:07:05.427 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED343B8: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.429 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED343B8: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.430 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED343B8: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.432 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 90FD9FFFFE8A5ECD

2019-03-19 20:07:05.433 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE8A5ECD: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.435 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE8A5ECD: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.437 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE8A5ECD: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.438 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 90FD9FFFFED2DB77

2019-03-19 20:07:05.440 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED2DB77: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.441 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED2DB77: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.447 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED2DB77: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.449 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 84182600000F1683

2019-03-19 20:07:05.451 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 84182600000F1683: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.452 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 84182600000F1683: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.454 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 84182600000F1683: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.456 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 0017880102487913

2019-03-19 20:07:05.457 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 0017880102487913: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.459 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 0017880102487913: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.460 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 0017880102487913: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.462 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 90FD9FFFFE88B7DA

2019-03-19 20:07:05.463 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE88B7DA: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.465 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE88B7DA: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.467 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE88B7DA: Node SVC Discovery: scheduled [NEIGHBORS, ROUTES]

2019-03-19 20:07:05.468 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 001788010670E695

2019-03-19 20:07:05.470 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 001788010670E695: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.471 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 001788010670E695: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.473 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 001788010670E695: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS]

2019-03-19 20:07:05.475 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 90FD9FFFFE752261

2019-03-19 20:07:05.476 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE752261: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.478 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE752261: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.479 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE752261: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.481 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 90FD9FFFFE860071

2019-03-19 20:07:05.483 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE860071: Node SVC Discovery: Update mesh

2019-03-19 20:07:05.484 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE860071: Node SVC Discovery: already scheduled or running

2019-03-19 20:07:05.486 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE860071: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]

2019-03-19 20:07:05.487 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ReadAttributesCommand [Level Control: 0/0 -> 35633/11, cluster=0008, TID=1A, identifiers=[0]]

2019-03-19 20:07:05.491 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=1B, ieeeAddr=7CB03EAA0A01CE94, requestType=0, startIndex=0]

2019-03-19 20:07:05.493 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ReadAttributesCommand [On/Off: 0/0 -> 32624/1, cluster=0006, TID=1C, identifiers=[0]]

2019-03-19 20:07:05.500 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ReadAttributesCommand [On/Off: 0/0 -> 19491/1, cluster=0006, TID=1D, identifiers=[0]]

2019-03-19 20:07:05.501 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE752261: Node SVC Discovery: running

2019-03-19 20:07:05.503 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=2F, ieeeAddr=90FD9FFFFE752261, requestType=0, startIndex=0]

2019-03-19 20:07:05.505 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65535/0, profile=0000, cluster=0, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=47, payload=00 61 22 75 FE FF 9F FD 90 00 00]

2019-03-19 20:07:06.419 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:06.420 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-19 20:07:07.426 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:07.428 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-19 20:07:09.936 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:09.939 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-19 20:07:10.885 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 11522: Node SVC Discovery: NetworkAddressRequest returned null

2019-03-19 20:07:10.890 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 001788010670E695: Node SVC Discovery: request NWK_ADDRESS failed. Retry 3, wait 4514ms before retry.

2019-03-19 20:07:10.893 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED343B8: Node SVC Discovery: running

2019-03-19 20:07:10.895 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=30, ieeeAddr=90FD9FFFFED343B8, requestType=0, startIndex=0]

2019-03-19 20:07:10.898 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65535/0, profile=0000, cluster=0, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=48, payload=00 B8 43 D3 FE FF 9F FD 90 00 00]

2019-03-19 20:07:12.449 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:12.451 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-19 20:07:13.464 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:13.465 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-19 20:07:15.975 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:15.980 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-19 20:07:16.421 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 43846: Node SVC Discovery: NetworkAddressRequest returned null

2019-03-19 20:07:16.423 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED2DB77: Node SVC Discovery: request NWK_ADDRESS failed. Retry 4, wait 11020ms before retry.

2019-03-19 20:07:16.424 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=1E, ieeeAddr=000B57FFFED9D2F1, requestType=0, startIndex=0]

2019-03-19 20:07:16.425 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE3497EF: Node SVC Discovery: running

2019-03-19 20:07:16.427 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=31, ieeeAddr=90FD9FFFFE3497EF, requestType=0, startIndex=0]

2019-03-19 20:07:16.429 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65535/0, profile=0000, cluster=0, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=49, payload=00 EF 97 34 FE FF 9F FD 90 00 00]

2019-03-19 20:07:18.490 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:18.493 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-19 20:07:19.507 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:19.509 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-19 20:07:21.520 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:21.523 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-19 20:07:22.465 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=114, lastReportTime=Sat Mar 16 18:50:55 CET 2019]

2019-03-19 20:07:22.467 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Level Control: 0/0 -> 39688/1, cluster=0008, TID=32, identifiers=[0]]

2019-03-19 20:07:22.469 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=50, commandId=0]

2019-03-19 20:07:22.472 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=39688/1, profile=0104, cluster=8, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=50, payload=00 32 00 00 00]

2019-03-19 20:07:23.537 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:23.538 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-19 20:07:24.545 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:24.546 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-19 20:07:26.553 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:26.557 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-19 20:07:28.495 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=114, lastReportTime=Sat Mar 16 18:50:56 CET 2019]

2019-03-19 20:07:28.498 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Level Control: 0/0 -> 43846/1, cluster=0008, TID=33, identifiers=[0]]

2019-03-19 20:07:28.500 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=51, commandId=0]

2019-03-19 20:07:28.503 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=43846/1, profile=0104, cluster=8, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=51, payload=00 33 00 00 00]

2019-03-19 20:07:28.565 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:28.566 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-19 20:07:29.574 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:29.575 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-19 20:07:31.589 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:31.595 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-19 20:07:33.539 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 35633: Node SVC Discovery: NetworkAddressRequest returned null

2019-03-19 20:07:33.542 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 0017880102487913: Node SVC Discovery: request NWK_ADDRESS failed. Retry 5, wait 12858ms before retry.

2019-03-19 20:07:33.545 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=1F, ieeeAddr=001788010670E695, requestType=0, startIndex=0]

2019-03-19 20:07:33.572 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=20, ieeeAddr=00124B001936ACE6, requestType=0, startIndex=0]

2019-03-19 20:07:33.576 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFED9D2F1: Node SVC Discovery: running

2019-03-19 20:07:33.578 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=34, ieeeAddr=000B57FFFED9D2F1, requestType=0, startIndex=0]

2019-03-19 20:07:33.581 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65535/0, profile=0000, cluster=0, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=52, payload=00 F1 D2 D9 FE FF 57 0B 00 00 00]

2019-03-19 20:07:33.678 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:33.680 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-19 20:07:34.687 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:34.690 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-19 20:07:37.200 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-19 20:07:37.206 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

chris · March 20, 2019, 8:04am

I’m not really sure of the context here. This doesn’t show any join command being sent, and no nodes are joining (as one would expect). There are simply no responses to any requests, and it seems that the dongle is not sending the data - in fact it seems it’s not even responding to any commands being sent.

A longer log is always helpful - probably from the binding start would be good so we can see if the dongle ever responds to commands or not.

LuigiTheHunter · March 21, 2019, 7:26pm

Here is the log: It hope there is some useful info inside

tail -f /var/log/openhab2/openhab.log /var/log/openhab2/events.log
zigbee
2019-03-21 20:25:06.780 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe88b7da' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:06.786 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:7cb03eaa00ad38a7' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:06.787 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed343b8' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:06.797 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe752261' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:06.799 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:7cb03eaa0a01ce94' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:06.804 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed59076' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:06.806 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:0017880102487913' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:06.808 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:84182600000f1683' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:06.810 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe8a5ecd' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:06.813 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe860071' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:06.815 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe8eede7' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2019-03-21 20:25:07.011 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.factoryPid=org.openhab.binding.zigbee.xbee)(service.factoryPid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee)(service.factoryPid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.xbee/2.4.0)))

2019-03-21 20:25:07.013 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.factoryPid=org.openhab.binding.zigbee.xbee)(service.factoryPid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee)(service.factoryPid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.xbee/2.4.0))

2019-03-21 20:25:07.019 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.pid=org.openhab.binding.zigbee.xbee)(service.pid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee)(service.pid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee|2.4.0)(service.pid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.xbee/2.4.0)))

2019-03-21 20:25:07.022 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.pid=org.openhab.binding.zigbee.xbee)(service.pid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee)(service.pid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee|2.4.0)(service.pid=org.openhab.binding.zigbee.xbee|org.openhab.binding.zigbee.xbee|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.xbee/2.4.0))

2019-03-21 20:25:07.072 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.binding.zigbee.xbee

2019-03-21 20:25:07.101 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.factoryPid=org.openhab.binding.zigbee.telegesis)(service.factoryPid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis)(service.factoryPid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.telegesis/2.4.0)))

2019-03-21 20:25:07.102 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.factoryPid=org.openhab.binding.zigbee.telegesis)(service.factoryPid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis)(service.factoryPid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.telegesis/2.4.0))

2019-03-21 20:25:07.104 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.pid=org.openhab.binding.zigbee.telegesis)(service.pid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis)(service.pid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis|2.4.0)(service.pid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.telegesis/2.4.0)))

2019-03-21 20:25:07.106 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.pid=org.openhab.binding.zigbee.telegesis)(service.pid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis)(service.pid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis|2.4.0)(service.pid=org.openhab.binding.zigbee.telegesis|org.openhab.binding.zigbee.telegesis|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.telegesis/2.4.0))

2019-03-21 20:25:07.108 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.factoryPid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant)(service.factoryPid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis)(service.factoryPid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.telegesis/2.4.0)))

2019-03-21 20:25:07.110 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.factoryPid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant)(service.factoryPid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis)(service.factoryPid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.telegesis/2.4.0))

2019-03-21 20:25:07.120 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.pid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant)(service.pid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis)(service.pid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis|2.4.0)(service.pid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.telegesis/2.4.0)))

2019-03-21 20:25:07.121 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.pid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant)(service.pid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis)(service.pid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis|2.4.0)(service.pid=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.telegesis|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.telegesis/2.4.0))

2019-03-21 20:25:07.131 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.binding.zigbee.telegesis

2019-03-21 20:25:07.183 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.factoryPid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant)(service.factoryPid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember)(service.factoryPid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.ember/2.4.0)))

2019-03-21 20:25:07.185 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.factoryPid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant)(service.factoryPid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember)(service.factoryPid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.ember/2.4.0))

2019-03-21 20:25:07.187 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.pid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant)(service.pid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember)(service.pid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember|2.4.0)(service.pid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.ember/2.4.0)))

2019-03-21 20:25:07.189 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.pid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant)(service.pid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember)(service.pid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember|2.4.0)(service.pid=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant|org.openhab.binding.zigbee.ember|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.ember/2.4.0))

2019-03-21 20:25:07.192 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.factoryPid=org.openhab.binding.zigbee.ember)(service.factoryPid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember)(service.factoryPid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.ember/2.4.0)))

2019-03-21 20:25:07.194 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.factoryPid=org.openhab.binding.zigbee.ember)(service.factoryPid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember)(service.factoryPid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.ember/2.4.0))

2019-03-21 20:25:07.196 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.pid=org.openhab.binding.zigbee.ember)(service.pid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember)(service.pid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember|2.4.0)(service.pid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.ember/2.4.0)))

2019-03-21 20:25:07.198 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.pid=org.openhab.binding.zigbee.ember)(service.pid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember)(service.pid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember|2.4.0)(service.pid=org.openhab.binding.zigbee.ember|org.openhab.binding.zigbee.ember|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.ember/2.4.0))

2019-03-21 20:25:07.208 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.binding.zigbee.ember

2019-03-21 20:25:07.284 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.factoryPid=org.openhab.binding.zigbee.cc2531)(service.factoryPid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531)(service.factoryPid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.cc2531/2.4.0)))

2019-03-21 20:25:07.288 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.factoryPid=org.openhab.binding.zigbee.cc2531)(service.factoryPid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531)(service.factoryPid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531|2.4.0)(service.factoryPid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.cc2531/2.4.0))

2019-03-21 20:25:07.291 [DEBUG] [org.apache.felix.configadmin        ] - listConfigurations(filter=(|(service.pid=org.openhab.binding.zigbee.cc2531)(service.pid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531)(service.pid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531|2.4.0)(service.pid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.cc2531/2.4.0)))

2019-03-21 20:25:07.295 [DEBUG] [org.apache.felix.configadmin        ] - Listing configurations matching (|(service.pid=org.openhab.binding.zigbee.cc2531)(service.pid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531)(service.pid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531|2.4.0)(service.pid=org.openhab.binding.zigbee.cc2531|org.openhab.binding.zigbee.cc2531|2.4.0|mvn:org.openhab.binding/org.openhab.binding.zigbee.cc2531/2.4.0))

2019-03-21 20:25:07.312 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.binding.zigbee.cc2531

2019-03-21 20:25:07.461 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:ba690b37' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING

2019-03-21 20:25:07.556 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:ba690b37' changed from INITIALIZING to UNKNOWN

2019-03-21 20:25:07.573 [INFO ] [internal.service.FeaturesServiceImpl] -   com.zsmartsystems.zigbee/1.1.6

2019-03-21 20:25:07.600 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed2db77' changed from UNINITIALIZED to INITIALIZING

2019-03-21 20:25:07.601 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:000b57fffed9d2f1' changed from UNINITIALIZED to INITIALIZING

2019-03-21 20:25:07.723 [DEBUG] [com.zsmartsystems.zigbee            ] - BundleEvent STARTING - com.zsmartsystems.zigbee

2019-03-21 20:25:07.756 [DEBUG] [com.zsmartsystems.zigbee            ] - BundleEvent STARTED - com.zsmartsystems.zigbee

2019-03-21 20:25:07.784 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle com.zsmartsystems.zigbee

2019-03-21 20:25:07.795 [INFO ] [internal.service.FeaturesServiceImpl] -   com.zsmartsystems.zigbee.dongle.xbee/1.1.6

2019-03-21 20:25:07.805 [DEBUG] [com.zsmartsystems.zigbee.dongle.xbee] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.xbee

2019-03-21 20:25:07.812 [DEBUG] [com.zsmartsystems.zigbee.dongle.xbee] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.xbee

2019-03-21 20:25:07.815 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle com.zsmartsystems.zigbee.dongle.xbee

2019-03-21 20:25:07.818 [INFO ] [internal.service.FeaturesServiceImpl] -   com.zsmartsystems.zigbee.dongle.telegesis/1.1.6

2019-03-21 20:25:07.831 [DEBUG] [smartsystems.zigbee.dongle.telegesis] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.telegesis

2019-03-21 20:25:07.837 [DEBUG] [smartsystems.zigbee.dongle.telegesis] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.telegesis

2019-03-21 20:25:07.848 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle com.zsmartsystems.zigbee.dongle.telegesis

2019-03-21 20:25:07.852 [INFO ] [internal.service.FeaturesServiceImpl] -   com.zsmartsystems.zigbee.dongle.ember/1.1.6

2019-03-21 20:25:07.856 [DEBUG] [om.zsmartsystems.zigbee.dongle.ember] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.ember

2019-03-21 20:25:07.867 [DEBUG] [om.zsmartsystems.zigbee.dongle.ember] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.ember

2019-03-21 20:25:07.878 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle com.zsmartsystems.zigbee.dongle.ember

2019-03-21 20:25:07.888 [INFO ] [internal.service.FeaturesServiceImpl] -   com.zsmartsystems.zigbee.dongle.cc2531/1.1.6

2019-03-21 20:25:07.894 [DEBUG] [m.zsmartsystems.zigbee.dongle.cc2531] - BundleEvent STARTING - com.zsmartsystems.zigbee.dongle.cc2531

2019-03-21 20:25:07.904 [DEBUG] [m.zsmartsystems.zigbee.dongle.cc2531] - BundleEvent STARTED - com.zsmartsystems.zigbee.dongle.cc2531

2019-03-21 20:25:07.909 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle com.zsmartsystems.zigbee.dongle.cc2531

2019-03-21 20:25:12.581 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:90fd9ffffed2db77' takes more than 5000ms.

2019-03-21 20:25:12.595 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:000b57fffed9d2f1' takes more than 5000ms.

2019-03-21 20:25:12.602 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:90fd9ffffe3497ef' takes more than 5000ms.

2019-03-21 20:25:12.846 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:90fd9ffffe8a5ecd' takes more than 5000ms.

2019-03-21 20:25:12.846 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:84182600000f1683' takes more than 5000ms.

2019-03-21 20:25:17.607 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:001788010670e695' takes more than 5000ms.

2019-03-21 20:25:17.626 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:90fd9ffffe88b7da' takes more than 5000ms.

2019-03-21 20:25:17.632 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:7cb03eaa00ad38a7' takes more than 5000ms.

2019-03-21 20:25:17.863 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:90fd9ffffed343b8' takes more than 5000ms.

2019-03-21 20:25:17.866 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:90fd9ffffe752261' takes more than 5000ms.

2019-03-21 20:25:22.640 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:7cb03eaa0a01ce94' takes more than 5000ms.

2019-03-21 20:25:22.651 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:90fd9ffffe8eede7' takes more than 5000ms.

2019-03-21 20:25:22.654 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:0017880102487913' takes more than 5000ms.

2019-03-21 20:25:22.881 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:90fd9ffffe860071' takes more than 5000ms.

2019-03-21 20:25:22.890 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:device:ba690b37:90fd9ffffed59076' takes more than 5000ms.

LuigiTheHunter · March 21, 2019, 9:45pm

And this

tail -f /var/log/openhab2/openhab.log /var/log/openhab2/events.log
zigbee
2019-03-21 22:44:32.662 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=false, lastReportTime=Sat Mar 16 18:45:36 CET 2019]

2019-03-21 22:44:32.664 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0/0 -> 27034/3, cluster=0006, TID=79, identifiers=[0]]

2019-03-21 22:44:32.667 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=121, commandId=0]

2019-03-21 22:44:32.668 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=27034/3, profile=0104, cluster=6, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=121, payload=00 79 00 00 00]

2019-03-21 22:44:33.275 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:33.276 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-21 22:44:34.285 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:34.286 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-21 22:44:36.797 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:36.799 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-21 22:44:37.702 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Sat Mar 16 18:45:59 CET 2019]

2019-03-21 22:44:37.705 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0/0 -> 1752/1, cluster=0006, TID=7A, identifiers=[0]]

2019-03-21 22:44:37.707 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=122, commandId=0]

2019-03-21 22:44:37.709 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=1752/1, profile=0104, cluster=6, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=122, payload=00 7A 00 00 00]

2019-03-21 22:44:39.309 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:39.311 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-21 22:44:40.319 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:40.325 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-21 22:44:42.334 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:42.336 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-21 22:44:43.285 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=140, lastReportTime=Sat Mar 16 18:46:21 CET 2019]

2019-03-21 22:44:43.287 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Level Control: 0/0 -> 35633/11, cluster=0008, TID=7B, identifiers=[0]]

2019-03-21 22:44:43.296 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=123, commandId=0]

2019-03-21 22:44:43.299 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=35633/11, profile=0104, cluster=8, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=123, payload=00 7B 00 00 00]

2019-03-21 22:44:44.345 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:44.348 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-21 22:44:45.360 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:45.361 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-21 22:44:47.879 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:47.883 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-21 22:44:49.313 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED2DB77: Node SVC Discovery: ManagementLqiRequest response CommandResult [TIMEOUT]

2019-03-21 22:44:49.315 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFED2DB77: Node SVC Discovery: request NEIGHBORS failed. Retry 8, wait 16079ms before retry.

2019-03-21 22:44:49.317 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ManagementLqiRequest [0/0 -> 27034/0, cluster=0031, TID=65, startIndex=0]

2019-03-21 22:44:49.322 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ManagementLqiRequest [0/0 -> 25806/0, cluster=0031, TID=66, startIndex=0]

2019-03-21 22:44:49.326 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ReadAttributesCommand [Level Control: 0/0 -> 19491/1, cluster=0008, TID=67, identifiers=[0]]

2019-03-21 22:44:49.329 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE88B7DA: Node SVC Discovery: running

2019-03-21 22:44:49.331 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 52957/0, cluster=0031, TID=7C, startIndex=0]

2019-03-21 22:44:49.334 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=52957/0, profile=0000, cluster=49, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=124, payload=00 00]

2019-03-21 22:44:49.899 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:49.900 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-21 22:44:50.914 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:50.916 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-21 22:44:53.429 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:53.431 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-21 22:44:54.351 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Sat Mar 16 18:45:25 CET 2019]

2019-03-21 22:44:54.352 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0/0 -> 23270/1, cluster=0006, TID=7D, identifiers=[0]]

2019-03-21 22:44:54.353 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=125, commandId=0]

2019-03-21 22:44:54.355 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=23270/1, profile=0104, cluster=6, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=125, payload=00 7D 00 00 00]

2019-03-21 22:44:55.952 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:55.954 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-21 22:44:56.982 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:56.983 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-21 22:44:59.500 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:44:59.501 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

2019-03-21 22:44:59.902 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE860071: Node SVC Discovery: ManagementLqiRequest response CommandResult [TIMEOUT]

2019-03-21 22:44:59.903 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 90FD9FFFFE860071: Node SVC Discovery: request NEIGHBORS failed. Retry 5, wait 6468ms before retry.

2019-03-21 22:44:59.904 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ReadAttributesCommand [On/Off: 0/0 -> 39688/1, cluster=0006, TID=68, identifiers=[0]]

2019-03-21 22:44:59.906 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFED9D2F1: Node SVC Discovery: running

2019-03-21 22:44:59.907 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=7E, ieeeAddr=000B57FFFED9D2F1, requestType=0, startIndex=0]

2019-03-21 22:44:59.909 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65535/0, profile=0000, cluster=0, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=126, payload=00 F1 D2 D9 FE FF 57 0B 00 00 00]

2019-03-21 22:45:01.514 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:45:01.517 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 3]

2019-03-21 22:45:02.543 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:45:02.546 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 1]

2019-03-21 22:45:04.558 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - AF_DATA_REQUEST executed and timed out while waiting for response.

2019-03-21 22:45:04.560 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Failed to send AF_DATA_REQUEST [attempt 2]

chris · March 21, 2019, 10:33pm

Why is there a 20 minute gap between these logs

LuigiTheHunter · March 22, 2019, 4:23pm

Sorry for that but im using the tail website, and at some point it just goes blank. I saved both logs before that happend.

chris · March 22, 2019, 4:44pm

I’m not really sure I understand. Do you have the complete log? The problem is that the beginning of the log (ie the first part) hasn’t really started the initialisation, and the second part (20 minutes late) there are problems. Somewhere in the middle (ie the part that’s missing) is what I need to see.

LuigiTheHunter · March 22, 2019, 4:50pm

Ah ok thanks for explaining im using this website to get the log “http://openhabian:9001/?filter=zigbee” but it clears itself after some hundred lines. Thats why there is a missing part.

chris · March 22, 2019, 4:50pm

Ok, I’m not familair with that - I’d recommend to use the raw logs which should not have this problem.

LuigiTheHunter · March 22, 2019, 4:56pm

Yeah sure, sorry to be so dumb but I don’t know how to get them, another way…

chris · March 22, 2019, 4:58pm

Take a look at the docs -:

LuigiTheHunter · March 22, 2019, 5:46pm

Ok sorry for that.

Here are the logs I first had to figure out how to capture the logs…

	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.rescheduleTask(ZigBeeNetworkManager.java:577) ~[294:com.zsmartsystems.zigbee:1.1.6]
	at com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer$NodeServiceDiscoveryTask.run(ZigBeeNodeServiceDiscoverer.java:632) [294:com.zsmartsystems.zigbee:1.1.6]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.rescheduleTask(ZigBeeNetworkManager.java:577) ~[294:com.zsmartsystems.zigbee:1.1.6]
	at com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer$NodeServiceDiscoveryTask.run(ZigBeeNodeServiceDiscoverer.java:632) [294:com.zsmartsystems.zigbee:1.1.6]
2019-03-22 18:26:08.320 [INFO ] [internal.service.FeaturesServiceImpl] - Adding features: openhab-binding-zigbee/[2.4.0,2.4.0]
2019-03-22 18:26:17.714 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/1.1.6
2019-03-22 18:26:17.715 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:com.zsmartsystems.zigbee/com.zsmartsystems.zigbee.dongle.cc2531/1.1.6
2019-03-22 18:26:17.717 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:com.zsmartsystems.zigbee/com.zsmartsystems.zigbee.dongle.ember/1.1.6
2019-03-22 18:26:17.718 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:com.zsmartsystems.zigbee/com.zsmartsystems.zigbee.dongle.telegesis/1.1.6
2019-03-22 18:26:17.720 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:com.zsmartsystems.zigbee/com.zsmartsystems.zigbee.dongle.xbee/1.1.6
2019-03-22 18:26:17.722 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:org.openhab.binding/org.openhab.binding.zigbee/2.4.0
2019-03-22 18:26:17.723 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:org.openhab.binding/org.openhab.binding.zigbee.cc2531/2.4.0
2019-03-22 18:26:17.725 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:org.openhab.binding/org.openhab.binding.zigbee.ember/2.4.0
2019-03-22 18:26:17.727 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:org.openhab.binding/org.openhab.binding.zigbee.telegesis/2.4.0
2019-03-22 18:26:17.728 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:org.openhab.binding/org.openhab.binding.zigbee.xbee/2.4.0
2019-03-22 18:26:17.739 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/1.1.6
2019-03-22 18:26:17.861 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:com.zsmartsystems.zigbee/com.zsmartsystems.zigbee.dongle.cc2531/1.1.6
2019-03-22 18:26:17.888 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:com.zsmartsystems.zigbee/com.zsmartsystems.zigbee.dongle.ember/1.1.6
2019-03-22 18:26:18.183 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:com.zsmartsystems.zigbee/com.zsmartsystems.zigbee.dongle.telegesis/1.1.6
2019-03-22 18:26:18.201 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:com.zsmartsystems.zigbee/com.zsmartsystems.zigbee.dongle.xbee/1.1.6
2019-03-22 18:26:18.218 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:org.openhab.binding/org.openhab.binding.zigbee/2.4.0
2019-03-22 18:26:18.238 [DEBUG] [org.openhab.binding.zigbee          ] - BundleEvent INSTALLED - org.openhab.binding.zigbee
2019-03-22 18:26:18.241 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:org.openhab.binding/org.openhab.binding.zigbee.cc2531/2.4.0
2019-03-22 18:26:18.251 [DEBUG] [org.openhab.binding.zigbee.cc2531   ] - BundleEvent INSTALLED - org.openhab.binding.zigbee.cc2531
2019-03-22 18:26:18.254 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:org.openhab.binding/org.openhab.binding.zigbee.ember/2.4.0
2019-03-22 18:26:18.266 [DEBUG] [org.openhab.binding.zigbee.ember    ] - BundleEvent INSTALLED - org.openhab.binding.zigbee.ember
2019-03-22 18:26:18.269 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:org.openhab.binding/org.openhab.binding.zigbee.telegesis/2.4.0
2019-03-22 18:26:18.279 [DEBUG] [org.openhab.binding.zigbee.telegesis] - BundleEvent INSTALLED - org.openhab.binding.zigbee.telegesis
2019-03-22 18:26:18.281 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:org.openhab.binding/org.openhab.binding.zigbee.xbee/2.4.0
2019-03-22 18:26:18.291 [DEBUG] [org.openhab.binding.zigbee.xbee     ] - BundleEvent INSTALLED - org.openhab.binding.zigbee.xbee
2019-03-22 18:26:18.618 [DEBUG] [org.openhab.binding.zigbee          ] - BundleEvent RESOLVED - org.openhab.binding.zigbee
2019-03-22 18:26:18.634 [DEBUG] [org.openhab.binding.zigbee.xbee     ] - BundleEvent RESOLVED - org.openhab.binding.zigbee.xbee
2019-03-22 18:26:18.647 [DEBUG] [org.openhab.binding.zigbee.telegesis] - BundleEvent RESOLVED - org.openhab.binding.zigbee.telegesis
2019-03-22 18:26:18.667 [DEBUG] [org.openhab.binding.zigbee.ember    ] - BundleEvent RESOLVED - org.openhab.binding.zigbee.ember
2019-03-22 18:26:18.683 [DEBUG] [org.openhab.binding.zigbee.cc2531   ] - BundleEvent RESOLVED - org.openhab.binding.zigbee.cc2531
2019-03-22 18:26:18.782 [DEBUG] [org.openhab.binding.zigbee          ] - BundleEvent STARTING - org.openhab.binding.zigbee
2019-03-22 18:26:18.803 [DEBUG] [org.openhab.binding.zigbee          ] - BundleEvent STARTED - org.openhab.binding.zigbee
2019-03-22 18:26:18.831 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=472, service.bundleid=309, service.scope=bundle, component.name=org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService, component.id=271} - org.openhab.binding.zigbee
2019-03-22 18:26:18.881 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.openhab.binding.zigbee.internal.converter.ZigBeeChannelConverterFactory}={service.id=473, service.bundleid=309, service.scope=bundle, component.name=org.openhab.binding.zigbee.internal.converter.ZigBeeChannelConverterFactory, component.id=272} - org.openhab.binding.zigbee
2019-03-22 18:26:18.906 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=474, service.bundleid=309, service.scope=bundle, component.name=org.openhab.binding.zigbee.internal.ZigBeeHandlerFactory, component.id=273} - org.openhab.binding.zigbee
2019-03-22 18:26:18.935 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryParticipant}={service.id=475, service.bundleid=309, service.scope=bundle, component.name=org.openhab.binding.zigbee.discovery.internal.ZigBeeDefaultDiscoveryParticipant, component.id=274} - org.openhab.binding.zigbee
2019-03-22 18:26:18.990 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed59076' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:18.998 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:0017880102487913' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.008 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:84182600000f1683' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.008 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.openhab.binding.zigbee.converter.ZigBeeChannelConverterProvider}={service.id=476, service.bundleid=309, service.scope=bundle, component.name=org.openhab.binding.zigbee.internal.converter.ZigBeeDefaultChannelConverterProvider, component.id=275} - org.openhab.binding.zigbee
2019-03-22 18:26:19.015 [DEBUG] [org.openhab.binding.zigbee          ] - BundleEvent [unknown:512] - org.openhab.binding.zigbee
2019-03-22 18:26:19.016 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe8a5ecd' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.023 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe860071' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.030 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe3497ef' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.036 [DEBUG] [org.openhab.binding.zigbee.xbee     ] - BundleEvent STARTING - org.openhab.binding.zigbee.xbee
2019-03-22 18:26:19.037 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed2db77' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.043 [DEBUG] [org.openhab.binding.zigbee.xbee     ] - BundleEvent STARTED - org.openhab.binding.zigbee.xbee
2019-03-22 18:26:19.046 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:000b57fffed9d2f1' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.054 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe8eede7' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.060 [DEBUG] [org.openhab.binding.zigbee.xbee     ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=477, service.bundleid=313, service.scope=bundle, component.name=org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory, component.id=276} - org.openhab.binding.zigbee.xbee
2019-03-22 18:26:19.062 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:001788010670e695' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.070 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe88b7da' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.071 [DEBUG] [org.openhab.binding.zigbee.xbee     ] - BundleEvent [unknown:512] - org.openhab.binding.zigbee.xbee
2019-03-22 18:26:19.077 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:7cb03eaa00ad38a7' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.085 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed343b8' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.093 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe752261' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.100 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:7cb03eaa0a01ce94' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-03-22 18:26:19.109 [DEBUG] [org.openhab.binding.zigbee.telegesis] - BundleEvent STARTING - org.openhab.binding.zigbee.telegesis
2019-03-22 18:26:19.116 [DEBUG] [org.openhab.binding.zigbee.telegesis] - BundleEvent STARTED - org.openhab.binding.zigbee.telegesis
2019-03-22 18:26:19.131 [DEBUG] [org.openhab.binding.zigbee.telegesis] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=478, service.bundleid=312, service.scope=bundle, component.name=org.openhab.binding.zigbee.telegesis.internal.TelegesisHandlerFactory, component.id=277} - org.openhab.binding.zigbee.telegesis
2019-03-22 18:26:19.151 [DEBUG] [org.openhab.binding.zigbee.telegesis] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.usbserial.UsbSerialDiscoveryParticipant}={service.id=479, service.bundleid=312, service.scope=bundle, component.name=org.openhab.binding.zigbee.telegesis.internal.discovery.ZigBeeTelegesisUsbSerialDiscoveryParticipant, component.id=278} - org.openhab.binding.zigbee.telegesis
2019-03-22 18:26:19.155 [DEBUG] [org.openhab.binding.zigbee.telegesis] - BundleEvent [unknown:512] - org.openhab.binding.zigbee.telegesis
2019-03-22 18:26:19.178 [DEBUG] [org.openhab.binding.zigbee.ember    ] - BundleEvent STARTING - org.openhab.binding.zigbee.ember
2019-03-22 18:26:19.185 [DEBUG] [org.openhab.binding.zigbee.ember    ] - BundleEvent STARTED - org.openhab.binding.zigbee.ember
2019-03-22 18:26:19.198 [DEBUG] [org.openhab.binding.zigbee.ember    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.usbserial.UsbSerialDiscoveryParticipant}={service.id=480, service.bundleid=311, service.scope=bundle, component.name=org.openhab.binding.zigbee.ember.internal.discovery.ZigBeeEmberUsbSerialDiscoveryParticipant, component.id=279} - org.openhab.binding.zigbee.ember
2019-03-22 18:26:19.217 [DEBUG] [org.openhab.binding.zigbee.ember    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=481, service.bundleid=311, service.scope=bundle, component.name=org.openhab.binding.zigbee.ember.internal.EmberHandlerFactory, component.id=280} - org.openhab.binding.zigbee.ember
2019-03-22 18:26:19.224 [DEBUG] [org.openhab.binding.zigbee.ember    ] - BundleEvent [unknown:512] - org.openhab.binding.zigbee.ember
2019-03-22 18:26:19.242 [DEBUG] [org.openhab.binding.zigbee.cc2531   ] - BundleEvent STARTING - org.openhab.binding.zigbee.cc2531
2019-03-22 18:26:19.247 [DEBUG] [org.openhab.binding.zigbee.cc2531   ] - BundleEvent STARTED - org.openhab.binding.zigbee.cc2531
2019-03-22 18:26:19.276 [DEBUG] [org.openhab.binding.zigbee.cc2531   ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=482, service.bundleid=310, service.scope=bundle, component.name=org.openhab.binding.zigbee.cc2531.internal.CC2531HandlerFactory, component.id=281} - org.openhab.binding.zigbee.cc2531
2019-03-22 18:26:19.302 [DEBUG] [org.openhab.binding.zigbee.cc2531   ] - ServiceEvent REGISTERED - {org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler}={service.id=483, service.bundleid=310, service.scope=singleton} - org.openhab.binding.zigbee.cc2531
2019-03-22 18:26:19.348 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:ba690b37' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2019-03-22 18:26:19.366 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - Initializing ZigBee CC2531 serial bridge handler.
2019-03-22 18:26:19.368 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_cc2531:ba690b37].
2019-03-22 18:26:19.387 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
2019-03-22 18:26:19.479 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - ZigBee CC2531 Coordinator opening Port:'/dev/ttyACM0' PAN:fffe, EPAN:4672150DCEDC2497, Channel:11
2019-03-22 18:26:19.493 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:ba690b37' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:19.501 [DEBUG] [org.openhab.binding.zigbee.cc2531   ] - BundleEvent [unknown:512] - org.openhab.binding.zigbee.cc2531
2019-03-22 18:26:19.518 [INFO ] [internal.service.FeaturesServiceImpl] -   com.zsmartsystems.zigbee/1.1.6
2019-03-22 18:26:19.552 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=484, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.553 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=486, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.554 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=485, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.566 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=487, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.570 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=489, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.571 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=490, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.589 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=488, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.606 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=493, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.592 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=492, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.603 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=491, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.620 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=494, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.626 [INFO ] [internal.service.FeaturesServiceImpl] -   com.zsmartsystems.zigbee.dongle.xbee/1.1.6
2019-03-22 18:26:19.638 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=495, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.642 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=496, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.646 [INFO ] [internal.service.FeaturesServiceImpl] -   com.zsmartsystems.zigbee.dongle.ember/1.1.6
2019-03-22 18:26:19.653 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=497, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.740 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=498, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.750 [INFO ] [internal.service.FeaturesServiceImpl] -   com.zsmartsystems.zigbee.dongle.telegesis/1.1.6
2019-03-22 18:26:19.715 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:000b57fffed9d2f1' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:19.763 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe88b7da' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:19.767 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe8a5ecd' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:19.768 [INFO ] [internal.service.FeaturesServiceImpl] -   com.zsmartsystems.zigbee.dongle.cc2531/1.1.6
2019-03-22 18:26:19.771 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe3497ef' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:19.785 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed2db77' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:19.791 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE88B7DA: Initializing ZigBee thing handler zigbee:device:ba690b37:90fd9ffffe88b7da
2019-03-22 18:26:19.791 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8A5ECD: Initializing ZigBee thing handler zigbee:device:ba690b37:90fd9ffffe8a5ecd
2019-03-22 18:26:19.793 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFED9D2F1: Initializing ZigBee thing handler zigbee:device:ba690b37:000b57fffed9d2f1
2019-03-22 18:26:19.791 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED2DB77: Initializing ZigBee thing handler zigbee:device:ba690b37:90fd9ffffed2db77
2019-03-22 18:26:19.794 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE3497EF: Initializing ZigBee thing handler zigbee:device:ba690b37:90fd9ffffe3497ef
2019-03-22 18:26:19.798 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED2DB77: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:19.799 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFED9D2F1: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:19.802 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8A5ECD: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:19.800 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED2DB77: Coordinator is unknown or not online.
2019-03-22 18:26:19.804 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE3497EF: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:19.804 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed2db77' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:19.807 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8A5ECD: Coordinator is unknown or not online.
2019-03-22 18:26:19.808 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFED9D2F1: Coordinator is unknown or not online.
2019-03-22 18:26:19.810 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE88B7DA: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:19.814 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE3497EF: Coordinator is unknown or not online.
2019-03-22 18:26:19.816 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:000b57fffed9d2f1' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:19.814 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE88B7DA: Coordinator is unknown or not online.
2019-03-22 18:26:19.813 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=499, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.825 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=500, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.829 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe8a5ecd' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:19.833 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe3497ef' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:19.834 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=501, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.841 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=503, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.841 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=502, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.850 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=504, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.835 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED2DB77: Channel zigbee:device:ba690b37:90fd9ffffed2db77:90FD9FFFFED2DB77_1_dimmer linked - polling started.
2019-03-22 18:26:19.856 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe88b7da' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:19.858 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFED9D2F1: Channel zigbee:device:ba690b37:000b57fffed9d2f1:000B57FFFED9D2F1_1_dimmer linked - polling started.
2019-03-22 18:26:19.858 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8A5ECD: Channel zigbee:device:ba690b37:90fd9ffffe8a5ecd:90FD9FFFFE8A5ECD_1_dimmer linked - polling started.
2019-03-22 18:26:19.862 [thome.event.ExtensionEvent] - Extension 'binding-zigbee' has been installed.
2019-03-22 18:26:19.868 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=506, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.877 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=509, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.851 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=505, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.873 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE88B7DA: Channel zigbee:device:ba690b37:90fd9ffffe88b7da:90FD9FFFFE88B7DA_1_dimmer linked - polling started.
2019-03-22 18:26:19.873 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=507, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.877 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=508, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.902 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe860071' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:19.900 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=510, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.903 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE860071: Initializing ZigBee thing handler zigbee:device:ba690b37:90fd9ffffe860071
2019-03-22 18:26:19.907 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE860071: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:19.909 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe860071' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:19.910 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE860071: Channel zigbee:device:ba690b37:90fd9ffffe860071:90FD9FFFFE860071_1_dimmer linked - polling started.
2019-03-22 18:26:19.911 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE860071: Coordinator is unknown or not online.
2019-03-22 18:26:19.916 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=513, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.912 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=512, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.918 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=511, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.918 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=514, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.927 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=515, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.941 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe8eede7' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:19.945 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED59076: Initializing ZigBee thing handler zigbee:device:ba690b37:90fd9ffffed59076
2019-03-22 18:26:19.946 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed59076' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:19.949 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED59076: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:19.951 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED59076: Coordinator is unknown or not online.
2019-03-22 18:26:19.953 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed59076' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:19.955 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED343B8: Initializing ZigBee thing handler zigbee:device:ba690b37:90fd9ffffed343b8
2019-03-22 18:26:19.954 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8EEDE7: Initializing ZigBee thing handler zigbee:device:ba690b37:90fd9ffffe8eede7
2019-03-22 18:26:19.958 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED343B8: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:19.958 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8EEDE7: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:19.961 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8EEDE7: Coordinator is unknown or not online.
2019-03-22 18:26:19.961 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED343B8: Coordinator is unknown or not online.
2019-03-22 18:26:19.965 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=516, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.973 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=518, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.973 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=517, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.975 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed343b8' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:19.978 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8EEDE7: Channel zigbee:device:ba690b37:90fd9ffffe8eede7:90FD9FFFFE8EEDE7_1_dimmer linked - polling started.
2019-03-22 18:26:19.979 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED343B8: Channel zigbee:device:ba690b37:90fd9ffffed343b8:90FD9FFFFED343B8_1_dimmer linked - polling started.
2019-03-22 18:26:19.982 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe752261' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:19.985 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe8eede7' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:19.985 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=519, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.987 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed343b8' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:19.990 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE752261: Initializing ZigBee thing handler zigbee:device:ba690b37:90fd9ffffe752261
2019-03-22 18:26:19.993 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=520, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:19.999 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE752261: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:20.002 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe752261' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:20.004 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 84182600000F1683: Initializing ZigBee thing handler zigbee:device:ba690b37:84182600000f1683
2019-03-22 18:26:20.009 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=521, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:20.009 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 84182600000F1683: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:20.014 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=522, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:20.016 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE752261: Channel zigbee:device:ba690b37:90fd9ffffe752261:90FD9FFFFE752261_1_dimmer linked - polling started.
2019-03-22 18:26:20.013 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=523, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:20.019 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 84182600000F1683: Coordinator is unknown or not online.
2019-03-22 18:26:20.025 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00AD38A7: Initializing ZigBee thing handler zigbee:device:ba690b37:7cb03eaa00ad38a7
2019-03-22 18:26:20.026 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:84182600000f1683' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:20.029 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00AD38A7: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:20.031 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00AD38A7: Coordinator is unknown or not online.
2019-03-22 18:26:20.037 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 84182600000F1683: Channel zigbee:device:ba690b37:84182600000f1683:84182600000F1683_3_switch linked - polling started.
2019-03-22 18:26:20.036 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:84182600000f1683' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:20.024 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE752261: Coordinator is unknown or not online.
2019-03-22 18:26:20.042 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:7cb03eaa00ad38a7' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:20.049 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:7cb03eaa00ad38a7' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:20.051 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00AD38A7: Channel zigbee:device:ba690b37:7cb03eaa00ad38a7:7CB03EAA00AD38A7_3_switch linked - polling started.
2019-03-22 18:26:20.055 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=524, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:20.055 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=525, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:20.064 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=527, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:20.065 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=526, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:20.067 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:001788010670e695' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:20.071 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 001788010670E695: Initializing ZigBee thing handler zigbee:device:ba690b37:001788010670e695
2019-03-22 18:26:20.075 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 001788010670E695: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:20.078 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102487913: Initializing ZigBee thing handler zigbee:device:ba690b37:0017880102487913
2019-03-22 18:26:20.078 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:001788010670e695' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:20.081 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:0017880102487913' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:20.083 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102487913: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:20.083 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 001788010670E695: Channel zigbee:device:ba690b37:001788010670e695:001788010670E695_1_switch linked - polling started.
2019-03-22 18:26:20.085 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102487913: Coordinator is unknown or not online.
2019-03-22 18:26:20.078 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 001788010670E695: Coordinator is unknown or not online.
2019-03-22 18:26:20.088 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:0017880102487913' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:20.090 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102487913: Channel zigbee:device:ba690b37:0017880102487913:0017880102487913_11_dimmer linked - polling started.
2019-03-22 18:26:20.097 [DEBUG] [org.openhab.binding.zigbee          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=528, service.bundleid=309, service.scope=singleton} - org.openhab.binding.zigbee
2019-03-22 18:26:20.108 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:7cb03eaa0a01ce94' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-03-22 18:26:20.113 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A01CE94: Initializing ZigBee thing handler zigbee:device:ba690b37:7cb03eaa0a01ce94
2019-03-22 18:26:20.117 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A01CE94: Coordinator status changed to UNKNOWN.
2019-03-22 18:26:20.120 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A01CE94: Coordinator is unknown or not online.
2019-03-22 18:26:20.119 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:7cb03eaa0a01ce94' changed from INITIALIZING to UNKNOWN
2019-03-22 18:26:20.120 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A01CE94: Channel zigbee:device:ba690b37:7cb03eaa0a01ce94:7CB03EAA0A01CE94_3_switch linked - polling started.
2019-03-22 18:26:22.316 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyACM0] at 115200 baud, flow control FLOWCONTROL_OUT_RTSCTS.
2019-03-22 18:26:22.329 [ERROR] [ding.zigbee.handler.ZigBeeSerialPort] - Serial Error: Port /dev/ttyACM0 does not exist.
2019-03-22 18:26:22.340 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE3497EF: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.344 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED2DB77: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.353 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:ba690b37' changed from UNKNOWN to OFFLINE: Failed to open communications port
2019-03-22 18:26:22.355 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED2DB77: Coordinator is unknown or not online.
2019-03-22 18:26:22.357 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe3497ef' changed from UNKNOWN to OFFLINE (BRIDGE_OFFLINE)
2019-03-22 18:26:22.348 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE88B7DA: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.366 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE88B7DA: Coordinator is unknown or not online.
2019-03-22 18:26:22.369 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE752261: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.371 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffed2db77' changed from UNKNOWN to OFFLINE (BRIDGE_OFFLINE)
2019-03-22 18:26:22.383 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:000b57fffed9d2f1' changed from UNKNOWN to OFFLINE (BRIDGE_OFFLINE)
2019-03-22 18:26:22.385 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe8a5ecd' changed from UNKNOWN to OFFLINE (BRIDGE_OFFLINE)
2019-03-22 18:26:22.346 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFED9D2F1: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.346 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8A5ECD: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.388 [hingStatusInfoChangedEvent] - 'zigbee:device:ba690b37:90fd9ffffe88b7da' changed from UNKNOWN to OFFLINE (BRIDGE_OFFLINE)
2019-03-22 18:26:22.375 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED343B8: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.390 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFED9D2F1: Coordinator is unknown or not online.
2019-03-22 18:26:22.391 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED343B8: Coordinator is unknown or not online.
2019-03-22 18:26:22.342 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE3497EF: Coordinator is unknown or not online.
2019-03-22 18:26:22.394 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8EEDE7: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.394 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE860071: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.396 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8EEDE7: Coordinator is unknown or not online.
2019-03-22 18:26:22.398 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED59076: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.400 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED59076: Coordinator is unknown or not online.
2019-03-22 18:26:22.403 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE752261: Coordinator is unknown or not online.
2019-03-22 18:26:22.405 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE8A5ECD: Coordinator is unknown or not online.
2019-03-22 18:26:22.405 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFE860071: Coordinator is unknown or not online.
2019-03-22 18:26:22.407 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00AD38A7: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.407 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 001788010670E695: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.410 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00AD38A7: Coordinator is unknown or not online.
2019-03-22 18:26:22.410 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 001788010670E695: Coordinator is unknown or not online.
2019-03-22 18:26:22.411 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A01CE94: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.414 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A01CE94: Coordinator is unknown or not online.
2019-03-22 18:26:22.414 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 90FD9FFFFED2DB77: Coordinator status changed to OFFLINE.
2019-03-22 18:26:22.415 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 84182600000F1683: