Zigbee2mqtt failed to start/restart after request timeout or request unsuccess #1656

dzungpv · 2019-06-21T16:18:33Z

Bug Report

What happened

Ihave 19 devices connected, sometimes z2m failed to restart/start after request timeout or request unsuccess, reboot device not help, only unplug the cc2530 usb and re-plug.
Logs:

  zigbee2mqtt:info 6/21/2019, 11:06:00 PM 
	{"message":"request unsuccess: 17","stack":"Error: request unsuccess: 17\n    at /zigbee2mqtt-1.4.0/node_modules/zigbee-shepherd/lib/components/zdo.js:45:21\n    at CcZnp.<anonymous> (/zigbee2mqtt-1.4.0/node_modules/cc-znp/lib/ccznp.js:272:13)\n    at Object.onceWrapper (events.js:273:13)\n    at CcZnp.emit (events.js:182:13)\n    at CcZnp._mtIncomingDataHdlr (/zigbee2mqtt-1.4.0/node_modules/cc-znp/lib/ccznp.js:374:14)\n    at Immediate._onImmediate (/zigbee2mqtt-1.4.0/node_modules/cc-znp/lib/ccznp.js:350:22)\n    at runCallback (timers.js:705:18)\n    at tryOnImmediate (timers.js:676:5)\n    at processImmediate (timers.js:658:5)"}

zigbee2mqtt:error 6/21/2019, 11:06:25 PM 
	{"message":"request timeout","stack":"Error: request timeout\n    at CcZnp.<anonymous> (/zigbee2mqtt-1.4.0/node_modules/cc-znp/lib/ccznp.js:269:22)\n    at Object.onceWrapper (events.js:273:13)\n    at CcZnp.emit (events.js:182:13)\n    at Timeout.<anonymous> (/zigbee2mqtt-1.4.0/node_modules/cc-znp/lib/ccznp.js:248:18)\n    at ontimeout (timers.js:436:11)\n    at tryOnTimeout (timers.js:300:5)\n    at listOnTimeout (timers.js:263:5)\n    at Timer.processTimers (timers.js:223:10)"}

What did you expect to happen

It is randomly

How to reproduce it (minimal and precise)

Offline some device (unplug) and then error occure

Debug Info

zigbee2mqtt version: 1.4.0
CC253X firmware version: CC2530_CC2591_20190515, z-stack 1.2

The text was updated successfully, but these errors were encountered:

Koenkk · 2019-06-23T19:23:27Z

