openHAB - Filtering event logs

Instructions unclear. I can’t get this to work for hiding logs from OpenHAB 3.2 docker image, which I believe uses STDOUT.

Editing ~/userdata/etc/log4j2.xml:

<?xml version="1.0" encoding="UTF-8" standalone="no"?><Configuration monitorInterval="10">

  <Appenders>
    <!-- Console appender not used by default (see Root logger AppenderRefs) -->
      <Console name="STDOUT">

        <!-- Add these to ignore -->
        <RegexFilter onMatch="DENY" onMismatch="ACCEPT" regex=".*(SmartPlug|Temperature).*"/>

        <PatternLayout pattern="%d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
      </Console>

      <!-- ... etc -->

I’ve placed the RegexFilter in multiple locations and restart the container, but I still get the event logs. Is there any obvious mistake I am making here?

No, the Docker image uses the same logger config as any other openHAB installation. Logs are located in userdata/logs instead of /var/logs/openhab because the openHAB inside the container is a manual install instead of an apt install.

You should have userdata mapped to a volume anyway so look there for the logs.

You probably are not looking at the events.log file.

Correct, I’m using the console for accessing logs as documented here in a docker call:

docker exec -t openhab /openhab/runtime/bin/client -u openhab -p habopen log:tail

Does that provide a clue as to why the modifications to userdata/etc/log4j2.xml don’t seem to be working for me?

Yes, volumes are mapped similar to this indeed.

Yes, because you are using the OSGi appender but have modified the STDOUT appender and the original instructions are assuming you are looking at the events.log file which is managed by the Event log appender.

Apologies for not being clearer from the start. I’ve placed the RegexFilter in multiple locations, including that entry:

<PaxOsgi filter="*" name="OSGI">
  <RegexFilter onMatch="DENY" onMismatch="ACCEPT" regex=".*(SmartPlug|Temperature).*"/>
</PaxOsgi>

I don’t think RegexFilter works on PaxOsgi. Is this there any other way to achieve what I’m trying to do?

Probably but I don’t know it. My recommendation is and has always been to use How to watch and look through logging instead of permanent filters in the logging config.

1 Like

Thanks. I’m not convinced the finite P/E cycles on flash memory agree that it is bad and unnecessary to minimize the verbosity of logs, but there are some interesting hints on how to grep through logs in general.

If anyone else knows how to mute certain sensors from announcing their changes every other seconds in the OSGI logger, please share how you did it!

If you are using openHABian you have ZRAM so logs get written to RAM, sparing the SD card. If you are not putting heavy writes into a ramdisk and are running off of an SD card, you should probably turn off events.log entirely.

Note that this logger and the STDOUT logger do not write to disk. Only the file appender loggers do.

I know. Docker does, by default, log all stdout to permanently growing files. This is how container and swarm managers can handle the logs for multiple containers at the same time. I recently figured out how much verbosity is written to flash on an hourly basis by OpenHAB on my Raspbian docker setup alone when the flash memory was full. This is due to sensors with a short refresh interval, and every change is logged.

I thought about disabling the logs, but I’d rather remove the high frequency sensors and keep the rest.

Some people consider it a best practice to minimize the amount of logging when building a docker image, so the OpenHAB configuration could ship with a different logger configuration for docker image builds, but that is a discussion for a different topic. For now, I’ll be happy to know how I can have more control over the logging through docker to files.

But openHAB, by default, logs almost nothing to STDOUT for logger to write, unless you’ve changed something.

When I run docker logs -f openhab all I get is the Karaf console prompt, which is the last thing that gets logged to STDOUT in default install.

+ sync
+ '[' true == false ']'
+ exec gosu openhab tini -s ./start.sh
Launching the openHAB runtime...

                           _   _     _     ____
   ___   ___   ___   ___  | | | |   / \   | __ )
  / _ \ / _ \ / _ \ / _ \ | |_| |  / _ \  |  _ \
 | (_) | (_) |  __/| | | ||  _  | / ___ \ | |_) )
  \___/|  __/ \___/|_| |_||_| |_|/_/   \_\|____/
       |_|       4.0.0-SNAPSHOT - Build #3265

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>

It might be the case if you log into the karaf console to look at the logs that it outputs those to both the console and STDOUT. I’ve never done that. If that’s the case, don’t do that. It’s all there in events.log and openhab.log anyway so just use them. There’s no purpose in having them logged to multiple files.

Or you can offload the logging to some other machine. Docker supports many logging services like GrayLog, syslog, etc.

You are correct. I’ve monkeypatched things to use the logs from client log:tail in my container monitoring software and I had forgotten about that. This is not a default docker installation.

