eclipse-archived / smarthome

Eclipse SmartHome™ project
https://www.eclipse.org/smarthome/
Eclipse Public License 2.0
861 stars 784 forks source link

[core] NPE in ThingRegistryImpl #6412

Open cweitkamp opened 5 years ago

cweitkamp commented 5 years ago

I edited a *.thing file three times in a row. Added a new thing, changed the configuration of the thing and renamed it afterwards.

Should this be handled?

2018-10-25 18:34:18.391 [WARN ] [ore.common.registry.AbstractRegistry] - Could not remove element: null
java.lang.NullPointerException: null
    at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.preserveDynamicState(ThingRegistryImpl.java:177) ~[?:?]
    at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.onRemoveElement(ThingRegistryImpl.java:158) ~[?:?]
    at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.onRemoveElement(ThingRegistryImpl.java:1) ~[?:?]
    at org.eclipse.smarthome.core.common.registry.AbstractRegistry.removed(AbstractRegistry.java:173) ~[?:?]
    at org.eclipse.smarthome.core.common.registry.AbstractRegistry.removed(AbstractRegistry.java:1) ~[?:?]
    at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:59) ~[?:?]
    at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:74) ~[?:?]
    at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListenersAboutRemovedElement(AbstractProvider.java:82) ~[?:?]
    at org.eclipse.smarthome.model.thing.internal.GenericThingProvider.lambda$20(GenericThingProvider.java:775) ~[?:?]
    at java.lang.Iterable.forEach(Iterable.java:75) ~[?:?]
    at org.eclipse.smarthome.model.thing.internal.GenericThingProvider.modelChanged(GenericThingProvider.java:777) ~[?:?]
    at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.notifyListeners(ModelRepositoryImpl.java:301) ~[?:?]
    at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.addOrRefreshModel(ModelRepositoryImpl.java:139) ~[?:?]
    at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.checkFile(FolderObserver.java:227) ~[?:?]
    at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.processWatchEvent(FolderObserver.java:291) ~[?:?]
    at org.eclipse.smarthome.core.service.WatchQueueReader.lambda$3(WatchQueueReader.java:323) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
    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) [?:?]
kaikreuzer commented 5 years ago

Definitely should, the question is where. Imho, the thing must not be null at that place in the first place, so I would not want to add a null check in ThingRegistryImpl.preserveDynamicState. We'll probably have to figure out, where it is getting null upstream to fix the right place. Can you reproduce it and do such an analysis?

cweitkamp commented 5 years ago

I have tried to figure it out yesterday. I think we could add the null check in the AbstractRegistry after line 172 - and after line 194 too:

https://github.com/eclipse/smarthome/blob/21d2a89b719ee853c62360ed9045351da74b228b/bundles/core/org.eclipse.smarthome.core/src/main/java/org/eclipse/smarthome/core/common/registry/AbstractRegistry.java#L169-L176

Why? Because the AbstractRegistry::get() method could return null if no element was found.

Wdyt?

kaikreuzer commented 5 years ago

If we are at that line, it means that some provider claims that an element has been removed, which wasn't (successfully) added before - so we might need to look for the bug even higher in the stack, i.e. in the GenericThingProvider. But it won't harm to add a safe guard here in the AbstractRegistry as well, I agree.

cweitkamp commented 5 years ago

I submitted a PR for NPE safe-guard in the AbstractRegistry but I am afraid I cannot help very much with analysing the GenericThingProvider. It is written in xtend and I am feeling not comfortable with it.

cweitkamp commented 5 years ago

From different point of views. Maybe it helps.

Before installing the new OH2 milestone during shutdown - again the ThingRegistryImpl:

