search

lagom / lagom-samples

https://developer.lightbend.com/start/?group=lagom
Creative Commons Zero v1.0 Universal
86 stars 82 forks source link

Running shopping cart java tests with Maven does not work with Akka's LogCapturing #122

Closed marcospereira closed 4 years ago

marcospereira commented 5 years ago

It works with sbt and also when running the test in isolation within IntelliJ. But when running using Maven:

mvn -Dlogback.debug=true test

The following error occurs:

Running com.example.shoppingcart.impl.ShoppingCartReportTest
18:44:33,671 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
18:44:33,671 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
18:44:33,671 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/Users/marcospereira/Lightbend/lagom/lagom-samples/shopping-cart/shopping-cart-java/shopping-cart/target/test-classes/logback.xml]
18:44:33,722 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
18:44:33,729 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
18:44:33,734 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
18:44:33,757 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [akka.actor.testkit.typed.internal.CapturingAppender]
18:44:33,824 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CapturingAppender]
18:44:33,825 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[akka.actor.testkit.typed.internal.CapturingAppenderDelegate]
18:44:33,825 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.cassandra] to ERROR
18:44:33,825 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.datastax.driver] to WARN
18:44:33,825 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [akka] to WARN
18:44:33,826 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
18:44:33,826 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
18:44:33,826 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CapturingAppender] to Logger[ROOT]
18:44:33,826 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
18:44:33,827 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@7fc229ab - Registering current configuration as safe fallback point
18:44:34,296 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
18:44:34,296 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
18:44:34,297 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
18:44:34,297 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [akka.actor.testkit.typed.internal.CapturingAppender]
18:44:34,297 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CapturingAppender]
18:44:34,297 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[akka.actor.testkit.typed.internal.CapturingAppenderDelegate]
18:44:34,298 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.cassandra] to ERROR
18:44:34,298 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.datastax.driver] to WARN
18:44:34,298 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [akka] to WARN
18:44:34,298 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
18:44:34,298 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
18:44:34,298 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CapturingAppender] to Logger[ROOT]
18:44:34,298 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
18:44:34,298 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@1921ad94 - Registering current configuration as safe fallback point
2019-10-31 18:44:34,915 INFO  play.api.db.HikariCPConnectionPool - Creating Pool for datasource 'default'
2019-10-31 18:44:34,932 INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
2019-10-31 18:44:34,943 INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
2019-10-31 18:44:34,949 INFO  play.api.db.HikariCPConnectionPool - datasource [default] bound to JNDI as DefaultDS
2019-10-31 18:44:36,763 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Executing cluster start task jdbcCreateTables.
2019-10-31 18:44:36,811 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Executing cluster start task slickOffsetStorePrepare.
2019-10-31 18:44:36,822 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Cluster start task slickOffsetStorePrepare done.
2019-10-31 18:44:36,827 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Cluster start task jdbcCreateTables done.
log4j:WARN No appenders could be found for logger (org.jboss.logging).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
2019-10-31 18:44:38,390 INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown initiated...
2019-10-31 18:44:38,395 INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown completed.
2019-10-31 18:44:38,418 INFO  play.api.db.HikariCPConnectionPool - Shutting down connection pool.
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 5.975 sec
Running com.example.shoppingcart.impl.ShoppingCartServiceTest
18:44:39,465 |-WARN in Logger[akka.actor.CoordinatedShutdown] - No appenders present in context [default] for logger [akka.actor.CoordinatedShutdown].
18:44:39,534 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
18:44:39,534 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
18:44:39,534 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
18:44:39,535 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [akka.actor.testkit.typed.internal.CapturingAppender]
18:44:39,535 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CapturingAppender]
18:44:39,535 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[akka.actor.testkit.typed.internal.CapturingAppenderDelegate]
18:44:39,535 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.cassandra] to ERROR
18:44:39,535 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.datastax.driver] to WARN
18:44:39,535 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [akka] to WARN
18:44:39,535 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
18:44:39,536 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
18:44:39,536 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CapturingAppender] to Logger[ROOT]
18:44:39,536 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
18:44:39,536 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@54234569 - Registering current configuration as safe fallback point
2019-10-31 18:44:39,568 INFO  play.api.db.HikariCPConnectionPool - Creating Pool for datasource 'default'
2019-10-31 18:44:39,569 INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-2 - Starting...
2019-10-31 18:44:39,569 INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-2 - Start completed.
2019-10-31 18:44:39,569 INFO  play.api.db.HikariCPConnectionPool - datasource [default] bound to JNDI as DefaultDS
2019-10-31 18:44:39,643 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Executing cluster start task jdbcCreateTables.
2019-10-31 18:44:39,653 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Executing cluster start task slickOffsetStorePrepare.
2019-10-31 18:44:39,656 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Executing cluster start task readSideGlobalPrepare-ShoppingCartReportProcessor.
2019-10-31 18:44:39,659 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Cluster start task slickOffsetStorePrepare done.
2019-10-31 18:44:39,661 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Cluster start task jdbcCreateTables done.
2019-10-31 18:44:39,852 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Cluster start task readSideGlobalPrepare-ShoppingCartReportProcessor done.
2019-10-31 18:44:40,426 INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-2 - Shutdown initiated...
2019-10-31 18:44:40,433 INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-2 - Shutdown completed.
2019-10-31 18:44:40,445 INFO  play.api.db.HikariCPConnectionPool - Shutting down connection pool.
Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.996 sec
Running com.example.shoppingcart.impl.ShoppingCartTest
Tests run: 12, Failures: 0, Errors: 12, Skipped: 0, Time elapsed: 0.083 sec <<< FAILURE!
shouldAllowGettingShoppingCartSummary(com.example.shoppingcart.impl.ShoppingCartTest)  Time elapsed: 0.002 sec  <<< ERROR!
java.lang.IllegalStateException: CapturingAppender not defined for [ROOT] in logback-test.xml
    at akka.actor.testkit.typed.internal.CapturingAppender$.get(CapturingAppender.scala:24)
    at akka.actor.testkit.typed.javadsl.LogCapturing.<init>(LogCapturing.scala:39)
    at com.example.shoppingcart.impl.ShoppingCartTest.<init>(ShoppingCartTest.java:31)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at org.junit.runners.BlockJUnit4ClassRunner.createTest(BlockJUnit4ClassRunner.java:217)
    at org.junit.runners.BlockJUnit4ClassRunner$1.runReflectiveCall(BlockJUnit4ClassRunner.java:266)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.BlockJUnit4ClassRunner.methodBlock(BlockJUnit4ClassRunner.java:263)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
    at org.junit.rules.RunRules.evaluate(RunRules.java:20)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:252)
    at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:141)
    at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:112)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189)
    at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165)
    at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85)
    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115)
    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75)

So, the correct file is picked:

18:44:33,671 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/Users/marcospereira/Lightbend/lagom/lagom-samples/shopping-cart/shopping-cart-java/shopping-cart/target/test-classes/logback.xml]

The appender is there:

18:44:34,297 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [akka.actor.testkit.typed.internal.CapturingAppender]
18:44:34,297 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CapturingAppender]

And that it is attached to the ROOT logger:

18:44:39,536 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CapturingAppender] to Logger[ROOT]
octonato commented 4 years ago

We are re-opening that issue because we observed that failing when building in MacOS.

Build passed in Travis though!

dwijnand commented 4 years ago

Problem removed by removing the use of LogCapturing in Java/Maven!