error 17 means that the buffer is full. Can you post the log_level: debug log when this happens? (http://www.zigbee2mqtt.io/configuration/configuration.html)

dzungpv · 2019-06-24T05:19:10Z

@Koenkk I restart Z2M and then all the log gone, i will get it next time

drbios · 2019-06-25T22:30:48Z

same problem : debug log

0 info it worked if it ends with ok
1 verbose cli [ '/usr/bin/node', '/usr/bin/npm', 'start' ]
2 info using npm@6.9.0
3 info using node@v10.16.0
4 verbose run-script [ 'prestart', 'start', 'poststart' ]
5 info lifecycle zigbee2mqtt@1.4.0prestart: zigbee2mqtt@1.4.0
6 info lifecycle zigbee2mqtt@1.4.0start: zigbee2mqtt@1.4.0
7 verbose lifecycle zigbee2mqtt@1.4.0start: unsafe-perm in lifecycle true
8 verbose lifecycle zigbee2mqtt@1.4.0start: PATH: /usr/lib/node_modules/npm/node_modules/npm-lifecycle/node-gyp-bin:/opt/zigbee2mqtt/node_modules/.bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
9 verbose lifecycle zigbee2mqtt@1.4.0start: CWD: /opt/zigbee2mqtt
10 silly lifecycle zigbee2mqtt@1.4.0start: Args: [ '-c', 'node index.js' ]
11 silly lifecycle zigbee2mqtt@1.4.0start: Returned: code: 1 signal: null
12 info lifecycle zigbee2mqtt@1.4.0start: Failed to exec start script
13 verbose stack Error: zigbee2mqtt@1.4.0 start: node index.js
13 verbose stack Exit status 1
13 verbose stack at EventEmitter. (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/index.js:301:16)
13 verbose stack at EventEmitter.emit (events.js:198:13)
13 verbose stack at ChildProcess. (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/lib/spawn.js:55:14)
13 verbose stack at ChildProcess.emit (events.js:198:13)
13 verbose stack at maybeClose (internal/child_process.js:982:16)
13 verbose stack at Process.ChildProcess._handle.onexit (internal/child_process.js:259:5)
14 verbose pkgid zigbee2mqtt@1.4.0
15 verbose cwd /opt/zigbee2mqtt
16 verbose Linux 4.19.50-v7+
17 verbose argv "/usr/bin/node" "/usr/bin/npm" "start"
18 verbose node v10.16.0
19 verbose npm v6.9.0
20 error code ELIFECYCLE
21 error errno 1
22 error zigbee2mqtt@1.4.0 start: node index.js
22 error Exit status 1
23 error Failed at the zigbee2mqtt@1.4.0 start script.
23 error This is probably not a problem with npm. There is likely additional logging output above.
24 verbose exit [ 1, true ]

drbios · 2019-06-25T22:37:18Z

Jun 25 18:17:51 hassbian npm[987]: #33[32m zigbee2mqtt:info#033[39m 6/25/2019, 6:17:51 PM Error while starting zigbee-shepherd, attempting to fix... (takes 60 seconds) (Error: request t imeout)
#11{"message":"request timeout","stack":"Error: request timeout\n at CcZnp. (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/cc-znp/index.js:208:22)\n at Object.once Wrapper (events.js:286:20)\n at CcZnp.emit (events.js:198:13)\n at Timeout. (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/cc-znp/index.js:192:18)\n at ontimeout (timers.js:436:11)\n at tryOnTimeout (timers.js:300:5)\n at listOnTimeout (timers.js:263:5)\n at Timer.processTimers (timers.js:223:10)"}Jun 25 18:18:51 hassbian npm[987]: #33[3 2m zigbee2mqtt:info#033[39m 6/25/2019, 6:18:51 PM Starting zigbee-shepherd

Koenkk · 2019-06-26T17:31:43Z

@drbios please post the DEBUG=* npm start log.

drbios · 2019-06-27T00:39:40Z

@Koenkk 2 things:

when i run DEBUG=* npm start log ... everything works normal
Where is the output log of DEBUG=* npm start log? (you mean publish all the screen output code??)

really sorry about my ignorance

dzungpv · 2019-06-27T10:27:53Z

@Koenkk This is log:

6/27/2019, 5:13:10 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genBasic","data":{"manufacturerName":"DNCKAT","modelId":"DNCKAT_S003","powerSource":1}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:13:10 PM - warn: No converter available for 'DNCKATSW003' with cid 'genBasic', type 'devChange' and data '{"cid":"genBasic","data":{"manufacturerName":"DNCKAT","modelId":"DNCKAT_S003","powerSource":1}}'
6/27/2019, 5:13:10 PM - warn: Please see: https://www.zigbee2mqtt.io/how_tos/how_to_support_new_devices.html.
6/27/2019, 5:13:10 PM - debug: Received zigbee message of type 'readRsp' with data '{"cid":"genBasic","data":{"zclVersion":0,"hwVersion":0,"dateCode":"20180702        "}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:13:10 PM - debug: Received zigbee message of type 'devInterview' with data '"0xxxxxxb001204eb34"'
6/27/2019, 5:13:10 PM - debug: Received zigbee message of type 'devInterview' with data '"0xxxxxxb001204eb34"'
6/27/2019, 5:13:10 PM - debug: Received zigbee message of type 'devInterview' with data '"0xxxxxxb001204eb34"'
6/27/2019, 5:13:10 PM - debug: Received zigbee message of type 'devInterview' with data '"0xxxxxxb001204eb34"'
6/27/2019, 5:13:10 PM - debug: Received zigbee message of type 'devInterview' with data '"0xxxxxxb001204eb34"'
6/27/2019, 5:13:11 PM - debug: Received zigbee message of type 'devInterview' with data '"0xxxxxxb001204eb34"'
6/27/2019, 5:13:11 PM - debug: Received zigbee message of type 'devInterview' with data '"0xxxxxxb001204eb34"'
6/27/2019, 5:13:11 PM - debug: Received zigbee message of type 'devInterview' with data '"0xxxxxxb001204eb34"'
6/27/2019, 5:13:11 PM - debug: Received zigbee message of type 'devInterview' with data '"0xxxxxxb001204eb34"'
6/27/2019, 5:13:11 PM - debug: Accept device incoming with ieeeAddr '0xxxxxxb001204eb34' permit join is 'true'
6/27/2019, 5:13:11 PM - debug: Allowing device '0xxxxxxb001204eb34' to join
6/27/2019, 5:13:11 PM - debug: Received zigbee message of type 'devIncoming' with data '"0xxxxxxb001204eb34"' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:13:11 PM - info: Device incoming...
6/27/2019, 5:13:11 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"pairing","message":"device incoming"}'
6/27/2019, 5:13:11 PM - debug: Received zigbee message of type 'devStatus' with data '"online"' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:13:41 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204e9fa/set' with data 'OFF'
6/27/2019, 5:13:41 PM - info: Zigbee publish to device '0xxxxxxb001204e9fa', genOnOff - off - {} - {"manufSpec":0,"disDefaultRsp":0} - null
6/27/2019, 5:13:47 PM - error: Zigbee publish to device '0xxxxxxb001204e9fa', genOnOff - off - {} - {"manufSpec":0,"disDefaultRsp":0} - null failed with error Error: AF data request fails, status code: 240. MAC transaction expired.
6/27/2019, 5:13:47 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Error: AF data request fails, status code: 240. MAC transaction expired.","meta":{"entity":{"ID":"0xxxxxxb001204e9fa","type":"device","friendlyName":"0xxxxxxb001204e9fa"},"message":"OFF"}}'
6/27/2019, 5:13:56 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'DNCKAT_S001' (0xxxxxxb000d662872) of endpoint 1
6/27/2019, 5:13:56 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb000d662872', payload '{"state":"OFF","linkquality":72}'
6/27/2019, 5:14:00 PM - debug: Received zigbee message of type 'endDeviceAnnce' with data '"0xxxxxxb001204eb34"' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:14:00 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:14:00 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":70,"state_center":"OFF","button_center":"hold","state_left":"OFF"}'
6/27/2019, 5:14:00 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:14:00 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":70,"state_center":"OFF","button_center":"hold","state_left":"OFF","button_left":"hold"}'
6/27/2019, 5:14:00 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 2
6/27/2019, 5:14:00 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":72,"state_center":"ON","button_center":"hold","state_left":"OFF"}'
6/27/2019, 5:14:00 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 2
6/27/2019, 5:14:00 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":72,"state_center":"ON","button_center":"release","state_left":"OFF"}'
6/27/2019, 5:14:00 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 3
6/27/2019, 5:14:00 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":72,"state_center":"ON","button_center":"release","state_left":"OFF"}'
6/27/2019, 5:14:00 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 3
6/27/2019, 5:14:00 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":72,"state_center":"ON","button_center":"release","state_left":"OFF","button_right":"hold"}'
6/27/2019, 5:14:03 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 2
6/27/2019, 5:14:03 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":65,"state_center":"OFF","button_center":"release","state_left":"OFF"}'
6/27/2019, 5:14:03 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 2
6/27/2019, 5:14:03 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":65,"state_center":"OFF","button_center":"hold","state_left":"OFF"}'
6/27/2019, 5:14:05 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:14:05 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":62,"state_center":"OFF","button_center":"hold","state_left":"ON"}'
6/27/2019, 5:14:05 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:14:05 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":62,"state_center":"OFF","button_center":"hold","state_left":"ON","button_left":"release"}'
6/27/2019, 5:14:06 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:14:06 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":67,"state_center":"OFF","button_center":"hold","state_left":"OFF"}'
6/27/2019, 5:14:06 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:14:06 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":67,"state_center":"OFF","button_center":"hold","state_left":"OFF","button_left":"hold"}'
6/27/2019, 5:14:09 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:14:09 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":67,"state_center":"OFF","button_center":"hold","state_left":"ON"}'
6/27/2019, 5:14:09 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'DNCKAT_S003' (0xxxxxxb001204eb34) of endpoint 1
6/27/2019, 5:14:09 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb001204eb34', payload '{"state_right":"OFF","linkquality":67,"state_center":"OFF","button_center":"hold","state_left":"ON","button_left":"release"}'
6/27/2019, 5:14:26 PM - debug: Saving state to file /share/zigbee2mqtt/state.json
6/27/2019, 5:14:56 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'DNCKAT_S001' (0xxxxxxb000d662872) of endpoint 1
6/27/2019, 5:14:56 PM - info: MQTT publish: topic 'zigbee2mqtt/0xxxxxxb000d662872', payload '{"state":"OFF","linkquality":80}'
6/27/2019, 5:15:24 PM - error:  Error: request timeout
    at CcZnp.<anonymous> (/zigbee2mqtt-1.4.0/node_modules/cc-znp/lib/ccznp.js:269:22)
    at Object.onceWrapper (events.js:273:13)
    at CcZnp.emit (events.js:182:13)
    at Timeout.<anonymous> (/zigbee2mqtt-1.4.0/node_modules/cc-znp/lib/ccznp.js:248:18)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10)
