search

jperkin / node-openzwave

node.js interface to libopenzwave
Other
110 stars 54 forks source link

Modifying device state not working #9

Closed zonak closed 10 years ago

zonak commented 10 years ago

Tried turning off and on a device.

I am testing with a z-stick s2 and a GE 45604 Outdoor Module. I am attempting to turn the device off by issuing zwave.switchOff(2) when the node ready event is fired for the respective device.

This is what I get in the log:

2013-10-19 00:44:49.296 Node002, Polling: COMMAND_CLASS_SWITCH_BINARY index = 0 instance = 1 (poll queue has 0 messages)
2013-10-19 00:44:49.297 Node002, Queuing (Poll) SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0x09, 0xee
2013-10-19 00:44:49.299
2013-10-19 00:44:49.299 Node002, Sending (Poll) message (Callback ID=0x09, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0x09, 0xee
2013-10-19 00:44:49.304 Node002,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2013-10-19 00:44:49.304 Node002,   ZW_SEND_DATA delivered to Z-Wave stack
2013-10-19 00:44:49.316 Node002,   Received: 0x01, 0x05, 0x00, 0x13, 0x09, 0x00, 0xe0
2013-10-19 00:44:49.316 Node002,   ZW_SEND_DATA Request with callback ID 0x09 received (expected 0x09)
2013-10-19 00:44:49.316 Node002, Request RTT 17 Average Request RTT 17
2013-10-19 00:44:49.323 Node002,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x02, 0x03, 0x25, 0x03, 0xff, 0x2a
2013-10-19 00:44:49.323
2013-10-19 00:44:49.323 Node002, Response RTT 23 Average Response RTT 23
2013-10-19 00:44:49.323 Node002, Received SwitchBinary report from node 2: level=On
2013-10-19 00:44:49.323 Node002, Refreshed Value: old value=true, new value=true, type=bool
2013-10-19 00:44:49.323 Node002, Changes to this value are not verified
2013-10-19 00:44:49.323 Node002,   Expected reply and command class was received
2013-10-19 00:44:49.323 Node002,   Message transaction complete
2013-10-19 00:44:49.323
2013-10-19 00:44:49.324 Node002, Removing current message

and as per the log, the device is not turning off. It keeps retrying but with no success.

I also have the zwcfg*.cfg file as a gist here.

jperkin commented 10 years ago

Can you try the latest (version 0.0.18)? My best guess (though I'm not certain) is that by not handling the ValueRemoved event it is possible it was trying to set an obsolete value. I've added initial support for that now, so try with the latest test.js - I'd be interested to know if this fixes the problem ;)

zonak commented 10 years ago

Hi Jonathan,

Thank you for looking into this.

I did install the latest 0.0.18 version and gave it a try.

What I am doing to test this is I am checking for the correct nodeid when the node ready event is fired and then just issue a simple switchOff(2). I see that the code is getting executed based on the logs around it but no values have changed.

After running the switchOff method I see the following in the log:

2013-10-21 13:43:42.114 Node002, Polling: COMMAND_CLASS_SWITCH_BINARY index = 0 instance = 1 (poll queue has 0 messages)
2013-10-21 13:43:42.115 Node002, Queuing (Poll) SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0x07, 0xe0
2013-10-21 13:43:42.116 
2013-10-21 13:43:42.117 Node002, Sending (Poll) message (Callback ID=0x07, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0x07, 0xe0
2013-10-21 13:43:42.124 Node002,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2013-10-21 13:43:42.125 Node002,   ZW_SEND_DATA delivered to Z-Wave stack
2013-10-21 13:43:42.136 Node002,   Received: 0x01, 0x05, 0x00, 0x13, 0x07, 0x00, 0xee
2013-10-21 13:43:42.137 Node002,   ZW_SEND_DATA Request with callback ID 0x07 received (expected 0x07)
2013-10-21 13:43:42.138 Node002, Request RTT 19 Average Request RTT 19
2013-10-21 13:43:42.143 Node002,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x02, 0x03, 0x25, 0x03, 0xff, 0x2a
2013-10-21 13:43:42.144 
2013-10-21 13:43:42.145 Node002, Response RTT 26 Average Response RTT 26
2013-10-21 13:43:42.145 Node002, Received SwitchBinary report from node 2: level=On
2013-10-21 13:43:42.146 Node002, Refreshed Value: old value=true, new value=true, type=bool
2013-10-21 13:43:42.147 Node002, Changes to this value are verified
2013-10-21 13:43:42.148 Node002,   Expected reply and command class was received
2013-10-21 13:43:42.148 Node002,   Message transaction complete
2013-10-21 13:43:42.149 
2013-10-21 13:43:42.150 Node002, Removing current message

but that doesn't seem to be related to what was executed - it just keeps repeating every 30 seconds even if I run the test.js unmodified - without running any state changing calls.

I also was looking at the value changed event and it is fired once but before the switchOff call is even made:

2013-10-21 13:43:41.644 Node002, Sending (Send) message (Callback ID=0x06, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0x06, 0xe1
2013-10-21 13:43:41.652 Node002,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2013-10-21 13:43:41.653 Node002,   ZW_SEND_DATA delivered to Z-Wave stack
2013-10-21 13:43:41.664 Node002,   Received: 0x01, 0x05, 0x00, 0x13, 0x06, 0x00, 0xef
2013-10-21 13:43:41.665 Node002,   ZW_SEND_DATA Request with callback ID 0x06 received (expected 0x06)
2013-10-21 13:43:41.666 Node002, Request RTT 20 Average Request RTT 19
2013-10-21 13:43:41.671 Node002,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x02, 0x03, 0x25, 0x03, 0xff, 0x2a
2013-10-21 13:43:41.672 
2013-10-21 13:43:41.673 Node002, Response RTT 27 Average Response RTT 26
2013-10-21 13:43:41.673 Node002, Received SwitchBinary report from node 2: level=On
2013-10-21 13:43:41.674 Node002, Initial read of value
2013-10-21 13:43:41.675 Node002,   Expected reply and command class was received
2013-10-21 13:43:41.675 Node002,   Message transaction complete
2013-10-21 13:43:41.676 
2013-10-21 13:43:41.676 Node002, Removing current message

I also tried again the one thing I know it works - setting the location for the node and it did work again but the value changed didn't fire again - maybe I am misunderstanding this event.

This is what I see in the log when I am setting the location:

2013-10-21 14:02:48.237 Node002, NodeNaming::SetLocation - Setting location to 'Office'
2013-10-21 14:02:48.240 Node002, Queuing (Send) NodeNaming Set (Node=2): 0x01, 0x10, 0x00, 0x13, 0x02, 0x09, 0x77, 0x04, 0x00, 0x4f, 0x66, 0x66, 0x69, 0x63, 0x65, 0x25, 0x07, 0x86

and this follows afterwards:

2013-10-21 14:02:48.248 Node002, Sending (Send) message (Callback ID=0x07, Expected Reply=0x13) - NodeNaming Set (Node=2): 0x01, 0x10, 0x00, 0x13, 0x02, 0x09, 0x77, 0x04, 0x00, 0x4f, 0x66, 0x66, 0x69, 0x63, 0x65, 0x25, 0x07, 0x86

Please let me know if you want me to try something else or if you notice that I am doing something wrong.

jperkin commented 10 years ago

Ok, try the latest (0.0.23) - there are a number of fixes which are likely to be related to this.

zonak commented 10 years ago

Awesome!!!

Modifying state with 0.0.23 works on the on/off switch I am testing with.

Thank you for your continuos great work.

Lots of more useful info in the logs too - loving it.