caldavio/caldav-command : multiple "events begin" fired for single calendar event

[aschor]

I am playing with caldav command, to try to trigger my heaters via calendar events. To play faster, I have set the reload time to 1 min in the conf. Issue also with 30 min set, see comment below.
I found out that an "event BEGIN" is triggered every minute during the duration of a calendar event, that is each time the calendar binding refreshes events from the caldav calendar (and while an event is active)

Expected Behavior

If an event has started, it is not supposed to start again even if the binding refreshes the events list. But it must be aware of an event that has already run (and is not running anymore), and that has been "recycled" for a future event to act as if it was a new event

Current Behavior

every time the binding reloads the events list, the "begin" line of the running events is triggered, wich is quit problematic :

my logs (look at the timestamps, I checked and the command WAS sent):

2016-10-10 12:12:00.011 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)
2016-10-10 12:12:00.014 [INFO ] [aldav_command.internal.CalDavBinding] - sending command 'on' to item 'gRadCaldavEtage' from event '9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)'

2016-10-10 12:12:23.022 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)
2016-10-10 12:12:23.024 [INFO ] [aldav_command.internal.CalDavBinding] - sending command 'on' to item 'gRadCaldavEtage' from event '9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)'

2016-10-10 12:13:22.989 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)
2016-10-10 12:13:22.991 [INFO ] [aldav_command.internal.CalDavBinding] - sending command 'on' to item 'gRadCaldavEtage' from event '9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)'

2016-10-10 12:14:22.946 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)
2016-10-10 12:14:22.948 [INFO ] [aldav_command.internal.CalDavBinding] - sending command 'on' to item 'gRadCaldavEtage' from event '9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)'

2016-10-10 12:15:22.980 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)
2016-10-10 12:15:22.982 [INFO ] [aldav_command.internal.CalDavBinding] - sending command 'on' to item 'gRadCaldavEtage' from event '9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)'

2016-10-10 12:16:00.007 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event END for: 9f4a95ae-912a-4dca-9546-fc10adc1469a(test_etage@10.10.2016/12:12-10.10.2016/12:16)

Possible Solution

check the running events before reloading the list from the caldav server, and don't fire the "begin" lines from them if we already have fired them

Steps to Reproduce (for bugs)

1. caldavio configuration :
   caldavio:chauffagecmd:reloadInterval=1
   caldavio:chauffagecmd:preloadTime=1440
2. set an event for a duration of x minutes
3. watch the logs fire a "event BEGIN" for the same event, each minute

Context

Your Environment

• Version used: openhab 2.0beta4
• Environment name and version : java8 on raspberry pi 3
• Operating System and version : raspbian jessie

[aschor]

creating the issue under openhab2 addons, closing this one

[aschor]

I was told it was the right place to open the issue, so here it is reopened.

confirmed also with a 30 min reload time in caldavio.cfg :

caldavio:chauffagecmd:reloadInterval=30

resulting in :

2016-10-21 09:40:17.383 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: b8edd2fc-c5a2-4cbd-97c7-600f9c264ab1(teletravail@21.10.2016/09:00-21.10.2016/18:00)
2016-10-21 09:40:17.385 [INFO ] [aldav_command.internal.CalDavBinding] - sending command 'on' to item 'Rad_bureau_A_command' from event 'b8edd2fc-c5a2-4cbd-97c7-600f9c264ab1(teletravail@21.10.2016/09:00-21.10.2016/18:00)'
.......
2016-10-21 10:10:17.219 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: b8edd2fc-c5a2-4cbd-97c7-600f9c264ab1(teletravail@21.10.2016/09:00-21.10.2016/18:00)
2016-10-21 10:10:17.220 [INFO ] [aldav_command.internal.CalDavBinding] - sending command 'on' to item 'Rad_bureau_A_command' from event 'b8edd2fc-c5a2-4cbd-97c7-600f9c264ab1(teletravail@21.10.2016/09:00-21.10.2016/18:00)'
........
2016-10-21 10:40:17.555 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: b8edd2fc-c5a2-4cbd-97c7-600f9c264ab1(teletravail@21.10.2016/09:00-21.10.2016/18:00)
2016-10-21 10:40:17.557 [INFO ] [aldav_command.internal.CalDavBinding] - sending command 'on' to item 'Rad_bureau_A_command' from event 'b8edd2fc-c5a2-4cbd-97c7-600f9c264ab1(teletravail@21.10.2016/09:00-21.10.2016/18:00)'
........
etc.

wich off course is an issue if I decide (because say I leave home) to send an "off command" to my heater, I know that in less that 30 min it will receive an "on" again ....

[Elv1zz]

Also confirmed in earlier version:

Your Environment

Version used: openhab 1.8.3, caldav-command 1.8.3
Environment name and version : java8 on Ubuntu 14.04
Operating System and version : Ubuntu 14.04

[aschor]

hi, found out that adding the following configuration to caldavio.cfg did solve the issue for me :
caldavio:chauffagecmd:lastModifiedFileTimeStampValid=False

this is however not documented I think

[9037568]

I added a troubleshooting note to the wiki.