This article talks about my experience when configuring Spring Boot Logback Configuration where I make use of Spring Boot - Profile Specific Configuration Extension feature to configure different rules per profile and logstash-logback-encoder library to pipe logs as JSON format.
The end state is simple
- In development, output the logs using
CONSOLE appender
- In production, output the logs using
JSON appender
With that in mind, let's see how we can achieve it.
It is recommended to create logback-spring.xml in src/main/resources instead of logback.xml because doing so allows us to use Spring Logback Extension such as Profile Specific Configuration feature.
What exactly does this extension help us with? Imagine that we want to configure different "rules" for different environments. We can do so using this configuration
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/base.xml" />
<springProfile name="default">
<logger name="com.bwgjoseph.springlogback" additivity="false" level="debug">
<appender-ref ref="CONSOLE" />
</logger>
<root level="INFO">
<appender-ref ref="CONSOLE" />
</root>
</springProfile>
<springProfile name="staging, production">
<logger name="com.bwgjoseph.springlogback" additivity="false" level="warn">
<appender-ref ref="CONSOLE" />
</logger>
<root level="INFO">
<appender-ref ref="CONSOLE" />
</root>
</springProfile>
</configuration>
For the default environment, we set the log level for com.bwgjoseph.springlogback to debug and to warn in the production environment.
Example
Assuming we have the following code
@SpringBootApplication
public class SpringLogbackApplication {
public static void main(String[] args) {
SpringApplication.run(SpringLogbackApplication.class, args);
}
@Bean
ApplicationRunner init() {
return arg -> {
Logger rootLogger = LoggerFactory.getLogger(SpringLogbackApplication.class);
rootLogger.trace("trace");
rootLogger.debug("debug");
rootLogger.info("info");
rootLogger.warn("warn");
rootLogger.error("error");
};
}
}
Spring will initialize your application with default profile unless overridden in application.properties, and since we did not, when the application is started, the logs would look like
2022-04-10 02:17:26.343 INFO 6372 --- [ restartedMain] c.b.s.SpringLogbackApplication : Started SpringLogbackApplication in 1.597 seconds (JVM running for 2.009)
2022-04-10 02:17:26.349 DEBUG 6372 --- [ restartedMain] c.b.s.SpringLogbackApplication : debug
2022-04-10 02:17:26.350 INFO 6372 --- [ restartedMain] c.b.s.SpringLogbackApplication : info
2022-04-10 02:17:26.353 WARN 6372 --- [ restartedMain] c.b.s.SpringLogbackApplication : warn
2022-04-10 02:17:26.354 ERROR 6372 --- [ restartedMain] c.b.s.SpringLogbackApplication : error
Now, let's configure it to run using production profile. To do so, update application.properties to indicate the profile to use
spring.profiles.active=production
And the logs would now look like
2022-04-10 02:31:51.306 INFO 13476 --- [ restartedMain] o.s.b.d.a.OptionalLiveReloadServer : LiveReload server is running on port 35729
2022-04-10 02:31:51.326 WARN 13476 --- [ restartedMain] c.b.s.SpringLogbackApplication : warn
2022-04-10 02:31:51.326 ERROR 13476 --- [ restartedMain] c.b.s.SpringLogbackApplication : error
As you can see, Spring Logback Profile Specific Configuration feature makes it easy for us to configure different sets of rules for each profile and it will automatically be applied based on the environment you have deployed it to.
One of our objective is to ensure that we can pipe the logs to JSON appender instead of the CONSOLE appender in production. But how can we do that?
Let me introduce you to logstash-logback-encoder library. Add the following to your Gradle/Maven config
implementation 'net.logstash.logback:logstash-logback-encoder:7.0.1'
<dependency>
<groupId>net.logstash.logback</groupId>
<artifactId>logstash-logback-encoder</artifactId>
<version>7.0.1</version>
</dependency>
And then head back to logback-spring.xml and add the following
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
</appender>
</configuration>
Perfect, let's also update our configuration to switch the production profile log to use JSON appender
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<springProfile name="production">
<logger name="com.bwgjoseph.springlogback" additivity="false" level="warn">
<appender-ref ref="JSON" />
</logger>
<root level="INFO">
<appender-ref ref="JSON" />
</root>
</springProfile>
</configuration>
And the result is...
2022-04-10 02:42:56.796 INFO 15268 --- [ restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
{"@timestamp":"2022-04-10T02:42:56.796+08:00","@version":"1","message":"Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable","logger_name":"org.springframework.boot.devtools.env.DevToolsPropertyDefaultsPostProcessor","thread_name":"restartedMain","level":"INFO","level_value":20000}
2022-04-10 02:42:57.578 INFO 15268 --- [ restartedMain] o.s.b.d.a.OptionalLiveReloadServer : LiveReload server is running on port 35729
{"@timestamp":"2022-04-10T02:42:57.578+08:00","@version":"1","message":"LiveReload server is running on port 35729","logger_name":"org.springframework.boot.devtools.autoconfigure.OptionalLiveReloadServer","thread_name":"restartedMain","level":"INFO","level_value":20000}
{"@timestamp":"2022-04-10T02:42:57.608+08:00","@version":"1","message":"warn","logger_name":"com.bwgjoseph.springlogback.SpringLogbackApplication","thread_name":"restartedMain","level":"WARN","level_value":30000}
{"@timestamp":"2022-04-10T02:42:57.609+08:00","@version":"1","message":"error","logger_name":"com.bwgjoseph.springlogback.SpringLogbackApplication","thread_name":"restartedMain","level":"ERROR","level_value":40000}
Cool, how easy was it? All it took was to just add logstash-logback-encoder library and configure a JSON appender and use it.
But, have you noticed something weird about the logs? You probably have, and that there are now two different type of log format CONSOLE and JSON but why is that happening? It turns out that we have this line under configuration tag in our configuration which brings in a number of default configurations including a root logger configuration
<include resource="org/springframework/boot/logging/logback/base.xml" />
If you are using VSCode (or any other IDE), you can see from the dependencies project, and what exactly was defined in base.xml or you can view it directly from spring-boot-github
I extracted the content for your convenience (based on spring-boot-2.6.6)
<included>
<include resource="org/springframework/boot/logging/logback/defaults.xml" />
<property name="LOG_FILE" value="${LOG_FILE:-${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}/spring.log}"/>
<include resource="org/springframework/boot/logging/logback/console-appender.xml" />
<include resource="org/springframework/boot/logging/logback/file-appender.xml" />
<root level="INFO">
<appender-ref ref="CONSOLE" />
<appender-ref ref="FILE" />
</root>
</included>
Notice the root logger have been configured with CONSOLE and FILE appender and because root logger is cumulative, the merged logback config would look something like (based on my understanding) in your logback-spring.xml
<springProfile name="production">
<logger name="com.bwgjoseph.springlogback" additivity="false" level="warn">
<appender-ref ref="JSON" />
</logger>
<root level="info">
<appender-ref ref="CONSOLE" />
<appender-ref ref="FILE" />
<appender-ref ref="JSON" />
</root>
</springProfile>
And that is probably the cause of why there are multiple type of logs being shown.
Solve conflicting root appender
The fix is easy; move base.xml resource to default profile
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<springProfile name="default">
<include resource="org/springframework/boot/logging/logback/base.xml" />
<logger name="com.bwgjoseph.springlogback" additivity="false" level="debug">
<appender-ref ref="CONSOLE" />
</logger>
<root level="INFO">
<appender-ref ref="CONSOLE" />
</root>
</springProfile>
</configuration>
This way, whatever that was defined in default profile will not affect production profile. The downside is that production profile can no longer use CONSOLE appender but that's okay, since we only want to log out as JSON.
Can we do better?
Yes, we definitely can do better
According to spring-boot-docs, base.xml was added for compatibility/legacy reason although I'm not entirely sure what is the use-case for that. We can safely assume that we don't need that, hence, we can just pick and choose what we need and then include it in our logback-spring.xml configuration.
In our case, we just need default.xml and console-appender.xml which would not have brought in root logger configuration
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<springProfile name="default">
<include resource="org/springframework/boot/logging/logback/defaults.xml" />
<include resource="org/springframework/boot/logging/logback/console-appender.xml" />
</configuration>
So far, I am unable to figure out if there is a way to override the root logger and remove just the appender. If you know how, please comment below!
After we have updated the configuration, let's run the application again to see if we have everything configured to what we desired for
{"@timestamp":"2022-04-10T16:57:59.853+08:00","@version":"1","message":"Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable","logger_name":"org.springframework.boot.devtools.env.DevToolsPropertyDefaultsPostProcessor","thread_name":"restartedMain","level":"INFO","level_value":20000}
{"@timestamp":"2022-04-10T16:58:00.679+08:00","@version":"1","message":"LiveReload server is running on port 35729","logger_name":"org.springframework.boot.devtools.autoconfigure.OptionalLiveReloadServer","thread_name":"restartedMain","level":"INFO","level_value":20000}
{"@timestamp":"2022-04-10T16:58:00.703+08:00","@version":"1","message":"warn","logger_name":"com.bwgjoseph.springlogback.SpringLogbackApplication","thread_name":"restartedMain","level":"WARN","level_value":30000}
{"@timestamp":"2022-04-10T16:58:00.703+08:00","@version":"1","message":"error","logger_name":"com.bwgjoseph.springlogback.SpringLogbackApplication","thread_name":"restartedMain","level":"ERROR","level_value":40000}
Congratulation! This time, it is without the extra CONSOLE appender log message
Note: this would have worked even if defaults.xml and console-appender.xml was placed outside of springProfile tag
Conclusion
We have looked at how to use Spring Profile in Logback to define different set of rules and configuration for each of the profile, how to output the logs in JSON format using logstash-logback-encoder and finally, how to resolve conflicting configs when we include configuration provided by spring-boot
Reading through the documentation of spring-boot and logback certainly helped further my understanding especially on the part where root logger are cumulative and it kind of cleared up my confusion as to why the different type of logs are shown even though we did not explicitly configured for it
Source Code
Full source code is available in GitHub
Resources
