Sonoff ZBDongle-P not working in Windows at all, Sonoff ZBDongle-E working only with ember driver

LamerTex commented 5 months ago

What happened?

I've thoroughly followed the installation instruction for Windows, but even after trying everything I'm not able to correctly start Zigbee2Mqtt on a Windows machine using the Sonoff ZBDongle-P and I have no more idea on what can I try to do.

Here is a little on what I've tried: I have bought both a Sonoff ZBDongle-P and a Sonoff ZBDongle-E.

Sonoff ZBDongle-P:

Driver not found by Windows and also not working with "standard" installation of VCP-Driver from FTDI, I had to manually select the FTDI "USB Serial port" with Windows telling me it cannot be sure the driver is right. I've tried several other drivers without differences in the result
Z2M in Windows is not working, I've pasted its output under the "Debug Log" section
Z2M in WSL (Ubuntu 18.04) with USB passthrough using "usbipd" works without any problem
Updated dongle firmware to the latest available (20230507) -> also done in WSL because in Windows I was not able to update it in any way
Z2M still works in WSL
Z2M still not working in Windows

Sonoff ZBDongle-E:

Driver installed directly by Windows and displayed as "USB-Enhanced-SERIAL CH9102"
Z2M on Windows is not working with the same output as the Sonoff ZBDongle-P
Z2M in WSL (Ubuntu 18.04) with USB passthrough using "usbipd" works without any problem
Updated dongle firmware to the lastest available (7.4.2 [GA]) -> done directly from the Silabs firmware builder website
Z2M still works in WSL
Z2M still not working in Windows
Added "adapter: ember" in configuration.yaml
Z2M work in Windows

What did you expect to happen?

From what I can see I thought there was a problem with the Windows driver for communicating with the ZBDongle-P (since it works without problems under WSL and I was not even able to update its firmware under Windows), but since the ZBDongle-E also doesn't work until the activation of the ember driver maybe there is also a problem in the "standard" driver is not working at all in Windows?

Next week I will return the ZBDongle-P and in the future I will use only the ZBDongle-E. If you have some other idea or test I can do to understand why the ZBDongle-P (and also the ZBDongle-E without activating the ember driver) is not working in Windows I'm always available.

Thanks for the amazing project!

How to reproduce it (minimal and precise)

