Weird Scene firing with PLEG

Hello, I have a scene which is fired by a PLEG with some conditions.

Everything is working ok, but some times ransomnly, the scen is fired without meeting the conditions…

The scene is the 102, the main trigger for it a Schedule which can be overriden by a gcal .

I put the log under. The weird firing happened at 19h49, but I cannot understand from the log why … if someone could help, would be great !

06 10/08/14 19:59:14.790 Device_Variable::m_szValue_set device: 94 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: e[35;1mKWHe[0m was: 0.1800 now: 0.1800 #hooks: 0 upnp: 0 v:0xfd7ce8/NONE duplicate:1 <0x2b3c9680> 06 10/08/14 19:59:14.799 Device_Variable::m_szValue_set device: 94 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: e[35;1mKWHReadinge[0m was: 1412790712 now: 1412791154 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b3c9680> 50 10/08/14 19:59:15.059 luup_log:55: PLEG-55:Initialize:Restart <0x2b5c9680> 06 10/08/14 19:59:15.106 Device_Variable::m_szValue_set device: 55 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: e[35;1mConditionSatisfiede[0m was: Fermer now: None #hooks: 0 upnp: 0 v:0x105b4f0/NONE duplicate:0 <0x2b5c9680> 06 10/08/14 19:59:15.106 Device_Variable::m_szValue_set device: 55 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: e[35;1mLastConditionChangee[0m was: 1412789140 now: 1412791155 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b5c9680> 06 10/08/14 19:59:15.642 Device_Variable::m_szValue_set device: 3 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: e[35;1mWattse[0m was: 18 now: 18 #hooks: 0 upnp: 0 v:0xfd8268/NONE duplicate:1 <0x2b3c9680> 06 10/08/14 19:59:15.642 Device_Variable::m_szValue_set device: 3 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: e[35;1mActualUsagee[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0xfd82a8/NONE duplicate:1 <0x2b3c9680> 02 10/08/14 19:59:16.814 e[33;1mZW_Send_Data node 32 NO ROUTE (nil)e[0m <0x2b7c9680> 06 10/08/14 19:59:16.942 Device_Variable::m_szValue_set device: 94 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: e[35;1mWattse[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:0xfd8268/NONE duplicate:1 <0x2b3c9680> 06 10/08/14 19:59:16.942 Device_Variable::m_szValue_set device: 94 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: e[35;1mActualUsagee[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0xfd82a8/NONE duplicate:1 <0x2b3c9680> 04 10/08/14 19:59:16.944 <Job ID="12" Name="pollnode_conf #32 4 cmds" Device="94" Created="2014-10-08 19:59:10" Started="2014-10-08 19:59:10" Completed="2014-10-08 19:59:16" Duration="6.573188000" Runtime="6.568559000" Status="Successful" LastNote="" Node="32" NodeType="ZWaveWindowCovering" NodeDescription="Volet Cuisine Porte"/> <0x2b3c9680> 06 10/08/14 19:59:16.995 Device_Variable::m_szValue_set device: 17 service: urn:rts-services-com:serviceId:ProgramLogicC variable: e[35;1mRegisterMsge[0m was: Installed: 1389998278 Free License which allows a total of 3 PLEG and/or PLTS plugins each with a max 5 inputs and 5 conditions. now: Installed: 1389998278 Free License which allows a total of 3 PLEG and/or PLTS plugins each with a max 5 inputs and 5 conditions. #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b5c9680> 06 10/08/14 19:59:17.002 Device_Variable::m_szValue_set device: 68 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mLastUpdatee[0m was: 1412728294 now: 1412791156 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b5c9680> 06 10/08/14 19:59:17.002 Device_Variable::m_szValue_set device: 68 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mConfigurede[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0xfd0150/NONE duplicate:1 <0x2b5c9680> 50 10/08/14 19:59:17.063 luup_log:69: GCAL: checking google calendar <0x2b5c9680> 50 10/08/14 19:59:17.064 luup_log:69: GCAL: start-min: 2014-10-08T17:59:17.000Z <0x2b5c9680> 50 10/08/14 19:59:17.064 luup_log:69: GCAL: start-max: 2014-10-08T18:00:17.000Z <0x2b5c9680> 50 10/08/14 19:59:17.412 luup_log:69: GCAL: query url: http://www.google.com/calendar/feeds/ddg3tl7u19n17l53d35hm06grc@group.calendar.google.com/private-c6a5425cc8420563df4815efd58aefcd/full?alt=json&fields=entry/title,entry/gd:when&singleevents=true&orderby=starttime&ctz=utc&start-min=2014-10-08T17:59:17.000Z&start-max=2014-10-08T18:00:17.000Z <0x2b5c9680> 50 10/08/14 19:59:17.413 luup_log:69: GCAL: query status: 200 <0x2b5c9680> 50 10/08/14 19:59:17.415 luup_log:69: GCAL: No event in the next time window. Retry later... <0x2b5c9680> 06 10/08/14 19:59:17.415 Device_Variable::m_szValue_set device: 69 service: urn:utz-com:serviceId:GCal1 variable: e[35;1mgcalnextevente[0m was: 30/05/14 00:00:00 Cong? now: No event #hooks: 0 upnp: 0 v:0x10993a8/NONE duplicate:0 <0x2b5c9680> 50 10/08/14 19:59:17.416 luup_log:69: GCAL: Timer: We already are outside an event, so untrigger now <0x2b5c9680> 06 10/08/14 19:59:17.416 Device_Variable::m_szValue_set device: 69 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: e[35;1mTrippede[0m was: 1 now: 0 #hooks: 1 upnp: 0 v:0xfcf098/NONE duplicate:0 <0x2b5c9680> 01 10/08/14 19:59:17.440 e[31;1mluvd_get_info /etc/cmh-ludl/S_ProgramLogicC.xml.lzo doesn't existe[0m <0x3200a680> 06 10/08/14 19:59:17.445 Device_Variable::m_szValue_set device: 55 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: e[35;1mConditionSatisfiede[0m was: None now: Ouvrir #hooks: 0 upnp: 0 v:0x105b4f0/NONE duplicate:0 <0x2b5c9680> 06 10/08/14 19:59:17.446 Device_Variable::m_szValue_set device: 55 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: e[35;1mLastConditionChangee[0m was: 1412791155 now: 1412791157 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b5c9680> 08 10/08/14 19:59:17.446 JobHandler_LuaUPnP::HandleActionRequest device: 55 service: urn:rts-services-com:serviceId:ProgramLogicC action: e[36;1mRunActione[0m <0x2b5c9680> 08 10/08/14 19:59:17.447 JobHandler_LuaUPnP::HandleActionRequest argument conditionName=Ouvrir <0x2b5c9680> 06 10/08/14 19:59:17.456 Device_Variable::m_szValue_set device: 55 service: urn:rts-services-com:serviceId:ProgramLogicC variable: e[35;1mObjectStatusMape[0m was: {{name = 'But_2_Long', state = false, seq = 1399568419.4091, oseq = 1410071010.2713},{name = 'Sched_Volets', state = false, seq = 1412744400.1004, oseq = 0},{name = 'Ouvrir', state = true, seq = 1412784053.6105, oseq = 1412725303.2106},{name = 'Fermer', state = true, seq = 1412789140.1581, oseq = 1412747060.138},{name = 'DayOff', state = '1', seq = 1412784053.5852, oseq = 1412725301.2724},{name = 'Ouvrir_Volets', state = '1', seq = 1412776945.3913, oseq = 1412725303.2069},{name = 'Night', state = '0', seq = 1412789140.1525, oseq = 1412747060.1265},} now: {{name = 'But_2_Long', state = false, seq = 1399568419.4091, oseq = 1410071010.2713},{name = 'Sched_Volets', state = false, seq = 1412744400.1004, oseq = 0},{name = 'Ouvrir', state = true, seq = 1412791157.4437, oseq = 1412725303.2106},{name = 'Fermer', state = true, seq = 1412789140.1581, oseq = 1412747060.138},{name = 'DayOff', state = '0', seq = 1412791157.4175, oseq = 1412784053.5852},{name = 'Ouvrir_Volets', state = '1', seq = 1412776945.3913, oseq = 1412725303.2069},{name = 'Night', state = '0', seq = 1412789140.1525, oseq = 1412747060.1265},} #hooks: 0 upnp: 0 v:0x1080200/NONE duplicate:0 <0x2b5c9680> 06 10/08/14 19:59:17.466 Device_Variable::m_szValue_set device: 69 service: urn:utz-com:serviceId:GCal1 variable: e[35;1mgcalvale[0m was: now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b5c9680> 06 10/08/14 19:59:17.467 Device_Variable::m_szValue_set device: 69 service: urn:utz-com:serviceId:GCal1 variable: e[35;1mgcalkeyworde[0m was: Cong? now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b5c9680> 50 10/08/14 19:59:17.467 luup_log:69: GCAL: Timer: Next event "timeout" in 60 seconds <0x2b5c9680> 50 10/08/14 19:59:17.468 luup_log:69: GCAL: Timer: Interrupt index : 1 = 1 <0x2b5c9680> 06 10/08/14 19:59:17.473 Device_Variable::m_szValue_set device: 55 service: urn:rts-services-com:serviceId:ProgramLogicC variable: e[35;1mActionsMape[0m was: {} now: {} #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2ac95000> 08 10/08/14 19:59:17.474 JobHandler_LuaUPnP::HandleActionRequest device: 55 service: urn:rts-services-com:serviceId:ProgramLogicC action: e[36;1mRunScenee[0m <0x2ac95000> 08 10/08/14 19:59:17.474 JobHandler_LuaUPnP::HandleActionRequest argument SceneNameOrNumber=102 <0x2ac95000> 04 10/08/14 19:59:17.476 <Job ID="13" Name="" Device="55" Created="2014-10-08 19:59:17" Started="2014-10-08 19:59:17" Completed="2014-10-08 19:59:17" Duration="0.28059000" Runtime="0.25355000" Status="Successful" LastNote=""/> <0x2ac95000> 08 10/08/14 19:59:17.478 JobHandler_LuaUPnP::HandleActionRequest device: 0 service: urn:micasaverde-com:serviceId:HomeAutomationGateway1 action: e[36;1mRunScenee[0m <0x2ac95000> 08 10/08/14 19:59:17.478 JobHandler_LuaUPnP::HandleActionRequest argument SceneNum=102 <0x2ac95000> 08 10/08/14 19:59:17.478 Scene::RunScene running 102 (Auto) Ouvrir Volets <0x2ac95000>

Have you looked at the trigger times in the status report?

Device Properties
Name Device Name Device Variable Value Last Change Previous Change
DayOff Calendrier Cong?s Tripped 0 2014-10-08 19:59:17.417 2014-10-08 18:00:53.585
Night Night Status 0 2014-10-08 19:25:40.152 2014-10-08 07:44:20.126
Ouvrir_Volets Calendrier Ouverture Volets Tripped 0 2014-10-08 19:59:17.979 2014-10-08 16:02:25.391

it seems that the 2 gcal were tripped at 19h59 ? am I seeing right ? But, the Gcal did not get any event at this time… So I might have a look why the GCAL is doing this ?