Zigbee binding

zigbee
beginners
Tags: #<Tag:0x00007fd3136aba10> #<Tag:0x00007fd3136ab8a8>

(Scott Karns) #1044

Kim, I’m not sure what the Switch channel is, it does nothing that I can detect on my Philips motion detector. The Occupancy channel indicates when motion is detected.


(Chris Jackson) #1045

I suspect it’s fundamentally not used. I believe it’s there to allow control of other devices directly - the binding of course doesn’t know this so it just shows all available channels.


(Kim Andersen) #1046

Hmm, I didnt think the motion sensor would be the Occupancy switch. I dont believe it´s registrering motions like it use to. But I´ll test it more later.


(Chris Jackson) #1047

Please consider that the binding will present ALL channels that it thinks the device supports - it does not mean the device supports them! The binding detects the features from the device, and then provides channels. In the case of this device, there are a few channels that are provided and some, like this switch, are not used. It’s as I said in my earlier message.

This switch is there to allow controlling other device (ie lights) directly - you can’t use this so I suggest to ignore it.


(Joe) #1048

Hi,

i have a Telegesis ETRX3 Dongle (long range).
Now i try to connect to a hue bulb (LTR001). I did a reset on the bulb with the philips dimmer and the discovery of the zigbee binding shows me the bulb. After adding the bulb as a thing the status says “Offline”.
The bulb is a about 4 meters away from the dongle with direct view connection.
What can i do?

2018-07-14 19:27:43.550 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 0017880103E631B0: Starting ZigBee device discovery

2018-07-14 19:27:43.552 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 0017880100FF64A9: Starting ZigBee device discovery

2018-07-14 19:27:43.563 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:04000A33:0017880103e631b0' to inbox.

2018-07-14 19:27:43.573 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:04000A33:0017880100ff64a9' to inbox.

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

2018-07-14 19:27:43.594 [home.event.InboxAddedEvent] - Discovery Result with UID 'zigbee:device:04000A33:0017880103e631b0' has been added.

2018-07-14 19:27:43.616 [home.event.InboxAddedEvent] - Discovery Result with UID 'zigbee:device:04000A33:0017880100ff64a9' has been added.

2018-07-14 19:28:27.094 [me.event.InboxRemovedEvent] - Discovery Result with UID 'zigbee:device:04000A33:0017880100ff64a9' has been removed.

2018-07-14 19:28:27.147 [hingStatusInfoChangedEvent] - 'zigbee:device:04000A33:0017880100ff64a9' changed from UNINITIALIZED to INITIALIZING

2018-07-14 19:28:27.163 [hingStatusInfoChangedEvent] - 'zigbee:device:04000A33:0017880100ff64a9' changed from INITIALIZING to OFFLINE

2018-07-14 19:28:27.205 [me.event.ThingUpdatedEvent] - Thing 'zigbee:device:04000A33:0017880100ff64a9' has been updated.

2018-07-14 19:28:27.209 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:04000A33:0017880100ff64a9 changed to UNKNOWN.

(Kim Andersen) #1049

I simply cant get this Hue motion sensor to work.
First time included, there are no motion, but temperature and illumination seemed to work. I then removed it and included it again, and now nothing seems to work (update value), except temperature, which is showen but not updating.


(Chris Jackson) #1050

Please use debug logging to see what is happening.


(Kim Andersen) #1051

I will, but it doesn´t really say anything…
Seems like both the Philips Dimmer Switch (which is stated offline) and the Philips motion sensor have no communication with the Elelabs Rpi shield (Zigbee controller).

Here is the log…
I startet a manual scan for devices at 19:38:22

2018-07-15 19:33:09.117 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...

2018-07-15 19:33:24.030 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 000D6F000FA0C316: Discovery notification

2018-07-15 19:33:24.038 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.

2018-07-15 19:33:24.295 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.

2018-07-15 19:34:11.451 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...

2018-07-15 19:35:13.787 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...

2018-07-15 19:36:16.122 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...

2018-07-15 19:37:18.457 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...

2018-07-15 19:38:20.791 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...

2018-07-15 19:38:22.807 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:6ec05458

2018-07-15 19:38:22.812 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 60 seconds.

2018-07-15 19:38:22.816 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=24, permitDuration=60, tcSignificance=true]

2018-07-15 19:38:22.820 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=54, addressMode=DEVICE, radius=31, sequence=36, payload=00 3C 01]

