Org.apache.felix.cm cannot load configuration

Hello everyone! I’m new to your community and glad to join!
I installed lates stable version of OPENHAB 4.1 and it worked fine couple of days. Then after power failure my Windows server 2019 restarted and now apache webserver not working for my OpenHAB machine I got this exception when starting start_debug.bat May be someone faced such problem already or knows what file to correct ? Any help would be much appreciated!

Thanks

Launching the openHAB runtime...
Listening for transport dt_socket at address: 5005
09:30:58.392 [Start Level: Equinox Container: edfa536f-22bb-4f5e-a5b0-2caad2a5e037] ERROR org.apache.felix.configadmin - Failure setting up dynamic configuration bindings
java.io.IOException: Unexpected token 78; expected: 61 (line=0, pos=85)
        at org.apache.felix.cm.file.ConfigurationHandler.readFailure(ConfigurationHandler.java:700) ~[?:?]
        at org.apache.felix.cm.file.ConfigurationHandler.readInternal(ConfigurationHandler.java:305) ~[?:?]
        at org.apache.felix.cm.file.ConfigurationHandler.read(ConfigurationHandler.java:268) ~[?:?]
        at org.apache.felix.cm.file.FilePersistenceManager._load(FilePersistenceManager.java:651) ~[?:?]
        at org.apache.felix.cm.file.FilePersistenceManager.load(FilePersistenceManager.java:592) ~[?:?]
        at org.apache.felix.cm.impl.DynamicBindings.<init>(DynamicBindings.java:53) ~[?:?]
        at org.apache.felix.cm.impl.ConfigurationManager.<init>(ConfigurationManager.java:158) ~[?:?]
        at org.apache.felix.cm.impl.ConfigurationAdminStarter.activate(ConfigurationAdminStarter.java:74) ~[?:?]
        at org.apache.felix.cm.impl.DependencyTracker.<init>(DependencyTracker.java:92) ~[?:?]
        at org.apache.felix.cm.impl.Activator.start(Activator.java:114) ~[?:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl$2.run(BundleContextImpl.java:818) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl$2.run(BundleContextImpl.java:1) ~[org.eclipse.osgi-3.18.0.jar:?]
        at java.security.AccessController.doPrivileged(AccessController.java:569) [?:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:810) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:767) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:1032) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:371) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.Module.doStart(Module.java:605) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.Module.start(Module.java:468) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1783) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345) [org.eclipse.osgi-3.18.0.jar:?]

                           _   _     _     ____
   ___   ___   ___   ___  | | | |   / \   | __ )
  / _ \ / _ \ / _ \ / _ \ | |_| |  / _ \  |  _ \
 | (_) | (_) |  __/| | | ||  _  | / ___ \ | |_) )
  \___/|  __/ \___/|_| |_||_| |_|/_/   \_\|____/
       |_|       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>

1 Like

Did you try clearing the cache ?

Hm nope! How can I do that ?

Thanks for your reply

I seem to have the exact same problem. I updated some days ago and it went fine. Tonight my hyper-v host did windows updates and (due to a bug in hyper-v) powered off the guest vms. After that it seemed that openhab was running but only KNX connector was offline. But when I restarted openhab then it wont come back online.
The openhab and events logs did not show up, so I checked wrapper log and it was full of errors, starting with the above mentioned.

Here is my output of start_debug:

