search

Koenkk / zigbee-herdsman

A Node.js Zigbee library
MIT License
456 stars 277 forks source link

Error while starting zigbee-herdsman #282

Closed JvD12 closed 3 years ago

JvD12 commented 3 years ago

Since I replaced my old coordinator with an CC2652 from https://www.tindie.com/products/slaesh/cc2652-zigbee-coordinator-or-openthread-router I often have issues like this: Error while starting zigbee-herdsman Zigbee2MQTT:error 2021-01-05 18:36:14: Failed to start zigbee Zigbee2MQTT:error 2021-01-05 18:36:14: Exiting... Zigbee2MQTT:error 2021-01-05 18:36:14: Error: Coordinator failed to start, probably the panID is already in use, try a different panID or channel at /zigbee2mqtt-1.17.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:172:23 at Generator.throw (<anonymous>) at rejected (/zigbee2mqtt-1.17.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:25:65) npm ERR! code ELIFECYCLE

Only if I change the PANID I got again access to the coordinator but after that the whole zigbee network is lost. Is there another solution for this?

JvD12 commented 3 years ago

Software version: 1.17.0 (commit #1.17.0) zigbee-herdsman (0.13.46)

Coordinator firmware version: '{"meta":{"maintrel":1,"majorrel":2,"minorrel":7,"product":1,"revision":20201026,"transportrev":2},"type":"zStack3x0"}'

Koenkk commented 3 years ago

For some reason your coordinator thinks it needs to setup a new network.

Can you provide the herdsman debug logging of this?

To enable herdsman debug logging, see https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging

JvD12 commented 3 years ago

It stops after: 2021-01-05T19:16:25.249Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [8,2,0] - 198 2021-01-05T19:16:25.250Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":8} 2021-01-05T19:16:25.250Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,8,2,0,198] 2021-01-05T19:16:25.250Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [8,2,0] - 198 2021-01-05T19:16:25.250Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":8} 2021-01-05T19:16:25.250Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []

After that the error message Zigbee2MQTT:error 2021-01-05 19:16:02: Error while starting zigbee-herdsman Zigbee2MQTT:error 2021-01-05 19:16:02: Failed to start zigbee Zigbee2MQTT:error 2021-01-05 19:16:02: Exiting... Zigbee2MQTT:error 2021-01-05 19:16:02: Error: Coordinator failed to start, probably the panID is already in use, try a different panID or channel at /zigbee2mqtt-1.17.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:172:23 at Generator.throw (<anonymous>) at rejected (/zigbee2mqtt-1.17.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:25:65) npm ERR! code ELIFECYCLE is shown and the process is restarted.

Koenkk commented 3 years ago

I need logs from starting, when sshing into your machine and doing a docker logs -f on the Zigbee2MQTT container you should get all logs.

JvD12 commented 3 years ago

I uploaded the requested log to: https://paste.ubuntu.com/p/4g7ptYssTp/

Koenkk commented 3 years ago

Seems the harm has already be done at this point. Could you capture such log the first time zigbee2mqtt fails to start after working correctly?

JvD12 commented 3 years ago

Each time the Zigbee2mqtt addon is started results in these errors. I need to change the PAN ID to start the coordinator once without issues. But I will try to make a log of it.

JvD12 commented 3 years ago

It looks like something related to the chosen PAN ID. With 7777 I got errors but for instance with 2038 it works much better. I will try to test it in more detail.

Koenkk commented 3 years ago

Can you try 5670

JvD12 commented 3 years ago

I spent a lot of time in testing and found the following:

A network with a single coordinator work fine without issues. Restart or specific PAN ID's does not matter.
But after joining a router device the problems starts after a restart of Home Assistant or a restart of the addon.

I have seen different error messages: "AREQ - ZDO - stateChangeInd after 60000ms" or "panID is already"

2021-01-07T14:48:29.272Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,14,103,0,0,224,62,204,33,0,75,18,0,254,255,7,0,0,5] 2021-01-07T14:48:29.272Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 14 - 3 - 7 - 0 - [0,224,62,204,33,0,75,18,0,254,255,7,0,0] - 5 2021-01-07T14:48:29.275Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- UTIL - getDeviceInfo - {"status":0,"ieeeaddr":"0x00124b0021cc3ee0","shortaddr":65534,"devicetype":7,"devicestate":0,"numassocdevices":0,"assocdeviceslist":[]} 2021-01-07T14:48:29.275Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:48:29.275Z zigbee-herdsman:adapter:zStack:startZnp Start ZNP as coordinator... 2021-01-07T14:48:29.276Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - startupFromApp - {"startdelay":100} 2021-01-07T14:48:29.277Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,37,64,100,0,3] 2021-01-07T14:48:31.603Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,64,0,36] 2021-01-07T14:48:31.604Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,64,0,36] 2021-01-07T14:48:31.604Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 64 - [0] - 36 2021-01-07T14:48:31.605Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - startupFromApp - {"status":0} 2021-01-07T14:48:31.605Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:48:31.607Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,79,128,2,0,0,206] 2021-01-07T14:48:31.607Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,2,0,0,206] 2021-01-07T14:48:31.607Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [2,0,0] - 206 2021-01-07T14:48:31.608Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":2} 2021-01-07T14:48:31.608Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:48:31.820Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,69,192,8,140] 2021-01-07T14:48:31.821Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,69,192,8,140] 2021-01-07T14:48:31.821Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 2 - 5 - 192 - [8] - 140 2021-01-07T14:48:31.822Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - stateChangeInd - {"state":8} 2021-01-07T14:48:31.822Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:48:32.380Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,69,192,8,140] 2021-01-07T14:48:32.381Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,69,192,8,140] 2021-01-07T14:48:32.381Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 2 - 5 - 192 - [8] - 140 2021-01-07T14:48:32.381Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - stateChangeInd - {"state":8} 2021-01-07T14:48:32.382Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:48:32.383Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,79,128,8,2,0,198] 2021-01-07T14:48:32.383Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,8,2,0,198] 2021-01-07T14:48:32.384Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [8,2,0] - 198 2021-01-07T14:48:32.384Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":8} 2021-01-07T14:48:32.385Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:48:32.945Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,69,192,0,132] 2021-01-07T14:48:32.946Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,69,192,0,132] 2021-01-07T14:48:32.946Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 2 - 5 - 192 - [0] - 132 2021-01-07T14:48:32.947Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - stateChangeInd - {"state":0} 2021-01-07T14:48:32.947Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:48:32.948Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,79,128,8,2,0,198,254,3,79,128,8,2,0,198] 2021-01-07T14:48:32.949Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,8,2,0,198,254,3,79,128,8,2,0,198] 2021-01-07T14:48:32.949Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [8,2,0] - 198 2021-01-07T14:48:32.949Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":8} 2021-01-07T14:48:32.950Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,8,2,0,198] 2021-01-07T14:48:32.950Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [8,2,0] - 198 2021-01-07T14:48:32.950Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":8} 2021-01-07T14:48:32.951Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] Zigbee2MQTT:error 2021-01-07 14:49:29: Error while starting zigbee-herdsman Zigbee2MQTT:error 2021-01-07 14:49:29: Failed to start zigbee Zigbee2MQTT:error 2021-01-07 14:49:29: Exiting... Zigbee2MQTT:error 2021-01-07 14:49:29: Error: AREQ - ZDO - stateChangeInd after 60000ms at Timeout._onTimeout (/zigbee2mqtt-1.17.0/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35) at listOnTimeout (internal/timers.js:549:17) at processTimers (internal/timers.js:492:7)