However, do I understand correctly that on a docker installation, by default, events.log and openhab.log still get filled with the same verbosity as I’m currently experiencing in the Osgi logger? In that case, docker image builds could have events.log turned off by default entirely.

Either way, I would like to know how to get more granular control over the non-file Appenders where RegexFilter doesn’t seem to work.

It gets filled with what ever it’s configured to log. The logging levels are defined in the bottom half of the file. If you want to apply filters, you need to apply them on the file appender loggers at the top.

By default, events.log will log Thing status events, Item commands, Item changes, and autoupdate predictions.

This is the universal default for logging on all OH installations.

They could but that would make the Docker install different from all the rest, and given the general recommendation is to not run OH in a container on an SBC like an RPi, the concerns about wearing out the SD card doesn’t come up and isn’t one of the concerns when choosing a default.

Should you choose to run it in unsupported ways (unsupported means we don’t support it, not that it won’t work perfectly fine) that’s fine, but it’s up to you to modify the settings to best meet your configuration. Disabling events.log is as easy as setting all the event loggers to ERROR which will suppress them everywhere.

https://logging.apache.org/log4j/log4j-2.2/manual/filters.html

1 Like

I also just played around with filters, thanks a lot for this helpful post!
While doing some playing around, I found a way to better organize multiple RegexFilters without concatenating them with OR.

			<Filters>
				<RegexFilter regex=".*Systeminfo_.*" onMatch="DENY" onMismatch="NEUTRAL"/>
				<RegexFilter regex=".*CPUUtilization_.*" onMatch="DENY" onMismatch="NEUTRAL"/>
				<RegexFilter regex=".*Nightscout_.*" onMatch="DENY" onMismatch="NEUTRAL"/>
			</Filters>

By wrapping RegexFilters inside the Filters tag, they can be combined.
Note that the onMismatch has to be set to NEUTRAL. If set to ACCEPT, the other filters will be skipped.

3 Likes

Thanks, this works great.

To add a little more detail, everything between <Filters></Filters> can directly replace the single <RegexFilter> line in the event log appender.

Nice having the ability to add comments on the various filters, and to add/remove individual lines when troubleshooting.

After modifying log4j.xml to add a filter, does it require a restart for the changes to take effect?

No, it picks up the change within a minute or so.

1 Like

Hey,
I’m on 4.1.0 and trying to filter out from events.log all item updates and state changes with the prefixes of EBUS and Vaillant but can’t get this to work. I finally focused on just Vaillant for the moment as below:

2024-02-13 20:53:17.791 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantBAI0008_Bai_boiler_tempDFlow_FlowTemperatureTargetValueOrReturnTargetValue' updated to 29.5
2024-02-13 20:53:22.490 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantBAI0008_Bai_boiler_control_getopdata_ServiceWaterReturnTemperature' updated to 47
2024-02-13 20:53:22.491 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantBAI0008_Bai_boiler_control_getopdata_LeadWaterReturnTemperature' updated to 27
2024-02-13 20:53:22.493 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantBAI0008_Bai_boiler_control_getopdata_LeadWaterTemperature' updated to 28.5
2024-02-13 20:53:25.331 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantBAI0008_Bai_boiler_control_getopdata_ServiceWaterReturnTemperature' updated to 47
2024-02-13 20:53:25.332 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantBAI0008_Bai_boiler_control_getopdata_LeadWaterReturnTemperature' updated to 27
2024-02-13 20:53:25.333 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantBAI0008_Bai_boiler_control_getopdata_LeadWaterTemperature' updated to 28.5
2024-02-13 20:53:32.561 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantBAI0008_Bai_boiler_control_getopdata_ServiceWaterReturnTemperature' updated to 47
2024-02-13 20:53:32.563 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantBAI0008_Bai_boiler_control_getopdata_LeadWaterReturnTemperature' updated to 27
2024-02-13 20:53:32.565 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantBAI0008_Bai_boiler_control_getopdata_LeadWaterTemperature' updated to 28.5
2024-02-13 20:53:35.580 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'VaillantVRC470Time' updated to 2024-02-13T20:54:41.000+0100
2024-02-13 20:53:35.581 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'VaillantVRC470Time' changed from 2024-02-13T20:53:41.000+0100 to 2024-02-13T20:54:41.000+0100

My file /var/lib/openhab/etc/org.ops4j.pax.logging.cfg looks like that (snippet), I copied examples from above and adapted to my case. Can paste whole if it matters:

# Event log appender
log4j2.appender.event.type = RollingRandomAccessFile
log4j2.appender.event.name = EVENT
log4j2.appender.event.fileName = ${openhab.logdir}/events.log
log4j2.appender.event.filePattern = ${openhab.logdir}/events.log.%i
log4j2.appender.event.immediateFlush = true
log4j2.appender.event.append = true
log4j2.appender.event.layout.type = PatternLayout
log4j2.appender.event.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-26.26c] - %m%n
log4j2.appender.event.policies.type = Policies
log4j2.appender.event.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.event.policies.size.size = 16MB

