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>
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.
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!
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?
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).
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).
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.
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!
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 cant do this in the OH console because its not running because this is the error I want to fix I thought?
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:?]
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.
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.
Now checking the directory again I found that the file was created again:
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
