spring-boot icon indicating copy to clipboard operation
spring-boot copied to clipboard

Published 20 hours ago • verified publisher icon spring-projects

Log messages appear in a single line when application name contains brackets

Open moonlight200 opened this issue 1 year ago • 6 comments

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 {dev the 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

moonlight200 avatar Feb 14 '24 16:02 moonlight200

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.

wilkinsona avatar Feb 14 '24 19:02 wilkinsona

I wonder if we could put the application name in a logback variable then use property{APPLICATION_NAME} in the console pattern.

philwebb avatar Feb 14 '24 20:02 philwebb

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.

moonlight200 avatar Feb 15 '24 10:02 moonlight200

@moonlight200 Out of interest, does setting logging.include-application-name to false "fix" the issue?

philwebb avatar Feb 15 '24 16:02 philwebb

We're considering failing fast with an exception then giving users the choice of either changing their application name or disabling the feature.

philwebb avatar Feb 15 '24 16:02 philwebb

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"

moonlight200 avatar Feb 15 '24 16:02 moonlight200

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.

wilkinsona avatar Feb 27 '24 13:02 wilkinsona

We're going to look at a custom converter because we're worried about regex performance.

philwebb avatar Feb 28 '24 16:02 philwebb