search

Koenkk / zigbee2mqtt

Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨
https://www.zigbee2mqtt.io
GNU General Public License v3.0
11.76k stars 1.64k forks source link

zigbee-shepherd does not start up #937

Closed Ulli2k closed 5 years ago

Ulli2k commented 5 years ago

I try to get zigbee2mqtt running on a nuc with docker. (I flashed the lastest firmware " CC2531ZNP-Prod_20181024.zip") I already tried different usb ports and finally I used the latest-dev version and got the following error ` Using '/app/data' as data directory, ,

zigbee2mqtt@1.0.1 start /app, node index.js, , zigbee2mqtt:info 2019-1-25 20:30:29 Logging to directory: '/app/data/log/2019-01-25.20-30-29', zigbee2mqtt:info 2019-1-25 20:30:29 Starting zigbee2mqtt version 1.0.1 (commit #5718cd0), zigbee2mqtt:info 2019-1-25 20:30:29 Starting zigbee-shepherd, zigbee2mqtt:info 2019-1-25 20:30:37 Error while starting zigbee-shepherd, attemping to fix... (takes 60 seconds), /app/node_modules/q/q.js:155, throw e;, ^, , TypeError: Cannot read property 'close' of undefined, at shepherd.start (/app/lib/zigbee.js:45:47), at /app/node_modules/q/q.js:2059:17, at runSingle (/app/node_modules/q/q.js:137:13), at flush (/app/node_modules/q/q.js:125:13), at _combinedTickCallback (internal/process/next_tick.js:132:7), at process._tickCallback (internal/process/next_tick.js:181:9), Using '/app/data' as data directory, , zigbee2mqtt@1.0.1 start /app, node index.js, , zigbee2mqtt:info 2019-1-25 20:32:30 Logging to directory: '/app/data/log/2019-01-25.20-32-30', zigbee2mqtt:info 2019-1-25 20:32:30 Starting zigbee2mqtt version 1.0.1 (commit #5718cd0), zigbee2mqtt:info 2019-1-25 20:32:30 Starting zigbee-shepherd, zigbee2mqtt:info 2019-1-25 20:32:43 Error while starting zigbee-shepherd, attemping to fix... (takes 60 seconds), /app/node_modules/q/q.js:155, throw e;, ^, , TypeError: Cannot read property 'close' of undefined, at shepherd.start (/app/lib/zigbee.js:45:47), at /app/node_modules/q/q.js:2059:17, at runSingle (/app/node_modules/q/q.js:137:13), at flush (/app/node_modules/q/q.js:125:13), at _combinedTickCallback (internal/process/next_tick.js:132:7), at process._tickCallback (internal/process/next_tick.js:181:9), npm ERR! code ELIFECYCLE, npm ERR! errno 1, npm ERR! zigbee2mqtt@1.0.1 start: node index.js, npm ERR! Exit status 1, `

Ulli2k commented 5 years ago

by the way: unplug the stick, reconnect and push the reset button does not work

lennartbecker commented 5 years ago

I have the same problem. Tried reflashing the stick and reinstalling zigbee2mqtt. If I exit the process right after the error message it says "Not connected to MQTT Server", maybe we did something wrong there?

Koenkk commented 5 years ago

What is your setup? hardware/os, etc.

lennartbecker commented 5 years ago

Running a cc2531 stick with the latest Firmware linked in the documentation. Tried it on a raspberry pi and on my Ubuntu 18.10 laptop and have the same error message on both. It worked very shortly once.

Koenkk commented 5 years ago

@Ulli2k does the green light also turn off when you press the reset button?

@lennartbecker can you post your log?

directman66 commented 5 years ago

Similar problem, ubuntu 18.04 and сс2531

pi@ubuntumd:~$ node --version
v10.15.0
pi@ubuntumd:~$ npm --version
6.4.1
pi@ubuntumd:~$ ls -l /dev/serial/by-id
итого 0
lrwxrwxrwx 1 root root 13 янв 29 00:06 usb-0658_0200_12345678-9012-3456-7890-123456789012-if00 -> ../../ttyACM0
lrwxrwxrwx 1 root root 13 янв 29 00:06 usb-Texas_Instruments_TI_CC2531_USB_CDC___0X00124B000E8967DA-if00 -> ../../ttyACM1
2019-1-29 00:37:12 - info: Logging to directory: '/opt/zigbee2mqtt/data/log/2019-01-29.00-37-11'
2019-1-29 00:37:12 - debug: Removing old log directory '/opt/zigbee2mqtt/data/log/2019-01-29.00-36-24'
2019-1-29 00:37:12 - debug: Using zigbee-shepherd with settings: '{"net":{"panId":6754,"channelList":[11],"precfgkey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]},"dbPath":"/opt/zigbee2mqtt/data/database.db","sp":{"baudRate":115200,"rtscts":true}}'
2019-1-29 00:37:12 - debug: Can't load state from file /opt/zigbee2mqtt/data/state.json (doesn't exsist)
2019-1-29 00:37:12 - info: Starting zigbee2mqtt version 1.0.1 (commit #16f3e88)
2019-1-29 00:37:12 - info: Starting zigbee-shepherd
2019-1-29 00:37:15 - info: Error while starting zigbee-shepherd, attemping to fix... (takes 60 seconds)]

