Timer scene triggered twice

Plugins & Plugin Development openLuup
1

Hi guys,
I’m running openLuup v17.3.9 and I’ve more than one scene using timer trigger (fixed time, sunrise ecc). They work but these scenes trigger twice: I’ve an http call to imperihome and I listen the sound twice.
I’ve checked this topic [url=http://forum.micasaverde.com/index.php/topic,48929.0.html]http://forum.micasaverde.com/index.php/topic,48929.0.html[/url] but I can’t find the solution.

Taking for example the scene #36, in my scheduled jobs I have:

Scheduled Jobs, Tue Jan 9 09:15:12 2018 # date time device status info 1 2018-01-09 09:15:13 system Run job#30 :HTTP request from 192.168.1.4 2 2018-01-09 09:15:13 system Wait job#29 :HTTP request from 192.168.1.4 3 2018-01-09 09:15:15 system Wait job#14 :HTTP new connection tcp{client}: 0x11dc980 4 2018-01-09 09:15:17 system Wait job#26 :HTTP new connection tcp{client}: 0x14c6f50 5 2018-01-09 09:44:13 0 Wait job#8 :timer 'new timer' for scene [2] Sincronizzazione e fix failures 6 2018-01-09 16:54:42 0 Wait job#10 :timer 'new timer' for scene [14] Chiusura parz tapp tramonto 7 2018-01-09 17:04:42 0 Wait job#9 :timer 'new timer' for scene [6] Faretti pavimento a tramonto 8 2018-01-09 17:24:42 0 Wait job#11 :timer 'new timer' for scene [16] Chiusura tapparelle notte 9 2018-01-10 06:58:03 0 Wait job#12 :timer 'new timer' for scene [36] Faretti pavimento alba 10 2018-01-10 07:00:00 0 Wait job#7 :timer 'new timer' for scene [1] Tapparelle mattino se casa

and my log is:

018-01-09 06:58:11.587 luup.call_action:3: 0.urn:micasaverde-com:serviceId:HomeAutomationGateway1.RunScene 2018-01-09 06:58:11.589 luup_log:3: ALTUI: error: invalid parameters for thingspeak 2018-01-09 06:58:16.148 luup.variable_set:5: 10013.urn:micasaverde-com:serviceId:EnergyMetering1.Log was: 0,0,0,1515477487,1688 now: 0,0,0,1515477493,1694 #hooks:0 2018-01-09 06:58:16.149 luup.variable_set:5: 10126.urn:micasaverde-com:serviceId:EnergyMetering1.KWH was: 4549.6190 now: 4549.6410 #hooks:0 2018-01-09 06:58:16.149 luup.variable_set:5: 10126.urn:micasaverde-com:serviceId:EnergyMetering1.KWHReading was: 1515477251 now: 1515477491 #hooks:0 2018-01-09 06:58:16.149 luup.variable_set:5: 10184.urn:micasaverde-com:serviceId:EnergyMetering1.Watts was: 1.1 now: 1.4 #hooks:0 2018-01-09 06:58:16.150 luup.variable_set:5: 10184.urn:micasaverde-com:serviceId:EnergyMetering1.Log was: 1,1,1,1515477193,1394 now: 1,1,1,1515477494,1695 #hooks:0 2018-01-09 06:58:16.150 luup.variable_set:5: 10185.urn:micasaverde-com:serviceId:EnergyMetering1.Watts was: 1.2 now: 1.1 #hooks:0 2018-01-09 06:58:16.150 luup.variable_set:5: 10185.urn:micasaverde-com:serviceId:EnergyMetering1.Log was: 1,1,1,1515477193,1394 now: 1,1,1,1515477494,1695 #hooks:0 2018-01-09 06:58:21.185 luup.variable_set:5: 10013.urn:micasaverde-com:serviceId:EnergyMetering1.Log was: 0,0,0,1515477493,1694 now: 0,0,0,1515477499,1700 #hooks:0 2018-01-09 06:58:23.689 luup.scenes:: scene 36, Faretti pavimento alba, initiated by new timer 2018-01-09 06:58:24.600 luup_log:0: (IFTTTMaker)::(triggerEvent) : Request successful 2018-01-09 06:58:24.601 luup.call_action:0: 10185.urn:upnp-org:serviceId:SwitchPower1.SetTarget 2018-01-09 06:58:24.601 luup.call_action:0: action will be handled by parent: 10184 2018-01-09 06:58:24.601 luup.call_action:0: action will be handled by parent: 1 2018-01-09 06:58:24.601 luup.call_action:0: action will be handled by parent: 5 2018-01-09 06:58:24.601 luup_log:5: http://192.168.1.31:3480/data_request?id=action&serviceId=urn:upnp-org:serviceId:SwitchPower1&action=SetTarget&DeviceNum=185&newTargetValue=0 2018-01-09 06:58:25.142 luup.scenes:: scene 36, Faretti pavimento alba, initiated by new timer 2018-01-09 06:58:26.003 luup_log:0: (IFTTTMaker)::(triggerEvent) : Request successful 2018-01-09 06:58:26.076 luup.call_action:0: 10185.urn:upnp-org:serviceId:SwitchPower1.SetTarget 2018-01-09 06:58:26.076 luup.call_action:0: action will be handled by parent: 10184 2018-01-09 06:58:26.076 luup.call_action:0: action will be handled by parent: 1 2018-01-09 06:58:26.076 luup.call_action:0: action will be handled by parent: 5 2018-01-09 06:58:26.076 luup_log:5: http://192.168.1.31:3480/data_request?id=action&serviceId=urn:upnp-org:serviceId:SwitchPower1&action=SetTarget&DeviceNum=185&newTargetValue=0
As you can see the scene is run twice.

I’ve tried to use luup.call_delay(func, 1) in order to make the scene fast and make http call after, but with no luck. Retried also to recreate the scene.

Any idea?

Thanks

2

And this is the json scene

{ "Timestamp":1515280123, "favorite":false, "groups":[{ "actions":[{ "action":"SetTarget", "arguments":[{ "name":"newTargetValue", "value":"0" }], "device":"10185", "service":"urn:upnp-org:serviceId:SwitchPower1" }], "delay":0 }], "id":36, "last_run":1515477505, "lua":"local a = require(\"ricciolo.Notifications\")\na.emailCristian(\"Faretti spenti\")", "modeStatus":"0", "name":"Faretti pavimento alba", "paused":0, "room":0, "timers":[{ "days_of_week":"1,2,3,4,5,6,7", "enabled":1, "id":1, "last_run":1515477505, "name":"new timer", "next_run":1515563883, "time":"-01:00:00R", "type":2 }], "triggers":[], "triggers_operator":"OR" }

3

Updated to v17.6.15 but the issue continues :cry:

4

Update to the latest development branch 17.11.14 and give it another go.

To update, type development in the Update box on the Plugins page and press the Update button (not the Update checkbox.)

5

Great, it works correctly!

Thank you

6

Sorry, after one day the problem came back again. It seems it happens only with sunset/sunrise trigger.

My log

2018-01-12 06:57:02.833 luup_log:3: ALTUI: error: invalid parameters for thingspeak 2018-01-12 06:57:08.092 luup.variable_set:5: 10013.urn:micasaverde-com:serviceId:EnergyMetering1.Log was: 0,0,0,1515736621,1622 now: 0,0,0,1515736627,1628 #hooks:0 2018-01-12 06:57:08.095 luup.variable_set:5: 10060.urn:micasaverde-com:serviceId:ZWaveDevice1.PollOk was: 15828 now: 15829 #hooks:0 2018-01-12 06:57:13.132 luup.variable_set:5: 10013.urn:micasaverde-com:serviceId:EnergyMetering1.Log was: 0,0,0,1515736627,1628 now: 0,0,0,1515736631,1632 #hooks:0 2018-01-12 06:57:14.636 luup.scenes:: scene 36, Faretti pavimento alba, initiated by new timer 2018-01-12 06:57:14.636 luup.call_action:0: 10185.urn:upnp-org:serviceId:SwitchPower1.SetTarget 2018-01-12 06:57:14.636 luup.call_action:0: action will be handled by parent: 10184 2018-01-12 06:57:14.636 luup.call_action:0: action will be handled by parent: 1 2018-01-12 06:57:14.636 luup.call_action:0: action will be handled by parent: 5 2018-01-12 06:57:14.637 luup_log:5: http://192.168.1.31:3480/data_request?id=action&serviceId=urn:upnp-org:serviceId:SwitchPower1&action=SetTarget&DeviceNum=185&newTargetValue=0 2018-01-12 06:57:15.171 luup.scenes:: scene 36, Faretti pavimento alba, initiated by new timer 2018-01-12 06:57:16.120 luup_log:0: (IFTTTMaker)::(triggerEvent) : Request successful 2018-01-12 06:57:16.988 luup_log:0: (IFTTTMaker)::(triggerEvent) : Request successful 2018-01-12 06:57:16.988 luup.call_action:0: 10185.urn:upnp-org:serviceId:SwitchPower1.SetTarget 2018-01-12 06:57:16.989 luup.call_action:0: action will be handled by parent: 10184 2018-01-12 06:57:16.989 luup.call_action:0: action will be handled by parent: 1 2018-01-12 06:57:16.989 luup.call_action:0: action will be handled by parent: 5

The scheduler is ok

7

After some days I can tell you that it works every other day :cry:

8

So this is just the sunset/sunrise with this problem?

9

Yep

10

@ricciolo

OK, this has taken a while. Looking very closely at your earlier logs, I see multiple timer jobs for separate scenes with the same name. The only way that this can happen is for you to have modified the scene in one way or another. Is this something you do regularly?

There is clearly something wrong, in that the out-of-date scene definitions should not run, and I am hunting this down. However, in the meantime, a Luup reload should fix the multiple definitions, hence the problem, until you once again edit the scenes.

This being the case, it may well not be happening for you now, but it would be interesting to know whilst I’m still addressing the root cause.

Thanks for your patience.

11

Thank you for reply @akbooer.
To be honest I didn’t make any change. Simply the timers have the same name because when I create the scene, ALTUI asks me for a timer name and I use the default one (see attachment). Should I choose a different name?

12

Trigger names don’t matter (although it becomes a bit confusing if they’re all called new timer !)

No, I’m wrong, the confusion is all mine. I was looking at this log extract:

    7  2018-01-09 17:04:42         0      Wait  job#9 :timer 'new timer' for scene [6] Faretti pavimento a tramonto 
    8  2018-01-09 17:24:42         0      Wait  job#11 :timer 'new timer' for scene [16] Chiusura tapparelle notte 
    9  2018-01-10 06:58:03         0      Wait  job#12 :timer 'new timer' for scene [36] Faretti pavimento alba

in a narrow window on a tablet which truncated the full names, so I thought that scene 6 and 36 were multiple copies of the same, which they are not.

I continue to look into this, but have anyway tidied up the real issue of old timer jobs still lingering when there has been a redefinition of the scene.

13

I believe this problem to be fixed in the latest development version 18.1.31

Please let me know, either way!

14

No, I lied. It’s not. :frowning:

15

Now, I really believe this problem to be fixed in the latest development version 18.2.1

Please let me know, either way!