search

openhab / openhab1-addons

Add-ons for openHAB 1.x
Eclipse Public License 2.0
3.43k stars 1.71k forks source link

[CalDAV-personal] Switch item ON only during server reload, but on time for OFF #5744

Closed Tobster77 closed 5 years ago

Tobster77 commented 5 years ago

Dear all,

I observed a behaviour for CalDAV-personal I cannot explain and it is really disturbing. I created a discussion here: https://community.openhab.org/t/caldav-personal-switch-item-is-always-delayed-for-on-on-time-for-off/60964.

Edit: Same issue is reported here: https://community.openhab.org/t/caldav-peronal-event-sheduled-only-at-reload/16320/2 and here: https://community.openhab.org/t/delayed-caldav-execution/34969

Expected Behavior

The switch associated with a CalDAV-personal calendar should fire on time both for end and beginning of an event

Current Behavior

If I got it right, the binding provides the ability to set a switch ON at the beginning of the event and OFF at its end. This does not work for me. The scheduler seems to create the jobs correctly, but only the end of the event fires the switch on time.

However, the trigger is fired when the reloadInterval for checking the server occurs.

Example: I scheduled an event to switch on a power plug at 02:00h and to switch it off at 03:00h. However, the switch is only activated at 2:22h, but deacitvated on time at 03:00h exactly.

Possible Solution

The scheduler does not seem to trigger the Switch item. The trigger is only fired when the reloadInterval for checking the server occurs.

Steps to Reproduce (for bugs)

  1. Create a CalDAV calender and filll it with events
  2. Create a Switch associated with that calendar
  3. Wait for switch going to ON (delayed)
  4. Wait for switch going to OFF (on time)

Context

I try to switch a plug for my TV recorder depending on the TV program in my calendar

Your Environment

9037568 commented 5 years ago

Need to attach logs and configs.

Tobster77 commented 5 years ago

Need to attach logs and configs.

Please find the files attached. Note, I had events in my calendar, e.g. from 18:11h-18:14h... Note, I used a setting caldavio:Recordings:reloadInterval=5. Indeed, the Switch is updated (and thus switched on) if the 5min interval occurs, but not on the event begin. In the logs I posted, the system went online at 18:06h, needed some time as I cleaned the cache before, and loads the CalDAV scheduler at 18:08h. Accordingly, the Switch is set to ON 5 mins later at 18:13h (delayed) while I expected it to switch ON at 18:11h. At 18:14h, the Switch goes offline on time!

The logs cover this time. I removed personal information like calendar ID, mail address, password etc. and replaced them by values of x.

Note I tested dozens of times, over night, immediately after reboots and also several hours after reboots. Same behaviour. openhab_caldav.zip

9037568 commented 5 years ago

We'll also need details on the events you had in the calendar for the time period covered by the log.

Tobster77 commented 5 years ago

We'll also need details on the events you had in the calendar for the time period covered by the log.

Here we go: 18:11h - 18:14 Event name 11111 18:16h - 18:19h Event name 22222 18:21h - 18:23h Event name 33333 The location and the event description are empty. Does this help?

9037568 commented 5 years ago

I don't see any output from your rules in these logs. The openhab log also stops in the middle of the second event (18:18).

And I'm not seeing anything probative.

I suggest you reset the log levels to TRACE and recapture. I would also recommend resetting the calendar refresh to 30 minutes or more so that no calendar refreshes occur during the set of events you're trying to test.

Tobster77 commented 5 years ago

First of all, thanks for caring :-)

Unfortunately I left for some days and can only provide a more detailed log next week.

Indeed, my issue is not related to any rule: I simply wait for the calendar Items to be switched. They should serve for applying rules later on.

The binding is already set to trace. If you go through the logs, you can see that while in the openhab.log the scheduler logs on time for both START (18:11h) and STOP (18:14h), in event.log the switch is only fired on time for STOP. At 18:13h, the calendar refresh fires the switch.

If you prefer, I will list the precise timestamps until tomorrow.

Am I wrong in the expectation of the binding behaviour or interpretion of the log data?

9037568 commented 5 years ago

The binding is already set to trace.

