Logo Questions Linux Laravel Mysql Ubuntu Git Menu
HTML CSS JAVASCRIPT SQL PYTHON PHP BOOTSTRAP JAVA JQUERY R React Kotlin
 

Update to Spring Boot 3 - Logging no longer works

Tags:

spring

spring-boot

logback

After updating to Spring Boot 3 the logging does not work anymore. No line is written into the logfiles. The file logback-spring.xml is present in the resource folder. It also exists in the jar-file (test-1.1.1.jar\BOOT-INF\classes).

  • This only thing that happens on the productive envorionment (starting the application via jar file)
  • Starting the application within Eclipse is working fine and makes no problems

In my opinion the logback file is used by spring boot by starting from jar-file, because empty logfiles with the defined file name in the logback-spring.xml is generated by starting the application.

It simply does not log any entry.

Content of logback-spring.xml:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE xml> 

<configuration>

  <if condition='property("SERVER_LOG_PATH").isEmpty()'>
    <then>
      <property name="SERVER_LOG_PATH" value="./log" />
    </then>
  </if>

  <springProfile name="dev">
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
      <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>INFO</level>
      </filter>
      <encoder>
        <pattern>%d %5p | %t | %-55logger{55} | %m %n</pattern>
      </encoder>
    </appender>
  </springProfile>

  <appender name="DEBUG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>DEBUG</level>
    </filter>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>${SERVER_LOG_PATH}/test_%d{yyyyMMdd}_debug_%i.log</fileNamePattern>
      <maxFileSize>300MB</maxFileSize>
      <maxHistory>60</maxHistory>
      <totalSizeCap>20GB</totalSizeCap>
      <cleanHistoryOnStart>true</cleanHistoryOnStart>
    </rollingPolicy>

    <encoder>
      <charset>UTF-8</charset>
      <pattern>%d %5p | %t | %-55logger{55} | %m %n</pattern>
    </encoder>
  </appender>

  <appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>INFO</level>
    </filter>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>${SERVER_LOG_PATH}/test_%d{yyyyMMdd}_%i.log</fileNamePattern>
      <maxFileSize>300MB</maxFileSize>
      <maxHistory>60</maxHistory>
      <totalSizeCap>20GB</totalSizeCap>
      <cleanHistoryOnStart>true</cleanHistoryOnStart>
    </rollingPolicy>

    <encoder>
      <charset>UTF-8</charset>
      <pattern>%d %5p | %t | %-55logger{55} | %m %n</pattern>
    </encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="DEBUG_FILE" />
    <appender-ref ref="INFO_FILE" />

    <springProfile name ="dev">
      <appender-ref ref="CONSOLE" />
    </springProfile>
  </root>

  <logger name="com.zaxxer.hikari" level="DEBUG" />

</configuration>

Maybe this helps - the following is written to the console:

15:22:34,079 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.11
15:22:34,087 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb - Here is a list of configurators discovered as a service, by rank: 
15:22:34,087 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb -   org.springframework.boot.logging.logback.RootLogLevelConfigurator
15:22:34,087 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb - They will be invoked in order until ExecutionStatus.DO_NOT_INVOKE_NEXT_IF_ANY is returned.
15:22:34,087 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb - Constructed configurator of type class org.springframework.boot.logging.logback.RootLogLevelConfigurator
15:22:34,093 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb - org.springframework.boot.logging.logback.RootLogLevelConfigurator.configure() call lasted 1 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
15:22:34,093 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
15:22:34,094 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
15:22:34,110 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
15:22:34,113 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
15:22:34,113 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 19 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
15:22:34,113 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
15:22:34,114 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
15:22:34,116 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
15:22:34,116 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:nested:/C:/Users/thomas/Desktop/test-1.1.1.jar/!BOOT-INF/classes/!/logback.xml]
15:22:34,137 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@39d9314d - URL [jar:nested:/C:/Users/thomas/Desktop/test-1.1.1.jar/!BOOT-INF/classes/!/logback.xml] is not of type file
15:22:34,403 |-INFO in ch.qos.logback.core.model.processor.conditional.IfModelHandler - Condition [property("SERVER_LOG_PATH").isEmpty()] evaluated to true on line 6
15:22:34,411 |-WARN in ch.qos.logback.core.model.processor.ImplicitModelHandler - Ignoring unknown property [springProfile] in [ch.qos.logback.classic.LoggerContext]
15:22:34,413 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [DEBUG_FILE]
15:22:34,413 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
15:22:34,430 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@194481424 - setting totalSizeCap to 20 GB
15:22:34,433 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@194481424 - Archive files will be limited to [300 MB] each.
15:22:34,457 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@194481424 - No compression will be used
15:22:34,459 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@194481424 - Will use the pattern ./log/test_%d{yyyyMMdd}_debug_%i.log for the active file
15:22:34,482 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@5b7a8434 - The date pattern is 'yyyyMMdd' from file name pattern './log/test_%d{yyyyMMdd}_debug_%i.log'.
15:22:34,482 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@5b7a8434 - Roll-over at midnight.
15:22:34,488 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@5b7a8434 - Setting initial period to 2023-12-21T14:22:34.488Z
15:22:34,496 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@194481424 - Cleaning on start up
15:22:34,503 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
15:22:34,503 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - first clean up after appender initialization
15:22:34,504 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - Multiple periods, i.e. 32 periods, seem to have elapsed. This is expected at application start.
15:22:34,540 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - Removed  0 Bytes of files
15:22:34,553 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[DEBUG_FILE] - Active log file name: ./log/test_20231221_debug_0.log
15:22:34,553 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[DEBUG_FILE] - File property is set to [null]
15:22:34,555 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [INFO_FILE]
15:22:34,555 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
15:22:34,556 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1548081008 - setting totalSizeCap to 20 GB
15:22:34,556 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1548081008 - Archive files will be limited to [300 MB] each.
15:22:34,556 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1548081008 - No compression will be used
15:22:34,556 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1548081008 - Will use the pattern ./log/test_%d{yyyyMMdd}_%i.log for the active file
15:22:34,556 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@2ce6c6ec - The date pattern is 'yyyyMMdd' from file name pattern './log/test_%d{yyyyMMdd}_%i.log'.
15:22:34,556 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@2ce6c6ec - Roll-over at midnight.
15:22:34,556 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@2ce6c6ec - Setting initial period to 2023-12-21T14:22:34.556Z
15:22:34,557 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1548081008 - Cleaning on start up
15:22:34,557 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
15:22:34,557 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - first clean up after appender initialization
15:22:34,557 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - Multiple periods, i.e. 32 periods, seem to have elapsed. This is expected at application start.
15:22:34,558 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[INFO_FILE] - Active log file name: ./log/test_20231221_0.log
15:22:34,558 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[INFO_FILE] - File property is set to [null]
15:22:34,558 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to INFO
15:22:34,559 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [DEBUG_FILE] to Logger[ROOT]
15:22:34,560 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [INFO_FILE] to Logger[ROOT]
15:22:34,563 |-WARN in ch.qos.logback.core.model.processor.ImplicitModelHandler - Ignoring unknown property [springProfile] in [ch.qos.logback.classic.Logger]
15:22:34,564 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [xx.xxx] to DEBUG
15:22:34,564 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [com.zaxxer.hikari] to DEBUG
15:22:34,564 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [com.vaadin.flow.server.communication.ServerRpcHandler] to DEBUG
15:22:34,564 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [com.vaadin.flow.server.communication.rpc.AbstractRpcInvocationHandler] to ERROR
15:22:34,564 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@1bae316d - End of configuration.
15:22:34,565 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@147a5d08 - Registering current configuration as safe fallback point
15:22:34,565 |-INFO in ch.qos.logback.classic.util.ContextInitializer@727eb8cb - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 451 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY

15:22:35,023 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@4efcf8a - URL [jar:nested:/C:/Users/thomas/Desktop/test-1.1.1.jar/!BOOT-INF/classes/!/logback.xml] is not of type file
15:22:35,033 |-WARN in org.springframework.boot.logging.logback.SpringProfileIfNestedWithinSecondPhaseElementSanityChecker@7a138fc5 - <springProfile> elements cannot be nested within an <appender>, <logger> or <root> element
15:22:35,034 |-WARN in org.springframework.boot.logging.logback.SpringProfileIfNestedWithinSecondPhaseElementSanityChecker@7a138fc5 - Element <root> at line 59 contains a nested <springProfile> element at line 63
15:22:35,037 |-INFO in ch.qos.logback.core.model.processor.conditional.IfModelHandler - Condition [property("SERVER_LOG_PATH").isEmpty()] evaluated to true on line 6
15:22:35,040 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [DEBUG_FILE]
15:22:35,040 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
15:22:35,041 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@932885627 - setting totalSizeCap to 20 GB
15:22:35,041 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@932885627 - Archive files will be limited to [300 MB] each.
15:22:35,041 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@932885627 - No compression will be used
15:22:35,042 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@932885627 - Will use the pattern ./log/test_%d{yyyyMMdd}_debug_%i.log for the active file
15:22:35,042 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@307765b4 - The date pattern is 'yyyyMMdd' from file name pattern './log/test_%d{yyyyMMdd}_debug_%i.log'.
15:22:35,042 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@307765b4 - Roll-over at midnight.
15:22:35,042 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@307765b4 - Setting initial period to 2023-12-21T14:22:35.042Z
15:22:35,043 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@932885627 - Cleaning on start up
15:22:35,043 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
15:22:35,043 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - first clean up after appender initialization
15:22:35,043 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - Multiple periods, i.e. 32 periods, seem to have elapsed. This is expected at application start.
15:22:35,043 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[DEBUG_FILE] - Active log file name: ./log/test_20231221_debug_0.log
15:22:35,043 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[DEBUG_FILE] - File property is set to [null]
15:22:35,044 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [INFO_FILE]
15:22:35,044 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
15:22:35,044 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1251897263 - setting totalSizeCap to 20 GB
15:22:35,044 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1251897263 - Archive files will be limited to [300 MB] each.
15:22:35,045 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1251897263 - No compression will be used
15:22:35,045 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1251897263 - Will use the pattern ./log/test_%d{yyyyMMdd}_%i.log for the active file
15:22:35,045 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@2c95ac9e - The date pattern is 'yyyyMMdd' from file name pattern './log/test_%d{yyyyMMdd}_%i.log'.
15:22:35,045 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@2c95ac9e - Roll-over at midnight.
15:22:35,045 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@2c95ac9e - Setting initial period to 2023-12-21T14:22:35.045Z
15:22:35,045 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1251897263 - Cleaning on start up
15:22:35,046 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
15:22:35,046 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - first clean up after appender initialization
15:22:35,046 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - Multiple periods, i.e. 32 periods, seem to have elapsed. This is expected at application start.
15:22:35,046 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[INFO_FILE] - Active log file name: ./log/test_20231221_0.log
15:22:35,046 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[INFO_FILE] - File property is set to [null]
15:22:35,047 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [xx.xxx] to DEBUG
15:22:35,047 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4e4efc1b - Propagating DEBUG level on Logger[xx.xxx] onto the JUL framework
15:22:35,048 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [com.zaxxer.hikari] to DEBUG
15:22:35,048 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4e4efc1b - Propagating DEBUG level on Logger[com.zaxxer.hikari] onto the JUL framework
15:22:35,048 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [com.vaadin.flow.server.communication.ServerRpcHandler] to DEBUG
15:22:35,048 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4e4efc1b - Propagating DEBUG level on Logger[com.vaadin.flow.server.communication.ServerRpcHandler] onto the JUL framework
15:22:35,048 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [com.vaadin.flow.server.communication.rpc.AbstractRpcInvocationHandler] to ERROR
15:22:35,048 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4e4efc1b - Propagating ERROR level on Logger[com.vaadin.flow.server.communication.rpc.AbstractRpcInvocationHandler] onto the JUL framework
15:22:35,048 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@459f7aa3 - End of configuration.
15:22:35,048 |-INFO in org.springframework.boot.logging.logback.SpringBootJoranConfigurator@7cc586a8 - Registering current configuration as safe fallback point

What can I do about it?

like image 774
Thomas Avatar asked Nov 28 '25 18:11

Thomas

1 Answers

You need to update/add following dependency:

<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>7.4</version>
    <scope>runtime</scope>
</dependency>

Spring Boot 3 works with version 7.4.

Ref:https://github.com/zalando/logbook/blob/180a1cce9f8f77f6775907bafa8bf121afdd9571/logbook-parent/pom.xml#L107

like image 192
Honey Keny Malviya Avatar answered Dec 01 '25 13:12

Honey Keny Malviya

Sign in to Comment

Related questions

Spring JMS listener - how to read messages based on a condition
Can not instantiate value of type [simple type, class java.time.LocalDate
Spring security oAuth 2.0 (Invalid token does not contain resource id (oauth2-resource))
Spring-Boot-Admin server fails to register clients from Eureka registry
Failed to solve: lstat /var/lib/docker/tmp/buildkit-mount2554488617/target: no such file or directory

Donate For Us

If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!