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.<br>
<br>--Matt--<br><br><div class="gmail_quote">On Fri, Jan 6, 2012 at 3:55 PM, ceki <span dir="ltr"><<a href="mailto:ceki@qos.ch">ceki@qos.ch</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Hi Matt,<br>
<br>
Response in line.<div><div class="h5"><br>
<br>
On 06.01.2012 19:53, Matt Bertolini wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Hello.<br>
<br>
I am trying to implement logback/slf4j and an extremely frustrating<br>
thing is occurring when I run my unit tests. All of the log messages are<br>
being duplicated. I am aware of the whole additive nature of appenders<br>
and I am pretty sure that I am doing things correctly in that regard but<br>
the messages continue to duplicate when running unit tests. When I run<br>
through a main method, they do not. Here is my configuration and the<br>
messages that are displayed when running unit tests.<br>
<br>
Dependencies I have included (via Ivy):<br>
<br>
<dependency org="org.slf4j" name="slf4j-api" rev="1.6.4"/><br>
<dependency org="ch.qos.logback" name="logback-core" rev="1.0.0"/><br>
<dependency org="ch.qos.logback" name="logback-classic" rev="1.0.0"/><br>
<br>
Configuration:<br>
<br>
<configuration debug="true"><br>
<contextName>example-test</<u></u>contextName><br>
<appender name="STDOUT" class="ch.qos.logback.core.<u></u>ConsoleAppender"><br>
<encoder><br>
<pattern>%d{HH:mm:ss.SSS} %-5level %logger - %msg%n</pattern><br>
</encoder><br>
</appender><br>
<logger name="com.example" level="debug"/><br>
<root level="warn"><br>
<appender-ref ref="STDOUT"/><br>
</root><br>
</configuration><br>
<br>
Log output when running unit tests:<br>
<br>
13:44:23,308 |-INFO in<br>
ch.qos.logback.classic.joran.<u></u>action.ContextNameAction - Setting logger<br>
context name as [example-test]<br>
13:44:23,308 |-INFO in ch.qos.logback.core.joran.<u></u>action.AppenderAction -<br>
About to instantiate appender of type [ch.qos.logback.core.<u></u>ConsoleAppender]<br>
13:44:23,313 |-INFO in ch.qos.logback.core.joran.<u></u>action.AppenderAction -<br>
Naming appender as [STDOUT]<br>
13:44:23,344 |-INFO in<br>
ch.qos.logback.core.joran.<u></u>action.NestedComplexPropertyIA - Assuming<br>
default type [ch.qos.logback.classic.<u></u>encoder.PatternLayoutEncoder] for<br>
[encoder] property<br>
13:44:23,431 |-INFO in ch.qos.logback.classic.joran.<u></u>action.LoggerAction<br>
- Setting level of logger [com.example] to DEBUG<br>
13:44:23,431 |-INFO in<br>
ch.qos.logback.classic.joran.<u></u>action.RootLoggerAction - Setting level of<br>
ROOT logger to WARN<br>
13:44:23,431 |-INFO in<br>
ch.qos.logback.core.joran.<u></u>action.AppenderRefAction - Attaching appender<br>
named [STDOUT] to Logger[ROOT]<br>
13:44:23,433 |-INFO in<br>
ch.qos.logback.classic.joran.<u></u>action.ConfigurationAction - End of<br>
configuration.<br>
<br>
13:44:23.453 INFO com.example.project.service.<u></u>impl.ExampleClassImpl -<br>
This is a test.<br>
13:44:23.466 INFO com.example.project.service.<u></u>impl.ExampleClassImpl -<br>
This is a test.<br>
</blockquote>
<br></div></div>
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?<div>
<div class="h5"><br>
<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<br>
Log output when running under main method:<br>
<br>
13:48:16,729 |-INFO in<br>
ch.qos.logback.classic.joran.<u></u>action.ContextNameAction - Setting logger<br>
context name as [example-test]<br>
13:48:16,729 |-INFO in ch.qos.logback.core.joran.<u></u>action.AppenderAction -<br>
About to instantiate appender of type [ch.qos.logback.core.<u></u>ConsoleAppender]<br>
13:48:16,734 |-INFO in ch.qos.logback.core.joran.<u></u>action.AppenderAction -<br>
Naming appender as [STDOUT]<br>
13:48:16,760 |-INFO in<br>
ch.qos.logback.core.joran.<u></u>action.NestedComplexPropertyIA - Assuming<br>
default type [ch.qos.logback.classic.<u></u>encoder.PatternLayoutEncoder] for<br>
[encoder] property<br>
13:48:16,825 |-INFO in ch.qos.logback.classic.joran.<u></u>action.LoggerAction<br>
- Setting level of logger [com.example] to DEBUG<br>
13:48:16,825 |-INFO in<br>
ch.qos.logback.classic.joran.<u></u>action.RootLoggerAction - Setting level of<br>
ROOT logger to WARN<br>
13:48:16,825 |-INFO in<br>
ch.qos.logback.core.joran.<u></u>action.AppenderRefAction - Attaching appender<br>
named [STDOUT] to Logger[ROOT]<br>
13:48:16,827 |-INFO in<br>
ch.qos.logback.classic.joran.<u></u>action.ConfigurationAction - End of<br>
configuration.<br>
<br>
13:48:16.843 INFO com.example.project.service.<u></u>impl.ExampleClassImpl -<br>
This is a test.<br>
<br>
I know that the unit tests are picking up my configuration correctly.<br>
When I examine my unit test results, I can see that tests are only being<br>
run once so I it is not a duplicate execution of the code. Is there<br>
anything special I have to do to stop the duplicates when running unit<br>
tests? Thanks for your help.<br>
</blockquote>
<br></div></div>
>From what you describe, I think the log statement for "This is a test" is being invoked twice.<br>
<br>
HTH,<br>
<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
--Matt--<br>
<br><span class="HOEnZb"><font color="#888888">
</font></span></blockquote><span class="HOEnZb"><font color="#888888">
<br>
-- <br>
Ceki<br>
<a href="http://twitter.com/#%21/ceki" target="_blank">http://twitter.com/#!/ceki</a><br>
______________________________<u></u>_________________<br>
Logback-user mailing list<br>
<a href="mailto:Logback-user@qos.ch" target="_blank">Logback-user@qos.ch</a><br>
<a href="http://mailman.qos.ch/mailman/listinfo/logback-user" target="_blank">http://mailman.qos.ch/mailman/<u></u>listinfo/logback-user</a><br>
</font></span></blockquote></div><br>