Zwavejs2mqtt: [bug] lock Access_Control-Lock_state not updated upon lock change

Created on 23 Feb 2021  ·  40Comments  ·  Source: zwave-js/zwavejs2mqtt

Version

Build/Run method

  • [x] Docker
  • [ ] PKG
  • [ ] Manually built (git clone - npm install - npm run build )

zwavejs2mqtt version: 1.2.3
zwavejs version: 6.4.0

Describe the bug

Using ID Lock 150: https://products.z-wavealliance.org/products/3450?selectedFrequencyId=1

The locks' accesscontrol attributes are not updated on MQTT:

This shows a complete mqtt flow of a unlock, open door, wait ~ 10 seconds, close door, wait for autolock:
https://gist.githubusercontent.com/roflmao/9a6c11b036576ef16ff437d83f6c5f08/raw/043bd0c3a3df572cca7991b5998668dee621af0c/gistfile1.txt

The attributes for the lock has not been updated since zwavejs2mqtt startup:

$ mosquitto_sub -h 192.168.67.11 -t "z2m/nodeID_40/113/#" -v
z2m/nodeID_40/113/0/alarmType {"id":"40-113-0-alarmType","nodeId":40,"commandClass":113,"commandClassName":"Notification","endpoint":0,"property":"alarmType","propertyName":"alarmType","type":"number","readable":true,"writeable":false,"label":"Alarm Type","stateless":false,"min":0,"max":255,"list":false,"lastUpdate":1614034764805,"nodeName":"","nodeLocation":""}
z2m/nodeID_40/113/0/Home_Security/Cover_status {"id":"40-113-0-Home Security-Cover status","nodeId":40,"commandClass":113,"commandClassName":"Notification","endpoint":0,"property":"Home Security","propertyName":"Home Security","propertyKey":"Cover status","propertyKeyName":"Cover status","type":"number","readable":true,"writeable":false,"label":"Cover status","stateless":false,"ccSpecific":{"notificationType":7},"min":0,"max":255,"list":true,"states":[{"text":"idle","value":0},{"text":"Tampering, product cover removed","value":3}],"value":0,"lastUpdate":1614034764809,"nodeName":"","nodeLocation":""}
z2m/nodeID_40/113/0/alarmLevel {"id":"40-113-0-alarmLevel","nodeId":40,"commandClass":113,"commandClassName":"Notification","endpoint":0,"property":"alarmLevel","propertyName":"alarmLevel","type":"number","readable":true,"writeable":false,"label":"Alarm Level","stateless":false,"min":0,"max":255,"list":false,"lastUpdate":1614034764807,"nodeName":"","nodeLocation":""}
z2m/nodeID_40/113/0/Access_Control/Lock_state {"id":"40-113-0-Access Control-Lock state","nodeId":40,"commandClass":113,"commandClassName":"Notification","endpoint":0,"property":"Access Control","propertyName":"Access Control","propertyKey":"Lock state","propertyKeyName":"Lock state","type":"number","readable":true,"writeable":false,"label":"Lock state","stateless":false,"ccSpecific":{"notificationType":6},"min":0,"max":255,"list":true,"states":[{"text":"idle","value":0},{"text":"Lock jammed","value":11}],"value":0,"lastUpdate":1614034764808,"nodeName":"","nodeLocation":""}

In OZW 1.6 i have the following data through mqtt on the same type of lock with same FW:

OpenZWave/1/node/47/instance/1/commandclass/113/value/1688850654838804/:

{
    "Label": "Access Control",
    "Value": {
        "List": [
            {
                "Value": 0,
                "Label": "Clear"
            },
            {
                "Value": 1,
                "Label": "Manual Lock Operation"
            },
            {
                "Value": 2,
                "Label": "Manual Unlock Operation"
            },
            {
                "Value": 3,
                "Label": "Wireless Lock Operation"
            },
            {
                "Value": 4,
                "Label": "Wireless Unlock Operation"
            },
            {
                "Value": 5,
                "Label": "Keypad Lock Operation"
            },
            {
                "Value": 6,
                "Label": "Keypad Unlock Operation"
            },
            {
                "Value": 9,
                "Label": "Auto Lock"
            },
            {
                "Value": 11,
                "Label": "Lock Jammed"
            },
            {
                "Value": 12,
                "Label": "All User Codes Deleted"
            },
            {
                "Value": 13,
                "Label": "Single User Code Deleted"
            },
            {
                "Value": 14,
                "Label": "New User Code Added"
            },
            {
                "Value": 15,
                "Label": "Duplicate User Code Not Added"
            },
            {
                "Value": 20,
                "Label": "Wireless Unlock Invalid UserCode Entered"
            },
            {
                "Value": 21,
                "Label": "Wireless Lock Invalid UserCode Entered"
            }
        ],
        "Selected": "Auto Lock",
        "Selected_id": 9
    },
    "Units": "",
    "ValueSet": true,
    "ValuePolled": false,
    "ChangeVerified": false,
    "Min": 0,
    "Max": 0,
    "Type": "List",
    "Instance": 1,
    "CommandClass": "COMMAND_CLASS_NOTIFICATION",
    "Index": 6,
    "Node": 47,
    "Genre": "User",
    "Help": "Access Control Alerts",
    "ValueIDKey": 1688850654838804,
    "ReadOnly": true,
    "WriteOnly": false,
    "Event": "valueChanged",
    "TimeStamp": 1614084892
}

Expected behavior

Access control notifications to be exposed.

Additional context

Add any other context about the problem here.

bug
Source
picture roflmao

All 40 comments

There are some awkward notification under this namespace which looks relevant, but not in the same format as the rest of the command classes:

$ mosquitto_sub -h 192.168.67.11 -t "z2m/nodeID_40/notification/#" -v 
z2m/nodeID_40/notification/Keypad_lock_operation_userId {"time":1613981036628,"value":null}
z2m/nodeID_40/notification/Unlock_by_RF_with_invalid_user_code {"time":1614084876324,"value":"01422420"}
z2m/nodeID_40/notification/Keypad_unlock_operation_userId {"time":1614084883016,"value":"1"}
z2m/nodeID_40/notification/Auto_lock_locked_operation {"time":1614084902782,"value":"00"}
roflmao picture roflmao on 23 Feb 2021

zwavejs log:
https://gist.githubusercontent.com/roflmao/5210e0be58825cd3e13f714729af5ca8/raw/816a56f4dadf8bafef898ab47050ddc44d77ef9c/gistfile1.txt

roflmao picture roflmao on 23 Feb 2021

@AlCalzone I remember an old issue like that where notifications where not sent from notification CC but as node notifications. Could be this something like that?

robertsLando picture robertsLando on 23 Feb 2021

I'll need to look at the attached logs later, but I'm seeing both V1 (alarmType/Level) and V2+ values (Access Control/...) for the same node. Something seems fishy. If the lock uses V1 alarms, you should not be seeing the V2 values and vice versa.

AlCalzone picture AlCalzone on 23 Feb 2021

Although that might be our fallback attempt where we treat V1 alarms that could be a V2 notification as such. That does not seem to be correct for this log. You'd need https://github.com/zwave-js/node-zwave-js/issues/1713

AlCalzone picture AlCalzone on 23 Feb 2021

The notification values (userId) come from the notification event's event parameters. Seems you're putting them under the incorrect topic @robertsLando

AlCalzone picture AlCalzone on 23 Feb 2021

Seems you're putting them under the incorrect topic @robertsLando