6/27/2019, 5:16:04 PM - error: Failed to reenable joining
6/27/2019, 5:16:07 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204ea46/set' with data 'OFF'
6/27/2019, 5:16:07 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204ea46'
6/27/2019, 5:16:07 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204ea46"}'
6/27/2019, 5:16:17 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204ea46/set' with data 'OFF'
6/27/2019, 5:16:17 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204ea46'
6/27/2019, 5:16:17 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204ea46"}'
6/27/2019, 5:16:19 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204ea46/set' with data 'OFF'
6/27/2019, 5:16:19 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204ea46'
6/27/2019, 5:16:19 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204ea46"}'
6/27/2019, 5:16:31 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204ea46/set' with data 'OFF'
6/27/2019, 5:16:31 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204ea46'
6/27/2019, 5:16:31 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204ea46"}'
6/27/2019, 5:16:40 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204ea46/set' with data 'OFF'
6/27/2019, 5:16:40 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204ea46'
6/27/2019, 5:16:40 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204ea46"}'
6/27/2019, 5:16:42 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204e9fa/set' with data 'OFF'
6/27/2019, 5:16:42 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204e9fa'
6/27/2019, 5:16:42 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204e9fa"}'
6/27/2019, 5:16:43 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204eb34/left/set' with data 'OFF'
6/27/2019, 5:16:43 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204eb34'
6/27/2019, 5:16:43 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204eb34"}'
6/27/2019, 5:16:43 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204eb34/center/set' with data 'OFF'
6/27/2019, 5:16:43 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204eb34'
6/27/2019, 5:16:43 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204eb34"}'
6/27/2019, 5:16:43 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb000d66287f/set' with data 'OFF'
6/27/2019, 5:16:43 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb000d66287f'
6/27/2019, 5:16:43 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb000d66287f"}'
6/27/2019, 5:16:45 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204ea64/set' with data 'ON'
6/27/2019, 5:16:45 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204ea64'
6/27/2019, 5:16:45 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204ea64"}'
6/27/2019, 5:16:50 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204eb34/right/set' with data 'ON'
6/27/2019, 5:16:50 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204eb34'
6/27/2019, 5:16:50 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204eb34"}'
6/27/2019, 5:16:51 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204eb34/center/set' with data 'ON'
6/27/2019, 5:16:51 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204eb34'
6/27/2019, 5:16:51 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204eb34"}'
6/27/2019, 5:16:52 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb000d662872/set' with data 'ON'
6/27/2019, 5:16:52 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb000d662872'
6/27/2019, 5:16:52 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb000d662872"}'
6/27/2019, 5:17:45 PM - debug: Received MQTT message on 'zigbee2mqtt/bridge/config/permit_join' with data 'false'
6/27/2019, 5:17:45 PM - info: Zigbee: disabling joining new devices.
6/27/2019, 5:17:45 PM - info:  Error: Shepherd is not enabled.
    at ZShepherd.permitJoin (/zigbee2mqtt-1.4.0/node_modules/zigbee-shepherd/lib/shepherd.js:291:25)
    at Zigbee.permitJoin (/zigbee2mqtt-1.4.0/lib/zigbee.js:202:23)
    at BridgeConfig.permitJoin (/zigbee2mqtt-1.4.0/lib/extension/bridgeConfig.js:75:21)
    at BridgeConfig.onMQTTMessage (/zigbee2mqtt-1.4.0/lib/extension/bridgeConfig.js:257:38)
    at results.extensions.filter.map (/zigbee2mqtt-1.4.0/lib/controller.js:152:27)
    at Array.map (<anonymous>)
    at Controller.onMQTTMessage (/zigbee2mqtt-1.4.0/lib/controller.js:152:14)
    at MQTT.onMessage (/zigbee2mqtt-1.4.0/lib/mqtt.js:81:18)
    at MqttClient.emit (events.js:182:13)
    at MqttClient._handlePublish (/zigbee2mqtt-1.4.0/node_modules/mqtt/lib/client.js:987:12)