configuration.yaml used (I've tried both \.\COM4 and COM4 directly):

homeassistant: false
frontend: true
mqtt:
  base_topic: zigbee2mqtt
  server: mqtt://localhost
serial:
  port: \\.\COM4
advanced:
  network_key:
    - 119
    - 255
    - 138
    - 155
    - 110
    - 89
    - 154
    - 132
    - 54
    - 17
    - 35
    - 238
    - 232
    - 5
    - 81
    - 219
  pan_id: 10650
  ext_pan_id:
    - 206
    - 207
    - 244
    - 17
    - 87
    - 204
    - 227
    - 232

Zigbee2MQTT version

1.37.1 (commit #cda867a3)

Adapter firmware version

20230507

Adapter

ZBDongle-P

Setup

Plain on x64 Windows laptop

Debug log

npm start

zigbee2mqtt@1.37.1 start node index.js

[2024-05-23 10:48:31] info: z2m: Logging to console, file (filename: log.log) [2024-05-23 10:48:31] info: z2m: Starting Zigbee2MQTT version 1.37.1 (commit #cda867a3) [2024-05-23 10:48:31] info: z2m: Starting zigbee-herdsman (0.46.6) [2024-05-23 10:48:31] error: zh:zstack:znp: Failed to determine if path is valid: 'Error: EINVAL: invalid argument, lstat '\.\COM4\'' [2024-05-23 10:48:31] info: zh:zstack:znp: Opening SerialPort with {"path":"\\.\COM4","baudRate":115200,"rtscts":false,"autoOpen":false} [2024-05-23 10:48:31] info: zh:zstack:znp: Serialport opened [2024-05-23 10:48:32] info: zh:zstack:znp: Writing CC2530/CC2531 skip bootloader payload [2024-05-23 10:48:33] info: zh:zstack:znp: Skip bootloader for CC2652/CC1352 [2024-05-23 10:48:51] error: z2m: Error while starting zigbee-herdsman [2024-05-23 10:48:51] error: z2m: Failed to start zigbee [2024-05-23 10:48:51] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions [2024-05-23 10:48:51] error: z2m: Exiting... [2024-05-23 10:48:51] error: z2m: Error: Failed to connect to the adapter (Error: SRSP - SYS - ping after 6000ms) at ZStackAdapter.start (D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\adapter\z-stack\adapter\zStackAdapter.ts:101:27) at Controller.start (D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\controller\controller.ts:124:29) at Zigbee.start (D:\Working\LocalProjects\MQTT\zigbee2mqtt\lib\zigbee.ts:62:27) at Controller.start (D:\Working\LocalProjects\MQTT\zigbee2mqtt\lib\controller.ts:109:27) at start (D:\Working\LocalProjects\MQTT\zigbee2mqtt\index.js:107:5)

Nerivec commented 5 months ago

Can you provide a log with debug level?

I don't have the Dongle-P, so no idea there, but I can confirm the Dongle-E works on Windows, with both ezsp and ember. Auto-detection does not work however (due to OS driver overwriting some parameters), you need to specify adapter: xyz.

LamerTex commented 5 months ago

Can you provide a log with debug level?

I don't have the Dongle-P, so no idea there, but I can confirm the Dongle-E works on Windows, with both ezsp and ember. Auto-detection does not work however (due to OS driver overwriting some parameters), you need to specify adapter: xyz.

Yes you are right, the Dongle-E works correctly with both ezsp and ember only without the option it doesn't work, thanks!

Dongle-P

The Dongle-P instead still doesn't work, when starting Z2M with the options:

serial:
  adapter: zstack
  port: \\.\COM4
advanced:
  log_level: debug

This is the log if I install the Windows driver "CDM-v2.12.36.4.U-WHQL-Certified" from FTDI chip's website as recommended in the installation instruction for the Dongle-P since it is based on the CC2652P chipset. Windows doesn't recognize it as the correct driver for the device and I have to "force it" to install, then the dongle is displayed just as "USB Serial Port (COM4)"

npm start

> zigbee2mqtt@1.37.1 start
> node index.js

[2024-05-25 17:13:38] info:     z2m: Logging to console, file (filename: log.log)
[2024-05-25 17:13:38] debug:    z2m: Loaded state from file D:\Working\LocalProjects\MQTT\zigbee2mqtt\data\state.json
[2024-05-25 17:13:38] info:     z2m: Starting Zigbee2MQTT version 1.37.1 (commit #cda867a3)
[2024-05-25 17:13:38] info:     z2m: Starting zigbee-herdsman (0.46.6)
[2024-05-25 17:13:38] debug:    z2m: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\coordinator_backup.json","databaseBackupPath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\database.db.backup","databasePath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\database.db","network":{"channelList":[11],"extendedPanID":[206,207,244,17,87,204,227,232],"networkKey":"HIDDEN","panID":10650},"serialPort":{"adapter":"zstack","path":"\\\\.\\COM4"}}'
[2024-05-25 17:13:39] error:    zh:zstack:znp: Failed to determine if path is valid: 'Error: EINVAL: invalid argument, lstat '\\.\COM4\''
[2024-05-25 17:13:39] debug:    zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[119,255,138,155,110,89,154,132,54,17,35,238,232,5,81,219],"panID":10650,"extendedPanID":[206,207,244,17,87,204,227,232],"channelList":[11]},"serialPort":{"path":"\\\\.\\COM4","adapter":"zstack"},"databasePath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\database.db","databaseBackupPath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\database.db.backup","backupPath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
[2024-05-25 17:13:39] info:     zh:zstack:znp: Opening SerialPort with {"path":"\\\\.\\COM4","baudRate":115200,"rtscts":false,"autoOpen":false}
[2024-05-25 17:13:39] info:     zh:zstack:znp: Serialport opened
[2024-05-25 17:13:39] debug:    zh:zstack:znp: SREQ: --> SYS - ping - {"capabilities":1}
[2024-05-25 17:13:39] debug:    zh:zstack:unpi:writer: --> frame [254,0,33,1,32]
[2024-05-25 17:13:39] info:     zh:zstack:znp: Writing CC2530/CC2531 skip bootloader payload
[2024-05-25 17:13:39] debug:    zh:zstack:unpi:writer: --> buffer [239]
[2024-05-25 17:13:40] debug:    zh:zstack:znp: SREQ: --> SYS - ping - {"capabilities":1}
[2024-05-25 17:13:40] debug:    zh:zstack:unpi:writer: --> frame [254,0,33,1,32]
[2024-05-25 17:13:40] info:     zh:zstack:znp: Skip bootloader for CC2652/CC1352
[2024-05-25 17:13:41] debug:    zh:zstack:znp: SREQ: --> SYS - ping - {"capabilities":1}
[2024-05-25 17:13:41] debug:    zh:zstack:unpi:writer: --> frame [254,0,33,1,32]
[2024-05-25 17:13:47] debug:    zh:zstack:znp: SREQ: --> SYS - ping - {"capabilities":1}
[2024-05-25 17:13:47] debug:    zh:zstack:unpi:writer: --> frame [254,0,33,1,32]
[2024-05-25 17:13:53] debug:    zh:zstack:znp: SREQ: --> SYS - ping - {"capabilities":1}
[2024-05-25 17:13:53] debug:    zh:zstack:unpi:writer: --> frame [254,0,33,1,32]
[2024-05-25 17:13:59] error:    z2m: Error while starting zigbee-herdsman
[2024-05-25 17:13:59] error:    z2m: Failed to start zigbee
[2024-05-25 17:13:59] error:    z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-05-25 17:13:59] error:    z2m: Exiting...
[2024-05-25 17:13:59] error:    z2m: Error: Failed to connect to the adapter (Error: SRSP - SYS - ping after 6000ms)

This instead is the (much longer) log if I install the "wrong" driver "CP210x_Universal_Windows_Driver" from Silicon Labs, in this case Windows install the driver without the need to force it and then the dongle is displayed as "Silicon Labs CP210x USB to UART Bridge (COM4)". Configuration.yaml is the same as the previous log.

npm start

> zigbee2mqtt@1.37.1 start
> node index.js

[2024-05-25 17:18:54] info:     z2m: Logging to console, file (filename: log.log)
[2024-05-25 17:18:54] debug:    z2m: Loaded state from file D:\Working\LocalProjects\MQTT\zigbee2mqtt\data\state.json
[2024-05-25 17:18:54] info:     z2m: Starting Zigbee2MQTT version 1.37.1 (commit #cda867a3)
[2024-05-25 17:18:54] info:     z2m: Starting zigbee-herdsman (0.46.6)
[2024-05-25 17:18:54] debug:    z2m: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\coordinator_backup.json","databaseBackupPath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\database.db.backup","databasePath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\database.db","network":{"channelList":[11],"extendedPanID":[206,207,244,17,87,204,227,232],"networkKey":"HIDDEN","panID":10650},"serialPort":{"adapter":"zstack","path":"\\\\.\\COM4"}}'
[2024-05-25 17:18:55] error:    zh:zstack:znp: Failed to determine if path is valid: 'Error: EINVAL: invalid argument, lstat '\\.\COM4\''
[2024-05-25 17:18:55] debug:    zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[119,255,138,155,110,89,154,132,54,17,35,238,232,5,81,219],"panID":10650,"extendedPanID":[206,207,244,17,87,204,227,232],"channelList":[11]},"serialPort":{"path":"\\\\.\\COM4","adapter":"zstack"},"databasePath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\database.db","databaseBackupPath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\database.db.backup","backupPath":"D:\\Working\\LocalProjects\\MQTT\\zigbee2mqtt\\data\\coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
[2024-05-25 17:18:55] info:     zh:zstack:znp: Opening SerialPort with {"path":"\\\\.\\COM4","baudRate":115200,"rtscts":false,"autoOpen":false}
[2024-05-25 17:18:55] info:     zh:zstack:znp: Serialport opened
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - ping - {"capabilities":1}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,0,33,1,32]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,2,97,1,89,6,61]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,2,97,1,89,6,61]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 2 - 3 - 1 - 1 - [89,6] - 61
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - ping - {"capabilities":1625}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - ping - {"capabilities":1}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,0,33,1,32]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,2,97,1,89,6,61]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,2,97,1,89,6,61]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 2 - 3 - 1 - 1 - [89,6] - 61
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - ping - {"capabilities":1625}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - version - {}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,0,33,2,35]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,10,97,2,2,1,2,7,1,107,177,52,1,0,129]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,10,97,2,2,1,2,7,1,107,177,52,1,0,129]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 10 - 3 - 1 - 2 - [2,1,2,7,1,107,177,52,1,0] - 129
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - version - {"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20230507}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack: Adapter concurrent: 16
[2024-05-25 17:18:55] debug:    zh:zstack: Detected znp version 'zStack3x0' ({"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20230507})
[2024-05-25 17:18:55] debug:    zh:adapter:zstack:manager: beginning znp startup
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvLength - {"id":130}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,2,33,19,130,0,178]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,2,97,19,24,0,104]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,2,97,19,24,0,104]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 2 - 3 - 1 - 19 - [24,0] - 104
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvLength - {"length":24}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvReadExt - {"id":130,"offset":0}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,4,33,28,130,0,0,0,187]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,26,97,28,0,24,0,215,91,109,87,20,5,168,176,135,200,102,165,30,22,52,167,1,0,32,1,0,0,0,247]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,26,97,28,0,24,0,215,91,109,87,20,5,168,176,135,200,102,165,30,22,52,167,1,0,32,1,0,0,0,247]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 26 - 3 - 1 - 28 - [0,24,0,215,91,109,87,20,5,168,176,135,200,102,165,30,22,52,167,1,0,32,1,0,0,0] - 247
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvReadExt - {"status":0,"len":24,"value":{"type":"Buffer","data":[0,215,91,109,87,20,5,168,176,135,200,102,165,30,22,52,167,1,0,32,1,0,0,0]}}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:adapter:zstack:manager: determining znp startup strategy
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvLength - {"id":96}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,2,33,19,96,0,80]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,2,97,19,1,0,113]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,2,97,19,1,0,113]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 2 - 3 - 1 - 19 - [1,0] - 113
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvLength - {"length":1}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvReadExt - {"id":96,"offset":0}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,4,33,28,96,0,0,0,89]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,3,97,28,0,1,85,42]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,3,97,28,0,1,85,42]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 3 - 3 - 1 - 28 - [0,1,85] - 42
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvReadExt - {"status":0,"len":1,"value":{"type":"Buffer","data":[85]}}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvLength - {"id":33}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,2,33,19,33,0,17]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,2,97,19,116,0,4]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,2,97,19,116,0,4]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 2 - 3 - 1 - 19 - [116,0] - 4
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvLength - {"length":116}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvReadExt - {"id":33,"offset":0}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,4,33,28,33,0,0,0,24]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,118,97,28,0,116,214,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,131,148,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,230]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,118,97,28,0,116,214,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,131,148,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,230]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [53,78,201,129,14,143,61,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0,196]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,118,97,28,0,116,214,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,131,148,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,230,53,78,201,129,14,143,61,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0,196][2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 118 - 3 - 1 - 28 - [0,116,214,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,131,148,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,230,53,78,201,129,14,143,61,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0] - 196
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvReadExt - {"status":0,"len":116,"value":{"type":"Buffer","data":[214,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,131,148,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,230,53,78,201,129,14,143,61,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0]}}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvLength - {"id":98}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,2,33,19,98,0,82]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,2,97,19,16,0,96]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,2,97,19,16,0,96]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 2 - 3 - 1 - 19 - [16,0] - 96
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvLength - {"length":16}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvReadExt - {"id":98,"offset":0}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,4,33,28,98,0,0,0,91]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,18,97,28,0,16,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152,226]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,18,97,28,0,16,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152,226]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 18 - 3 - 1 - 28 - [0,16,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152] - 226
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvReadExt - {"status":0,"len":16,"value":{"type":"Buffer","data":[23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152]}}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvLength - {"id":58}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,2,33,19,58,0,10]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,2,97,19,17,0,97]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,2,97,19,17,0,97]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 2 - 3 - 1 - 19 - [17,0] - 97
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvLength - {"length":17}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvReadExt - {"id":58,"offset":0}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,4,33,28,58,0,0,0,3]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,19,97,28,0,17,0,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152,226]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,19,97,28,0,17,0,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152,226]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 19 - 3 - 1 - 28 - [0,17,0,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152] - 226
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvReadExt - {"status":0,"len":17,"value":{"type":"Buffer","data":[0,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152]}}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvLength - {"id":59}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,2,33,19,59,0,11]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,2,97,19,17,0,97]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,2,97,19,17,0,97]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 2 - 3 - 1 - 19 - [17,0] - 97
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvLength - {"length":17}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvReadExt - {"id":59,"offset":0}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,4,33,28,59,0,0,0,2]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,19,97,28,0,17,0,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152,226]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,19,97,28,0,17,0,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152,226]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 19 - 3 - 1 - 28 - [0,17,0,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152] - 226
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvReadExt - {"status":0,"len":17,"value":{"type":"Buffer","data":[0,23,23,235,101,34,195,44,74,160,205,107,136,228,225,135,152]}}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:adapter:zstack:manager: (stage-1) adapter is configured
[2024-05-25 17:18:55] debug:    zh:adapter:zstack:manager: (stage-2) adapter state does not match configuration
[2024-05-25 17:18:55] debug:    zh:adapter:zstack:manager: (stage-3) got adapter backup
[2024-05-25 17:18:55] debug:    zh:adapter:zstack:manager: (stage-4) adapter state does not match backup
[2024-05-25 17:18:55] debug:    zh:adapter:zstack:manager: (stage-5) adapter backup does not match configuration
[2024-05-25 17:18:55] debug:    zh:adapter:zstack:manager: determined startup strategy: startCommissioning
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvLength - {"id":33}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,2,33,19,33,0,17]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,2,97,19,116,0,4]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,2,97,19,116,0,4]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 2 - 3 - 1 - 19 - [116,0] - 4
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvLength - {"length":116}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvDelete - {"id":33,"len":116}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,4,33,18,33,0,116,0,98]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,1,97,18,0,114]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,1,97,18,0,114]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 1 - 3 - 1 - 18 - [0] - 114
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvDelete - {"status":0}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:adapter:zstack:manager: clearing adapter using startup option 3
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvLength - {"id":3}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,2,33,19,3,0,51]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,2,97,19,1,0,113]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,2,97,19,1,0,113]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 2 - 3 - 1 - 19 - [1,0] - 113
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvLength - {"length":1}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SREQ: --> SYS - osalNvWriteExt - {"id":3,"offset":0,"len":1,"value":{"type":"Buffer","data":[3]}}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,7,33,29,3,0,0,0,1,0,3,58]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: <-- [254,1,97,29,0,125]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext [254,1,97,29,0,125]
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --> parsed 1 - 3 - 1 - 29 - [0] - 125
[2024-05-25 17:18:55] debug:    zh:zstack:znp: SRSP: <-- SYS - osalNvWriteExt - {"status":0}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:parser: --- parseNext []
[2024-05-25 17:18:55] debug:    zh:adapter:zstack:manager: adapter reset requested
[2024-05-25 17:18:55] debug:    zh:zstack:znp: AREQ: --> SYS - resetReq - {"type":1}
[2024-05-25 17:18:55] debug:    zh:zstack:unpi:writer: --> frame [254,1,65,0,1,65]
[2024-05-25 17:19:25] error:    z2m: Error while starting zigbee-herdsman
[2024-05-25 17:19:25] error:    z2m: Failed to start zigbee
[2024-05-25 17:19:25] error:    z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-05-25 17:19:25] error:    z2m: Exiting...
[2024-05-25 17:19:25] error:    z2m: Error: AREQ - SYS - resetInd after 30000ms
    at Object.start (D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\utils\waitress.ts:63:23)    at D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\adapter\z-stack\znp\znp.ts:327:31
    at Queue.execute (D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\utils\queue.ts:35:26)
    at Znp.request (D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\adapter\z-stack\znp\znp.ts:293:27)
    at ZnpAdapterManager.resetAdapter (D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\adapter\z-stack\adapter\manager.ts:459:24)
    at ZnpAdapterManager.clearAdapter (D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\adapter\z-stack\adapter\manager.ts:469:20)
    at ZnpAdapterManager.beginCommissioning (D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\adapter\z-stack\adapter\manager.ts:325:9)
    at ZnpAdapterManager.start (D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\adapter\z-stack\adapter\manager.ts:86:17)
    at Controller.start (D:\Working\LocalProjects\MQTT\zigbee2mqtt\node_modules\zigbee-herdsman\src\controller\controller.ts:124:29)
    at Zigbee.start (D:\Working\LocalProjects\MQTT\zigbee2mqtt\lib\zigbee.ts:62:27)

