We have moved at community.getvera.com

Author Topic: Timed scenes triggering more than once?  (Read 4430 times)

Offline a-lurker

  • Hero Member
  • *****
  • Posts: 872
  • Karma: +66/-8
Timed scenes triggering more than once?
« on: May 01, 2017, 06:54:29 pm »
I have a few scenes that are triggered every day at particular times or at sunset/sunrise. Randomly (say 50/50) some of these scenes seem to be running more than once - three times in one case. It hasn't been very obvious because, for example, if you turn something off twice in a row, it's already off second time round. Note, the scene in the log below, also starts a little early.

Any one else see this - check your logs for evidence - it may just be me!

Example log report:

Code: [Select]
2017-05-01 17:54:58.456   luup_log:0: My Lua ver 0.50 debug: executing scene 9: "It is 5.55 PM" in room: "XYZ"
2017-05-01 17:54:59.947   luup_log:0: My Lua ver 0.50 debug: rest of scene 9 was executed
2017-05-01 17:54:59.947   luup.scenes:: scene 9, It is 5.55 PM, initiated by It is 5.55 PM

2017-05-01 17:54:59.958   openLuup.server:: request completed (4130 bytes, 1 chunks, 10828 ms) tcp{client}: 0x177bdd0

2017-05-01 17:55:00.001   luup.variable_set:5: 10175.urn:micasaverde-com:serviceId:EnergyMetering1.KWHReading was: 1493625254 now: 1493625295 #hooks:0
2017-05-01 17:55:00.001   luup.variable_set:5: 10175.urn:micasaverde-com:serviceId:ZWaveNetwork1.LastPollSuccess was: 1493624427 now: 1493625297 #hooks:0
2017-05-01 17:55:00.032   openLuup.server:: GET /data_request?id=user_data&output_format=json&DataVersion=497071145&_=1493447195948 HTTP/1.1 tcp{client}: 0x177bdd0

2017-05-01 17:55:00.033   luup_log:0: My Lua ver 0.50 debug: executing scene 9: "It is 5.55 PM" in room: "XYZ"
2017-05-01 17:55:01.637   luup_log:0: My Lua ver 0.50 debug: rest of scene 9 was executed
2017-05-01 17:55:01.637   luup.scenes:: scene 9, It is 5.55 PM, initiated by It is 5.55 PM

2017-05-01 17:55:02.440   openLuup.server:: request completed (1159383 bytes, 73 chunks, 2407 ms) tcp{client}: 0x177bdd0

Couple of side issues:

Note the long openLuup.server times - nearly 11 seconds in one case.

This scene above just does a luup.inet.wget. It would be good if the log reported wget URLs so you could see if they are constructed correctly when developing code.
« Last Edit: May 01, 2017, 08:43:12 pm by a-lurker »

Offline sebby

  • Sr. Member
  • ****
  • Posts: 306
  • Karma: +15/-3
Re: Timed scenes triggering more than once?
« Reply #1 on: May 01, 2017, 07:35:45 pm »
not sure what version you are on, but i was/am also having this problem:

http://forum.micasaverde.com/index.php/topic,48345.msg318773.html#msg318773

