No longer able to Control Zigbee Devices

[damooooooooooh]

Recently my xstick appears to have lost the ability to control devices. No specific brand. It started with lag, i.e. tried to turn off a light and it would take approx 10 secs to react and now not at all. Ive rebuilt a fresh gateway and the same issue occurs.

Is there anyway to clear down the xstick network? Could it be interference from 2.4GHZ wifi? Its rendered the gateway unuseable from a zigbee perspective.

Any advice on debugging failed packets etc?

[mrstegeman]

Is there anything relevant in your logs (~/.mozilla-iot/log)?

[damooooooooooh]

I've spun up 0.9.2 Gateway and older version of the Zigbee Adapter and all is fine now. This is after trying a fresh 0.10.0 gateway, latest zigbee adapter and flashing the xsitck with no success. Will try an older zigbee adapter version on the 0.10.0 gateway now. Issue started a few weeks back which coincides with a new release. Logs are verbose will try and compare to working gateway,

[mrstegeman]

Interesting. The gateway version shouldn't matter, but there have been a few (minimal) changes in the Zigbee adapter. This is the only commit I know of that could have broken things: https://github.com/mozilla-iot/zigbee-adapter/commit/e62c28411dfef62bad90ca157fcef367ee751630

[damooooooooooh]

Yeah I figured that the gateway wouldn't matter, but I wasnt sure if the issue was caused by the change to a single socket on the UI or the zigbee adapter. When I was interacting with the zigbee devices i.e. turn on/off a light, the GUI was not responsive. Will install the earlier version of the 10.3 zigbee adapter and see if that resolves it. Looking at the logs, there seemed to be alot of queueing of zigbee adapter commands which timed out.

[damooooooooooh]

Ok, created a fresh 0.10.0 gateway with the 10.4 zigbee adapter and there are no issues. As soon as I update to 10.5 Zigbee adapter, zigbee commands are unresponsive. This is with a single Zigbee device. Whatever that change you referenced does, it rendered my zigbee install defunct. This includes Tradfri, SmartThings and Ember zigbee devices. Here is a log output when trying to turn a bulb on, which does not succeed

