The spf4j-slf4j-test module is a backend implementation for the slf4j api.
This is an opinionated logging backend implementation for testing(junit) with the following features:
Add to your pom.xml dependency section (make sure it is ahead of other slf4j backends you might have in your classpath):
<dependency> <groupId>org.spf4j</groupId> <artifactId>spf4j-slf4j-test</artifactId> <scope>test</scope> <version>LATEST</version> </dependency>
Register the junit runListener in your surefire plugin config:
<plugin> <groupId>org.apache.maven.plugins</groupId> <artifactId>maven-surefire-plugin</artifactId> <configuration> <properties> <property> <name>listener</name> <value>org.spf4j.test.log.junit4.Spf4jTestLogRunListener</value> <!-- comma separate multiple listeners --> </property> </properties> </configuration> </plugin>
Or if your IDE is not smart enough (you InteliJ and Eclipse) to pick the run listeners up from your pom.xml, you can use the Spf4jTestLogJUnitRunner in conjunction junit @RunWith annotation. If you have CustomClassRunners already, you can easily upgrade them to register Spf4jTestLogRunListener as done in Spf4jTestLogJUnitRunner.
NOTE: since logging is JVM global, you should run your unit tests single threaded to be able to easily reason about your logging, and more accurate log message attribution.
When using junit 5 you will need to use:
<dependency> <groupId>org.spf4j</groupId> <artifactId>spf4j-slf4j-test-junit5</artifactId> <scope>test</scope> <version>LATEST</version> </dependency>
you will not need to manually specify the listener, this will happen automatically through the ServiceLoader mechanism.
When running on java 9 or higher you will receive warnings like:
WARNING: Illegal reflective access by ...
you can remove these warnings by adding to you java command line:
--add-opens=java.logging/java.util.logging=ALL-UNNAMED --add-opens=java.base/java.lang=ALL-UNNAMED
LogAssert expect = TestLoggers.sys().expect("org.spf4j.test", Level.ERROR, LogMatchers.hasFormat("Booo")); LOG.error("Booo", new RuntimeException()); expect.assertObservation(); // whithout assert the unit test fails when logging an error.
@Test @ExpectLog(level = Level.ERROR) public void testLoggingAnnot() { LOG.error("Booo", new RuntimeException()); }
LogAssert expect = TestLoggers.sys().expect("org.spf4j.test.log", Level.ERROR, 3, TimeUnit.SECONDS LogMatchers.hasFormat("async")); new Thread(() -> { LOG.error("async"); }).start(); expect.assertObservation();
AsyncObservationAssert obs = TestLoggers.sys().expectUncaughtException(5, TimeUnit.SECONDS, Matchers.hasProperty("throwable", Matchers.any(IllegalStateException.class))); executor.execute(new Runnable() { @Override public void run() { throw new IllegalStateException("Yohoo"); } }); obs.assertObservation(5, TimeUnit.SECONDS);
try (LogCollection<Long> c = TestLoggers.sys().collect("org.spf4j.test", Level.INFO, true, Collectors.counting())) { LOG.info("m1"); LOG.info("m2"); Assert.assertEquals(2L, (long) c.get()); }
try (HandlerRegistration printer = TestLoggers.sys().print("my.log.package", Level.TRACE)) { ... LOG.error("Booo", new RuntimeException()); .. }
or for a unit test:
@Test @PrintLogs(category = "org.spf4", ideMinLevel = Level.TRACE) public void testSomeHandler2() { .... LOG.trace("test"); .... }
or a more complex print config:
@Test @PrintLogsConfigs( { @PrintLogs(ideMinLevel = Level.TRACE), @PrintLogs(category = "com.sun", ideMinLevel = Level.WARN) } ) public void testLogging() { ....
LOG.debug("log {} {} {}", 1, 2, 3, /* extra object */ 4);
will be logged as:
09:23:32.731 DEBUG o.s.t.l.TestLoggerFactoryTest "main" "log 1 2 3" ["4"]
If your objects implement JsonWriteable or you register a Json serializer for a particular type like:
LogPrinter.getAppenderSupplier().register(TestLoggerFactoryTest.class, MimeTypes.APPLICATION_JSON, (o, a) -> {a.append("{\"a\" : \"b\"}");}); LOG.info("Json Payload", this); // this will be not part of the messages string and will be logged as extra payload
will be logged like:
12:13:00.656 INFO o.s.t.l.TestLoggerFactoryTest "main" "Json Payload" [{"a" : "b"}]
For example if you have spf4j.test.log.rootPrintLevel=DEBUG and you want everything above trace available if a unit test fails, you can either set globaly spf4j.test.log.collectMinLevel=TRACE or you can control this at test level like:
@Test @CollectLogs(minLevel = Level.TRACE) public void testLogging4() { LOG.trace("lala"); LOG.debug("log {}", 1); LOG.debug("log {} {}", 1, 2); LOG.debug("log {} {} {}", 1, 2, 3); LOG.debug("log {} {} {}", 1, 2, 3, 4); Assert.fail("booo"); }
Will result in the following output:
Running org.spf4j.test.log.TestLoggerFactoryTest 09:23:32.691 DEBUG o.s.t.l.TestLoggerFactoryTest "main" "log 1" 09:23:32.731 DEBUG o.s.t.l.TestLoggerFactoryTest "main" "log 1 2" 09:23:32.731 DEBUG o.s.t.l.TestLoggerFactoryTest "main" "log 1 2 3" 09:23:32.731 DEBUG o.s.t.l.TestLoggerFactoryTest "main" "log 1 2 3" ["4"] 09:23:32.759 INFO o.s.t.l.j.Spf4jTestLogRunListenerSingleton "main" "Dumping last 100 unprinted logs for testLogging4(org.spf4j.test.log.TestLoggerFactoryTest)" 09:23:32.691 TRACE o.s.t.l.TestLoggerFactoryTest "main" "lala" 09:23:32.759 INFO o.s.t.l.j.Spf4jTestLogRunListenerSingleton "main" "End dump for testLogging4(org.spf4j.test.log.TestLoggerFactoryTest)" testLogging4(org.spf4j.test.log.TestLoggerFactoryTest) Time elapsed: 0.054 s <<< FAILURE! java.lang.AssertionError: booo at org.junit.Assert.fail(Assert.java:88) at org.spf4j.test.log.TestLoggerFactoryTest.testLogging4(TestLoggerFactoryTest.java:200) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
# default root log level when tests executed from IDE. see TestUtils.class for more info. spf4j.test.log.rootPrintLevelIDE = DEBUG # default root log level. spf4j.test.log.rootPrintLevel = INFO # default log level collected for availability when a unit test fails. spf4j.test.log.collectMinLevel = DEBUG # maximum number of logs to collect for availability in case of a failure. (by default only unprinted logs are collected) spf4j.test.log.collectmaxLogs = 100 # collect printed logs. spf4j.test.log.collectPrintedLogs # loggers where ERROR should not fail your unit tests. (comma separated) spf4j.test.log.expectingErrorsIn
You can add to your test resources a file with the name spf4j-test-prtcfg.properties or spf4j-test-prtcfg-ide.properties if you want different configuration when executing your tests from the IDE. The file format is a property file with key=values in the format:
[category(package) name]=[LOG_LEVEL](,[greedy])?
You can control TimeSource like:
@Test public void testAssertionError() { TestTimeSource.setTimeStream(0L, 1L, 2L); Assert.assertEquals(0L, TimeSource.nanoTime()); Assert.assertEquals(1L, TimeSource.nanoTime()); ....
[ISO UTC Timestaamp] [LOG Level] [Markers(jsonstr/json obj)]? [LOGGER] [THREAD(jsonstr)] [MESSAGE(json str)] [Extra Objects(array<json>)]? [StackTrace]?
sample log messages:
2018-01-25T19:55:06.080Z ERROR o.s.t.l.TestLoggerFactoryTest "main" "Hello logger" 2018-01-25T19:55:06.081Z ERROR o.s.t.l.TestLoggerFactoryTest "main" "Hello logger 1" 2018-01-25T19:55:06.081Z ERROR o.s.t.l.TestLoggerFactoryTest "main" "Hello logger 1 2 3" 2018-01-25T19:55:06.081Z ERROR o.s.t.l.TestLoggerFactoryTest "main" "Hello logger 1 2 3" ["4"] java.lang.RuntimeException at o.s.t.l.TestLoggerFactoryTest.logMarkerTests(TestLoggerFactoryTest.java:116)[test-classes/] at ^.testLogging(^:43)[^] at s.r.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_162] at ^.invoke(^:62)[^] at s.r.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[^] at j.l.r.Method.invoke(Method.java:498)[^] ...