2021-01-07T14:49:47.158Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,97,9,0,105] 2021-01-07T14:49:47.158Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,97,9,0,105] 2021-01-07T14:49:47.158Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 1 - 9 - [0] - 105 2021-01-07T14:49:47.159Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvWrite - {"status":0} 2021-01-07T14:49:47.159Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:47.160Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvWrite - {"id":131,"len":2,"offset":0,"value":{"type":"Buffer","data":[97,30]}} 2021-01-07T14:49:47.161Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,6,33,9,131,0,0,2,97,30,208] 2021-01-07T14:49:47.173Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,97,9,0,105] 2021-01-07T14:49:47.173Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,97,9,0,105] 2021-01-07T14:49:47.173Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 1 - 9 - [0] - 105 2021-01-07T14:49:47.174Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvWrite - {"status":0} 2021-01-07T14:49:47.174Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:47.175Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvWrite - {"id":45,"len":8,"offset":0,"value":{"type":"Buffer","data":[221,221,221,221,221,221,221,221]}} 2021-01-07T14:49:47.175Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,12,33,9,45,0,0,8,221,221,221,221,221,221,221,221,1] 2021-01-07T14:49:47.188Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,97,9,0,105] 2021-01-07T14:49:47.189Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,97,9,0,105] 2021-01-07T14:49:47.189Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 1 - 9 - [0] - 105 2021-01-07T14:49:47.189Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvWrite - {"status":0} 2021-01-07T14:49:47.189Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:47.190Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvWrite - {"id":98,"configid":98,"len":16,"offset":0,"value":{"type":"Buffer","data":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2021-01-07T14:49:47.191Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,20,33,9,98,0,0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,77] 2021-01-07T14:49:47.205Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,97,9,0,105] 2021-01-07T14:49:47.205Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,97,9,0,105] 2021-01-07T14:49:47.205Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 1 - 9 - [0] - 105 2021-01-07T14:49:47.205Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvWrite - {"status":0} 2021-01-07T14:49:47.205Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:47.206Z zigbee-herdsman:adapter:zStack:znp:SREQ --> APP_CNF - bdbSetChannel - {"isPrimary":1,"channel":2048} 2021-01-07T14:49:47.207Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,47,8,1,0,8,0,0,43] 2021-01-07T14:49:47.211Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,111,8,0,102] 2021-01-07T14:49:47.211Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,111,8,0,102] 2021-01-07T14:49:47.211Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 15 - 8 - [0] - 102 2021-01-07T14:49:47.212Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- APP_CNF - bdbSetChannel - {"status":0} 2021-01-07T14:49:47.212Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:47.213Z zigbee-herdsman:adapter:zStack:znp:SREQ --> APP_CNF - bdbSetChannel - {"isPrimary":0,"channel":0} 2021-01-07T14:49:47.214Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,47,8,0,0,0,0,0,34] 2021-01-07T14:49:47.217Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,111,8,0,102] 2021-01-07T14:49:47.218Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,111,8,0,102] 2021-01-07T14:49:47.218Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 15 - 8 - [0] - 102 2021-01-07T14:49:47.218Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- APP_CNF - bdbSetChannel - {"status":0} 2021-01-07T14:49:47.219Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:47.220Z zigbee-herdsman:adapter:zStack:znp:SREQ --> APP_CNF - bdbStartCommissioning - {"mode":4} 2021-01-07T14:49:47.221Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,1,47,5,4,47] 2021-01-07T14:49:50.488Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,111,5,0,107] 2021-01-07T14:49:50.489Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,111,5,0,107] 2021-01-07T14:49:50.489Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 15 - 5 - [0] - 107 2021-01-07T14:49:50.489Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- APP_CNF - bdbStartCommissioning - {"status":0} 2021-01-07T14:49:50.490Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:50.491Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,79,128,1,2,4,203] 2021-01-07T14:49:50.491Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,1,2,4,203] 2021-01-07T14:49:50.492Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [1,2,4] - 203 2021-01-07T14:49:50.492Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":1} 2021-01-07T14:49:50.492Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:50.753Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,69,192,8,140] 2021-01-07T14:49:50.753Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,69,192,8,140] 2021-01-07T14:49:50.753Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 2 - 5 - 192 - [8] - 140 2021-01-07T14:49:50.754Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - stateChangeInd - {"state":8} 2021-01-07T14:49:50.754Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:51.313Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,69,192,8,140] 2021-01-07T14:49:51.314Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,69,192,8,140] 2021-01-07T14:49:51.314Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 2 - 5 - 192 - [8] - 140 2021-01-07T14:49:51.315Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - stateChangeInd - {"state":8} 2021-01-07T14:49:51.315Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:51.316Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,79,128,8,2,0,198] 2021-01-07T14:49:51.317Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,8,2,0,198] 2021-01-07T14:49:51.317Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [8,2,0] - 198 2021-01-07T14:49:51.317Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":8} 2021-01-07T14:49:51.318Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:51.879Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,69,192,0,132] 2021-01-07T14:49:51.880Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,69,192,0,132] 2021-01-07T14:49:51.880Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 2 - 5 - 192 - [0] - 132 2021-01-07T14:49:51.881Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - stateChangeInd - {"state":0} 2021-01-07T14:49:51.881Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2021-01-07T14:49:51.882Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,79,128,8,2,0,198,254,3,79,128,8,2,0,198] 2021-01-07T14:49:51.882Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,8,2,0,198,254,3,79,128,8,2,0,198] 2021-01-07T14:49:51.883Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [8,2,0] - 198 2021-01-07T14:49:51.883Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":8} 2021-01-07T14:49:51.883Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,8,2,0,198] 2021-01-07T14:49:51.884Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [8,2,0] - 198 2021-01-07T14:49:51.884Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":8} 2021-01-07T14:49:51.884Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] Zigbee2MQTT:error 2021-01-07 14:50:50: Error while starting zigbee-herdsman Zigbee2MQTT:error 2021-01-07 14:50:50: Failed to start zigbee Zigbee2MQTT:error 2021-01-07 14:50:50: Exiting... Zigbee2MQTT:error 2021-01-07 14:50:50: Error: Coordinator failed to start, probably the panID is already in use, try a different panID or channel at /zigbee2mqtt-1.17.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:172:23 at Generator.throw (<anonymous>) at rejected (/zigbee2mqtt-1.17.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:25:65) npm

