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.88k stars 1.66k forks source link

CC2652P pairing failure - zigbee2mqtt crashed #20317

Closed nitr0man closed 2 months ago

nitr0man commented 9 months ago

What happened?

I'm trying to pair device to new adapter. device is paired, but no endpoints found. when pairing time expired - zigbee2mqtt just crashed, and no pairing can be retried till dongle re-plugging or waiting for some time. with old cc2531 dongle all is OK.

What did you expect to happen?

No response

How to reproduce it (minimal and precise)

No response

Zigbee2MQTT version

1.34.0 commit: 56589dcc

Adapter firmware version

20230507

Adapter

CC2652P CH9102X dongle https://www.aliexpress.com/item/1005005057048658.html

Debug log

  zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0} +33s
  zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228] +33s
Zigbee2MQTT:debug 2023-12-20 21:04:03: Received MQTT message on 'zigbee2mqtt/bridge/request/permit_join' with data '{"device":null,"time":254,"transaction":"3lv3i-2","value":true}'
Zigbee2MQTT:info  2023-12-20 21:04:03: Zigbee: allowing new devices to join.
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82,254,3,69,182,0,0,0,240] +33s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82,254,3,69,182,0,0,0,240] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82 +1ms
  zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0} +33s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0} +33s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +2ms
  zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - mgmtPermitJoinReq - {"addrmode":15,"dstaddr":65532,"duration":254,"tcsignificance":0} +57ms
  zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,37,54,15,252,255,254,0,228] +56ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,54,0,82,254,3,69,182,0,0,0,240] +11ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,54,0,82,254,3,69,182,0,0,0,240] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 54 - [0] - 82 +1ms
  zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - mgmtPermitJoinReq - {"status":0} +18ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,69,182,0,0,0,240] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 5 - 182 - [0,0,0] - 240 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - mgmtPermitJoinRsp - {"srcaddr":0,"status":0} +18ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +2ms
  zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":2,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,3,2,11,254,0]}} +18ms
  zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,2,0,30,6,0,25,3,2,11,254,0,234] +18ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103] +15ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103 +0ms
  zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0} +23ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
  zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":3,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,4,2,11,254,0]}} +20ms
  zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,3,0,30,6,0,25,4,2,11,254,0,236] +20ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,0,242,2,55] +7ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,0,242,2,55] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [0,242,2] - 55 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":0,"endpoint":242,"transid":2} +31ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,0,103] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,0,103] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [0] - 103 +1ms
  zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":0} +18ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,0,242,3,54] +3ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,0,242,3,54] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [0,242,3] - 54 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":0,"endpoint":242,"transid":3} +14ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +2ms
Zigbee2MQTT:info  2023-12-20 21:04:04: MQTT publish: topic 'zigbee2mqtt/bridge/response/permit_join', payload '{"data":{"time":254,"value":true},"status":"ok","transaction":"3lv3i-1"}'
Zigbee2MQTT:info  2023-12-20 21:04:04: MQTT publish: topic 'zigbee2mqtt/bridge/response/permit_join', payload '{"data":{"time":254,"value":true},"status":"ok","transaction":"3lv3i-2"}'
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,12,69,202,19,47,28,248,75,25,170,56,193,164,0,0,254] +17s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,12,69,202,19,47,28,248,75,25,170,56,193,164,0,0,254] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 12 - 2 - 5 - 202 - [19,47,28,248,75,25,170,56,193,164,0,0] - 254 +2ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - tcDeviceInd - {"nwkaddr":12051,"extaddr":"0xa4c138aa194bf81c","parentaddr":0} +17s
  zigbee-herdsman:controller:log Device '0xa4c138aa194bf81c' joined +51s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +15ms
  zigbee-herdsman:controller:log Device '0xa4c138aa194bf81c' accepted by handler +7ms
  zigbee-herdsman:controller:log New device '0xa4c138aa194bf81c' joined +1ms
  zigbee-herdsman:controller:log Creating device '0xa4c138aa194bf81c' +2ms
  zigbee-herdsman:controller:database:log Writing database to '/opt/zigbee2mqtt/data/database.db' +0ms
