The Vera Community forums have moved!

Advanced => Plugins & Plugin Development => Programming => openLuup => Topic started by: CudaNet on November 23, 2015, 11:50:34 am

Title: Watched Variables
Post by: CudaNet on November 23, 2015, 11:50:34 am
I'm interested in knowing where the Watch List is maintained (handled by AltUI I believe). For instance, can this list be managed outside of the scenes themselves. I see log entries (JSON) of the watch but I seem to be having difficulties getting a watch to trigger.

For instance, I've noticed some issues whereby a watch was assigned to one scene and I've seen it show up in other scenes. Also seems that when I create new scenes, well - a watch is always assigned by default within that scene (a constant remnant of sort from another scene). I have no idea how this is happening. I define the watch, add necessary actions/Lua etc. I then Save the scene and reload the Luup engine. So, I'm just trying to gather additional information which will help me/others troubleshoot.
Title: Re: Watched Variables
Post by: akbooer on November 23, 2015, 04:22:36 pm
They're stored in the VariablesToWatch variable in the AltUI plugin, l believe.  I wouldn't mess with them if I were you.  It is actually quite a complex mechanism handled by that plugin.
Title: Re: Watched Variables
Post by: CudaNet on November 23, 2015, 04:34:56 pm
That's unfortunate, I was hoping for a simpler method. I'll see what I can gather and post on the UI forum. Thanks for the heads up (don't touch, really - don't touch).

They're stored in the VariablesToWatch variable in the AltUI plugin, l believe.  I wouldn't mess with them if I were you.  It is actually quite a complex mechanism handled by that plugin.
Title: Re: Watched Variables
Post by: akbooer on November 23, 2015, 04:37:34 pm
You really need to try and isolate this behaviour.  Are we talking an openLuup problem, or an AltUI one.  Have you seen this happen on a real Vera?
Title: Re: Watched Variables
Post by: CudaNet on November 23, 2015, 05:07:28 pm
Everything happens on openLuup now, Vera has been stripped of those responsibilities. I'll see what I can gather and I'll post in this thread.

You really need to try and isolate this behaviour.  Are we talking an openLuup problem, or an AltUI one.  Have you seen this happen on a real Vera?
Title: Re: Watched Variables
Post by: CudaNet on November 23, 2015, 09:33:55 pm
OK, I'm not sure how to troubleshoot this so I'll start here. When creating a new scene, for whatever reason, I start out with a Watched Variable.

A little history of when this started. This weekend I added two identical Leviton switches onto Vera (10[508] and 10[509]). On openLuup/AltUI, I added two scenes - 'Hallway' [10508] and 'Den' [10509]. The triggers for each were (new ~= old). This worked in the 'Hallway' but didn't work in the 'Den'. I then noticed that 'Den' had 'Hallways' watched variable and it's own (how ?). I eventually ended up removing the watched variable from both. Now whenever I create a new scene, there it is... The watched variable that was created for 'Den'.

None of my existing scenes exhibited any issues (thankfully).. New scenes, well - I just have to re
move the trigger each time and the scene saves just fine.
Title: Re: Watched Variables
Post by: akbooer on November 24, 2015, 03:34:50 am
Quote
On openLuup/AltUI, I added two scenes - 'Hallway' [10508] and 'Den' [10509].

How did you do that?  Local scenes should have low numbers.  Are you sure you're using the latest VeraBridge from Release 6?  This would be the behaviour of an earlier version. I would check that first.
Title: Re: Watched Variables
Post by: CudaNet on November 24, 2015, 08:41:53 am
Sorry, not scenes - rather bridged devices within openLuup. The scenes in question are 8 (Hallway) and 9 (Den).

Quote
On openLuup/AltUI, I added two scenes - 'Hallway' [10508] and 'Den' [10509].

How did you do that?  Local scenes should have low numbers.  Are you sure you're using the latest VeraBridge from Release 6?  This would be the behaviour of an earlier version. I would check that first.
Title: Re: Watched Variables
Post by: CudaNet on November 24, 2015, 10:23:49 am
Looks like perhaps the latest UI update corrected things. I added my watched variables back to both scenes and they work perfectly. I then created a new scene and it was clean - no remnants whatsoever. So things look good..

Edit: Looking through the release notes, I don't see anything related to watched variables. Here is the debug from the UI with things working correctly.

Code: [Select]
2015-11-24 08:25:10.356   luup_log:3: ALTUI: debug: fixVariableWatches(3)
2015-11-24 08:25:10.356   luup_log:3: ALTUI: debug: fixVariableWatches(3)
2015-11-24 08:25:10.356   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.VariablesToSend was: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#undefined#undefined#undefined#undefined#undefined;urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#undefined#undefined#undefined#undefined#undefined;urn:upnp-org:serviceId:VContainer1#Variable1#0-36#undefined#undefined#undefined#undefined#undefined;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#undefined#undefined#undefined#undefined#undefined now: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#undefined#undefined#undefined#undefined#undefined;urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#undefined#undefined#undefined#undefined#undefined;urn:upnp-org:serviceId:VContainer1#Variable1#0-36#undefined#undefined#undefined#undefined#undefined;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#undefined#undefined#undefined#undefined#undefined #hooks:0
2015-11-24 08:25:10.357   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.RemoteVariablesToWatch was:  now:  #hooks:0
2015-11-24 08:25:10.357   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.VariablesToWatch was: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#6#(new=="1");urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#7#new == "1";urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-39#10#(new == '1')#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="289" y="16"><value name="Condition"><block type="logic_compare"><field name="OP">EQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="text"><field name="TEXT">1</field></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#9#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="263" y="18"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml> now: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#6#(new=="1");urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#7#new == "1";urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-39#10#(new == '1')#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="289" y="16"><value name="Condition"><block type="logic_compare"><field name="OP">EQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="text"><field name="TEXT">1</field></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#9#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="263" y="18"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml> #hooks:0
2015-11-24 08:25:10.358   luup_log:3: ALTUI: debug: initVariableWatches(3)
2015-11-24 08:25:10.358   luup_log:3: ALTUI: debug: _addWatch(urn:micasaverde-com:serviceId:SecuritySensor1,Tripped,0-10505,6,(new=="1"),,,,,,)
2015-11-24 08:25:10.358   luup.variable_watch:3: callback=variableWatchCallback, watching=10505.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped
2015-11-24 08:25:10.358   luup_log:3: ALTUI: debug: registeredWatches: {"0-10505":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new==\"1\")":[{"SceneID":6}]}}}}}
2015-11-24 08:25:10.358   luup_log:3: ALTUI: debug: _addWatch(urn:micasaverde-com:serviceId:SecuritySensor1,Tripped,0-10301,7,new == "1",,,,,,)
2015-11-24 08:25:10.359   luup.variable_watch:3: callback=variableWatchCallback, watching=10301.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped
2015-11-24 08:25:10.359   luup_log:3: ALTUI: debug: registeredWatches: {"0-10505":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new==\"1\")":[{"SceneID":6}]}}}},"0-10301":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"new == \"1\"":[{"SceneID":7}]}}}}}
2015-11-24 08:25:10.359   luup_log:3: ALTUI: debug: _addWatch(urn:micasaverde-com:serviceId:SecuritySensor1,Tripped,0-39,10,(new == '1'),,,,,,)
2015-11-24 08:25:10.359   luup.variable_watch:3: callback=variableWatchCallback, watching=39.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped
2015-11-24 08:25:10.360   luup_log:3: ALTUI: debug: registeredWatches: {"0-10301":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"new == \"1\"":[{"SceneID":7}]}}}},"0-39":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new == '1')":[{"SceneID":10}]}}}},"0-10505":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new==\"1\")":[{"SceneID":6}]}}}}}
2015-11-24 08:25:10.360   luup_log:3: ALTUI: debug: _addWatch(urn:upnp-org:serviceId:SwitchPower1,Status,0-10509,9,(new ~= old),,,,,,)
2015-11-24 08:25:10.360   luup.variable_watch:3: callback=variableWatchCallback, watching=10509.urn:upnp-org:serviceId:SwitchPower1.Status
2015-11-24 08:25:10.361   luup_log:3: ALTUI: debug: registeredWatches: {"0-10301":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"new == \"1\"":[{"SceneID":7}]}}}},"0-10509":{"urn:upnp-org:serviceId:SwitchPower1":{"Status":{"Expressions":{"(new ~= old)":[{"SceneID":9}]}}}},"0-39":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new == '1')":[{"SceneID":10}]}}}},"0-10505":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new==\"1\")":[{"SceneID":6}]}}}}}
Title: Re: Watched Variables
Post by: akbooer on November 24, 2015, 05:53:43 pm
Looking through the release notes, I don't see anything related to watched variables.

It's here http://forum.micasaverde.com/index.php/topic,33308.msg248521.html#msg248521
Title: Re: Watched Variables
Post by: CudaNet on December 01, 2015, 05:13:44 pm
@Akbooer,

I haven't really researched this heavily (been out of town for the holidays) but thought I'd share an observation. I'm seeing a delay of a few seconds (5-6 at most) between the time I engage my Leviton (instant status) switch and my Hue bulbs illuminating. I realize of lot of things are happening behind the scenes here (Vera <> openLuup, watched variable firing the scene etc.). I was thinking about a couple of tests I could perform so I could trap some log data, but again - was kind of wondering if this type of behavior is to be expected given all the players involved.
Title: Re: Watched Variables
Post by: akbooer on December 01, 2015, 05:28:39 pm
Welcome back.  I hope you had a good break.

Yes, in fact that delay doesn't surprise me.  The response would be much quicker the other way around.  It should be virtually instant if triggered from openLuup, even if the device was on Vera.

The delay is due to the polling of Vera's status from openLuup.  I need to make a change to the bridge to use asynchronous I/O and then it will be as fast both ways.  I originally wrote the bridge to be able to run on a real Vera, but I have evolved away from that as I demanded more and more functionality from it.  You couldn't possibly play the games it does with device numbering on a real Vera.

