Problem with binding from marketplace being installed and subsequently uninstalled on OH start-up

andan · January 3, 2022, 5:54pm

I’m facing the following issue with my bindings I’ve published on the Community Marketplace ( Sony Binding , SkyQ Receiver Binding)

The bindings can be successfully installed from the marketplace and discovered/set-up things work fine
When OH 3.2 is restarted, it seems that the bindings get properly activated for a short time, but shortly afterwards are being uninstalled. After start-up is finished, the associated things are in status UNITIALIZED, and the bindings are not shown up in the add thing dialog
The bindings can be successfully installed from the local marketplace cache with the kar:install command

For me this looks like a conflict between the bindings and the OH start-up process. Some further context infos:

It seems that the issue does not occur on each restart (this however might be wrong impression)
The bindings are provided as kar files and uses the DynamicStateOptionProvider service
I cannot find any warning or error log message related to that problem

The following log excerpt shows the successful initializationof the skyq thing @16:35:32.443, and the uninstallation of the binding @16:35:45.681

2022-01-03 16:35:32.272 [DEBUG] [.thing.internal.GenericThingProvider] - ThingHandlerFactory added org.openhab.binding.skyq.internal.SkyQHandlerFactory@70547c
2022-01-03 16:35:32.274 [DEBUG] [.thing.internal.GenericThingProvider] - bundle org.openhab.core.model.thing:3.2.0 (206)[org.openhab.core.model.thing.internal.GenericThingProvider(213)] : dm ThingHandlerFactory tracking 14 MultipleDynamic added {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317} (exit)
2022-01-03 16:35:32.276 [DEBUG] [core.thing.internal.ThingManagerImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingManagerImpl(236)] : dm ThingHandlerFactory tracking 21 MultipleDynamic added {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317} (enter)
2022-01-03 16:35:32.277 [DEBUG] [core.thing.internal.ThingManagerImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingManagerImpl(236)] : dm ThingHandlerFactory tracking 21 MultipleDynamic already active, binding {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317}
2022-01-03 16:35:32.279 [DEBUG] [core.thing.internal.ThingManagerImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingManagerImpl(236)] : invoking bind: addThingHandlerFactory: parameters [org.openhab.binding.skyq.internal.SkyQHandlerFactory]
2022-01-03 16:35:32.280 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing handler factory 'SkyQHandlerFactory' added
2022-01-03 16:35:32.282 [DEBUG] [core.thing.internal.ThingManagerImpl] - Not registering a handler at this point. The thing types of bundle 'org.openhab.binding.skyq' are not fully loaded yet.
2022-01-03 16:35:32.284 [DEBUG] [core.thing.internal.ThingManagerImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingManagerImpl(236)] : dm ThingHandlerFactory tracking 21 MultipleDynamic added {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317} (exit)
2022-01-03 16:35:32.285 [DEBUG] [ore.thing.internal.ThingRegistryImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingRegistryImpl(237)] : dm ThingHandlerFactory tracking 10 MultipleDynamic added {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317} (enter)
2022-01-03 16:35:32.286 [DEBUG] [ore.thing.internal.ThingRegistryImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingRegistryImpl(237)] : dm ThingHandlerFactory tracking 10 MultipleDynamic already active, binding {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317}
2022-01-03 16:35:32.288 [DEBUG] [ore.thing.internal.ThingRegistryImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingRegistryImpl(237)] : invoking bind: addThingHandlerFactory: parameters [org.openhab.binding.skyq.internal.SkyQHandlerFactory]
2022-01-03 16:35:32.290 [DEBUG] [ore.thing.internal.ThingRegistryImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingRegistryImpl(237)] : dm ThingHandlerFactory tracking 10 MultipleDynamic added {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317} (exit)
2022-01-03 16:35:32.301 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/OH-INF/thing/thing-types.xml' in module 'org.openhab.binding.skyq'...
2022-01-03 16:35:32.301 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/OH-INF/binding/binding.xml' in module 'org.openhab.binding.skyq'...
2022-01-03 16:35:32.332 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling 'SkyQHandlerFactory.registerHandler()' for thing 'skyq:skyqreceiver:8be83df8f7'.
2022-01-03 16:35:32.437 [DEBUG] [core.thing.internal.ThingManagerImpl] - Configuration of 'skyq:skyqreceiver:8be83df8f7' needs [hostname], has [deviceMacAddress, hostname, checkStatusInterval, refreshInterval, configurablePresets, retryInterval].
2022-01-03 16:35:32.438 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'skyq:controlCommand' is not resolvable, assuming 'skyq:skyqreceiver:8be83df8f7:control#controlCommand' is initializable
2022-01-03 16:35:32.439 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'skyq:channelPreset' is not resolvable, assuming 'skyq:skyqreceiver:8be83df8f7:control#channelPreset' is initializable
2022-01-03 16:35:32.440 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'skyq:power' is not resolvable, assuming 'skyq:skyqreceiver:8be83df8f7:control#power' is initializable
2022-01-03 16:35:32.441 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'skyq:currentChannelTitle' is not resolvable, assuming 'skyq:skyqreceiver:8be83df8f7:statusChannels#currentChannelTitle' is initializable
2022-01-03 16:35:32.442 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'skyq:powerStatus' is not resolvable, assuming 'skyq:skyqreceiver:8be83df8f7:statusChannels#powerStatus' is initializable
2022-01-03 16:35:32.443 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling initialize handler for thing 'skyq:skyqreceiver:8be83df8f7' at 'org.openhab.binding.skyq.internal.SkyQHandler@98989f'.
2022-01-03 16:35:32.505 [DEBUG] [or.internal.metrics.EventCountMetric] - Received event on topic openhab/items/SkyQReceiver_ControlReceiverCommand/state.
2022-01-03 16:35:32.521 [DEBUG] [or.internal.metrics.EventCountMetric] - Received event on topic openhab/items/SkyQReceiver_Power/state.
2022-01-03 16:35:32.522 [DEBUG] [d4j.internal.RRD4jPersistenceService] - Stored 'SkyQReceiver_Power' as value '0.0' in rrd4j database (again)
2022-01-03 16:35:32.523 [DEBUG] [or.internal.metrics.EventCountMetric] - Received event on topic openhab/items/SkyQReceiver_CurrentChannelTitle/state.
2022-01-03 16:35:32.529 [DEBUG] [or.internal.metrics.EventCountMetric] - Received event on topic openhab/items/SkyQReceiver_PowerStatus/state.
2022-01-03 16:35:45.492 [DEBUG] [g.discovery.internal.PersistentInbox] - bundle org.openhab.core.config.discovery:3.2.0 (164)[org.openhab.core.config.discovery.internal.PersistentInbox(114)] : dm ThingHandlerFactory tracking 15 MultipleDynamic removed {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317} (enter)
2022-01-03 16:35:45.504 [DEBUG] [g.discovery.internal.PersistentInbox] - bundle org.openhab.core.config.discovery:3.2.0 (164)[org.openhab.core.config.discovery.internal.PersistentInbox(114)] : invoking unbind: removeThingHandlerFactory: parameters [org.openhab.binding.skyq.internal.SkyQHandlerFactory]
2022-01-03 16:35:45.506 [DEBUG] [g.discovery.internal.PersistentInbox] - bundle org.openhab.core.config.discovery:3.2.0 (164)[org.openhab.core.config.discovery.internal.PersistentInbox(114)] : dm ThingHandlerFactory tracking 15 MultipleDynamic removed (unbind) {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317}
2022-01-03 16:35:45.508 [DEBUG] [.thing.internal.GenericThingProvider] - bundle org.openhab.core.model.thing:3.2.0 (206)[org.openhab.core.model.thing.internal.GenericThingProvider(213)] : dm ThingHandlerFactory tracking 15 MultipleDynamic removed {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317} (enter)
2022-01-03 16:35:45.519 [DEBUG] [.thing.internal.GenericThingProvider] - bundle org.openhab.core.model.thing:3.2.0 (206)[org.openhab.core.model.thing.internal.GenericThingProvider(213)] : invoking unbind: removeThingHandlerFactory: parameters [org.openhab.binding.skyq.internal.SkyQHandlerFactory]
2022-01-03 16:35:45.521 [DEBUG] [.thing.internal.GenericThingProvider] - bundle org.openhab.core.model.thing:3.2.0 (206)[org.openhab.core.model.thing.internal.GenericThingProvider(213)] : dm ThingHandlerFactory tracking 15 MultipleDynamic removed (unbind) {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317}
2022-01-03 16:35:45.523 [DEBUG] [core.thing.internal.ThingManagerImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingManagerImpl(236)] : dm ThingHandlerFactory tracking 22 MultipleDynamic removed {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317} (enter)
2022-01-03 16:35:45.533 [DEBUG] [core.thing.internal.ThingManagerImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingManagerImpl(236)] : invoking unbind: removeThingHandlerFactory: parameters [org.openhab.binding.skyq.internal.SkyQHandlerFactory]
2022-01-03 16:35:45.534 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing handler factory 'SkyQHandlerFactory' removed
2022-01-03 16:35:45.535 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling dispose handler for thing 'skyq:skyqreceiver:8be83df8f7' at 'org.openhab.binding.skyq.internal.SkyQHandler@98989f'.
2022-01-03 16:35:45.556 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling unregisterHandler handler for thing 'skyq:skyqreceiver:8be83df8f7' at 'org.openhab.binding.skyq.internal.SkyQHandlerFactory@70547c'.
2022-01-03 16:35:45.565 [DEBUG] [core.thing.internal.ThingManagerImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingManagerImpl(236)] : dm ThingHandlerFactory tracking 22 MultipleDynamic removed (unbind) {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317}
2022-01-03 16:35:45.567 [DEBUG] [ore.thing.internal.ThingRegistryImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingRegistryImpl(237)] : dm ThingHandlerFactory tracking 11 MultipleDynamic removed {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317} (enter)
2022-01-03 16:35:45.580 [DEBUG] [ore.thing.internal.ThingRegistryImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingRegistryImpl(237)] : invoking unbind: removeThingHandlerFactory: parameters [org.openhab.binding.skyq.internal.SkyQHandlerFactory]
2022-01-03 16:35:45.582 [DEBUG] [ore.thing.internal.ThingRegistryImpl] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ThingRegistryImpl(237)] : dm ThingHandlerFactory tracking 11 MultipleDynamic removed (unbind) {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=505, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQHandlerFactory, component.id=317}
2022-01-03 16:35:45.602 [DEBUG] [rnal.ChannelStateDescriptionProvider] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ChannelStateDescriptionProvider(233)] : dm DynamicStateDescriptionProvider tracking 8 MultipleDynamic removed {org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.skyq.internal.SkyQStateDescriptionOptionProvider}={service.id=504, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQStateDescriptionOptionProvider, component.id=318} (enter)
2022-01-03 16:35:45.612 [DEBUG] [rnal.ChannelStateDescriptionProvider] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ChannelStateDescriptionProvider(233)] : invoking unbind: removeDynamicStateDescriptionProvider: parameters [org.openhab.binding.skyq.internal.SkyQStateDescriptionOptionProvider]
2022-01-03 16:35:45.614 [DEBUG] [rnal.ChannelStateDescriptionProvider] - bundle org.openhab.core.thing:3.2.0 (212)[org.openhab.core.thing.internal.ChannelStateDescriptionProvider(233)] : dm DynamicStateDescriptionProvider tracking 8 MultipleDynamic removed (unbind) {org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.skyq.internal.SkyQStateDescriptionOptionProvider}={service.id=504, service.bundleid=267, service.scope=bundle, component.name=org.openhab.binding.skyq.internal.SkyQStateDescriptionOptionProvider, component.id=318}
2022-01-03 16:35:45.633 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Releasing the XmlDocumentProvider for module 'org.openhab.binding.skyq'.
2022-01-03 16:35:45.634 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Releasing the XmlDocumentProvider for module 'org.openhab.binding.skyq'.
2022-01-03 16:35:45.647 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 16, for automation bundle 'org.openhab.binding.skyq' 
2022-01-03 16:35:45.648 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 16, for automation bundle 'org.openhab.binding.skyq' 
2022-01-03 16:35:45.649 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 16, for automation bundle 'org.openhab.binding.skyq' 
2022-01-03 16:35:45.681 [DEBUG] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-skyq'
2022-01-03 16:36:00.656 [DEBUG] [d4j.internal.RRD4jPersistenceService] - Stored 'SkyQReceiver_Power' as value '0.0' in rrd4j database (again)
2022-01-03 16:36:55.076 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing 'skyq:skyqreceiver:8be83df8f7' is no longer tracked by ThingManager.

