After upgrade to latest snapshot: Error installing boot features | invalid header field

Hi All,

My openHAB 2.2 runtime is no longer starting after the usual package upgrade. I am getting the only error in openhab.log below, and the openHAB is not working at all. Prior the upgrade the installation worked just fine.

I am using the SNAPSHOT builds, and my current (not working version) is:
2.2.0~20170916011924-1

Here is what I did:

sudo apt-get update
sudo apt-get upgrade

My Java version:

java version "1.8.0_65"
Java(TM) SE Runtime Environment (build 1.8.0_65-b17)
Java HotSpot(TM) Client VM (build 25.65-b01, mixed mode)

My OS is Raspbian Stretch (Debian).

Typically, when I had errors after upgrade I usually did cleanup the \var\lib\openhab2 directory and problems went away. This time I deleted the tmp, kar and cache folders. This did not fix the issue.

Any ideas how to fix this?
I could downgrade to an earlier version, but not sure where to get previous snapshot version numbers?

Here is the openhab.log error:

2017-09-16 21:21:23.512 [ERROR] [ternal.service.BootFeaturesInstaller] - Error installing boot features
org.apache.karaf.features.internal.util.MultiException: Error:
	invalid header field
	at org.apache.karaf.features.internal.download.impl.MavenDownloadManager$MavenDownloader.<init>(MavenDownloadManager.java:84) ~[?:?]
	at org.apache.karaf.features.internal.download.impl.MavenDownloadManager.createDownloader(MavenDownloadManager.java:72) ~[?:?]
	at org.apache.karaf.features.internal.region.Subsystem.downloadBundles(Subsystem.java:375) ~[?:?]
	at org.apache.karaf.features.internal.region.Subsystem.downloadBundles(Subsystem.java:372) ~[?:?]
	at org.apache.karaf.features.internal.region.SubsystemResolver.resolve(SubsystemResolver.java:187) ~[?:?]
	at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:291) ~[?:?]
	at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:287) ~[?:?]
	at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1233) ~[?:?]
	at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$0(FeaturesServiceImpl.java:1132) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
	Suppressed: java.io.IOException: invalid header field
		at java.util.jar.Attributes.read(Attributes.java:406) [?:?]
		at java.util.jar.Manifest.read(Manifest.java:199) [?:?]
		at java.util.jar.Manifest.<init>(Manifest.java:69) [?:?]
		at org.apache.karaf.features.internal.region.Subsystem.getMetadata(Subsystem.java:540) [9:org.apache.karaf.features.core:4.1.2]
		at org.apache.karaf.features.internal.region.Subsystem$1.downloaded(Subsystem.java:402) [9:org.apache.karaf.features.core:4.1.2]
		at org.apache.karaf.features.internal.download.impl.MavenDownloadManager$MavenDownloader$1.operationComplete(MavenDownloadManager.java:133) [9:org.apache.karaf.features.core:4.1.2]
		at org.apache.karaf.features.internal.download.impl.MavenDownloadManager$MavenDownloader$1.operationComplete(MavenDownloadManager.java:127) [9:org.apache.karaf.features.core:4.1.2]
		at org.apache.karaf.features.internal.download.impl.DefaultFuture.notifyListener(DefaultFuture.java:350) [9:org.apache.karaf.features.core:4.1.2]
		at org.apache.karaf.features.internal.download.impl.DefaultFuture.notifyListeners(DefaultFuture.java:335) [9:org.apache.karaf.features.core:4.1.2]
		at org.apache.karaf.features.internal.download.impl.DefaultFuture.setValue(DefaultFuture.java:259) [9:org.apache.karaf.features.core:4.1.2]
		at org.apache.karaf.features.internal.download.impl.AbstractDownloadTask.setFile(AbstractDownloadTask.java:61) [9:org.apache.karaf.features.core:4.1.2]
		at org.apache.karaf.features.internal.download.impl.AbstractRetryableDownloadTask.run(AbstractRetryableDownloadTask.java:61) [9:org.apache.karaf.features.core:4.1.2]
		at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
		at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
		at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
		at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
		at java.lang.Thread.run(Thread.java:745) [?:?]