I did add a scene to reboot my vera every night ( and it seems to have calmed them down a bit... keep in mind that i did an actual reboot via os.execute as a luup reload was not doing jack...

Offline akbooer

  • Moderator
  • Master Member
  • *****
  • Posts: 6387
  • Karma: +292/-70
  • "Less is more"
Re: Timed scenes triggering more than once?
« Reply #2 on: May 02, 2017, 03:24:06 am »
not sure what version you are on, but i was/am also having this problem:

This is a completely different issue... nothing to do with openLuup.
3x Vera Lite-UI5/Edge-UI7, 25x Fibaro, 23x TKB, 9x MiniMote, 2x NorthQ Power, 2x Netatmo, 1x Foscam FI9831P, 9x Philips Hue,
Razberry, MySensors Arduino, HomeWave, AltUI, AltHue, DataYours, Grafana, openLuup, ZWay, ZeroBrane Studio.

Offline DesT

  • Sr. Member
  • ****
  • Posts: 364
  • Karma: +5/-1
Re: Timed scenes triggering more than once?
« Reply #3 on: May 02, 2017, 06:31:51 am »
AK,

I'm still having this issue also!
Vera Edge-UI7/Plus-UI7 (2), DSC Partition (5 ) + Zones Sensors(31), Nest thermostat (1) & Protect Fire/CO (3), GE Sw (8 ), GE Dimr (14), FGMS-001 (2), ZW100 (2), RZCS4 (1), AL-DSC11 (1), Aeon HEM 2nd Edition (1), Aeon SSE (5), YRD220-ZW (1), SONOS (6), MyQ Chamberlain (1)
PINE64/openLuup/ALTUI/Rules

Offline akbooer

  • Moderator
  • Master Member
  • *****
  • Posts: 6387
  • Karma: +292/-70
  • "Less is more"
Re: Timed scenes triggering more than once?
« Reply #4 on: May 02, 2017, 01:09:49 pm »
Sorry for delay in responding - my internet connection has been down all day (someone dug through the fibre!)

I'm still having this issue also!

Ah, glad you noticed the thread... I was going to say that I knew of one other with this problem.

I have a few scenes that are triggered every day at particular times or at sunset/sunrise. Randomly (say 50/50) some of these scenes seem to be running more than once - three times in one case.

So there, you see, it's not just you.  In fact, @DesT pointed this out at least a couple of months ago, and my problem since then is that I simply cannot reproduce this on any of my systems.  I have dozens of scheduled scenes, and I've never seen this happen.  It may be some function of system load, but I don't know.  I've been through the code with a fine-toothed comb several times.  If there was anything fundamentally wrong with the scheduler or timers, then NOTHING would work.

I will give more thought to the best way to approach this.  Since you're reliably seeing it, I expect that my next step would be to add some more diagnostics to the log and ask you to give that a go.

Quote
Note the long openLuup.server times - nearly 11 seconds in one case.

This is absolutely standard, indeed desirable, behaviour.  It's the 'long polling' that AltUI does to get system status (on both Vera and openLuup.)  This request is undoubtedly from AltUI and will have both Timeout and MinimumTime parameters.  Typically the response will occur within tens of seconds, when something of interest happens, but the maximum value will be 60 seconds.  It's just a mechanism to cut down on the IO between the openLuup and the AltUI browser code.

Quote
This scene above just does a luup.inet.wget. It would be good if the log reported wget URLs so you could see if they are constructed correctly when developing code.

It was a design decision not to log luup.inet.wget() requests, since there are SO many of them and they would flood the log.  If you're debugging a scene, I suggest a specific luup.log() call to record the value.
« Last Edit: May 02, 2017, 01:11:43 pm by akbooer »
3x Vera Lite-UI5/Edge-UI7, 25x Fibaro, 23x TKB, 9x MiniMote, 2x NorthQ Power, 2x Netatmo, 1x Foscam FI9831P, 9x Philips Hue,
Razberry, MySensors Arduino, HomeWave, AltUI, AltHue, DataYours, Grafana, openLuup, ZWay, ZeroBrane Studio.

Offline a-lurker

  • Hero Member
  • *****
  • Posts: 872
  • Karma: +66/-8
Re: Timed scenes triggering more than once?
« Reply #5 on: May 02, 2017, 05:08:03 pm »
Quote
someone dug through the fibre!
I dream of having fibre to dig up.

Quote
next step would be to add some more diagnostics to the log
Happy to try out any logging - what's the bet, once some logging is added, the problem will disappear?

Quote
'long polling' that AltUI does to get system status
Mmm - I thought the log was telling me it was taking that long to send the bytes.

Quote
design decision not to log luup.inet.wget() requests
OK. Vera seems to take the opposite approach and reports failed requests. May be that's a possibility - or perhaps openLuup already does that. I haven't checked.

Offline akbooer

  • Moderator
  • Master Member
  • *****
  • Posts: 6387
  • Karma: +292/-70
  • "Less is more"
Re: Timed scenes triggering more than once?
« Reply #6 on: May 02, 2017, 06:41:37 pm »
I thought the log was telling me it was taking that long to send the bytes..

No, it's the same as a browser console performance monitor: time from request to completion.

For request errors, I could perhaps add logging.  I'll take a look.
3x Vera Lite-UI5/Edge-UI7, 25x Fibaro, 23x TKB, 9x MiniMote, 2x NorthQ Power, 2x Netatmo, 1x Foscam FI9831P, 9x Philips Hue,
Razberry, MySensors Arduino, HomeWave, AltUI, AltHue, DataYours, Grafana, openLuup, ZWay, ZeroBrane Studio.

Offline a-lurker

  • Hero Member
  • *****
  • Posts: 872
  • Karma: +66/-8
Re: Timed scenes triggering more than once?
« Reply #7 on: May 02, 2017, 07:01:06 pm »
I read the background post - not very similar:
http://forum.micasaverde.com/index.php/topic,39819.0.html

Checked the user_data.json. There are no duplicate scenes.

Some of the scenes (imported from Vera) contain "interval":"1h" - which is left over fluff? Regardless I believe this is nothing to do with scenes running twice:

Code: [Select]
{
    "Timestamp":1490757743,
    "favorite":false,
    "groups":[],
    "id":9,
    "last_run":1493711702,
    "lua":"return myLua.executeSceneNumber(9)",
    "modeStatus":"0",
    "name":"It is 5.55 PM",
    "paused":"0",
    "room":33,
    "timers":[{
      "days_of_week":"1,2,3,4,5,6,7",
      "enabled":1,
      "id":1,
      "interval":"1h",
      "last_run":1493711702,
      "name":"It is 5.55 PM",
      "next_run":1493798100,
      "time":"17:55:00",
      "type":2
    }],
    "triggers":[]
  },

I checked the time stamps in the above json - shows 2 second delay on  "last_run". Also - in the log posted above you see the scene started early by about 2 seconds. And the second scene was late by two seconds. Is  "last_run"  every used to calculate anything in this case? Is the two second offset a problem? Just guessing - as I would have thought the scheduler just says it's 8 AM again - run the scene. "last_run" would not be considered or enter into the calculations.

Offline sebby

  • Sr. Member
  • ****
  • Posts: 306
  • Karma: +15/-3
Re: Timed scenes triggering more than once?
« Reply #8 on: May 02, 2017, 09:02:18 pm »
not sure what version you are on, but i was/am also having this problem:

This is a completely different issue... nothing to do with openLuup.

Yeah, i realized that after posting...  apologies for confusing things. 

Offline akbooer

  • Moderator
  • Master Member
  • *****
  • Posts: 6387
  • Karma: +292/-70
  • "Less is more"
Re: Timed scenes triggering more than once?
« Reply #9 on: May 03, 2017, 05:57:15 am »
Some of the scenes (imported from Vera) contain "interval":"1h" - which is left over fluff?

Interesting.  This should have been fixed 18 months ago in AltUI...
http://forum.micasaverde.com/index.php/topic,34864.0.html

It may be that it's left over from that time.  Would be interesting to check that it stays away if you delete it from user_data.

Incidentally, you can easily view the scene JSON by printing the scene in Lua Test:

Code: [Select]
print (luup.scenes[6])

Code: [Select]
{
  "Timestamp":1490268377,
  "favorite":false,
  "groups":[{
    "actions":[],
    "delay":0
  }],
  "id":6,
  "last_run":1493805711,
  "lua":"-- code goes herepoll Tripped status of any Ping sensors\n-- so that it's refreshed every minute even if no status change (for logging)\nlocal SID = \"urn:micasaverde-com:serviceId:SecuritySensor1\"\nfor i,d in pairs (luup.devices) do\n    if d.device_type == \"urn:schemas-demo-ted-striker:device:PingSensor:1\" then\n        local t = luup.variable_get (SID, \"Tripped\", i)\n        luup.variable_set (SID, \"TrippedPoll\", t, i)\n    end\nend\n\n",
  "modeStatus":"0",
  "name":"Ping Poll",
  "paused":0,
  "room":4,
  "timers":[{
    "enabled":1,
    "id":1,
    "interval":"1m",
    "last_run":1493805711,
    "name":"minute ping",
    "next_run":1493805771,
    "type":1
  }],
  "triggers":[]
}
3x Vera Lite-UI5/Edge-UI7, 25x Fibaro, 23x TKB, 9x MiniMote, 2x NorthQ Power, 2x Netatmo, 1x Foscam FI9831P, 9x Philips Hue,
Razberry, MySensors Arduino, HomeWave, AltUI, AltHue, DataYours, Grafana, openLuup, ZWay, ZeroBrane Studio.

Offline a-lurker

  • Hero Member
  • *****
  • Posts: 872
  • Karma: +66/-8
Re: Timed scenes triggering more than once?
« Reply #10 on: May 03, 2017, 06:04:16 am »
Quote
should have been fixed 18 months ago in AltUI

Probably was - I'll manually delete them - like I said; just fluff.

Offline DesT

  • Sr. Member
  • ****
  • Posts: 364
  • Karma: +5/-1
Re: Timed scenes triggering more than once?
« Reply #11 on: May 03, 2017, 02:19:19 pm »
AK,

If I can do anything to help... let me know.   I'm still having this issue.  Not every day and not for all the same scene!

Yesterday got the issue at least with 4 scenes.  Today, got it one time already!

Vera Edge-UI7/Plus-UI7 (2), DSC Partition (5 ) + Zones Sensors(31), Nest thermostat (1) & Protect Fire/CO (3), GE Sw (8 ), GE Dimr (14), FGMS-001 (2), ZW100 (2), RZCS4 (1), AL-DSC11 (1), Aeon HEM 2nd Edition (1), Aeon SSE (5), YRD220-ZW (1), SONOS (6), MyQ Chamberlain (1)
PINE64/openLuup/ALTUI/Rules

Offline DesT

  • Sr. Member
  • ****
  • Posts: 364
  • Karma: +5/-1
Re: Timed scenes triggering more than once?
« Reply #12 on: May 03, 2017, 03:05:55 pm »
I also check to make sure, the problem is not coming from the clock!

offset -0.002822 sec

My NTP config works fine and with a 0.002 sec ofset, don't think the problem come from the clock!
Vera Edge-UI7/Plus-UI7 (2), DSC Partition (5 ) + Zones Sensors(31), Nest thermostat (1) & Protect Fire/CO (3), GE Sw (8 ), GE Dimr (14), FGMS-001 (2), ZW100 (2), RZCS4 (1), AL-DSC11 (1), Aeon HEM 2nd Edition (1), Aeon SSE (5), YRD220-ZW (1), SONOS (6), MyQ Chamberlain (1)
PINE64/openLuup/ALTUI/Rules

Offline akbooer

  • Moderator
  • Master Member
  • *****
  • Posts: 6387
  • Karma: +292/-70
  • "Less is more"
Re: Timed scenes triggering more than once?
« Reply #13 on: May 03, 2017, 04:17:49 pm »
Thanks for the offers of help.

I did worry whether there was a clock-related thing going on.  In particular, I checked that this:

Code: [Select]
local socket = require "socket"
print (os.time(), socket.gettime())

gave compatible answers.  On my system, it does:

Code: [Select]
1493842887 1493842887.1853

When I think of the next step, I'll be asking...
3x Vera Lite-UI5/Edge-UI7, 25x Fibaro, 23x TKB, 9x MiniMote, 2x NorthQ Power, 2x Netatmo, 1x Foscam FI9831P, 9x Philips Hue,
Razberry, MySensors Arduino, HomeWave, AltUI, AltHue, DataYours, Grafana, openLuup, ZWay, ZeroBrane Studio.

Offline a-lurker

  • Hero Member
  • *****
  • Posts: 872
  • Karma: +66/-8
Re: Timed scenes triggering more than once?
« Reply #14 on: May 03, 2017, 04:49:49 pm »
AK - I get this:

1493844308    1493844308.1115