[bug] S2 bootstrapping failed when adding S2 device

[kpine]

Version

Checklist:

• [X] I am not using HomeAssistant. Or: a developer has told me to come here.
• [X] I have checked the troubleshooting section and my problem is not described there.
• [X] I have read the changelog problem was not mentioned there.

Build/Run method

• [X] Docker
• [ ] PKG
• [ ] Snap package
• [ ] Manually built (git clone - yarn install - yarn run build )

zwavejs2mqtt version: 5.5.1 zwave-js version: 8.2.1

Describe the bug

I tried to add a node that supports Security S2 and it was added with no security. The driver logs indicate the S2 bootstrapping failed. z2m never prompted me for the DSK.

To Reproduce

Steps to reproduce the behavior:

1. Include node using the default inclusion strategy.
2. Dialog shows list of requested S2 security class. I left the defaults.
3. After some time, the dialog says the node was added with no security. It never prompted for the DSK.

Expected behavior

The node is successfully added with S2 security.

Additional context

The device is a HomeSeer HS-FC200+ fan controller. The device supports Security S2 and has a sticker with the DSK and SmartStart QR code.

Logs: z2m.log zwavejs_2021-08-25.log

[billyburly]

Having the same issue with a Inovelli LZW60.

Aug 25 15:23:11 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:11.673 INFO ZWAVE: Calling api startInclusion with args: [ 0, { forceSecurity: false }, [length]: 2 ]
Aug 25 15:23:11 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:11.706 INFO ZWAVE: Controller status: Secure inclusion started
Aug 25 15:23:11 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:11.709 INFO ZWAVE: Success zwave api call startInclusion true
Aug 25 15:23:15 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:15.670 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:19 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:19.167 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:21 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:21.804 INFO ZWAVE: Controller status: Inclusion stopped
Aug 25 15:23:22 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:22.223 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:22 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:22.319 INFO ZWAVE: Grant security classes: { securityClasses: [ 0, 7, [length]: 2 ], clientSideAuth: false }
Aug 25 15:23:22 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:22.756 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:23 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:23.051 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:23 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:23.870 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:24 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:24.997 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:26 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:26.117 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:27 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:27.237 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:28 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:28.357 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:29 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:29.476 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:30 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:30.596 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:30 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:30.849 INFO ZWAVE: Calling api grantSecurityClasses with args: [
Aug 25 15:23:30 hahub.durrnet.billdurr.com node[775]:   { securityClasses: [ 0, 7, [length]: 2 ], clientSideAuth: false },
Aug 25 15:23:30 hahub.durrnet.billdurr.com node[775]:   [length]: 1
Aug 25 15:23:30 hahub.durrnet.billdurr.com node[775]: ]
Aug 25 15:23:30 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:30.851 INFO ZWAVE: Success zwave api call grantSecurityClasses undefined
Aug 25 15:23:31 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:31.875 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:33 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:33.004 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:34 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:34.137 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:35 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:35.270 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:36 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:36.403 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:37 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:37.535 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:38 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:38.667 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:39 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:39.798 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:40 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:40.734 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:40 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:40.934 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:42 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:42.064 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:43 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:43.196 INFO ZWAVE: Node 38: value updated: 37-1-currentValue false => false
Aug 25 15:23:44 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:44.313 INFO ZWAVE: Node 41: added with security None
Aug 25 15:23:44 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:44.339 INFO ZWAVE: Node 39: value updated: 37-1-currentValue false => false
Aug 25 15:23:44 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:44.458 INFO ZWAVE: Node 41: interview stage PROTOCOLINFO completed
Aug 25 15:23:44 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:44.559 INFO ZWAVE: Node 41: interview stage NODEINFO completed
Aug 25 15:23:44 hahub.durrnet.billdurr.com node[775]: 2021-08-25 15:23:44.618 INFO ZWAVE: Node 41: value added: 114-0-manufacturerId => 798

