Luup.variable_watch - what am I missing?

Hi, I was trying to make use of luup.variable_watch, against a virtual switch, but I must be missing something - please could someone look at the following code and let me know what’s wrong? .

function watchCallBackTest (lul_device, lul_service, lul_variable, lul_value_old, lul_value_new) 
	require "xxprowlnotification"
	local a = lul_service or "nothing"
	local b = lul_variable or "nothing"
	local c = lul_value_old or "nothing"
	local d = lul_device or "nothing"
	local e = lul_value_new or "nothing"
	
	xxprowlnotification.my_prowl ("VeraPlus Testing", "Watch Callback Test", "Callback information equals " ..a.." , " ..b.. " , " ..c.." , " ..d.. " , " ..e.. ".")
	end

luup.variable_watch ('watchCallBackTest', "urn:upnp-org:serviceId:SwitchPower1", "Status", 60)
luup.variable_watch ('watchCallBackTest', "urn:upnp-org:serviceId:SwitchPower1", "Target", 60)

The log shows the variable changing, but there is no response - the function is not called…

01 10/27/20 22:48:03.621 JobHandler_LuaUPnP::REQ_VariableGet variable not found <0x73394520>
08 10/27/20 22:48:03.624 JobHandler_LuaUPnP::HandleActionRequest device: 60 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x738bd520>
08 10/27/20 22:48:03.624 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=60 <0x738bd520>
08 10/27/20 22:48:03.624 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x738bd520>
08 10/27/20 22:48:03.624 JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x738bd520>
08 10/27/20 22:48:03.625 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x738bd520>
08 10/27/20 22:48:03.625 JobHandler_LuaUPnP::HandleActionRequest argument rid=86 <0x738bd520>
06 10/27/20 22:48:03.625 Device_Variable::m_szValue_set device: 60 service: urn:upnp-org:serviceId:SwitchPower1 variable: Target was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xa73308/NONE duplicate:0 <0x738bd520>
06 10/27/20 22:48:03.626 Device_Variable::m_szValue_set device: 60 service: urn:upnp-org:serviceId:VSwitch1 variable: Target was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x738bd520>
06 10/27/20 22:48:03.627 Device_Variable::m_szValue_set device: 60 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xa72180/NONE duplicate:0 <0x738bd520>
06 10/27/20 22:48:03.627 Device_Variable::m_szValue_set device: 60 service: urn:upnp-org:serviceId:VSwitch1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x738bd520>
01 10/27/20 22:48:03.639 JobHandler_LuaUPnP::REQ_VariableGet variable not found <0x73ae3520>
06 10/27/20 22:48:04.116 Device_Variable::m_szValue_set device: 52 service: urn:demo-ted-striker:serviceId:PingSensor1 variable: CurrentFailureCount was: 0 now: 0 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x75724520>
01 10/27/20 22:48:05.122 JobHandler_LuaUPnP::REQ_VariableGet variable not found <0x738bd520>
01 10/27/20 22:48:06.756 JobHandler_LuaUPnP::REQ_VariableGet variable not found <0x738bd520>

Hi,

You could put a luup.log statement in the watch function to see if that is not called or the my_prowl is the problem. Have you tried that?

Also where did you put the code? You cannot put in in a Scene for example. It should be part of a plugin or in the startup code.

Cheers Rene

Hi @reneboer

Thanks for responding.

The function works fine when I call it on its own, plus I’ve added actions into the function too, like turning lights on or off, but for some reason the function is never called when the variable being watched changes.

Sorry I should have said, yes the code is in Lua Startup…

I’m wondering - Is there a way to see what variables are being watched , so I know that it’s been registered, and if not what am I missing , what could be wrong that stops it being registered/called.

It’s a weird one … :thinking:

Try this:
_G.watchCallBackTest = watchCallBackTest

Thanks @tinman, sadly that didnt seem to make any difference.

Could these errors mean anything ?

JobHandler_LuaUPnP::REQ_VariableGet variable not found

Turning on verbose, it adds other aspects, but I’m still none the wiser

Anyone able to work out what the issue is?

