I’ve got a problem with my Google Latitude plugin (developing it) that I’m hoping others can help me identify the root cause of.
I’m not sure how to explain the behavior, so here’s my best attempt as well as the log file that shows it:
For some reason, whenever a trigger “fires” (the event occurs), a few hundreds of a second later, that event gets reset (unset) again. It shows up most because I have PLEG installed and PLEG has two Triggers with A condition and actions for each trigger that illustrates the behavior. I have also had a user report of this behavior and I was - fortunately ? - able to experience it first hand on my Vera 3 w/UI5 1.5.622.
I realize I’m probably doing something wrong in the code somewhere, but I’ve tried to figure it out by reading the little documentation I can find on the Wiki page and looking at other plugins. But I just can’t seem to be able to identify the problem!
As mentioned, I’m using PLEG to try and help me debug this, so here’s the configuration I’ve got in PLEG.
Conditions:: Radius #1 is TRIPPED (input/trigger 1) and Radius 1 is not tripped (Input/Trigger 2).
Actions: Update Variable Container w/text “Home” for Tripped and “Not Home” for NOT Tripped.
What got captured in the LuaUPnP log.
I force the plugin to Trip:
08 04/22/13 18:11:55.061 JobHandler_LuaUPnP::HandleActionRequest device: 165 service: urn:mark-watkins:serviceId:GoogleLatitudeSensor1 action: ChangeInvert <0x316c6680>
08 04/22/13 18:11:55.061 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=165 <0x316c6680>
08 04/22/13 18:11:55.061 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:mark-watkins:serviceId:GoogleLatitudeSensor1 <0x316c6680>
08 04/22/13 18:11:55.061 JobHandler_LuaUPnP::HandleActionRequest argument action=ChangeInvert <0x316c6680>
08 04/22/13 18:11:55.061 JobHandler_LuaUPnP::HandleActionRequest argument rand=0.0006616516038775444 <0x316c6680>
50 04/22/13 18:11:55.062 luup_log:165: Invert value now: 1 <0x316c6680>
06 04/22/13 18:11:55.062 Device_Variable::m_szValue_set device: 165 service: urn:mark-watkins:serviceId:GoogleLatitudeSensor1 variable: Invert was: 1 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x316c6680>
06 04/22/13 18:11:55.063 Device_Variable::m_szValue_set device: 165 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: Tripped was: 0 now: 1 #hooks: 2 upnp: 0 v:0xc91340/NONE duplicate:0 <0x316c6680>PLEG “sees” the (forced) trip activity/event:
07 04/22/13 18:11:55.063 Event::Evaluate 33 ThomasIsHome scene ProgramLogic_216 is false repeat 0/-1 <0x316c6680>
08 04/22/13 18:11:55.084 JobHandler_LuaUPnP::HandleActionRequest device: 216 service: urn:rts-services-com:serviceId:ProgramLogicC action: TriggerAction <0x316c6680>
08 04/22/13 18:11:55.085 JobHandler_LuaUPnP::HandleActionRequest argument triggerName=ThomasIsNotHome <0x316c6680>
50 04/22/13 18:11:55.157 luup_log:216: PLEG:216:TriggerAction:ThomasIsNotHome <0x316c6680>
06 04/22/13 18:11:55.158 Device_Variable::m_szValue_set device: 216 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: ConditionSatisfied was: ThomasArrived now: #hooks: 0 upnp: 0 v:0xe12370/NONE duplicate:0 <0x316c6680>
06 04/22/13 18:11:55.158 Device_Variable::m_szValue_set device: 216 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: LastConditionChange was: 1366668702 now: 1366668715 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x316c6680>
50 04/22/13 18:11:55.159 luup_log:216: PLEG:216:EvalTriggers:Name:Open_DoorToGarage State:false Device:148 <0x316c6680>
50 04/22/13 18:11:55.160 luup_log:216: PLEG:216:EvalTriggers:Name:GarageMotion State:false Device:75 <0x316c6680>
50 04/22/13 18:11:55.160 luup_log:216: PLEG:216:EvalTriggers:Name:Open_FrontDoor State:false Device:93 <0x316c6680>
50 04/22/13 18:11:55.161 luup_log:216: PLEG:216:EvalTriggers:Name:SensorArmed_DenMotion State:false Device:19 <0x316c6680>
50 04/22/13 18:11:55.161 luup_log:216: PLEG:216:EvalTriggers:Name:Sensor_DenMotion State:false Device:19 <0x316c6680>
50 04/22/13 18:11:55.161 luup_log:216: PLEG:216:EvalTriggers:Name:OnVacation State:false Device:131 <0x316c6680>
50 04/22/13 18:11:55.162 luup_log:216: PLEG:216:EvalTriggers:Name:NotOnVacation State:true Device:131 <0x316c6680>
50 04/22/13 18:11:55.162 luup_log:216: PLEG:216:EvalTriggers:Name:isDay State:true Device:176 <0x316c6680>
50 04/22/13 18:11:55.163 luup_log:216: PLEG:216:EvalTriggers:Name:isNight State:false Device:176 <0x316c6680>
50 04/22/13 18:11:55.163 luup_log:216: PLEG:216:EvalTriggers:Name:NoGuestsPresent State:true Device:209 <0x316c6680>
50 04/22/13 18:11:55.164 luup_log:216: PLEG:216:EvalTriggers:Name:GuestsPresent State:false Device:209 <0x316c6680>
50 04/22/13 18:11:55.175 luup_log:216: PLEG:216:EvalTriggers:Name:ChristineIsHome State:true Device:166 <0x316c6680>
50 04/22/13 18:11:55.176 luup_log:216: PLEG:216:EvalTriggers:Name:ChristineIsNotHome State:false Device:166 <0x316c6680>
50 04/22/13 18:11:55.176 luup_log:216: PLEG:216:EvalTriggers:Name:ThomasIsHome State:false Device:165 <0x316c6680>
50 04/22/13 18:11:55.177 luup_log:216: PLEG:216:EvalTriggers:Name:ThomasIsNotHome State:true Device:165 <0x316c6680>
50 04/22/13 18:11:55.177 luup_log:216: PLEG:216:EvalTriggers:Name:ChristineIsNear State:false Device:166 <0x316c6680>
50 04/22/13 18:11:55.178 luup_log:216: PLEG:216:EvalTriggers:Name:ChristineIsAway State:true Device:166 <0x316c6680>
50 04/22/13 18:11:55.178 luup_log:216: PLEG:216:EvalTriggers:Name:ThomasIsNear State:true Device:165 <0x316c6680>
50 04/22/13 18:11:55.179 luup_log:216: PLEG:216:EvalTriggers:Name:ThomasIsAway State:false Device:165 <0x316c6680>
50 04/22/13 18:11:55.182 luup_log:216: PLEG:216:EvalConditions:Condition:earlyMorning Trigger:ThomasIsNotHome Result:false <0x316c6680>
50 04/22/13 18:11:55.184 luup_log:216: PLEG:216:EvalConditions:Condition:morning Trigger:ThomasIsNotHome Result:false <0x316c6680>
50 04/22/13 18:11:55.196 luup_log:216: PLEG:216:EvalConditions:Condition:dayTime Trigger:ThomasIsNotHome Result:true <0x316c6680>
50 04/22/13 18:11:55.198 luup_log:216: PLEG:216:EvalConditions:Condition:afternoon Trigger:ThomasIsNotHome Result:false <0x316c6680>
50 04/22/13 18:11:55.199 luup_log:216: PLEG:216:EvalConditions:Condition:nightTime Trigger:ThomasIsNotHome Result:false <0x316c6680>
50 04/22/13 18:11:55.202 luup_log:216: PLEG:216:EvalConditions:Condition:evening Trigger:ThomasIsNotHome Result:true <0x316c6680>
50 04/22/13 18:11:55.224 luup_log:216: PLEG:216:EvalConditions:Condition:lateNight Trigger:ThomasIsNotHome Result:false <0x316c6680>
50 04/22/13 18:11:55.225 luup_log:216: PLEG:216:EvalConditions:Condition:ThomasLeft Trigger:ThomasIsNotHome Result:true <0x316c6680>Yeah, the plugin definitely has me - correctly, because of the inversion - marked as “not being home”. And according to the log, it sets the Variable (Variable1 & VariableName1) to what I’d expect.
50 04/22/13 18:11:55.225 luup_log:216: PLEG:216:TriggerCondition:ThomasLeft <0x316c6680>
06 04/22/13 18:11:55.226 Device_Variable::m_szValue_set device: 216 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: ConditionSatisfied was: now: ThomasLeft #hooks: 0 upnp: 0 v:0xe12370/NONE duplicate:0 <0x316c6680>
06 04/22/13 18:11:55.227 Device_Variable::m_szValue_set device: 216 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: LastConditionChange was: 1366668715 now: 1366668715 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x316c6680>
50 04/22/13 18:11:55.227 luup_log:216: PLEG:216:FireAction:ThomasLeft <0x316c6680>Updating the variable & variable name in the Variable Container
08 04/22/13 18:11:55.228 JobHandler_LuaUPnP::HandleActionRequest device: 193 service: urn:upnp-org:serviceId:VContainer1 action: SetVariableName1 <0x316c6680>
08 04/22/13 18:11:55.228 JobHandler_LuaUPnP::HandleActionRequest argument newVariableName1=Thomas <0x316c6680>
06 04/22/13 18:11:55.228 Device_Variable::m_szValue_set device: 193 service: urn:upnp-org:serviceId:VContainer1 variable: VariableName1 was: Thomas now: Thomas #hooks: 0 upnp: 0 v:0xd1d310/NONE duplicate:1 <0x316c6680>
08 04/22/13 18:11:55.230 JobHandler_LuaUPnP::HandleActionRequest device: 193 service: urn:upnp-org:serviceId:VContainer1 action: SetVariable1 <0x316c6680>
08 04/22/13 18:11:55.230 JobHandler_LuaUPnP::HandleActionRequest argument newVariable1=Not Home <0x316c6680>
06 04/22/13 18:11:55.230 Device_Variable::m_szValue_set device: 193 service: urn:upnp-org:serviceId:VContainer1 variable: Variable1 was: Home now: Not Home #hooks: 0 upnp: 0 v:0xd1d8b8/NONE duplicate:0 <0x316c6680>All done, so it should be over, right…? Nope!
Note that I have actually not - as far as I can tell(!) - done anything more to the plugin. I have not fired the Invert button again (at least not intentionally!), nor have I physically moved the Latitude app/device either (it’s still with me, on my desk. Just like it was before I clicked the “invert” button the first time!
Here goes the “phantom” reset:
50 04/22/13 18:11:55.232 luup_log:216: PLEG:216:EvalConditions:Condition:ThomasLeft_Morning Trigger:ThomasIsNotHome Result:false <0x316c6680>
50 04/22/13 18:11:55.233 luup_log:216: PLEG:216:EvalConditions:Condition:ThomasArrived Trigger:ThomasIsNotHome Result:false <0x316c6680>
50 04/22/13 18:11:55.245 luup_log:216: PLEG:216:EvalConditions:Condition:ChristineLeft Trigger:ThomasIsNotHome Result:false <0x316c6680>
50 04/22/13 18:11:55.246 luup_log:216: PLEG:216:EvalConditions:Condition:ChristineArrived Trigger:ThomasIsNotHome Result:true <0x316c6680>
50 04/22/13 18:11:55.250 luup_log:216: PLEG:216:SaveDB:{{name ='earlyMorning', state = false, seq = 1366617617},{name ='morning', state = false, seq = 1366624817},{name ='dayTime', state = true, seq = 1366625575},{name ='afternoon', state = false, seq = 1366658122},{name ='nightTime', state = false, seq = 1366588561},{name ='evening', state = true, seq = 1366668022},{name ='lateNight', state = false, seq = 0},{name ='checkDeIce', state = false, seq = 1366668000},{name ='checkSeason', state = false, seq = 1366668000},{name ='frontDeIce', state = false, seq = 0},{name ='backDeIce', state = false, seq = 0},{name ='frontTopDeIce', state = false, seq = 0},{name ='Open_DoorToGarage', state = false, seq = 1366668544},{name ='GarageMotion', state = false, seq = 1366668529},{name ='Open_FrontDoor', state = false, seq = 1366658668},{name ='SensorArmed_DenMotion', state = false, seq = 1366659610},{name ='Sensor_DenMotion', state = false, seq = 1366659610},{name ='OnVacation', state = false, seq = 0},{name ='NotOnVacation', state = true, seq = 0},{name ='isDay', state = true, seq = 1366625575},{name ='isNight', state = false, seq = 1366588561},{name ='NoGuestsPresent', state = true, seq = 0},{name ='GuestsPresent', state = false, seq = 0},{name ='ChristineIsHome', state = true, seq = 1366668651},{name ='ChristineIsAway', state = true, seq = 1366627956},{name ='ThomasIsHome', state = false, seq = 1366668702},{name ='ThomasIsAway', state = false, seq = 1366668445},{name ='ThomasLeft', state = true, seq = 1366668715},{name ='ThomasLeft_Morning', state = false, seq = 1366628300},{name ='ThomasArrived', state = false, seq = 1366668702},{name ='ChristineLeft', state = false, seq = 1366659441},{name ='ChristineArrived', state = true, seq = 1366668651},{name ='ChristineIsNotHome', state = false, seq = 1366659441},{name ='ThomasIsNotHome', state = true, seq = 1366668715},{name ='ChristineIsNear', state = false, seq = 1366627776},{name ='ThomasIsNear', state = true, seq = 1366668625},{name ='NOW', state = false, seq = 1366668682},} <0x316c6680>
06 04/22/13 18:11:55.250 Device_Variable::m_szValue_set device: 216 service: urn:rts-services-com:serviceId:ProgramLogicC variable: ObjectStatusMap was: {{name ='earlyMorning', state = false, seq = 1366617617},{name ='morning', state = false, seq = 1366624817},{name ='dayTime', state = true, seq = 1366625575},{name ='afternoon', state = false, seq = 1366658122},{name ='nightTime', state = false, seq = 1366588561},{name ='evening', state = true, seq = 1366668022},{name ='lateNight', state = false, seq = 0},{name ='checkDeIce', state = false, seq = 1366668000},{name ='checkSeason', state = false, seq = 1366668000},{name ='frontDeIce', state = false, seq = 0},{name ='backDeIce', state = false, seq = 0},{name ='frontTopDeIce', state = false, seq = 0},{name ='Open_DoorToGarage', state = false, seq = 1366668544},{name ='GarageMotion', state = false, seq = 1366668529},{name ='Open_FrontDoor', state = false, seq = 1366658668},{name ='SensorArmed_DenMotion', state = false, seq = 1366659610},{name ='Sensor_DenMotion', state = false, seq = 1366659610},{name ='OnVacation', state = false, seq = 0},{name ='NotOnVacation', state = true, seq = 0},{name ='isDay', state = true, seq = 1366625575},{name ='isNight', state = false, seq = 1366588561},{name ='NoGuestsPresent', state = true, seq = 0},{name ='GuestsPresent', state = false, seq = 0},{name ='ChristineIsHome', state = true, seq = 1366668651},{name ='ChristineIsAway', state = true, seq = 1366627956},{name ='ThomasIsHome', state = true, seq = 1366668702},{name ='ThomasIsAway', state = false, seq = 1366668445},{name ='ThomasLeft', state = false, seq = 1366668643},{name ='ThomasLeft_Morning', state = false, seq = 1366628300},{name ='ThomasArrived', state = true, seq = 1366668702},{name ='ChristineLeft', state = false, seq = 1366659441},{name ='ChristineArrived', state = true, seq = 1366668651},{name ='ChristineIsNotHome', state = false, seq = 1366659441},{name ='ThomasIsNotHome', state = false, seq = 1366668643},{name ='ChristineIsNear', state = false, seq = 1366627776},{name ='ThomasIsNear', state = true, seq = 1366668625},{name ='NOW', state = false, seq = 1366668682},} now: {{name ='earlyMorning', state = false, seq = 1366617617},{name ='morning', state = false, seq = 1366624817},{name ='dayTime', state = true, seq = 1366625575},{name ='afternoon', state = false, seq = 1366658122},{name ='nightTime', state = false, seq = 1366588561},{name ='evening', state = true, seq = 1366668022},{name ='lateNight', state = false, seq = 0},{name ='checkDeIce', state = false, seq = 1366668000},{name ='checkSeason', state = false, seq = 1366668000},{name ='frontDeIce', state = false, seq = 0},{name ='backDeIce', state = false, seq = 0},{name ='frontTopDeIce', state = false, seq = 0},{name ='Open_DoorToGarage', state = false, seq = 1366668544},{name ='GarageMotion', state = false, seq = 1366668529},{name ='Open_FrontDoor', state = false, seq = 1366658668},{name ='SensorArmed_DenMotion', state = false, seq = 1366659610},{name ='Sensor_DenMotion', state = false, seq = 1366659610},{name ='OnVacation', state = false, seq = 0},{name ='NotOnVacation', state = true, seq = 0},{name ='isDay', state = true, seq = 1366625575},{name ='isNight', state = false, seq = 1366588561},{name ='NoGuestsPresent', state = true, seq = 0},{name ='GuestsPresent', state = false, seq = 0},{name ='ChristineIsHome', state = true, seq = 1366668651},{name ='ChristineIsAway', state = true, seq = 1366627956},{name ='ThomasIsHome', state = false, seq = 1366668702},{name ='ThomasIsAway', state = false, seq = 1366668445},{name ='ThomasLeft', state = true, seq = 1366668715},{name ='ThomasLeft_Morning', state = false, seq = 1366628300},{name ='ThomasArrived', state = false, seq = 1366668702},{name ='ChristineLeft', state = false, seq = 1366659441},{name ='ChristineArrived', state = true, seq = 1366668651},{name ='ChristineIsNotHome', state = false, seq = 1366659441},{name ='ThomasIsNotHome', state = true, seq = 1366668715},{name ='ChristineIsNear', state = false, seq = 1366627776},{name ='ThomasIsNear', state = true, seq = 1366668625},{name ='NOW', state = false, seq = 1366668682},} #hooks: 0 upnp: 0 v:0xe16360/NONE duplicate:0 <0x316c6680>
07 04/22/13 18:11:55.252 Event::Evaluate 34 ThomasIsNotHome scene ProgramLogic_216 is true users:(null) allow:1 <0x316c6680>Variable Container contents gets set back to the value I would expect it to be in the event of a “de-trigger” event (trigger = off). This is not at all what I’d expect to see!
08 04/22/13 18:11:55.252 Scene::RunScene running 199 ProgramLogic_216 <0x316c6680>
08 04/22/13 18:11:55.253 JobHandler_LuaUPnP::HandleActionRequest device: 193 service: urn:upnp-org:serviceId:VContainer1 action: SetVariable1 <0x316c6680>
08 04/22/13 18:11:55.253 JobHandler_LuaUPnP::HandleActionRequest argument newVariable1=Home <0x316c6680>
06 04/22/13 18:11:55.253 Device_Variable::m_szValue_set device: 193 service: urn:upnp-org:serviceId:VContainer1 variable: Variable1 was: Not Home now: Home #hooks: 0 upnp: 0 v:0xd1d8b8/NONE duplicate:0 <0x316c6680>
02 04/22/13 18:12:03.103 ZW_Send_Data node 55 USING ROUTE 255.72.244.185 <0x2be85680>Here’s the eventlist2 JSON that the plugin uses:
"eventList2": [
{
"id": 1,
"label": {
"lang_tag": "radius_boundary_trips",
"text": "Radius #1 (Home)"
},
"serviceId": "urn:micasaverde-com:serviceId:SecuritySensor1",
"argumentList": [
{
"id": 1,
"dataType": "boolean",
"defaultValue": "",
"allowedValueList": [
{
"Yes": "1",
"HumanFriendlyText": {
"lang_tag": "hft_latitude_radius1_active",
"text": "_DEVICE_NAME_: Further than Radius #1 (NOT Tripped)"
}
},
{
"No": "0",
"HumanFriendlyText": {
"lang_tag": "htf_latitude_radius1_inactive",
"text": "_DEVICE_NAME_: Closer than Radius #1 (Tripped)"
}
}
],
"name": "Tripped",
"comparisson": "=",
"prefix": {
"lang_tag": "status",
"text": "Status?"
},
"suffix": {
}
}
]
},
{
"id": 2,
"label": {
"lang_tag": "radius_boundary_trips",
"text": "Radius #2 (Near)"
},
"serviceId": "urn:micasaverde-com:serviceId:SecuritySensor1",
"argumentList": [
{
"id": 1,
"dataType": "boolean",
"defaultValue": "",
"allowedValueList": [
{
"Yes": "1",
"HumanFriendlyText": {
"lang_tag": "hft_latitude_radius2_active",
"text": "_DEVICE_NAME_: Further than Radius #2 (NOT Tripped)"
}
},
{
"No": "0",
"HumanFriendlyText": {
"lang_tag": "htf_latitude_radius2_inactive",
"text": "_DEVICE_NAME_: Closer than Radius #2 (Tripped)"
}
}
],
"name": "Tripped_2",
"comparisson": "=",
"prefix": {
"lang_tag": "status",
"text": "Status?"
},
"suffix": {
}
}
]
}
]