openhab / openhab-core

Core framework of openHAB
https://www.openhab.org/
Eclipse Public License 2.0
912 stars 421 forks source link

4.2: bundles automatically restored to their original version #3983

Open lolodomo opened 8 months ago

lolodomo commented 8 months ago

Using 4.2 snapshot (3808), I encounter a strange behaviour: if I update one bundle (bundle:update) then after a short time (max few minutes), my bundle is automatically restored to its original version ! I encountered that behaviour yesterday after updating either o.o.core.io.transport.mdns or o.o.webui.ui.basic bundles. What could be the trigger of that behaviour ?

Just to explain the conditions: I just installed the snapshot 3808 form scratch in a new directory. No kar file. Remote add-ons is enabled. I update bundles using bundle:update command.

Earlier I played many hours with release 4.1 and applying many times updates of o.o.webui.ui.basic without encountering that behaviour. It seems something new in 4.2...

wborn commented 8 months ago

I also just noticed this. Enabling Karaf debug logging with log:set debug org.apache.karaf shows me:

18:30:17.923 [DEBUG] [af.features.internal.service.Deployer] - New snapshot available for mvn:org.openhab.addons.bundles/org.openhab.binding.shelly/4.2.0-SNAPSHOT
18:30:17.940 [INFO ] [.internal.service.FeaturesServiceImpl] - Changes to perform:
18:30:17.940 [INFO ] [.internal.service.FeaturesServiceImpl] -   Region: root
18:30:17.941 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to uninstall:
18:30:17.941 [INFO ] [.internal.service.FeaturesServiceImpl] -       org.openhab.core.config.discovery.addon.mdns/4.2.0.202312301510
18:30:17.941 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to update:
18:30:17.941 [INFO ] [.internal.service.FeaturesServiceImpl] -       org.openhab.binding.shelly/4.2.0.202312301537 with mvn:org.openhab.addons.bundles/org.openhab.binding.shelly/4.2.0-SNAPSHOT
18:30:17.941 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to install:
18:30:17.941 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:net.java.dev.jna/jna-platform/5.13.0
18:30:17.941 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:com.neuronrobotics/nrjavaserial/5.2.1.OH1
18:30:17.941 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
18:30:17.941 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.openhab.core.bundles/org.openhab.core.config.discovery.addon.usb/4.2.0-SNAPSHOT
18:30:17.942 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.openhab.core.bundles/org.openhab.core.config.discovery.usbserial/4.2.0-SNAPSHOT
18:30:17.942 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.openhab.core.bundles/org.openhab.core.config.discovery.usbserial.linuxsysfs/4.2.0-SNAPSHOT
18:30:17.942 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.openhab.core.bundles/org.openhab.core.config.discovery.usbserial.ser2net/4.2.0-SNAPSHOT
18:30:17.942 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.openhab.core.bundles/org.openhab.core.config.serial/4.2.0-SNAPSHOT
18:30:17.942 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.openhab.core.bundles/org.openhab.core.io.transport.serial/4.2.0-SNAPSHOT
18:30:17.942 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.openhab.core.bundles/org.openhab.core.io.transport.serial.rxtx/4.2.0-SNAPSHOT
18:30:17.942 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.openhab.core.bundles/org.openhab.core.io.transport.serial.rxtx.rfc2217/4.2.0-SNAPSHOT
18:30:17.942 [INFO ] [.internal.service.FeaturesServiceImpl] - Stopping bundles:

So it may be triggered by the addon suggestion functionality that (un)installs features.

J-N-K commented 8 months ago

Yes. Whenever a feature is installed/uninstalled we refresh the other features, which results in a reset of the bundles to their original version. This also happens when you install/uninstall add-ons.

lolodomo commented 8 months ago

Do we have behind the scene a new feature that is installed or uninstalled ? One of the new suggestion finder ? When simply restarting OH, we must not loose our updated bundles. I am going to run a simple scenario to check that. And I will compare 4.1 and 4.2.

lolodomo commented 8 months ago

A custom Basic UI bundle does not survive after the restart of OH (4.2 snapshot 3808) !

openhab> bundle:list -s | grep basic
258 │ Active │  80 │ 4.2.0.202312301338     │ org.openhab.ui.basic
openhab> logout

D:\Domotique\openHAB\test>start.bat
Launching the openHAB runtime...

                           _   _     _     ____
   ___   ___   ___   ___  | | | |   / \   | __ )
  / _ \ / _ \ / _ \ / _ \ | |_| |  / _ \  |  _ \
 | (_) | (_) |  __/| | | ||  _  | / ___ \ | |_) )
  \___/|  __/ \___/|_| |_||_| |_|/_/   \_\|____/
       |_|       4.2.0-SNAPSHOT - Build #3808

Use '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
To exit, use '<ctrl-d>' or 'logout'.

