search

OpenZWave / open-zwave

a C++ library to control Z-Wave Networks via a USB Z-Wave Controller.
http://www.openzwave.net/
GNU Lesser General Public License v3.0
1.05k stars 917 forks source link

MIMOLite "momentary" relay setting not reflecting the "off" state after turning "on" #2317

Closed rccoleman closed 4 years ago

rccoleman commented 4 years ago

I'm using the "allinone-build-150" container version of ozwdaemon with Home assistant 0.113.b1 running on Ubuntu 18.04 LTS.

I have a MIMOLite that I use with my garage door and it has a relay a dry contact sensor. I use the relay in "momentary" mode to emulate pressing the button on a remote control, and the dry contact sensor is connected to a magnet/reed sensor to indicate whether the garage door is closed.

The P5 jumper was removed prior to network inclusion (as described in the manual) and I have the MIMOLite "momentary" config parameter 11 set to 10 (1000ms) to have the button remain pressed for 1s and then turn off automatically. This was working fine in OZW v1.4, and I saw the switch returning to "off" after the specified time period. With v1.6 and no change to the pairing with my Z-Stick, I hear the relay turning on and then turning off, but the state in OZWDaemon and MQTT doesn't reflect the new "off" state. In addition to uploading my ozwcache_*.xml and full logs, I extracted a snippet below (see node 23). I can clearly see the switch being turned on at the beginning, but I don't see any indication of the device reporting that the switch was subsequently turned off. Unfortunately, I don't have a v1.4 system anymore to see the log from that.

As a workaround, I now have an automation that turns the relay off after a few seconds, and I don't hear anything actually happening when the automation runs. I think that means that the relay was already off and only the OZW state was wrong.

