openHAB - Filtering event logs

Just a quick note to all that have issues with multiple filters on the same appender. It just wont work. I have been at it for some time now.

For anyone interested in the log4j rabbit hole:
Here are some things that I learned, but still did not make any difference.

I have tested with the following filter rules:

## Danfoss Air Updates (because the key is cair this will be the first filter)
log4j2.appender.event.filter.cairupdate.type = RegexFilter
log4j2.appender.event.filter.cairupdate.regex = .*(Solar_PowerTotal).*
log4j2.appender.event.filter.cairupdate.onMatch = DENY
log4j2.appender.event.filter.cairupdate.onMismatch = NEUTRAL

## Frequest updates
log4j2.appender.event.filter.frequpdates.type = RegexFilter
log4j2.appender.event.filter.frequpdates.regex = .*(C_Solar_PowerWest).*
log4j2.appender.event.filter.frequpdates.onMatch = DENY
log4j2.appender.event.filter.frequpdates.onMismatch = NEUTRAL

and frequpdates are not tested (i.e. item updates for C_Solar_PowerWest shows up in the log C_Solar_PowerTotal does not)

Finally multiple event filters fixed.

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

log4j2.appender.event.filter.1.a.type = RegexFilter
log4j2.appender.event.filter.1.a.regex = .*(C_Radon_(Level|Updated|Running)|C_Solar_(PowerTotal|PowerEast|PowerWest|TotalYield|DailyYield)|OFFLINE.*10\.13\.0\.70).*
log4j2.appender.event.filter.1.a.onMatch = DENY
log4j2.appender.event.filter.1.a.onMismatch = NEUTRAL

log4j2.appender.event.filter.1.b.type = RegexFilter
log4j2.appender.event.filter.1.b.regex = .*(C_Air_).*
log4j2.appender.event.filter.1.b.onMatch = DENY
log4j2.appender.event.filter.1.b.onMismatch = NEUTRAL

The formal documentation for adding filters is located here: http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PropertyConfigurator.html#method_detail

And it is incorrect!

The correct way is to create a filters attribute and then add new filters under that. The above sample will work, but it will generate an error in the console log file (systemctl status openhab2) that can be ignored

org.ops4j.pax.logging.pax-logging-api [log4j2] ERROR : Filters contains invalid attributes "onMatch", "onMismatch" Ignored FQCN: org.apache.logging.log4j.spi.AbstractLogger

I am on the latest milestone build M5 (this changes with the log4j version)

3 Likes

Hi @jpwise

I just updated to OH 2.5.1 and have seen that I get this error in OH status

systemctrl status openhab2.service
Jan 28 21:48:34 openHABianPi karaf[4032]: org.ops4j.pax.logging.pax-logging-api [log4j2] ERROR : RegexFilter contains an invalid element or attribute "onMismatch" Ignored FQCN:

according to apache.org the last line of the filter should be

log4j2.appender.event.filter.<your-filter-name>.onMismatch = ACCEPT

with lower case “m”. With this the warning is gone.

2 Likes

I now have multiple filters working in OH 2.5.1.2.

Per @petero’s last post, you have to define the filter attribute, and then add filters to it. I defined “Stuff” and then filled it with filter sets for general, astro, ups, wifi, and zwave.

Note that the onMismatch line in each filter set must be NEUTRAL. If it’s set to ACCEPT, the filters will stop evaluating at that point. This stackoverflow link explains it better than I can.

@Schrott.Micha I tried changing the last line to ACCEPT, and my filter immediately stopped working. Going back to NEUTRAL fixed it. I can live with the error in the console log file, which I think is a bug in the version of Log4j2 used in openHAB (see this link).

Honestly, there’s no real benefit to this unless your regex string is extremely long and hard to manage…but it’s satisfying if you like things to be grouped together.

# custom filters for events.log
log4j2.appender.event.filter.stuff.type = Filters

log4j2.appender.event.filter.stuff.general.type = RegexFilter
log4j2.appender.event.filter.stuff.general.regex = .*(has been updated|received command|predicted to|through).*
log4j2.appender.event.filter.stuff.general.onMatch = DENY
log4j2.appender.event.filter.stuff.general.onMismatch = NEUTRAL