Not as far as I can tell. The logs don't contain any of the trace events they should.

I can't say you're wrong. It does appear the ON event is delayed in the events log. But I'm not seeing a cause.

Do you have a large number of rules running? Have you checked the installed bundles for oddities/conflicts?

Tobster77 commented 5 years ago

That is weird. I yesterday set the TRACE level, but I will double check next weekend.

I also see no root cause. The scheduler seems to have a complete list of all events and works for OFF events and also time-triggered rules using CRON statements.

I use three to four rules currently. One fires at midnight or so (and is always on time, by the way), the others are triggered by manual switches. I use three timers within the rules, e.g. to have time delays for switching off the lights. They work also fine.

That's it... quite small setup.

Maybe someone could do a test and try to use a Switch item with CalDAV-personal, in the ideal case using a RPi? I found no example on the web of people really using the binding with the Switch item. Most people use CalDAV-command for firing events. So maybe the issue has simply not been discovered yet? Thanks!

Tobster77 commented 5 years ago

So no one uses CalDAV-personal and the associated Switch?

9037568 commented 5 years ago

You're more likely to get an answer to that question in the forum. Not too many people will see it here.

Tobster77 commented 5 years ago

What does the removal of the "awaiting-feedback" label mean? Should I do something? Thanks

9037568 commented 5 years ago

It means we're not waiting for anything from you. You can add updates as you wish (e.g. a TRACE log).

Tobster77 commented 5 years ago

I don't see any output from your rules in these logs. The openhab log also stops in the middle of the second event (18:18).

And I'm not seeing anything probative.

I suggest you reset the log levels to TRACE and recapture. I would also recommend resetting the calendar refresh to 30 minutes or more so that no calendar refreshes occur during the set of events you're trying to test.

@9037568 I did a completely new and fresh install of the WHOLE system. The only add-on is CalDAV-personal. TRACE level is now set which I indeed forgot before. Log files attached. There is an event that should switch ON at 15:05h and OFF at 15:10h. The behaviour is as before: ON is not happening, OFF ist switched on time!

Note, after installation, an error occured on specifying caldavio.cfg and caldavPersonal.cfg. Therefore, I rebooted the system at 15:01h. Maybe, because I deleted some older entries in the calendar and thus confused the database? Therefore, I rebooted the system. Afterwards, there was no error. events.log openhab.log

Tobster77 commented 5 years ago

I also tested a completely different CalDAV provider. Same problem...

So this really confuses me. I changed everything (except the RPi hardware, the switch definition and the config files), but still have the issue.

To summarize: I changed the installation and started from scratch. I changed the CalDAV provider. Still no success. Whether I do a fundamental mistake in using the Switch, or the Switch implementation of the binding is broken.

Tobster77 commented 5 years ago

Today I tested OH snapshot (2.5 no. 1491) on an x86 Linux machine using Xubuntu.

I just copied my config and item files. The missing fire for the Switch occurs there as well.

Some people reported that their Switch is working. Is it possible that they chose a periodic server check (reloadInterval) of one minute or so? This would mean the trigger comes on time, but that also the caldendar server is called every minute which makes no sense…

Tobster77 commented 5 years ago

Same issue is reported here: https://community.openhab.org/t/caldav-peronal-event-sheduled-only-at-reload/16320/2 and here: https://community.openhab.org/t/delayed-caldav-execution/34969

Tobster77 commented 5 years ago

The user who reported the issue already here https://community.openhab.org/t/caldav-peronal-event-sheduled-only-at-reload/16320/2 told that the Switch did not work reliability already in OpenHAB 1 back in 2016... So it seems not to be an issue of the major version change!

Tobster77 commented 5 years ago

@hakan42 I was informed you have some experience in this binding. As the original developer is not active anymore: Would you be able and interested in fixing this? I will help as much as I can, but I am no Java programmer... Thanks a lot in advance :-)

MathiasMoog commented 5 years ago

@Tobster77 I had a look on the soruce code. In CalDavBinding.java, method eventBegins I wounderd about the if (event.getStart().isBeforeNow()). Strange, if the event had been started, this condition is allways true and hence no update is performed. I remove the if an add some debug information:

