search

openhab / openhab1-addons

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

[CalDav][personal] NPE while starting the binding #5389

Closed cweitkamp closed 6 years ago

cweitkamp commented 6 years ago

Occurs on every start of OH2. Any ideas? What do you need? Shall I post my service/item configuration?

I use a Google calendar. Configured one item for type:ACTIVE and several for type:UPCOMING. My calendar contains one active event on 2017-12-18.

2017-12-18 15:21:58.744 [ERROR] [org.openhab.binding.caldav-personal ] - [org.openhab.binding.caldav_personal(195)] The addBindingProvider method has thrown an exception
java.lang.NullPointerException: null
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.getActiveEvents(CalDavBinding.java:305) [226:org.openhab.binding.caldav-personal:1.11.0]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.updateItem(CalDavBinding.java:254) [226:org.openhab.binding.caldav-personal:1.11.0]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.updateItemsForEvent(CalDavBinding.java:228) [226:org.openhab.binding.caldav-personal:1.11.0]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.allBindingsChanged(CalDavBinding.java:134) [226:org.openhab.binding.caldav-personal:1.11.0]
    at org.openhab.core.binding.AbstractBinding.addBindingProvider(AbstractBinding.java:61) [233:org.openhab.core.compat1x:2.2.0]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.addBindingProvider(CalDavBinding.java:85) [226:org.openhab.binding.caldav-personal:1.11.0]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
    at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:229) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:650) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:506) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BindMethod.invoke(BindMethod.java:658) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1722) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager.open(DependencyManager.java:1556) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:261) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:109) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:906) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:879) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:823) [46:org.apache.felix.scr:2.0.12]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) [?:?]
    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619) [?:?]
    at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39) [19:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
    at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) [?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) [?:?]
    at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) [?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) [?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:915) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464) [?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:887) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:874) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:941) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:741) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:799) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:743) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127) [46:org.apache.felix.scr:2.0.12]
    at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:915) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464) [?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:887) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:874) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:941) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:741) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:675) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:430) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:657) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:341) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:390) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.Activator.access$200(Activator.java:54) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:265) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:254) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:227) [46:org.apache.felix.scr:2.0.12]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) [?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) [?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:903) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:156) [?:?]
    at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) [?:?]
    at org.eclipse.osgi.container.Module.start(Module.java:467) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1620) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1600) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1571) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1514) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]
9037568 commented 6 years ago

Well, stopping the NPE should be simple enough, but if we want to find out why it's happening, we probably need at least a DEBUG log.

cweitkamp commented 6 years ago

No problem. Here you are. The DEBUG log of an complete restart. Is there anything useful in it? I guess not. Should I try it again with TRACE log?

I set up a logger for log4j2.logger.CALDAV.name = org.openhab.binding.caldav-personal. Is that correct?

