AeonStick getting error on Windows 11

CristianMori commented 2 years ago

Hello. I am running zwave-js server on a win 10 machine, and everything works fine. I am moving to a windows 11 and when running zwave-server I get the following output

00:14:50.880 DRIVER   ███████╗ ██╗    ██╗  █████╗  ██╗   ██╗ ███████╗             ██╗ ███████╗
                      ╚══███╔╝ ██║    ██║ ██╔══██╗ ██║   ██║ ██╔════╝             ██║ ██╔════╝
                        ███╔╝  ██║ █╗ ██║ ███████║ ██║   ██║ █████╗   █████╗      ██║ ███████╗
                       ███╔╝   ██║███╗██║ ██╔══██║ ╚██╗ ██╔╝ ██╔══╝   ╚════╝ ██   ██║ ╚════██║
                      ███████╗ ╚███╔███╔╝ ██║  ██║  ╚████╔╝  ███████╗        ╚█████╔╝ ███████║
                      ╚══════╝  ╚══╝╚══╝  ╚═╝  ╚═╝   ╚═══╝   ╚══════╝         ╚════╝  ╚══════╝
00:14:50.885 DRIVER   version 10.0.4
00:14:50.886 DRIVER
00:14:50.887 DRIVER   starting driver...
00:14:50.905 DRIVER   opening serial port COM6
00:14:50.918 DRIVER   serial port opened
00:14:50.920 SERIAL » [NAK]                                                                   (0x15)
00:14:50.923 DRIVER   loading configuration...
00:14:50.928 CONFIG   version 10.0.4
00:14:51.793 DRIVER   beginning interview...
00:14:51.795 DRIVER   added request handler for AddNodeToNetwork (0x4a)...
                      1 registered
00:14:51.796 DRIVER   added request handler for RemoveNodeFromNetwork (0x4b)...
                      1 registered
00:14:51.797 DRIVER   added request handler for ReplaceFailedNode (0x63)...
                      1 registered
00:14:51.798 CNTRLR   querying controller IDs...
00:14:51.946 SERIAL » 0x01030020dc                                                         (5 bytes)
00:14:51.950 DRIVER » [REQ] [GetControllerId]
00:14:51.953 SERIAL « [ACK]                                                                   (0x06)
00:14:51.960 SERIAL « 0x01080120fa1cf99e0156                                              (10 bytes)
00:14:51.962 SERIAL » [ACK]                                                                   (0x06)
00:14:51.965 DRIVER « [RES] [GetControllerId]
                        home ID:     0xfa1cf99e
                        own node ID: 1
00:14:51.968 DRIVER « [RES] [GetControllerId]                                           [unexpected]
                        home ID:     0xfa1cf99e
                        own node ID: 1
00:14:51.969 DRIVER   unexpected response, discarding...
00:14:52.965 CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                      n 100 ms.
00:14:53.071 SERIAL » 0x01030020dc                                                         (5 bytes)
00:14:53.074 DRIVER » [REQ] [GetControllerId]
00:14:53.079 SERIAL « [ACK]                                                                   (0x06)
00:14:53.088 SERIAL « 0x01080120fa1cf99e0156                                              (10 bytes)
00:14:53.091 SERIAL » [ACK]                                                                   (0x06)
00:14:53.094 DRIVER « [RES] [GetControllerId]
                        home ID:     0xfa1cf99e
                        own node ID: 1
00:14:53.101 DRIVER « [RES] [GetControllerId]                                           [unexpected]
                        home ID:     0xfa1cf99e
                        own node ID: 1
00:14:53.103 DRIVER   unexpected response, discarding...
00:14:54.095 CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                      n 1100 ms.
00:14:55.209 SERIAL » 0x01030020dc                                                         (5 bytes)
00:14:55.210 DRIVER » [REQ] [GetControllerId]
00:14:55.213 SERIAL « [ACK]                                                                   (0x06)
00:14:55.216 SERIAL « 0x01080120fa1cf99e0156                                              (10 bytes)
00:14:55.218 SERIAL » [ACK]                                                                   (0x06)
00:14:55.221 DRIVER « [RES] [GetControllerId]
                        home ID:     0xfa1cf99e
                        own node ID: 1