10 10/28/20 23:09:28.965 GlobalLog: mongoose get_socket2: 0xf951d8 idle: 2 threads: 7 max: 100 head: 14 tail: 13 s: d:12388 <0x73e8d520>
10 10/28/20 23:09:28.966 GlobalLog: mongoose get_socket3: 0xf951d8 idle: 2 threads: 7 max: 100 head: 14 tail: 14 s: d:12388 <0x73e8d520>
10 10/28/20 23:09:28.966 GlobalLog: mongoose ctx: 0xf951d8 idle: 2 threads: 7 max: 100 pthread_self: 1944638752 s: d:12388 <0x73e8d520>
10 10/28/20 23:09:28.967 mg_callback from IP:127.0.0.1:42779 /port_3480/data_request id=variableget&Variable=mode_change_time start id: 394 <0x73e8d520>
12 10/28/20 23:09:28.967 luvd_get_info_data_request starting /data_request?id=variableget&Variable=mode_change_time pMem 0x1728000/24281088 diff: 9261056 <0x73e8d520>
10 10/28/20 23:09:28.967 JobHandler_LuaUPnP::HandleRequest id variableget request pMem 0x1728000/24281088 diff: 9261056 <0x73e8d520>
01 10/28/20 23:09:28.968 JobHandler_LuaUPnP::REQ_VariableGet variable not found <0x73e8d520>
10 10/28/20 23:09:28.968 luvd_get_info_data_request creating file buffer /data_request?id=variableget&Variable=mode_change_time pMem 0x1728000/24281088 diff: 9261056 <0x73e8d520>
10 10/28/20 23:09:28.969 luvd_get_info_data_request done /data_request?id=variableget&Variable=mode_change_time ret 0 size 25 pMem 0x1728000/24281088 diff: 9261056 took 0 info (nil) <0x73e8d520>
10 10/28/20 23:09:28.970 mg_callback /data_request stop id: 394 <0x73e8d520>
10 10/28/20 23:09:28.966 GlobalLog: mongoose put_socket: idle: 2 threads: 7 max: 100 s: d:12388 <0x7408d520>
10 10/28/20 23:09:28.977 GlobalLog: mongoose get_socket: 0xf951d8 idle: 2 threads: 7 max: 100 head: 15 tail: 14 s: d:12388 <0x73e8d520>
10 10/28/20 23:09:28.977 GlobalLog: mongoose get_socket2: 0xf951d8 idle: 2 threads: 7 max: 100 head: 15 tail: 14 s: d:12388 <0x73e8d520>
10 10/28/20 23:09:28.977 GlobalLog: mongoose get_socket3: 0xf951d8 idle: 2 threads: 7 max: 100 head: 15 tail: 15 s: d:12388 <0x73e8d520>
10 10/28/20 23:09:28.977 GlobalLog: mongoose ctx: 0xf951d8 idle: 2 threads: 7 max: 100 pthread_self: 1944638752 s: d:12388 <0x73e8d520>
10 10/28/20 23:09:28.978 mg_callback from IP:127.0.0.1:42780 /port_3480/data_request id=action&DeviceNum=60&serviceId=urn:upnp-org:serviceId:SwitchPower1&action=SetTarget&newTargetValue=1&rid=71 start id: 395 <0x73e8d520>
12 10/28/20 23:09:28.978 luvd_get_info_data_request starting /data_request?id=action&DeviceNum=60&serviceId=urn:upnp-org:serviceId:SwitchPower1&action=SetTarget&newTargetValue=1&rid=71 pMem 0x1728000/24281088 diff: 9261056 <0x73e8d520>
10 10/28/20 23:09:28.979 JobHandler_LuaUPnP::HandleRequest id action request pMem 0x1728000/24281088 diff: 9261056 <0x73e8d520>
10 10/28/20 23:09:28.979 sbrk JobHandler_LuaUPnP::HandleActionRequest Problem with getnameinfo <0x73e8d520>
08 10/28/20 23:09:28.979 JobHandler_LuaUPnP::HandleActionRequest device: 60 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x73e8d520>
08 10/28/20 23:09:28.980 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=60 <0x73e8d520>
08 10/28/20 23:09:28.980 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x73e8d520>
08 10/28/20 23:09:28.980 JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x73e8d520>
08 10/28/20 23:09:28.980 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x73e8d520>
08 10/28/20 23:09:28.980 JobHandler_LuaUPnP::HandleActionRequest argument rid=71 <0x73e8d520>
35 10/28/20 23:09:28.981 JobHandler_LuaUPnP::ConfirmGlobalActionRules start <0x73e8d520>
06 10/28/20 23:09:28.981 Device_Variable::m_szValue_set device: 60 service: urn:upnp-org:serviceId:SwitchPower1 variable: Target was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xfbf678/NONE duplicate:0 <0x73e8d520>
10 10/28/20 23:09:28.981 UserData::m_iDataVersion_Variables_incr Target user data 926358005 variables 926358178 <0x73e8d520>
10 10/28/20 23:09:28.982 UserData::DataIsDirty UpdateStateList was 1 incr 0 user data 926358005 variables 926358178 <0x73e8d520>
10 10/28/20 23:09:28.988 AlarmManager::AddRelativeAlarm current time 1603926568 delay 0 type 45 <0x73e8d520>
10 10/28/20 23:09:28.988 AlarmManager::AddAbsoluteAlarm alarm 0xe55008 entry 0x1416980 id 308 type 45 param=(nil) entry->when: 1603926568 time: 1603926568 bCancelFirst 0=0 <0x73e8d520>
31 10/28/20 23:09:28.989 AlarmManager::Run 0xe55008 notified of a change entry 0x16c5418 id 266 deleted 0 <0x774ce520>
31 10/28/20 23:09:28.989 AlarmManager::Run 0xe55008 notified of a change entry 0x1245990 id 307 deleted 0 <0x772ce520>
31 10/28/20 23:09:28.989 AlarmManager::Run callback for alarm 0xe55008 entry 0x1416980 type 45 id 308 param=(nil) entry->when: 1603926568 time: 1603926568 tnum: 1 slow 0 tardy 0 <0x772ce520>
31 10/28/20 23:09:28.990 AlarmManager::Run finish callback for alarm 0xe55008 entry 0x1416980 type 45 id 308 param=(nil) entry->when: 1603926568 time: 1603926568 tnum: 1 slow 0 duration 0 <0x772ce520>
06 10/28/20 23:09:28.989 Device_Variable::m_szValue_set device: 60 service: urn:upnp-org:serviceId:VSwitch1 variable: Target was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73e8d520>
10 10/28/20 23:09:29.008 luvd_get_info_data_request creating file buffer /data_request?id=status&LoadTime=1603926358&DataVersion=926358177&Timeout=50&MinimumDelay=1500 pMem 0x1728000/24281088 diff: 9261056 <0x73c8d520>
10 10/28/20 23:09:29.010 UserData::m_iDataVersion_Variables_incr Target user data 926358005 variables 926358179 <0x73e8d520>
10 10/28/20 23:09:29.010 UserData::DataIsDirty UpdateStateList was 1 incr 0 user data 926358005 variables 926358179 <0x73e8d520>
10 10/28/20 23:09:29.010 AlarmManager::AddRelativeAlarm current time 1603926569 delay 0 type 45 <0x73e8d520>