Hi @zarusz,

I’ve only just seen this post, so apologies for any delay in reply to you. Is this still an issue for you? One thing I can suggest is to update your Java, the minimum recommended version is 1.8.0_101. I’d suggest trying out Zulu embedded, which works very well on Rasbian Stretch.

Hi @Benjy

Thanks for your response. Actually, I have the latest Oracle 8 JDK installed for my distribution:

sudo apt-get install oracle-java8-jdk
Reading package lists... Done
Building dependency tree
Reading state information... Done
oracle-java8-jdk is already the newest version (8u65).
0 upgraded, 0 newly installed, 0 to remove and 4 not upgraded.

In fact, prior the upgrade openHAB used to work just fine with this JDK version.

I managed to get around the problem by:

  1. Switching to beta/testing distribution of openHAB
  2. Waiting 1-2 days for another openHAB update package to get released and doing another apt-get update

This helped. However, I am left with another problem:
No UIs get automatically installed. I am not even sure if any of the bindings get installed either.

Here is my addons.cfg:

package = minimal

# Access Remote Add-on Repository
# Defines whether the remote openHAB add-on repository should be used for browsing and installing add-ons.
# This not only makes latest snapshots of add-ons available, it is also required for the installation of
# any legacy 1.x add-on. (default is true)
#
remote = true

# Include legacy 1.x bindings. If set to true, it also allows the installation of 1.x bindings for which there is 
# already a 2.x version available (requires remote repo access, see above). (default is false)
#
legacy = true

# A comma-separated list of bindings to install (e.g. "sonos,knx,zwave")
binding = yamahareceiver,mqtt1,xbmc1,mqttitude1,yahooweather,weather1

# A comma-separated list of UIs to install (e.g. "basic,paper")
ui = basic,paper,habpanel

# A comma-separated list of persistence services to install (e.g. "rrd4j,jpa")
persistence = rrd4j

# A comma-separated list of actions to install (e.g. "mail,pushover")
#action = xbmc

# A comma-separated list of transformation services to install (e.g. "map,jsonpath")
transformation = map

# A comma-separated list of voice services to install (e.g. "marytts,freetts")
#voice = 

# A comma-separated list of miscellaneous services to install (e.g. "myopenhab")
#misc = 

During openHAB start I only get this in openhab.log:

