luup/lua engine crashes with deadlock error everytime a scene is run

sjolshagen · December 18, 2011, 9:51pm

Running on a Vera2 with UI5 (1.5.236).

I’ve got a scene that runs every couple of minutes to make sure the dimmable lights in my house is set at 80%. Sometime over the past couple of days, this scene appears to be causing some sort of deadlock problem (has not happened before) on my Vera2. This causes the Luup engine to restart and I have the resulting issues (UI awaiting server restart, etc). It also appears to happen every time a scene is run.

Are there more UI5 bugs that have crop’ed up in the past couple of days that I’ve not noticed which could be at the root of this?

07	12/16/11 3:17:24.165	Event::Evaluate 3 LR Ceiling Lights - On scene 1st: Lights on (Heat) is true <0x803>
08	12/16/11 3:17:24.166	Scene::RunScene running 57 1st: Lights on (Heat) <0x803>
01	12/16/11 3:17:54.000	Failed to get lock(0x76a87c) Lua: LuaInterface.cpp:1732 last used LuaInterface.cpp:1823  first used LuaInterface.cpp:1823  thread: 0x402 (>12466)  handler 0x422ac0 bOkToFail 0 <0x803>
02	12/16/11 3:17:54.075	Dumping 9 locks <0x803>
02	12/16/11 3:17:54.076	finished check for exceptions <0x803>
02	12/16/11 3:17:54.076	finished check for exceptions <0x803>
02	12/16/11 3:17:54.077	finished check for exceptions <0x803>
02	12/16/11 3:17:54.078	OL: (0x76a7c8) (>7892) ThreadedClass ../JobHandler/JobHandler.cpp l:394 time: 7:00:00p (1324023474 s) thread: 0x400 Rel: Y Got: Y <0x803>
02	12/16/11 3:17:54.078	finished check for exceptions <0x803>
02	12/16/11 3:17:54.079	OL: (0xbcd0c0) (>12157) ThreadedClass ../JobHandler/JobHandler.cpp l:394 time: 7:00:00p (1324023474 s) thread: 0xc04 Rel: Y Got: Y <0x803>
02	12/16/11 3:17:54.079	finished check for exceptions <0x803>
02	12/16/11 3:17:54.080	OL: (0xbcd0c0) (>12163) ThreadedClass ../ZWave/ZWaveJobHandler.cpp l:771 time: *****DL******3:17:24a (30 s) thread: 0x803 Rel: N Got: Y <0x803>
02	12/16/11 3:17:54.081	finished check for exceptions <0x803>
02	12/16/11 3:17:54.082	OL: (0x76a838) (>12165) Variable Device_Basic.cpp l:336 time: 3:17:24a (30 s) thread: 0x803 Rel: Y Got: Y <0x803>
02	12/16/11 3:17:54.082	finished check for exceptions <0x803>
02	12/16/11 3:17:54.083	OL: (0x76a87c) (>12169) Lua LuaInterface.cpp l:1732 time: 3:17:24a (30 s) thread: 0x803 Rel: N Got: N <0x803>
02	12/16/11 3:17:54.084	finished check for exceptions <0x803>
02	12/16/11 3:17:54.084	OL: (0x76a838) (>12459) Variable JobHandler_LuaUPnP.cpp l:6583 time: 7:00:00p (1324023474 s) thread: 0x4008 Rel: Y Got: Y <0x803>
02	12/16/11 3:17:54.085	finished check for exceptions <0x803>
02	12/16/11 3:17:54.085	OL: (0x76a87c) (>12466) Lua LuaInterface.cpp l:1823 time: 3:17:48a (6 s) thread: 0x402 Rel: N Got: Y <0x803>
01	12/16/11 3:17:54.086	Deadlock problem. going to reload and quit <0x803>
03	12/16/11 3:17:54.087	JobHandler_LuaUPnP::Reload: deadlock Critical 1 m_bCriticalOnly 0 dirty data 1 <0x803>
06	12/16/11 3:17:58.535	Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusID was: 1 now: 2 #hooks: 0 upnp: 0 v:0xb499c0/NONE duplicate:0 <0x803>
06	12/16/11 3:17:58.537	Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusText was: OK now: Resetting ZWave Network #hooks: 0 upnp: 0 v:0xb68fd8/NONE duplicate:0 <0x803>
01	12/16/11 3:18:01.440	Main WatchDogRoutine: blocked - terminating 1 <0x440e>
02	12/16/11 3:18:01.444	Dumping 7 locks <0x440e>
02	12/16/11 3:18:01.445	finished check for exceptions <0x440e>
02	12/16/11 3:18:01.445	finished check for exceptions <0x440e>
02	12/16/11 3:18:01.446	OL: (0x76a7c8) (>7892) ThreadedClass ../JobHandler/JobHandler.cpp l:394 time: 7:00:00p (1324023481 s) thread: 0x400 Rel: Y Got: Y <0x440e>
02	12/16/11 3:18:01.447	finished check for exceptions <0x440e>
02	12/16/11 3:18:01.447	OL: (0xbcd0c0) (>12157) ThreadedClass ../JobHandler/JobHandler.cpp l:394 time: 7:00:00p (1324023481 s) thread: 0xc04 Rel: Y Got: Y <0x440e>
02	12/16/11 3:18:01.448	finished check for exceptions <0x440e>
02	12/16/11 3:18:01.448	OL: (0xbcd0c0) (>12163) ThreadedClass ../ZWave/ZWaveJobHandler.cpp l:771 time: *****DL******3:17:24a (37 s) thread: 0x803 Rel: N Got: Y <0x440e>
02	12/16/11 3:18:01.449	finished check for exceptions <0x440e>
02	12/16/11 3:18:01.450	OL: (0x76a838) (>12165) Variable Device_Basic.cpp l:336 time: 3:17:24a (37 s) thread: 0x803 Rel: Y Got: Y <0x440e>
02	12/16/11 3:18:01.451	finished check for exceptions <0x440e>
02	12/16/11 3:18:01.451	OL: (0x76a87c) (>12169) Lua LuaInterface.cpp l:1732 time: 3:17:24a (37 s) thread: 0x803 Rel: N Got: N <0x440e>
02	12/16/11 3:18:01.452	finished check for exceptions <0x440e>
02	12/16/11 3:18:01.452	OL: (0xbcd0c0) (>12497) ThreadedClass ThreadedClass.cpp l:49 time: 3:17:58a (3 s) thread: 0x803 Rel: Y Got: Y <0x440e>


