search

zwave-js / node-zwave-js

Z-Wave driver written entirely in JavaScript/TypeScript
https://zwave-js.github.io/node-zwave-js/
MIT License
748 stars 598 forks source link

Touchscreen Deadbolt Z-Wave Plus no longer reports Keypad unlock notifcations #4883

Closed DanielBaulig closed 2 years ago

DanielBaulig commented 2 years ago

Is your problem within Home Assistant (Core or Z-Wave JS Integration)?

NO, my problem is NOT within Home Assistant or the ZWave JS integration

Is your problem within ZWaveJS2MQTT?

NO, my problem is NOT within ZWaveJS2MQTT

Checklist

Describe the bug

What causes the bug? Unclear

What do you observe? Unlocking the lock through the keypad does not trigger a keypad unlock notification event.

What did you expect to happen? A keypad unlock operation being logged under events.

Steps to reproduce the behavior:

  1. Go to the Touchscreen Deadbolt Z-Wave Plus device in device list
  2. Click on Events
  3. Lock and unlock the device manually, lock and then unlock the device through the keypad
  4. See that manual lock, manual unlock and keypad lock notifications are logged as events, but no keypad unlock event

Device information

Manufacturer: Allegion Model name: Touchscreen Deadbolt Z-Wave Plus BE469ZP Node ID in your network: 7

How are you using node-zwave-js?

Which branches or versions?

zwavejs2mqtt: 6.15.1 zwave-js: 9.6.2 home id: 4169456423 home hex: 0xf884db27

Did you change anything?

yes (please describe)

If yes, what did you change?

My lock used to emit this event. I recently updated the docker image. I am not sure if the breakage already occurred before the update or with the update. I only noticed it after the update.

Did this work before?

Yes (please describe)

If yes, where did it work?

See above.

Attach Driver Logfile

zwavejs_2022-08-04.log

DanielBaulig commented 2 years ago

Note that I have reinterviewed the lock as suggested in the troubleshooting section, but that did not fix the issue.

AlCalzone commented 2 years ago

Can you make another log, without the nodes filter? It looks like the lock sometimes sends the notifications in addition to the Door Lock CC Report (at least I see one lock and one unlock notification) and sometimes it doesn't. But this could also be due to an invalid command that doesn't appear correctly in the log.

DanielBaulig commented 2 years ago

@AlCalzone Here's a new log without a node filter applied: zwavejs_2022-08-05.log

Note that I did the following operations on the lock while logging was enabled:

Manually locked the door. Manually unlocked the door. Locked the door by entering a lock code. Unlocked the door by entering a lock code.

Only the last step is not correctly reported through a notification event. The other operations all correctly report as a notification event.

DanielBaulig commented 2 years ago

Note that I do see two NotificationCCReport entries with userId event parameters, indicating that both the keypad lock and keypad unlock operation are correctly reported by the Z-Wave lock. However, only a single "NOTIFICATION" event with a set userId is reported under events:

2022-08-05T17:20:13.831Z - NOTIFICATION 
Arg 0:
113
Arg 1:
└─type: 6
└─event: 5
└─label: Access Control
└─eventLabel: Keypad lock operation
└─parameters
└──userId: 5

Without knowing really anything about Z-Wave JS internals, I assume that means that the Z-Wave JS device driver fails to correctly generate the notification event in response to receiving the raw Z-Wave NotificationCCReport for the unlock operation.

AlCalzone commented 2 years ago

Sorry I always forget to ask this. Can you send me your network key (S0 Legacy) via e-mail (see profile)? Logging currently has a bug where it only logs the V1 alarm values, so I need it to decode whats's being received.

DanielBaulig commented 2 years ago

Sent you an email with the key, @AlCalzone.

AlCalzone commented 2 years ago

I have a suspicion whats going on. Can you also email me your f884db27.jsonl and f884db27.values.jsonl files from your store folder?

DanielBaulig commented 2 years ago

@AlCalzone Just sent you the requested files. Excuse the long turn around time. Greatly appreciate your help here.

