search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.88k stars 3.59k forks source link

Issue deleting things after converting to new build system #5519

Closed mhilbush closed 5 years ago

mhilbush commented 5 years ago

I was converting one of my WIP bindings to the new build system. While testing the binding I noticed an issue when deleting a thing. After deleting a thing using Paper UI, even though the thing was deleted, when I stop/start my binding, the thing handler is initialized for the thing I just deleted.

To eliminate my binding from the mix, I created a skeleton binding, which I built using the old build system. I made only very minor logging changes to the skeleton. Using this binding I was able to successfully delete things with no issue.

Then I converted the skeleton binding to the new build system. I've done several conversions to the new build system, so I'm pretty sure I did this correctly.

Then I built the binding, dropped it in addons, and repeated my tests adding and deleting things.

Here's the log with my comments describing what was happening. Note near the end of the log where I delete the thing. When I stop/start the binding, the handler is initialized for the thing I just deleted.

I'm at a loss to explain this. Could someone please take a look at this to see if I'm doing something wrong. The source is in these two branches.

Log file illustrating the issue

// Deployed binding built with old build system to addons
2019-04-27 10:11:16.930 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent UPDATED - org.openhab.binding.testbinding
2019-04-27 10:11:16.950 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent RESOLVED - org.openhab.binding.testbinding
2019-04-27 10:11:16.951 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STARTING - org.openhab.binding.testbinding
2019-04-27 10:11:16.952 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STARTED - org.openhab.binding.testbinding
2019-04-27 10:11:16.954 [DEBUG] [org.openhab.binding.testbinding     ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=425, service.bundleid=265, service.scope=bundle, component.name=org.openhab.binding.testbinding.internal.TestBindingHandlerFactory, component.id=265} - org.openhab.binding.testbinding

// Added a thing
2019-04-27 10:11:52.629 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler initializing for thing testbinding:sample:65b2d6c1

// Deleted thing using Paper UI
2019-04-27 10:12:08.341 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler disposing for thing testbinding:sample:65b2d6c1

// Added another thing
2019-04-27 10:12:25.825 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler initializing for thing testbinding:sample:cc5f745e

// Deleted thing using Paper UI
2019-04-27 10:12:33.777 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler disposing for thing testbinding:sample:cc5f745e

// Removed binding built with old build system from addons
2019-04-27 10:43:37.013 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STOPPING - org.openhab.binding.testbinding
2019-04-27 10:43:37.014 [DEBUG] [org.openhab.binding.testbinding     ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=425, service.bundleid=265, service.scope=bundle, component.name=org.openhab.binding.testbinding.internal.TestBindingHandlerFactory, component.id=265} - org.openhab.binding.testbinding
2019-04-27 10:43:37.019 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STOPPED - org.openhab.binding.testbinding
2019-04-27 10:43:37.019 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent UNRESOLVED - org.openhab.binding.testbinding
2019-04-27 10:43:37.020 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent UNINSTALLED - org.openhab.binding.testbinding

// Converted binding to new build system, built binding, installed in addons
2019-04-27 10:44:17.034 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent INSTALLED - org.openhab.binding.testbinding
2019-04-27 10:44:17.048 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent RESOLVED - org.openhab.binding.testbinding
2019-04-27 10:44:17.050 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STARTING - org.openhab.binding.testbinding
2019-04-27 10:44:17.051 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STARTED - org.openhab.binding.testbinding
2019-04-27 10:44:17.054 [DEBUG] [org.openhab.binding.testbinding     ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=426, service.bundleid=266, service.scope=bundle, component.name=org.openhab.binding.testbinding.internal.TestBindingHandlerFactory, component.id=266} - org.openhab.binding.testbinding

// Added a thing
2019-04-27 10:44:43.022 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler initializing for thing testbinding:sample:e40d9411

// Deleted the thing using Paper UI
2019-04-27 10:44:53.656 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler disposing for thing testbinding:sample:e40d9411
// Paper UI reported "Thing removal initiated"
// However, thing was still visible in Configuration.Things list
// Refreshed Configuration.Things list page and thing was gone
// When I inspect the jsondb, the thing is not there

// Stopped binding using Karaf console
2019-04-27 10:45:48.868 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STOPPING - org.openhab.binding.testbinding
2019-04-27 10:45:48.868 [DEBUG] [org.openhab.binding.testbinding     ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=426, service.bundleid=266, service.scope=bundle, component.name=org.openhab.binding.testbinding.internal.TestBindingHandlerFactory, component.id=266} - org.openhab.binding.testbinding
2019-04-27 10:45:48.874 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STOPPED - org.openhab.binding.testbinding