Has anyone an idea what might be wrong here or what I could do to further analyse the issue?

rlkoshak · January 3, 2022, 6:13pm

Are you using addons.cfg to manage your installed addons? If so, what’s happening is OH periodically checks that file and make sure the set of installed add-ons match what’s listed there. The Marketplace add-on isn’t listed so it gets removed.

I don’t know if it’s even possible to add Marketplace add-ons through addons.cfg. You might need to drop use of that config file and manage your add-ons through the Karaf Console or the UI.

J-N-K · January 3, 2022, 6:23pm

I agree with @rlkoshak, but probably managing through UI will result in the same problem, because installing via UI results in the same issue.

The distributions karaf-feature-handler uninstalls everything with openhab-binding prefix if it’s not in the list of installed addons. You could try changing the feature-name to something different (something that does NOT start with openhab) and see if it improves.

andan · January 3, 2022, 6:56pm

Thank you for your quick and helpful responses!

I’ve installed the bindings via the UI, and I assume the other users who reported the issue have done the same.

@J-N-K I’m currently using this feature.xml to build the kar files:

<?xml version="1.0" encoding="UTF-8"?>
<features name="org.openhab.binding.skyq-${project.version}" xmlns="http://karaf.apache.org/xmlns/features/v1.4.0">
	<feature name="openhab-binding-skyq" description="skyq Binding" version="${project.version}">
		<feature>openhab-runtime-base</feature>
		<bundle start-level="80">mvn:org.openhab.addons.bundles/org.openhab.binding.skyq/${project.version}</bundle>
	</feature>
