Hi Both,
just a short thing that I figured you some minutes ago for Bubs connected to the Mains.
If I disable the Thing (the Bulb), enable it again it remains in “Unknown”.
Now If I turn on the Mains => It immediately comes online from “Unknown”.
BR
/Franz
I edited my previous post to clarify a bit.
to keep the Hue bulbs registered as online a brightness command can be sent as a “keepalive”.
So, Send a brightness command when a bulb goes from online to offline to see if it really is offline?
It means in the device - there is no table in the coordinator.
That is not related to the binding table - it is related to the size of routing tables. If you have a larger network, then you csn try increasing the size, however most firmware has not been compiled correctly and doesn’t increase the memory, so this can cause problems.
How large is your network?
Hue bulbs definitely do send reports.
Yes. Before setting a device to offline the binding also tries to poll, so if it has not sent a report, it still should answer a poll to stay online.
Apologies it has taken me a while to look at these logs - I’ve been quite busy over the past 10 days or so.
I’ve just had a quick look, and all the OFFLINE devices in the log occur right at the beginning during the initialisation. It seems that they are not communicating - at least commands sent to them do not receive a response as far as I can see.
One interesting thing I noted is one of the devices (a battery device, but I don’t know what it is - 0017880104B777D4) is continually changing parent - so it leaves and rejoins the network. When it leaves, it gets marked offline by the framework, and then it normally rejoins with a new parent. This might just be that the device is “half way” (in an RF sense) between multiple devices, and as the RF environment changes, it swaps parent. This happens over 100 times in a 1 hour log, so something doesn’t really seem right here but I can’t really say what. It does seem strange as the device uses quite a few different parents so maybe there is something else going on, or maybe the device has a problem. Really a device should stick with a single parent unless the parent is not contactable - this device seems to change every 30 or so seconds, so I think it might have a problem.
This device failed to send the reports, AND it failed to respond to the “last chance” poll -:
2021-12-19 12:55:41.615 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:62ec522f14:00178801042f8978
2021-12-19 12:55:41.617 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00178801042F8978: Polling stopped
2021-12-19 12:55:41.618 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00178801042F8978: Polling initialised at 941807ms
2021-12-19 12:55:58.952 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:62ec522f14:001788010204b546
2021-12-19 12:55:58.954 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Polling stopped
2021-12-19 12:55:58.955 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Polling initialised at 943865ms
2021-12-19 12:56:11.620 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:62ec522f14:00178801042f8978
I don’t see the EZSP TX frames in your log so I can’t verify 100% that the poll was sent, but the “last chance poll” is sent by the binding when a binding has failed to receive a report from the device within the expected time - it then tries to poll the device, and if it still doesn’t receive a response it marks the device as offline.
I do see this with a few devices - it looks like the binding is working correctly here, but devices are not responding for some reason.
Sorry - this isn’t particularly helpful I know, but it does seem that devices aren’t responding on the network, so the binding is correct (IMHO) in marking them as offline. A sniffer log might provide more information about what is happening down in the network layer (the binding doesn’t get to see this as it’s managed by the NCP) - or the sniffer log might just confirm that devices aren’t talking at the network layer either (which seems likely based on the information here)…
My guess is that maybe there’s a rogue device in your system - possibly the battery device that is changing parents every 30 seconds or so, but this could be a consequence of something else.
It would be interesting to see the full output from the ncpscan command to see if you have an RF issue - possibly running this a few times to try and get the energy values (unfortunately I don’t think it’s possible to just request the energy scan).
Hi Chris,
Currently it looks like this (With one Coordinator Ember Stick)
openhab> zigbee nodes | grep ROUTER | WC -l
17
openhab> zigbee nodes | grep END_DEVICE | WC -l
11
Another good news to let you know today I connected a Zigbee Valve openener designed for Tuya and it worked out of the box! Kudos!
BR
/Franz
Hi Chris,
thanks for doing the logfile analysis! Thats really great so far.
Yes with that Device (its a SML001 Motion Sensor von Philipps) I often phase issues.
UID: zigbee:philips_sml001:62ec522f14:0017880104b777d4
label: Zigbee Hue Wirtschaftsraum MotionSensor
thingTypeUID: zigbee:philips_sml001
configuration:
zigbee_macaddress: 0017880104B777D4
bridgeUID: zigbee:coordinator_ember:62ec522f14
But on the other hand the Motion sensor is not too far (2 walls on the same level) away from the coordinator and really close to a Zigbee panel that is always connected to the MAINS.
I often need to relearn this Sensor back to the network because it “stucks” (seems to be online but not reporting data).
BR
/Franz
Hi Chris,
How can I start the ncpscan? Do I have to disable the coordinator?
openhab> zigbee ncpscan
Error performing active scan
CH RSSI
In theory it should work when the system is running - there are two scans - the active scan (which may give errors when the system is running - and this is what you see) and the energy scan, which doesn’t seem to give an error, but also doesn’t print data.
I recall you provided a debug log in the past for this, but can I ask for another one please so I can take a second look at this second part.
Hi Chris,
Now I did:
log:set debug org.openhab.binding.zigbee
log:set debug com.zsmartsystems.zigbee
log:set debug com.zsmartsystems.zigbee.dongle.ember
log:set info com.zsmartsystems.zigbee.dongle.ember.internal.ash
zigbee ncpscan
log:set warn org.openhab.binding.zigbee
log:set warn com.zsmartsystems.zigbee
log:set warn com.zsmartsystems.zigbee.dongle.ember
log:set warn com.zsmartsystems.zigbee.dongle.ember.internal.ash
log:display
And this is the output:
10:46:16.593 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'FritzBox_DSLMaxDownstreamRate' changed from 105.119 Mbit/s to 104.448 Mbit/s
10:46:36.950 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'FJSIphonePingableNetworkDevice_Location' changed from 49.04281112608675,12.087916947826516,0.0 to 49.042696387806856,12.088019665841172,0.0
10:46:36.957 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DistanceFromHome' changed from 5 to 9
10:46:37.975 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspNetworkFoundHandler [networkId=0, networkFound=EmberZigbeeNetwork [channel=17, panId=D896, extendedPanId=D1EDA82EE040441A, allowingJoin=false, stackProfile=2, nwkUpdateId=0], lastHopLqi=156, lastHopRssi=-61]
10:46:37.996 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspNetworkFoundHandler [networkId=0, networkFound=EmberZigbeeNetwork [channel=17, panId=D896, extendedPanId=D1EDA82EE040441A, allowingJoin=false, stackProfile=2, nwkUpdateId=0], lastHopLqi=228, lastHopRssi=-43]
10:46:38.001 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspNetworkFoundHandler [networkId=0, networkFound=EmberZigbeeNetwork [channel=17, panId=D896, extendedPanId=D1EDA82EE040441A, allowingJoin=false, stackProfile=2, nwkUpdateId=0], lastHopLqi=72, lastHopRssi=-82]
10:46:38.006 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspNetworkFoundHandler [networkId=0, networkFound=EmberZigbeeNetwork [channel=17, panId=D896, extendedPanId=D1EDA82EE040441A, allowingJoin=false, stackProfile=2, nwkUpdateId=0], lastHopLqi=216, lastHopRssi=-46]
10:46:38.010 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspNetworkFoundHandler [networkId=0, networkFound=EmberZigbeeNetwork [channel=17, panId=D896, extendedPanId=D1EDA82EE040441A, allowingJoin=false, stackProfile=2, nwkUpdateId=0], lastHopLqi=136, lastHopRssi=-66]
10:46:38.016 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspNetworkFoundHandler [networkId=0, networkFound=EmberZigbeeNetwork [channel=17, panId=D896, extendedPanId=D1EDA82EE040441A, allowingJoin=false, stackProfile=2, nwkUpdateId=0], lastHopLqi=168, lastHopRssi=-58]
10:46:38.021 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspNetworkFoundHandler [networkId=0, networkFound=EmberZigbeeNetwork [channel=17, panId=D896, extendedPanId=D1EDA82EE040441A, allowingJoin=false, stackProfile=2, nwkUpdateId=0], lastHopLqi=156, lastHopRssi=-61]
10:46:38.036 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspNetworkFoundHandler [networkId=0, networkFound=EmberZigbeeNetwork [channel=17, panId=D896, extendedPanId=D1EDA82EE040441A, allowingJoin=false, stackProfile=2, nwkUpdateId=0], lastHopLqi=152, lastHopRssi=-62]
10:46:39.265 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Polling [zigbee:device:62ec522f14:001788010204b546:001788010204B546_11_dimmer, zigbee:device:62ec522f14:001788010204b546:001788010204B546_11_colortemperature] channels...
10:46:41.937 [DEBUG] [tsystems.zigbee.dongle.ember.EmberNcp] - Active scan response: EzspNetworkFoundHandler [networkId=0, networkFound=EmberZigbeeNetwork [channel=17, panId=D896, extendedPanId=D1EDA82EE040441A, allowingJoin=false, stackProfile=2, nwkUpdateId=0], lastHopLqi=152, lastHopRssi=-62]
10:46:41.942 [DEBUG] [tsystems.zigbee.dongle.ember.EmberNcp] - Invalid response during active scan: EzspNetworkFoundHandler [networkId=0, networkFound=EmberZigbeeNetwork [channel=17, panId=D896, extendedPanId=D1EDA82EE040441A, allowingJoin=false, stackProfile=2, nwkUpdateId=0], lastHopLqi=152, lastHopRssi=-62]
10:46:41.955 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspStartScanResponse [networkId=0, status=EMBER_MAC_SCANNING]
10:46:44.417 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker Timeout has been reached for thingUID=zigbee:device:62ec522f14:001788010204b546
10:46:44.423 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:62ec522f14:001788010204b546' changed from ONLINE to OFFLINE
10:46:44.426 [INFO ] [.model.script.rules.SendColoAndBright] - event: Thing 'zigbee:device:62ec522f14:001788010204b546' changed from ONLINE to OFFLINE
10:46:44.432 [INFO ] [.model.script.rules.SendColoAndBright] - event.itemName: undefined
10:46:44.436 [INFO ] [.model.script.rules.SendColoAndBright] - event.thingUID: zigbee:device:62ec522f14:001788010204b546
10:46:44.440 [INFO ] [.model.script.rules.SendColoAndBright] - event.statusInfo: OFFLINE
10:46:44.445 [INFO ] [.model.script.rules.SendColoAndBright] - myaction: OfflineUpdate
10:46:44.449 [INFO ] [.model.script.rules.SendColoAndBright] - myTagToSearchFor: LightAutomatic,LightAutomaticOffline
10:46:44.454 [INFO ] [.model.script.rules.SendColoAndBright] - Found items: 6
10:46:44.460 [INFO ] [.model.script.rules.SendColoAndBright] - myAction: UpdateSend: :ZigbeeHueKuchePanel_LevelControl old: 100 new: 100
10:46:44.468 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'ZigbeeHueKuchePanel_LevelControl' received command 100
10:46:44.469 [INFO ] [.model.script.rules.SendColoAndBright] - myAction: UpdateSend: :ZigbeeHueEsszimmerR_LevelControl old: 100 new: 100
10:46:44.473 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'ZigbeeHueKuchePanel_LevelControl' predicted to become 100
10:46:44.480 [INFO ] [.model.script.rules.SendColoAndBright] - myAction: UpdateSend: :ZigbeeHueEsszimmerR_ColorTemperature old: 71 new: 71
10:46:44.481 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 00178801045014FA: Command for channel zigbee:device:62ec522f14:00178801045014fa:00178801045014FA_11_dimmer --> 100 [PercentType]
10:46:44.482 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'ZigbeeHueEsszimmerR_LevelControl' received command 100
10:46:44.488 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'ZigbeeHueEsszimmerR_LevelControl' predicted to become 100
10:46:44.491 [INFO ] [.model.script.rules.SendColoAndBright] - myAction: UpdateSend: :ZigbeeHueKuchePanel_ColorTemperature old: 71 new: 71
10:46:44.497 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'ZigbeeHueEsszimmerR_ColorTemperature' received command 71
10:46:44.499 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00178801045014FA: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00178801045014FA queueTime=0, state=WAITING, sendCnt=0, command=MoveToLevelWithOnOffCommand [Level Control: 0000/0 -> 56C8/11, cluster=0008, TID=--, level=254, transitionTime=10]]
10:46:44.502 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'ZigbeeHueEsszimmerR_ColorTemperature' predicted to become 71
10:46:44.507 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
10:46:44.512 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'ZigbeeHueKuchePanel_ColorTemperature' received command 71
10:46:44.513 [DEBUG] [.transaction.ZigBeeTransactionManager] - 56C8/11: Sending ZigBeeTransaction [ieeeAddress=00178801045014FA queueTime=19, state=WAITING, sendCnt=0, command=MoveToLevelWithOnOffCommand [Level Control: 0000/0 -> 56C8/11, cluster=0008, TID=DC, level=254, transitionTime=10]]
10:46:44.519 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:62ec522f14:001788010204b546' changed from OFFLINE to UNINITIALIZED
10:46:44.524 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 00178801045014FA: Command for channel zigbee:device:62ec522f14:00178801045014fa:00178801045014FA_11_colortemperature --> 71 [PercentType]
10:46:44.524 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204ACCE: Command for channel zigbee:device:62ec522f14:001788010204acce:001788010204ACCE_11_dimmer --> 100 [PercentType]
10:46:44.525 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'ZigbeeHueKuchePanel_ColorTemperature' predicted to become 71
10:46:44.528 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
10:46:44.529 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Handler dispose.
10:46:44.540 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Polling stopped
10:46:44.545 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker removed for thingUID=zigbee:device:62ec522f14:001788010204b546
10:46:44.554 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: MoveToLevelWithOnOffCommand [Level Control: 0000/0 -> 56C8/11, cluster=0008, TID=DC, level=254, transitionTime=10]
10:46:44.559 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=220, commandId=4]
10:46:44.560 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:62ec522f14:001788010204b546' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
10:46:44.570 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=56C8/11, profile=0104, cluster=0008, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=98, rssi=--, lqi=--, payload=01 DC 04 FE 0A 00]
10:46:44.576 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 00178801045014FA: Channel zigbee:device:62ec522f14:00178801045014fa:00178801045014FA_11_dimmer waiting for response to 100
10:46:44.576 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 001788010204ACCE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=001788010204ACCE queueTime=0, state=WAITING, sendCnt=0, command=MoveToLevelWithOnOffCommand [Level Control: 0000/0 -> 0CE1/11, cluster=0008, TID=--, level=254, transitionTime=10]]
10:46:44.580 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204ACCE: Command for channel zigbee:device:62ec522f14:001788010204acce:001788010204ACCE_11_colortemperature --> 71 [PercentType]
10:46:44.583 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
10:46:44.588 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=82]
10:46:44.590 [DEBUG] [.transaction.ZigBeeTransactionManager] - 0CE1/11: Sending ZigBeeTransaction [ieeeAddress=001788010204ACCE queueTime=14, state=WAITING, sendCnt=0, command=MoveToLevelWithOnOffCommand [Level Control: 0000/0 -> 0CE1/11, cluster=0008, TID=DD, level=254, transitionTime=10]]
10:46:44.596 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
10:46:44.601 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: MoveToLevelWithOnOffCommand [Level Control: 0000/0 -> 0CE1/11, cluster=0008, TID=DD, level=254, transitionTime=10]
10:46:44.605 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=221, commandId=4]
10:46:44.609 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=0CE1/11, profile=0104, cluster=0008, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=99, rssi=--, lqi=--, payload=01 DD 04 FE 0A 00]
10:46:44.615 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 001788010204ACCE: Channel zigbee:device:62ec522f14:001788010204acce:001788010204ACCE_11_dimmer waiting for response to 100
10:46:44.615 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00178801045014FA: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00178801045014FA queueTime=0, state=WAITING, sendCnt=0, command=MoveToColorTemperatureCommand [Color Control: 0000/0 -> 56C8/11, cluster=0300, TID=--, colorTemperature=289, transitionTime=10]]
10:46:44.622 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
10:46:44.626 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 00178801045014FA: Channel zigbee:device:62ec522f14:00178801045014fa:00178801045014FA_11_colortemperature waiting for response to 71
10:46:44.626 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=83]
10:46:44.627 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 001788010204ACCE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=001788010204ACCE queueTime=0, state=WAITING, sendCnt=0, command=MoveToColorTemperatureCommand [Color Control: 0000/0 -> 0CE1/11, cluster=0300, TID=--, colorTemperature=289, transitionTime=10]]
10:46:44.636 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=2, sleepy=0/3
10:46:44.640 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 001788010204ACCE: Channel zigbee:device:62ec522f14:001788010204acce:001788010204ACCE_11_colortemperature waiting for response to 71
10:46:45.880 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'A52SandraPingableNetworkDevice_LastSeen' changed from 2022-01-03T10:46:06.101+0100 to 2022-01-03T10:46:41.191+0100
10:46:46.080 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:62ec522f14:001788010204b546' changed from UNINITIALIZED (DISABLED) to INITIALIZING
10:46:46.092 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Initializing ZigBee thing handler zigbee:device:62ec522f14:001788010204b546
10:46:46.103 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Coordinator status changed to ONLINE.
10:46:46.103 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:62ec522f14:001788010204b546' changed from INITIALIZING to UNKNOWN
10:46:46.109 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Coordinator is ONLINE. Starting device initialisation.
10:46:46.114 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 001788010204B546: NWK Discovery starting node rediscovery
10:46:46.118 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 001788010204B546: NWK Discovery: Rediscovery using unicast to 47B8
10:46:46.125 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Start initialising ZigBee Thing handler
10:46:46.128 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 001788010204B546: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=001788010204B546 queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 47B8/0, cluster=0000, TID=--, ieeeAddr=001788010204B546, requestType=0, startIndex=0]]
10:46:46.134 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 001788010204B546: ZigBee node property discovery start
10:46:46.137 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=3, sleepy=0/3
10:46:46.140 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 001788010204B546: ZigBee node property discovery using basic cluster on endpoint 47B8/11
10:46:46.143 [DEBUG] [.transaction.ZigBeeTransactionManager] - 47B8/0: Sending ZigBeeTransaction [ieeeAddress=001788010204B546 queueTime=17, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 47B8/0, cluster=0000, TID=DE, ieeeAddr=001788010204B546, requestType=0, startIndex=0]]
10:46:46.146 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 001788010204B546: ZigBee node property discovery using OTA cluster on endpoint 47B8/11
10:46:46.149 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding
10:46:46.152 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 001788010204B546: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x100b, modelId=LTW001, zigbee_networkaddress=18360, zigbee_powersource=MAINS, zigbee_datecode=20210331, zigbee_stkversion=1, zigbee_zclversion=1, zigbee_routes=[], zigbee_lastupdate=, zigbee_stkcompliance=0, vendor=Signify Netherlands B.V., zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS, RECHARGABLE_BATTERY, DISPOSABLE_BATTERY], hardwareVersion=20, firmwareVersion=0x43005801, zigbee_neighbors=[], zigbee_applicationVersion=2, zigbee_device_initialised=false, zigbee_devices=[]}
10:46:46.155 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> 47B8/0, cluster=0000, TID=DE, ieeeAddr=001788010204B546, requestType=0, startIndex=0]
10:46:46.169 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Checking endpoint 242 channels
10:46:46.172 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=47B8/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=9A, rssi=--, lqi=--, payload=DE 46 B5 04 02 01 88 17 00 00 00]
10:46:46.180 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Checking endpoint 11 channels
10:46:46.191 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=84]
10:46:46.191 [DEBUG] [ter.ZigBeeChannelConverterFactoryImpl] - 001788010204B546: Removing channel zigbee:switch_onoff in favor of zigbee:switch_level
10:46:46.198 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Dynamically created 2 channels
10:46:46.203 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Initializing device
10:46:46.207 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Initializing channel zigbee:device:62ec522f14:001788010204b546:001788010204B546_11_colortemperature with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterColorTemperature@1620941
10:46:46.212 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 001788010204B546: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=001788010204B546 queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 47B8/0, cluster=0021, TID=--, srcAddress=001788010204B546, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=04CD15FFFEBB3E7B, dstEndpoint=1]]
10:46:46.216 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=3, sleepy=0/3
10:46:47.615 [INFO ] [.model.script.rules.SendColoAndBright] - myAction: UpdateSend: :ZigbeeHueEsszimmerL_LevelControl old: 100 new: 100
10:46:47.622 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'ZigbeeHueEsszimmerL_LevelControl' received command 100
10:46:47.623 [INFO ] [.model.script.rules.SendColoAndBright] - myAction: UpdateSend: :ZigbeeHueEsszimmerL_ColorTemperature old: 71 new: 71
10:46:47.627 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'ZigbeeHueEsszimmerL_LevelControl' predicted to become 100
10:46:47.634 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Command for channel zigbee:device:62ec522f14:001788010204b546:001788010204B546_11_dimmer --> 100 [PercentType]
10:46:47.636 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'ZigbeeHueEsszimmerL_ColorTemperature' received command 71
10:46:47.638 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: No handler found for zigbee:device:62ec522f14:001788010204b546:001788010204B546_11_dimmer
10:46:47.640 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'ZigbeeHueEsszimmerL_ColorTemperature' predicted to become 71
10:46:47.653 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: Command for channel zigbee:device:62ec522f14:001788010204b546:001788010204B546_11_colortemperature --> 71 [PercentType]
10:46:47.657 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 001788010204B546: No handler found for zigbee:device:62ec522f14:001788010204b546:001788010204B546_11_colortemperature
10:46:48.012 [DEBUG] [tsystems.zigbee.dongle.ember.EmberNcp] - EzspScanCompleteHandler [networkId=0, channel=0, status=EMBER_SUCCESS]
10:46:48.012 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspScanCompleteHandler [networkId=0, channel=0, status=EMBER_SUCCESS]
10:46:48.040 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=56C8, apsFrame=EmberApsFrame [profileId=0104, clusterId=0008, sourceEndpoint=1, destinationEndpoint=11, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=82], messageTag=DC, status=EMBER_SUCCESS, messageContents=]
10:46:48.046 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DC state=RX_ACK
Stupid question but could channel 0 be the issue?
10:46:48.012 [DEBUG] [tsystems.zigbee.dongle.ember.EmberNcp] - EzspScanCompleteHandler [networkId=0, channel=0, status=EMBER_SUCCESS]
10:46:48.012 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspScanCompleteHandler [networkId=0, channel=0, status=EMBER_SUCCESS]
No - the problem is much earlier than this - it’s to do with the way the handler associates the responses to this command as it receives multiple responses to a single command. I need to look into this more as it’s normally only used before the network is online and I suspect it’s getting another message being received when it’s waiting for the scan responses.
I’ve found the cause of the scan problem. It is a timeout in the scan commands - it’s something I’d raised an issue on a while ago but then forget about 
This will require an update of the libraries in the binding - I’ll look to do this in the next week or so.
Hi Chris,
thanks a lot for the update don the NCPScan.
I did a closer look the “We change the parrent each and every time”.
I hope this is the right log passage. (It looks like its trying all possible nodes as parents.
This is really really strange
2021-12-19 12:17:55.616 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=00C2]
2021-12-19 12:18:34.302 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=D2B0]
2021-12-19 12:22:47.421 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=09E7]
2021-12-19 12:25:06.872 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=09E7]
2021-12-19 12:32:00.271 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=09E7]
2021-12-19 12:32:14.802 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=09E7]
2021-12-19 12:32:51.958 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=56C8]
2021-12-19 12:33:01.709 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=0CE1]
2021-12-19 12:33:26.252 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=CA63]
2021-12-19 12:33:35.601 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=0000]
2021-12-19 12:33:54.970 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=CA63]
2021-12-19 12:34:27.948 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=5716]
2021-12-19 12:34:56.078 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=CA63]
2021-12-19 12:35:23.226 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=CA63]
2021-12-19 12:35:56.104 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=D2B0]
2021-12-19 12:36:26.256 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=CA63]
2021-12-19 12:36:59.137 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=5CF0]
2021-12-19 12:37:32.107 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=87BF]
2021-12-19 12:37:32.191 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=87BF]
2021-12-19 12:38:04.888 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=D2B0]
2021-12-19 12:38:37.763 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=CA63]
2021-12-19 12:39:10.739 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=129D]
2021-12-19 12:39:43.581 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=0CE1]
2021-12-19 12:40:16.438 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=87BF]
2021-12-19 12:40:16.507 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=87BF]
2021-12-19 12:40:49.328 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=5372]
2021-12-19 12:41:22.111 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=47B8]
2021-12-19 12:41:54.993 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=0CE1]
2021-12-19 12:42:27.861 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=129D]
2021-12-19 12:43:00.832 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=129D]
2021-12-19 12:43:33.706 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=D2B0]
2021-12-19 12:44:06.456 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=129D]
2021-12-19 12:44:39.408 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=5CF0]
2021-12-19 12:45:11.569 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=0000]
2021-12-19 12:45:13.555 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=BC63, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=0000]
2021-12-19 13:16:32.218 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=A1FA, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=47B8]
2021-12-19 13:16:52.066 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=A1FA, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=5CF0]
2021-12-19 13:17:11.932 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=A1FA, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=129D]
2021-12-19 13:17:31.743 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=A1FA, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=129D]
2021-12-19 13:17:51.481 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=A1FA, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=D2B0]
2021-12-19 13:18:11.509 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=A1FA, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=00C2]
2021-12-19 13:18:31.181 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=A1FA, newNodeEui64=0017880104B777D4, status=EMBER_STANDARD_SECURITY_SECURED_REJOIN, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=D2B0]
I guess this is an issue that happens quite often with the new learning of the Button.
If i recapitulate the only thing that makes the device work again (It did not worked during the Parent change was to reset it.
Hi @chris,
I did some more research and found some interesting things in this thread:
It seems to be related to “source_routing”
Some Commits are described here:
This thread is not really relevant - as far as I understand you are using the Ember chipset (or am I wrong)? This thread is about the CC2531 and it’s not really possible to use source routing as the NCP does all the routing.
Hello @chris,
Thanks for the update here.
Yes I’m using an Ember chipset EFR32MG21.
Okay I’m still in the learning phase and not yet aware about what does what when.
But the Symptoms are exactly what the same here. The device disconnects and creates trouble in the Network.
The most weired thing here is that i have 3 SML001 Hue Sensors.
One of them required to be learned multiple times (0017880104B75CAC), that is showing the name also twice below but is working now fine since round about 14 days.
openhab> zigbee nodes | grep SML001
4635 121B 0017880104B75CAC END_DEVICE ONLINE 1 ZIGBEE_LIGHT_LINK ZLL_ON_OFF_SENSOR Philips SML001
2 ZIGBEE_HOME_AUTOMATION OCCUPANCY_SENSOR Philips SML001
10095 276F 0017880104B76DA0 END_DEVICE ONLINE 1 ZIGBEE_LIGHT_LINK ZLL_ON_OFF_SENSOR Philips SML001
26647 6817 0017880104B777D4 END_DEVICE ONLINE 1 ZIGBEE_LIGHT_LINK ZLL_ON_OFF_SENSOR Philips SML001
The Second one is the one where you’ve seen the log already. (Disconnects daily)
And the 3rd one is also disconnecting nearly daily.
For this one I’ve took a closer look in the file file below.
The whole thing worked till 20:18 and then the sensor did no longer report data and stopped at “ON”.
The next transaction was then 10 minutes later at 20:28.
https://drive.google.com/file/d/1bKZM5hNCBdLaBKE7Y3TFviuhlSzsIn5F/view?usp=sharing
I guess one defect device could maybe be an hardware issue but two is very unlikely.
But for sure I would be also willing to exchange the Sensors.
Is there a better compatible Sensor known?
BR
/Franz
And one more thing
I found this statement. Is it really true that Osram devices can prevent re join of Hue devices?
Did you have some Osram plugs in your network? In #1474 it’s described that Osram plugs prevent a re-join of some devices (maily Hue motion sensors). By myself I got two Osram plugs in the network and Hue motion and Hue dimmer are randomly disconnected. After I removed the plugs from the network it seems to be stable.
Yes.
openhab> zigbee nodes|grep -i osram
23145 5A69 7CB03EAA00AF43EA ROUTER ONLINE 3 ZIGBEE_LIGHT_LINK ZLL_COLOR_TEMPERATURE_LIGHT OSRAM CLA60 TW OSRAM
55436 D88C 7CB03EAA00B0DF50 ROUTER ONLINE 3 ZIGBEE_LIGHT_LINK ZLL_ON_OFF_PLUG_IN_UNIT OSRAM Plug 01
64425 FBA9 7CB03EAA0A0C730C ROUTER ONLINE 3 ZIGBEE_LIGHT_LINK ZLL_ON_OFF_PLUG_IN_UNIT OSRAM Plug 01
openhab>
openhab> zigbee neighbors 23145
Total neighbors: 16
Extended PAN ID Extended Address Network Address Device Type RX On When Idle Relationship Permit Joining Depth LQI
AEF4E912E8CE2CD9 0017880106BCD664 54428 ROUTER RX_ON SIBLING ENABLED 1 24
AEF4E912E8CE2CD9 680AE2FFFEA4BF70 11592 ROUTER RX_ON SIBLING ENABLED 1 40
AEF4E912E8CE2CD9 00178801088701D7 29086 ROUTER RX_ON SIBLING ENABLED 1 76
AEF4E912E8CE2CD9 CCCCCCFFFEA4AFBC 43991 ROUTER RX_ON SIBLING ENABLED 1 60
AEF4E912E8CE2CD9 5C0272FFFE53C1E4 43610 ROUTER RX_ON SIBLING ENABLED 1 68
AEF4E912E8CE2CD9 00178801067B5C2D 6386 ROUTER RX_ON SIBLING ENABLED 1 58
AEF4E912E8CE2CD9 680AE2FFFE902839 44055 ROUTER RX_ON SIBLING ENABLED 1 24
AEF4E912E8CE2CD9 EC1BBDFFFE239C85 21907 ROUTER RX_ON SIBLING ENABLED 1 60
AEF4E912E8CE2CD9 086BD7FFFE1AFDDC 28852 ROUTER RX_ON SIBLING ENABLED 1 62
AEF4E912E8CE2CD9 001788010633DBD1 32393 ROUTER RX_ON SIBLING ENABLED 1 48
AEF4E912E8CE2CD9 680AE2FFFEA98766 50747 ROUTER RX_ON SIBLING ENABLED 1 20
AEF4E912E8CE2CD9 086BD7FFFE51A217 22691 ROUTER RX_ON SIBLING ENABLED 1 40
AEF4E912E8CE2CD9 EC1BBDFFFE1806E0 11303 ROUTER RX_ON SIBLING ENABLED 1 64
AEF4E912E8CE2CD9 EC1BBDFFFE003744 59646 ROUTER RX_ON SIBLING ENABLED 1 68
AEF4E912E8CE2CD9 EC1BBDFFFE8EAE4B 45876 ROUTER RX_ON SIBLING ENABLED 1 66
AEF4E912E8CE2CD9 0017880103FE0276 61537 ROUTER RX_ON SIBLING ENABLED 1 76
openhab> zigbee routingtable 23145
Routing table request not supported
openhab> zigbee neighbors 64425
Total neighbors: 9
Extended PAN ID Extended Address Network Address Device Type RX On When Idle Relationship Permit Joining Depth LQI
AEF4E912E8CE2CD9 680AE2FFFE876B81 19619 ROUTER RX_ON SIBLING ENABLED 2 18
AEF4E912E8CE2CD9 CCCCCCFFFEA4AFBC 43991 ROUTER RX_ON SIBLING ENABLED 2 12
AEF4E912E8CE2CD9 D0CF5EFFFE44B835 27332 ROUTER RX_ON PARENT ENABLED 2 38
AEF4E912E8CE2CD9 680AE2FFFEA98766 50747 ROUTER RX_ON SIBLING ENABLED 2 14
AEF4E912E8CE2CD9 680AE2FFFE902839 44055 ROUTER RX_ON SIBLING ENABLED 2 24
AEF4E912E8CE2CD9 90FD9FFFFE647A13 29463 ROUTER RX_ON SIBLING ENABLED 2 16
AEF4E912E8CE2CD9 0017880103FE0276 61537 ROUTER RX_ON SIBLING ENABLED 2 8
AEF4E912E8CE2CD9 7CB03EAA00B0DF50 55436 ROUTER RX_ON SIBLING ENABLED 2 28
AEF4E912E8CE2CD9 00178801062BF764 64775 ROUTER RX_ON SIBLING ENABLED 2 36
openhab> zigbee routingtable 64425
Routing table request not supported
openhab>
Mybe related. The Osrams have a firmware problem according to this: Failed to execute routing table for OSRAM Smart+ Plug · Issue #204 · Koenkk/zigbee-herdsman · GitHub
It looks like my devices have the latest firmware.
I use the “Plug 01” ones as engine heater switches. I have not found other outdoor wallplugs, so they are a bit difficult to replace.
But, it looks like I have to. I have Hue outdoor sensors i planned to mount next to them…
Related to the Hue sensor problem or not. It is not clear to me how this bug are problematic for the other devices in the mesh.
Edit to add:
It serms like the Osrams do not have a good radio.
My bulb is only a couple of meters from a bunch of Hues and Ikeas.
As for the "plug 01"s, they are at the edge of the mesh, but LQI values are lower than expected.
Hello Friends,
I want to give you a short update on this topic (Maybe also for other guys that read this article)
I’ve replaced all of my Osram Smart Plug+ with a TS011F Plug (Neo NAS-WR01B).
Since then I never needed to repair the Hue Motion Sensors anymore!
@chris: Thanks again for the great analytics that figured out there is an issue with the ZigBee motion sensor
@NilsOF Thanks a lot sharing your experience with the Smart+ Plug.
BR
/Franz
Just for the record:
These Hue motion sensors seems to have problem taking some Ikea bulbs as ‘parents’ too.
It is obvious when sniffing; the motion sensors will try several times before they give up and look for another parent. This can not be good for battery life…
Hi @chris .
Performing energy scan… (openhab> zigbee ncpscan)
is now working.
What can we learn from the output?
Ember NCP active scan found 1 networks
CH PAN Extended PAN Stk Join Upd
17 D896 D1EDA82EE040441A 2 False 0
Performing energy scan...
CH RSSI
11 -81
12 -76
13 -72
14 -82
15 -65
16 -87
17 -68
18 -69
19 -87
20 -64
21 -63
22 -11
23 -64
24 -19
25 -59
26 -67