Help with logs, Deadlock Critical & luup Reload

Community Playground Scenes & Automations
,
#1

So i occasionally have a luup reload when i run a scene, i occasionally see

03	01/08/20 21:15:27.091	JobHandler_LuaUPnP::Reload: deadlock Critical 1 m_bCriticalOnly 0 dirty data 1 running 1 <0x74517520>`

01	01/08/20 21:15:27.005	Failed to get lock(0x17fd954) Lua: LuaInterface.cpp:2144 last used LuaInterface.cpp:2556  first used LuaInterface.cpp:2556  thread: 0x74517520 (>26037100)  handler 0x44d114 bOkToFail 0 <0x6cdb2520>

01 01/08/20 21:14:15.610 LuaInterface::CallFunction_Variable func: w_switch Device_Variable 517 urn:micasaverde-com:serviceId:EnergyMetering1:Watts failed [string "..."]:14: bad argument #1 to 'sub' (string expected, got nil)

I get these a lot

|01|01/08/20 20:31:30.989|eLuaInterface::CallFunction_Variable func: w_switch Device_Variable 626 urn:micasaverde-com:serviceId:EnergyMetering1:Watts failed [string "..."]:14: bad argument #1 to 'sub' (string expected, got nil)e <0x77317520>|
|---|---|---|
|01|01/08/20 20:31:38.976|eLuaInterface::CallFunction_Variable func: w_switch Device_Variable 620 urn:upnp-org:serviceId:TemperatureSensor1:CurrentTemperature failed [string "..."]:14: bad argument #1 to 'sub' (string expected, got nil)e <0x71517520>|
|01|01/08/20 20:31:38.977|eLuaInterface::CallFunction_Variable func: w_switch Device_Variable 620 urn:upnp-org:serviceId:TemperatureSensor1:CurrentTemperature failed [string "..."]:14: bad argument #1 to 'sub' (string expected, got nil)e <0x71517520>|
|01|01/08/20 20:31:38.992|eLuaInterface::CallFunction_Variable func: w_switch Device_Variable 623 urn:micasaverde-com:serviceId:HumiditySensor1:CurrentLevel failed [string "..."]:14: bad argument #1 to 'sub' (string expected, got nil)e <0x71517520>|
|01|01/08/20 20:31:38.996|eLuaInterface::CallFunction_Variable func: w_switch Device_Variable 616 urn:upnp-org:serviceId:TemperatureSensor1:CurrentTemperature failed [string "..."]:14: bad argument #1 to 'sub' (string expected, got nil)e <0x71517520>|
|01|01/08/20 20:31:38.997|eLuaInterface::CallFunction_Variable func: w_switch Device_Variable 616 urn:upnp-org:serviceId:TemperatureSensor1:CurrentTemperature failed [string "..."]:14: bad argument #1 to 'sub' (string expected, got nil)e <0x71517520>|
|01|01/08/20 20:31:48.613|eLuaInterface::CallFunction_Variable func: w_switch Device_Variable 184 urn:micasaverde-com:serviceId:EnergyMetering1:Watts failed [string "..."]:14: bad argument #1 to 'sub' (string expected, got nil)e <0x77317520>|
|01|01/08/20 20:31:48.813|eLuaInterface::CallFunction_Variable func: w_switch Device_Variable 676 urn:micasaverde-com:serviceId:EnergyMetering1:Watts failed [string "..."]:14: bad argument #1 to 'sub' (string expected, got nil)e <0x77317520>|
|01|01/08/20 20:31:55.162|eLuaInterface::CallFunction_Variable func: w_switch Device_Variable 184 urn:micasaverde-com:serviceId:EnergyMetering1:Watts failed [string "..."]:14: bad argument #1 to 'sub' (string expected, got nil)e <0x77317520>|
|24|01/08/20 20:31:55.202|ZWaveNode::m_bLastContactFailed_set device 184 = 0, force 0, m_bNotListening 0 zw poll3 <0x77317520>|

Attached is an export of the logs
logs.zip (9.0 KB)

#2

I hate deadlocks. But they are relatively easy to understand, and there are a number of posts here about troubleshooting them. The way to get started is to look back in the log 30 seconds before the deadlock message - essentially what happens is the z-wave network does not respond timely and after 30 seconds the Vera code declares a deadlock and issues the reload. This is often an issue with multiple z-wave commands being sent at the same time, and if three get queued up, a deadlock is very likely…The deadlock message should be on the same thread as the device causing the deadlock.

Now in your log, following the 0x6cdb2520 and 0x74517520 threads, it looks like you need to look back 60 seconds (maybe Vera Controls changed to 60 seconds in a recent firmware). I don’t have more time to look at this now, but I do think I see at least two simultaneous jobs at 21:14:27, followed by the deadlock causing “Failed to get lock” at 21:15:27.

#3

Do you have a function called w_switch defined in your Startup Lua?

#4

nope deen seeing that for aa long time dont know what that is

#5

You need to dig in through your plugin code and find it, then. FWIW, it’s not a name I use in any of my plugins.