Run manual:

pi@ubuntumd:/opt/zigbee2mqtt$ npm start

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

  zigbee2mqtt:info 2019-1-29 00:45:16 Logging to directory: '/opt/zigbee2mqtt/data/log/2019-01-29.00-45-16'
  zigbee2mqtt:debug 2019-1-29 00:45:16 Removing old log directory '/opt/zigbee2mqtt/data/log/2019-01-29.00-43-34'
  zigbee2mqtt:debug 2019-1-29 00:45:17 Using zigbee-shepherd with settings: '{"net":{"panId":6754,"channelList":[11],"precfgkey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]},"dbPath":"/opt/zigbee2mqtt/data/database.db","sp":{"baudRate":115200,"rtscts":true}}'
  zigbee2mqtt:debug 2019-1-29 00:45:17 Can't load state from file /opt/zigbee2mqtt/data/state.json (doesn't exsist)
  zigbee2mqtt:info 2019-1-29 00:45:17 Starting zigbee2mqtt version 1.0.1 (commit #16f3e88)
  zigbee2mqtt:info 2019-1-29 00:45:17 Starting zigbee-shepherd
  zigbee2mqtt:info 2019-1-29 00:45:20 Error while starting zigbee-shepherd, attemping to fix... (takes 60 seconds)
/opt/zigbee2mqtt/node_modules/q/q.js:155
                throw e;
                ^

TypeError: Cannot read property 'close' of undefined
    at shepherd.start (/opt/zigbee2mqtt/lib/zigbee.js:45:47)
    at /opt/zigbee2mqtt/node_modules/q/q.js:2059:17
    at runSingle (/opt/zigbee2mqtt/node_modules/q/q.js:137:13)
    at flush (/opt/zigbee2mqtt/node_modules/q/q.js:125:13)
    at process._tickCallback (internal/process/next_tick.js:61:11)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! zigbee2mqtt@1.0.1 start: `node index.js`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the zigbee2mqtt@1.0.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-01-28T19_45_20_445Z-debug.log
pi@ubuntumd:/opt/zigbee2mqtt$

configuration.yaml:

homeassistant: false
permit_join: true
advanced:
#  channel: 26
  log_level: debug
mqtt:
  base_topic: zigbee2mqtt
  server: 'mqtt://192.168.1.39'
serial:
  port: /dev/ttyACM1

Such a problem occurs quite often, it helps to flashing the stick, removing the entire project and installing zigbee2mqtt from scratch. And it works for about a week and then the situation repeats. Developers branch needed to support xiaomi light bulbs

Pressing the cc2531 button causes the red LED to light up and solves the startup problem. But this solution requires periodically removing the stick and pressing the button, which can sometimes be very difficult.

subzero79 commented 5 years ago

Same error, master branch

DEBUG=zigbee-shepherd* node index.js
  zigbee2mqtt:info 2019-1-30 00:03:34 Logging to directory: '/home/ricardo/Documents/develop/zigbee2mqtt/data/log/2019-01-30.00-03-34'
  zigbee2mqtt:debug 2019-1-30 00:03:34 Using zigbee-shepherd with settings: '{"net":{"panId":6754,"channelList":[11]},"dbPath":"/home/ricardo/Documents/develop/zigbee2mqtt/data/database.db","sp":{"baudRate":115200,"rtscts":true}}'
  zigbee2mqtt:debug 2019-1-30 00:03:34 Loaded state from file /home/ricardo/Documents/develop/zigbee2mqtt/data/state.json
  zigbee2mqtt:info 2019-1-30 00:03:34 Starting zigbee2mqtt version 1.0.1 (commit #b95dcd0)
  zigbee2mqtt:info 2019-1-30 00:03:34 Starting zigbee-shepherd
  zigbee-shepherd:init zigbee-shepherd booting... +0ms
  zigbee-shepherd:request REQ --> SYS:osalNvRead +5s
  zigbee-shepherd:request RSP <-- SYS:osalNvRead +3s
  zigbee-shepherd:init Coordinator initialize had an error: Error: request timeout
    at CcZnp.<anonymous> (/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:255:22)
    at Object.onceWrapper (events.js:315:30)
    at emitOne (events.js:116:13)
    at CcZnp.emit (events.js:211:7)
    at Timeout.<anonymous> (/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:234:18)
    at ontimeout (timers.js:498:11)
    at tryOnTimeout (timers.js:323:5)
    at Timer.listOnTimeout (timers.js:290:5) +5ms
  zigbee2mqtt:info 2019-1-30 00:03:42 Error while starting zigbee-shepherd, attemping to fix... (takes 60 seconds)
  zigbee2mqtt:info 2019-1-30 00:04:42 Starting zigbee-shepherd
  zigbee-shepherd:init zigbee-shepherd booting... +1m
  zigbee-shepherd:request REQ --> SYS:osalNvRead +5s
  zigbee-shepherd:request RSP <-- SYS:osalNvRead +3s
  zigbee-shepherd:init Coordinator initialize had an error: Error: request timeout
    at CcZnp.<anonymous> (/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:255:22)
    at Object.onceWrapper (events.js:315:30)
    at emitOne (events.js:116:13)
    at CcZnp.emit (events.js:211:7)
    at Timeout.<anonymous> (/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:234:18)
    at ontimeout (timers.js:498:11)
    at tryOnTimeout (timers.js:323:5)
    at Timer.listOnTimeout (timers.js:290:5) +1ms
  zigbee2mqtt:error 2019-1-30 00:04:51 Error while starting zigbee-shepherd!
  zigbee2mqtt:error 2019-1-30 00:04:51 Press the reset button on the stick (the one closest to the USB) and start again
  zigbee2mqtt:error 2019-1-30 00:04:51 Failed to start
    {"message":"request timeout","stack":"Error: request timeout\n    at CcZnp.<anonymous> (/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:255:22)\n    at Object.onceWrapper (events.js:315:30)\n    at emitOne (events.js:116:13)\n    at CcZnp.emit (events.js:211:7)\n    at Timeout.<anonymous> (/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:234:18)\n    at ontimeout (timers.js:498:11)\n    at tryOnTimeout (timers.js:323:5)\n    at Timer.listOnTimeout (timers.js:290:5)"}
^C  zigbee2mqtt:debug 2019-1-30 00:05:05 Saving state to file /home/ricardo/Documents/develop/zigbee2mqtt/data/state.json
  zigbee2mqtt:error 2019-1-30 00:05:05 Not connected to MQTT server!
  zigbee2mqtt:error 2019-1-30 00:05:05 Cannot send message: topic: 'zigbee2mqtt/bridge/state', payload: 'offline
  zigbee-shepherd zigbee-shepherd is stopping. +15s
  zigbee-shepherd zigbee-shepherd is stopped. +1ms
  zigbee2mqtt:info 2019-1-30 00:05:05 zigbee-shepherd stopped

dev branch

 DEBUG=zigbee-shepherd* node index.js
  zigbee2mqtt:info 2019-1-30 00:08:01 Logging to directory: '/home/ricardo/Documents/develop/zigbee2mqtt/data/log/2019-01-30.00-08-01'
  zigbee2mqtt:debug 2019-1-30 00:08:01 Using zigbee-shepherd with settings: '{"net":{"panId":6754,"channelList":[11],"precfgkey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]},"dbPath":"/home/ricardo/Documents/develop/zigbee2mqtt/data/database.db","sp":{"baudRate":115200,"rtscts":true}}'
  zigbee2mqtt:debug 2019-1-30 00:08:01 Loaded state from file /home/ricardo/Documents/develop/zigbee2mqtt/data/state.json
  zigbee2mqtt:info 2019-1-30 00:08:01 Starting zigbee2mqtt version 1.0.1 (commit #fd93292)
  zigbee2mqtt:info 2019-1-30 00:08:01 Starting zigbee-shepherd
  zigbee-shepherd:init zigbee-shepherd booting... +0ms
  zigbee-shepherd:request REQ --> SYS:osalNvRead +0ms
  zigbee-shepherd:request RSP <-- SYS:osalNvRead +3s
  zigbee-shepherd:init Coordinator initialize had an error: Error: request timeout
    at CcZnp.<anonymous> (/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:255:22)
    at Object.onceWrapper (events.js:315:30)
    at emitOne (events.js:116:13)
    at CcZnp.emit (events.js:211:7)
    at Timeout.<anonymous> (/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/cc-znp/lib/ccznp.js:234:18)
    at ontimeout (timers.js:498:11)
    at tryOnTimeout (timers.js:323:5)
    at Timer.listOnTimeout (timers.js:290:5) +0ms
  zigbee2mqtt:info 2019-1-30 00:08:10 Error while starting zigbee-shepherd, attemping to fix... (takes 60 seconds)
/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/q/q.js:155
                throw e;
                ^

TypeError: Cannot read property 'close' of undefined
    at shepherd.start (/home/ricardo/Documents/develop/zigbee2mqtt/lib/zigbee.js:45:47)
    at /home/ricardo/Documents/develop/zigbee2mqtt/node_modules/q/q.js:2059:17
    at runSingle (/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/q/q.js:137:13)
    at flush (/home/ricardo/Documents/develop/zigbee2mqtt/node_modules/q/q.js:125:13)
    at _combinedTickCallback (internal/process/next_tick.js:131:7)
    at process._tickCallback (internal/process/next_tick.js:180:9

I use to reboot the machine to make it work sometime, but that doesn't even work now. Everybody is using the latest fw with group support?

subzero79 commented 5 years ago

I can see in the host dmesg

[ 3477.635917] cdc_acm 3-1:1.0: failed to set dtr/rts

changing the adv setting false to true or vice versa doesn't make a change

directman66 commented 5 years ago

Temporarily for tests, I registered in the config software a stick reset

advanced:
  log_level: debug
  soft_reset_timeout: 3600
Koenkk commented 5 years ago

@subzero79 what coordinator device do you use?

subzero79 commented 5 years ago

I use the cc2531 naked usb dongle.

Koenkk commented 5 years ago

Can you check if this has been fixed in the latest dev branch? Should be fixed by https://github.com/Koenkk/zigbee2mqtt/commit/30823a5a0cedc5989bf2a689a46ff73e03512f5a

waldher commented 5 years ago

Switching to the dev branch and running npm install fixed the issue for me, revealing that the root cause of my issue was the user I was running this as didn't have permission to access /dev/ttyACM1

lennartbecker commented 5 years ago

Switching to the dev branch and running npm install fixed the issue for me, revealing that the root cause of my issue was the user I was running this as didn't have permission to access /dev/ttyACM1

What Permissions did you change? I tried searching and trying some out but it still does not work.

waldher commented 5 years ago

@lennartbecker The user that you run zigbee2mqtt as needs read/write permission for this device. You can test by running: test -w /dev/ttyACM0 && echo success || echo failure I just ran chown testuser /dev/ttyACM0 where testuser was the user I was running zigbee2mqtt as.

lennartbecker commented 5 years ago

@lennartbecker The user that you run zigbee2mqtt as needs read/write permission for this device. You can test by running: test -w /dev/ttyACM0 && echo success || echo failure I just ran chown testuser /dev/ttyACM0 where testuser was the user I was running zigbee2mqtt as.

Thank you, it told me "success", seems like I have a different problem now :D Something with a request timeout.

Koenkk commented 5 years ago

This issue should be fixed in zigbee2mqtt 1.1.1, can anybody confirm?

djchen commented 5 years ago

I can confirm 1.1.1 fixes the issue for me.

sultanakaneel commented 5 years ago

i have the same problem, however I can't upgrade since I don't have a debugger, any other fixes?

Koenkk commented 5 years ago

@sultanakaneel you dont need the debugger to update zigbee2mqtt

sultanakaneel commented 5 years ago

@sultanakaneel you dont need the debugger to update zigbee2mqtt

I must be retarded, but how would I update through hassio?

Koenkk commented 5 years ago

@sultanakaneel 1.1.1 isn't available yet. You can use edge for now (but keep in mind this is a development branch). As soon as 1.1.1 for hassio is available switch to 1.1.1.

sultanakaneel commented 5 years ago

@sultanakaneel 1.1.1 isn't available yet. You can use edge for now (but keep in mind this is a development branch). As soon as 1.1.1 for hassio is available switch to 1.1.1.

ah alright, the edge version somehow grinds my pi to a halt so guess I'll just have to wait for a while

mgsb commented 5 years ago

I got 1.1.1 via hassio and I still have this failure. I did a full reboot of hassio.

zigbee2mqtt:info 2019-2-3 09:29:11 Zigbee: allowing new devices to join. zigbee2mqtt:info 2019-2-3 09:29:11 Connecting to MQTT server at mqtt://homeassistant /zigbee2mqtt-1.1.1/node_modules/q/q.js:155 throw e; ^ TypeError: Cannot read property 'zigbeeModel' of undefined at devices.forEach (/zigbee2mqtt-1.1.1/lib/extension/coordinatorGroup.js:24:34) at Array.forEach () at zigbee.getAllClients.forEach (/zigbee2mqtt-1.1.1/lib/extension/coordinatorGroup.js:23:21) at Array.forEach () at CoordinatorGroup.onZigbeeStarted (/zigbee2mqtt-1.1.1/lib/extension/coordinatorGroup.js:22:37) at extensions.filter.forEach (/zigbee2mqtt-1.1.1/lib/controller.js:98:75) at Array.forEach () at Controller.onZigbeeStarted (/zigbee2mqtt-1.1.1/lib/controller.js:98:58) at zigbee.start (/zigbee2mqtt-1.1.1/lib/controller.js:149:26) at shepherd.start (/zigbee2mqtt-1.1.1/lib/zigbee.js:64:17) npm

Koenkk commented 5 years ago

@mgsb do you use a custom devices.js?

mgsb commented 5 years ago

Yes. I have an added GE light switch defined in it since it was not in the shepherd list.

Koenkk commented 5 years ago

@mgsb can you try without? Perhaps your devices.js is not compatible anymore. It would be the best if you make a PR so this device is natively supported by zigbee2mqtt.

mgsb commented 5 years ago

Thanks - that worked. I got the latest devices.js and replaced my "custom" version. You had merged the GE switch earlier. Other devices are working, but not the GE switch. The switch is recognized now but when I try to turn it on via HA, I get an error:

zigbee2mqtt:info 2019-2-3 10:11:18 Zigbee publish to device '0x0022a300001c942f', genOnOff - on - {} - {"manufSpec":0,"disDefaultRsp":0} - null zigbee2mqtt:info 2019-2-3 10:11:18 MQTT publish: topic 'zigbee2mqtt/0x0022a300001c942f', payload '{"state":"ON","linkquality":0,"power":0}' /zigbee2mqtt-1.1.1/lib/extension/deviceReceive.js:71 return c.cid === cid && c.type === message.type; ^ TypeError: Cannot read property 'cid' of undefined at mappedDevice.fromZigbee.filter (/zigbee2mqtt-1.1.1/lib/extension/deviceReceive.js:71:26) at Array.filter () at DeviceReceive.onZigbeeMessage (/zigbee2mqtt-1.1.1/lib/extension/deviceReceive.js:69:52) at extensions.filter.forEach (/zigbee2mqtt-1.1.1/lib/controller.js:125:31) at Array.forEach () at Controller.onZigbeeMessage (/zigbee2mqtt-1.1.1/lib/controller.js:125:14) at Zigbee.onMessage (/zigbee2mqtt-1.1.1/lib/zigbee.js:179:18) at emitOne (events.js:116:13) at ZShepherd.emit (events.js:211:7) at ZShepherd. (/zigbee2mqtt-1.1.1/node_modules/zigbee-shepherd/lib/shepherd.js:158:14)

mgsb commented 5 years ago

It's odd that "On" works but "Off" fails. Not sure why the mapping fails for "Off". This is not related to the original issue, so if you prefer, I can take this a different issue.

zigbee2mqtt:info 2019-2-3 10:26:12 Zigbee publish to device '0x0022a300001c942f', genOnOff - on - {} - {"manufSpec":0,"disDefaultRsp":0} - null zigbee2mqtt:info 2019-2-3 10:26:13 MQTT publish: topic 'zigbee2mqtt/0x0022a300001c942f', payload '{"state":"ON","linkquality":0,"power":0}' zigbee2mqtt:info 2019-2-3 10:26:43 Zigbee publish to device '0x0022a300001c942f', genOnOff - off - {} - {"manufSpec":0,"disDefaultRsp":0} - null zigbee2mqtt:info 2019-2-3 10:26:43 MQTT publish: topic 'zigbee2mqtt/0x0022a300001c942f', payload '{"state":"OFF","linkquality":0,"power":0}' /zigbee2mqtt-1.1.1/lib/extension/deviceReceive.js:71 return c.cid === cid && c.type === message.type; ^

Koenkk commented 5 years ago

@mgsb can you try without using a custom devices.js?

mgsb commented 5 years ago

Ok, I deleted devices.js and now it works after a restart.

chrisrock1984 commented 5 years ago

hi i am having problems running on latest zigbee2mqtt. resetting, restarting and reinstalling did not help this is the log

2019-2-9 21:02:34 - info: Logging to directory: '/share/zigbee2mqtt/log/2019-02-09.21-02-34' 2019-2-9 21:02:36 - info: Starting zigbee2mqtt version 1.1.1 (commit #unknown) 2019-2-9 21:02:36 - info: Starting zigbee-shepherd 2019-2-9 21:02:44 - info: Error while starting zigbee-shepherd, attemping to fix... (takes 60 seconds) 2019-2-9 21:03:44 - info: Starting zigbee-shepherd 2019-2-9 21:03:52 - error: Error while starting zigbee-shepherd! 2019-2-9 21:03:52 - error: Press the reset button on the stick (the one closest to the USB) and start again 2019-2-9 21:03:52 - error: Failed to start Error: request timeout at CcZnp. (/zigbee2mqtt-1.1.1/node_modules/cc-znp/lib/ccznp.js:255:22) at Object.onceWrapper (events.js:315:30) at emitOne (events.js:116:13) at CcZnp.emit (events.js:211:7) at Timeout. (/zigbee2mqtt-1.1.1/node_modules/cc-znp/lib/ccznp.js:234:18) at ontimeout (timers.js:498:11) at tryOnTimeout (timers.js:323:5) at Timer.listOnTimeout (timers.js:290:5)

mschmidt29 commented 5 years ago

I got 1.1.1 via hassio and I still have this failure, too. where can I find the devices.js in hass.io installation?

Koenkk commented 5 years ago

@chrisrock1984 @mschmidt29

Also try to:

chrisrock1984 commented 5 years ago

thank you for your help: It worked for almost a year before, but after the latest updated it stopped. I am using a Rock64 running hassio in a docker container. The last config I used was the standard when installing zigbee2mqtt. I also checked the correct com port, "ACM1" in my case. What I tried so far is:

So, what have I missed in the standard procedure of searching for errors? ;-)

Koenkk commented 5 years ago

@chrisrock1984 when downgrading, does it work again?

chrisrock1984 commented 5 years ago

@Koenkk what is the easiest way to downgrade an hassio add-on? i have never done a downgrade. sorry for asking....

Koenkk commented 5 years ago

@danielwelch is there any way to downgrade addons with hassio?

chrisrock1984 commented 5 years ago

@Koenkk i will try it with snapshots - will let you know if it works and which version it was

chrisrock1984 commented 5 years ago

still, downgrading (full whipe) does not work. it seems that it still runs 1.1.1

Log [Info] Configuration file found: /share/zigbee2mqtt/configuration.yaml [Info] Configuration written to /share/zigbee2mqtt/configuration.yaml 2019-02-11T16:16:32: PM2 log: Launching in no daemon mode 2019-02-11T16:16:33: PM2 log: App [npm:0] starting in -fork mode- 2019-02-11T16:16:33: PM2 log: App [npm:0] online

zigbee2mqtt@1.1.1 start /zigbee2mqtt-1.1.1 node index.js zigbee2mqtt:info 2019-2-11 16:16:39 Logging to directory: '/share/zigbee2mqtt/log/2019-02-11.16-16-38' zigbee2mqtt:info 2019-2-11 16:16:40 Starting zigbee2mqtt version 1.1.1 (commit #unknown) zigbee2mqtt:info 2019-2-11 16:16:40 Starting zigbee-shepherd zigbee2mqtt:info 2019-2-11 16:16:49 Error while starting zigbee-shepherd, attemping to fix... (takes 60 seconds) zigbee2mqtt:info 2019-2-11 16:17:49 Starting zigbee-shepherd zigbee2mqtt:error 2019-2-11 16:17:57 Error while starting zigbee-shepherd! zigbee2mqtt:error 2019-2-11 16:17:57 Press the reset button on the stick (the one closest to the USB) and start again zigbee2mqtt:error 2019-2-11 16:17:57 Failed to start {"message":"request timeout","stack":"Error: request timeout\n at CcZnp. (/zigbee2mqtt-1.1.1/node_modules/cc-znp/lib/ccznp.js:255:22)\n at Object.onceWrapper (events.js:315:30)\n at emitOne (events.js:116:13)\n at CcZnp.emit (events.js:211:7)\n at Timeout. (/zigbee2mqtt-1.1.1/node_modules/cc-znp/lib/ccznp.js:234:18)\n at ontimeout (timers.js:498:11)\n at tryOnTimeout (timers.js:323:5)\n at Timer.listOnTimeout (timers.js:290:5)"}

Koenkk commented 5 years ago

@chrisrock1984 you are having the same issue as in #1067. What is the output of ls -l /dev/serial/by-id/?

hanzoh commented 5 years ago

Hi Koen, I have the exact same issue.

My environment:

I set everything up 4 days ago with 1.1.1, except for the TRADFRI remote, which I did not get to work, so I switched to latest-dev for that and after that worked, I switched back to 1.1.1. Everything ran fine for the last 4 days. Today, I had to reboot the server because of a network issue, the configuration did not change. No I always get Error while starting zigbee-shepherd, attemping to fix... (takes 60 seconds), no matter what I try:

I use a udev rule to give the CC2531 a unique id (/dev/zigbee), this works fine since years with the Home Assistant Docker image and my Z-Wave stick (/dev/zwave). I have also tried to map /dev/ttyACM1 directly, or via /dev/serial/by-id/usb-Texas_Instruments...

I have not yet reflashed the stick yet, but I really want to avoid that as pairing all devices again (which are hidden under the kitchen) would be a real pain.

Let me know if I can provide or test anything else

chrisrock1984 commented 5 years ago

@Koenkk : it gives me ->

rock64@rock64:~$ ls -l /dev/serial/by-id/ total 0 lrwxrwxrwx 1 root root 13 Feb 11 15:27 usb-0658_0200-if00 -> ../../ttyACM0 lrwxrwxrwx 1 root root 13 Feb 11 15:27 usb-Texas_Instruments_TI_CC2531_USB_CDC___0X9C1D58897D43FFFF-if00 -> ../../ttyACM1

Koenkk commented 5 years ago

Can you all check with the latest dev branch? (-edge for hassio, should be available within an hour).

sander816 commented 5 years ago

i assume i can use the update instrctions from the documentation for that?

for me its running again for now:

`pi@rpi3:/opt/zigbee2mqtt/data$ npm start

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

  zigbee2mqtt:info 2/12/2019, 8:06:42 PM Logging to directory: '/opt/zigbee2mqtt/data/log/2019-02-12.20-06-42'
  zigbee2mqtt:info 2/12/2019, 8:06:43 PM Starting zigbee2mqtt version 1.1.1 (commit #d9ddce5)
  zigbee2mqtt:info 2/12/2019, 8:06:43 PM Starting zigbee-shepherd
  zigbee2mqtt:info 2/12/2019, 8:06:45 PM zigbee-shepherd started
  zigbee2mqtt:info 2/12/2019, 8:06:45 PM Coordinator firmware version: '20181119'
  zigbee2mqtt:info 2/12/2019, 8:06:45 PM Currently 7 devices are joined:
  zigbee2mqtt:info 2/12/2019, 8:06:45 PM 0x00158d00029bff93 (0x00158d00029bff93): RTCGQ11LM - Xiaomi Aqara human body movement and illuminance sensor (EndDevice)
  zigbee2mqtt:info 2/12/2019, 8:06:45 PM 0x00158d000252a53d (0x00158d000252a53d): MCCGQ11LM - Xiaomi Aqara door & window contact sensor (EndDevice)
  zigbee2mqtt:info 2/12/2019, 8:06:45 PM 0x00158d000278e797 (0x00158d000278e797): MFKZQ01LM - Xiaomi Mi/Aqara smart home cube (EndDevice)
  zigbee2mqtt:info 2/12/2019, 8:06:45 PM 0x00158d00028b6b2f (0x00158d00028b6b2f): MCCGQ01LM - Xiaomi MiJia door & window contact sensor (EndDevice)
  zigbee2mqtt:info 2/12/2019, 8:06:45 PM 0x00158d000268d9e6 (0x00158d000268d9e6): ZNCZ02LM - Xiaomi Mi power plug ZigBee (Router)
  zigbee2mqtt:info 2/12/2019, 8:06:45 PM 0xd0cf5efffeebda06 (0xd0cf5efffeebda06): 404000/404005/404012 - Müller Licht Tint LED bulb GU10/E14/E27 350/470/806 lumen, dimmable, color, opal white (Router)
  zigbee2mqtt:info 2/12/2019, 8:06:45 PM 0xd0cf5efffef919e6 (0xd0cf5efffef919e6): 404000/404005/404012 - Müller Licht Tint LED bulb GU10/E14/E27 350/470/806 lumen, dimmable, color, opal white (Router)

`

mschmidt29 commented 5 years ago

@Koenkk

{
  "data_path": "/share/zigbee2mqtt",
  "homeassistant": true,
  "permit_join": false,
  "mqtt_base_topic": "zigbee2mqtt",
  "mqtt_server": "mqtt://192.168.178.41",
  "serial_port": "/dev/ttyACM0",
  "devices": [],
  "network_key": [],
  "mqtt_user": "mqttuser",
  "mqtt_pass": "kennwort"
}

core-ssh:~# ls /dev
fd       mqueue   pts      stderr   tty      urandom
full     null     random   stdin    ttyACM0  zero
init     ptmx     shm      stdout   ttyAMA0

Also try to:

` [Info] Configuration file found: /share/zigbee2mqtt/configuration.yaml Traceback (most recent call last): File "set_config.py", line 159, in main(args.options_path, args.data_path) File "set_config.py", line 106, in main cfg.set_option('homeassistant') File "set_config.py", line 16, in set_option if self.get_config(name, category) is not None: File "set_config.py", line 39, in get_config return self.config.get(config_name, None) AttributeError: 'NoneType' object has no attribute 'get' 2019-02-12T20:10:08: PM2 log: Launching in no daemon mode 2019-02-12T20:10:08: PM2 log: App [npm:0] starting in -fork mode- 2019-02-12T20:10:08: PM2 log: App [npm:0] online

zigbee2mqtt@1.1.1 start /zigbee2mqtt-1.1.1 node index.js zigbee2mqtt:info 2019-2-12 20:10:13 Logging to directory: '/share/zigbee2mqtt/log/2019-02-12.20-10-12' zigbee2mqtt:info 2019-2-12 20:10:14 Starting zigbee2mqtt version 1.1.1 (commit #unknown) zigbee2mqtt:info 2019-2-12 20:10:14 Starting zigbee-shepherd /zigbee2mqtt-1.1.1/lib/zigbee.js:40 this.shepherd = new ZShepherd(settings.get().serial.port, shepherdSettings); ^ TypeError: Cannot read property 'port' of undefined at Zigbee.start (/zigbee2mqtt-1.1.1/lib/zigbee.js:40:60) at startupLogVersion (/zigbee2mqtt-1.1.1/lib/controller.js:145:25) at git.getLastCommit (/zigbee2mqtt-1.1.1/lib/controller.js:185:13) at /zigbee2mqtt-1.1.1/node_modules/git-last-commit/source/index.js:44:5 at /zigbee2mqtt-1.1.1/node_modules/git-last-commit/source/index.js:14:4 at ChildProcess.exithandler (child_process.js:283:5) at emitTwo (events.js:126:13) at ChildProcess.emit (events.js:214:7) at maybeClose (internal/child_process.js:915:16) at Socket.stream.socket.on (internal/child_process.js:336:11) npm ERR! code ELIFECYCLE npm ERR! errno 1 npm ERR! zigbee2mqtt@1.1.1 start: node index.js npm ERR! Exit status 1 npm ERR! npm ERR! Failed at the zigbee2mqtt@1.1.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! /root/.npm/_logs/2019-02-12T19_10_14_974Z-debug.log 2019-02-12T20:10:15: PM2 log: App [npm:0] exited with code [1] via signal [SIGINT] 2019-02-12T20:10:15: PM2 log: App [npm:0] starting in -fork mode- 2019-02-12T20:10:15: PM2 log: App [npm:0] online zigbee2mqtt@1.1.1 start /zigbee2mqtt-1.1.1 node index.js zigbee2mqtt:info 2019-2-12 20:10:19 Logging to directory: '/share/zigbee2mqtt/log/2019-02-12.20-10-19' zigbee2mqtt:info 2019-2-12 20:10:21 Starting zigbee2mqtt version 1.1.1 (commit #unknown) zigbee2mqtt:info 2019-2-12 20:10:21 Starting zigbee-shepherd /zigbee2mqtt-1.1.1/lib/zigbee.js:40 this.shepherd = new ZShepherd(settings.get().serial.port, shepherdSettings); ^ TypeError: Cannot read property 'port' of undefined at Zigbee.start (/zigbee2mqtt-1.1.1/lib/zigbee.js:40:60) at startupLogVersion (/zigbee2mqtt-1.1.1/lib/controller.js:145:25) at git.getLastCommit (/zigbee2mqtt-1.1.1/lib/controller.js:185:13) at /zigbee2mqtt-1.1.1/node_modules/git-last-commit/source/index.js:44:5 at /zigbee2mqtt-1.1.1/node_modules/git-last-commit/source/index.js:14:4 at ChildProcess.exithandler (child_process.js:283:5) at emitTwo (events.js:126:13) at ChildProcess.emit (events.js:214:7) at maybeClose (internal/child_process.js:915:16) at Socket.stream.socket.on (internal/child_process.js:336:11) npm ERR! code ELIFECYCLE npm ERR! errno 1 npm ERR! zigbee2mqtt@1.1.1 start: node index.js npm ERR! Exit status 1 npm ERR! npm ERR! Failed at the zigbee2mqtt@1.1.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! /root/.npm/_logs/2019-02-12T19_10_21_149Z-debug.log 2019-02-12T20:10:21: PM2 log: App [npm:0] exited with code [1] via signal [SIGINT] 2019-02-12T20:10:21: PM2 log: App [npm:0] starting in -fork mode- 2019-02-12T20:10:21: PM2 log: App [npm:0] online zigbee2mqtt@1.1.1 start /zigbee2mqtt-1.1.1 node index.js `

hanzoh commented 5 years ago

For me, it is still the same. I get these errors in dmesg: cdc_acm 1-6:1.0: failed to set dtr/rts

And this is the complete log with DEBUG=* z2m.log

sander816 commented 5 years ago

never mind, resolved

Koenkk commented 5 years ago

For me, it is still the same. I get these errors in dmesg: cdc_acm 1-6:1.0: failed to set dtr/rts

And this is the complete log with DEBUG=* z2m.log

Does it work when not running on Docker (bare metal)?

update on my problem: zigbee2mqtt is running fine again, but, i am not able to add new devices.:

`  zigbee2mqtt:warn 2/13/2019, 8:38:46 AM `permit_join` set to  `true` in configuration.yaml.
  zigbee2mqtt:warn 2/13/2019, 8:38:46 AM Allowing new devices to join.
  zigbee2mqtt:warn 2/13/2019, 8:38:46 AM Set `permit_join` to `false` once you joined all devices.
  zigbee2mqtt:info 2/13/2019, 8:38:46 AM Zigbee: allowing new devices to join.
  zigbee2mqtt:info 2/13/2019, 8:38:46 AM Connecting to MQTT server at mqtt://localhost:1883
  zigbee2mqtt:info 2/13/2019, 8:38:47 AM zigbee-shepherd ready
  zigbee2mqtt:info 2/13/2019, 8:38:47 AM Connected to MQTT server
  zigbee2mqtt:info 2/13/2019, 8:38:47 AM MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'
  zigbee2mqtt:info 2/13/2019, 8:38:47 AM MQTT publish: topic 'zigbee2mqtt/0x00158d00029bff93', payload '{"illuminance":6,"linkquality":47,"occupancy":false,"battery":62,"voltage":2935}'
  zigbee2mqtt:info 2/13/2019, 8:38:47 AM MQTT publish: topic 'zigbee2mqtt/0x00158d000252a53d', payload '{"contact":true,"linkquality":5,"battery":86,"voltage":2975}'
  zigbee2mqtt:info 2/13/2019, 8:38:47 AM MQTT publish: topic 'zigbee2mqtt/0x00158d000278e797', payload '{"battery":100,"voltage":3005,"linkquality":23}'
  zigbee2mqtt:info 2/13/2019, 8:38:47 AM MQTT publish: topic 'zigbee2mqtt/0x00158d00028b6b2f', payload '{"contact":true,"linkquality":60,"battery":100,"voltage":3015}'
  zigbee2mqtt:info 2/13/2019, 8:38:47 AM MQTT publish: topic 'zigbee2mqtt/0x00158d000268d9e6', payload '{"state":"ON","power":92.97,"voltage":227.5,"consumption":2.45,"temperature":27,"linkquality":81}'
  zigbee2mqtt:info 2/13/2019, 8:38:49 AM MQTT publish: topic 'zigbee2mqtt/0x00158d00028b6b2f', payload '{"contact":true,"linkquality":63,"battery":100,"voltage":3015}'
  zigbee2mqtt:info 2/13/2019, 8:39:25 AM MQTT publish: topic 'zigbee2mqtt/0x00158d000278e797', payload '{"battery":100,"voltage":3005,"linkquality":36}'

adding a new device does nothing, on my mihome it works fine

Can you try unplugging your xiaomi hub while pairing? Having 2 zigbee networks can be problematic.

sander816 commented 5 years ago

pressing the reset button made it discovering new devices again