00:14:55.224 DRIVER « [RES] [GetControllerId]                                           [unexpected]
                        home ID:     0xfa1cf99e
                        own node ID: 1
00:14:55.225 DRIVER   unexpected response, discarding...
00:14:56.247 DRIVER   Failed to initialize the driver: ZWaveError: Timeout while waiting for an ACK
                      from the controller (ZW0200)
                          at Driver.sendMessage (C:\Users\Cristian\node_modules\zwave-js\src\lib\dri
                      ver\Driver.ts:3895:23)
                          at ZWaveController.identify (C:\Users\Cristian\node_modules\zwave-js\src\l
                      ib\controller\Controller.ts:713:33)
                          at Driver.initializeControllerAndNodes (C:\Users\Cristian\node_modules\zwa
                      ve-js\src\lib\driver\Driver.ts:1186:26)
                          at Immediate.<anonymous> (C:\Users\Cristian\node_modules\zwave-js\src\lib\
                      driver\Driver.ts:993:16)

I tried with two different zwave stick a gen5 and an old S2. Both works fine on win 10 and have the same issue on windows 11. (same node version)

AlCalzone commented 2 years ago

To be honest, I'm not quite sure why this is erroring. Can you share the first couple of lines from Windows 10, so I can compare?

CristianMori commented 2 years ago

Sure thing. Here it is

02:58:13.551 DRIVER   ███████╗ ██╗    ██╗  █████╗  ██╗   ██╗ ███████╗             ██╗ ███████╗
                      ╚══███╔╝ ██║    ██║ ██╔══██╗ ██║   ██║ ██╔════╝             ██║ ██╔════╝
                        ███╔╝  ██║ █╗ ██║ ███████║ ██║   ██║ █████╗   █████╗      ██║ ███████╗
                       ███╔╝   ██║███╗██║ ██╔══██║ ╚██╗ ██╔╝ ██╔══╝   ╚════╝ ██   ██║ ╚════██║
                      ███████╗ ╚███╔███╔╝ ██║  ██║  ╚████╔╝  ███████╗        ╚█████╔╝ ███████║
                      ╚══════╝  ╚══╝╚══╝  ╚═╝  ╚═╝   ╚═══╝   ╚══════╝         ╚════╝  ╚══════╝
02:58:13.554 DRIVER   version 10.0.4
02:58:13.555 DRIVER
02:58:13.555 DRIVER   starting driver...
02:58:13.566 DRIVER   opening serial port COM3
02:58:14.578 DRIVER   serial port opened
02:58:14.579 SERIAL » [NAK]                                                                   (0x15)
02:58:14.582 DRIVER   loading configuration...
02:58:14.585 CONFIG   version 10.0.4
02:58:15.515 DRIVER   beginning interview...
02:58:15.517 DRIVER   added request handler for AddNodeToNetwork (0x4a)...
                      1 registered
02:58:15.518 DRIVER   added request handler for RemoveNodeFromNetwork (0x4b)...
                      1 registered
02:58:15.519 DRIVER   added request handler for ReplaceFailedNode (0x63)...
                      1 registered
02:58:15.519 CNTRLR   querying controller IDs...
02:58:15.615 SERIAL » 0x01030020dc                                                         (5 bytes)
02:58:15.617 DRIVER » [REQ] [GetControllerId]
02:58:15.620 SERIAL « [ACK]                                                                   (0x06)
02:58:15.622 SERIAL « 0x01080120fa1cf99e0156                                              (10 bytes)
02:58:15.624 SERIAL » [ACK]                                                                   (0x06)
02:58:15.625 DRIVER « [RES] [GetControllerId]
                        home ID:     0xfa1cf99e
                        own node ID: 1
02:58:15.632 CNTRLR   received controller IDs:
                        home ID:     0xfa1cf99e
                        own node ID: 1
