search

OpenZWave / node-openzwave-shared

OpenZWave addon for Node.js (all versions) including management and security functions
Other
198 stars 113 forks source link

Exception: Manager.cpp:1633 - 101 - Invalid ValueID #81

Closed polarathene closed 8 years ago

polarathene commented 8 years ago

TL;DR: Any device that triggers node event event appears to pass a bad value to zwaveValue2v8Value(value). OpenZWave::Manager doesn't seem to like lines that call it such as:

Nan::Set(valobj, Nan::New<String>("label").ToLocalChecked(),     Nan::New<String> (mgr->GetValueLabel(value).c_str()).ToLocalChecked());

Which leads to terminal output:

Warning, Exception: Manager.cpp:1633 - 101 - Invalid ValueID passed to GetValueLabel

And that causes a default value to be set to the property resulting in a valueId param value for node event event being incorrect, thus no useful data to read.

Looked the error up at OpenZwave, it's popped up a few times but general response is the issue doesn't belong there, so I guess I've made some sort of error or this is an odd bug being triggered by the device or caused by node-openzwave-shared.

OpenZWave's Manager class is throwing errors when calling zwaveValue2v8Value(value). I'm pretty positive the source of the issue is here: OpenZWave::Notification::Type_NodeEvent, however I have no C++ experience or knowledge of how to debug.

Device is Fibaro Motion Sensor, FGMS-001.

This is the value object node event reports after the error:

class_id: 0
genre: "basic"
help: ""
index: 0
instance: 1
is_polled: false
label: ""
max: 0
min: 0
node_id: 7
read_only: false
type: "bool"
units: ""
value: true
value_id: "7-0-1-0"
write_only: false

The value_id of 7-0-1-0 is node-command_class-instance-value from what I understand? CC 0 is NO_OPERATION. I take it, the class_id is 0 because that's the default value for an Integer, or is the device actually reporting the 0/255 event with CC 0?

This is the first z-wave device I've been trying to listen to events for rather than just calling setValue() on. Seems a bit odd with node 7 getting added but not performing a node ready event, What could cause this? Would adding it with addNode(true) possibly be the cause? I'll remove the node and try to add it with addNode(false) instead. Tried this, no difference.

Extra details

When I log the object stored to an array of nodes like examples show nodes[nodeid]. It doesn't seem like it has anything but the command classes updated, everything else is default as of node added event:

classes: {
48: Object // Sensor Binary
49: Object // Sensor Multilevel
128: Object // Battery
132: Object // Wakeup
134: Object // Version
156: Object // Sensor Alarm
}
loc: ""
manufacturer: ""
manufacturerid: ""
name: ""
product: ""
productid: ""
producttype: ""
ready: false
type: ""

Perhaps it's missing some sort of xml definition file? I have no idea what makes the node ready so that it can trigger the node ready event.

node ready event, I think this was when I added it initially (via zwave.addNode(true)), perhaps I should have used false? scan complete finishes without logging this node, yet when it's sensor is triggered the error still logs :S :

node7: FIBARO System, Unknown: type=0800, id=3001
node7: name="", type="Routing Binary Sensor", location=""
node7: class 48
node7:   Sensor=false
node7: class 49
node7:   Temperature=0.0
node7:   Luminance=0.0
node7: class 128
node7:   Battery Level=100
node7: class 132
node7:   Wake-up Interval=7200
node7: class 134
node7:   Library Version=3
node7:   Protocol Version=3.67
node7:   Application Version=2.06
node7: class 156
node7:   General=0

Full Error:

