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
_______________________________________________
logback-user mailing list
[email protected]
http://mailman.qos.ch/mailman/listinfo/logback-user
