I recently upgraded to Spring Boot 3.2.2. After the update, all log messages appeared in one single line:
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v3.2.2)
2024-02-14T17:04:13.529+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:13.532+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:13.574+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:13.574+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.022+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.036+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.398+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.408+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.408+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.438+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.439+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.461+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.601+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.602+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.614+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.725+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.757+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.779+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.940+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:14.970+01:00 WARN 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:15.188+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:15.192+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:15.241+01:00 WARN 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:15.515+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:15.549+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:15.556+01:00 INFO 849908 --- [Test Name (dev] [ restartedMain]2024-02-14T17:04:16.024+01:00 INFO 849908 --- [Test Name (dev] [ionShutdownHook]2024-02-14T17:04:16.032+01:00 WARN 849908 --- [Test Name (dev] [ionShutdownHook]2024-02-14T17:04:16.033+01:00 INFO 849908 --- [Test Name (dev] [ionShutdownHook]2024-02-14T17:04:16.035+01:00 INFO 849908 --- [Test Name (dev] [ionShutdownHook]
The 3.2 Release Notes state, that the application name is now included in the log messages. I had my application name setup with a ... (dev) at the end which was the cause for this issue.
Observed Behavior
On a new spring boot 3.2.2 project (I used Kotlin for both, the source code and Gradle config):
- If the application name contains a ) (e.g. spring.application.name=Test Name (dev)), all logs appear in a single line (see example above)
- If the application name contains only a ( but no ) everything is fine
- If the application name contains both ( and ), the behavior is the same as with only the closing bracket
- No combination of [ and/or ] caused an issue
- If the application name contains a } but no opening {, e.g. spring.application.name=Test Name }dev everything after the } is cut away:
2024-02-14T17:18:05.108+01:00 INFO 854102 --- [Test Name [ restartedMain] c.s.s.SpringLoggingTestApplicationKt : No active profile set, falling back to 1 default profile: "default"
- If the application name contains both
{and}, e.g.spring.application.name=Test Name {dev}everything looks fine:
2024-02-14T17:20:22.210+01:00 INFO 854996 --- [Test Name {dev}] [ restartedMain] c.s.s.SpringLoggingTestApplicationKt : No active profile set, falling back to 1 default profile: "default"
- If the application name contains only a
{but no}, e.g.spring.application.name=Test Name {devthe application fails to start:
Logging system failed to initialize using configuration from 'null'
java.lang.IllegalArgumentException: All tokens consumed but was expecting "}"
at ch.qos.logback.core.subst.Parser.expectNotNull(Parser.java:160)
at ch.qos.logback.core.subst.Parser.expectCurlyRight(Parser.java:165)
at ch.qos.logback.core.subst.Parser.T(Parser.java:93)
at ch.qos.logback.core.subst.Parser.E(Parser.java:58)
at ch.qos.logback.core.subst.Parser.Eopt(Parser.java:75)
at ch.qos.logback.core.subst.Parser.E(Parser.java:62)
at ch.qos.logback.core.subst.Parser.parse(Parser.java:54)
at ch.qos.logback.core.subst.NodeToStringTransformer.tokenizeAndParseString(NodeToStringTransformer.java:59)
at ch.qos.logback.core.subst.NodeToStringTransformer.handleVariable(NodeToStringTransformer.java:102)
at ch.qos.logback.core.subst.NodeToStringTransformer.compileNode(NodeToStringTransformer.java:77)
at ch.qos.logback.core.subst.NodeToStringTransformer.handleVariable(NodeToStringTransformer.java:117)
at ch.qos.logback.core.subst.NodeToStringTransformer.compileNode(NodeToStringTransformer.java:77)
at ch.qos.logback.core.subst.NodeToStringTransformer.transform(NodeToStringTransformer.java:64)
at ch.qos.logback.core.subst.NodeToStringTransformer.substituteVariable(NodeToStringTransformer.java:52)
at ch.qos.logback.core.util.OptionHelper.substVars(OptionHelper.java:112)
at ch.qos.logback.core.util.OptionHelper.substVars(OptionHelper.java:104)
at org.springframework.boot.logging.logback.DefaultLogbackConfiguration.resolve(DefaultLogbackConfiguration.java:168)
at org.springframework.boot.logging.logback.DefaultLogbackConfiguration.defaults(DefaultLogbackConfiguration.java:76)
at org.springframework.boot.logging.logback.DefaultLogbackConfiguration.apply(DefaultLogbackConfiguration.java:58)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.lambda$loadDefaults$0(LogbackLoggingSystem.java:234)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.withLoggingSuppressed(LogbackLoggingSystem.java:467)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadDefaults(LogbackLoggingSystem.java:223)
at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:84)
at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:61)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:189)
at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:332)
at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:298)
at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:246)
at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:223)
at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:178)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:171)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:149)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:137)
at org.springframework.boot.context.event.EventPublishingRunListener.multicastInitialEvent(EventPublishingRunListener.java:136)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:81)
at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:64)
at java.base/java.lang.Iterable.forEach(Iterable.java:75)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:118)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:112)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:63)
at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:369)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:329)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1354)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343)
at com.sfc.springloggingtest.SpringLoggingTestApplicationKt.main(SpringLoggingTestApplication.kt:13)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:50)
Expected behavior
Regardless of the appearance of any of ([{}]) in the application name, the log output is formatted correctly
Comment From: wilkinsona
Thanks for reporting this, @moonlight200. As far as I can tell, Logback does not support escaping of the characters that have special meaning to its support for variable substitution. This means that we'd have to replace the problematic characters ({, }, (, or )) with something else or omit them entirely. I think we'll need to discuss this one as a team to see if we can agree on something. If you have any suggestions based on your experience please do share them.
Comment From: philwebb
I wonder if we could put the application name in a logback variable then use property{APPLICATION_NAME} in the console pattern.
Comment From: moonlight200
Thank you for the quick replies. From what I could see in the spring-boot-project/spring-boot/src/main/resources/org/springframework/boot/logging/logback resources the application name is inserted into the format string of the log message. Maybe there is a way to only place a reference in the format string pass the name as an input instead. It looks like the suggestion from @philwebb is about just that. I am not sure if or how this is doable, as I don't have much experience with the internals of logback or spring boot.
Comment From: philwebb
@moonlight200 Out of interest, does setting logging.include-application-name to false "fix" the issue?
Comment From: philwebb
We're considering failing fast with an exception then giving users the choice of either changing their application name or disabling the feature.
Comment From: moonlight200
With this config:
spring.application.name=Test Name (dev)
logging.include-application-name=false
Logging works fine:
2024-02-15T17:20:29.487+01:00 INFO 1302973 --- [ restartedMain] c.s.s.SpringLoggingTestApplicationKt : No active profile set, falling back to 1 default profile: "default"
Comment From: wilkinsona
The problem doesn't occur with Log4j2. With that in mind, this branch contains a fix that's Logback-specific.
The fix uses %property to retrieve LOGGED_APPLICATION_NAME. Unfortunately, %property doesn't support default values so it will evaluate to null when LOGGED_APPLICATION_NAME hasn't been set. To overcome this, %replace is used to turn null into an empty string. This works, but I am a little wary of it as it's implemented using a regular expression which may have some performance implications.
An alternative to this would be to use a custom converter for the logged application name, similar to what we're already doing for the correlation ID.
Comment From: philwebb
We're going to look at a custom converter because we're worried about regex performance.