annotation based Logger injection in Spring with Kotlin

what’s it all about

In this post I show how to implement an annotation-based Logger injection in Spring when writing the application with Kotlin.

The used technique is quite far from new, basically what I do is implement a BeanPostProcessor which scans the properties of the beans for fields annotated with a custom annotation and sets these fields to a Logger instance. Examples how to implement this in Java can be found on the web, here I show the Kotlin version.

In this example I have an innovative REST controller wich has the ability to say hello. This controller has an injected service to do the processing of the incoming name. The reason for implementing this in two classes is that I want to show 2 different ways to inject a Logger.

The whole project for this example is available on GitHub.

The setup

I use Spring-Boot to setup the project. There is nothing special in relation to boot here, but it gets me fast on the track. I created my project from within IntelliJ IDEA as a Spring-Boot project, but you can use https://start.spring.io/ as well. Language is Kotlin, and the only dependency needed is web.

The logging configuration

I added a simple logback.xml to my project:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/base.xml"/>
    <logger name="com.sothawo" level="DEBUG"/>
    <root level="WARN"/>
</configuration>

this sets the global level to WARN, and everything from my code to DEBUG.

The classes that get a Logger injected

The first class I show is HelloService, this is a Spring component which has one method that takes a string, and returns it concatenated to “hello “, and of course this is logged. In this class the Logger is injected in a normal property of the class by using the @Slf4jLogger annotation which I will show later:

package com.sothawo

import org.slf4j.Logger
import org.springframework.stereotype.Service

/**
 * @author P.J. Meisch (pj.meisch@sothawo.com)
 */
@Service
class HelloService {

    @Slf4jLogger
    lateinit var log: Logger

    fun sayHello(name: String): String {
        log.info("saying hello to: $name")
        return "hello $name"
    }
}

Using a normal property would create multiple instances of the same Logger-name if multiple HelloService instances were created (which they aren’t, but if you would change the scope this might happen). Therefore a better solution is to put the Logger in the companion object . This can be seen in the HelloController class:

package com.sothawo

import org.slf4j.Logger
import org.springframework.beans.factory.annotation.Autowired
import org.springframework.http.ResponseEntity
import org.springframework.web.bind.annotation.GetMapping
import org.springframework.web.bind.annotation.PathVariable
import org.springframework.web.bind.annotation.RequestMapping
import org.springframework.web.bind.annotation.RestController

/**
 * @author P.J. Meisch (pj.meisch@sothawo.com)
 */
@RestController
@RequestMapping("/hello")
class HelloController(val helloService: HelloService) {

    @GetMapping("/{name}")
    fun sayHello(@PathVariable name: String): ResponseEntity {
        log.info("sayHello called with arg $name")
        return ResponseEntity.ok(helloService.sayHello(name))
    }

    companion object {
        @Slf4jLogger
        lateinit var log: Logger
    }
}

The annotation and injection code

package com.sothawo

import org.slf4j.LoggerFactory
import org.springframework.beans.factory.config.BeanPostProcessor
import org.springframework.stereotype.Component
import kotlin.reflect.KMutableProperty
import kotlin.reflect.full.companionObjectInstance
import kotlin.reflect.full.declaredMemberProperties

/**
 * @author P.J. Meisch (pj.meisch@sothawo.com)
 */

@Target(AnnotationTarget.PROPERTY)
annotation class Slf4jLogger

@Component
class LoggingInjector : BeanPostProcessor {

    override fun postProcessBeforeInitialization(bean: Any?, beanName: String?): Any? {
        bean?.let {
            val loggerName = it::class.java.canonicalName
            processObject(it, loggerName)
            it::class.companionObjectInstance?.let {
                processObject(it, loggerName)
            }
        }

        return bean
    }

    override fun postProcessAfterInitialization(bean: Any?, beanName: String?) = bean

    private fun processObject(target: Any, loggerName: String) {
        target::class.declaredMemberProperties.forEach {
            property ->
            property.annotations
                    .filter { it is Slf4jLogger }
                    .forEach {
                        if (property is KMutableProperty<*>) {
                            property.setter.call(target, LoggerFactory.getLogger(loggerName))
                        }
                    }
        }
    }
}

First I create the annotation with the AnnotationTarget.PROPERTY  (lines 14, 15). Then I define a Spring component that implements the BeanPostProcessor interface. The postProcessAfterInitialization method does nothing, it just returns the bean that is passed in, the magic happens in postProcessBeforeInitialization. Here, if the bean that is passed in is not null, it is passed into my processObject method, and then I check if there is a companion object and analyze this in the same way. The Logger name is built from the bean’s class as I do not want to have the companion object’s name in there.

In the processObject method I iterate over the properties of the target object that was passed in. For each property I check if it has the @SLF4JLogger annotation and if so I set it’s value to a newly created Logger instance with the requested name.

The output

When running the program and issuing a call like

curl localhost:8080/hello/world

the log output shows:

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v1.5.4.RELEASE)

