CalDAV binding: fix openHAB 2 config compatibility

[ThomDietrich]

Summarizing what was found here:

• calDAV Binding not loading Events under OH2 #4074 (comment)
• calDAV Binding not loading Events under OH2 #4074 (comment)

When configuring the CalDAV binding, it's needed to prepend the binding prefix inside the specific config files - other than known from all other bindings. Example:

caldavio.cfg:

caldavio:bms:username=XXXXXX
caldavio:bms:password=XXXXXX
caldavio:bms:reloadInterval=30

@kaikreuzer Who's best able to fix this?

[querdenker2k]

I updated to the build from yesterday and the caldav-command binding isn't woking anymore. Is there something changed in the runtime? No log outputs for the binding.

[fab33]

Quite strange here. It works yesterday but after restart, i'v got error about unkown calendar id. Copy all config file (caldavio.cfg and caldavcommand.cfg with prefix) uninstall binding, delete cadav* files in userdata dir.
Reinstall binding, copy config (caldavio.cfg and caldavCommand.cfg). Everything works fine. I will see tomorow if it's ok after restarting openhab

[staehler]

@fab33 Did your workaround survive the restart? Just to be clear:
You used the syntax from OH1, with prefixes in all three files caldavio.cfg and caldavCommand.cfg and calcavPersonal.cfg?
I did it like here, but without reinstallation of bindings and without removing caldav* files in userdata dir. This didn't help, I'm going to try your hint.

Edit: at least the binding reads some of my owncloud entries, but get lots of errors:
2017-02-07 16:55:52.279 [ERROR] [caldav.internal.job.EventReloaderJob] - cannot load events java.util.ServiceConfigurationError: net.fortuna.ical4j.model.PropertyFactory: Provider net.fortuna.ical4j.model.property.Action$Factory not a subtype at java.util.ServiceLoader.fail(ServiceLoader.java:239)[:1.8.0_121] at java.util.ServiceLoader.access$300(ServiceLoader.java:185)[:1.8.0_121] at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:376)[:1.8.0_121] at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)[:1.8.0_121] at java.util.ServiceLoader$1.next(ServiceLoader.java:480)[:1.8.0_121] at net.fortuna.ical4j.model.AbstractContentFactory.getFactory(AbstractContentFactory.java:85)[245:org.openhab.io.caldav:1.9.0.RC1] at net.fortuna.ical4j.model.PropertyFactoryImpl.createProperty(PropertyFactoryImpl.java:78)[245:org.openhab.io.caldav:1.9.0.RC1] at net.fortuna.ical4j.data.CalendarBuilder$ContentHandlerImpl.startProperty(CalendarBuilder.java:326)[245:org.openhab.io.caldav:1.9.0.RC1] at net.fortuna.ical4j.data.CalendarParserImpl$PropertyParser.parse(CalendarParserImpl.java:206)[245:org.openhab.io.caldav:1.9.0.RC1] at net.fortuna.ical4j.data.CalendarParserImpl$PropertyParser.access$1100(CalendarParserImpl.java:190)[245:org.openhab.io.caldav:1.9.0.RC1] at net.fortuna.ical4j.data.CalendarParserImpl$PropertyListParser.parse(CalendarParserImpl.java:173)[245:org.openhab.io.caldav:1.9.0.RC1] at net.fortuna.ical4j.data.CalendarParserImpl.parse(CalendarParserImpl.java:122)[245:org.openhab.io.caldav:1.9.0.RC1] at net.fortuna.ical4j.data.CalendarBuilder.build(CalendarBuilder.java:198)[245:org.openhab.io.caldav:1.9.0.RC1] at org.openhab.io.caldav.internal.job.EventReloaderJob.loadEvents(EventReloaderJob.java:334)[245:org.openhab.io.caldav:1.9.0.RC1] at org.openhab.io.caldav.internal.job.EventReloaderJob.execute(EventReloaderJob.java:97)[245:org.openhab.io.caldav:1.9.0.RC1] at org.quartz.core.JobRunShell.run(JobRunShell.java:202)[104:org.eclipse.smarthome.core.scheduler:0.9.0.b3] at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)[104:org.eclipse.smarthome.core.scheduler:0.9.0.b3] 2017-02-07 16:55:58.815 [ERROR] [org.quartz.core.JobRunShell ] - Job event-reloader.dienstlich threw an unhandled Exception: java.util.ServiceConfigurationError: net.fortuna.ical4j.model.PropertyFactory: Provider net.fortuna.ical4j.model.property.Action$Factory not a subtype at java.util.ServiceLoader.fail(ServiceLoader.java:239)[:1.8.0_121] at java.util.ServiceLoader.access$300(ServiceLoader.java:185)[:1.8.0_121] at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:376)[:1.8.0_121] at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)[:1.8.0_121] at java.util.ServiceLoader$1.next(ServiceLoader.java:480)[:1.8.0_121] at net.fortuna.ical4j.model.AbstractContentFactory.getFactory(AbstractContentFactory.java:85) at net.fortuna.ical4j.model.PropertyFactoryImpl.createProperty(PropertyFactoryImpl.java:78) at net.fortuna.ical4j.data.CalendarBuilder$ContentHandlerImpl.startProperty(CalendarBuilder.java:326) at net.fortuna.ical4j.data.CalendarParserImpl$PropertyParser.parse(CalendarParserImpl.java:206) at net.fortuna.ical4j.data.CalendarParserImpl$PropertyParser.access$1100(CalendarParserImpl.java:190) at net.fortuna.ical4j.data.CalendarParserImpl$PropertyListParser.parse(CalendarParserImpl.java:173) at net.fortuna.ical4j.data.CalendarParserImpl.parse(CalendarParserImpl.java:122) at net.fortuna.ical4j.data.CalendarBuilder.build(CalendarBuilder.java:198) at org.openhab.io.caldav.internal.job.EventReloaderJob.loadEvents(EventReloaderJob.java:334) at org.openhab.io.caldav.internal.job.EventReloaderJob.loadEvents(EventReloaderJob.java:315) at org.openhab.io.caldav.internal.job.EventReloaderJob.execute(EventReloaderJob.java:134) at org.quartz.core.JobRunShell.run(JobRunShell.java:202)[104:org.eclipse.smarthome.core.scheduler:0.9.0.b3] at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)[104:org.eclipse.smarthome.core.scheduler:0.9.0.b3]

