search

Koenkk / zigbee2mqtt

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

Error while starting zigbee-herdsman #2587

Closed kisseler closed 4 years ago

kisseler commented 4 years ago

Hey there, I'm facing a big problem: zigbee2mqtt seems to restart every few seconds. I was running without any issues by now z2m, openhab (2.4), just upgraded (flawlessly) to Texas Instruments CC1352P-2 to increase range. Now after pressing a wall switch, the system stopped working. The only "action" from z2m I see is, that it creates a new log folder every few seconds. Since it deletes old folders, I cannot read the logs from beginning of the problem. Restart, unplugging, updating (re-install) all does not help. Has anyone an idea, what's the problem here?

kisseler commented 4 years ago

My original problem changed after correcting my configuration (I hat a doulbe friendly name entry). But now I'm not able to get the service running again.

info  2019-12-21 23:56:08: Logging to console and directory: '/opt/zigbee2mqtt/data/log/2019-12-21.23-56-08'
debug 2019-12-21 23:56:08: Removing old log directory '/opt/zigbee2mqtt/data/log/2019-12-21.23-29-34'
debug 2019-12-21 23:56:08: Loaded state from file /opt/zigbee2mqtt/data/state.json
info  2019-12-21 23:56:08: Starting zigbee2mqtt version 1.8.0 (commit #da4d26a)
info  2019-12-21 23:56:08: Starting zigbee-herdsman...
debug 2019-12-21 23:56:08: Using zigbee-herdsman with settings: '{"network":{"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11],"networkKey":"HIDDEN"},"databasePath":"/opt/zigbee2mqtt/data/database.db","databaseBackupPath":"/opt/zigbee2mqtt/data/database.db.backup","backupPath":"/opt/zigbee2mqtt/data/coordinator_backup.json","serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/ttyACM0"}}'
error 2019-12-21 23:56:15: Failed to call 'DeviceEvent' 'stop' (TypeError: Cannot read property 'getEntries' of null
    at Function.loadFromDatabaseIfNecessary (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/model/device.js:133:55)
    at Function.all (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/model/device.js:153:16)
    at Controller.getDevices (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/controller/controller.js:208:31)
    at Zigbee.getClients (/opt/zigbee2mqtt/lib/zigbee.js:115:30)
    at DeviceEvent.stop (/opt/zigbee2mqtt/lib/extension/deviceEvent.js:18:42)
    at Controller.callExtensionMethod (/opt/zigbee2mqtt/lib/controller.js:322:44)
    at Controller.stop (/opt/zigbee2mqtt/lib/controller.js:148:20)
    at process.handleQuit (/opt/zigbee2mqtt/index.js:21:20)
    at process.emit (events.js:198:13))
debug 2019-12-21 23:56:15: Saving state to file /opt/zigbee2mqtt/data/state.json
error 2019-12-21 23:56:15: Not connected to MQTT server!
error 2019-12-21 23:56:15: Cannot send message: topic: 'zigbee/bridge/state', payload: 'offline
info  2019-12-21 23:56:15: Disconnecting from MQTT server
error 2019-12-21 23:57:10: Error while starting zigbee-herdsman
kisseler commented 4 years ago

DEBUG=zigbee-herdsman:controller* npm start delivers

> zigbee2mqtt@1.8.0-dev start /opt/zigbee2mqtt
> node index.js

zigbee2mqtt:info  2019-12-22 00:34:09: Logging to console and directory: '/opt/zigbee2mqtt/data/log/2019-12-22.00-34-09'
zigbee2mqtt:debug 2019-12-22 00:34:09: Removing old log directory '/opt/zigbee2mqtt/data/log/2019-12-22.00-11-06'
zigbee2mqtt:debug 2019-12-22 00:34:10: Loaded state from file /opt/zigbee2mqtt/data/state.json
zigbee2mqtt:info  2019-12-22 00:34:10: Starting zigbee2mqtt version 1.8.0-dev (commit #66b3bcb)
zigbee2mqtt:info  2019-12-22 00:34:10: Starting zigbee-herdsman...
zigbee2mqtt:debug 2019-12-22 00:34:10: Using zigbee-herdsman with settings: '{"network":{"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11],"networkKey":"HIDDEN"},"databasePath":"/opt/zigbee2mqtt/data/database.db","databaseBackupPath":"/opt/zigbee2mqtt/data/database.db.backup","backupPath":"/opt/zigbee2mqtt/data/coordinator_backup.json","serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/ttyACM0"}}'
  zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/ttyACM0"},"databasePath":"/opt/zigbee2mqtt/data/database.db","databaseBackupPath":"/opt/zigbee2mqtt/data/database.db.backup","backupPath":"/opt/zigbee2mqtt/data/coordinator_backup.json"}' +0ms
zigbee2mqtt:error 2019-12-22 00:35:11: Error while starting zigbee-herdsman
zigbee2mqtt:error 2019-12-22 00:35:11: Failed to start zigbee
zigbee2mqtt:error 2019-12-22 00:35:11: Exiting...
zigbee2mqtt:error 2019-12-22 00:35:11: Error: AREQ - ZDO - stateChangeInd after 60000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
    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)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! zigbee2mqtt@1.8.0-dev start: `node index.js`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the zigbee2mqtt@1.8.0-dev 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/openhabian/.npm/_logs/2019-12-21T23_35_11_911Z-debug.log

I also tried re-flashing my CC1352P-2 modul. No success.

kisseler commented 4 years ago

Re-Installing and not restoring original data folder leads back to my original problem: The only thing that happens is a recreation of the log folder every 2 seconds (now empty). I'm cunfused!

kisseler commented 4 years ago

Re-Flashing CC1352P-2 modul with erasing complete flash beforehand resolved my issue.

Does anyone have any idea, what could be the origin of the problem, so it can be avoided next time?

Kryzek commented 4 years ago

I also got this error after updating to latest 1.8.0-dev (commit #66b3bcb), I'm using CC2652R:

zigbee2mqtt:error 2019-12-22 09:01:30: Error while starting zigbee-herdsman
zigbee2mqtt:error 2019-12-22 09:01:30: Failed to start zigbee
zigbee2mqtt:error 2019-12-22 09:01:30: Exiting...
zigbee2mqtt:error 2019-12-22 09:01:30: Error: AREQ - ZDO - stateChangeInd after 60000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/dist/utils/waitress.js:44:24)
    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)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! zigbee2mqtt@1.8.0-dev start: `node index.js`
