Problems with BEGIN Events in iCalendar 3.0.1

Add-ons Bindings
1

Hi all

I have a problem with the iCalendar Binding in OH3. According to the event logfile the Items that should be modified in the events (e. g. BEGIN:SWT_Homeoffice:ON) did not occur at the starttime of the event (in this case 6:30) but some time later (actually 7:10).
I guess this is the refresh time, my interval is 60min.

The END events were executed at the correct time, and also the calendar items I show in the frontend are correct.

For clarification here some logentries:

Change of the calendar items:

2021-03-05 05:15:00.199 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'VAL_Calendar_Name' changed from Wecker to Homeoffice
2021-03-05 05:15:00.200 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'VAL_Calendar_Start' changed from 2021-03-05T05:15:00.000+0100 to 2021-03-05T06:30:00.000+0100
2021-03-05 05:15:00.200 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'VAL_Calendar_End' changed from 2021-03-05T10:00:00.000+0100 to 2021-03-05T15:00:00.000+0100

The actual change:

2021-03-05 07:10:45.619 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'SWT_Homeoffice' received command ON
2021-03-05 07:10:45.620 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SWT_Homeoffice' changed from OFF to ON

Am I missing something? Of course I could easily write a rule that does update the events. But the idea was to use the binding.

Regards
Dieter

2

The scheduling is written for triggering the changes for beginnings and ends exactly (second precision). I was not able to reproduce this on my daily used system. But i had similar behaviour on a system where i found OutOfMemoryExceptions in the logs also.

Please increase the log level generally (not just for icalendar, as f.e. scheduling is based on the framework) for debugging.

3

Hi Michael
Thank you for your answer. I’ve set the level to debug in the logger org.openhab, but personally couldn’t find any relevant information.
Nevertheless I attach the log from 7:55 to 8:15 this morning, maybe it helps you: openhab.log (158.4 KB)
The event that took place at 8:11 was scheduled for 8:00. (Before you ask: I removed log messages that were not for the public and have nothing to do with that problem).

I also send you my things configuration, maybe you can find the problem there:

Bridge icalendar:calendar:smarthome "Smarthome Kalendar" [
    url="https://xxx/remote.php/dav/calendars/openhab/smarthome_shared_by_dieter@dblamberty.de/?export",
    refreshTime=60,
    username="xxx",
    password="xxx"
]

If you need any more information, please feel free to ask.

Thanks & regards
Dieter

4

Hi Dieter,

hm, anything there what leads to more details. The strange thing is, after downloading, a rescheduling is done which logs in every case something. But that is missing in your log. Using a current version, the last update time is also saved into a channel. Maybe this leads to the real error.

Regards,
Michael

5

Hi Michael

It seems that I was able to track down the problem: It seems to have something to do with overlapping events.

Let’s say you have an event from 7 to 9 and one from 8 to 10. In this case the start at 8 won’t be triggered in time. If the first event ends before 8, everything is ok (I guess this is the reason why it works for you and probably most others)

In my installation I use this for most time-based events, e.g. start heating in the morning and end again in the evening. This makes it more flexible that hard-coded rules. As a workaround I’ve now split my events (one for start, one for end) to remove the overlapping and now it works for my as well.

Nevertheless it would be nice if you fix it in a future release (so that I could go on with the next problem: changes in recurring events :wink: )

Regards
Dieter

6

This is still strange. I would expect that the actions defined should be executed at least at any beginning or end of an event. Was there something ending at 8:11?

This is quite hard to debug without the required data and specific information. In this case i can’t fix anything, because i still can’t identify anything.

Also i do not know any issues about recurring events beside there was an issue with endless series which is already solved.

If you don’t want to share your productive calendar and data that is okay. But i need some data to reproduce this. In combination of both requirements that does mean i need a test calendar for both issues for reproduction of the issues - in best case an automated test can be written (depends on which part of the binding causes the issues).

7

Hi Michael

I would also expect this, that‘s why I started this thread.
To make things a bit clearer: If there are overlapping events, the start trigger does not occur at the beginning of the event but on the next regular refresh (this happened at 8:11). After I removed the overlapping (by creating seperat start and end events) the problem is solved.

I guess you should be able to reproduce it quite easily. If not, there might be another issue. But in that case it can be anywhere, maybe even in OS configuration and I have no idea where to look for it…

The problem with recurring events already existed in OH1 in the caldav binding. It comes up if you move a single event to a different time, e.g. an hour later. In this case OH has both events, the original and the moved one. The workaround is to delete the single event and create a new one. But that‘s a different topic, and I must admit that I‘m not even sure whether or not I tested it already on OH3.

Regards
Dieter

8