// Started binding using Karaf console
2019-04-27 10:45:52.153 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STARTING - org.openhab.binding.testbinding
2019-04-27 10:45:52.153 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STARTED - org.openhab.binding.testbinding
2019-04-27 10:45:52.155 [DEBUG] [org.openhab.binding.testbinding     ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=427, service.bundleid=266, service.scope=bundle, component.name=org.openhab.binding.testbinding.internal.TestBindingHandlerFactory, component.id=267} - org.openhab.binding.testbinding

// Note that handler is initialized for thing that was deleted
2019-04-27 10:45:52.161 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler initializing for thing testbinding:sample:e40d9411
J-N-K commented 5 years ago

Did you try restarting the bundle with the old version after removing the thing? Is this working?

mhilbush commented 5 years ago

Did you try restarting the bundle with the old version after removing the thing? Is this working?

I haven't tried that directly, but I will.

The only way I've found so far to clear it is to restart openHAB. I assume that's because the thing isn't in the jsondb, and so a fresh start of the systems clears out any internal knowledge that the thing exists.

mhilbush commented 5 years ago

Did you try restarting the bundle with the old version after removing the thing? Is this working?

Replacing the binding built using the new build system with the binding built using the old build system results in the handler being initialized for the deleted thing. Odd, but not surprising since something believes the thing still exists.

Also note: If I list the things in the Karaf console (smarthome:things list), nothing shows up for the deleted thing, even thought there exists a handler for the thing.

J-N-K commented 5 years ago

So we have to fix that in core and it is not build-System related.

mhilbush commented 5 years ago

Ok, but I'm not sure how to track this down any further. Do you have any suggestions where to look next?

But what I don't understand... Nothing is different in the core. The only variable is the binding built with the new build system versus the old build system. If I delete a thing using the binding built with the old build system, everything works fine. But, if I delete a thing using the binding built with the new build system, it says it's deleted, but it really isn't deleted (at least not fully deleted).

Note that I do see differences in the jar files (e.g. manifest, etc.), but I don't know enough to interpret the differences.

J-N-K commented 5 years ago

To get things clear:

  1. creating thing with the old binding, deleting it, restarting the (old) bundle ->not initializing
  2. creating thing with the old binding, deleting it, installing the new binding -> initializing
  3. creating thing with the old binding, deleting it, installing the new binding, installing the old binding -> initializing

Is that right?

mhilbush commented 5 years ago

Close. Here are the two key scenarios.

Binding built with old build system (i.e. old binding)

Binding built with new build system (i.e. new binding)

mhilbush commented 5 years ago

FTR, here are the two jars

J-N-K commented 5 years ago

Can you try setting org.eclipse.smarthome.core.thing.internal.ThingManagerImpl do DEBUG and see if there is any difference when removing the thing?

mhilbush commented 5 years ago

Here you go. I don't see a difference on the delete. But there's definitely a difference when starting the binding after the delete.

Old Binding

// Create thing
2019-04-27 14:23:48.855 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing 'testbinding:sample:18d9bacb' is tracked by ThingManager.
2019-04-27 14:23:48.856 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling 'TestBindingHandlerFactory.registerHandler()' for thing 'testbinding:sample:18d9bacb'.
2019-04-27 14:23:48.859 [DEBUG] [core.thing.internal.ThingManagerImpl] - Configuration of 'testbinding:sample:18d9bacb' needs [config1], has [config1].
2019-04-27 14:23:48.860 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'testbinding:sample-channel' is not resolvable, assuming 'testbinding:sample:18d9bacb:channel1' is initializable
2019-04-27 14:23:48.860 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling initialize handler for thing 'testbinding:sample:18d9bacb' at 'org.openhab.binding.testbinding.internal.TestBindingHandler@e7b4610'.
2019-04-27 14:23:48.863 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler initializing for thing testbinding:sample:18d9bacb

// Delete thing
2019-04-27 14:24:04.963 [DEBUG] [core.thing.internal.ThingManagerImpl] - Removal handling of thing 'testbinding:sample:18d9bacb' completed. Going to remove it now.
2019-04-27 14:24:04.968 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing 'testbinding:sample:18d9bacb' is no longer tracked by ThingManager.
2019-04-27 14:24:04.969 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling dispose handler for thing 'testbinding:sample:18d9bacb' at 'org.openhab.binding.testbinding.internal.TestBindingHandler@e7b4610'.
2019-04-27 14:24:04.969 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler disposing for thing testbinding:sample:18d9bacb
2019-04-27 14:24:04.970 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling unregisterHandler handler for thing 'testbinding:sample:18d9bacb' at 'org.openhab.binding.testbinding.internal.TestBindingHandlerFactory@7e7ff904'.