2016-03-03 14:11:51.844 Detail, Node007,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x07, 0x03, 0x20, 0x01, 0xff, 0x28
2016-03-03 14:11:51.844 Detail, 
2016-03-03 14:11:51.844 Info, Node007, Received Basic set from node 7: level=255.  Sending event notification.
2016-03-03 14:11:51.844 Detail, Node007, Notification: NodeEvent
2016-03-03 14:11:51.845 Warning, Exception: Manager.cpp:1633 - 101 - Invalid ValueID passed to GetValueLabel
2016-03-03 14:11:51.845 Warning, Exception: Manager.cpp:1681 - 101 - Invalid ValueID passed to GetValueUnits
2016-03-03 14:11:51.845 Warning, Exception: Manager.cpp:1729 - 101 - Invalid ValueID passed to GetValueHelp
2016-03-03 14:11:51.845 Warning, Exception: Manager.cpp:1827 - 101 - Invalid ValueID passed to IsValueReadOnly
2016-03-03 14:11:51.845 Warning, Exception: Manager.cpp:1852 - 101 - Invalid ValueID passed to IsValueWriteOnly
2016-03-03 14:11:51.845 Warning, Exception: Manager.cpp:1902 - 101 - Invalid ValueID passed to IsValuePolled
2016-03-03 14:11:51.845 Warning, Exception: Manager.cpp:1777 - 101 - Invalid ValueID passed to GetValueMin
2016-03-03 14:11:51.845 Warning, Exception: Manager.cpp:1802 - 101 - Invalid ValueID passed to GetValueMax
2016-03-03 14:11:51.845 Warning, Exception: Manager.cpp:1934 - 101 - Invalid ValueID passed to GetValueAsBool
polarathene commented 8 years ago

Removed node 7, added with addNode(false), device was added as node 8. Still throws the warning/exceptions.

I've tried another device, node 2 which is a Door/Window Sensor from Aeotec (Gen5), these are all paired to a USB Z-wave Gen 5 controller by Aeotec as well. This device also throws the same errors for it's sensor.

2016-03-03 16:48:11.060 Detail, Node002,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x02, 0x03, 0x20, 0x01, 0x00, 0xd2
2016-03-03 16:48:11.060 Detail, 
2016-03-03 16:48:11.060 Info, Node002, Received Basic set from node 2: level=0.  Sending event notification.
2016-03-03 16:48:11.060 Detail, Node002, Notification: NodeEvent
2016-03-03 16:48:11.060 Warning, Exception: Manager.cpp:1633 - 101 - Invalid ValueID passed to GetValueLabel
2016-03-03 16:48:11.060 Warning, Exception: Manager.cpp:1681 - 101 - Invalid ValueID passed to GetValueUnits
2016-03-03 16:48:11.060 Warning, Exception: Manager.cpp:1729 - 101 - Invalid ValueID passed to GetValueHelp
2016-03-03 16:48:11.060 Warning, Exception: Manager.cpp:1827 - 101 - Invalid ValueID passed to IsValueReadOnly
2016-03-03 16:48:11.060 Warning, Exception: Manager.cpp:1852 - 101 - Invalid ValueID passed to IsValueWriteOnly
2016-03-03 16:48:11.060 Warning, Exception: Manager.cpp:1902 - 101 - Invalid ValueID passed to IsValuePolled
2016-03-03 16:48:11.060 Warning, Exception: Manager.cpp:1777 - 101 - Invalid ValueID passed to GetValueMin
2016-03-03 16:48:11.060 Warning, Exception: Manager.cpp:1802 - 101 - Invalid ValueID passed to GetValueMax
2016-03-03 16:48:11.060 Warning, Exception: Manager.cpp:1934 - 101 - Invalid ValueID passed to GetValueAsBool

2016-03-03 16:50:55.545 Detail, Node002,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x02, 0x0a, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x06, 0x17, 0x00, 0x00, 0x79
2016-03-03 16:50:55.545 Detail, 
2016-03-03 16:50:55.545 Info, Node002, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Access Control event:23, status=255
2016-03-03 16:50:55.545 Detail, Node002, Refreshed Value: old value=0, new value=0, type=byte
2016-03-03 16:50:55.545 Detail, Node002, Changes to this value are not verified
2016-03-03 16:50:55.545 Detail, Node002, Refreshed Value: old value=0, new value=0, type=byte
2016-03-03 16:50:55.545 Detail, Node002, Changes to this value are not verified
2016-03-03 16:50:55.545 Detail, Node002, Refreshed Value: old value=0, new value=0, type=byte
2016-03-03 16:50:55.545 Detail, Node002, Changes to this value are not verified
2016-03-03 16:50:55.545 Detail, Node002, Refreshed Value: old value=22, new value=23, type=byte
2016-03-03 16:50:55.545 Detail, Node002, Changes to this value are not verified
2016-03-03 16:50:55.545 Detail, Node002, Notification: ValueChanged
2016-03-03 16:50:55.545 Detail, Node002, Notification: ValueChanged
2016-03-03 16:50:55.545 Detail, Node002, Notification: ValueChanged
2016-03-03 16:50:55.545 Detail, Node002, Notification: ValueChanged