public void eventBegins(CalDavEvent event) {
        logger.debug("event begins: {}", event.getShortName());
        if (!calendars.contains(event.getCalendarId())) {
            return;
        }

        logger.debug("check start of event: {}", event.getShortName());
        // if (event.getStart().isBeforeNow()) {
        logger.debug("event start time: {} ", event.getStart().toString());
        logger.debug("now:              {} ", DateTime.now().toString());
        // return;
        // }

        logger.debug("adding event to map: {}", event.getShortName());

        this.updateItemsForEvent();
    }

The fix worked for me, but I am not familar with the caldav-personal bindings. Someone who has more experience with that binding should check it. Here is a sample output from my check:

2019-01-18 08:00:00.014 [DEBUG] [ldav_personal.internal.CalDavBinding] - check start of event: 0fb10038-28d8-439c-97a8-487b53b39639(Abschließender Test@18.01.2019/08:00-18.01.2019/08:10)
2019-01-18 08:00:00.016 [DEBUG] [ldav_personal.internal.CalDavBinding] - event start time: 2019-01-18T08:00:00.000+01:00 
2019-01-18 08:00:00.018 [DEBUG] [ldav_personal.internal.CalDavBinding] - now:              2019-01-18T08:00:00.017+01:00 
2019-01-18 08:00:00.019 [DEBUG] [ldav_personal.internal.CalDavBinding] - adding event to map: 0fb10038-28d8-439c-97a8-487b53b39639(Abschließender Test@18.01.2019/08:00-18.01.2019/08:10)

If you want to try it, you find it on my fork https://github.com/MathiasMoog/openhab1-addons.git. Use the branch caldav_fix_5744. I did not create a pull request since my code contains a lot of debug output.

Tobster77 commented 5 years ago

@MathiasMoog Dear Mathias, thanks a lot! If this is a fix, we made a great step. As I am not able to compile, I hope some programmer will find the time to confirm the bug and the fix.

@hakan42: Maybe this could be a hint?

9037568 commented 5 years ago

I made a few modifications to the code change suggested:

    public void eventBegins(CalDavEvent event) {
        logger.debug("eventBegins() called for event '{}'", event.getShortName());

        if (!calendars.contains(event.getCalendarId())) {
            logger.debug("event calendarId does not exist in calendars");
            return;
        }

        logger.debug("check start of event '{}'", event.getShortName());
        if (event.getStart().isBeforeNow()) {
            logger.warn("event is before now; ignoring and updating anyway.");
            logger.debug("event start time: {} ", event.getStart());
            logger.debug("now:              {} ", DateTime.now());
        //    return;
        }

        logger.debug("adding event to map: {}", event.getShortName());

        this.updateItemsForEvent();
    }

These jars contain the change: caldav-io caldav-personal

Tobster77 commented 5 years ago

@9037568, @MathiasMoog I tested the JARs: Removed the standard binding, cleared cache and tmp directories and copied the two *.jar files to the addon-folder.

