openHAB 3 - Windows Install - Missing Log Files

msexton187 · December 22, 2020, 6:00am

I’ve done a fresh install of openHAB 3 on my Windows machine, and wrapper.log is the only log file currently being created. None of the other log files are exist in the logs folder. I’ve restarted the service and machine several times, and still no logs. Odd thing is the other log files were created when I initially ran start.bat, but after I setup the Windows service I deleted all the log files and rebooted`. Upon reboot openHAB worked as expected except the logs aren’t being created. I’m at a loss on how to debug this without access to the logs. I’ll continue to tinker, but any help is appreciated.

Marty

Platform information:
- Hardware: Intel 64bit
- OS: Windows 10
- Java Runtime Environment: Zulu 11
- openHAB version: 3.0.0

ganymed · December 22, 2020, 8:04am

Same here on my windows machine, the only log file is the wrapper.log when I start openHAB through the windows service:

STATUS | wrapper  | 2020/12/21 22:54:37 | --> Wrapper Started as Service
STATUS | wrapper  | 2020/12/21 22:54:37 | Launching a JVM...
INFO   | jvm 1    | 2020/12/21 22:54:38 | Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org
INFO   | jvm 1    | 2020/12/21 22:54:38 |   Copyright 1999-2006 Tanuki Software, Inc.  All Rights Reserved.
INFO   | jvm 1    | 2020/12/21 22:54:38 | 
INFO   | jvm 1    | 2020/12/21 22:54:38 | WARNING: An illegal reflective access operation has occurred
INFO   | jvm 1    | 2020/12/21 22:54:38 | WARNING: Illegal reflective access by org.eclipse.osgi.storage.FrameworkExtensionInstaller (file:/C:/openhab/runtime/system/org/eclipse/platform/org.eclipse.osgi/3.12.100/org.eclipse.osgi-3.12.100.jar) to method java.net.URLClassLoader.addURL(java.net.URL)
INFO   | jvm 1    | 2020/12/21 22:54:38 | WARNING: Please consider reporting this to the maintainers of org.eclipse.osgi.storage.FrameworkExtensionInstaller
INFO   | jvm 1    | 2020/12/21 22:54:38 | WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
INFO   | jvm 1    | 2020/12/21 22:54:38 | WARNING: All illegal access operations will be denied in a future release
INFO   | jvm 1    | 2020/12/21 22:54:39 | Dez. 21, 2020 10:54:39 NACHM. org.apache.karaf.main.lock.SimpleFileLock lock
INFO   | jvm 1    | 2020/12/21 22:54:39 | INFORMATION: Trying to lock C:\openhab\userdata\tmp\lock
INFO   | jvm 1    | 2020/12/21 22:54:39 | Dez. 21, 2020 10:54:39 NACHM. org.apache.karaf.main.lock.SimpleFileLock lock
INFO   | jvm 1    | 2020/12/21 22:54:39 | INFORMATION: Lock acquired
INFO   | jvm 1    | 2020/12/21 22:54:39 | Dez. 21, 2020 10:54:39 NACHM. org.apache.karaf.main.Main$KarafLockCallback lockAcquired
INFO   | jvm 1    | 2020/12/21 22:54:39 | INFORMATION: Lock acquired. Setting startlevel to 100
INFO   | jvm 1    | 2020/12/21 22:54:39 | Dez. 21, 2020 10:54:39 NACHM. org.apache.karaf.main.ShutdownSocketThread run
INFO   | jvm 1    | 2020/12/21 22:54:39 | INFORMATION: Shutdown socket thread is listening on 127.0.0.1:52936
INFO   | jvm 1    | 2020/12/21 22:54:44 | Warning: Nashorn engine is planned to be removed from a future JDK release

Bruce_Osborne · December 22, 2020, 9:53am

Was this an upgrade? All references to eclipse have been removed from OH3.it appears that some OH2 parts are still installed.

ganymed · December 22, 2020, 10:57am

Yes, I made an upgrade from OH 2.5.10

msexton187 · December 22, 2020, 1:22pm

I did a fresh install.

Bruce_Osborne · December 22, 2020, 1:23pm

Sorry, I have not installed on Windows.

msexton187 · December 22, 2020, 2:00pm

Per the wrapper log it seems like openHAB can’t create the log files when booting from the service. My home directory is named properly and pointed to the right location. As I mentioned yesterday, it works fine when booting from start.bat.

These two lines may indicate the problem:

INFO   | jvm 1    | 2020/12/22 07:51:10 | org.ops4j.pax.logging.pax-logging-api [log4j2] ERROR : Unable to create file ${sys:openhab.logdir}/openhab.log Ignored FQCN: org.apache.logging.log4j.spi.AbstractLogger
INFO   | jvm 1    | 2020/12/22 07:51:10 | java.io.IOException: The filename, directory name, or volume label syntax is incorrect

Full Log:

STATUS | wrapper  | 2020/12/22 07:51:08 | --> Wrapper Started as Service
STATUS | wrapper  | 2020/12/22 07:51:08 | Launching a JVM...
INFO   | jvm 1    | 2020/12/22 07:51:09 | Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org
INFO   | jvm 1    | 2020/12/22 07:51:09 |   Copyright 1999-2006 Tanuki Software, Inc.  All Rights Reserved.
INFO   | jvm 1    | 2020/12/22 07:51:09 | 
INFO   | jvm 1    | 2020/12/22 07:51:09 | WARNING: An illegal reflective access operation has occurred
INFO   | jvm 1    | 2020/12/22 07:51:09 | WARNING: Illegal reflective access by org.eclipse.osgi.storage.FrameworkExtensionInstaller (file:/C:/openhab/runtime/system/org/eclipse/platform/org.eclipse.osgi/3.12.100/org.eclipse.osgi-3.12.100.jar) to method java.net.URLClassLoader.addURL(java.net.URL)
INFO   | jvm 1    | 2020/12/22 07:51:09 | WARNING: Please consider reporting this to the maintainers of org.eclipse.osgi.storage.FrameworkExtensionInstaller
INFO   | jvm 1    | 2020/12/22 07:51:09 | WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
INFO   | jvm 1    | 2020/12/22 07:51:09 | WARNING: All illegal access operations will be denied in a future release
INFO   | jvm 1    | 2020/12/22 07:51:09 | Dec 22, 2020 7:51:09 AM org.apache.karaf.main.lock.SimpleFileLock lock
INFO   | jvm 1    | 2020/12/22 07:51:09 | INFO: Trying to lock C:\openhab\userdata\tmp\lock
INFO   | jvm 1    | 2020/12/22 07:51:09 | Dec 22, 2020 7:51:09 AM org.apache.karaf.main.lock.SimpleFileLock lock
INFO   | jvm 1    | 2020/12/22 07:51:09 | INFO: Lock acquired
INFO   | jvm 1    | 2020/12/22 07:51:09 | Dec 22, 2020 7:51:09 AM org.apache.karaf.main.Main$KarafLockCallback lockAcquired
INFO   | jvm 1    | 2020/12/22 07:51:09 | INFO: Lock acquired. Setting startlevel to 100
INFO   | jvm 1    | 2020/12/22 07:51:09 | Dec 22, 2020 7:51:09 AM org.apache.karaf.main.ShutdownSocketThread run
INFO   | jvm 1    | 2020/12/22 07:51:09 | INFO: Shutdown socket thread is listening on 127.0.0.1:53451
INFO   | jvm 1    | 2020/12/22 07:51:10 | org.ops4j.pax.logging.pax-logging-api [log4j2] ERROR : Unable to create file ${sys:openhab.logdir}/openhab.log Ignored FQCN: org.apache.logging.log4j.spi.AbstractLogger
INFO   | jvm 1    | 2020/12/22 07:51:10 | java.io.IOException: The filename, directory name, or volume label syntax is incorrect
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at java.base/java.io.WinNTFileSystem.canonicalize0(Native Method)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at java.base/java.io.WinNTFileSystem.canonicalize(WinNTFileSystem.java:438)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at java.base/java.io.File.getCanonicalPath(File.java:620)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at java.base/java.io.File.getCanonicalFile(File.java:645)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.util.FileUtils.makeParentDirs(FileUtils.java:142)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.rolling.RollingFileManager$RollingFileManagerFactory.createManager(RollingFileManager.java:650)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.rolling.RollingFileManager$RollingFileManagerFactory.createManager(RollingFileManager.java:631)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.AbstractManager.getManager(AbstractManager.java:113)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.OutputStreamManager.getManager(OutputStreamManager.java:114)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.getFileManager(RollingFileManager.java:205)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.RollingFileAppender$Builder.build(RollingFileAppender.java:146)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.RollingFileAppender$Builder.build(RollingFileAppender.java:62)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:122)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:1002)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:942)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:934)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:552)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:241)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:288)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:579)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:285)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.ops4j.pax.logging.log4j2.internal.PaxLoggingServiceImpl.configureLog4J2(PaxLoggingServiceImpl.java:427)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.ops4j.pax.logging.log4j2.internal.PaxLoggingServiceImpl.updated(PaxLoggingServiceImpl.java:269)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.ops4j.pax.logging.log4j2.internal.PaxLoggingServiceImpl$1ManagedPaxLoggingService.updated(PaxLoggingServiceImpl.java:569)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.helper.ManagedServiceTracker.updated(ManagedServiceTracker.java:189)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.helper.ManagedServiceTracker.updateService(ManagedServiceTracker.java:152)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.helper.ManagedServiceTracker.provideConfiguration(ManagedServiceTracker.java:85)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.ConfigurationManager$ManagedServiceUpdate.provide(ConfigurationManager.java:1118)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.ConfigurationManager$ManagedServiceUpdate.run(ConfigurationManager.java:1074)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.UpdateThread.run0(UpdateThread.java:138)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:105)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at java.base/java.lang.Thread.run(Thread.java:834)
INFO   | jvm 1    | 2020/12/22 07:51:10 | org.ops4j.pax.logging.pax-logging-api [log4j2] ERROR : Could not create plugin of type class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile: java.lang.IllegalStateException: ManagerFactory [org.apache.logging.log4j.core.appender.rolling.RollingFileManager$RollingFileManagerFactory@71aabda5] unable to create manager for [${sys:openhab.logdir}/openhab.log] with data [org.apache.logging.log4j.core.appender.rolling.RollingFileManager$FactoryData@95dd3e0[pattern=${sys:openhab.logdir}/openhab.log.%i, append=true, bufferedIO=true, bufferSize=8192, policy=CompositeTriggeringPolicy(policies=[OnStartupTriggeringPolicy, SizeBasedTriggeringPolicy(size=16777216)]), strategy=DefaultRolloverStrategy(min=1, max=7, useMax=true), advertiseURI=null, layout=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n, filePermissions=null, fileOwner=null]] Ignored FQCN: org.apache.logging.log4j.spi.AbstractLogger
INFO   | jvm 1    | 2020/12/22 07:51:10 | java.lang.IllegalStateException: ManagerFactory [org.apache.logging.log4j.core.appender.rolling.RollingFileManager$RollingFileManagerFactory@71aabda5] unable to create manager for [${sys:openhab.logdir}/openhab.log] with data [org.apache.logging.log4j.core.appender.rolling.RollingFileManager$FactoryData@95dd3e0[pattern=${sys:openhab.logdir}/openhab.log.%i, append=true, bufferedIO=true, bufferSize=8192, policy=CompositeTriggeringPolicy(policies=[OnStartupTriggeringPolicy, SizeBasedTriggeringPolicy(size=16777216)]), strategy=DefaultRolloverStrategy(min=1, max=7, useMax=true), advertiseURI=null, layout=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n, filePermissions=null, fileOwner=null]]
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.AbstractManager.getManager(AbstractManager.java:115)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.OutputStreamManager.getManager(OutputStreamManager.java:114)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.getFileManager(RollingFileManager.java:205)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.RollingFileAppender$Builder.build(RollingFileAppender.java:146)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.appender.RollingFileAppender$Builder.build(RollingFileAppender.java:62)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:122)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:1002)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:942)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:934)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:552)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:241)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:288)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:579)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:285)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.ops4j.pax.logging.log4j2.internal.PaxLoggingServiceImpl.configureLog4J2(PaxLoggingServiceImpl.java:427)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.ops4j.pax.logging.log4j2.internal.PaxLoggingServiceImpl.updated(PaxLoggingServiceImpl.java:269)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.ops4j.pax.logging.log4j2.internal.PaxLoggingServiceImpl$1ManagedPaxLoggingService.updated(PaxLoggingServiceImpl.java:569)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.helper.ManagedServiceTracker.updated(ManagedServiceTracker.java:189)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.helper.ManagedServiceTracker.updateService(ManagedServiceTracker.java:152)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.helper.ManagedServiceTracker.provideConfiguration(ManagedServiceTracker.java:85)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.ConfigurationManager$ManagedServiceUpdate.provide(ConfigurationManager.java:1118)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.ConfigurationManager$ManagedServiceUpdate.run(ConfigurationManager.java:1074)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.UpdateThread.run0(UpdateThread.java:138)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:105)
INFO   | jvm 1    | 2020/12/22 07:51:10 | 	at java.base/java.lang.Thread.run(Thread.java:834)

Bruce_Osborne · December 22, 2020, 2:04pm

INFO | jvm 1 | 2020/12/22 07:51:10 | java.io.IOException: The filename, directory name, or volume label syntax is incorrect

What is your configuration for this? Java is saying there is a problem with it.

msexton187 · December 22, 2020, 2:08pm

Mine is set to (which worked in OH2): set.default.OPENHAB_HOME=C:\openhab

I tried both set.default.OPENHAB_HOME=C:\openhab\ and set.default.OPENHAB_HOME=“C:\openhab”, but neither of those helped.

RiotMode · December 22, 2020, 2:14pm

can’t help you, but

get into Console/Karaf and type
log:tail

or Terminal: openhab-cli showlogs

that helped me out so far.

rlkoshak · December 22, 2020, 6:39pm

I suspect that the service wrapper has incorrect file paths and I believe there is a PR to update the screen shots and that service wrapper in the Windows Installation docs.

In your case it looks like the variable sys:openhab.logdir didn’t get defined.

I don’t run on Windows (don’t even have a Windows machine any more) so I’m not going to be much more help beyond pointing in the right direction.

killarneygetaway · December 23, 2020, 5:49pm

Is there a solution for this? I just installed a new installation of OH3 and have no event or openhab logs. Installation is on a Windows 10 PC.

msexton187 · December 23, 2020, 6:37pm

Not yet. I/we need to log the issue on GitHub for the devopers to investigate. I plan to once I get some free time, but not sure when that will be. For now I’m sticking with 2.5 M10.

killarneygetaway · December 23, 2020, 9:28pm

Yeah. I think I will revert back to 2.5.11. Thanks for being on top of this.

J…

msexton187 · December 24, 2020, 1:37am

I’ve posted the issue on GitHub: OH3 - Windows - Fresh Install - openhab.log and events.log not generated after installing service wrapper · Issue #1227 · openhab/openhab-distro · GitHub
Let’s hope it gets resolved soon so we can enjoy the new release.

Marty

Zoo_Guy · January 2, 2021, 6:01am

I think there are larger issues with the wrapper going on with v3. I too was having identical logging problems and was unsuccessful troubleshooting. Disabled the Windows service and reverted to a native startup. HabPanel blank, all things are missing although items are there. This was a fresh install - going back to v2.

msexton187 · January 2, 2021, 6:25am

I actually took it a step further and started migrating my system to openHabian on a Raspberry Pi. I’ve been wanting to migrate for a while, and this was the catalyst I needed.

killarneygetaway · January 4, 2021, 1:56pm

I did the same as msexton187. I used this opportunity to buy myself a RPi4 for xmas and setup OH3 on it over the holidays. So far so good but there is a lot to learn.

J…

msexton187 · January 4, 2021, 3:57pm

Do you use a Aeotec Z-stick and/or sitemaps? I had serious trouble with both and ended up going back to my Windows solution on 2.5M10. I’m curious if you’re seeing the same issues that I was?

Z-Stick: My version requires the use of a hub as a workaround to a design flaw in the z-stick
Sitemaps: I’m getting json sitemap errors that seem to be bogging down the Pi every so often. So much so that I decided to revert back to Windows.

Marty

killarneygetaway · January 4, 2021, 4:10pm

I do use an Aeotec z-stick. It won’t work connected directly to the PI. I had to run it through a USB hub. Something to do with USB3.0 on the PI causes issues. Using a hub has given me no issues. I haven’t tried setting up sitemaps yet.