2017-09-19 20:06:34.138 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.action.ActionService}={component.name=org.eclipse.smarthome.action.audio, component.id=117, service.id=648, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-19 20:06:34.187 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.action.ActionService}={component.name=org.eclipse.smarthome.action.persistence.action, component.id=119, service.id=649, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-19 20:06:34.198 [DEBUG] [org.eclipse.smarthome.model.script  ] - BundleEvent STARTING - org.eclipse.smarthome.model.script
2017-09-19 20:06:34.209 [DEBUG] [org.eclipse.smarthome.model.script  ] - BundleEvent STARTED - org.eclipse.smarthome.model.script
2017-09-19 20:06:34.241 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.voice.text.HumanLanguageInterpreter}={service.pid=org.eclipse.smarthome.rulehli, service.config.category=voice, service.config.label=Rule Voice Interpreter, component.name=org.eclipse.smarthome.rulehli, component.id=120, service.config.description.uri=voice:rulehli, service.id=652, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-19 20:06:34.271 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.jvmmodel.ScriptItemRefresher}={component.name=org.eclipse.smarthome.model.script.jvmmodel.scriptitemrefresher, component.id=121, service.id=654, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-19 20:06:34.322 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.ScriptServiceUtil}={component.name=org.eclipse.smarthome.model.script.ScriptServiceUtil, component.id=122, service.id=655, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-19 20:06:37.147 [DEBUG] [thome.model.script.ScriptServiceUtil] - ScriptServiceUtil started
2017-09-19 20:06:37.163 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.action.ActionService}={component.name=org.eclipse.smarthome.action.thing.action, component.id=123, service.id=656, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-19 20:06:37.182 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.action.ActionService}={component.name=org.eclipse.smarthome.action.transformation.action, component.id=124, service.id=657, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-19 20:06:37.203 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.action.ActionService}={component.name=org.eclipse.smarthome.action.voice, component.id=125, service.id=658, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-19 20:06:37.214 [DEBUG] [org.eclipse.smarthome.model.script  ] - BundleEvent [unknown:512] - org.eclipse.smarthome.model.script
2017-09-19 20:07:06.343 [DEBUG] [ime.internal.engine.ScriptEngineImpl] - Registered 'script' configuration parser
2017-09-19 20:07:06.350 [DEBUG] [lipse.smarthome.model.script.runtime] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.ScriptEngine, org.eclipse.smarthome.model.core.ModelParser}={component.name=org.eclipse.smarthome.model.script, component.id=129, service.id=683, service.bundleid=131, service.scope=bundle} - org.eclipse.smarthome.model.script.runtime
2017-09-19 20:07:06.355 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.console.extensions.ConsoleCommandExtension}={component.name=org.eclipse.smarthome.model.script.engine.consolecommandextension, component.id=118, service.id=684, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-19 20:07:14.587 [DEBUG] [lipse.smarthome.model.script.runtime] - BundleEvent STARTING - org.eclipse.smarthome.model.script.runtime
2017-09-19 20:07:14.597 [DEBUG] [lipse.smarthome.model.script.runtime] - BundleEvent STARTED - org.eclipse.smarthome.model.script.runtime

Any ideas what happened ?
I did not even change the addons.cfg file. Was there a breaking change introduced recently or do I have bad luck with my upgrade process?

EDIT:
Changing the package = simple in addons.cfg causes the UI to get installed. However, in my opinion this indicates breaking behavior in the latest release. Given the ui entry, the UIs should have been installed even when package was set to minimal - at least this is how it used to work.

That’s how I would assume it would work too. I don’t use the textual configuration though so have very little experience with it (@rlkoshak, you have experience with this right? is this correct?). The default configuration contains the following:


# Valid options:
#   - minimal  : Installation only with dashboard, but no UIs or other add-ons. Use this for custom setups.
#   - simple   : Setup for using openHAB purely through UIs - you need to expect MANY constraints in functionality!
#   - standard : Default setup for normal users, best for textual setup
#   - expert   : Setup for expert users, especially for people migrating from openHAB 1.x
#   - demo     : A demo setup which includes UIs, a few bindings, config files etc.
#
# See http://docs.openhab.org/configuration/packages.html for a detailed explanation of these packages.
#
#package = minimal

I’m on an older build of the SNAPSHOT so have not run into this but I completely agree. No matter what you set the package to it should then install everything listed later on in addons.cfg.

This is a bug and an issue should be filed. I’m not absolutely certain which repo is the correct one though. Do you know where the code is that handles addons.cfg, ESH or openhab2 @Benjy?

Many thanks @rlkoshak and @Benjy for your input here.

I did upgrade to another newer snapshot as of today. The good news is that the UI got installed and worked until next restart. After restarting my RiPi (or openHAB service restart) causes the UIs to get installed again. When I attempt to access any UI via browser (http://:8080/start/index) I am stuck on a screen that says:

Please stand by while UIs are being installed. This can take several minutes.

The opanhab.log does not yeld anything interesting:

2017-09-20 23:00:20.795 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.action.ActionService}={component.name=org.eclipse.smarthome.action.audio, component.id=117, service.id=675, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-20 23:00:20.847 [DEBUG] [org.eclipse.smarthome.model.script  ] - BundleEvent STARTING - org.eclipse.smarthome.model.script
2017-09-20 23:00:20.862 [DEBUG] [org.eclipse.smarthome.model.script  ] - BundleEvent STARTED - org.eclipse.smarthome.model.script
2017-09-20 23:00:20.911 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.action.ActionService}={component.name=org.eclipse.smarthome.action.persistence.action, component.id=119, service.id=679, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-20 23:00:20.933 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.voice.text.HumanLanguageInterpreter}={service.pid=org.eclipse.smarthome.rulehli, service.config.category=voice, service.config.label=Rule Voice Interpreter, component.name=org.eclipse.smarthome.rulehli, component.id=120, service.config.description.uri=voice:rulehli, service.id=680, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-20 23:00:20.967 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.jvmmodel.ScriptItemRefresher}={component.name=org.eclipse.smarthome.model.script.jvmmodel.scriptitemrefresher, component.id=121, service.id=681, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-20 23:00:21.021 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.ScriptServiceUtil}={component.name=org.eclipse.smarthome.model.script.ScriptServiceUtil, component.id=122, service.id=682, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-20 23:00:21.044 [DEBUG] [thome.model.script.ScriptServiceUtil] - ScriptServiceUtil started
2017-09-20 23:00:21.058 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.action.ActionService}={component.name=org.eclipse.smarthome.action.thing.action, component.id=123, service.id=683, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-20 23:00:21.079 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.action.ActionService}={component.name=org.eclipse.smarthome.action.transformation.action, component.id=124, service.id=684, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-20 23:00:21.098 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.action.ActionService}={component.name=org.eclipse.smarthome.action.voice, component.id=125, service.id=685, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-20 23:00:21.120 [DEBUG] [org.eclipse.smarthome.model.script  ] - BundleEvent [unknown:512] - org.eclipse.smarthome.model.script
2017-09-20 23:01:09.445 [DEBUG] [lipse.smarthome.model.script.runtime] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.script.engine.ScriptEngine, org.eclipse.smarthome.model.core.ModelParser}={component.name=org.eclipse.smarthome.model.script, component.id=129, service.id=699, service.bundleid=131, service.scope=bundle} - org.eclipse.smarthome.model.script.runtime
2017-09-20 23:01:12.647 [DEBUG] [ime.internal.engine.ScriptEngineImpl] - Registered 'script' configuration parser
2017-09-20 23:01:13.312 [DEBUG] [org.eclipse.smarthome.model.script  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.console.extensions.ConsoleCommandExtension}={component.name=org.eclipse.smarthome.model.script.engine.consolecommandextension, component.id=118, service.id=701, service.bundleid=130, service.scope=bundle} - org.eclipse.smarthome.model.script
2017-09-20 23:01:13.337 [DEBUG] [lipse.smarthome.model.script.runtime] - BundleEvent STARTING - org.eclipse.smarthome.model.script.runtime
2017-09-20 23:01:13.358 [DEBUG] [lipse.smarthome.model.script.runtime] - BundleEvent STARTED - org.eclipse.smarthome.model.script.runtime

I will attempt to downgrade to latest stable version and see if the issue persists. The goal is to exclude any possible corruptions that might had occurred with my installation during upgrade process. In the worst case I will uninstall fully and install clean again :confused:

Let me know if you have better ideas.

Thanks for the confirmation @rlkoshak, if it’s reproduceable, it’s most likely a bug with openHAB2 but hopefully if we can past this loading ui stage then all will be well.

It’s a shame you’re coming across these issues @zarusz. I’d stop openhab and delete the contents of /var/lib/openhab2/cache and /var/lib/openhab2/tmp before restarting it, hopefully that has some effect.

As per your suggestion I have stopped the openHAB service, deleted the tmp and cache and started the openhab service. The UI showed up. Unfortunately, restarting the service again, causes the Please stand by while UIs are being installed. This can take several minutes. to get shown and it gets stuck.

Here is the current version that I have:

2.2.0~20170920221851-1
openHAB 2.2.0 Build #1044

Furthermore, the map transform has not been installed either:

2017-09-21 22:52:31.429 [WARN ] [.core.transform.TransformationHelper] - Cannot get service reference for transformation service of type MAP
2017-09-21 22:52:31.435 [WARN ] [.core.transform.TransformationHelper] - Couldn't transform value because transformation service of type 'MAP' is not available

I will attempt to install a stable version and see how it goes.

So I reverted to the latest stable release 2.1.0-1 and my problems went away. The UIs and other addons mentioned in addons.cfg load fine. Also restarting the service works as expected.

I will file a bug/issue report soon.

1 Like

I filed a bug report: https://github.com/openhab/openhab-core/issues/212

Thanks for all your input.

1 Like