Sengled Zigbee Bulbs don't work properly

[Jon_A]

• Platform information:
  • Hardware: Rasberri Pi 3, 8GB with the Ember HUSBZB zwave/zigbee combo stick
  • OS: Openhabian 2.5.10
  • Issue of the topic: When adding Sengled zigbee bulbs, they either stay offline, or show online but then don’t actually work.

I have added Osram zigbee bulbs, and GE zigbee bulbs, and they all work fine.

It’s also worth noting that with the exact same hardware when I previously ran home assistant (HASSIO), I was able to add these 4 bulbs with no issues and they all worked fine.

I turned on debug logging for zigbee; for Sengled_3rd_Bulb_log.txt, I have 3 bulbs that are doing this same thing, they basically show up like they are about to work (found in paperUI inbox), I add them then go to config>things, and they show there as offline and never come online.

The Sengled_4th_Bulb_log.txt shows the 4th bulb (same model as the others), which adds and then goes to the unknown state, then after a couple minutes shows as online. The problem is after I add items, and then try to control the light, it appears to send the commands, but the light doesn’t do anything.

20:43:19.786 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A65A68: Polling [zigbee:device:bf9f1ab6:7cb03eaa00a65a68:7CB03EAA00A65A68_3_dimmer] channels...
20:43:19.789 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A65A68: Polling zigbee:device:bf9f1ab6:7cb03eaa00a65a68:7CB03EAA00A65A68_3_dimmer
20:43:26.139 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE1814030BAFA0: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Thu Nov 19 20:43:26 CET 2020, implemented=false]
20:43:26.145 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE1814030BAFA0: Channel zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer updated to 23
20:43:26.148 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE1814030BAFA0: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer to 23
20:43:26.157 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0
20:43:26.160 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0
20:43:26.162 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0 in 1830 seconds
20:43:43.083 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=251, lastReportTime=Thu Nov 19 20:43:43 CET 2020, implemented=true]
20:43:50.212 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Thu Nov 19 20:43:50 CET 2020, implemented=false]
20:43:50.215 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to OFF
20:43:50.218 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to OFF
20:43:50.223 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:43:50.227 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:43:50.230 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
20:44:15.221 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:45:01.697 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - 7CE52400000AD578: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Thu Nov 19 20:45:01 CET 2020, implemented=false]
20:45:01.709 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 7CE52400000AD578: Channel zigbee:device:bf9f1ab6:7ce52400000ad578:7CE52400000AD578_1_dimmer updated to 100
20:45:01.717 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Updating ZigBee channel state zigbee:device:bf9f1ab6:7ce52400000ad578:7CE52400000AD578_1_dimmer to 100
20:45:01.730 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578
20:45:01.739 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578
20:45:01.747 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578 in 1830 seconds
20:45:02.687 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - 7CE52400000AD578: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Thu Nov 19 20:45:02 CET 2020, implemented=true]
20:45:02.701 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 7CE52400000AD578: Channel zigbee:device:bf9f1ab6:7ce52400000ad578:7CE52400000AD578_1_dimmer updated to 100
20:45:02.710 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Updating ZigBee channel state zigbee:device:bf9f1ab6:7ce52400000ad578:7CE52400000AD578_1_dimmer to 100
20:45:02.725 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578
20:45:02.733 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578
20:45:02.741 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578 in 1830 seconds
20:45:15.343 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:45:22.015 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:bf9f1ab6:7cb03eaa00a65a68
20:45:22.026 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A65A68: Polling stopped
20:45:22.033 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A65A68: Polling initialised at 939311ms
20:45:34.198 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item '3rdFloorBathroomLight1_LevelControl' received command 99
20:45:34.228 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Command for channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer --> 99 [PercentType]
20:45:35.373 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Thu Nov 19 20:45:35 CET 2020, implemented=false]
20:45:35.379 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to 99
20:45:35.384 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to 99
20:45:35.390 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:45:35.394 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:45:35.398 [INFO ] [smarthome.event.ItemStateChangedEvent] - 3rdFloorBathroomLight1_LevelControl changed from 0 to 99
20:45:35.399 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
20:45:52.041 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:bf9f1ab6:7cb03eaa00a65a68
20:45:52.056 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:7cb03eaa00a65a68' changed from ONLINE to OFFLINE
20:45:56.241 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A65A68: Polling [zigbee:device:bf9f1ab6:7cb03eaa00a65a68:7CB03EAA00A65A68_3_dimmer] channels...
20:45:56.246 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A65A68: Polling zigbee:device:bf9f1ab6:7cb03eaa00a65a68:7CB03EAA00A65A68_3_dimmer
20:46:00.069 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item '3rdFloorBathroomLight1_LevelControl' received command 1
20:46:00.098 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Command for channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer --> 1 [PercentType]
20:46:01.765 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item '3rdFloorBathroomLight1_LevelControl' received command 0
20:46:01.790 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Command for channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer --> 0 [PercentType]
20:46:02.495 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=3, lastReportTime=Thu Nov 19 20:46:02 CET 2020, implemented=true]
20:46:02.501 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to 1
20:46:02.509 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to 1
20:46:02.516 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:46:02.524 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:46:02.528 [INFO ] [smarthome.event.ItemStateChangedEvent] - 3rdFloorBathroomLight1_LevelControl changed from 99 to 1
20:46:02.536 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
20:46:02.974 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Thu Nov 19 20:46:02 CET 2020, implemented=false]
20:46:02.979 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to OFF
20:46:02.989 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to OFF
20:46:03.001 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:46:03.001 [INFO ] [smarthome.event.ItemStateChangedEvent] - 3rdFloorBathroomLight1_LevelControl changed from 1 to 0
20:46:03.010 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:46:03.017 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
20:46:15.349 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:46:19.193 [INFO ] [smarthome.event.ItemStateChangedEvent] - ZWaveNode002WADWAZ1DoorWindowsSensor_SensorBinary changed from CLOSED to OPEN
20:46:23.579 [INFO ] [smarthome.event.ItemStateChangedEvent] - ZWaveNode002WADWAZ1DoorWindowsSensor_SensorBinary changed from OPEN to CLOSED
20:47:13.443 [INFO ] [smarthome.event.ItemStateChangedEvent] - ZWaveNode002WADWAZ1DoorWindowsSensor_SensorBinary changed from CLOSED to OPEN
20:47:15.237 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:47:51.470 [INFO ] [smarthome.event.ItemStateChangedEvent] - ZWaveNode002WADWAZ1DoorWindowsSensor_SensorBinary changed from OPEN to CLOSED
20:48:15.183 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:48:51.609 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181403550d75' changed from ONLINE to REMOVING
20:48:51.617 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - B0CE181403550D75: ZigBee leave command
20:48:51.625 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - B0CE181403550D75: ZigBee leave command to 50564
20:48:51.883 [ERROR] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181403550D75: ZigBee removing network state complete
20:48:51.901 [ERROR] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181403550D75: Error removing network state
20:48:51.902 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zigbee:device:bf9f1ab6:b0ce181403550d75' has been updated.
20:48:51.918 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181403550d75' changed from REMOVING to REMOVED
20:48:51.933 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181403550d75' changed from REMOVED to UNINITIALIZED
20:48:51.958 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Handler dispose.
20:48:51.966 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Polling stopped
20:48:51.974 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker removed for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:48:51.981 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:48:52.023 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181403550d75' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
20:49:15.168 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:50:15.171 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:50:30.613 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030BAB17: Discovery: Starting discovery for existing device
20:50:30.625 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030CB302: Discovery: Starting discovery for existing device
20:50:30.634 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030BAB17: Starting ZigBee device discovery
20:50:30.640 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030BAB17: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6
20:50:30.643 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:bf9f1ab6
20:50:30.650 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030BAB17: Node discovery not complete
20:50:30.653 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030CB302: Starting ZigBee device discovery
20:50:30.665 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030CB302: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6
20:50:30.676 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030CB302: Node discovery not complete
20:50:33.395 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - B0CE181400118009: Starting ZigBee device discovery
20:50:33.402 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE181400118009: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6
20:50:33.411 [INFO ] [ig.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:bf9f1ab6:b0ce181400118009' to inbox.
20:50:33.412 [INFO ] [smarthome.event.InboxAddedEvent      ] - Discovery Result with UID 'zigbee:device:bf9f1ab6:b0ce181400118009' has been added.
20:50:33.417 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE181400118009: Node discovery not complete
20:50:33.645 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181400118009: ZigBee saving network state complete.
20:50:55.865 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181400118009: ZigBee saving network state complete.
20:51:01.447 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181400118009: ZigBee saving network state complete.
20:51:15.182 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:51:23.678 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181400118009: ZigBee saving network state complete.
20:51:24.780 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE5240000066888: Polling [zigbee:device:bf9f1ab6:7ce5240000066888:7CE5240000066888_1_dimmer] channels...
20:51:24.787 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE5240000066888: Polling zigbee:device:bf9f1ab6:7ce5240000066888:7CE5240000066888_1_dimmer
20:51:24.866 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - 7CE5240000066888: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Thu Nov 19 20:51:24 CET 2020, implemented=false]
20:51:24.877 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 7CE5240000066888: Channel zigbee:device:bf9f1ab6:7ce5240000066888:7CE5240000066888_1_dimmer updated to 100
20:51:24.887 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE5240000066888: Updating ZigBee channel state zigbee:device:bf9f1ab6:7ce5240000066888:7CE5240000066888_1_dimmer to 100
20:51:24.897 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:7ce5240000066888
20:51:24.903 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:7ce5240000066888
20:51:24.913 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:7ce5240000066888 in 1830 seconds
20:51:24.946 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - 7CE5240000066888: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Thu Nov 19 20:51:24 CET 2020, implemented=true]
20:51:24.958 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 7CE5240000066888: Channel zigbee:device:bf9f1ab6:7ce5240000066888:7CE5240000066888_1_dimmer updated to 100
20:51:24.966 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE5240000066888: Updating ZigBee channel state zigbee:device:bf9f1ab6:7ce5240000066888:7CE5240000066888_1_dimmer to 100
20:51:24.971 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:7ce5240000066888
20:51:24.975 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:7ce5240000066888
20:51:24.983 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:7ce5240000066888 in 1830 seconds
20:51:26.016 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181400118009: ZigBee saving network state complete.
20:51:40.051 [INFO ] [smarthome.event.InboxRemovedEvent    ] - Discovery Result with UID 'zigbee:device:bf9f1ab6:b0ce181400118009' has been removed.
20:51:40.111 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181400118009' changed from UNINITIALIZED to INITIALIZING
20:51:40.142 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181400118009: Initializing ZigBee thing handler zigbee:device:bf9f1ab6:b0ce181400118009
20:51:40.154 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181400118009' changed from INITIALIZING to UNKNOWN
20:51:40.155 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181400118009: Coordinator status changed to ONLINE.
20:51:40.162 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181400118009: Coordinator is ONLINE. Starting device initialisation.
20:51:40.184 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181400118009: Node has not finished discovery
20:51:40.198 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181400118009' changed from UNKNOWN to OFFLINE: Node has not completed discovery
20:51:40.265 [INFO ] [arthome.event.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:bf9f1ab6:b0ce181400118009 changed to UNKNOWN.
20:51:51.775 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181400118009: Node updated - ZigBeeNode [state=ONLINE, IEEE=B0CE181400118009, NWK=1679, endpoints=[]]
20:51:51.787 [WARN ] [.zsmartsystems.zigbee.ZigBeeExecutors] - Uncaught exception in thread NotificationService-thread-1619
java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.nodeUpdated(ZigBeeThingHandler.java:872) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager$14.run(ZigBeeNetworkManager.java:1733) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_265]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_265]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
20:51:52.032 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181400118009: ZigBee saving network state complete.
20:52:15.204 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:52:24.473 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Polling [zigbee:device:bf9f1ab6:7ce52400000ad578:7CE52400000AD578_1_dimmer] channels...
20:52:24.478 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Polling zigbee:device:bf9f1ab6:7ce52400000ad578:7CE52400000AD578_1_dimmer
20:52:24.644 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - 7CE52400000AD578: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Thu Nov 19 20:52:24 CET 2020, implemented=false]
20:52:24.655 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 7CE52400000AD578: Channel zigbee:device:bf9f1ab6:7ce52400000ad578:7CE52400000AD578_1_dimmer updated to 100
20:52:24.667 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Updating ZigBee channel state zigbee:device:bf9f1ab6:7ce52400000ad578:7CE52400000AD578_1_dimmer to 100
20:52:24.677 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578
20:52:24.695 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578
20:52:24.700 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578 in 1830 seconds
20:52:25.076 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - 7CE52400000AD578: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Thu Nov 19 20:52:25 CET 2020, implemented=true]
20:52:25.086 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 7CE52400000AD578: Channel zigbee:device:bf9f1ab6:7ce52400000ad578:7CE52400000AD578_1_dimmer updated to 100
20:52:25.094 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Updating ZigBee channel state zigbee:device:bf9f1ab6:7ce52400000ad578:7CE52400000AD578_1_dimmer to 100
20:52:25.104 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578
20:52:25.112 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578
20:52:25.116 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578 in 1830 seconds
20:52:57.586 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:bf9f1ab6:b0ce1814030b9a02
20:52:57.595 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE1814030B9A02: Polling stopped
20:52:57.603 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE1814030B9A02: Polling initialised at 1859522ms
20:53:02.119 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE1814030BAFA0: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=58, lastReportTime=Thu Nov 19 20:53:02 CET 2020, implemented=true]
20:53:02.131 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE1814030BAFA0: Channel zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer updated to 23
20:53:02.136 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE1814030BAFA0: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer to 23
20:53:02.146 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0
20:53:02.155 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0
20:53:02.159 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0 in 1830 seconds
20:53:10.631 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - 7CE5240000066888: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Thu Nov 19 20:53:10 CET 2020, implemented=false]
20:53:10.641 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 7CE5240000066888: Channel zigbee:device:bf9f1ab6:7ce5240000066888:7CE5240000066888_1_dimmer updated to 100
20:53:10.650 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE5240000066888: Updating ZigBee channel state zigbee:device:bf9f1ab6:7ce5240000066888:7CE5240000066888_1_dimmer to 100
20:53:10.661 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:7ce5240000066888
20:53:10.669 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:7ce5240000066888
20:53:10.681 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:7ce5240000066888 in 1830 seconds
20:53:11.634 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - 7CE5240000066888: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Thu Nov 19 20:53:11 CET 2020, implemented=true]
20:53:11.644 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 7CE5240000066888: Channel zigbee:device:bf9f1ab6:7ce5240000066888:7CE5240000066888_1_dimmer updated to 100
20:53:11.652 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CE5240000066888: Updating ZigBee channel state zigbee:device:bf9f1ab6:7ce5240000066888:7CE5240000066888_1_dimmer to 100
20:53:11.658 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:7ce5240000066888
20:53:11.664 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:7ce5240000066888
20:53:11.669 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:7ce5240000066888 in 1830 seconds
20:53:15.197 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:53:27.608 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:bf9f1ab6:b0ce1814030b9a02
20:53:27.619 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce1814030b9a02' changed from ONLINE to OFFLINE
20:54:15.285 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:54:22.466 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE1814030BAFA0: Polling [zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer] channels...
20:54:22.472 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE1814030BAFA0: Polling zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer
20:54:22.588 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE1814030BAFA0: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Thu Nov 19 20:54:22 CET 2020, implemented=false]
20:54:22.597 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE1814030BAFA0: Channel zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer updated to 23
20:54:22.606 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE1814030BAFA0: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer to 23
20:54:22.616 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0
20:54:22.622 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0
20:54:22.626 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0 in 1830 seconds
20:54:22.723 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE1814030BAFA0: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=58, lastReportTime=Thu Nov 19 20:54:22 CET 2020, implemented=true]
20:54:22.729 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE1814030BAFA0: Channel zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer updated to 23
20:54:22.734 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE1814030BAFA0: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer to 23
20:54:22.740 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0
20:54:22.744 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0
20:54:22.749 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0 in 1830 seconds

