Problem after running OpenHAB restore script

maxheartrate · December 4, 2020, 4:52pm

Hi everyone,

I need help (again …). After my SD card file system was most likely corrupted I set up my system with a fresh install (thanks to @rlkoshak and @mstormi for their help!).
Reinstall went well and OH2 started from the new card without problems. I managed to do a backup of my settings using the backup script to a USB drive. Restore on the new card completed without errors.
Afterwards I restarted the openhab2 service. It started but I could not reach my website. It stays the same after a reboot.

sudo systemctl status openhab2.service result:

● openhab2.service - openHAB2 instance, reachable at http://openhab:8080
   Loaded: loaded (/usr/lib/systemd/system/openhab2.service; enabled; vendor preset: enabled)
  Drop-In: /etc/systemd/system/openhab2.service.d
           └─override.conf
   Active: active (running) since Fri 2020-12-04 17:25:16 CET; 17min ago
     Docs: https://www.openhab.org/docs/
           https://community.openhab.org
  Process: 738 ExecStartPre=/bin/bash -c /usr/bin/find ${OPENHAB_CONF} -name "*.rules" -exec /usr/bin/rename.ul .rules .x {} \; (code=exited, status=0/SUCCESS)
  Process: 763 ExecStartPost=/bin/sleep 120 (code=exited, status=0/SUCCESS)
  Process: 1354 ExecStartPost=/bin/bash -c /usr/bin/find ${OPENHAB_CONF} -name "*.x" -exec /usr/bin/rename.ul .x .rules {} \; (code=exited, status=0/SUCCESS)
 Main PID: 762 (java)
    Tasks: 27 (limit: 2063)
   CGroup: /system.slice/openhab2.service
           └─762 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/lo

Dec 04 17:23:28 openhab karaf[762]:         at org.eclipse.osgi.container.Module.doStart(Module.java:581) [org.eclipse.osgi-3.12.100.jar:?]
Dec 04 17:23:28 openhab karaf[762]:         at org.eclipse.osgi.container.Module.start(Module.java:449) [org.eclipse.osgi-3.12.100.jar:?]
Dec 04 17:23:28 openhab karaf[762]:         at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) [org.eclipse.osgi-3.12.100.jar:?]
Dec 04 17:23:28 openhab karaf[762]:         at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) [org.eclipse.osgi-3.12.100.jar:?]
Dec 04 17:23:28 openhab karaf[762]:         at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) [org.eclipse.osgi-3.12.100.jar:?]
Dec 04 17:23:28 openhab karaf[762]:         at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) [org.eclipse.osgi-3.12.100.jar:?]
Dec 04 17:23:28 openhab karaf[762]:         at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.12.100.jar:?]
Dec 04 17:23:28 openhab karaf[762]:         at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi-3.12.100.jar:?]
Dec 04 17:23:28 openhab karaf[762]:         at org.eclipse.osgi.fraWarning: The unit file, source configuration file or drop-ins of openhab2.service changed on disk. Run 'systemctl daemon-reload' to rel
mework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [org.eclipse.osgi-3.12.100.jar:?]
Dec 04 17:25:16 openhab systemd[1]: Started openHAB2 instance, reachable at http://openhab:8080.

Status says website is up and running. However, it isn’t reachable. Any ideas?

Platform information:
- Hardware: Raspberry 3B+
- openHAB version: 2.5.10-1

EDIT: This is my openhab.log. A lot of starting and stopping:

2020-12-04 12:58:30.923 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 12:58:30.978 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 12:58:32.974 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-04 12:59:38.810 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-12-04 12:59:39.187 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 12:59:39.189 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 13:02:18.138 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-12-04 13:02:18.471 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 13:02:18.473 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 13:02:19.582 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-12-04 13:03:23.673 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-04 13:03:26.193 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 13:03:26.200 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 13:07:49.394 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-04 13:07:53.143 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 13:07:53.153 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 15:14:39.454 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-04 15:14:43.094 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 15:14:43.103 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 15:23:30.918 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-12-04 15:47:00.818 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 15:47:00.882 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 15:47:02.890 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-12-04 17:01:23.823 [ERROR] [raf.deployer.features.osgi.Activator] - BundleContext is no longer valid
java.lang.IllegalStateException: BundleContext is no longer valid
	at org.eclipse.osgi.internal.framework.BundleContextImpl.checkValid(BundleContextImpl.java:989) ~[org.eclipse.osgi-3.12.100.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:468) ~[org.eclipse.osgi-3.12.100.jar:?]
	at org.apache.karaf.util.tracker.BaseActivator.register(BaseActivator.java:450) ~[?:?]
	at org.apache.karaf.util.tracker.BaseActivator.register(BaseActivator.java:435) ~[?:?]
	at org.apache.karaf.deployer.features.osgi.Activator.access$300(Activator.java:35) ~[?:?]
	at org.apache.karaf.deployer.features.osgi.Activator$DeploymentFinishedListener.deploymentEvent(Activator.java:87) ~[?:?]
	at org.apache.karaf.features.internal.service.FeaturesServiceImpl.callListeners(FeaturesServiceImpl.java:321) ~[?:?]
	at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:1067) ~[?:?]
	at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1062) ~[?:?]
	at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$13(FeaturesServiceImpl.java:998) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_272]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_272]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_272]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_272]
Dec 04, 2020 5:07:00 PM org.apache.karaf.main.Main launch
INFO: Installing and starting initial bundles
Dec 04, 2020 5:07:02 PM org.apache.karaf.main.Main launch
INFO: All initial bundles installed and set to start
Dec 04, 2020 5:07:02 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /var/lib/openhab2/tmp/lock
Dec 04, 2020 5:07:02 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Dec 04, 2020 5:07:02 PM org.apache.karaf.main.Main$KarafLockCallback lockAcquired
INFO: Lock acquired. Setting startlevel to 100
Dec 04, 2020 5:11:12 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /var/lib/openhab2/tmp/lock
Dec 04, 2020 5:11:12 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Dec 04, 2020 5:11:12 PM org.apache.karaf.main.Main$KarafLockCallback lockAcquired
INFO: Lock acquired. Setting startlevel to 100
Dec 04, 2020 5:23:25 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /var/lib/openhab2/tmp/lock
Dec 04, 2020 5:23:25 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Dec 04, 2020 5:23:25 PM org.apache.karaf.main.Main$KarafLockCallback lockAcquired
INFO: Lock acquired. Setting startlevel to 100