AlCalzone commented 2 years ago

Hmm no, that was not it. The strange thing is that the report does get interpreted as an unlock notification:

2022-08-05T17:09:05.093Z CNTRLR   [Node 007] [~] [Notification] alarmType: 18 => 19                 [Endpoint 0]
2022-08-05T17:09:05.095Z CNTRLR   [Node 007] [~] [Notification] alarmLevel: 5 => 5                  [Endpoint 0]
2022-08-05T17:09:05.097Z DRIVER « [Node 007] [REQ] [ApplicationCommand]
                                  └─[SecurityCCCommandEncapsulation]
                                    │ sequenced: false
                                    └─[NotificationCCReport]
                                        V1 alarm type:    19
                                        V1 alarm level:   5
                                        event parameters:
                                          userId: 0x05
2022-08-05T17:09:05.099Z CNTRLR   [Node 007] [~] [Door Lock] currentMode: 255 => 0                  [Endpoint 0]

See last line, currentMode 0 means "unsecured".

The next thing that happens in code (and in my local reproduction) is emitting the corresponding event.

@robertsLando could this be a UI issue?

DanielBaulig commented 2 years ago

@AlCalzone I do not believe it to be a UI issue. The reason I started looking at this is because my Home Assistant automation that uses the unlock event as a trigger stopped running.

Do you mind pointing me to the code you are referring to?

AlCalzone commented 2 years ago

Do you mind pointing me to the code you are referring to?

Sure thing: Here's the line that causes the door lock value change: https://github.com/zwave-js/node-zwave-js/blob/087d8b7759ae44296224c490f923c68d1dcc3ca9/packages/zwave-js/src/lib/node/Node.ts#L3028-L3029

This also means that the notification type is 0x06 and the notification event is one of 0x02, 0x04 or 0x06 (since the door lock status changes to unlocked).

This also means (unless your configuration files are completely messed up) that notificationConfig contains the parsed representation of https://github.com/zwave-js/node-zwave-js/blob/087d8b7759ae44296224c490f923c68d1dcc3ca9/packages/config/config/notifications.json#L383-L384 and that valueConfig contains the parsed representation of one of these events: https://github.com/zwave-js/node-zwave-js/blob/087d8b7759ae44296224c490f923c68d1dcc3ca9/packages/config/config/notifications.json#L555-L562 Which means the else branch must be taken here: https://github.com/zwave-js/node-zwave-js/blob/087d8b7759ae44296224c490f923c68d1dcc3ca9/packages/zwave-js/src/lib/node/Node.ts#L3036-L3045

I'm also going to add logging for notification events so this is no longer a guessing game: https://github.com/zwave-js/node-zwave-js/pull/4948

Unless we figure out whats going on, you can redo the tests as soon as HA has updated to node-zwave-js v10. Then we should know for sure if the driver emits an event or not.

AlCalzone commented 2 years ago

Just for reference, this is how it looks with my lock and the new logging:

10:17:39.471 SERIAL « 0x011c00a800011b139f035000df8f1f953ab94459cb8836255be1fb00d00b      (30 bytes)
10:17:39.473 SERIAL » [ACK]                                                                   (0x06)
10:17:39.476 CNTRLR   [Node 027] [~] [Door Lock] currentMode: 0 => 0                    [Endpoint 0]
10:17:39.478 CNTRLR   [Node 027] [~] [Door Lock] outsideHandlesCanOpenDoor: true,false, [Endpoint 0]
                      false,false => true,false,false,false
10:17:39.479 CNTRLR   [Node 027] [~] [Door Lock] insideHandlesCanOpenDoor: false,false, [Endpoint 0]
                      false,false => false,false,false,false