2018-07-15 19:38:22.823 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendBroadcastRequest [destination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=36], radius=31, messageTag=36, messageContents=00 3C 01]

2018-07-15 19:38:22.827 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue: 1

2018-07-15 19:38:22.830 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendBroadcastRequest [destination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=36], radius=31, messageTag=36, messageContents=00 3C 01]

2018-07-15 19:38:22.834 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=0, ackNum=4, reTx=false, data=24 00 FF 00 36 FC FF 00 00 36 00 00 00 40 11 00 00 24 1F 24 03 00 3C 01]

2018-07-15 19:38:22.838 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=25, permitDuration=60, tcSignificance=true]

2018-07-15 19:38:22.842 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=54, addressMode=DEVICE, radius=31, sequence=37, payload=00 3C 01]

2018-07-15 19:38:22.846 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=37], messageTag=37, messageContents=00 3C 01]

2018-07-15 19:38:22.849 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue: 1

2018-07-15 19:38:22.952 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=1, reTx=false, data=24 80 FF 00 36 00 3C]

2018-07-15 19:38:22.955 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=0, ackNum=4, reTx=false, data=24 00 FF 00 36 FC FF 00 00 36 00 00 00 40 11 00 00 24 1F 24 03 00 3C 01]

2018-07-15 19:38:22.957 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=60]

2018-07-15 19:38:22.959 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=60]

2018-07-15 19:38:22.960 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=60]

2018-07-15 19:38:22.962 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]

2018-07-15 19:38:22.965 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=37], messageTag=37, messageContents=00 3C 01]

2018-07-15 19:38:22.968 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=5, reTx=false, data=25 00 FF 00 34 00 00 00 00 00 36 00 00 00 40 11 00 00 25 25 03 00 3C 01]

2018-07-15 19:38:22.973 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=1, reTx=false, data=24 90 FF 00 45 05 00 00 36 00 00 00 00 01 00 00 3C FF 00 00 00 FF FF 03 00 3C 01]

2018-07-15 19:38:22.976 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=60], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]

2018-07-15 19:38:22.979 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=60], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]

2018-07-15 19:38:22.982 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=54, addressMode=null, radius=0, sequence=36, payload=00 3C 01]

2018-07-15 19:38:22.985 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=NULL, permitDuration=60, tcSignificance=true]

2018-07-15 19:38:22.989 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]

2018-07-15 19:38:23.024 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000D6F000FA0C316: Node SVC Discovery scheduled [NEIGHBORS, ROUTES]

2018-07-15 19:38:23.028 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 0017880102139D00: Node SVC Discovery already scheduled or running

2018-07-15 19:38:23.098 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=2, reTx=false, data=25 80 FF 00 34 00 3D]

2018-07-15 19:38:23.102 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=5, reTx=false, data=25 00 FF 00 34 00 00 00 00 00 36 00 00 00 40 11 00 00 25 25 03 00 3C 01]

2018-07-15 19:38:23.105 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=61]

2018-07-15 19:38:23.115 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=61]

2018-07-15 19:38:23.118 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=61]

2018-07-15 19:38:23.129 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]

2018-07-15 19:38:23.142 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=2, reTx=false, data=25 90 FF 00 45 00 00 00 36 00 00 00 40 01 00 00 3D FF 00 00 00 FF FF 03 00 3C 01]

2018-07-15 19:38:23.146 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=61], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]

2018-07-15 19:38:23.151 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=61], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]

2018-07-15 19:38:23.155 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=54, addressMode=null, radius=0, sequence=37, payload=00 3C 01]

2018-07-15 19:38:23.158 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=NULL, permitDuration=60, tcSignificance=true]

2018-07-15 19:38:23.161 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]

2018-07-15 19:38:23.167 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=2, reTx=false, data=25 90 FF 00 45 00 00 00 36 80 00 00 40 01 00 00 3E FF 00 00 00 FF FF 02 00 00]

2018-07-15 19:38:23.171 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32822, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=62], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]

2018-07-15 19:38:23.174 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32822, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=62], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]

2018-07-15 19:38:23.177 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=32822, addressMode=null, radius=0, sequence=37, payload=00 00]

2018-07-15 19:38:23.180 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=NULL, status=SUCCESS]

2018-07-15 19:38:23.183 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]

2018-07-15 19:38:23.186 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=2, reTx=false, data=25 90 FF 00 3F 00 00 00 00 00 36 00 00 00 40 11 00 00 3D 25 00 00]

