Using SpringBoot version 1.3.2.RELEASE
Occasionally my tests fail with the error below. It is sporadic, but it appears that one LoggingSystem might be cleaning up when another is initialized.:
Caused by: java.lang.IllegalStateException: Logback configuration error detected:
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - There is no conversion class registered for composite conversion word [clr]
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - Failed to create converter for [%clr] keyword
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - There is no conversion class registered for composite conversion word [clr]
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - Failed to create converter for [%clr] keyword
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - There is no conversion class registered for composite conversion word [clr]
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - Failed to create converter for [%clr] keyword
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - There is no conversion class registered for composite conversion word [clr]
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - Failed to create converter for [%clr] keyword
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - There is no conversion class registered for composite conversion word [clr]
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - Failed to create converter for [%clr] keyword
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - There is no conversion class registered for composite conversion word [clr]
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - Failed to create converter for [%clr] keyword
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - There is no conversion class registered for composite conversion word [clr]
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - Failed to create converter for [%clr] keyword
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - There is no conversion class registered for conversion word [wEx]
ERROR in ch.qos.logback.core.pattern.parser.Compiler@729ed61b - [wEx] is not a valid conversion word
ERROR in ch.qos.logback.core.pattern.parser.Compiler@71516065 - There is no conversion class registered for conversion word [wEx]
ERROR in ch.qos.logback.core.pattern.parser.Compiler@71516065 - [wEx] is not a valid conversion word
at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:153)
at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:71)
at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:49)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:106)
at org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:262)
at org.springframework.boot.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:233)
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:200)
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:176)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:163)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:136)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:119)
at org.springframework.boot.context.event.EventPublishingRunListener.publishEvent(EventPublishingRunListener.java:111)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:65)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
at org.springframework.boot.SpringApplication.createAndRefreshContext(SpringApplication.java:330)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:307)
at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:134)
at org.springframework.cloud.bootstrap.BootstrapApplicationListener.bootstrapServiceContext(BootstrapApplicationListener.java:129)
at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:78)
at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:58)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:163)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:136)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:119)
at org.springframework.boot.context.event.EventPublishingRunListener.publishEvent(EventPublishingRunListener.java:111)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:65)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
at org.springframework.boot.SpringApplication.createAndRefreshContext(SpringApplication.java:330)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:307)
at org.springframework.boot.test.SpringApplicationContextLoader.loadContext(SpringApplicationContextLoader.java:98)
at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:98)
at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:116)
... 51 more
I've tried to create a sample application that consistently triggers the behavior, but the best I've been able to do is initialize the logging system a bunch in separate threads and observer that similar occur (though not identical)
for(int i =0; i < 100; i++){
new Thread(() -> {
LoggingSystem system = LoggingSystem.get(LoggingSystem.class.getClassLoader());
system.initialize(new LoggingInitializationContext(environment), (String)null, (LogFile)null);
}).start();
}
Comment From: wilkinsona
I suspect this is a duplicate of #5568. @checketts can you please try a 1.3.4 snapshot or override Logback's version to 1.1.7
Comment From: pfernandom
@checketts, upgrading Logback's version to 1.1.7 fix this issue for me. Thank you.
Comment From: checketts
Try this @westse
Comment From: checketts
@wilkinsona Just to give you an update. I'm attempting to upgrade to Logback 1.1.7 to verify the fix. The nature of the race condition makes it a bit difficult to verify (along with the fact that the upgrade requires me to upgrade slf4j and some other internal libs)
Comment From: wilkinsona
@checketts Thanks for the update. Given the success reported by @pfernandom, I'm going to close this issue for now. If it turns out that the problem is not fixed by upgrading Logback please let us know and we can re-open.
Comment From: checketts
@wilkinsona The upgrade to logback 1.1.7 didn't solve this for us.
We see this primarily in our integration tests. The error message has changed a little, from the one I posted before, though we had seen this same error message (stream closed) before as well.
at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:124)
at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:83)
at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:117)
at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:83)
at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:228)
at org.springframework.test.context.testng.AbstractTestNGSpringContextTests.springTestContextPrepareTestInstance(AbstractTestNGSpringContextTests.java:149)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
at org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:510)
at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:211)
at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:138)
at org.testng.internal.TestMethodWorker.invokeBeforeClassMethods(TestMethodWorker.java:170)
at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:104)
at org.testng.TestRunner.privateRun(TestRunner.java:774)
at org.testng.TestRunner.run(TestRunner.java:624)
at org.testng.SuiteRunner.runTest(SuiteRunner.java:359)
at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:354)
at org.testng.SuiteRunner.privateRun(SuiteRunner.java:312)
at org.testng.SuiteRunner.run(SuiteRunner.java:261)
at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
at org.testng.TestNG.runSuitesSequentially(TestNG.java:1215)
at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
at org.testng.TestNG.run(TestNG.java:1048)
at org.gradle.api.internal.tasks.testing.testng.TestNGTestClassProcessor.runTests(TestNGTestClassProcessor.java:133)
at org.gradle.api.internal.tasks.testing.testng.TestNGTestClassProcessor.stop(TestNGTestClassProcessor.java:83)
at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:61)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
at org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
at org.gradle.messaging.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)
at org.gradle.messaging.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
at com.sun.proxy.$Proxy2.stop(Unknown Source)
at org.gradle.api.internal.tasks.testing.worker.TestWorker.stop(TestWorker.java:120)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
at org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
at org.gradle.messaging.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:360)
at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:54)
at org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:40)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: Logback configuration error detected:
ERROR in c.q.l.c.recovery.ResilientFileOutputStream@761951571 - IO failure while writing to file [logs/output.log] java.io.IOException: Stream Closed
at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:153)
at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:71)
at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:49)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:106)
at org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:262)
at org.springframework.boot.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:233)
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:200)
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:176)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:163)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:136)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:119)
at org.springframework.boot.context.event.EventPublishingRunListener.publishEvent(EventPublishingRunListener.java:111)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:65)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
at org.springframework.boot.SpringApplication.createAndRefreshContext(SpringApplication.java:330)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:307)
at org.springframework.boot.test.SpringApplicationContextLoader.loadContext(SpringApplicationContextLoader.java:98)
at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:98)
at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:116)
... 51 more
Comment From: checketts
2 other details that can help diagnose this:
1- We are using Spring Cloud. Which initializes a BootStrapApplicationContext, I suspect that when the main application context is restarting the logging reinitialization it is causing this.
2- We are using the logback-spring.xml file so we can use the <springProperty> functionality.
Comment From: checketts
Other set of error messages I'm able to see: 'File' option has the same value "logs/output.log" as that given for appender [FILE] defined earlier
java.lang.IllegalStateException: Logback configuration error detected:
ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - 'File' option has the same value "logs/output.log" as that given for appender [FILE] defined earlier.
ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Collisions detected with FileAppender/RollingAppender instances defined earlier. Aborting.
ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - For more information, please visit http://logback.qos.ch/codes.html#earlier_fa_collision
at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:153)
at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:71)
at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:49)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:106)
at org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:262)
at org.springframework.boot.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:233)
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:200)
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:176)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:163)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:136)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:119)
at org.springframework.boot.context.event.EventPublishingRunListener.publishEvent(EventPublishingRunListener.java:111)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:65)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
at org.springframework.boot.SpringApplication.createAndRefreshContext(SpringApplication.java:330)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:307)
at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:134)
at org.springframework.cloud.bootstrap.BootstrapApplicationListener.bootstrapServiceContext(BootstrapApplicationListener.java:129)
at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:78)
at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:58)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:163)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:136)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:119)
at org.springframework.boot.context.event.EventPublishingRunListener.publishEvent(EventPublishingRunListener.java:111)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:65)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
at org.springframework.boot.SpringApplication.createAndRefreshContext(SpringApplication.java:330)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:307)
at org.springframework.boot.test.SpringApplicationContextLoader.loadContext(SpringApplicationContextLoader.java:98)
at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:98)
at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:116)
at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:83)
at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:117)
at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:83)
at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:228)
at org.springframework.test.context.testng.AbstractTestNGSpringContextTests.springTestContextPrepareTestInstance(AbstractTestNGSpringContextTests.java:149)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
at org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:510)
at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:211)
at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:138)
at org.testng.internal.TestMethodWorker.invokeBeforeClassMethods(TestMethodWorker.java:170)
at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:104)
at org.testng.TestRunner.privateRun(TestRunner.java:774)
at org.testng.TestRunner.run(TestRunner.java:624)
at org.testng.SuiteRunner.runTest(SuiteRunner.java:359)
at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:354)
at org.testng.SuiteRunner.privateRun(SuiteRunner.java:312)
at org.testng.SuiteRunner.run(SuiteRunner.java:261)
at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
at org.testng.TestNG.runSuitesSequentially(TestNG.java:1215)
at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
at org.testng.TestNG.run(TestNG.java:1048)
at org.testng.IDEARemoteTestNG.run(IDEARemoteTestNG.java:74)
at org.testng.RemoteTestNGStarter.main(RemoteTestNGStarter.java:121)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:144)
Comment From: checketts
The good (and bad news) is that now I can make this error happen every time. Should I still try using 1.3.4-SNAPSHOT or did you remove your workaround there?
Comment From: philwebb
@checketts Are you able to share something that consistently replicates the issue?
Comment From: checketts
@philwebb Yes! I think I found the root cause. So we have some code that adds in some extra PropertySources, then triggers the LoggingApplicationInitializer code that initializes logging.
However, it turns out that my code that was adding the extra property source and triggering the logging reinitialization was occurring on a separate thread. So I'm guessing it had started reinitializing logging on the second thread while to main thread was doing the same thing.
Maybe the solution would be as simple as making the initialize method use a synchronized block? https://github.com/spring-projects/spring-boot/blob/2364bcc1172b570f917dc24819776813cb27def0/spring-boot/src/main/java/org/springframework/boot/logging/LoggingApplicationListener.java#L254
Let me know if you would like more details.
In the application that I was wrestling with I just ensured that the failing path doesn't spin off an async thread to do its work and the problem went way.
Comment From: NiteshMehta
We are facing this problem quite frequently, We have spring boot (1.3.0) application with hibernate hibernate and we are using external logback.xml. We upgraded logback to 1.1.7 but no success. It looks like Hibernate Validator is initialized in different thread using BackgroundPreinitializer. When spring boot is re-configuring logging system, Hibernate Validator is having handle to old logger instance, which is causing the problem Stack traces:
Defect Logs:
java.lang.IllegalStateException: Logback configuration error detected:
ERROR in c.q.l.c.recovery.ResilientFileOutputStream@885755284 - IO failure while writing to file [C:\testProject\logs\server.log] java.io.IOException: Stream Closed
at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:153) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.logging.logback.LogbackLoggingSystem.reinitialize(LogbackLoggingSystem.java:197) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:64) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:49) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:106) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:261) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:232) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:199) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:176) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:163) ~[spring-context-4.2.3.RELEASE.jar:4.2.3.RELEASE]
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:136) ~[spring-context-4.2.3.RELEASE.jar:4.2.3.RELEASE]
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:119) ~[spring-context-4.2.3.RELEASE.jar:4.2.3.RELEASE]
at org.springframework.boot.context.event.EventPublishingRunListener.publishEvent(EventPublishingRunListener.java:111) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:65) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.SpringApplication.doRun(SpringApplication.java:315) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.SpringApplication.run(SpringApplication.java:295) ~[spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.context.web.SpringBootServletInitializer.run(SpringBootServletInitializer.java:149) [spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.context.web.SpringBootServletInitializer.createRootApplicationContext(SpringBootServletInitializer.java:129) [spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.boot.context.web.SpringBootServletInitializer.onStartup(SpringBootServletInitializer.java:85) [spring-boot-1.3.0.RELEASE.jar:1.3.0.RELEASE]
at org.springframework.web.SpringServletContainerInitializer.onStartup(SpringServletContainerInitializer.java:175) [spring-web-4.2.3.RELEASE.jar:4.2.3.RELEASE]
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5170) [catalina.jar:8.0.28]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) [catalina.jar:8.0.28]
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:725) [catalina.jar:8.0.28]
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:701) [catalina.jar:8.0.28]
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:717) [catalina.jar:8.0.28]
at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:945) [catalina.jar:8.0.28]
at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1798) [catalina.jar:8.0.28]
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [na:1.8.0_91]
at java.util.concurrent.FutureTask.run(Unknown Source) [na:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [na:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [na:1.8.0_91]
at java.lang.Thread.run(Unknown Source) [na:1.8.0_91]
**ROOT CAUSE:
Thread Stack: when logging system is initialize as default:**
Thread [main] (Suspended (breakpoint at line 27 in ResilientFileOutputStream))
owns: LogbackLock (id=30)
ResilientFileOutputStream.<init>(File, boolean) line: 27
RollingFileAppender<E>(FileAppender<E>).openFile(String) line: 148
RollingFileAppender<E>(FileAppender<E>).start() line: 108
RollingFileAppender<E>.start() line: 86
AppenderAction<E>.end(InterpretationContext, String) line: 96
Interpreter.callEndAction(List<Action>, String) line: 317
Interpreter.endElement(String, String, String) line: 196
Interpreter.endElement(EndEvent) line: 182
EventPlayer.play(List<SaxEvent>) line: 62
JoranConfigurator(GenericConfigurator).doConfigure(List<SaxEvent>) line: 149
JoranConfigurator(GenericConfigurator).doConfigure(InputSource) line: 135
JoranConfigurator(GenericConfigurator).doConfigure(InputStream) line: 99
JoranConfigurator(GenericConfigurator).doConfigure(URL) line: 49
ContextInitializer.configureByResource(URL) line: 77
ContextInitializer.autoConfig() line: 152
StaticLoggerBinder.init() line: 85
StaticLoggerBinder.<clinit>() line: 55
LoggerFactory.bind() line: 140
LoggerFactory.performInitialization() line: 119
LoggerFactory.getILoggerFactory() line: 328
LoggerFactory.getLogger(String) line: 280
SLF4JLogFactory.getInstance(String) line: 155
SLF4JLogFactory.getInstance(Class) line: 132
LogFactory.getLog(Class) line: 273
SpringApplication.<init>(Object...) line: 181
SpringApplication.run(Object[], String[]) line: 1112
SpringApplication.run(Object, String...) line: 1101
`
**Thread Stack: when logging system is reconfigured by spring and it’s trying to shut down existing system: (Notice output stream is being closed here)**
`
Thread [main] (Suspended (breakpoint at line 111 in ResilientOutputStreamBase))
ResilientFileOutputStream(ResilientOutputStreamBase).close() line: 111
RollingFileAppender<E>(OutputStreamAppender<E>).closeOutputStream() line: 131
RollingFileAppender<E>(OutputStreamAppender<E>).stop() line: 116
RollingFileAppender<E>.stop() line: 106
AppenderAttachableImpl<E>.detachAndStopAllAppenders() line: 104
Logger.detachAndStopAllAppenders() line: 209
Logger.recursiveReset() line: 338
LoggerContext.reset() line: 213
LogbackLoggingSystem.reinitialize(LoggingInitializationContext) line: 195
LogbackLoggingSystem(AbstractLoggingSystem).initializeWithConventions(LoggingInitializationContext, LogFile) line: 64
LogbackLoggingSystem(AbstractLoggingSystem).initialize(LoggingInitializationContext, String, LogFile) line: 49
LogbackLoggingSystem.initialize(LoggingInitializationContext, String, LogFile) line: 106
LoggingApplicationListener.initializeSystem(ConfigurableEnvironment, LoggingSystem) line: 261
LoggingApplicationListener.initialize(ConfigurableEnvironment, ClassLoader) line: 232
LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(ApplicationEnvironmentPreparedEvent) line: 199
LoggingApplicationListener.onApplicationEvent(ApplicationEvent) line: 176
SimpleApplicationEventMulticaster.invokeListener(ApplicationListener, ApplicationEvent) line: 163
SimpleApplicationEventMulticaster.multicastEvent(ApplicationEvent, ResolvableType) line: 136
SimpleApplicationEventMulticaster.multicastEvent(ApplicationEvent) line: 119
EventPublishingRunListener.publishEvent(SpringApplicationEvent) line: 111
EventPublishingRunListener.environmentPrepared(ConfigurableEnvironment) line: 65
SpringApplicationRunListeners.environmentPrepared(ConfigurableEnvironment) line: 54
SpringApplication.doRun(SpringApplicationRunListeners, String...) line: 315
SpringApplication.run(String...) line: 295
SpringApplication.run(Object[], String[]) line: 1112
SpringApplication.run(Object, String...) line: 1101
TestApplication.main(String[]) line: 80
`
**Thread Stack: when logging system is reconfigured spring: (Notice new stream being created)**
`com.test.TestApplication at localhost:60330
Thread [main] (Suspended (breakpoint at line 27 in ResilientFileOutputStream))
owns: LogbackLock (id=30)
ResilientFileOutputStream.<init>(File, boolean) line: 27
RollingFileAppender<E>(FileAppender<E>).openFile(String) line: 148
RollingFileAppender<E>(FileAppender<E>).start() line: 108
RollingFileAppender<E>.start() line: 86
AppenderAction<E>.end(InterpretationContext, String) line: 96
Interpreter.callEndAction(List<Action>, String) line: 317
Interpreter.endElement(String, String, String) line: 196
Interpreter.endElement(EndEvent) line: 182
EventPlayer.play(List<SaxEvent>) line: 62
SpringBootJoranConfigurator(GenericConfigurator).doConfigure(List<SaxEvent>) line: 149
SpringBootJoranConfigurator(GenericConfigurator).doConfigure(InputSource) line: 135
SpringBootJoranConfigurator(GenericConfigurator).doConfigure(InputStream) line: 99
SpringBootJoranConfigurator(GenericConfigurator).doConfigure(URL) line: 49
LogbackLoggingSystem.configureByResourceUrl(LoggingInitializationContext, LoggerContext, URL) line: 165
LogbackLoggingSystem.loadConfiguration(LoggingInitializationContext, String, LogFile) line: 137
LogbackLoggingSystem.reinitialize(LoggingInitializationContext) line: 197
LogbackLoggingSystem(AbstractLoggingSystem).initializeWithConventions(LoggingInitializationContext, LogFile) line: 64
LogbackLoggingSystem(AbstractLoggingSystem).initialize(LoggingInitializationContext, String, LogFile) line: 49
LogbackLoggingSystem.initialize(LoggingInitializationContext, String, LogFile) line: 106
LoggingApplicationListener.initializeSystem(ConfigurableEnvironment, LoggingSystem) line: 261
LoggingApplicationListener.initialize(ConfigurableEnvironment, ClassLoader) line: 232
LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(ApplicationEnvironmentPreparedEvent) line: 199
LoggingApplicationListener.onApplicationEvent(ApplicationEvent) line: 176
SimpleApplicationEventMulticaster.invokeListener(ApplicationListener, ApplicationEvent) line: 163
SimpleApplicationEventMulticaster.multicastEvent(ApplicationEvent, ResolvableType) line: 136
SimpleApplicationEventMulticaster.multicastEvent(ApplicationEvent) line: 119
EventPublishingRunListener.publishEvent(SpringApplicationEvent) line: 111
EventPublishingRunListener.environmentPrepared(ConfigurableEnvironment) line: 65
SpringApplicationRunListeners.environmentPrepared(ConfigurableEnvironment) line: 54
SpringApplication.doRun(SpringApplicationRunListeners, String...) line: 315
SpringApplication.run(String...) line: 295
SpringApplication.run(Object[], String[]) line: 1112
SpringApplication.run(Object, String...) line: 1101
TestApplication.main(String[]) line: 80
`
**And here come the Show Stopper (This Thread is fire flush on output stream which is already closed)**
` Thread [pool-1-thread-1] (Suspended (breakpoint at line 101 in ResilientOutputStreamBase))
ResilientFileOutputStream(ResilientOutputStreamBase).postIOFailure(IOException) line: 101
ResilientFileOutputStream(ResilientOutputStreamBase).flush() line: 82
PatternLayoutEncoder(LayoutWrappingEncoder<E>).doEncode(E) line: 137
RollingFileAppender<E>(OutputStreamAppender<E>).writeOut(E) line: 194
RollingFileAppender<E>(FileAppender<E>).writeOut(E) line: 220
RollingFileAppender<E>(OutputStreamAppender<E>).subAppend(E) line: 219
RollingFileAppender<E>.subAppend(E) line: 182
RollingFileAppender<E>(OutputStreamAppender<E>).append(E) line: 103
RollingFileAppender<E>(UnsynchronizedAppenderBase<E>).doAppend(E) line: 88
AppenderAttachableImpl<E>.appendLoopOnAppenders(E) line: 48
Logger.appendLoopOnAppenders(ILoggingEvent) line: 273
Logger.callAppenders(ILoggingEvent) line: 260
Logger.buildLoggingEventAndAppend(String, Marker, Level, String, Object[], Throwable) line: 442
Logger.filterAndLog_0_Or3Plus(String, Marker, Level, String, Object[], Throwable) line: 396
Logger.log(Marker, String, int, String, Object[], Throwable) line: 788
NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]
NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62
DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43
Method.invoke(Object, Object...) line: 498
Slf4jLocationAwareLogger.doLog(LocationAwareLogger, String, int, String, Throwable) line: 89
Slf4jLocationAwareLogger.doLogf(Logger$Level, String, String, Object[], Throwable) line: 82
Slf4jLocationAwareLogger(Logger).logf(String, Logger$Level, Throwable, String, Object) line: 2398
Log_$logger.version(String) line: 211
Version.<clinit>() line: 17
ConfigurationImpl.<clinit>() line: 69
HibernateValidator.createGenericConfiguration(BootstrapState) line: 31
Validation$GenericBootstrapImpl.configure() line: 276
BackgroundPreinitializer$ValidationInitializer.run() line: 107
BackgroundPreinitializer$FailSafeRunnable.run() line: 67
Executors$RunnableAdapter<T>.call() line: 511
FutureTask<V>.run() line: 266
ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) line: 1142
ThreadPoolExecutor$Worker.run() line: 617
Thread.run() line: 745
Comment From: checketts
I also need to report back that my assumption of my multithreading fix had been incomplete. My code had been making it much worse, but even with its removal I still occasionally get:
java.lang.IllegalStateException: Logback configuration error detected: ERROR in c.q.l.c.recovery.ResilientFileOutputStream@885755284 - IO failure while writing to file
Breaking logging reconfiguration
Comment From: NiteshMehta
I have to provide a workaroud. Is there a way to disable reinitializing of logging feamework or can Hibernate validator be configured to initialize in main thread?
Comment From: davidmelia
I wonder if this is linked to my issue #6831 which is now raised with the Spring Cloud team?
Comment From: NiteshMehta
Symptoms for my issue looks similar to #4871. We will try to update our product to later version of spring boot and test. Mean while, we are planning to either override org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LoggingInitializationContext, String, LogFile) and add some delay to allow BackgroundPreinitializer to complete.
or override org.springframework.boot.logging.logback.LogbackLoggingSystem.reinitialize(LoggingInitializationContext)
Comment From: bin01
@NiteshMehta Did your work around help? We are facing a similar issue, so not sure if just upgrading logback to 1.17 would work.
Comment From: NiteshMehta
@bin01 Upgrade logback to 1.1.7 did not help and we have yet not upgraded spring boot. Workaround which we did is working for us. It is bit different from one mentioned above. As we are driving our logging using logback.xml and not by logging configuration in application.properties, therefore we skipped revitalization of LogbackLoggingSystem. Here is what we did, we crated below class and added it to classpath
import org.springframework.boot.logging.LoggingInitializationContext;
import org.springframework.boot.logging.logback.LogbackLoggingSystem;
public class AppLoggingSystem extends LogbackLoggingSystem {
public AppLoggingSystem(ClassLoader classLoader) {
super(classLoader);
}
@Override
protected void reinitialize(LoggingInitializationContext initializationContext) {
//Workaround for spring and logback integration issue https://github.com/spring-projects/spring-boot/issues/5669";
//Skipping re-initialization of Logback, because we are using logback xml configuration which is already initialized
}
}
then passed -Dorg.springframework.boot.logging.LoggingSystem=com.ca.tdm.utils.AppLoggingSystem
as jvm argument.
and we are done.
you may also try switching to different logging system.
like -Dorg.springframework.boot.logging.LoggingSystem=org.springframework.boot.logging.log4j.Log4JLoggingSystem
Comment From: bin01
@NiteshMehta Thanks a lot!
Comment From: glyn
I hit this issue consistently when I specified $TRACE=true in a Spring Cloud Services integration test (note to self in case I am asked to reproduce the problem: ConfigServerSecurityIntegrationTests.java), based on Spring Boot 1.5.2.RELEASE and logback 1.1.11. The issue does not occur with $DEBUG=true. Any update on a definitive solution?
Comment From: sandipchitale
We are seeing the same issue intermittently on certain VMs (linux only -we do not see this on windows). The bad part is that the startup fails and the app does not come up. A speedy solution will be really helpful. I will try to first reproduce the problem consistently on my setup so that I can get to the root cause. As such we are not doing anything special with logging framework except to use logback-spring.xml based configuration.
Specifically here is the stack trace we got:
2017-04-21 08:47:38.989 ERROR o.s.boot.SpringApplication - Application startup failed
java.lang.IllegalStateException: Logback configuration error detected:
ERROR in c.q.l.c.recovery.ResilientFileOutputStream@1758008124 - IO failure while writing to file [gatewaylogs/gateway.log] java.io.IOException: Stream Closed
at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:161)
at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:81)
at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:59)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:114)
at org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:303)
at org.springframework.boot.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:276)
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:239)
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:212)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:167)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:122)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:73)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:336)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:307)
Comment From: philwebb
@glyn is the ConfigServerSecurityIntegrationTests public, or can we get access to it?
Comment From: glyn
@philwebb It's private but I've added you as a collaborator and you should have received an invitation. I run that single test under IntelliJ to reproduce the problem. Let me know if you can't get access or you have trouble reproducing the problem.
Comment From: sandipchitale
@glyn Are you running into this issue on Linux only? If so, are you running the haveged daemon (http://www.issihosts.com/haveged/) on your Linux VM?
@philwebb Without haveged running on Linux VMs with low file system entropy, the startup is slow. Could this cause the race condition? Just a thought.
Comment From: glyn
@sandipchitale I've only tried it on macOS, not Linux.
Comment From: sandipchitale
Did more testing on this. What I am finding is that if I pass the
-Dlogging.level.=TRACE
via system property I run into the issue 1 in 5 times. However if I set the logging.level. in application.yml I am not able to reproduce the issue. So could this be a Environment initialization race condition issue? And looking at the stack trace it kind of hints that it has to do with Environment initialization.
Comment From: sandipchitale
When you run logging at DEBUG or TRACE level a lot more log output is produced. Thus, it also may be related the log rollover size for log appenders and if the log files are getting rolled over and archived.
Comment From: wilkinsona
@glyn Could you please add me as a collaborator as well?
Comment From: glyn
@wilkinsona Added. Please check your email.
Comment From: wilkinsona
Thanks, @glyn.
I can reliably reproduce the failure by running ConfigServerSecurityIntegrationTests.vaultRenewalWithUserTokenIsOk with trace level logging enabling:
java.lang.IllegalStateException: Failed to load ApplicationContext
at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:124)
at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:83)
at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:117)
at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:83)
at org.springframework.boot.test.autoconfigure.SpringBootDependencyInjectionTestExecutionListener.prepareTestInstance(SpringBootDependencyInjectionTestExecutionListener.java:44)
at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:230)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:228)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:287)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:289)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:247)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:94)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:119)
at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:42)
at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:234)
at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:74)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:144)
Caused by: java.lang.IllegalStateException: Logback configuration error detected:
ERROR in c.q.l.c.recovery.ResilientFileOutputStream@749098095 - IO failure while writing to file [/var/folders/zq/v6xkr2696kv05jbf3bddt9680000gn/T/spring.log] java.io.IOException: Stream Closed
at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:162)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.reinitialize(LogbackLoggingSystem.java:208)
at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:74)
at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:59)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:115)
at org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:303)
at org.springframework.boot.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:276)
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:239)
at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:212)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:167)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:122)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:74)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:325)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:296)
at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:120)
at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:98)
at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:116)
... 30 more
Comment From: glyn
@wilkinsona Thanks. They do say a problem shared is a problem halved...
Comment From: wilkinsona
I've found one problem that is certainly related to this: https://github.com/spring-projects/spring-boot/issues/9869
Comment From: wilkinsona
Fixing #9869 doesn't fix the problem, however I think I know what will.
The root cause appears to be that we return from SpringApplication.run while the background preinitialisation may still be in progress. This then opens a window for a race between the background preinitialisation thread using the logging system and something else trying to configure it. This is much more likely to happen in a Spring Cloud app thanks to the bootstrap context and the extra logging system initialisation that it performs to pick up changes that may have come from a config server.
Some initial testing suggests that updating the background preinitializer to handle ApplicationReadyEvent and ApplicationFailedEvent and block until background preinitialisation has completed will resolve the problem. Thankfully, with info level tracing enabled, it appears that this will have negligible impact on startup time. It's only when lots of logging is done on the background thread that we actually have to wait.
Comment From: StepeCZ
Im getting this error in 2020 and Spring Boot 2.2.4 and Logback 1.2.3
Configuration worked when loaded from application.yml but then I had to move it to logback-spring.xml and the same pattern string does not work, same error thrown.
Comment From: wilkinsona
@StepeCZ If you can create a minimal sample that reproduces the problem, please create a new issue attaching the sample and we can take a look.