Log handling with SpringBot server-side

Logging libraries

SpringBot uses two different logging libraries:

• SLF4J is a popular logging tool in Java that uses the conventional log levels and typically logs to the console.
• Logback focuses on logging requests that are sent to the server-side by writing logs into the file system and managing the archiving of older logs.

Logging strategy

Logging configuration files

To provide more options to configure the logging files, SpringBot currently has two files which configure different logging functionality.

logback-spring.xml

The logback-spring.xml file is used to configure the file logging done in the server. SpringBot mainly uses the logback-spring.xml to manage the output target and pattern of the log (e.g. output file path, output logging format and the log rolling out policy).

You can manage Logback through a XML file called logback-spring.xml. This XML file allows you to modify which log levels you would like to record, the location and maximum size of the log file, and how frequently it should be archived.

The file can be located at serverside/src/main/resources/logback/logback-spring.xml.

application-[EnvironmentName].profile

Spring uses different application profiles for setting environment variables for each stage of development. Each of the application profiles inherit from the parent level application profile called application-default.properties. All of the application.properties files can be found at serverside/src/main/resources/.

Within SpringBot, the application profile manages the logging configuration. To make it easy to configure and understand, the default application profile currently includes the logback-spring.xml file as the Logback configuration.

The application profile is used to change the configuration for the logging levels used for each environment.

Currently, all the root log levels are set to WARN, but this will change in a future release to make sure that different environments have appropriate logging levels. Different logback-spring-[EnvironmentName].xml files may also be changed to config different Logback outputs in different environments.

In the latest version of the bots, the logging configuration can be configured in the application-[EnvironmentName].profile using the following code:

logging.level.org.hibernate.SQL=DEBUG
logging.level.org.hibernate.type.descriptor.sql.BasicBinder=TRACE

These two log levels are also set for development purposes:

logging.level.org.springframework.web=DEBUG
logging.level.org.hibernate=ERROR

To change these configurations, you need to turn on the protected region in application-[EnvironmentName].profile and change them to the required level.

Log levels

There are five different log levels used in SpringBot:

• TRACE
• DEBUG
• INFO
• WARN
• ERROR

Best practice for the log levels

Loggers are simple and powerful tools for development and debugging, but if they are not used properly they can severely affect the performance and storage of your server. We have some basic recommendations on using the different levels of logs to prevent that from happening:

1. Production environment logging should be in WARN level.
2. Do not use the log level DEBUG in the production environment.
3. Use the INFO level selectively
4. If WARN is used to record business logic, pay attention to the size of the log file as it can become very big very quickly.
5. Consider whether you need specific logs. Outputting a large number of invalid logs will have impact on system performance, and reducing the number you use can prevent this.
6. WARN level can used to record invalid parameters. This is useful to track data when a problem occurs
7. ERROR level should only be used to record the system logic error, such as abnormalities and other error messages.

You can learn more from the Best Practice for Logging guidelines.

Setting log levels

Log levels are inherited, but can be changed in the application-[EnvironmentName].profile file using logging.level.root=ERROR.

Adding loggers

The best way to add a logger to a class is by adding the Spring Annotation @Slf4j, which will allow the whole class to use the simple logger. Once the annotation is added to the class, the log can be called using log.[LogLevel]("your logging message");.

A large number of bot-written classes will contain the @Slf4j annotation. If there is a specific class or file which requires logging but doesn’t contain that annotation, you can use an alternative method; Add the logger in by initialising the LoggerFactory in the class. For example:

private final Logger log = LoggerFactory.getLogger(Example.class);

Then you can call the log using log.[LogLevel]("your logging message").

Using loggers

Setting a specific log level will change what is being output, however loggers still use system resources unless they are called properly. There are two different ways that are considered to be best practice:

Preferred Method (used by SpringBot)

log.debug("The value of id: {} and condition : {} ", id,condition);

Alternative Method

if (log.isDebugEnabled()) { 
    log.debug("The value of id is " + id + " and  conditions: " + conditions);
}

Due to the string concatenation process used in logging, system resources will still be used despite being set to the contrary. For that reason, we highly recommend you avoid logging using logger.debug ("Example with id: " + id + " symbol: " + symbol);, and instead follow the best practice guidelines defined previously.

Log file location

The location of the configured log files are defined in logback-spring.xml:

<property name="LOGS" value="./logs" />

By default, logs are stored as files in the file system. Currently, the default location for log files is serverside/logs/ but this can be changed by editing the property tag (<property name="LOGS" value="./logs" />) by change the value to the desired location.

Example:

<property name="LOGS" value="./NewLogs" />

If the file logger is not configured in logback-spring.xml, the bot will default to printing the logs in the console. There are plans in the future to capture all ERROR level logs into one file to make it easier to track the errors in your application.

Archiving the log

To make it easier to manage the log, we use the RollingFileAppender feature in Logback to archive log files over a period of time. You can register the file appender and logger in logback-spring.xml. A good example of this is written by SpringBot to capture a request log called requestLogger:

<appender name="Request" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOGS}/request-log.log</file>
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <Pattern>%d %p %C{1.} [ %t ] %m%n</Pattern>
    </encoder>

    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">

        <fileNamePattern>${LOGS}/archived/request-logger-%d{yyyy-MM-dd}.%i.log
        </fileNamePattern>
        <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
            <maxFileSize>100MB</maxFileSize>
        </timeBasedFileNamingAndTriggeringPolicy>
    </rollingPolicy>
</appender>

<logger name="requestLogger">
    <appender-ref ref="Request" />
</logger>

In this example requests are being logged into the file called request-log.log which is located in serverside/logs. We have also instructed Logback to clean and archive everyday or when the request-log.log file size exceeds 100MB, in order to make it easier to manage log files.

For more information about about the RollingFileAppender, please read Logback’s Appenders documentation. The article will also cover additional options that can be used to configure beyond the basics.

SpringBot, by default contains two standard loggers that are stored in a file and archived.

• HakariCP Log To monitor the database connection pool status.
• Request Log To record all the incoming requests.

Other logs are printed out to console by default.

Custom log configuration

In the following section, we detail how you can create a completely custom log configuration.

Changing the output

Logback allows the developer to change the output of certain loggers by using configurations, to then output them to specific files. In this example, we are trying to configure the logging configuration for the Hibernate SQL log.

1. Turn on protected region in the logback-spring.xml

2. Add your custom appender into the protected region

    <appender name="HIBERNATE_SQL" class="ch.qos.logback.core.rolling.RollingFileAppender">
     <file>${LOGS}/sql.log</file>
     <append>true</append>
     <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
         <Pattern>[ %d{dd-MMM-yyyy HH:mm:ss.SSS}] [ %logger] [ %-5level] - %msg%n</Pattern>
     </encoder>
     <rollingPolicy
             class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
       
         <fileNamePattern>${LOGS}/archived/sql/sql-%d{yyyy-MM-dd}.%i.log
         </fileNamePattern>
         <timeBasedFileNamingAndTriggeringPolicy
                 class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
             <maxFileSize>100MB</maxFileSize>
         </timeBasedFileNamingAndTriggeringPolicy>
     </rollingPolicy>
    </appender>
   

   There are a lot of different types of appenders. The primary one used in SpringBot is RollingFileAppender, which would provides the feature for rolling the files. There are some custom options you can add which you can learn more in Logback’s Appender Documentation.

3. Add the logger tag with its appender options.

    <logger name="org.hibernate.SQL">
     <appender-ref ref="HIBERNATE_SQL" />
    </logger>
   

   The name attribute must match the name of the appender. You can use the Logback appender to capture the logs of classes, packages or 3rd party libraries.

Changing the log levels

To update a log level, you will need to change the Spring application[EnvironmentName].profile file.
In this example, we will set the org.hibernate.SQL package to the DEBUG level.

1. Turn on the protected region in the application-{env}.profile

2. Change the log level for the package or class you want.

    logging.level.org.hibernate.SQL=DEBUG
   

3. You will also need to change the root logger. The root logger is the default logging level inherited across all classes and functions, unless specifically declared like we did in step 2.

    logging.level.root=WARN
   

The logger also depends on the hierarchy of the application-[EnvironmentName].profile. For example:

application-default.profiles

logging.level.root=WARN

application-dev.profiles

logging.level.root=DEBUG

In this situation if we ran the serverside with SPRING_PROFILES_ACTIVE=dev, the value for logging.level.root would be in DEBUG level. If we ran the application using the same settings in SPRING_PROFILES_ACTIVE=test, then the application would default to WARN.