I have tested it in a Zigbee network of only 2 devices. The CC2652 as coordinator with an INNR SP120 as router. And in another test with the CC2652 and an INNR 220. Both times with the same results.

I can imagine router devices sends periodically Zigbee messages/packets with the specified PAN ID. But what will happen if the coordinator is restarted and detect other devices are already using this PAN ID?

JvD12 commented 3 years ago

The total log can be found here: https://paste.ubuntu.com/p/dHPVK4h4p7/

I started a new Zigbee network with a single coordinator, after that an INNR SP120 was joined as router. At line 1442 I restarted the Zigbee2mqtt addon.

Koenkk commented 3 years ago

But what will happen if the coordinator is restarted and detect other devices are already using this PAN ID?

The coordinator shouldn't care about this since it knows it has setup this network itself. But this is the point where things go wrong (and unfortunately I haven't seen this before). Currently can think of two reasons why this happens:

JvD12 commented 3 years ago

I stopped Zigbee2mqtt by pressing the restart "button" in the info tab from the Zigbee2mqtt add on. For me this sound like the normal way to restart it. But tomorrow I will test the other option as well.

The same for the reflashing option. I try to do that tomorrow or this weekend. Thanks for now!

JvD12 commented 3 years ago

I tested both items. But without results...

First the more graceful stop action. This is the log:

[cont-finish.d] executing container finish scripts... [cont-finish.d] done. [s6-finish] waiting for services. [s6-finish] sending all processes the TERM signal. [s6-init] making user provided files available at /var/run/s6/etc...exited 0. [s6-init] ensuring user provided files have correct perms...exited 0. [fix-attrs.d] applying ownership & permissions fixes... [fix-attrs.d] done. [cont-init.d] executing container initialization scripts... [cont-init.d] done. [services.d] starting services [services.d] done. ./run.sh: line 17: [Info] Configuration backup found in /share/zigbee2mqtt/.configuration.yaml.bk. Skipping config backup.: No such file or directory [Info] Zigbee Herdsman debug logging enabled. [Info] Socat is DISABLED and not started 2021-01-08T19:23:05: PM2 log: Launching in no daemon mode 2021-01-08T19:23:05: PM2 log: App [npm:0] starting in -fork mode- 2021-01-08T19:23:05: PM2 log: App [npm:0] online zigbee2mqtt@1.17.0 start /zigbee2mqtt-1.17.0 ...

2021-01-08T19:23:21.953Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [8,2,0] - 198 2021-01-08T19:23:21.953Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":8} 2021-01-08T19:23:21.953Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,8,2,0,198] 2021-01-08T19:23:21.954Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [8,2,0] - 198 2021-01-08T19:23:21.954Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":8} 2021-01-08T19:23:21.954Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext

Second I updated several times the coordinator with 2 different versions of the coordinator software but also without success. This version with "test software" http://slae.sh/downloads/znp_CC2652RB_20200715.bin and this https://github.com/Koenkk/Z-Stack-firmware/blob/master/coordinator/Z-Stack_3.x.0/bin/CC2652RB_20201026.zip

I also did a test with a single coordinator and a single end device (a Xiaomi temperature sensor). This works without issues. Does this mean something does not work with CC2652 the INNR SP120 and INNR SP220 routers? Are you able to test that on your side?

Koenkk commented 3 years ago

I'm still puzzled how this could happen.

I also did a test with a single coordinator and a single end device (a Xiaomi temperature sensor).

This is expected since there will be no pan id conflict on startup (since device is sleeping during the scan)

JvD12 commented 3 years ago

For test I installed another Home Assistant instance with only the Zigbee@mqtt and the Mosquitto broker add-ons but with the same result

JvD12 commented 3 years ago