2019-12-31 19:51:34.522 INFO : zigbee: setProperty property: on for: zb-086bd7fffe234c14-Node profileId: 0104 endpoint: 1 clusterId: 0006 zcl: on value: true 2019-12-31 19:51:34.526 INFO : zigbee: queueCommands 2019-12-31 19:51:34.527 INFO : zigbee: Commands (3) 2019-12-31 19:51:34.529 INFO : zigbee: | 0: p:- SEND: Explicit Tx 086bd7fffe234c14 ZHA 0006 genOnOff on 2019-12-31 19:51:34.530 INFO : zigbee: | 0: p:- SEND: payload: [] 2019-12-31 19:51:34.531 INFO : zigbee: | 1: p:- WAIT: ZigBee Explicit Rx Indicator (AO=1) (0x91) from: 086bd7fffe234c14 2019-12-31 19:51:34.533 INFO : zigbee: | 2: p:- RESOLVE_SET_PROPERTY: 086bd7fffe234c14 on 2019-12-31 19:51:34.534 INFO : zigbee: --- 2019-12-31 19:51:34.535 INFO : zigbee: run queue len = 3 running = false 2019-12-31 19:51:34.537 INFO : zigbee: SEND_FRAME 2019-12-31 19:51:34.539 INFO : zigbee: findNodeFromTxFrame: addr64: 086bd7fffe234c14 addr16: 5e98 2019-12-31 19:51:34.540 INFO : zigbee: WAIT_FRAME type: 145 timeoutDelay = 10000 2019-12-31 19:51:39.276 INFO : zigbee: Waiting for { type: 145, 2019-12-31 19:51:39.278 INFO : zigbee: remote64: '086bd7fffe234c14', 2019-12-31 19:51:39.279 INFO : zigbee: waitRetryCount: 1, 2019-12-31 19:51:39.281 INFO : zigbee: waitRetryMax: 3 } 2019-12-31 19:51:39.283 INFO : zigbee: Wait NOT satisified 2019-12-31 19:51:39.284 INFO : zigbee: waitFrame = { type: 145, 2019-12-31 19:51:39.285 INFO : zigbee: remote64: '086bd7fffe234c14', 2019-12-31 19:51:39.287 INFO : zigbee: waitRetryCount: 1, 2019-12-31 19:51:39.288 INFO : zigbee: waitRetryMax: 3 } 2019-12-31 19:51:39.289 INFO : zigbee: run queue len = 1 running = false 2019-12-31 19:51:39.291 INFO : zigbee: Queue stalled waiting for frame. 2019-12-31 19:51:44.534 INFO : zigbee: WAIT_FRAME timed out 2019-12-31 19:51:44.536 INFO : zigbee: queueCommandsAtFront 2019-12-31 19:51:44.538 INFO : zigbee: Commands (3) 2019-12-31 19:51:44.539 INFO : zigbee: | 0: p:- SEND: Explicit Tx 086bd7fffe234c14 ZHA 0006 genOnOff on 2019-12-31 19:51:44.540 INFO : zigbee: | 0: p:- SEND: payload: [] 2019-12-31 19:51:44.542 INFO : zigbee: | 1: p:- WAIT: ZigBee Explicit Rx Indicator (AO=1) (0x91) from: 086bd7fffe234c14 2019-12-31 19:51:44.543 INFO : zigbee: | 2: p:- RESOLVE_SET_PROPERTY: 086bd7fffe234c14 on 2019-12-31 19:51:44.545 INFO : zigbee: --- 2019-12-31 19:51:44.546 INFO : zigbee: run queue len = 3 running = false 2019-12-31 19:51:44.547 INFO : zigbee: ReSEND_FRAME 2019-12-31 19:51:44.549 INFO : zigbee: findNodeFromTxFrame: addr64: 086bd7fffe234c14 addr16: 5e98 2019-12-31 19:51:44.551 INFO : zigbee: WAIT_FRAME type: 145 timeoutDelay = 10000 2019-12-31 19:51:49.295 INFO : zigbee: Waiting for { type: 145, 2019-12-31 19:51:49.297 INFO : zigbee: remote64: '086bd7fffe234c14', 2019-12-31 19:51:49.298 INFO : zigbee: waitRetryCount: 2, 2019-12-31 19:51:49.300 INFO : zigbee: waitRetryMax: 3 } 2019-12-31 19:51:49.302 INFO : zigbee: Wait NOT satisified 2019-12-31 19:51:49.303 INFO : zigbee: waitFrame = { type: 145, 2019-12-31 19:51:49.305 INFO : zigbee: remote64: '086bd7fffe234c14', 2019-12-31 19:51:49.306 INFO : zigbee: waitRetryCount: 2, 2019-12-31 19:51:49.307 INFO : zigbee: waitRetryMax: 3 } 2019-12-31 19:51:49.308 INFO : zigbee: run queue len = 1 running = false 2019-12-31 19:51:49.310 INFO : zigbee: Queue stalled waiting for frame. 2019-12-31 19:51:53.377 INFO : zigbee: Saved device information in /home/pi/.mozilla-iot/data/zigbee-adapter/zb-0013a2004158725d.json 2019-12-31 19:51:54.538 INFO : zigbee: WAIT_FRAME timed out 2019-12-31 19:51:54.541 INFO : zigbee: queueCommandsAtFront 2019-12-31 19:51:54.543 INFO : zigbee: Commands (3) 2019-12-31 19:51:54.544 INFO : zigbee: | 0: p:- SEND: Explicit Tx 086bd7fffe234c14 ZHA 0006 genOnOff on 2019-12-31 19:51:54.548 INFO : zigbee: | 0: p:- SEND: payload: [] 2019-12-31 19:51:54.549 INFO : zigbee: | 1: p:- WAIT: ZigBee Explicit Rx Indicator (AO=1) (0x91) from: 086bd7fffe234c14 2019-12-31 19:51:54.550 INFO : zigbee: | 2: p:- RESOLVE_SET_PROPERTY: 086bd7fffe234c14 on 2019-12-31 19:51:54.552 INFO : zigbee: --- 2019-12-31 19:51:54.554 INFO : zigbee: run queue len = 3 running = false 2019-12-31 19:51:54.556 INFO : zigbee: ReSEND_FRAME 2019-12-31 19:51:54.558 INFO : zigbee: findNodeFromTxFrame: addr64: 086bd7fffe234c14 addr16: 5e98 2019-12-31 19:51:54.559 INFO : zigbee: WAIT_FRAME type: 145 timeoutDelay = 10000 2019-12-31 19:51:57.079 ERROR : zigbee: No handler for ZDO cluster: 8038 2019-12-31 19:51:57.083 ERROR : zigbee: { type: 145, 2019-12-31 19:51:57.085 ERROR : zigbee: remote64: '0013a2004158725d', 2019-12-31 19:51:57.086 ERROR : zigbee: remote16: '0000', 2019-12-31 19:51:57.087 ERROR : zigbee: sourceEndpoint: '00', 2019-12-31 19:51:57.088 ERROR : zigbee: destinationEndpoint: '00', 2019-12-31 19:51:57.090 ERROR : zigbee: clusterId: '8038', 2019-12-31 19:51:57.091 ERROR : zigbee: profileId: '0000', 2019-12-31 19:51:57.097 ERROR : zigbee: receiveOptions: 1, 2019-12-31 19:51:57.098 ERROR : zigbee: data: <Buffer 00 00 00 f8 ff 07 16 00 06 00 10 4b 51 5d 52 5c 4b 39 45 39 4e 4f 51 4e 54 53 49>, 2019-12-31 19:51:57.099 ERROR : zigbee: zdoSeq: 0, 2019-12-31 19:51:57.101 ERROR : zigbee: status: 0, 2019-12-31 19:51:57.102 ERROR : zigbee: scannedChannels: '07fff800', 2019-12-31 19:51:57.104 ERROR : zigbee: totalTransmissions: 22, 2019-12-31 19:51:57.105 ERROR : zigbee: transmissionFailures: 6, 2019-12-31 19:51:57.106 ERROR : zigbee: numEnergyValues: 16, 2019-12-31 19:51:57.108 ERROR : zigbee: energyValues: [ 75, 81, 93, 82, 92, 75, 57, 69, 57, 78, 79, 81, 78, 84, 83, 73 ] } 2019-12-31 19:51:57.110 INFO : zigbee: Waiting for { type: 145, 2019-12-31 19:51:57.112 INFO : zigbee: remote64: '086bd7fffe234c14', 2019-12-31 19:51:57.114 INFO : zigbee: waitRetryCount: 3, 2019-12-31 19:51:57.115 INFO : zigbee: waitRetryMax: 3 } 2019-12-31 19:51:57.117 INFO : zigbee: Wait NOT satisified 2019-12-31 19:51:57.118 INFO : zigbee: waitFrame = { type: 145, 2019-12-31 19:51:57.120 INFO : zigbee: remote64: '086bd7fffe234c14', 2019-12-31 19:51:57.121 INFO : zigbee: waitRetryCount: 3, 2019-12-31 19:51:57.123 INFO : zigbee: waitRetryMax: 3 } 2019-12-31 19:51:57.124 INFO : zigbee: run queue len = 1 running = false 2019-12-31 19:51:57.130 INFO : zigbee: Queue stalled waiting for frame. 2019-12-31 19:51:59.299 INFO : zigbee: Waiting for { type: 145, 2019-12-31 19:51:59.300 INFO : zigbee: remote64: '086bd7fffe234c14', 2019-12-31 19:51:59.302 INFO : zigbee: waitRetryCount: 3, 2019-12-31 19:51:59.303 INFO : zigbee: waitRetryMax: 3 } 2019-12-31 19:51:59.305 INFO : zigbee: Wait NOT satisified 2019-12-31 19:51:59.306 INFO : zigbee: waitFrame = { type: 145, 2019-12-31 19:51:59.308 INFO : zigbee: remote64: '086bd7fffe234c14', 2019-12-31 19:51:59.309 INFO : zigbee: waitRetryCount: 3, 2019-12-31 19:51:59.310 INFO : zigbee: waitRetryMax: 3 } 2019-12-31 19:51:59.311 INFO : zigbee: run queue len = 1 running = false 2019-12-31 19:51:59.313 INFO : zigbee: Queue stalled waiting for frame. 2019-12-31 19:52:04.553 INFO : zigbee: WAIT_FRAME timed out 2019-12-31 19:52:04.555 INFO : zigbee: WAIT_FRAME waitRetryCount: 3 exceeded waitRetryMax: 3 2019-12-31 19:52:04.556 INFO : zigbee: run queue len = 1 running = false 2019-12-31 19:52:04.557 INFO : zigbee: RESOLVE_SET_PROPERTY 086bd7fffe234c14 on value: true 2019-12-31 19:52:14.556 INFO : zigbee: setProperty property: on for: zb-086bd7fffe234c14-Node profileId: 0104 endpoint: 1 clusterId: 0006 zcl: on value: true 2019-12-31 19:52:14.559 INFO : zigbee: queueCommands 2019-12-31 19:52:14.560 INFO : zigbee: Commands (3) 2019-12-31 19:52:14.562 INFO : zigbee: | 0: p:- SEND: Explicit Tx 086bd7fffe234c14 ZHA 0006 genOnOff on 2019-12-31 19:52:14.563 INFO : zigbee: | 0: p:- SEND: payload: [] 2019-12-31 19:52:14.565 INFO : zigbee: | 1: p:- WAIT: ZigBee Explicit Rx Indicator (AO=1) (0x91) from: 086bd7fffe234c14 2019-12-31 19:52:14.566 INFO : zigbee: | 2: p:- RESOLVE_SET_PROPERTY: 086bd7fffe234c14 on 2019-12-31 19:52:14.568 INFO : zigbee: --- 2019-12-31 19:52:14.569 INFO : zigbee: run queue len = 3 running = false 2019-12-31 19:52:14.570 INFO : zigbee: SEND_FRAME 2019-12-31 19:52:14.571 INFO : zigbee: findNodeFromTxFrame: addr64: 086bd7fffe234c14 addr16: 5e98 2019-12-31 19:52:14.573 INFO : zigbee: WAIT_FRAME type: 145 timeoutDelay = 10000 2019-12-31 19:52:19.308 INFO : zigbee: Waiting for { type: 145, 2019-12-31 19:52:19.309 INFO : zigbee: remote64: '086bd7fffe234c14', 2019-12-31 19:52:19.311 INFO : zigbee: waitRetryCount: 1, 2019-12-31 19:52:19.312 INFO : zigbee: waitRetryMax: 3 } 2019-12-31 19:52:19.314 INFO : zigbee: Wait NOT satisified 2019-12-31 19:52:19.315 INFO : zigbee: waitFrame = { type: 145, 2019-12-31 19:52:19.316 INFO : zigbee: remote64: '086bd7fffe234c14', 2019-12-31 19:52:19.318 INFO : zigbee: waitRetryCount: 1, 2019-12-31 19:52:19.319 INFO : zigbee: waitRetryMax: 3 } 2019-12-31 19:52:19.320 INFO : zigbee: run queue len = 1 running = false 2019-12-31 19:52:19.321 INFO : zigbee: Queue stalled waiting for frame.

[mrstegeman]

Can you test something for me?

1. mkdir ~/.mozilla-iot/addons/zigbee-adapter/.git
2. Edit ~/.mozilla-iot/addons/zigbee-adapter/zb-adapter.js. On line 655, replace zdoAddr16: reqFrame.zdoAddr16 with zdoAddr16: node.addr16.
3. Save file.
4. Reload add-on through UI by navigating to Settings -> Add-ons and clicking Disable and then Enable for "Zigbee".

[damooooooooooh]

Hi, on my current setup, the code is already set as zdoAddr16: node.addr16 as I am running version 10.4 of the zigbee adapter, this version behaves normally.

When I install 10.5, which is the default head version (and seems to auto install) then I encounter the lag/latency/unresponsive issues.

Line 655 on version 10.5 is zdoAddr16: reqFrame.zdoAddr16 as per #149

[damooooooooooh]

Happy New Year btw!

[mrstegeman]

I just pushed out 0.10.6, which reverts that change. Let me know if things are still broken for some reason. And happy new year to you, too!