Unfortunately, I receive errors during startup: `2019-01-22 20:56:18.306 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI

2019-01-22 20:56:18.344 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel

2019-01-22 20:56:18.362 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Stopped Home Builder

2019-01-22 20:56:18.389 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard

2019-01-22 20:58:59.250 [WARN ] [org.apache.felix.fileinstall ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.io.caldav-1.14.0-SNAPSHOT.jar

org.osgi.framework.BundleException: Could not resolve module: org.openhab.io.caldav [192]

Unresolved requirement: Import-Package: org.apache.commons.codec

at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]

at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.startAllBundles(DirectoryWatcher.java:1221) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:515) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [10:org.apache.felix.fileinstall:3.6.4]

2019-01-22 20:58:59.287 [WARN ] [org.apache.felix.fileinstall ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.caldav-personal-1.14.0-SNAPSHOT.jar

org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.caldav-personal [191]

Unresolved requirement: Import-Package: org.openhab.core.binding

at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]

at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:520) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [10:org.apache.felix.fileinstall:3.6.4]

2019-01-22 20:58:59.304 [WARN ] [org.apache.felix.fileinstall ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.io.caldav-1.14.0-SNAPSHOT.jar

org.osgi.framework.BundleException: Could not resolve module: org.openhab.io.caldav [192]

Unresolved requirement: Import-Package: org.apache.commons.codec

at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]

at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:520) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [10:org.apache.felix.fileinstall:3.6.4]

at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [10:org.apache.felix.fileinstall:3.6.4]

2019-01-22 20:59:07.924 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.

2019-01-22 20:59:07.942 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.

2019-01-22 20:59:08.986 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.0.18:8080

2019-01-22 20:59:08.991 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.0.18:8443

2019-01-22 20:59:25.262 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.rules'

2019-01-22 20:59:29.556 [ERROR] [org.eclipse.smarthome.core ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(72)] : doFindMethod: Suitable but non-accessible method found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl

2019-01-22 20:59:29.561 [ERROR] [org.eclipse.smarthome.core ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(72)] : findMethod: Suitable but non-accessible method setScheduler found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl, subclass of org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl

2019-01-22 20:59:29.566 [ERROR] [org.eclipse.smarthome.core ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(72)] : bind method [setScheduler] not found; Component will fail

2019-01-22 20:59:29.569 [ERROR] [org.eclipse.smarthome.core ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(72)] : bind method [setScheduler] not found

2019-01-22 20:59:29.574 [ERROR] [org.eclipse.smarthome.core ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(72)] : doFindMethod: Suitable but non-accessible method found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl

2019-01-22 20:59:29.577 [ERROR] [org.eclipse.smarthome.core ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(72)] : findMethod: Suitable but non-accessible method unsetScheduler found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl, subclass of org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl

2019-01-22 20:59:29.580 [ERROR] [org.eclipse.smarthome.core ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(72)] : unbind method [unsetScheduler] not found; Component will fail

2019-01-22 20:59:29.583 [ERROR] [org.eclipse.smarthome.core ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(72)] : unbind method [unsetScheduler] not found`

hakan42 commented 5 years ago

Seems like you are using the M1 milestone build (or even current SNAPSHOT builds).

Startup problems are reported in the forums, I'd suggest waiting a few days until the big move from ESH to openHAB ist finalized.

Tobster77 commented 5 years ago

Okay, so this is related to 2.5 M1, not due to the manually added JARs? I am on milestone...

Tobster77 commented 5 years ago

Seems like you are using the M1 milestone build (or even current SNAPSHOT builds). Startup problems are reported in the forums, I'd suggest waiting a few days until the big move from ESH to openHAB ist finalized.

I also have a testing system with 2.4 release on an old laptop: I uninstalled the original CalDAV binding, deleted the cache and copied the files "org.openhab.binding.caldav-personal-1.14.0-SNAPSHOT.jar" and "org.openhab.io.caldav-1.14.0-SNAPSHOT" into the directory "/usr/share/openhab/addons". Then made an OH restart.

However, I receive errors, see attached log. Did I forget something?

These "Could not resolve module: org.openhab.io.caldav" error appeared in both setups, so maybe I'm doing something wrong or there is an issue with the *.jar files?

openhab.log.txt

Tobster77 commented 5 years ago

Dear all,

@hakan42, @9037568, @MathiasMoog : I re-tested the fix as provided by @9037568.

I could swear that I didn't change anything since my first tests where I only received errors , but now the switch triggers on time!

Beautiful!

I still get scheduler error messages at the beginning (see below), but these might be related to the general OH 2.5 issues.

2019-01-28 06:31:34.570 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(107)] : doFindMethod: Suitable but non-accessible method found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl

2019-01-28 06:31:34.576 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(107)] : findMethod: Suitable but non-accessible method setScheduler found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl, subclass of org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl

2019-01-28 06:31:34.582 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(107)] : bind method [setScheduler] not found; Component will fail
2019-01-28 06:31:34.585 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(107)] : bind method [setScheduler] not found
2019-01-28 06:31:34.589 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(107)] : doFindMethod: Suitable but non-accessible method found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl
2019-01-28 06:31:34.594 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(107)] : findMethod: Suitable but non-accessible method unsetScheduler found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl, subclass of org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl
2019-01-28 06:31:34.596 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(107)] : unbind method [unsetScheduler] not found; Component will fail
2019-01-28 06:31:34.599 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(107)] : unbind method [unsetScheduler] not found
...
...
019-01-29 15:55:00.003 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@29.01.2019/15:55-29.01.2019/17:15)
2019-01-29 15:55:00.004 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@30.01.2019/15:55-30.01.2019/17:15)
2019-01-29 15:55:00.008 [WARN ] [ldav_personal.internal.CalDavBinding] - event is before now; ignoring and updating anyway.
2019-01-29 15:55:00.236 [INFO ] [smarthome.model.script.Regel Horizon] - Calendar event switched Horizon power plug ON: Aufnahme "Verrückt nach Meer"
2019-01-29 16:05:02.399 [INFO ] [ome.model.script.Regel Entertainment] - TV set status to on!
2019-01-29 17:15:00.003 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event END for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@29.01.2019/15:55-29.01.2019/17:15)
2019-01-29 17:15:00.004 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event END for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@30.01.2019/15:55-30.01.2019/17:15)
2019-01-29 17:15:00.155 [INFO ] [smarthome.model.script.Regel Horizon] - Command sent to Horizon power plug is OFF!

Great! Maybe someone - Mathias? Chris? - could make a pull request for the code in the latest version, i.e. as provided in the *.jar files by Chris?

Stupid that I don't know why the manual add-on didn't work at the beginning. Strange...

9037568 commented 5 years ago

I'd want to see a debug log to try to understand why this fix changes the result.

We might need to make this user configurable...

9037568 commented 5 years ago

I also just noticed you appear to be getting events you shouldn't be getting.

The event for 1/30 shouldn't be getting a begin or an end here...

019-01-29 15:55:00.003 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@29.01.2019/15:55-29.01.2019/17:15)
2019-01-29 15:55:00.004 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@30.01.2019/15:55-30.01.2019/17:15)
[...]
2019-01-29 17:15:00.003 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event END for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@29.01.2019/15:55-29.01.2019/17:15)
2019-01-29 17:15:00.004 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event END for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@30.01.2019/15:55-30.01.2019/17:15)
Tobster77 commented 5 years ago

I'd want to see a debug log to try to understand why this fix changes the result.

@9037568 Chris, I did a logging today for nearly the full day, with a scheduled recording from 15:55h to 17:15h. You will see that the rule "Regel Horizon" is triggered on time which is simply depending on the Switch Item associated with the CalDAV-personal calendar.

The binding was set to DEBUG. I hope this helps. If you prefer TRACE or something, please let me know :-)

caldav_log_2019_01_30.txt

We might need to make this user configurable...

Just because I'm curious: What exactly do you have in mind to make user configurable?

I also just noticed you appear to be getting events you shouldn't be getting. The event for 1/30 shouldn't be getting a begin or an end here...

Absolutely true. I did not recognize this, thank you! Indeed, the event is scheduled for 1/30 as well (from Monday to Friday), but I assume it should not appear in this situation.

Still, the fix sets the trigger for ON on time which was not the case before...

Tobster77 commented 5 years ago

Can I do something else?

9037568 commented 5 years ago

That log looks better. I don't see any begin/end events firing where they shouldn't. I'm going to ask you to run with this for a week and recheck the logs carefully for such bad events. If you can find other users who can also run with it, even better. If we don't see any issues, we'll take the change.

MathiasMoog commented 5 years ago

Some days ago @Tobster77 showed a log file where an event from the future appeared. I started a test run, but it had not found the time to have a look on the log files. I'm using the binding since several years and I never saw any wrong events. Therefor I tried a complicated test case. Three openHAB item reacting on one calendar event series, the calendar events starts at 7:45 and ends at 7:55 repeating every days. But I had to stop the test run just after the first occurence of the event series.

Here is the openhab.log report for the start of the calendar event:

