|
»
Log Messages duplicate when running unit tests.
|
View:
New views
3 Messages
—
Rating Filter:
Alert me
|
 |
Log Messages duplicate when running unit tests.
by Matt Bertolini
::
Rate this Message:
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. 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. --Matt-- _______________________________________________ Logback-user mailing list Logback-user@... http://mailman.qos.ch/mailman/listinfo/logback-user |
|
|
Re: Log Messages duplicate when running unit tests.
by Ceki Gulcu
::
Rate this Message:
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@... http://mailman.qos.ch/mailman/listinfo/logback-user |
|
|
Re: Log Messages duplicate when running unit tests.
by Matt Bertolini
::
Rate this Message:
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@...> wrote: Hi Matt, _______________________________________________ Logback-user mailing list Logback-user@... http://mailman.qos.ch/mailman/listinfo/logback-user |
| Free embeddable forum powered by Nabble | Forum Help |
