If your main method throws an exception, e.g.
@SpringBootApplication
public class DemoApplication {
public static void main(String[] args) {
SpringApplication.run(DemoApplication.class, args);
throw new IllegalStateException("boo ya");
}
}
and you have Spring devtools enabled, the behavior is as follows:
mvn spring-boot:run
2021-06-14 16:46:22.907 INFO 72419 --- [ restartedMain] com.example.demo.DemoApplication : Started DemoApplication in 1.626 seconds (JVM running for 1.937)
Exception in thread "restartedMain" java.lang.reflect.InvocationTargetException
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:567)
at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)
Caused by: java.lang.IllegalStateException: boo ya
at com.example.demo.DemoApplication.main(DemoApplication.java:11)
... 5 more
2021-06-14 16:46:23.650 INFO 72419 --- [nio-1234-exec-2] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2021-06-14 16:46:23.650 INFO 72419 --- [nio-1234-exec-2] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2021-06-14 16:46:23.651 INFO 72419 --- [nio-1234-exec-2] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
It all looks normal.
touch target/classes/application.properties
2021-06-14 16:46:47.657 INFO 72419 --- [ restartedMain] com.example.demo.DemoApplication : Started DemoApplication in 0.209 seconds (JVM running for 26.687)
2021-06-14 16:46:47.659 INFO 72419 --- [ restartedMain] .ConditionEvaluationDeltaLoggingListener : Condition evaluation unchanged
Exception in thread "restartedMain" java.lang.reflect.InvocationTargetException
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:567)
at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)
Caused by: java.lang.IllegalStateException: boo ya
at com.example.demo.DemoApplication.main(DemoApplication.java:11)
... 5 more
Still looks normal.
touch target/classes/application.properties
2021-06-14 16:47:17.350 INFO 72419 --- [ restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 1234 (http)
2021-06-14 16:47:17.350 INFO 72419 --- [ restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 1234 (http)
2021-06-14 16:47:17.351 INFO 72419 --- [ restartedMain] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2021-06-14 16:47:17.351 INFO 72419 --- [ restartedMain] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2021-06-14 16:47:17.351 INFO 72419 --- [ restartedMain] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.46]
2021-06-14 16:47:17.351 INFO 72419 --- [ restartedMain] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.46]
2021-06-14 16:47:17.359 INFO 72419 --- [ restartedMain] o.a.c.c.C.[Tomcat-1].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2021-06-14 16:47:17.359 INFO 72419 --- [ restartedMain] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 108 ms
2021-06-14 16:47:17.360 INFO 72419 --- [ restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2021-06-14 16:47:17.360 INFO 72419 --- [ restartedMain] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 106 ms
2021-06-14 16:47:17.406 WARN 72419 --- [ restartedMain] o.s.b.d.a.OptionalLiveReloadServer : Unable to start LiveReload server
2021-06-14 16:47:17.406 WARN 72419 --- [ restartedMain] o.s.b.d.a.OptionalLiveReloadServer : Unable to start LiveReload server
2021-06-14 16:47:17.410 WARN 72419 --- [ restartedMain] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.context.ApplicationContextException: Failed to start bean 'webServerStartStop'; nested exception is org.springframework.boot.web.server.PortInUseException: Port 1234 is already in use
2021-06-14 16:47:17.410 INFO 72419 --- [ restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 1234 (http) with context path ''
2021-06-14 16:47:17.411 INFO 72419 --- [ restartedMain] o.apache.catalina.core.StandardService : Stopping service [Tomcat]
2021-06-14 16:47:17.413 INFO 72419 --- [ restartedMain] com.example.demo.DemoApplication : Started DemoApplication in 0.174 seconds (JVM running for 56.442)
2021-06-14 16:47:17.414 INFO 72419 --- [ restartedMain] .ConditionEvaluationDeltaLoggingListener : Condition evaluation unchanged
Exception in thread "restartedMain" java.lang.reflect.InvocationTargetException
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:567)
at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)
Caused by: java.lang.IllegalStateException: boo ya
at com.example.demo.DemoApplication.main(DemoApplication.java:11)
... 5 more
2021-06-14 16:47:17.415 INFO 72419 --- [ restartedMain] ConditionEvaluationReportLoggingListener :
Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2021-06-14 16:47:17.427 ERROR 72419 --- [ restartedMain] o.s.b.d.LoggingFailureAnalysisReporter :
***************************
APPLICATION FAILED TO START
***************************
Description:
Web server failed to start. Port 1234 was already in use.
Action:
Identify and stop the process that's listening on port 1234 or configure this application to listen on another port.
No longer looks normal as two application instances are started.
After this, 3 instances are started. Then 4 and so on.
Or then at some point, it all just fails with
Logging system failed to initialize using configuration from 'null'
java.util.NoSuchElementException
at java.base/java.util.ArrayList$Itr.next(ArrayList.java:970)
at ch.qos.logback.classic.LoggerContext.fireOnStop(LoggerContext.java:335)
at ch.qos.logback.classic.LoggerContext.stop(LoggerContext.java:349)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.stopAndReset(LogbackLoggingSystem.java:196)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadDefaults(LogbackLoggingSystem.java:144)
at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:83)
at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:60)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:132)
at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:313)
at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:282)
at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:240)
at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:216)
at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:82)
at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:63)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:117)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:111)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:62)
at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:374)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:332)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332)
at com.example.demo.DemoApplication.main(DemoApplication.java:10)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:567)
at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)
Logging system failed to initialize using configuration from 'null'
Not sure what you can or will want to do about this but it caused quite some confusion for me.
Comment From: Artur-
Example: https://github.com/Artur-/springboot-main-exception
Comment From: wilkinsona
We need to distinguish between a failure that occurs when refreshing the application context and a failure that occurs outside of that. Only the former should result in a retry once the user's made a change.
One approach would be to check the stack trace of the failure and see if it was thrown from within SpringApplication.run. I've prototyped this here and it seems to address the problem. I tested using spring-boot-smoke-test-devtools, adding the throw of an exception to the end of the main method. With the prototyped change in place, restarts triggered by changes to the code no longer result in port clashes and duplicated log output.
I'd like to chat to @philwebb before merging anything.
Comment From: xyraclius
Hi @wilkinsona,
I’d like to contribute to this issue. May I?
I’ve fixed it locally based on your previous concerns:
• If main() throws an exception (e.g., IllegalStateException at the end of main()), DevTools restarts could duplicate the application multiple times, because InvocationTargetException (from reflection) wraps the actual exception.
• Simply ignoring InvocationTargetException is not acceptable, because DevTools needs to retry if the failure happens inside the Spring context refresh (i.e., the application context fails to start due to a misconfiguration).
• The previous PR that proposed was declined because it silenced all failures, including ones that DevTools should retry after a change, which breaks the intended recovery mechanism.
If this aligns with your guidance, I can create a PR for review.