The device has two parts, contact/separation activates the sensor(presumably CC 48 binary switch?). The alarm report went off at the same time(I guess because it's not properly mounted and assumed it was being tampered with). As you can see it has the same node event problems that the Fibaro device had. Although this device has information in nodes[nodeid] so I take it the node ready event fired fine for it at least. Hopefully that helps narrow down the problem? Seems the bug belongs to node-openzwave-shared?

I've tried 1.4 and master branch( OpenZwave Version 1.4.77?) of OpenZWave library btw. We have quite a few zwave devices here, and can probably get one that you have if you have a similar device that triggers node event but doesn't trigger Invalid ValueID, if that happens hopefully can identify the cause and inform others in the README if I'm at fault. Otherwise I guess if you can replicate the bug you'd probably know what's wrong with the value? :)

2016-03-03 16:39:35.535 Started up node-openzwave-shared 2016-03-03 16:41:56.427 Scan Complete. First Node 2 event.

polarathene commented 8 years ago

I noticed that Node 2 was not ready initially either, it too had an empty device object in nodes[nodeid] originally but later became ready after scan complete event. This didn't have any effect on the node event errors from happening. You can see via this filtered log that node 2 was sleeping and waking up a bit, much later at Line 59 2016-03-03 17:03:28.660 it sends a wakeup notification and initilizes its device object at Line 290 2016-03-03 17:03:29.593

No idea if this helps.

Initial device object config:

classes: {
32: Object
48: Object
94: Object
113: Object
115: Object
128: Object
132: Object
134: Object
}
loc: ""
manufacturer: ""
manufacturerid: ""
name: ""
product: ""
productid: ""
producttype: ""
ready: false
type: ""

Device ready config:

classes: {
32: Object
48: Object
94: Object
113: Object
115: Object
128: Object
132: Object
134: Object
}
loc: ""
manufacturer: "Aeotec"
manufacturerid: "0x0086"
name: ""
product: "Unknown: type=0202, id=0078"
productid: "0x0078"
producttype: "0x0202"
ready: true
type: "Access Control Sensor"
polarathene commented 8 years ago

Hello again. I have a Pi around that has licensed software with it's own Z-Wave control library. I had been using that today, the Fibaro multi sensor is reporting updates to it correctly. Tried again with node-openzwave-shared, still getting the node event error events like before but the sensor is actually logging value updates unlike yesterday. Not sure what caused this behaviour change, beyond removing the node and adding it again to the controller with the other Z-Wave control library.

Fibaro Multi Sensor, node 9(previously 7), log Aeotec Door/Window Sensor, node 10(previously 2), log Fibaro Door/Window Sensor, node 6, log node ready device object:

classes: {
48: Object
128: Object
132: Object
134: Object
156: Object
}
loc: ""
manufacturer: "FIBARO System"
manufacturerid: "0x010f"
name: ""
product: "Unknown: type=0700, id=3000"
productid: "0x3000"
producttype: "0x0700"
ready: true
type: "Routing Binary Sensor"

The other two(mentioned in prior posts) did not trigger node ready.

You can see that node 9 is reporting more info, and that the error event seems to be due to the binary sensor value change, but for some reason it's being treated as a basic set command? Or perhaps level=255 is referring to Unhandled Command Class 0x60 which is either MULTI_CHANNEL_V2/MULTI_INSTANCE.

For the node 10 log we can see another Unhandled Command Class, this time 0x71 which is ALARM. On the other Z-Wave software, it's log reports the event as ALARM as well, but with values of 0/1, I'm assuming it's just treating them as boolean values which 0/255 are meant to be as well?

Node 6 on the other hand, which is pretty much the Fibaro version of Node 10 isn't reporting any Unhandled Command Class in it's log. But still throws the node event error like the other two were doing yesterday.

ekarak commented 8 years ago

Thanks for the bug report, that was a good one. I've just removed the ValueID from the "node event" callback's 3rd argument as its simply never being populated in the 1st place! You were indeed getting garbage from the addon... (hence the 'invalid ValueId') The only information that's available from the "node event" is 1) the node id and 2) the raw data passed to the Basic Set command payload. I've updated the documentation (README-events.md) accordingly. Big thanks to @Fishwaldo who stepped in to help!!