[logback-user] config question (why is debug on, and why is my filter not filtering?)

[Mike Wertheim]

I'm maintaining a Java application that's using logback1.2.2. Someone who
isn't around anymore set up the logback configuration, and I'm having some
trouble understanding it.

I am trying to add a filter. The behavior I'm seeing is that the filter
works fine on lines that are logged at the INFO level, but the filter is
not filtering lines that are logged at the DEBUG level. (So the INFO lines
are removed correctly, but the DEBUG lines are still being logged.)

Furthermore, I'm realizing that I don't actually understand why any of the
DEBUG logging (regardless of the filter) is happening at all. DEBUG logging
is working, and I want DEBUG logging to be working, but I'm not
understanding why it's working. The reason I was thinking that it wouldn't
be working is that the logback.xml adds the file appender to a root node
that has level=INFO, so I was expecting to only see INFO logging and not
DEBUG logging.

Here is the logback.xml (including the filter that I added to both of the
appenders)...
<configuration debug="true">
    <logger name="com.mycompany" level="debug"/>
    <logger name="com.mycompany.app.server.config.AccessLogHandler"
level="INFO" />
    <logger name="org.hibernate" level="info"/>
    <logger name="org.springframework" level="info"/>
    <logger name="org.apache" level="info"/>

    <jmxConfigurator />
    <contextListener
class="ch.qos.logback.classic.jul.LevelChangePropagator"/>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%date \(%thread\) %-5level [%logger{40}]
%message%n</pattern>
        </encoder>
        <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
          <evaluator>
            <expression>return
message.contains("UserInfoEntry");</expression>
          </evaluator>
          <OnMismatch>NEUTRAL</OnMismatch>
          <OnMatch>DENY</OnMatch>
        </filter>
    </appender>

    <property name="LOG_PATH" value="var/log"/>
    <appender name="FILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
          <evaluator>
            <expression>return
message.contains("UserInfoEntry");</expression>
          </evaluator>
          <OnMismatch>NEUTRAL</OnMismatch>
          <OnMatch>DENY</OnMatch>
        </filter>

        <file>${LOG_PATH}/app.log</file>
        <rollingPolicy
class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- daily rollover. Make sure the path matches the one in the
file element or else
             the rollover logs are placed in the working directory. -->

<fileNamePattern>${LOG_PATH}/app_%d{yyyy-MM-dd}.%i.log</fileNamePattern>

            <timeBasedFileNamingAndTriggeringPolicy
class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>5MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!-- keep 30 days' worth of history -->
            <maxHistory>30</maxHistory>
        </rollingPolicy>

        <encoder>
            <charset>UTF-8</charset>
            <pattern>%date [%thread] %-5level %logger{36} %X -
%msg%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="FILE"/>
    </root>
</configuration>

