Zigbee2mqtt: Moved from pi3 to pi4 - stopped working

Created on 4 Oct 2019  路  29Comments  路  Source: Koenkk/zigbee2mqtt

Bug Report

What happened

I moved my hassio installation from a pi3 to a pi4 - everything worked great only I realised that my zigbee devices were not responding. The only useful information that I find in the logs is:

zigbee2mqtt:error 2019-10-04T16:02:36: Failed to execute LQI for '0x0017880102be5dc8'
zigbee2mqtt:error 2019-10-04T16:02:36: Failed to execute LQI for 'Unterschraenke'

And it also complained about not finding an entity once. I see no reason why it shouldn't just work as before, but right now I am afraid I have to repair all of my devices... Any help would be highly appreciated.

Debug Info

zigbee2mqtt version: 1.6.0 (zigbee-edge on hassio)
CC2531 firmware version: 20190608

Most helpful comment

Found an extension, deactivated the scans and it works straight away! Thanks for the support <3

All 29 comments

I tried running non edge version and downgraded to 1.5.1

Now I get this error:

zigbee2mqtt:info 10/5/2019, 10:55:05 AM Starting zigbee2mqtt version 1.5.1 (commit #unknown)
  zigbee2mqtt:info 10/5/2019, 10:55:06 AM Starting zigbee-shepherd
  zigbee2mqtt:info 10/5/2019, 10:55:07 AM Error while starting zigbee-shepherd, attempting to fix... (takes 60 seconds) (TypeError: Spec attributes should be wrapped in an object.)
  zigbee2mqtt:info 10/5/2019, 10:56:07 AM Starting zigbee-shepherd
  zigbee2mqtt:error 10/5/2019, 10:56:14 AM Error while starting zigbee-shepherd! (Error: request timeout)
  zigbee2mqtt:error 10/5/2019, 10:56:14 AM Press the reset button on the stick (the one closest to the USB) and start again
  zigbee2mqtt:error 10/5/2019, 10:56:14 AM Failed to start
    {"message":"request timeout","stack":"Error: request timeout\n    at CcZnp.<anonymous> (/zigbee2mqtt-1.5.1/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> (/zigbee2mqtt-1.5.1/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 10/5/2019, 10:56:14 AM Exiting...
npm
 ERR!
 code ELIFECYCLE
npm ERR! errno 1
npm
 ERR! [email protected] start: `node index.js`
npm ERR! Exit status 1
npm ERR! 
npm
 ERR! Failed at the [email protected] 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-10-05T08_56_14_734Z-debug.log
2019-10-05T10:56:18: PM2 log: App [npm:0] exited with code [1] via signal [SIGINT]
2019-10-05T10:56:18: PM2 log: App [npm:0] starting in -fork mode-
2019-10-05T10:56:18: PM2 log: App [npm:0] online

I tried pushing the button but nothing happens (as I can recall correctly the light should turn off until it fixes itself). Replugging the stick and then pressing the button worked. I think I might have a problem with my stick? I am going to try and reflash, but I see no reason why it should stop working when switching devices.

Reflashed the stick, tried the edge-version again (as before), now zigbee2mqtt won't start at all:

./run.sh: line 16: [Info] Configuration backup found in /share/zigbee2mqtt/.configuration.yaml.bk. Skipping config backup.: No such file or directory
2019-10-05T11:12:06: PM2 log: Launching in no daemon mode
2019-10-05T11:12:06: PM2 log: App [npm:0] starting in -fork mode-
2019-10-05T11:12:06: PM2 log: App [npm:0] online
> [email protected] start /app
> node index.js
zigbee2mqtt:info  2019-10-05T09:12:10: Logging to directory: '/share/zigbee2mqtt/log/2019-10-05.11-12-09'
zigbee2mqtt:debug 2019-10-05T09:12:10: Removing old log directory '/share/zigbee2mqtt/log/2019-10-05.10-55-05'
zigbee2mqtt:debug 2019-10-05T09:12:10: Loaded state from file /share/zigbee2mqtt/state.json
zigbee2mqtt:info  2019-10-05T09:12:10: Starting zigbee2mqtt version 1.6.0 (commit #3e75108741a0d7328b278a8c26daaf8a5adf0934)
zigbee2mqtt:info  2019-10-05T09:12:10: Starting zigbee-herdsman...
zigbee2mqtt:debug 2019-10-05T09:12:10: Using zigbee-herdsman with settings: '{"network":{"panID":6754,"extenedPanID":[221,221,221,221,221,221,221,221],"channelList":[11],"networkKey":"HIDDEN"},"databasePath":"/share/zigbee2mqtt/database.db","backupPath":"/share/zigbee2mqtt/coordinator_backup.json","serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/ttyACM0"}}'
zigbee2mqtt:error 2019-10-05T09:13:11: Error while starting zigbee-herdsman
zigbee2mqtt:error 2019-10-05T09:13:11: Error: AREQ - ZDO - stateChangeInd after 60000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/app/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)
zigbee2mqtt:error 2019-10-05T09:13:11: Failed to start zigbee
zigbee2mqtt:error 2019-10-05T09:13:11: Exiting...
zigbee2mqtt:error 2019-10-05T09:13:11: Error: AREQ - ZDO - stateChangeInd after 60000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/app/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! [email protected] start: `node index.js`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the [email protected] start script.
npm
 ERR! This is probably not a problem with npm. There is likely additional logging output above.

Tried it with non-edge version again:

> [email protected] start /zigbee2mqtt-1.6.0
> node index.js
  zigbee2mqtt:info 10/5/2019, 1:01:29 PM Logging to directory: '/share/zigbee2mqtt/log/2019-10-05.13-01-28'
  zigbee2mqtt:info 10/5/2019, 1:01:29 PM Starting zigbee2mqtt version 1.6.0 (commit #unknown)
  zigbee2mqtt:info 10/5/2019, 1:01:29 PM Starting zigbee-shepherd
  zigbee2mqtt:info 10/5/2019, 1:01:31 PM Error while starting zigbee-shepherd, attempting to fix... (takes 60 seconds) (TypeError: Spec attributes should be wrapped in an object.)
  zigbee2mqtt:info 10/5/2019, 1:02:31 PM Starting zigbee-shepherd
  zigbee2mqtt:error 10/5/2019, 1:02:32 PM Error while starting zigbee-shepherd! (Error: dev exists, unregister it first.)
  zigbee2mqtt:error 10/5/2019, 1:02:32 PM Press the reset button on the stick (the one closest to the USB) and start again
  zigbee2mqtt:error 10/5/2019, 1:02:32 PM Failed to start
    {"message":"dev exists, unregister it first.","stack":"Error: dev exists, unregister it first.\n    at /zigbee2mqtt-1.6.0/node_modules/zigbee-herdsman/dist/lib/shepherd.js:449:19\n    at Promise.apply (/zigbee2mqtt-1.6.0/node_modules/zigbee-herdsman/node_modules/q/q.js:1185:26)\n    at Promise.promise.promiseDispatch (/zigbee2mqtt-1.6.0/node_modules/zigbee-herdsman/node_modules/q/q.js:808:41)\n    at /zigbee2mqtt-1.6.0/node_modules/zigbee-herdsman/node_modules/q/q.js:1411:14\n    at runSingle (/zigbee2mqtt-1.6.0/node_modules/zigbee-herdsman/node_modules/q/q.js:137:13)\n    at flush (/zigbee2mqtt-1.6.0/node_modules/zigbee-herdsman/node_modules/q/q.js:125:13)\n    at process._tickCallback (internal/process/next_tick.js:61:11)"}
  zigbee2mqtt:error 10/5/2019, 1:02:32 PM Exiting...
npm
 ERR! code
 ELIFECYCLE
npm ERR! errno 1
npm
 ERR! [email protected] start: `node index.js`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the [email protected] 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-10-05T11_02_32_545Z-debug.log

The stick now sometimes turns red. I have another stick, I still have my old pi, I could double check if the stick is still ok, but now I get the feeling that the problem is either with the raspberry pi 4 or the new Raspbian Buster (used stretch before).

What firmware were you running? (nevermind)

  • Can you reflash the stick again and immediately try with the latest edge?
  • Also; what firmware did you reflash?

I reflashed the stick with the version I already used - which was the latest: 20190608 (default) I could also try source_routing?

Still same error on edge/dev - stick also turns from green to red:

./run.sh: line 16: [Info] Configuration backup found in /share/zigbee2mqtt/.configuration.yaml.bk. Skipping config backup.: No such file or directory
2019-10-06T15:57:41: PM2 log: Launching in no daemon mode
2019-10-06T15:57:41: PM2 log: App [npm:0] starting in -fork mode-
2019-10-06T15:57:41: PM2 log: App [npm:0] online
> [email protected] start /app
> node index.js
zigbee2mqtt:info  2019-10-06T13:57:45: Logging to directory: '/share/zigbee2mqtt/log/2019-10-06.15-57-44'
zigbee2mqtt:debug 2019-10-06T13:57:45: Removing old log directory '/share/zigbee2mqtt/log/2019-10-06.15-43-38'
zigbee2mqtt:debug 2019-10-06T13:57:45: Loaded state from file /share/zigbee2mqtt/state.json
zigbee2mqtt:info  2019-10-06T13:57:45: Starting zigbee2mqtt version 1.6.0 (commit #3e75108741a0d7328b278a8c26daaf8a5adf0934)
zigbee2mqtt:info  2019-10-06T13:57:45: Starting zigbee-herdsman...
zigbee2mqtt:debug 2019-10-06T13:57:45: Using zigbee-herdsman with settings: '{"network":{"panID":6754,"extenedPanID":[221,221,221,221,221,221,221,221],"channelList":[11],"networkKey":"HIDDEN"},"databasePath":"/share/zigbee2mqtt/database.db","backupPath":"/share/zigbee2mqtt/coordinator_backup.json","serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/ttyACM0"}}'
zigbee2mqtt:error 2019-10-06T13:58:49: Error while starting zigbee-herdsman
zigbee2mqtt:error 2019-10-06T13:58:49: Error: AREQ - ZDO - stateChangeInd after 60000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/app/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)
zigbee2mqtt:error 2019-10-06T13:58:49: Failed to start zigbee
zigbee2mqtt:error 2019-10-06T13:58:49: Exiting...
zigbee2mqtt:error 2019-10-06T13:58:49: Error: AREQ - ZDO - stateChangeInd after 60000ms
    at Timeout.object.timer.setTimeout [as _onTimeout] (/app/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! [email protected] start: `node index.js`
npm ERR! Exit status 1
npm ERR! 
npm ERR!
 Failed at the [email protected] 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-10-06T13_58_49_586Z-debug.log
2019-10-06T15:58:52: PM2 log: App [npm:0] exited with code [1] via signal [SIGINT]

After pressing the soft-reset it "works" (no more error, only on edge) but the behaviour is still the same as mentioned in my first post (no device is responding), it seems that the coordinator has no routes to all the devices or that the coordinator/USB-connection does not work properly anymore. I'm going to switch back to my pi3 and see if that "fixes the problem". I'm willing to do some testing afterwards to narrow down the issue.

So, I switched back to my pi3 and everything works as expected. So the only thing different to my setup before is: raspberrip4 instead of 3 and raspian buster instead of stretch.
How should we proceed?

Can you provide the logging when starting zigbee2mqtt with DEBUG=zigbee-herdsman* npm start?

Since I am using hassio, is this any different than starting the addon with log Level debug? Or can I just docker exec into the container and run the command? (Alternatively, I could simply install zigbee2mqtt without using hassio.)

@ciB89 for the sake of simplicity perhaps you could indeed try an install on the pi 4 without hassio

When I instlall on my pi and try to run with npm this is the error I get:

> [email protected] start /opt/zigbee2mqtt
> node index.js

internal/modules/cjs/loader.js:638
    throw err;
    ^

Error: Cannot find module 'zigbee-herdsman/dist/deprecated/ziee'
    at Function.Module._resolveFilename (internal/modules/cjs/loader.js:636:15)
    at Function.Module._load (internal/modules/cjs/loader.js:562:25)
    at Module.require (internal/modules/cjs/loader.js:692:17)
    at require (internal/modules/cjs/helpers.js:25:18)
    at Object.<anonymous> (/opt/zigbee2mqtt/lib/zapp/cie.js:6:14)
    at Module._compile (internal/modules/cjs/loader.js:778:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:789:10)
    at Module.load (internal/modules/cjs/loader.js:653:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:593:12)
    at Function.Module._load (internal/modules/cjs/loader.js:585:3)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! [email protected] start: `node index.js`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the [email protected] 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-10-09T11_49_50_818Z-debug.log

Also during the install I got the following errors:

npm WARN optional SKIPPING OPTIONAL DEPENDENCY: [email protected] (node_modules/zigbee-shepherd-converters/node_modules/zigbee-herdsman/node_modules/fsevents):
npm WARN notsup SKIPPING OPTIONAL DEPENDENCY: Unsupported platform for [email protected]: wanted {"os":"darwin","arch":"any"} (current: {"os":"linux","arch":"arm"})
npm WARN optional SKIPPING OPTIONAL DEPENDENCY: [email protected] (node_modules/zigbee-herdsman/node_modules/fsevents):
npm WARN notsup SKIPPING OPTIONAL DEPENDENCY: Unsupported platform for [email protected]: wanted {"os":"darwin","arch":"any"} (current: {"os":"linux","arch":"arm"})
npm WARN optional SKIPPING OPTIONAL DEPENDENCY: [email protected] (node_modules/fsevents):
npm WARN notsup SKIPPING OPTIONAL DEPENDENCY: Unsupported platform for [email protected]: wanted {"os":"darwin","arch":"any"} (current: {"os":"linux","arch":"arm"})

added 2097 packages from 594 contributors and audited 877679 packages in 118.641s
found 3 vulnerabilities (2 moderate, 1 high)
  run `npm audit fix` to fix them, or `npm audit` for details

The logfile contains this info:

0 info it worked if it ends with ok
1 verbose cli [ '/usr/bin/node', '/usr/bin/npm', 'start' ]
2 info using [email protected]
3 info using [email protected]
4 verbose run-script [ 'prestart', 'start', 'poststart' ]
5 info lifecycle [email protected]~prestart: [email protected]
6 info lifecycle [email protected]~start: [email protected]
7 verbose lifecycle [email protected]~start: unsafe-perm in lifecycle true
8 verbose lifecycle [email protected]~start: PATH: /usr/lib/node_modules/npm/node_modules/npm-lifecycle/node-gyp-bin:/opt/zi$
9 verbose lifecycle [email protected]~start: CWD: /opt/zigbee2mqtt
10 silly lifecycle [email protected]~start: Args: [ '-c', 'node index.js' ]
11 silly lifecycle [email protected]~start: Returned: code: 1  signal: null
12 info lifecycle [email protected]~start: Failed to exec start script
13 verbose stack Error: [email protected] start: `node index.js`
13 verbose stack Exit status 1
13 verbose stack     at EventEmitter.<anonymous> (/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.<anonymous> (/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 [email protected]
15 verbose cwd /opt/zigbee2mqtt
16 verbose Linux 4.19.75-v7l+
17 verbose argv "/usr/bin/node" "/usr/bin/npm" "start"

This is a known error and I'm not sure how to fix it; you might want to try the dev branch. https://www.zigbee2mqtt.io/how_tos/how-to-switch-to-dev-branch.html

dev-branch starts, but 0 devices connected (just as the hass version) log for DEBUG=zigbee-herdsman* npm start:
Pastebin

Now you should copy over the database.db and configuration.yaml from pi 3.

Ups, okay that's a little embarassing that I just forgot about that xD. I'm gonna blame it on me being busy for my birthday preperations. Going to report back after my birthday, thanks for your support so far.

Okay, copied everything (including the db and devices.yaml) to the data folder I ran it for a couple of seconds withDEBUG=zigbee-herdsman* npm start:

Pastebin

Pressing any buttons or so did not show anything in the logs :-/

I am the only one with this issue? Is my RaspberryPi4 faulty?

any kernel messages ? dmesg -T at the time the serial port is closed

nothing suspicous:

[Tue Oct 15 10:53:19 2019] usb 1-1.3: new full-speed USB device number 4 using xhci_hcd
[Tue Oct 15 10:53:19 2019] usb 1-1.3: New USB device found, idVendor=0451, idProduct=16a8, bcdDevice= 0.09
[Tue Oct 15 10:53:19 2019] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[Tue Oct 15 10:53:19 2019] usb 1-1.3: Product: TI CC2531 USB CDC
[Tue Oct 15 10:53:19 2019] usb 1-1.3: Manufacturer: Texas Instruments
[Tue Oct 15 10:53:19 2019] usb 1-1.3: SerialNumber: __0X00124B0012023164
[Tue Oct 15 10:53:19 2019] cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device
[Tue Oct 15 10:58:08 2019] hassio: port 7(veth636cc69) entered disabled state
[Tue Oct 15 10:58:08 2019] veth603f9ad: renamed from eth0
[Tue Oct 15 10:58:09 2019] hassio: port 7(veth636cc69) entered disabled state
[Tue Oct 15 10:58:09 2019] device veth636cc69 left promiscuous mode
[Tue Oct 15 10:58:09 2019] hassio: port 7(veth636cc69) entered disabled state
[Tue Oct 15 10:58:39 2019] hassio: port 3(veth4cf6eef) entered blocking state
[Tue Oct 15 10:58:39 2019] hassio: port 3(veth4cf6eef) entered disabled state
[Tue Oct 15 10:58:39 2019] device veth4cf6eef entered promiscuous mode
[Tue Oct 15 10:58:39 2019] IPv6: ADDRCONF(NETDEV_UP): veth4cf6eef: link is not ready
[Tue Oct 15 10:58:39 2019] hassio: port 3(veth4cf6eef) entered blocking state
[Tue Oct 15 10:58:39 2019] hassio: port 3(veth4cf6eef) entered forwarding state
[Tue Oct 15 10:58:39 2019] hassio: port 3(veth4cf6eef) entered disabled state
[Tue Oct 15 10:58:39 2019] IPv6: ADDRCONF(NETDEV_UP): veth65de95c: link is not ready
[Tue Oct 15 10:58:39 2019] IPv6: ADDRCONF(NETDEV_CHANGE): veth65de95c: link becomes ready
[Tue Oct 15 10:58:39 2019] IPv6: ADDRCONF(NETDEV_CHANGE): veth4cf6eef: link becomes ready
[Tue Oct 15 10:58:39 2019] hassio: port 3(veth4cf6eef) entered blocking state
[Tue Oct 15 10:58:39 2019] hassio: port 3(veth4cf6eef) entered forwarding state

Just to summarize: zigbee2mqtt starts successfully on my new raspberrypi4, but the stick (that still works perfectly on my raspberrypi3) does not seem to be able to communicate with any of my devices (for whatever reason). I am going to try using rasbian stretch instead of buster and see if that changes anything... that's the last thing I can do; I'd love to know of anyone who has a raspberrypi4 and uses zigbee2mqtt with a cc2531 successfully, just to make sure that this is _only_ a _specific_ problem for me.

@ciB89 that problem is very unlikely to be caused by the pi 4. Are you sure you migrated configuration.yaml? Not able to communicate with other devices would mean a different channel or pan id.

Yes, I did. I only forgot to copy the database once when I was trying to run it directly without hassio, but both the hassio-version with all the files/settings from my pi3 and the non-hassio version with all the files have the same issue.

Can you provide the debug logging when starting both on pi3 and pi4?

To enable debug logging set in configuration.yaml:

advanced:
  log_level: debug

sure. Logs after fresh start and running for a couple of seconds:

pi3 hassio: https://pastebin.com/UGEPbUKY
pi4 hassio: https://pastebin.com/vRbMSwi8

config/configuration.yaml, database.db, groups.yaml and devices.yaml are identical.

Looks good, things I notice:

  • a network scan is initiated right after start, on a cold boot of the adapter this can take very long (minutes) especially if all of them fail. The rate of failure is higher after cold boot because the adapter didn't get the time to collect routes. I would recommend to disable the network scan for now. (https://github.com/Koenkk/zigbee2mqtt/issues/2118#issuecomment-541339790)
  • could interference be an issue? did you try connecting the adapter with a USB extension cable?

I'm not using an extension cable, wasn't an issue for me so far. Haven't considered it being an issue with the pi4. Gong to test it (might need to buy extension first) and also going to disable the network scans.

Found an extension, deactivated the scans and it works straight away! Thanks for the support <3

I still do not understand how to disable scan. Can you please explain to me step by step? thanks

In zigbee2mqtt inself there is no option to create a networkmap regularily. So if you have problems with this, you have another addon installed that performs a scan regularily. For me, I had the zigbee2mqtt-adminPanel in Node-Red "installed", which performed a scan every 30 seconds. I simply removed it again.

Was this page helpful?
0 / 5 - 0 ratings