Logging to events.log not working in OH3

Hello,

I’m having problems with logger configuration. Since upgrading to OH 3, all logs messages are written to openhab.log (including “openhab.event.*” messages). I’d like to have events written to event.log file (same as OH 2 did) but can’t find a way to do it. Found some other threads mentioning this but none seems relevant to my issue.
I’ve tried tweaking log4j2.xml file - I’ve moved log files to /mnt/ramdisk which seems to be working fine, but everything is being written to openhab.log, events.log file is empty. My config looks like this:

<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<Configuration monitorInterval="60">
        <Appenders>
                <!-- Console appender not used by default (see Root logger AppenderRefs) -->
                <Console name="STDOUT">
                        <PatternLayout pattern="%d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
                </Console>

                <!-- Rolling file appender -->
                <RollingFile fileName="/mnt/ramdisk/openhab.log" filePattern="${sys:openhab.logdir}/openhab.log.%i" name="LOGFILE">
                        <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
                        <Policies>
                                <OnStartupTriggeringPolicy/>
                                <SizeBasedTriggeringPolicy size="8 MB"/>
                        </Policies>
                </RollingFile>

                <!-- Event log appender -->
                <RollingFile fileName="/mnt/ramdisk/events.log" filePattern="${sys:openhab.logdir}/events.log.%i" name="EVENT">
                        <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
                        <Policies>
                                <OnStartupTriggeringPolicy/>
                                <SizeBasedTriggeringPolicy size="8 MB"/>
                        </Policies>
                </RollingFile>

                <!-- Audit file appender -->
                <RollingRandomAccessFile fileName="/mnt/ramdisk/audit.log" filePattern="${sys:openhab.logdir}/audit.log.%i" name="AUDIT">
                        <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
                        <Policies>
                                <OnStartupTriggeringPolicy/>
                                <SizeBasedTriggeringPolicy size="8 MB"/>
                        </Policies>
                </RollingRandomAccessFile>

                <!-- OSGi appender -->
                <PaxOsgi filter="*" name="OSGI"/>
        </Appenders>

        <Loggers>
                <!-- Root logger configuration -->
                <Root level="WARN">
                        <AppenderRef ref="LOGFILE"/>
                        <AppenderRef ref="OSGI"/>
                </Root>

                <!-- Karaf Shell logger -->
                <Logger level="OFF" name="org.apache.karaf.shell.support">
                        <AppenderRef ref="STDOUT"/>
                </Logger>

                <!-- Security audit logger -->
                <Logger additivity="false" level="INFO" name="org.apache.karaf.jaas.modules.audit">
                        <AppenderRef ref="AUDIT"/>
                </Logger>

                <!-- openHAB specific logger configuration -->

                <Logger level="INFO" name="org.openhab"/>
<!--
                <Logger level="ERROR" name="openhab.event.ItemStateEvent"/>
                <Logger level="ERROR" name="openhab.event.ItemAddedEvent"/>
                <Logger level="ERROR" name="openhab.event.ItemRemovedEvent"/>
                <Logger level="ERROR" name="openhab.event.ItemChannelLinkAddedEvent"/>
                <Logger level="ERROR" name="openhab.event.ItemChannelLinkRemovedEvent"/>
                <Logger level="ERROR" name="openhab.event.ThingStatusInfoEvent"/>
                <Logger level="ERROR" name="openhab.event.ThingAddedEvent"/>
                <Logger level="ERROR" name="openhab.event.ThingUpdatedEvent"/>
                <Logger level="ERROR" name="openhab.event.ThingRemovedEvent"/>
                <Logger level="ERROR" name="openhab.event.InboxUpdatedEvent"/>
                <Logger level="ERROR" name="openhab.event.RuleStatusInfoEvent"/>
                <Logger level="ERROR" name="openhab.event.RuleAddedEvent"/>
                <Logger level="ERROR" name="openhab.event.RuleRemovedEvent"/>
                <Logger level="ERROR" name="openhab.event.StartlevelEvent"/>
                <Logger level="ERROR" name="openhab.event.AddonEvent"/>