# Audit file appender
log4j2.appender.audit.type = RollingRandomAccessFile
log4j2.appender.audit.name = AUDIT
log4j2.appender.audit.fileName = ${openhab.logdir}/audit.log
log4j2.appender.audit.filePattern = ${openhab.logdir}/audit.log.%i
log4j2.appender.audit.append = true
log4j2.appender.audit.layout.type = PatternLayout
log4j2.appender.audit.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j2.appender.audit.policies.type = Policies
log4j2.appender.audit.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.audit.policies.size.size = 8MB

# OSGi appender
log4j2.appender.osgi.type = PaxOsgi
log4j2.appender.osgi.name = OSGI
log4j2.appender.osgi.filter = *

############ CUSTOM FILTERS START HERE #################
log4j2.appender.event.filter.stuff.type = Filters

log4j2.appender.event.filter.stuff.ebus.type = RegexFilter
log4j2.appender.event.filter.stuff.ebus.regex = .*Vaillant.*
log4j2.appender.event.filter.stuff.ebus.onMatch = DENY
log4j2.appender.event.filter.stuff.ebus.onMismatch = NEUTRAL

################# END OF FILTERS ######################

I restarted OH to avoid doubts that it didn’t pick up the config change.
Is my filter screwed or it makes a difference where exactly in the file it sits or yet else?

It appears that you’ve used the example from the first post, which was written for OH2 over six years ago. Per the discussion, it does not work in OH3 (or OH4). You need this:

And if you want to have multiple filters, you can use this.

right! it works! Don’t know why/how I missed it :frowning: thanks @rpwong

Is there a trick to get it to block multi-line logs in events.log?

log4j2.xml:

                <!-- Event log appender -->
                <RollingRandomAccessFile fileName="${sys:openhab.logdir}/events.log" filePattern="${sys:openhab.logdir}/events.log.%i.gz" name="EVENT">
                        <RegexFilter regex=".*LastEventData.*" onMatch="DENY" onMismatch="ACCEPT"/>
                        <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
                        <!-- <RegexFilter regex="(?<=EventNotificationAlert version)(?s).*(?=EventNotificationAlert)" onMatch="DENY" onMismatch="NEUTRAL"/> -->
                        <Policies>
                                <OnStartupTriggeringPolicy/>
                                <SizeBasedTriggeringPolicy size="16 MB"/>
                        </Policies>
                        <DefaultRolloverStrategy max="7"/>
                </RollingRandomAccessFile>

For instance i can’t ever get it to hide this line:

2024-02-13 20:27:07.953 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'CAMERA_FrontYard_LastEventData' changed from <EventNotificationAlert version="2.0" xmlns="http://www.hikvision.com/ver20/XMLSchema">
<ipAddress>192.168.3.201</ipAddress>
<ipv6Address>::</ipv6Address>
<portNo>80</portNo>
<protocol>HTTP</protocol>
<macAddress>4c:f5:dc:4b:7d:f4</macAddress>
<channelID>1</channelID>
<dateTime>2024-02-13T20:26:56+08:00</dateTime>
<activePostCount>1</activePostCount>
<eventType>videoloss</eventType>
<eventState>inactive</eventState>
<eventDescription>videoloss alarm</eventDescription>
<channelName>Front Yard</channelName>
<Extensions>
<serialNumber>DS-2CD2347G2-</serialNumber>
<eventPush>DS-2CD2347G2-,2024-02-13T20:26:56+08:00,0,1.0</eventPush>
</Extensions>
</EventNotificationAlert>
 to <EventNotificationAlert version="2.0" xmlns="http://www.hikvision.com/ver20/XMLSchema">
<ipAddress>192.168.3.201</ipAddress>
<ipv6Address>::</ipv6Address>
<portNo>80</portNo>
<protocol>HTTP</protocol>
<macAddress>4c:f5:dc:4b:7d:f4</macAddress>
<channelID>1</channelID>
<dateTime>2024-02-13T20:27:06+08:00</dateTime>
<activePostCount>1</activePostCount>
<eventType>videoloss</eventType>
<eventState>inactive</eventState>
<eventDescription>videoloss alarm</eventDescription>
<channelName>Front Yard</channelName>
<Extensions>
<serialNumber>DS-2CD2347G2-</serialNumber>
<eventPush>DS-2CD2347G2-,2024-02-13T20:27:06+08:00,0,1.0</eventPush>
</Extensions>
</EventNotificationAlert>