2019-01-30 07:43:09.310 [DEBUG] [ldav_personal.internal.CalDavBinding] - 0 non matching place events
2019-01-30 07:45:00.005 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 294cc9d5-7eee-4d73-86d1-de52d3e46816(Termin Test Urlaub@30.01.2019/07:45-30.01.2019/07:55)
2019-01-30 07:45:00.009 [DEBUG] [ldav_personal.internal.CalDavBinding] - event begins: 294cc9d5-7eee-4d73-86d1-de52d3e46816(Termin Test Urlaub@30.01.2019/07:45-30.01.2019/07:55)
2019-01-30 07:45:00.011 [DEBUG] [ldav_personal.internal.CalDavBinding] - check start of event: 294cc9d5-7eee-4d73-86d1-de52d3e46816(Termin Test Urlaub@30.01.2019/07:45-30.01.2019/07:55)
2019-01-30 07:45:00.037 [DEBUG] [ldav_personal.internal.CalDavBinding] - event start time: 2019-01-30T07:45:00.000+01:00 
2019-01-30 07:45:00.038 [DEBUG] [ldav_personal.internal.CalDavBinding] - now:              2019-01-30T07:45:00.038+01:00 
2019-01-30 07:45:00.039 [DEBUG] [ldav_personal.internal.CalDavBinding] - adding event to map: 294cc9d5-7eee-4d73-86d1-de52d3e46816(Termin Test Urlaub@30.01.2019/07:45-30.01.2019/07:55)

All three openhab Events fire (event.log):

2019-01-30 07:45:00.048 [ome.event.ItemCommandEvent] - Item 'CalTest' received command ON
2019-01-30 07:45:00.051 [vent.ItemStateChangedEvent] - CalTest changed from OFF to ON
2019-01-30 07:45:00.053 [ome.event.ItemCommandEvent] - Item 'CalAlle' received command ON
2019-01-30 07:45:00.055 [vent.ItemStateChangedEvent] - CalAlle changed from OFF to ON
2019-01-30 07:45:00.057 [ome.event.ItemCommandEvent] - Item 'CalUrlaub' received command ON
2019-01-30 07:45:00.059 [vent.ItemStateChangedEvent] - CalUrlaub changed from OFF to ON

Everything worked fine. Here are the logs for the end of the event alt 7:55:

2019-01-30 07:55:00.002 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event END for: 294cc9d5-7eee-4d73-86d1-de52d3e46816(Termin Test Urlaub@30.01.2019/07:45-30.01.2019/07:55)
2019-01-30 07:55:00.010 [DEBUG] [ldav_personal.internal.CalDavBinding] - remove event from map: 294cc9d5-7eee-4d73-86d1-de52d3e46816(Termin Test Urlaub@30.01.2019/07:45-30.01.2019/07:55)
2019-01-30 07:55:00.012 [DEBUG] [ldav_personal.internal.CalDavBinding] - No events found in event cache for item 'CalTest'. Attempting to load from calendar.

and 

2019-01-30 07:55:00.022 [ome.event.ItemCommandEvent] - Item 'CalTest' received command OFF
2019-01-30 07:55:00.028 [vent.ItemStateChangedEvent] - CalTest changed from ON to OFF
2019-01-30 07:55:00.031 [ome.event.ItemCommandEvent] - Item 'CalAlle' received command OFF
2019-01-30 07:55:00.032 [vent.ItemStateChangedEvent] - CalAlle changed from ON to OFF
2019-01-30 07:55:00.034 [ome.event.ItemCommandEvent] - Item 'CalUrlaub' received command OFF
2019-01-30 07:55:00.035 [vent.ItemStateChangedEvent] - CalUrlaub changed from ON to OFF

From my point of view the fix worked fine.

Tobster77 commented 5 years ago

@9037568, @MathiasMoog, @hakan42

I did a logging for the last week as requested. I only get a double BEGIN (and a double END) a single time. Hmm, since @MathiasMoog does not have the problem, maybe it is on my side? Maybe a corrupt database? Can I reset the whole database? I erased the cache and the directory with the ICS files, but the binding still lists very old appointments I used for testing. Maybe they are grabbed again from the calendar provider?

Is it possible that the double BEGIN comes from the fact that there are daily repeated entries with the same name?

I post the lines with the double BEGIN below and I attach my log files for the last week below... maybe that helps to see why I get the double BEGINs. Please let me know if I can provide further support!