02:58:15.633 CNTRLR   querying API capabilities...
02:58:15.638 SERIAL » 0x01030007fb                                                         (5 bytes)
02:58:15.638 DRIVER » [REQ] [GetSerialApiCapabilities]
02:58:15.639 SERIAL « [ACK]                                                                   (0x06)
02:58:15.644 SERIAL « 0x012b0107010000860101005afe81ff884f1f0000fb9f7da067000080008086000 (45 bytes)
                      000e87300000e0000600000fa
02:58:15.645 SERIAL » [ACK]                                                                   (0x06)
02:58:15.652 DRIVER « [RES] [GetSerialApiCapabilities]
                        payload: 0x010000860101005afe81ff884f1f0000fb9f7da067000080008086000000e8730
                      0000e0000600000
02:58:15.656 CNTRLR   received API capabilities:
                        firmware version:    1.0
                        manufacturer ID:     0x86
                        product type:        0x0101
                        product ID:          0x5a
                        supported functions:
                        · GetSerialApiInitData (0x02)
                        · SetApplicationNodeInformation (0x03)
                        · ApplicationCommand (0x04)
                        · GetControllerCapabilities (0x05)
                        · SetSerialApiTimeouts (0x06)
                        · GetSerialApiCapabilities (0x07)
                        · SoftReset (0x08)
                        · GetProtocolVersion (0x09)
                        · SetRFReceiveMode (0x10)
                        · UNKNOWN_FUNC_SET_SLEEP_MODE (0x11)
                        · FUNC_ID_ZW_SEND_NODE_INFORMATION (0x12)
                        · SendData (0x13)
                        · SendDataMulticast (0x14)
                        · GetControllerVersion (0x15)
                        · SendDataAbort (0x16)
                        · FUNC_ID_ZW_R_F_POWER_LEVEL_SET (0x17)
                        · UNKNOWN_FUNC_SEND_DATA_META (0x18)
                        · FUNC_ID_ZW_GET_RANDOM (0x1c)
                        · GetControllerId (0x20)
                        · UNKNOWN_FUNC_MEMORY_GET_BYTE (0x21)
                        · UNKNOWN_FUNC_MEMORY_PUT_BYTE (0x22)
                        · UNKNOWN_FUNC_MEMORY_GET_BUFFER (0x23)
                        · UNKNOWN_FUNC_MEMORY_PUT_BUFFER (0x24)
                        · UNKNOWN_FUNC_FlashAutoProgSet (0x27)
                        · GetNVMId (0x29)
                        · ExtNVMReadLongBuffer (0x2a)
                        · ExtNVMWriteLongBuffer (0x2b)
                        · ExtNVMReadLongByte (0x2c)
                        · ExtExtWriteLongByte (0x2d)
                        · GetNodeProtocolInfo (0x41)
                        · HardReset (0x42)

AlCalzone commented 2 years ago

Are you running the server natively using Node.js or somehow packaged with Docker or whatever? If natively, which version of Node.js (node -v)?

CristianMori commented 2 years ago

Natively. 16.17.0

AlCalzone commented 2 years ago

Ok, what's the output of this when you're in the server dir?

npm ls --all

CristianMori commented 2 years ago

Output from Windows 10 machine win10.txt

Output from Windows 11 machine win11.txt

AlCalzone commented 2 years ago

That doesn't look wrong either... The stick's ACK definitely gets received, but this info somehow doesn't find its way to the state machine. Aside from actually debugging on a Windows 11 machine (I only have 10), I have honestly no idea how to proceed.

CristianMori commented 2 years ago

It looks like somehow the same message is processed twice 00:14:53.094 DRIVER « [RES] [GetControllerId] home ID: 0xfa1cf99e own node ID: 1 00:14:53.101 DRIVER « [RES] [GetControllerId] [unexpected] home ID: 0xfa1cf99e own node ID: 1 00:14:53.103 DRIVER unexpected response, discarding...

If you need me to run any test code on that setup, happy to. In the meanwhile I moved to an RPI and had no problems

AlCalzone commented 2 years ago

It's not processed twice, just logged twice (once on receipt, then again because it is unexpected).

AlCalzone commented 1 year ago