2017-12-19 10:40:45.544 [DEBUG] [org.openhab.binding.caldav-personal ] - ServiceEvent UNREGISTERING - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.caldavPersonal, component.name=org.openhab.binding.caldav_personal, component.id=195, service.id=343, service.bundleid=226, service.scope=bundle} - org.openhab.binding.caldav-personal
2017-12-19 10:40:45.554 [DEBUG] [org.openhab.binding.caldav-personal ] - ServiceEvent UNREGISTERING - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.caldav_personal.CalDavBindingProvider}={component.name=org.openhab.binding.caldav_personal.caldavbindingprovider, component.id=196, service.id=324, service.bundleid=226, service.scope=bundle} - org.openhab.binding.caldav-personal
2017-12-19 10:40:45.558 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent STOPPING - org.openhab.binding.caldav-personal
2017-12-19 10:40:45.560 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent STOPPED - org.openhab.binding.caldav-personal
2017-12-19 10:46:40.111 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent STARTING - org.openhab.binding.caldav-personal
2017-12-19 10:46:40.121 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent STARTED - org.openhab.binding.caldav-personal
2017-12-19 10:46:40.157 [DEBUG] [org.openhab.binding.caldav-personal ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.caldav_personal.CalDavBindingProvider}={component.name=org.openhab.binding.caldav_personal.caldavbindingprovider, component.id=196, service.id=324, service.bundleid=226, service.scope=bundle} - org.openhab.binding.caldav-personal
2017-12-19 10:48:12.022 [ERROR] [org.openhab.binding.caldav-personal ] - [org.openhab.binding.caldav_personal(195)] The addBindingProvider method has thrown an exception
java.lang.NullPointerException: null
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.getActiveEvents(CalDavBinding.java:305) [226:org.openhab.binding.caldav-personal:1.11.0]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.updateItem(CalDavBinding.java:254) [226:org.openhab.binding.caldav-personal:1.11.0]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.updateItemsForEvent(CalDavBinding.java:228) [226:org.openhab.binding.caldav-personal:1.11.0]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.allBindingsChanged(CalDavBinding.java:134) [226:org.openhab.binding.caldav-personal:1.11.0]
    at org.openhab.core.binding.AbstractBinding.addBindingProvider(AbstractBinding.java:61) [233:org.openhab.core.compat1x:2.2.0]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.addBindingProvider(CalDavBinding.java:85) [226:org.openhab.binding.caldav-personal:1.11.0]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
    at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:229) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:650) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:506) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BindMethod.invoke(BindMethod.java:658) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1722) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager.open(DependencyManager.java:1556) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:261) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:109) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:906) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:879) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:823) [46:org.apache.felix.scr:2.0.12]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) [?:?]
    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619) [?:?]
    at org.apache.felix.metatype.internal.ManagedServiceTracker.addingService(ManagedServiceTracker.java:52) [2:org.apache.felix.metatype:1.1.4]
    at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) [?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) [?:?]
    at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) [?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) [?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:915) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464) [?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:887) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:874) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:941) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:741) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:799) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:743) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127) [46:org.apache.felix.scr:2.0.12]
    at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:915) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464) [?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:887) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:874) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:941) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:741) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:675) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:430) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:657) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:341) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:390) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.Activator.access$200(Activator.java:54) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:265) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:254) [46:org.apache.felix.scr:2.0.12]
    at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:227) [46:org.apache.felix.scr:2.0.12]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) [?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) [?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:903) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:156) [?:?]
    at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) [?:?]
    at org.eclipse.osgi.container.Module.start(Module.java:467) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1620) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1600) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1571) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1514) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]
2017-12-19 10:48:12.049 [DEBUG] [org.openhab.binding.caldav-personal ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.caldavPersonal, component.name=org.openhab.binding.caldav_personal, component.id=195, service.id=345, service.bundleid=226, service.scope=bundle} - org.openhab.binding.caldav-personal
9037568 commented 6 years ago

I set up a logger for log4j2.logger.CALDAV.name = org.openhab.binding.caldav-personal. Is that correct?

Looks ok to me, especially since you're getting DEBUG output in the log. But you should probably also add caldavio as well. There should be a lot more DEBUG output than that.

But I think I may see where it's going wrong. I added a new DEBUG line there. Care to try this updated jar?

9037568 commented 6 years ago

I've now updated that jar with code that I believe should fix the NPE.

cweitkamp commented 6 years ago

Thank you. First of all here is another log with DEBUG enabled for org.openhab.io.caldav. The *.ics file contains at least on item. I configured a preload time of one week.

