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

[Mike Wertheim]

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 at 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 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/20190920/d0267af6/attachment.html>