openhab> bundle:list -s | grep basic
258 │ Resolved │  80 │ 4.2.0.202312301338     │ org.openhab.ui.basic
openhab> log:tail
19:42:19.971 [INFO ] [org.openhab.core.Activator           ] - Starting openHAB 4.2.0 (build Build #3808)
19:42:20.458 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Paris'.
19:42:20.458 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Locale set to 'fr_FR'.
19:42:27.988 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
19:42:28.815 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test18.sitemap'
19:42:28.982 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
19:42:29.047 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test13.sitemap'
19:42:29.078 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test20.sitemap'
19:42:29.103 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test19.sitemap'
19:42:29.115 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test2.sitemap'
19:42:32.939 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
19:42:33.079 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'
19:42:41.110 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
19:43:04.161 [INFO ] [.basic.internal.servlet.WebAppServlet] - Stopped Basic UI
19:43:04.499 [INFO ] [.basic.internal.servlet.WebAppServlet] - Stopped Basic UI
openhab>

openhab> bundle:list -s | grep basic
258 │ Active │  80 │ 4.2.0.202312300006     │ org.openhab.ui.basic
openhab>

I even do not understand why "Stopped Basic UI" is logged twice. But at least this log appears because Basic UI is uninstalled before being installed again with an old version, I guess the version downloaded from the WEB.

It is a critical bug IMHO.

Let's try now with 4.1 release...

lolodomo commented 8 months ago

One good news is that I can't reproduce this scenario with 4.1 release:

openhab> bundle:list -s | grep basic
247 │ Active │  80 │ 4.1.0                  │ org.openhab.ui.basic
openhab> bundle:update 247 file:///d:/dev/basicui41.jar
openhab> bundle:list -s | grep basic
247 │ Active │  80 │ 4.1.1.202312301921     │ org.openhab.ui.basic
openhab> log:tail
20:12:24.407 [INFO ] [org.openhab.core.Activator           ] - Starting openHAB 4.1.0 (build Release Build)
20:12:24.895 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Paris'.
20:12:24.895 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Locale set to 'fr_FR'.
20:12:48.646 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
20:12:55.722 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
20:23:44.422 [INFO ] [.basic.internal.servlet.WebAppServlet] - Stopped Basic UI
openhab>

openhab> bundle:list -s | grep basic
247 │ Active │  80 │ 4.1.1.202312301921     │ org.openhab.ui.basic
openhab> logout

D:\Domotique\openHAB\test41>start.bat
Launching the openHAB runtime...

                           _   _     _     ____
   ___   ___   ___   ___  | | | |   / \   | __ )
  / _ \ / _ \ / _ \ / _ \ | |_| |  / _ \  |  _ \
 | (_) | (_) |  __/| | | ||  _  | / ___ \ | |_) )
  \___/|  __/ \___/|_| |_||_| |_|/_/   \_\|____/
       |_|       4.1.0 - Release Build

Use '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
To exit, use '<ctrl-d>' or 'logout'.

openhab> bundle:list -s | grep basic
247 │ Resolved │  80 │ 4.1.1.202312301921     │ org.openhab.ui.basic
openhab> log:tail
20:25:25.121 [INFO ] [org.openhab.core.Activator           ] - Starting openHAB 4.1.0 (build Release Build)
20:25:25.506 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Paris'.
20:25:25.507 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Locale set to 'fr_FR'.
20:25:33.808 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
20:25:40.728 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.

openhab>
openhab> bundle:list -s | grep basic
247 │ Active │  80 │ 4.1.1.202312301921     │ org.openhab.ui.basic
openhab>
lolodomo commented 8 months ago

We don't have many changes in core framework in 4.2. Could it be #3922 that introduced this problem ? @andrewfg is your PR doing stuff with installing/uninstalling feature ?

J-N-K commented 8 months ago

IIRC (we had a similar issue in the past) it only occurs between snapshots, not releases and snapshots.

lolodomo commented 8 months ago

Here are logs with DEBUG logs from karaf. The added features at boot are openhab-core-config-discovery-addon-ip and openhab-core-config-discovery-addon-upnp.

openhab> bundle:list -s | grep basic
258 │ Active │  80 │ 4.2.0.202312301505     │ org.openhab.ui.basic
openhab> bundle:update 258 file:///d:/dev/basicui.jar
openhab> bundle:list -s | grep basic
258 │ Active │  80 │ 4.2.0.202312301951     │ org.openhab.ui.basic
openhab> logout

D:\Domotique\openHAB\test>start.bat
Launching the openHAB runtime...

                           _   _     _     ____
   ___   ___   ___   ___  | | | |   / \   | __ )
  / _ \ / _ \ / _ \ / _ \ | |_| |  / _ \  |  _ \
 | (_) | (_) |  __/| | | ||  _  | / ___ \ | |_) )
  \___/|  __/ \___/|_| |_||_| |_|/_/   \_\|____/
       |_|       4.2.0-SNAPSHOT - Build #3808

Use '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
To exit, use '<ctrl-d>' or 'logout'.