Zigbee2MQTT:info  2023-12-20 21:04:21: Device 'bedroom temp' joined
Zigbee2MQTT:info  2023-12-20 21:04:21: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"bedroom temp","ieee_address":"0xa4c138aa194bf81c"},"type":"device_joined"}'
Zigbee2MQTT:info  2023-12-20 21:04:21: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":{"friendly_name":"bedroom temp"},"type":"device_connected"}'
Zigbee2MQTT:info  2023-12-20 21:04:21: MQTT publish: topic 'zigbee2mqtt/bedroom temp/availability', payload 'online'
  zigbee-herdsman:controller:log Interview '0xa4c138aa194bf81c' start +216ms
Zigbee2MQTT:info  2023-12-20 21:04:21: Starting interview of 'bedroom temp'
Zigbee2MQTT:info  2023-12-20 21:04:21: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"bedroom temp","ieee_address":"0xa4c138aa194bf81c","status":"started"},"type":"device_interview"}'
Zigbee2MQTT:info  2023-12-20 21:04:21: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"interview_started","meta":{"friendly_name":"bedroom temp"},"type":"pairing"}'
  zigbee-herdsman:controller:device:log Interview - start device '0xa4c138aa194bf81c' +51s
  zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - nodeDescReq - {"dstaddr":12051,"nwkaddrofinterest":12051} +17s
  zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,37,2,19,47,19,47,35] +17s
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,2,0,102,254,13,69,193,19,47,19,47,28,248,75,25,170,56,193,164,128,72] +425ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,2,0,102,254,13,69,193,19,47,19,47,28,248,75,25,170,56,193,164,128,72] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 2 - [0] - 102 +1ms
  zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - nodeDescReq - {"status":0} +18s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,13,69,193,19,47,19,47,28,248,75,25,170,56,193,164,128,72] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 13 - 2 - 5 - 193 - [19,47,19,47,28,248,75,25,170,56,193,164,128] - 72 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - endDeviceAnnceInd - {"srcaddr":12051,"nwkaddr":12051,"ieeeaddr":"0xa4c138aa194bf81c","capabilities":128} +445ms
  zigbee-herdsman:controller:log Device announce '0xa4c138aa194bf81c' +219ms
Zigbee2MQTT:debug 2023-12-20 21:04:21: Device 'bedroom temp' announced itself
Zigbee2MQTT:info  2023-12-20 21:04:21: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"bedroom temp","ieee_address":"0xa4c138aa194bf81c"},"type":"device_announce"}'
Zigbee2MQTT:info  2023-12-20 21:04:21: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"announce","meta":{"friendly_name":"bedroom temp"},"type":"device_announced"}'
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +65ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,18,69,130,19,47,0,19,47,2,64,128,65,17,66,66,0,0,42,66,0,0,47] +381ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,18,69,130,19,47,0,19,47,2,64,128,65,17,66,66,0,0,42,66,0,0,47] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 18 - 2 - 5 - 130 - [19,47,0,19,47,2,64,128,65,17,66,66,0,0,42,66,0,0] - 47 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - nodeDescRsp - {"srcaddr":12051,"status":0,"nwkaddr":12051,"logicaltype_cmplxdescavai_userdescavai":2,"apsflags_freqband":64,"maccapflags":128,"manufacturercode":4417,"maxbuffersize":66,"maxintransfersize":66,"servermask":10752,"maxouttransfersize":66,"descriptorcap":0} +448ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
  zigbee-herdsman:adapter:zStack:adapter Discovering route to 12051 +55s
  zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - extRouteDisc - {"dstAddr":12051,"options":0,"radius":30} +590ms
  zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,37,69,19,47,0,30,70] +590ms
  zigbee-herdsman:controller:device:log Interview - got node descriptor for device '0xa4c138aa194bf81c' +611ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,69,0,33] +21ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,69,0,33] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 69 - [0] - 33 +1ms
  zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - extRouteDisc - {"status":0} +477ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
  zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - activeEpReq - {"dstaddr":12051,"nwkaddrofinterest":12051} +16ms
  zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,37,5,19,47,19,47,36] +16ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,5,0,97] +8ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,5,0,97] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 5 - [0] - 97 +1ms
  zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - activeEpReq - {"status":0} +13ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,6,65,128,0,2,1,2,7,1,192] +2s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,6,65,128,0,2,1,2,7,1,192] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 6 - 2 - 1 - 128 - [0,2,1,2,7,1] - 192 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- SYS - resetInd - {"reason":0,"transportrev":2,"productid":1,"majorrel":2,"minorrel":7,"hwrev":1} +3s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
  zigbee-herdsman:controller:device:log Interview - active endpoints request failed for '0xa4c138aa194bf81c', attempt 1 +10s
  zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - activeEpReq - {"dstaddr":12051,"nwkaddrofinterest":12051} +10s
  zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,37,5,19,47,19,47,36] +10s
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,5,194,163] +8s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,5,194,163] +2ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 5 - [194] - 163 +1ms
  zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - activeEpReq - {"status":194} +10s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
  zigbee-herdsman:controller:device:log Interview - active endpoints request failed for '0xa4c138aa194bf81c', attempt 2 +23ms
  zigbee-herdsman:controller:device:log Interview - quirks check for 'undefined'-'undefined'-'EndDevice' +5ms
  zigbee-herdsman:controller:device:log Interview - quirks did not match +3ms
  zigbee-herdsman:controller:device:log Interview - failed for device '0xa4c138aa194bf81c' with error 'Error: Interview failed because can not get active endpoints ('0xa4c138aa194bf81c')
  zigbee-herdsman:controller:device:log     at Device.interviewInternal (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/controller/model/device.ts:636:19)
  zigbee-herdsman:controller:device:log     at Device.interview (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/controller/model/device.ts:488:13)
  zigbee-herdsman:controller:device:log     at Controller.onDeviceJoined (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/controller/controller.ts:579:17)' +837ms
  zigbee-herdsman:controller:database:log Writing database to '/opt/zigbee2mqtt/data/database.db' +12s
  zigbee-herdsman:controller:error Interview failed for '0xa4c138aa194bf81c with error 'Error: Interview failed because can not get active endpoints ('0xa4c138aa194bf81c')' +0ms
