Debugging options ? (device turns itself off)

are there any other helpers out there to debug some things ?

i recently spend quite some time to figoure out why 1 light keeps going off …
with alot of luup this is kind of difficult since the log does not reveal the part does execute it.

any suggestions ?

would also help in getting things more organised as well

Add lots of calls to luup.log to your luup code.

Or start moving over to PLEG … It’s Status report provides lots of details about what/when your logic was doing something.

strangely … all my scenes do have log entries
but none of them seems to trigger it

here is all related log Entries

08	09/01/13 2:37:55.445	JobHandler_LuaUPnP::HandleActionRequest device: 62 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x2fbd9680>
08	09/01/13 2:37:55.445	JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=62 <0x2fbd9680>
08	09/01/13 2:37:55.446	JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x2fbd9680>
08	09/01/13 2:37:55.446	JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x2fbd9680>
08	09/01/13 2:37:55.446	JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=100 <0x2fbd9680>
08	09/01/13 2:37:55.446	JobHandler_LuaUPnP::HandleActionRequest argument rand=0.46200778847560287 <0x2fbd9680>
06	09/01/13 2:37:55.447	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelTarget was: 100 now: 100 #hooks: 0 upnp: 0 v:0x9b2ed0/NONE duplicate:1 <0x2fbd9680>
06	09/01/13 2:37:55.681	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 0 now: 100 #hooks: 5 upnp: 0 v:0x8ce150/NONE duplicate:0 <0x2bbd9680>
06	09/01/13 2:37:55.682	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 v:0x954868/NONE duplicate:0 <0x2bbd9680>

[ Cut some other log entries ]

02	09/01/13 2:43:01.103	ZW_Send_Data node 6 NO ROUTE (nil) <0x2bdd9680>
06	09/01/13 2:43:01.246	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 0 #hooks: 0 upnp: 0 v:0x954868/NONE duplicate:0 <0x2bbd9680>
06	09/01/13 2:43:01.247	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 100 now: 0 #hooks: 5 upnp: 0 v:0x8ce150/NONE duplicate:0 <0x2bbd9680>
04	09/01/13 2:43:01.248	 <0x2bbd9680>

first is me turning on the light via UI (twice)
and later it turned off without me doing anything to it.

Is this happening all the time or random again.
The Job Code 6 is a resubmit and the words turned on twice (what happened on between).

Do you have Smart Switch or virtual Ghost installed?

the duplicate on turning it on was me clicking twice on the UI
in between is alot of data collecting happening and a few other switches (untelated) beeing used.

no ghost or smart switch installed.

my scenes have in all trigger-luup and general luup luup.log enties
but none do print anything in the log.

it seem like to happen (if it happens) just a few minutes after it has been turned on.
if its on longer as a few minutes it stays on forever. (like now … i keep watching the log)

the lamp is controlled by serval scenes
with serval triggers like XBMC Plugin, “return from away scene” and “sleep/leaving scene”

but all this scenes do print log entries on any activity
also functions inside the code do (some things happens on some delay)
to catch this i added in each delayed function luup.log as well.
(besides the triggers would show in the log as well by standard)
but no output and no trigger has been used.

it happens basically at 8 out of 10 times.

the device is a Dimmer
is not acotiated with anything else (100% controlled by vera only)

I had similar behaviour, turned out to be a defective switch (Duwi)

Look at the job and “6” being the resubmitted, in this case it appears it may be the queued until resubmitted.

Does the same happen if the status is changed from another 3rd party app (mobile phone) or using another browser?

just made another test with Homwave turn it on … same result

04	09/01/13 11:15:27.664	 <0x2bbd9680>
08	09/01/13 11:15:27.712	JobHandler_LuaUPnP::HandleActionRequest device: 62 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x2f7d9680>
08	09/01/13 11:15:27.713	JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=62 <0x2f7d9680>
08	09/01/13 11:15:27.713	JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x2f7d9680>
08	09/01/13 11:15:27.713	JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x2f7d9680>
08	09/01/13 11:15:27.714	JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=100 <0x2f7d9680>
06	09/01/13 11:15:27.714	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelTarget was: 100 now: 100 #hooks: 0 upnp: 0 v:0x9b2ed0/NONE duplicate:1 <0x2f7d9680>
02	09/01/13 11:15:27.715	ZWJob_SendData  UPDATE MANUAL ROUTE 6=(nil) <0x2f7d9680>
02	09/01/13 11:15:27.716	UPDATE MANUAL ROUTE2 6=(nil) <0x2bdd9680>
02	09/01/13 11:15:27.717	ZW_Send_Data node 6 NO ROUTE (nil) <0x2bdd9680>
02	09/01/13 11:15:27.814	UPDATE MANUAL ROUTE2 6=(nil) <0x2bdd9680>
02	09/01/13 11:15:27.814	ZW_Send_Data node 6 NO ROUTE (nil) <0x2bdd9680>
06	09/01/13 11:15:27.922	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 0 now: 100 #hooks: 5 upnp: 0 v:0x8ce150/NONE duplicate:0 <0x2bbd9680>
06	09/01/13 11:15:27.923	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 v:0x954868/NONE duplicate:0 <0x2bbd9680>


