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 <[email protected]> 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 > [email protected] > http://mailman.qos.ch/mailman/**listinfo/logback-user<http://mailman.qos.ch/mailman/listinfo/logback-user> >
_______________________________________________ Logback-user mailing list [email protected] http://mailman.qos.ch/mailman/listinfo/logback-user