-->
                <Logger additivity="false" level="WARN" name="openhab.event">
                        <AppenderRef ref="EVENT"/>
                        <AppenderRef ref="OSGI"/>
                </Logger>

                <Logger level="ERROR" name="javax.jmdns"/>
                <Logger level="ERROR" name="org.jupnp"/>

                <!-- This suppresses all Maven download issues from the log when doing feature installations -->
                <!-- as we are logging errors ourselves in a nicer way anyhow. -->
                <Logger level="ERROR" name="org.ops4j.pax.url.mvn.internal.AetherBasedResolver"/>

                <!-- Filters known issues of pax-web (issue link to be added here). -->
                <!-- Can be removed once the issues are resolved in an upcoming version. -->
                <Logger level="OFF" name="org.ops4j.pax.web.pax-web-runtime"/>

                <!-- Filters known issues of lsp4j, see -->
                <!-- https://github.com/eclipse/smarthome/issues/4639 -->
                <!-- https://github.com/eclipse/smarthome/issues/4629 -->
                <!-- https://github.com/eclipse/smarthome/issues/4643 -->
                <!-- Can be removed once the issues are resolved in an upcoming version. -->
                <Logger level="OFF" name="org.eclipse.lsp4j"/>

                <!-- Filters warnings for events that could not be delivered to a disconnected client. -->
                <Logger level="ERROR" name="org.apache.cxf.jaxrs.sse.SseEventSinkImpl"/>

                <!-- Filters known issues of KarServiceImpl, see -->
                <!-- https://github.com/openhab/openhab-distro/issues/519#issuecomment-351944506 -->
                <!-- Can be removed once the issues are resolved in an upcoming version. -->
                <Logger level="ERROR" name="org.apache.karaf.kar.internal.KarServiceImpl"/>

                <!-- Filters warnings about unavailable ciphers when JCE is not installed, see -->
                <!-- https://github.com/openhab/openhab-distro/issues/999 -->
                <Logger level="ERROR" name="org.apache.karaf.shell.ssh.SshUtils"/>

                <!-- Filters known issues of javax.mail, see -->
                <!-- https://github.com/openhab/openhab-addons/issues/5530 -->
                <Logger level="ERROR" name="javax.mail"/>

                <!-- Added by Karaf to prevent debug logging loops, see -->
                <!-- https://issues.apache.org/jira/browse/KARAF-5559 -->
                <Logger level="WARN" name="org.apache.sshd"/>
        </Loggers>

</Configuration>

You can see I tried to change log levels of “openhab.event” but it didn’t have any effect, with this config I’m still getting all events logged into openhab.log (event with default config which has INFO level).

I have actually noticed one weird thing - If i run “log:get” in openhab-cli, I get this output:

openhab> log:get
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
ROOT                                               │ INFO
Sunblock                                           │ DEBUG
binding.miio                                       │ DEBUG
com.zsmartsystems.zigbee                           │ INFO
com.zsmartsystems.zigbee.dongle.ember.internal.ash │ INFO
javax.jmdns                                        │ ERROR
openhab.event.RuleStatusInfoEvent                  │ WARN
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.apache.sshd                                    │ WARN
org.eclipse.jetty.util.thread.ThreadPoolBudget     │ ERROR
org.eclipse.lsp4j                                  │ OFF
org.eclipse.smarthome                              │ INFO
org.eclipse.smarthome.core.common                  │ INFO
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
org.openhab.binding.miio                           │ INFO
org.openhab.binding.miio.internal.basic            │ DEBUG
org.openhab.binding.zigbee                         │ INFO
org.openhab.binding.zigbee.handler                 │ INFO
org.openhab.binding.zwave                          │ INFO
org.openhab.persistence.mapdb                      │ INFO
org.openhab.zigbee.binding                         │ INFO
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF
smarthome.event                                    │ INFO
smarthome.event.InboxUpdatedEvent                  │ ERROR
smarthome.event.ItemAddedEvent                     │ ERROR
smarthome.event.ItemRemovedEvent                   │ ERROR
smarthome.event.ItemStateEvent                     │ ERROR
smarthome.event.ThingAddedEvent                    │ ERROR
smarthome.event.ThingRemovedEvent                  │ ERROR
smarthome.event.ThingStatusInfoEvent               │ ERROR

Notice that instead of “openhab.event” there is bunch of configs for “smarthome.event”. Does anyone have any idea how to fix this, so that all event logs are written to events.log?

What do you get in case you do e.g.

cd /var/lib/openhab
grep -R smarthome.event.ThingStatusInfoEvent .

on an OH3 system here I get:

./etc/org.ops4j.pax.logging.cfg.dpkg-old:log4j2.logger.smarthomeThingStatusInfoEvent.name = smarthome.event.ThingStatusInfoEvent
./config/org/ops4j/pax/logging.config.bak:log4j2.logger.smarthomeThingStatusInfoEvent.name="smarthome.event.ThingStatusInfoEvent"

checking the file extensions you can see that these files are not actively used ( .dpkg-old resp. .config.bak ).
Is that the same in your case ?

I’m getting this:

./etc/org.ops4j.pax.logging.cfg:log4j2.logger.smarthomeThingStatusInfoEvent.name = smarthome.event.ThingStatusInfoEvent
./config/org/ops4j/pax/logging.config.bak:log4j2.logger.smarthomeThingStatusInfoEvent.name="smarthome.event.ThingStatusInfoEvent"
./config/org/ops4j/pax/logging.config:log4j2.logger.smarthomeThingStatusInfoEvent.name="smarthome.event.ThingStatusInfoEvent"

My /var/lib/openhab/etc/org.ops4j.pax.logging.cfg file has following content:

org.ops4j.pax.logging.log4j2.config.file=${karaf.etc}/log4j2.xml

as far as I remember this is also described in the release notes under breaking changes ( Releases · openhab/openhab-distro · GitHub )

the other - /var/lib/openhab/config/org/ops4j/pax/logging.config - contains

:org.apache.felix.configadmin.revision:=L"2"
felix.fileinstall.filename="file:/var/lib/openhab/etc/org.ops4j.pax.logging.cfg"
org.ops4j.pax.logging.log4j2.config.file="/var/lib/openhab/etc/log4j2.xml"
service.bundleLocation="?"
service.pid="org.ops4j.pax.logging"

I have the impression that this is the reason why your events are not logged to the events.log file.

2 Likes

Thanks, I replaced the file with yours and it works now.

1 Like