That events are from zwaveNode.on('notification' and I have reserved a special topic for this

robertsLando picture robertsLando on 23 Feb 2021

Yup, but the other values should come from the same notification. E.g. you'll get a notification with notificationEvent "Keypad lock operation" and the userId is part of that notification because they belong together.

AlCalzone picture AlCalzone on 23 Feb 2021

Also needs https://github.com/zwave-js/node-zwave-js/issues/1869 ?

robertsLando picture robertsLando on 23 Feb 2021
👍1

Depends on what command version the device actually sends

AlCalzone picture AlCalzone on 23 Feb 2021

So it looks like we are receiving V2+ commands, but I have no clue where Lock_state comes from

AlCalzone picture AlCalzone on 23 Feb 2021

@roflmao did you remove some lines? I'm missing the SERIAL data for security encapsulated NotificationCCReports

AlCalzone picture AlCalzone on 23 Feb 2021

node40.lock.log

Sorry, my grep foo failed again

roflmao picture roflmao on 23 Feb 2021

@roflmao Is this fixed?

robertsLando picture robertsLando on 15 Mar 2021

@robertsLando Same on 2.1.2, will test 2.3.0 tonight

roflmao picture roflmao on 15 Mar 2021

If it persists, please make logs with the new version and keep track which notification events do not update the status.

AlCalzone picture AlCalzone on 15 Mar 2021

@roflmao Any time to also give a try to #864 ?

robertsLando picture robertsLando on 15 Mar 2021

@robertsLando Will have to build it first.

First off zwavejs2mqtt 2.3.0/zwave-js 6.6.2:

First off; MQTT on unlock (with autolock after 5 secs)
Nothing on z2m/nodeID_40/113/#"
This on "z2m/nodeID_40/notification/#":

z2m/nodeID_40/notification/Auto_lock_locked_operation {"time":1615843304716,"value":"00"}

zwave-js log:
node40.lock.log

Notice: The lock has "interview stage" RestartFromCache after upgrade from 2.2.x to 2.3.0

roflmao picture roflmao on 15 Mar 2021

zwavejs2mqtt 2.3.0+5a726f9.5a726f9 / zwave-js 7.0.0-beta.0-d5cf49b :

z2m/nodeID_40/113/0/Access_Control/Lock_state {"id":"40-113-0-Access Control-Lock state","nodeId":40,"commandClass":113,"commandClassName":"Notification","endpoint":0,"property":"Access Control","propertyName":"Access Control","propertyKey":"Lock state","propertyKeyName":"Lock state","type":"number","readable":true,"writeable":false,"label":"Lock state","stateless":false,"ccSpecific":{"notificationType":6},"min":0,"max":255,"list":true,"states":[{"text":"idle","value":0},{"text":"Lock jammed","value":11}],"value":0,"lastUpdate":1615846098376,"nodeName":"","nodeLocation":""}
z2m/nodeID_40/113/0/Home_Security/Cover_status {"id":"40-113-0-Home Security-Cover status","nodeId":40,"commandClass":113,"commandClassName":"Notification","endpoint":0,"property":"Home Security","propertyName":"Home Security","propertyKey":"Cover status","propertyKeyName":"Cover status","type":"number","readable":true,"writeable":false,"label":"Cover status","stateless":false,"ccSpecific":{"notificationType":7},"min":0,"max":255,"list":true,"states":[{"text":"idle","value":0},{"text":"Tampering, product cover removed","value":3}],"value":0,"lastUpdate":1615846098377,"nodeName":"","nodeLocation":""}
z2m/nodeID_40/113/0/Access_Control/Lock_state {"id":"40-113-0-Access Control-Lock state","nodeId":40,"commandClass":113,"commandClassName":"Notification","endpoint":0,"property":"Access Control","propertyName":"Access Control","propertyKey":"Lock state","propertyKeyName":"Lock state","type":"number","readable":true,"writeable":false,"label":"Lock state","stateless":false,"ccSpecific":{"notificationType":6},"min":0,"max":255,"list":true,"states":[{"text":"idle","value":0},{"text":"Lock jammed","value":11}],"value":0,"lastUpdate":1615846132779,"nodeName":"","nodeLocation":""}
z2m/nodeID_40/113/0/Home_Security/Cover_status {"id":"40-113-0-Home Security-Cover status","nodeId":40,"commandClass":113,"commandClassName":"Notification","endpoint":0,"property":"Home Security","propertyName":"Home Security","propertyKey":"Cover status","propertyKeyName":"Cover status","type":"number","readable":true,"writeable":false,"label":"Cover status","stateless":false,"ccSpecific":{"notificationType":7},"min":0,"max":255,"list":true,"states":[{"text":"idle","value":0},{"text":"Tampering, product cover removed","value":3}],"value":0,"lastUpdate":1615846132779,"nodeName":"","nodeLocation":""}

Nothing for z2m/nodeID_40/notification/#

zwavejs2mqtt crashed:

 2021-03-15 23:08:01.907 INFO ZWAVE: Node 40: value updated: 98-0-currentMode 255 => 255                                                                                                                           
 2021-03-15 23:08:01.911 INFO ZWAVE: Node 40: value updated: 98-0-outsideHandlesCanOpenDoor false,false,false,false => false,false,false,false                                                                     
 2021-03-15 23:08:01.914 INFO ZWAVE: Node 40: value updated: 98-0-insideHandlesCanOpenDoor false,false,false,false => false,false,false,false                                                                      
 2021-03-15 23:08:01.917 INFO ZWAVE: Node 40: value updated: 98-0-latchStatus open => open                                                                                                                         
 2021-03-15 23:08:01.919 INFO ZWAVE: Node 40: value updated: 98-0-boltStatus locked => locked                                                                                                                      
 2021-03-15 23:08:01.921 INFO ZWAVE: Node 40: value updated: 98-0-doorStatus closed => closed                                                                                                                      
 2021-03-15 23:08:02.042 INFO ZWAVE: Node 49: metadata updated: 49-2-Air temperature                                                                                                                               
 2021-03-15 23:08:02.045 INFO ZWAVE: Node 49: value updated: 49-2-Air temperature 25 => 25                                                                                                                         
 2021-03-15 23:08:02.592 INFO ZWAVE: Node 49: metadata updated: 49-4-Air temperature                                                                                                                               
 2021-03-15 23:08:02.597 INFO ZWAVE: Node 49: value updated: 49-4-Air temperature 27.1 => 26.9                                                                                                                     
 2021-03-15 23:08:04.377 INFO ZWAVE: Node 42: value updated: 38-1-currentValue 99 => 99                                                                                                                            
 2021-03-15 23:08:04.999 INFO ZWAVE: Node 42: metadata updated: 49-1-Power                                                                                                                                         
 2021-03-15 23:08:05.002 INFO ZWAVE: Node 42: value updated: 49-1-Power 0.2 => 16.2                                                                                                                                
 2021-03-15 23:08:05.415 INFO ZWAVE: Node 40: value updated: 98-0-currentMode 255 => 0                                                                                                                             
 This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason:                  
 TypeError: Right-hand side of 'instanceof' is not an object                                                                                                                                                       
     at ZwaveClient.onNodeNotification (/usr/src/app/lib/ZwaveClient.js:682:12)                                                                                                                                    
     at ZWaveNode.emit (events.js:326:22)                                                                                                                                                                          
     at ZWaveNode.EventEmitter.emit (domain.js:483:12)                                                                                                                                                             
     at ZWaveNode.handleNotificationReport (/usr/src/app/node_modules/zwave-js/src/lib/node/Node.ts:2391:10)                                                                                                       
     at ZWaveNode.handleCommand (/usr/src/app/node_modules/zwave-js/src/lib/node/Node.ts:1821:16)                                                                                                                  
     at Driver.handleRequest (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:1922:16)                                                                                                                 
     at Driver.handleUnsolicitedMessage (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:1698:16)                                                                                                      
     at Object.notifyUnsolicited (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:503:16)                                                                                                              
     at notifyUnsolicited (/usr/src/app/node_modules/zwave-js/src/lib/driver/SendThreadMachine.ts:568:19)                                                                                                          
     at Interpreter.exec (/usr/src/app/node_modules/xstate/lib/interpreter.js:657:24)

zwavejs log:
node40.lock.log

roflmao picture roflmao on 15 Mar 2021

@AlCalzone It's happening here:

https://github.com/zwave-js/zwavejs2mqtt/pull/864/files#diff-517f45dc25a0d4f803722882eff496478dbc7e2e775fe485d049b5dec1185641R682

Could it be that args are undefined?

robertsLando picture robertsLando on 16 Mar 2021

The notification event is only used in two locations within zwave-js, both times with a value for args.
This is line 2391 which causes the error above:

grafik

🤷🏻‍♂️

AlCalzone picture AlCalzone on 16 Mar 2021

So what why that error? I cannot explain...

robertsLando picture robertsLando on 16 Mar 2021

@roflmao Fixed, please try to rebuild and test :)

