eclipse-archived / smarthome

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

"Scan for Things" is causing issues in the log #6295

Closed NorbertHD closed 6 years ago

NorbertHD commented 6 years ago

For me the issue #6266 that should be fixed with #6216 is still there. I tested with openhabian and openHAB build 1378. At least with the binding AVMFRITZ!Box, HUE, Harmony and Onkyo the issue is still there:

2018-10-01 14:59:29.907 [ERROR] [nternal.DiscoveryServiceRegistryImpl] - Cannot notify the DiscoveryListener org.eclipse.smarthome.config.discovery.internal.PersistentInbox on Thing discovered event!
java.lang.ClassCastException: org.eclipse.smarthome.config.discovery.internal.DiscoveryResultImpl cannot be cast to org.eclipse.smarthome.config.discovery.DiscoveryResult
        at org.eclipse.smarthome.config.discovery.internal.PersistentInbox.get(PersistentInbox.java:422) ~[97:org.eclipse.smarthome.config.discovery:0.10.0.201809271800]
        at org.eclipse.smarthome.config.discovery.internal.PersistentInbox.notifyListeners(PersistentInbox.java:488) ~[97:org.eclipse.smarthome.config.discovery:0.10.0.201809271800]
        at org.eclipse.smarthome.config.discovery.internal.PersistentInbox.add(PersistentInbox.java:191) ~[97:org.eclipse.smarthome.config.discovery:0.10.0.201809271800]
        at org.eclipse.smarthome.config.discovery.internal.PersistentInbox.thingDiscovered(PersistentInbox.java:345) ~[97:org.eclipse.smarthome.config.discovery:0.10.0.201809271800]
        at org.eclipse.smarthome.config.discovery.internal.DiscoveryServiceRegistryImpl$1.run(DiscoveryServiceRegistryImpl.java:268) ~[97:org.eclipse.smarthome.config.discovery:0.10.0.201809271800]
        at org.eclipse.smarthome.config.discovery.internal.DiscoveryServiceRegistryImpl$1.run(DiscoveryServiceRegistryImpl.java:1) ~[97:org.eclipse.smarthome.config.discovery:0.10.0.201809271800]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.eclipse.smarthome.config.discovery.internal.DiscoveryServiceRegistryImpl.thingDiscovered(DiscoveryServiceRegistryImpl.java:265) [97:org.eclipse.smarthome.config.discovery:0.10.0.201809271800]
        at org.eclipse.smarthome.config.discovery.AbstractDiscoveryService.thingDiscovered(AbstractDiscoveryService.java:278) [97:org.eclipse.smarthome.config.discovery:0.10.0.201809271800]
        at org.eclipse.smarthome.config.discovery.upnp.internal.UpnpDiscoveryService.remoteDeviceAdded(UpnpDiscoveryService.java:190) [196:org.eclipse.smarthome.config.discovery.upnp:0.10.0.201809271800]
        at org.jupnp.registry.RemoteItems$1.run(RemoteItems.java:114) [198:org.jupnp:2.4.0]
        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) [?:?]
2018-10-01 14:59:53.992 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.ClassCastException: org.eclipse.smarthome.config.discovery.internal.DiscoveryResultImpl cannot be cast to org.eclipse.smarthome.config.discovery.DiscoveryResult
        at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:174) ~[?:?]
        at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1382) ~[?:?]
        at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) ~[?:?]
        at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) ~[?:?]
        at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708) ~[?:?]
        at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
        at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499) ~[?:?]
        at org.eclipse.smarthome.config.discovery.internal.PersistentInbox.getAll(PersistentInbox.java:295) ~[?:?]
        at org.eclipse.smarthome.config.discovery.internal.PersistentInbox$TimeToLiveCheckingThread.run(PersistentInbox.java:114) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:?]
        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) [?:?]

I noticed something else, when I have installed these bindings, the spinning circle for busy remains forever. I have to go to another menue and then back to Add-ons->Bindings to see that the binding is installed.

MHerbst commented 6 years ago

I have the same problem with the installation of the HomeMatic binding. I have performed a new test and saw some additional messages right before the exception:

10:38:58.432 [INFO ] [i.dashboard.internal.DashboardService] - Stopped Dashboard
10:39:06.442 [INFO ] [mebuilder.internal.HomeBuilderServlet] - Stopped Home Builder
10:39:06.445 [INFO ] [bpanel.internal.HABPanelDashboardTile] - Stopped HABPanel
10:39:06.453 [INFO ] [marthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
10:39:06.469 [INFO ] [.basic.internal.servlet.WebAppServlet] - Stopped Basic UI
10:39:27.229 [WARN ] [rg.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.80.225
10:39:27.702 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.2.10:8080
10:39:27.703 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.2.10:8443
10:39:27.716 [INFO ] [mebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
10:39:27.734 [INFO ] [bpanel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
10:39:27.749 [INFO ] [marthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
10:39:27.783 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.ClassCastException: org.eclipse.smarthome.config.discovery.internal.DiscoveryResultImpl cannot be cast to org.eclipse.smarthome.config.discovery.DiscoveryResult
        at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:174) ~[?:?]

The services were stopped immediately after I clicked on the "Install" link for the binding Paper UI. This does not happen for all bindings (e.g. with Astro or Network). Same happens if I uninstall the HomeMatic binding in Paper UI.

htreu commented 6 years ago

Thanks @MHerbst for the additional logs. According to stackoverflow this happens when a bundle tries to load a class with a different classloader. In our case the discoveryResultStorage instance created in the PersistentInbox is created with the classloader of the org.eclipse.smarthome.config.discovery bundle. When this bundle restarts and later on requests the discoveryResultStorage again, the instance still exists in case of the JsonStorageService.

Question @NorbertHD & @MHerbst: do you have JSONStorageService configured?

It should not have the same issue for the MapDBStorageService, because new Storage instances are created every time one os requested.

NorbertHD commented 6 years ago

@htreu I don't know. Is JSONStorageService default? Because to test I did a clean openHAB installation and the only things changed are the language, location and "Simple Item Linking" before I installed the aformentioned bindings.

MHerbst commented 6 years ago

Same here, @htreu. I used the default configuration and as far as I can see all settings are stored in subdir jsondb. If you give me a hint where I can configure the storage service I would test it with MapDBStorageService.

htreu commented 6 years ago

It should be Json storage then, when I enter services | grep Storage in the karaf console of a fresh instal the output is

Eclipse SmartHome Json Storage Service (145) provides:
[org.eclipse.smarthome.core.storage.StorageService]

I will investigate what makes the discovery bundle restart. Apart from that my fix proposal would be to also provide a new Storage instance from JsonStorageService every time it is requested.

kaikreuzer commented 6 years ago

I will investigate what makes the discovery bundle restart.

This usually happens upon an update of openHAB - when Karaf initializes a new OSGi container with all the bundles and then starts adding openHAB features, I see it more or less restarts all ESH core bundles at some moment. Whether or not we can avoid this is out of scope here, I would say. In any case, if the discovery bundle is restarted, the system should just continue to work as expected.