02	09/01/13 11:19:21.029	ZW_Send_Data node 6 NO ROUTE (nil) <0x2bdd9680>
06	09/01/13 11:19:21.162	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 0 #hooks: 0 upnp: 0 v:0x954868/NONE duplicate:0 <0x2bbd9680>
06	09/01/13 11:19:21.163	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 100 now: 0 #hooks: 5 upnp: 0 v:0x8ce150/NONE duplicate:0 <0x2bbd9680>
04	09/01/13 11:19:21.165	 <0x2bbd9680>

but now there are some routing updates as well … (could be coincidental)

i also have seen quite alot errors like this:

02	09/01/13 11:18:51.110	ZWaveNode::AddPollingCommand light/switch node 4 doesn't support any COMMAND_CLASS_BASIC <0x2bdd9680>
02	09/01/13 11:18:51.122	ZW_Send_Data node 4 NO ROUTE (nil) <0x2bdd9680>
02	09/01/13 11:18:53.454	ZW_Send_Data node 4 NO ROUTE (nil) <0x2bdd9680>
02	09/01/13 11:18:55.774	ZW_Send_Data node 4 NO ROUTE (nil) <0x2bdd9680>

but they from Node 4 … the switch in question is Node 6 (id:62)
but they close to each other and most likely share mesh routing.
Node 4 works perfectly btw (its a Fibaro dual switch) … even there is a error.

Go to Dashboard > Overview > Triggers. Is there any corresponding trigger around these time or if you repeat the activity is there then?

The time is about the same as the last and thus appears to be repeatable and not random.

Go to Dashboard > Overview > Triggers. Is there any corresponding trigger around these time or if you repeat the activity is there then?

The time is about the same as the last and thus appears to be repeatable and not random.

to be on the safe side i turned off ALL Triggers, reloaded, turned on the dimmer in question
6 minutes later … the lamp is Off again.

08	09/01/13 16:06:42.091	JobHandler_LuaUPnP::HandleActionRequest device: 62 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x2ef35680>
08	09/01/13 16:06:42.092	JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=62 <0x2ef35680>
08	09/01/13 16:06:42.092	JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x2ef35680>
08	09/01/13 16:06:42.092	JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x2ef35680>
08	09/01/13 16:06:42.092	JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=100 <0x2ef35680>
08	09/01/13 16:06:42.092	JobHandler_LuaUPnP::HandleActionRequest argument rand=0.9261570619419217 <0x2ef35680>
06	09/01/13 16:06:42.093	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelTarget was: 100 now: 100 #hooks: 0 upnp: 0 v:0xff4ed0/NONE duplicate:1 <0x2ef35680>
02	09/01/13 16:06:42.093	ZWJob_SendData  UPDATE MANUAL ROUTE 6=(nil) <0x2ef35680>
04	09/01/13 16:06:42.186	 <0x2bd35680>
02	09/01/13 16:06:44.135	ZWaveSerial::GetFrame 0x2c134f58 timed out now 0 m_listGetFramePending 0 <0x2c135680>
02	09/01/13 16:06:44.135	ZWaveJobHandler::SendDataAbort got m_iFrameID 0 <0x2c135680>
02	09/01/13 16:06:44.139	UPDATE MANUAL ROUTE2 6=(nil) <0x2c135680>
02	09/01/13 16:06:44.139	ZW_Send_Data node 6 NO ROUTE (nil) <0x2c135680>
02	09/01/13 16:06:44.236	UPDATE MANUAL ROUTE2 6=(nil) <0x2c135680>
02	09/01/13 16:06:44.237	ZW_Send_Data node 6 NO ROUTE (nil) <0x2c135680>
06	09/01/13 16:06:44.345	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 0 now: 100 #hooks: 5 upnp: 0 v:0xf10150/NONE duplicate:0 <0x2bd35680>
06	09/01/13 16:06:44.346	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 0 upnp: 0 v:0xf96868/NONE duplicate:0 <0x2bd35680>


02	09/01/13 16:08:02.103	ZW_Send_Data node 6 NO ROUTE (nil) <0x2c135680>



02	09/01/13 16:12:32.103	ZW_Send_Data node 6 NO ROUTE (nil) <0x2c135680>
06	09/01/13 16:12:32.235	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 0 #hooks: 0 upnp: 0 v:0xf96868/NONE duplicate:0 <0x2bd35680>
06	09/01/13 16:12:32.236	Device_Variable::m_szValue_set device: 62 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 100 now: 0 #hooks: 5 upnp: 0 v:0xf10150/NONE duplicate:0 <0x2bd35680>

Is a bit of d?j? vu for you…, There is nothing that jumps out and unless there is a an app - program logic etc that is doing this… The if it is excluded and then included again it will give it a new device/node id does it repeat the behaviour?

well … beeing on the end of the line… i really did exclude and reinclude the device
node 6 became 26 and device 62 became 112

changed all the luup with the new device ID … enabled back all triggers …
it stays on !

it works, but iam completly clueless now. and iam really NOT like to do things the Microsoft way … some switches took me hours to install them
hope this not happens with one of them.