2011-12-16 03:18:01 - LuaUPnP Terminated with Exit Code: 137



2011-12-16 03:18:01 - LuaUPnP crash

guessed · December 18, 2011, 10:06pm

If something in the Scene logic takes longer than 30s to run, Vera (currently) assumes that it’ll never come backhand it restarts the LuaUPnP engine.

Can you paste the Lua code of what you’re doing?

I’d also recommend turning on verbose logging, causing it to occur and then opening a formal ticket for the problem to help build the case.

sjolshagen · December 18, 2011, 11:25pm

Thanks @guessed!

Not sure I understand how this can take >30 seconds, but anything is possible Will try to get the time to turn on verbose logging, etc. As all, time is at a premium

-- Stored in Startup
function logMsg(message, l_dbg)
    local showDBG = l_dbg or 0
    local logTxt
    if ((showDBG == 1))
    then
    	logTxt = "Debug: "
    	logTxt = logTxt .. message
    	luup.log(logTxt)
    end
end
-- Returns the Dimmer value that the device is set to
function dimmerStrength(ID)
  logMsg("Checking Dimmer level for: " .. tostring(ID), global_enableDebugging)
  local str_devURN = luup.devices[tonumber(ID)].device_type
  logMsg("Collected URN: " .. str_devURN, global_enableDebugging)
  str_devURN = convertNewURN{ devURN=str_devURN, dimmerStats=true }
  logMsg("Checking the setting for (" .. ID .. ") with URN: " .. str_devURN, global_enableDebugging)
  local d_Strength = luup.variable_get(str_devURN, "LoadLevelStatus", ID) or 0
  logMsg("Value for (" .. tostring(ID) ..") is: " .. tostring(d_Strength), global_enableDebugging)
  return d_Strength
end-- Checks whether or not to permit changing/running of heat scenes