6/27/2019, 5:17:45 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"version":"1.4.0","commit":"unknown","log_level":"debug","permit_join":false}'
6/27/2019, 5:19:26 PM - debug: Saving state to file /share/zigbee2mqtt/state.json
6/27/2019, 5:20:00 PM - debug: Received MQTT message on 'zigbee2mqtt/bridge/networkmap' with data 'graphviz'
6/27/2019, 5:20:00 PM - info: Starting network scan...
6/27/2019, 5:20:00 PM - info: Network scan completed
6/27/2019, 5:20:00 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/networkmap/graphviz', payload 'digraph G {
node[shape=record];
}'
6/27/2019, 5:20:53 PM - debug: Received MQTT message on 'zigbee2mqtt/0xxxxxxb001204ea2e/set' with data 'OFF'
6/27/2019, 5:20:53 PM - error: Failed to find device with ieeeAddr: '0xxxxxxb001204ea2e'
6/27/2019, 5:20:53 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"entity_not_found","message":"0xxxxxxb001204ea2e"}'

Koenkk · 2019-06-27T17:17:46Z

@drbios @dzungpv

What firmware are you running?
The debug output log can be acquired by running with DEBUG=* npm start (necessary to solve this). You should see MUCH more output when running with this option.

drbios · 2019-06-28T02:32:55Z

@Koenkk This is my log
log.txt

drbios · 2019-06-28T03:12:33Z

@Koenkk why when I execute DEBUG=* npm start z2m works?

Koenkk · 2019-07-01T13:45:54Z

@drbios I'm not sure, is this consistent?

When starting without, does it always fail?
When start with DEBUG=* does it always succeed?

drbios · 2019-07-01T16:23:13Z

@Koenkk
When starting without, does it always fail?
yes

When start with DEBUG=* does it always succeed?
yes

Koenkk · 2019-07-01T17:23:22Z

Can you try with DEBUG=cc-znp* npm start?

drbios · 2019-07-01T17:57:49Z

@Koenkk executing 'DEBUG=cc-znp* npm start' appears some errors and z2m doesnt start

``pi@hassbian:/opt/zigbee2mqtt $ DEBUG=cc-znp* npm start

zigbee2mqtt@1.4.0 start /opt/zigbee2mqtt
node index.js