2017-12-20 10:04:59.943 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent INSTALLED - org.openhab.binding.caldav-personal
2017-12-20 10:04:59.998 [DEBUG] [org.openhab.io.caldav               ] - BundleEvent INSTALLED - org.openhab.io.caldav
2017-12-20 10:05:00.513 [DEBUG] [org.openhab.io.caldav               ] - BundleEvent RESOLVED - org.openhab.io.caldav
2017-12-20 10:05:00.524 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent RESOLVED - org.openhab.binding.caldav-personal
2017-12-20 10:05:00.566 [DEBUG] [org.openhab.io.caldav               ] - BundleEvent [unknown:512] - org.openhab.io.caldav
2017-12-20 10:05:00.751 [DEBUG] [org.openhab.io.caldav               ] - BundleEvent STARTING - org.openhab.io.caldav
2017-12-20 10:05:00.756 [DEBUG] [b.io.caldav.internal.CalDavActivator] - CalDav Calendar IO has been started.
2017-12-20 10:05:00.764 [DEBUG] [org.openhab.io.caldav               ] - BundleEvent STARTED - org.openhab.io.caldav
2017-12-20 10:05:00.786 [DEBUG] [org.openhab.io.caldav               ] - ServiceEvent REGISTERED - {org.osgi.service.cm.ManagedService, org.openhab.io.caldav.CalDavLoader}={service.pid=org.openhab.caldavio, component.name=org.openhab.io.caldav.caldavloader, component.id=242, service.id=393, service.bundleid=256, service.scope=bundle} - org.openhab.io.caldav
2017-12-20 10:05:00.793 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - Update was called for CalDAV IO.
2017-12-20 10:05:00.819 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - Overriding default timezone Europe/Berlin with Europe/Berlin
2017-12-20 10:05:00.852 [INFO ] [.io.caldav.internal.CalDavLoaderImpl] - CalDAV IO is properly configured.
2017-12-20 10:05:00.863 [INFO ] [.io.caldav.internal.CalDavLoaderImpl] - reload job scheduled for: waste
2017-12-20 10:05:03.896 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent STARTING - org.openhab.binding.caldav-personal
2017-12-20 10:05:03.923 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent STARTED - org.openhab.binding.caldav-personal
2017-12-20 10:05:04.075 [ERROR] [org.openhab.binding.caldav-personal ] - [org.openhab.binding.caldav_personal(243)] The addBindingProvider method has thrown an exception
java.lang.NullPointerException: null
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.getActiveEvents(CalDavBinding.java:305) ~[?:?]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.updateItem(CalDavBinding.java:254) ~[?:?]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.updateItemsForEvent(CalDavBinding.java:228) ~[?:?]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.allBindingsChanged(CalDavBinding.java:134) ~[?:?]
    at org.openhab.core.binding.AbstractBinding.addBindingProvider(AbstractBinding.java:61) ~[?:?]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.addBindingProvider(CalDavBinding.java:85) ~[?:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
    at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:229) ~[?:?]
    at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39) ~[?:?]
    at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:650) ~[?:?]
    at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:506) ~[?:?]
    at org.apache.felix.scr.impl.inject.BindMethod.invoke(BindMethod.java:658) ~[?:?]
    at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1722) ~[?:?]
    at org.apache.felix.scr.impl.manager.DependencyManager.open(DependencyManager.java:1556) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:261) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:109) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:906) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:879) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:823) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) ~[?:?]
    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619) ~[?:?]
    at org.apache.felix.metatype.internal.ManagedServiceTracker.addingService(ManagedServiceTracker.java:52) ~[?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) ~[?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) ~[?:?]
    at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) ~[?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) ~[?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:915) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:887) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:874) ~[?:?]
    at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:941) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:741) ~[?:?]
    at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:333) ~[?:?]
    at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:291) ~[?:?]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215) ~[?:?]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136) ~[?:?]
    at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945) ~[?:?]
    at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881) ~[?:?]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167) ~[?:?]
    at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:915) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:887) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:874) ~[?:?]
    at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:941) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:741) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:675) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:430) ~[?:?]
    at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:657) ~[?:?]
    at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:341) ~[?:?]
    at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:390) ~[?:?]
    at org.apache.felix.scr.impl.Activator.access$200(Activator.java:54) ~[?:?]
    at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:265) ~[?:?]
    at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:254) ~[?:?]
    at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:227) ~[?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) ~[?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) ~[?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) ~[?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:903) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:156) ~[?:?]
    at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) ~[?:?]
    at org.eclipse.osgi.container.Module.start(Module.java:467) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:402) ~[?:?]
    at org.apache.karaf.features.internal.service.FeaturesServiceImpl.startBundle(FeaturesServiceImpl.java:1361) ~[?:?]
    at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:888) ~[?:?]
    at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1248) ~[?:?]
    at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$1(FeaturesServiceImpl.java:1147) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
