nullx8
August 30, 2013, 2:16pm
#1
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.
nullx8
August 31, 2013, 7:47pm
#3
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?
nullx8
August 31, 2013, 8:17pm
#5
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?
nullx8
September 1, 2013, 4:26am
#8
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.
nullx8
September 1, 2013, 9:16am
#11
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?
nullx8
September 1, 2013, 10:23am
#13
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.