2017-07-12 15:58:32.567  INFO 2797 --- [           main] KotlinSpringLoggerInjectionApplicationKt : Starting KotlinSpringLoggerInjectionApplicationKt on pjm.local with PID 2797 (/Users/peter/Entwicklung/sothawo/kotlin-spring-logger-injection/target/classes started by peter in /Users/peter/Entwicklung/sothawo/kotlin-spring-logger-injection)
2017-07-12 15:58:32.571 DEBUG 2797 --- [           main] KotlinSpringLoggerInjectionApplicationKt : Running with Spring Boot v1.5.4.RELEASE, Spring v4.3.9.RELEASE
2017-07-12 15:58:32.571  INFO 2797 --- [           main] KotlinSpringLoggerInjectionApplicationKt : No active profile set, falling back to default profiles: default
2017-07-12 15:58:35.423  INFO 2797 --- [           main] KotlinSpringLoggerInjectionApplicationKt : Started KotlinSpringLoggerInjectionApplicationKt in 3.355 seconds (JVM running for 3.776)
2017-07-12 15:58:51.745  INFO 2797 --- [nio-8080-exec-1] com.sothawo.HelloController              : sayHello called with arg world
2017-07-12 15:58:51.745  INFO 2797 --- [nio-8080-exec-1] com.sothawo.HelloService                 : saying hello to: world

Conclusion

As shown here it is pretty simple to process annotation in Kotlin and use this for custom injection in Spring. Especially statments like annotations.filter { it is Slf4jLogger } are a pretty cool feature.

load java logging properties from the classpath

When using plain Java logging the configuration file normally must be set by setting the System property java.util.logging.config.file. There also is the possibility to configure the logging system with a configuration class, but this article deals with file configuration.

Using the system property is quite uncomfortable as it involves changing run configurations in the IDE or typing more on the commandline when starting the program. Especially in maven powered builds, where I might wish to have different configurations for test and normal execution this is not an optimal solution.

So I was looking for a way to configure the logging system by using a logging.properties file which is searched in the classpath. The logging properties file I am going to use in this post is:

#
.level = WARNING
handlers = java.util.logging.ConsoleHandler

com.sothawo.level = ALL

java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.ConsoleHandler.level = ALL

# Timestamp Level Source log message backtrace
java.util.logging.SimpleFormatter.format = %1$tF %1$tT:%1$tL %1$tZ %4$s %2$s: %5$s %6$s%n

I want to log everything from my com.sothawo classes, but all other messages should be restricted to level WARNING. The first solution I came up with was:

// SAMPLE CODE! NOT WORKING AS EXPECTED!
package com.sothawo.mapjfx.demo;
public class DemoApp extends Application {
   private static final Logger logger = Logger.getLogger(DemoApp.class.getCanonicalName());

  public static void main(String[] args) {
    InputStream inputStream = DemoApp.class.getResourceAsStream("/logging.properties");
    if (null != inputStream) {
      try {
        LogManager.getLogManager().readConfiguration(inputStream);
      } catch (IOException e) {
        Logger.getGlobal().log(Level.SEVERE, "init logging system", e);
      }
    }
    logger.fine("fine test logging");
    }
  }
}

This did not work. Debugging through the code I found that the input stream was loaded and the LogManager was reconfigured, but my logger was still configured to INFO level, which is the default and therefore the fine message was not logged. I checked the Javadoc for LogManager.readConfiguration() and there it says: “Any log level definitions in the new configuration file will be applied using Logger.setLevel(), if the target Logger exists.“. So why was my logger not set to the correct level?

I dug into the code for LogManager and found that only the level of the loggers with names that are exactly the same as the names defined in the properties are set and not the the levels of loggers which have a configured logger in their parent chain. In my case: In the properties I have the line
[code]
com.sothawo.level = ALL
[/code]
This sets the level for a logger named com.sothawo but in my code the logger has the name com.sothawo.mapjfx.demo.DemoApp, and so it is not set. The LogManager does not consider the parental relationships when reading the configuration, this is only done when a logger is created.

So care has to be taken and the logger must be created after reading the configuration:

// WORKING CODE BUT UGLY
package com.sothawo.mapjfx.demo;
public class DemoApp extends Application {

  private static Logger logger; // NOT FINAL ANY MORE!

  public static void main(String[] args) {
    InputStream inputStream = DemoApp.class.getResourceAsStream("/logging.properties");
    if (null != inputStream) {
      try {
        LogManager.getLogManager().readConfiguration(inputStream);
      } catch (IOException e) {
        Logger.getGlobal().log(Level.SEVERE, "init logging system", e);
      }
    }
    logger = Logger.getLogger(DemoApp.class.getCanonicalName());
    logger.fine("fine test logging");
    }
  }
}

This I consider to be ugly code, as I like my loggers to be final, and it clutters up the main method.

So my final solution is to put the relevant code in a static initializer:

package com.sothawo.mapjfx.demo;
public class DemoApp extends Application {
  private static final Logger logger;

  static {
    InputStream inputStream = DemoApp.class.getResourceAsStream("/logging.properties");
    if (null != inputStream) {
    try {
      LogManager.getLogManager().readConfiguration(inputStream);
    } catch (IOException e) {
      Logger.getGlobal().log(Level.SEVERE, "init logging system", e);
    }
    logger = Logger.getLogger(DemoApp.class.getCanonicalName());
  }

  public static void main(String[] args) {
    logger.fine("fine test logging");
  }
}