I thought a period of stability would not be a bad thing.  I have had my latest system up and running for 15 days continuously, and really wanted to break the one month barrier (something that simply can't be done on a Vera.)  It's using between 8 and 12 Mbytes and consuming about 4% of the CPU on an Arduino Yun.

Title: Re: Watched Variables
Post by: CudaNet on December 01, 2015, 05:49:35 pm
OH it was great getting away from work, traffic - all that pains us daily.  I meant to stop in here and wish everyone a happy holidays but I had to make a mad dash to break away. I'm hoping everyone had a safe enjoyable holiday.

Quote
Welcome back.  I hope you had a good break.

That's really good to here and I've observed nothing but immediacy when requests initiate from openLuup. 2 thumbs up !

Quote
Yes, in fact that delay doesn't surprise me.  The response would be much quicker the other way around.  It should be virtually instant if triggered from openLuup, even if the device was on Vera. The delay is due to the polling of Vera's status from openLuup.

Yes, I recall reading that I could run the Bridge on my Vera but never heard mention of it again by anyone. Glad I asked  ;)

Quote
I need to make a change to the bridge to use asynchronous I/O and then it will be as fast both ways.  I originally wrote the bridge to be able to run on a real Vera, but I have evolved away from that as I demanded more and more functionality from it.  You couldn't possibly play the games it does with device numbering on a real Vera.
Quote

Good plan... Interestingly enough, my numbers don't look all that different from yours and this is on my Jetway server. I'm seeing almost identical numbers on memory and the CPU is >1%. I will admit though, I took the latest update from amg0 this morning but this in no way required a system reboot.

Quote
I thought a period of stability would not be a bad thing.  I have had my latest system up and running for 15 days continuously, and really wanted to break the one month barrier (something that simply can't be done on a Vera.)  It's using between 8 and 12 Mbytes and consuming about 4% of the CPU on an Arduino Yun.
Title: Re: Watched Variables
Post by: CudaNet on December 06, 2015, 05:58:21 pm
Having some issues deleting a set of watched variables within a scene.  Scene '12' was a test whereby I'm working with my Schlage lock to identify a PIN user. I tried a couple of methods just to see which worked best but now I simply cannot delete them at all. The process is as follows: I remove all 3 WV's, hit submit, wait - then reload engine and their back. I can remove the Lua code, actions, everything but the watched variables for this scene (12). I do see two errors generated by openLuup - hope this helps. If not, let me know what I can provide.

AltUI v0.101.981
openLuup v6.

Code: [Select]
2015-12-06 16:47:34.630   luup_log:0: ALTUI: ALTUI_Handler: parameters is: {"scene":"12","service":"urn:micasaverde-com:serviceId:DoorLock1","data":"undefined","expression":"(UserName == UserName)","channelid":"undefined","provider":"undefined","graphicurl":"undefined","readkey":"undefined","command":"delWatch","variable":"sl_UserCode","_":"1449441401209","device":"0-10237"}
2015-12-06 16:47:34.631   luup_log:0: ALTUI: ALTUI_Handler: outputformat is: null
2015-12-06 16:47:34.631   luup.variable_set:0: 3.urn:upnp-org:serviceId:altui1.VariablesToWatch was: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#7#new == "1";urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-39#10#(new == '1')#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="289" y="16"><value name="Condition"><block type="logic_compare"><field name="OP">EQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="text"><field name="TEXT">1</field></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#9#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="263" y="18"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10508#8#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="227" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#6#(new=="1");urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName == UserName);urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= UserName);urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10511#13#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="279" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#10110#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="233" y="3"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#14#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="236" y="14"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= nil) now: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#7#new == "1";urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-39#10#(new == '1')#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="289" y="16"><value name="Condition"><block type="logic_compare"><field name="OP">EQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="text"><field name="TEXT">1</field></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#9#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="263" y="18"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10508#8#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="227" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#6#(new=="1");urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName == UserName);urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= UserName);urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10511#13#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="279" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#10110#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="233" y="3"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#14#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="236" y="14"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= nil) #hooks:0
2015-12-06 16:47:34.633   openLuup.context_switch::  ERROR: ./openLuup/server.lua:178: attempt to get length of local 'x' (a number value)
2015-12-06 16:47:34.633   openLuup.scheduler:: job aborted : ./openLuup/server.lua:178: attempt to get length of local 'x' (a number value)
Title: Re: Watched Variables
Post by: akbooer on December 06, 2015, 06:38:03 pm
Something is trying to send a number, instead of a string, as the response to an HTTP request.  From the information given, I can't tell what.  It could be AltUI, but equally well may not be. I have not seen this before.
Title: Re: Watched Variables
Post by: RichardTSchaefer on December 06, 2015, 08:55:16 pm
I did mean to correct you on an earlier statement when you said all of the data from luup.variable_get was a string ...
That's not true. The Z-Wave devices send their numbers as strings ... But there is nothing stopping you from putting other datatypes in device variables.

It only has to be a datatype that can be saved/restored naturally from JSON for persistence ...  Numbers and Strings fit into that category.
 



Title: Re: Watched Variables
Post by: akbooer on December 07, 2015, 03:31:27 am
Interesting, thanks for that.  All numeric values I've ever seen have been stored as strings in device variables.  Attributes are sometimes numeric or boolean.
Title: Re: Watched Variables
Post by: akbooer on December 07, 2015, 06:30:36 am
I did mean to correct you on an earlier statement when you said all of the data from luup.variable_get was a string ...
That's not true. The Z-Wave devices send their numbers as strings ... But there is nothing stopping you from putting other datatypes in device variables.

Taking a closer look, I find this not to be the case.  Ran this bit of code...

Code: [Select]
local sid = "urn:akb:serviceId:akb1"
local print = luup.log

local function set (n,x)
  luup.variable_set (sid, n,x, 97)
end

local function get (n)
  return luup.variable_get (sid, n, 97)
end

set ("number", 42)
set ("string", "abc")

local n = get "number"
print (type(n))

local s = get "string"
print (type(s))

And got this from the log...

Code: [Select]
06 12/07/15 11:22:02.443 Device_Variable::m_szValue_set device: 97 service: urn:akb:serviceId:akb1 variable: number was: 42 now: 42 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x734e4520>
06 12/07/15 11:22:02.444 Device_Variable::m_szValue_set device: 97 service: urn:akb:serviceId:akb1 variable: string was: abc now: abc #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x734e4520>
50 12/07/15 11:22:02.444 luup_log:0: string <0x734e4520>
50 12/07/15 11:22:02.445 luup_log:0: string <0x734e4520>
Title: Re: Watched Variables
Post by: CudaNet on December 07, 2015, 09:20:50 am
When I have more time (tonight) I'll see if I can turn on verbose logging (w/in AltUI) and see what I can capture. I loaded the latest UI [v0.101.994] this morning and the problem persists.
Do you think it's OK to load the latest openLuup before this issue is understood ?

Something is trying to send a number, instead of a string, as the response to an HTTP request.  From the information given, I can't tell what.  It could be AltUI, but equally well may not be. I have not seen this before.
Title: Re: Watched Variables
Post by: akbooer on December 07, 2015, 09:40:54 am
Do you think it's OK to load the latest openLuup before this issue is understood ?

Yes.  In fact, there's a fix for it... that means it won't produce that error, but something else might still be wrong (it doesn't seem right that something should try to return a number as an HTTP response.)
Title: Re: Watched Variables
Post by: CudaNet on December 07, 2015, 09:52:01 am
Sounds good, I'll get everything up and running tonight and report back...

Do you think it's OK to load the latest openLuup before this issue is understood ?

Yes.  In fact, there's a fix for it... that means it won't produce that error, but something else might still be wrong (it doesn't seem right that something should try to return a number as an HTTP response.)
Title: Re: Watched Variables
Post by: CudaNet on December 08, 2015, 09:31:53 am
@Akbooer,

Upgrade went very well, no issues so far. I do however still have issues with the Watched Variables.. So I enabled the AltUI debug mode, and stepped through the process of removing the WV's.

[1] Edit scene 12.
[2] Deleted the 3 watched variables.
[3] Hit submit
[4] Grabbed the logs.

Code: [Select]
2015-12-08 08:15:13.489   openLuup.server:: new client connection: tcp{client}: 0x1afca68
2015-12-08 08:15:13.489   openLuup.server:: /data_request?id=lr_ALTUI_Handler&command=delWatch&service=urn:micasaverde-com:serviceId:DoorLock1&variable=sl_UserCode&device=0-10237&scene=12&expression=(UserName%20~%3D%20nil)&xml=&provider=undefined&channelid=undefined&readkey=undefined&data=undefined&graphicurl=undefined&_=1449583794416 tcp{client}: 0x1afa9b8
2015-12-08 08:15:13.489   luup_log:0: ALTUI: ALTUI_Handler: request is: lr_ALTUI_Handler
2015-12-08 08:15:13.490   luup_log:0: ALTUI: ALTUI_Handler: parameters is: {"scene":"12","service":"urn:micasaverde-com:serviceId:DoorLock1","data":"undefined","expression":"(UserName ~= nil)","channelid":"undefined","provider":"undefined","graphicurl":"undefined","readkey":"undefined","command":"delWatch","variable":"sl_UserCode","_":"1449583794416","device":"0-10237"}
2015-12-08 08:15:13.490   luup_log:0: ALTUI: ALTUI_Handler: outputformat is: null
2015-12-08 08:15:13.490   luup_log:0: ALTUI: debug: hostname=10.0.4.10
2015-12-08 08:15:13.490   luup_log:0: ALTUI: debug: delWatch(3,urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,0-10237,12,(UserName ~= nil),,undefined,undefined,undefined,undefined,undefined)
2015-12-08 08:15:13.490   luup_log:0: ALTUI: debug: _delWatch(urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,0-10237,12,(UserName ~= nil),,undefined,undefined,undefined,undefined,undefined)
2015-12-08 08:15:13.491   luup.variable_set:0: 3.urn:upnp-org:serviceId:altui1.VariablesToWatch was: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#7#new == "1";urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-39#10#(new == '1')#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="289" y="16"><value name="Condition"><block type="logic_compare"><field name="OP">EQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="text"><field name="TEXT">1</field></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#9#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="263" y="18"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10508#8#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="227" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#6#(new=="1");urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName == UserName);urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= UserName);urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10511#13#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="279" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#10110#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="233" y="3"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#14#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="236" y="14"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= nil) now: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#7#new == "1";urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-39#10#(new == '1')#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="289" y="16"><value name="Condition"><block type="logic_compare"><field name="OP">EQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="text"><field name="TEXT">1</field></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#9#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="263" y="18"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10508#8#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="227" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#6#(new=="1");urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName == UserName);urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= UserName);urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10511#13#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="279" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#10110#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="233" y="3"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#14#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="236" y="14"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= nil) #hooks:0
2015-12-08 08:15:13.492   luup_log:0: ALTUI: debug: registeredWatches: {"0-10512":{"urn:upnp-org:serviceId:SwitchPower1":{"Status":{"Expressions":{"(new ~= old)":[{"SceneID":10110},{"SceneID":14}],"true":[{"SceneID":-1}]}}}},"0-10508":{"urn:upnp-org:serviceId:SwitchPower1":{"Status":{"Expressions":{"(new ~= old)":[{"SceneID":8}]}}}},"0-36":{"urn:upnp-org:serviceId:VContainer1":{"Variable1":{"Expressions":{"true":[{"SceneID":-1}]}}}},"0-10505":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"true":[{"SceneID":-1}],"(new==\"1\")":[{"SceneID":6}]}}}},"0-10237":{"urn:micasaverde-com:serviceId:DoorLock1":{"sl_UserCode":{"Expressions":{"(UserName ~= UserName)":[{"SceneID":12}]}}}},"0-39":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new == '1')":[{"SceneID":10}]}}}},"0-10511":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new ~= old)":[{"SceneID":13}],"true":[{"SceneID":-1}]}}}},"0-10509":{"urn:upnp-org:serviceId:SwitchPower1":{"Status":{"Expressions":{"(new ~= old)":[{"SceneID":9}],"true":[{"SceneID":-1}]}}}},"0-10248":{"urn:micasaverde-com:serviceId:EnergyMetering1":{"Watts":{"DataProviders":{"thingspeak":[{"Data":"key=5QBTW7D2VMYJS38F&field1=%s"}]},"Expressions":{"true":[{"SceneID":-1}]}}}},"0-10301":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"true":[{"SceneID":-1}],"new == \"1\"":[{"SceneID":7}]}}}}}
2015-12-08 08:15:13.492   luup_log:0: ALTUI: debug: lul_html:1
2015-12-08 08:15:13.494   openLuup.context_switch::  ERROR: ./openLuup/server.lua:226: attempt to get length of a number value
2015-12-08 08:15:13.494   openLuup.scheduler:: job aborted : ./openLuup/server.lua:226: attempt to get length of a number value
2015-12-08 08:15:13.494   openLuup.server:: /data_request?id=scene&action=create&json=%7B%22timers%22%3A%5B%5D%2C%22triggers%22%3A%5B%5D%2C%22groups%22%3A%5B%7B%22actions%22%3A%5B%5D%2C%22delay%22%3A0%7D%5D%2C%22Timestamp%22%3A1448979204%2C%22favorite%22%3Afalse%2C%22id%22%3A12%2C%22lua%22%3A%22luup.log(%5C%22Front%20Door%5C%22)%22%2C%22modeStatus%22%3A%220%22%2C%22name%22%3A%22Front%20Door%22%2C%22room%22%3A0%2C%22paused%22%3A0%7D tcp{client}: 0x1afca68
2015-12-08 08:15:13.497   openLuup.server:: request completed (2 bytes, 1 chunks, 2 ms) tcp{client}: 0x1afca68
2015-12-08 08:15:14.010   openLuup.server:: request completed (26168 bytes, 2 chunks, 10591 ms) tcp{client}: 0x1d67068
2015-12-08 08:15:14.014   openLuup.server:: /data_request?id=user_data&output_format=json&DataVersion=584032115&_=1449583794417 tcp{client}: 0x1d67068
2015-12-08 08:15:14.345   openLuup.server:: request completed (668112 bytes, 42 chunks, 330 ms) tcp{client}: 0x1d67068
2015-12-08 08:15:16.363   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=584036527&Timeout=60&MinimumDelay=1500&_=1449583794418 tcp{client}: 0x1d67068
2015-12-08 08:15:19.025   luup.variable_set:43: 10027.urn:micasaverde-com:serviceId:ZWaveNetwork1.LastPollSuccess was: 1449583479 now: 1449584179 #hooks:0
2015-12-08 08:15:19.501   openLuup.server:: /data_request?id=lr_ALTUI_Handler&command=oscommand&oscommand=tail%20-n%20500%20%2Fetc%2Fcmh-ludl%2FLuaUPnP.log&_=1449583794419 tcp{client}: 0x1afca68
2015-12-08 08:15:19.502   luup_log:0: ALTUI: ALTUI_Handler: request is: lr_ALTUI_Handler
2015-12-08 08:15:19.502   luup_log:0: ALTUI: ALTUI_Handler: parameters is: {"command":"oscommand","oscommand":"tail -n 500 /etc/cmh-ludl/LuaUPnP.log","_":"1449583794419"}
2015-12-08 08:15:19.502   luup_log:0: ALTUI: ALTUI_Handler: outputformat is: null
2015-12-08 08:15:19.502   luup_log:0: ALTUI: debug: hostname=10.0.4.10