robertsLando picture robertsLando on 16 Mar 2021

Version 2.3.0+c5f0c92.c5f0c92 / zwavejs 7.0.0-beta.0-8a504ba
crashes even worse on every start:

2021-03-16 22:19:34.434 INFO ZWAVE: Controller status: Scan completed 2021-03-16 22:19:34.434 INFO ZWAVE: Network scan complete. Found: 19 nodes 2021-03-16 22:19:39.140 INFO ZWAVE: Node 11: value updated: 50-0-value-66049 0 => 0 2021-03-16 22:19:52.786 INFO ZWAVE: Node 47: value updated: 50-1-value-65537 1055.4 => 1055.4 This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason: TypeError: Cannot read property 'type' of undefined at Object.dumpMetadata (/usr/src/app/node_modules/@zwave-js/server/dist/lib/state.js:42:24) at /usr/src/app/node_modules/@zwave-js/server/dist/lib/forward.js:91:58 at Array.forEach (<anonymous>) at notifyNodeOnValueOrMetadataUpdates (/usr/src/app/node_modules/@zwave-js/server/dist/lib/forward.js:86:34) at ZWaveNode.<anonymous> (/usr/src/app/node_modules/@zwave-js/server/dist/lib/forward.js:147:21) at ZWaveNode.emit (events.js:326:22) at ZWaveNode.EventEmitter.emit (domain.js:483:12) at ZWaveNode.translateValueEvent (/usr/src/app/node_modules/zwave-js/src/lib/node/Node.ts:349:8) at ValueDB.emit (events.js:314:20) at ValueDB.EventEmitter.emit (domain.js:483:12)