Tried with both the default option (Allow S2 and S0) as well as only allowing S2

[asucrews]

adding my logs, in case it can help

2021-08-26T00:25:52.409Z DRIVER » [Node 031] [REQ] [SendDataBridge] │ source node id: 1 │ transmit options: 0x25 │ route: 0, 0, 0, 0 │ callback id: 17 └─[Security2CCKEXSet] echo: false selected scheme: KEXScheme1 selected ECDH profile: Curve25519 CSA permitted: false granted security classes: · S2_Authenticated 2021-08-26T00:25:52.422Z SERIAL « [ACK] (0x06) 2021-08-26T00:25:52.429Z SERIAL » [ACK] (0x06) 2021-08-26T00:25:52.432Z DRIVER « [RES] [SendDataBridge] was sent: true 2021-08-26T00:25:56.946Z SERIAL » [ACK] (0x06) 2021-08-26T00:25:56.947Z DRIVER « [REQ] [SendDataBridge] callback id: 17 transmit status: NoAck 2021-08-26T00:25:56.953Z CNTRLR [Node 031] did not respond after 1/3 attempts. Scheduling next try in 500 ms. 2021-08-26T00:25:56.955Z SERIAL « 0x010b00a800011f02840700b774 (13 bytes) 2021-08-26T00:25:56.959Z SERIAL » [ACK] (0x06) 2021-08-26T00:25:56.961Z DRIVER « [Node 031] [REQ] [BridgeApplicationCommand] └─[WakeUpCCWakeUpNotification] 2021-08-26T00:25:56.966Z CNTRLR « [Node 031] received wakeup notification 2021-08-26T00:25:57.460Z DRIVER » [Node 031] [REQ] [SendDataBridge] │ source node id: 1 │ transmit options: 0x25 │ route: 0, 0, 0, 0 │ callback id: 17 └─[Security2CCKEXSet] echo: false selected scheme: KEXScheme1 selected ECDH profile: Curve25519 CSA permitted: false granted security classes: · S2_Authenticated 2021-08-26T00:25:57.467Z SERIAL « [ACK] (0x06) 2021-08-26T00:25:57.468Z SERIAL « 0x010401a90152 (6 bytes) 2021-08-26T00:25:57.470Z SERIAL » [ACK] (0x06) 2021-08-26T00:25:57.471Z DRIVER « [RES] [SendDataBridge] was sent: true 2021-08-26T00:25:57.507Z SERIAL » [ACK] (0x06) 2021-08-26T00:25:57.508Z DRIVER « [REQ] [SendDataBridge] callback id: 17 transmit status: OK 2021-08-26T00:26:07.513Z CNTRLR [Node 031] Security S2 bootstrapping failed, the node was not granted any S2 s ecurity class

[ehsman]

Not sure if this is the same - butI had a similar issue the first time, because I hadn’t added in keys for S2 Unauthenticated, S2 Authenticated, and S2 Access Control under settings->zwave

[kpine]

All my keys are configured.

[billyburly]

setting the keys worked for me, so conf issue on my end

[kpine]

setting the keys worked for me, so conf issue on my end

What was the failure message reported in the logs previously?

[asucrews]

After power cycling my host, witch power cycled my Aeotec 700 stick, I was able to get S2 to work.

[kpine]

Well, this is a real head-scratcher. After these last few comments of success, I went ahead and restarted zwavejs2mqtt and repeated the process. It added successfully this time with S2_Authenticated. No configuration changes on my end. 🤔

[asucrews]

Let add the head-scratcher, i tried second 700 series device, and so far can't get second device added with s2