Hi

Any other ideas? I’m completely flummoxed?

@reneboer earlier suggested that you add a luup.log() statement in the watch function. This is the way. You need to add it as the first line, before the require. The require is the riskiest statement in the bunch and could be failing, so everything after is not being executed, including all the other actions you tried to make it do. I would follow his suggestion, being careful as I said to make the log statement be the first thing it does.

Then, if you see the log message emitted to the log, you know (a) the callback is working, and (b) something else, possibly the require, is not. Let’s take it one step at a time and see if you can make the log statement work first.

Many thanks,

I have moved the luup.log to the very top, plus added a few more variables to the watch list - but it seems to have made no difference, the updated code is below and the logs show the following…


function watchCallBackTest (lul_device, lul_service, lul_variable, lul_value_old, lul_value_new) 
	luup.log("watchCallBackTest function called")
	local a = lul_service or "nothing"
	local b = lul_variable or "nothing"
	local c = lul_value_old or "nothing"
	local d = lul_device or "nothing"
	local e = lul_value_new or "nothing"
	
	luup.log("watchCallBackTest function called")
	require "xxprowlnotification"
	xxprowlnotification.my_prowl ("VeraPlus Testing", "Watch Callback Test", "Callback information equals " ..a.." , " ..b.. " , " ..c.." , " ..d.. " , " ..e.. ".")
	end

luup.variable_watch ('watchCallBackTest', "urn:upnp-org:serviceId:SwitchPower1", "Status", 60)
luup.variable_watch ('watchCallBackTest', "urn:upnp-org:serviceId:SwitchPower1", "Target", 60)
luup.variable_watch ('watchCallBackTest', "urn:upnp-org:serviceId:VSwitch1", "Status", 60)
luup.variable_watch ('watchCallBackTest', "urn:upnp-org:serviceId:VSwitch1", "Target", 60)

|01|10/31/20 0:04:15.219|JobHandler_LuaUPnP::REQ_VariableGet variable not found <0x7367b520>|
|08|10/31/20 0:04:15.220|JobHandler_LuaUPnP::HandleActionRequest device: 60 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x7327b520>|
|08|10/31/20 0:04:15.221|JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=60 <0x7327b520>|
|08|10/31/20 0:04:15.221|JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x7327b520>|
|08|10/31/20 0:04:15.221|JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x7327b520>|
|08|10/31/20 0:04:15.221|JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x7327b520>|
|08|10/31/20 0:04:15.222|JobHandler_LuaUPnP::HandleActionRequest argument rid=18 <0x7327b520>|
|06|10/31/20 0:04:15.223|Device_Variable::m_szValue_set device: 60 service: urn:upnp-org:serviceId:SwitchPower1 variable: Target was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0x119edb8/NONE duplicate:0 <0x7327b520>|
|06|10/31/20 0:04:15.223|Device_Variable::m_szValue_set device: 60 service: urn:upnp-org:serviceId:VSwitch1 variable: Target was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7327b520>|
|06|10/31/20 0:04:15.234|Device_Variable::m_szValue_set device: 60 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0x119dbc0/NONE duplicate:0 <0x7327b520>|
|06|10/31/20 0:04:15.235|Device_Variable::m_szValue_set device: 60 service: urn:upnp-org:serviceId:VSwitch1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7327b520>|