2018-07-15 19:38:23.188 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=61], messageTag=37, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:23.190 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=61], messageTag=37, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:23.191 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=61], messageTag=37, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:23.193 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]

2018-07-15 19:38:23.898 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=2, reTx=false, data=25 90 FF 00 3F 06 FC FF 00 00 36 00 00 00 00 01 00 00 3C 24 00 00]

2018-07-15 19:38:23.903 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=60], messageTag=36, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:23.907 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=60], messageTag=36, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:23.911 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=60], messageTag=36, status=EMBER_SUCCESS, messageContents=]


(Kim Andersen) #1052

Log continue:

2018-07-15 19:38:23.914 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]

2018-07-15 19:38:24.626 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000D6F000FA0C316: Node SVC Discovery running

2018-07-15 19:38:24.630 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=26, startIndex=0]

2018-07-15 19:38:24.633 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=49, addressMode=DEVICE, radius=31, sequence=38, payload=00 00]

2018-07-15 19:38:24.661 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=38], messageTag=38, messageContents=00 00]

2018-07-15 19:38:24.663 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue: 1

2018-07-15 19:38:24.666 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=38], messageTag=38, messageContents=00 00]

2018-07-15 19:38:24.670 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=3, reTx=false, data=26 00 FF 00 34 00 00 00 00 00 31 00 00 00 40 11 00 00 26 26 02 00 00]

2018-07-15 19:38:24.799 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=3, reTx=false, data=26 80 FF 00 34 00 3F]

2018-07-15 19:38:24.802 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=3, reTx=false, data=26 00 FF 00 34 00 00 00 00 00 31 00 00 00 40 11 00 00 26 26 02 00 00]

2018-07-15 19:38:24.806 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=63]

2018-07-15 19:38:24.810 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=63]

2018-07-15 19:38:24.814 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=63]

2018-07-15 19:38:24.817 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]

2018-07-15 19:38:24.822 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=3, reTx=false, data=26 90 FF 00 45 00 00 00 31 00 00 00 40 01 00 00 3F FF 00 00 00 FF FF 02 00 00]

2018-07-15 19:38:24.825 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=63], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]

2018-07-15 19:38:24.828 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=63], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]

2018-07-15 19:38:24.830 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=49, addressMode=null, radius=0, sequence=38, payload=00 00]

2018-07-15 19:38:24.833 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=NULL, startIndex=0]

2018-07-15 19:38:24.838 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]

2018-07-15 19:38:24.842 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=3, reTx=false, data=26 90 FF 00 45 00 00 00 31 80 00 00 40 01 00 00 40 FF 00 00 00 FF FF 05 00 00 00 00 00]

2018-07-15 19:38:24.845 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32817, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=64], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 00 00 00]

2018-07-15 19:38:24.847 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32817, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=64], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 00 00 00]

2018-07-15 19:38:24.850 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=32817, addressMode=null, radius=0, sequence=38, payload=00 00 00 00 00]

2018-07-15 19:38:24.852 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=NULL, status=SUCCESS, neighborTableEntries=0, startIndex=0, neighborTableList=[]]

2018-07-15 19:38:24.855 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]

2018-07-15 19:38:24.856 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000D6F000FA0C316: Node SVC Discovery ManagementLqiRequest response CommandResult [SUCCESS, ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=NULL, status=SUCCESS, neighborTableEntries=0, startIndex=0, neighborTableList=[]]]

2018-07-15 19:38:24.859 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=3, reTx=false, data=26 90 FF 00 3F 00 00 00 00 00 31 00 00 00 40 11 00 00 3F 26 00 00]

2018-07-15 19:38:24.859 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000FA0C316: Neighbor table unchanged

2018-07-15 19:38:24.861 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=63], messageTag=38, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:24.863 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=63], messageTag=38, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:24.863 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000D6F000FA0C316: Node SVC Discovery request NEIGHBORS successful. Advanced to ROUTES.

2018-07-15 19:38:24.864 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=63], messageTag=38, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:24.866 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]

2018-07-15 19:38:24.870 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000D6F000FA0C316: Node SVC Discovery running

2018-07-15 19:38:24.872 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=27, startIndex=0]

2018-07-15 19:38:24.875 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=50, addressMode=DEVICE, radius=31, sequence=39, payload=00 00]

2018-07-15 19:38:24.877 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=39], messageTag=39, messageContents=00 00]

2018-07-15 19:38:24.880 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue: 1