10:17:39.481 CNTRLR   [Node 027] [~] [Door Lock] doorStatus: "open" => "open"           [Endpoint 0]
10:17:39.482 CNTRLR   [Node 027] [~] [Door Lock] boltStatus: "unlocked" => "unlocked"   [Endpoint 0]
10:17:39.483 CNTRLR   [Node 027] [~] [Door Lock] latchStatus: "open" => "open"          [Endpoint 0]
10:17:39.484 DRIVER « [Node 027] [REQ] [BridgeApplicationCommand]
                      │ RSSI: -48 dBm
                      └─[Security2CCMessageEncapsulation]
                        │ sequence number: 80
                        └─[DoorLockCCOperationReport]
                            current mode:           Unsecured
                            active outside handles: true, false, false, false
                            active inside handles:  false, false, false, false
                            latch status:           open
                            bolt status:            unlocked
                            door status:            open
10:17:40.469 SERIAL « 0x011900a800011b109f035100354f80e44eb3a29623de8ef800d005            (27 bytes)
10:17:40.471 SERIAL » [ACK]                                                                   (0x06)
10:17:40.474 CNTRLR   [Node 027] compat mapping found, treating V1 Alarm frame as Notification Repor
                      t
10:17:40.474 CNTRLR   [Node 027] [~] [Notification] alarmType: 144 => 144               [Endpoint 0]
10:17:40.474 CNTRLR   [Node 027] [~] [Notification] alarmLevel: 1 => 1                  [Endpoint 0]
10:17:40.474 DRIVER « [Node 027] [REQ] [BridgeApplicationCommand]
                      │ RSSI: -48 dBm
                      └─[Security2CCMessageEncapsulation]
                        │ sequence number: 81
                        └─[NotificationCCReport]
                            V1 alarm type:       144
                            V1 alarm level:      1
                            notification type:   Access Control
                            notification status: undefined
                            notification event:  Keypad unlock operation
                            event parameters:
                              userId: 0x01
10:17:40.475 CNTRLR   [Node 027] [handleNotificationReport] notificationName: Access Control
10:17:40.475 CNTRLR   [Node 027] [handleNotificationReport] valueConfig:
                        label: Keypad unlock operation
                        type: event
10:17:40.476 CNTRLR   [Node 027] [~] [Door Lock] currentMode: 0 => 0                    [Endpoint 0]
10:17:40.476 CNTRLR   [Node 027] [Notification]
                        type:   Access Control
                        event:  Keypad unlock operation
                        userId: 1
robertsLando commented 2 years ago

@robertsLando could this be a UI issue?

No clue, did you figure it out or shold I investigate?

AlCalzone commented 2 years ago

Not yet. v10 has additional logging to diagnose though.

robertsLando commented 2 years ago

What about tell him to try using test docker tag?

DanielBaulig commented 2 years ago

@robertsLando I'll give that a shot later today. Good call.

robertsLando commented 2 years ago

Now that branch is merged on master so you can use master tag

DanielBaulig commented 2 years ago

I just updated from master and recapture logs from me locking the door and unlocking again it using the keypad. I again did not get an unlock event.

zwavejs_2022-08-31.log

AlCalzone commented 2 years ago

I'm on mobile right now, so reading the logs is impossible. Is your log on level "silly"? If not, please make another one. I'm hoping to get some more insight with these new logs.

DanielBaulig commented 2 years ago

@AlCalzone Ah I had it on debug. Will rerecord them when I get an opportunity to do so.

AlCalzone commented 2 years ago

Anyways, this time it looks like the lock never sent the unlock notification.

Lock:

2022-08-31T17:34:35.694Z DRIVER « [Node 007] [REQ] [ApplicationCommand]
                                  └─[SecurityCCCommandEncapsulation]
                                    │ sequenced: false
                                    └─[NotificationCCReport]
                                        V1 alarm type:       18
                                        V1 alarm level:      0
                                        notification type:   Access Control
                                        notification status: 255
                                        notification event:  Keypad lock operation
2022-08-31T17:34:35.698Z CNTRLR   [Node 007] [~] [Door Lock] currentMode: 0 => 255                  [Endpoint 0]
2022-08-31T17:34:35.704Z CNTRLR   [Node 007] [Notification]
                                    type:  Access Control
                                    event: Keypad lock operation
