Logging has been around on the JVM for a while now. It all started with Log4J back in 2001. Log4J was the first logging framework and it is still around today (in its version 2). It provides a simple and efficient API (compare to System.out.println that was in use before).
- Get a logger for a class
- Use that logger to log messages
val logger = Logger.getLogger(classOf[MyClass])
...
logger.log(Level.DEBUG, "I am doing something right now")
...
logger.error("Oops, something went wrong", theException)
...
Today there are a few more frameworks on the JVM but they all provide similar APIs as Log4J:
- JUL(2002): java.util.logging provides a standardisation of Log4J and of course provides a similar API
- Commons-logging (2002): Apache project providing a façade over Log4J, JUL, … still the same API
- SLF4J (2005): Another façade over Log4J (1&2), JUL, JCL, … no much changes in the API
- Logback (2006): Brings structured logging with an API compatible (and similar) to SLF4J (and Log4J)
- Log4J2 (2012): Rewrite of Log4J inspired by Log4J and Logback with improved performances. The API does not change much though.
As you can see the logging APIs available on the JVM haven’t changed much over the last 15 years. The most interesting additions are structured logging and the Mapped Dependent Context (MDC) as we shall see later.
In this post I am going to look at the current limitations of these APIs and see how we can overcome them while still relying on this frameworks to actually write the logs.
Let’s start by looking at some of the problems inherent to the Log4J-family API.
Unnecessary string computation
When one call:
logger.debug("User "+userId+" connected to "+endpoint)
// or using scala string interpolation
logger.debug(s"User $userId connected to $endpoint")
The problem with this API is that the String containing the debug message is computed even though the debug level is disabled. If we had checked the log level first we could have avoided a (potentially expensive) string computation.
One obvious solution is to actually wrap the log instructions into an if statement:
if (logger.isDebugEnabled()) {
logger.debug(s"User $userId connected to $endpoint")
}
This surely solves the problem but on the other hand it clutters the code with cumbersome if statements. We’d like to have our log statements as discreet as possible so that they don’t dilute too much the intent of the code.
A partial solution to this problem was to use place holders in the messages so that the placeholders are only replaced if the log level is enabled.
logger.debug("User {} connected to {}", userId, endpoint)
It seems fine but consider this logging statement:
logger.debug("The very expensive result is {}", computeSomeVeryExpensiveResult())
Now if the debug level is disabled this call still performs a very expensive computation because in Java the arguments are always evaluated before the function call.
Luckily Java (since version 8) supports lambda expressions so we can fix this problem by wrapping the log message into a lambda:
logger.debug(() -> "The very expensive result is "+computeSomeVeryExpensiveResult())
Now the message is only computed if the debug level is enabled and avoid the expensive computation otherwise.
This API is already available in JUL and Log4J2 but not in SLF4J which is still widely used on the JVM.
Of course Scala support similar lambda expressions although not (yet) compatible with their Java counter-parts. Scala also supports call-by-name parameters where such parameters are not evaluated before invoking the function. We can leverage this to avoid cumbersome if statements (and even lambda calls) in our logging API as we shall see.
No fine-grained log level configuration
On Log4J-like APIs the log levels are defined per logger and there is usually one logger per class. It doesn’t have to be this way as one can create a logger with any given name, but a logger for each class has become standard practice. So much that the Logger.getLogger method also accepts a class as parameter.
Anyway it means that the most fine-grained configuration level is the class level. Now imagine that your application handles thousands of requests per second and you have a problem with only a specific request (let’s say that the problem occurs only for a specific user). If you need to turn the debug logs on you have no choice but to enable it for the whole class logging thousands of useless debug messages per second. You’ll then have to look for that particular logs of interests among all of these messages. Not ideal!
Obviously we can create one logger for each user and enable the debug level only for the user of interests but that would be a lot of logger to deal with.
Instead several frameworks (Log4J2, Logback, SLF4J) provides MDC (Mapped Dependent Context) logging. What we need is actually a way to enable a log level according to the content present in the MDC.
Log levels are enabled globally. The debug level is enable for a whole class (or it isn’t) whoever calls the methods in this class. For example imagine a utility class for which you want to enable debug messages only when called through a given class. Well, there is no way to configure such things are debug messages are enable/disable globally for a class.
Inconsistent log messages
Many times I have seen recommended logging policies trying to define when a log level should be used or what components should be logged in a message or even how log messages must be formatted… There were always good reason behind such policies, however in the end of the day is the developer who writes the log messages and most often than note these policies are not correctly applied in the code based.
It’s true that code-review process can help here but the truth is that logging is never a priority. As a result log messages are many and varied making it more difficult to look for patterns.
Using MDC in a multi-threaded environment
In Log4J-like framework that provide MDC functionality the context is always build up using global method.
MDC.put("user.id", user.getId())
MDC.put("transaction.id", transaction.getId())
...
logger.debug("Doing something here")
...
MDC.clear()
Of course using a global method would be terrible in a multi-threaded environment. What happens if multiple users requests are served simultaneously. Does it mess up the entire context? Of course not! In fact the MDC is backed by a ThreadLocal variable. It means that although it looks like that there is one unique global variable there is actually one map per thread.
That’s nice because as long as we stay on the same thread we can use the MDC to pass the context around. Calling a nested method preserves the MDC context and in fact the MDC content is also available within the nested method where it can be enriched or used in log messages.
The problem comes when the control flow passes onto another thread. This is the case when calling a service that is backed up by a dedicated ThreadPool or ExecutorService. The MDC doesn’t cross such boundaries. The developper needs to get the current MDC and pass it explicitly to the target service.
Logging is (almost) never tested
Logging is most often not a priority plus it’s not easy to test. How do you check that the expected log messages have been logged? Do you have to read the log file of the tests?
The main problem is that the logger instance is retrieved directly inside the class.
class MyService {
private val logger = Logger.getLogger(classOf[MyService])
...
}
There is no (easy) way to replace it with a mock or a test instance. It would have been much easier it the logger was injected into the class:
class MyService(logger: Logger) {
...
}
Introducing Logoon
Now that we’ve seen the limitations inherent to the Log4J API let me introduce Logoon, a flexible log service that runs on top of any Log4J-like framework and addresses the above limitations (or at least tries to).
Logoon architecture
Logoon is an extra layer that sits on top of any Log4J-like frameworks (or anything that can log messages – it can even work on top of System.out).
Its main component is the LogService. This components replaces the Logger used to log messages in the application code.
Below the LogServicesits a binding layer used to bridge the LogService to the underlying logging framework.
Logoon also defines its own log levels which are identical to the ones provided by Log4J.
Finally the LogContext provides the MDC functionality.
The Log Service
The LogService is the main component. It needs to be extended into a subclass that provides a LoggerAdapter and LogLevelConfig instances.
By-name parameters
All logging methods take by-name parameters allowing to compute the messages only if the required log level is enabled.
log.info(s"Some expensive computation result: ${computeSomeExpensiveResult()}")
As info takes a by-name parameter the message parameter is not evaluated on the function call. It allows to check for the effective log level first and then compute the string only if the log level is enabled.
We got the best of both world: A nice syntax without surrounding if statement nor lambda call.
Log4J compatible API
The LogService provides Log4J-like API to ease the integration with existing code. It provides all the familiar logging method: debug, info, error, …
However this is not the recommended usage as it always leads to inconsistent log messages spread throughout the code base.
Extensibility
LogService is also a natural place to gather all the logs messages of an application or service.
class RestApiLogService(
val loggerAdapter: LoggerAdapter,
val loggerConfig: LogLevelConfig
) extends LogService {
override val name: String = "RestApi"
def restApiCalled(
request: Request,
response: Response,
duration: Long
)(implicit context: LogContext): Unit = {
val url = request.url
val res = response.statusCode
info("RestApiPerf", s"$url ($res) - ${duration}ms")
if (duration > 100) warn("RestApiAlert", s"$url ($res) - ${duration}ms")
}
def startTransaction(user: String, id: Int)(implicit context: LogContext): Unit =
info("start transaction $id - $user")
def endTransaction(user: String, id: Int, res: Int)(implicit context: LogContext): Unit =
info("end transaction $id - $user: $res")
...
}
By gathering all the log messages into our LogService it’s a lot easier to come up with consistent logging messages.
Then the application code simply looks like
class MyRestController(log: RestApiLogService) {
...
def myEndpoint() = Action { request =>
val startTime = System.currentTimeMillis()
val transaction = ...
log.startTransaction(request.user.id, transaction.id)
transaction.start()
// do more things here
// ...
val result = transaction.commit()
log.endTransaction(request.user.id, transaction.id, result)
// build response
// ...
val elapsedTime = System.currentTimeMillis() - startTime
log.restApiCalled(request, response, elapsedTime)
}
}
...
}
All the log messages have been replaced by specific business calls log.restApiCalled(...), etc.
It makes the application code much clearer with short and concise logging calls and all the log messages are “unified” inside the ResApiLogService.
Integration with existing frameworks
Moving down one layer, let’s see how Logoon integrates with existing frameworks.
In fact it doesn’t impose any framework at all. All it needs is a way to log messages. This is done by implementing the LoggerAdapter trait.
trait LoggerAdapter {
def log(
name: String,
level: LogLevel,
message: => String,
context: Map[String, String]
): Unit
def log(
name: String,
level: LogLevel,
message: => String,
throwable: => Throwable,
context: Map[String, String]
): Unit
}
As you can see there is no constraints imposed here. All you need to do is provide an implementation of this trait. It can even be implemented using System.out. You can have a look at some adapters examples in the test directory.
The second things that needs to be provided is a way to set and retrieve log levels as defined by the LogLevelConfig trait:
trait LogLevelConfig {
def logLevel(name: String): LogLevel
def setLogLevel(name: String, level: LogLevel): Unit
...
}
Here again there is no constraint on the implementation. It can be done by converting the log levels and then delegating the calls to the underlying frameworks.
It can also be done using a simple Map[String, LogLevel] instance.
The LogContext is provided as a regular Map[String, String] to be easily compatible with the MDC API provided by the underlying framework. All you need to do is place all the entries into the underlying MDC (if available) before logging the message.
With Log4J2 it looks like this:
val existingContext = ThreadContext.getImmutableContext ThreadContext.clearMap() ThreadContext.putAll(context.asJava) // log the message here ThreadContext.clearMap() ThreadContext.putAll(existingContext)
Configuration
Logoon strives to provide fine-grained control over the log levels in order to be able to enable logging only for the required messages. The main idea is that log levels now depends on the content of the log context.
Configure log levels for context entries
Ideally all the LogContext would contain an entry for the classname. Therefore we could still achieve the same functionality as the one-logger-per-class by enabling logging for a given classname
val config: LogLevelConfig = ...
config.setLogLevel("classname.com.myapplication.MyService", LogLevel.DEBUG)
It’s also possible to enable the logging only for a given user id:
val config: LogLevelConfig = ...
// enables debugging only for user with id 1234
config.setLogLevel("user.id.1234", LogLevel.DEBUG)
Whenever the LogContext contains a user.id entry with the value 1234 the DEBUG level is enabled.
That’s quite powerful as it’s now possible to enable logging on many different criteria.
Note that the LogContext always contains an entry log.service for the log service used to log the message. This entry can be used to set the log level for a given service.
As the LogContext contains multiple values there are probably multiple log level configured for a given context. In this case it’s always the entry with the lowest value that is chosen as the effective log level.
Of course it would be nice to be able to combine multiple entries to specify a log level. Something like
IF log.service = MyRestService AND user.id = 1234 THEN level = DEBUG
The LogLevelConfig trait already provides a method that checks if a specific level is enabled for a given LogContext
trait LogLevelConfig {
...
def isLogEnabled(level: LogLevel, context: LogContext): Boolean = {
import scala.Ordering.Implicits._
level < LogLevel.OFF && context.exists {
entry => logLevel(s"${entry.key}.${entry.value}") <= level
}
}
}
However this is not supported and it’s not directly possible using the underlying frameworks for the level configuration.
Using multiple log level configuration
One of the caveat of the Log4J-family frameworks is that the log level configuration are global. Once a logger is enabled it is enabled for anyone who calls its methods.
Logoon suffers from the same limitation if the LogLevelConfig is backed by such frameworks. However if using different instances (e.g. by using a simple class with a Map[String, LogLevel] to store the log level configuration)
class InMemoryLogLevelConfig extends LogLevelConfig {
var levels: Map[String, LogLevel] = Map("" -> LogLevel.OFF)
override def logLevel(name: String): LogLevel =
levels.get(name) match {
case Some(level) => level
case None => logLevel(name.substring(0, name.length - 1))
}
override def setLogLevel(name: String, level: LogLevel): Unit = levels += (name -> level)
}
Using such implementations allows us to configure different log levels for the same key. For instance MyRestService can use a LogLevelConfig where level for user.id.1234 is set to DEBUG. At the same time we can have another service with a different LogLevelConfig instance where the level for user.id.1234 is set to ERROR.
Underlying logger configuration
Note that as the underlying logging is performed by a Log4J-like framework, logging must be enabled for any loggers used by the LogServices. In the above example we used 3 loggers: RestApiPerf, RestApiAlert and RestApi. All log levels must be enabled for these loggers in order to be able to actually log the messages. The actual log level will be determine by the levels set for the log context entries.
Log context
The MDC functionality is provided by mean of the LogContext. The LogContext is just a wrapper around a Map[String, String]. It is passed as an implicit parameter to any of the log methods of the LogServices.
class LogContext private (val entries: Map[String, String] = Map.empty) {
def +(entry: (String, String)): LogContext = new LogContext(entries + entry)
def -(key: String): LogContext = new LogContext(entries - key)
def exists(p: ((String, String)) => Boolean): Boolean = entries.exists(p)
}
The implicit parameter provides the best flexibility as it allows to both specify an explicit context or use one available implicitly in the current scope.
Going back to our rest api service it can be used this way:
class MyRestController(log: RestApiLogService) {
...
def myEndpoint() = Action { request =>
implicit val logContext = LogContext(
"classname" -> classOf[MyRestController].getName,
"method" -> "myEndpoint",
"user.id" -> request.user.id
)
val startTime = System.currentTimeMillis()
val transaction = ...
log.startTransaction(request.user.id, transaction.id)
transaction.start()
// do more things here
// ...
val result = transaction.commit()
log.endTransaction(request.user.id, transaction.id, result)
// build response
// ...
val elapsedTime = System.currentTimeMillis() - startTime
// the context can also be set explicitly
val updatedContext = logContext + ("elapsedTime" -> elapsedTime.toString)
log.restApiCalled(request, response, elapsedTime)(updatedContext)
}
}
...
}
It is also immutable so it can be passed in onto other threads without much concerns.
Testing logged messages
As LogServices are not a global objects (well they can be, but they don’t have to) it’s much easier to inject mocked instances into the code under test, making sure that the expected logging methods are invoked.
Conclusion
The Log4J-style API widely use on the JVM today is a low-level API that provide a tight-coupling between the application code and the logging framework.
Moreover the global logger configurations prevent fine-grained logging.
Logoon is an experiment that tries to solve this issue by adding an extra layer on top of the Log4J-family framework, although it doesn’t depend on any of these framework, letting the user choose and implement the binding of their choice.
All the source code of Logoon is available on github under the MIT License, so feel free to have a look, try it and let me know what you think (or contribute and help to improve it)!