2018-07-15 19:38:24.882 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=39], messageTag=39, messageContents=00 00]

2018-07-15 19:38:24.885 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=3, ackNum=7, reTx=false, data=27 00 FF 00 34 00 00 00 00 00 32 00 00 00 40 11 00 00 27 27 02 00 00]

2018-07-15 19:38:25.027 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=4, reTx=false, data=27 80 FF 00 34 00 41]

2018-07-15 19:38:25.030 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=3, ackNum=7, reTx=false, data=27 00 FF 00 34 00 00 00 00 00 32 00 00 00 40 11 00 00 27 27 02 00 00]

2018-07-15 19:38:25.031 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=65]

2018-07-15 19:38:25.033 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=65]

2018-07-15 19:38:25.035 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=65]

2018-07-15 19:38:25.037 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]

2018-07-15 19:38:25.040 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=4, reTx=false, data=27 90 FF 00 45 00 00 00 32 00 00 00 40 01 00 00 41 FF 00 00 00 FF FF 02 00 00]

2018-07-15 19:38:25.043 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=65], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]

2018-07-15 19:38:25.045 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=65], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]

2018-07-15 19:38:25.047 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=50, addressMode=null, radius=0, sequence=39, payload=00 00]

2018-07-15 19:38:25.049 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=NULL, startIndex=0]

2018-07-15 19:38:25.056 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]

2018-07-15 19:38:25.061 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=4, reTx=false, data=27 90 FF 00 45 00 00 00 32 80 00 00 40 01 00 00 42 FF 00 00 00 FF FF 50 00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00]

2018-07-15 19:38:25.064 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=66], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00]

2018-07-15 19:38:25.067 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=66], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00]

2018-07-15 19:38:25.070 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=32818, addressMode=null, radius=0, sequence=39, payload=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00]

2018-07-15 19:38:25.073 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=NULL, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]

2018-07-15 19:38:25.076 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]

2018-07-15 19:38:25.078 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=4, reTx=false, data=27 90 FF 00 3F 00 00 00 00 00 32 00 00 00 40 11 00 00 41 27 00 00]

2018-07-15 19:38:25.080 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=65], messageTag=39, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:25.080 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000D6F000FA0C316: Node SVC Discovery ManagementRoutingRequest returned CommandResult [SUCCESS, ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=NULL, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]]

2018-07-15 19:38:25.081 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=65], messageTag=39, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:25.083 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=28, startIndex=15]

2018-07-15 19:38:25.093 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=50, addressMode=DEVICE, radius=31, sequence=40, payload=00 0F]

2018-07-15 19:38:25.095 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=40], messageTag=40, messageContents=00 0F]

2018-07-15 19:38:25.097 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue: 1

2018-07-15 19:38:25.099 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=40], messageTag=40, messageContents=00 0F]

2018-07-15 19:38:25.101 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=4, ackNum=2, reTx=false, data=28 00 FF 00 34 00 00 00 00 00 32 00 00 00 40 11 00 00 28 28 02 00 0F]

2018-07-15 19:38:25.103 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=65], messageTag=39, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:25.105 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]

2018-07-15 19:38:25.230 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=5, reTx=false, data=28 80 FF 00 34 00 43]

2018-07-15 19:38:25.232 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=4, ackNum=2, reTx=false, data=28 00 FF 00 34 00 00 00 00 00 32 00 00 00 40 11 00 00 28 28 02 00 0F]

2018-07-15 19:38:25.233 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=67]

2018-07-15 19:38:25.235 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=67]

2018-07-15 19:38:25.236 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=67]

2018-07-15 19:38:25.238 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]

2018-07-15 19:38:25.240 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=5, reTx=false, data=28 90 FF 00 45 00 00 00 32 00 00 00 40 01 00 00 43 FF 00 00 00 FF FF 02 00 0F]

2018-07-15 19:38:25.242 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=67], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 0F]

2018-07-15 19:38:25.246 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=67], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 0F]

2018-07-15 19:38:25.247 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=50, addressMode=null, radius=0, sequence=40, payload=00 0F]

2018-07-15 19:38:25.249 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=NULL, startIndex=15]

2018-07-15 19:38:25.256 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]

2018-07-15 19:38:25.259 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=5, reTx=false, data=28 90 FF 00 45 00 00 00 32 80 00 00 40 01 00 00 44 FF 00 00 00 FF FF 0A 00 00 10 0F 01 00 00 03 00 00]

