I use a zooZ ZE18 motion sensor to trigger a Leviton DZ6HD switch. I use DelayLight to turn off the switch after 10 minutes when motion detected between the hours of 2200 and 0500. Arrangement works as expected. However, for the past few days (maybe longer - don’t always wake up) the lights controlled by the switch come on for 10 minutes at 2:30AM with no motion detected. Where should I be looking to see what might be causing this? Note, a similar arrangement with identical devices in my den works as expected.
Unfortunately Vera is plagued with false alarms from motion sensors. I have 4-5 z wave motion sensor and each of them have ghost trips. This is not a device problem it’s a Vera problem that has been around for a longgg time.
Look in the logs to see if there was a LUUP reload immediately prior to the light coming on. As DelayLight initializes, it will check the status of controlled loads. If it thinks that the load was manually activated, it will turn it on for the time set by the manual value.
A motion even will also be shown in the logs, even if its a false one.
The logs only show motion detected after I got up and walked past the sensor several minutes after it unexpectedly triggered the lights. The light then stayed on for the prescribed 10 minute delay. Just don’t see anything in the logs otherwise. Strange that it comes on at exactly the same time each morning?
Agreed. That was why I was looking for a LUUP restart at that time. Why LUUP would be restarting would be another question.
I have some defensive code in my scenes/code, that’s checking for LastTrip variable, and I excecute code only if Tripped is different. Something like this, in meta-code:
local devNum = 666
local lastTripped = getVar("LastTripped", devNum)
local tripped = getVar("Tripped", devNum)
if lastTripped ~= tripped then
setVar("LastTripped", tripped, devNum)
return true
end
return false
In the DelayLight master device Advanced > Variables tab, set the DebugMode variable to “1”.
Now the hard part: capture the entire LuaUPnP.log file when the stray trigger occurs. You can either grab it using scp or WinSCP, or by right-click saving the display from this URL:
http://your-vera-local-ip6/cgi-bin/cmh/log.sh?Device=LuaUPnP
Please ZIP the log file and attach it to a PM to me (don’t post/reply it here). Don’t reduce, redact, or reformat it in any way.
Does this reduce the chance of ghost trips?
Can you explain how this code is intended to work? The LastTrip variable in SecuritySensor1 contains a Unix timestamp, currently values > 1,593,700,000. The Tripped variable contains a boolean 0 or 1. Comparing them is pretty much guaranteed to always take the “not equal” branch in your code. The setVar() has no value to set. Is this real or pseudo-code? I’m not seeing what this meant to do, or how it can do anything.
Have set the variable to 1 and will wait for event to occur tomorrow morning. Standby for .zip if it happens again tonight.
OK. Forgot to add, you need to reload Luup after changing the variable.
I’m sorry, I was meta-coding. It is LastTripped, so a totally different variable, to hold the previous status before it was changed by luup engine.
In my case, I have some devices tripping again even if already tripped, so this 100% prevents the code from running if the state is not really changed.
Original code updated as well.
yep, the correct one does. 100% working, since I had false trips for the sensor attached to my alarms and it was causing very odd behavior before I got the defensive in place.
That makes more sense. All moot for DelayLight anyway, as it already only reacts to changes in state, like Reactor (and your code).
1 Like
Please do the following:
For each of the lights controlled by the subject DelayLightTimer, go in and look at the list of state variables for each device in its Advanced > Variables tab. Please report if any of them has a Tripped or Armed variable, and what its value is.
1 Like
The device controlling the lights is a Leviton DZ6HD and I see no evidence of any Tripped or Armed variable for it.
Did you actually check, or did you assume based on the device type?
I checked. Under Advanced>Variables for the DZ6HD there are none that include the words Tripped or Armed. There is a list of Configured Variables: 1-Fade On Time (0=Instant On or 1-127s or 128-253m),1d,2-Fade Off Time (0=Instant Off or 1-127s or 128-253m),1d,3-Minimum Light Level (0-100),1d,4-Maximum Light Level (0-100),1d,5-Preset Light Level (0=Last State or 1-100),1d,6-LED Dim Level Indicator Timeout (0=Indicator Off or 1-254s or 255=Indicator On),1d,7-Locator LED Status (0=LED or 254=Status Mode or 255=Locator Mode),1d,8-Load Type (0=Incandescent or 1=LED or 2=CFL),1d,
Perhaps I’m not looking at the right place?
No, that’s Device Options, a different tab, not the Advanced > Variables tab.
But, let’s have a look here… and excerpt from your logs:
04 07/05/20 2:40:16.535 <Job ID="431" Name="update nnu 109" Device="280" Created="2020-07-05 2:40:09" Started="2020-07-05 2:40:09" Completed="2020-07-05 2:40:16" Duration="7.429167000" Runtime="7.417978000" Status="Successful" LastNote=""/> <0x76388520>
02 07/05/20 2:40:16.557 JobHandler::Run job#432 :Wakeup done 109 dev:280 (0x198fb48) N:109 P:102 S:0 Id: 432 is 7.450078000 seconds old <0x76388520>
04 07/05/20 2:40:16.895 <Job ID="432" Name="Wakeup done 109" Device="280" Created="2020-07-05 2:40:09" Started="2020-07-05 2:40:16" Completed="2020-07-05 2:40:16" Duration="7.788202000" Runtime="0.338169000" Status="Successful" LastNote="SUCCESS! Transmit was OK" Node="109" NodeType="ZWaveNode" NodeDescription="Mirror sensor"/> <0x76b88520>
06 07/05/20 2:40:17.292 Device_Variable::m_szValue_set device: 280 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: LastWakeup was: 1593942009 now: 1593942017 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76b88520>
02 07/05/20 2:40:17.293 ZWJob_GetNodeDetails::ZWJob_GetNodeDetails skipping return_route for 109 2/1/-1 job job#434 :getnodedetails_ri_wake 109 dev:280 (0x178cb78) P:50 S:0 Id: 434 <0x76b88520>
01 07/05/20 2:40:20.296 ZWaveNode::DecryptMessage node 109 dev 280 failed and backup nonce is 112 <0x76b88520>
01 07/05/20 2:40:20.297 XXX-ZWaveNode::DecryptMessage node 109 dev 280 len=0/20 m_iFrameID 4107 good 112 command class 0x66 command 0x77 status 0x0 int nonce 0x1b 0xe4 0x82 0x2a 0xb3 0x26 0x23 0x7c (###*#&#|) ext nonce 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f (\r####Mk#) temp key 0 auth key 0x4d 0x7a 0x35 0xac 0x21 0x5c 0x6c 0xe 0x1d 0xf0 0x37 0x6f 0x3e 0xb7 0xba 0xf0 (Mz5#!\l###7o>###) mac 0xc3 0xa7 0x38 0x21 0x1b 0xf5 0x3a 0xd8 0x9b 0xc8 0x2c 0x18 0xb 0x6d 0xa8 0xd2 (##8!##:###,##m##) data 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f 0x88 0x66 0x77 0x8f 0x53 0x0 0x18 0x5f 0x9c 0x3b 0xc0 0xb4 (\r####Mk##fw#S##_#;##) <0x76b88520>
01 07/05/20 2:40:20.299 ZWaveNode::DecryptMessage node 109 dev 280 failed and backup nonce is 112 <0x76b88520>
01 07/05/20 2:40:20.299 XXX-ZWaveNode::DecryptMessage node 109 dev 280 len=0/20 m_iFrameID 4108 good 112 command class 0x66 command 0x77 status 0x0 int nonce 0x1b 0xe4 0x82 0x2a 0xb3 0x26 0x23 0x7c (###*#&#|) ext nonce 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f (\r####Mk#) temp key 0 auth key 0x4d 0x7a 0x35 0xac 0x21 0x5c 0x6c 0xe 0x1d 0xf0 0x37 0x6f 0x3e 0xb7 0xba 0xf0 (Mz5#!\l###7o>###) mac 0xc3 0xa7 0x38 0x21 0x1b 0xf5 0x3a 0xd8 0x9b 0xc8 0x2c 0x18 0xb 0x6d 0xa8 0xd2 (##8!##:###,##m##) data 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f 0x88 0x66 0x77 0x8f 0x53 0x0 0x18 0x5f 0x9c 0x3b 0xc0 0xb4 (\r####Mk##fw#S##_#;##) <0x76b88520>
01 07/05/20 2:40:20.301 ZWaveNode::DecryptMessage node 109 dev 280 failed and backup nonce is 112 <0x76b88520>
01 07/05/20 2:40:20.302 XXX-ZWaveNode::DecryptMessage node 109 dev 280 len=0/20 m_iFrameID 4109 good 112 command class 0x66 command 0x77 status 0x0 int nonce 0x1b 0xe4 0x82 0x2a 0xb3 0x26 0x23 0x7c (###*#&#|) ext nonce 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f (\r####Mk#) temp key 0 auth key 0x4d 0x7a 0x35 0xac 0x21 0x5c 0x6c 0xe 0x1d 0xf0 0x37 0x6f 0x3e 0xb7 0xba 0xf0 (Mz5#!\l###7o>###) mac 0xc3 0xa7 0x38 0x21 0x1b 0xf5 0x3a 0xd8 0x9b 0xc8 0x2c 0x18 0xb 0x6d 0xa8 0xd2 (##8!##:###,##m##) data 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f 0x88 0x66 0x77 0x8f 0x53 0x0 0x18 0x5f 0x9c 0x3b 0xc0 0xb4 (\r####Mk##fw#S##_#;##) <0x76b88520>
01 07/05/20 2:40:20.304 ZWaveNode::DecryptMessage node 109 dev 280 failed and backup nonce is 112 <0x76b88520>
01 07/05/20 2:40:20.305 XXX-ZWaveNode::DecryptMessage node 109 dev 280 len=0/20 m_iFrameID 4113 good 112 command class 0x66 command 0x77 status 0x0 int nonce 0x1b 0xe4 0x82 0x2a 0xb3 0x26 0x23 0x7c (###*#&#|) ext nonce 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f (\r####Mk#) temp key 0 auth key 0x4d 0x7a 0x35 0xac 0x21 0x5c 0x6c 0xe 0x1d 0xf0 0x37 0x6f 0x3e 0xb7 0xba 0xf0 (Mz5#!\l###7o>###) mac 0xc3 0xa7 0x38 0x21 0x1b 0xf5 0x3a 0xd8 0x9b 0xc8 0x2c 0x18 0xb 0x6d 0xa8 0xd2 (##8!##:###,##m##) data 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f 0x88 0x66 0x77 0x8f 0x53 0x0 0x18 0x5f 0x9c 0x3b 0xc0 0xb4 (\r####Mk##fw#S##_#;##) <0x76b88520>
01 07/05/20 2:40:20.307 ZWaveNode::DecryptMessage node 109 dev 280 failed and backup nonce is 112 <0x76b88520>
01 07/05/20 2:40:20.307 XXX-ZWaveNode::DecryptMessage node 109 dev 280 len=0/20 m_iFrameID 4114 good 112 command class 0x66 command 0x77 status 0x0 int nonce 0x1b 0xe4 0x82 0x2a 0xb3 0x26 0x23 0x7c (###*#&#|) ext nonce 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f (\r####Mk#) temp key 0 auth key 0x4d 0x7a 0x35 0xac 0x21 0x5c 0x6c 0xe 0x1d 0xf0 0x37 0x6f 0x3e 0xb7 0xba 0xf0 (Mz5#!\l###7o>###) mac 0xc3 0xa7 0x38 0x21 0x1b 0xf5 0x3a 0xd8 0x9b 0xc8 0x2c 0x18 0xb 0x6d 0xa8 0xd2 (##8!##:###,##m##) data 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f 0x88 0x66 0x77 0x8f 0x53 0x0 0x18 0x5f 0x9c 0x3b 0xc0 0xb4 (\r####Mk##fw#S##_#;##) <0x76b88520>
01 07/05/20 2:40:20.476 ZWaveNode::DecryptMessage node 109 dev 280 failed and backup nonce is 112 <0x76b88520>
01 07/05/20 2:40:20.477 XXX-ZWaveNode::DecryptMessage node 109 dev 280 len=0/20 m_iFrameID 4121 good 112 command class 0x66 command 0x77 status 0x0 int nonce 0x1b 0xe4 0x82 0x2a 0xb3 0x26 0x23 0x7c (###*#&#|) ext nonce 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f (\r####Mk#) temp key 0 auth key 0x4d 0x7a 0x35 0xac 0x21 0x5c 0x6c 0xe 0x1d 0xf0 0x37 0x6f 0x3e 0xb7 0xba 0xf0 (Mz5#!\l###7o>###) mac 0xc3 0xa7 0x38 0x21 0x1b 0xf5 0x3a 0xd8 0x9b 0xc8 0x2c 0x18 0xb 0x6d 0xa8 0xd2 (##8!##:###,##m##) data 0xd 0xd8 0x80 0x8c 0xf3 0x4d 0x6b 0x9f 0x88 0x66 0x77 0x8f 0x53 0x0 0x18 0x5f 0x9c 0x3b 0xc0 0xb4 (\r####Mk##fw#S##_#;##) <0x76b88520>
01 07/05/20 2:40:21.493 ZWaveNode::DecryptMessage node 109 dev 280 failed and backup nonce is 75 <0x76b88520>
01 07/05/20 2:40:21.494 XXX-ZWaveNode::DecryptMessage node 109 dev 280 len=0/20 m_iFrameID 4127 good 75 command class 0x4a command 0x40 status 0x0 int nonce 0x4e 0x4c 0x15 0x9d 0x72 0x71 0x7b 0x3 (NL##rq{#) ext nonce 0x16 0x63 0xd5 0xd8 0xa0 0xad 0xf2 0xea (#c######) temp key 0 auth key 0x4d 0x7a 0x35 0xac 0x21 0x5c 0x6c 0xe 0x1d 0xf0 0x37 0x6f 0x3e 0xb7 0xba 0xf0 (Mz5#!\l###7o>###) mac 0xbe 0xe1 0x1d 0x8c 0x33 0x35 0x9f 0x8e 0x25 0x2c 0xd4 0x8f 0x51 0x25 0xa4 0xc2 (####35##%,##Q%##) data 0x16 0x63 0xd5 0xd8 0xa0 0xad 0xf2 0xea 0x24 0x4a 0x40 0x6 0x73 0x60 0xab 0x7d 0x86 0xcd 0xfe 0xa7 (#c######$J@#s`#}####) <0x76b88520>
06 07/05/20 2:40:24.992 Device_Variable::m_szValue_set device: 280 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: LastWakeup was: 1593942017 now: 1593942024 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76b88520>
02 07/05/20 2:40:25.013 ZWaveNode::Wakeup did a poll for 109 7 seconds interval 43200 existing (nil) heal (nil) <0x76b88520>
04 07/05/20 2:40:25.016 <Job ID="433" Name="pollnode_wake #109 1 cmds" Device="280" Created="2020-07-05 2:40:17" Started="2020-07-05 2:40:17" Completed="2020-07-05 2:40:25" Duration="7.722462000" Runtime="7.721967000" Status="Successful" LastNote="" Node="109" NodeType="ZWaveNode" NodeDescription="Mirror sensor"/> <0x76b88520>
02 07/05/20 2:40:25.016 Device_Basic::AddPoll 280 poll list full, deleting old one <0x76b88520>
06 07/05/20 2:40:25.017 Device_Variable::m_szValue_set device: 280 service: urn:micasaverde-com:serviceId:HaDevice1 variable: PollRatings was: 3.40 now: 3.40 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x76b88520>
06 07/05/20 2:40:25.017 Device_Variable::m_szValue_set device: 280 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastPollSuccess was: 1593855510 now: 1593942025 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76b88520>
06 07/05/20 2:40:25.018 Device_Variable::m_szValue_set device: 280 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: ConsecutivePollFails was: 0 now: 0 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x76b88520>
02 07/05/20 2:40:25.019 JobHandler::Run job#434 :getnodedetails_ri_wake 109 dev:280 (0x178cb78) P:50 S:0 Id: 434 node 109 is 7.725325000 seconds old <0x76388520>
06 07/05/20 2:40:25.054 Device_Variable::m_szValue_set device: 280 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: LastRouteUpdate was: 1593855511 now: 1593942025 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76388520>
06 07/05/20 2:40:25.055 Device_Variable::m_szValue_set device: 280 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: Neighbors was: 8,13,14,25,81,82,92,93,98,114, now: 8,13,14,25,31,81,82,92,93,98,114,116, #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76388520>
04 07/05/20 2:40:25.057 <Job ID="434" Name="getnodedetails_ri_wake 109" Device="280" Created="2020-07-05 2:40:17" Started="2020-07-05 2:40:25" Completed="2020-07-05 2:40:25" Duration="7.763045000" Runtime="0.37783000" Status="Successful" LastNote=""/> <0x76388520>
02 07/05/20 2:40:25.057 JobHandler::Run job#435 :Wakeup done 109 dev:280 (0x1809278) N:109 P:102 S:0 Id: 435 is 7.763065000 seconds old <0x76388520>
04 07/05/20 2:40:25.395 <Job ID="435" Name="Wakeup done 109" Device="280" Created="2020-07-05 2:40:17" Started="2020-07-05 2:40:25" Completed="2020-07-05 2:40:25" Duration="8.100436000" Runtime="0.337415000" Status="Successful" LastNote="SUCCESS! Transmit was OK" Node="109" NodeType="ZWaveNode" NodeDescription="Mirror sensor"/> <0x76b88520>
04 07/05/20 2:40:25.735 <Job ID="436" Name="Wakeup done 109" Device="280" Created="2020-07-05 2:40:25" Started="2020-07-05 2:40:25" Completed="2020-07-05 2:40:25" Duration="0.720411000" Runtime="0.338851000" Status="Successful" LastNote="SUCCESS! Transmit was OK" Node="109" NodeType="ZWaveNode" NodeDescription="Mirror sensor"/> <0x76b88520>
06 07/05/20 2:40:27.604 Device_Variable::m_szValue_set device: 280 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: LastTrip was: 1593937338 now: 1593942027 #hooks: 0 upnp: 0 skip: 0 v:0xfc9568/NONE duplicate:0 <0x76b88520>
06 07/05/20 2:40:27.605 Device_Variable::m_szValue_set device: 280 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: Tripped was: 0 now: 1 #hooks: 1 upnp: 0 skip: 0 v:0xfd9bb0/NONE duplicate:0 <0x76b88520>
50 07/05/20 2:40:27.606 luup_log:208: DelayLight(debug)::: watch(280,"urn:micasaverde-com:serviceId:SecuritySensor1","Tripped","0","1") luup.device(tdev)=208 <0x76b88520>
The first line here shows that the Vera was starting a neighbor node update on the motion sensor device. The lines that follow show a wakeup, and then a bunch of failures in device communication. The last thing at the bottom is Vera/Luup telling DelayLight that the sensor is now tripped.
So DelayLight seems to be doing what it’s supposed to do. I’m guessing that Vera’s infamous “nightly heal” and/or the wakeup heal is causing a problem for this sensor (that’s the “update nnu” job). Here’s what I recommend you try to get around the issue:
- Disable the wakeup neighbor update on the device. This is done by running the following code in the Apps > Develop Apps > Test Luup Code tool. Then wait and see what happens.
luup.variable_set("urn:micasaverde-com:serviceId:ZWaveDevice1", "DisableWakeupARR_NNU", "1", 280)
luup.reload()
- If that doesn’t do it, you can try disabling the nightly heal on the Vera:
luup.attr_set("EnableNightlyHeal", "0", 0)
luup.reload()
- If that doesn’t do it, then if it’s possible to include the sensor not in secure mode, I would exclude the sensor, then re-include it in not-secure mode.
Beyond that, I can’t really tell you anything else. DelayLight is doing what it thinks is right based on what Luup is reporting for the sensor.
One more thing… your log shows sensor trips (and DelayLight activations) at 1:20am, 3:00am, 4:09am… There are more trips here than you are complaining about, so if that’s unexpected, then maybe you just have a bum sensor, or its positioning is somehow troublesome.
Edit: Don’t forget to turn DebugMode back to 0 in the DelayLight master device.
Started with #1. Let’s see how that works before moving to #2 and #3.
Might there be some significance to the fact that the Advanced>Variables tab for the DZ6HD light has a blank for the Neighbors setting? DebugMode back to 0. Engine Reloaded.
Yes, the other trips are accounted for as a test triggers, or my wife and/or I going past the sensor on the way to the bathroom.
Appreciate the detailed help. Will report back.