// Stop binding
2019-04-27 14:24:38.946 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing handler factory 'TestBindingHandlerFactory' removed
2019-04-27 14:24:38.950 [DEBUG] [org.openhab.binding.testbinding     ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=417, service.bundleid=269, service.scope=bundle, component.name=org.openhab.binding.testbinding.internal.TestBindingHandlerFactory, component.id=257} - org.openhab.binding.testbinding
2019-04-27 14:24:38.953 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STOPPING - org.openhab.binding.testbinding
2019-04-27 14:24:38.955 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STOPPED - org.openhab.binding.testbinding

// Start binding
2019-04-27 14:24:54.780 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STARTING - org.openhab.binding.testbinding
2019-04-27 14:24:54.783 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing handler factory 'TestBindingHandlerFactory' added
2019-04-27 14:24:54.783 [DEBUG] [org.openhab.binding.testbinding     ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=418, service.bundleid=269, service.scope=bundle, component.name=org.openhab.binding.testbinding.internal.TestBindingHandlerFactory, component.id=258} - org.openhab.binding.testbinding
2019-04-27 14:24:54.784 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STARTED - org.openhab.binding.testbinding

New Binding

// Create thing
2019-04-27 14:28:09.961 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing 'testbinding:sample:4ff1ed1e' is tracked by ThingManager.
2019-04-27 14:28:09.961 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling 'TestBindingHandlerFactory.registerHandler()' for thing 'testbinding:sample:4ff1ed1e'.
2019-04-27 14:28:09.964 [DEBUG] [core.thing.internal.ThingManagerImpl] - Configuration of 'testbinding:sample:4ff1ed1e' needs [config1], has [config1].
2019-04-27 14:28:09.964 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'testbinding:sample-channel' is not resolvable, assuming 'testbinding:sample:4ff1ed1e:channel1' is initializable
2019-04-27 14:28:09.965 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling initialize handler for thing 'testbinding:sample:4ff1ed1e' at 'org.openhab.binding.testbinding.internal.TestBindingHandler@2f037552'.
2019-04-27 14:28:09.967 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler initializing for thing testbinding:sample:4ff1ed1e

//Delete
2019-04-27 14:28:21.895 [DEBUG] [core.thing.internal.ThingManagerImpl] - Removal handling of thing 'testbinding:sample:4ff1ed1e' completed. Going to remove it now.
2019-04-27 14:28:21.897 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing 'testbinding:sample:4ff1ed1e' is no longer tracked by ThingManager.
2019-04-27 14:28:21.897 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling dispose handler for thing 'testbinding:sample:4ff1ed1e' at 'org.openhab.binding.testbinding.internal.TestBindingHandler@2f037552'.
2019-04-27 14:28:21.898 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler disposing for thing testbinding:sample:4ff1ed1e
2019-04-27 14:28:21.898 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling unregisterHandler handler for thing 'testbinding:sample:4ff1ed1e' at 'org.openhab.binding.testbinding.internal.TestBindingHandlerFactory@392a34e'.

// Stop binding
2019-04-27 14:28:41.518 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing handler factory 'TestBindingHandlerFactory' removed
2019-04-27 14:28:41.522 [DEBUG] [org.openhab.binding.testbinding     ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=419, service.bundleid=270, service.scope=bundle, component.name=org.openhab.binding.testbinding.internal.TestBindingHandlerFactory, component.id=259} - org.openhab.binding.testbinding
2019-04-27 14:28:41.525 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STOPPING - org.openhab.binding.testbinding
2019-04-27 14:28:41.526 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STOPPED - org.openhab.binding.testbinding

// Start binding
2019-04-27 14:28:52.798 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STARTING - org.openhab.binding.testbinding
2019-04-27 14:28:52.800 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing handler factory 'TestBindingHandlerFactory' added
2019-04-27 14:28:52.801 [DEBUG] [core.thing.internal.ThingManagerImpl] - Not registering a handler at this point. The thing types of bundle org.openhab.binding.testbinding are not fully loaded yet.
2019-04-27 14:28:52.802 [DEBUG] [org.openhab.binding.testbinding     ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=420, service.bundleid=270, service.scope=bundle, component.name=org.openhab.binding.testbinding.internal.TestBindingHandlerFactory, component.id=260} - org.openhab.binding.testbinding
2019-04-27 14:28:52.802 [DEBUG] [org.openhab.binding.testbinding     ] - BundleEvent STARTED - org.openhab.binding.testbinding
2019-04-27 14:28:52.805 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling 'TestBindingHandlerFactory.registerHandler()' for thing 'testbinding:sample:4ff1ed1e'.
2019-04-27 14:28:52.808 [DEBUG] [core.thing.internal.ThingManagerImpl] - Configuration of 'testbinding:sample:4ff1ed1e' needs [config1], has [config1].
2019-04-27 14:28:52.809 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'testbinding:sample-channel' is not resolvable, assuming 'testbinding:sample:4ff1ed1e:channel1' is initializable
2019-04-27 14:28:52.809 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling initialize handler for thing 'testbinding:sample:4ff1ed1e' at 'org.openhab.binding.testbinding.internal.TestBindingHandler@1ea4cd06'.
2019-04-27 14:28:52.810 [DEBUG] [tbinding.internal.TestBindingHandler] - Handler initializing for thing testbinding:sample:4ff1ed1e
mhilbush commented 5 years ago