And to "exclude" the INNR SP120 routers I reprogrammed a CC2531 USB stick as router. (https://github.com/Koenkk/Z-Stack-firmware/blob/master/router/CC2531/bin/CC2531_router_2020_09_29.zip) But again with the same result: Error: "Coordinator failed to start, probably the panID is already in use, try a different panID or channel". Now I'm running out of test options...

Are you able to test/reproduce it on your side? Do you have the same CC2652 USB dongle?

Koenkk commented 3 years ago

@JvD12 I also have this dongle but cannot reproduce this. How is the dongle connected? Directly/hub? I know @golddragon007 also got such very vague issues in https://github.com/Koenkk/zigbee2mqtt/issues/4513 and it turned out a bad power supply was the issue.

JvD12 commented 3 years ago

It was connected with a short extension cable of 1 meter. Now it's connected directly on the Pi4, but unfortunately no improvements .The Pi is powered with the official adapter: https://www.sossolutions.nl/originele-raspberry-pi-foundation-usbc-3a-voeding-zwart

Only this USB device, the power adapter and an ethernet cable are connected.

Koenkk commented 3 years ago

Can you try running it on a different system? Want to isolate the pi 4 from being the issue.

JvD12 commented 3 years ago

I'm testing it right now on a old Pi 3 B+

@slaesh what's your opinion about this issue? Have you seen it before?

JvD12 commented 3 years ago

No, it does not work... Error: Coordinator failed to start, probably the panID is already in use, try a different panID or channel.

JvD12 commented 3 years ago

And same for ZHA

Koenkk commented 3 years ago

And same for ZHA

I would expect that indeed, issue looks to be in the stick side.

JvD12 commented 3 years ago

@slaesh, it looks like the CC2652 is (partly) hand soldered. How do you test this hardware before shipping?

@Koenkk, do you know someone close to Veenendaal to test this stick?

Koenkk commented 3 years ago

@JvD12 if you are interested, you can send the stick to me so I can compare it with my own slaesh stick.

JvD12 commented 3 years ago

Sounds like a good plan. But first I will wait for some input from slaesh. Thanks!

golddragon007 commented 3 years ago

@JvD12 He testing it with this script: https://github.com/slaesh/cc2652-stick/tree/master/coordinator-test Btw Did you try to change the pan id? Maybe it's a neighbour's Zigbee network that using the same? Or if you have a second coordinator with the same pan id...

JvD12 commented 3 years ago

Thanks!

I changed maybe 30 times the pan id, channel, network key, extended pan id (but this doesn'r work. it always 221,221,221,221,221,221,221,221 without results...

JvD12 commented 3 years ago

where is all data about connected routers and end devices stored? Sometimes let's say 1 of 10 the coordinator is started after an add-on restart. But if I press the rst(reset) button of the CC2652 stick just after restarting the add-on the previously connected router will be lost.

Koenkk commented 3 years ago

connected router will be lost.

What do you mean with lost here? Missing from the connected devices list on startup?

JvD12 commented 3 years ago

I test it with the CC2652 as coordinator and an INNR 120 as router. If the add-on is restarted without issues (in 1 out of 10 attempts) I expected the router is still connectedto the coordinator. But that's not the case.

Zigbee2MQTT:error 2021-01-10 20:26:00: Error: Coordinator failed to start, probably the panID is already in use, try a different panID or channel at /app/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:172:23 at Generator.throw () at rejected (/app/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:25:65) npm ERR! code ELIFECYCLE npm ERR! errno 1 npm ERR! zigbee2mqtt@1.17.0-dev start: node index.js npm ERR! Exit status 1 npm ERR! npm ERR! Failed at the zigbee2mqtt@1.17.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! /root/.npm/_logs/2021-01-10T20_26_00_241Z-debug.log 2021-01-10T20:26:02: PM2 log: App [npm:0] exited with code [1] via signal [SIGINT] 2021-01-10T20:26:02: PM2 log: App [npm:0] starting in -fork mode- 2021-01-10T20:26:02: PM2 log: App [npm:0] online zigbee2mqtt@1.17.0-dev start /app node index.js Zigbee2MQTT:debug 2021-01-10 20:26:06: Loaded state from file /share/zigbee2mqtt/state.json Zigbee2MQTT:info 2021-01-10 20:26:06: Logging to console and directory: '/share/zigbee2mqtt/log/2021-01-10.20-26-05' filename: log.txt Zigbee2MQTT:debug 2021-01-10 20:26:06: Removing old log directory '/share/zigbee2mqtt/log/2021-01-10.19-28-09' Zigbee2MQTT:info 2021-01-10 20:26:06: Starting Zigbee2MQTT version 1.17.0-dev (commit #09d436f) Zigbee2MQTT:info 2021-01-10 20:26:06: Starting zigbee-herdsman (0.13.50) Zigbee2MQTT:debug 2021-01-10 20:26:06: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null},"backupPath":"/share/zigbee2mqtt/coordinator_backup.json","databaseBackupPath":"/share/zigbee2mqtt/database.db.backup","databasePath":"/share/zigbee2mqtt/database.db","network":{"channelList":[12],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":7642},"serialPort":{"path":"/dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rbstick-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_3E_E0-if00-port0"}}' Zigbee2MQTT:info 2021-01-10 20:26:23: zigbee-herdsman started Zigbee2MQTT:info 2021-01-10 20:26:23: Coordinator firmware version: '{"meta":{"maintrel":1,"majorrel":2,"minorrel":7,"product":1,"revision":20201026,"transportrev":2},"type":"zStack3x0"}' Zigbee2MQTT:debug 2021-01-10 20:26:23: Zigbee network parameters: {"channel":12,"extendedPanID":"0xdddddddddddddddd","panID":7642} Zigbee2MQTT:info 2021-01-10 20:26:23: Currently 0 devices are joined: Zigbee2MQTT:warn 2021-01-10 20:26:23: permit_join set to true in configuration.yaml. Zigbee2MQTT:warn 2021-01-10 20:26:23: Allowing new devices to join. Zigbee2MQTT:warn 2021-01-10 20:26:23: Set permit_join to false once you joined all devices. Zigbee2MQTT:info 2021-01-10 20:26:23: Zigbee: allowing new devices to join. Zigbee2MQTT:info 2021-01-10 20:26:23: Started frontend on port 0.0.0.0:8099

For that reason the question were data about connected devices is stored. In the (nv?) memory of the coordinator or somewhere else. Like an configuration file in the zigbee2mqtt add-on

slaesh commented 3 years ago

@JvD12 could you please check this script? https://github.com/slaesh/cc2652-stick/tree/master/coordinator-test

the HW is tested two times:

we changed the manufacturer multiple times, I will check you EUID to see where it was manufactured. Could you text me on telegram? https://t.me/slaesh We can send you another device, to check if it's an HW related problem.

Another thing, we could check this debug-fw: https://slae.sh/projects/cc2652/#from-me

the LED's will let us know the current state of the MCU. maybe another process is interrupting us..

JvD12 commented 3 years ago

@slaesh, thanks for your reply. We already discussed it a bit on Telegram. For next wednesday we planned an session to debug it together.

This it the output after running the script with debug level set to 10

`C:\Users\Gast\Desktop\CC2652>python test.py -p COM8 Opening port COM8, baud 115200

sending synch sequence Got 0 additional bytes before ACK/NACK GetChipId command (0x28) Got 0 additional bytes before ACK/NACK received 6 bytes GetStatus command (0x23) Got 0 additional bytes before ACK/NACK received 3 bytes Command Successful Version 0x3102F000 --> Bootloader is working! received 12 ---> 00: 00 (0) ---> 01: fe (254) ---> 02: 06 (6) ---> 03: 41 (65) ---> 04: 80 (128) ---> 05: 00 (0) ---> 06: 02 (2) ---> 07: 01 (1) ---> 08: 02 (2) ---> 09: 07 (7) ---> 10: 01 (1) ---> 11: c0 (192) received 0 received 0 received 0 ReadFwVersion cmd received 15 --> ZigBee coordinator is working! ---> transportrev 2, product 1, majorrel 2, minorrel 7, maintrel 1, revision: 20201026 received 0

Check done!`

JvD12 commented 3 years ago

Once again I downloaded the test software with debug LEDs into the coordinator. Below a summary of the actions and the results.

1: Programmed CC2652 with test software: http://slae.sh/downloads/znp_CC2652RB_20200715.bin 2: CC2652 connected to the Raspberry Pi 4. Only this device is connected. To a new installation of Home Assistant. With the Mosquitto broker and Zigbee2mqtt add-ons installed. 3: All 3 LEDs are active (Blue, Green and Red/Orange) 4: After a few seconds the Red/Orange led is disabled. Blue and Green LEDs remain active 5: Join INNR SP120 to Zigbee network 6: Toggle switch in Home Assistant lovelace dashboard to verify it works 7: Restart the add-on by pressing the RESTART button in the info tab of the Zigbee2mqtt add-on 8: Error shown: AREQ-ZDO - stateCHangeInd after 60000ms... Blue and Green LED still active 9: Wait for the next attempt of Zigbee@mqtt to start the coordinator 10: Blue, Green and Red/Orange LED active 11: Error shown: PAN ID is already in use 12: Wait for the next attempt of Zigbee@mqtt to start the coordinator 13: Coordinator started, Blue and Green LED active 14: INNR120 router is disconnected: "Currently 0 devices are joined:"

I have taken several pictures of all these steps. If needed I can send it with Telegram.

JvD12 commented 3 years ago

@slaesh question; I expect you mean with the orange LED the red LED? On the schematics and the BOM I see 5 LEDs in total. But I have/see only 3 LEDs. Also I do not have a blinking LED.

JvD12 commented 3 years ago

Last week I had a call with slaesh about this issue. He provides good support! Today I received another CC2652 stick but unfortnely with the same results. slaesh asked me to test it also on the Raspbian OS but also with the same results.

Is it possible to get custom coordinator software without the PAN ID in use check?

Koenkk commented 3 years ago

Is it possible to get custom coordinator software without the PAN ID in use check?

This is not possible, this check is in the closed source parts of the coordinator firmware. I see we did not try to sniff the traffic when starting fails, is this something you can do? https://www.zigbee2mqtt.io/how_tos/how_to_sniff_zigbee_traffic.html

JvD12 commented 3 years ago

Yes, I can do that. See attached file below.

08:00 start sniffing 08:00 start zigbee2mqtt

Zigbee2MQTT:info  2021-01-20 19:01:30: Logging to console and directory: '/share/zigbee2mqtt/log/2021-01-20.19-01-29' filename: log.txt
Zigbee2MQTT:info  2021-01-20 19:01:30: Starting Zigbee2MQTT version 1.17.0 (commit #1.17.0)
Zigbee2MQTT:info  2021-01-20 19:01:30: Starting zigbee-herdsman (0.13.46)
Zigbee2MQTT:info  2021-01-20 19:01:46: zigbee-herdsman started
Zigbee2MQTT:info  2021-01-20 19:01:46: Coordinator firmware version: '{"meta":{"maintrel":1,"majorrel":2,"minorrel":7,"product":1,"revision":20201026,"transportrev":2},"type":"zStack3x0"}'
Zigbee2MQTT:info  2021-01-20 19:01:46: Currently 0 devices are joined:
Zigbee2MQTT:warn  2021-01-20 19:01:46: `permit_join` set to  `true` in configuration.yaml.
Zigbee2MQTT:warn  2021-01-20 19:01:46: Allowing new devices to join.
Zigbee2MQTT:warn  2021-01-20 19:01:46: Set `permit_join` to `false` once you joined all devices.
Zigbee2MQTT:info  2021-01-20 19:01:46: Zigbee: allowing new devices to join.
Zigbee2MQTT:info  2021-01-20 19:01:46: Started frontend on port 0.0.0.0:8099
Zigbee2MQTT:info  2021-01-20 19:01:46: Connecting to MQTT server at mqtt://core-mosquitto
Zigbee2MQTT:info  2021-01-20 19:01:46: Connected to MQTT server
Zigbee2MQTT:info  2021-01-20 19:01:46: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'
Zigbee2MQTT:info  2021-01-20 19:01:47: MQTT publish: topic 'zigbee2mqtt/bridge/info', payload '{"commit":"1.17.0","config":{"advanced":{"adapter_concurrent":null,"adapter_delay":null,"availability_blacklist":[],"availability_blocklist":[],"availability_passlist":[],"availability_timeout":0,"availability_whitelist":[],"cache_state":true,"cache_state_persistent":true,"cache_state_send_on_startup":true,"channel":22,"elapsed":false,"ext_pan_id":[221,221,221,221,221,221,221,221],"homeassistant_discovery_topic":"homeassistant","homeassistant_legacy_triggers":true,"homeassistant_status_topic":"hass/status","last_seen":"disable","legacy_api":true,"log_directory":"/share/zigbee2mqtt/log/%TIMESTAMP%","log_file":"log.txt","log_level":"info","log_output":["console","file"],"log_rotation":true,"log_syslog":{},"pan_id":6754,"report":false,"soft_reset_timeout":0,"timestamp_format":"YYYY-MM-DD HH:mm:ss"},"ban":[],"blocklist":[],"device_options":{},"devices":{},"experimental":{"new_api":true,"output":"json"},"external_converters":[],"frontend":{"port":8099},"groups":{},"homeassistant":true,"map_options":{"graphviz":{"colors":{"fill":{"coordinator":"#e04e5d","enddevice":"#fff8ce","router":"#4ea3e0"},"font":{"coordinator":"#ffffff","enddevice":"#000000","router":"#ffffff"},"line":{"active":"#009900","inactive":"#994444"}}}},"mqtt":{"base_topic":"zigbee2mqtt","force_disable_retain":false,"include_device_information":false,"server":"mqtt://core-mosquitto","user":"MQTT"},"passlist":[],"permit_join":true,"queue":{},"serial":{"disable_led":false,"port":"/dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_4B_48-if00-port0"},"whitelist":[]},"coordinator":{"meta":{"maintrel":1,"majorrel":2,"minorrel":7,"product":1,"revision":20201026,"transportrev":2},"type":"zStack3x0"},"log_level":"info","network":{"channel":22,"extended_pan_id":"0xdddddddddddddddd","pan_id":6754},"permit_join":true,"version":"1.17.0"}'
Zigbee2MQTT:info  2021-01-20 19:01:47: MQTT publish: topic 'zigbee2mqtt/bridge/devices', payload '[{"definition":null,"endpoints":{"1":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"10":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"11":{"bindings":[],"clusters":{"input":["ssIasAce"],"output":["ssIasZone","ssIasWd"]},"configured_reportings":[]},"110":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"12":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"13":{"bindings":[],"clusters":{"input":["genOta"],"output":[]},"configured_reportings":[]},"2":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"242":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"3":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"4":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"47":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"5":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"6":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"8":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]}},"friendly_name":"Coordinator","ieee_address":"0x00124b0021cc4b48","interview_completed":true,"interviewing":false,"network_address":0,"supported":false,"type":"Coordinator"}]'
Zigbee2MQTT:info  2021-01-20 19:01:47: MQTT publish: topic 'zigbee2mqtt/bridge/groups', payload '[]'
Zigbee2MQTT:info  2021-01-20 19:01:47: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"commit":"1.17.0","coordinator":{"meta":{"maintrel":1,"majorrel":2,"minorrel":7,"product":1,"revision":20201026,"transportrev":2},"type":"zStack3x0"},"log_level":"info","network":{"channel":22,"extendedPanID":"0xdddddddddddddddd","panID":6754},"permit_join":true,"version":"1.17.0"}'

1 hour time zone difference!

08:02 connect sp120 as router 08:04 second attempt -> now sp120 connected: 

Zigbee2MQTT:info  2021-01-20 19:01:47: MQTT publish: topic 'zigbee2mqtt/bridge/groups', payload '[]'
Zigbee2MQTT:info  2021-01-20 19:01:47: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"commit":"1.17.0","coordinator":{"meta":{"maintrel":1,"majorrel":2,"minorrel":7,"product":1,"revision":20201026,"transportrev":2},"type":"zStack3x0"},"log_level":"info","network":{"channel":22,"extendedPanID":"0xdddddddddddddddd","panID":6754},"permit_join":true,"version":"1.17.0"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: Device '0x00158d000342b40e' joined
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x00158d000342b40e","ieee_address":"0x00158d000342b40e"},"type":"device_joined"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: Starting interview of '0x00158d000342b40e'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x00158d000342b40e","ieee_address":"0x00158d000342b40e","status":"started"},"type":"device_interview"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":{"friendly_name":"0x00158d000342b40e"},"type":"device_connected"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"interview_started","meta":{"friendly_name":"0x00158d000342b40e"},"type":"pairing"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x00158d000342b40e","ieee_address":"0x00158d000342b40e"},"type":"device_announce"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"0x00158d000342b40e"},"type":"device_announced"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: Successfully interviewed '0x00158d000342b40e', device has successfully been paired
Zigbee2MQTT:info  2021-01-20 19:04:14: Device '0x00158d000342b40e' is supported, identified as: Innr Smart plug (SP 120)
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"definition":{"description":"Smart plug","exposes":[{"access":5,"description":"Instantaneous measured power","name":"power","property":"power","type":"numeric","unit":"W"},{"access":5,"description":"Instantaneous measured electrical current","name":"current","property":"current","type":"numeric","unit":"A"},{"access":5,"description":"Measured electrical potential value","name":"voltage","property":"voltage","type":"numeric","unit":"V"},{"features":[{"access":7,"description":"On/off state of the switch","name":"state","property":"state","type":"binary","value_off":"OFF","value_on":"ON","value_toggle":"TOGGLE"}],"type":"switch"},{"access":5,"description":"Sum of consumed energy","name":"energy","property":"energy","type":"numeric","unit":"kWh"},{"access":1,"description":"Link quality (signal strength)","name":"linkquality","property":"linkquality","type":"numeric","unit":"lqi","value_max":255,"value_min":0}],"model":"SP 120","vendor":"Innr"},"friendly_name":"0x00158d000342b40e","ieee_address":"0x00158d000342b40e","status":"successful","supported":true},"type":"device_interview"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'zigbee2mqtt/bridge/devices', payload '[{"definition":null,"endpoints":{"1":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"10":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"11":{"bindings":[],"clusters":{"input":["ssIasAce"],"output":["ssIasZone","ssIasWd"]},"configured_reportings":[]},"110":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"12":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"13":{"bindings":[],"clusters":{"input":["genOta"],"output":[]},"configured_reportings":[]},"2":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"242":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"3":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"4":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"47":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"5":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"6":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"8":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]}},"friendly_name":"Coordinator","ieee_address":"0x00124b0021cc4b48","interview_completed":true,"interviewing":false,"network_address":0,"supported":false,"type":"Coordinator"},{"date_code":"20171027-100","definition":{"description":"Smart plug","exposes":[{"access":5,"description":"Instantaneous measured power","name":"power","property":"power","type":"numeric","unit":"W"},{"access":5,"description":"Instantaneous measured electrical current","name":"current","property":"current","type":"numeric","unit":"A"},{"access":5,"description":"Measured electrical potential value","name":"voltage","property":"voltage","type":"numeric","unit":"V"},{"features":[{"access":7,"description":"On/off state of the switch","name":"state","property":"state","type":"binary","value_off":"OFF","value_on":"ON","value_toggle":"TOGGLE"}],"type":"switch"},{"access":5,"description":"Sum of consumed energy","name":"energy","property":"energy","type":"numeric","unit":"kWh"},{"access":1,"description":"Link quality (signal strength)","name":"linkquality","property":"linkquality","type":"numeric","unit":"lqi","value_max":255,"value_min":0}],"model":"SP 120","vendor":"Innr"},"endpoints":{"1":{"bindings":[],"clusters":{"input":["genBasic","genGroups","genIdentify","genOnOff","genLevelCtrl","genScenes","haElectricalMeasurement","seMetering","genTime"],"output":["genIdentify","genOta","genTime"]},"configured_reportings":[]},"2":{"bindings":[],"clusters":{"input":["touchlink"],"output":[]},"configured_reportings":[]}},"friendly_name":"0x00158d000342b40e","ieee_address":"0x00158d000342b40e","interview_completed":true,"interviewing":false,"model_id":"SP 120","network_address":59288,"power_source":"Mains (single phase)","software_build_id":"2.0","supported":true,"type":"Router"}]'
Zigbee2MQTT:info  2021-01-20 19:04:14: Configuring '0x00158d000342b40e'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"interview_successful","meta":{"description":"Smart plug","friendly_name":"0x00158d000342b40e","model":"SP 120","supported":true,"vendor":"Innr"},"type":"pairing"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'homeassistant/sensor/0x00158d000342b40e/power/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state"}],"device":{"identifiers":["zigbee2mqtt_0x00158d000342b40e"],"manufacturer":"Innr","model":"Smart plug (SP 120)","name":"0x00158d000342b40e","sw_version":"Zigbee2MQTT 1.17.0"},"icon":"mdi:flash","json_attributes_topic":"zigbee2mqtt/0x00158d000342b40e","name":"0x00158d000342b40e power","state_topic":"zigbee2mqtt/0x00158d000342b40e","unique_id":"0x00158d000342b40e_power_zigbee2mqtt","unit_of_measurement":"W","value_template":"{{ value_json.power }}"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'homeassistant/sensor/0x00158d000342b40e/current/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state"}],"device":{"identifiers":["zigbee2mqtt_0x00158d000342b40e"],"manufacturer":"Innr","model":"Smart plug (SP 120)","name":"0x00158d000342b40e","sw_version":"Zigbee2MQTT 1.17.0"},"icon":"mdi:current-ac","json_attributes_topic":"zigbee2mqtt/0x00158d000342b40e","name":"0x00158d000342b40e current","state_topic":"zigbee2mqtt/0x00158d000342b40e","unique_id":"0x00158d000342b40e_current_zigbee2mqtt","unit_of_measurement":"A","value_template":"{{ value_json.current }}"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'homeassistant/sensor/0x00158d000342b40e/voltage/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state"}],"device":{"identifiers":["zigbee2mqtt_0x00158d000342b40e"],"manufacturer":"Innr","model":"Smart plug (SP 120)","name":"0x00158d000342b40e","sw_version":"Zigbee2MQTT 1.17.0"},"icon":"mdi:alpha-v","json_attributes_topic":"zigbee2mqtt/0x00158d000342b40e","name":"0x00158d000342b40e voltage","state_topic":"zigbee2mqtt/0x00158d000342b40e","unique_id":"0x00158d000342b40e_voltage_zigbee2mqtt","unit_of_measurement":"V","value_template":"{{ value_json.voltage }}"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'homeassistant/switch/0x00158d000342b40e/switch/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state"}],"command_topic":"zigbee2mqtt/0x00158d000342b40e/set","device":{"identifiers":["zigbee2mqtt_0x00158d000342b40e"],"manufacturer":"Innr","model":"Smart plug (SP 120)","name":"0x00158d000342b40e","sw_version":"Zigbee2MQTT 1.17.0"},"json_attributes_topic":"zigbee2mqtt/0x00158d000342b40e","name":"0x00158d000342b40e","payload_off":"OFF","payload_on":"ON","state_topic":"zigbee2mqtt/0x00158d000342b40e","unique_id":"0x00158d000342b40e_switch_zigbee2mqtt","value_template":"{{ value_json.state }}"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'homeassistant/sensor/0x00158d000342b40e/energy/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state"}],"device":{"identifiers":["zigbee2mqtt_0x00158d000342b40e"],"manufacturer":"Innr","model":"Smart plug (SP 120)","name":"0x00158d000342b40e","sw_version":"Zigbee2MQTT 1.17.0"},"icon":"mdi:power-plug","json_attributes_topic":"zigbee2mqtt/0x00158d000342b40e","name":"0x00158d000342b40e energy","state_topic":"zigbee2mqtt/0x00158d000342b40e","unique_id":"0x00158d000342b40e_energy_zigbee2mqtt","unit_of_measurement":"kWh","value_template":"{{ value_json.energy }}"}'
Zigbee2MQTT:info  2021-01-20 19:04:14: MQTT publish: topic 'homeassistant/sensor/0x00158d000342b40e/linkquality/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state"}],"device":{"identifiers":["zigbee2mqtt_0x00158d000342b40e"],"manufacturer":"Innr","model":"Smart plug (SP 120)","name":"0x00158d000342b40e","sw_version":"Zigbee2MQTT 1.17.0"},"icon":"mdi:signal","json_attributes_topic":"zigbee2mqtt/0x00158d000342b40e","name":"0x00158d000342b40e linkquality","state_topic":"zigbee2mqtt/0x00158d000342b40e","unique_id":"0x00158d000342b40e_linkquality_zigbee2mqtt","unit_of_measurement":"lqi","value_template":"{{ value_json.linkquality }}"}'
Zigbee2MQTT:info  2021-01-20 19:04:15: Successfully configured '0x00158d000342b40e'
Zigbee2MQTT:info  2021-01-20 19:04:15: MQTT publish: topic 'zigbee2mqtt/bridge/devices', payload '[{"definition":null,"endpoints":{"1":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"10":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"11":{"bindings":[],"clusters":{"input":["ssIasAce"],"output":["ssIasZone","ssIasWd"]},"configured_reportings":[]},"110":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"12":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"13":{"bindings":[],"clusters":{"input":["genOta"],"output":[]},"configured_reportings":[]},"2":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"242":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"3":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"4":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"47":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"5":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"6":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]},"8":{"bindings":[],"clusters":{"input":[],"output":[]},"configured_reportings":[]}},"friendly_name":"Coordinator","ieee_address":"0x00124b0021cc4b48","interview_completed":true,"interviewing":false,"network_address":0,"supported":false,"type":"Coordinator"},{"date_code":"20171027-100","definition":{"description":"Smart plug","exposes":[{"access":5,"description":"Instantaneous measured power","name":"power","property":"power","type":"numeric","unit":"W"},{"access":5,"description":"Instantaneous measured electrical current","name":"current","property":"current","type":"numeric","unit":"A"},{"access":5,"description":"Measured electrical potential value","name":"voltage","property":"voltage","type":"numeric","unit":"V"},{"features":[{"access":7,"description":"On/off state of the switch","name":"state","property":"state","type":"binary","value_off":"OFF","value_on":"ON","value_toggle":"TOGGLE"}],"type":"switch"},{"access":5,"description":"Sum of consumed energy","name":"energy","property":"energy","type":"numeric","unit":"kWh"},{"access":1,"description":"Link quality (signal strength)","name":"linkquality","property":"linkquality","type":"numeric","unit":"lqi","value_max":255,"value_min":0}],"model":"SP 120","vendor":"Innr"},"endpoints":{"1":{"bindings":[{"cluster":"genOnOff","target":{"endpoint":1,"ieee_address":"0x00124b0021cc4b48","type":"endpoint"}},{"cluster":"haElectricalMeasurement","target":{"endpoint":1,"ieee_address":"0x00124b0021cc4b48","type":"endpoint"}},{"cluster":"seMetering","target":{"endpoint":1,"ieee_address":"0x00124b0021cc4b48","type":"endpoint"}}],"clusters":{"input":["genBasic","genGroups","genIdentify","genOnOff","genLevelCtrl","genScenes","haElectricalMeasurement","seMetering","genTime"],"output":["genIdentify","genOta","genTime"]},"configured_reportings":[{"attribute":"onOff","cluster":"genOnOff","maximum_report_interval":3600,"minimum_report_interval":0,"reportable_change":0},{"attribute":"activePower","cluster":"haElectricalMeasurement","maximum_report_interval":3600,"minimum_report_interval":5,"reportable_change":1},{"attribute":"rmsCurrent","cluster":"haElectricalMeasurement","maximum_report_interval":3600,"minimum_report_interval":5,"reportable_change":1},{"attribute":"rmsVoltage","cluster":"haElectricalMeasurement","maximum_report_interval":3600,"minimum_report_interval":5,"reportable_change":1},{"attribute":"currentSummDelivered","cluster":"seMetering","maximum_report_interval":3600,"minimum_report_interval":5,"reportable_change":[1,1]}]},"2":{"bindings":[],"clusters":{"input":["touchlink"],"output":[]},"configured_reportings":[]}},"friendly_name":"0x00158d000342b40e","ieee_address":"0x00158d000342b40e","interview_completed":true,"interviewing":false,"model_id":"SP 120","network_address":59288,"power_source":"Mains (single phase)","software_build_id":"2.0","supported":true,"type":"Router"}]'
Zigbee2MQTT:info  2021-01-20 19:04:21: MQTT publish: topic 'zigbee2mqtt/0x00158d000342b40e', payload '{"linkquality":66,"voltage":237}'
Zigbee2MQTT:info  2021-01-20 19:04:36: MQTT publish: topic 'zigbee2mqtt/0x00158d000342b40e', payload '{"linkquality":63,"voltage":234}'
Zigbee2MQTT:info  2021-01-20 19:04:49: MQTT publish: topic 'zigbee2mqtt/0x00158d000342b40e', payload '{"linkquality":57,"voltage":237}'
Zigbee2MQTT:info  2021-01-20 19:04:54: MQTT publish: topic 'zigbee2mqtt/0x00158d000342b40e', payload '{"linkquality":60,"voltage":234}'