Here is the output from logback (since i have debug=true on)...
20:50:55,109 |-INFO in ch.qos.logback.classic.LoggerContext[default] -
Could NOT find resource [logback-test.xml]
20:50:55,109 |-INFO in ch.qos.logback.classic.LoggerContext[default] -
Could NOT find resource [logback.groovy]
20:50:55,109 |-INFO in ch.qos.logback.classic.LoggerContext[default] -
Found resource [logback.xml] at
[file:/opt/app/app-server-4.3.1-SNAPSHOT/etc/logback.xml]
20:50:55,224 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction -
Setting level of logger [com.mycompany] to DEBUG
20:50:55,224 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction -
Setting level of logger [org.springframework.security] to INFO
20:50:55,224 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction -
Setting level of logger [com.mycompany.app.server.config.AccessLogHandler]
to INFO
20:50:55,224 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction -
Setting level of logger [org.hibernate] to INFO
20:50:55,224 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction -
Setting level of logger [org.springframework] to INFO
20:50:55,224 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction -
Setting level of logger [com.zaxxer.hikari.pool.PoolBase] to WARN
20:50:55,225 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction -
Setting level of logger [org.springframework.aop.framework.CglibAopProxy]
to ERROR
20:50:55,225 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction -
Setting level of logger [org.eclipse.jetty.util.log] to WARN
20:50:55,225 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction -
Setting level of logger [com.netflix.hystrix] to WARN
20:50:55,225 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction -
Setting level of logger [org.apache] to INFO
20:50:55,225 |-INFO in
ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin
20:50:55,291 |-INFO in
ch.qos.logback.classic.joran.action.LoggerContextListenerAction - Adding
LoggerContextListener of type
[ch.qos.logback.classic.jul.LevelChangePropagator] to the object stack
20:50:55,293 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
DEBUG level on Logger[ROOT] onto the JUL framework
20:50:55,293 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
WARN level on Logger[com.netflix.hystrix] onto the JUL framework
20:50:55,293 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
DEBUG level on Logger[com.mycompany] onto the JUL framework
20:50:55,293 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
INFO level on Logger[com.mycompany.app.server.config.AccessLogHandler] onto
the JUL framework
20:50:55,293 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
WARN level on Logger[com.zaxxer.hikari.pool.PoolBase] onto the JUL framework
20:50:55,293 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
INFO level on Logger[org.apache] onto the JUL framework
20:50:55,294 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
WARN level on Logger[org.eclipse.jetty.util.log] onto the JUL framework
20:50:55,294 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
INFO level on Logger[org.hibernate] onto the JUL framework
20:50:55,294 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
INFO level on Logger[org.springframework] onto the JUL framework
20:50:55,294 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
ERROR level on Logger[org.springframework.aop.framework.CglibAopProxy] onto
the JUL framework
20:50:55,294 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
INFO level on Logger[org.springframework.security] onto the JUL framework
20:50:55,294 |-INFO in
ch.qos.logback.classic.joran.action.LoggerContextListenerAction - Starting
LoggerContextListener
20:50:55,294 |-INFO in ch.qos.logback.core.joran.action.AppenderAction -
About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
20:50:55,298 |-INFO in ch.qos.logback.core.joran.action.AppenderAction -
Naming appender as [CONSOLE]
20:50:55,303 |-INFO in
ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default
type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder]
property
20:50:55,336 |-INFO in
ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default
type [ch.qos.logback.classic.boolex.JaninoEventEvaluator] for [evaluator]
property
20:50:55,582 |-INFO in ch.qos.logback.core.joran.action.AppenderAction -
About to instantiate appender of type
[ch.qos.logback.core.rolling.RollingFileAppender]
20:50:55,585 |-INFO in ch.qos.logback.core.joran.action.AppenderAction -
Naming appender as [FILE]
20:50:55,586 |-INFO in
ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default
type [ch.qos.logback.classic.boolex.JaninoEventEvaluator] for [evaluator]
property
20:50:55,603 |-INFO in
ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP at 419c5f1a - The date
pattern is 'yyyy-MM-dd' from file name pattern
'var/log/app_%d{yyyy-MM-dd}.%i.log'.
20:50:55,603 |-INFO in
ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP at 419c5f1a - Roll-over at
midnight.
20:50:55,607 |-INFO in
ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP at 419c5f1a - Setting
initial period to Thu Sep 19 20:50:54 UTC 2019
20:50:55,607 |-WARN in
ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP at 419c5f1a -
SizeAndTimeBasedFNATP is deprecated. Use SizeAndTimeBasedRollingPolicy
instead
20:50:55,608 |-WARN in
ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP at 419c5f1a - For more
information see
http://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedRollingPolicy
20:50:55,611 |-INFO in
ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default
type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder]
property
20:50:55,613 |-INFO in
ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file
name: var/log/app.log
20:50:55,613 |-INFO in
ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is
set to [var/log/app.log]
20:50:55,615 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction
- Setting level of ROOT logger to INFO
20:50:55,615 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator at 5e853265 - Propagating
INFO level on Logger[ROOT] onto the JUL framework
20:50:55,615 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction -
Attaching appender named [FILE] to Logger[ROOT]
20:50:55,622 |-INFO in
ch.qos.logback.classic.joran.action.ConfigurationAction - End of
configuration.
20:50:55,622 |-INFO in
ch.qos.logback.classic.joran.JoranConfigurator at 96def03 - Registering
current configuration as safe fallback point


Can anyone help determine what's going on?

The two questions are:
1) What is it that's causing the DEBUG logging to be on? (I like that it's
on, but don't understand why it's on.)
2) Why is the filter filtering INFO lines but not filtering DEBUG lines? (I
want it filtering DEBUG lines.)


Thanks,
Mike
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20190919/59062a34/attachment.html>