OK, let’s hit the obvious stuff…

First of all, are you reloading Luup after every time you change the code? It is, after all, startup Lua… so it will only be re-parsed/executed at startup. You can make sure that’s going well by adding a luup.log() statement at the start and end of the code, each with different strings (e.g. “START STARTUPLUA” and “END STARTUPLUA”). You should be able to restart Luup, and at then go look at the LuaUPnP log file and find at least the output of the first luup.log() statement’s output (e.g. “START STARTUPLUA”). From there, follow the log output and see if there are errors logged, or if you get the final luup.log() statement’s output. If you have errors, fix what is indicated by the errors.

Ok, let’s do this… :grin:

As I’ve got this code in LuaStartup, doesn’t the act of hitting ‘Go’ after i’ve made a change reload luup ?

Like it, will do.

Interesting, I’ve just seen this, does this have potential ?

0	10/31/20 1:10:46.541	luup_log:0: STARTSTARTUPLUA <0x76a32520>
01	10/31/20 1:10:47.293	LuaInterface::StartEngine failed run: 0 [string "function scene_3()..."]:117: attempt to call field 'cifsmount' (a nil value) <0x76a32520>
01	10/31/20 1:10:47.303	<0x1b>[31;1mJobHandler_LuaUPnP::AlarmCallback EXECUTE_GLOBAL_LUA failed:
function scene_3()
function cabinTVOn()
     luup.call_action('urn:a-lurker-com:serviceId:IrTransmitter1', 'SendProntoCode', {ProntoCode = '0000 006C 0000 0022 00AD 00AD 0016 0041 0016 0041 0016 0041 0016 0016 0016 0016 0016 0016 0016 0016 0016 0016 0016 0041 0016 0041 0016 0041 0016 0016 0016 0016 0016 0016 0016 0016 0016 0016 0016 0016 0016 0041 0016 0016 0016 0016 0016 0016 0016 0016 0016 0016 0016 0016 0016 0041 0016 0016 0016 0041 0016 0041 0016 0041 0016 0041 0016 0041 0016 0041 0016 06FB'},49)
 end

 luup.call_delay("cabinTVOn",2)
end
function scene_4()

I checked under Lua (in LuaView) and there are no errors or warnings.

OK, so in one of your scenes… cifsmount… go hunting! LuaView is built for this… remember LuaView only finds syntax errors, not runtime errors (e.g. a module that can’t be loaded, reference to a device that doesn’t exist, etc.).

One of the horrid things Vera does at startup is it combines all the Lua from all of your scenes, plus the startup Lua, into one big code block, and then executes that. If you have an error in any scene Lua or startup Lua, it blows up everything (probably why your startup Lua is failing then). And then they only show the error, but not the entire block, so it makes it really hard to isolate the code (the line number shown is meaningless, for example, because it’s relative to the block, which you cannot see).

But if you find that string “cifsmount”, you’re in the hot zone for the problem here…

1 Like

Many Thanks @rigpapa,

That did it ! :partying_face:

I’ve just added ‘ - -‘ to the beginning of that line for now to try and work out what it was causing an error, especially as it had been working fine for ages.

QQ: when using modules, and wanting to call functions stored within them from luastartup - do they need to be global functions in the module ?

The luastartup code is …

require "xxcifsmount"
xxcifsmount.cifsmount()

The upload file is called xxcifsmount.lua

module("xxcifsmount", package.seeall)

local function cifsmount()

Awesome! By the way, together with that error you should have seen a “Error in Lua for Scenes and Events” or something to that effect in your UI, even before you started this particular effort. If you’re not seeing those messages, you may want to turn them on in the notification settings or by running this:

luup.attr_set( "adv_status_message", "1", 0 )
luup.reload()

The function is declared local, so it will not be accessible outside the module in which it is declared. Remove that local keyword to make a function you can access from outside the module.

Well, they’re not “global” in the real sense, they have “module scope”, which is to say, they appear to be global within the module, but if you want to access them from outside the module, you need to qualify them with the scope. When you do a require, you get a table with the module name… you require "xxcifsmount" and you get a table called “xxcifsmount” through which you can access the function: xxcifsmount.cifsmount( arguments ). So the “xxcifsmount” table is your scope qualifier.

Thanks so much @rigpapa .

For some reason I never received/saw an “ Error in Lua for Scenes and Event’ message