...
2022-08-31T17:34:36.104Z DRIVER « [Node 007] [REQ] [ApplicationCommand]
                                  └─[SecurityCCCommandEncapsulation]
                                    │ sequenced: false
                                    └─[DoorLockCCOperationReport]
                                        current mode:           Secured
                                        active outside handles: false, false, false, false
                                        active inside handles:  false, false, false, false
                                        latch status:           open
                                        bolt status:            locked
                                        door status:            open

Unlock:

2022-08-31T17:34:46.681Z DRIVER « [Node 007] [REQ] [ApplicationCommand]
                                  └─[SecurityCCCommandEncapsulation]
                                    │ sequenced: false
                                    └─[DoorLockCCOperationReport]
                                        current mode:           Unsecured
                                        active outside handles: false, false, false, false
                                        active inside handles:  false, false, false, false
                                        latch status:           open
                                        bolt status:            unlocked
                                        door status:            open
DanielBaulig commented 2 years ago

@AlCalzone I’ve rerun the test sequence and it appears the unlock notification isn’t sent by the lock (anymore). I now start to wonder if this was the case the entire time and we just misread the original logs.

I’ve also tried re-interviewing the lock, but it gets stuck in the “NodeInfo” step and never completes. I am wondering if there’s something off with the lock. Maybe I’ll try to fully exclude and re-include it.

Any other suggestions?

AlCalzone commented 2 years ago

but it gets stuck in the “NodeInfo” step and never completes

Got a log of that?

DanielBaulig commented 2 years ago

This should include a re-interview attempt: zwavejs_2022-09-06.log

I had excluded the node, factory reset it, re-included it, which - after some self-inflicted hiccups - worked. The door lock was responding to lock and unlock commands and I was able to set user codes. However, it didn't report any notifications anymore (manual, keypad or otherwise lock or unlock).

Trying to re-interview the device appears to fail and get stuck in the Node Info step again and renders the door lock unusable. I fear I'll have to factory reset and re-include it again.

I tried doing some health checks between the door lock and some other routers that are in physical proximity to the door lock, but the health checks seemed to all fail. I don't recall if that was before re-interviewing the door lock though or not.

DanielBaulig commented 2 years ago

Does this here make any sense to you? I have this exact Lock.

https://forum.z-wave.me/viewtopic.php?p=88588#p88588

Schlage informed us on the issue. Please try to do zway.devices[X].Supervision.data.disabled = true and then set the association again. This should help.

The problem was that they ignore Associaiton (LifeLine) in Supervision encapsulation. Definitely a bug, but they assume this is legal.

DanielBaulig commented 2 years ago

Not sure if this is because the re-interview didn't complete successfully, but the node does indeed not show any associations (including no Lifeline association). Cannot add one manually either.

Screen Shot 2022-09-06 at 12 00 27 AM Screen Shot 2022-09-06 at 12 00 36 AM
AlCalzone commented 2 years ago

Your current seems to be something else entirely, pretty likely https://github.com/zwave-js/node-zwave-js/issues/4918:

At some (early) point during the interview, the lock suddenly stops responding to queries. We get the list of securely supported CCs (so it understands the encrypted commands):

2022-09-06T00:40:08.844Z DRIVER » [Node 037] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      29
                                  └─[Security2CCMessageEncapsulation]
                                    │ sequence number: 241
                                    └─[Security2CCCommandsSupportedGet]
2022-09-06T00:40:08.856Z DRIVER « [RES] [SendData]
                                    was sent: true
2022-09-06T00:40:09.004Z DRIVER « [REQ] [SendData]
                                    callback id:            29
                                    transmit status:        OK, took 150 ms
                                    repeater node IDs:      18, 8
                                    routing attempts:       1
                                    protocol & route speed: Z-Wave, 40 kbit/s
                                    ACK RSSI:               -57 dBm
                                    ACK RSSI on repeaters:  N/A, N/A
                                    ACK channel no.:        1
                                    TX channel no.:         1