I don't know what exactly changed, but I'm also getting this on Windows 10 now. The commit that broke this is the upgrade to Serialport v10: 4f52ac5cad4b4f115ba26d9257b0e932c5960592

This bug is super weird...

Data read and written by the driver is identical across commits (at least before the re-transmission attempt)
This bug does not appear in e2e tests, where everything but the serialport instance is the same

ptorrent commented 1 year ago

Hello,

Same error here on windows 10

To reproduce:

1)driver.controller.beginInclusion() 2)Disconnect the USB 3)Reconnect the USB

Even if I remove the usb key ZW200 and replug it.

11:23:14.687 DRIVER   version 10.3.1
11:23:14.695 DRIVER
11:23:14.696 DRIVER   starting driver...
11:23:14.708 DRIVER   opening serial port COM11
11:23:14.716 DRIVER   serial port opened
11:23:14.718 SERIAL » [NAK]                                                                   (0x15)
11:23:14.721 DRIVER   loading configuration...
11:23:14.724 CONFIG   version 10.3.1
11:23:15.233 DRIVER   beginning interview...
11:23:15.234 DRIVER   added request handler for AddNodeToNetwork (0x4a)...
                      1 registered
11:23:15.235 DRIVER   added request handler for RemoveNodeFromNetwork (0x4b)...
                      1 registered
11:23:15.243 DRIVER   added request handler for ReplaceFailedNode (0x63)...
                      1 registered
11:23:15.245 CNTRLR   querying controller IDs...
11:23:15.311 SERIAL » 0x01030020dc                                                         (5 bytes)
11:23:15.313 DRIVER » [REQ] [GetControllerId]
11:23:15.316 SERIAL « [ACK]                                                                   (0x06)
11:23:15.325 SERIAL « 0x01080120edbfdb0b0155                                              (10 bytes)
11:23:15.326 SERIAL » [ACK]                                                                   (0x06)
11:23:15.331 DRIVER « [RES] [GetControllerId]
                        home ID:     0xedbfdb0b
                        own node ID: 1
11:23:15.337 CNTRLR   received controller IDs:
                        home ID:     0xedbfdb0b
                        own node ID: 1
11:23:15.337 CNTRLR   querying API capabilities...
11:23:15.342 SERIAL » 0x01030007fb                                                         (5 bytes)
11:23:15.347 DRIVER » [REQ] [GetSerialApiCapabilities]
11:23:15.349 SERIAL « [ACK]                                                                   (0x06)
11:23:15.359 SERIAL « 0x012b01070525011504000001fe877f88cf3fc047fbdffde067008080008086000 (45 bytes)
                      000e87300800f000060da00ec
11:23:15.361 SERIAL » [ACK]                                                                   (0x06)
11:23:15.368 DRIVER « [RES] [GetSerialApiCapabilities]
                        payload: 0x0525011504000001fe877f88cf3fc047fbdffde067008080008086000000e8730
                      0800f000060da00
11:23:15.370 DRIVER « [RES] [GetSerialApiCapabilities]                                  [unexpected]
                        payload: 0x0525011504000001fe877f88cf3fc047fbdffde067008080008086000000e8730
                      0800f000060da00
11:23:15.371 DRIVER   unexpected response, discarding...
11:23:16.358 CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                      n 100 ms.
11:23:16.462 SERIAL » 0x01030007fb                                                         (5 bytes)
11:23:16.463 DRIVER » [REQ] [GetSerialApiCapabilities]
11:23:16.467 SERIAL « [ACK]                                                                   (0x06)
11:23:16.475 SERIAL « 0x012b01070525011504000001fe877f88cf3fc047fbdffde067008080008086000 (45 bytes)
                      000e87300800f000060da00ec
11:23:16.478 SERIAL » [ACK]                                                                   (0x06)
11:23:16.489 DRIVER « [RES] [GetSerialApiCapabilities]
                        payload: 0x0525011504000001fe877f88cf3fc047fbdffde067008080008086000000e8730
                      0800f000060da00
11:23:16.493 DRIVER « [RES] [GetSerialApiCapabilities]                                  [unexpected]
                        payload: 0x0525011504000001fe877f88cf3fc047fbdffde067008080008086000000e8730
                      0800f000060da00