In both cases, Z2M is not able to start correctly.

I hope the debug log can help find something wrong on my setup and if you have some other test that can help debug the problem I'm always available, thanks again

MartinVerges commented 4 weeks ago

Mine won't work as well, but due to not using the correct serial port.

Starting Zigbee2MQTT without watchdog.
[2024-10-06 20:30:40] info:     z2m: Logging to console, file (filename: log.log)
[2024-10-06 20:30:40] debug:    z2m: Can't load state from file C:\Program Files\zigbee2mqtt\data\state.json (doesn't exist)
[2024-10-06 20:30:40] info:     z2m: Starting Zigbee2MQTT version 1.40.2 (commit #e06848d)
[2024-10-06 20:30:40] debug:    z2m: sd-notify loaded
[2024-10-06 20:30:40] info:     z2m: Starting zigbee-herdsman (2.1.3)
[2024-10-06 20:30:40] debug:    z2m: Using zigbee-herdsman with settings: '"{\"network\":{\"panID\":6754,\"extendedPanID\":[221,221,221,221,221,221,221,221],\"channelList\":[11],\"networkKey\":\"HIDDEN\"},\"databasePath\":\"C:\\\\Program Files\\\\zigbee2mqtt\\\\data\\\\database.db\",\"databaseBackupPath\":\"C:\\\\Program Files\\\\zigbee2mqtt\\\\data\\\\database.db.backup\",\"backupPath\":\"C:\\\\Program Files\\\\zigbee2mqtt\\\\data\\\\coordinator_backup.json\",\"serialPort\":{\"path\":\"COM6\",\"adapter\":\"zstack\"},\"adapter\":{\"disableLED\":false}}"'
[2024-10-06 20:30:41] error:    zh:zstack:znp: Failed to determine if path is valid: 'Error: ENOENT: no such file or directory, lstat 'C:\Program Files\zigbee2mqtt\COM6''
[2024-10-06 20:30:41] debug:    zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":"HIDDEN","panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"path":"COM6","adapter":"zstack"},"adapter":{"disableLED":false},"databasePath":"C:\\Program Files\\zigbee2mqtt\\data\\database.db","databaseBackupPath":"C:\\Program Files\\zigbee2mqtt\\data\\database.db.backup","backupPath":"C:\\Program Files\\zigbee2mqtt\\data\\coordinator_backup.json"}'
[2024-10-06 20:30:41] info:     zh:zstack:znp: Opening SerialPort with {"path":"COM6","baudRate":115200,"rtscts":false,"autoOpen":false}
[2024-10-06 20:30:41] error:    z2m: Error while starting zigbee-herdsman
[2024-10-06 20:30:41] error:    z2m: Failed to start zigbee
[2024-10-06 20:30:41] error:    z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-10-06 20:30:41] error:    z2m: Exiting...
[2024-10-06 20:30:41] error:    z2m: Error: Opening COM6: Access denied