2017-12-20 10:05:04.765 [DEBUG] [org.openhab.binding.caldav-personal ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.caldavPersonal, component.name=org.openhab.binding.caldav_personal, component.id=243, service.id=399, service.bundleid=255, service.scope=bundle} - org.openhab.binding.caldav-personal
2017-12-20 10:05:04.771 [DEBUG] [org.openhab.binding.caldav-personal ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.caldav_personal.CalDavBindingProvider}={component.name=org.openhab.binding.caldav_personal.caldavbindingprovider, component.id=244, service.id=397, service.bundleid=255, service.scope=bundle} - org.openhab.binding.caldav-personal
2017-12-20 10:05:04.767 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:05:04.767+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:05:04.816 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:05:04.813+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:05:10.878 [DEBUG] [caldav.internal.job.EventReloaderJob] - running EventReloaderJob for config : waste
2017-12-20 10:05:10.880 [DEBUG] [caldav.internal.job.EventReloaderJob] - reload cached events for config: waste
2017-12-20 10:05:10.882 [DEBUG] [caldav.internal.job.EventReloaderJob] - loading events for config: waste
2017-12-20 10:05:12.463 [DEBUG] [caldav.internal.job.EventReloaderJob] - loading resource: /calendar/dav/g0pmbrlm5apk3ml9r9sc4dso6o@group.calendar.google.com/events/33c33f31b513d203bb043acc375c6115.ics (FSchangedTS not valid)
cweitkamp commented 6 years ago

Care to try this updated jar?

I downloaded your .jar file. Removed the binding with Paper UI and put the new version into my addons folder together with a self compiled org.openhab.io.caldav-1.12.0-SNAPSHOT.jar file. Here are the results:

2017-12-20 10:00:43.204 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent INSTALLED - org.openhab.binding.caldav-personal
2017-12-20 10:01:04.943 [DEBUG] [org.openhab.io.caldav               ] - BundleEvent INSTALLED - org.openhab.io.caldav
2017-12-20 10:01:05.155 [DEBUG] [org.openhab.io.caldav               ] - BundleEvent RESOLVED - org.openhab.io.caldav
2017-12-20 10:01:05.168 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent RESOLVED - org.openhab.binding.caldav-personal
2017-12-20 10:01:05.177 [DEBUG] [org.openhab.io.caldav               ] - BundleEvent [unknown:512] - org.openhab.io.caldav
2017-12-20 10:01:05.357 [DEBUG] [org.openhab.io.caldav               ] - BundleEvent STARTING - org.openhab.io.caldav
2017-12-20 10:01:05.362 [DEBUG] [b.io.caldav.internal.CalDavActivator] - CalDav Calendar IO has been started.
2017-12-20 10:01:05.368 [DEBUG] [org.openhab.io.caldav               ] - BundleEvent STARTED - org.openhab.io.caldav
2017-12-20 10:01:05.387 [DEBUG] [org.openhab.io.caldav               ] - ServiceEvent REGISTERED - {org.osgi.service.cm.ManagedService, org.openhab.io.caldav.CalDavLoader}={service.pid=org.openhab.caldavio, component.name=org.openhab.io.caldav.caldavloader, component.id=239, service.id=389, service.bundleid=254, service.scope=bundle} - org.openhab.io.caldav
2017-12-20 10:01:05.390 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - Update was called for CalDAV IO.
2017-12-20 10:01:05.394 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent STARTING - org.openhab.binding.caldav-personal
2017-12-20 10:01:05.408 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - Overriding default timezone Europe/Berlin with Europe/Berlin
2017-12-20 10:01:05.410 [DEBUG] [org.openhab.binding.caldav-personal ] - BundleEvent STARTED - org.openhab.binding.caldav-personal
2017-12-20 10:01:05.429 [INFO ] [.io.caldav.internal.CalDavLoaderImpl] - CalDAV IO is properly configured.
2017-12-20 10:01:05.442 [INFO ] [.io.caldav.internal.CalDavLoaderImpl] - reload job scheduled for: waste
2017-12-20 10:01:05.443 [INFO ] [.io.caldav.internal.CalDavLoaderImpl] - reload job scheduled for: heating
2017-12-20 10:01:05.484 [DEBUG] [org.openhab.binding.caldav-personal ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.caldavPersonal, component.name=org.openhab.binding.caldav_personal, component.id=240, service.id=391, service.bundleid=253, service.scope=bundle} - org.openhab.binding.caldav-personal
2017-12-20 10:01:05.627 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.626+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.632 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.631+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.637 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.636+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.642 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.641+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.647 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.646+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.650 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.650+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.653 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.653+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.657 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.656+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.660 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.660+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.664 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.663+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.668 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.667+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.671 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.670+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.674 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.674+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.678 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.677+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.681 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.680+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.684 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.683+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.687 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.687+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.691 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.690+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.694 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.693+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.697 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.696+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.700 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:05.699+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:05.708 [DEBUG] [org.openhab.binding.caldav-personal ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.caldav_personal.CalDavBindingProvider}={component.name=org.openhab.binding.caldav_personal.caldavbindingprovider, component.id=241, service.id=390, service.bundleid=253, service.scope=bundle} - org.openhab.binding.caldav-personal
2017-12-20 10:01:08.305 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:08.304+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:08.400 [DEBUG] [.io.caldav.internal.CalDavLoaderImpl] - return event list for CalDavQuery [calendarIds=[waste], from=2017-12-20T10:01:08.400+01:00, to=null, sort=ASCENDING, filterName=null] with 0 entries
2017-12-20 10:01:15.473 [DEBUG] [caldav.internal.job.EventReloaderJob] - running EventReloaderJob for config : waste
2017-12-20 10:01:15.475 [DEBUG] [caldav.internal.job.EventReloaderJob] - reload cached events for config: waste
2017-12-20 10:01:15.479 [DEBUG] [caldav.internal.job.EventReloaderJob] - loading events for config: waste
2017-12-20 10:01:17.329 [DEBUG] [caldav.internal.job.EventReloaderJob] - loading resource: /calendar/dav/g0pmbrlm5apk3ml9r9sc4dso6o@group.calendar.google.com/events/33c33f31b513d203bb043acc375c6115.ics (FSchangedTS not valid)