2018-07-15 19:38:25.266 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=68], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 0F 01 00 00 03 00 00]

2018-07-15 19:38:25.268 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=68], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 0F 01 00 00 03 00 00]

2018-07-15 19:38:25.271 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=32818, addressMode=null, radius=0, sequence=40, payload=00 00 10 0F 01 00 00 03 00 00]

2018-07-15 19:38:25.273 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=NULL, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]

2018-07-15 19:38:25.276 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]

2018-07-15 19:38:25.276 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000D6F000FA0C316: Node SVC Discovery ManagementRoutingRequest returned CommandResult [SUCCESS, ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=NULL, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]]

2018-07-15 19:38:25.279 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000FA0C316: Routing table NEW: [RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]

2018-07-15 19:38:25.281 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000FA0C316: Routing table OLD: [RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]

2018-07-15 19:38:25.282 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=5, reTx=false, data=28 90 FF 00 3F 00 00 00 00 00 32 00 00 00 40 11 00 00 43 28 00 00]

2018-07-15 19:38:25.284 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=67], messageTag=40, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:25.284 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000FA0C316: Routing table unchanged

2018-07-15 19:38:25.286 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=67], messageTag=40, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:25.287 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000D6F000FA0C316: Node SVC Discovery request ROUTES successful. Advanced to null.

2018-07-15 19:38:25.288 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=67], messageTag=40, status=EMBER_SUCCESS, messageContents=]

2018-07-15 19:38:25.289 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000D6F000FA0C316: Node SVC Discovery running

2018-07-15 19:38:25.290 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]

2018-07-15 19:38:25.293 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000D6F000FA0C316: Node SVC Discovery complete

2018-07-15 19:38:25.297 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000FA0C316: Node 0 update

2018-07-15 19:38:25.303 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 000D6F000FA0C316: Discovery notification

2018-07-15 19:38:25.310 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.

2018-07-15 19:38:25.524 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.

2018-07-15 19:39:23.127 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: 
Polling...

(Kim Andersen) #1053

And the polling just continue without any respond.

2018-07-15 19:50:48.812 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...
2018-07-15 19:51:51.147 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...
2018-07-15 19:52:53.482 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...

(Kim Andersen) #1054

Hmm, i think there are some problems located last in the log sequence:

2018-07-15 20:05:21.502 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...

2018-07-15 20:05:47.275 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 0017880102139D00: Node SVC Discovery running

2018-07-15 20:05:47.277 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 51573/0, cluster=0031, TID=3A, startIndex=0]

2018-07-15 20:05:47.280 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=51573/0, profile=0000, cluster=49, addressMode=DEVICE, radius=31, sequence=58, payload=00 00]

2018-07-15 20:05:47.282 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=51573, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=58], messageTag=58, messageContents=00 00]

2018-07-15 20:05:47.284 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue: 1

2018-07-15 20:05:47.286 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=51573, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=58], messageTag=58, messageContents=00 00]

2018-07-15 20:05:47.289 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=6, ackNum=7, reTx=false, data=3A 00 FF 00 34 00 75 C9 00 00 31 00 00 00 40 11 00 00 3A 3A 02 00 00]

2018-07-15 20:05:47.401 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=7, reTx=false, data=3A 80 FF 00 34 00 65]

2018-07-15 20:05:47.405 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=6, ackNum=7, reTx=false, data=3A 00 FF 00 34 00 75 C9 00 00 31 00 00 00 40 11 00 00 3A 3A 02 00 00]

2018-07-15 20:05:47.407 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=101]

2018-07-15 20:05:47.410 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=101]

2018-07-15 20:05:47.412 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=101]

2018-07-15 20:05:47.414 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]

2018-07-15 20:05:52.098 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=7, reTx=false, data=3A 90 FF 00 3F 00 75 C9 00 00 31 00 00 00 40 10 00 00 65 3A 66 00]

2018-07-15 20:05:52.102 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=51573, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=101], messageTag=58, status=EMBER_DELIVERY_FAILED, messageContents=]

2018-07-15 20:05:52.106 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=51573, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=101], messageTag=58, status=EMBER_DELIVERY_FAILED, messageContents=]

2018-07-15 20:05:52.109 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=51573, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=101], messageTag=58, status=EMBER_DELIVERY_FAILED, messageContents=]

2018-07-15 20:05:52.113 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]

2018-07-15 20:05:57.293 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 0017880102139D00: Node SVC Discovery ManagementLqiRequest response CommandResult [TIMEOUT]