C:\openhab2>start_debug.bat
Launching the openHAB runtime...
Listening for transport dt_socket at address: 5005
22:55:07.931 [Start Level: Equinox Container: 8b2123b1-0cd1-4d1e-80e3-e7fd94b3aa86] ERROR org.apache.felix.configadmin - Failure setting up dynamic configuration bindings
java.io.IOException: Unexpected token 78; expected: 61 (line=0, pos=184)
        at org.apache.felix.cm.file.ConfigurationHandler.readFailure(ConfigurationHandler.java:700) ~[?:?]
        at org.apache.felix.cm.file.ConfigurationHandler.readInternal(ConfigurationHandler.java:305) ~[?:?]
        at org.apache.felix.cm.file.ConfigurationHandler.read(ConfigurationHandler.java:268) ~[?:?]
        at org.apache.felix.cm.file.FilePersistenceManager._load(FilePersistenceManager.java:651) ~[?:?]
        at org.apache.felix.cm.file.FilePersistenceManager.load(FilePersistenceManager.java:592) ~[?:?]
        at org.apache.felix.cm.impl.DynamicBindings.<init>(DynamicBindings.java:53) ~[?:?]
        at org.apache.felix.cm.impl.ConfigurationManager.<init>(ConfigurationManager.java:158) ~[?:?]
        at org.apache.felix.cm.impl.ConfigurationAdminStarter.activate(ConfigurationAdminStarter.java:74) ~[?:?]
        at org.apache.felix.cm.impl.DependencyTracker.<init>(DependencyTracker.java:92) ~[?:?]
        at org.apache.felix.cm.impl.Activator.start(Activator.java:114) ~[?:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl$2.run(BundleContextImpl.java:818) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl$2.run(BundleContextImpl.java:1) ~[org.eclipse.osgi-3.18.0.jar:?]
        at java.security.AccessController.doPrivileged(AccessController.java:569) [?:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:810) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:767) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:1032) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:371) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.Module.doStart(Module.java:605) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.Module.start(Module.java:468) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1783) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345) [org.eclipse.osgi-3.18.0.jar:?]

I have done update to 4.1.1 (because I thought this might be an issue that 4.1.1 solves). I have also cleared cache and tmp folder in userdata - problem still remains. :frowning:

Upon searching the error, I found this post Problem after running OpenHAB restore script - #12 by maxheartrate, where also an error with “org.apache.felix.configadmin - Failure setting up dynamic configuration bindings” is in some logs. But the proposed solution (reinstalling openhab and copying configs) is something I would like to avoid. Especially because I would not find the root cause and the same ting could happen with the next unexpected shutdown.

My openhab vm has been running for 5 years and despite many unexpected shutdowns no problems have occurred. The fact that we now already have two Openhab 4.1 installations on Windows, which show an identical error pattern after an unexpected shutdown, does not indicate a coincidence to me, but a causal connection. I therefore strongly assume that a change in 4.0 or 4.1 (my upgrade was from 3.4 to 4.1) could be the root cause.

I’m sorry to hear about your problems…I’m sure there are folks here willing to help.

I think re-installing openhab and restoring from a backup should not take more than a few minutes and may be the quickest way to restore the system.

You should consider adding an uninterruptable power supply to eliminate unexpected shutdowns. Expecting your system to always recover from these shutdowns might be a challenge.

Powered off by graceful shutdown or powered off like the power plug was pulled ?
If it is the second then it is ‘normal’ that you could have corrupted files as the power could have gone away during a write to disk cycle.

I could indeed focus on the issue, that VMs are shutdown unexpectetly - but the issue is new since OpenHAB 4.1 migration, and eliminating all possible causes for unexpected shutdowns is not possible! :slight_smile:

During researching I have read about an issue in the Windows update process that leads to unexpected shutdowns. Windows restarts several times when installing updates - in this case, however, the vmms is probably already started during the “Updates are being installed - please do not turn off” phase.
The VMMS seems to start VMs that are set to automatical start up - but the update process then restarts the host without waiting until the guests have shut down.

I have this issue for about 5 years with several VMs. Never had an issue where this caused a software to stop working. And I cannot think of any issue to any of my desktop windows PCs in the last 15 years, where pull-the-plug lead to “software not working anymore” (only to data beeing lost).

So please lets get back to topic and try to identify whats the root cause in openHAB and how to fix it? :slight_smile:

Checking my openHAB config files I noticed, that the config.properties file has a change timestamp right before the shutdown (11-01-2024 22:46). But I do not understand how openhab works, and if it is normal that config files are generated/altered during execution?

