call_delay() problem in beta version of FW?

At the behest of Vera support I upgraded to v1.1147 (Beta) and now it appears that the luup function call_delay() does not seem to trigger after the specified number of seconds.

A (I believe) related problem is that any scene that contains the logic “after XX seconds|minutes|hours” for an action does not perform the action requested.

It does not seem to matter if the action pertains to a thermostat’s temperature set point or a binary light switch. These are two types of devices where I’m using the functionality on my Vera2.

An example of a scene I’ve got configured that fails on both counts is a scene that uses luup code to trigger two other scenes (scene A & scene B). Scene A is expected to run immediately and the second scene - scene B - is set up using the call_delay() function to trigger after 62 minutes. Scene A and scene B both contain a command to turn on a power switch and then disable it - turn it off - 60 minutes afer the switch was turned on. For scene A, the disable never triggers and for scene B, the scene itself is never run. And, yes, I’ve verified in the logs that the call_delay() doesn’t fail :slight_smile:

Scene that triggers scene A (#40) and Scene B (#9) :

-- We start the count-down until the back of the house de-icing cables are enabled
-- (62 minutes from when this scene was started), then we fire up the de-icing
-- cables at the front of the house (so we start de-icing at the front, end with
-- the back of the house).
--
-- The "back of the house" scene will disable power to the "front of the house" cables
-- then turn itself off after 60 minutes.
--
-- Programmed delay: 62(min) x 60(seconds) = 3270
--
local delayTime = 3720 
-- Do the actual work
luup.log("Starting the delay-timer for the back of the house")
local deicestatus = luup.call_delay("runScene", delayTime, sceneID_RearHouseDeIcing)
if (deicestatus ~= 0)
then
    luup.log("Failed to initiate call_delay() for Rear De-Icing scene")
    return false
end
luup.log("Queued the de-icing process for the back of the house")
runScene(sceneID_FrontHouseDeIcing)
luup.log("Started the de-icing process for the front of the house")

Have anybody else with the beta version installed noticed this change in behavior?

In a single scene with no commands, just Luup code, I tested the following:

[code]switch_it_on ( “21” )
luup.call_delay(“switch_it_off”, 60, “21”)
luup.call_delay(“switch_it_on”, 62, “22”)
luup.call_delay(“switch_it_off”, 122, “22”)

function switch_it_on ( devId )
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”,“SetTarget”,{ newTargetValue=“1” }, tonumber(devId))
end

function switch_it_off ( devId )
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”,“SetTarget”,{ newTargetValue=“0” }, tonumber(devId))
end[/code]

I did not test it with the longer times you mentioned. Change the device id’s from 21 and 22 to what ever ids your de-icing devices are assigned.

Since you are running a heating device, I suggest adding code to turn the devices off in your Startup Lua, just to ensure they are off in the event your Vera reboots or there is a power loss. If its critical that the devices are on, send an alert in the startup so you know the de-ice cycle did not complete and you can manually restart the scene.

It’s the longer delays that are the problem, it seems, based on my testing.

But you reminded me to run an uptime check against the vera (have a while/sleep loop running via ssh to see if it reboots with any frequency) just to make sure the problem isn’t that simple :slight_smile:

The addition of the stop code at startup is a good idea that I’ve since implemented.

Lastly, the device ID’s I’m using in the example are defined constants in the luup startup window (and are numeric). If they weren’t numeric (or actual device IDs), I do not believe the code snippet would work at all.

So I take it I’m the only person who’ve noticed this?

