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.84k stars 1.65k forks source link

CC1352P-2 does not start - same issue as #156 with different controller #3364

Closed hartmood closed 4 years ago

hartmood commented 4 years ago

Bug Report What happened Same issue as #156 but with CC1352P-2

What did you expect to happen Zigbee2mqtt should start

How to reproduce it (minimal and precise) Zigbee2mqtt does not start each time I start with 'npm start'

Debug Info Zigbee2mqtt version: 1.12.2 Adapter hardware: CC1352P-2 Adapter firmware version: 20191106

2020_04_14_z2m_log.txt

BudBundi commented 4 years ago

Bug Report

What happened

My coordinator also won't start anymore. It is a CC26X2R1 Rev E Try to install FW CC26X2R1_20200328 after this try the error Error: SREQ '--> SYS - osalNvRead - {"id":96,"offset":0,"len":1,"value":{"type":"Buffer","data":[85]}}' failed with status '2' (expected '0') persists. Try to flash FW versions CC26X2R1_20191106, CC26X2R1_20200229, CC26X2R1_20200306, CC26X2R1_20200312 and CC26X2R1_20200328 With UNIFLASH following https://www.zigbee2mqtt.io/information/flashing_via_uniflash.html and with Flash Programmer 2. The error persists

Also try to start with default config without backup and check write access to port.

What did you expect to happen

z2m to start

How to reproduce it (minimal and precise)

flash fw try to start

Debug Info

Zigbee2mqtt version: Docker image koenkk/zigbee2mqtt:latest-dev 1.12.2-dev on RaspPi4 4GB Adapter hardware: CC26X2R1 Rev E Adapter firmware version: CC26X2R1_20200328

Logfile with DEBUG=* Network key revoked

Koenkk commented 4 years ago

@BudBundi can you check if this is a regression in the dev branch by switching to 1.12.2 (non-dev)?

hartmood commented 4 years ago

I just re-flashed and it works now - but as far as I can see not every device re-connects. I am happy to go back to a previous version if I'd knew how :-)

noohi commented 4 years ago

Had the same issue with the latest dev release and CC1352 after updating the firmware and the docker, tried reflashing, button pressing, nothing helped. Went back to 1.12.2, kept the new firmware, and it started.

Could be a coincidence since these USB issues are seemingly random, currently don't want to risk retrying due to the entire house being "unusable", but if you think it needs confirmation and there is something to it that was changed in the latest dev releases, I can retest as this issue is plaguing me from time to time.

Btw I have cc1352, got cc26X2R1 as someone said they don't have as much USB issues, but it turned out to be identical. Tried many USB controllers, nothing helps stabilize it, and chip revisions are newer.

Koenkk commented 4 years ago

@noohi can you try if switching back to the dev branch gives the same issue again? I'm asking because something has been changed there related to this. If you could provide me the herdsman debug log I can check how to fix it.

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

noohi commented 4 years ago

@Koenkk, thanks for your interest.

OK, now of course it works, so it could be something with restoring the database on upgrades. Will keep deep logging at hand when it comes up next time.

Attaching the pre-button press adapter on reboot issue, that is much more common and happen this time on rebooting the machine, probably cannot be fixed, but just in case.