Issue is - the configuration objects which are created from source files i.e. runtime.cfg, files in runtime/etc/ directory get copied to deep internal storage (somewhere under userdata/cache/bundles). This is needed in order to track configuration changes across restarts.
The problem you observe is - reading of internal copy from storage fails and it fails due to invalid file format. The file is encoded as key value pairs and after each key (if I read properly) there should be equal sign (61 is ascii code for =). Yet, for some reason file contains key, bud next entry parser sees is name (78 is ascii code for N).

Cleaning of cache folder should help to flush issue, however if it happens with each restart we have to look closer if there is a bug coming from updated version of configuration admin (unbalanced write/read cycle).

Format description and parser sources: https://github.com/apache/felix-dev/blob/org.apache.felix.configadmin-1.9.6/src/main/java/org/apache/felix/cm/file/ConfigurationHandler.java#L53.

Version used in OH 4.1.0 (Karaf 4.4.4 > felix-configadmin 1.9.26).
Version used in OH 4.0.4 (Karaf 4.4.3 > felix-configadmin 1.9.26); same for OH 4.0.3, 4.0.2, 4.0.1, 4.0.0).
Version used in OH 3.4.5 (Karaf 4.3.7 > felix-configadmin 1.9.24).

Does anyone have a reliable reproducer?

Thank you for the detailed feedback and RCA approach. My userdata/cache looks like this, and deleting its contents did not help.
grafik

So is there any other folder/ method to find the possible corruption?

Interestingly the two ascii characters are defined in the file you linked next to each other as TOKEN_NAME and TOKEN_EQ - only a cooincidence?
grafik

The cache cleanup is definitely a solution for that error. It should not cause side effects, especially that you do it when system is shut.

There is no coincidence in code you looked at - this is really where issue comes from. I don’t know yet why it fails, but that’s the place which is rising error. If it didn’t happen with OH3 and happens with OH4 I’d look carefully at most recent versions of configadmin. As shown above there was version bump between last 3.4.x release and 4.0.x and 4.1.x.

Well, the definition of insanity is trying the same thing repeatedly with the aim of achieving a different result. :wink:

I cleaned up cache and tmp folder again and the result is the same error message. So its definetly not the cache or tmp folder thats causing the problem here!

Other ideas?

Maybe it will tell you what file it is loading if you enable debug logging on org.apache.felix

Ok, could you help me, how to do this?

Hi @fuetti, it’s all explained in the logging docs:

Either type this on the Console:

log:set debug org.apache.felix

Or you can configure the logger by editting your log4j2.xml and then add:

<Logger level="DEBUG" name="org.apache.felix"/>

There is a quick test if the latest version of configuration admin shipped with Karaf is guilty of your trouble.

Just do

openhab> update 12 https://repo1.maven.org/maven2/org/apache/felix/org.apache.felix.configadmin/1.9.24/org.apache.felix.configadmin-1.9.24.jar

This command downgrades config admin to earlier version. After that do a restart of service and check if its any better.
The 12 in above command comes from this output:

openhab> la -s|grep 'org.apache.felix.configadmin'
 12 x Active    x  10 x 1.9.26                 x org.apache.felix.configadmin  // << 12 is module identifier 
 15 x Active    x  11 x 1.2.6                  x org.apache.felix.configadmin.plugin.interpolation

Thank you for the help. But as mentioned above, I am on windows :-).
Where should I put this - on thecomand line? There is a update script, but afaik its only to update to other OH version? So it throws an error:

I found a shell.bat that startet something… but was not lucky with the comand

I cant do this in the OH console because its not running because this is the error I want to fix I thought? :face_with_raised_eyebrow:

C:\openhab2\runtime\bin>client
Logging in as openhab
Failed to get the session.

I added the logging to the log4j2.xml, but the output in start_debug seems not to change?