The NPE is gone. But the calendar events as well.

// EDIT: While watching a special log-file for the caldav loggers the following error was logged in my openhab.log.

2017-12-20 10:01:05.434 [INFO ] [b.core.service.AbstractActiveService] - CalDav Loader has been started
2017-12-20 10:01:17.635 [ERROR] [org.quartz.core.JobRunShell         ] - Job event-reloader.waste 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) ~[?:?]
    at java.util.ServiceLoader.access$300(ServiceLoader.java:185) ~[?:?]
    at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:376) ~[?:?]
    at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404) ~[?:?]
    at java.util.ServiceLoader$1.next(ServiceLoader.java:480) ~[?:?]
    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:339) ~[?:?]
    at org.openhab.io.caldav.internal.job.EventReloaderJob.loadEvents(EventReloaderJob.java:320) ~[?:?]
    at org.openhab.io.caldav.internal.job.EventReloaderJob.execute(EventReloaderJob.java:137) ~[?:?]
    at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [119:org.eclipse.smarthome.core.scheduler:0.10.0.b1]
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [119:org.eclipse.smarthome.core.scheduler:0.10.0.b1]
2017-12-20 10:01:17.679 [ERROR] [org.quartz.core.ErrorLogger         ] - Job (event-reloader.waste threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
    at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [119:org.eclipse.smarthome.core.scheduler:0.10.0.b1]
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [119:org.eclipse.smarthome.core.scheduler:0.10.0.b1]
Caused by: 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) ~[?:?]
    at java.util.ServiceLoader.access$300(ServiceLoader.java:185) ~[?:?]
    at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:376) ~[?:?]
    at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404) ~[?:?]
    at java.util.ServiceLoader$1.next(ServiceLoader.java:480) ~[?:?]
    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:339) ~[?:?]
    at org.openhab.io.caldav.internal.job.EventReloaderJob.loadEvents(EventReloaderJob.java:320) ~[?:?]
    at org.openhab.io.caldav.internal.job.EventReloaderJob.execute(EventReloaderJob.java:137) ~[?:?]
    at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[?:?]
    ... 1 more