log4j2.appender.event.filter.stuff.astro.type = RegexFilter
log4j2.appender.event.filter.stuff.astro.regex = .*(morningNight|astroDawn|astroDusk|nauticDawn|nauticDusk|civilDawn|civilDusk|daylight|noon).*
log4j2.appender.event.filter.stuff.astro.onMatch = DENY
log4j2.appender.event.filter.stuff.astro.onMismatch = NEUTRAL

log4j2.appender.event.filter.stuff.ups.type = RegexFilter
log4j2.appender.event.filter.stuff.ups.regex = .*(UPS_Output_Voltage changed|UPS_Runtime changed|UPS_Runtime_Transformed changed).*
log4j2.appender.event.filter.stuff.ups.onMatch = DENY
log4j2.appender.event.filter.stuff.ups.onMismatch = NEUTRAL

log4j2.appender.event.filter.stuff.wifi.type = RegexFilter
log4j2.appender.event.filter.stuff.wifi.regex = .*(Wemo changed|harmonyhub:hub|LED_|_led changed|_rssi).*
log4j2.appender.event.filter.stuff.wifi.onMatch = DENY
log4j2.appender.event.filter.stuff.wifi.onMismatch = NEUTRAL

log4j2.appender.event.filter.stuff.zwave.type = RegexFilter
log4j2.appender.event.filter.stuff.zwave.regex = .*(Alarm_Raw changed|Lock_Battery changed|Zooz changed).*
log4j2.appender.event.filter.stuff.zwave.onMatch = DENY
log4j2.appender.event.filter.stuff.zwave.onMismatch = NEUTRAL
1 Like

I would love to have an option to turn on/off a filter for the log… As time goes, my tail log is so filled with stuff going on all the time. And sometimes I need to look for something special, it would be great to turn off (temporary) stuff I dont need to look at, (cause I know it´s working fine).

I wonder if this kind of filter would do, and then create a proxy switch to turn on/off several filters? I suspect it´ll have to be done using exec/scripts and commandline to Karaf consol?

Here you go, Kim…

1 Like

Thanks Scott… Seems to be exactly what I´m looking for… Will give it a try soon as my tail log is driven me nuts sometime :smiley:

This is a good point for using filter sets. If you want to see the log entries for something specific, it’s easier to find and comment out the filter specific to the device type than editing those entries out of a long regex list and adding them back later.

1 Like

Exactly my point.
Right now I have aprox 15-20 rows of line every 5 seconds. Things are going crazy sometimes :smiley:

I was wondering if anyone know how to filter the log:tail … i tried the console but it seems to have no effect

Pipe the output to grep…

Is that what you’re looking for?

yea but i was hoping for a permanent solution… i tried pretty much all of the log4j2 settings but nada… there must be a way though since we can exclude specific bindings and levels…

Paste an example of what you are seeing in the log that you’d like to filer out.

I want to filter anything with amazonechocontrol:smartHomeDevice or other regex compatible lines from log:tail ( i have no issue with log files filtering but that is not what i specifically want )

amazonechocontrol:smartHomeDevice:0a4c3487:517c0f67-cdd7-45c7-8dac-3cdcd8114a1b’

and tried this in the org.ops4j.pax.logging.cfg but no effect in karaf ssh…

    log4j2.appender.console.filter.1.type = Filters
    log4j2.appender.console.filter.1.a.type = RegexFilter
    log4j2.appender.console.filter.1.a.regex = .*amazonechocontrol.*
    log4j2.appender.console.filter.1.a.onMatch = DENY
    log4j2.appender.console.filter.1.a.onMismatch = ACCEPT

I quick question.

Is it possible to check out events that have already been filtered? I had a Item filtered and I would like to check out when changed the status yesterday and I do not know if it is stored in another file into the system.

Thanks.

When you filter the logs like this, that log statement is lost. That’s why I’m very much against filtering logs like this except in extreme circumstances. The whole purpose of logs is to preserve information like this so you can go back and see information like this. It’s better to let the log statements be written and use tools available to you to filter the logs based on what’s important to you at that time. Everything continues to be written but you can narrow down what you are looking at to just those lines that are relevant to what you are working on. And then, when something happens and you have to go back and do a forensic analysis, all the logs are there.

You cannot know ahead of time what logs will be relevant so let everything log as normal and search/filter the logs as needed.

2 Likes

yes, you are right.

I will try to minimize the filter.
Thanks.

