Luup gives different results when scene launched via web or scene controller

Hi, very new to lua/luup programming so I imagine that I’m doing something wrong here, but for the life of me I can’t figure out what. (USA vera edge, firmware 1.7.1181, the latest as of this writing.)

What I’m trying to do is turn on a binary light, then have my scene pause until it’s confirmed that the light is on, then continue execution.

The code that I have works in the ‘test luup code’, and also works if put in a scene and launched from the web:

local mydevice=50 local counter=0 local switchOnOff = luup.variable_get("urn:upnp-org:serviceId:SwitchPower1", "Status", mydevice) luup.log("switchOnOff before:" .. switchOnOff) luup.call_action("urn:upnp-org:serviceId:SwitchPower1", "SetTarget", {newTargetValue = "1"}, mydevice) while (switchOnOff == "0" and counter < 10) do luup.sleep (1000) switchOnOff = luup.variable_get("urn:upnp-org:serviceId:SwitchPower1", "Status", mydevice) luup.log ("counter: " .. counter .. " switchOnOff: " .. switchOnOff) counter = counter + 1 end if (counter == 10) then luup.log ("***TIMEOUT!***") end

If launched via the web attached to a scene, it works every time (typical output):

50 06/25/15 12:12:41.774 luup_log:0: switchOnOff before:0 <0x7491f520> 50 06/25/15 12:12:42.799 luup_log:0: counter: 0 switchOnOff: 1 <0x7491f520>

(Occasionally I’ll get counter incrementing to 1 or 2, depending on exactly how busy the vera is. To be expected.)

The problem happens when I trigger that scene from a scene controller, such as my aeon minimote or my wall scene controller. It seems as though switchOnOff will never changes state! (This is despite the light turning on right away!)

50 06/25/15 12:14:15.397 luup_log:0: switchOnOff before:0 <0x7731f520> 50 06/25/15 12:14:16.419 luup_log:0: counter: 0 switchOnOff: 0 <0x7731f520> 50 06/25/15 12:14:17.421 luup_log:0: counter: 1 switchOnOff: 0 <0x7731f520> 50 06/25/15 12:14:18.423 luup_log:0: counter: 2 switchOnOff: 0 <0x7731f520> 50 06/25/15 12:14:19.424 luup_log:0: counter: 3 switchOnOff: 0 <0x7731f520> 50 06/25/15 12:14:20.426 luup_log:0: counter: 4 switchOnOff: 0 <0x7731f520> 50 06/25/15 12:14:21.427 luup_log:0: counter: 5 switchOnOff: 0 <0x7731f520> 50 06/25/15 12:14:22.429 luup_log:0: counter: 6 switchOnOff: 0 <0x7731f520> 50 06/25/15 12:14:23.431 luup_log:0: counter: 7 switchOnOff: 0 <0x7731f520> 50 06/25/15 12:14:24.432 luup_log:0: counter: 8 switchOnOff: 0 <0x7731f520> 50 06/25/15 12:14:25.433 luup_log:0: counter: 9 switchOnOff: 0 <0x7731f520> 50 06/25/15 12:14:25.433 luup_log:0: ***TIMEOUT!*** <0x7731f520>

So… what am I doing wrong here? Why is this luup code behaving differently seemingly based solely on what is calling it? (Web vs. scene controller)

Thanks in advance!


Random things that might (not) matter… this is for a fibaro rgbw LED controller. The device I’m controlling & probing is technically a child device, as the parent device doesn’t respond to binarylight commands, nor does the parent honor status requests.

I do not have a direct answer to your question, but I do have some thoughts:

There will be a difference in the way things execute when initiating a scene from the web vice from a remote. Vera will “program” remotes to directly turn on the light, rather than Vera having to send the on command when the scene is run from the remote. This will mean a difference in timing, and the order of actions.

What I would do is turn on the light using LUA code, rather than through the Vera scene interface. That way the execution will be the same if run from the web or a remote.

