Error when paired device is not known

[dabont]

Really impressed with the progress from the original work of Andrew. I found a little error.

I previously paired devices to my dongle (with the Andrew version of the software). With the new fork when the program receives a message from an previuosly paired device it crashes, perhaps you can easily ctach this error.

2018-5-9 17:55:40 INFO MQTT publish, topic: 'zigbee2mqtt/sensorWoonkamer', payload: '{"temperature":26.67,"humidity":49.44,"pressure":1002}'
spinlock: false []
/home/pi/zigbee2mqtt/node_modules/q/q.js:155
                throw e;
                ^

Error: Unhandled "error" event. (Cannot get the Node Descriptor of the Device: 0x00158d00012434f4 (Error: Timed out after 10000 ms))
    at ZShepherd.emit (events.js:186:19)
    at /home/pi/zigbee2mqtt/node_modules/zigbee-shepherd/lib/components/controller.js:609:28
    at _rejected (/home/pi/zigbee2mqtt/node_modules/q/q.js:864:24)
    at /home/pi/zigbee2mqtt/node_modules/q/q.js:890:30
    at Promise.when (/home/pi/zigbee2mqtt/node_modules/q/q.js:1142:31)
    at Promise.promise.promiseDispatch (/home/pi/zigbee2mqtt/node_modules/q/q.js:808:41)
    at /home/pi/zigbee2mqtt/node_modules/q/q.js:624:44
    at runSingle (/home/pi/zigbee2mqtt/node_modules/q/q.js:137:13)
    at flush (/home/pi/zigbee2mqtt/node_modules/q/q.js:125:13)
    at _combinedTickCallback (internal/process/next_tick.js:131:7)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! zigbee2mqtt@0.1.0 start: `node index.js`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the zigbee2mqtt@0.1.0 start script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /home/pi/.npm/_logs/2018-05-09T17_56_21_421Z-debug.log

[Koenkk]

Did you also copy the database.db?

[kirovilya]

Hi. I seen this problem: "Error: Timed out after 10000 ms"...
For devices: RTCGQ01LM, MCCGQ01LM, WXKG01LM (may be more) need press setup key (small button on sensor) for 5 second at start until led blinking and than every 2-3 seconds on pairing process to revoke sleeping.
(sorry for my English)

[dabont]

Hi, no did not copy the database. Lost all information after a clean install on my Raspberry pi.

@kirovilya Thanks

[ciotlosm]

Still this is a bug on pairing on new devices where you get a timeout if you don't do what @kirovilya suggested (pressing link buttons). I think this needs either a fix or a mention in the documentation for linking devices to the stick.

[Koenkk]

Yes, this needs to be fixed in zigbee-shepherd.

[dabont]

Since the topic is on pairing and I dont want to start another one.

I see from the suported list that the 1000lm E27 is supported however, I get a not supported error.

2018-5-10 18:31:09 INFO New device joined the network!
2018-5-10 18:31:09 WARN Device with modelID 'TRADFRI bulb E27 W opal 1000lm' is not supported.
2018-5-10 18:31:09 WARN Please create an issue on https://github.com/Koenkk/zigbee2mqtt/issues to add support for your device
2018-5-10 18:31:09 WARN Device with modelID 'TRADFRI bulb E27 W opal 1000lm' is not supported.
2018-5-10 18:31:09 WARN Please create an issue on https://github.com/Koenkk/zigbee2mqtt/issues to add support for your device
^C2018-5-10 18:31:22 INFO MQTT publish, topic: 'zigbee2mqtt/bridge/state', payload: 'offline'

I'm sure that I did not update it correctly.

I have performed a npm update should that be enough?

Thanks guys

[Koenkk]

You need to do a git pull

[dabont]

Thanks Koen, I have a lot to learn.

The git pull result in a stashing thing which I need to find out for myself. However i found the follwing, it looks like a W is missing.

2018-5-10 18:49:39 WARN Device with modelID 'TRADFRI bulb E27 W opal 1000lm' is not supported.
Since it shows in the devices.js as