9037568 commented 6 years ago

This error:

Caused by: java.util.ServiceConfigurationError: net.fortuna.ical4j.model.PropertyFactory: Provider net.fortuna.ical4j.model.property.Action$Factory not a subtype

Is also found in this thread, wherein the author says his CalDav binding started working again within a few days.

It's also seen in a few other threads (eg. this one).

Possibly it's the same as this defect reported in the ical4j library, which is purportedly fixed. So, if I can find some time, I'll try upgrading the ical4j jar to the latest version.

cweitkamp commented 6 years ago

The ical4j error disappeared after a restart. The reported NPE didn't occur again with your fixed version. Will you submit a PR?

JohnnyXXX commented 6 years ago

I see same NPE in my OH2.2 - where can I download the updated jar-file? (sorry for asking dumb questions but in OH Jenkins I wasn't able to find it)

9037568 commented 6 years ago

It's here in cloudbees.

JohnnyXXX commented 6 years ago

I just tried all Caldav bindings v1.12.-snapshot - unfortunately is does not work (see NPE below).

First I was happy....

29-Dez-2017 17:38:13.529 [INFO ] [org.openhab.io.caldav.internal.CalDavLoaderImpl   ] - CalDAV IO is properly configured.
29-Dez-2017 17:38:13.533 [INFO ] [org.openhab.core.service.AbstractActiveService    ] - CalDav Loader has been started
29-Dez-2017 17:38:13.567 [INFO ] [org.openhab.io.caldav.internal.CalDavLoaderImpl   ] - reload job scheduled for: smarthome

...until I scrolled down....

29-Dez-2017 17:38:23.289 [ERROR] [org.openhab.binding.caldav-personal               ] - [org.openhab.binding.caldav_personal(236)] The addBindingProvider method has thrown an exception
java.lang.NullPointerException: null
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.getUpcomingEvents(CalDavBinding.java:317) [252:org.openhab.binding.caldav-personal:1.12.0.201712260210]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.updateItem(CalDavBinding.java:256) [252:org.openhab.binding.caldav-personal:1.12.0.201712260210]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.updateItemsForEvent(CalDavBinding.java:228) [252:org.openhab.binding.caldav-personal:1.12.0.201712260210]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.allBindingsChanged(CalDavBinding.java:134) [252:org.openhab.binding.caldav-personal:1.12.0.201712260210]
    at org.openhab.core.binding.AbstractBinding.addBindingProvider(AbstractBinding.java:61) [200:org.openhab.core.compat1x:2.2.0]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.addBindingProvider(CalDavBinding.java:85) [252:org.openhab.binding.caldav-personal:1.12.0.201712260210]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
    at java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]
    at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:229) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:650) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:506) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.inject.BindMethod.invoke(BindMethod.java:658) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1722) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager.open(DependencyManager.java:1556) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:261) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:109) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:906) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:879) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:823) [42:org.apache.felix.scr:2.0.12]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) [?:?]
    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619) [?:?]
    at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39) [15:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
    at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) [?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) [?:?]
    at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) [?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) [?:?]
    at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:915) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464) [?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:887) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:874) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:941) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:741) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:333) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:291) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127) [42:org.apache.felix.scr:2.0.12]
    at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:915) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464) [?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:887) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:874) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:941) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:741) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:675) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:430) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:657) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:341) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:390) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.Activator.access$200(Activator.java:54) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:265) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:254) [42:org.apache.felix.scr:2.0.12]
    at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:227) [42:org.apache.felix.scr:2.0.12]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) [?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) [?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:903) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:156) [?:?]
    at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) [?:?]
    at org.eclipse.osgi.container.Module.start(Module.java:467) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1620) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1600) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1571) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1514) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]

Just to have it said: the calendar items aren't loaded at all.

caldavCommand.cfg

caldavCommand:readCalendars=smarthome

caldavPersonal.cfg

caldavPersonal:usedCalendars=smarthome
caldavPersonal:homeIdentifiers=smarthome