`Using '/app/data' as data directory, ,

zigbee2mqtt@1.12.2-dev start /app, node index.js, , zigbee2mqtt:info 2020-04-15 15:59:09: Logging to console and directory: '/app/data/log/2020-04-15.15-59-09' filename: log.txt, zigbee2mqtt:debug 2020-04-15 15:59:09: Removing old log directory '/app/data/log/2020-04-15.15-53-03', zigbee2mqtt:debug 2020-04-15 15:59:09: Loaded state from file /app/data/state.json, zigbee2mqtt:info 2020-04-15 15:59:09: Starting zigbee2mqtt version 1.12.2-dev (commit #62254bb), zigbee2mqtt:info 2020-04-15 15:59:09: Starting zigbee-herdsman..., zigbee2mqtt:debug 2020-04-15 15:59:09: Using zigbee-herdsman with settings: '{"network":{"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11],"networkKey":"HIDDEN"},"databasePath":"/app/data/database.db","databaseBackupPath":"/app/data/database.db.backup","backupPath":"/app/data/coordinator_backup.json","serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/ttyACM0","adapter":"zstack"},"adapter":{"concurrent":null}}', 2020-04-15T13:59:09.397Z zigbee-herdsman:adapter Path '/dev/ttyACM0' is valid for 'ZStackAdapter', 2020-04-15T13:59:09.397Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/ttyACM0","adapter":"zstack"},"databasePath":"/app/data/database.db","databaseBackupPath":"/app/data/database.db.backup","backupPath":"/app/data/coordinator_backup.json","adapter":{"concurrent":null}}', 2020-04-15T13:59:09.399Z zigbee-herdsman:adapter:zStack:znp:log Opening SerialPort with /dev/ttyACM0 and {"baudRate":115200,"rtscts":true,"autoOpen":false}, 2020-04-15T13:59:09.400Z zigbee-herdsman:adapter:zStack:znp:log Serialport opened, 2020-04-15T13:59:09.400Z zigbee-herdsman:adapter:zStack:znp:log Writing skip bootloader payload, 2020-04-15T13:59:09.400Z zigbee-herdsman:adapter:zStack:unpi:writer --> buffer [239], 2020-04-15T13:59:10.402Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1}, 2020-04-15T13:59:10.402Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32], 2020-04-15T13:59:13.013Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,5,69,196,176,99,1,72], 2020-04-15T13:59:13.013Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,5,69,196,176,99,1,72], 2020-04-15T13:59:13.014Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [96,126], 2020-04-15T13:59:13.014Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,5,69,196,176,99,1,72,96,126], 2020-04-15T13:59:13.014Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 5 - 2 - 5 - 196 - [176,99,1,72,96] - 126, 2020-04-15T13:59:13.014Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":25520,"relaycount":1,"relaylist":[24648]}, 2020-04-15T13:59:13.015Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:13.026Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,5,69,196,247,37,1,111], 2020-04-15T13:59:13.026Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,5,69,196,247,37,1,111], 2020-04-15T13:59:13.027Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [238,214], 2020-04-15T13:59:13.027Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,5,69,196,247,37,1,111,238,214], 2020-04-15T13:59:13.027Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 5 - 2 - 5 - 196 - [247,37,1,111,238] - 214, 2020-04-15T13:59:13.027Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":9719,"relaycount":1,"relaylist":[61039]}, 2020-04-15T13:59:13.027Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:13.062Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,27,68,129,0,0,6,0], 2020-04-15T13:59:13.062Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0], 2020-04-15T13:59:13.062Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [176,99,11,1,0,15,0,251], 2020-04-15T13:59:13.062Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0,176,99,11,1,0,15,0,251], 2020-04-15T13:59:13.063Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [142,143,0,0,7,24,124,10], 2020-04-15T13:59:13.063Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0,176,99,11,1,0,15,0,251,142,143,0,0,7,24,124,10], 2020-04-15T13:59:13.064Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,16,0,72,96,28,185], 2020-04-15T13:59:13.064Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0,176,99,11,1,0,15,0,251,142,143,0,0,7,24,124,10,0,0,16,0,72,96,28,185], 2020-04-15T13:59:13.064Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 27 - 2 - 4 - 129 - [0,0,6,0,176,99,11,1,0,15,0,251,142,143,0,0,7,24,124,10,0,0,16,0,72,96,28] - 185, 2020-04-15T13:59:13.064Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":25520,"srcendpoint":11,"dstendpoint":1,"wasbroadcast":0,"linkquality":15,"securityuse":0,"timestamp":9408251,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,124,10,0,0,16,0]}}, 2020-04-15T13:59:13.065Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:13.075Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,27,68,129,0,0,6,0], 2020-04-15T13:59:13.075Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0], 2020-04-15T13:59:13.075Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [247,37,11,1,0,24,0,36], 2020-04-15T13:59:13.075Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0,247,37,11,1,0,24,0,36], 2020-04-15T13:59:13.076Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [146,143,0,0,7,24,97,10], 2020-04-15T13:59:13.076Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0,247,37,11,1,0,24,0,36,146,143,0,0,7,24,97,10], 2020-04-15T13:59:13.077Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,16,0,111,238,28,216], 2020-04-15T13:59:13.077Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0,247,37,11,1,0,24,0,36,146,143,0,0,7,24,97,10,0,0,16,0,111,238,28,216], 2020-04-15T13:59:13.077Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 27 - 2 - 4 - 129 - [0,0,6,0,247,37,11,1,0,24,0,36,146,143,0,0,7,24,97,10,0,0,16,0,111,238,28] - 216, 2020-04-15T13:59:13.077Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":9719,"srcendpoint":11,"dstendpoint":1,"wasbroadcast":0,"linkquality":24,"securityuse":0,"timestamp":9409060,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,97,10,0,0,16,0]}}, 2020-04-15T13:59:13.077Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:13.543Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,9,69,196,101,177,3,114], 2020-04-15T13:59:13.543Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,9,69,196,101,177,3,114], 2020-04-15T13:59:13.544Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [198,154,44,72,96,117], 2020-04-15T13:59:13.544Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,9,69,196,101,177,3,114,198,154,44,72,96,117], 2020-04-15T13:59:13.544Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 9 - 2 - 5 - 196 - [101,177,3,114,198,154,44,72,96] - 117, 2020-04-15T13:59:13.544Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":45413,"relaycount":3,"relaylist":[50802,11418,24648]}, 2020-04-15T13:59:13.544Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:13.624Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,27,68,129,0,0,6,4], 2020-04-15T13:59:13.624Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,4], 2020-04-15T13:59:13.624Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [101,177,1,1,0,15,0,56], 2020-04-15T13:59:13.624Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,4,101,177,1,1,0,15,0,56], 2020-04-15T13:59:13.625Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [24,144,0,0,7,24,2,10], 2020-04-15T13:59:13.625Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,4,101,177,1,1,0,15,0,56,24,144,0,0,7,24,2,10], 2020-04-15T13:59:13.626Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,24,1,72,96,26,139], 2020-04-15T13:59:13.626Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,4,101,177,1,1,0,15,0,56,24,144,0,0,7,24,2,10,0,0,24,1,72,96,26,139], 2020-04-15T13:59:13.626Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 27 - 2 - 4 - 129 - [0,0,6,4,101,177,1,1,0,15,0,56,24,144,0,0,7,24,2,10,0,0,24,1,72,96,26] - 139, 2020-04-15T13:59:13.626Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":1030,"srcaddr":45413,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":15,"securityuse":0,"timestamp":9443384,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,2,10,0,0,24,1]}}, 2020-04-15T13:59:13.626Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:14.522Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,7,69,196,62,2,2,11], 2020-04-15T13:59:14.522Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,7,69,196,62,2,2,11], 2020-04-15T13:59:14.522Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [90,72,96,193], 2020-04-15T13:59:14.522Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,7,69,196,62,2,2,11,90,72,96,193], 2020-04-15T13:59:14.522Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 7 - 2 - 5 - 196 - [62,2,2,11,90,72,96] - 193, 2020-04-15T13:59:14.523Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":574,"relaycount":2,"relaylist":[23051,24648]}, 2020-04-15T13:59:14.523Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:14.580Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,9,69,196,57,120,3,27], 2020-04-15T13:59:14.580Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,9,69,196,57,120,3,27], 2020-04-15T13:59:14.581Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [225,247,37,111,238,99], 2020-04-15T13:59:14.581Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,9,69,196,57,120,3,27,225,247,37,111,238,99], 2020-04-15T13:59:14.581Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 9 - 2 - 5 - 196 - [57,120,3,27,225,247,37,111,238] - 99, 2020-04-15T13:59:14.581Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":30777,"relaycount":3,"relaylist":[57627,9719,61039]}, 2020-04-15T13:59:14.581Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:14.604Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,28,68,129,0,0,0,4], 2020-04-15T13:59:14.604Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4], 2020-04-15T13:59:14.605Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [62,2,2,1,0,15,0,121], 2020-04-15T13:59:14.605Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,1,0,15,0,121], 2020-04-15T13:59:14.605Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [7,145,0,0,8,8,141,10], 2020-04-15T13:59:14.605Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,1,0,15,0,121,7,145,0,0,8,8,141,10], 2020-04-15T13:59:14.606Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,33,214,120,72,96,27], 2020-04-15T13:59:14.606Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,1,0,15,0,121,7,145,0,0,8,8,141,10,0,0,33,214,120,72,96,27], 2020-04-15T13:59:14.606Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [57], 2020-04-15T13:59:14.606Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,1,0,15,0,121,7,145,0,0,8,8,141,10,0,0,33,214,120,72,96,27,57], 2020-04-15T13:59:14.606Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 28 - 2 - 4 - 129 - [0,0,0,4,62,2,2,1,0,15,0,121,7,145,0,0,8,8,141,10,0,0,33,214,120,72,96,27] - 57, 2020-04-15T13:59:14.606Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":1024,"srcaddr":574,"srcendpoint":2,"dstendpoint":1,"wasbroadcast":0,"linkquality":15,"securityuse":0,"timestamp":9504633,"transseqnumber":0,"len":8,"data":{"type":"Buffer","data":[8,141,10,0,0,33,214,120]}}, 2020-04-15T13:59:14.607Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:14.645Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,27,68,129,0,0,6,0], 2020-04-15T13:59:14.645Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0], 2020-04-15T13:59:14.646Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [57,120,3,1,0,27,0,78], 2020-04-15T13:59:14.646Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0,57,120,3,1,0,27,0,78], 2020-04-15T13:59:14.647Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [17,145,0,0,7,24,135,10], 2020-04-15T13:59:14.647Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0,57,120,3,1,0,27,0,78,17,145,0,0,7,24,135,10], 2020-04-15T13:59:14.647Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,16,1,111,238,26,86], 2020-04-15T13:59:14.647Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,6,0,57,120,3,1,0,27,0,78,17,145,0,0,7,24,135,10,0,0,16,1,111,238,26,86], 2020-04-15T13:59:14.648Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 27 - 2 - 4 - 129 - [0,0,6,0,57,120,3,1,0,27,0,78,17,145,0,0,7,24,135,10,0,0,16,1,111,238,26] - 86, 2020-04-15T13:59:14.648Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":30777,"srcendpoint":3,"dstendpoint":1,"wasbroadcast":0,"linkquality":27,"securityuse":0,"timestamp":9507150,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,135,10,0,0,16,1]}}, 2020-04-15T13:59:14.648Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:15.012Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,5,69,196,176,99,1,72], 2020-04-15T13:59:15.012Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,5,69,196,176,99,1,72], 2020-04-15T13:59:15.013Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [96,126], 2020-04-15T13:59:15.013Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,5,69,196,176,99,1,72,96,126], 2020-04-15T13:59:15.013Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 5 - 2 - 5 - 196 - [176,99,1,72,96] - 126, 2020-04-15T13:59:15.013Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":25520,"relaycount":1,"relaylist":[24648]}, 2020-04-15T13:59:15.013Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:15.029Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,5,69,196,247,37,1,111], 2020-04-15T13:59:15.029Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,5,69,196,247,37,1,111], 2020-04-15T13:59:15.029Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [238,214], 2020-04-15T13:59:15.029Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,5,69,196,247,37,1,111,238,214], 2020-04-15T13:59:15.030Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 5 - 2 - 5 - 196 - [247,37,1,111,238] - 214, 2020-04-15T13:59:15.030Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":9719,"relaycount":1,"relaylist":[61039]}, 2020-04-15T13:59:15.030Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:15.058Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,27,68,129,0,0,8,0], 2020-04-15T13:59:15.059Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,8,0], 2020-04-15T13:59:15.059Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [176,99,11,1,0,15,0,112], 2020-04-15T13:59:15.059Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,8,0,176,99,11,1,0,15,0,112], 2020-04-15T13:59:15.060Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [118,145,0,0,7,24,125,10], 2020-04-15T13:59:15.060Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,8,0,176,99,11,1,0,15,0,112,118,145,0,0,7,24,125,10], 2020-04-15T13:59:15.060Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,32,1,72,96,28,234], 2020-04-15T13:59:15.061Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,8,0,176,99,11,1,0,15,0,112,118,145,0,0,7,24,125,10,0,0,32,1,72,96,28,234], 2020-04-15T13:59:15.061Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 27 - 2 - 4 - 129 - [0,0,8,0,176,99,11,1,0,15,0,112,118,145,0,0,7,24,125,10,0,0,32,1,72,96,28] - 234, 2020-04-15T13:59:15.061Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":8,"srcaddr":25520,"srcendpoint":11,"dstendpoint":1,"wasbroadcast":0,"linkquality":15,"securityuse":0,"timestamp":9533040,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,125,10,0,0,32,1]}}, 2020-04-15T13:59:15.061Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:15.074Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,27,68,129,0,0,8,0], 2020-04-15T13:59:15.074Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,8,0], 2020-04-15T13:59:15.075Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [247,37,11,1,0,24,0,86], 2020-04-15T13:59:15.075Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,8,0,247,37,11,1,0,24,0,86], 2020-04-15T13:59:15.076Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [122,145,0,0,7,24,98,10], 2020-04-15T13:59:15.076Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,8,0,247,37,11,1,0,24,0,86,122,145,0,0,7,24,98,10], 2020-04-15T13:59:15.076Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,32,1,111,238,28,96], 2020-04-15T13:59:15.077Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,8,0,247,37,11,1,0,24,0,86,122,145,0,0,7,24,98,10,0,0,32,1,111,238,28,96], 2020-04-15T13:59:15.077Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 27 - 2 - 4 - 129 - [0,0,8,0,247,37,11,1,0,24,0,86,122,145,0,0,7,24,98,10,0,0,32,1,111,238,28] - 96, 2020-04-15T13:59:15.077Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":8,"srcaddr":9719,"srcendpoint":11,"dstendpoint":1,"wasbroadcast":0,"linkquality":24,"securityuse":0,"timestamp":9534038,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[24,98,10,0,0,32,1]}}, 2020-04-15T13:59:15.077Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:16.167Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,28,68,129,0,0,0,4], 2020-04-15T13:59:16.167Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4], 2020-04-15T13:59:16.167Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [62,2,2,47,1,24,0,152], 2020-04-15T13:59:16.167Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,47,1,24,0,152], 2020-04-15T13:59:16.168Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [131,146,0,0,8,24,142,10], 2020-04-15T13:59:16.168Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,47,1,24,0,152,131,146,0,0,8,24,142,10], 2020-04-15T13:59:16.169Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,33,214,120,111,238,27], 2020-04-15T13:59:16.169Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,47,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27], 2020-04-15T13:59:16.171Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [221,254,28,68,129,0,0,0,4,62,2,2,13,1,24,0], 2020-04-15T13:59:16.171Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,47,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27,221,254,28,68,129,0,0,0,4,62,2,2,13,1,24,0], 2020-04-15T13:59:16.171Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 28 - 2 - 4 - 129 - [0,0,0,4,62,2,2,47,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27] - 221, 2020-04-15T13:59:16.171Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":1024,"srcaddr":574,"srcendpoint":2,"dstendpoint":47,"wasbroadcast":1,"linkquality":24,"securityuse":0,"timestamp":9601944,"transseqnumber":0,"len":8,"data":{"type":"Buffer","data":[24,142,10,0,0,33,214,120]}}, 2020-04-15T13:59:16.171Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,13,1,24,0], 2020-04-15T13:59:16.171Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [152,131,146,0,0,8,24,142], 2020-04-15T13:59:16.171Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,13,1,24,0,152,131,146,0,0,8,24,142], 2020-04-15T13:59:16.172Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [10,0,0,33,214,120,111,238], 2020-04-15T13:59:16.172Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,13,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238], 2020-04-15T13:59:16.172Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [27,255], 2020-04-15T13:59:16.172Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,13,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27,255], 2020-04-15T13:59:16.172Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 28 - 2 - 4 - 129 - [0,0,0,4,62,2,2,13,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27] - 255, 2020-04-15T13:59:16.172Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":1024,"srcaddr":574,"srcendpoint":2,"dstendpoint":13,"wasbroadcast":1,"linkquality":24,"securityuse":0,"timestamp":9601944,"transseqnumber":0,"len":8,"data":{"type":"Buffer","data":[24,142,10,0,0,33,214,120]}}, 2020-04-15T13:59:16.173Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:16.179Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,28,68,129,0,0,0,4], 2020-04-15T13:59:16.179Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4], 2020-04-15T13:59:16.180Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [62,2,2,110,1,24,0,152], 2020-04-15T13:59:16.180Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,110,1,24,0,152], 2020-04-15T13:59:16.180Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [131,146,0,0,8,24,142,10], 2020-04-15T13:59:16.180Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,110,1,24,0,152,131,146,0,0,8,24,142,10], 2020-04-15T13:59:16.181Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,33,214,120,111,238,27], 2020-04-15T13:59:16.181Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,110,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27], 2020-04-15T13:59:16.181Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [156], 2020-04-15T13:59:16.181Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,110,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27,156], 2020-04-15T13:59:16.181Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 28 - 2 - 4 - 129 - [0,0,0,4,62,2,2,110,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27] - 156, 2020-04-15T13:59:16.181Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":1024,"srcaddr":574,"srcendpoint":2,"dstendpoint":110,"wasbroadcast":1,"linkquality":24,"securityuse":0,"timestamp":9601944,"transseqnumber":0,"len":8,"data":{"type":"Buffer","data":[24,142,10,0,0,33,214,120]}}, 2020-04-15T13:59:16.181Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:16.205Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,28,68,129,0,0,0,4], 2020-04-15T13:59:16.205Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4], 2020-04-15T13:59:16.206Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [62,2,2,11,1,24,0,152], 2020-04-15T13:59:16.206Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,11,1,24,0,152], 2020-04-15T13:59:16.206Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [131,146,0,0,8,24,142,10], 2020-04-15T13:59:16.206Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,11,1,24,0,152,131,146,0,0,8,24,142,10], 2020-04-15T13:59:16.207Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,33,214,120,111,238,27], 2020-04-15T13:59:16.207Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,11,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27], 2020-04-15T13:59:16.207Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [249], 2020-04-15T13:59:16.208Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,11,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27,249], 2020-04-15T13:59:16.208Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 28 - 2 - 4 - 129 - [0,0,0,4,62,2,2,11,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27] - 249, 2020-04-15T13:59:16.208Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":1024,"srcaddr":574,"srcendpoint":2,"dstendpoint":11,"wasbroadcast":1,"linkquality":24,"securityuse":0,"timestamp":9601944,"transseqnumber":0,"len":8,"data":{"type":"Buffer","data":[24,142,10,0,0,33,214,120]}}, 2020-04-15T13:59:16.208Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], 2020-04-15T13:59:16.215Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,28,68,129,0,0,0,4], 2020-04-15T13:59:16.215Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4], 2020-04-15T13:59:16.216Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [62,2,2,8,1,24,0,152], 2020-04-15T13:59:16.216Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,8,1,24,0,152], 2020-04-15T13:59:16.216Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [131,146,0,0,8,24,142,10], 2020-04-15T13:59:16.216Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,8,1,24,0,152,131,146,0,0,8,24,142,10], 2020-04-15T13:59:16.217Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0,0,33,214,120,111,238,27], 2020-04-15T13:59:16.217Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,8,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27], 2020-04-15T13:59:16.218Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [250,254,28,68,129,0,0,0], 2020-04-15T13:59:16.218Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,8,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27,250,254,28,68,129,0,0,0], 2020-04-15T13:59:16.218Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 28 - 2 - 4 - 129 - [0,0,0,4,62,2,2,8,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27] - 250, 2020-04-15T13:59:16.218Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":1024,"srcaddr":574,"srcendpoint":2,"dstendpoint":8,"wasbroadcast":1,"linkquality":24,"securityuse":0,"timestamp":9601944,"transseqnumber":0,"len":8,"data":{"type":"Buffer","data":[24,142,10,0,0,33,214,120]}}, 2020-04-15T13:59:16.218Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0], 2020-04-15T13:59:16.219Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [4,62,2,2,1,1,24,0], 2020-04-15T13:59:16.219Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,1,1,24,0], 2020-04-15T13:59:16.219Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [152,131,146,0,0,8,24,142], 2020-04-15T13:59:16.219Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,1,1,24,0,152,131,146,0,0,8,24,142], 2020-04-15T13:59:16.220Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [10,0,0,33,214,120,111,238], 2020-04-15T13:59:16.220Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,1,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238], 2020-04-15T13:59:16.220Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [27,243], 2020-04-15T13:59:16.220Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,0,4,62,2,2,1,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27,243], 2020-04-15T13:59:16.221Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 28 - 2 - 4 - 129 - [0,0,0,4,62,2,2,1,1,24,0,152,131,146,0,0,8,24,142,10,0,0,33,214,120,111,238,27] - 243, 2020-04-15T13:59:16.221Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":1024,"srcaddr":574,"srcendpoint":2,"dstendpoint":1,"wasbroadcast":1,"linkquality":24,"securityuse":0,"timestamp":9601944,"transseqnumber":0,"len":8,"data":{"type":"Buffer","data":[24,142,10,0,0,33,214,120]}}, 2020-04-15T13:59:16.221Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [], zigbee2mqtt:error 2020-04-15 15:59:16: Error while starting zigbee-herdsman, zigbee2mqtt:error 2020-04-15 15:59:16: Failed to start zigbee, zigbee2mqtt:error 2020-04-15 15:59:16: Exiting..., zigbee2mqtt:error 2020-04-15 15:59:16: Error: Failed to connect to the adapter (Error: SRSP - SYS - ping after 6000ms), at ZStackAdapter. (/app/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/zStackAdapter.js:71:23), at Generator.throw (), at rejected (/app/node_modules/zigbee-herdsman/dist/adapter/z-stack/adapter/zStackAdapter.js:6:65), npm ERR! code ELIFECYCLE, npm ERR! errno 1, npm ERR! zigbee2mqtt@1.12.2-dev start: node index.js, npm ERR! Exit status 1,, , npm ERR! Failed at the zigbee2mqtt@1.12.2-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/2020-04-15T13_59_16_412Z-debug.log,`