zigbee2mqtt:info 7/1/2019, 1:55:57 PM Logging to directory: '/opt/zigbee2mqtt/data/log/2019-07-01.13-55-56'
zigbee2mqtt:debug 7/1/2019, 1:55:57 PM Removing old log directory '/opt/zigbee2mqtt/data/log/2019-06-30.07-38-38'
zigbee2mqtt:debug 7/1/2019, 1:55:57 PM Loaded state from file /opt/zigbee2mqtt/data/state.json
zigbee2mqtt:debug 7/1/2019, 1:55:57 PM Saving state to file /opt/zigbee2mqtt/data/state.json
zigbee2mqtt:info 7/1/2019, 1:55:57 PM Starting zigbee2mqtt version 1.4.0 (commit #51df6b7)
zigbee2mqtt:info 7/1/2019, 1:55:57 PM Starting zigbee-shepherd
zigbee2mqtt:debug 7/1/2019, 1:55:57 PM Using zigbee-shepherd with settings: '{"net":{"panId":6760,"extPanId":[221,221,221,221,221,221,221,221],"channelList":[20],"precfgkey":"HIDDEN"},"dbPath":"/opt/zigbee2mqtt/data/database.db","coordBackupPath":"/opt/zigbee2mqtt/data/coordinator_backup.json","sp":{"baudRate":115200,"rtscts":false}}'
cc-znp Initialize, opening serial port +0ms
cc-znp The serialport /dev/ttyAMA0 is opened. +1s
cc-znp:SREQ --> SYS:version, {} +0ms
cc-znp Frame {
cc-znp type: 'SRSP',
cc-znp subsystem: 1,
cc-znp commandID: 2,
cc-znp data: [ 2, 0, 2, 6, 3, 155, 21, 52, 1, 2, 0, 0, 0, 0 ],
cc-znp length: 14,
cc-znp fcs: 209,
cc-znp csum: 209,
cc-znp sof: 254,
cc-znp len: 14,
cc-znp subsys: 'SYS',
cc-znp cmd: 'version',
cc-znp payload:
cc-znp { transportrev: 2,
cc-znp product: 0,
cc-znp majorrel: 2,
cc-znp minorrel: 6,
cc-znp maintrel: 3,
cc-znp revision: 20190619 } } +36ms
cc-znp:SRSP <-- SYS:version, { transportrev: 2, product: 0, majorrel: 2, minorrel: 6, maintrel: 3, revision: 20190619 } +0ms
cc-znp:SREQ --> SYS:osalNvRead, { id: 3840, offset: 0, len: 1, value: [ 85 ] } +51ms
cc-znp Frame {
cc-znp type: 'SRSP',
cc-znp subsystem: 1,
cc-znp commandID: 8,
cc-znp data: [ 0, 1, 85 ],
cc-znp length: 3,
cc-znp fcs: 62,
cc-znp csum: 62,
cc-znp sof: 254,
cc-znp len: 3,
cc-znp subsys: 'SYS',
cc-znp cmd: 'osalNvRead',
cc-znp payload: { status: 0, len: 1, value: <Buffer 55> } } +49ms
cc-znp:SRSP <-- SYS:osalNvRead, { status: 0, len: 1, value: <Buffer 55> } +39ms
cc-znp:SREQ --> SYS:osalNvRead, { id: 131, len: 2, offset: 0, value: [ 104, 26 ] } +47ms
cc-znp:SRSP <-- SYS:osalNvRead, timeout +3s
zigbee2mqtt:info 7/1/2019, 1:56:01 PM Error while starting zigbee-shepherd, attempting to fix... (takes 60 seconds) (Error: request timeout)
cc-znp The serialport /dev/ttyAMA0 is closed. +3s
zigbee2mqtt:info 7/1/2019, 1:57:01 PM Starting zigbee-shepherd
cc-znp Initialize, opening serial port +1m
cc-znp The serialport /dev/ttyAMA0 is opened. +1s
cc-znp:SREQ --> SYS:version, {} +1m
cc-znp:SRSP <-- SYS:version, timeout +1m
cc-znp:SREQ --> SYS:osalNvRead, { id: 3840, offset: 0, len: 1, value: [ 85 ] } +3s
cc-znp:SRSP <-- SYS:osalNvRead, timeout +3s
zigbee2mqtt:error 7/1/2019, 1:57:08 PM Error while starting zigbee-shepherd! (Error: request timeout)
zigbee2mqtt:error 7/1/2019, 1:57:08 PM Press the reset button on the stick (the one closest to the USB) and start again
zigbee2mqtt:error 7/1/2019, 1:57:08 PM Failed to start
{"message":"request timeout","stack":"Error: request timeout\n at CcZnp. (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/cc-znp/index.js:208:22)\n at Object.onceWrapper (events.js:286:20)\n at CcZnp.emit (events.js:198:13)\n at Timeout. (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/cc-znp/index.js:192:18)\n at ontimeout (timers.js:436:11)\n at tryOnTimeout (timers.js:300:5)\n at listOnTimeout (timers.js:263:5)\n at Timer.processTimers (timers.js:223:10)"}
zigbee2mqtt:error 7/1/2019, 1:57:08 PM Exiting...
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! zigbee2mqtt@1.4.0 start: node index.js
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the zigbee2mqtt@1.4.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/2019-07-01T17_57_08_997Z-debug.log

drbios · 2019-07-01T18:19:24Z

@Koenkk i am using a cc2531+cc2591 connected to the uart port of my rasberry
what is the best option? uart port or usb serial adaptor?

drbios · 2019-07-01T19:31:49Z

`pi@hassbian:/opt/zigbee2mqtt $ nano /home/pi/.npm/_logs/2019-07-01T19_30_22_111Z-debug.log
GNU nano 3.2 /home/pi/.npm/_logs/2019-07-01T19_30_22_111Z-debug.log

0 info it worked if it ends with ok
1 verbose cli [ '/usr/bin/node', '/usr/bin/npm', 'start' ]
2 info using npm@6.9.0
3 info using node@v10.16.0
4 verbose run-script [ 'prestart', 'start', 'poststart' ]
5 info lifecycle zigbee2mqtt@1.4.0prestart: zigbee2mqtt@1.4.0
6 info lifecycle zigbee2mqtt@1.4.0start: zigbee2mqtt@1.4.0
7 verbose lifecycle zigbee2mqtt@1.4.0start: unsafe-perm in lifecycle true
8 verbose lifecycle zigbee2mqtt@1.4.0start: PATH: /usr/lib/node_modules/npm/node_modules/npm-lifecycle/node-gyp-bin:/opt/zigbee2mqtt/node_modules/.bin:/home/pi/.local/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/s$
9 verbose lifecycle zigbee2mqtt@1.4.0start: CWD: /opt/zigbee2mqtt
10 silly lifecycle zigbee2mqtt@1.4.0start: Args: [ '-c', 'node index.js' ]
11 silly lifecycle zigbee2mqtt@1.4.0start: Returned: code: 1 signal: null
12 info lifecycle zigbee2mqtt@1.4.0start: Failed to exec start script
13 verbose stack Error: zigbee2mqtt@1.4.0 start: node index.js
13 verbose stack Exit status 1
13 verbose stack at EventEmitter. (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/index.js:301:16)
13 verbose stack at EventEmitter.emit (events.js:198:13)
13 verbose stack at ChildProcess. (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/lib/spawn.js:55:14)
13 verbose stack at ChildProcess.emit (events.js:198:13)
13 verbose stack at maybeClose (internal/child_process.js:982:16)
13 verbose stack at Process.ChildProcess._handle.onexit (internal/child_process.js:259:5)
14 verbose pkgid zigbee2mqtt@1.4.0
15 verbose cwd /opt/zigbee2mqtt
16 verbose Linux 4.19.56-v7+
17 verbose argv "/usr/bin/node" "/usr/bin/npm" "start"
18 verbose node v10.16.0
19 verbose npm v6.9.0
20 error code ELIFECYCLE
21 error errno 1
22 error zigbee2mqtt@1.4.0 start: node index.js
22 error Exit status 1
23 error Failed at the zigbee2mqtt@1.4.0 start script.
23 error This is probably not a problem with npm. There is likely additional logging output above.
24 verbose exit [ 1, true ]
`

Koenkk · 2019-07-02T09:08:58Z

Does it work via USB? Also please don't post logs here but post them on pastebin.com and post the link here. (it makes this thread unreadable).

drbios · 2019-07-02T12:09:45Z

@Koenkk sorry about postong the logan directly here
These is the url of `DEBUG=cc-znp* npm start'

https://pastebin.com/39in1eCM

In there are 2 timeouts that could be the problem
Meanwhile I'll try connecting through a usb serial adapter

drbios · 2019-07-03T02:02:00Z

@Koenkk i coonect the cc2530-cc2591 with a usb adater and works but whit errors
https://pastebin.com/21gBhxSc

Koenkk · 2019-07-04T18:37:52Z

It seems the connection is not stable, what do you have in configuration.yaml?

rickkdotnet · 2019-07-04T19:24:33Z

FWIW, I haven't seen this error after my network stabilized. I haven't looked at the code so I don't know if this makes sense, but I have the feeling it might have something to do with events happening in the network itself when z2m is starting.

drbios · 2019-07-04T19:41:57Z

https://pastebin.com/DJ9RPt5S

Koenkk · 2019-07-05T06:39:18Z

Looks OK, when running with DEBUG=* npm start via USB adapter, do you also have timeouts?

drbios · 2019-07-05T14:05:16Z

@Koenkk it takes some time but after no more 5 minutes timeouts appears

Koenkk · 2019-07-05T21:44:00Z

@drbios also when on the master branch?

drbios · 2019-07-05T22:42:39Z

In the master branch work but my devices are not supported
I always use the latest dev and the latest source routing firmware

not problem at all until two weeks ago that I update the dev branch

Koenkk · 2019-07-06T16:29:29Z

Ok, so last thing I need to know, when running with latest dev and DEBUG=* npm start, do you get any timeouts?

drbios · 2019-07-07T17:13:50Z

@Koenkk after a few minutes running I get timeouts ... I suspect that cc2530+cc2591 have some memory capacity problems. Last night I flash a cc2531 with SR-firmware and using the latest dev branch...like magic every thing works perfect (fast and responsive) no errors at all I have 16 bulbs and 1 cc2530+cc2591 router.
Cc2530+cc2591 are good routers but awfull coordinators maybe.

Koenkk · 2019-07-08T06:27:58Z

@drbios what version of the coordinator firmware are you using?

drbios · 2019-07-08T12:46:12Z

@Koenkk i am using source routing 20190706
It's working great ...so far so good...I add 5 more devices (21 in total)

Koenkk · 2019-07-08T13:41:26Z

@drbios for the Cc2530+cc2591 or cc2531? Which one did you use for Cc2530+cc2591

drbios · 2019-07-09T04:20:30Z

@Koenkk for the cc2530+cc2591 I was using the 20190619 coordinator firmware source routig and the latest dev branch (this combination transform my apartment in a haunted house)

Last night I flash a cc2531 with the latest 20190706 source routing firmware and in combination with the latest dev branch everything works perfect (I call this combination...the exorcism one) and for now ...so far, so good

drbios · 2019-07-14T17:17:32Z

@Koenkk I update to dev 1.5.0 branch and using cc2531 with 20190706 source routing firmware and works perfect. I also try the new option of queue and delay and works like a charm. I can reproduce errors if I use a delay to low. The problem basically occurs when I hit the home assistant button for all lights (the one that turn on and off all lights in a list). When I use low latency errors occur but when I use higher latency it's just a little slow response but no error at all (responsiveness it's perfect). When I hit a single light button very fast using very low latency no errors occurs at all. The delay and queue options were the answer for this particular behavior. Congratulations 👌👌👌👌

Koenkk · 2019-07-14T18:13:27Z

Great! What settings do you use know?

drbios · 2019-07-14T18:29:40Z

homeassistant: false
permit_join: true
mqtt:
base_topic: zigbee2mqtt
server: 'mqtt://localhost'
user: ''
password: ''
serial:
port: /dev/ttyACM0
advanced:
channel: 20
queue:
delay: 75
simultaneously: 5

Koenkk · 2019-07-14T19:27:34Z

I dont understand, this delay is even lower than the default one?

drbios · 2019-07-14T20:06:25Z

@Koenkk yes, i've been testing which value suitable for my configuration. by now i am using something between 50-75 (default is 250). in this range the responsivness is incredible fast, in conjuntion with z2m i use a custom wifi mqtt tasmota module wall switches (aliexpess esp8285 flashed with tasmota and powered by a 3.3v small power supply, basically a wifi button connected to my standar wall switches) that triggers the zigbee lights in Home Assistant and i can't notice the delay. works perfect

dzungpv · 2019-07-17T15:44:26Z

@Koenkk I retry with 1.5.1, firmware ROUTING for CC2530+CC2591 CC2530_CC2591_SOURCE_ROUTING_20190619.zip , the same error, this time i am running the dev environment so with all the debug. Only reboot the devices, or unplug cc2530 could solve the problem, but it occurs in some days

pi@raspberrypi:/opt/zigbee2mqtt $ DEBUG=* npm start

> zigbee2mqtt@1.5.1 start /opt/zigbee2mqtt
> node index.js

  serialport/bindings loading LinuxBinding +0ms
  zigbee2mqtt:info 7/17/2019, 3:33:57 PM Logging to directory: '/opt/zigbee2mqtt/data/log/2019-07-17.15-33-56'
  zigbee2mqtt:debug 7/17/2019, 3:33:57 PM Removing old log directory '/opt/zigbee2mqtt/data/log/2019-07-11.15-49-14'
  zigbee2mqtt:debug 7/17/2019, 3:33:57 PM Removing old log directory '/opt/zigbee2mqtt/data/log/2019-07-17.15-16-19'
  zigbee2mqtt:debug 7/17/2019, 3:33:57 PM Loaded state from file /opt/zigbee2mqtt/data/state.json
  zigbee2mqtt:debug 7/17/2019, 3:33:57 PM Saving state to file /opt/zigbee2mqtt/data/state.json
  zigbee2mqtt:info 7/17/2019, 3:33:57 PM Starting zigbee2mqtt version 1.5.1 (commit #ac3b924)
  zigbee2mqtt:info 7/17/2019, 3:33:57 PM Starting zigbee-shepherd
  zigbee2mqtt:debug 7/17/2019, 3:33:57 PM Using zigbee-shepherd with settings: '{"net":{"panId":6754,"extPanId":[221,221,221,221,221,221,221,221],"channelList":[25],"precfgkey":"HIDDEN"},"dbPath":"/opt/zigbee2mqtt/data/database.db","coordBackupPath":"/opt/zigbee2mqtt/data/coordinator_backup.json","sp":{"baudRate":115200,"rtscts":false}}'
  zigbee-shepherd:init zigbee-shepherd booting... +0ms
  cc-znp Initialize, opening serial port +0ms
  serialport/stream opening path: /dev/ttyUSB0 +0ms
  serialport/binding-abstract open +0ms
  serialport/stream _read queueing _read for after open +5ms
  serialport/bindings/poller Creating poller +0ms
  serialport/stream opened path: /dev/ttyUSB0 +9ms
  serialport/stream _write 1 bytes of data +1ms
  serialport/binding-abstract write 1 bytes +14ms
  serialport/stream _read reading +2ms
  serialport/binding-abstract read +2ms
  serialport/bindings/unixWrite Starting write 1 bytes offset 0 bytesToWrite 1 +0ms
  serialport/bindings/unixRead Starting read +0ms
  serialport/bindings/unixWrite write returned null 1 +7ms
  serialport/bindings/unixWrite wrote 1 bytes +0ms
  serialport/bindings/unixWrite Finished writing 1 bytes +0ms
  serialport/stream binding.write write finished +10ms
  serialport/bindings/unixRead waiting for readable because of code: EAGAIN +8ms
  serialport/bindings/poller Polling for "readable" +17ms
  cc-znp The serialport /dev/ttyUSB0 is opened. +1s
  zigbee-shepherd:request REQ --> SYS:version +0ms
  cc-znp:SREQ --> SYS:version, {} +0ms
  unpi:writer --> frame [254,0,33,2,35] +0ms
  serialport/stream _write 5 bytes of data +1s
  serialport/binding-abstract write 5 bytes +1s
  serialport/bindings/unixWrite Starting write 5 bytes offset 0 bytesToWrite 5 +1s
  serialport/bindings/unixWrite write returned null 5 +1ms
  serialport/bindings/unixWrite wrote 5 bytes +1ms
  serialport/bindings/unixWrite Finished writing 5 bytes +0ms
  serialport/stream binding.write write finished +6ms
  cc-znp:SRSP <-- SYS:version, __timeout__ +0ms
  zigbee-shepherd:request RSP <-- SYS:version +3s
  zigbee-shepherd:request REQ --> SYS:osalNvRead +11ms
  cc-znp:SREQ --> SYS:osalNvRead, { id: 3840, offset: 0, len: 1, value: [ 85 ] } +3s
  unpi:writer --> frame [254,3,33,8,0,15,0,37] +3s
  serialport/stream _write 8 bytes of data +3s
  serialport/binding-abstract write 8 bytes +3s
  serialport/bindings/unixWrite Starting write 8 bytes offset 0 bytesToWrite 8 +3s
  serialport/bindings/unixWrite write returned null 8 +1ms
  serialport/bindings/unixWrite wrote 8 bytes +1ms
  serialport/bindings/unixWrite Finished writing 8 bytes +0ms
  serialport/stream binding.write write finished +6ms
  cc-znp:SRSP <-- SYS:osalNvRead, __timeout__ +3s
  zigbee-shepherd:request RSP <-- SYS:osalNvRead +3s
  zigbee-shepherd:init Coordinator initialize had an error: Error: request timeout
    at CcZnp.<anonymous> (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/cc-znp/index.js:208:22)
    at Object.onceWrapper (events.js:286:20)
    at CcZnp.emit (events.js:198:13)
    at Timeout.<anonymous> (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/cc-znp/index.js:192:18)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) +0ms
  zigbee2mqtt:info 7/17/2019, 3:34:04 PM Error while starting zigbee-shepherd, attempting to fix... (takes 60 seconds) (Error: request timeout)
  serialport/stream #flush +3s
  serialport/binding-abstract flush +3s
  serialport/stream binding.flush finished +4ms
  serialport/stream #close +2ms
  serialport/binding-abstract close +6ms
  serialport/bindings/poller Stopping poller +7s
  serialport/bindings/poller Destroying poller +3ms
  serialport/stream binding.read error { Error: Canceled
    at Poller.emitCanceled (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/node_modules/@serialport/bindings/lib/poller.js:101:17)
    at Poller.stop (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/node_modules/@serialport/bindings/lib/poller.js:91:10)
    at close.then (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/node_modules/@serialport/bindings/lib/linux.js:48:19) canceled: true } +6ms
  serialport/stream _read queueing _read for after open +2ms
  serialport/stream binding.close finished +2ms
  cc-znp The serialport /dev/ttyUSB0 is closed. +6s
  zigbee2mqtt:info 7/17/2019, 3:35:04 PM Starting zigbee-shepherd
  zigbee-shepherd:init zigbee-shepherd booting... +1m
  cc-znp Initialize, opening serial port +1m
  serialport/stream opening path: /dev/ttyUSB0 +1m
  serialport/binding-abstract open +1m
  serialport/bindings/poller Creating poller +1m
  serialport/stream opened path: /dev/ttyUSB0 +6ms
  serialport/stream _write 1 bytes of data +1ms
  serialport/binding-abstract write 1 bytes +6ms
  serialport/bindings/unixWrite Starting write 1 bytes offset 0 bytesToWrite 1 +1m
  serialport/bindings/unixWrite write returned null 1 +1ms
  serialport/bindings/unixWrite wrote 1 bytes +1ms
  serialport/bindings/unixWrite Finished writing 1 bytes +0ms
  serialport/stream binding.write write finished +4ms
  cc-znp The serialport /dev/ttyUSB0 is opened. +1s
  zigbee-shepherd:request REQ --> SYS:version +1m
  cc-znp:SREQ --> SYS:version, {} +1m
  unpi:writer --> frame [254,0,33,2,35] +1m
  cc-znp:SRSP <-- SYS:version, __timeout__ +1m
  zigbee-shepherd:request RSP <-- SYS:version +3s
  zigbee-shepherd:request REQ --> SYS:osalNvRead +2ms
  cc-znp:SREQ --> SYS:osalNvRead, { id: 3840, offset: 0, len: 1, value: [ 85 ] } +3s
  unpi:writer --> frame [254,3,33,8,0,15,0,37] +3s
  cc-znp:SRSP <-- SYS:osalNvRead, __timeout__ +3s
  zigbee-shepherd:request RSP <-- SYS:osalNvRead +3s
  zigbee-shepherd:init Coordinator initialize had an error: Error: request timeout
    at CcZnp.<anonymous> (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/cc-znp/index.js:208:22)
    at Object.onceWrapper (events.js:286:20)
    at CcZnp.emit (events.js:198:13)
    at Timeout.<anonymous> (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/cc-znp/index.js:192:18)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) +1m
  zigbee2mqtt:error 7/17/2019, 3:35:11 PM Error while starting zigbee-shepherd! (Error: request timeout)
  zigbee2mqtt:error 7/17/2019, 3:35:11 PM Press the reset button on the stick (the one closest to the USB) and start again
  zigbee2mqtt:error 7/17/2019, 3:35:11 PM Failed to start
        {"message":"request timeout","stack":"Error: request timeout\n    at CcZnp.<anonymous> (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/cc-znp/index.js:208:22)\n    at Object.onceWrapper (events.js:286:20)\n    at CcZnp.emit (events.js:198:13)\n    at Timeout.<anonymous> (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/cc-znp/index.js:192:18)\n    at ontimeout (timers.js:436:11)\n    at tryOnTimeout (timers.js:300:5)\n    at listOnTimeout (timers.js:263:5)\n    at Timer.processTimers (timers.js:223:10)"}
  zigbee2mqtt:error 7/17/2019, 3:35:11 PM Exiting...
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! zigbee2mqtt@1.5.1 start: `node index.js`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the zigbee2mqtt@1.5.1 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/2019-07-17T15_35_11_895Z-debug.log

Koenkk · 2019-07-18T18:34:07Z

@dzungpv do you get the same with the default firmware? We perhaps have to increase the memory heap for this firmware.

dzungpv · 2019-07-19T03:04:57Z

@Koenkk it occure with source routing with direct 5 children firmware too, it is not the most stable?

Koenkk · 2019-07-20T15:32:12Z

@dzungpv depends, but did you check with default?

arjanvroege · 2019-08-04T21:31:55Z

I had exactly the same as described in this issue with the CC2531 and the default firmware. I switched based on this topic to the Source Routing Firmware (my network contains 15 Bulbs, 3 Remotes, 1 on/off switch and 4 Xiaomi sensors) and it looks like its stable with the settings applied. It looks like there is a buffer which is filling and reaching his maximum. Before I receive the timeouts it works for a couple of days and then I'm busy with getting it all working. Sometimes re-adding the stick into my NUC is solving the issues but sometimes I need to re-flash it before it's going to work again.

Also could network scan and reporting a possible cause? I've them now both disabled and Zigbee2MQTT is working much more stable. In the old scenario most of the time not all Bulbs were reacting to commands. Today each action was working during the day.

Let me know if you need/want something from my side (logging,etc)..

Koenkk · 2019-08-05T18:11:49Z

A network scan has a BIG impact on the network traffic, and therefore only recommended to do when you need it (for debugging).
Reporting also puts extra stress on the network, especially when changing multiple bulbs at once, you could try enabling this again (and leave out the network scan).

DrMucki · 2019-09-30T20:16:25Z

May I ask for a similar problem here..CC2531, default fw
After reading all the stuff I fixed many of my problems, BUT
when trying to start I get the "Error while starting zigbee-shepherd..." Timeout ...
OK I plugged out the Zigbee Stick plugged it in again (I do not hav a reset button it, so I replugged it). Therefor it changes its device from ttyACM0 to ttyACM1.
I changed the config file with the new serial info and started up again with nom start.
Et voila. no problems it runs
After a reboot the device changes back to ttyACM0 again (of cause) ok, so I changed the config file back again and started up again.. ERROR...

before I started I checked the rights and the owner of /dev/ttyACMO and of /opt/zibgee2mqtt

but no success... I just want a stable system, so I can use a systemctl

Thank you

Koenkk · 2019-10-01T06:37:07Z

@DrMucki in that case map it by /dev/serial/by-id as explained here: https://www.zigbee2mqtt.io/getting_started/running_zigbee2mqtt.html#1-determine-location-of-cc2531-usb-sniffer-and-checking-user-permissions

stale · 2019-11-30T07:04:02Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

Koenkk mentioned this issue Jul 1, 2019

Latest dev not working #1681

Closed

drbios mentioned this issue Jul 3, 2019

error with clean install Raspbian-Buster #1682

Closed

rickkdotnet mentioned this issue Jul 29, 2019

Question: network stability and t-shooting #1566

Closed

stale bot added the stale Stale issues label Nov 30, 2019

stale bot closed this as completed Dec 7, 2019

Zigbee2mqtt failed to start/restart after request timeout or request unsuccess #1656

Zigbee2mqtt failed to start/restart after request timeout or request unsuccess #1656

Comments

dzungpv commented Jun 21, 2019

Bug Report

What happened

What did you expect to happen

How to reproduce it (minimal and precise)

Debug Info

Koenkk commented Jun 23, 2019

dzungpv commented Jun 24, 2019

drbios commented Jun 25, 2019

drbios commented Jun 25, 2019

Koenkk commented Jun 26, 2019

drbios commented Jun 27, 2019

dzungpv commented Jun 27, 2019

Koenkk commented Jun 27, 2019

drbios commented Jun 28, 2019

drbios commented Jun 28, 2019

Koenkk commented Jul 1, 2019

drbios commented Jul 1, 2019

Koenkk commented Jul 1, 2019

drbios commented Jul 1, 2019 • edited Loading

drbios commented Jul 1, 2019

drbios commented Jul 1, 2019

Koenkk commented Jul 2, 2019

drbios commented Jul 2, 2019

drbios commented Jul 3, 2019 • edited Loading

Koenkk commented Jul 4, 2019

rickkdotnet commented Jul 4, 2019

drbios commented Jul 4, 2019

Koenkk commented Jul 5, 2019

drbios commented Jul 5, 2019

Koenkk commented Jul 5, 2019

drbios commented Jul 5, 2019

Koenkk commented Jul 6, 2019

drbios commented Jul 7, 2019 • edited Loading

Koenkk commented Jul 8, 2019 • edited Loading

drbios commented Jul 8, 2019

Koenkk commented Jul 8, 2019

drbios commented Jul 9, 2019

drbios commented Jul 14, 2019

Koenkk commented Jul 14, 2019

drbios commented Jul 14, 2019

Koenkk commented Jul 14, 2019

drbios commented Jul 14, 2019

dzungpv commented Jul 17, 2019

Koenkk commented Jul 18, 2019

dzungpv commented Jul 19, 2019

Koenkk commented Jul 20, 2019

arjanvroege commented Aug 4, 2019

Koenkk commented Aug 5, 2019

DrMucki commented Sep 30, 2019

Koenkk commented Oct 1, 2019

stale bot commented Nov 30, 2019

drbios commented Jul 1, 2019 •

edited

Loading

drbios commented Jul 3, 2019 •

edited

Loading

drbios commented Jul 7, 2019 •

edited

Loading

Koenkk commented Jul 8, 2019 •

edited

Loading