[logback-user] Log Messages duplicate when running unit tests.

[ceki]

Hi Matt,

Response in line.

On 06.01.2012 19:53, Matt Bertolini wrote:
> Hello.
>
> I am trying to implement logback/slf4j and an extremely frustrating
> thing is occurring when I run my unit tests. All of the log messages are
> being duplicated. I am aware of the whole additive nature of appenders
> and I am pretty sure that I am doing things correctly in that regard but
> the messages continue to duplicate when running unit tests. When I run
> through a main method, they do not. Here is my configuration and the
> messages that are displayed when running unit tests.
>
> Dependencies I have included (via Ivy):
>
> <dependency org="org.slf4j" name="slf4j-api" rev="1.6.4"/>
> <dependency org="ch.qos.logback" name="logback-core" rev="1.0.0"/>
> <dependency org="ch.qos.logback" name="logback-classic" rev="1.0.0"/>
>
> Configuration:
>
> <configuration debug="true">
> <contextName>example-test</contextName>
> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
> <encoder>
> <pattern>%d{HH:mm:ss.SSS} %-5level %logger - %msg%n</pattern>
> </encoder>
> </appender>
> <logger name="com.example" level="debug"/>
> <root level="warn">
> <appender-ref ref="STDOUT"/>
> </root>
> </configuration>
>
> Log output when running unit tests:
>
> 13:44:23,308 |-INFO in
> ch.qos.logback.classic.joran.action.ContextNameAction - Setting logger
> context name as [example-test]
> 13:44:23,308 |-INFO in ch.qos.logback.core.joran.action.AppenderAction -
> About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
> 13:44:23,313 |-INFO in ch.qos.logback.core.joran.action.AppenderAction -
> Naming appender as [STDOUT]
> 13:44:23,344 |-INFO in
> ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming
> default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for
> [encoder] property
> 13:44:23,431 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction
> - Setting level of logger [com.example] to DEBUG
> 13:44:23,431 |-INFO in
> ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of
> ROOT logger to WARN
> 13:44:23,431 |-INFO in
> ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender
> named [STDOUT] to Logger[ROOT]
> 13:44:23,433 |-INFO in
> ch.qos.logback.classic.joran.action.ConfigurationAction - End of
> configuration.
>
> 13:44:23.453 INFO  com.example.project.service.impl.ExampleClassImpl -
> This is a test.
> 13:44:23.466 INFO  com.example.project.service.impl.ExampleClassImpl -
> This is a test.

Notice that the timestamps, 13:44:23.453 and 13:44:23.466 are different. 
It really looks like the log statement for "This is a test" is run 
twice. Have you tried replacing the logger calls with System.out.println 
as a comparison?

>
> Log output when running under main method:
>
> 13:48:16,729 |-INFO in
> ch.qos.logback.classic.joran.action.ContextNameAction - Setting logger
> context name as [example-test]
> 13:48:16,729 |-INFO in ch.qos.logback.core.joran.action.AppenderAction -
> About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
> 13:48:16,734 |-INFO in ch.qos.logback.core.joran.action.AppenderAction -
> Naming appender as [STDOUT]
> 13:48:16,760 |-INFO in
> ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming
> default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for
> [encoder] property
> 13:48:16,825 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction
> - Setting level of logger [com.example] to DEBUG
> 13:48:16,825 |-INFO in
> ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of
> ROOT logger to WARN
> 13:48:16,825 |-INFO in
> ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender
> named [STDOUT] to Logger[ROOT]
> 13:48:16,827 |-INFO in
> ch.qos.logback.classic.joran.action.ConfigurationAction - End of
> configuration.
>
> 13:48:16.843 INFO  com.example.project.service.impl.ExampleClassImpl -
> This is a test.
>
> I know that the unit tests are picking up my configuration correctly.
> When I examine my unit test results, I can see that tests are only being
> run once so I it is not a duplicate execution of the code. Is there
> anything special I have to do to stop the duplicates when running unit
> tests? Thanks for your help.

 From what you describe, I think the log statement for "This is a test" 
is being invoked twice.

HTH,

> --Matt--
>

-- 
Ceki
http://twitter.com/#!/ceki