I do not think its your problem here, but in some releases because of bugs, Vera fails to program the remote properly to send the scene run command back to Vera. So the lights will go on, but the Vera scene is never run.

Hmmm, thanks for the reply! Not entirely sure I follow you, but I think I’m already doing that. In both cases I’m turning on the light via luup; the scene is completely empty (no device actions) except for lua/luup code. In case A (successful), I’m hitting the play icon next to the “test luup code” scene on the web interface. In case B (unsuccessful), button #3 on my minimote is assigned to play the “test luup code” scene.

(I’m actually watching the light while it’s happening, and the light is turning on immediately in both scenarios!)

I do not think its your problem here, but in some releases because of bugs, Vera fails to program the remote properly to send the scene run command back to Vera. So the lights will go on, but the Vera scene is never run.

Huh! I think that’d only be relevant if the scene contained a device action instead of 100% luup code, right?


I did do some creative grepping of the logs, and think I may have found a smoking gun. Here’s the (partial) zwave logs of a successful run… Node 41 is the parent device, node 49 is the first child device, node 50 is the child device that accepts binary light stuff:

24 06/25/15 12:30:25.711 ZWaveJobHandler::DoReceivedFrame m_iFrameID 1384 gwf_ach node 41 command 0x4 data <0x7731f520> 24 06/25/15 12:30:25.712 ZWaveNode::HandlePollUpdate node 41 device 49 class 0x60 command 0xd m_iFrameID 1384/14556840 data 0x5 0x5 0x26 0x3 0x63 (##&#c) <0x7731f520> 24 06/25/15 12:30:25.712 ZWaveNode::HandlePollUpdate_Multi_Channel_Cmd node 41 device 49 passing poll update to embedded 54 <0x7731f520> 24 06/25/15 12:30:25.713 ZWaveNode::HandlePollUpdate node 41 device 54 class 0x26 command 0x3 m_iFrameID 1384/14556840 data 0x63 (c) <0x7731f520> 24 06/25/15 12:30:25.713 ZWaveNode::HandlePollUpdate_Basic_Report node 41 device 54 now is 99 was 0/0 <0x7731f520> 24 06/25/15 12:30:25.720 ZWaveJobHandler::DoReceivedFrame m_iFrameID 1384 done 1 <0x7731f520> 24 06/25/15 12:30:25.731 ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1385 gwf_ach <0x76b1f520> 24 06/25/15 12:30:25.748 ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1385 gwf_ach <0x76b1f520> 24 06/25/15 12:30:25.748 ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1385 gwf_ach <0x76b1f520> 24 06/25/15 12:30:25.751 ZWaveJobHandler::DoReceivedFrame m_iFrameID 1385 gwf_ach node 41 command 0x4 data <0x7731f520> 24 06/25/15 12:30:25.752 ZWaveNode::HandlePollUpdate node 41 device 49 class 0x20 command 0x3 m_iFrameID 1385/17478440 data 0x63 (c) <0x7731f520> 24 06/25/15 12:30:25.752 ZWaveNode::HandlePollUpdate_Basic_Report node 41 device 49 now is 99 was 0/0 <0x7731f520> 24 06/25/15 12:30:25.759 ZWaveJobHandler::DoReceivedFrame m_iFrameID 1385 done 1 <0x7731f520> 24 06/25/15 12:30:25.771 ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1386 gwf_ach <0x76b1f520> 24 06/25/15 12:30:25.788 ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1386 gwf_ach <0x76b1f520> 24 06/25/15 12:30:25.788 ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1386 gwf_ach <0x76b1f520> 24 06/25/15 12:30:25.791 ZWaveJobHandler::DoReceivedFrame m_iFrameID 1386 gwf_ach node 41 command 0x4 data <0x7731f520> 24 06/25/15 12:30:25.792 ZWaveNode::HandlePollUpdate node 41 device 49 class 0x60 command 0xd m_iFrameID 1386/15631776 data 0x1 0x1 0x26 0x3 0x63 (##&#c) <0x7731f520> 24 06/25/15 12:30:25.792 ZWaveNode::HandlePollUpdate_Multi_Channel_Cmd node 41 device 49 passing poll update to embedded 50 <0x7731f520> 24 06/25/15 12:30:25.793 ZWaveNode::HandlePollUpdate node 41 device 50 class 0x26 command 0x3 m_iFrameID 1386/15631776 data 0x63 (c) <0x7731f520> 24 06/25/15 12:30:25.793 ZWaveNode::HandlePollUpdate_Basic_Report node 41 device 50 now is 99 was 1/100 <0x7731f520> 24 06/25/15 12:30:25.793 ZWaveJobHandler::DoReceivedFrame m_iFrameID 1386 done 1 <0x7731f520> 50 06/25/15 12:30:26.170 luup_log:0: counter: 0 switchOnOff: 1 <0x7431f520>

So there you see a poll request hit device 41, then get passed up to 49, then up to 50 right before switchOnOff switches state and reports that the device is on.

Here’s what an unsuccessful run looks like:

24      06/25/15 12:25:37.852   ZWaveController::HandlePollUpdate_SceneActivation scene_act node 39 device 48 scene 5 button 5 duration 0 last ID 5 at 1435252465 <0x7731f520>
50      06/25/15 12:25:37.857   luup_log:0: switchOnOff before:0 <0x7731f520>
24      06/25/15 12:25:37.892   sbrk ZWaveJobHandler::sbrkaddjob pMem 0x10ba000/17539072 diff: 4935680 quit 0 <0x7731f520>
24      06/25/15 12:25:37.898   ZWJob_SendData::Run job job#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:25 S:1 to node 41 command 0x26/0x1 callback 19 m_iFrameID 1105 method 1 options 0x4 retries 0 of 5 <0x76f1f520>
24      06/25/15 12:25:37.899   ZWaveSerial::m_pZWaveFrame_Sending_set this 0xdec538 m_p (nil) now 0xcf9ad0 <0x76f1f520>
24      06/25/15 12:25:37.900   ZWaveCommand::~ZWaveCommand 0xcfa578/(nil) <0x76f1f520>
24      06/25/15 12:25:37.958   ZWaveSerial::Send m_iFrameID 1105 type 0x0 command 0x13 sent ok waiting for 2 ulTime 1180957 timeout 2:2000 bWaitingForAck 1 abort 0 <0x76f1f520>
24      06/25/15 12:25:37.970   ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 1106 gwf_sd <0x76b1f520>
24      06/25/15 12:25:37.971   ZWaveSerial::Send woke up: ulTime 1180957 ulTime_end 1180970 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x76f1f520>
24      06/25/15 12:25:37.971   ZWaveSerial::Send m_iFrameID 1105 type 0x0 command 0x13 sent ok waiting for 2 ulTime 1180957 timeout 20:20000 bWaitingForAck 0 abort 0 <0x76f1f520>
24      06/25/15 12:25:37.988   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1106 gwf_sd <0x76b1f520>
24      06/25/15 12:25:37.988   ZWaveSerial::ReceivedFrame m_iFrameID 1106 gwf_sd is a response frame for m_iFrameID 1105 sd_rjob#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:25 S:1 we're waiting got ack 1 expected response 2 <0x76b1f520>
24      06/25/15 12:25:37.989   ZWaveSerial::Send woke up: ulTime 1180957 ulTime_end 1180988 TimeToWaitInMs 20000 m_pres 0xdef728 m_preq (nil) status 1 <0x76f1f520>
24      06/25/15 12:25:37.989   ZWaveSerial::Send m_iFrameID 1105 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x76f1f520>
24      06/25/15 12:25:37.990   ZWaveSerial::m_pZWaveFrame_Sending_set this 0xdec538 m_p 0xcf9ad0 now (nil) <0x76f1f520>
24      06/25/15 12:25:37.992   ZWJob_SendData::Run done: job job#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:25 S:7 took 96 ms m_enumSendMethod 1 to node 41 command 0x26/0x1 callback 19 m_iFrameID 1105 total 0.97803000 sec type 1 <0x76f1f520>
24      06/25/15 12:25:38.018   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 1107 gwf_sd <0x76b1f520>
24      06/25/15 12:25:38.038   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1107 gwf_sd <0x76b1f520>
24      06/25/15 12:25:38.038   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:13/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x13 m_iFrameID 1107 gwf_sd <0x76b1f520>
24      06/25/15 12:25:38.263   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1108 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.278   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1108 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.278   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1108 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.301   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1109 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.318   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1109 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.318   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1109 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.341   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1110 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.358   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1110 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.358   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1110 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.388   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1111 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.408   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1111 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.408   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1111 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.431   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1112 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.448   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1112 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.448   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1112 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.617   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1113 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.648   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1113 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.648   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1113 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.688   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1114 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.708   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1114 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.708   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1114 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.780   ZWaveSerial::ReceiveData Receive data not enough to process <0x76b1f520>
24      06/25/15 12:25:38.802   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1115 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.828   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1115 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.828   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1115 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.879   ZWaveSerial::ReceiveData Receive data not enough to process <0x76b1f520>
24      06/25/15 12:25:38.902   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1116 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.928   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1116 gwf_ach <0x76b1f520>
24      06/25/15 12:25:38.928   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1116 gwf_ach <0x76b1f520>
50      06/25/15 12:25:38.929   luup_log:0: counter: 0  switchOnOff: 0 <0x7731f520>
24      06/25/15 12:25:38.979   ZWaveSerial::ReceiveData Receive data not enough to process <0x76b1f520>
24      06/25/15 12:25:39.002   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1117 gwf_ach <0x76b1f520>
24      06/25/15 12:25:39.028   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1117 gwf_ach <0x76b1f520>
24      06/25/15 12:25:39.028   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1117 gwf_ach <0x76b1f520>
24      06/25/15 12:25:39.103   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1118 gwf_ach <0x76b1f520>
24      06/25/15 12:25:39.128   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1118 gwf_ach <0x76b1f520>
24      06/25/15 12:25:39.128   ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null ack -1 expect 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 1118 gwf_ach <0x76b1f520>
50      06/25/15 12:25:39.941   luup_log:0: counter: 1  switchOnOff: 0 <0x7731f520>
24      06/25/15 12:25:40.780   ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 1119 gwf_ach <0x76b1f520>
24      06/25/15 12:25:40.798   ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 1119 gwf_ach <0x76b1f520>
50      06/25/15 12:25:40.943   luup_log:0: counter: 2  switchOnOff: 0 <0x7731f520>
50      06/25/15 12:25:41.944   luup_log:0: counter: 3  switchOnOff: 0 <0x7731f520>
50      06/25/15 12:25:42.946   luup_log:0: counter: 4  switchOnOff: 0 <0x7731f520>
50      06/25/15 12:25:43.947   luup_log:0: counter: 5  switchOnOff: 0 <0x7731f520>
50      06/25/15 12:25:44.949   luup_log:0: counter: 6  switchOnOff: 0 <0x7731f520>
50      06/25/15 12:25:45.951   luup_log:0: counter: 7  switchOnOff: 0 <0x7731f520>
50      06/25/15 12:25:46.952   luup_log:0: counter: 8  switchOnOff: 0 <0x7731f520>
50      06/25/15 12:25:47.953   luup_log:0: counter: 9  switchOnOff: 0 <0x7731f520>
50      06/25/15 12:25:47.954   luup_log:0: ***TIMEOUT!*** <0x7731f520>
24      06/25/15 12:25:47.966   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1104 done 1 <0x7731f520>
24      06/25/15 12:25:47.967   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1107 gwf_sd node 0 command 0x13 data  <0x7731f520>
24      06/25/15 12:25:47.968   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1107 passing to job#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:25 S:5 <0x7731f520>
24      06/25/15 12:25:47.968   ZWJob_SendData::ReceivedFrame ok job job#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:25 S:5 to node 41 command 38/1 ok first try resend: 1 waiting 0/0 got 0 <0x7731f520>
24      06/25/15 12:25:47.977   ZWJob_SendData::Run job job#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:35 S:1 to node 41 command 0x26/0x1 callback 19 m_iFrameID 1120 method 2 options 0x5 retries 0 of 5 <0x76f1f520>
24      06/25/15 12:25:47.979   ZWaveSerial::m_pZWaveFrame_Sending_set this 0xdec538 m_p (nil) now 0xf96900 <0x76f1f520>
24      06/25/15 12:25:47.979   ZWaveCommand::~ZWaveCommand 0xf97978/(nil) <0x76f1f520>
24      06/25/15 12:25:47.992   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1108 gwf_ach node 41 command 0x4 data  <0x7731f520>
24      06/25/15 12:25:47.993   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1108 collission with job#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:35 S:7 <0x7731f520>
24      06/25/15 12:25:47.996   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1109 gwf_ach node 41 command 0x4 data  <0x7731f520>
24      06/25/15 12:25:47.996   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1109 collission with job#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:35 S:7 <0x7731f520>
24      06/25/15 12:25:47.999   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1110 gwf_ach node 41 command 0x4 data  <0x7731f520>
24      06/25/15 12:25:47.999   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1110 collission with job#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:35 S:7 <0x7731f520>
24      06/25/15 12:25:48.002   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1111 gwf_ach node 41 command 0x4 data  <0x7731f520>
24      06/25/15 12:25:48.002   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1111 collission with job#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:35 S:7 <0x7731f520>
24      06/25/15 12:25:48.005   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1112 gwf_ach node 41 command 0x4 data  <0x7731f520>
24      06/25/15 12:25:48.005   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1112 collission with job#47 :Level 99 node 41 dev:50 (0xf952a0) N:41 P:35 S:7 <0x7731f520>
24      06/25/15 12:25:48.007   ZWaveJobHandler::DoReceivedFrame m_iFrameID 1113 gwf_ach node 31 command 0x4 data  <0x7731f520>

It almost seems like for some reason it’s queuing up the poll events until after the job completes.

I’m really thinking I need to open up a bug report with vera. Holy hell is this going to be ugly trying to get them to understand.

Oops, missed that line where you turned on the light. Sorry.

What kind of light are you turning on? Is it an instant status device? If it is not, then the state change won’t be recognized until Vera can poll the light, which will be sometime after your scene completes (which does not explain why it works when ran from the web).

Note that “luup.sleep” works kind of funny on this box. A lot of things will not run during this sleep. In fact, you can crash the box by having too long of sleep (a timeout interrupt will occur, causing Vera to automatically reboot).

Not really sure how to answer that question. It’s a Fibaro RGBW LED controller. When it was added, it made two “master” devices (one accepts dimming commands, the other does binary light though they both appear as dimmers in the web interface), along with four individual dimmers to set the R,G,B,W channels individually. If you dink with the R,G,B, or W channel, the masters are also updated to the same value nearly instantaneously. So if you set R to 50% and that’s the channel with the highest output, both masters will also read 50% when you’re done. Occasionally I’ll tweak a slider and notice that one or the other of the masters didn’t update, but then another (literal) second or so goes by and it does. So… I guess so? How does one tell authoritatively?

Ahhh, thanks for the heads up! Originally I was calling sleep for 100ms between tests. 100ms worked just fine, it just looked impatient in the logs when the on command didn’t legitimately take hold immediately. (You can imagine how it bad it looks when I run the scene from the remote! :D)

I suspect that is the problem. Hopefully some one more familiar with the Fibaro can chime in, but I believe that device is not “instant status”. And therefore, it would have to wait until Vera polled it, which could be several minutes after your scene has already timed out. (An “instant status” device will immediately send a message to Vera informing Vera that the device’s status has changed. Battery operated devices are usually instant status. AC devices are not always instant status, you have to be careful to get the right ones. And I do not know for sure about a Fibaro controller.)

Edit: Have you perused this thread: http://forum.micasaverde.com/index.php/topic,15132.msg229757.html#msg229757 It may shed some light on your issue. Perhaps ask your question in that thread.

Ahhh, thanks for the heads up! Originally I was calling sleep for 100ms between tests. 100ms worked just fine, it just looked impatient in the logs when the on command didn't legitimately take hold immediately. (You can imagine how it bad it looks when I run the scene from the remote! :D)

A little bit more work, but a much safer method is to use luup.call_delay(). That is what I do when I have similiar requirements. You could always put the call_delay in a loop, with one second delays, if needed.

Heh, I look at the same description and draw the exact opposite conclusion, that it must be an instant status device! My vera is set to not even attempt polling until 20 minutes after the zwave network has been sitting idle, so … yeah, it’s definitely not polling that’s causing the status change. So walks like a duck, looks like a duck, quacks like a duck, probably a duck. ;D

Edit: Have you perused this thread: http://forum.micasaverde.com/index.php/topic,15132.msg229757.html#msg229757 It may shed some light on your issue. Perhaps ask your question in that thread.

Yeah I’ve looked at it, but that’s more of a base user level thread (at least what I’ve skimmed of it) than a luup based thread.

[hr]

For anyone digging this thread up later, I wound up working around the problem. Turns out if you use call_delay on a function (even if that entire scene was initiated by a minimote instead of the web interface), it jumps the train to the correct track and luup.variable_get starts reflecting live (vs. frozen) data again. So I did a dummy function wrap, then called that function with call_delay with a delay of zero. A 2 out of 10 on the ugly scale, but it works reliably, and more importantly it saves me the hell of going through support to try and get them to fix this bug. So win-win! :smiley:

Oh, and one other interesting thing I noticed… turns out call_delay isn’t based on delta time, but clock ticks. Here I set my routine to call itself with a delay of 1s every time, but the first call only has a time delta of 0.4s. :smiley:

50 06/29/15 8:39:39.782 luup_log:0: RGB: main scene called, light not already on. Turning light on. <0x75499520> 50 06/29/15 8:39:39.807 luup_log:0: RGB: (prep) waiting for confirmation that light is on before commencing color cycling. <0x75a99520> 50 06/29/15 8:39:40.101 luup_log:0: RGB: (prep) waiting for confirmation that light is on before commencing color cycling. <0x75a99520> 50 06/29/15 8:39:41.100 luup_log:0: RGB: (prep) light is on <0x75a99520>

Thanks for the help!

Forgot the fixed example code. :wink:

[code]local mydevice=50
local counter=0
local switchOnOff = luup.variable_get(“urn:upnp-org:serviceId:SwitchPower1”, “Status”, mydevice)
luup.log(“switchOnOff before:” … switchOnOff)
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”, “SetTarget”, {newTargetValue = “1”}, mydevice)

luup.call_delay(‘dummy_function’,0)

function dummy_function()
switchOnOff = luup.variable_get(“urn:upnp-org:serviceId:SwitchPower1”, “Status”, mydevice)
luup.log ("counter: " … counter … " switchOnOff: " … switchOnOff)
counter = counter + 1

if (counter == 10) then
	luup.log ("***TIMEOUT!***")
	return;
end

if (switchOnOff == "0") then
	luup.call_delay('dummy_function', 1)
else
	luup.log ("Light is on.")
end

end
[/code]