openhab> log:tail
20:54:19.251 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.eclipse.xtext.ide
20:54:19.251 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.eclipse.xtext.util
20:54:19.252 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.eclipse.xtext.xbase
20:54:19.252 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.eclipse.xtext.xbase.ide
20:54:19.253 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.eclipse.xtext.xbase.lib
20:54:19.253 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.base-fixes
20:54:19.290 [INFO ] [org.openhab.core.Activator           ] - Starting openHAB 4.2.0 (build Build #3808)
20:54:19.291 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core
20:54:19.437 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Command: '//
...
20:54:19.589 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Paris'.
20:54:19.590 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Locale set to 'fr_FR'.
20:54:19.718 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.addon
20:54:20.004 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.addon.marketplace
20:54:20.021 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.addon.marketplace.karaf
20:54:20.026 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.audio
20:54:20.055 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.auth.jaas
20:54:20.060 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.automation
20:54:20.151 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.automation.module.media
20:54:20.162 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.automation.module.script
20:54:20.184 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.automation.module.script.rulesupport
20:54:20.212 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.automation.rest
20:54:20.219 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.core
20:54:20.276 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery
20:54:20.295 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery.addon
20:54:20.310 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery.addon.process
20:54:20.315 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery.mdns
20:54:20.317 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.dispatch
20:54:20.374 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.ephemeris
20:54:20.413 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.id
20:54:20.428 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.console
20:54:20.435 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.console.karaf
20:54:20.436 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.core.io.console.karaf (174): Starting extension synchronously
20:54:20.439 [INFO ] [ell.impl.action.osgi.CommandExtension] - Registering commands for bundle org.openhab.core.io.console.karaf/4.2.0.202312290304
20:54:20.447 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.http
20:54:20.454 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.http.auth
20:54:20.474 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.monitor
20:54:20.479 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.net
20:54:20.496 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest
20:54:20.688 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest.audio
20:54:20.693 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest.auth
20:54:20.743 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest.core
20:54:20.985 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest.mdns
20:54:20.987 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest.sitemap
20:54:20.992 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest.sse
20:54:21.029 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest.swagger
20:54:21.059 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest.transform
20:54:21.062 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest.ui
20:54:21.064 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.rest.voice
20:54:21.068 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.transport.mdns
20:54:21.740 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Executing command: 'log:tail'
20:54:22.276 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.websocket
20:54:22.297 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.karaf
20:54:22.330 [INFO ] [.internal.service.FeaturesServiceImpl] - Adding features: openhab-core-config-discovery-addon-ip/[4.2.0.SNAPSHOT,4.2.0.SNAPSHOT]
20:54:22.332 [INFO ] [.internal.service.FeaturesServiceImpl] - Adding features: openhab-core-config-discovery-addon-upnp/[4.2.0.SNAPSHOT,4.2.0.SNAPSHOT]
20:54:22.362 [INFO ] [ell.impl.action.osgi.CommandExtension] - Updating commands for bundle org.apache.karaf.jaas.command/4.4.4
20:54:22.367 [INFO ] [ell.impl.action.osgi.CommandExtension] - Updating commands for bundle org.apache.karaf.jaas.command/4.4.4
20:54:22.376 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.core
20:54:22.446 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.item
20:54:22.458 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.item.ide
20:54:22.492 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.item.runtime
20:54:23.329 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.lsp
20:54:23.338 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.persistence
20:54:23.352 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.persistence.ide
20:54:23.358 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.persistence.runtime
20:54:23.495 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.rule
20:54:23.506 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.rule.ide
20:54:23.508 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.rule.runtime
20:54:23.516 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.script
20:54:23.543 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.script.ide
20:54:23.546 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.script.runtime
20:54:23.551 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.sitemap
20:54:23.555 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.sitemap.ide
20:54:23.562 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.sitemap.runtime
20:54:23.674 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.thing
20:54:23.681 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.thing.ide
20:54:23.686 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.thing.runtime
20:54:23.744 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.model.yaml
20:54:23.976 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.persistence
20:54:24.004 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.semantics
20:54:24.011 [INFO ] [.internal.service.FeaturesServiceImpl] - Changes to perform:
20:54:24.013 [INFO ] [.internal.service.FeaturesServiceImpl] -   Region: root
20:54:24.016 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to update:
20:54:24.018 [INFO ] [.internal.service.FeaturesServiceImpl] -       org.openhab.ui.basic/4.2.0.202312301951 with mvn:org.openhab.ui.bundles/org.openhab.ui.basic/4.2.0-SNAPSHOT
20:54:24.021 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.storage.json
20:54:24.021 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to install:
20:54:24.023 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:54:24.030 [INFO ] [.internal.service.FeaturesServiceImpl] - Updating bundles:
20:54:24.033 [INFO ] [.internal.service.FeaturesServiceImpl] -   mvn:org.openhab.ui.bundles/org.openhab.ui.basic/4.2.0-SNAPSHOT
20:54:24.194 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.ui.basic (258): Starting destruction process
20:54:24.196 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.ui.basic (258): Not an extended bundle or destruction of extension already finished
20:54:24.202 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.ui.basic (258): Starting destruction process
20:54:24.206 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.ui.basic (258): Not an extended bundle or destruction of extension already finished
20:54:24.223 [INFO ] [.internal.service.FeaturesServiceImpl] - Installing bundles:
20:54:24.241 [INFO ] [.internal.service.FeaturesServiceImpl] -   mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:54:24.260 [INFO ] [.internal.service.FeaturesServiceImpl] - Stopping bundles:
20:54:24.274 [DEBUG] [af.features.internal.service.Deployer] - Usage for bundle org.openhab.ui.basic_4.2.0.202312301505 [258] is 0
20:54:24.285 [DEBUG] [af.features.internal.service.Deployer] - Selected bundles [org.openhab.ui.basic_4.2.0.202312301505 [258]] for destroy (no services in use)
20:54:24.305 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.ui.basic/4.2.0.202312301505
20:54:24.311 [INFO ] [.internal.service.FeaturesServiceImpl] - Refreshing bundles:
20:54:24.315 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.ui.basic/4.2.0.202312301505 (Bundle will be updated)
20:54:24.316 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.ui.basic (258): Starting destruction process
20:54:24.327 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.ui.basic (258): Not an extended bundle or destruction of extension already finished
20:54:24.330 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.ui.basic (258): Starting destruction process
20:54:24.342 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.ui.basic (258): Not an extended bundle or destruction of extension already finished
20:54:24.344 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.ui.basic (258): Starting destruction process
20:54:24.351 [DEBUG] [hell.impl.action.osgi.CommandExtender] - org.openhab.ui.basic (258): Not an extended bundle or destruction of extension already finished
20:54:24.357 [INFO ] [.internal.service.FeaturesServiceImpl] - Starting bundles:
20:54:24.360 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.ui.basic
20:54:24.369 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.transform/4.2.0.202312290305
20:54:24.378 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.transform
20:54:24.453 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.thing/4.2.0.202312290306
20:54:24.462 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.thing
20:54:25.458 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
20:54:25.476 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.ui
20:54:25.757 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.ui.icon
20:54:25.854 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.voice
20:54:26.006 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.ui
20:54:26.028 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.ui.iconset.classic
20:54:26.043 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.osgi.service.jaxrs
20:54:26.046 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.threeten.extra
20:54:26.049 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.yaml.snakeyaml
20:54:26.055 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle si-units
20:54:26.059 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle si.uom.si-quantity
20:54:26.062 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle stax2-api
20:54:26.066 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle tech.units.indriya
20:54:26.071 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle uom-lib-common
20:54:26.075 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle xstream
20:54:26.078 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.jupnp
20:54:26.170 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.config.discovery.usbserial.ser2net/4.2.0.202312290311
20:54:26.176 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery.usbserial.ser2net
20:54:26.182 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.config.discovery.usbserial.linuxsysfs/4.2.0.202312290311
20:54:26.186 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery.usbserial.linuxsysfs
20:54:26.194 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.config.discovery.usbserial/4.2.0.202312290310
20:54:26.198 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery.usbserial
20:54:26.241 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.threeten.extra/1.5.0
20:54:26.243 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.ui.iconset.classic/4.2.0.202312271908
20:54:26.245 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.ui.icon/4.2.0.202312290311
20:54:26.247 [INFO ] [.internal.service.FeaturesServiceImpl] -   nrjavaserial/5.2.1.OH1
20:54:26.249 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle nrjavaserial
20:54:26.250 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.io.transport.serial.rxtx/4.2.0.202312290305
20:54:26.252 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.transport.serial.rxtx
20:54:26.257 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.io.transport.serial/4.2.0.202312290304
20:54:26.260 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.transport.serial
20:54:26.268 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.io.transport.serial.rxtx.rfc2217/4.2.0.202312290306
20:54:26.271 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.io.transport.serial.rxtx.rfc2217
20:54:26.276 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.config.serial/4.2.0.202312290311
20:54:26.278 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.serial
20:54:26.286 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.ui.basic/4.2.0.202312301505
20:54:26.287 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.ui/4.2.0.202312290309
20:54:26.290 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.voice/4.2.0.202312290307
20:54:26.291 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.ui/4.2.0.202312271915
20:54:26.292 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.config.discovery.addon.mdns/4.2.0.202312290312
20:54:26.296 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery.addon.mdns
20:54:26.323 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.config.discovery.addon.usb/4.2.0.202312290311
20:54:26.326 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery.addon.usb
20:54:26.380 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery.addon.upnp
20:54:26.388 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core.config.discovery.addon.ip
20:54:26.401 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle com.sun.jna.platform
20:54:26.413 [DEBUG] [impl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.apache.commons.commons-net
20:54:31.398 [DEBUG] [karaf.scr.state.ScrBundleStateService] - bundle org.apache.karaf.scr.state:4.4.4 (84)[org.apache.karaf.scr.state.ScrBundleStateService(0)] : dm scr tracking 3 SingleStatic modified {org.osgi.service.component.runtime.ServiceComponentRuntime}={service.changecount=1700, service.id=81, service.bundleid=73, service.scope=singleton} (enter)
20:54:31.403 [DEBUG] [karaf.scr.state.ScrBundleStateService] - bundle org.apache.karaf.scr.state:4.4.4 (84)[org.apache.karaf.scr.state.ScrBundleStateService(0)] : dm scr tracking 3 SingleStatic modified {org.osgi.service.component.runtime.ServiceComponentRuntime}={service.changecount=1700, service.id=81, service.bundleid=73, service.scope=singleton} (exit)
20:54:34.732 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
20:54:51.405 [INFO ] [.internal.service.FeaturesServiceImpl] - Done.
20:54:52.302 [INFO ] [.internal.service.FeaturesServiceImpl] - Changes to perform:
20:54:52.303 [INFO ] [.internal.service.FeaturesServiceImpl] -   Region: root
20:54:52.304 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to install:
20:54:52.305 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:54:52.306 [INFO ] [.internal.service.FeaturesServiceImpl] - Installing bundles:
20:54:52.307 [INFO ] [.internal.service.FeaturesServiceImpl] -   mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:54:52.313 [INFO ] [.internal.service.FeaturesServiceImpl] - Done.
20:54:56.382 [DEBUG] [karaf.scr.state.ScrBundleStateService] - bundle org.apache.karaf.scr.state:4.4.4 (84)[org.apache.karaf.scr.state.ScrBundleStateService(0)] : dm scr tracking 4 SingleStatic modified {org.osgi.service.component.runtime.ServiceComponentRuntime}={service.changecount=1701, service.id=81, service.bundleid=73, service.scope=singleton} (enter)
20:54:56.385 [DEBUG] [karaf.scr.state.ScrBundleStateService] - bundle org.apache.karaf.scr.state:4.4.4 (84)[org.apache.karaf.scr.state.ScrBundleStateService(0)] : dm scr tracking 4 SingleStatic modified {org.osgi.service.component.runtime.ServiceComponentRuntime}={service.changecount=1701, service.id=81, service.bundleid=73, service.scope=singleton} (exit)
20:55:20.316 [INFO ] [.internal.service.FeaturesServiceImpl] - Adding features: openhab-core-config-discovery-addon-ip/[4.2.0.SNAPSHOT,4.2.0.SNAPSHOT]
20:55:21.137 [INFO ] [.internal.service.FeaturesServiceImpl] - Changes to perform:
20:55:21.138 [INFO ] [.internal.service.FeaturesServiceImpl] -   Region: root
20:55:21.141 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to install:
20:55:21.142 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:55:21.144 [INFO ] [.internal.service.FeaturesServiceImpl] - Installing bundles:
20:55:21.144 [INFO ] [.internal.service.FeaturesServiceImpl] -   mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:55:21.149 [INFO ] [.internal.service.FeaturesServiceImpl] - Done.
20:56:17.575 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Command: 'log:tail' failed: java.lang.InterruptedException
20:56:17.577 [DEBUG] [shell.impl.console.ConsoleSessionImpl] - Console session is closed

If I filter only most important lines:

20:54:22.330 [INFO ] [.internal.service.FeaturesServiceImpl] - Adding features: openhab-core-config-discovery-addon-ip/[4.2.0.SNAPSHOT,4.2.0.SNAPSHOT]
20:54:22.332 [INFO ] [.internal.service.FeaturesServiceImpl] - Adding features: openhab-core-config-discovery-addon-upnp/[4.2.0.SNAPSHOT,4.2.0.SNAPSHOT]
...
20:54:24.011 [INFO ] [.internal.service.FeaturesServiceImpl] - Changes to perform:
20:54:24.013 [INFO ] [.internal.service.FeaturesServiceImpl] -   Region: root
20:54:24.016 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to update:
20:54:24.018 [INFO ] [.internal.service.FeaturesServiceImpl] -       org.openhab.ui.basic/4.2.0.202312301951 with mvn:org.openhab.ui.bundles/org.openhab.ui.basic/4.2.0-SNAPSHOT
20:54:24.021 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to install:
20:54:24.023 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:54:24.030 [INFO ] [.internal.service.FeaturesServiceImpl] - Updating bundles:
20:54:24.033 [INFO ] [.internal.service.FeaturesServiceImpl] -   mvn:org.openhab.ui.bundles/org.openhab.ui.basic/4.2.0-SNAPSHOT
20:54:24.223 [INFO ] [.internal.service.FeaturesServiceImpl] - Installing bundles:
20:54:24.241 [INFO ] [.internal.service.FeaturesServiceImpl] -   mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:54:24.260 [INFO ] [.internal.service.FeaturesServiceImpl] - Stopping bundles:
20:54:24.305 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.ui.basic/4.2.0.202312301505
20:54:24.311 [INFO ] [.internal.service.FeaturesServiceImpl] - Refreshing bundles:
20:54:24.315 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.ui.basic/4.2.0.202312301505 (Bundle will be updated)
...
20:54:24.357 [INFO ] [.internal.service.FeaturesServiceImpl] - Starting bundles:
...
20:54:34.732 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
20:54:51.405 [INFO ] [.internal.service.FeaturesServiceImpl] - Done.
20:54:52.302 [INFO ] [.internal.service.FeaturesServiceImpl] - Changes to perform:
20:54:52.303 [INFO ] [.internal.service.FeaturesServiceImpl] -   Region: root
20:54:52.304 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to install:
20:54:52.305 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:54:52.306 [INFO ] [.internal.service.FeaturesServiceImpl] - Installing bundles:
20:54:52.307 [INFO ] [.internal.service.FeaturesServiceImpl] -   mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:54:52.313 [INFO ] [.internal.service.FeaturesServiceImpl] - Done.
20:55:20.316 [INFO ] [.internal.service.FeaturesServiceImpl] - Adding features: openhab-core-config-discovery-addon-ip/[4.2.0.SNAPSHOT,4.2.0.SNAPSHOT]
20:55:21.137 [INFO ] [.internal.service.FeaturesServiceImpl] - Changes to perform:
20:55:21.138 [INFO ] [.internal.service.FeaturesServiceImpl] -   Region: root
20:55:21.141 [INFO ] [.internal.service.FeaturesServiceImpl] -     Bundles to install:
20:55:21.142 [INFO ] [.internal.service.FeaturesServiceImpl] -       mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:55:21.144 [INFO ] [.internal.service.FeaturesServiceImpl] - Installing bundles:
20:55:21.144 [INFO ] [.internal.service.FeaturesServiceImpl] -   mvn:org.eclipse.jetty.http2/http2-hpack/9.4.52.v20230823
20:55:21.149 [INFO ] [.internal.service.FeaturesServiceImpl] - Done.

openhab>
openhab> bundle:list -s | grep basic
258 │ Active │  80 │ 4.2.0.202312301505     │ org.openhab.ui.basic

What is strange is:

lolodomo commented 8 months ago

If I do not update my bundle (Basic UI), the restart is clean. If I update again my bundle and restart, now the restart is clean !

Maybe my problem is that the first time I restarted the server while not all the bundles were still installed ? I will try again waiting more time after the initial startup.

lolodomo commented 8 months ago

I tried again from scratch, waiting enough beofre restarting the server. If I update my bundle after the initial startup, the next start (second) will restore the initial bundle. If I update my bundle after the second start, the next start (thrid) will restore the initial bundle. If I update my bundle after the third start, the next start (fourth and the next ones) are fine, my updated bundle is still there.

For an enigmatic reason, now you need to start the server three times before "being safe".

J-N-K commented 8 months ago

My guess would be that if you restart over and over again, you'll lose the bundle. It's not fully deterministic.

lolodomo commented 8 months ago

My guess would be that if you restart over and over again, you'll lose the bundle. It's not fully deterministic.

It seems it is working well at the third start and next ones, even if I update again my bundle. I have now restarted maybe 10 times.

lolodomo commented 8 months ago

Regarding org.eclipse.jetty.http2/http2-hpack, any idea why it needs to be reinstalled each time you install a new add-on ? I tried to install rrd4j for example and http2-hpack comes again with the install.

andrewfg commented 8 months ago

@andrewfg is your PR doing stuff with installing/uninstalling feature ?

@lolodomo yes I made it un-installable in the same way that the mDNS, UPnP and IP finders are. But as I am no expert on feature installation, I just copied the other's code, so maybe I did something wrong, or overlooked something?

andrewfg commented 8 months ago

Regarding org.eclipse.jetty.http2/http2-hpack

I think the Jetty version was bumped. ?? So perhaps a binding is asking for a version different than the core had installed? Or something like that. PS have a look at the Hue binding, which was the first (maybe still only) one to introduce this dependency?

lolodomo commented 8 months ago

@lolodomo yes I made it un-installable in the same way that the mDNS, UPnP and IP finders are. But as I am no expert on feature installation, I just copied the other's code, so maybe I did something wrong, or overlooked something?

Probably not.

lolodomo commented 8 months ago

Regarding org.eclipse.jetty.http2/http2-hpack

I think the Jetty version was bumped. ?? So perhaps a binding is asking for a version different than the core had installed? Or something like that. PS have a look at the Hue binding, which was the first (maybe still only) one to introduce this dependency?

openhab> feature:list | grep jetty
pax-web-jetty                                     │ 9.4.52.v20230823 │          │ Started     │ org.ops4j.pax.web-8.0.22      │ Jetty 9 bundles
pax-web-jetty-extras                              │ 9.4.52.v20230823 │          │ Started     │ org.ops4j.pax.web-8.0.22      │ Jetty 9 additional bundles
pax-web-jetty-websockets                          │ 9.4.52.v20230823 │          │ Started     │ org.ops4j.pax.web-8.0.22      │ Jetty 9 bundles for Web Sockets support
pax-web-jetty-http2                               │ 9.4.52.v20230823 │          │ Started     │ org.ops4j.pax.web-8.0.22      │ Jetty 9 bundles for HTTP/2 support
pax-web-jetty-http2-extras                        │ 9.4.52.v20230823 │          │ Started     │ org.ops4j.pax.web-8.0.22      │ Jetty 9 additional bundles for HTTP/2 support
pax-web-jetty-http2-jdk8                          │ 9.4.52.v20230823 │          │ Uninstalled │ org.ops4j.pax.web-8.0.22      │ Jetty 9 bundles for HTTP/2 support (JDK8)
pax-web-jetty-http2-jdk9                          │ 9.4.52.v20230823 │          │ Started     │ org.ops4j.pax.web-8.0.22      │ Jetty 9 bundles for HTTP/2 support (JDK9+)
pax-web-http-jetty                                │ 8.0.22           │          │ Started     │ org.ops4j.pax.web-8.0.22      │ Http Service implementation using Jetty 9
pax-web-jetty-keycloak18                          │ 8.0.22           │          │ Uninstalled │ org.ops4j.pax.web-8.0.22      │ Keycloak 18.x Jetty bundles
pax-web-jetty-keycloak                            │ 8.0.22           │          │ Uninstalled │ org.ops4j.pax.web-8.0.22      │ Keycloak 20.x+ Jetty bundles
jetty                                             │ 9.4.52.v20230823 │          │ Uninstalled │ standard-4.4.4                │ Transition feature for backward compatibility
openhab>

Looks like the proper version is installed and started. I assume thge important line is:

pax-web-jetty-http2-jdk9                          │ 9.4.52.v20230823 │          │ Started     │ org.ops4j.pax.web-8.0.22      │ Jetty 9 bundles for HTTP/2 support (JDK9+)
openhab-bot commented 5 months ago

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/openhab-4-2-milestone-discussion/154316/103

mherwege commented 5 months ago

@lolodomo If I understand this well, this issue is not specific to the suggestion finders, but it is aggrevated by it. It also pops up if you install a distribution add-on after you have installed a custom bundle. That will also make your custom bundle revert to the default. I am not an expert on karaf and feature installation/deinstallation. When working on the capability to install/deinstall add-on finders, I reused the existing pattern used for installing/deinstalling add-ons, that is actually called from various places (to install from jar or kar, or from a call through the REST API). The relevant class for the finders is here: https://github.com/openhab/openhab-core/blob/dc17296e078cd78e7bc5e2a2ac6bbf76115c4f0f/bundles/org.openhab.core.config.discovery.addon/src/main/java/org/openhab/core/config/discovery/addon/AddonSuggestionService.java. I will have a look if it can be improved, but I doubt if I can avoid it completely. The alternative to always install and run the add-on finders is definitely also something I don't think we should go for.

J-N-K commented 5 months ago

The issue with reverting bundles is the following code in FeatureInstaller:

        try {
            if (changed) {
                featuresService.refreshFeatures(EnumSet.noneOf(FeaturesService.Option.class));
            }
        } catch (Exception e) {
            logger.error("Failed to refresh bundles after processing config update", e);
        }

On refresh the original version is installed from cache. I don't think there is a way to prevent that. IIRC simply removing it is not possible, some add-ons had resolving probems if we don't refresh.

Regarding the 3rd party add-ons: The issue might be that installation if the features and refreshing of an older install results in a failing installation. Failed add-ons are removed from the list to prvent continous re-installation attempts.

mherwege commented 5 months ago

@J-N-K Comparing the feature installation for the suggestion finders and and in FeatureInstaller, I notice there are extra options used in FeatureInstaller:

https://github.com/openhab/openhab-core/blob/dc17296e078cd78e7bc5e2a2ac6bbf76115c4f0f/bundles/org.openhab.core.karaf/src/main/java/org/openhab/core/karaf/internal/KarafAddonFinderService.java#L54

vs

https://github.com/openhab/openhab-core/blob/dc17296e078cd78e7bc5e2a2ac6bbf76115c4f0f/bundles/org.openhab.core.karaf/src/main/java/org/openhab/core/karaf/internal/FeatureInstaller.java#L439

I couldn't find clear documentation on these extra options. Would adding these to the suggestion finder installer improve the situation?

J-N-K commented 5 months ago

The options just suppress the error in case of a failed installation and the refreshing of the bundles after each installation (instead the code I posted above refreshes the bundles after everything is installed.

I think it would probably be better if you used the FeatureInstaller than using the FeaturesService (didn't check if that would work).

splatch commented 5 months ago

The options just suppress the error in case of a failed installation and the refreshing of the bundles after each installation (instead the code I posted above refreshes the bundles after everything is installed.

These options have impact on behavior of entire system. Because openhab addon features are constructed in specific way (they usually depend on openhab-core-base or openhab-runtime-base feature) installation of any addon causes refreshing (reloading) of core. Its super verbose and in my opinion not needed, because core is already tracking all needed services and can react to services which appear after addon gets installed. The reload is needed only if bundles are a) improperly managing their service references b) scanning own/system classpath. Present way partially contradicts use of OSGi.

cdjackson commented 3 months ago

I have an issue that is likely related (or the same!). I've got a stock openhabian install running on a Pi, and if I install a custom zigbee binding (which is a fat kar) it doesn't survive a reboot. I've not installed the zigbee binding from the UI, although it does show it as being installed. Other custom JARs are fine in the addons folder are fine - they come back up when the system starts, but the zigbee binding always need to be removed from addons, wait 30 seconds, then drop it back again.

Is there any workaround to this?

lolodomo commented 3 months ago

In my use case, I was not using custom jar/kar files but bundle:update command to update the existing bundles.

cdjackson commented 3 months ago

The problem also occurs when a new addon is installed from the marketplace - ie if I install a new addon from the UI marketplace, then the custom zigbee binding gets uninstalled.

This does make development of official bindings somewhat more difficult - @J-N-K do you have any thoughts as to why custom bundles are getting uninstalled? If this is considered to be a different issue, I'm happy to open a new issue.

lolodomo commented 3 months ago

As soon as something is installed, all custom bundles are reverted. That is the known issue.

cdjackson commented 3 months ago

Sure - but in my case, it's not exactly reverted - it's removed. I guess you can say this is reverted, since the zigbee binding was never installed, so I guess the fact that the system is removing it is in some view reverted.

Either way, it makes it very annoying/difficult to develop with this issue.

lolodomo commented 3 months ago

Removed in your use case, reverted in mine.

cdjackson commented 3 months ago

Sure - understood - and both are not good ;)

J-N-K commented 3 months ago

https://github.com/openhab/openhab-core/issues/3983#issuecomment-2073325504 This explains what happens and why. We would need to change the way features are declared and probably add correct import statements in the manifest.

cdjackson commented 3 months ago

Thanks. I guess the question is if anyone plans to look at this or if we have to live with it? If it's not going to be fixed, and there's no easy workaround, then it's a bit of a killer...

J-N-K commented 3 months ago

Does it improve if you add

-snapshot: SNAPSHOT

to the BND instructions (in openhab-addons that would be around https://github.com/openhab/openhab-addons/blob/280f5c5beb53e95744122085bc45c3774c4ce1aa/pom.xml#L111

cdjackson commented 3 months ago

No - that doesn't seem to make any difference.

cdjackson commented 3 months ago

So... The problem is even worse...

When I drop in a new KAR, it is actually not used for the most part. I'd not noticed before, but the bundles that are loaded are from the addons snapshot, and not from the KAR. This KAR has one extra bundle for a new coordinator we've been testing, and this bundle does get loaded, so clearly the new KAR is recognised, but all other bundles are taken from the distribution rather than the KAR I've dropped in addons. Now that I'm making changes to the bundles that are in the distro, these are ignored.

I've tried to get the system to update from the kar, but so far no joy. I'll try also dropping in a JAR for the bundles that I want to update, but this is really quite problematic to develop now and I'm open to suggestions on how to move forward.

wborn commented 3 months ago

IIRC as a workaround I just disabled all suggestion finders in the advanced settings of "Add-on Management" to stop bundles from reverting during development.

lolodomo commented 3 months ago

IIRC, that is the reverse, you should not disable finders in settings because if disabled some are installed and then uninstalled during OH startup and that triggers the problem. That is what I discovered when analysing the JUPnP issue.

https://github.com/openhab/openhab-core/issues/4140#issuecomment-2004947016

mherwege commented 3 months ago

IIRC, that is the reverse, you should not disable finders in settings because if disabled some are installed and then uninstalled during OH startup and that triggers the problem. That is probably what I discovered and explained in that issue or maybe the JUPnP issue.

That's not what it does. If you disable them in the settings and do a restart, they will not get loaded and installed at all the next start. They are not part of a feature that gets started with OH start. These finders are not installed at start of OH, but when the finder service gets started. And this finder service looks for the enabled/disabled configuration. So once disabled, it will not start anymore when you restart OH. You can even disable them before first start in the services config file.

The only thing this avoids is the bundle refresh caused by the add-on finders. I remain to be convinced this solves the whole problem (and I do admit the finder installation is one cause of bundle refreshes, so makes the problem worse).

Could it be that this issue happens mainly when the distribution addons kar file has been downloaded? It seems to me it picks parts from both the dropped kar file and distribution kar file and mixes them wrongly. Dropping a kar or jar file in the addons folder causes a bundle refresh. And I have the impression it is fairly indeterministic what gets loaded, especially when testing on a snapshot distribution with a snapshot kar dropped in. My guess is it works better with a snapshot kar dropped in a milestone or release distribution (as the snapshot will take precedence).

mherwege commented 3 months ago

4140 (comment)

Since then, the mechanism has been adjusted to use the same FeatureInstaller used when installing all other bundles (https://github.com/openhab/openhab-core/pull/4188). This FeatureInstaller queues installation/deinstallation and therefore should make the issue less present (without eliminating it completely).

lolodomo commented 3 months ago

In my case, tests were done with an offline distribution, that is with a distribution kar file. Updates were not done with jar or kar files put in addons folder but with command bundle:update.

cdjackson commented 3 months ago

Thanks @wborn Disabling the addon management does seem to work around this problem - but only if I use JARs - not KAR. If I use a KAR, the bundles that get loaded are from the distro - not from the new KAR that I put in addons. It's possible that the addon management settings actually make no difference to this and it's just the JARs that are solving the problem, but I don't seem to be able to change the addons settings back - as soon as I now click on these suggestion finder settings to enable them, they now disappear from the UI!!!

addons

andrewfg commented 3 months ago

as soon as I now click on these suggestion finder settings to enable them, they now disappear from the UI!!!

You need to ensure that “Show Advanced” is checked..