openHAB - Filtering event logs

OK - now had a bit of time to fiddle around with it a bit more.

Filtering works in general now; I tried both a simple single-filtering on some item in the event log - and that works. Also the multiple filter works as shown below - although it gives an errormessage in the karaf log, which can be ignored (filtering still works).

log4j2.appender.event.filter.stuff.type = Filters

log4j2.appender.event.filter.stuff.runsw.type = RegexFilter
log4j2.appender.event.filter.stuff.runsw.regex = .*(aduroh2_opdata_Run_switch).*
log4j2.appender.event.filter.stuff.runsw.onMatch = DENY
log4j2.appender.event.filter.stuff.runsw.onMismatch = NEUTRAL

log4j2.appender.event.filter.stuff.sled2.type = RegexFilter
log4j2.appender.event.filter.stuff.sled2.regex = .*(SaunaLED2ColorControl).*
log4j2.appender.event.filter.stuff.sled2.onMatch = DENY
log4j2.appender.event.filter.stuff.sled2.onMismatch = NEUTRAL

My issue is now, that the event log entries I originally wanted to filter out - still wont be filtered. The only thing which makes it different is, that the contents of the event (string item update) is very big/long:

2021-05-12 12:46:00.628 [vent.ItemStateChangedEvent] - aduroh2_opdata_Output_str changed from operating_data/time=12/05-21 12:45:03
operating_data/boiler_temp=14.4
operating_data/smoke_temp=13.3
operating_data/return_temp=999.9
operating_data/dhw_temp=13.2
operating_data/external_temp=0.0
operating_data/t6_temp=0.0
operating_data/t7_temp=0.0
operating_data/distance=999
operating_data/photo_level=100
operating_data/shaft_temp=14.4
operating_data/milli_ampere=30
operating_data/oxygen=20.0
operating_data/flow1=0
operating_data/flow2=0
operating_data/flow3=0
operating_data/flow4=0
operating_data/power_pct=0
operating_data/power_kw=0.0
operating_data/oxygen_ref=0.0
operating_data/boiler_ref=21.0
operating_data/mean_out_temp=0.0
operating_data/dhw_ref=0.0
operating_data/forward_ref=0.0
operating_data/sun2_temp=0.0
operating_data/sun_dhw_temp=0.0
operating_data/sun_surplus_temp=0.0
operating_data/pressure=0.00
operating_data/air_flow=0
operating_data/sun_temp=0.0
operating_data/house_valve_state=1
operating_data/chill_out=0.0
operating_data/sun_pumpspeed=0
operating_data/sun_power_kw=0.0
operating_data/cloud_level=0
operating_data/forward_temp=0.0
operating_data/back_pressure=0
operating_data/t1_temp=0
operating_data/air_quality=0
operating_data/feed_low=1500
operating_data/feed_medium=210
operating_data/feed_high=400
operating_data/content=0
operating_data/state=14
operating_data/substate=0
operating_data/boiler_pump_state=0
operating_data/dhw_valve_state=0
operating_data/house_pump_state=0
operating_data/sun_pump_state=0
operating_data/sun_surplus_state=0
operating_data/ashbox_minutes=0.0
operating_data/ashbox_contact=0.0
operating_data/internet_uptime=99
operating_data/off_on_alarm=0
operating_data/contact2=1
operating_data/NA=1
operating_data/NA=0
operating_data/NA=0
operating_data/corr_medium=0
operating_data/NA=0
operating_data/NA=34
operating_data/compressor_clean=0.0
operating_data/fan_speed=0.0 to operating_data/time=12/05-21 12:46:03
operating_data/boiler_temp=14.4
operating_data/smoke_temp=13.2
operating_data/return_temp=999.9
operating_data/dhw_temp=13.2
operating_data/external_temp=0.0
operating_data/t6_temp=0.0
operating_data/t7_temp=0.0
operating_data/distance=999
operating_data/photo_level=100
operating_data/shaft_temp=14.4
operating_data/milli_ampere=20
operating_data/oxygen=20.0
operating_data/flow1=0
operating_data/flow2=0
operating_data/flow3=0
operating_data/flow4=0
operating_data/power_pct=0
operating_data/power_kw=0.0
operating_data/oxygen_ref=0.0
operating_data/boiler_ref=21.0
operating_data/mean_out_temp=0.0
operating_data/dhw_ref=0.0
operating_data/forward_ref=0.0
operating_data/sun2_temp=0.0
operating_data/sun_dhw_temp=0.0
operating_data/sun_surplus_temp=0.0
operating_data/pressure=0.00
operating_data/air_flow=0
operating_data/sun_temp=0.0
operating_data/house_valve_state=1
operating_data/chill_out=0.0
operating_data/sun_pumpspeed=0
operating_data/sun_power_kw=0.0
operating_data/cloud_level=0
operating_data/forward_temp=0.0
operating_data/back_pressure=0
operating_data/t1_temp=0
operating_data/air_quality=0
operating_data/feed_low=1500
operating_data/feed_medium=210
operating_data/feed_high=400
operating_data/content=0
operating_data/state=14
operating_data/substate=0
operating_data/boiler_pump_state=0
operating_data/dhw_valve_state=0
operating_data/house_pump_state=0
operating_data/sun_pump_state=0
operating_data/sun_surplus_state=0
operating_data/ashbox_minutes=0.0
operating_data/ashbox_contact=0.0
operating_data/internet_uptime=99
operating_data/off_on_alarm=0
operating_data/contact2=1
operating_data/NA=1
operating_data/NA=0
operating_data/NA=0
operating_data/corr_medium=0
operating_data/NA=0
operating_data/NA=34
operating_data/compressor_clean=0.0
operating_data/fan_speed=0.0

