In the first article in this series we looked at a simple way of capturing and verifying logging statements using a static list appender. The static list appender method works great if you are executing your test suite in a single thread, but isn’t practical when executing tests in parallel due to all the logging statements being written to a single list.

Whether or not a test suite can be executed in parallel should not depend upon if there are tests case verifying logging statements. We shouldn’t need to choose between a fast executing test suite or an application that produces accurate logging statements. So in this article we are going to look at a couple different methodologies for testing logging statements in a multi-threaded environment. We will also preview some of the new parallel testing features coming in JUnit 5.3, which should be released sometime in August.

Using a Thread Safe Appender

Parallel test execution works by spinning up multiple threads and using those threads to execute test simultaneously. This causes havoc when using a single list to capture logging statements across the entire JVM, but a way to get around this is to create a new list in each thread. To accomplish this we will make use of the ThreadLocal functionality in Java. Here is an example of an appender using ThreadLocal to capture logging statements:

In the code above we have the static field threadLocal that will accept a Listof ILoggingEvents. When append() is called the appender will retrieve the List for the current thread. If no list is present a new List is initialized and added to ThreadLocal. Finally the logging statement is added to the list.

getEvents() will retrieve the list of logging statements for the current thread and clearEvents() will remove the logging statements for the current thread. This class is pretty similar to StaticAppender, just with a few tweaks.

Configuration will look more or less the same, just we will be referencing the ThreadSafeAppender instead of StaticAppender:

The next step is configuring Maven to execute the test suite in parallel. The updated surefire configuration looks like this:

There are several different options for executing a test suite in parallel in JUnit 5.3, in this example we are using the dynamic behavior. Dynamic behavior with a factor of “1” means that for each core that is available on the computer executing the test suite, create a thread to execute tests. So if a computer has two cores, then JUnit will create two threads to execute tests with. There is also fixed, and custom, and you can read more about the parallel test support in JUnit 5.3 here.

We will be reusing the same scenario from the last article of printing out two log statements; one in the same thread of the test case being executed and also spinning up a separate thread to write a second log message, here it is again:

This scenario is designed to demonstrate the major shortcoming of the thread safe method, which will be covered in more detail in a moment.

For the test class we will essentially set it up to run the same scenario twice, with only a small difference in the logging ouput:

Looking at the test cases, I am only checking for a single logging statement despite two being written by the code under test. This is the major shortcoming with the ThreadSafeAppender, a new list is being created for each thread, not for each test case. So if the code under test creates a new thread itself, any logging statement within that new thread will be written to a separate list that the test case won’t have (easy) access too.

Typically this isn’t going to be a problem. First, writing code that spins and executes code in a separate thread isn’t that common of a need. Second, following the single responsibility principle, code that is being executed in a separate thread should be in its own class, which can then be tested independently.

That said, there might still be times where this does happen. Maybe like in the scenario above the code being executed in a separate thread is so trivial that it might not warrant a separate class, or maybe you inherited a code base that didn’t follow the single responsibility principle and you want to be able to write some tests that cover that area before you refactor it. Luckily there is a solution, which I will cover below, but first I need to talk about issues of executing tests in parallel that will apply to both methodologies.

The Joys of Concurrency

If you copy and pasted the above code into a project it would work when executing within your preferred IDE (I personally tested in Eclipse), however that is only being executed using a single thread, and if you tried running mvn test you probably get some tests failures and text that looks like the below printed to the console:

SLF4J: A number (4) of logging calls during the initialization phase have been intercepted and are
SLF4J: now being replayed. These are subject to the filtering rules of the underlying logging system.
SLF4J: See also http://www.slf4j.org/codes.html#replay

This is really only a problem that would occur when executing tests in parallel and wouldn’t really impact a deployed application. Unfortunately this will lead to “flickeringh tests” (tests that don’t pass or fail in a consistent manner) and so this issue must be addressed.

First to describe the problem. What is happening is tests are being executed before logback has initialized. This is because logback is being initialized in a separate thread and the threads executing the tests do not know this. SLF4J recognizes this, captures the log statements, and then replays them. SLF4J isn’t doing anything wrong, in-fact it is being very helpful, unfortunately for us though the replay isn’t happening until after the assert phase of some test cases, so they end up failing.

The good news is there is a work-around, and it is pretty easy to implement. What we need is to find a way to check if logback is ready, and not let a test class execute and until that check passes. Here is some code that is performing that check:

Before logback is ready, calling getILoggerFactory() will return a default SLF4J implementation of ILoggerFactory. So the while loop is designed to to block execution of the test class until it breaks when getILoggerFactory()returns the logback implementation of ILoggerFactory; LoggerContext.

For convenience, I implemented this behavior using JUnit 5’s new extension model, so that I can simply add @ExtendWith(LogbackInitializerExtension.class) at the top of a test class that will be checking log statements. Otherwise I would have to add a @BeforeAll method implementing or calling pauseTillLogbackReady() in every test class that is testing log statements. Don’t worry, unlike RunWith in JUnit 4, in JUnit 5 a class can have multiple extensions.

I can further simplify this process by creating a custom annotation, so instead of @ExtendWith(LogbackInitializerExtension.class), which might be confusing to remember, I can just add @LogbackInitializer to the top of a test class. Creating a custom annotation with JUnit 5 is pretty easy:

Figuring this all out was admittedly a bit of a headache, but resolving these problems that crop up when executing tests in parallel doesn’t require complex configuration or relying on what I would call “winking” solutions, such as using wait timers to delay test case execution. Such solutions can lead to the flickering test failures described earlier in the article, or just unnecessarily slow down the execution of your test suite, which defeats the whole purpose of executing the test suite in parallel in the first place!

Using a Local Appender

Using the “Thread Safe” method is the method I would recommend for testing logging statements when executing tests in parallel, primarily because of its ease of configuration. However as explained above you might have inherited a poorly written code base or don’t want to separate your code out. If that is the case then you might want to try what I call the “Local Appender” method.

I call this the “Local Appender” method because you will be setting up a new appender for every test case where you will be verifying logging statements (i.e. an appender local to each test case). The advantage is this appender will capture logging statements executed in threads separate from the test case, resolving the major disadvantage of the Thread Safe method, but at cost of additional configuration overhead, which will be covered below.

The first step is implementing the appender:

The bare essential elements of the LocalAppender are pretty similar to the StaticAppender from the previous article, the only difference is the List is an instance member instead of a static one and in the constructor we are starting the appender.

The other differences aren’t strictly necessary but are present for convenience. initialize() is a factory method for creating new LocalAppenders. initialize() is taking in logger coordinates and configuring an instance of LocalAppender to only capture log statements from those loggers. The second method, cleanup(), as the name suggests cleans up the appender by stopping it and clearing out all logging statements. This frees up system resources, but really isn’t that important unless you are using a lot of LocalAppenders.

Let’s see what using the LocalAppender might look like in a test class:

So there’s a good amount going on here. Let’s walk through it step by step.

At the top I have @LogbackInitializer. Like mentioned above this is present to ensure that logback is initialized before the test cases begin executing.

Next you might notice all the test cases are marked with @ResourceLock. This is one of the new parallel features being added in JUnit 5.3. The JUnit team realized that the desire to execute tests in parallel isn’t entirely a binary decision. Most tests might be able to execute fine in parallel, but some tests might be sharing a resource, in this case logging, and so might have some special conditions around how they can be executed.

@ResourceLock takes two arguments, the resource key (which uses the valuefield), and mode which takes the values of either READ or READ_WRITE(defaults to READ_WRITE). Test cases marked READ can be executed at the same time as other test cases using the same resource marked READ, but will not be executed at the same time as a test case marked READ_WRITE that is also using the same resource. Finally @ResourceLock is applied across the entire test suite. So if we were to add @ResourceLock(value = “LOGGING”, mode = ResourceAccessMode.READ_WRITE) to a test case in one of the other test classes in the project, it wouldn’t execute at the same time as either testLocalAppenderA() or testLocalAppenderB().

Note: There is no execution order guarantee when using @ResourceLock, so a test case marked READ might be executed before or after a test case marked READ_WRITE.

Within the test cases themselves I am using the initialize() factory method I mentioned earlier and this gets at the advantage of the LocalAppender. With LocalAppender I can easily configure it to only capture logs from a very narrow area, typically the specific class (or classes) I am testing with that test case. With this fine grained control on what logging statements to capture and using features like @ResourceLock we can guarantee only the expected logging statements are being captured.

Finally justAnotherTest() and yetAnotherTest() are dummy test cases I added to further demonstrate the @ResourceLock functionality. If those annotations are removed then testLocalAppenderA() or testLocalAppenderB() might begin to fail because of the additional logging statements being written during their test execution. I would recommend trying it out!