I tried it with \\.\COM6 and just COM6 but the path in the error message is always incorrect (C:\Program Files\zigbee2mqtt\COM6) and does not represent a Windows Serial device

Nerivec commented 4 weeks ago

@MartinVerges Without the slashes is the best way, COM3, COM6, etc.. Since yours is failing with your installation in Program Files folder, and the error somehow adds Program Files in the port path, I'd say this has something to do with the fact that Program Files is a special folder, and might be messing with Z2M. As a first step, I'd suggest taking the installation out of that folder, and putting it in a regular folder, where you are sure Z2M has the correct permissions & such (like C:\Users\User\yourusename\zigbee2mqtt).

MartinVerges commented 4 weeks ago

I tried to move it into c:\zigbee2mqtt but the path still gets prefixed to the COM6 port name.

PS C:\zigbee2mqtt> cat .\data\configuration.yaml
# Home Assistant integration (MQTT discovery)
homeassistant: false

# allow new devices to join
permit_join: true

# MQTT settings
mqtt:
  # MQTT base topic for zigbee2mqtt MQTT messages
  base_topic: zigbee2mqtt
  # MQTT server URL
  server: 'mqtt://localhost'
  # MQTT server authentication, uncomment if required:
  # user: my_user
  # password: my_password

# Serial settings
serial:
  adapter: zstack
  port: COM6

