Unexpected behavior with DevTools when 'main' throws an exception

[Artur-]

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.

[Artur-]

Example: https://github.com/Artur-/springboot-main-exception

[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.