2019-02-06 15:04:56.211 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[Recordings], from=2019-02-06T15:04:56.210+01:00, to=null, sort=ASCENDING, filterName=null] with 2 entries
2019-02-06 15:04:56.226 [DEBUG] [caldav.internal.job.EventReloaderJob] - jobs scheduled : 
2019-02-06 15:04:56.228 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-end-316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@07.02.2019/15:55-07.02.2019/17:15)-1 - [groupName] : event-end - Thu Feb 07 17:15:00 CET 2019
2019-02-06 15:04:56.245 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-end-316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@06.02.2019/15:55-06.02.2019/17:15)-0 - [groupName] : event-end - Wed Feb 06 17:15:00 CET 2019
2019-02-06 15:04:56.247 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-end-316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@06.02.2019/15:55-06.02.2019/17:15)-1 - [groupName] : event-end - Wed Feb 06 17:15:00 CET 2019
2019-02-06 15:04:56.249 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : Recordings - [groupName] : event-reloader - Wed Feb 06 16:04:55 CET 2019
2019-02-06 15:04:56.251 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-start-316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@07.02.2019/15:55-07.02.2019/17:15)-1 - [groupName] : event-start - Thu Feb 07 15:55:00 CET 2019
2019-02-06 15:04:56.254 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-start-316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@06.02.2019/15:55-06.02.2019/17:15)-1 - [groupName] : event-start - Wed Feb 06 15:55:00 CET 2019
2019-02-06 15:04:56.256 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-start-316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@06.02.2019/15:55-06.02.2019/17:15)-0 - [groupName] : event-start - Wed Feb 06 15:55:00 CET 2019
2019-02-06 15:04:56.260 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : default.rules#Regel Tägliche Regeln#0 1 0 1/1 * ? * - [groupName] : DEFAULT - Thu Feb 07 00:01:00 CET 2019
2019-02-06 15:04:56.264 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : default.rules#Regel Alles aus#0 0 2 1/1 * ? * - [groupName] : DEFAULT - Thu Feb 07 02:00:00 CET 2019
2019-02-06 15:04:56.276 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : default.rules#Regel Alles aus#0 0 12 ? * MON-FRI * - [groupName] : DEFAULT - Thu Feb 07 12:00:00 CET 2019
2019-02-06 15:55:00.003 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@06.02.2019/15:55-06.02.2019/17:15)
2019-02-06 15:55:00.004 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@07.02.2019/15:55-07.02.2019/17:15)
2019-02-06 15:55:00.009 [WARN ] [ldav_personal.internal.CalDavBinding] - event is before now; ignoring and updating anyway.
2019-02-06 15:55:00.013 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[Recordings], from=2019-02-06T15:55:00.012+01:00, to=null, sort=ASCENDING, filterName=null] with 2 entries
2019-02-06 15:55:00.012 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[Recordings], from=2019-02-06T15:55:00.011+01:00, to=null, sort=ASCENDING, filterName=null] with 2 entries
[...]
2019-02-06 17:04:55.421 [DEBUG] [caldav.internal.job.EventReloaderJob] - old eventlist contains the event : Aufnahme "Verrückt nach Meer" -- deb : 2019-02-06T15:55:00.000+01:00 -- fin : 2019-02-06T17:15:00.000+01:00 -- lastchanged 2019-01-15T20:15:13.000+01:00
2019-02-06 17:04:55.424 [DEBUG] [caldav.internal.job.EventReloaderJob] - old eventlist contains the event : Aufnahme "Verrückt nach Meer" -- deb : 2019-02-07T15:55:00.000+01:00 -- fin : 2019-02-07T17:15:00.000+01:00 -- lastchanged 2019-01-15T20:15:13.000+01:00
2019-02-06 17:04:56.280 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[Recordings], from=2019-02-06T17:04:56.279+01:00, to=null, sort=ASCENDING, filterName=null] with 2 entries
2019-02-06 17:04:56.302 [DEBUG] [caldav.internal.job.EventReloaderJob] - jobs scheduled : 
2019-02-06 17:04:56.306 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-end-316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@07.02.2019/15:55-07.02.2019/17:15)-1 - [groupName] : event-end - Thu Feb 07 17:15:00 CET 2019
2019-02-06 17:04:56.313 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-end-316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@06.02.2019/15:55-06.02.2019/17:15)-0 - [groupName] : event-end - Wed Feb 06 17:15:00 CET 2019
2019-02-06 17:04:56.315 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-end-316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@06.02.2019/15:55-06.02.2019/17:15)-1 - [groupName] : event-end - Wed Feb 06 17:15:00 CET 2019
2019-02-06 17:04:56.318 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : Recordings - [groupName] : event-reloader - Wed Feb 06 18:04:55 CET 2019
2019-02-06 17:04:56.326 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-start-316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@07.02.2019/15:55-07.02.2019/17:15)-1 - [groupName] : event-start - Thu Feb 07 15:55:00 CET 2019
2019-02-06 17:04:56.330 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : default.rules#Regel Tägliche Regeln#0 1 0 1/1 * ? * - [groupName] : DEFAULT - Thu Feb 07 00:01:00 CET 2019
2019-02-06 17:04:56.339 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : default.rules#Regel Alles aus#0 0 2 1/1 * ? * - [groupName] : DEFAULT - Thu Feb 07 02:00:00 CET 2019
2019-02-06 17:04:56.343 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : default.rules#Regel Alles aus#0 0 12 ? * MON-FRI * - [groupName] : DEFAULT - Thu Feb 07 12:00:00 CET 2019
2019-02-06 17:15:00.004 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event END for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@07.02.2019/15:55-07.02.2019/17:15)
2019-02-06 17:15:00.003 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event END for: 316c740f-8a28-4fb2-b1e8-5270d413d258.kalender.gmx.net(Aufnahme "Verrückt nach Meer"@06.02.2019/15:55-06.02.2019/17:15)
2019-02-06 17:15:00.009 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[Recordings], from=2019-02-06T17:15:00.008+01:00, to=null, sort=ASCENDING, filterName=null] with 1 entries
2019-02-06 17:15:00.009 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[Recordings], from=2019-02-06T17:15:00.008+01:00, to=null, sort=ASCENDING, filterName=null] with 1 entries
2019-02-06 18:04:55.297 [DEBUG] [caldav.internal.job.EventReloaderJob] - running EventReloaderJob for config : Recordings

