StartupStep are closed twice in SpringApplicationRunListeners

[mdeinum]

With the introduction of #22600 I was eager to test this with Flight Recorder based events. For this purpose, I cloned the Petclinic, updated it to Spring Boot 2.4.0-SNAPSHOT and confined it to run using the FlightRecorderApplicationStartup. However, when doing so it results in an exception during startup.

xception 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:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)
Caused by: java.util.NoSuchElementException
	at java.base/java.util.ArrayDeque.getFirst(ArrayDeque.java:403)
	at org.springframework.core.metrics.jfr.FlightRecorderApplicationStartup.start(FlightRecorderApplicationStartup.java:52)
	at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:111)
	at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:106)
	at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:57)
	at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:356)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:318)
	at org.springframework.samples.petclinic.PetClinicApplication.main(PetClinicApplication.java:39)
	... 5 more

The events that are logged are

1. spring.boot.application.starting, sequenceId = 0
2. spring.boot.application.starting (?), sequenceId = 0
3. spring.boot.application.environment-prepared, sequenceId = 1
4. spring.boot.application.failed , sequenceId = 2 -> which leads to the error due to the currentSteps Deque is empty.

EDIT (1): The second spring.boot.application.starting event appears to be the result of including spring-boot-devtools as a dependency. Which I thought might be the culprit, however even without Devtools the applications breaks.

To reproduce checkout petclinic, upgrade Spring Boot and use the following PetClinicApplication class

@SpringBootApplication(proxyBeanMethods = false)
public class PetClinicApplication {

	public static void main(String[] args) {
		SpringApplication springApplication = new SpringApplicationBuilder()
			.applicationStartup(new FlightRecorderApplicationStartup())
			.sources(PetClinicApplication.class)
			.build();
		springApplication.run(args);
	}
}

The application starts successfully when commenting the .applicationStartup(new FlightRecorderApplicationStartup()) line.

Parameters used to start the application with JFR metrics -XX:StartFlightRecording:filename=recording.jfr,duration=10s

After some debugging it appears that the error is this the doWithListeners method in the SpringApplicationRunListeners class.

EDIT (2)

private void doWithListeners(String stepName, Consumer<SpringApplicationRunListener> listenerAction) {
	doWithListeners(stepName, listenerAction, StartupStep::end);
}

private void doWithListeners(String stepName, Consumer<SpringApplicationRunListener> listenerAction,
		Consumer<StartupStep> stepAction) {
	StartupStep step = this.applicationStartup.start(stepName);
	this.listeners.forEach(listenerAction);
	stepAction.accept(step);
	step.end();
}

The lambda passed into stepAction results in the StartupStep.end method being invoked twice, leading to exhausting the Deque.

Relates to: #22600

[bclozel]

Thanks @mdeinum !
This is now fixed, let us know how this goes for you - we'll continue improving/building on this feature for the next milestone.

[mdeinum]

Although this works, doesn't this break the call from failed which uses a lambda to enrich the tags being written? Wouldn't the better solution be to, by default, pass a no-op lambda, then call end, else it might lead to situation where the end method might not be called.