config question (why is debug on, and why is my filter not filtering?)
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@5e853265 - Propagating DEBUG level on Logger[ROOT] onto the JUL framework 20:50:55,293 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@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@5e853265 - Propagating DEBUG level on Logger[com.mycompany] onto the JUL framework 20:50:55,293 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@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@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@5e853265 - Propagating INFO level on Logger[org.apache] onto the JUL framework 20:50:55,294 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@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@5e853265 - Propagating INFO level on Logger[org.hibernate] onto the JUL framework 20:50:55,294 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@5e853265 - Propagating INFO level on Logger[org.springframework] onto the JUL framework 20:50:55,294 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@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@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@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@419c5f1a - Roll-over at midnight. 20:50:55,607 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@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@419c5f1a - SizeAndTimeBasedFNATP is deprecated. Use SizeAndTimeBasedRollingPolicy instead 20:50:55,608 |-WARN in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@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@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@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
A followup on this... It turns out that the log level (info vs debug) was not actually relevant. The problem is actually this... My application invokes a logger like this: logger.info("some constant message string here: {}", myObject); The filter seems to only be filtering on the constant message string. What I want is for the filter to be filtering the contents of myObject.toString() Is there a way to make that happen? On Thu, Sep 19, 2019 at 7:00 PM Mike Wertheim <mike.wertheim@gmail.com> wrote:
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@5e853265 - Propagating DEBUG level on Logger[ROOT] onto the JUL framework 20:50:55,293 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@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@5e853265 - Propagating DEBUG level on Logger[com.mycompany] onto the JUL framework 20:50:55,293 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@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@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@5e853265 - Propagating INFO level on Logger[org.apache] onto the JUL framework 20:50:55,294 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@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@5e853265 - Propagating INFO level on Logger[org.hibernate] onto the JUL framework 20:50:55,294 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@5e853265 - Propagating INFO level on Logger[org.springframework] onto the JUL framework 20:50:55,294 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@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@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@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@419c5f1a - Roll-over at midnight. 20:50:55,607 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@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@419c5f1a - SizeAndTimeBasedFNATP is deprecated. Use SizeAndTimeBasedRollingPolicy instead 20:50:55,608 |-WARN in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@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@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@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
participants (1)
-
Mike Wertheim