The log files: caldav_openhab.log caldav_events.log

I would love to see this finally resolved as the binding basically does it's job and switches on time :-)

MathiasMoog commented 5 years ago

Dear @Tobster77, I had a look on your log files. In lines 3794 and 4899 I saw thes duplicated Events. In both cases the Ids of the present and the future events are the same. How did you create these events? I tried to create a series event, but this results inside the caldav binding in single events with different IDs. I did not manage to create two events with the same id ?!

This might be a problem of your gmx calendar and not of the caldav plugin.

Tobster77 commented 5 years ago

@mathiasmoog This is simply a series event in my GMX calendar.

Hmm. But all my TV recordings are series events. However, only this one ("Verrückt nach Meer", 15:55h, workdays) creates the error. Am I right? Or did I oversee something?

Tobster77 commented 5 years ago

In any case, we can confirm to @9037568 that the fix is doing the job properly, right? Can you confirm that the double ID is not related to the fix?

Tobster77 commented 5 years ago

@9037568 Dear Chris, you proposed to pause the pull request until the effects described below are resolved.

@mathiasmoog supported the clarification and provided explanations.

Would that be enough to initiate a pull request? Currently we are somehow stuck, and I have no idea how to push things forward.

Thanks for help :-)

9037568 commented 5 years ago

If @MathiasMoog wishes to submit a PR, I'll be happy to close this one in favor of his.

MathiasMoog commented 5 years ago

@9037568 allready submitted the pull request. The issue #5819 is just a duplicate of this one here. My fix is not different vom Chris fix, therefor I will not submit an additional pull request. Or do you expect an additional pull request Chris?

9037568 commented 5 years ago

No, as long as you're ok with it, we're good to go. I'll see if I can get another maintainer to give it a final review...

Tobster77 commented 5 years ago

Thanks a lot, guys!