[5] Reloaded engine. See attached for those logs.

I hope this helps. Last resort I'll simply have to either try to delete the scene all together OR remove it from the user_data.json file...

Title: Re: Watched Variables
Post by: akbooer on December 08, 2015, 11:12:58 am
Quote
Upgrade went very well, no issues so far.

That's good.  Can you confirm that the latest AltUI shows your Vera username at the bottom?  This will be key for the v1.0 upgrade.

I'll take a look at the WV problem, and I see there's definitely another error in the log.
Title: Re: Watched Variables
Post by: CudaNet on December 08, 2015, 11:26:17 am
Yes, I can confirm that my username is displaying properly.
Let me know what else I can provide regarding the WV, I'm home today trying to catch up on some things so I'll check back when I get a chance.

Quote
Upgrade went very well, no issues so far.

That's good.  Can you confirm that the latest AltUI shows your Vera username at the bottom?  This will be key for the v1.0 upgrade.

I'll take a look at the WV problem, and I see there's definitely another error in the log.
Title: Re: Watched Variables
Post by: akbooer on December 08, 2015, 11:42:50 am
Let me know what else I can provide regarding the WV, I'm home today trying to catch up on some things so I'll check back when I get a chance.

OK, well try this more carefully instrumented server.lua file.  Thanks
Title: Re: Watched Variables
Post by: CudaNet on December 08, 2015, 12:00:25 pm
Same process except for the reload...