</features>

Are you suggesting to just change the name attribute of the feature element, or do I need to change also other (package) names to avoid the removal of the binding?

And would that be a workaround or a final fix? Meaning should the installed community add-ons being part of the add-ons list, in which case they wouldn’t be removed if my understanding is correct?

andirs · January 3, 2022, 7:04pm

Not true for me. I have installed my bindings via the addons.cfg, except for the Sony binding since i have found no way to install maketplace binding via file…

J-N-K · January 3, 2022, 7:14pm

<?xml version="1.0" encoding="UTF-8"?>
<features name="org.openhab.binding.skyq-${project.version}" xmlns="http://karaf.apache.org/xmlns/features/v1.4.0">
	<feature name="marketplace-binding-skyq" description="skyq Binding" version="${project.version}">
		<feature>openhab-runtime-base</feature>
		<bundle start-level="80">mvn:org.openhab.addons.bundles/org.openhab.binding.skyq/${project.version}</bundle>
	</feature>
</features>

should be enough. It’s really about the naming of the feature. The logic is something like

// get a list of all features and mark for removal
List<Feature> tobeRemoved = installedFeatures;
for (Feature feature : configuredFeatures) {
    if (toBeRemoved.contains(feature) {
        // feature is installed and needs to be installed, remove it from the removal list
        toBeRemoved.remove(feature);
    } else {
        // feature is not installed, install it
        install(feature);
    }
}
// uninstall everything in the list (it's installed but should not be installed)
toBeRemoved.forEach(this::uninstall);

This happens every time a feature in installed from the distribution. The list of features is retrieved from all installed features that start with openhab-binding- (and some other prefixes for other addon types).

This works fine until the marketplace shows up. It also installs a feature, but the feature is not added to the list of installed features (and that’s correct, because the logic above would not know how to install the addon if it’s not part of the distribution and missing).

So: Until something better shows up .kar files from the marketplace should not have feature-names in the namespace openhab- but something else. But that is purely my personal opinion.

DrRSatzteil · January 3, 2022, 8:06pm

I installed the Sony binding via the UI but I also downloaded the kar file manually and put it in the addons folder. Both ways however led to the same result.

andan · January 4, 2022, 12:01pm

I’ve changed the feature names of my bindings on the community marketplace and it seems that they now survive a restart of OH

On a general note: What I’m missing (or haven’t found yet) is a short but concise how-to for developers for building kar based bindings distributed via the community market place (see also my reported issue How to build kar files for marketplace that is compatible with milestone and SNAPSHOT builds)

In general I would be happy to contribute missing documentations, but I have to admit that I’m lacking expert knowledge on this topic even for a kind of ‘good enough’ contribution.

J-N-K · January 5, 2022, 6:47am

@hmerk It might be worth adding a note to the marketplace description that add-ons need a feature name that doesn‘t start with openhab- if they are provided as .kar. Maybe it would be a good idea to suggest a prefix like marketplace- or similar, that might be useful fürchte future.

hmerk · January 5, 2022, 7:54am

I am not really keen on that, as it is just a workaround. We should find the root cause and provide a proper solution.

@ysc WDYT ??

ysc · January 5, 2022, 11:33am

No strong opinion
I think @J-N-K identified the root cause and provided a solution - don’t name any non-distribution feature “openhab-something”, those are reserved for the distribution.
I added a note in the marketplace post template:

you can package your add-on as a JAR or KAR file. In the former case, provide a direct link to the binary ending in .jar. In the latter case, provide a direct link to a binary ending in .kar, and add the kar tag (mandatory). Don’t name any Karaf feature “openhab-something”, as the “openhab” prefix is reserved for the distribution features and has special behavior.

system · February 16, 2022, 3:34am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.