Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

When using Logback, log messages appear in a single line when application name contains brackets #39564

Closed
moonlight200 opened this issue Feb 14, 2024 · 8 comments
Closed

When using Logback, log messages appear in a single line when application name contains brackets #39564

moonlight200 opened this issue Feb 14, 2024 · 8 comments
Labels
type: regression A regression from a previous release
Milestone
3.2.4

Comments

@moonlight200
Copy link

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
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Feb 14, 2024
@wilkinsona
Copy link
Member

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 wilkinsona added type: regression A regression from a previous release and removed status: waiting-for-triage An issue we've not yet triaged labels Feb 14, 2024
@wilkinsona wilkinsona added this to the 3.2.x milestone Feb 14, 2024
@wilkinsona wilkinsona added the for: team-meeting An issue we'd like to discuss as a team to make progress label Feb 14, 2024
@philwebb
Copy link
Member

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

@moonlight200
Copy link
Author

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.

@philwebb
Copy link
Member

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

@philwebb
Copy link
Member

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

@moonlight200
Copy link
Author

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"

@philwebb philwebb removed the for: team-meeting An issue we'd like to discuss as a team to make progress label Feb 21, 2024
@wilkinsona
Copy link
Member

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 wilkinsona added the for: team-meeting An issue we'd like to discuss as a team to make progress label Feb 27, 2024
@philwebb
Copy link
Member

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

@philwebb philwebb removed the for: team-meeting An issue we'd like to discuss as a team to make progress label Feb 28, 2024
@wilkinsona wilkinsona changed the title Log messages appear in a single line when application name contains brackets When using Logback , log messages appear in a single line when application name contains brackets Feb 29, 2024
@wilkinsona wilkinsona mentioned this issue Feb 29, 2024
Closed
@wilkinsona wilkinsona modified the milestones: 3.2.x, 3.2.4 Feb 29, 2024
@wilkinsona wilkinsona changed the title When using Logback , log messages appear in a single line when application name contains brackets When using Logback, log messages appear in a single line when application name contains brackets Feb 29, 2024
wilkinsona added a commit that referenced this issue Mar 1, 2024
@wilkinsona
Register new Logback converter for reflection in a native image
753bbf4 
See gh-39564
@Netyyyy Netyyyy mentioned this issue Mar 22, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
type: regression A regression from a previous release
Projects
None yet
Milestone
3.2.4
Development

No branches or pull requests
4 participants
@philwebb @wilkinsona @moonlight200 @spring-projects-issues