Code: [Select]
2015-12-08 10:54:14.879   openLuup.server:: request completed (17378 bytes, 2 chunks, 5510 ms) tcp{client}: 0x25d50f8
2015-12-08 10:54:14.984   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=593609536&Timeout=60&MinimumDelay=1500&_=1449593683100 tcp{client}: 0x25d50f8
2015-12-08 10:54:15.816   openLuup.server:: /data_request?id=lr_ALTUI_Handler&command=delWatch&service=urn:micasaverde-com:serviceId:DoorLock1&variable=sl_UserCode&device=0-10237&scene=12&expression=(UserName%20%3D%3D%20UserName)&xml=&provider=undefined&channelid=undefined&readkey=undefined&data=undefined&graphicurl=undefined&_=1449593683101 tcp{client}: 0x2a31458
2015-12-08 10:54:15.817   luup_log:0: ALTUI: ALTUI_Handler: request is: lr_ALTUI_Handler
2015-12-08 10:54:15.817   luup_log:0: ALTUI: ALTUI_Handler: parameters is: {"scene":"12","service":"urn:micasaverde-com:serviceId:DoorLock1","data":"undefined","expression":"(UserName == UserName)","channelid":"undefined","provider":"undefined","graphicurl":"undefined","readkey":"undefined","command":"delWatch","variable":"sl_UserCode","_":"1449593683101","device":"0-10237"}
2015-12-08 10:54:15.817   luup_log:0: ALTUI: ALTUI_Handler: outputformat is: null
2015-12-08 10:54:15.818   luup_log:0: ALTUI: debug: hostname=10.0.4.10
2015-12-08 10:54:15.818   luup_log:0: ALTUI: debug: delWatch(3,urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,0-10237,12,(UserName == UserName),,undefined,undefined,undefined,undefined,undefined)
2015-12-08 10:54:15.818   luup_log:0: ALTUI: debug: _delWatch(urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,0-10237,12,(UserName == UserName),,undefined,undefined,undefined,undefined,undefined)
2015-12-08 10:54:15.818   luup.variable_set:0: 3.urn:upnp-org:serviceId:altui1.VariablesToWatch was: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#7#new == "1";urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-39#10#(new == '1')#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="289" y="16"><value name="Condition"><block type="logic_compare"><field name="OP">EQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="text"><field name="TEXT">1</field></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#9#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="263" y="18"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10508#8#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="227" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#6#(new=="1");urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName == UserName);urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= UserName);urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10511#13#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="279" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#10110#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="233" y="3"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#14#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="236" y="14"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= nil) now: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#7#new == "1";urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-39#10#(new == '1')#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="289" y="16"><value name="Condition"><block type="logic_compare"><field name="OP">EQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="text"><field name="TEXT">1</field></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#9#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="263" y="18"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10508#8#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="227" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#6#(new=="1");urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName == UserName);urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= UserName);urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10511#13#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="279" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#10110#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="233" y="3"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#14#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="236" y="14"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= nil) #hooks:0
2015-12-08 10:54:15.820   luup_log:0: ALTUI: debug: registeredWatches: {"0-10512":{"urn:upnp-org:serviceId:SwitchPower1":{"Status":{"Expressions":{"(new ~= old)":[{"SceneID":10110},{"SceneID":14}],"true":[{"SceneID":-1}]}}}},"0-10508":{"urn:upnp-org:serviceId:SwitchPower1":{"Status":{"Expressions":{"(new ~= old)":[{"SceneID":8}]}}}},"0-36":{"urn:upnp-org:serviceId:VContainer1":{"Variable1":{"Expressions":{"true":[{"SceneID":-1}]}}}},"0-10505":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"true":[{"SceneID":-1}],"(new==\"1\")":[{"SceneID":6}]}}}},"0-10237":{"urn:micasaverde-com:serviceId:DoorLock1":{"sl_UserCode":{"Expressions":{"(UserName ~= UserName)":[{"SceneID":12}],"(UserName ~= nil)":[{"SceneID":12}]}}}},"0-39":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new == '1')":[{"SceneID":10}]}}}},"0-10511":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new ~= old)":[{"SceneID":13}],"true":[{"SceneID":-1}]}}}},"0-10509":{"urn:upnp-org:serviceId:SwitchPower1":{"Status":{"Expressions":{"(new ~= old)":[{"SceneID":9}],"true":[{"SceneID":-1}]}}}},"0-10248":{"urn:micasaverde-com:serviceId:EnergyMetering1":{"Watts":{"DataProviders":{"thingspeak":[{"Data":"key={Removed by Cuda}&field1=%s"}]},"Expressions":{"true":[{"SceneID":-1}]}}}},"0-10301":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"true":[{"SceneID":-1}],"new == \"1\"":[{"SceneID":7}]}}}}}
2015-12-08 10:54:15.820   luup_log:0: ALTUI: debug: lul_html:1
2015-12-08 10:54:15.820   openLuup.server:: WARNING - HTTP response is of type number
2015-12-08 10:54:15.821   openLuup.server:: HTTP response: 1
2015-12-08 10:54:15.822   openLuup.server:: request completed (1 bytes, 1 chunks, 6 ms) tcp{client}: 0x2a31458
2015-12-08 10:54:15.823   openLuup.server:: /data_request?id=scene&action=create&json=%7B%22timers%22%3A%5B%5D%2C%22triggers%22%3A%5B%5D%2C%22groups%22%3A%5B%7B%22actions%22%3A%5B%5D%2C%22delay%22%3A0%7D%5D%2C%22Timestamp%22%3A1448979204%2C%22favorite%22%3Afalse%2C%22id%22%3A12%2C%22lua%22%3A%22luup.log(%5C%22Front%20Door%5C%22)%22%2C%22modeStatus%22%3A%220%22%2C%22name%22%3A%22Front%20Door%22%2C%22room%22%3A0%2C%22paused%22%3A0%7D tcp{client}: 0x2829178
2015-12-08 10:54:15.823   openLuup.server:: /data_request?id=lr_ALTUI_Handler&command=delWatch&service=urn:micasaverde-com:serviceId:DoorLock1&variable=sl_UserCode&device=0-10237&scene=12&expression=(UserName%20~%3D%20nil)&xml=&provider=undefined&channelid=undefined&readkey=undefined&data=undefined&graphicurl=undefined&_=1449593683102 tcp{client}: 0x20ba778
2015-12-08 10:54:15.826   openLuup.server:: request completed (2 bytes, 1 chunks, 3 ms) tcp{client}: 0x2829178
2015-12-08 10:54:15.826   luup_log:0: ALTUI: ALTUI_Handler: request is: lr_ALTUI_Handler
2015-12-08 10:54:15.827   luup_log:0: ALTUI: ALTUI_Handler: parameters is: {"scene":"12","service":"urn:micasaverde-com:serviceId:DoorLock1","data":"undefined","expression":"(UserName ~= nil)","channelid":"undefined","provider":"undefined","graphicurl":"undefined","readkey":"undefined","command":"delWatch","variable":"sl_UserCode","_":"1449593683102","device":"0-10237"}
2015-12-08 10:54:15.827   luup_log:0: ALTUI: ALTUI_Handler: outputformat is: null
2015-12-08 10:54:15.827   luup_log:0: ALTUI: debug: hostname=10.0.4.10
2015-12-08 10:54:15.827   luup_log:0: ALTUI: debug: delWatch(3,urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,0-10237,12,(UserName ~= nil),,undefined,undefined,undefined,undefined,undefined)
2015-12-08 10:54:15.827   luup_log:0: ALTUI: debug: _delWatch(urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,0-10237,12,(UserName ~= nil),,undefined,undefined,undefined,undefined,undefined)
2015-12-08 10:54:15.828   luup.variable_set:0: 3.urn:upnp-org:serviceId:altui1.VariablesToWatch was: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#7#new == "1";urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-39#10#(new == '1')#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="289" y="16"><value name="Condition"><block type="logic_compare"><field name="OP">EQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="text"><field name="TEXT">1</field></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#9#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="263" y="18"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10508#8#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="227" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#6#(new=="1");urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName == UserName);urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= UserName);urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10511#13#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="279" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#10110#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="233" y="3"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#14#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="236" y="14"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= nil) now: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10301#7#new == "1";urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-39#10#(new == '1')#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="289" y="16"><value name="Condition"><block type="logic_compare"><field name="OP">EQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="text"><field name="TEXT">1</field></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10509#9#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="263" y="18"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10508#8#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="227" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10505#6#(new=="1");urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName == UserName);urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= UserName);urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-10511#13#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="279" y="25"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#10110#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="233" y="3"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:upnp-org:serviceId:SwitchPower1#Status#0-10512#14#(new ~= old)#<xml xmlns="http://www.w3.org/1999/xhtml"><block type="when" x="236" y="14"><value name="Condition"><block type="logic_compare"><field name="OP">NEQ</field><value name="A"><block type="new_value"></block></value><value name="B"><block type="old_value"></block></value></block></value></block></xml>;urn:micasaverde-com:serviceId:DoorLock1#sl_UserCode#0-10237#12#(UserName ~= nil) #hooks:0
2015-12-08 10:54:15.829   luup_log:0: ALTUI: debug: registeredWatches: {"0-10512":{"urn:upnp-org:serviceId:SwitchPower1":{"Status":{"Expressions":{"(new ~= old)":[{"SceneID":10110},{"SceneID":14}],"true":[{"SceneID":-1}]}}}},"0-10508":{"urn:upnp-org:serviceId:SwitchPower1":{"Status":{"Expressions":{"(new ~= old)":[{"SceneID":8}]}}}},"0-36":{"urn:upnp-org:serviceId:VContainer1":{"Variable1":{"Expressions":{"true":[{"SceneID":-1}]}}}},"0-10505":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"true":[{"SceneID":-1}],"(new==\"1\")":[{"SceneID":6}]}}}},"0-10237":{"urn:micasaverde-com:serviceId:DoorLock1":{"sl_UserCode":{"Expressions":{"(UserName ~= UserName)":[{"SceneID":12}]}}}},"0-39":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new == '1')":[{"SceneID":10}]}}}},"0-10511":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"(new ~= old)":[{"SceneID":13}],"true":[{"SceneID":-1}]}}}},"0-10509":{"urn:upnp-org:serviceId:SwitchPower1":{"Status":{"Expressions":{"(new ~= old)":[{"SceneID":9}],"true":[{"SceneID":-1}]}}}},"0-10248":{"urn:micasaverde-com:serviceId:EnergyMetering1":{"Watts":{"DataProviders":{"thingspeak":[{"Data":"key={Removed by Cuda}&field1=%s"}]},"Expressions":{"true":[{"SceneID":-1}]}}}},"0-10301":{"urn:micasaverde-com:serviceId:SecuritySensor1":{"Tripped":{"Expressions":{"true":[{"SceneID":-1}],"new == \"1\"":[{"SceneID":7}]}}}}}
2015-12-08 10:54:15.829   luup_log:0: ALTUI: debug: lul_html:1
2015-12-08 10:54:15.830   openLuup.server:: WARNING - HTTP response is of type number
2015-12-08 10:54:15.830   openLuup.server:: HTTP response: 1
2015-12-08 10:54:15.832   openLuup.server:: request completed (1 bytes, 1 chunks, 8 ms) tcp{client}: 0x20ba778
2015-12-08 10:54:16.843   openLuup.server:: request completed (16096 bytes, 2 chunks, 1859 ms) tcp{client}: 0x25d50f8
2015-12-08 10:54:16.848   openLuup.server:: /data_request?id=user_data&output_format=json&DataVersion=593605118&_=1449593683103 tcp{client}: 0x25d50f8
2015-12-08 10:54:17.170   openLuup.server:: request completed (668528 bytes, 42 chunks, 322 ms) tcp{client}: 0x25d50f8
2015-12-08 10:54:19.189   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=593609539&Timeout=60&MinimumDelay=1500&_=1449593683104 tcp{client}: 0x25d50f8

Let me know what else I can provide regarding the WV, I'm home today trying to catch up on some things so I'll check back when I get a chance.

OK, well try this more carefully instrumented server.lua file.  Thanks
Title: Re: Watched Variables
Post by: CudaNet on December 08, 2015, 12:04:14 pm
And the reload...
Title: Re: Watched Variables
Post by: akbooer on December 08, 2015, 12:36:05 pm
OK, I have no real idea what is going on here.  This is all AltUI stuff.

What I do know is that the message:
Code: [Select]
luup_log:0: ALTUI: debug: lul_html:1

comes from line 1261 of L_ALTUI.lua, and shows that the call to whatever function 'switch' dispatches returns a number '1'.  In my book, this is just plain wrong.  Suggest that you confer with @amg0.

Have you simply deleted the scene and tried this again?  All the 'undefined' entries in the log look unwelcoming.
Title: Re: Watched Variables
Post by: CudaNet on December 08, 2015, 12:57:00 pm
I'll point amg0 to this thread. I'm not confident I can recreate the problem so I'll just let the scene sit untouched until amg0 has a look. Thanks for looking at this though. I'll rename the server.lua file and revert to the latest release.

OK, I have no real idea what is going on here.  This is all AltUI stuff.

What I do know is that the message:
Code: [Select]
luup_log:0: ALTUI: debug: lul_html:1

comes from line 1261 of L_ALTUI.lua, and shows that the call to whatever function 'switch' dispatches returns a number '1'.  In my book, this is just plain wrong.  Suggest that you confer with @amg0.

Have you simply deleted the scene and tried this again?  All the 'undefined' entries in the log look unwelcoming.
Title: Re: Watched Variables
Post by: akbooer on December 08, 2015, 01:16:00 pm
I'm not confident I can recreate the problem so I'll just let the scene sit untouched until amg0 has a look.

Well, that's the point, really.  Who knows what iterations of openLuup / VeraBridge / AltUI you've gone through to generate this situation?  It might not be a real problem at all.