BudBundi commented 4 years ago

@Koenkk, thanks for your interest.

OK, now of course it works, so it could be something with restoring the database on upgrades. Will keep deep logging at hand when it comes up next time.

For me also. Start zigbee2mqtt version 1.12.2 (commit #7d27a54) work and after that also zigbee2mqtt version 1.12.2-dev (commit #62254bb) worked. The theory with failing to restore the backup seems legit.

BudBundi commented 4 years ago

And sorry the DEBUG=* output seems to missing in the mapped log.txt files

fail.txt good.txt

Koenkk commented 4 years ago

Can you check if this has been fixed in the latest dev branch.

hartmood commented 4 years ago

Just for the records as I initially started this issue: Mine is solved. Re-flashed with steps #4 and #5 and all devices are back.

noohi commented 4 years ago

@Koenkk, thanks. As far as I'm concerned, this can be closed, upgraded these days to dev at least twice and no issues so far. Since the nature of the issue is to happen only in certain upgrade situations, it is actually unknown how to replicate the initial situation. You'll be the best judge by looking at other similar topics these days.

For the uninitiated, this is the CC1352 and CC2652 survival kit:

Koenkk commented 4 years ago

@noohi i've added this instructions to the faq.

Regarding SREQ '--> SYS - osalNvRead - {...}' failed with status '2' (expected '0') this shouldn't happen anymore because I fixed this bug in the latest dev branch.

I assume this issue can be closed as its all about the failed with status '2' issue.