npm ERR! Exit status 1

I will also try re-flashing the board if that helped with you.

Kryzek commented 4 years ago

Flasher V2 did say something about "update board firmware" (other than Koenkk's firmware) and did not recognize board. After letting software do it's work re-flashing the board did the work.

kisseler commented 4 years ago

Now upgraded to 1.8.0-dev groups don't work and seem to cause errors/delays. @Koenkk recently extended group functionality. Maybe that has to do with my groups not working anymore? After re-installing und re-creating configuration a thousand times, does anyone know a way to clean up the database? And is there any cache to be deleted? (Restoring the data folder might cause orphan or deprecated entries.)

insensitiveclod commented 4 years ago

Having exactly this problem since hassio-zigbee2mqtt update in hassio. Will re-flash module today/tomorrow and report back.

tcherokee commented 4 years ago

Now upgraded to 1.8.0-dev groups don't work and seem to cause errors/delays. @Koenkk recently extended group functionality. Maybe that has to do with my groups not working anymore? After re-installing und re-creating configuration a thousand times, does anyone know a way to clean up the database? And is there any cache to be deleted? (Restoring the data folder might cause orphan or deprecated entries.)

So is it groups that causes this issue? My setup was working almost flawlessly but then I moved to 1.8.0-dev and set up groups... then overnight, I ran into the Error: AREQ - ZDO - stateChangeInd after 60000ms error. Since it seems a number of people are on the dev branch and are not running into this error, I am wondering if maybe groups caused it?

insensitiveclod commented 4 years ago

I am not sure if it is, but I did try the 'reflash the usb-stick' suggestion, and it solved my issues. I did not use any new/recent firmware , either; just one of the ones that were available from when I first flashed my stick and was still in the 'cc-tool' directory I made to compile the flash-tool.

I downloaded it on the 23rd of Oct, a3da8d933f435ee53c13f5eff3d6c559 CC2531ZNP-Prod.hex

Not sure what version of the firmware it was, either, but after flashing it, i could get the hassio-zigbee2mqtt package to start up without causing the above-mentioned failure. Not sure why/what/etc. For me, it was the error KRYZEK described, which is fixed/gone after a reflash of the stick

Kryzek commented 4 years ago

Last night Z2M died again (Devices did not work but software was running) and I cannot restart it. Getting zigbee2mqtt:error 2019-12-28 14:03:06: Error: SRSP - SYS - version after 6000ms error. Need to try reflashing again when I get back home.

Kryzek commented 4 years ago

After reflash it works again. What could be causing this? It worked before 1.8 for over than a month without problems.

dmenne commented 4 years ago

Same problem for me. Reflashing did not help. Using the latest-dev docker image now everything is fine.

Thanks a lot for your Christmas Support Work!!!

conphilpott commented 4 years ago

Same issue here with the CC26X2R1 but reflashing does not help and neither does running with zigbee2mqtt-edge.

stale[bot] commented 4 years ago

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.