11:23:16.496 DRIVER   unexpected response, discarding...
11:23:17.472 CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                      n 1100 ms.
11:23:18.575 SERIAL » 0x01030007fb                                                         (5 bytes)
11:23:18.577 DRIVER » [REQ] [GetSerialApiCapabilities]
11:23:18.586 SERIAL « [ACK]                                                                   (0x06)
11:23:18.603 SERIAL « 0x012b01070525011504000001fe877f88cf3fc047fbdffde067008080008086000 (45 bytes)
                      000e87300800f000060da00ec
11:23:18.606 SERIAL » [ACK]                                                                   (0x06)
11:23:18.618 DRIVER « [RES] [GetSerialApiCapabilities]
                        payload: 0x0525011504000001fe877f88cf3fc047fbdffde067008080008086000000e8730
                      0800f000060da00
11:23:18.620 DRIVER « [RES] [GetSerialApiCapabilities]                                  [unexpected]
                        payload: 0x0525011504000001fe877f88cf3fc047fbdffde067008080008086000000e8730
                      0800f000060da00
11:23:18.625 DRIVER   unexpected response, discarding...
11:23:19.600 DRIVER   Failed to initialize the driver: ZWaveError: Timeout while waiting for an ACK
                      from the controller (ZW0200)
                          at Driver.sendMessage (C:\Users\ptorrent\Desktop\api\zwave\node_modules\zw
                      ave-js\src\lib\driver\Driver.ts:3990:23)
                          at ZWaveController.identify (C:\Users\ptorrent\Desktop\api\zwave\node_modu
                      les\zwave-js\src\lib\controller\Controller.ts:728:22)
                          at Driver.initializeControllerAndNodes (C:\Users\ptorrent\Desktop\api\zwav
                      e\node_modules\zwave-js\src\lib\driver\Driver.ts:1208:4)
                          at Immediate.<anonymous> (C:\Users\ptorrent\Desktop\api\zwave\node_modules
                      \zwave-js\src\lib\driver\Driver.ts:1015:5)
ZWaveError: Failed to initialize the driver: ZWaveError: Timeout while waiting for an ACK from the controller (ZW0200)
    at Driver.sendMessage (C:\Users\ptorrent\Desktop\api\zwave\node_modules\zwave-js\src\lib\driver\Driver.ts:3990:23)
    at ZWaveController.identify (C:\Users\ptorrent\Desktop\api\zwave\node_modules\zwave-js\src\lib\controller\Controller.ts:728:22)
    at Driver.initializeControllerAndNodes (C:\Users\ptorrent\Desktop\api\zwave\node_modules\zwave-js\src\lib\driver\Driver.ts:1208:4)
    at Immediate.<anonymous> (C:\Users\ptorrent\Desktop\api\zwave\node_modules\zwave-js\src\lib\driver\Driver.ts:1015:5) (ZW0100)
    at Immediate.<anonymous> (C:\Users\ptorrent\Desktop\api\zwave\node_modules\zwave-js\src\lib\driver\Driver.ts:1032:6)
    at processTicksAndRejections (node:internal/process/task_queues:95:5) {
  code: 100,
  context: undefined,
  transactionSource: undefined
}
11:23:19.613 DRIVER   destroying driver instance...
11:23:19.615 DRIVER   driver instance destroyed

Thanks for your help !

jriker1 commented 1 year ago

I posted an issue in the HA forum like this and was referenced to this issue.

https://community.home-assistant.io/t/failed-to-execute-controller-command-after-1-3-attempts-scheduling-next-try/528787/9

Apparently the same except for me running on Windows 2022 Server.

Log: https://www.dropbox.com/s/12rio3prde2y7ik/zwavejs_2023-02-01.log?dl=0

zwave-js-ui: 8.8.0 zwave-js: 10.4.0

AlCalzone commented 1 year ago

I'm curious if this is still happening for you on the latest version. I just tried to fix this and I can no longer reproduce on Windows 11.

StreetCube commented 1 year ago