To make the record more complete, here's the diff of the two jars.

$ diff --recursive old new
diff --recursive old/META-INF/MANIFEST.MF new/META-INF/MANIFEST.MF
1a2
> Bundle-Description: "This project contains the add-ons of openHAB"
3c4,6
< Bundle-SymbolicName: org.openhab.binding.testbinding;singleton:=true
---
> Bundle-License: "Eclipse Public License 2.0";link="https://www.eclipse
>  .org/legal/epl-2.0/"
> Bundle-SymbolicName: org.openhab.binding.testbinding
5c8
< Bundle-ActivationPolicy: lazy
---
> Bnd-LastModified: 1556376132268
7,19c10,31
< Bundle-RequiredExecutionEnvironment: JavaSE-1.8
< Bundle-Vendor: openHAB
< Import-Package: org.eclipse.jdt.annotation;resolution:=optional,org.ec
<  lipse.smarthome.config.core,org.eclipse.smarthome.core.library.types,
<  org.eclipse.smarthome.core.thing,org.eclipse.smarthome.core.thing.bin
<  ding,org.eclipse.smarthome.core.thing.binding.builder,org.eclipse.sma
<  rthome.core.thing.type,org.eclipse.smarthome.core.types,org.eclipse.s
<  marthome.core.util,org.slf4j
< Service-Component: OSGI-INF/*.xml
< Bundle-Name: TestBinding Binding
< Bundle-Version: 2.5.0.201904271410
< Bundle-ClassPath: .
< Created-By: Apache Maven 3.3.9
---
> Bundle-Vendor: openHAB.org
> Import-Package: org.eclipse.smarthome.core.thing,org.eclipse.smarthome
>  .core.thing.binding,org.eclipse.smarthome.core.types,org.slf4j;versio
>  n="[1.7,2)"
> Require-Capability: osgi.extender;filter:="(&(osgi.extender=osgi.compo
>  nent)(version>=1.3.0)(!(version>=2.0.0)))",osgi.ee;filter:="(&(osgi.e
>  e=JavaSE)(version=1.8))"
> Service-Component: OSGI-INF/org.openhab.binding.testbinding.internal.T
>  estBindingHandlerFactory.xml
> Tool: Bnd-4.2.0.201903051501
> Provide-Capability: osgi.service;objectClass:List<String>="org.eclipse
>  .smarthome.core.thing.binding.ThingHandlerFactory"
> Bundle-Name: openHAB Add-ons :: Bundles :: TestBinding Binding
> Bundle-Version: 2.5.0.201904271442
> Bundle-SCM: url="https://github.com/org.openhab.addons.reactor.bundles
>  /org.openhab.binding.testbinding",connection="scm:git:https://github.
>  com/org.openhab.addons.reactor.bundles/org.openhab.binding.testbindin
>  g",developer-connection="scm:git:https://github.com/org.openhab.addon
>  s.reactor.bundles/org.openhab.binding.testbinding",tag=HEAD
> Private-Package: ESH-INF.binding,ESH-INF.i18n,ESH-INF.thing,org.openha
>  b.binding.testbinding.internal
> Created-By: 1.8.0_92 (Oracle Corporation)
Only in new/META-INF/maven: org.openhab.addons.bundles
Only in old/META-INF/maven: org.openhab.binding
Binary files old/org/openhab/binding/testbinding/internal/TestBindingHandlerFactory.class and new/org/openhab/binding/testbinding/internal/TestBindingHandlerFactory.class differ
diff --recursive old/OSGI-INF/org.openhab.binding.testbinding.internal.TestBindingHandlerFactory.xml new/OSGI-INF/org.openhab.binding.testbinding.internal.TestBindingHandlerFactory.xml
1,7c1,7
< <?xml version="1.0" encoding="UTF-8"?>
< <scr:component xmlns:scr="http://www.osgi.org/xmlns/scr/v1.2.0" name="org.openhab.binding.testbinding.internal.TestBindingHandlerFactory" configuration-pid="binding.testbinding">
<     <service servicefactory="false">
<         <provide interface="org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory"/>
<     </service>
<     <implementation class="org.openhab.binding.testbinding.internal.TestBindingHandlerFactory"/>
< </scr:component>
---
> <?xml version="1.0" encoding="UTF-8"?>
> <scr:component xmlns:scr="http://www.osgi.org/xmlns/scr/v1.3.0" name="org.openhab.binding.testbinding.internal.TestBindingHandlerFactory" configuration-pid="binding.testbinding">
>   <service>
>     <provide interface="org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory"/>
>   </service>
>   <implementation class="org.openhab.binding.testbinding.internal.TestBindingHandlerFactory"/>
> </scr:component>
J-N-K commented 5 years ago

I'm not an expert on that but maybe:

< Bundle-SymbolicName: org.openhab.binding.testbinding;singleton:=true
> Bundle-SymbolicName: org.openhab.binding.testbinding

and 

<     <service servicefactory="false">
<         <provide interface="org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory"/>
<     </service>
>   <service>
>     <provide interface="org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory"/>
>   </service>

are part of the problem. The singleton shpuld make sure that there is only one instance of the factory. Maybe it is not properly removed with the new version when restarting the bundle.

davidgraeff commented 5 years ago

@openhab/core-maintainers That bug might be interesting

maggu2810 commented 5 years ago

Cannot reproduce it myself:

22:18:17.699 DEBUG [qtp1864451953-243] Creating thing for type 'astro:moon'.
22:18:17.723 DEBUG [qtp1864451953-243] Thing 'astro:moon:test' is tracked by ThingManager.
22:18:17.725 INFO [safeCall-3] Thing 'astro:moon:test' has been added.
22:18:17.725 DEBUG [qtp1864451953-243] Calling 'AstroHandlerFactory.registerHandler()' for thing 'astro:moon:test'.
22:18:17.730 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test' needs [geolocation], has [interval, geolocation].
22:18:17.731 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:rise#start' needs [], has [offset].
22:18:17.732 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:rise#end' needs [], has [offset].
22:18:17.733 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:rise#event' needs [], has [offset].
22:18:17.734 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:set#start' needs [], has [offset].
22:18:17.734 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:set#end' needs [], has [offset].
22:18:17.735 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:set#event' needs [], has [offset].
22:18:17.735 DEBUG [qtp1864451953-243] Config description for 'astro:firstQuarter' is not resolvable, assuming 'astro:moon:test:phase#firstQuarter' is initializable
22:18:17.736 DEBUG [qtp1864451953-243] Config description for 'astro:thirdQuarter' is not resolvable, assuming 'astro:moon:test:phase#thirdQuarter' is initializable
22:18:17.737 DEBUG [qtp1864451953-243] Config description for 'astro:fullMoon' is not resolvable, assuming 'astro:moon:test:phase#full' is initializable
22:18:17.738 DEBUG [qtp1864451953-243] Config description for 'astro:newMoon' is not resolvable, assuming 'astro:moon:test:phase#new' is initializable
22:18:17.739 DEBUG [qtp1864451953-243] Config description for 'astro:age' is not resolvable, assuming 'astro:moon:test:phase#age' is initializable
22:18:17.742 DEBUG [qtp1864451953-243] Config description for 'astro:ageDegree' is not resolvable, assuming 'astro:moon:test:phase#ageDegree' is initializable
22:18:17.743 DEBUG [qtp1864451953-243] Config description for 'astro:agePercent' is not resolvable, assuming 'astro:moon:test:phase#agePercent' is initializable
22:18:17.744 DEBUG [qtp1864451953-243] Config description for 'astro:illumination' is not resolvable, assuming 'astro:moon:test:phase#illumination' is initializable
22:18:17.745 DEBUG [qtp1864451953-243] Config description for 'astro:phaseName' is not resolvable, assuming 'astro:moon:test:phase#name' is initializable
22:18:17.746 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:phase#event' needs [], has [offset].
22:18:17.748 DEBUG [qtp1864451953-243] Config description for 'astro:total' is not resolvable, assuming 'astro:moon:test:eclipse#total' is initializable
22:18:17.750 DEBUG [qtp1864451953-243] Config description for 'astro:partial' is not resolvable, assuming 'astro:moon:test:eclipse#partial' is initializable
22:18:17.751 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:eclipse#event' needs [], has [offset].
22:18:17.752 DEBUG [qtp1864451953-243] Config description for 'astro:distanceDate' is not resolvable, assuming 'astro:moon:test:distance#date' is initializable
22:18:17.753 DEBUG [qtp1864451953-243] Config description for 'astro:distance' is not resolvable, assuming 'astro:moon:test:distance#distance' is initializable
22:18:17.753 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:distance#event' needs [], has [offset].
22:18:17.754 DEBUG [qtp1864451953-243] Config description for 'astro:distanceDate' is not resolvable, assuming 'astro:moon:test:perigee#date' is initializable
22:18:17.755 DEBUG [qtp1864451953-243] Config description for 'astro:distance' is not resolvable, assuming 'astro:moon:test:perigee#distance' is initializable
22:18:17.755 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:perigee#event' needs [], has [offset].
22:18:17.756 DEBUG [qtp1864451953-243] Config description for 'astro:distanceDate' is not resolvable, assuming 'astro:moon:test:apogee#date' is initializable
22:18:17.757 DEBUG [qtp1864451953-243] Config description for 'astro:distance' is not resolvable, assuming 'astro:moon:test:apogee#distance' is initializable
22:18:17.757 DEBUG [qtp1864451953-243] Configuration of 'astro:moon:test:apogee#event' needs [], has [offset].
22:18:17.758 DEBUG [qtp1864451953-243] Config description for 'astro:azimuth' is not resolvable, assuming 'astro:moon:test:position#azimuth' is initializable
22:18:17.759 DEBUG [qtp1864451953-243] Config description for 'astro:elevation' is not resolvable, assuming 'astro:moon:test:position#elevation' is initializable
22:18:17.759 DEBUG [qtp1864451953-243] Config description for 'astro:shadeLength' is not resolvable, assuming 'astro:moon:test:position#shadeLength' is initializable
22:18:17.760 DEBUG [qtp1864451953-243] Config description for 'astro:sign' is not resolvable, assuming 'astro:moon:test:zodiac#sign' is initializable
22:18:17.762 INFO [safeCall-1] 'astro:moon:test' updated: INITIALIZING
22:18:17.762 DEBUG [qtp1864451953-243] Calling initialize handler for thing 'astro:moon:test' at 'org.openhab.binding.astro.internal.handler.MoonHandler@5634e965'.
22:18:17.767 INFO [safeCall-2] 'astro:moon:test' changed from UNINITIALIZED to INITIALIZING
22:18:17.777 INFO [safeCall-2] 'astro:moon:test' updated: ONLINE
22:18:17.793 INFO [safeCall-2] 'astro:moon:test' changed from INITIALIZING to ONLINE
22:18:17.826 INFO [safeCall-3] Scheduled Astro event-jobs for thing astro:moon:test
22:19:15.726 INFO [safeCall-2] 'astro:moon:test' updated: REMOVING
22:19:15.727 DEBUG [ESH-thingManager-1] Removal handling of thing 'astro:moon:test' completed. Going to remove it now.
22:19:15.731 INFO [safeCall-1] 'astro:moon:test' changed from ONLINE to REMOVING
22:19:15.740 INFO [safeCall-3] 'astro:moon:test' updated: REMOVED
22:19:15.747 INFO [safeCall-1] 'astro:moon:test' changed from REMOVING to REMOVED
22:19:15.749 DEBUG [forceRemove-1] Thing 'astro:moon:test' is no longer tracked by ThingManager.
22:19:15.751 DEBUG [forceRemove-1] Calling dispose handler for thing 'astro:moon:test' at 'org.openhab.binding.astro.internal.handler.MoonHandler@5634e965'.
22:19:15.752 INFO [safeCall-3] 'astro:moon:test' updated: UNINITIALIZED
22:19:15.760 INFO [safeCall-2] 'astro:moon:test' changed from REMOVED to UNINITIALIZED
22:19:15.762 DEBUG [forceRemove-1] Calling unregisterHandler handler for thing 'astro:moon:test' at 'org.openhab.binding.astro.internal.AstroHandlerFactory@1db4cf91'.
22:19:15.769 INFO [safeCall-1] 'astro:moon:test' updated: UNINITIALIZED (HANDLER_MISSING_ERROR)
22:19:15.773 INFO [safeCall-2] 'astro:moon:test' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
22:19:15.780 INFO [safeCall-1] Thing 'astro:moon:test' has been removed.
karaf@root()> log:clear
karaf@root()> bundle:stop org.openhab.binding.astro
karaf@root()> log:tail
22:20:06.184 DEBUG [pipe-bundle:stop org.openhab.binding.astro] Thing handler factory 'AstroHandlerFactory' removed
karaf@root()> log:clear
karaf@root()> bundle:start org.openhab.binding.astro
karaf@root()> log:tail
22:20:40.492 DEBUG [pipe-bundle:start org.openhab.binding.astro] Thing handler factory 'AstroHandlerFactory' added
mhilbush commented 5 years ago

Cannot reproduce it myself:

Can you try the jar file linked to in my comment above? Use the second one in the list (i.e. the one labeled new).

J-N-K commented 5 years ago

@mhilbush: which core are you running?

mhilbush commented 5 years ago

The one that came with build 1577.

133 │ Active │  80 │ 2.5.0.201904260301    │ org.openhab.core
maggu2810 commented 5 years ago 
2019-04-27T22:29:20,227 | DEBUG | pipe-bundle:start 248 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Thing handler factory 'TestBindingHandlerFactory' added
2019-04-27T22:30:50,994 | DEBUG | qtp1864451953-404 | ThingRegistryImpl                | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Creating thing for type 'testbinding:sample'.
2019-04-27T22:30:50,997 | DEBUG | qtp1864451953-404 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Thing 'testbinding:sample:test' is tracked by ThingManager.
2019-04-27T22:30:50,997 | INFO  | safeCall-8       | ThingAddedEvent                  | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | Thing 'testbinding:sample:test' has been added.
2019-04-27T22:30:50,998 | DEBUG | qtp1864451953-404 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Calling 'TestBindingHandlerFactory.registerHandler()' for thing 'testbinding:sample:test'.
2019-04-27T22:30:51,000 | DEBUG | qtp1864451953-404 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Configuration of 'testbinding:sample:test' needs [config1], has [config1].
2019-04-27T22:30:51,000 | DEBUG | qtp1864451953-404 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Config description for 'testbinding:sample-channel' is not resolvable, assuming 'testbinding:sample:test:channel1' is initializable
2019-04-27T22:30:51,001 | DEBUG | qtp1864451953-404 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Calling initialize handler for thing 'testbinding:sample:test' at 'org.openhab.binding.testbinding.internal.TestBindingHandler@c4a40e1'.
2019-04-27T22:30:51,001 | INFO  | safeCall-7       | ThingStatusInfoEvent             | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' updated: INITIALIZING
2019-04-27T22:30:51,002 | INFO  | safeCall-9       | ThingStatusInfoChangedEvent      | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' changed from UNINITIALIZED to INITIALIZING
2019-04-27T22:30:51,005 | INFO  | safeCall-8       | ThingStatusInfoEvent             | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' updated: UNKNOWN
2019-04-27T22:30:51,006 | INFO  | safeCall-8       | ThingStatusInfoChangedEvent      | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' changed from INITIALIZING to UNKNOWN
2019-04-27T22:30:51,006 | INFO  | safeCall-9       | ThingStatusInfoEvent             | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' updated: ONLINE
2019-04-27T22:30:51,007 | INFO  | safeCall-7       | ThingStatusInfoChangedEvent      | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' changed from UNKNOWN to ONLINE
2019-04-27T22:31:19,467 | INFO  | safeCall-9       | ThingStatusInfoEvent             | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' updated: REMOVING
2019-04-27T22:31:19,468 | DEBUG | ESH-thingManager-2 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Removal handling of thing 'testbinding:sample:test' completed. Going to remove it now.
2019-04-27T22:31:19,468 | INFO  | safeCall-8       | ThingStatusInfoChangedEvent      | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' changed from ONLINE to REMOVING
2019-04-27T22:31:19,469 | INFO  | safeCall-9       | ThingStatusInfoEvent             | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' updated: REMOVED
2019-04-27T22:31:19,469 | DEBUG | forceRemove-2    | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Thing 'testbinding:sample:test' is no longer tracked by ThingManager.
2019-04-27T22:31:19,470 | DEBUG | forceRemove-2    | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Calling dispose handler for thing 'testbinding:sample:test' at 'org.openhab.binding.testbinding.internal.TestBindingHandler@c4a40e1'.
2019-04-27T22:31:19,470 | DEBUG | forceRemove-2    | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Calling unregisterHandler handler for thing 'testbinding:sample:test' at 'org.openhab.binding.testbinding.internal.TestBindingHandlerFactory@26dda575'.
2019-04-27T22:31:19,472 | INFO  | safeCall-7       | ThingStatusInfoChangedEvent      | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' changed from REMOVING to REMOVED
2019-04-27T22:31:19,472 | INFO  | safeCall-9       | ThingStatusInfoEvent             | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' updated: UNINITIALIZED
2019-04-27T22:31:19,472 | INFO  | safeCall-7       | ThingStatusInfoChangedEvent      | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' changed from REMOVED to UNINITIALIZED
2019-04-27T22:31:19,477 | INFO  | safeCall-7       | ThingStatusInfoEvent             | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' updated: UNINITIALIZED (HANDLER_MISSING_ERROR)
2019-04-27T22:31:19,477 | INFO  | safeCall-8       | ThingStatusInfoChangedEvent      | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
karaf@root()> Exception in thread "forceRemove-2" java.lang.NoClassDefFoundError: org.eclipse.smarthome.config.core.Configuration not found by org.openhab.binding.testbinding [248]
        at com.sun.proxy.$Proxy134.<clinit>(Unknown Source)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at java.lang.reflect.Proxy.newProxyInstance(Proxy.java:739)
        at org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0(SafeCallerBuilderImpl.java:68)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build(SafeCallerBuilderImpl.java:59)
        at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl.thingRemoved(ThingManagerImpl.java:480)
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyTrackers(ThingRegistryImpl.java:215)
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutRemovedElement(ThingRegistryImpl.java:135)
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutRemovedElement(ThingRegistryImpl.java:1)
        at org.eclipse.smarthome.core.common.registry.AbstractRegistry.removed(AbstractRegistry.java:240)
        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.core.common.registry.AbstractManagedProvider.remove(AbstractManagedProvider.java:100)
        at org.eclipse.smarthome.core.common.registry.AbstractRegistry.remove(AbstractRegistry.java:335)
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.forceRemove(ThingRegistryImpl.java:102)
        at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$8$1.run(ThingManagerImpl.java:992)
        at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$8$1.run(ThingManagerImpl.java:1)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$8.run(ThingManagerImpl.java:989)
        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)
2019-04-27T22:32:32,691 | DEBUG | pipe-bundle:stop 248 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Thing handler factory 'TestBindingHandlerFactory' removed
2019-04-27T22:33:01,936 | DEBUG | pipe-bundle:stop 248 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Thing handler factory 'TestBindingHandlerFactory' added
2019-04-27T22:33:01,937 | DEBUG | pipe-bundle:stop 248 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Not registering a handler at this point. The thing types of bundle org.openhab.binding.testbinding are not fully loaded yet.
2019-04-27T22:33:01,942 | DEBUG | ESH-file-processing-17 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Calling 'TestBindingHandlerFactory.registerHandler()' for thing 'testbinding:sample:test'.
2019-04-27T22:33:01,944 | DEBUG | ESH-file-processing-17 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Configuration of 'testbinding:sample:test' needs [config1], has [config1].
2019-04-27T22:33:01,944 | DEBUG | ESH-file-processing-17 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Config description for 'testbinding:sample-channel' is not resolvable, assuming 'testbinding:sample:test:channel1' is initializable
2019-04-27T22:33:01,945 | DEBUG | ESH-file-processing-17 | ThingManagerImpl                 | 218 - org.openhab.core.thing - 2.5.0.201904271855 | Calling initialize handler for thing 'testbinding:sample:test' at 'org.openhab.binding.testbinding.internal.TestBindingHandler@26fe720e'.
2019-04-27T22:33:01,945 | INFO  | safeCall-13      | ThingStatusInfoEvent             | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' updated: INITIALIZING
2019-04-27T22:33:01,947 | INFO  | safeCall-12      | ThingStatusInfoChangedEvent      | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2019-04-27T22:33:01,947 | INFO  | safeCall-14      | ThingStatusInfoEvent             | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' updated: UNKNOWN
2019-04-27T22:33:01,948 | INFO  | safeCall-13      | ThingStatusInfoChangedEvent      | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' changed from INITIALIZING to UNKNOWN
2019-04-27T22:33:01,948 | INFO  | safeCall-12      | ThingStatusInfoEvent             | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' updated: ONLINE
2019-04-27T22:33:01,948 | INFO  | safeCall-13      | ThingStatusInfoChangedEvent      | 181 - org.openhab.core.io.monitor - 2.5.0.201904271901 | 'testbinding:sample:test' changed from UNKNOWN to ONLINE

I assume the exception is the root cause of your problem.

mhilbush commented 5 years ago

@maggu2810 I suppose, but I never got an exception in my log. Why would I be missing that class?

maggu2810 commented 5 years ago

Hm...

Your bundle don't import the config.core package because you don't use anything of it. The ThingManagerImpl creates a safe caller in line 480 for your thing handler factory implementation using the ThingHandlerFactory.class. This interface class references classes of config.core. For the proxy the classloader of the specific implementation is used (that don't access config.core stuff itself) and so it complains that the specific classes cannot be found (if I understand the whole thing correctly). Can you try to add org.eclipse.smarthome.config.core.Configuration.class.toString(); at some place in your TestBindingHandlerFactory.java and check if the error is still present?

mhilbush commented 5 years ago

Yes, that appears to have resolved the problem.

maggu2810 commented 5 years ago

It works around the real problem in core... :wink:

mhilbush commented 5 years ago

I wish I had seen that exception, as it would've provided a better clue what was going on. For the life of me, I couldn't understand why it worked when the binding was built with the old build system, and didn't work when it was built with the new build system.

Thank you for getting to the root cause so quickly!!!

maggu2810 commented 5 years ago

Let's wait for comments on https://github.com/openhab/openhab-core/pull/763 Perhaps you can give it a try yourself (without the workaround in your thing factory).

mhilbush commented 5 years ago

Perhaps you can give it a try yourself (without the workaround in your thing factory).

See my comment here. https://github.com/openhab/openhab-core/pull/763#issuecomment-487373047

mhilbush commented 5 years ago

Confirming this is fixed in build 1580. Thanks @maggu2810!!