rlkoshak · December 4, 2020, 5:03pm

Please How to use code fences.

What’s in openhab.log?

maxheartrate · December 4, 2020, 5:07pm

I just added openhab.log to my original post. Probably at the same moment you replied. Here’s the content of openhab.log:

2020-12-04 12:58:30.978 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 12:58:32.974 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-04 12:59:38.810 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-12-04 12:59:39.187 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 12:59:39.189 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 13:02:18.138 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-12-04 13:02:18.471 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 13:02:18.473 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 13:02:19.582 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-12-04 13:03:23.673 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-04 13:03:26.193 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 13:03:26.200 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 13:07:49.394 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-04 13:07:53.143 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 13:07:53.153 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 15:14:39.454 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-04 15:14:43.094 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 15:14:43.103 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 15:23:30.918 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-12-04 15:47:00.818 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.77:8080
2020-12-04 15:47:00.882 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.77:8443
2020-12-04 15:47:02.890 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-12-04 17:01:23.823 [ERROR] [raf.deployer.features.osgi.Activator] - BundleContext is no longer valid
java.lang.IllegalStateException: BundleContext is no longer valid
	at org.eclipse.osgi.internal.framework.BundleContextImpl.checkValid(BundleContextImpl.java:989) ~[org.eclipse.osgi-3.12.100.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:468) ~[org.eclipse.osgi-3.12.100.jar:?]
	at org.apache.karaf.util.tracker.BaseActivator.register(BaseActivator.java:450) ~[?:?]
	at org.apache.karaf.util.tracker.BaseActivator.register(BaseActivator.java:435) ~[?:?]
	at org.apache.karaf.deployer.features.osgi.Activator.access$300(Activator.java:35) ~[?:?]
	at org.apache.karaf.deployer.features.osgi.Activator$DeploymentFinishedListener.deploymentEvent(Activator.java:87) ~[?:?]
	at org.apache.karaf.features.internal.service.FeaturesServiceImpl.callListeners(FeaturesServiceImpl.java:321) ~[?:?]
	at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:1067) ~[?:?]
	at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1062) ~[?:?]
	at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$13(FeaturesServiceImpl.java:998) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_272]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_272]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_272]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_272]
Dec 04, 2020 5:07:00 PM org.apache.karaf.main.Main launch
INFO: Installing and starting initial bundles
Dec 04, 2020 5:07:02 PM org.apache.karaf.main.Main launch
INFO: All initial bundles installed and set to start
Dec 04, 2020 5:07:02 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /var/lib/openhab2/tmp/lock
Dec 04, 2020 5:07:02 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Dec 04, 2020 5:07:02 PM org.apache.karaf.main.Main$KarafLockCallback lockAcquired
INFO: Lock acquired. Setting startlevel to 100
Dec 04, 2020 5:11:12 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /var/lib/openhab2/tmp/lock
Dec 04, 2020 5:11:12 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Dec 04, 2020 5:11:12 PM org.apache.karaf.main.Main$KarafLockCallback lockAcquired
INFO: Lock acquired. Setting startlevel to 100
Dec 04, 2020 5:23:25 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /var/lib/openhab2/tmp/lock
Dec 04, 2020 5:23:25 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Dec 04, 2020 5:23:25 PM org.apache.karaf.main.Main$KarafLockCallback lockAcquired
INFO: Lock acquired. Setting startlevel to 100

rlkoshak · December 4, 2020, 5:08pm

Please use code fences.

maxheartrate · December 4, 2020, 5:13pm