Zigbee2MQTT:error 2023-12-20 21:04:32: Failed to interview 'bedroom temp', device has not successfully been paired
Zigbee2MQTT:info  2023-12-20 21:04:33: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"bedroom temp","ieee_address":"0xa4c138aa194bf81c","status":"failed"},"type":"device_interview"}'
Zigbee2MQTT:info  2023-12-20 21:04:33: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"interview_failed","meta":{"friendly_name":"bedroom temp"},"type":"pairing"}'
  zigbee-herdsman:controller:log Disable joining +2m
  zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":4,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,5,2,10,0,0]}} +2m
  zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,26,36,2,2,253,255,0,0,0,0,0,0,242,0,0,242,33,0,4,0,30,6,0,25,5,2,10,0,0,21] +2m
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,2,2,101] +2m
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,2,2,101] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 2 - [2] - 101 +3ms
  zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequestExt - {"status":2} +2m
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +5ms
Error: SREQ '--> AF - dataRequestExt - {"dstaddrmode":2,"dstaddr":"0x000000000000fffd","destendpoint":242,"dstpanid":0,"srcendpoint":242,"clusterid":33,"transid":4,"options":0,"radius":30,"len":6,"data":{"type":"Buffer","data":[25,5,2,10,0,0]}}' failed with status '(0x02: INVALID_PARAM)' (expected '(0x00: SUCCESS)')
    at Object.func (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:322:27)
    at Queue.executeNext (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
nitr0man commented 9 months ago

update: it's paired and work with CC1352P2_CC2652P_launchpad_coordinator_20221226. after upgrade to latest with nvram reset before z2m start - it looks to work OK too.

nitr0man commented 9 months ago

update: after a ~day version 20230507 lost all (2) temperature sensors. nothing else wasn't connected to it (plug was registered but powered off). after z2m restart temperature sensor connected OK; after a while dongle fails to communicate with sensors and plug:

warn  2023-12-27 14:17:14: Failed to ping 'zigbee heater plug' (attempt 2/2, Read 0x70b3d52b6003c2e2/1 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (SREQ '--> AF - dataRequest - {"dstaddr":5023,"destendpoint":1,"srcendpoint":1,"clusterid":0,"transid":55,"options":0,"radius":30,"len":5,"data":{"type":"Buffer","data":[16,47,0,0,0]}}' failed with status '(0x02: INVALID_PARAM)' (expected '(0x00: SUCCESS)')))
github-actions[bot] commented 3 months ago

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