node40.lock.log

roflmao picture roflmao on 16 Mar 2021

That's a bug in zwave-js-server 1.2.0. Not sure what they did there.
Or rather: I know what, but not why

AlCalzone picture AlCalzone on 16 Mar 2021

Ok, will test again when its sorted out then :+1:

roflmao picture roflmao on 17 Mar 2021

1.2.1 is out

AlCalzone picture AlCalzone on 17 Mar 2021
👍1

Also available in zjs2mqtt 2.4.0

robertsLando picture robertsLando on 18 Mar 2021

node40.log

Lock is suddenly unknown manufacter, product etc.

roflmao picture roflmao on 21 Mar 2021

Argg.. :confounded: @AlCalzone ?

robertsLando picture robertsLando on 22 Mar 2021 
2021-03-21T20:18:24.189Z DRIVER » [Node 040] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      31
                                  └─[SecurityCCCommandEncapsulation]
                                    │ nonce id: 241
                                    └─[SecurityCCCommandsSupportedGet]
2021-03-21T20:18:24.192Z SERIAL « [ACK]                                                                   (0x06)
2021-03-21T20:18:24.199Z SERIAL « 0x0104011301e8                                                       (6 bytes)
2021-03-21T20:18:24.200Z SERIAL » [ACK]                                                                   (0x06)
2021-03-21T20:18:24.200Z DRIVER « [RES] [SendData]
                                    was sent: true
2021-03-21T20:18:24.319Z SERIAL « 0x010700131f00000df9                                                 (9 bytes)
2021-03-21T20:18:24.320Z SERIAL » [ACK]                                                                   (0x06)
2021-03-21T20:18:24.321Z DRIVER « [REQ] [SendData]
                                    callback id:     31
                                    transmit status: OK
2021-03-21T20:18:34.334Z CNTRLR   [Node 040] Timed out while waiting for a response from the node
2021-03-21T20:18:34.334Z CNTRLR   [Node 040] The node is not included securely. Continuing interview non-securel
                                  y.

No response when zwave-js requests the list of secure commands. As a result, zwave-js assumes the device is insecure, when it is not. ==> No responses to anything.

@roflmao did you change the network key or something?

AlCalzone picture AlCalzone on 23 Mar 2021

Nothing changed im afraid, only 6.x to 7.x zwavejs and zwavev7 branch for zwavejs2mqtt

roflmao picture roflmao on 23 Mar 2021

It worked fine on first beta IIRC

roflmao picture roflmao on 23 Mar 2021