Conclusion

If you have a very large test suite, executing tests in parallel can be a good option for cutting down build times, particularly if you have a build server with a lot of resources. Using the common method of capturing and verifying logging statements, like described in the first article, would mean either having to ignore the occasional failing test, or configuring your build to ignore those tests when the test suite is being executed in parallel (if you look at the full project I link below, I demonstrate how this can be done). Luckily though with the methods covered in this article we can execute our test suite in parallel and verify our logging statements too.

I hope also this article excited you about the upcoming JUnit 5.3 release. JUnit 5.3 should be out sometime in August and I will have an article covering some of the key new features in JUnit 5.3, as well as some changes in closely associated projects. That article will be published shortly after JUnit 5.3’s release. Until then happy testing!

The code for this article can be found here: https://github.com/wkorando/assert-logging-statements

Whether you are building microservices or monoliths, accurate and robust logging is a critical element in any application. Logging can give insight on how an application is being used and provide developers and operations with detailed information on why an error occurred. It is important then, like any other feature in an application, that we use automated tests to verify that logging statements are accurate and do not cause errors themselves.

In this two part series we will look at some strategies for capturing and verifying logging statements. In part one we will look at a simple and easy to implement strategy for when you are executing your test suite sequentially. In part two we will focus on a couple of strategies for when you are executing your test suite in parallel.

The Scenario

For demonstrating how to capture and assert logging statements we have the very useful and accurately named LogProducingService:

The LogProducingService has a single method, writeSomeLoggingStatements(), which produces a pair of logging statements. One statement written within the same thread as that of the calling test case and another statement written in a separate thread (this will be more important in part two).

Implementing a Custom Appender

In normal operation an application will typically be using either some form of a file appender to write statements to system logs, or in more recent trends, using an appender that sends statements to a message queue such as Kafka. There are some other options, but none are practical for verifying if the logging statements being produced are valid. So to handle this we will need to implement our own appender like this one:

In the above class I am extending AppenderBase and instead of printing the logging statements out to a file or sending them to a message queue I am adding them to a List. To retrieve the logging statements for asserting in a test case there is getEvents(), and to clear the list out between test cases I added clearEvents().

I named this class StaticAppender because the list I am storing the logging statements in, as well as the methods to retrieve and clear that list, are all static. This is necessary as I want to be able to globally configure my test suite using logback-test.xml; and the instance of StaticAppender that logback creates won’t be easily available to my test code. By declaring the aforementioned fields and methods static, I have easy access to the logging statements my application is producing from within my test cases.

After implementing the appender, we need to configure logback to use it:

As mentioned above I am configuring logback for my test suite using logback-test.xml and placed it in the src/test/resources directory of the project. I did this because by order of precedence logback will load logback-test.xmlfirst if it is present on classpath. So even though I have logback.xml defined in my src/main/resources, when executing my test suite I will be using StaticAppender instead of ConsoleAppender defined in logback.xml. This is important as we don’t want to modify production code so that it is aware it is running in a test scenario versus actually deployed; that is a big no-no.

Finally the test case would look something like this:

I am a huge fan of AssertJ, which I am making use of here to quickly extract out the message field from a list of ILoggingEvent and assert its value. If you want to learn more about using AssertJ in your automated testing, I wrote a blog article on that as well.

Parallel Concerns

When executing a test suite in a single thread, as would often be the case, using a static appender should work fine, as long as you are cleaning up logging statements between test cases like I am doing in clearLoggingStatements(). However if you have a large test suite and are wanting to execute tests in parallel to speed up your build times, then you will run into issues when using the StaticAppender. This is because while multiple test cases are being executed simultaneously, all their logging statements are being written to a single List. Your test cases won’t be able to know which log statements were written from the code it is executing from versus that of other test cases. There could create issues of logging statements being deleted when clearEvents() is called mid test execution.

Luckily the issues around executing tests in parallel can be overcome with relative ease which I will cover in the next article in this series.

Conclusion

Capturing and verifying logging statements is actually a pretty simple task as seen in this article. No additional libraries, beyond your logging libraries, are needed, nor is complex configuration.

While testing logging output might never be the highest priority for a development shop, it is useful to know that testing logging output is easy and practical. Writing some tests for the logging statements your application is producing might save you some frustration next time you have a production issue and you are able to look through accurate and detailed logs as you track down the cause of the problem.

The code for this article can be found here: https://github.com/wkorando/assert-logging-statements