2018-10-30 21:20:37.676 [WARN ] [ore.common.registry.AbstractRegistry] - Could not remove element: null
java.lang.NullPointerException: null
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.preserveDynamicState(ThingRegistryImpl.java:177) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.onRemoveElement(ThingRegistryImpl.java:158) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.onRemoveElement(ThingRegistryImpl.java:1) ~[?:?]
        at org.eclipse.smarthome.core.common.registry.AbstractRegistry.removed(AbstractRegistry.java:173) ~[?:?]
        at org.eclipse.smarthome.core.common.registry.AbstractRegistry.removed(AbstractRegistry.java:1) ~[?:?]
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:59) ~[?:?]
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:74) ~[?:?]
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListenersAboutRemovedElement(AbstractProvider.java:82) ~[?:?]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider.lambda$21(GenericThingProvider.java:792) ~[?:?]
        at java.util.ArrayList.forEach(ArrayList.java:1257) [?:?]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider.modelChanged(GenericThingProvider.java:794) [142:org.eclipse.smarth
ome.model.thing:0.10.0.oh240M4]
        at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.notifyListeners(ModelRepositoryImpl.java:301) [125:org.eclipse.smarth
ome.model.core:0.10.0.oh240M4]
        at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.removeAllModelsOfType(ModelRepositoryImpl.java:215) [125:org.eclipse.
smarthome.model.core:0.10.0.oh240M4]
        at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.removeModelParser(FolderObserver.java:91) [125:org.eclipse.smarthom
e.model.core:0.10.0.oh240M4]
        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.methods.BaseMethod.invokeMethod(BaseMethod.java:228) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:664) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:510) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.inject.methods.BindMethod.invoke(BindMethod.java:42) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:1923) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeUnbindMethod(SingleComponentManager.java:432) [39:org.apache.felix.s
cr:2.1.2]
        at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:390) [39:org.ap
ache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:302) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1242) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1137) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.untrack(ServiceTracker.java:997) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1176) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:125) [39:org.apache.felix.scr:2.1.2]
        at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:920) [?:?]
        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.unregister(ServiceRegistrationImpl.java:222) [?:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:912) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:877) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:135) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterService(AbstractComponentManager.java:954) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:808) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:790) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:579) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:716) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:511) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:428) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.Activator.access$300(Activator.java:49) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:291) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.AbstractExtender$1.run(AbstractExtender.java:216) [39:org.apache.felix.scr:2.1.2]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at org.apache.felix.scr.impl.AbstractExtender.destroyExtension(AbstractExtender.java:238) [39:org.apache.felix.scr:2.1.2]
        at org.apache.felix.scr.impl.AbstractExtender.bundleChanged(AbstractExtender.java:132) [39:org.apache.felix.scr:2.1.2]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908) [?:?]
        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:168) [?:?]
        at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) [?:?]
        at org.eclipse.osgi.container.Module.doStop(Module.java:634) [?:?]
        at org.eclipse.osgi.container.Module.stop(Module.java:498) [?:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1675) [?:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1594) [?:?]
        at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:270) [?:?]
        at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:147) [?:?]
        at org.eclipse.osgi.container.Module.doStop(Module.java:636) [?:?]
        at org.eclipse.osgi.container.Module.stop(Module.java:498) [?:?]
        at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:202) [?:?]
        at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:165) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]

After installing the new OH2 milestone during restart - this time it is the ItemRegistryImpl:

