Different log levels and hierarchy in Spring

by microideation · October 25, 2018

Logging is a very important concept which is mostly overlooked at the time of development. But this becomes even more relevant when the application is in production and the only source of truth is the generated logs. Now there are different logs levels and it is important to understand the difference and significance of each.

What are the log levels available?

Following are the different types of log levels available in Spring / Java.

TRACE
DEBUG
INFO
WARN
ERROR

At this point, we might feel what is the requirement for all these different levels and why can’t we do away with a single level. We can practically have all our logs under may be INFO and set the application to run on this log level. But this has the following impacts:

For a production application, the logs generated could be huge and there is a chance of disk space running out.
Logging has a performance penalty when your system is doing time critical operations.

Different Logs Levels

Let’s see when we can use each of the log levels and what is the application hierarchy,

ERROR

This is the most restrictive log level and developers usually log critical errors or business rule exceptions using this log level. Most of the production applications are by default set to run on this log level. This should be used to get information regarding critical operational information of the system. When this log level is enabled, all the logs under other levels are not logged into the logging system.
Eg: When the application is running in the ERROR log, the WARN, INFO, DEBUG and TRACE type logs are not logged.

WARN

This is a log level above the ERROR Log and can be used to log the warnings and non-fatal errors. When the application log level is WARN, this will log both WARN as well as ERROR type logs into the logging system.

INFO

This log level can be used to log different information regarding the state of the system like the request parameters received in a controller, the response being sent or any other processing information of interest. This is mostly used during the development stage and most of the logs in an application would be under this level. When the log level for the entire application is set to INFO, then both the WARN and ERROR logs are also logged into the logging system.

DEBUG

This log level is used to log information regarding each operation or different steps in a operation. For eg: You can log the data before and after each step in a function to get a complete idea of how the data or object is getting modified. This is mostly used during development and may activate in production for specific classes to trace an error. Enabling DEBUG level at the application level will cause INFO, WARN and ERROR logs to be also sent to the logging system.

TRACE

This is the most verbose log level and is used to sent basically all the actions happening in the application.
For eg: If your application is connected to a different service like Rabbitmq, you can log each request and response, timeouts etc.

Enabling TRACE will enable all the subsequent log levels and is not at all recommended in the production environment.

Sample Application to test logging level

Let’s create a sample spring boot application to test the logging levels. The entire source code is available at the following Github repo:

https://github.com/microideation/logging-sample

This is a simple application which contains one API to accept the name and return a greeting. Let’s first create the service class

GreetService

@Service
class GreetService {

  private Logger log = LoggerFactory.getLogger(GreetService.class);

  public String greet(String name) {

    log.info("greetService -> greet -> Received : name " + name);
    if ( name.equals("test")) {
      log.warn("greetService -> greet -> No name specified");
    }
    String upperName = name.toUpperCase();
    log.debug("greetService -> Name converted to upperCase: " + upperName);
    String response = "Hello!, " + upperName;
    log.debug("greetService -> greet -> Sending response : " + response);
    return response;

  }
}

In the service, we have added info, warn and debug level logging.

GreetController

@RestController
class GreetController {

  private Logger log = LoggerFactory.getLogger(GreetService.class);

  private final GreetService greetService;

  GreetController(GreetService greetService) {
    this.greetService = greetService;
  }

  @GetMapping("/greet/{name}")
  public String greet(@PathVariable String name, HttpServletRequest request) {
    log.info("greetController -> greet -> Received : name " + name);
    log.debug("greetController -> greet -> Received request IP: " + request.getRemoteAddr());
    return greetService.greet(name);
  }
}

In the controller, we have added info and debug level logging.

application.properties

logging.level.org.springframework.web: error
logging.level.com.microideation.sample.logging.loggingdemo.LoggingDemoApplication:ERROR

In the application.properties, we are setting the MVC to ERROR log. This is for the entire springframework classes and then for our individual class ( which contains the service and controller), we are setting custom value which we will change and see the behaviour.

Running the application with INFO log level

We will set the application.properties value of logging.level.com.microideation.sample.logging.loggingdemo.LoggingDemoApplication to INFO and let’s hit the API. This will generate the following log in the console.

2018-10-25 20:10:02.240  INFO 29217 --- [nio-8080-exec-1] .l.l.LoggingDemoApplication$GreetService : greetController -> greet -> Received : name microideation
2018-10-25 20:10:02.240  INFO 29217 --- [nio-8080-exec-1] .l.l.LoggingDemoApplication$GreetService : greetService -> greet -> Received : name microideation

Here we can see that the info logs in both the service and controller were logged. The debug logs were not logged in this case.

Running the application with DEBUG log level

Let’s set application.properties value of logging.level.com.microideation.sample.logging.loggingdemo.LoggingDemoApplication to DEBUG and hit the API. This will generate the following log in the console.

2018-10-25 20:12:29.764  INFO 30795 --- [nio-8080-exec-1] .l.l.LoggingDemoApplication$GreetService : greetController -> greet -> Received : name microideation
2018-10-25 20:12:29.764 DEBUG 30795 --- [nio-8080-exec-1] .l.l.LoggingDemoApplication$GreetService : greetController -> greet -> Received request IP: 0:0:0:0:0:0:0:1
2018-10-25 20:12:29.764  INFO 30795 --- [nio-8080-exec-1] .l.l.LoggingDemoApplication$GreetService : greetService -> greet -> Received : name microideation
2018-10-25 20:12:29.764 DEBUG 30795 --- [nio-8080-exec-1] .l.l.LoggingDemoApplication$GreetService : greetService -> Name converted to upperCase: MICROIDEATION
2018-10-25 20:12:29.764 DEBUG 30795 --- [nio-8080-exec-1] .l.l.LoggingDemoApplication$GreetService : greetService -> greet -> Sending response : Hello!, MICROIDEATION

In this case, you can see that the DEBUG, as well as INFO level logs, were logged into the console.

You can configure different logs and try with different levels to see how the hierarchy is affected.

Conclusion

We have seen the different log levels and as specified in the beginning, we need to give attention to put different details of the system state as logs during the development phase itself. Care need to be taken to put each log into the corresponding level so that they can be changed and monitored when the application is in production. It is advisable to put the application in production to ERROR level and only change individual log level in case something needs to be checked or traced.

In case you are interested more about logging, you can refer to below post.

Let me know if you have queries in the comments section.

regards
Microideation