Something to mull over. The call_action function accepts a string or number as its fourth parameter. If its a number the function treats it as device id, and if its a string the function treats it as a udn. The Luup Lua extensions documentation says the parameter value returned from a delay is a string (see http://wiki.micasaverde.com/index.php/Luup_Declarations#timed_function_callback). Since the behavior is different based on string vs number, out of caution I added the tonumber function. I wonder if that makes any difference?

Unless lua has some sort of behavior I’ve missed, the devID_* string I use is a variable which contains a number. I’d be a little surprised if the interpreter decides to override that?

But there still seems to be a problem with long delays (regardless) since the scene’s triggered by the delay call do not activate the “after 1 hour, turn this device off” portion of the scene (and I’ve validated that the vera does not restart inbetween, nor did the luup engine)

You could try to use a freshly included Z-Wave lamp module to make sure that the delayed command doesn’t interfere with scenes, manual operations, remote scripts, …

@Ap15e: I had a long night, so I may be a bit more dense than normal, but I’m not sure I understand what you mean by “interfere”?

Keep in mind that the devices managed by these scenes are actually only managed by the 3 scenes described above. True, that is a rarity in my network.

Couldn’t it be possible that the delayed command gets cancelled/superseded by other commands or events by design?

I would suggest settling for a hypothesis and trying to prove or disprove it, e.g.

“A command defined on the ‘Command’ tab of a scene does not work if the scene is called from another scene/via Luup Lua extensions.”

My previous suggestion matches the hypothesis “A delayed call to a function which changes the state of a device does not work if the delay is > x.”

Would you mind posting your complete code and your current hypothesis?

Sure.

So the hypothesis is that a delay of an hour is missed/ignored, regardless of whether it’s a luup.call_delay() or a scene command like this: “ON” “after 1 hour” “OFF” (for a urn:schemas-upnp-org:device:BinaryLight:1 device).

I have not tested 30 minutes, 45 minutes, only the hour or or more. I also acknowledge that there’s a possibility the problem for the scenes with commands is related to the “hour” versus “minutes” difference, but I will attempt to test that over the weekend to verify (we have enough snow to melt around here, so no hazard at this point)

In Edit startup LUA I’ve got:

ALERT_SMTP_SERVER = "host"
ALERT_SMTP_AUTH_USER = "user"
ALERT_SMTP_AUTH_PW = "password"        
ALERT_SMTP_PORT = "587"
ALERT_USER_SENDING = "me"
ALERT_USER_RECEIVING = "me"
devID_FrontDeIcingSwitch = 3
devID_RearDeIcingSwitch = 4
sceneID_FrontHouseDeIcing = "40"
sceneID_RearHouseDeIcing = "9"
-- Function is used to call/run scenes on the Vera controller
function runScene(str_idOfScene)
  local body
  local subj = "Scene start warning"
  local lul_resultcode
  local lul_resultstring
  local lul_job
  local lul_returnarguments
  -- Call the scene we've preconfigured for this purpose
  -- str_idOfScene = tostring(str_idOfScene)
  lul_resultcode,lul_resultstring,lul_job,lul_returnarguments = luup.call_action("urn:micasaverde-com:serviceId:HomeAutomationGateway1","RunScene", { SceneNum=str_idOfScene }, 0)
  if (lul_resultcode == 0)
  then
      body = "Successfully started scene number " .. str_idOfScene
  else 
      body = "Failed to start scene number " .. str_idOfScene .. ". Result string was: " .. lul_resultstring .. "!"
  end
  sendMailWarning( subj, body )
end
-- Used to send e-mail warnings to the administrator of the network
function sendMailWarning(subjectText, bodyText)
    local CRLF = '\r\n'
    local from = ALERT_USER_SENDING
    local rcpt = {ALERT_USER_RECEIVING}
    local message_out = bodyText .. CRLF
	local smtp = require("socket.smtp")
    local mesgt = {
                  headers = {
                              to   = ALERT_USER_RECEIVING,
                              from = from,
                              subject = subjectText
                            },
                  body    = message_out
                }

    local r, e = smtp.send{ from     = from,
             rcpt     = rcpt,
             source   = smtp.message(mesgt),
             server   = ALERT_SMTP_SERVER,
             port     = ALERT_SMTP_PORT,
             user     = ALERT_SMTP_AUTH_USER,
             password = ALERT_SMTP_AUTH_PW
        }
end

In the Trigger Scene, which is luup only:

-- We start the count-down until the back of the house de-icing cables are enabled
-- (62 minutes from when this scene was started), then we fire up the de-icing
-- cables at the front of the house (so we start de-icing at the front, end with
-- the back of the house).
--
-- The "back of the house" scene will disable power to the "front of the house" cables
-- then turn itself off after 60 minutes.
--
-- Programmed delay: 62(min) x 60(seconds) = 3270
--
local delayTime = 3720 
-- Do the actual work
luup.log("Starting the delay-timer for the back of the house")
local deicestatus = luup.call_delay("runScene", delayTime, sceneID_RearHouseDeIcing)
if (deicestatus ~= 0) 
then
   luup.log("Failed to set up de-icing for the back of the house")
   return false
end
luup.log("Queued the de-icing process for the back of the house")
runScene(sceneID_FrontHouseDeIcing)
luup.log("Started the de-icing process for the front of the house")

There are two scenes (Scene 9 & Scene 40) which consist of a single command, “ON” “after 1 Hour” “OFF” in both cases.

Testing last night showed me that a scene with the command “ON” “after 15 minutes” “OFF” does result in the switch being turned off.

function tree_off()

   luup.call_action("urn:upnp-org:serviceId:SwitchPower1","SetTarget",{ newTargetValue="0" },5)
   luup.log('Tree off')

end

luup.call_delay( 'tree_off', 3700 )

does work (V1@1.1.1156).

I upgraded to .1156 last night, and sure enough my call_delay() scene now works!

Only problem I’m seeing with 1156 is a (fairly small on a per-incident) memory leak that seems to cause the Lua engine to be restarted intentionally by the MIOS FW approximately every 4(ish) hours during daytime and every 7(ish) hours over night. I’m guessing the daytime versus nighttime difference is because there’s more lua code being executed as part of the scenes I’ve got defined during the day.

I think I remember reading a Lua/Vera restart will adversely affect the call_delay() - i.e. the delay is not persistent across lua engine restarts.

If you haven’t already done it then 1156 supports using a USB drive to log to. It’ll free up more RAM which should get you running longer and also the logs are no longer lost between reboots or power cycles. To enable it go the logs tab in advanced and then select the Log to USB option after you’ve inserted a drive.

I added a USB stick to the vera2 yesterday & enabled it, however the LUA engine restart interval hasn’t changed. After looking through the logs, it appears that there’s a programmed restart after a certain amount of memory is leaked. I guess it’s a workaround, but I’d argue it’s not a very good one considering the implications in the context of call_delay() for instance.

There’s always been watchdogs on processes but I don’t know about if they have addded some other logic now that restarts processes that are consuming too much RAM?! But I think if your box is restarting that regularly even after adding the stick, then something else must be up! Did tech support recommend you try to load 1156? You should perhaps consider filing a ticket and getting them to look at either whats causing the memory leak or whats causing the engine to restart.

I filed a ticket against 1155 which they did ask me to upgrade to regarding the leak and support (Ovidiu) was going to forward the case to the dev engineers to ask if this was important to get fixed. At the time I filed the report I didn’t realize the restarts were as frequent and consistent as they have turned out to be. The upgrade to 1156 was on my own volition to see if it fixed the, to me, critical call_delay() problem I was having. Thus I’ve not really made any fuss about this to support (since I’m technically on an unsupported configuration right now.

That said, you raise a good point and I probably should reply to supports latest e-mail with the fact that I’m a little alarmed that the restarts are happening this frequently. 4-6 restarts, which translates to about 4-6MB leaked per day and is actually quite the memory leak for an “embedded” energy management solution, IMHO.