On Fri, Jan 6, 2012 at 3:55 PM, ceki <ceki@qos.ch> wrote:

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
_______________________________________________
Logback-user mailing list
Logback-user@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user