Logback duplicates records

Question

I have a problem with a logback configuration. Here is my logback.xml:

<configuration>

<appender name="EMS" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>../logs/ems.log</file>
    <append>true</append>
    <encoder>
        <pattern>[%d{ISO8601}] {%t} [%p] %c - %m%n</pattern>
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
        <fileNamePattern>../logs/ems.log.%i</fileNamePattern>
        <minIndex>1</minIndex>
        <maxIndex>99</maxIndex>
    </rollingPolicy>
    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
        <maxFileSize>50MB</maxFileSize>
    </triggeringPolicy>
</appender>

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
   <encoder>
     <pattern>[%d{ISO8601}] {%t} [%p] %c - %m%n</pattern>
   </encoder>
</appender>

<logger name="a.b.c" level="DEBUG">
  <appender-ref ref="EMS"/>
</logger>

<logger name="a.b.c.d.SomeServiceImpl" level="INFO">
    <appender-ref ref="EMS"/>
</logger>

<logger name="a.b.c.e.SomeFilter" level="INFO">
    <appender-ref ref="EMS"/>
</logger>

<root level="OFF">
    <appender-ref ref="EMS"/>
</root>

</configuration>

The problem is when I set the following line for the root logger:

<appender-ref ref="EMS"/>

in the ems.log file each line duplicates:

[2013-12-31 13:16:59,217] {[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'} [DEBUG] a.b.c.f.CallerImpl - qweqweqwe
[2013-12-31 13:16:59,217] {[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'} [DEBUG] a.b.c.f.CallerImpl - qweqweqwe

but when I set the following:

<appender-ref ref="STDOUT"/>

everything works as expected:

[2013-12-31 13:16:59,217] {[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'} [DEBUG] a.b.c.f.CallerImpl - qweqweqwe

I've expected that as far as the root logger had the 'OFF' level, there should't have been problems...

Can anybody, please, assist?

Answer 1

I think the problem is that despite of the fact that root level has "OFF" level, you change effective logging levels of loggers that starts with "a.b.c" to DEBUG with the following:

<logger name="a.b.c" level="DEBUG">
  <appender-ref ref="EMS"/>
</logger>

You can read more about this here.

Only loggers with names that does not start with "a.b.c" will not be printed. All loggers with names that starts with "a.b.c" will have level DEBUG, with except to "a.b.c.d.SomeServiceImpl" and "a.b.c.e.SomeFilter" that will have INFO as their effective logging level.

"OFF" logging level will be ignored by and will not be used to filter logging events. Instead, it will log same log messages second time after they were logged by "a.b.c." logger.

To solve your problem I would recommend to remove this:

<root level="OFF">
    <appender-ref ref="EMS"/>
</root>

from your logging configuration, since it does not change effective logging level of your loggers, but appends all log events to log.file for "a.b.c" loggers.