@rlkoshak just chucked a link to your thread into the main post. When i wrote this up the intent was to keep stuff I didn’t want ‘out’ of the log, but I can see some users won’t always know the difference between filtering something to prevent it being logged, and filtering a log view to only show what they want. Thx.

2 Likes

I originally implemented log filtering both to reduce what I see in my log (understanding fully what it was doing) and to reduce writes to my SD card. I recently enabled ZRAM, which takes care of the latter goal. That didn’t occur to me until reading this just now.

If of any help, this is how I implemented a filter on events per item “categories”. Purpose was to make it easier to track particular events while debugging my scripts. Of course, following rules should be disabled once debugging is over as the rule trigger on all monitored items which adds useless processing.

  1. I created Group items for each category to monitor and attached the corresponding items to these groups. For example, to monitor items related to alarm system, I created a group named SEC_Alarm and assign to items in the definition in the .items file
    Group SEC_AlarmMode Number SEC_System_AlarmMode_G1 "Garage côté rue" <_garagerue> (SEC_AlarmMode) {autoupdate = "false" } Number SEC_System_AlarmMode_G2 "Garage de l'impasse" <_garageimpasse> (SEC_AlarmMode) {autoupdate = "false" } Number SEC_System_AlarmMode_Cave "Cave" <_cave> (SEC_AlarmMode) {autoupdate = "false" } Number SEC_System_AlarmMode_HomeAxs "Accès maison" <_access> (SEC_AlarmMode) {autoupdate = "false" } Number SEC_System_AlarmMode_HomeMvt "Mouvements maison" <_motion> (SEC_AlarmMode) {autoupdate = "false" }

  2. I created a Number item that holds the expected level of monitoring: 0=no monitoring, 1=monitor changes, 2=monitor commands, 3 (1+2)=monitor both changes and commands
    Number SYS_LogGroup_SEC_AlarmMode "SEC_AlarmMode" (SYS_LogGroup)
    This item is exposes in the sitemap and allows changing the log level from the UI

  3. I wrote rules to monitor the expected event (indeed I have 2 rules : one monitors change events and the other monitors command events):

import java.util.HashMap
val HashMap<String, String> itemChanges = newHashMap()
var found = false

rule "Log item change"
when
    Member of SEC_AlarmMode changed
then
    try{
        found = false
        SYS_LogGroup.members.forEach[GenericItem curLogGroup | 
            if(found == false){
                if(curLogGroup.state != NULL){
                    if(Integer.parseInt(curLogGroup.state.toString).bitwiseAnd(1) != 0){
                        val String logGroupName = curLogGroup.name.replace("SYS_LogGroup_", "")
                        if(triggeringItem.getGroupNames.contains(logGroupName)){
                            found = true
                            if(triggeringItem.state == NULL){
                                if(itemChanges.get(triggeringItem.name) != ""){
                                    logInfo("rules.sys." +  triggeringItem.name, "[" + logGroupName + "] " + triggeringItem.name + " changed from " + itemChanges.get(triggeringItem.name) + " to NULL")
                                    itemChanges.put(triggeringItem.name,"")
                                }
                            }
                            else{
                                if(itemChanges.get(triggeringItem.name) != triggeringItem.state.toString){
                                    logInfo("rules.sys.ItemChange", "[" + logGroupName + "] " + triggeringItem.name + " changed from " + itemChanges.get(triggeringItem.name) + " to " + triggeringItem.state.toString)
                                }
                                itemChanges.put(triggeringItem.name,triggeringItem.state.toString)
                            }
                        }
                    }
                }
            }
        ]
    }
    catch(Exception e){
        logWarn("rules.sys.ItemChange", triggeringItem.name + "=" + triggeringItem.state.toString)
    }
end`
  1. mute the “standard” event logging with :
    log:set ERROR smarthome.event.ItemStateChangedEvent

I am a bit ashamed to propose such an ugly workaround but at least it works. And I am afraid that the headless development of OH will let more of these awful tricks to develop as I have not seen one single improvement since OH 1.8 to improve script development despite the ever-changing XTend / JAVA / smarthome environment which forces us to review/readapt our code at every OH “upgrade” with no functional improvement for an end user like me.

OH is definitely a powerful modular tool but is not aimed at audience like me who would prefer concentrating on automation logic rather than Java and all that clumsy stuff.