I also had this error, I'm gonna check it out tomorrow, and get back to you with the information

StreetCube commented 1 year ago

It seems to be still wrong for me, same issue.

bostjane commented 1 year ago

I haven't encountered this issue since I started using Zwave JS UI, that is few months now. However, latest version 8.14.2 produces this error on two different Windows 10 machines, both have different USB sticks, different ZWave networks.

I have no clue what else could do the difference. As a cause for error I would exclude Windows Updates, other system components and also Zwave store folder and saved stuff in it as simply running previous version (8.14.1) in the same location makes the problem disappear.

Could some extra logging info be added to track the error in details?

AlCalzone commented 1 year ago

I just tried again. I can reproduce. Sometimes...

Attempt 1 was fine.

Attempt 2:

12:27:14.359 CNTRLR   querying controller IDs...
12:27:14.417 SERIAL » 0x01030020dc                                                         (5 bytes)
12:27:14.419 DRIVER » [REQ] [GetControllerId]
12:27:14.425 SERIAL « [ACK]                                                                   (0x06)
12:27:14.427 SERIAL « 0x01080120deab0b21028b                                              (10 bytes)
12:27:14.428 SERIAL » [ACK]                                                                   (0x06)
12:27:14.430 DRIVER « [RES] [GetControllerId]
                        home ID:     0xdeab0b21
                        own node ID: 2
12:27:14.432 DRIVER « [RES] [GetControllerId]                                           [unexpected]
                        home ID:     0xdeab0b21
                        own node ID: 2
12:27:14.433 DRIVER   unexpected response, discarding...
12:27:15.437 CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                      n 100 ms.
12:27:15.546 SERIAL » 0x01030020dc                                                         (5 bytes)
12:27:15.547 DRIVER » [REQ] [GetControllerId]
12:27:15.552 SERIAL « [ACK]                                                                   (0x06)
12:27:15.553 SERIAL « 0x01080120deab0b21028b                                              (10 bytes)
12:27:15.554 SERIAL » [ACK]                                                                   (0x06)
12:27:15.555 DRIVER « [RES] [GetControllerId]
                        home ID:     0xdeab0b21
                        own node ID: 2
12:27:15.559 CNTRLR   received controller IDs:
                        home ID:     0xdeab0b21
                        own node ID: 2
12:27:15.559 CNTRLR   querying API capabilities...

here it works after the retry.

Attempt 3 without issues at first:

12:27:27.896 CNTRLR   querying controller IDs...
12:27:27.953 SERIAL » 0x01030020dc                                                         (5 bytes)
12:27:27.955 DRIVER » [REQ] [GetControllerId]
12:27:27.961 SERIAL « [ACK]                                                                   (0x06)
12:27:27.963 SERIAL « 0x01080120deab0b21028b                                              (10 bytes)
12:27:27.964 SERIAL » [ACK]                                                                   (0x06)
12:27:27.966 DRIVER « [RES] [GetControllerId]
                        home ID:     0xdeab0b21
                        own node ID: 2
12:27:27.970 CNTRLR   received controller IDs:
                        home ID:     0xdeab0b21
                        own node ID: 2
12:27:27.970 CNTRLR   querying API capabilities...

but a later command shows the same issue

12:27:28.462 DRIVER » [REQ] [SerialAPISetup]
                        command: GetPowerlevel16Bit
                        payload: 0x13
...
12:27:28.474 DRIVER « [RES] [SerialAPISetup]
                        command:               GetPowerlevel16Bit
                        normal powerlevel:     0.0 dBm
                        output power at 0 dBm: 3.3 dBm
12:27:28.475 DRIVER « [RES] [SerialAPISetup]                                            [unexpected]
                        command:               GetPowerlevel16Bit
                        normal powerlevel:     0.0 dBm
                        output power at 0 dBm: 3.3 dBm
12:27:28.475 DRIVER   unexpected response, discarding...

AlCalzone commented 1 year ago

Good news, I think I finally figured out what causes this. A fix (hopefully) is up and will be merged soon.

zwave-js / node-zwave-js

AeonStick getting error on Windows 11 #5024