As a developer I recognise the importance of generating logs for the systems that I help design and develop. At the outset often everyone recognizes the importance of logging but somehow it’s very difficult to engage stake-holders in requirements.
Building an application or system is a learning process that involves feedback. Agile software development practices highlight the importance of these feedback cycles with showcases of the developing application. Quite often these ceremonies highlight the functionality delivered and leave little room for conversations around cross functional requirements. For most development projects this is quite reaonable - after all the functionality is what is going to generate revenue. Logging and other cross functional requirements are considered a cost of doing business. This is true for logging as much as other cross cutting concerns.
Despite this lack of interest during development, development teams include logging for their own benefit - pre-production evaluation and a future insurance when things go wrong.
Logging often becomes a topic as systems are deployed into production and receiving customer traffic. Even with continuous deployment into production environments it’s not until customers are actively using the application that stakeholders become very interested in logging.
- Not testing logs
-
The impact of not testing logging was brought home to me on a project recently. We were using the ELK stack. Our services produced JSON formatted structured logs that were then shipped to ElasticSearch. ElasticSearch has a great capabiltiy of generating its own schema (mapping in ElasticSearch terminology). This is a great feature, until you dump an object graph into your log message and end up with MBytes mapping file and things start to really slow down.
Assuming everyone recognizes the importance of logging why is it typically not rigorously tested beyond visual inspection prior to release? With release and functional development time pressures and that visual inspection is relatively inexpensive arguing for more comprehensive testing is hard. We need to make automated testing of logging easy. IMO this means tools that are easy to introduce and less expensive to maintain than the occasional visual inspection.
The available techniques are not that well known and without a simple way of testing logging other aspects that are easier to test get tested.
Logging is complex
Logging is a deceptively complex topic. Over logging leads to performance impact and storage issues. Storage is particularly relevant in regulated environments logs often need to be retained for extended periods. What needs to be logged and at what level is often a contentious topic. Partly because these rules or guidelines try to apply to all parts of a system.
HTTP response codes are a really good example of where context matters.
Codes starting with 4 are considered client errors (e.g. 404 Not found). The client is asking for something that the server knows nothing about. Maybe its a race condition or some coding issue in the client application. Because the code is an 'error' it is often logged as such within the server. IMO this should be logged as at WARN level - it becomes a server issue if a lot of 404 errors are returns not if there is only one or two.
For the client receiving a 4xx response the situation is very different. Typically this would be considered an ERROR.
These are examples of general logging rules that development teams often agree on. They affect aspects of the system. The HTTP example above would be handled in the client HTTP libraries and in the server HTTP request handling code. The controller in MVC.
To be useful the log would need to contain the request, context and the response. At this point we need to consider how to test these capabilities that apply to a layer within our architecture.
Some data should not be logged. Credit card details and other personal data items either need to be excluded from the log or masked so they are of little or no use without additional context.
These tests are general and typically apply to a set of components - e.g. Web services.
Testing these general requirements is difficult because they apply based on code responsibilities. One of the most common service patterns is Model View Controller (MVC). In MVC general informational logging is a responsibility of the controller. It handled the request, initiates changes to the model and delegates responses to the view. Errors and exceptions are often handled either by the controller or the framework being used.
- A testing requirement might be
-
-
All requests are logged at INFO level and contain the supplied request parameters and response code.
-
To satisfy this requirements the test code needs to recognize calls to controllers, capture the generated log messages and compare the log content with the parameters of the particular request.
Testing Cross cutting requirements
Testing that cross cutting requirements are met is a tougher challenge than testing specific scenarios. Requirements are often given like this:
-
all requests are logged with their parameters and reponse codes.
-
Exceptions are logged at level x
-
All log messages are in JSON line format
Some environments may go further
-
All method entry and exist points are logged with parameters
-
Sensistive personal information is masked in logs.
Verifying these requirements automatically requires that first of all we have a very high level of test coverage to make sure that all the interesting methods that produce logs. We need to recognize when an interesting method has executed, capture the logs generated during that execution and check them against the agreed rules.
Most of the projects that I have worked on over the last few years have used a web framework. These frameworks provide some really useful abstractions over the complex world of HTTP request/response processing. Each framework presents its own challenges to identifying the methods that generate logs.
At least we can check the log formats…
Testing specific log requirements is a little simpler.
Testing Specifics
There are times when we want to write an automated test to verify that a particular method or class generates a log entry given a specific set of inputs. In most cases these are related to failure scenarios.
We could consider testing the generated log files themselves. After each test run example the expanding logs for format and structure.
Logging frameworks are very flexible, allowing both static (configuration file) and runtime customization. Appenders and formatters can be configured, loaded and unloaded at runtime. Tests can take advantage of this flexibility and runtime configuration to verify that logging is being generated as expected.
We need both specific tests for a function or class e.g. Given this invalid value a log containing the value is output at a particular log level. We also need more cross cutting tests e.g. All logging contains a component name and are JSON formatted.
The example test below is taken from a github project https://github.com/grahambrooks/testing-logging put together to show the basics of wiring up a logging appender in Log4j2./
@BeforeAll
public static void addAppender() {
ConfigurationBuilder<BuiltConfiguration> builder = ConfigurationBuilderFactory.newConfigurationBuilder();
builder.setConfigurationName("LogTestingBuilder");
AppenderComponentBuilder appenderBuilder = builder.newAppender("TestLogging", "TestingLoggingAppender");
builder.add(appenderBuilder);
builder.add(builder.newRootLogger(Level.ALL).add(builder.newAppenderRef("TestLogging")));
LoggerContext context = Configurator.initialize(builder.build());
context.start();
}
@Test
@DisplayName("Some long name that could be the method name.")
public void testLogging() {
assertLogs("Global logger", () -> AClassThatLogs.functionLoggingWithRootLogger());
assertLogs(INFO, "Global logger", () -> AClassThatLogs.functionLoggingWithRootLogger());
}
@Test
public void testDefaultLoggerCapture() {
assertLogs(INFO, "Default logger info message", () -> AClassThatLogs.functionThatUsesDefaultLogger());
}
@Test
public void testNamedLoggerCapture() {
assertLogs(TRACE, "Named logger info message", () -> AClassThatLogs.functionThatUsesNamedLogger());
}
@Test
public void testMultipleLogsDuringASingleCall() {
List<LogEvent> logEvents = assertLogs(() -> AClassThatLogs.multipleLogMessages());
assertEquals("Message 1", logEvents.get(0).getMessage().getFormattedMessage());
assertEquals("Message 2", logEvents.get(1).getMessage().getFormattedMessage());
assertEquals("Message 3", logEvents.get(2).getMessage().getFormattedMessage());
assertEquals("Message 4", logEvents.get(3).getMessage().getFormattedMessage());
assertEquals("Message 5", logEvents.get(4).getMessage().getFormattedMessage());
}Wrapping Up
More investment in tools to make testing logging easier for teams. At the moment the effort required in early investment during a project is not seen as an urgent need. So each project follows the same pattern leaving logging testing to be a very late if at all activity.
It would be great to see framework developers provide easier ways to verify cross cutting logging requirements.
In the interim testing specific logging actions is possible with a little work with your favorite logging and unit testing frameworks. Hopefully we will see more support for this style of testing in the future.