C:\openhab2>start_debug.bat
Launching the openHAB runtime...
Listening for transport dt_socket at address: 5005
14:17:54.819 [Start Level: Equinox Container: d32e8287-527b-48a3-a7a8-aeab3a8bc2f6] ERROR org.apache.felix.configadmin - Failure setting up dynamic configuration bindings
java.io.IOException: Unexpected token 78; expected: 61 (line=0, pos=184)
        at org.apache.felix.cm.file.ConfigurationHandler.readFailure(ConfigurationHandler.java:700) ~[?:?]
        at org.apache.felix.cm.file.ConfigurationHandler.readInternal(ConfigurationHandler.java:305) ~[?:?]
        at org.apache.felix.cm.file.ConfigurationHandler.read(ConfigurationHandler.java:268) ~[?:?]
        at org.apache.felix.cm.file.FilePersistenceManager._load(FilePersistenceManager.java:651) ~[?:?]
        at org.apache.felix.cm.file.FilePersistenceManager.load(FilePersistenceManager.java:592) ~[?:?]
        at org.apache.felix.cm.impl.DynamicBindings.<init>(DynamicBindings.java:53) ~[?:?]
        at org.apache.felix.cm.impl.ConfigurationManager.<init>(ConfigurationManager.java:158) ~[?:?]
        at org.apache.felix.cm.impl.ConfigurationAdminStarter.activate(ConfigurationAdminStarter.java:74) ~[?:?]
        at org.apache.felix.cm.impl.DependencyTracker.<init>(DependencyTracker.java:92) ~[?:?]
        at org.apache.felix.cm.impl.Activator.start(Activator.java:114) ~[?:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl$2.run(BundleContextImpl.java:818) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl$2.run(BundleContextImpl.java:1) ~[org.eclipse.osgi-3.18.0.jar:?]
        at java.security.AccessController.doPrivileged(AccessController.java:569) [?:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:810) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:767) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:1032) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:371) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.Module.doStart(Module.java:605) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.Module.start(Module.java:468) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1783) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345) [org.eclipse.osgi-3.18.0.jar:?]

So what now?

Try cleaning up a cache and then, with clean start you should have working console. Or does it happen right after clean start?

It does happen right after start. I only get wrapper.log - nothing in openhab.log.

I delete cache folder and start (either start_debug or start via service) and then I see this beeing created in cache:

and this on the console/ wrapper.log:

when I try to access console I get this.

The shell comand works somehow. But I always get that error “unknown command entered”:

Hm, I mentioned I updated to 4.1.1 because I thought its a bug that might be fixed. Now I reverted to the snapshot before the uptate.
After deleting cache and tmp directories, I ran a powershell script to identify recently changed files.

And I found something that got my attention:

    Directory: C:\openhab2\userdata\config


Mode                LastWriteTime         Length Name
----                -------------         ------ ----
-a----       11.01.2024     21:33            179 org_apache_felix_cm_impl_DynamicBindings.config

When I tried to open it in code, it would warn me and give me this output then:

So I am not an expert, but this looks not like a proper config file to me. I am wondering why this config file is there, how it was created and why openhab would use it anyways.

So I just renamed it to …_org and give it a try (with start_debug and the debug logging added to l4j as @wborn suggested).
It was immediatly starting to fill the openhab.log (~5k lines - so I wont paste it here). And after some time the console was displayed and the log indicated, that OH did startup.

grafik

Now checking the directory again I found that the file was created again:

    Directory: C:\openhab2\userdata\config


Mode                LastWriteTime         Length Name
----                -------------         ------ ----
d-----       28.12.2020     22:50                binding
d-----       26.12.2020     23:53                com
d-----       16.05.2019     21:30                jmx
d-----       16.05.2019     21:30                org
-a----       13.01.2024     17:05             97 org_apache_felix_cm_impl_DynamicBindings.config
-a----       11.01.2024     21:33            179 org_apache_felix_cm_impl_DynamicBindings.config_org
-a----       28.12.2023     23:36           7848 profile.config
-a----       16.05.2019     21:30             79 SymmetricKeyCipher.config

But in the editor now its looking different (moke like a config file).

So I guess, I found the cause. I am going to do another snapshot, check if it also works after reboot and without debugging. And then probably go for 4.1.1. again… so fingers crossed :slight_smile:

Thank you <3

1 Like