2022-09-06T00:40:09.105Z DRIVER « [Node 037] [REQ] [ApplicationCommand]
                                  └─[Security2CCMessageEncapsulation]
                                    │ sequence number: 218
                                    └─[Security2CCCommandsSupportedReport]
                                        supportedCCs:
                                        · Anti-Theft
                                        · Association
                                        · Configuration
                                        · Battery
                                        · Door Lock
                                        · Notification
                                        · User Code
                                        · Schedule Entry Lock
                                        · Time
                                        · Supervision
                                        · Manufacturer Specific
                                        · Version
                                        · Firmware Update Meta Data
                                        · Application Status
                                        · Association Group Information
                                        · Device Reset Locally
                                        · Powerlevel
                                        · Indicator

but when trying to identify the lock itself next, it simply does not respond. It does ACK the command though:

2022-09-06T00:40:09.119Z DRIVER » [Node 037] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      30
                                  └─[Security2CCMessageEncapsulation]
                                    │ sequence number: 242
                                    └─[ManufacturerSpecificCCGet]
2022-09-06T00:40:09.129Z DRIVER « [RES] [SendData]
                                    was sent: true
2022-09-06T00:40:09.276Z DRIVER « [REQ] [SendData]
                                    callback id:            30
                                    transmit status:        OK, took 150 ms
                                    repeater node IDs:      18, 8
                                    routing attempts:       1
                                    protocol & route speed: Z-Wave, 40 kbit/s
                                    ACK RSSI:               -57 dBm
                                    ACK RSSI on repeaters:  N/A, N/A
                                    ACK channel no.:        1
                                    TX channel no.:         1
2022-09-06T00:40:10.451Z CNTRLR   [Node 037] Timed out while waiting for a response from the node (ZW0201)

After that I don't see a single response from the lock, despite it acknowledging every single command. You can try the workaround in the linked issue of upping the response timeout. Sadly this isn't something we can work around with a device-specific compat flag, since the device isn't even identified before the issue happens.

DanielBaulig commented 2 years ago

Ok, this was really helpful. I was able to increase the report timeout to 10 seconds as described in the issue you've linked to. That (mostly) fixed my interview problem. I did still end up with a couple of timeouts during the interview though. Is that of concern or should that not cause further issues?

After the successful interview the lock seemed to have basic functionality again. It still didn't send any notifications though.

I checked the Groups tab again and there still was no association. I manually created a Lifeline association which (after refreshing the view) did indeed show up. Once I had that created ZWaveJS started receiving notifications from the lock again, too.

It is also receiving the keypad unlock notifications again now, which was the type of notification it wasn't receiving in the beginning that led me to open this ticket in the first place. So we can consider it resolved?

I captured some logs of me interviewing the device (including the couple timeouts it experienced in the process) and re-adding the lifeline association and attach them in case they are useful. zwavejs_2022-09-06 (1).log

I'm not very familiar with the ZWave protocol, but how come that association was missing? Shouldn't it be established either during pairing / re-interviewing or upon factory reset of the device (depending if it's a feature of the network or a device local feature)?

DanielBaulig commented 2 years ago

It appears a lot of people seem to have problems with this specific lock. Is there something that we can share with the manufacturer/firmware developer and/or the Z-Wave Alliance to help them improve the locks (or at least their future implementations thereof) compatibility?

AlCalzone commented 2 years ago

Everyone who has this lock and is having these issues should reach out to the manufacturer and complain IMO. I'm guessing the answer will be along the lines of "the lock is certified, not our problem 🤷🏻‍♂️" though.

AlCalzone commented 2 years ago

how come that association was missing?

Now that's what you quoted before. The device doesn't support Supervision for setting Associations. But the latest version should detect this and retry without supervision automatically now.

zwave-js-assistant[bot] commented 2 years ago

This issue has not seen any recent activity and was marked as "cannot fix ❌". Closing for housekeeping purposes... 🧹

Feel free to reopen if the issue persists.