advanced:
  log_level: debug
PS C:\zigbee2mqtt> npm start

> zigbee2mqtt@1.40.2 start
> node index.js

Starting Zigbee2MQTT without watchdog.
[2024-10-07 07:52:07] info:     z2m: Logging to console, file (filename: log.log)
[2024-10-07 07:52:07] debug:    z2m: Can't load state from file C:\zigbee2mqtt\data\state.json (doesn't exist)
[2024-10-07 07:52:07] info:     z2m: Starting Zigbee2MQTT version 1.40.2 (commit #e06848d)
[2024-10-07 07:52:07] debug:    z2m: sd-notify loaded
[2024-10-07 07:52:07] info:     z2m: Starting zigbee-herdsman (2.1.3)
[2024-10-07 07:52:07] debug:    z2m: Using zigbee-herdsman with settings: '"{\"network\":{\"panID\":6754,\"extendedPanID\":[221,221,221,221,221,221,221,221],\"channelList\":[11],\"networkKey\":\"HIDDEN\"},\"databasePath\":\"C:\\\\zigbee2mqtt\\\\data\\\\database.db\",\"databaseBackupPath\":\"C:\\\\zigbee2mqtt\\\\data\\\\database.db.backup\",\"backupPath\":\"C:\\\\zigbee2mqtt\\\\data\\\\coordinator_backup.json\",\"serialPort\":{\"path\":\"COM6\",\"adapter\":\"zstack\"},\"adapter\":{\"disableLED\":false}}"'
[2024-10-07 07:52:08] error:    zh:zstack:znp: Failed to determine if path is valid: 'Error: ENOENT: no such file or directory, lstat 'C:\zigbee2mqtt\COM6''
[2024-10-07 07:52:08] debug:    zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":"HIDDEN","panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"path":"COM6","adapter":"zstack"},"adapter":{"disableLED":false},"databasePath":"C:\\zigbee2mqtt\\data\\database.db","databaseBackupPath":"C:\\zigbee2mqtt\\data\\database.db.backup","backupPath":"C:\\zigbee2mqtt\\data\\coordinator_backup.json"}'
[2024-10-07 07:52:08] info:     zh:zstack:znp: Opening SerialPort with {"path":"COM6","baudRate":115200,"rtscts":false,"autoOpen":false}
[2024-10-07 07:52:08] error:    z2m: Error while starting zigbee-herdsman
[2024-10-07 07:52:08] error:    z2m: Failed to start zigbee
[2024-10-07 07:52:08] error:    z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-10-07 07:52:08] error:    z2m: Exiting...
[2024-10-07 07:52:08] error:    z2m: Error: Opening COM6: Access denied

the same happens in the suggested User folder: [2024-10-07 07:54:38] error: zh:zstack:znp: Failed to determine if path is valid: 'Error: ENOENT: no such file or directory, lstat 'C:\Users\Administrator\zigbee2mqtt\COM6''

Nerivec commented 4 weeks ago

Hmm, seems it's just the path test that gets this preprend, not the actual opening (as last log line would indicate). (This will all be refactored in 2.0.0.)

So, let's assume the problem is only the "Access denied"...

Make sure the port is the right one -in Device Manager > Ports- (and hasn't changed for some reason)
Make sure you have the proper driver installed
Make sure nothing else could be using the port
In Device Manager > Ports > COM6 > Properties > Port Settings > Advanced > uncheck SerEnum (Serial Port Enumerator) if checked > validate

MartinVerges commented 4 weeks ago

Hello,

thanks, it was indeed just a wrong port. I guess I got confused by the error message with the incorrect path that maybe should be fixed, besides that it's working great. Thank you so much!

Regards Martin

Koenkk / zigbee2mqtt