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

[Matt Bertolini]

I spent the last 4 hours pouring over my code and I finally found a bug in
my ant script related to the code coverage/junit tests. That bug was
causing the test to run twice. I apologize for posting on the Logback list
when it was clearly my mistake. Thanks for your help.

--Matt--

On Fri, Jan 6, 2012 at 3:55 PM, ceki <ceki at 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 at qos.ch
> http://mailman.qos.ch/mailman/**listinfo/logback-user<http://mailman.qos.ch/mailman/listinfo/logback-user>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20120106/f0b4a645/attachment-0001.html>