2018-10-30 21:27:49.148 [WARN ] [ore.common.registry.AbstractRegistry] - Could not remove element: null
java.lang.NullPointerException: null
        at org.eclipse.smarthome.core.internal.items.ItemRegistryImpl.onRemoveElement(ItemRegistryImpl.java:238) ~[101:org.eclipse.smarthome.c
ore:0.10.0.oh240M5]
        at org.eclipse.smarthome.core.internal.items.ItemRegistryImpl.onRemoveElement(ItemRegistryImpl.java:1) ~[101:org.eclipse.smarthome.cor
e:0.10.0.oh240M5]
        at org.eclipse.smarthome.core.common.registry.AbstractRegistry.removed(AbstractRegistry.java:173) [101:org.eclipse.smarthome.core:0.10
.0.oh240M5]
        at org.eclipse.smarthome.core.internal.items.ItemRegistryImpl.removed(ItemRegistryImpl.java:403) [101:org.eclipse.smarthome.core:0.10.
0.oh240M5]
        at org.eclipse.smarthome.core.internal.items.ItemRegistryImpl.removed(ItemRegistryImpl.java:1) [101:org.eclipse.smarthome.core:0.10.0.
oh240M5]
        at org.eclipse.smarthome.core.common.registry.AbstractRegistry.removed(AbstractRegistry.java:1) [101:org.eclipse.smarthome.core:0.10.0
.oh240M5]
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:59) [101:org.eclipse.smarthome.co
re:0.10.0.oh240M5]
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:74) [101:org.eclipse.smarthome.co
re:0.10.0.oh240M5]
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListenersAboutRemovedElement(AbstractProvider.java:82) [101:org.e
clipse.smarthome.core:0.10.0.oh240M5]
        at org.eclipse.smarthome.model.item.internal.GenericItemProvider.notifyAndCleanup(GenericItemProvider.java:452) [128:org.eclipse.smart
home.model.item:0.10.0.oh240M5]
        at org.eclipse.smarthome.model.item.internal.GenericItemProvider.modelChanged(GenericItemProvider.java:444) [128:org.eclipse.smarthome
.model.item:0.10.0.oh240M5]
        at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.notifyListeners(ModelRepositoryImpl.java:301) [127:org.eclipse.smarth
ome.model.core:0.10.0.oh240M5]
        at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.removeModel(ModelRepositoryImpl.java:158) [127:org.eclipse.smarthome.
model.core:0.10.0.oh240M5]
        at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.checkFile(FolderObserver.java:235) [127:org.eclipse.smarthome.model
.core:0.10.0.oh240M5]
        at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.processWatchEvent(FolderObserver.java:291) [127:org.eclipse.smartho
me.model.core:0.10.0.oh240M5]
        at org.eclipse.smarthome.core.service.WatchQueueReader.run(WatchQueueReader.java:240) [101:org.eclipse.smarthome.core:0.10.0.oh240M5]
        at java.lang.Thread.run(Thread.java:748) [?:?]
cweitkamp commented 5 years ago

Something else which might help and could be related:

2018-10-30 21:42:20.550 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'max.items'
2018-10-30 21:42:20.790 [WARN ] [ore.common.registry.AbstractRegistry] - Metadata with key 'channel:maxOfficeSetTemperature' already exists from provider GenericMetadataProvider! Failed to add a second with the same UID from provider GenericMetadataProvider!
2018-10-30 21:42:20.812 [WARN ] [ore.common.registry.AbstractRegistry] - Metadata with key 'channel:maxLeonieSetTemperature' already exists from provider GenericMetadataProvider! Failed to add a second with the same UID from provider GenericMetadataProvider!
2018-10-30 21:42:20.838 [WARN ] [ore.common.registry.AbstractRegistry] - Metadata with key 'channel:maxLinaSetTemperature' already exists from provider GenericMetadataProvider! Failed to add a second with the same UID from provider GenericMetadataProvider!
...
2018-10-30 21:42:22.493 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'tradfri.items'
2018-10-30 21:42:22.621 [WARN ] [ore.common.registry.AbstractRegistry] - Metadata with key 'channel:tradfriTerraceLeftStatus' already exists from provider GenericMetadataProvider! Failed to add a second with the same UID from provider GenericMetadataProvider!
2018-10-30 21:42:22.633 [WARN ] [ore.common.registry.AbstractRegistry] - Metadata with key 'channel:tradfriTerraceRightStatus' already exists from provider GenericMetadataProvider! Failed to add a second with the same UID from provider GenericMetadataProvider!

All those items use a follow profile like this:

Switch tradfriTerraceLeftStatus "Beleuchtung links [MAP(de.map):%s]" <light> (gTERRACELIGHTS,gSUNSETLIGHTS) ["Terrasse","Licht"] {
    channel="hue:0220:XXXXXX:10:brightness", channel="hue:0210:XXXXXX:8:color"[profile="follow"]
}