[20200719 1:14:18.222 UTC] [ozw.mqtt.commands] [debug]: Got  "OpenZWave/1/command/setvalue/"  Message:  "{\"ValueIDKey\": 390676496, \"Value\": true}" 
[20200719 1:14:18.223 UTC] [ozw.mqtt.commands.setValue] [info]: Setting  390676496  to Value  QVariant(bool, true) 
[20200719 1:14:18.223 UTC] [ozw.values] [debug]: setData Called for Row 443  With Value QVariant(bool, true) 
[20200719 1:14:18.223 UTC] [ozw.values] [debug]: valueModel Changed! QTOZW_ValueIds::Value - 443 :  QVariant(bool, true) 
[20200719 1:14:18.223 UTC] [ozw.values] [debug]: valueModel Changed! vidKey: 390676496 QVariant(bool, true) 
[20200719 1:14:18.223 UTC] [ozw.library] [info]: Info - Node: 23 Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True 
[20200719 1:14:18.223 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.224 UTC] [ozw.library] [info]: Info - Node: 23 SwitchBinary::Set - Setting to On 
[20200719 1:14:18.224 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.225 UTC] [ozw.library] [debug]: Detail - Node: 23 Queuing (Send) SwitchBinaryCmd_Set (Node=23): 0x01, 0x0a, 0x00, 0x13, 0x17, 0x03, 0x25, 0x01, 0xff, 0x25, 0x0d, 0x01 
[20200719 1:14:18.225 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.225 UTC] [ozw.library] [debug]: Detail - Node: 23 Queuing (Send) SwitchBinaryCmd_Get (Node=23): 0x01, 0x09, 0x00, 0x13, 0x17, 0x02, 0x25, 0x02, 0x25, 0x0e, 0xfc 
[20200719 1:14:18.226 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.226 UTC] [ozw.library] [info]: Info - Node: 23 Sending (Send) message (Callback ID=0x0d, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=23): 0x01, 0x0a, 0x00, 0x13, 0x17, 0x03, 0x25, 0x01, 0xff, 0x25, 0x0d, 0x01 
[20200719 1:14:18.227 UTC] [ozw.mqtt.commands] [info]: Processed Message for  "setvalue" :  "{\"ValueIDKey\": 390676496, \"Value\": true}" 
[20200719 1:14:18.227 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.227 UTC] [ozw.library] [info]: Info - Node: 23 Encrypted Flag is 0 
[20200719 1:14:18.227 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.236 UTC] [ozw.library] [debug]: Detail - Node: 23   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8 
[20200719 1:14:18.236 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.236 UTC] [ozw.library] [debug]: Detail - Node: 23   ZW_SEND_DATA delivered to Z-Wave stack 
[20200719 1:14:18.236 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.307 UTC] [ozw.library] [debug]: Detail - Node: 23   Received: 0x01, 0x07, 0x00, 0x13, 0x0d, 0x00, 0x00, 0x08, 0xee 
[20200719 1:14:18.307 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.308 UTC] [ozw.library] [debug]: Detail - Node: 23   ZW_SEND_DATA Request with callback ID 0x0d received (expected 0x0d) 
[20200719 1:14:18.308 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.309 UTC] [ozw.library] [info]: Info - Node: 23 Request RTT 80 Average Request RTT 79 
[20200719 1:14:18.309 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.310 UTC] [ozw.library] [debug]: Detail - Node: 23   Expected callbackId was received 
[20200719 1:14:18.310 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.310 UTC] [ozw.library] [debug]: Detail - Node: 23   Expected reply was received 
[20200719 1:14:18.310 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.311 UTC] [ozw.library] [debug]: Detail - Node: 23   Message transaction complete 
[20200719 1:14:18.311 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.312 UTC] [ozw.library] [debug]: Detail - Node: 23 Removing current message 
[20200719 1:14:18.312 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.312 UTC] [ozw.library] [info]: Info - Node: 23 Sending (Send) message (Callback ID=0x0e, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=23): 0x01, 0x09, 0x00, 0x13, 0x17, 0x02, 0x25, 0x02, 0x25, 0x0e, 0xfc 
[20200719 1:14:18.312 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.313 UTC] [ozw.library] [info]: Info - Node: 23 Encrypted Flag is 0 
[20200719 1:14:18.313 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.321 UTC] [ozw.library] [debug]: Detail - Node: 23   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8 
[20200719 1:14:18.321 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.322 UTC] [ozw.library] [debug]: Detail - Node: 23   ZW_SEND_DATA delivered to Z-Wave stack 
[20200719 1:14:18.322 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.393 UTC] [ozw.library] [debug]: Detail - Node: 23   Received: 0x01, 0x07, 0x00, 0x13, 0x0e, 0x00, 0x00, 0x08, 0xed 
[20200719 1:14:18.393 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.394 UTC] [ozw.library] [debug]: Detail - Node: 23   ZW_SEND_DATA Request with callback ID 0x0e received (expected 0x0e) 
[20200719 1:14:18.394 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.395 UTC] [ozw.library] [info]: Info - Node: 23 Request RTT 81 Average Request RTT 80 
[20200719 1:14:18.395 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.396 UTC] [ozw.library] [debug]: Detail - Node: 23   Expected callbackId was received 
[20200719 1:14:18.396 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.444 UTC] [ozw.library] [debug]: Detail - Node: 23   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x17, 0x03, 0x25, 0x03, 0xff, 0x3f 
[20200719 1:14:18.445 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.445 UTC] [ozw.library] [info]: Info - Node: 23 Response RTT 131 Average Response RTT 131 
[20200719 1:14:18.445 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.446 UTC] [ozw.library] [info]: Info - Node: 23 Received SwitchBinary report from node 23: level=On 
[20200719 1:14:18.446 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.447 UTC] [ozw.library] [debug]: Detail - Node: 23 Refreshed Value: old value=false, new value=true, type=bool 
[20200719 1:14:18.447 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.447 UTC] [ozw.library] [debug]: Detail - Node: 23 Changes to this value are not verified 
[20200719 1:14:18.447 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.448 UTC] [ozw.library] [debug]: Detail - Node: 23   Expected reply and command class was received 
[20200719 1:14:18.448 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.449 UTC] [ozw.library] [debug]: Detail - Node: 23   Message transaction complete 
[20200719 1:14:18.449 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.449 UTC] [ozw.library] [debug]: Detail - Node: 23 Removing current message 
[20200719 1:14:18.449 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.450 UTC] [ozw.library] [debug]: Detail - Node: 23 Notification: ValueChanged CC: COMMAND_CLASS_SWITCH_BINARY Instance: 1 Index: 0 
[20200719 1:14:18.450 UTC] [ozw.logging] [debug]: popping Log Mesages 
[20200719 1:14:18.451 UTC] [ozw.notifications] [debug]: Notification pvt_valueChanged:  390676496 Thread:  0x7fc90ebd9c80 
[20200719 1:14:18.452 UTC] [ozw.mqtt.publisher] [debug]: Publishing Event valueChanged: 390676496 