I'll give it up at the moment and hope for a fix, soon.

[fab33]

Works fine here after few restart

[9037568]

I've been looking for a document that describes where the freaking prefix comes from, but no luck so far.
Why the thing insists on looking for a prefix here and not elsewhere baffles me.

From what I see so far, the system is creating a cached config file for every "prefix" it finds:

myCalendar:url=https://something.here/
yiminy:url=https://something.else/

 Directory of <openhabHome>\userdata\config\org\openhab

02/27/2017  12:39 AM               120 myCalendar.config
02/27/2017  12:39 AM               120 yiminy.config

[9037568]

As far as I can tell, there's nothing that can be done on the OH1 side of things to fix this. I think this should be opened against OH2 or ESH.

[ThomDietrich]

@kaikreuzer any advice on how to move forward? Would be nice to finally fix this issue.

[kaikreuzer]

What is the outcome of the debugging and analysis? I just briefly scanned through the linked issues, but couldn't really get a consolidated picture. It seems that exactly the same mechanism is working in other bindings? So did anybody find out the difference? There must be one...

[9037568]

@kaikreuzer Here's what I found.

with the prefix on each config item in caldavio.cfg, I see the configuration keys were sent to the CalDAV IO binding (see the TRACE messages). But if the prefix is omitted, it appears that updated() is never called at all.

(There's obviously something wrong with the line numbers in this log, but I haven't figured out how to fix that yet, either.)

Log messages WITH prefix configured:

2017-03-15 18:39:55.240 [DEBUG] [b.io.caldav.internal.CalDavActivator:a:34)] - CalDav Calendar IO has been started.
2017-03-15 18:39:55.240 [DEBUG] [org.openhab.io.caldav               :     ] - BundleEvent STARTED - org.openhab.io.caldav
2017-03-15 18:39:55.600 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl::150)] - Update was called for CalDAV IO.
2017-03-15 18:39:55.662 [TRACE] [.io.caldav.internal.CalDavLoaderImpl::163)] - processing configuration parameter: myCalendar:password
2017-03-15 18:39:55.662 [TRACE] [.io.caldav.internal.CalDavLoaderImpl::163)] - processing configuration parameter: myCalendar:reloadInterval
2017-03-15 18:39:55.662 [TRACE] [.io.caldav.internal.CalDavLoaderImpl::163)] - processing configuration parameter: myCalendar:url
2017-03-15 18:39:55.662 [TRACE] [.io.caldav.internal.CalDavLoaderImpl::163)] - processing configuration parameter: myCalendar:username
2017-03-15 18:39:55.662 [TRACE] [.io.caldav.internal.CalDavLoaderImpl::159)] - received service.pid = org.openhab.caldavio
2017-03-15 18:39:55.662 [TRACE] [.io.caldav.internal.CalDavLoaderImpl::222)] - config for calendar 'myCalendar': CalDavConfig [key=myCalendar, username=me, password=myPassword, url=https://www.google.com/calendar/dav/meagain/events, reloadMinutes=10, preloadMinutes=1440, disableCertificateVerification=false, lastModifiedFileTimeStampValid=true]
2017-03-15 18:39:55.850 [INFO ] [.io.caldav.internal.CalDavLoaderImpl::238)] - CalDAV IO is properly configured.
2017-03-15 18:39:55.850 [INFO ] [b.core.service.AbstractActiveService::169)] - CalDav Loader has been started

Log messages WITHOUT prefix configured:

2017-03-15 18:45:16.493 [DEBUG] [b.io.caldav.internal.CalDavActivator:a:34)] - CalDav Calendar IO has been started.
2017-03-15 18:45:16.493 [DEBUG] [org.openhab.io.caldav               :     ] - BundleEvent STARTED - org.openhab.io.caldav
2017-03-15 18:45:17.852 [INFO ] [el.core.internal.ModelRepositoryImpl:a:88)] - Loading model 'cal.items'
2017-03-15 18:45:18.649 [INFO ] [el.core.internal.ModelRepositoryImpl:a:88)] - Loading model 'cal.sitemap'
2017-03-15 18:45:19.071 [INFO ] [.dashboard.internal.DashboardService:a:58)] - Started dashboard at /start
2017-03-15 18:45:19.258 [INFO ] [basic.internal.servlet.WebAppServlet:a:84)] - Started Basic UI at /basicui/app
2017-03-15 18:45:19.305 [INFO ] [assic.internal.servlet.WebAppServlet:a:84)] - Started Classic UI at /classicui/app
2017-03-15 18:45:19.352 [INFO ] [arthome.ui.paper.internal.PaperUIApp:a:31)] - Started Paper UI at /paperui
2017-03-15 18:45:19.399 [INFO ] [ui.habmin.internal.servlet.HABminApp:a:31)] - Started HABmin servlet at /habmin
2017-03-15 18:45:19.414 [INFO ] [panel.internal.HABPanelDashboardTile:a:54)] - Started HABPanel at /habpanel
2017-03-15 18:45:19.477 [TRACE] [.io.caldav.internal.CalDavLoaderImpl::532)] - quering events for filter: CalDavQuery [calendarIds=[myCalendar], from=2017-03-15T18:45:19.446-04:00, to=null, sort=ASCENDING, filterName=null]
2017-03-15 18:45:19.477 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl::539)] - calendar id myCalendar not found
2017-03-15 18:45:19.477 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl::629)] - return event list for CalDavQuery [calendarIds=[myCalendar], from=2017-03-15T18:45:19.446-04:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-03-15 18:45:19.477 [TRACE] [.io.caldav.internal.CalDavLoaderImpl::532)] - quering events for filter: CalDavQuery [calendarIds=[myCalendar], from=2017-03-15T18:45:19.477-04:00, to=null, sort=null, filterName=null]
2017-03-15 18:45:19.477 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl::539)] - calendar id myCalendar not found
2017-03-15 18:45:19.477 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl::629)] - return event list for CalDavQuery [calendarIds=[myCalendar], from=2017-03-15T18:45:19.477-04:00, to=null, sort=null, filterName=null] with 0 entries