-- Convert the URN for getting the level of a dimmer:
function convertNewURN( options )
   -- Grab arguments
   devURN = options.devURN
   dimmerStats = options.dimmerStats or false

   logMsg("Original URN: " .. devURN, global_enableDebugging)
   -- Check if we're looking for the Dimmer Stats
   if (dimmerStats ~= false)
   then
      if (devURN:find('DimmableLight') ~= nil)
      then
            logMsg("Converting to the correct Dimmer URN", global_enableDebugging)
            devURN = string.gsub(devURN, 'device', 'service')
            devURN = string.gsub(devURN, 'DimmableLight', 'Dimming')
      end -- if
   end -- if
   if (devURN:find('BinaryLight') ~= nil)
   then
            logMsg("Converting a BinaryLight URN", global_enableDebugging)
            devURN = string.gsub(devURN, 'device', 'service')
            devURN = string.gsub(devURN, 'BinaryLight', 'SwitchPower')
   elseif (devURN:find('Dimmable') ~= nil)
   then
            logMsg("Converting a Dimmer URN", global_enableDebugging)
            devURN = string.gsub(devURN, 'device', 'service')
            devURN = string.gsub(devURN, 'DimmableLight', 'SwitchPower')
   end -- if
   devURN = string.gsub(devURN, '(%a+):(%a+%-)(%a+)%-(%a+):(%a+):(%a+):(%d)', '%1:%3-%4:%5Id:%6%7')
   logMsg("Converted URN: " .. devURN, global_enableDebugging)
   return devURN
end -- function

-- -----------------------------
-- -----------------------------

-- Scene specific luup/lua
-- Used to manage the dimmable lights
local lvl
local lights = {
      devID_1stHallwayLights,
      devID_2ndMasterBedroomLanterns,
      devID_1stKitchenIslandLights,
      devID_1stLivingroomCeilingLights,
      devID_BasementHallwayLights,
      devID_BasementCeilingLights,
      devID_BasementTo1stStairLights,
      devID_1stSWCornerLamp
}
-- Iterate through the list of Dimmable lights and lower them to 80% of full power
-- But only if the lights are currently set to > 80%. If not, leave it alone.
for key, value in pairs(lights)
do
  logMsg("Processing light w/Device ID of: " .. value, global_enableDebugging)
   -- Iterate through the lights and set them to 80% of full power
  local lvl = tonumber(dimmerStrength(value))
  logMsg("Light level for #: " .. tostring(value) .. " is at " .. tostring(lvl) .. " percent", global_enableDebugging)
  if ( lvl > 80)
  then
      logMsg("Dimming light (" .. tostring(value) .. ") to 80%", global_enableDebugging)
      luup.call_action("urn:upnp-org:serviceId:Dimming1","SetLoadLevelTarget",{ newLoadlevelTarget = "80" }, value)
  end
end

guessed · December 18, 2011, 11:35pm

Two things:

a) I don’t see any of your log messages in the log output above
So it’s not clear how much (if any?) of your code is actually running, but I’m going on these log lines showing a 30s time difference before hand detection kicks in:

07 12/16/11 3:17:24.165 Event::Evaluate 3 LR Ceiling Lights - On scene 1st: Lights on (Heat) is true <0x803> 08 12/16/11 3:17:24.166 Scene::RunScene running 57 1st: Lights on (Heat) <0x803> 01 12/16/11 3:17:54.000 Failed to get lock(0x76a87c) Lua: LuaInterface.cpp:1732 last used LuaInterface.cpp:1823 first used LuaInterface.cpp:18

b) Don’t forget to file a Verbose logging enabled trouble ticket against MiOS
There are a bunch of these going on for different people, and we’re all trying to get test cases to MCV for a “real” fix for whatever the root problem is.

sjolshagen · December 19, 2011, 3:46am

I’m being a bad community member right now… Took the hit and downgraded to UI4 again. Once I feel more confident that UI5 meets my needs, I’ll move back up again. But for now, having a consistently functional house is more important to the wife than my desire/preference for tinkering.

frichter09 · May 11, 2012, 4:40pm

Did you ever figure this out?
I can reproduce this by installing the ERGY plugin.
Removing the plugin helps… no more restarts at all…

Unbelievable…
\Flo