[20200719 1:14:29.123 UTC] [ozw.library] [debug]: Detail - Node: 39   Received: 0x01, 0x0f, 0x00, 0x04, 0x00, 0x27, 0x09, 0x71, 0x05, 0x00, 0x00, 0x
00, 0xff, 0x07, 0x08, 0x00, 0x5e
[20200719 1:14:29.123 UTC] [ozw.logging] [debug]: popping Log Mesages
[20200719 1:14:29.124 UTC] [ozw.library] [info]: Info - Node: 39 Got a AlarmCmd_Report Message....
[20200719 1:14:29.124 UTC] [ozw.logging] [debug]: popping Log Mesages
[20200719 1:14:29.124 UTC] [ozw.library] [info]: Info - Node: 39 Received Notification report (>v1): Type: Home Security (7) Event: Motion Detected
at Unknown Location (8) Status: true, Param Length: 0
[20200719 1:14:29.125 UTC] [ozw.logging] [debug]: popping Log Mesages
[20200719 1:14:29.125 UTC] [ozw.library] [debug]: Detail - Node: 39 Refreshed Value: old value=1, new value=1, type=list
[20200719 1:14:29.125 UTC] [ozw.logging] [debug]: popping Log Mesages
[20200719 1:14:29.125 UTC] [ozw.library] [debug]: Detail - Node: 39 Changes to this value are not verified
[20200719 1:14:29.125 UTC] [ozw.logging] [debug]: popping Log Mesages
[20200719 1:14:29.126 UTC] [ozw.library] [debug]: Detail - Node: 39 Notification: ValueChanged CC: COMMAND_CLASS_NOTIFICATION Instance: 1 Index: 7
[20200719 1:14:29.126 UTC] [ozw.logging] [debug]: popping Log Mesages
[20200719 1:14:29.127 UTC] [ozw.notifications] [debug]: Notification pvt_valueChanged:  1970325497331732 Thread:  0x7fc90ebd9c80
[20200719 1:14:29.128 UTC] [ozw.mqtt.publisher.value] [debug]: List Selected Value has Not Changed:  "Motion Detected at Unknown Location"
[20200719 1:14:29.363 UTC] [ozw.library] [debug]: Detail - Node: 39   Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x27, 0x04, 0x30, 0x03, 0xff, 0x0c, 0x
12
[20200719 1:14:29.363 UTC] [ozw.logging] [debug]: popping Log Mesages
[20200719 1:14:29.364 UTC] [ozw.library] [info]: Info - Node: 39 Received SensorBinary report: Sensor:12 State=On
[20200719 1:14:29.364 UTC] [ozw.logging] [debug]: popping Log Mesages
[20200719 1:14:29.364 UTC] [ozw.library] [debug]: Detail - Node: 39 Refreshed Value: old value=true, new value=true, type=bool

Archive.zip

rccoleman commented 4 years ago

Nevermind. I excluded the device and reincluded it, and now it's working fine. I now see the correct momentary switch behavior.