search

OpenZWave / node-openzwave-shared

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

Wrong final values being reported for Cooper Dimmer #190

Closed rgerrans closed 6 years ago

rgerrans commented 7 years ago

If I change my Cooper dimmer from on/off it's reporting an intermediate dim level instead of the final. Here is an example of going from off to full on at a switch push. openzwave-shared is reporting a final value of 6 but if I run the same experiment with MinOZW I can clearly see the final value of 99 in the logs. Below are logs from both experiment.

node-openzwave-shared

2017-08-09 09:14:17.908 Detail, Node003,   Received: 0x01, 0x17, 0x00, 0x49, 0x84, 0x03, 0x11, 0x04, 0x11, 0x04, 0x26, 0x27, 0x75, 0x86, 0x70, 0x71, 0x85, 0x77, 0x2b, 0x2c, 0x72, 0x73, 0x82, 0x87, 0x24
2017-08-09 09:14:17.908 Detail, 
2017-08-09 09:14:17.909 Info, Node003, UPDATE_STATE_NODE_INFO_RECEIVED from node 3
2017-08-09 09:14:17.909 Detail, Node003, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2017-08-09 09:14:17.909 Detail, Node003, QueryStage_Dynamic
2017-08-09 09:14:17.910 Detail, Node003, Queuing (Send) SwitchMultilevelCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x26, 0x02, 0x25, 0x31, 0xd4
2017-08-09 09:14:17.910 Detail, Node003, Queuing (Send) AlarmCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x71, 0x04, 0x25, 0x32, 0x86
2017-08-09 09:14:17.911 Detail, Node003, Queuing (Send) IndicatorCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x87, 0x02, 0x25, 0x33, 0x77
2017-08-09 09:14:17.911 Detail, Node003, Queuing (Query) Query Stage Complete (Dynamic)
2017-08-09 09:14:17.911 Detail, 
2017-08-09 09:14:17.912 Info, Node003, Sending (Send) message (Callback ID=0x31, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x26, 0x02, 0x25, 0x31, 0xd4
2017-08-09 09:14:17.921 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2017-08-09 09:14:17.921 Detail, Node003,   ZW_SEND_DATA delivered to Z-Wave stack
2017-08-09 09:14:17.938 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x31, 0x00, 0x00, 0x02, 0xd8
2017-08-09 09:14:17.939 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x31 received (expected 0x31)
2017-08-09 09:14:17.939 Info, Node003, Request RTT 27 Average Request RTT 33
2017-08-09 09:14:17.939 Detail,   Expected callbackId was received
2017-08-09 09:14:18.304 Detail, Node003,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x03, 0x03, 0x26, 0x03, 0x06, 0xd1
2017-08-09 09:14:18.304 Detail, 
2017-08-09 09:14:18.304 Info, Node003, Response RTT 393 Average Response RTT 233
2017-08-09 09:14:18.305 Info, Node003, Received SwitchMultiLevel report: level=6
2017-08-09 09:14:18.305 Detail, Node003, Refreshed Value: old value=0, new value=6, type=byte
2017-08-09 09:14:18.305 Detail, Node003, Changes to this value are not verified
2017-08-09 09:14:18.306 Detail, Node003,   Expected reply and command class was received
2017-08-09 09:14:18.306 Detail, Node003,   Message transaction complete
2017-08-09 09:14:18.306 Detail, 
2017-08-09 09:14:18.306 Detail, Node003, Removing current message
2017-08-09 09:14:18.307 Detail, Node003, Notification: ValueChanged
2017-08-09 09:14:18.307 Detail, 
2017-08-09 09:14:18.308 Info, Node003, Sending (Send) message (Callback ID=0x32, Expected Reply=0x04) - AlarmCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x71, 0x04, 0x25, 0x32, 0x86
2017-08-09 09:14:18.317 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2017-08-09 09:14:18.318 Detail, Node003,   ZW_SEND_DATA delivered to Z-Wave stack
2017-08-09 09:14:18.333 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x32, 0x00, 0x00, 0x02, 0xdb
2017-08-09 09:14:18.335 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x32 received (expected 0x32)
2017-08-09 09:14:18.337 Info, Node003, Request RTT 28 Average Request RTT 30
2017-08-09 09:14:18.338 Detail,   Expected callbackId was received
2017-08-09 09:14:18.344 Detail, Node003,   Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x03, 0x04, 0x71, 0x05, 0xd0, 0x00, 0x52
2017-08-09 09:14:18.345 Detail, 
2017-08-09 09:14:18.347 Info, Node003, Response RTT 38 Average Response RTT 135
2017-08-09 09:14:18.349 Info, Node003, Received Alarm report: type=208, level=0
2017-08-09 09:14:18.350 Detail, Node003, Refreshed Value: old value=216, new value=208, type=byte
2017-08-09 09:14:18.352 Detail, Node003, Changes to this value are not verified
2017-08-09 09:14:18.353 Detail, Node003, Refreshed Value: old value=0, new value=0, type=byte
2017-08-09 09:14:18.355 Detail, Node003, Changes to this value are not verified
2017-08-09 09:14:18.356 Detail, Node003,   Expected reply and command class was received
2017-08-09 09:14:18.357 Detail, Node003,   Message transaction complete
2017-08-09 09:14:18.358 Detail, 
2017-08-09 09:14:18.358 Detail, Node003, Removing current message
2017-08-09 09:14:18.359 Detail, Node003, Notification: ValueChanged
2017-08-09 09:14:18.360 Detail, Node003, Notification: ValueChanged
2017-08-09 09:14:18.361 Detail, 
2017-08-09 09:14:18.362 Info, Node003, Sending (Send) message (Callback ID=0x33, Expected Reply=0x04) - IndicatorCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x87, 0x02, 0x25, 0x33, 0x77
2017-08-09 09:14:18.370 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2017-08-09 09:14:18.372 Detail, Node003,   ZW_SEND_DATA delivered to Z-Wave stack
2017-08-09 09:14:18.388 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x33, 0x00, 0x00, 0x02, 0xda
2017-08-09 09:14:18.390 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x33 received (expected 0x33)
2017-08-09 09:14:18.391 Info, Node003, Request RTT 28 Average Request RTT 29
2017-08-09 09:14:18.393 Detail,   Expected callbackId was received
2017-08-09 09:14:18.398 Detail, Node003,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x03, 0x03, 0x87, 0x03, 0x00, 0x76
2017-08-09 09:14:18.400 Detail, 
2017-08-09 09:14:18.401 Info, Node003, Response RTT 38 Average Response RTT 86
2017-08-09 09:14:18.403 Info, Node003, Received an Indicator report: Indicator=0
2017-08-09 09:14:18.404 Detail, Node003, Refreshed Value: old value=0, new value=0, type=byte
2017-08-09 09:14:18.405 Detail, Node003, Changes to this value are not verified
2017-08-09 09:14:18.405 Detail, Node003,   Expected reply and command class was received
2017-08-09 09:14:18.406 Detail, Node003,   Message transaction complete
2017-08-09 09:14:18.406 Detail, 
2017-08-09 09:14:18.407 Detail, Node003, Removing current message
2017-08-09 09:14:18.408 Detail, Node003, Notification: ValueChanged
2017-08-09 09:14:18.412 Detail, Node003, Query Stage Complete (Dynamic)
2017-08-09 09:14:18.414 Detail, Node003, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2017-08-09 09:14:18.416 Detail, Node003, QueryStage_Configuration
2017-08-09 09:14:18.416 Detail, Node003, QueryStage_Complete
2017-08-09 09:14:18.417 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=1
2017-08-09 09:14:18.418 Warning, CheckCompletedNodeQueries all=0, deadFound=1 sleepingOnly=1
2017-08-09 09:14:18.418 Detail, Node003, Notification: NodeQueriesComplete

MinOZW

2017-08-09 09:20:18.782 Info, Node003, Sending (Query) message (Callback ID=0x34, Expected Reply=0x04) - ManufacturerSpecificCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x72, 0x04, 0x25, 0x34, 0x83
2017-08-09 09:20:18.785 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x00, 0xe9
2017-08-09 09:20:18.785 Error, Node003, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2017-08-09 09:20:19.682 Detail, Node003,   Received: 0x01, 0x17, 0x00, 0x49, 0x84, 0x03, 0x11, 0x04, 0x11, 0x04, 0x26, 0x27, 0x75, 0x86, 0x70, 0x71, 0x85, 0x77, 0x2b, 0x2c, 0x72, 0x73, 0x82, 0x87, 0x24
2017-08-09 09:20:19.686 Detail, 
2017-08-09 09:20:19.686 Info, Node003, UPDATE_STATE_NODE_INFO_RECEIVED from node 3
2017-08-09 09:20:19.687 Detail, Node003, AdvanceQueries queryPending=1 queryRetries=0 queryStage=ManufacturerSpecific1 live=1
2017-08-09 09:20:19.743 Detail, Node003,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x03, 0x03, 0x20, 0x01, 0x63, 0xb0
2017-08-09 09:20:19.743 Detail, 
2017-08-09 09:20:19.743 Info, Node003, Response RTT 962 Average Response RTT 962
2017-08-09 09:20:19.744 Info, Node003, Received Basic set from node 3: level=99.  Sending event notification.
2017-08-09 09:20:19.744 Detail, Node003, Notification: NodeEvent
2017-08-09 09:20:26.047 Detail, Node003,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x03, 0x02, 0x82, 0x01, 0x71
2017-08-09 09:20:26.047 Detail, 
2017-08-09 09:20:26.048 Info, Node003, Response RTT 7266 Average Response RTT 4114
2017-08-09 09:20:26.048 Info, Node003, Received Hail command from node 3
2017-08-09 09:20:26.048 Detail, Node003, Queuing (Send) SwitchMultilevelCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x26, 0x02, 0x25, 0x49, 0xac
2017-08-09 09:20:26.049 Detail, Node003, Queuing (Send) AlarmCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x71, 0x04, 0x25, 0x4a, 0xfe
2017-08-09 09:20:26.049 Detail, Node003, Queuing (Send) IndicatorCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x87, 0x02, 0x25, 0x4b, 0x0f
2017-08-09 09:20:28.781 Error, Node003, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-08-09 09:20:28.781 Detail, Node003, Removing current message
2017-08-09 09:20:28.782 Detail, Node003, Notification: Notification - TimeOut
2017-08-09 09:20:28.782 Detail, 
2017-08-09 09:20:28.782 Info, Node003, Sending (Send) message (Callback ID=0x49, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x26, 0x02, 0x25, 0x49, 0xac
2017-08-09 09:20:29.783 Error, Node003, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-08-09 09:20:29.783 Detail, Node003, Removing current message
2017-08-09 09:20:29.783 Detail, Node003, Notification: Notification - TimeOut
2017-08-09 09:20:29.784 Detail, 
2017-08-09 09:20:29.784 Info, Node003, Sending (Send) message (Callback ID=0x4a, Expected Reply=0x04) - AlarmCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x71, 0x04, 0x25, 0x4a, 0xfe
2017-08-09 09:20:30.671 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x00, 0xe9
2017-08-09 09:20:30.671 Error, Node003, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2017-08-09 09:20:30.672 Detail, Node003, CAN received...triggering resend
2017-08-09 09:20:30.672 Detail, 
2017-08-09 09:20:30.673 Info, Node003, Sending (Send) message (Attempt 2, Callback ID=0x4c, Expected Reply=0x04) - AlarmCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x71, 0x04, 0x25, 0x4c, 0xf8
2017-08-09 09:20:30.675 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x00, 0xe9
2017-08-09 09:20:30.675 Error, Node003, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2017-08-09 09:20:38.838 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x4c, 0x01, 0x03, 0x30, 0x95
2017-08-09 09:20:38.838 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x4c received (expected 0x4c)
2017-08-09 09:20:38.838 Info, Node003, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2017-08-09 09:20:38.839 Warning, Node003, WARNING: Device is not a sleeping node.
2017-08-09 09:20:38.839 Detail, Node001,   Expected callbackId was received
2017-08-09 09:20:39.164 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x4c, 0x01, 0x03, 0x51, 0xf4
2017-08-09 09:20:39.164 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x4c received (expected 0x00)
2017-08-09 09:20:39.165 Warning, Node003, WARNING: Unexpected Callback ID received
2017-08-09 09:20:39.784 Error, Node003, ERROR: Dropping command, expected response not received after 2 attempt(s)
2017-08-09 09:20:39.784 Detail, Node003, Removing current message
2017-08-09 09:20:39.785 Detail, Node003, Notification: Notification - TimeOut
2017-08-09 09:20:39.785 Detail, 
2017-08-09 09:20:39.785 Info, Node003, Sending (Send) message (Callback ID=0x4b, Expected Reply=0x04) - IndicatorCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x87, 0x02, 0x25, 0x4b, 0x0f
2017-08-09 09:20:39.793 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2017-08-09 09:20:39.793 Detail, Node003,   ZW_SEND_DATA delivered to Z-Wave stack
2017-08-09 09:20:39.811 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x4b, 0x00, 0x00, 0x03, 0xa3
2017-08-09 09:20:39.811 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x4b received (expected 0x4b)
2017-08-09 09:20:39.811 Info, Node003, Request RTT 25 Average Request RTT 25
2017-08-09 09:20:39.811 Detail,   Expected callbackId was received
2017-08-09 09:20:39.821 Detail, Node003,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x03, 0x03, 0x87, 0x03, 0x00, 0x76
2017-08-09 09:20:39.822 Detail, 
2017-08-09 09:20:39.822 Info, Node003, Response RTT 36 Average Response RTT 2075
2017-08-09 09:20:39.823 Info, Node003, Received an Indicator report: Indicator=0
2017-08-09 09:20:39.823 Detail, Node003, Initial read of value
2017-08-09 09:20:39.824 Detail, Node003,   Expected reply and command class was received
2017-08-09 09:20:39.824 Detail, Node003,   Message transaction complete
2017-08-09 09:20:39.825 Detail, 
2017-08-09 09:20:39.825 Detail, Node003, Removing current message
2017-08-09 09:20:39.826 Detail, Node003, Notification: ValueChanged
2017-08-09 09:20:39.827 Detail, Node003, Query Stage Complete (ManufacturerSpecific1)
2017-08-09 09:20:39.827 Detail, Node003, AdvanceQueries queryPending=0 queryRetries=0 queryStage=NodeInfo live=1
2017-08-09 09:20:39.828 Detail, Node003, QueryStage_NodePlusInfo
2017-08-09 09:20:39.829 Detail, Node003, QueryStage_SecurityReport
2017-08-09 09:20:39.829 Detail, Node003, QueryStage_ManufacturerSpecific2
2017-08-09 09:20:39.830 Detail, Node003, Queuing (Query) ManufacturerSpecificCmd_Get (Node=3): 0x01, 0
rgerrans commented 7 years ago

Wanted to follow-up to see if any had a chance to look I to this?

fraser73 commented 6 years ago

Not a fix, but a workaround: I have the same problem with a couple of different dimmers, only for switching off. One I resolved by changing the speed that the dimmer dims at (usually a config option, I found using open-zwave control panel), the other by sending the command to switch off, but splitting the flow via a 2sec delay, and sending it again, this results in the status being updated to the correct value.

I have to say that I'd always presumed this was a problem with open-zwave or the dimmers themselves, so hadn't bothered to report it as a problem here...

rgerrans commented 6 years ago

Thanks. Now that Homeseer has an MQTT plugin I ended up going that route for my ZWave needs.

ekarak commented 6 years ago

Devices that do not properly implement status updates typically need to be polled from the OZW lib at regular intervals. I had the same problem with a (long gone) HomePro dimmer module...

Resolving. This is not a node-openzwave problem, but a limitation in the underlying OZW library.