2018-07-15 20:05:57.299 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 0017880102139D00: Node SVC Discovery request NEIGHBORS failed. Retry 325, wait 230928ms before retry.

2018-07-15 20:06:23.840 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102139D00: Polling...

(Kim Andersen) #1055

@chris
Did you see the log entries above?


(Chris Jackson) #1056

Yes, but I was quite busy yesterday so did not have the chance to look at them. I’ll try and take a look tonight - it would probably be good in future to keep the logs as a single attachment, and then post them on a site somewhere (eg dropbox, github, …).


(Kim Andersen) #1057

No worries. I was unsure wether you have seen it.

I´ll try use Dropbox next time then. These debug logs seems to be rather big.


(Kim Andersen) #1058

I think I got it running.
Had to exclude and include both the hue motion sensor as well as the hue dimmer switch several times. All of a sudden it seems to work. I wonder for how long…

Anyway, and new question…
When the hue devices seemed to work, I added a Osram Plug as well… It went super fast and added just fine. But…
When I enter Habmin to look at the plug, it says no channels are active… This make me wonder, cause I created the item file manually. PaperUI do see the items allright. How come Habmin doesn´t?

Second - it seems like the Osram plug tend to update very often, probably because it´s not battery driven. But how about battery drive devices. How often do they update? I had to force an update on the hue motion sensor from within habmin, before I received any Battery as well as Voltage status. It has been about 3 hours since i included the Hue sensor.


(James Twigger) #1059

Good evening Matt,

I’ve just experienced the exact same issue with my Telegesis ZigBee dongle. “Error setting Telegesis Prompt 1 register”.

I was looking, but couldn’t tell if you were able to resolve your issue. If so, would you mind sharing the solution with me?

Thank you sir,
Jim


(Chris Jackson) #1060

If I remember correctly, this is the first thing that is sent to the dongle so I would double check that you have the port configuration set correctly - eg 9600bd for starters unless you’ve somehow changed the speed.

If that’s all set, then I’d suggest to check the debug logs to see what is shown.


(James Twigger) #1061

Thanks Chris; however, a 9600 baud rate is not an option. The default (and lowest) baud rate available in the drop-down list is 19200 (I’ve also tried all other baud rate too just to see and none worked).

I have the debug also enabled for ZigBee. Below is what I see in the logs:

2018-07-17 20:39:16.460 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2018-07-17 20:39:16.462 [DEBUG] [bee.internal.ZigBeeNetworkDiscoverer] - Network discovery task shutdown
2018-07-17 20:39:16.512 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TelegesisFrameHandler thread exited.
2018-07-17 20:39:16.514 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port '/dev/ttyAMA0' closed.
2018-07-17 20:39:16.517 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TelegesisFrameHandler closed.
2018-07-17 20:39:16.519 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis dongle shutdown.
2018-07-17 20:39:16.521 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network [zigbee:coordinator_telegesis:695d80a3] closed.
2018-07-17 20:39:16.524 [DEBUG] [e.telegesis.handler.TelegesisHandler] - Initializing ZigBee Telegesis serial bridge handler.
2018-07-17 20:39:16.526 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_telegesis:695d80a3].
2018-07-17 20:39:16.529 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel -1
2018-07-17 20:39:16.531 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 42645
2018-07-17 20:39:16.534 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID 9B62F00E645D95F0
2018-07-17 20:39:16.536 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key null
2018-07-17 20:39:16.539 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key String 
2018-07-17 20:39:16.542 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key initialised 4B91EDCED1014512AC63B31859814077
2018-07-17 20:39:16.545 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key final array 4B91EDCED1014512AC63B31859814077
2018-07-17 20:39:16.549 [DEBUG] [e.telegesis.handler.TelegesisHandler] - ZigBee Telegesis Coordinator opening Port:'/dev/ttyAMA0' PAN:a695, EPAN:9B62F00E645D95F0, Channel:-1
2018-07-17 20:39:16.553 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
2018-07-17 20:39:17.556 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2018-07-17 20:39:17.560 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2018-07-17 20:39:17.566 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key initialise 4B91EDCED1014512AC63B31859814077
2018-07-17 20:39:17.569 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis dongle initialize.
2018-07-17 20:39:17.572 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyAMA0] at 38400 baud, flow control FLOWCONTROL_OUT_NONE.
2018-07-17 20:39:17.581 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port [/dev/ttyAMA0] is initialized.
2018-07-17 20:39:17.586 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TelegesisFrameHandler thread started
2018-07-17 20:39:17.590 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSetPromptEnable1Command [configuration=8804]
2018-07-17 20:39:17.586 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-07-17 20:39:17.596 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 53 30 45 3D 38 38 30 34 0D 0A
2018-07-17 20:39:18.586 [DEBUG] [gesis.internal.TelegesisFrameHandler] - Telegesis interrupted in sendRequest TelegesisSetPromptEnable1Command [configuration=8804]
2018-07-17 20:39:18.591 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Error setting Telegesis Prompt 1 register
2018-07-17 20:39:18.600 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Loading ZigBee network state: Start.
2018-07-17 20:39:18.621 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Loading ZigBee network state: Done.
2018-07-17 20:39:18.624 [DEBUG] [bee.internal.ZigBeeNetworkDiscoverer] - Network discovery task starting
2018-07-17 20:39:19.760 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration received (Coordinator).
2018-07-17 20:39:19.809 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2018-07-17 20:39:19.813 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2018-07-17 20:39:19.816 [DEBUG] [bee.internal.ZigBeeNetworkDiscoverer] - Network discovery task shutdown
2018-07-17 20:39:19.885 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TelegesisFrameHandler thread exited.
2018-07-17 20:39:19.885 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port '/dev/ttyAMA0' closed.
2018-07-17 20:39:19.891 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TelegesisFrameHandler closed.
2018-07-17 20:39:19.894 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis dongle shutdown.
2018-07-17 20:39:19.897 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network [zigbee:coordinator_telegesis:695d80a3] closed.
2018-07-17 20:39:19.900 [DEBUG] [e.telegesis.handler.TelegesisHandler] - Initializing ZigBee Telegesis serial bridge handler.
2018-07-17 20:39:19.903 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_telegesis:695d80a3].
2018-07-17 20:39:19.906 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel -1
2018-07-17 20:39:19.909 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 42645
2018-07-17 20:39:19.913 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID 9B62F00E645D95F0
2018-07-17 20:39:19.916 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key null
2018-07-17 20:39:19.919 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key String 
2018-07-17 20:39:19.923 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key initialised 03076C07844DE0FB82165510DBAC0CEC
2018-07-17 20:39:19.926 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key final array 03076C07844DE0FB82165510DBAC0CEC
2018-07-17 20:39:19.930 [DEBUG] [e.telegesis.handler.TelegesisHandler] - ZigBee Telegesis Coordinator opening Port:'/dev/ttyAMA0' PAN:a695, EPAN:9B62F00E645D95F0, Channel:-1
2018-07-17 20:39:19.935 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
2018-07-17 20:39:20.941 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2018-07-17 20:39:20.943 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2018-07-17 20:39:20.951 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key initialise 03076C07844DE0FB82165510DBAC0CEC
2018-07-17 20:39:20.953 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis dongle initialize.
2018-07-17 20:39:20.955 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyAMA0] at 19200 baud, flow control FLOWCONTROL_OUT_NONE.
2018-07-17 20:39:20.963 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port [/dev/ttyAMA0] is initialized.
2018-07-17 20:39:20.965 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TelegesisFrameHandler thread started
2018-07-17 20:39:20.965 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-07-17 20:39:20.968 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSetPromptEnable1Command [configuration=8804]
2018-07-17 20:39:20.971 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 53 30 45 3D 38 38 30 34 0D 0A
2018-07-17 20:39:21.966 [DEBUG] [gesis.internal.TelegesisFrameHandler] - Telegesis interrupted in sendRequest TelegesisSetPromptEnable1Command [configuration=8804]
2018-07-17 20:39:21.969 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Error setting Telegesis Prompt 1 register
2018-07-17 20:39:21.973 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Loading ZigBee network state: Start.
2018-07-17 20:39:21.996 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Loading ZigBee network state: Done.
2018-07-17 20:39:21.999 [DEBUG] [bee.internal.ZigBeeNetworkDiscoverer] - Network discovery task starting
2018-07-17 20:39:27.600 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TELEGESIS Timer: Timeout
2018-07-17 20:39:28.697 [INFO ] [marthome.model.script.iPhone is Home] - iPhone is away.
2018-07-17 20:39:30.973 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TELEGESIS Timer: Timeout
2018-07-17 20:39:40.413 [WARN ] [he.commons.httpclient.HttpMethodBase] - Cookie rejected: "$Version=0; TS01b44c2d=01fc40691fcd69fd2b213258db5a3b34d7bacad45ee1977fe4d53a1f77492f963bef34b660087397a7c56119ec36fda5469183a1e2b7a4f63d879195329d74ccc5f5aa4a0b; $Path=/; $Domain=.myqexternal.myqdevice.com". Illegal domain attribute ".myqexternal.myqdevice.com". Domain of origin: "myqexternal.myqdevice.com"
2018-07-17 20:40:10.816 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration received (Coordinator).
2018-07-17 20:40:10.823 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Unhandled configuration parameter zigbee_initialise >> true.
2018-07-17 20:40:10.829 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Unhandled configuration parameter zigbee_channel >> -1.
2018-07-17 20:40:10.835 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Unhandled configuration parameter zigbee_password >> password.
2018-07-17 20:40:10.839 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Unhandled configuration parameter zigbee_panid >> 42645.
2018-07-17 20:40:10.845 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Unhandled configuration parameter zigbee_extendedpanid >> 9B62F00E645D95F0.
2018-07-17 20:40:10.865 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Setting Telegesis trust centre link mode: TC_JOIN_SECURE
2018-07-17 20:40:10.870 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-07-17 20:40:10.873 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisDisallowTcJoinCommand [disallowJoin=false, password=password]
2018-07-17 20:40:10.876 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 53 30 41 35 3D 30 3A 70 61 73 73 77 6F 72 64 0D 0A
2018-07-17 20:40:11.875 [DEBUG] [gesis.internal.TelegesisFrameHandler] - Telegesis interrupted in sendRequest TelegesisDisallowTcJoinCommand [disallowJoin=false, password=password]
2018-07-17 20:40:11.882 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-07-17 20:40:12.883 [DEBUG] [gesis.internal.TelegesisFrameHandler] - Telegesis interrupted in sendRequest TelegesisDisallowUnsecuredRejoinCommand [disallowRejoin=true, password=password]
2018-07-17 20:40:12.929 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2018-07-17 20:40:12.934 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2018-07-17 20:40:12.940 [DEBUG] [bee.internal.ZigBeeNetworkDiscoverer] - Network discovery task shutdown
2018-07-17 20:40:12.956 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TelegesisFrameHandler thread exited.
2018-07-17 20:40:12.966 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port '/dev/ttyAMA0' closed.
2018-07-17 20:40:12.970 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TelegesisFrameHandler closed.
2018-07-17 20:40:12.975 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis dongle shutdown.
2018-07-17 20:40:12.979 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network [zigbee:coordinator_telegesis:695d80a3] closed.
2018-07-17 20:40:12.984 [DEBUG] [e.telegesis.handler.TelegesisHandler] - Initializing ZigBee Telegesis serial bridge handler.
2018-07-17 20:40:12.988 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_telegesis:695d80a3].
2018-07-17 20:40:12.993 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel -1
2018-07-17 20:40:12.998 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 42645
2018-07-17 20:40:13.002 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID 9B62F00E645D95F0
2018-07-17 20:40:13.006 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key null
2018-07-17 20:40:13.010 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising network
2018-07-17 20:40:13.022 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key String 
2018-07-17 20:40:13.028 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key initialised E545C214BF99E6AEAAFBCC8471E5DD44
2018-07-17 20:40:13.034 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Key final array E545C214BF99E6AEAAFBCC8471E5DD44
2018-07-17 20:40:13.039 [DEBUG] [e.telegesis.handler.TelegesisHandler] - ZigBee Telegesis Coordinator opening Port:'/dev/ttyAMA0' PAN:a695, EPAN:9B62F00E645D95F0, Channel:-1
2018-07-17 20:40:13.044 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start

(Chris Jackson) #1062

Sorry - you’re right - 19200 is the correct value.

I would suggest to try using a serial terminal to see if you can communicate with the device - my guess is that either the stick is broken, or it’s in some strange mode. In any case, it looks like it’s not responding to commands.


(Chris Jackson) #1063

Sorry for the slow response - it’s been a busy few days with both ZWave and ZigBee updates…

Agreed - it doesn’t really show a lot is happening -:

This shows communication with the coordinator as expected, but no devices are joining the network. Maybe the devices aren’t being put into join mode at the right time - I’m not really sure. Unfortunately there’s no easy way to see what’s happening as that level of communications is only between the coordinator and the device.