I was using the CODE and /CODE at beginning and end. However, the formatting was awkward. I reformatted it using the three `. This looks better now.

rlkoshak · December 4, 2020, 5:16pm

To my knowledge that doesn’t work the same. It will use unispaced font but not preserve whitespace and provide scroll bars.

maxheartrate · December 4, 2020, 5:17pm

I edited my posts. Now they look better.

rlkoshak · December 4, 2020, 5:19pm

I don’t see anything I recognize in there that might indicate a problem. It’s odd that ti had to acquire the lock so many times. I would try clearing the cache and see if that changes anything.

maxheartrate · December 4, 2020, 5:26pm

I cleaned the cache and restartet openhab2 service. I can access the log viewer on port 9001 but my configuration is not loaded. Normally I would see my things and items initializing but the log stays empty and the web server is not reachable.

This is the new openhab.log section:

Dec 04, 2020 6:20:58 PM org.apache.karaf.main.Main launch
INFO: Installing and starting initial bundles
Dec 04, 2020 6:20:59 PM org.apache.karaf.main.Main launch
INFO: All initial bundles installed and set to start
Dec 04, 2020 6:21:00 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /var/lib/openhab2/tmp/lock
Dec 04, 2020 6:21:00 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Dec 04, 2020 6:21:00 PM org.apache.karaf.main.Main$KarafLockCallback lockAcquired
INFO: Lock acquired. Setting startlevel to 100

Wolfgang_S · December 4, 2020, 6:07pm

If you haven’t done yet check if

sudo openhab-cli reset-ownership

fixes the problem.
It could be that your files that you copied back have wrong permissions.

rlkoshak · December 4, 2020, 6:08pm

How long are you waiting. After clearing the cache OH needs to dowload all the add-ons and install them again which can take a bit of time.

I doubt it only took one second.

Have you actually looked in /etc/openhab2 and /var/lib/openhab2 to see if your config was in fact restored and restored correctly?

maxheartrate · December 4, 2020, 6:25pm

Thank you for your suggestions, @Wolfgang_S and @rlkoshak.

I reset the ownership but so far nothing changed. And I’ve been waiting for about an hour since I cleaned the cache. But Openhab does not seem to download anything. I checked the directories and it looks like all relevant files have been restored. My things, items and rules have been placed in their folders. As for /var/lib/openhab2 I cannot really tell a difference to check whether this is my configuration.

rlkoshak · December 4, 2020, 6:31pm

Look in the config folder. At a minimum look in addons.cfg and see if those settings look correct. If you’ve done anything through the UI look in the jsondb folder too.

With the information we have right now there really isn’t anything concrete we can offer. OH is starting so there isn’t a problem with Java. But it’s not reporting any errors in it’s log.

There is that part of an exception reported by systemctl. Look in the syslog or journalctl to get to the top of that stack trace. Maybe that will tell us something useful.

maxheartrate · December 4, 2020, 7:08pm

My addons.cfg does not look correct. Rather blank:

# The installation package of this openHAB instance
# Note: This is only regarded at the VERY FIRST START of openHAB
# Note: If you want to specify your add-ons yourself through entries below, set the package to "minimal"
# as otherwise your definition might be in conflict with what the installation package defines.
#
# Optional. If not set, the dashboard (https://<yourserver>:8080/) will ask you to choose a package.
#
# 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 https://www.openhab.org/docs/configuration/packages.html for a detailed explanation of these packages.
#
#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. "binding = sonos,knx,zwave")
#binding = 

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

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

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

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

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

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

This is a part of my sysylog:

ec  4 19:12:10 openhab systemd[1]: Starting User Runtime Directory /run/user/1000...
Dec  4 19:12:10 openhab systemd[1]: Started User Runtime Directory /run/user/1000.
Dec  4 19:12:10 openhab systemd[1]: Starting User Manager for UID 1000...
Dec  4 19:12:11 openhab systemd[968]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Dec  4 19:12:11 openhab systemd[968]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Dec  4 19:12:11 openhab systemd[968]: Listening on GnuPG network certificate management daemon.
Dec  4 19:12:11 openhab systemd[968]: Listening on GnuPG cryptographic agent and passphrase cache.
Dec  4 19:12:11 openhab systemd[968]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Dec  4 19:12:11 openhab systemd[968]: Reached target Sockets.
Dec  4 19:12:11 openhab systemd[968]: Reached target Timers.
Dec  4 19:12:11 openhab systemd[968]: Reached target Paths.
Dec  4 19:12:11 openhab systemd[968]: Reached target Basic System.
Dec  4 19:12:11 openhab systemd[968]: Reached target Default.
Dec  4 19:12:11 openhab systemd[968]: Startup finished in 477ms.
Dec  4 19:12:11 openhab systemd[1]: Started User Manager for UID 1000.
Dec  4 19:12:11 openhab systemd[1]: Started Session 1 of user openhabian.
Dec  4 19:13:15 openhab systemd[1]: openhab2.service: Control process exited, code=killed, status=15/TERM
Dec  4 19:13:15 openhab systemd[1]: openhab2.service: Succeeded.
Dec  4 19:13:15 openhab systemd[1]: Stopped openHAB2 instance, reachable at http://openhab:8080.
Dec  4 19:13:15 openhab systemd[1]: Starting openHAB2 instance, reachable at http://openhab:8080...
Dec  4 19:13:24 openhab karaf[1420]: 19:13:24.285 [Start Level: Equinox Container: c09b9459-aa68-4138-bad7-a6d9bc865690] ERROR org.apache.felix.configadmin - Failure setting up dynamic configuration bindings
Dec  4 19:13:24 openhab karaf[1420]: java.io.IOException: Unexpected token 78; expected: 61 (line=5, pos=76)
Dec  4 19:13:24 openhab karaf[1420]: #011at org.apache.felix.cm.file.ConfigurationHandler.readFailure(ConfigurationHandler.java:700) ~[bundleFile:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.apache.felix.cm.file.ConfigurationHandler.readInternal(ConfigurationHandler.java:304) ~[bundleFile:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.apache.felix.cm.file.ConfigurationHandler.read(ConfigurationHandler.java:267) ~[bundleFile:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.apache.felix.cm.file.FilePersistenceManager._load(FilePersistenceManager.java:651) ~[bundleFile:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.apache.felix.cm.file.FilePersistenceManager.load(FilePersistenceManager.java:592) ~[bundleFile:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.apache.felix.cm.impl.DynamicBindings.<init>(DynamicBindings.java:53) ~[bundleFile:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.apache.felix.cm.impl.ConfigurationManager.<init>(ConfigurationManager.java:158) ~[bundleFile:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.apache.felix.cm.impl.ConfigurationAdminStarter.activate(ConfigurationAdminStarter.java:74) [bundleFile:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.apache.felix.cm.impl.DependencyTracker.<init>(DependencyTracker.java:99) [bundleFile:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.apache.felix.cm.impl.Activator.start(Activator.java:114) [bundleFile:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:779) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at java.security.AccessController.doPrivileged(Native Method) [?:1.8.0_272]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:772) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:729) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:933) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:309) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.container.Module.doStart(Module.java:581) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.container.Module.start(Module.java:449) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:13:24 openhab karaf[1420]: #011at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:15:01 openhab CRON[1548]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec  4 19:15:15 openhab systemd[1]: Started openHAB2 instance, reachable at http://openhab:8080.
Dec  4 19:15:15 openhab systemd[1]: Started Frontail openHAB instance, reachable at http://openhab:9001.
Dec  4 19:15:15 openhab systemd[1]: Reached target Multi-User System.
Dec  4 19:15:15 openhab systemd[1]: Starting Update UTMP about System Runlevel Changes...
Dec  4 19:15:15 openhab systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
Dec  4 19:15:15 openhab systemd[1]: Started Update UTMP about System Runlevel Changes.
Dec  4 19:15:15 openhab systemd[1]: Startup finished in 3.486s (kernel) + 4min 15.880s (userspace) = 4min 19.367s.
Dec  4 19:16:48 openhab dhcpcd[667]: eth0: Router Advertisement from fe80::ca0e:14ff:febd:41b0
Dec  4 19:16:48 openhab systemd[1]: Stopping Network Time Synchronization...
Dec  4 19:16:48 openhab systemd[1]: systemd-timesyncd.service: Succeeded.
Dec  4 19:16:48 openhab systemd[1]: Stopped Network Time Synchronization.
Dec  4 19:16:48 openhab systemd[1]: Starting Network Time Synchronization...
Dec  4 19:16:48 openhab systemd[1]: Started Network Time Synchronization.
Dec  4 19:16:48 openhab systemd-timesyncd[1615]: Synchronized to time server for the first time 159.69.150.81:123 (0.debian.pool.ntp.org).
Dec  4 19:16:49 openhab systemd[1]: Stopping Network Time Synchronization...
Dec  4 19:16:49 openhab systemd[1]: systemd-timesyncd.service: Succeeded.
Dec  4 19:16:49 openhab systemd[1]: Stopped Network Time Synchronization.
Dec  4 19:16:49 openhab systemd[1]: Starting Network Time Synchronization...
Dec  4 19:16:49 openhab systemd[1]: Started Network Time Synchronization.
Dec  4 19:16:49 openhab systemd-timesyncd[1635]: Synchronized to time server for the first time 159.69.150.81:123 (0.debian.pool.ntp.org).
Dec  4 19:17:01 openhab CRON[1639]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec  4 19:17:03 openhab systemd[1]: Reloading.
Dec  4 19:17:03 openhab systemd[1]: /lib/systemd/system/nmbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/nmbd.pid → /run/samba/nmbd.pid; please update the unit file accordingly.
Dec  4 19:17:04 openhab systemd[1]: getty@tty1.service: Current command vanished from the unit file, execution of the command list won't be resumed.
Dec  4 19:18:55 openhab systemd[1]: Stopped target Sound Card.
Dec  4 19:18:55 openhab systemd[1]: Condition check resulted in Turns off Raspberry Pi display backlight on shutdown/reboot being skipped.
Dec  4 19:18:55 openhab systemd[1]: Stopped target Timers.
Dec  4 19:18:55 openhab systemd[1]: logrotate.timer: Succeeded.
Dec  4 19:18:55 openhab systemd[1]: Stopped Daily rotation of log files.
Dec  4 19:18:55 openhab systemd[1]: systemd-tmpfiles-clean.timer: Succeeded.
Dec  4 19:18:55 openhab systemd[1]: Stopped Daily Cleanup of Temporary Directories.
Dec  4 19:18:55 openhab systemd[1]: Unmounting RPC Pipe File System...
Dec  4 19:18:55 openhab systemd[1]: Stopping Authorization Manager...
Dec  4 19:18:55 openhab systemd[1]: Stopping Session 1 of user openhabian.
Dec  4 19:18:55 openhab systemd[1]: Removed slice system-bthelper.slice.
Dec  4 19:18:55 openhab systemd[1]: Stopped target Multi-User System.
Dec  4 19:18:55 openhab systemd[1]: Stopped target Login Prompts.
Dec  4 19:18:55 openhab systemd[1]: Stopping Samba SMB Daemon...
Dec  4 19:18:55 openhab systemd[1]: Stopping dphys-swapfile - set up, mount/unmount, and delete a swap file...
Dec  4 19:18:55 openhab systemd[1]: Stopping Frontail openHAB instance, reachable at http://openhab:9001...
Dec  4 19:18:55 openhab systemd[1]: sysstat.service: Succeeded.
Dec  4 19:18:55 openhab systemd[1]: Stopped Resets System Activity Data Collector.
Dec  4 19:18:55 openhab systemd[968]: run-rpc_pipefs.mount: Succeeded.
Dec  4 19:19:49 openhab systemd[1]: Stopping System Logging Service...
Dec  4 19:19:49 openhab rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="366" x-info="https://www.rsyslog.com"] exiting on signal 15.
Dec  4 19:19:49 openhab systemd[1]: rsyslog.service: Succeeded.
Dec  4 19:19:49 openhab systemd[1]: Stopped System Logging Service.
Dec  4 19:19:49 openhab systemd[1]: Started Samba NMB Daemon.
Dec  4 19:19:49 openhab systemd[1]: Starting System Logging Service...
Dec  4 19:19:49 openhab zram-config[857]: + createZdir
Dec  4 19:19:49 openhab zram-config[857]: + local dirPerm
Dec  4 19:19:49 openhab zram-config[857]: + local dirUser
Dec  4 19:19:49 openhab zram-config[857]: + local dirGroup
Dec  4 19:19:49 openhab zram-config[857]: + local dirMountOpt
Dec  4 19:19:49 openhab zram-config[857]: + local dirFSType
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n /log.bind ]]
Dec  4 19:19:49 openhab zram-config[857]: + mkdir -p /opt/zram/log.bind
Dec  4 19:19:49 openhab rsyslogd: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.1901.0]
Dec  4 19:19:49 openhab rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="874" x-info="https://www.rsyslog.com"] start
Dec  4 19:19:49 openhab systemd[1]: Started System Logging Service.
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n /var/log ]]
Dec  4 19:19:49 openhab zram-config[857]: ++ stat -c %a /var/log
Dec  4 19:19:49 openhab zram-config[857]: + dirPerm=755
Dec  4 19:19:49 openhab zram-config[857]: ++ stat -c %u /var/log
Dec  4 19:19:49 openhab zram-config[857]: + dirUser=0
Dec  4 19:19:49 openhab zram-config[857]: ++ stat -c %g /var/log
Dec  4 19:19:49 openhab zram-config[857]: + dirGroup=0
Dec  4 19:19:49 openhab zram-config[857]: + echo 'dirPerm /var/log 755 0:0'
Dec  4 19:19:49 openhab zram-config[857]: + mount --verbose --bind /var/log/ /opt/zram/log.bind/
Dec  4 19:19:49 openhab zram-config[857]: + mount --verbose --make-private /opt/zram/log.bind/
Dec  4 19:19:49 openhab zram-config[857]: ++ head -1
Dec  4 19:19:49 openhab zram-config[857]: ++ awk -v a=/opt/zram/log.bind '$2 == a {print $4}' /proc/mounts
Dec  4 19:19:49 openhab zram-config[857]: + dirMountOpt=rw,noatime
Dec  4 19:19:49 openhab zram-config[857]: ++ awk -v a=/opt/zram/log.bind '$2 == a {print $3}' /proc/mounts
Dec  4 19:19:49 openhab zram-config[857]: ++ head -1
Dec  4 19:19:49 openhab zram-config[857]: + dirFSType=ext4
Dec  4 19:19:49 openhab zram-config[857]: + echo 'dirMountOpt: rw,noatime; dirFsType: ext4'
Dec  4 19:19:49 openhab zram-config[857]: + createZdevice
Dec  4 19:19:49 openhab zram-config[857]: + [[ -d /sys/class/zram-control ]]
Dec  4 19:19:49 openhab zram-config[857]: ++ cat /sys/class/zram-control/hot_add
Dec  4 19:19:49 openhab zram-config[857]: + RAM_DEV=1
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n 150M ]]
Dec  4 19:19:49 openhab zram-config[857]: + echo 150M
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n 500M ]]
Dec  4 19:19:49 openhab zram-config[857]: + echo 500M
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n lzo ]]
Dec  4 19:19:49 openhab zram-config[857]: + echo lzo
Dec  4 19:19:49 openhab kernel: [   24.536927] zram: Added device: zram1
Dec  4 19:19:49 openhab kernel: [   24.543862] zram1: detected capacity change from 0 to 524288000
Dec  4 19:19:49 openhab zram-config[857]: /usr/local/sbin/zram-config: line 30: echo: write error: Device or resource busy
Dec  4 19:19:49 openhab zram-config[857]: + echo 'zram1 created comp_algorithm=lzo mem_limit=150M disksize=500M'
Dec  4 19:19:49 openhab zram-config[857]: + mke2fs -v -t ext4 /dev/zram1
Dec  4 19:19:49 openhab kernel: [   24.546465] zram: Can't change algorithm for initialized device
Dec  4 19:19:49 openhab zram-config[857]: + mkdir -p /opt/zram/zram1
Dec  4 19:19:49 openhab zram-config[857]: + mount --verbose --types ext4 -o rw,noatime /dev/zram1 /opt/zram/zram1/
Dec  4 19:19:49 openhab zram-config[857]: + mkdir -p /opt/zram/zram1/upper /opt/zram/zram1/workdir /var/log
Dec  4 19:19:49 openhab kernel: [   24.846336] EXT4-fs (zram1): mounted filesystem with ordered data mode. Opts: (null)
Dec  4 19:19:49 openhab kernel: [   24.846389] ext4 filesystem being mounted at /opt/zram/zram1 supports timestamps until 2038 (0x7fffffff)
Dec  4 19:19:49 openhab zram-config[857]: + mount --verbose --types overlay -o redirect_dir=on,lowerdir=/opt/zram/log.bind,upperdir=/opt/zram/zram1/upper,workdir=/opt/zram/zram1/workdir overlay1 /var/log
Dec  4 19:19:49 openhab zram-config[857]: + chown 0:0 /opt/zram/zram1/upper /opt/zram/zram1/workdir /var/log
Dec  4 19:19:49 openhab zram-config[857]: + chmod 755 /opt/zram/zram1/upper /opt/zram/zram1/workdir /var/log
Dec  4 19:19:49 openhab zram-config[857]: + echo 'log#011#011/zram1#011#011/var/log#011#011/log.bind'
Dec  4 19:19:49 openhab zram-config[857]: + systemctl restart rsyslog.service
Dec  4 19:19:49 openhab rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="874" x-info="https://www.rsyslog.com"] exiting on signal 15.
Dec  4 19:19:49 openhab systemd[1]: Stopping System Logging Service...
Dec  4 19:19:49 openhab systemd[1]: rsyslog.service: Succeeded.
Dec  4 19:19:49 openhab systemd[1]: Stopped System Logging Service.
Dec  4 19:19:49 openhab NetworkManager[394]: <warn>  [1607105989.6715] device (wlan0): re-acquiring supplicant interface (#1).
Dec  4 19:19:49 openhab systemd[1]: Starting System Logging Service...
Dec  4 19:19:49 openhab rsyslogd: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.1901.0]
Dec  4 19:19:49 openhab rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="904" x-info="https://www.rsyslog.com"] start
Dec  4 19:19:49 openhab systemd[1]: Started System Logging Service.
Dec  4 19:19:49 openhab zram-config[857]: ++ dpkg -s nginx
Dec  4 19:19:49 openhab zram-config[857]: dpkg-query: package 'nginx' is not installed and no information is available
Dec  4 19:19:49 openhab zram-config[857]: Use dpkg --info (= dpkg-deb --info) to examine archive files.
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n '' ]]
Dec  4 19:19:49 openhab zram-config[857]: + journalctl --flush
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n '' ]]
Dec  4 19:19:49 openhab zram-config[857]: + echo 'createZlog: no oldlog directory provided in ztab'
Dec  4 19:19:49 openhab zram-config[857]: + read -r line
Dec  4 19:19:49 openhab zram-config[857]: + case "$line" in
Dec  4 19:19:49 openhab zram-config[857]: + continue
Dec  4 19:19:49 openhab zram-config[857]: + read -r line
Dec  4 19:19:49 openhab zram-config[857]: + case "$line" in
Dec  4 19:19:49 openhab zram-config[857]: + continue
Dec  4 19:19:49 openhab zram-config[857]: + read -r line
Dec  4 19:19:49 openhab zram-config[857]: + case "$line" in
Dec  4 19:19:49 openhab zram-config[857]: + set -- dir lz4 150M 500M /var/lib/openhab2/persistence /persistence.bind
Dec  4 19:19:49 openhab zram-config[857]: + echo 'ztab create dir lz4 150M 500M /var/lib/openhab2/persistence /persistence.bind   '
Dec  4 19:19:49 openhab zram-config[857]: + ZTAB_EMPTY=false
Dec  4 19:19:49 openhab zram-config[857]: + ZTYPE=dir
Dec  4 19:19:49 openhab zram-config[857]: + ALG=lz4
Dec  4 19:19:49 openhab zram-config[857]: + MEM_SIZE=150M
Dec  4 19:19:49 openhab zram-config[857]: + DISK_SIZE=500M
Dec  4 19:19:49 openhab zram-config[857]: + [[ -f /tmp/zram-device-list ]]
Dec  4 19:19:49 openhab zram-config[857]: + [[ dir == \s\w\a\p ]]
Dec  4 19:19:49 openhab zram-config[857]: ++ grep 'dir.*/var/lib/openhab2/persistence' /tmp/zram-device-list
Dec  4 19:19:49 openhab zram-config[857]: + entry=
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n '' ]]
Dec  4 19:19:49 openhab zram-config[857]: + test -f /tmp/zram-device-list.new
Dec  4 19:19:49 openhab zram-config[857]: + case "$1" in
Dec  4 19:19:49 openhab zram-config[857]: + TARGET_DIR=/var/lib/openhab2/persistence
Dec  4 19:19:49 openhab zram-config[857]: + BIND_DIR=/persistence.bind
Dec  4 19:19:49 openhab zram-config[857]: + [[ false == \f\a\l\s\e ]]
Dec  4 19:19:49 openhab zram-config[857]: + createZdir
Dec  4 19:19:49 openhab zram-config[857]: + local dirPerm
Dec  4 19:19:49 openhab zram-config[857]: + local dirUser
Dec  4 19:19:49 openhab zram-config[857]: + local dirGroup
Dec  4 19:19:49 openhab zram-config[857]: + local dirMountOpt
Dec  4 19:19:49 openhab zram-config[857]: + local dirFSType
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n /persistence.bind ]]
Dec  4 19:19:49 openhab zram-config[857]: + mkdir -p /opt/zram/persistence.bind
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n /var/lib/openhab2/persistence ]]
Dec  4 19:19:49 openhab zram-config[857]: ++ stat -c %a /var/lib/openhab2/persistence
Dec  4 19:19:49 openhab zram-config[857]: + dirPerm=755
Dec  4 19:19:49 openhab zram-config[857]: ++ stat -c %u /var/lib/openhab2/persistence
Dec  4 19:19:49 openhab zram-config[857]: + dirUser=111
Dec  4 19:19:49 openhab zram-config[857]: ++ stat -c %g /var/lib/openhab2/persistence
Dec  4 19:19:49 openhab zram-config[857]: + dirGroup=115
Dec  4 19:19:49 openhab zram-config[857]: + echo 'dirPerm /var/lib/openhab2/persistence 755 111:115'
Dec  4 19:19:49 openhab zram-config[857]: + mount --verbose --bind /var/lib/openhab2/persistence/ /opt/zram/persistence.bind/
Dec  4 19:19:49 openhab wpa_supplicant[395]: ctrl_iface exists and seems to be in use - cannot override it
Dec  4 19:19:49 openhab wpa_supplicant[395]: Delete '/run/wpa_supplicant/wlan0' manually if it is not used anymore
Dec  4 19:19:49 openhab zram-config[857]: + mount --verbose --make-private /opt/zram/persistence.bind/
Dec  4 19:19:49 openhab wpa_supplicant[395]: Failed to initialize control interface '/run/wpa_supplicant'.#012You may have another wpa_supplicant process already running or the file was#012left by an unclean termination of wpa_supplicant in which case you will need#012to manually remove this file before starting wpa_supplicant again.
Dec  4 19:19:49 openhab zram-config[857]: ++ awk -v a=/opt/zram/persistence.bind '$2 == a {print $4}' /proc/mounts
Dec  4 19:19:49 openhab zram-config[857]: ++ head -1
Dec  4 19:19:49 openhab zram-config[857]: + dirMountOpt=rw,noatime
Dec  4 19:19:49 openhab zram-config[857]: ++ awk -v a=/opt/zram/persistence.bind '$2 == a {print $3}' /proc/mounts
Dec  4 19:19:49 openhab zram-config[857]: ++ head -1
Dec  4 19:19:49 openhab zram-config[857]: + dirFSType=ext4
Dec  4 19:19:49 openhab zram-config[857]: + echo 'dirMountOpt: rw,noatime; dirFsType: ext4'
Dec  4 19:19:49 openhab zram-config[857]: + createZdevice
Dec  4 19:19:49 openhab zram-config[857]: + [[ -d /sys/class/zram-control ]]
Dec  4 19:19:49 openhab zram-config[857]: ++ cat /sys/class/zram-control/hot_add
Dec  4 19:19:49 openhab zram-config[857]: + RAM_DEV=2
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n 150M ]]
Dec  4 19:19:49 openhab zram-config[857]: + echo 150M
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n 500M ]]
Dec  4 19:19:49 openhab zram-config[857]: + echo 500M
Dec  4 19:19:50 openhab kernel: [   25.326386] zram: Added device: zram2
Dec  4 19:19:50 openhab kernel: [   25.330390] zram2: detected capacity change from 0 to 524288000
Dec  4 19:19:50 openhab kernel: [   25.331013] zram: Can't change algorithm for initialized device
Dec  4 19:19:49 openhab zram-config[857]: + [[ -n lz4 ]]
Dec  4 19:19:49 openhab zram-config[857]: + echo lz4
Dec  4 19:19:49 openhab zram-config[857]: /usr/local/sbin/zram-config: line 30: echo: write error: Device or resource busy
Dec  4 19:19:49 openhab zram-config[857]: + echo 'zram2 created comp_algorithm=lz4 mem_limit=150M disksize=500M'
Dec  4 19:19:49 openhab zram-config[857]: + mke2fs -v -t ext4 /dev/zram2
Dec  4 19:19:50 openhab wpa_supplicant[395]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Dec  4 19:19:50 openhab NetworkManager[394]: <error> [1607105990.2024] sup-iface[0x74bc88,wlan0]: error adding interface: wpa_supplicant couldn't grab this interface.
Dec  4 19:19:50 openhab NetworkManager[394]: <info>  [1607105990.2026] device (wlan0): supplicant interface state: starting -> down
Dec  4 19:19:50 openhab zram-config[857]: + mkdir -p /opt/zram/zram2
Dec  4 19:19:50 openhab zram-config[857]: + mount --verbose --types ext4 -o rw,noatime /dev/zram2 /opt/zram/zram2/
Dec  4 19:19:50 openhab kernel: [   25.623343] EXT4-fs (zram2): mounted filesystem with ordered data mode. Opts: (null)
Dec  4 19:19:50 openhab kernel: [   25.623397] ext4 filesystem being mounted at /opt/zram/zram2 supports timestamps until 2038 (0x7fffffff)
Dec  4 19:19:50 openhab zram-config[857]: + mkdir -p /opt/zram/zram2/upper /opt/zram/zram2/workdir /var/lib/openhab2/persistence
Dec  4 19:19:50 openhab zram-config[857]: + mount --verbose --types overlay -o redirect_dir=on,lowerdir=/opt/zram/persistence.bind,upperdir=/opt/zram/zram2/upper,workdir=/opt/zram/zram2/workdir overlay2 /var/lib/openhab2/persistence
Dec  4 19:19:50 openhab zram-config[857]: + chown 111:115 /opt/zram/zram2/upper /opt/zram/zram2/workdir /var/lib/openhab2/persistence
Dec  4 19:19:50 openhab zram-config[857]: + chmod 755 /opt/zram/zram2/upper /opt/zram/zram2/workdir /var/lib/openhab2/persistence
Dec  4 19:19:50 openhab zram-config[857]: + echo 'dir#011#011/zram2#011#011/var/lib/openhab2/persistence#011#011/persistence.bind'
Dec  4 19:19:50 openhab zram-config[857]: + read -r line
Dec  4 19:19:50 openhab zram-config[857]: + [[ false == \t\r\u\e ]]
Dec  4 19:19:50 openhab systemd[1]: Started zram-config.
Dec  4 19:19:50 openhab systemd[1]: Mounting openhab2-conf mount...
Dec  4 19:19:50 openhab systemd[1]: Mounting openhab2-logs mount...
Dec  4 19:19:50 openhab systemd[1]: Starting openHAB2 instance, reachable at http://openhab:8080...
Dec  4 19:19:50 openhab systemd[1]: Started zramsync.
Dec  4 19:19:50 openhab systemd[1]: Mounting openhab2-userdata mount...
Dec  4 19:19:50 openhab systemd[1]: Mounting openhab2-sys mount...
Dec  4 19:19:50 openhab systemd[1]: Mounting openhab2-addons mount...
Dec  4 19:19:50 openhab systemd[1]: Mounted openhab2-conf mount.
Dec  4 19:19:50 openhab systemd[1]: Mounted openhab2-logs mount.
Dec  4 19:19:50 openhab systemd[1]: Mounted openhab2-userdata mount.
Dec  4 19:19:50 openhab systemd[1]: Mounted openhab2-sys mount.
Dec  4 19:19:50 openhab systemd[1]: Mounted openhab2-addons mount.
Dec  4 19:19:50 openhab systemd[1]: Starting Samba SMB Daemon...
Dec  4 19:19:51 openhab systemd[1]: Started Samba SMB Daemon.
Dec  4 19:19:52 openhab systemd[1]: Stopping Network Time Synchronization...
Dec  4 19:19:52 openhab systemd[1]: systemd-timesyncd.service: Succeeded.
Dec  4 19:19:52 openhab systemd[1]: Stopped Network Time Synchronization.
Dec  4 19:19:52 openhab systemd[1]: Starting Network Time Synchronization...
Dec  4 19:19:53 openhab systemd[1]: Started Network Time Synchronization.
Dec  4 19:19:53 openhab systemd-timesyncd[1100]: Synchronized to time server for the first time 194.25.134.196:123 (0.debian.pool.ntp.org).
Dec  4 19:19:54 openhab systemd[1]: NetworkManager-dispatcher.service: Succeeded.
Dec  4 19:19:58 openhab systemd[1]: Created slice User Slice of UID 1000.
Dec  4 19:19:58 openhab systemd[1]: Starting User Runtime Directory /run/user/1000...
Dec  4 19:19:58 openhab systemd[1]: Started User Runtime Directory /run/user/1000.
Dec  4 19:19:58 openhab systemd[1]: Starting User Manager for UID 1000...
Dec  4 19:19:59 openhab systemd[1129]: Reached target Paths.
Dec  4 19:19:59 openhab systemd[1129]: Listening on GnuPG cryptographic agent and passphrase cache.
Dec  4 19:19:59 openhab systemd[1129]: Reached target Timers.
Dec  4 19:19:59 openhab systemd[1129]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Dec  4 19:19:59 openhab systemd[1129]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Dec  4 19:19:59 openhab systemd[1129]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Dec  4 19:19:59 openhab systemd[1129]: Listening on GnuPG network certificate management daemon.
Dec  4 19:19:59 openhab systemd[1129]: Reached target Sockets.
Dec  4 19:19:59 openhab systemd[1129]: Reached target Basic System.
Dec  4 19:19:59 openhab systemd[1129]: Reached target Default.
Dec  4 19:19:59 openhab systemd[1129]: Startup finished in 498ms.
Dec  4 19:19:59 openhab systemd[1]: Started User Manager for UID 1000.
Dec  4 19:19:59 openhab systemd[1]: Started Session 1 of user openhabian.
Dec  4 19:20:00 openhab NetworkManager[394]: <warn>  [1607106000.6718] device (wlan0): re-acquiring supplicant interface (#2).
Dec  4 19:20:00 openhab wpa_supplicant[395]: ctrl_iface exists and seems to be in use - cannot override it
Dec  4 19:20:00 openhab wpa_supplicant[395]: Delete '/run/wpa_supplicant/wlan0' manually if it is not used anymore
Dec  4 19:20:00 openhab wpa_supplicant[395]: Failed to initialize control interface '/run/wpa_supplicant'.#012You may have another wpa_supplicant process already running or the file was#012left by an unclean termination of wpa_supplicant in which case you will need#012to manually remove this file before starting wpa_supplicant again.
Dec  4 19:20:00 openhab wpa_supplicant[395]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Dec  4 19:20:00 openhab NetworkManager[394]: <error> [1607106000.9534] sup-iface[0x74bcf8,wlan0]: error adding interface: wpa_supplicant couldn't grab this interface.
Dec  4 19:20:00 openhab NetworkManager[394]: <info>  [1607106000.9537] device (wlan0): supplicant interface state: starting -> down
Dec  4 19:20:02 openhab karaf[959]: 19:20:02.192 [Start Level: Equinox Container: 1ce3ffee-02be-4a4f-a5cc-008b0ca033bd] ERROR org.apache.felix.configadmin - Failure setting up dynamic configuration bindings
Dec  4 19:20:02 openhab karaf[959]: java.io.IOException: Unexpected token 78; expected: 61 (line=5, pos=76)
Dec  4 19:20:02 openhab karaf[959]: #011at org.apache.felix.cm.file.ConfigurationHandler.readFailure(ConfigurationHandler.java:700) ~[bundleFile:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.apache.felix.cm.file.ConfigurationHandler.readInternal(ConfigurationHandler.java:304) ~[bundleFile:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.apache.felix.cm.file.ConfigurationHandler.read(ConfigurationHandler.java:267) ~[bundleFile:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.apache.felix.cm.file.FilePersistenceManager._load(FilePersistenceManager.java:651) ~[bundleFile:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.apache.felix.cm.file.FilePersistenceManager.load(FilePersistenceManager.java:592) ~[bundleFile:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.apache.felix.cm.impl.DynamicBindings.<init>(DynamicBindings.java:53) ~[bundleFile:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.apache.felix.cm.impl.ConfigurationManager.<init>(ConfigurationManager.java:158) ~[bundleFile:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.apache.felix.cm.impl.ConfigurationAdminStarter.activate(ConfigurationAdminStarter.java:74) [bundleFile:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.apache.felix.cm.impl.DependencyTracker.<init>(DependencyTracker.java:99) [bundleFile:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.apache.felix.cm.impl.Activator.start(Activator.java:114) [bundleFile:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:779) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at java.security.AccessController.doPrivileged(Native Method) [?:1.8.0_272]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:772) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:729) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:933) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:309) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.container.Module.doStart(Module.java:581) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.container.Module.start(Module.java:449) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:02 openhab karaf[959]: #011at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [org.eclipse.osgi-3.12.100.jar:?]
Dec  4 19:20:04 openhab systemd[1]: systemd-fsckd.service: Succeeded.
Dec  4 19:20:11 openhab NetworkManager[394]: <warn>  [1607106011.6811] device (wlan0): re-acquiring supplicant interface (#3).
Dec  4 19:20:11 openhab wpa_supplicant[395]: ctrl_iface exists and seems to be in use - cannot override it
Dec  4 19:20:11 openhab wpa_supplicant[395]: Delete '/run/wpa_supplicant/wlan0' manually if it is not used anymore
Dec  4 19:20:11 openhab wpa_supplicant[395]: Failed to initialize control interface '/run/wpa_supplicant'.#012You may have another wpa_supplicant process already running or the file was#012left by an unclean termination of wpa_supplicant in which case you will need#012to manually remove this file before starting wpa_supplicant again.
Dec  4 19:20:11 openhab wpa_supplicant[395]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Dec  4 19:20:11 openhab NetworkManager[394]: <error> [1607106011.9529] sup-iface[0x74bc18,wlan0]: error adding interface: wpa_supplicant couldn't grab this interface.
Dec  4 19:20:11 openhab NetworkManager[394]: <info>  [1607106011.9531] device (wlan0): supplicant interface state: starting -> down
Dec  4 19:20:13 openhab systemd[1]: systemd-hostnamed.service: Succeeded.
Dec  4 19:20:22 openhab NetworkManager[394]: <warn>  [1607106022.6793] device (wlan0): re-acquiring supplicant interface (#4).
Dec  4 19:20:22 openhab wpa_supplicant[395]: ctrl_iface exists and seems to be in use - cannot override it
Dec  4 19:20:22 openhab wpa_supplicant[395]: Delete '/run/wpa_supplicant/wlan0' manually if it is not used anymore
Dec  4 19:20:22 openhab wpa_

I can’t find journalctl.

rlkoshak · December 4, 2020, 7:27pm

OK, what about /var/lib/openhab2/config/org/openhab/addons.conf? Is that empty too?

Now that we see the root of that exception shown at startup I think we have something close to a cause of the problems. There is some config file (unfortunately it doesn’t say which one) that is corrupted. OH can’t parse it. It’s likely one of the files in /var/lib/openhab2/etc.

maxheartrate · December 4, 2020, 7:40pm

This is what’s inside openhab.config:

rnal/rngom/parse/xml/SchemaParser$EmptyContentStateEmptyContentState7com/sun/xml/internal/rngom/parse/xml/SchemaParser$State1com/sun/xml/internal/rngom/parse/xml/SchemaParser
access$100k(Lcom/sun/xml/internal/rngom/parse/xml/SchemaParser;)Lcom/sun/xml/internal/rngom/ast/builder/SchemaBuilder;
startLocation,Lcom/sun/xml/internal/rngom/ast/om/Locat

rlkoshak · December 4, 2020, 7:44pm

openhab.conf or addons.conf which is what I asked you look at?

Either way, that doesn’t look like a properly formatted config file so either the restore of that file was corrupted or the file became corrupted after the restore. Look in other conf files and files in /var/lib/openhab2/etc to see if they are similarly corrupted.

maxheartrate · December 4, 2020, 7:48pm

I only have .config files in /var/lib/openhab2/config/org/openhab/. No addons.conf and no openhab.conf:

addons.config  basicui.config  dashboard.config  ephemeris.config  fritzboxtr064.config  habpanel.config  mapdb.config  openhabcloud.config  rrd4j.config  runtime.config  services.config

Do you think it makes sense to try and copy/ overwrite the files manually from the old SD card to the new one?

maxheartrate · December 4, 2020, 7:52pm

The files in openhab2/etc look similarily corrupted.

EDIT: Just checked the old SD card. Looks the same. I wonder why it’s still possible to launch OpenHAB from the old card while the backup & restore won’t work.
Do you see a chance to repair the file system on the old card without losing data? I could try and put the SD card in a USB adapter so that it is not mounted as the boot partition.

rlkoshak · December 4, 2020, 8:09pm

That’s the joy of a worn out SD card. It kind of behaves randomly.

If what you see when you look at the files are corrupted, that is probably what the files actually are. Somehow OH is loading them from where those files used to be on the SD card somehow. But I know of no way to do the same. You can try to mount the file system on another host but I do not have any great expectations that it will work.

I think you’ll probably need to recover what you can from /etc/openhab2 and rebuild anything you’ve done through the UI manually on the new system, assuming that all your files in /etc/openhab2 are OK and uncorrupted.