Then it might just be a temporary RF problem. IMO zwave-js is doing the correct thing here, given the information it has. The only situations where the response to SecurityCCCommandsSupportedGet can be expected to time out is when the device isn't actually secure (we use the command to test for secure inclusion) or when the response gets lost due to bad connectivity or bad routes.

AlCalzone picture AlCalzone on 23 Mar 2021

Fun story; the battery was drained so it was without power. The lock had 45% before upgrading so something fishy happened, also the lock prints as alive and does respond for so very strange.

roflmao picture roflmao on 24 Mar 2021

zwavejs2mqtt: 3.0.2
zwave-js: 7.0.0

I only get these through MQTT on CC 113:

mars 29 16:35:12 z2m/nodeID_40/113/0/Access_Control/Keypad_unlock_operation {"time":1617028512815,"value":{"userId":109}}
mars 29 16:35:32 z2m/nodeID_40/113/0/Access_Control/Auto_lock_locked_operation {"time":1617028532741,"value":"00"}
mars 29 16:52:32 z2m/nodeID_40/113/0/Access_Control/Keypad_unlock_operation {"time":1617029552699,"value":{"userId":109}}
mars 29 16:52:52 z2m/nodeID_40/113/0/Access_Control/Auto_lock_locked_operation {"time":1617029572684,"value":"00"}
mars 29 17:23:38 z2m/nodeID_40/113/0/Access_Control/Keypad_unlock_operation {"time":1617031418206,"value":{"userId":1}}
mars 29 17:24:01 z2m/nodeID_40/113/0/Access_Control/Auto_lock_locked_operation {"time":1617031441146,"value":"00"}
mars 29 17:27:07 z2m/nodeID_40/113/0/Access_Control/Keypad_unlock_operation {"time":1617031627210,"value":{"userId":1}}
mars 29 17:27:15 z2m/nodeID_40/113/0/Access_Control/Keypad_lock_operation {"time":1617031635654,"value":{"userId":0}}
mars 29 17:27:21 z2m/nodeID_40/113/0/Access_Control/Keypad_unlock_operation {"time":1617031641339,"value":{"userId":1}}
mars 29 17:27:25 z2m/nodeID_40/113/0/Access_Control/Auto_lock_locked_operation {"time":1617031645988,"value":"00"}
mars 29 19:03:35 z2m/nodeID_40/113/0/Access_Control/Keypad_unlock_operation {"time":1617037415803,"value":{"userId":109}}
mars 29 19:03:59 z2m/nodeID_40/113/0/Access_Control/Auto_lock_locked_operation {"time":1617037439248,"value":"00"}

node40.log

roflmao picture roflmao on 29 Mar 2021

Long story short - we're not acting on these events yet. Will add that.

AlCalzone picture AlCalzone on 29 Mar 2021
👍1

Correction - keypad (un)lock should be doing something already. And I do see it change the currentMode property for the Door Lock CC:

2021-03-29T14:35:12.807Z DRIVER « [Node 040] [REQ] [ApplicationCommand]
                                  └─[SecurityCCCommandEncapsulation]
                                    │ sequenced: false
                                    └─[NotificationCCReport]
                                        notification type:   Access Control
                                        notification status: 255
                                        notification event:  Keypad unlock operation
                                        event parameters:    [object Object]
2021-03-29T14:35:12.809Z CNTRLR   [Node 040] [~] [Door Lock] currentMode: 255 => 0                  [Endpoint 0]
AlCalzone picture AlCalzone on 29 Mar 2021

I've raised https://github.com/zwave-js/node-zwave-js/pull/2192 for the Auto lock event.

Lock_state (jammed/idle) is not yet updated by this, because we need to be a bit smarter => https://github.com/zwave-js/node-zwave-js/issues/1543

AlCalzone picture AlCalzone on 29 Mar 2021

This should be fixed now

robertsLando picture robertsLando on 14 Jun 2021
Was this page helpful?
0 / 5 - 0 ratings

Related issues

jmgiaever picture jmgiaever  ·  5Comments
haavardNO picture haavardNO  ·  3Comments
raymonvdm picture raymonvdm  ·  3Comments
jonathan-reisdorf picture jonathan-reisdorf  ·  3Comments
drjjr2 picture drjjr2  ·  7Comments