You can always save the user_data.json and restart a system from there.
Title: Re: Watched Variables
Post by: CudaNet on December 08, 2015, 03:00:51 pm
Well, yes... I deleted the scene, reloaded the engine. I then added a new scene, new name, saved it and refreshed the page. It's now scene 12 (I assume it fills the open slot) with the new name I gave it and it has inherited the 3 watched variables. So I halted the engine and removed scene 12 all together from the user_data.json file. I started it back up, created a new scene, new name, saved it - refreshed and all is well. I then renamed it back to the old scene name (Front Door), reloaded and it's holding. No issues so far...

Thoughts on why this might be happening. Seems like when I add a watched variable (when I know exactly what I want) things are fine. When I change, add or experiment with the WV for a scene, well - things get strange quickly...

I'm not confident I can recreate the problem so I'll just let the scene sit untouched until amg0 has a look.

Well, that's the point, really.  Who knows what iterations of openLuup / VeraBridge / AltUI you've gone through to generate this situation?  It might not be a real problem at all.

You can always save the user_data.json and restart a system from there.
Title: Re: Watched Variables
Post by: CudaNet on December 08, 2015, 03:11:35 pm
Probably spoke too soon. I noticed I now have no watched variables for any of my scenes. I'll add them back and see if the issues persist.
Title: Re: Watched Variables
Post by: amg0 on December 08, 2015, 05:03:20 pm
V 0.102.1001 fixes a number of things you may want to try.  especially the return ( number / string ) which has nothing to do with your problem,   and some weirdness with add and deleting ( or changing ) a variable watch - which is more likely related to your issues.

let me know.
I also added some more debug statements in ALTUI in debug mode so eventually we can look at Luup logs if pb persists.
thx
Title: Re: Watched Variables
Post by: CudaNet on December 08, 2015, 07:12:37 pm
Thank you.. I loaded the latest and will let the two of you know if I run into any issues...

V 0.102.1001 fixes a number of things you may want to try.  especially the return ( number / string ) which has nothing to do with your problem,   and some weirdness with add and deleting ( or changing ) a variable watch - which is more likely related to your issues.

let me know.
I also added some more debug statements in ALTUI in debug mode so eventually we can look at Luup logs if pb persists.
thx
Title: Re: Watched Variables
Post by: CudaNet on December 13, 2015, 02:04:59 pm
Need a little direction here... Just trying to accomplish the following two watched tasks:

[1] Door code entered. [sl_UserCode]. Any valid code entered.
[2] Door lock button was pushed. [sl_LockButton]. Only when pushed from exterior.

Vera log data for #1:
Code: [Select]
06      12/13/15 12:16:06.208   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_UserCode was: UserID="3" UserName="Cuda" now: UserID="3" UserName="Cuda" #hooks: 0 upnp: 0 skip: 0 v:0xb3b2c0/DL_USERCODE duplicate:0 <0x2ba58680>

openLuup/AltUI for #1:
Code: [Select]
Schlage [237] urn:micasaverde-com:serviceId:DoorLock1 sl_UserCode (UserID ~= "0")

Vera log data for #2:
Code: [Select]
06      12/13/15 12:04:00.887   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_LockButton was: 1 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xb3c678/DL_LOCK_BUTTON duplicate:0 <0x2ba58680>

openLuup/AltUI for #2:
Code: [Select]
Schlage [237] urn:micasaverde-com:serviceId:DoorLock1 sl_LockButton (new == "1")

Using these, the only log data I ever see is this...
Code: [Select]
06 12/13/15 12:59:22.703 Device_Variable::m_szValue_set device: 10237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 1 now: 0 #hooks: 0
06 12/13/15 13:01:19.713 Device_Variable::m_szValue_set device: 10237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 0 now: 1 #hooks: 0
Title: Re: Watched Variables
Post by: CudaNet on December 17, 2015, 08:56:48 am
Hewwo, Jingle Bells... Anyone able to provide input on this, has a lock and can trigger off these variables ?

Need a little direction here... Just trying to accomplish the following two watched tasks:

[1] Door code entered. [sl_UserCode]. Any valid code entered.
[2] Door lock button was pushed. [sl_LockButton]. Only when pushed from exterior.

Vera log data for #1:
Code: [Select]
06      12/13/15 12:16:06.208   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_UserCode was: UserID="3" UserName="Cuda" now: UserID="3" UserName="Cuda" #hooks: 0 upnp: 0 skip: 0 v:0xb3b2c0/DL_USERCODE duplicate:0 <0x2ba58680>

openLuup/AltUI for #1:
Code: [Select]
Schlage [237] urn:micasaverde-com:serviceId:DoorLock1 sl_UserCode (UserID ~= "0")

Vera log data for #2:
Code: [Select]
06      12/13/15 12:04:00.887   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_LockButton was: 1 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xb3c678/DL_LOCK_BUTTON duplicate:0 <0x2ba58680>

openLuup/AltUI for #2:
Code: [Select]
Schlage [237] urn:micasaverde-com:serviceId:DoorLock1 sl_LockButton (new == "1")

Using these, the only log data I ever see is this...
Code: [Select]
06 12/13/15 12:59:22.703 Device_Variable::m_szValue_set device: 10237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 1 now: 0 #hooks: 0
06 12/13/15 13:01:19.713 Device_Variable::m_szValue_set device: 10237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 0 now: 1 #hooks: 0
Title: Re: Watched Variables
Post by: amg0 on December 17, 2015, 09:30:31 am
not sure about others but for me to be able to help you I would need you to follow the following protocol:

a) explain the whole thing you are trying to do from scratch , telling clearly what device id, what watch variable you want and version of ALTUI openluup
b) enable ALTUI device in debug mode
c) give , at this precise point the value of the VariableToWatch value so we verify your watch is properly setup
d) reload Luup
e) exercise the device you want to watch , make sure the old value is different from the new value
f) wait 20sec
g) capture the lua cmh log file and share with us in PM

then we can have a look at the log and see what happens maybe
Title: Re: Watched Variables
Post by: CudaNet on December 17, 2015, 09:56:15 am
Thank you, I'll do this tonight when I get home and post all the pertinent data..

not sure about others but for me to be able to help you I would need you to follow the following protocol:

a) explain the whole thing you are trying to do from scratch , telling clearly what device id, what watch variable you want and version of ALTUI openluup
b) enable ALTUI device in debug mode
c) give , at this precise point the value of the VariableToWatch value so we verify your watch is properly setup
d) reload Luup
e) exercise the device you want to watch , make sure the old value is different from the new value
f) wait 20sec
g) capture the lua cmh log file and share with us in PM

then we can have a look at the log and see what happens maybe
Title: Re: Watched Variables
Post by: akbooer on December 17, 2015, 12:24:36 pm
Hewwo, Jingle Bells... Anyone able to provide input on this, has a lock and can trigger off these variables ?

Sorry, completely missed seeing the original post for some reason.

The thing I'd like to see is, as @amg0 mentions, a complete log, so that we can see what variables actually DID change, and then what happened in the variable callback.  There should be tons of diagnostic information in that sequence of events, but it's not just the lock device, or the AltUI plugin actions, it's the way they all play together.

Thanks.
Title: Re: Watched Variables
Post by: CudaNet on December 17, 2015, 01:13:24 pm
Tis OK, it's a busy week for everyone with the Holidays approaching. I'll pull everything together tonight..

Hewwo, Jingle Bells... Anyone able to provide input on this, has a lock and can trigger off these variables ?

Sorry, completely missed seeing the original post for some reason.

The thing I'd like to see is, as @amg0 mentions, a complete log, so that we can see what variables actually DID change, and then what happened in the variable callback.  There should be tons of diagnostic information in that sequence of events, but it's not just the lock device, or the AltUI plugin actions, it's the way they all play together.

Thanks.
Title: Re: Watched Variables
Post by: CudaNet on December 21, 2015, 11:27:13 am
Hey all, just a quick update. I'm really trying to not bother anyone with this until I've exhausted all avenues. This is just a matter of a learning curve whereby I need to identify how to isolate the variables for triggering the scene. I can honestly say, I forgot about amg0's log data and therefore I'm focusing on that now (in debug mode). I see some new data and I'm hoping I can adjust and resolve this myself.

Either way, I'll post my results for those who may be in search of the same...
Title: Re: Watched Variables
Post by: CudaNet on February 02, 2016, 03:23:21 pm
And it's time to revive this thread, totally my fault for letting this go but like many of us - I got distracted with other things. SO I'm revisiting this.
What's the simplest method of determining a variable for isolation within a Watch.
I often struggle with this and I don't know why... It seems simple enough in concept but in execution I've failed to reach a level of confidence.  A perfect case is my failed attempts at isolating the user code for my lock. The log below is taken directly from Vera and the variable itself will change based on the user.

Code: [Select]
06      12/13/15 12:16:06.208   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_UserCode was: UserID="3" UserName="Cuda" now: UserID="3" UserName="Cuda" #hooks: 0 upnp: 0 skip: 0 v:0xb3b2c0/DL_USERCODE duplicate:0 <0x2ba58680>

As you can see, the variable is sl_UserCode and the content within that variable is was: UserID="3" UserName="Cuda" now: UserID="3" UserName="Cuda". Now this variable may occur back to back (userA enters, leaves then returns again before userB) or it may change (userA enters then userB enters). So in this real life example, what's the best way to isolate this within a watched variable ? Perhaps I just need to learn by example...
Title: Re: Watched Variables
Post by: akbooer on February 02, 2016, 05:40:50 pm
I think my problem in constructing a solution is that I don't understand what you mean by 'isolate' within this context.
Title: Re: Watched Variables
Post by: CudaNet on February 02, 2016, 05:54:09 pm
I want to execute a scene using a watched variable, however - I can't seem to get this particular scene to fire (in this case, a lock with various user codes; variable=sl_UserCode).

I think my problem in constructing a solution is that I don't understand what you mean by 'isolate' within this context.
Title: Re: Watched Variables
Post by: CudaNet on February 02, 2016, 10:47:18 pm
According to this MCV/Wiki page, it documents 2 variables I'm attempting to watch to execute a pair of scenes.
http://wiki.micasaverde.com/index.php/Luup_UPnP_Variables_and_Actions (http://wiki.micasaverde.com/index.php/Luup_UPnP_Variables_and_Actions)