caldavio.cfg

caldavio:smarthome:url=https://www.google.com/calendar/dav/myUsername@gmail.com/events
caldavio:smarthome:username=myUsername
caldavio:smarthome:password=myPassword
caldavio:smarthome:reloadInterval=60
caldavio:smarthome:preloadTime=2880
# caldavio:smarthome:lastModifiedFileTimeStampValid=false
# caldavio:smarthome:disableCertificateVerification=
# caldavio:timeZone=Berlin
# charset=UTF-8
9037568 commented 6 years ago 
29-Dez-2017 17:38:23.289 [ERROR] [org.openhab.binding.caldav-personal               ] - [org.openhab.binding.caldav_personal(236)] The addBindingProvider method has thrown an exception
java.lang.NullPointerException: null
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.getUpcomingEvents(CalDavBinding.java:317) [252:org.openhab.binding.caldav-personal:1.12.0.201712260210]
    at org.openhab.binding.caldav_personal.internal.CalDavBinding.updateItem(CalDavBinding.java:256) [252:org.openhab.binding.caldav-personal:1.12.0.201712260210]

These line numbers don't match up with current code. I'd suggest uninstalling the binding, doing a full restart and then reinstalling it. Also, if you find you're still having issues after that, get a debug log.

9037568 commented 6 years ago

Oh, I see the problem now. The cloudbees build hasn't been updated since the merge. You can try my original test jar, or wait a day for cloudbees to update...

JohnnyXXX commented 6 years ago

I'll come back with a feedback tomorrow. Thanks for checking it so far.

JohnnyXXX commented 6 years ago

Update about my observations:

  1. file size

    • your personal binding from google drive has bigger file size then the most current one in cloudbees --> are all your changes correctly transferred to cloudbees?

  2. Testing yesterday/last night

    • yesterady CalDav already started working without the updated "personal" binding; I assume that I did not see any events because of caldavio:smarthome:reloadInterval=60 --> for testing I reduced now to 5
    • events were triggered correctly
    • upcoming events showed up correctly in sitemap
    • active events were not displayed in sitemap (but could be found in the log)

  3. Testing today

    • after replacement of "personal" binding this morning with your original test jar (not cloudbees)
    • still NPE appeared
    • then I deleted all files acc. to my screenshot above
    • NPE disappeared, no further CalDav related errors found in log so far
    • upcoming events show up correctly in sitemap
    • log file shows active events but they appear twice --> why? 
      30-Dez-2017 11:10:00.002 [INFO ] [org.openhab.io.caldav.internal.job.EventJob       ] - event BEGIN for: 7s6rfd6pncvaq4t5gc4vagbjvf@google.com(TEST@30.12.2017/11:10-30.12.2017/11:25)
30-Dez-2017 11:10:00.024 [INFO ] [nhab.binding.caldav_command.internal.CalDavBinding] - sending command 'ON' to item 'Licht_DG_Zi3_W' from event '7s6rfd6pncvaq4t5gc4vagbjvf@google.com(TEST@30.12.2017/11:10-30.12.2017/11:25)'
30-Dez-2017 11:11:56.289 [INFO ] [org.openhab.io.caldav.internal.job.EventJob       ] - event BEGIN for: 7s6rfd6pncvaq4t5gc4vagbjvf@google.com(TEST@30.12.2017/11:10-30.12.2017/11:25)
30-Dez-2017 11:11:56.290 [INFO ] [nhab.binding.caldav_command.internal.CalDavBinding] - sending command 'ON' to item 'Licht_DG_Zi3_W' from event '7s6rfd6pncvaq4t5gc4vagbjvf@google.com(TEST@30.12.2017/11:10-30.12.2017/11:25)'
    • active events are still not displayed in sitemap (see screenshot) --> in OH 1.8.3 this was working correctly
    • UI issue: the subject of the calendar entry overwrites the sitemap label --> would it be possible to have it displayed in 2 lines, like 1st line = sitemap label, 2nd line = subject of calendar entry?

image

9037568 commented 6 years ago

Please move this discussion to the community forum.