There is no regular refresh without rescheduling (which should have been logged, scheduling is done by next event, end of current event or reload of calendar, but not regularly if an event is “now or in future”). If there are overlapping events the command tags still seems to be executed at the beginning or end of an event. In my reproducible case i had two events, one ending two minutes after the begin of a second one. There the command tags were executed at the end of the first event. I would now expect the binding to behave differently but will take a bit work as the solution is not as easy as the scheduling is currently done per event.

The point in time which seems random is something i can’t reproduce. Sorry.

9

Hi Michael

The 8:11 was the calendar reload, sorry if I haven‘t stated that clearly. So I understand that you had both events, the start of the second and the end of the first at the same time? If yes, this should be the problem. I just didn‘t have it that way, as the overlapping of my events was serveral hours. But it fit‘s into the scheme.

As I now have a workaround it‘s no longer an urgent problem, at least for my point of view.

Regards
Dieter

10

I face the exact same problem. Here is a screenshot of my calender:

image
image1370×304 6.34 KB

I have multiple timers and each timer triggers a different switch. And all BEGIN-events are not fired on time.

This is my thing -config:

Bridge icalendar:calendar:google “Kalender” [ url=“google-url”, refreshTime=1, username=“username”, password=“password” ]
Thing icalendar:eventfilter:bedroom “Timer-Schlafzimmer-Wecker” (icalendar:calendar:google) [ maxEvents=1, refreshTime=10, datetimeUnit=“DAY”, datetimeStart=0, datetimeEnd=1, datetimeRound=true, textEventField=“SUMMARY”, textEventValue=“Timer-Schlafzimmer-Wecker”, textValueType=“TEXT”]
Thing icalendar:eventfilter:hall “Timer-Flur-Decke” (icalendar:calendar:google) [ maxEvents=1, refreshTime=10, datetimeUnit=“DAY”, datetimeStart=0, datetimeEnd=1, datetimeRound=true, textEventField=“SUMMARY”, textEventValue=“Timer-Flur-Decke”, textValueType=“TEXT”]
Thing icalendar:eventfilter:livingroom “Timer-Wohnzimmer-Deko” (icalendar:calendar:google) [ maxEvents=1, refreshTime=10, datetimeUnit=“DAY”, datetimeStart=0, datetimeEnd=1, datetimeRound=true, textEventField=“SUMMARY”, textEventValue=“Timer-Wohnzimmer-Deko”, textValueType=“TEXT”]
Thing icalendar:eventfilter:blinds “Timer-Jalousie” (icalendar:calendar:google) [ maxEvents=1, refreshTime=10, datetimeUnit=“DAY”, datetimeStart=0, datetimeEnd=1, datetimeRound=true, textEventField=“SUMMARY”, textEventValue=“Timer-Jalousie”, textValueType=“TEXT”]
Thing icalendar:eventfilter:vacation “Timer-Urlaub” (icalendar:calendar:google) [ maxEvents=1, refreshTime=10, datetimeUnit=“DAY”, datetimeStart=0, datetimeEnd=1, datetimeRound=true, textEventField=“SUMMARY”, textEventValue=“Timer-Urlaub”, textValueType=“TEXT”]
Thing icalendar:eventfilter:test “Timer-Test” (icalendar:calendar:google) [ maxEvents=1, refreshTime=1, datetimeUnit=“DAY”, datetimeStart=0, datetimeEnd=1, datetimeRound=true, textEventField=“SUMMARY”, textEventValue=“Timer-Test”, textValueType=“TEXT”]

this is my item config:

DateTime CalDav_Hall_Start “Flur - Beginn [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:hall:result_0#begin” }
DateTime CalDav_Hall_End “Flur - Ende [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:hall:result_0#end” }
DateTime CalDav_Bedroom_Start “Schlafzimmer-Wecker - Beginn [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:bedroom:result_0#begin” }
DateTime CalDav_Bedroom_End “Schlafzimmer-Wecker - Ende [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:bedroom:result_0#end” }
DateTime CalDav_Livingroom_Start “Wohnzimmer-Deko - Beginn [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:livingroom:result_0#begin” }
DateTime CalDav_Livingroom_End “Wohnzimmer-Deko - Ende [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:livingroom:result_0#end” }
DateTime CalDav_Blinds_Start “Jalousie - Beginn [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:blinds:result_0#begin” }
DateTime CalDav_Blinds_End “Jalousie - Ende [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:blinds:result_0#end” }
DateTime CalDav_Vacation_Start “Urlaub - Beginn [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:vacation:result_0#begin” }
DateTime CalDav_Vacation_End “Urlaub - Ende [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:vacation:result_0#end” }
DateTime CalDav_Test_Start “Test - Beginn [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:test:result_0#begin” }
DateTime CalDav_Test_End “Test - Ende [%1$td.%1$tm.%1$tY, %1$tT]” { channel=“icalendar:eventfilter:test:result_0#end” }

is this enough or can I provide more information?

11

@DieterL please check out the tomorrows snapshot or newer. I’ve changed the scheduling of events. short events are now also shown as current events.