Any ideas why this wont filter out ? - do I need a more complicated REGEX-statement for it than just the item name ? Any ideas would be appreciated - as I still very much would like to fix this in my log…

Google is my friend; through this page:
https://gist.github.com/jsvd/2ceed2eccf1c14f197ce791a302af838

What I needed was a “enable DOTALL” (?s) in front of the regex statement I had.

My filter section now looks like this - and works;

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

log4j2.appender.event.filter.stuff.oprunsw.type = RegexFilter
log4j2.appender.event.filter.stuff.oprunsw.regex = .*(aduroh2_opdata_Run_switch).*
log4j2.appender.event.filter.stuff.oprunsw.onMatch = DENY
log4j2.appender.event.filter.stuff.oprunsw.onMismatch = NEUTRAL

log4j2.appender.event.filter.stuff.sbrunsw.type = RegexFilter
log4j2.appender.event.filter.stuff.sbrunsw.regex = .*(aduroh2_setboiler_Run_switch ).*
log4j2.appender.event.filter.stuff.sbrunsw.onMatch = DENY
log4j2.appender.event.filter.stuff.sbrunsw.onMismatch = NEUTRAL

log4j2.appender.event.filter.stuff.opodata.type = RegexFilter
log4j2.appender.event.filter.stuff.opodata.regex = (?s).*(aduroh2_opdata_Output_str).*
log4j2.appender.event.filter.stuff.opodata.onMatch = DENY
log4j2.appender.event.filter.stuff.opodata.onMismatch = NEUTRAL

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

I can’t seem to figure out this filtering. I just upgraded to OH3.1 from 2.5 yesterday. I have been wanting to filter out these events for a long time, but never got around to it.

2021-10-28 10:59:03.780 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Local_DateTime' changed from 2021-10-28T10:58:03.763-0400 to 2021-10-28T10:59:03.765-0400

Below is the contents of my /var/lib/openhab/etc/org.ops4j.pax.logging.cfg.

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

# Filtering Rules
log4j2.appender.event.filter.cleanup.type = Filters
log4j2.appender.event.filter.cleanup.Local_DateTime.type = RegexFilter
log4j2.appender.event.filter.cleanup.Local_DateTime.regex = (?s).*(Local_DateTime).*
log4j2.appender.event.filter.cleanup.Local_DateTime.onMatch = DENY
log4j2.appender.event.filter.cleanup.Local_DateTime.onMismatch = ACCEPT

Thanks for any assistance you can provide.

I see now it’s different in OH3. I suppose I have to do everything in the XML file or at least in this file, but in XML format as the file it’s referencing in the first line?

I added the filter to the XML file and that worked. I guess this could get lost on upgrades.

shouldn’t be the case as log4j2.xml is tagged to be a configuration file in the .deb package:

dpkg -s openhab |grep log4j2.xml
 /var/lib/openhab/etc/log4j2.xml eac9f92535d20fa8f344b049c8696ec4

during an update/upgrade the installer should ask how to behave ( replace/keep modified version/keep maintainers version ).

So for those that want an OH3 filter that does as the first post asks with a simple cut and past solution try this example. (OpenHabian on Raspi 4 OpenHAB 3.2.0)

To filter out an entry in the log like:

2022-04-30 18:55:21.231 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SqueezeBoxReceiverCurrentPlayingTime' changed from 227 to 228

Then edit /var/lib/openhab/etc/log4j2.xml

	...
	                <!-- Event log appender -->
                <RollingRandomAccessFile fileName="${sys:openhab.logdir}/events.log" filePattern="${sys:openhab.logdir}/events.log.%i" name="EVENT">


                        <!-- Regex Filter added below -->
                        <RegexFilter regex=".*CurrentPlayingTime.*" onMatch="DENY" onMismatch="ACCEPT"/>

                        <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
                        <Policies>
                                <OnStartupTriggeringPolicy/>
                                <SizeBasedTriggeringPolicy size="16 MB"/>
                        </Policies>
                </RollingRandomAccessFile>
...

An example to filter out:

2022-04-30 19:07:05.368 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveSerialControllerSerialSof' changed from 2489 to 2490

would be:

<RegexFilter regex=".*ZWaveSerial.*" onMatch="DENY" onMismatch="ACCEPT"/>

There can be only one filter line! So a compound filter to remove both log lines uses the OR operator and looks like:

<RegexFilter regex=".*CurrentPlayingTime.*||.*ZWaveSerial.*" onMatch="DENY" onMismatch="ACCEPT"/>

A good resource: https://logging.apache.org/log4j/2.x/manual/filters.html

3 Likes

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