[Jon_A]

20:57:13.686 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181400118009' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
20:57:15.218 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:57:57.481 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030BAB17: Discovery: Starting discovery for existing device
20:57:57.492 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030CB302: Discovery: Starting discovery for existing device
20:57:57.501 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030BAB17: Starting ZigBee device discovery
20:57:57.501 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:bf9f1ab6
20:57:57.506 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030BAB17: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6
20:57:57.517 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030BAB17: Node discovery not complete
20:57:57.521 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030CB302: Starting ZigBee device discovery
20:57:57.534 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030CB302: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6
20:57:57.548 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE1814030CB302: Node discovery not complete
20:57:59.619 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - B0CE181403550D75: Starting ZigBee device discovery
20:57:59.627 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE181403550D75: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6
20:57:59.638 [INFO ] [smarthome.event.InboxAddedEvent      ] - Discovery Result with UID 'zigbee:device:bf9f1ab6:b0ce181403550d75' has been added.
20:57:59.641 [INFO ] [ig.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:bf9f1ab6:b0ce181403550d75' to inbox.
20:57:59.649 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE181403550D75: Node discovery not complete
20:57:59.873 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181403550D75: ZigBee saving network state complete.
20:58:08.525 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:0c054324:node3' has been updated.
20:58:08.608 [INFO ] [smarthome.event.ItemStateChangedEvent] - ZWaveNode003WADWAZ1DoorWindowsSensor_BatteryLevel changed from 100 to 83
20:58:15.199 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:58:19.978 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - B0CE181403550D75: Starting ZigBee device discovery
20:58:19.985 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE181403550D75: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6
20:58:19.997 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery start
20:58:20.006 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery using basic cluster on endpoint C584/1
20:58:20.858 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181403550D75: ZigBee saving network state complete.
20:58:23.830 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: Date code failed
20:58:23.835 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery using OTA cluster on endpoint C584/1
20:58:25.530 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1160, modelId=E11-G13, zigbee_networkaddress=50564, zigbee_powersource=MAINS, zigbee_stkversion=0, zigbee_zclversion=1, vendor=sengled, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x00000003, zigbee_applicationVersion=1}
20:58:25.539 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - B0CE181403550D75: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6, label 'sengled E11-G13'
20:58:26.193 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181403550D75: ZigBee saving network state complete.
20:58:28.144 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE1814030BAFA0: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Thu Nov 19 20:58:28 CET 2020, implemented=false]
20:58:28.151 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE1814030BAFA0: Channel zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer updated to 23
20:58:28.159 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE1814030BAFA0: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce1814030bafa0:B0CE1814030BAFA0_1_dimmer to 23
20:58:28.167 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0
20:58:28.177 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0
20:58:28.184 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce1814030bafa0 in 1830 seconds
20:58:46.363 [INFO ] [smarthome.event.InboxRemovedEvent    ] - Discovery Result with UID 'zigbee:device:bf9f1ab6:b0ce181403550d75' has been removed.
20:58:46.397 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181403550d75' changed from UNINITIALIZED to INITIALIZING
20:58:46.424 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Initializing ZigBee thing handler zigbee:device:bf9f1ab6:b0ce181403550d75
20:58:46.431 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Coordinator status changed to ONLINE.
20:58:46.433 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181403550d75' changed from INITIALIZING to UNKNOWN
20:58:46.444 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Coordinator is ONLINE. Starting device initialisation.
20:58:46.461 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Start initialising ZigBee Thing handler
20:58:46.473 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery start
20:58:46.478 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery using basic cluster on endpoint C584/1
20:58:46.512 [INFO ] [arthome.event.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:bf9f1ab6:b0ce181403550d75 changed to UNKNOWN.
20:58:49.228 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Polling initialised at 1830118ms
20:58:49.323 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Polling stopped
20:58:49.330 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Polling initialised at 1923031ms
20:58:54.271 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:0c054324:node7' has been updated.
20:58:54.778 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Polling stopped
20:58:54.785 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Polling initialised at 1812652ms
20:58:54.834 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Polling stopped
20:58:54.842 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Polling initialised at 1880201ms
20:59:15.223 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
20:59:16.098 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: Date code failed
20:59:16.104 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery using OTA cluster on endpoint C584/1
20:59:16.109 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1160, modelId=E11-G13, zigbee_networkaddress=50564, zigbee_powersource=MAINS, zigbee_stkversion=0, zigbee_zclversion=1, vendor=sengled, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x00000003, zigbee_applicationVersion=1}
20:59:16.115 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Checking endpoint 1 channels
20:59:16.134 [DEBUG] [ter.ZigBeeChannelConverterFactoryImpl] - B0CE181403550D75: Removing channel zigbee:switch_onoff in favor of zigbee:switch_level
20:59:16.144 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Dynamically created 1 channels
20:59:16.156 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating thing definition as channels have changed from [] to [zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer]
20:59:16.172 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zigbee:device:bf9f1ab6:b0ce181403550d75' has been updated.
20:59:16.172 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Initializing device
20:59:16.184 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Initializing channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel@1aa5e91
20:59:25.620 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: Failed to bind level control cluster
20:59:35.048 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: Failed to bind on off control cluster
20:59:35.055 [ERROR] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: Error initialising device
20:59:35.061 [INFO ] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer failed to initialise device
20:59:38.283 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: Level control initialized as server
20:59:38.392 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Thu Nov 19 20:59:38 CET 2020, implemented=false]
20:59:38.397 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to OFF
20:59:38.401 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to OFF
20:59:38.690 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Channel initialisation complete
20:59:38.699 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Thing is RFD, using long poll period of 1800sec
20:59:38.705 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Setting ONLINE/OFFLINE timeout interval to: 1830
20:59:38.718 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker added for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:59:38.724 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:59:38.732 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
20:59:38.844 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Polling stopped
20:59:38.845 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce181403550d75' changed from UNKNOWN to ONLINE
20:59:38.849 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Polling initialised at 1896350ms
20:59:38.865 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Done initialising ZigBee Thing handler
20:59:38.872 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:59:38.877 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
20:59:38.883 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
20:59:38.893 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=3, lastReportTime=Thu Nov 19 20:59:38 CET 2020, implemented=true]
20:59:39.484 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - B0CE181403550D75: ZigBee saving network state complete.
21:00:15.211 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
21:00:28.022 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer unlinked - polling stopped.
21:00:28.024 [INFO ] [ome.event.ItemChannelLinkRemovedEvent] - Link '3rdFloorBathroomLight1_LevelControl => zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer' has been removed.
21:00:34.692 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer linked - polling started.
21:00:34.694 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link '3rdFloorBathroomLight2_LevelControl-zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer' has been added.
21:00:36.456 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Thu Nov 19 21:00:36 CET 2020, implemented=false]
21:00:36.465 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to OFF
21:00:36.476 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to OFF
21:00:36.490 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:36.497 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:36.502 [INFO ] [smarthome.event.ItemStateChangedEvent] - 3rdFloorBathroomLight2_LevelControl changed from NULL to 0
21:00:36.507 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
21:00:36.644 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=3, lastReportTime=Thu Nov 19 21:00:36 CET 2020, implemented=true]
21:00:38.087 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Thu Nov 19 21:00:38 CET 2020, implemented=false]
21:00:38.096 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to OFF
21:00:38.104 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to OFF
21:00:38.118 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:38.128 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:38.137 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
21:00:49.328 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item '3rdFloorBathroomLight2_LevelControl' received command 99
21:00:49.358 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Command for channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer --> 99 [PercentType]
21:00:50.495 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Thu Nov 19 21:00:50 CET 2020, implemented=false]
21:00:50.509 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to 1
21:00:50.519 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to 1
21:00:50.530 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:50.534 [INFO ] [smarthome.event.ItemStateChangedEvent] - 3rdFloorBathroomLight2_LevelControl changed from 0 to 1
21:00:50.539 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:50.546 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
21:00:51.737 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=251, lastReportTime=Thu Nov 19 21:00:51 CET 2020, implemented=true]
21:00:51.743 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to 99
21:00:51.753 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to 99
21:00:51.763 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:51.771 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:51.774 [INFO ] [smarthome.event.ItemStateChangedEvent] - 3rdFloorBathroomLight2_LevelControl changed from 1 to 99
21:00:51.778 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
21:00:55.394 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item '3rdFloorBathroomLight2_LevelControl' received command 1
21:00:55.418 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Command for channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer --> 1 [PercentType]
21:00:56.578 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item '3rdFloorBathroomLight2_LevelControl' received command 0
21:00:56.599 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Command for channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer --> 0 [PercentType]
21:00:57.745 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=3, lastReportTime=Thu Nov 19 21:00:57 CET 2020, implemented=true]
21:00:57.752 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to 1
21:00:57.757 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to 1
21:00:57.768 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:57.772 [INFO ] [smarthome.event.ItemStateChangedEvent] - 3rdFloorBathroomLight2_LevelControl changed from 99 to 1
21:00:57.780 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:57.790 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
21:00:58.298 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Thu Nov 19 21:00:58 CET 2020, implemented=false]
21:00:58.305 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to OFF
21:00:58.314 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to OFF
21:00:58.323 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:58.328 [INFO ] [smarthome.event.ItemStateChangedEvent] - 3rdFloorBathroomLight2_LevelControl changed from 1 to 0
21:00:58.328 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:00:58.346 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
21:01:05.628 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - B0CE181403550D75: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=true, lastReportTime=Thu Nov 19 21:01:05 CET 2020, implemented=false]
21:01:05.637 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - B0CE181403550D75: Channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer updated to 1
21:01:05.645 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Updating ZigBee channel state zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer to 1
21:01:05.660 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:01:05.660 [INFO ] [smarthome.event.ItemStateChangedEvent] - 3rdFloorBathroomLight2_LevelControl changed from 0 to 1
21:01:05.665 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75
21:01:05.679 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:b0ce181403550d75 in 1830 seconds
21:01:15.188 [ERROR] [.core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:
	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest
21:01:35.551 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A65A68: Polling [zigbee:device:bf9f1ab6:7cb03eaa00a65a68:7CB03EAA00A65A68_3_dimmer] channels...
21:01:35.559 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A65A68: Polling zigbee:device:bf9f1ab6:7cb03eaa00a65a68:7CB03EAA00A65A68_3_dimmer

[Bruce_Osborne]

Welcome
I am not a Zigbee user but please use code fences for posted data & configuration. It makes posts much more readable and retains configuration spacing, which is important.

How to use code fences

We all have to type this content over and over and over. Here is a posting we can all point to when the topic comes up. Why use code fences? Because rules, sitemap, logs, and configs are all but unreadable when code fences are not used. When to use code fences? Whenever one is posting any sort of code, config, log, and any text where line wrapping, indentation, and using an equal spaced font makes the text more legible. How to use code fences? Use 3 backticks (```)... Or use <code>... …

Also, while you are waiting, perhaps the Zigbee Log Viewer could help.

ZigBee Log Viewer

[Jon_A]

I tried using the code and /code in brackets and all it seems to have done is changed the font of my logs, but the formatting is still all messed up. Not sure why, I’m just cutting and pasting from a text file.

[Bruce_Osborne]

Use 3 backticks on a line before & after

```

text here
```

[Jon_A]

Success, thanks.

[chris (Chris Jackson)]

Please have a read of the binding docs to see how to enable debug logging and then post some new logs showing the issue. It’s likely that short logs like this will not show a lot either - possibly getting a log during initialisation might be useful. Additionally, the XML file for the device (in the userdata/zigbee/nework folder) might be of use.

[Jon_A]

The logs I posted already had debug enabled. What’s the best way to log the initialization phase? Should I unplug the USB dongle, start logging, and then plug it in?

I’m also not proficient in linux, how do I get to the userdata/zigbee folder over SSH?
Thanks in advance

[chris (Chris Jackson)]

@Jon_A

The logs I posted already had debug enabled.

Yes, but it’s missing information which is why I suggested to read the docs to check how it’s meant to be configured.

@Jon_A

What’s the best way to log the initialization phase?

There’s an option to re-initialise the device in the UI.

@Jon_A

how do I get to the userdata/zigbee folder over SSH?

I’m not sure I can answer that as I’ve no idea how your system is set up - you could use ssh, or you could use folder mapping - I don’t know how your system works - sorry.

[Jon_A]

I haven’t figured out how to get to that zigbee folder yet, but will try this afternoon. I the mean time, here is a fresh reboot and initialization log, where you can see about 5 zigbee devices try to initialize, and they all freeze at either “UNKNOWN” or “OFFLINE” in the things menu after a few minutes.

2020-11-24 13:56:23.745 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node15' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2020-11-24 13:56:23.748 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node30' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2020-11-24 13:56:24.099 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:0c054324' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.125 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:0c054324' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.239 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node28' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.281 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node30' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.286 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node28' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.302 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node30' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.407 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node29' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.434 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node29' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.446 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node10' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.453 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node27' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.456 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node14' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.459 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node13' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.462 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node24' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.484 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node20' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.494 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node14' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.497 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node10' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.508 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node27' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.541 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node24' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.574 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node13' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.576 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node15' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.579 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node20' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.582 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node16' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.585 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node11' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.609 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node18' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.611 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node5' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.614 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node2' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.626 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node15' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.649 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node5' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.660 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node11' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.668 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node12' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.688 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node18' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.695 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node3' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.701 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node16' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.720 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.724 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node7' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.743 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node8' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.745 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node6' changed from UNINITIALIZED to INITIALIZING

2020-11-24 13:56:24.748 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node9' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2020-11-24 13:56:24.763 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node12' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.769 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.779 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node7' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.784 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node8' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.788 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node9' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:24.793 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node6' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2020-11-24 13:56:27.531 [hingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:7cb03eaa00a65a68' changed from UNKNOWN to ONLINE

2020-11-24 13:56:27.543 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:bf9f1ab6:7cb03eaa00a65a68 changed to UNKNOWN.

2020-11-24 13:56:27.618 [vent.ItemStateChangedEvent] - OfficeLamp_LevelControl changed from NULL to 100

2020-11-24 13:56:27.998 [hingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:b0ce1814030bafa0' changed from UNKNOWN to ONLINE

2020-11-24 13:56:28.016 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:bf9f1ab6:b0ce1814030bafa0 changed to UNKNOWN.

2020-11-24 13:56:28.018 [vent.ItemStateChangedEvent] - BasementTallLamp_LevelControl changed from NULL to 0

2020-11-24 13:56:29.411 [hingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:7ce5240000066888' changed from UNKNOWN to ONLINE

2020-11-24 13:56:29.421 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:bf9f1ab6:7ce5240000066888 changed to UNKNOWN.

2020-11-24 13:56:29.423 [vent.ItemStateChangedEvent] - BasementStairLights_LevelControl changed from NULL to 100

2020-11-24 13:56:40.112 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:0c054324' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.119 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node24' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.130 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node30' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.142 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node28' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.150 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node27' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.153 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node29' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.170 [me.event.ThingUpdatedEvent] - Thing 'zwave:serial_zstick:0c054324' has been updated.

2020-11-24 13:56:40.250 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node14' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.255 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node13' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.268 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node15' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.283 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node16' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.290 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node20' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.322 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node18' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.331 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node5' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.336 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node2' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.346 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node5' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:56:40.353 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node24' changed from ONLINE to ONLINE: Node initialising: PING

2020-11-24 13:56:40.358 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node10' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.361 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node3' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.364 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node9' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.367 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node6' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.372 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node12' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.375 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node11' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.378 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node8' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.380 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node7' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2020-11-24 13:56:40.382 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node12' changed from ONLINE to ONLINE: Node initialising: PING

2020-11-24 13:56:40.385 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node15' changed from ONLINE to ONLINE: Node initialising: PING

2020-11-24 13:56:40.390 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node3' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:56:41.700 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node11' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:56:41.813 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node28' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:56:42.085 [vent.ItemStateChangedEvent] - ZWaveNode011WS15Z1WallMountedSwitch_Switch changed from NULL to OFF

2020-11-24 13:56:42.112 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node11' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:56:42.477 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node27' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:56:42.505 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node30' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:56:42.659 [vent.ItemStateChangedEvent] - BasementFireplace_Switch changed from NULL to OFF

2020-11-24 13:56:42.790 [vent.ItemStateChangedEvent] - DomeWaterMainShutOff_Switch changed from NULL to ON

2020-11-24 13:56:42.805 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node30' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:56:42.839 [vent.ItemStateChangedEvent] - BasementFireplace_ElectricMeterAmps changed from NULL to 0

2020-11-24 13:56:51.116 [vent.ItemStateChangedEvent] - BasementFireplace_ElectricMeterVolts changed from NULL to 123.282

2020-11-24 13:56:51.369 [vent.ItemStateChangedEvent] - BasementFireplace_ElectricMeterWatts changed from NULL to 0

2020-11-24 13:56:51.873 [vent.ItemStateChangedEvent] - PatioLights changed from NULL to OFF

2020-11-24 13:56:52.093 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node27' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:56:52.204 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:0c054324:node28' has been updated.

2020-11-24 13:56:52.223 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]

2020-11-24 13:56:54.009 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:0c054324:node28' has been updated.

2020-11-24 13:56:54.010 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]

2020-11-24 13:56:54.308 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:0c054324:node28' has been updated.

2020-11-24 13:56:54.310 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]

2020-11-24 13:56:54.708 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:0c054324:node28' has been updated.

2020-11-24 13:56:54.710 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]

2020-11-24 13:56:55.663 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:0c054324:node28' has been updated.

2020-11-24 13:56:55.665 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]

2020-11-24 13:57:00.209 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:0c054324:node28' has been updated.

2020-11-24 13:57:00.211 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]

2020-11-24 13:57:00.221 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node28' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:57:02.562 [me.event.ThingUpdatedEvent] - Thing 'zigbee:device:bf9f1ab6:7cb03eaa00a65a68' has been updated.

2020-11-24 13:57:04.242 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node18' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:57:04.271 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node16' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:57:04.930 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node18' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:57:05.279 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node13' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:57:05.416 [vent.ItemStateChangedEvent] - ZWaveNode016WS15Z1WallMountedSwitch_Switch changed from NULL to ON

2020-11-24 13:57:05.424 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node16' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:57:05.495 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node14' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:57:05.534 [vent.ItemStateChangedEvent] - ZWaveNode013WD500Z1WallDimmerSwitch_Dimmer changed from NULL to 0

2020-11-24 13:57:05.543 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node13' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:57:05.806 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node20' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:57:06.283 [vent.ItemStateChangedEvent] - ZWaveNode014WD500Z1WallDimmerSwitch_Dimmer changed from NULL to 0

2020-11-24 13:57:06.291 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node14' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:57:11.527 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node24' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:57:11.550 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node12' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:57:11.931 [vent.ItemStateChangedEvent] - Fireplace_Switch changed from NULL to OFF

2020-11-24 13:57:12.221 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node24' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:57:12.342 [vent.ItemStateChangedEvent] - ZWaveNode012WS15Z1WallMountedSwitch_Switch changed from NULL to ON

2020-11-24 13:57:12.363 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node12' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:57:12.366 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node15' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF

2020-11-24 13:57:12.496 [vent.ItemStateChangedEvent] - ZWaveNode015WD500Z1WallDimmerSwitch_Dimmer changed from NULL to 0

2020-11-24 13:57:12.505 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node15' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2020-11-24 13:57:12.983 [vent.ItemStateChangedEvent] - Flush1Relay_Switch changed from NULL to OFF

2020-11-24 13:57:17.595 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:bf9f1ab6:b0ce1814030b9a02 changed to UNKNOWN.

2020-11-24 13:57:17.602 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:bf9f1ab6:7ce52400000ad578 changed to UNKNOWN.

2020-11-24 13:57:17.617 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:bf9f1ab6:b0ce1814030bab17 changed to UNKNOWN.

2020-11-24 13:57:17.622 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:bf9f1ab6:b0ce181403550d75 changed to UNKNOWN.

2020-11-24 13:57:17.732 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:bf9f1ab6:b0ce1814030cb302 changed to UNKNOWN.

2020-11-24 13:57:19.114 [vent.ItemStateChangedEvent] - Flush1Relay_ElectricMeterWatts changed from NULL to 0

2020-11-24 13:57:19.533 [hingStatusInfoChangedEvent] - 'zwave:device:0c054324:node20' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

==> /var/log/openhab2/openhab.log <==

2020-11-24 13:57:26.375 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE1814030B9A02: Node updated - ZigBeeNode [state=ONLINE, IEEE=B0CE1814030B9A02, NWK=C584, Type=END_DEVICE, endpoints=[1]]

2020-11-24 13:57:26.386 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - B0CE1814030B9A02: Starting ZigBee device discovery

2020-11-24 13:57:26.389 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - B0CE1814030B9A02: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6

2020-11-24 13:57:26.399 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE1814030B9A02: ZigBee node property discovery start

2020-11-24 13:57:26.405 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE1814030B9A02: ZigBee node property discovery using basic cluster on endpoint C584/1

2020-11-24 13:57:27.178 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - B0CE1814030B9A02: ZigBee saving network state complete.

2020-11-24 13:57:29.537 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: Date code failed

2020-11-24 13:57:29.539 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery using OTA cluster on endpoint C584/1

2020-11-24 13:57:29.542 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1160, modelId=E11-G13, zigbee_networkaddress=50564, zigbee_powersource=MAINS, zigbee_stkversion=0, zigbee_zclversion=1, vendor=sengled, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x00000003, zigbee_applicationVersion=1}

2020-11-24 13:57:29.545 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - B0CE181403550D75: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6, label 'sengled E11-G13'

2020-11-24 13:57:30.268 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - B0CE181403550D75: ZigBee saving network state complete.

2020-11-24 13:57:30.511 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE1814030BAFA0: Node updated - ZigBeeNode [state=ONLINE, IEEE=B0CE1814030BAFA0, NWK=CBE3, Type=END_DEVICE, endpoints=[1]]

2020-11-24 13:57:30.516 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A65A68: Node updated - ZigBeeNode [state=ONLINE, IEEE=7CB03EAA00A65A68, NWK=2DFA, Type=ROUTER, endpoints=[3]]

2020-11-24 13:57:30.553 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Channel initialisation complete

2020-11-24 13:57:30.557 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Setting ONLINE/OFFLINE timeout interval to: 1830

2020-11-24 13:57:30.560 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker added for thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578

2020-11-24 13:57:30.562 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578

2020-11-24 13:57:30.572 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:bf9f1ab6:7ce52400000ad578 in 1830 seconds

2020-11-24 13:57:31.233 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - B0CE1814030BAFA0: ZigBee saving network state complete.

2020-11-24 13:57:31.303 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA00A65A68: ZigBee saving network state complete.

2020-11-24 13:57:36.081 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 000D6F000B3D6172: ZigBee saving network state complete.

==> /var/log/openhab2/events.log <==

2020-11-24 13:57:35.833 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_ember:bf9f1ab6' has been updated.

==> /var/log/openhab2/openhab.log <==

2020-11-24 13:57:40.069 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE1814030B9A02: Date code failed

2020-11-24 13:57:40.072 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE1814030B9A02: ZigBee node property discovery using OTA cluster on endpoint C584/1

2020-11-24 13:57:40.075 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE1814030B9A02: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1160, modelId=E11-G13, zigbee_networkaddress=50564, zigbee_powersource=MAINS, zigbee_stkversion=0, zigbee_zclversion=1, vendor=sengled, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x00000003, zigbee_applicationVersion=1}

2020-11-24 13:57:40.078 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - B0CE1814030B9A02: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:bf9f1ab6, label 'sengled E11-G13'

2020-11-24 13:57:40.677 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - B0CE1814030B9A02: ZigBee saving network state complete.

2020-11-24 13:57:42.300 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:

	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest

2020-11-24 13:57:49.439 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Error getting binding table

2020-11-24 13:57:49.443 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Polling initialised at 928411ms

2020-11-24 13:57:49.446 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CE52400000AD578: Done initialising ZigBee Thing handler

2020-11-24 13:57:49.738 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CE52400000AD578: ZigBee saving network state complete.

==> /var/log/openhab2/events.log <==

2020-11-24 13:57:49.445 [hingStatusInfoChangedEvent] - 'zigbee:device:bf9f1ab6:7ce52400000ad578' changed from UNKNOWN to ONLINE

==> /var/log/openhab2/openhab.log <==

2020-11-24 13:57:58.932 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE1814030B9A02: Date code failed

2020-11-24 13:57:58.935 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE1814030B9A02: ZigBee node property discovery using OTA cluster on endpoint C584/1

2020-11-24 13:57:58.938 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE1814030B9A02: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1160, modelId=E11-G13, zigbee_networkaddress=50564, zigbee_powersource=MAINS, zigbee_stkversion=0, zigbee_zclversion=1, zigbee_routes=[], zigbee_lastupdate=, zigbee_stkcompliance=0, vendor=sengled, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x00000003, zigbee_neighbors=[], zigbee_applicationVersion=1, zigbee_device_initialised=true, zigbee_devices=[]}

2020-11-24 13:57:58.942 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE1814030B9A02: Checking endpoint 1 channels

2020-11-24 13:57:58.954 [DEBUG] [er.ZigBeeChannelConverterFactoryImpl] - B0CE1814030B9A02: Removing channel zigbee:switch_onoff in favor of zigbee:switch_level

2020-11-24 13:57:58.957 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE1814030B9A02: Dynamically created 1 channels

2020-11-24 13:57:58.960 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE1814030B9A02: Device initialization will be skipped as the device is already initialized

2020-11-24 13:57:58.974 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - B0CE1814030B9A02: Level control initialized as server

2020-11-24 13:58:08.354 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: Date code failed

2020-11-24 13:58:08.359 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery using OTA cluster on endpoint C584/1

2020-11-24 13:58:08.361 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - B0CE181403550D75: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1160, modelId=E11-G13, zigbee_networkaddress=50564, zigbee_powersource=MAINS, zigbee_stkversion=0, zigbee_zclversion=1, vendor=sengled, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x00000003, zigbee_applicationVersion=1}

2020-11-24 13:58:08.366 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Checking endpoint 1 channels

2020-11-24 13:58:08.378 [DEBUG] [er.ZigBeeChannelConverterFactoryImpl] - B0CE181403550D75: Removing channel zigbee:switch_onoff in favor of zigbee:switch_level

2020-11-24 13:58:08.380 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Dynamically created 1 channels

2020-11-24 13:58:08.382 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Initializing device

2020-11-24 13:58:08.387 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE181403550D75: Initializing channel zigbee:device:bf9f1ab6:b0ce181403550d75:B0CE181403550D75_1_dimmer with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel@1b0a503

2020-11-24 13:58:42.248 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-openhabcloud': Error:

	Resource mvn:org.apache.servicemix.bundles/org.apache.servicemix.bundles.jsr305/3.0.2_1 does not contain a manifest

[Bruce_Osborne]

@Jon_A

you can see about 5 zigbee devices t

That log shows Z-Wave devices, not Zigbee.They are 2 totally different wireless protocols.

Did you upgrade your system from an earlier version to 2.5.x ? That behaviour looks like OH is tring once a minuter to load an invalid addon, reloading all addons including zwave.

[Jon_A]

I’m not sure what you mean about showing my z-wave logs, you can see the word zigbee written in about 50 lines of that log. It’s showing both controllers.

Regarding upgrade, no I did not go from an earlier version, this was installed about a week ago from the latest 2.5 on the site on a formatted SD card.

On another note, in trying to find the correct folder for userdata/zigbee, I’m lost there too. I did cd… to get to as root as possible, and then my options are:

[14:18:50] openhabian@openHABianDevice:/$ dir
bin  boot  dev	etc  home  lib	lost+found  media  mnt	opt  proc  root  run  sbin  srv  sys  tmp  usr	var

According to another thread I found, I should go into “etc”, then have a folder called openhab2 (I do not), the only thing in there is one called openhabian which just has a series of config files under it.

I’m totally at a loss here.

[Bruce_Osborne]

Sorry, I just looked at the top of the log.

userdata varies depending on how openHAB was installed. For openHABian it is likely in /var/lib/openhab2.

[chris (Chris Jackson)]

Unfortunately this log still doesn’t contain the debug information that’s needed. Did you enable all debug including the ZigBee framework debug, or just the debug coming from the binding (which appears to be the case).

Also you don’t need to provide the events log - just the debug log is fine (ie the openhab.log file).

[Jon_A]

Ok I think I have everything enabled to what it should be. Here are my logging settings:

ROOT                                               │ WARN
com.zsmartsystems.zigbee                           │ DEBUG
com.zsmartsystems.zigbee.dongle.ember.internal.ash │ DEBUG
javax.jmdns                                        │ ERROR
javax.mail                                         │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.ssh.SshUtils                │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.apache.sshd                                    │ ERROR
org.eclipse.lsp4j                                  │ OFF
org.eclipse.smarthome                              │ INFO
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
org.openhab.binding.zigbee                         │ DEBUG
org.openhab.ui.paper                               │ WARN
org.openhab.ui.paper.internal                      │ INFO
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF
smarthome.event                                    │ INFO
smarthome.event.InboxUpdatedEvent                  │ ERROR
smarthome.event.ItemAddedEvent                     │ ERROR
smarthome.event.ItemRemovedEvent                   │ ERROR
smarthome.event.ItemStateEvent                     │ ERROR
smarthome.event.ThingAddedEvent                    │ ERROR
smarthome.event.ThingRemovedEvent                  │ ERROR
smarthome.event.ThingStatusInfoEvent               │ ERROR

After setting those, I rebooted the PI to let everything come up naturally, and here are the logs again (I hope these are the correct logs). I cut off part of the log because it’s just going nonstop.

2020-11-25 16:56:39.345 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=0, sleepy=0/3

2020-11-25 16:56:39.347 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=0, sleepy=0/3

2020-11-25 16:56:39.397 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:39.398 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=5, reTx=false, data=99 00 18]

2020-11-25 16:56:39.407 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=2, reTx=false, data=99 80 18 02]

2020-11-25 16:56:39.409 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=5, reTx=false, data=99 00 18]

2020-11-25 16:56:39.410 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]

2020-11-25 16:56:40.400 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:40.402 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=6, reTx=false, data=9A 00 18]

2020-11-25 16:56:40.410 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=3, reTx=false, data=9A 80 18 02]

2020-11-25 16:56:40.412 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=6, reTx=false, data=9A 00 18]

2020-11-25 16:56:40.413 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]

2020-11-25 16:56:40.875 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=3, reTx=false, data=9A 90 3F 00 22 63 00 00 00 00 00 00 40 10 00 00 05 8B 66 00]

2020-11-25 16:56:40.877 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=6322, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=05], messageTag=8B, status=EMBER_DELIVERY_FAILED, messageContents=]

2020-11-25 16:56:40.879 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]

2020-11-25 16:56:40.879 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8B state=RX_NAK

2020-11-25 16:56:40.880 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8B, state=RX_NAK, outstanding=2

2020-11-25 16:56:40.882 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CE52400000AD578 queueTime=9471, state=FAILED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 6322/0, cluster=0000, TID=8B, ieeeAddr=7CE52400000AD578, requestType=0, startIndex=0]]

2020-11-25 16:56:40.884 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-11-25 16:56:40.885 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CE52400000AD578: transactionComplete, state=FAILED, outstanding=0

2020-11-25 16:56:40.886 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CE52400000AD578: transactionComplete exceeded max retries 2

2020-11-25 16:56:40.888 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=7CE52400000AD578 queueTime=9477, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 6322/0, cluster=0000, TID=8B, ieeeAddr=7CE52400000AD578, requestType=0, startIndex=0]]

2020-11-25 16:56:40.889 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CE52400000AD578: Node SVC Discovery: NetworkAddressRequest returned null

2020-11-25 16:56:40.892 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=7CE52400000AD578 queueTime=9481, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 6322/0, cluster=0000, TID=8B, ieeeAddr=7CE52400000AD578, requestType=0, startIndex=0]]

2020-11-25 16:56:40.893 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-11-25 16:56:40.895 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CE52400000AD578: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-11-25 16:56:40.897 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3

2020-11-25 16:56:40.899 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3

2020-11-25 16:56:40.900 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=6322, TID=8B, event=RX_NAK, state=CANCELLED

2020-11-25 16:56:40.900 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=7CE52400000AD578, requestType=0, startIndex=0]]

2020-11-25 16:56:40.901 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3

2020-11-25 16:56:40.903 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=3, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=8D, ieeeAddr=7CE52400000AD578, requestType=0, startIndex=0]]

2020-11-25 16:56:40.905 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-11-25 16:56:40.906 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=8D, ieeeAddr=7CE52400000AD578, requestType=0, startIndex=0]

2020-11-25 16:56:40.908 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=D1, rssi=--, lqi=--, payload=8D 78 D5 0A 00 00 24 E5 7C 00 00]

2020-11-25 16:56:40.910 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendBroadcastRequest [networkId=0, destination=FFFF, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=D1], radius=8, messageTag=8D, messageContents=8D 78 D5 0A 00 00 24 E5 7C 00 00]

2020-11-25 16:56:40.912 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:40.914 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=3, ackNum=0, reTx=false, data=9B 00 36 FF FF 00 00 00 00 00 00 40 11 00 00 D1 08 8D 0B 8D 78 D5 0A 00 00 24 E5 7C 00 00]

2020-11-25 16:56:40.928 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=4, reTx=false, data=9B 80 36 00 06]

2020-11-25 16:56:40.930 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=3, ackNum=0, reTx=false, data=9B 00 36 FF FF 00 00 00 00 00 00 40 11 00 00 D1 08 8D 0B 8D 78 D5 0A 00 00 24 E5 7C 00 00]

2020-11-25 16:56:40.932 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=06]

2020-11-25 16:56:40.933 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]

2020-11-25 16:56:40.952 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=4, reTx=false, data=9B 90 45 05 00 00 00 00 00 00 08 01 00 00 06 FF 00 00 00 FF FF 0B 8D 78 D5 0A 00 00 24 E5 7C 00 00]

2020-11-25 16:56:40.954 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=06], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=8D 78 D5 0A 00 00 24 E5 7C 00 00]

2020-11-25 16:56:40.956 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]

2020-11-25 16:56:41.911 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=4, reTx=false, data=9B 90 3F 04 FF FF 00 00 00 00 00 00 08 01 00 00 06 8D 00 00]

2020-11-25 16:56:41.914 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_MULTICAST_WITH_ALIAS, indexOrDestination=FFFF, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=06], messageTag=8D, status=EMBER_SUCCESS, messageContents=]

2020-11-25 16:56:41.915 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]

2020-11-25 16:56:41.915 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8D state=RX_ACK

2020-11-25 16:56:41.916 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8D, state=RX_ACK, outstanding=2

2020-11-25 16:56:41.918 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFF, TID=8D, event=RX_ACK, state=ACKED

2020-11-25 16:56:42.404 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:42.406 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=4, ackNum=3, reTx=false, data=9C 00 18]

2020-11-25 16:56:42.414 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=5, reTx=false, data=9C 80 18 02]

2020-11-25 16:56:42.416 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=4, ackNum=3, reTx=false, data=9C 00 18]

2020-11-25 16:56:42.417 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]

2020-11-25 16:56:42.838 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - B0CE1814030CB302: Node SVC Discovery: running NODE_DESCRIPTOR

2020-11-25 16:56:42.840 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - B0CE1814030CB302: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=B0CE1814030CB302 queueTime=0, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> FF9F/0, cluster=0002, TID=--, nwkAddrOfInterest=FF9F]]

2020-11-25 16:56:42.841 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3

2020-11-25 16:56:42.843 [DEBUG] [transaction.ZigBeeTransactionManager] - FF9F/0: Sending ZigBeeTransaction [ieeeAddress=B0CE1814030CB302 queueTime=4, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> FF9F/0, cluster=0002, TID=8E, nwkAddrOfInterest=FF9F]]

2020-11-25 16:56:42.845 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding

2020-11-25 16:56:42.847 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> FF9F/0, cluster=0002, TID=8E, nwkAddrOfInterest=FF9F]

2020-11-25 16:56:42.849 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FF9F/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=D2, rssi=--, lqi=--, payload=8E 9F FF]

2020-11-25 16:56:42.851 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=FF9F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=D2], messageTag=8E, messageContents=8E 9F FF]

2020-11-25 16:56:42.853 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:42.855 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=5, ackNum=4, reTx=false, data=9D 00 34 00 9F FF 00 00 02 00 00 00 40 11 00 00 D2 8E 03 8E 9F FF]

2020-11-25 16:56:42.868 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=6, reTx=false, data=9D 80 34 00 07]

2020-11-25 16:56:42.870 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=5, ackNum=4, reTx=false, data=9D 00 34 00 9F FF 00 00 02 00 00 00 40 11 00 00 D2 8E 03 8E 9F FF]

2020-11-25 16:56:42.871 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=07]

2020-11-25 16:56:42.873 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]

2020-11-25 16:56:44.408 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:44.410 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=6, ackNum=5, reTx=false, data=9E 00 18]

2020-11-25 16:56:44.419 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=7, reTx=false, data=9E 80 18 02]

2020-11-25 16:56:44.421 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=6, ackNum=5, reTx=false, data=9E 00 18]

2020-11-25 16:56:44.422 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]

2020-11-25 16:56:45.005 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=10007, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=8C, ieeeAddr=B0CE1814030BAB17, requestType=0, startIndex=0]]

2020-11-25 16:56:45.006 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding

2020-11-25 16:56:45.007 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=1

2020-11-25 16:56:45.008 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded max retries 1

2020-11-25 16:56:45.010 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=10012, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=8C, ieeeAddr=B0CE1814030BAB17, requestType=0, startIndex=0]]

2020-11-25 16:56:45.011 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - B0CE1814030BAB17: Node SVC Discovery: NetworkAddressRequest returned null

2020-11-25 16:56:45.011 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=10014, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=8C, ieeeAddr=B0CE1814030BAB17, requestType=0, startIndex=0]]

2020-11-25 16:56:45.012 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding

2020-11-25 16:56:45.012 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - B0CE1814030BAB17: Node SVC Discovery: NetworkAddressRequest failed after unicast and broadcast

2020-11-25 16:56:45.014 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - B0CE1814030BAB17: Node SVC Discovery: request NWK_ADDRESS failed. Retry 8, wait 11605ms before retry.

2020-11-25 16:56:45.014 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=1

2020-11-25 16:56:45.015 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=0, sleepy=0/3

2020-11-25 16:56:45.017 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=0, sleepy=0/3

2020-11-25 16:56:45.413 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:45.414 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=7, ackNum=6, reTx=false, data=9F 00 18]

2020-11-25 16:56:45.422 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=0, reTx=false, data=9F 80 18 02]

2020-11-25 16:56:45.424 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=7, ackNum=6, reTx=false, data=9F 00 18]

2020-11-25 16:56:45.425 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]

2020-11-25 16:56:46.417 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:46.419 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=0, ackNum=7, reTx=false, data=A0 00 18]

2020-11-25 16:56:46.428 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=1, reTx=false, data=A0 80 18 02]

2020-11-25 16:56:46.429 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=0, ackNum=7, reTx=false, data=A0 00 18]

2020-11-25 16:56:46.430 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]

2020-11-25 16:56:47.422 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:47.424 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=0, reTx=false, data=A1 00 18]

2020-11-25 16:56:47.433 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=2, reTx=false, data=A1 80 18 02]

2020-11-25 16:56:47.434 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=0, reTx=false, data=A1 00 18]

2020-11-25 16:56:47.435 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]

2020-11-25 16:56:47.564 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=2, reTx=false, data=A1 90 3F 00 9F FF 00 00 02 00 00 00 40 11 00 00 07 8E 66 00]

2020-11-25 16:56:47.565 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=FF9F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=07], messageTag=8E, status=EMBER_DELIVERY_FAILED, messageContents=]

2020-11-25 16:56:47.566 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]

2020-11-25 16:56:47.567 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8E state=RX_NAK

2020-11-25 16:56:47.568 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8E, state=RX_NAK, outstanding=2

2020-11-25 16:56:47.571 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=B0CE1814030CB302 queueTime=4731, state=FAILED, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> FF9F/0, cluster=0002, TID=8E, nwkAddrOfInterest=FF9F]]

2020-11-25 16:56:47.572 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-11-25 16:56:47.573 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - B0CE1814030CB302: transactionComplete, state=FAILED, outstanding=0

2020-11-25 16:56:47.575 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - B0CE1814030CB302: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=B0CE1814030CB302 queueTime=4735, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> FF9F/0, cluster=0002, TID=8E, nwkAddrOfInterest=FF9F]]

2020-11-25 16:56:47.576 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3

2020-11-25 16:56:47.578 [DEBUG] [transaction.ZigBeeTransactionManager] - FF9F/0: Sending ZigBeeTransaction [ieeeAddress=B0CE1814030CB302 queueTime=4739, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> FF9F/0, cluster=0002, TID=8E, nwkAddrOfInterest=FF9F]]

2020-11-25 16:56:47.579 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-11-25 16:56:47.581 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> FF9F/0, cluster=0002, TID=8E, nwkAddrOfInterest=FF9F]

2020-11-25 16:56:47.582 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FF9F/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=D3, rssi=--, lqi=--, payload=8E 9F FF]

2020-11-25 16:56:47.584 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FF9F, TID=8E, event=RX_NAK, state=DISPATCHED

2020-11-25 16:56:47.584 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=FF9F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=D3], messageTag=8E, messageContents=8E 9F FF]

2020-11-25 16:56:47.586 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:47.587 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=2, reTx=false, data=A2 00 34 00 9F FF 00 00 02 00 00 00 40 11 00 00 D3 8E 03 8E 9F FF]

2020-11-25 16:56:47.600 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=3, reTx=false, data=A2 80 34 00 08]

2020-11-25 16:56:47.602 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=2, reTx=false, data=A2 00 34 00 9F FF 00 00 02 00 00 00 40 11 00 00 D3 8E 03 8E 9F FF]

2020-11-25 16:56:47.604 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=08]

2020-11-25 16:56:47.607 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]

2020-11-25 16:56:49.427 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:49.429 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=3, ackNum=3, reTx=false, data=A3 00 18]

2020-11-25 16:56:49.437 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=4, reTx=false, data=A3 80 18 02]

2020-11-25 16:56:49.439 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=3, ackNum=3, reTx=false, data=A3 00 18]

2020-11-25 16:56:49.440 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]

2020-11-25 16:56:50.431 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:50.432 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=4, ackNum=4, reTx=false, data=A4 00 18]

2020-11-25 16:56:50.440 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=5, reTx=false, data=A4 80 18 02]

2020-11-25 16:56:50.442 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=4, ackNum=4, reTx=false, data=A4 00 18]

2020-11-25 16:56:50.444 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]

2020-11-25 16:56:50.907 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=10006, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=8D, ieeeAddr=7CE52400000AD578, requestType=0, startIndex=0]]

2020-11-25 16:56:50.908 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-11-25 16:56:50.909 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=0

2020-11-25 16:56:50.911 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded max retries 1

2020-11-25 16:56:50.912 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=10012, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=8D, ieeeAddr=7CE52400000AD578, requestType=0, startIndex=0]]

2020-11-25 16:56:50.914 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CE52400000AD578: Node SVC Discovery: NetworkAddressRequest returned null

2020-11-25 16:56:50.914 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=10013, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=8D, ieeeAddr=7CE52400000AD578, requestType=0, startIndex=0]]

2020-11-25 16:56:50.915 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-11-25 16:56:50.915 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CE52400000AD578: Node SVC Discovery: NetworkAddressRequest failed after unicast and broadcast

2020-11-25 16:56:50.917 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-11-25 16:56:50.917 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CE52400000AD578: Node SVC Discovery: request NWK_ADDRESS failed. Retry 7, wait 14833ms before retry.

2020-11-25 16:56:50.918 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3

2020-11-25 16:56:50.919 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3

2020-11-25 16:56:51.435 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:51.436 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=5, ackNum=5, reTx=false, data=A5 00 18]

2020-11-25 16:56:51.444 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=6, reTx=false, data=A5 80 18 02]

2020-11-25 16:56:51.445 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=5, ackNum=5, reTx=false, data=A5 00 18]

2020-11-25 16:56:51.446 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]

2020-11-25 16:56:52.297 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=6, reTx=false, data=A5 90 3F 00 9F FF 00 00 02 00 00 00 40 11 00 00 08 8E 66 00]

2020-11-25 16:56:52.299 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=FF9F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=08], messageTag=8E, status=EMBER_DELIVERY_FAILED, messageContents=]

2020-11-25 16:56:52.301 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]

2020-11-25 16:56:52.301 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8E state=RX_NAK

2020-11-25 16:56:52.302 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8E, state=RX_NAK, outstanding=1

2020-11-25 16:56:52.305 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=B0CE1814030CB302 queueTime=9465, state=FAILED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> FF9F/0, cluster=0002, TID=8E, nwkAddrOfInterest=FF9F]]

2020-11-25 16:56:52.306 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-11-25 16:56:52.307 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - B0CE1814030CB302: transactionComplete, state=FAILED, outstanding=0

2020-11-25 16:56:52.308 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - B0CE1814030CB302: transactionComplete exceeded max retries 2

2020-11-25 16:56:52.310 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=B0CE1814030CB302 queueTime=9471, state=CANCELLED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> FF9F/0, cluster=0002, TID=8E, nwkAddrOfInterest=FF9F]]

2020-11-25 16:56:52.312 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=B0CE1814030CB302 queueTime=9473, state=CANCELLED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> FF9F/0, cluster=0002, TID=8E, nwkAddrOfInterest=FF9F]]

2020-11-25 16:56:52.312 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - B0CE1814030CB302: Node SVC Discovery: NodeDescriptorResponse returned null

2020-11-25 16:56:52.313 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-11-25 16:56:52.314 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - B0CE1814030CB302: Node SVC Discovery: request NODE_DESCRIPTOR failed. Retry 10, wait 27936ms before retry.

2020-11-25 16:56:52.315 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - B0CE1814030CB302: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-11-25 16:56:52.316 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3

2020-11-25 16:56:52.317 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3

2020-11-25 16:56:52.319 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FF9F, TID=8E, event=RX_NAK, state=CANCELLED

2020-11-25 16:56:52.438 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:52.440 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=6, ackNum=7, reTx=false, data=A6 00 18]

2020-11-25 16:56:52.448 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=7, reTx=false, data=A6 80 18 02]

2020-11-25 16:56:52.449 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=6, ackNum=7, reTx=false, data=A6 00 18]

2020-11-25 16:56:52.451 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]

2020-11-25 16:56:53.405 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - B0CE181403550D75: Node SVC Discovery: running NWK_ADDRESS

2020-11-25 16:56:53.407 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - B0CE181403550D75: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=B0CE181403550D75 queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> C584/0, cluster=0000, TID=--, ieeeAddr=B0CE181403550D75, requestType=0, startIndex=0]]

2020-11-25 16:56:53.408 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3

2020-11-25 16:56:53.410 [DEBUG] [transaction.ZigBeeTransactionManager] - C584/0: Sending ZigBeeTransaction [ieeeAddress=B0CE181403550D75 queueTime=4, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> C584/0, cluster=0000, TID=8F, ieeeAddr=B0CE181403550D75, requestType=0, startIndex=0]]

2020-11-25 16:56:53.412 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-11-25 16:56:53.413 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> C584/0, cluster=0000, TID=8F, ieeeAddr=B0CE181403550D75, requestType=0, startIndex=0]

2020-11-25 16:56:53.415 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=C584/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=D4, rssi=--, lqi=--, payload=8F 75 0D 55 03 14 18 CE B0 00 00]

2020-11-25 16:56:53.417 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=C584, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=D4], messageTag=8F, messageContents=8F 75 0D 55 03 14 18 CE B0 00 00]

2020-11-25 16:56:53.419 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:53.421 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=7, ackNum=0, reTx=false, data=A7 00 34 00 84 C5 00 00 00 00 00 00 40 11 00 00 D4 8F 0B 8F 75 0D 55 03 14 18 CE B0 00 00]

2020-11-25 16:56:53.435 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=0, reTx=false, data=A7 80 34 00 09]

2020-11-25 16:56:53.437 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=7, ackNum=0, reTx=false, data=A7 00 34 00 84 C5 00 00 00 00 00 00 40 11 00 00 D4 8F 0B 8F 75 0D 55 03 14 18 CE B0 00 00]

2020-11-25 16:56:53.438 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=09]

2020-11-25 16:56:53.439 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]

2020-11-25 16:56:54.442 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:54.444 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=0, ackNum=1, reTx=false, data=A8 00 18]

2020-11-25 16:56:54.452 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=1, reTx=false, data=A8 80 18 02]

2020-11-25 16:56:54.453 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=0, ackNum=1, reTx=false, data=A8 00 18]

2020-11-25 16:56:54.454 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]

2020-11-25 16:56:55.446 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:55.448 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=2, reTx=false, data=A9 00 18]

2020-11-25 16:56:55.455 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=2, reTx=false, data=A9 80 18 02]

2020-11-25 16:56:55.456 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=2, reTx=false, data=A9 00 18]

2020-11-25 16:56:55.457 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]

2020-11-25 16:56:56.449 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:56.451 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=3, reTx=false, data=AA 00 18]

2020-11-25 16:56:56.459 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=3, reTx=false, data=AA 80 18 02]

2020-11-25 16:56:56.462 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=3, reTx=false, data=AA 00 18]

2020-11-25 16:56:56.464 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]

2020-11-25 16:56:56.621 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - B0CE1814030BAB17: Node SVC Discovery: running NWK_ADDRESS

2020-11-25 16:56:56.623 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - B0CE1814030BAB17: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=B0CE1814030BAB17 queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> E75D/0, cluster=0000, TID=--, ieeeAddr=B0CE1814030BAB17, requestType=0, startIndex=0]]

2020-11-25 16:56:56.625 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3

2020-11-25 16:56:56.627 [DEBUG] [transaction.ZigBeeTransactionManager] - E75D/0: Sending ZigBeeTransaction [ieeeAddress=B0CE1814030BAB17 queueTime=4, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> E75D/0, cluster=0000, TID=90, ieeeAddr=B0CE1814030BAB17, requestType=0, startIndex=0]]

2020-11-25 16:56:56.628 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-11-25 16:56:56.630 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> E75D/0, cluster=0000, TID=90, ieeeAddr=B0CE1814030BAB17, requestType=0, startIndex=0]

2020-11-25 16:56:56.632 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=E75D/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=D5, rssi=--, lqi=--, payload=90 17 AB 0B 03 14 18 CE B0 00 00]

2020-11-25 16:56:56.635 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=E75D, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=D5], messageTag=90, messageContents=90 17 AB 0B 03 14 18 CE B0 00 00]

2020-11-25 16:56:56.636 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:56.639 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=3, ackNum=4, reTx=false, data=AB 00 34 00 5D E7 00 00 00 00 00 00 40 11 00 00 D5 90 0B 90 17 AB 0B 03 14 18 CE B0 00 00]

2020-11-25 16:56:56.655 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=4, reTx=false, data=AB 80 34 00 0A]

2020-11-25 16:56:56.658 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=3, ackNum=4, reTx=false, data=AB 00 34 00 5D E7 00 00 00 00 00 00 40 11 00 00 D5 90 0B 90 17 AB 0B 03 14 18 CE B0 00 00]

2020-11-25 16:56:56.662 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=0A]

2020-11-25 16:56:56.663 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]

2020-11-25 16:56:58.134 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=4, reTx=false, data=AB 90 3F 00 84 C5 00 00 00 00 00 00 40 10 00 00 09 8F 66 00]

2020-11-25 16:56:58.136 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=C584, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=09], messageTag=8F, status=EMBER_DELIVERY_FAILED, messageContents=]

2020-11-25 16:56:58.137 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]

2020-11-25 16:56:58.137 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8F state=RX_NAK

2020-11-25 16:56:58.138 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8F, state=RX_NAK, outstanding=2

2020-11-25 16:56:58.141 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=B0CE181403550D75 queueTime=4734, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> C584/0, cluster=0000, TID=8F, ieeeAddr=B0CE181403550D75, requestType=0, startIndex=0]]

2020-11-25 16:56:58.142 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-11-25 16:56:58.144 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - B0CE181403550D75: transactionComplete, state=FAILED, outstanding=0

2020-11-25 16:56:58.146 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - B0CE181403550D75: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=B0CE181403550D75 queueTime=4739, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> C584/0, cluster=0000, TID=8F, ieeeAddr=B0CE181403550D75, requestType=0, startIndex=0]]

2020-11-25 16:56:58.147 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3

2020-11-25 16:56:58.148 [DEBUG] [transaction.ZigBeeTransactionManager] - C584/0: Sending ZigBeeTransaction [ieeeAddress=B0CE181403550D75 queueTime=4742, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> C584/0, cluster=0000, TID=8F, ieeeAddr=B0CE181403550D75, requestType=0, startIndex=0]]

2020-11-25 16:56:58.150 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-11-25 16:56:58.151 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> C584/0, cluster=0000, TID=8F, ieeeAddr=B0CE181403550D75, requestType=0, startIndex=0]

2020-11-25 16:56:58.153 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=C584/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=D6, rssi=--, lqi=--, payload=8F 75 0D 55 03 14 18 CE B0 00 00]

2020-11-25 16:56:58.155 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=C584, TID=8F, event=RX_NAK, state=DISPATCHED

2020-11-25 16:56:58.155 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=C584, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=D6], messageTag=8F, messageContents=8F 75 0D 55 03 14 18 CE B0 00 00]

2020-11-25 16:56:58.157 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:58.159 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=4, ackNum=6, reTx=false, data=AC 00 34 00 84 C5 00 00 00 00 00 00 40 11 00 00 D6 8F 0B 8F 75 0D 55 03 14 18 CE B0 00 00]

2020-11-25 16:56:58.174 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=5, reTx=false, data=AC 80 34 00 0B]

2020-11-25 16:56:58.176 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=4, ackNum=6, reTx=false, data=AC 00 34 00 84 C5 00 00 00 00 00 00 40 11 00 00 D6 8F 0B 8F 75 0D 55 03 14 18 CE B0 00 00]

2020-11-25 16:56:58.178 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=0B]

2020-11-25 16:56:58.179 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]

2020-11-25 16:56:59.454 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

2020-11-25 16:56:59.456 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=5, ackNum=7, reTx=false, data=AD 00 18]

2020-11-25 16:56:59.466 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=6, reTx=false, data=AD 80 18 02]

2020-11-25 16:56:59.467 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=5, ackNum=7, reTx=false, data=AD 00 18]

2020-11-25 16:56:59.468 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]

2020-11-25 16:57:00.459 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1

[Bruce_Osborne]

While waiting for Chris perhaps the log viewer can help.

ZigBee Log Viewer

[chris (Chris Jackson)]

There are only a few transactions in the log, but none of the commands receive a response. It seems that the devices are not contactable by the coordinator.

[Jon_A]

So what does that mean? The devices added fine, and operated fine on the same rasp PI running home assistant. So it has to be a software issue with openhab.

[Bruce_Osborne]

@Jon_A

So what does that mean?

the log had no meaningful information. What works well is to det the DEBUG flag and then either restart just the zwave binding or restart openHAB. That would capture all the discovery information & communication. You could then try & control to add that information top the log file.

@Jon_A

operated fine on the same rasp PI running home assistant. So it has to be a software issue with openhab.

Home Assistant “eavesdrops” when a device is first added to the network A Z-Wave device is required to respond with its information to a PIR request, That is what openHAB uses. We have over 1300 supported devices in the community maintained database.

these posts should really be in a new thread since we are not even discussing Zigbee, but a competing technology.

[Jon_A]

Now I’m really confused. You keep referencing restarting the zwave binding (which has no issues at all), and the 1300 zwave devices supported.

What do you mean we are not discussing zigbee but a competing technology? I’m just talking about zigbee bulbs here.