Code: [Select]
sl_LockButton boolean This is "1" if the Lock button has been pressed on the lock keypad.
sl_UserCode     string Contains information about the last used PIN code: UserID="<pin_slot>" UserName="<pin_code_name>"

I've now entered a PIN code to unlock the door. This event appears for DoorLock1.sl_UserCode within the openLuup logs.

Code: [Select]
2016-02-02 20:51:21.442   luup.variable_set:43: 10237.urn:micasaverde-com:serviceId:DoorLock1.Status was: 1 now: 0 #hooks:0
2016-02-02 20:51:21.442   luup.variable_set:43: 10237.urn:micasaverde-com:serviceId:DoorLock1.sl_UserCode was: UserID="4" UserName="{NameD}" now: UserID="3" UserName="{NameC}" #hooks:0

And an actual Vera.
Code: [Select]
06      02/02/16 21:15:00.480   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 1 now: 0 #hooks: 0 upnp: 0 skip: 0 v:0x829808/NONE duplicate:0 <0x2b2a8680>
06      02/02/16 21:15:00.481   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_UserCode was: UserID="3" UserName="{NameC}" now: UserID="3" UserName="{NameC]" #hooks: 0 upnp: 0 skip: 0 v:0xa3ec28/DL_USERCODE duplicate:0 <0x2b2a8680>

Questions:
[1] What expression do I use for DoorLock1.sl_UserCode so I can trigger off any User/UserName entered ?
[2] Why would I never see an DoorLock1.sl_LockButton event ? Vera shows it but no event occurs on openLuup other than this log. :

Code: [Select]
2016-02-02 21:24:13.269   luup_log:0: ALTUI: ALTUI_Handler: parameters is: {"command":"oscommand","oscommand":"tail -n 500 /etc/cmh-ludl/LuaUPnP.log","_":"1454465793867"}
2016-02-02 21:24:13.269   luup_log:0: ALTUI: ALTUI_Handler: outputformat is: null
2016-02-02 21:24:13.269   luup_log:0: ALTUI: debug: hostname=10.0.4.10

2016-02-02 21:24:13.282   openLuup.server:: request completed (94262 bytes, 6 chunks, 14 ms) tcp{client}: 0x2f51038
2016-02-02 21:24:14.328   luup.variable_set:43: 10237.urn:micasaverde-com:serviceId:DoorLock1.Status was: 0 now: 1 #hooks:0
2016-02-02 21:24:14.328   luup.variable_set:43: 10366.urn:micasaverde-com:serviceId:GenericSensor1.CurrentLevel was: 2252 now: 2250 #hooks:0
2016-02-02 21:24:14.329   luup.variable_set:43: 10506.urn:micasaverde-com:serviceId:GenericSensor1.CurrentLevel was: 2252 now: 2250 #hooks:0
2016-02-02 21:24:14.845   openLuup.server:: request completed (21457 bytes, 2 chunks, 3336 ms) tcp{client}: 0x2f4e408
2016-02-02 21:24:14.952   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=469845919&Timeout=60&MinimumDelay=1500&_=1454465793868 tcp{client}: 0x2f4e408
2016-02-02 21:24:18.961   luup_log:3: ALTUI: Clearing...
2016-02-02 21:24:18.961   luup.task:3: status=4 ALTUI : Clearing...
2016-02-02 21:24:20.135   luup.task:4: status=4 Philips Hue by MiOS : Clearing...
2016-02-02 21:24:21.137   luup.task:4: status=4 Philips Hue by MiOS : Clearing...

Vera logs:
Code: [Select]
06      02/02/16 21:24:25.849   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0x829808/NONE duplicate:0 <0x2b2a8680>
06      02/02/16 21:24:25.850   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_LockButton was: 1 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xa3f5a8/DL_LOCK_BUTTON duplicate:0 <0x2b

For this my expression would be (new=='1') for DoorLock1.sl_LockButton  ...
Title: Re: Watched Variables
Post by: akbooer on February 03, 2016, 03:26:49 am
I think the clue is here

Code: [Select]
237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 0 now: 1
237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_LockButton was: 1 now: 1

...whilst Status changes value from 0 to 1, sl_LockButton remains at 1, so no change of state, so no trigger.
Title: Re: Watched Variables
Post by: cybrmage on February 03, 2016, 05:39:46 am
I think the clue is here

Code: [Select]
237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 0 now: 1
237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_LockButton was: 1 now: 1

...whilst Status changes value from 0 to 1, sl_LockButton remains at 1, so no change of state, so no trigger.

On a real Vera device... When a device variable is used as a trigger or in a variable watch, the trigger is evaluated whenever the variable is updated, independent of a change in value.

This is why many plugins are coded to prevent calling luup.variable_set to update a variable unless the value of the variable has changed...

A real world example is the EVL3 plugin with a scene being triggered when a motion/door sensor is faulted... Originally, it would set the "Tripped" variable on a motion/door sensor when the alarm panel reported that the sensor had been faulted... But the EVL3 reports the fault as both a sensor fault in a keypad update (which causes the variable to be set to 1) and a zone fault in a zone update (which sets the variable to 1)... This would cause the scene to be run twice, once for each time the variable is set... The plugin now calls a helper function each time it sets a variable, and this helper function prevents calling luup.variable_set unless the value has changed.

This behavior (evaluating trigger conditions) are also used in Vera Scene Controllers... The "Sl_SceneActivated" and "Sl_SceneDeactivated" variables are used as a trigger, and is set the scene number being activated. If the trigger was not evaluated when the value does not change, you could only trigger a scene once and would need to trigger a different scene before being able to trigger the scene a second time.


Title: Re: Watched Variables
Post by: martynwendon on February 03, 2016, 06:47:49 am

On a real Vera device... When a device variable is used as a trigger or in a variable watch, the trigger is evaluated whenever the variable is updated, independent of a change in value.

This doesn't seem to match the behaviour that I see!

If I set a watch on a real Vera on say:

service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature

Unless CurrentTemperature *changes*, the watch doesn't fire, because the variable doesn't change.

If I set a watch on an entire service:

service: urn:upnp-org:serviceId:SwitchPower1

then any time ANY variable is changed within that service, the watch will fire, but if nothing changes in any variable, then the watch doesn't fire.

At least that's my experience ever since early UI5 versions up until current and seems consistent with the docs at http://wiki.micasaverde.com/index.php/Luup_Lua_extensions#function:_variable_watch

Quote
Whenever the UPnP variable is changed for the specified device, which if a string is interpreted as a UDN and if a number as a device ID, function_name will be called. See Luup Declarations#watch_callback for the values that will be passed to function_name. If variable is nil, function_name will be called whenever any variable in the service is changed.

Scene Controllers are slightly different because there's a lot of lower level shenanigans occuring to handle the various Scene Controller command classes.  The Scene Controller variables don't directly correspond to the underlying command classes being used, Vera generates these at some lower level and forces them to be evaluated every time they are updated.
Title: Re: Watched Variables
Post by: CudaNet on February 03, 2016, 09:14:11 am
So yes, we have a problem....

[1] UserA enters and leaves, UserA returns. The events are the same and therefor the watch never fires the scene.
[2] The lock button being pressed always results in a variable of '1', same problem as item 1.

So how would we know which devices exhibit this behavior (aside from locks and scene controllers) ? Trial and error. Ugh ! I've been trying to overcome this issue for some time now.  Should I let amg0 know what's being observed so we can possibly approach a solution ?

Here is a log whereby I used (new~=nil) for a sl_UserCode.

Code: [Select]
2016-02-03 08:01:34.744   luup_log:3: ALTUI: debug: -----> evaluateExpression() {"(new ~= nil)":[{"SceneID":12}]}
2016-02-03 08:01:34.744   luup_log:3: ALTUI: debug: evaluateExpression(0-10237,urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,(new ~= nil),UserID="3" UserName="UserC",UserID="4" UserName="UserD",1454508094,1,12)
2016-02-03 08:01:34.744   luup_log:3: ALTUI: debug: _evaluateUserExpression(0-10237,urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,UserID="3" UserName="UserC",UserID="4" UserName="UserD",1454508094,(new ~= nil))
2016-02-03 08:01:34.745   luup_log:3: ALTUI: debug: Evaluation of user watch expression returned: [true]
2016-02-03 08:01:34.745   luup_log:3: ALTUI: debug: run_scene(12)

However, enter a second time with the same user code and this happens...

Code: [Select]
2016-02-03 08:04:42.881   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=506764955&Timeout=60&MinimumDelay=1500&_=1454506622711 tcp{client}: 0x2b84478
2016-02-03 08:04:52.307   luup.variable_set:43: 10237.urn:micasaverde-com:serviceId:DoorLock1.Status was: 1 now: 0 #hooks:0
2016-02-03 08:04:52.307   luup.variable_set:43: 10366.urn:micasaverde-com:serviceId:GenericSensor1.CurrentLevel was: 2255 now: 2267 #hooks:0
2016-02-03 08:04:52.308   luup.variable_set:43: 10506.urn:micasaverde-com:serviceId:GenericSensor1.CurrentLevel was: 2255 now: 2267 #hooks:0
2016-02-03 08:04:52.822   openLuup.server:: request completed (21453 bytes, 2 chunks, 9941 ms) tcp{client}: 0x2b84478
2016-02-03 08:04:52.926   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=506764958&Timeout=60&MinimumDelay=1500&_=1454506622712 tcp{client}: 0x2b84478
2016-02-03 08:04:56.943   openLuup.server:: new client connection: tcp{client}: 0x2c78c98
Title: Re: Watched Variables
Post by: akbooer on February 03, 2016, 10:00:05 am
What's wrong with triggering from the Status variable which seems to change?
Title: Re: Watched Variables
Post by: CudaNet on February 03, 2016, 10:03:15 am
The status variable doesn't allow me to discern between the lock button being pressed from the outside and the lock being turned on the inside. I have scenes the need to know if the lock was secured from outside the house.

What's wrong with triggering from the Status variable which seems to change?
Title: Re: Watched Variables
Post by: martynwendon on February 03, 2016, 10:05:22 am
akbooer beat me to it :-)

The trick I usually use is to find something else in the service that *does* change:

http://wiki.micasaverde.com/index.php/Luup_UPnP_Variables_and_Actions#DoorLock1

Then set your event to trigger off that and use variable_get to retrieve the current value for the other data (sl_UserCode in your case).

For Scene Controllers I normally watch "LastSceneTime" because that's a time stamp in seconds since epoch that always changes.
Title: Re: Watched Variables
Post by: CudaNet on February 03, 2016, 11:54:56 am
Yes, I'm all for a workaround if it presents itself. In this case, status won't get me there...

akbooer beat me to it :-)

The trick I usually use is to find something else in the service that *does* change:

http://wiki.micasaverde.com/index.php/Luup_UPnP_Variables_and_Actions#DoorLock1

Then set your event to trigger off that and use variable_get to retrieve the current value for the other data (sl_UserCode in your case).

For Scene Controllers I normally watch "LastSceneTime" because that's a time stamp in seconds since epoch that always changes.
Title: Re: Watched Variables
Post by: martynwendon on February 03, 2016, 01:51:20 pm
Yes, I'm all for a workaround if it presents itself. In this case, status won't get me there...

Maybe I'm missing what you're trying to do, status always changes when the lock is locked / unlocked?

And you want the value of sl_UserCode and sl_LockButton to do something with them?

So why can't you watch Status and do a variable_get on those 2 variables to get the values?

Or have I missed something?

Title: Re: Watched Variables
Post by: CudaNet on February 03, 2016, 02:59:20 pm
DoorLock1.sl_LockButton allows us to differentiate between someone leaving the property and a momentary process (fetching the mail). Evaluating status tells us nothing other than the state changed from 0 to 1 and vice versa. Great if you want to secure the door in a scene but poor in identifying if someone is actually leaving. 

DoorLock1.sl_UserCode identifies that someone is coming home and who exactly that someone is. Again, evaluating the Status and fetching the UserID may only return the last UserID that entered the house. For example, if UserA entered then left (forgot something at the store) and UserB is still home and decides to walk out and check the mail, well - triggering off status and fetching the UserID would yield UserA when all you wanted to do was check the mail.

These variables exist because Status alone doesn't help isolate exactly what happened other than the obvious (door locked/unlocked). I can only hope that Amg0 has a possible solution as I honestly have no idea how many 'devices' do exactly this. If a conditional can be applied then this would overcome the issue all together. Then again, I never try to reduce this to a simple fix as I have no doubt this is complex code.

Yes, I'm all for a workaround if it presents itself. In this case, status won't get me there...

Maybe I'm missing what you're trying to do, status always changes when the lock is locked / unlocked?

And you want the value of sl_UserCode and sl_LockButton to do something with them?

So why can't you watch Status and do a variable_get on those 2 variables to get the values?

Or have I missed something?
Title: Re: Watched Variables
Post by: martynwendon on February 04, 2016, 04:38:39 am
I must be having a slow week because I'm still not following :-)

If the status changes every time *something* happens, then I still don't see why you can't trigger off of that event but then retrieve the values of the other variables and use them to determine your logic flow?

Or are you saying that sl_LockButton is only a momentary event and flips from 0 to 1 and then back to 0?  So the *current* value is irrelevant?

If that's the case then I guess the question becomes is this possible on a *real* Vera. 

Vera may show the event in the logs, but can you set a trigger for a scene on it and can you set a variable watch that will fire when the event occurs?

Here's an example from a real Vera:

Code: [Select]
Device_Variable::m_szValue_set device: 464 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 20 now: 20 #hooks: 1 upnp: 0 v:0x11fb368/NONE duplicate:1 <0x2bd87680>
That "event" shows in the logs, but the variable watch does not fire because the data hasn't changed.

If you're saying that you can set a trigger or variable watch on sl_UserCode and sl_LockButton and they fire even though the data hasn't changed, then this is indeed another special case where Vera always forces the trigger or variable watch to fire whether the data has changed or not.

And that will be a problem for akbooer and amg0 unfortunately :-)
Title: Re: Watched Variables
Post by: akbooer on February 04, 2016, 05:35:13 am
I must be having a slow week because I'm still not following :-)

I am having exactly the same difficulties in understanding why there's an issue here.

Quote
If you're saying that you can set a trigger or variable watch on sl_UserCode and sl_LockButton and they fire even though the data hasn't changed, then this is indeed another special case where Vera always forces the trigger or variable watch to fire whether the data has changed or not.

In order to try and push my understanding forward a bit, I took a look at the service file S_DoorLock1.xml  In the serviceStateTable section it contains, amongst others, these entries:

Code: [Select]
    <stateVariable sendEvents="yes" allowRepeats="yes">
      <name>sl_UserCode</name>
      <dataType>string</dataType>
      <logCode>DL_USERCODE</logCode>
      <logSeverity>3</logSeverity>
    </stateVariable>

   <stateVariable sendEvents="yes" allowRepeats="yes">
      <name>sl_LockButton</name>
      <dataType>boolean</dataType>
      <logCode>DL_LOCK_BUTTON</logCode>
      <logSeverity>3</logSeverity>
    </stateVariable>

So I'm really at a loss if you're telling me that they don't BOTH report repeated events on a real Vera.

Code: [Select]
And that will be a problem for akbooer and amg0 unfortunately :-)

I feel sure the problem will be all mine.

Title: Re: Watched Variables
Post by: amg0 on February 04, 2016, 07:28:52 am
I also have still not understood what ( in wording terms ) you are trying to do.

But some additional info regarding watches in ALTUI.

The watch expression can contain predefined variables new & old so you can use new / old and compare them in your expression.  also the function trueSince(expr,sec) can test if an expr is true and remains true for x sec.
so a valid expression could be for instance:
Code: [Select]
trueSince((new == '1' and new ~= old), 10)
To properly debug watch , you need to run ALTUI in DEBUG mode and get back the logs
Title: Re: Watched Variables
Post by: CudaNet on February 04, 2016, 09:26:30 am
@amg0 and Akbooer. I'm going to run a quick battery of tests (with debug enabled) and send them to both of you this morning. For the record, this is what an actual Vera log looks like...

Expressions currently used in openLuup/AltUI scenes:
Code: [Select]
Scene 16 (front door locked)
Schlage [237] urn:micasaverde-com:serviceId:DoorLock1 sl_LockButton (new=='1' and old == '1')

Scene 12(Front door unlocked)
Schlage [237] urn:micasaverde-com:serviceId:DoorLock1 sl_UserCode (new ~= nil and old ~=nil)

UserA presses the lock button on the outside of the door, this variable (sl_LockButton) will always appear as '1' (never 0 - 1 or 1 - 0):
Code: [Select]
VERA LOG:
06      02/04/16 8:00:54.376    Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xb7c810/NONE duplicate:0 <0x2b
06      02/04/16 8:00:54.377    Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_LockButton was: 1 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xd925a8/DL_LOCK_BUTTON duplicate:0

UserA enters, leaves and returns where UserB has not returned home yet.
Code: [Select]
VERA LOG:
06      02/04/16 8:03:01.536    Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 1 now: 0 #hooks: 0 upnp: 0 skip: 0 v:0xb7c810/NONE duplicate:0 <0x2b83a6
06      02/04/16 8:03:01.538    Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_UserCode was: UserID="4" UserName="User A" now: UserID="4" UserName="User A" #hooks: 0 upnp: 0 skip: 0 v:0xd91c28/DL_USERCODE duplicate:0 <0x2b83a680>

UserB enters just after UserA.
Code: [Select]
VERA LOG:
06      02/04/16 8:04:06.376    Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 1 now: 0 #hooks: 0 upnp: 0 skip: 0 v:0xb7c810/NONE duplicate:0 <0x2b83a680>
06      02/04/16 8:04:06.378    Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_UserCode was: UserID="4" UserName="User A" now: UserID="3" UserName="UserB" #hooks: 0 upnp: 0 skip: 0 v:0xd91c28/DL_USERCODE duplicate:0

When the above happens (UserB enters after UserA), my openLuup/AltUI scene triggers... openLuup/AltUI log.
Code: [Select]
OPENLUUP/ALTUI LOG:
2016-02-04 08:16:55.418   luup_log:3: ALTUI: debug: evaluateExpression(0-10237,urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,(new ~= nil and old ~=nil),UserID="3" UserName="User B",UserID="4" UserName="User A",1454595415,1,12)
2016-02-04 08:16:55.418   luup_log:3: ALTUI: debug: _evaluateUserExpression(0-10237,urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,UserID="3" UserName="User B",UserID="4" UserName="User A",1454595415,(new ~= nil and old ~=nil))
2016-02-04 08:16:55.419   luup_log:3: ALTUI: debug: Evaluation of user watch expression returned: [true]
2016-02-04 08:16:55.419   luup_log:3: ALTUI: debug: run_scene(12)

Edit: Added clarity to my logs....

I also have still not understood what ( in wording terms ) you are trying to do.

But some additional info regarding watches in ALTUI.