2021-08-25 22:20:22.428 INFO ZWAVE: Calling api startInclusion with args: [ 0, { forceSecurity: false }, length: 2 ] 2021-08-25 22:20:22.458 INFO ZWAVE: Controller status: Secure inclusion started 2021-08-25 22:20:22.461 INFO ZWAVE: Success zwave api call startInclusion true 2021-08-25 22:20:34.942 INFO ZWAVE: Controller status: Inclusion stopped 2021-08-25 22:20:35.487 INFO ZWAVE: Grant security classes: { securityClasses: [ 0, 1, length: 2 ], clientSideAuth: false } 2021-08-25 22:20:38.101 INFO ZWAVE: Calling api grantSecurityClasses with args: [ { securityClasses: [ 1, 0, length: 2 ], clientSideAuth: false },

] 2021-08-25 22:20:38.105 INFO ZWAVE: Success zwave api call grantSecurityClasses undefined 2021-08-25 22:20:38.185 INFO ZWAVE: DSK received 2021-08-25 22:20:51.055 INFO ZWAVE: Calling api validateDSK with args: [ '58257', length: 1 ] 2021-08-25 22:20:51.058 INFO ZWAVE: Success zwave api call validateDSK undefined 2021-08-25 22:25:08.700 INFO ZWAVE: Node 36: added with security None 2021-08-25 22:25:08.729 INFO ZWAVE: Node 36: interview stage PROTOCOLINFO completed

[asucrews]

My both devices are battery powered, has any one had this issue with mains power device?

[AlCalzone]

1. Please attach logfiles, don't post them as text here.
2. Like with almost everything that's not strictly UI related, application logs don't help debug this. This requires driver logs

So far, this looks like it is working as intended. S2 bootstrapping has strict requirements and if a required message does not come within the allowed timeout, bootstrapping must be aborted.

[AlCalzone]

If anyone is interested:

All timeouts described in Section 3.6.6.4.2 MUST be implemented. If a node times out, it MUST silently abort the S2 bootstrapping

[kpine]

@AlCalzone Thanks for those details. It does look like there is exactly a 10 second break in-between sending the Security2CCKEXSet message and the bootstrapping being reported as failed. In this case is the node reporting the failure, or is the driver timing it out? If it's the latter, would it be useful if the log message indicated that? I'm wondering how common these kinds of timeouts are. I've never had a connectivity issue with this node, and the second attempt had no issue, so it's weird.

I think one thing that is missing from the UI is a more prominent warning that the security bootstrapping failed. According to your application docs I would expect some UI indicators that something went wrong.

[AlCalzone]

In this case is the node reporting the failure, or is the driver timing it out?

The driver didn't receive the expected response within the 10 seconds, so it times out.

If it's the latter, would it be useful if the log message indicated that?

Agreed - the "node added" handler could also be given that information along with the warning that the security is lower than intended.

I think one thing that is missing from the UI is a more prominent warning that the security bootstrapping failed.

Which UI are you talking about? I guess zwavejs2mqtt, in which case @robertsLando would have some more work to do :)

[asucrews]

Attach is driver log on debug for mains power S2 500 device.

I am not sure where I am going wrong this this, not matter if I chose S2 Auth or S2 Unauth.

Can you let me know if there anything i am doing worng?

zwavejs_2021-08-26 (1).log

[AlCalzone]

In your case the process stops here because the node doesn't start requesting the keys:

[asucrews]

If I understand correctly this correct I need to reach out to the vendor, and see if there a firmware bug in there S2 process

[AlCalzone]

You can try bringing the device closer and test if this is a connectivity problem first, but ultimately - yeah.

[asucrews]

Sadly the device is a power switch, so not the easies to move. Do you then a zwave extend would help?

[AlCalzone]

It might, it might not. Depends on your mesh.

[asucrews]

At this point i am leaning toward the device, i posted on the vendor's community site. And others with their on/off switch are having the same issue. But there dimmers switch are working for what people report. Thanks for all the great work and help @AlCalzone

[zwave-js-assistant[bot]]

This issue has not seen any recent activity and was marked as "working as intended ✔". Closing for housekeeping purposes... 🧹

Feel free to reopen if the issue persists.