Search code examples
log4j2

Log4j2 Regexfilter seems to ignore filter configuration

I'm trying to filter out Apache Tomcat startup(/shutdown) events from normal application logging for a third-party tool that manages the application lifecycle of various Tomcat instances. The base is Log4j2 (2.12.1) using a Regexfilter in the Appender Context for a simple File appender (example below massively simplyfied, including hard-coded values):

<Properties>
    <Property name="fileName" value="logs/application.log" />
    <Property name="filePattern" value="logs/application-%d{MM-dd-yyyy}-%i.log.gz" />
    <Property name="pattern" value="%d{ISO8601} %-5p %c - [%t] %m %n"/>
</Properties>
<Appenders>
    <RollingFile name="APPLICATION" fileName="${fileName}" filePattern="${filePattern}" bufferedIO="true" append="true">
        <PatternLayout pattern="${pattern}" alwaysWriteExceptions="true" />
        <Policies>
            <TimeBasedTriggeringPolicy />
            <SizeBasedTriggeringPolicy size="50 MB"/>
        </Policies>
        <DefaultRolloverStrategy min="1" max="5" compressionLevel="5" />
    </RollingFile>
    <File name="STARTUP" fileName="logs/startup.log" bufferedIO="true" immediateFlush="true" append="true">
        <PatternLayout>
            <Pattern>%d %m%n</Pattern>
        </PatternLayout>
        <Filters>
            <RegexFilter regex=".* startup .*"   onMatch="ACCEPT" onMismatch="DENY"/>
            <RegexFilter regex=".* Java Home .*" onMatch="ACCEPT" onMismatch="DENY"/>
        <Filters>
    </File>
</Appenders>

The respective logger looks as follows:

<Logger name="org.apache.catalina.startup" level="INFO" additivity="false">
    <Appender-ref ref="STARTUP"  />
    <Appender-ref ref="APPLICATION"  />
</Logger>

When I fire up the instance, both log files are created. However only the application log file (APPLICATION appender) contains entries, including the ones I'm interested in filtering out:

[ec2-user@AWS:./logs] $ grep -Ern "\[main\].*Java Home|\[main\].*Server startup" application.log
4415:2020-03-26T17:40:15,226 INFO  org.apache.catalina.startup.VersionLoggerListener - [main]   Java Home:             /opt/jdk1.8.0_201/jre
4588:2020-03-26T17:41:04,578 INFO  org.apache.catalina.startup.Catalina - [main]   Server startup in 49087 ms
4786:2020-03-26T17:48:18,043 INFO  org.apache.catalina.startup.VersionLoggerListener - [main]   Java Home:             /opt/jdk1.8.0_201/jre
4959:2020-03-26T17:49:04,625 INFO  org.apache.catalina.startup.Catalina - [main]   Server startup in 46323 ms
5396:2020-03-26T17:57:58,673 INFO  org.apache.catalina.startup.VersionLoggerListener - [main]   Java Home:             /opt/jdk1.8.0_201/jre
5569:2020-03-26T17:58:45,442 INFO  org.apache.catalina.startup.Catalina - [main]   Server startup in 46543 ms
6182:2020-03-26T18:13:39,914 INFO  org.apache.catalina.startup.VersionLoggerListener - [main]   Java Home:             /opt/jdk1.8.0_201/jre
6355:2020-03-26T18:14:27,238 INFO  org.apache.catalina.startup.Catalina - [main]   Server startup in 47073 ms
7096:2020-03-26T18:32:39,525 INFO  org.apache.catalina.startup.VersionLoggerListener - [main]   Java Home:             /opt/jdk1.8.0_201/jre
7266:2020-03-26T18:33:27,550 INFO  org.apache.catalina.startup.Catalina - [main]   Server startup in 47812 ms

Any ideas how to debug why this does not work or did I miss something obvious? I have performed a lot of trial and error configurations (Compositefilter configuration included, albeit even using one Regexfilter does not work) and also enabled log4j2 debug (StatusLogger looks fine), however there is simply no indication of what is wrong or why the matching lines are not routed out separately into the configured File appender log.

Reading the documentation (https://logging.apache.org/log4j/log4j-2.3/manual/filters.html) and the source code (https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/main/java/org/apache/logging/log4j/core/filter/RegexFilter.java), as well as trying to find examples (https://duckduckgo.com/?q=log4j2+regexfilter+examples) did not help me further in my quest.

Solution

  • I fully agree that the filter documentation leaves a lot to be desired. Even though you seem to have solved your problem already, I've found two more points that are worth pointing out:

    • The regexp isn't anchored, so the .* at the beginning and end are unnecessary.
    • The matching only applies to the message text itself. With your Java Home: ..., it appears to be at the start, so the .* at the beginning actually prevents a match. Better anchor it with ^.
    • onMismatch="DENY" will abort any further processing, so following filter rules will not be applied any longer! If you have multiple filters, you need to use NEUTRAL for the negative case (except for the last filter rule).
    <Filters>
    <RegexFilter regex=" startup "   onMatch="ACCEPT" onMismatch="NEUTRAL"/>
    <RegexFilter regex="^Java Home " onMatch="ACCEPT" onMismatch="DENY"/>
<Filters>

    Alternatively, as you want to select just two possible matches (and discard everything else), you could also use a single filter with a combined regex:

    <RegexFilter regex="^Java Home | startup " onMatch="ACCEPT" onMismatch="DENY"/>