The watch expression can contain predefined variables new & old so you can use new / old and compare them in your expression.  also the function trueSince(expr,sec) can test if an expr is true and remains true for x sec.
so a valid expression could be for instance:
Code: [Select]
trueSince((new == '1' and new ~= old), 10)
To properly debug watch , you need to run ALTUI in DEBUG mode and get back the logs
Title: Re: Watched Variables
Post by: oTi@ on February 04, 2016, 10:57:35 am
AFAIK it was previously established (http://forum.micasaverde.com/index.php/topic,5462.msg33504.html#msg33504) that a "Door Lock Button" event (driven by sl_LockButton?) is not functional, at least for Schlage.

I have scenes the need to know if the lock was secured from outside the house.
Don't know if this at all applies to your case, but where I'm at storm doors are very common. I detect directionality by having a sensor on both the front door and the storm door, based on timing. Perhaps combining that with a lock event in the same window is a reasonable indicator from which side of the door the event was triggered? (If that is truly what you are after.)
Title: Re: Watched Variables
Post by: CudaNet on February 04, 2016, 11:44:52 am
Interesting, I actually just installed a storm door but currently don't have a sensor on it. As for these locks, I do have Schlages and if I setup a scene on Vera, they work perfectly (lock button and user pin entered). As for a bad pin, alarm (which these locks have) etc.. I've never tried to test that. So not sure if MCV fixed the issue with the lock button prior to me buying the locks as I've never had an issue, well - at least not on an actual Vera.

AFAIK it was previously established (http://forum.micasaverde.com/index.php/topic,5462.msg33504.html#msg33504) that a "Door Lock Button" event (driven by sl_LockButton?) is not functional, at least for Schlage.

I have scenes the need to know if the lock was secured from outside the house.
Don't know if this at all applies to your case, but where I'm at storm doors are very common. I detect directionality by having a sensor on both the front door and the storm door, based on timing. Perhaps combining that with a lock event in the same window is a reasonable indicator from which side of the door the event was triggered? (If that is truly what you are after.)
Title: Re: Watched Variables
Post by: CudaNet on February 04, 2016, 11:56:18 am
@Amg0/Akbooer,

Attached are untouched logs (debug mode enabled) for both Vera and openLuup/AltUI.... Sending you both a separate email.
Title: Re: Watched Variables
Post by: amg0 on February 04, 2016, 12:23:58 pm
@Amg0/Akbooer,

Attached are untouched logs (debug mode enabled) for both Vera and openLuup/AltUI.... Sending you both a separate email.

First info, maybe unrelated but your VariablesToSend is corrupted. all watches with
Code: [Select]
undefined#undefined#undefined etc...  are corrupted you need to delete and recreate them

Then about the lua logs, what I observe is:

logs starts at 08:30
08:31 sl_UserCode changes,  watch expression is true,  Scene 12 is run
08:32 sl_UserCode changes, watch expression is true, Scene 12 is run
logs stops at 08:32


Code: [Select]
2016-02-04 08:30:41.702   luup_log:3: ALTUI: debug: _addWatch(urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,0-10237,12,(new ~= nil and old ~=nil),,,"")
2016-02-04 08:30:41.703   luup.variable_watch:3: callback=variableWatchCallback, watching=10237.urn:micasaverde-com:serviceId:DoorLock1.sl_UserCode
2016-02-04 08:30:41.703   luup_log:3: ALTUI: debug: _addWatch(urn:micasaverde-com:serviceId:DoorLock1,sl_LockButton,0-10237,16,(new=='1' and old == '1'),,,"")
2016-02-04 08:30:41.703   luup.variable_watch:3: callback=variableWatchCallback, watching=10237.urn:micasaverde-com:serviceId:DoorLock1.sl_LockButton

the Watch is properly declared in ALTUI
Code: [Select]
{
  "0-10237": {
    "urn:micasaverde-com:serviceId:DoorLock1": {
      "sl_UserCode": {
        "Expressions": {
          "(new ~= nil and old ~=nil)": [
            {
              "SceneID": 12
            }
          ]
        }
      },
      "sl_LockButton": {
        "Expressions": {
          "(new=='1' and old == '1')": [
            {
              "SceneID": 16
            }
          ]
        }
      }
    }
  }
}

But when looking at actually fired watch events:
Code: [Select]
2016-02-04 08:31:18.736   luup_log:3: ALTUI: debug: _internalVariableWatchCallback(0-10237,urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,old:'UserID="4" UserName="Monika Sapp"',new:'UserID="3" UserName="Andy Sapp"')
2016-02-04 08:31:42.912   luup_log:3: ALTUI: debug: _internalVariableWatchCallback(0-48,urn:micasaverde-com:serviceId:EnergyMetering1,Watts,old:'1682',new:'1671')
2016-02-04 08:32:07.989   luup_log:3: ALTUI: debug: _internalVariableWatchCallback(0-10237,urn:micasaverde-com:serviceId:DoorLock1,sl_UserCode,old:'UserID="3" UserName="Andy Sapp"',new:'UserID="4" UserName="Monika Sapp"')

Conclusion:
I do not see any watch being fired by VERA for sl_LockButton

now is this normal or not ?   is this because new & old have the same value ?
I do not see in the logs any luup variable set calls to set the value of sl_LockButton to be '1' anyhow.
so may that is the problem you were after ?

I suggest you debug with Lua code on UI5/UI7 just to eliminate openLuup & ALTUI from the problem.  register a watch on "sl_LockButton" and see if it is called
Title: Re: Watched Variables
Post by: CudaNet on February 04, 2016, 04:05:47 pm
Thank you Amg0,

Yes, the new and old values are the same for sl_LockButton - this being a constant of '1' each time the button is pressed. sl_UserCode 'may' also exhibit the same value only if the user enters the same pin from event 1 to event 2 and so on. The exception obviously being another user enters a different pin, this (as you've seen) triggers the scene.
Quote
Conclusion:
I do not see any watch being fired by VERA for sl_LockButton
now is this normal or not ?   is this because new & old have the same value ?

Yes, nor do I but is this attributed to the fact that the variable 'must' change in order for the event to appear within the log ? Might be a question for both you and Akbooer. I simply don't know enough about Watched Variables and the rules encompassing use.
Quote
I do not see in the logs any luup variable set calls to set the value of sl_LockButton to be '1' anyhow.
so may that is the problem you were after ?

Sorry, not sure I'm clear on how to do that as I've only ever used Watched variables within openLuup.
Quote
I suggest you debug with Lua code on UI5/UI7 just to eliminate openLuup & ALTUI from the problem.  register a watch on "sl_LockButton" and see if it is called
Title: Re: Watched Variables
Post by: CudaNet on February 05, 2016, 02:11:38 pm
OK, so I created a work around now that I "think" I fully understand a Watch variable.

Execute the following on Vera.
Code: [Select]
luup.variable_set("urn:cuda-net:serviceId:DoorLock1", "ol_UserCode", os.time(), DevId)
luup.variable_set("urn:cuda-net:serviceId:DoorLock1", "ol_LockButton", os.time(), DevId)

Instruct Vera when either the lock button is pressed or a user's PIN code is supplied, simply update the variables (in this case use os.time()).
Here is the result of a lock button press now on Vera.
Code: [Select]
06      02/04/16 20:11:37.158   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xca97f0/NONE duplicate:0 <0x2b4b2680>
06      02/04/16 20:11:37.159   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_LockButton was: 1 now: 1 #hooks: 1 upnp: 0 skip: 0 v:0xec0e98/DL_LOCK_BUTTON duplicate:0 <0x2b4b2680>
06      02/04/16 20:11:37.161   Device_Variable::m_szValue_set device: 237 service: urn:cuda-net:serviceId:DoorLock1 variable: ol_LockButton was: 1454637314 now: 1454638297 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2b4b2680>

And here is a user entering the house a second time (again on Vera).
Code: [Select]
06      02/04/16 20:13:15.548   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: Status was: 1 now: 0 #hooks: 0 upnp: 0 skip: 0 v:0xca97f0/NONE duplicate:0 <0x2b4b2680>
06      02/04/16 20:13:15.550   Device_Variable::m_szValue_set device: 237 service: urn:micasaverde-com:serviceId:DoorLock1 variable: sl_UserCode was: UserID="4" UserName="Monika Sapp" now: UserID="4" UserName="Monika Sapp" #hooks: 1 upnp: 0 skip: 0 v:0xec0518/DL_USERCODE duplicate:0 <0x2b4b2680>
06      02/04/16 20:13:15.551   Device_Variable::m_szValue_set device: 237 service: urn:cuda-net:serviceId:DoorLock1 variable: ol_UserCode was: 1454637305 now: 1454638395 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0

And here are the openLuup/AltUI logs showing the WV firing.
Code: [Select]
2016-02-04 20:11:15.345   luup_log:3: ALTUI: debug: -----> evaluateExpression() {"(new~= old)":[{"SceneID":16}]}
2016-02-04 20:11:15.346   luup_log:3: ALTUI: debug: evaluateExpression(0-10237,urn:cuda-net:serviceId:DoorLock1,ol_LockButton,(new~= old),1454637314,1454638297,1454638275,1,16)
2016-02-04 20:11:15.346   luup_log:3: ALTUI: debug: _evaluateUserExpression(0-10237,urn:cuda-net:serviceId:DoorLock1,ol_LockButton,1454637314,1454638297,1454638275,(new~= old))
2016-02-04 20:11:15.346   luup_log:3: ALTUI: debug: Evaluation of user watch expression returned: [true]
2016-02-04 20:11:15.346   luup_log:3: ALTUI: debug: run_scene(16)
2016-02-04 20:11:15.346   luup.call_action:3: 0.urn:micasaverde-com:serviceId:HomeAutomationGateway1.RunScene
2016-02-04 20:11:15.347   luup_log:0: >>>>>>> Executing Scene [16] via remote action. <<<<<<<

--

2016-02-04 20:12:58.528   luup_log:3: ALTUI: debug: -----> evaluateExpression() {"(new ~= old)":[{"SceneID":12}]}
2016-02-04 20:12:58.528   luup_log:3: ALTUI: debug: evaluateExpression(0-10237,urn:cuda-net:serviceId:DoorLock1,ol_UserCode,(new ~= old),1454637305,1454638395,1454638378,1,12)
2016-02-04 20:12:58.529   luup_log:3: ALTUI: debug: _evaluateUserExpression(0-10237,urn:cuda-net:serviceId:DoorLock1,ol_UserCode,1454637305,1454638395,1454638378,(new ~= old))
2016-02-04 20:12:58.529   luup_log:3: ALTUI: debug: Evaluation of user watch expression returned: [true]
2016-02-04 20:12:58.529   luup_log:3: ALTUI: debug: run_scene(12)
2016-02-04 20:12:58.529   luup.call_action:3: 0.urn:micasaverde-com:serviceId:HomeAutomationGateway1.RunScene
2016-02-04 20:12:58.529   luup_log:0: >>>>>>> Executing Scene [12] via remote action. <<<<<<<

Thanks to everyone who contributed to this discussion. I realize reading thanks over and over has a numbing effect on some, but I actually really do appreciate everyone's commitment to helping others. For those that might ask why I didn't just do this earlier (yes, my wife asked me this), it was simply because I wanted to understand everything I could regarding Watched Variables and why I couldn't make this work. This might be common knowledge for some and obvious for others but I simply needed to understand and learn.

So this solution (I'm sure one of many) required me to use Vera ... Which, honestly, I'm trying to avoid at every and all costs, so I do hope that explains my persistence...