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

Spring Boot 3.2.0.: Bad resolving LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN in Tomcat 10.1 with multiple applications #43306

Closed
micobarac opened this issue Nov 27, 2024 · 8 comments
Closed

Spring Boot 3.2.0.: Bad resolving LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN in Tomcat 10.1 with multiple applications #43306

micobarac opened this issue Nov 27, 2024 · 8 comments
Labels
status: invalid An issue that we don't feel is valid

Comments

@micobarac
Copy link

micobarac commented Nov 27, 2024 •
edited
Loading

When resolving LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN in Tomcat 10.1 with multiple applications, Spring Boot 3.2.0 with Logback 1.4.14 gets ${LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN} value from a first application, and reuses it in others, making other applications save *.gz files with wrong location and application name.

org/springframework/boot/logging/logback/file-appender.xml

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

<!--
File appender logback configuration provided for import, equivalent to the programmatic
initialization performed by Boot
-->

<included>
	<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
		<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
			<level>${FILE_LOG_THRESHOLD}</level>
		</filter>
		<encoder>
			<pattern>${FILE_LOG_PATTERN}</pattern>
			<charset>${FILE_LOG_CHARSET}</charset>
		</encoder>
		<file>${LOG_FILE}</file>
		<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
			<fileNamePattern>${LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN:-${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz}</fileNamePattern>
			<cleanHistoryOnStart>${LOGBACK_ROLLINGPOLICY_CLEAN_HISTORY_ON_START:-false}</cleanHistoryOnStart>
			<maxFileSize>${LOGBACK_ROLLINGPOLICY_MAX_FILE_SIZE:-10MB}</maxFileSize>
			<totalSizeCap>${LOGBACK_ROLLINGPOLICY_TOTAL_SIZE_CAP:-0}</totalSizeCap>
			<maxHistory>${LOGBACK_ROLLINGPOLICY_MAX_HISTORY:-7}</maxHistory>
		</rollingPolicy>
	</appender>
</included>

Application 1:

logging:
  level:
    ROOT: INFO
    tech.jhipster: INFO
    com.acme.example: INFO
  file:
    name: /tmp/app1/app1.log
  logback:
    rollingpolicy:
      max-file-size: 10MB
      max-history: 30
      total-size-cap: 100MB
      clean-history-on-start: true
      file-name-pattern: /tmp/app1/app1.log.%d{yyyy-MM-dd}.%i.gz

Application 2:

logging:
  level:
    ROOT: INFO
    tech.jhipster: INFO
    com.acme.example: INFO
  file:
    name: /tmp/app2/app2.log
  logback:
    rollingpolicy:
      max-file-size: 10MB
      max-history: 30
      total-size-cap: 100MB
      clean-history-on-start: true
      file-name-pattern: /tmp/app2/app2.log.%d{yyyy-MM-dd}.%i.gz

Application 2 *.gz files get stored under the location and name prefix of Application 1. Application 2 *.gz files are never created in the dedicated location and name, obviously resolving file-name-pattern of wrong application as ${LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN} value.

Result:

/tmp/app2

-rw-r----- 1 tomcat tomcat 16855 Nov 27 14:24 app2.log

/tmp/app1

-rw-r----- 1 tomcat tomcat 7736 Nov 27 14:25 app1.log
-rw-r----- 1 tomcat tomcat 1106 Nov 27 14:24 app1.log.2024-11-27.0.gz
-rw-r----- 1 tomcat tomcat 3723 Nov 27 14:25 app1.log.2024-11-27.1.gz

Change logback-spring.xml:

<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
    <fileNamePattern>${LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN:-${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz}</fileNamePattern>
    <cleanHistoryOnStart>${LOGBACK_ROLLINGPOLICY_CLEAN_HISTORY_ON_START:-false}</cleanHistoryOnStart>
    <maxFileSize>${LOGBACK_ROLLINGPOLICY_MAX_FILE_SIZE:-10MB}</maxFileSize>
    <totalSizeCap>${LOGBACK_ROLLINGPOLICY_TOTAL_SIZE_CAP:-0}</totalSizeCap>
    <maxHistory>${LOGBACK_ROLLINGPOLICY_MAX_HISTORY:-7}</maxHistory>
</rollingPolicy>

into:

<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
    <fileNamePattern>${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
    <cleanHistoryOnStart>${LOGBACK_ROLLINGPOLICY_CLEAN_HISTORY_ON_START:-false}</cleanHistoryOnStart>
    <maxFileSize>${LOGBACK_ROLLINGPOLICY_MAX_FILE_SIZE:-10MB}</maxFileSize>
    <totalSizeCap>${LOGBACK_ROLLINGPOLICY_TOTAL_SIZE_CAP:-0}</totalSizeCap>
    <maxHistory>${LOGBACK_ROLLINGPOLICY_MAX_HISTORY:-7}</maxHistory>
</rollingPolicy>

and log file rolling policy executes ok.

Result:

/tmp/app2

-rw-r----- 1 tomcat tomcat 16855 Nov 27 14:24 app2.log
-rw-r----- 1 tomcat tomcat 1106 Nov 27 14:24 app2.log.2024-11-27.0.gz

/tmp/app1

-rw-r----- 1 tomcat tomcat 7736 Nov 27 14:25 app1.log
-rw-r----- 1 tomcat tomcat 1106 Nov 27 14:24 app1.log.2024-11-27.0.gz
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Nov 27, 2024
@micobarac micobarac changed the title Spring Boot 3.2.: Bad resolving LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN in Tomcat 10.1 with multiple applications Spring Boot 3.2.0.: Bad resolving LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN in Tomcat 10.1 with multiple applications Nov 27, 2024
@wilkinsona
Copy link
Member

This sounds very similar to #24835 so perhaps there's been a regression somewhere since that fix was made.

Spring Boot 3.2.0 is no longer supported. Please upgrade to a supported version (3.3.6 or 3.4.0 at the time of writing). If the problem persists and you would like us to investigate further, please provide a complete yet minimal example that reproduces the problem and we can take another look.

@wilkinsona wilkinsona added the status: waiting-for-feedback We need additional information before we can continue label Nov 27, 2024
@micobarac
Copy link
Author

micobarac commented Nov 28, 2024 •
edited
Loading

I upgraded both applications to Spring Boot 3.3.6, but the problem with faulty rolling policy persists.

When multiple applications share a JVM, LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN variable is somehow shared between apps, with no isolation, causing logging to wrong *.gz location and file names.

Bwt, it's odd the fact that LOG_FILE variable used within the same org/springframework/boot/logging/logback/file-appender.xml is resolved just fine.

It is very difficult to provide an example, as the code I provided is simplified from two big Spring Boot projects.

@micobarac
Copy link
Author

Btw, upgrading from Spring Boot 3.2.0 to Spring Boot 3.3.6 took me a huge amount of time.

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Nov 28, 2024
@wilkinsona
Copy link
Member

wilkinsona commented Nov 28, 2024 •
edited
Loading

It is very difficult to provide an example, as the code I provided is simplified from two big Spring Boot projects.

Two minimal war applications, created using https://start.spring.io, with just enough configuration to reproduce the problem when deployed to Tomcat would suffice.

Btw, upgrading from Spring Boot 3.2.0 to Spring Boot 3.3.6 took me a huge amount of time.

Sorry to hear that. If there's anything in particular that tripped you up and think should have been covered in the release notes, please open a new issue with some details and we can take a look.

@wilkinsona wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Nov 28, 2024
@micobarac
Copy link
Author

Well, dependencies inside pom.xml were troublesome when upgrading Spring Boot. But, I managed.

@wilkinsona wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: waiting-for-feedback We need additional information before we can continue labels Nov 28, 2024
@micobarac
Copy link
Author

micobarac commented Nov 28, 2024 •
edited
Loading

These are the relevant Catalina log lines:

13:44:08,116 |-INFO in ch.qos.logback.core.model.processor.ModelInterpretationContext@5d4d1928 - value "/tmp/app1/app1.log" substituted for "${LOG_FILE}"
13:44:08,118 |-INFO in ch.qos.logback.core.model.processor.ModelInterpretationContext@5d4d1928 - value "/tmp/app1/app1.log.%d{yyyy-MM-dd-HH-mm}.%i.gz" substituted for "${LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN:-${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz}"

13:05:48,637 |-INFO in ch.qos.logback.core.model.processor.ModelInterpretationContext@305e0cb7 - value "/tmp/app2/app2.log" substituted for "${LOG_FILE}"
13:05:48,639 |-INFO in ch.qos.logback.core.model.processor.ModelInterpretationContext@305e0cb7 - value "/tmp/app1/app1.log.%d{yyyy-MM-dd-HH-mm}.%i.gz" substituted for "${LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN:-${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz}"

It's obvious that LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN is substituted incorrectly for app2.

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Nov 28, 2024
@wilkinsona wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Nov 28, 2024
@wilkinsona
Copy link
Member

Unfortunately, I can't reproduce the behavior that you've described using the information that you've provided thus far.

I have two Spring Boot 3.3.6 apps, one and two, deployed as war files to Tomcat 10.1. App one is configured as follows:

spring:
  application:
    name: one
logging:
  level:
    ROOT: INFO
  file:
    name: app1/app1.log
  logback:
    rollingpolicy:
      max-file-size: 10MB
      max-history: 30
      total-size-cap: 100MB
      clean-history-on-start: true
      file-name-pattern: app1/app1.log.%d{yyyy-MM-dd}.%i.gz

And app2 is configured as follows:

spring:
  application:
    name: two
logging:
  level:
    ROOT: INFO
  file:
    name: app2/app2.log
  logback:
    rollingpolicy:
      max-file-size: 10MB
      max-history: 30
      total-size-cap: 100MB
      clean-history-on-start: true
      file-name-pattern: app2/app2.log.%d{yyyy-MM-dd}.%i.gz

I've started Tomcat with -Dlogback.debug=true so that Logback outputs some diagnostics information about its configuration. Here's the relevant log output when I start Tomcat:

28-Nov-2024 13:05:15.608 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/Users/awilkinson/dev/temp/gh-43306/apache-tomcat-10.1.33/webapps/two-0.0.1-SNAPSHOT.war]
28-Nov-2024 13:05:17.307 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
13:05:18,043 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Adding conversion rule of type 'org.springframework.boot.logging.logback.ApplicationNameConverter' for word 'applicationName'
13:05:18,047 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Adding conversion rule of type 'org.springframework.boot.logging.logback.ColorConverter' for word 'clr'
13:05:18,048 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Adding conversion rule of type 'org.springframework.boot.logging.logback.CorrelationIdConverter' for word 'correlationId'
13:05:18,049 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Adding conversion rule of type 'org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter' for word 'wex'
13:05:18,051 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Adding conversion rule of type 'org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter' for word 'wEx'
13:05:18,064 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Configuring logger 'org.apache.catalina.startup.DigesterFactory' with level 'ERROR'. Additive: true
13:05:18,065 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Configuring logger 'org.apache.catalina.util.LifecycleBase' with level 'ERROR'. Additive: true
13:05:18,065 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Configuring logger 'org.apache.coyote.http11.Http11NioProtocol' with level 'WARN'. Additive: true
13:05:18,065 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Configuring logger 'org.apache.sshd.common.util.SecurityUtils' with level 'WARN'. Additive: true
13:05:18,065 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Configuring logger 'org.apache.tomcat.util.net.NioSelectorPool' with level 'WARN'. Additive: true
13:05:18,065 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Configuring logger 'org.eclipse.jetty.util.component.AbstractLifeCycle' with level 'ERROR'. Additive: true
13:05:18,065 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Configuring logger 'org.hibernate.validator.internal.util.Version' with level 'WARN'. Additive: true
13:05:18,065 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Configuring logger 'org.springframework.boot.actuate.endpoint.jmx' with level 'WARN'. Additive: true
13:05:18,067 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Starting 'ch.qos.logback.classic.encoder.PatternLayoutEncoder@5b53c3c5'
13:05:18,099 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Adding appender 'ch.qos.logback.core.ConsoleAppender[null]' named 'CONSOLE'
13:05:18,099 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Starting 'ch.qos.logback.core.ConsoleAppender[CONSOLE]'
13:05:18,102 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Starting 'ch.qos.logback.classic.encoder.PatternLayoutEncoder@5e085259'
13:05:18,107 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575 - setting totalSizeCap to 100 MB
13:05:18,108 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Starting 'c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575'
13:05:18,111 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575 - Archive files will be limited to [10 MB] each.
13:05:18,116 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575 - Will use gz compression
13:05:18,119 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575 - Will use the pattern app2/app2.log.%d{yyyy-MM-dd}.%i for the active file
13:05:18,128 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@1735e1c4 - The date pattern is 'yyyy-MM-dd' from file name pattern 'app2/app2.log.%d{yyyy-MM-dd}.%i.gz'.
13:05:18,128 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@1735e1c4 - Roll-over at midnight.
13:05:18,131 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@1735e1c4 - Setting initial period to 2024-11-28T13:01:34.753Z
13:05:18,136 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575 - Cleaning on start up
13:05:18,137 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Adding appender 'ch.qos.logback.core.rolling.RollingFileAppender[null]' named 'FILE'
13:05:18,137 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - first clean up after appender initialization
13:05:18,137 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Starting 'ch.qos.logback.core.rolling.RollingFileAppender[FILE]'
13:05:18,139 |-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.
13:05:18,141 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: app2/app2.log
13:05:18,144 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Setting currentFileLength to 833 for app2/app2.log
13:05:18,144 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [app2/app2.log]
13:05:18,164 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - No removal attempts were made.

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/

 :: Spring Boot ::                (v3.3.6)

2024-11-28T13:05:18.295Z  INFO 92164 --- [two] [           main] com.example.two.ServletInitializer       : Starting ServletInitializer v0.0.1-SNAPSHOT using Java 17.0.13 with PID 92164 (/Users/awilkinson/dev/temp/gh-43306/apache-tomcat-10.1.33/webapps/two-0.0.1-SNAPSHOT/WEB-INF/classes started by awilkinson in /Users/awilkinson/dev/temp/gh-43306)
2024-11-28T13:05:18.298Z  INFO 92164 --- [two] [           main] com.example.two.ServletInitializer       : No active profile set, falling back to 1 default profile: "default"
2024-11-28T13:05:19.218Z  INFO 92164 --- [two] [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 858 ms
2024-11-28T13:05:19.997Z  INFO 92164 --- [two] [           main] com.example.two.ServletInitializer       : Started ServletInitializer in 2.408 seconds (process running for 5.109)
28-Nov-2024 13:05:20.048 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/Users/awilkinson/dev/temp/gh-43306/apache-tomcat-10.1.33/webapps/two-0.0.1-SNAPSHOT.war] has finished in [4,439] ms
28-Nov-2024 13:05:20.050 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/Users/awilkinson/dev/temp/gh-43306/apache-tomcat-10.1.33/webapps/one-0.0.1-SNAPSHOT.war]
28-Nov-2024 13:05:21.315 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
13:05:21,928 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Adding conversion rule of type 'org.springframework.boot.logging.logback.ApplicationNameConverter' for word 'applicationName'
13:05:21,930 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Adding conversion rule of type 'org.springframework.boot.logging.logback.ColorConverter' for word 'clr'
13:05:21,931 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Adding conversion rule of type 'org.springframework.boot.logging.logback.CorrelationIdConverter' for word 'correlationId'
13:05:21,932 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Adding conversion rule of type 'org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter' for word 'wex'
13:05:21,934 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Adding conversion rule of type 'org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter' for word 'wEx'
13:05:21,942 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Configuring logger 'org.apache.catalina.startup.DigesterFactory' with level 'ERROR'. Additive: true
13:05:21,943 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Configuring logger 'org.apache.catalina.util.LifecycleBase' with level 'ERROR'. Additive: true
13:05:21,943 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Configuring logger 'org.apache.coyote.http11.Http11NioProtocol' with level 'WARN'. Additive: true
13:05:21,943 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Configuring logger 'org.apache.sshd.common.util.SecurityUtils' with level 'WARN'. Additive: true
13:05:21,943 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Configuring logger 'org.apache.tomcat.util.net.NioSelectorPool' with level 'WARN'. Additive: true
13:05:21,943 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Configuring logger 'org.eclipse.jetty.util.component.AbstractLifeCycle' with level 'ERROR'. Additive: true
13:05:21,943 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Configuring logger 'org.hibernate.validator.internal.util.Version' with level 'WARN'. Additive: true
13:05:21,943 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Configuring logger 'org.springframework.boot.actuate.endpoint.jmx' with level 'WARN'. Additive: true
13:05:21,945 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Starting 'ch.qos.logback.classic.encoder.PatternLayoutEncoder@7d9277f7'
13:05:21,976 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Adding appender 'ch.qos.logback.core.ConsoleAppender[null]' named 'CONSOLE'
13:05:21,976 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Starting 'ch.qos.logback.core.ConsoleAppender[CONSOLE]'
13:05:21,978 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Starting 'ch.qos.logback.classic.encoder.PatternLayoutEncoder@6b02c3c4'
13:05:21,981 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285 - setting totalSizeCap to 100 MB
13:05:21,981 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Starting 'c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285'
13:05:21,984 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285 - Archive files will be limited to [10 MB] each.
13:05:21,986 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285 - Will use gz compression
13:05:21,990 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285 - Will use the pattern app1/app1.log.%d{yyyy-MM-dd}.%i for the active file
13:05:21,994 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@2efbc6f9 - The date pattern is 'yyyy-MM-dd' from file name pattern 'app1/app1.log.%d{yyyy-MM-dd}.%i.gz'.
13:05:21,995 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@2efbc6f9 - Roll-over at midnight.
13:05:21,995 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@2efbc6f9 - Setting initial period to 2024-11-28T13:01:38.175Z
13:05:21,997 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285 - Cleaning on start up
13:05:21,999 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Adding appender 'ch.qos.logback.core.rolling.RollingFileAppender[null]' named 'FILE'
13:05:21,999 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Starting 'ch.qos.logback.core.rolling.RollingFileAppender[FILE]'
13:05:21,999 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - first clean up after appender initialization
13:05:22,000 |-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.
13:05:22,003 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: app1/app1.log
13:05:22,003 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Setting currentFileLength to 833 for app1/app1.log
13:05:22,003 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [app1/app1.log]
13:05:22,024 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - No removal attempts were made.

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/

 :: Spring Boot ::                (v3.3.6)

2024-11-28T13:05:22.148Z  INFO 92164 --- [one] [           main] com.example.one.ServletInitializer       : Starting ServletInitializer v0.0.1-SNAPSHOT using Java 17.0.13 with PID 92164 (/Users/awilkinson/dev/temp/gh-43306/apache-tomcat-10.1.33/webapps/one-0.0.1-SNAPSHOT/WEB-INF/classes started by awilkinson in /Users/awilkinson/dev/temp/gh-43306)
2024-11-28T13:05:22.151Z  INFO 92164 --- [one] [           main] com.example.one.ServletInitializer       : No active profile set, falling back to 1 default profile: "default"
2024-11-28T13:05:23.022Z  INFO 92164 --- [one] [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 806 ms
2024-11-28T13:05:23.658Z  INFO 92164 --- [one] [           main] com.example.one.ServletInitializer       : Started ServletInitializer in 2.157 seconds (process running for 8.77)
28-Nov-2024 13:05:23.669 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/Users/awilkinson/dev/temp/gh-43306/apache-tomcat-10.1.33/webapps/one-0.0.1-SNAPSHOT.war] has finished in [3,619] ms
28-Nov-2024 13:05:23.674 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
28-Nov-2024 13:05:23.688 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [8139] milliseconds

It chooses to deploy app two and then app one. The log lines for the rolling policy for app two are:

13:05:18,107 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575 - setting totalSizeCap to 100 MB
13:05:18,108 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@553d828a - Starting 'c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575'
13:05:18,111 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575 - Archive files will be limited to [10 MB] each.
13:05:18,116 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575 - Will use gz compression
13:05:18,119 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@587108575 - Will use the pattern app2/app2.log.%d{yyyy-MM-dd}.%i for the active file
13:05:18,128 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@1735e1c4 - The date pattern is 'yyyy-MM-dd' from file name pattern 'app2/app2.log.%d{yyyy-MM-dd}.%i.gz'.
13:05:18,128 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@1735e1c4 - Roll-over at midnight.
13:05:18,131 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@1735e1c4 - Setting initial period to 2024-11-28T13:01:34.753Z

And the eqivalent log lines for app one:

13:05:21,981 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285 - setting totalSizeCap to 100 MB
13:05:21,981 |-INFO in org.springframework.boot.logging.logback.DebugLogbackConfigurator@42f5ee2d - Starting 'c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285'
13:05:21,984 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285 - Archive files will be limited to [10 MB] each.
13:05:21,986 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285 - Will use gz compression
13:05:21,990 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@60695285 - Will use the pattern app1/app1.log.%d{yyyy-MM-dd}.%i for the active file
13:05:21,994 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@2efbc6f9 - The date pattern is 'yyyy-MM-dd' from file name pattern 'app1/app1.log.%d{yyyy-MM-dd}.%i.gz'.
13:05:21,995 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@2efbc6f9 - Roll-over at midnight.
13:05:21,995 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFileNamingAndTriggeringPolicy@2efbc6f9 - Setting initial period to 2024-11-28T13:01:38.175Z

There's no sign of app one picking up configuration for the already-deployed app two.

Unfortunately, we won't be able to spend any more time on this one without a minimal sample that reproduces the problem.

@micobarac
Copy link
Author

micobarac commented Nov 28, 2024 •
edited
Loading

In my case, I concluded that all of logging.logback.rollingpolicy variables in app2 are mapped from app1. I've seen others having the similar problem, too. Anyway, let's not waste any time on this, as you said. You may close this issue.

My projects are too complex to be simplified for analysis, I'll investigate further.

UPDATE: Removing logging.logback.rollingpolicy.* from application-prod.yml and setting RollingFileAppender in logback-spring.xml with explicit rolling policy settings for both apps works a workaround. The problem is mapping logging.logback.rollingpolicy.* from application-prod.yml to logback-spring.xml.

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Nov 28, 2024
@wilkinsona wilkinsona closed this as not planned Won't fix, can't repro, duplicate, stale Nov 28, 2024
@wilkinsona wilkinsona added status: invalid An issue that we don't feel is valid and removed status: waiting-for-triage An issue we've not yet triaged status: feedback-provided Feedback has been provided labels Nov 28, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
status: invalid An issue that we don't feel is valid
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@wilkinsona @micobarac @spring-projects-issues