During development of server-side software, I routinely encountered requirements to audit logging. This ranged from logging routine events such as system startup and shutdown, to information when errors occur. For example, a component I worked on was responsible for generating binary data structures and forwarding them to a distribution component. The data generator must limit the size of the structures to protect end devices from data packets that were too large to be processed within their resource constraints. The requirements stipulated that data attributes should be placed into the structure in ascending order, and an error message shall be logged in the audit log for any attributes that were not included in the structure. I have added verification on audit logging in the unit tests that test the handling of attribute omission. Since unit tests have been implemented to check the error handling already, it was not much more effort to include checks on the logging for the same conditions.
A naïve approach to unit test logging is to create the error within a unit test, write the log to a file, read the log file from disk, and then search the file for the expected error message. However, there is a simpler and more elegant way to assert logging behavior by using mock objects. By adding a mock Appender to the target Logger, all log requests to the target Logger are now also forwarded to the mock Appender. Logging events can then be verified directly with the mock Appender.
I use JUnit and Mockito for my unit testing. The following code snippet sets up a mock Appender for use in the unit test class.
@Mock private Appender appender;
private static final Logger AUDIT = Logger.getLogger("org.whileloop.org.data.generator");
@Before
public void setUp() {
AUDIT.addAppender(appender);
}
@After
public void tearDown() {
AUDIT.removeAppender(appender);
}
To assert that a log message is written during a unit test, I use Mockito’s verify on the mock Appender’s doAppend method:
verify(appender).doAppend((LoggingEvent) anyObject());
Obviously, this only checks for the existence of a log message when the unit test is run. I normally run our unit tests with logging at trace level to make sure logging calls at the lowest level are exercised. If a debug message is written during the unit test, the above verification will pass even when no error messages were written.
Mockito’s ArgumentCaptor can be used to check for a specific message at a specific logging level. The following code captures all the LoggingEvents that occur in a unit test. It then iterates over the list of captured events, checking their logging level and message content. If one of the log messages matches the expected level and keyword, then the test will pass the assert statement after the loop. Searching for an exact match in the message could lead to brittle tests. They will break if the log message is updated. Therefore I prefer searching for keywords like ‘error’, ‘exceeds’, ‘dropped’ instead.
verify(appender, atLeastOnce()).doAppend(argumentCaptor.capture());
List<LoggingEvent> loggingEvents = argumentCaptor.getAllValues();
for (LoggingEvent le : loggingEvents) {
if (le.getLevel().equals(ERROR) &&
le.getMessage().toString().contains(keyword) {
matched = true;
}
}
assertTrue("Cannot find error message [" + keyword + "] in audit log", matched);
Mock objects provide an easy way to test logging in unit tests. To do this I exploit the fact that a mock object remembers all its interactions. Logging can be verified by looking at interactions with the mock Appender’s doAppend method, instead of reading and parsing the log file on disk. By including logging in unit tests, I can verify that audit logging requirements are fulfilled. It also guards against future changes to the code from inadvertently breaking the logging requirement compliance. Problems with audit logging caused by refactoring can be caught during development automatically, removing the chance that the failure could reach testers or even clients.
This post was originally written and published in August 2013 for a newsletter.