'TRADFRI bulb E27 opal 1000lm': {

Is there an issue in the code? When I try to insert the W the program crashes

[dabont]

After some fidling around it now works.

Changed it to TRADFRI bulb E27 W opal 1000lm in devices.js

[Koenkk]

@dabont this seems to be related to #21, let's continue over there.

[Koenkk]

Only thing left here is the Cannot get the Node Descriptor of the Device bug. Let's continue that over here #41

[mcsSolutions]

The pairing solution for multiple devices looks to be similar to kirovilya post of pressing the link button during the process. I receive the same Timed out after 10000 ms error with Iris 3326-L motion sensor. This unit does not have link button. Pairing is done by remove/replace the battery. It keeps trying every 20 seconds. Any suggestions on how to overcome the error for this device?

When running with debug I captured the following snippit for 0x000d6f001099e6c1 (Motion Sensor) which was unable to pair
[code]
zigbee2mqtt:info 2018-11-14 21:48:43 Connected to MQTT server
zigbee2mqtt:info 2018-11-14 21:48:43 MQTT publish, topic: 'zigbee/bridge/state', payload: 'online'
zigbee2mqtt:debug 2018-11-14 21:48:43 Soft reset timeout disabled
zigbee2mqtt:info 2018-11-14 21:48:43 MQTT publish, topic: 'zigbee/0x00158d00026e2bf1', payload: '{"water_leak":false,"linkquality":23,"battery":"99.00","voltage":3015}'
zigbee2mqtt:info 2018-11-14 21:48:43 MQTT publish, topic: 'zigbee/0x00158d000256d2c9', payload: '{"water_leak":false,"linkquality":78,"battery":"100.00","voltage":3045}'
zigbee2mqtt:info 2018-11-14 21:48:43 MQTT publish, topic: 'zigbee/0x00158d000256d0d0', payload: '{"water_leak":false,"linkquality":110,"battery":"99.00","voltage":3025}'
zigbee2mqtt:info 2018-11-14 21:48:43 MQTT publish, topic: 'zigbee/0x00158d000256d24a', payload: '{"water_leak":false,"linkquality":5,"battery":"99.00","voltage":3025}'
serialport:poller received "readable" +30s
serialport:bindings read +30s
serialport:unixRead Starting read +30s
serialport:unixRead Finished read 18 bytes +0ms
serialport:main binding.read finished +30s
cc-znp { sof: 254,
cc-znp len: 13,
cc-znp type: 'AREQ',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'leaveInd',
cc-znp payload:
cc-znp { srcaddr: 59419,
cc-znp extaddr: '0x000d6f001099e6c1',
cc-znp request: 0,
cc-znp removechildren: 0,
cc-znp rejoin: 0 },
cc-znp fcs: 190,
cc-znp csum: 190 } +30s
serialport:main _read reading +11ms
serialport:bindings read +14ms
serialport:unixRead Starting read +13ms
cc-znp:AREQ <-- ZDO:leaveInd, { srcaddr: 59419, extaddr: '0x000d6f001099e6c1', request: 0, removechildren: 0, rejoin: 0 } +5ms
zigbee-shepherd:msgHdlr IND <-- ZDO:leaveInd +2ms
serialport:unixRead waiting for readable because of code: EAGAIN +4ms
serialport:poller Polling for "readable" +20ms
serialport:poller received "readable" +966ms
serialport:bindings read +971ms
serialport:unixRead Starting read +967ms
serialport:unixRead Finished read 17 bytes +1ms
serialport:main binding.read finished +973ms
cc-znp { sof: 254,
cc-znp len: 12,
cc-znp type: 'AREQ',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'tcDeviceInd',
cc-znp payload: { nwkaddr: 2745, extaddr: '0x000d6f001099e6c1', parentaddr: 0 },
cc-znp fcs: 252,
cc-znp csum: 252 } +972ms
serialport:main _read reading +4ms
serialport:bindings read +6ms
serialport:unixRead Starting read +5ms
cc-znp:AREQ <-- ZDO:tcDeviceInd, { nwkaddr: 2745, extaddr: '0x000d6f001099e6c1', parentaddr: 0 } +2ms
zigbee-shepherd:msgHdlr IND <-- ZDO:tcDeviceInd +2ms
serialport:unixRead waiting for readable because of code: EAGAIN +2ms
serialport:poller Polling for "readable" +8ms
serialport:poller received "readable" +409ms
serialport:bindings read +411ms
serialport:unixRead Starting read +410ms
serialport:unixRead Finished read 18 bytes +0ms
serialport:main binding.read finished +413ms
cc-znp { sof: 254,
cc-znp len: 13,
cc-znp type: 'AREQ',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'endDeviceAnnceInd',
cc-znp payload:
cc-znp { srcaddr: 2745,
cc-znp nwkaddr: 2745,
cc-znp ieeeaddr: '0x000d6f001099e6c1',
cc-znp capabilities: 128 },
cc-znp fcs: 197,
cc-znp csum: 197 } +413ms
serialport:main _read reading +4ms
serialport:bindings read +5ms
serialport:unixRead Starting read +5ms
cc-znp:AREQ <-- ZDO:endDeviceAnnceInd, { srcaddr: 2745, nwkaddr: 2745, ieeeaddr: '0x000d6f001099e6c1', capabilities: 128 } +2ms
zigbee-shepherd spinlock: false [] +2ms
zigbee-shepherd:request REQ --> ZDO:nodeDescReq +2ms
cc-znp:SREQ --> ZDO:nodeDescReq, { dstaddr: 2745, nwkaddrofinterest: 2745 } +1ms
serialport:main _write 9 bytes of data +7ms
serialport:bindings write 9 bytes +7ms
zigbee-shepherd:msgHdlr IND <-- ZDO:endDeviceAnnceInd +2ms
serialport:unixWrite Starting write 9 bytes offset 0 bytesToWrite 9 +32s
serialport:unixRead waiting for readable because of code: EAGAIN +8ms
serialport:poller Polling for "readable" +15ms
serialport:unixWrite write returned null 9 +1ms
serialport:unixWrite wrote 9 bytes +0ms
serialport:unixWrite Finished writing 9 bytes +0ms
serialport:main binding.write write finished +3ms
serialport:poller received "readable" +6ms
serialport:bindings read +10ms
serialport:unixRead Starting read +8ms
serialport:unixRead Finished read 6 bytes +0ms
serialport:main binding.read finished +8ms
cc-znp { sof: 254,
cc-znp len: 1,
cc-znp type: 'SRSP',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'nodeDescReq',
cc-znp payload: { status: 0 },
cc-znp fcs: 102,
cc-znp csum: 102 } +12ms
serialport:main _read reading +3ms
serialport:bindings read +5ms
serialport:unixRead Starting read +5ms
cc-znp:SRSP <-- ZDO:nodeDescReq, { status: 0 } +3ms
serialport:unixRead waiting for readable because of code: EAGAIN +1ms
serialport:poller Polling for "readable" +8ms
serialport:poller received "readable" +962ms
serialport:bindings read +965ms
serialport:unixRead Starting read +964ms
serialport:unixRead Finished read 23 bytes +1ms
serialport:main binding.read finished +967ms
cc-znp { sof: 254,
cc-znp len: 18,
cc-znp type: 'AREQ',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'nodeDescRsp',
cc-znp payload:
cc-znp { srcaddr: 2745,
cc-znp status: 0,
cc-znp nwkaddr: 2745,
cc-znp logicaltype_cmplxdescavai_userdescavai: 2,
cc-znp apsflags_freqband: 64,
cc-znp maccapflags: 128,
cc-znp manufacturercode: 49887,
cc-znp maxbuffersize: 82,
cc-znp maxintransfersize: 82,
cc-znp servermask: 0,
cc-znp maxouttransfersize: 82,
cc-znp descriptorcap: 0 },
cc-znp fcs: 88,
cc-znp csum: 88 } +972ms
serialport:main _read reading +11ms
serialport:bindings read +13ms
serialport:unixRead Starting read +12ms
cc-znp:AREQ <-- ZDO:nodeDescRsp, { srcaddr: 2745, status: 0, nwkaddr: 2745, logicaltype_cmplxdescavai_userdescavai: 2, apsflags_freqband: 64, maccapflags: 128, manufacturercode: 49887, maxbuffersize: 82, maxintransfersize: 82, servermask: 0, maxouttransfersize: 82, descriptorcap: 0 } +7ms
zigbee-shepherd:msgHdlr IND <-- ZDO:nodeDescRsp +2ms
zigbee-shepherd:request REQ --> ZDO:activeEpReq +1ms
cc-znp:SREQ --> ZDO:activeEpReq, { dstaddr: 2745, nwkaddrofinterest: 2745 } +2ms
serialport:main _write 9 bytes of data +10ms
serialport:bindings write 9 bytes +9ms
serialport:unixWrite Starting write 9 bytes offset 0 bytesToWrite 9 +1s
serialport:unixRead waiting for readable because of code: EAGAIN +11ms
serialport:poller Polling for "readable" +25ms
serialport:unixWrite write returned null 9 +2ms
serialport:unixWrite wrote 9 bytes +0ms
serialport:unixWrite Finished writing 9 bytes +1ms
serialport:main binding.write write finished +4ms
serialport:poller received "readable" +6ms
serialport:bindings read +9ms
serialport:unixRead Starting read +7ms
serialport:unixRead Finished read 6 bytes +0ms
serialport:main binding.read finished +5ms
cc-znp { sof: 254,
cc-znp len: 1,
cc-znp type: 'SRSP',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'activeEpReq',
cc-znp payload: { status: 0 },
cc-znp fcs: 97,
cc-znp csum: 97 } +14ms
serialport:main _read reading +4ms
serialport:bindings read +5ms
serialport:unixRead Starting read +5ms
cc-znp:SRSP <-- ZDO:activeEpReq, { status: 0 } +2ms
serialport:unixRead waiting for readable because of code: EAGAIN +1ms
serialport:poller Polling for "readable" +7ms
serialport:poller received "readable" +961ms
serialport:bindings read +962ms
serialport:unixRead Starting read +961ms
serialport:unixRead Finished read 13 bytes +0ms
serialport:main binding.read finished +964ms
cc-znp { sof: 254,
cc-znp len: 8,
cc-znp type: 'AREQ',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'activeEpRsp',
cc-znp payload:
cc-znp { srcaddr: 2745,
cc-znp status: 0,
cc-znp nwkaddr: 2745,
cc-znp activeepcount: 2,
cc-znp activeeplist: <Buffer 01 02> },
cc-znp fcs: 201,
cc-znp csum: 201 } +966ms
serialport:main _read reading +5ms
serialport:bindings read +6ms
serialport:unixRead Starting read +6ms
cc-znp:AREQ <-- ZDO:activeEpRsp, { srcaddr: 2745, status: 0, nwkaddr: 2745, activeepcount: 2, activeeplist: <Buffer 01 02> } +3ms
zigbee-shepherd:msgHdlr IND <-- ZDO:activeEpRsp +1ms
zigbee-shepherd:request REQ --> ZDO:simpleDescReq +1ms
cc-znp:SREQ --> ZDO:simpleDescReq, { dstaddr: 2745, nwkaddrofinterest: 2745, endpoint: 1 } +0ms
serialport:main _write 10 bytes of data +5ms
serialport:bindings write 10 bytes +5ms
serialport:unixWrite Starting write 10 bytes offset 0 bytesToWrite 10 +984ms
serialport:unixRead waiting for readable because of code: EAGAIN +6ms
serialport:poller Polling for "readable" +12ms
serialport:unixWrite write returned null 10 +1ms
serialport:unixWrite wrote 10 bytes +0ms
serialport:unixWrite Finished writing 10 bytes +0ms
serialport:main binding.write write finished +2ms
serialport:poller received "readable" +8ms
serialport:bindings read +9ms
serialport:unixRead Starting read +8ms
serialport:unixRead Finished read 6 bytes +1ms
serialport:main binding.read finished +8ms
cc-znp { sof: 254,
cc-znp len: 1,
cc-znp type: 'SRSP',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'simpleDescReq',
cc-znp payload: { status: 0 },
cc-znp fcs: 96,
cc-znp csum: 96 } +14ms
serialport:main _read reading +4ms
serialport:bindings read +5ms
serialport:unixRead Starting read +4ms
cc-znp:SRSP <-- ZDO:simpleDescReq, { status: 0 } +3ms
serialport:unixRead waiting for readable because of code: EAGAIN +1ms
serialport:poller Polling for "readable" +7ms
serialport:poller received "readable" +976ms
serialport:bindings read +978ms
serialport:unixRead Starting read +978ms
serialport:unixRead Finished read 35 bytes +0ms
serialport:main binding.read finished +979ms
cc-znp { sof: 254,
cc-znp len: 30,
cc-znp type: 'AREQ',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'simpleDescRsp',
cc-znp payload:
cc-znp { srcaddr: 2745,
cc-znp status: 0,
cc-znp nwkaddr: 2745,
cc-znp len: 24,
cc-znp endpoint: 1,
cc-znp profileid: 260,
cc-znp deviceid: 1026,
cc-znp deviceversion: 0,
cc-znp numinclusters: 7,
cc-znp inclusterlist: <Buffer 00 00 01 00 03 00 20 00 02 04 00 05 05 0b>,
cc-znp numoutclusters: 1,
cc-znp outclusterlist: <Buffer 19 00> },
cc-znp fcs: 245,
cc-znp csum: 245 } +982ms
serialport:main _read reading +6ms
serialport:bindings read +12ms
serialport:unixRead Starting read +11ms
cc-znp:AREQ <-- ZDO:simpleDescRsp, { srcaddr: 2745, status: 0, nwkaddr: 2745, len: 24, endpoint: 1, profileid: 260, deviceid: 1026, deviceversion: 0, numinclusters: 7, inclusterlist: <Buffer 00 00 01 00 03 00 20 00 02 04 00 05 05 0b>, numoutclusters: 1, outclusterlist: <Buffer 19 00> } +8ms
zigbee-shepherd:msgHdlr IND <-- ZDO:simpleDescRsp +1ms
zigbee-shepherd:request REQ --> ZDO:simpleDescReq +1ms
cc-znp:SREQ --> ZDO:simpleDescReq, { dstaddr: 2745, nwkaddrofinterest: 2745, endpoint: 2 } +1ms
serialport:main _write 10 bytes of data +11ms
serialport:bindings write 10 bytes +6ms
serialport:unixWrite Starting write 10 bytes offset 0 bytesToWrite 10 +1s
serialport:unixRead waiting for readable because of code: EAGAIN +7ms
serialport:poller Polling for "readable" +19ms
serialport:unixWrite write returned null 10 +1ms
serialport:unixWrite wrote 10 bytes +0ms
serialport:unixWrite Finished writing 10 bytes +0ms
serialport:main binding.write write finished +3ms
serialport:poller received "readable" +8ms
serialport:bindings read +9ms
serialport:unixRead Starting read +9ms
serialport:unixRead Finished read 6 bytes +1ms
serialport:main binding.read finished +8ms
cc-znp { sof: 254,
cc-znp len: 1,
cc-znp type: 'SRSP',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'simpleDescReq',
cc-znp payload: { status: 0 },
cc-znp fcs: 96,
cc-znp csum: 96 } +18ms
serialport:main _read reading +7ms
serialport:bindings read +9ms
serialport:unixRead Starting read +8ms
cc-znp:SRSP <-- ZDO:simpleDescReq, { status: 0 } +4ms
serialport:unixRead waiting for readable because of code: EAGAIN +2ms
serialport:poller Polling for "readable" +12ms
serialport:poller received "readable" +945ms
serialport:bindings read +948ms
serialport:unixRead Starting read +946ms
serialport:unixRead Finished read 18 bytes +0ms
serialport:main binding.read finished +949ms
cc-znp { sof: 254,
cc-znp len: 13,
cc-znp type: 'AREQ',
cc-znp subsys: 'ZDO',
cc-znp cmd: 'leaveInd',
cc-znp payload:
cc-znp { srcaddr: 2745,
cc-znp extaddr: '0x000d6f001099e6c1',
cc-znp request: 0,
cc-znp removechildren: 0,
cc-znp rejoin: 0 },
cc-znp fcs: 254,
cc-znp csum: 254 } +953ms
serialport:main _read reading +8ms
serialport:bindings read +9ms
serialport:unixRead Starting read +9ms
cc-znp:AREQ <-- ZDO:leaveInd, { srcaddr: 2745, extaddr: '0x000d6f001099e6c1', request: 0, removechildren: 0, rejoin: 0 } +4ms
zigbee-shepherd:msgHdlr IND <-- ZDO:leaveInd +1ms
[/code]