08:05 toggle switch in home assistant 5 times

08:06 wait 1 minute without doing anything.

08:07 restart zigbee2mqtt add on (around packet No. 339)

Zigbee2MQTT:info  2021-01-20 19:07:41: Logging to console and directory: '/share/zigbee2mqtt/log/2021-01-20.19-07-39' filename: log.txt
Zigbee2MQTT:info  2021-01-20 19:07:41: Starting Zigbee2MQTT version 1.17.0 (commit #1.17.0)
Zigbee2MQTT:info  2021-01-20 19:07:41: Starting zigbee-herdsman (0.13.46)

08:08 first error

Zigbee2MQTT:error 2021-01-20 19:08:49: Error while starting zigbee-herdsman
Zigbee2MQTT:error 2021-01-20 19:08:49: Failed to start zigbee
Zigbee2MQTT:error 2021-01-20 19:08:49: Exiting...
Zigbee2MQTT:error 2021-01-20 19:08:49: Error: AREQ - ZDO - stateChangeInd after 60000ms
    at Timeout._onTimeout (/zigbee2mqtt-1.17.0/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7)

08:10 and second error

Zigbee2MQTT:info  2021-01-20 19:08:56: Logging to console and directory: '/share/zigbee2mqtt/log/2021-01-20.19-08-55' filename: log.txt
Zigbee2MQTT:info  2021-01-20 19:08:56: Starting Zigbee2MQTT version 1.17.0 (commit #1.17.0)
Zigbee2MQTT:info  2021-01-20 19:08:56: Starting zigbee-herdsman (0.13.46)
Zigbee2MQTT:error 2021-01-20 19:10:10: Error while starting zigbee-herdsman
Zigbee2MQTT:error 2021-01-20 19:10:10: Failed to start zigbee
Zigbee2MQTT:error 2021-01-20 19:10:10: Exiting...
Zigbee2MQTT:error 2021-01-20 19:10:10: Error: Coordinator failed to start, probably the panID is already in use, try a different panID or channel
    at /zigbee2mqtt-1.17.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:172:23
    at Generator.throw (<anonymous>)
    at rejected (/zigbee2mqtt-1.17.0/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/startZnp.js:25:65)
npm
 ERR! code ELIFECYCLE
npm ERR! errno 1

Attached the Zigbee sniffer log of all these steps made with Wireshark

Zigbee logging.zip

Koenkk commented 3 years ago

Unfortunately nothing to see here. It goes wrong on no 341, coordinator sends a beacon request (indicating it wants to setup a new network), SP 120 answers so coordinator refuses to start.

Since you now have 2 coordinators, could you send one to me so I can try to reproduce this issue? If yes please contact me on telegram (@koenkk)

github-actions[bot] commented 3 years ago

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days

JvD12 commented 3 years ago

For some reason the programmed firmware was corrupt. AFter programming the same hardware with the same commands but on another PC eveything works fine. More detailed anaylsis is needed to understand why the programming failed. The tool indicates eveything was fine. For now this issue can be closed

dummys commented 2 years ago

@JvD12 may i ask you if you encounter the same problem again ? Like after upgrading your instance, or rebooting it ?

JvD12 commented 2 years ago

No, after programming it with another pc everything works fine. Also after reboots, (unexpected) power cycles or updates of the home assistant software

GeorgeCastanza commented 2 years ago

I've got this problem now. I have/had the issue #8670 so reflashed Slaesh's stick and a new install of zigbee2mqtt (new image of Armbian). Now the stick wont start, due herdsman failing.

I've reflashed on multiple computers (windows and pi and Odroid). Even with different firmwares - using Slaesh's test file which showed different colored LEDs - so it's flashing. Through it all, herdsmen will not start.

I've tried /dev/ttyUSB0 and specific ID. I have write permission to the port.

image

Note, it seems that if I restore a backup of zigbee2mqtt, it does start. But I then am back in my orginal problem of not being able to join any devices. #8670

parkwart commented 2 years ago

ran into this issue after I added network_key to my configuration (just got my slaesh stick yesterday and noticed after reading the docs that I was using the default key for zigbee2mqtt).

after hours of flashing, docker-compose up and downs I somehow fixed it by:

  1. docker-compose down
  2. deleted the entire data volume
  3. flashed the stick using JelmerT cc2538-bsl, used fw CC2652RB_coordinator_20210708.zip on raspberry pi
  4. physically cut off power from my raspberry pi
  5. removed all light bulbs from power source (aka zigbee routers)
  6. factory reset all motion sensors (aka zigbee end-devices)
  7. made a coffee and drank it
  8. plugged in raspberry again
  9. docker compose up

finally zigbee2mqtt started and it works again 🥳. i was able to set a new network_key and was not forced to switch to another pan_id or something like that.

after that I repaired all devices. first the routers (bulbs), then the end-devices (motion sensors). I paired the end-devices at their designated location to ensure that they are connected to the next best router.