springboot Executable war file goes into infinite loop and then stacktraces

If you create an executable jar or war, you used to be able to do this via the Spring Boot Gradle or Maven plugins, and it would work with no problem. We have recently upgraded to Spring Boot 2.2.2 (from 1.4) and have found that unless you add the spring-boot-loader to the classpath, you get the following behaviour:

Process goes into a loop, consuming 100% cpu, and eventually gets a stack overflow. Looking at the output from this, you see that it is looping as below:

| *** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message transform method call failed at JPLISAgent.c line: 844
Exception in thread "main" java.lang.reflect.InvocationTargetException
    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 org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:51)
    at org.springframework.boot.loader.WarLauncher.main(WarLauncher.java:58)
 Caused by: java.lang.reflect.InvocationTargetException
    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 org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:51)
    at org.springframework.boot.loader.WarLauncher.main(WarLauncher.java:58)
    ... 8 more
 Caused by: java.lang.reflect.InvocationTargetException
    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 org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:51)
    at org.springframework.boot.loader.WarLauncher.main(WarLauncher.java:58)
    ... 16 more

Comment From: wilkinsona

It looks like the launcher is calling itself rather than the application's own main method. That would suggest that the Start-Class in the manifest is wrong. Can you please share a small sample that reproduces the problem?

Comment From: ghost

Thanks for getting back to me so quickly, I'll try and create an example that replicates it.

Comment From: ghost

I've created a github project here that replicates the issue (https://github.com/paulnuk/springbootissue19577)

In order to replicate, do a clean and package, then cd to the target directory and do:

java -jar demo-0.0.1-SNAPSHOT-exec.jar

Comment From: ghost

Update to this - it seems that it is indeed trying to call itself, and can be fixed by specifying the main class of the Spring Boot Application instead on the plugin. The plugin probably needs some defensive code in it to make sure it doesn't call itself.

           <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
                <executions>
                    <execution>
                        <goals>
                            <goal>repackage</goal>
                        </goals>
                        <configuration>

                            <classifier>exec</classifier>
                            <mainClass>com.example.demo.DemoApplication</mainClass>
                        </configuration>
                    </execution>
                </executions>
            </plugin>

Comment From: wilkinsona

Thanks for the sample. Unfortunately, it doesn't reproduce the problem for me:

$ java -jar target/demo-0.0.1-SNAPSHOT.jar 

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.2.2.RELEASE)

2020-01-08 15:32:02.026  INFO 93728 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication v0.0.1-SNAPSHOT on Andys-MacBook-Pro.local with PID 93728 (/Users/awilkinson/dev/temp/springbootissue19577/target/demo-0.0.1-SNAPSHOT.jar started by awilkinson in /Users/awilkinson/dev/temp/springbootissue19577)
2020-01-08 15:32:02.029  INFO 93728 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2020-01-08 15:32:02.823  INFO 93728 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2020-01-08 15:32:02.831  INFO 93728 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-01-08 15:32:02.831  INFO 93728 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.29]
2020-01-08 15:32:02.875  INFO 93728 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-01-08 15:32:02.875  INFO 93728 --- [           main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 802 ms
2020-01-08 15:32:03.000  INFO 93728 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-01-08 15:32:03.150  INFO 93728 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2020-01-08 15:32:03.153  INFO 93728 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 1.488 seconds (JVM running for 1.871)

Can you please update it with the changes that are required to reproduce the problem?

Comment From: ghost

You need to run the repackaged jar, not the original (sorry, I edited my original instructions after the first post)

i.e.

java -jar target/demo-0.0.1-SNAPSHOT-exec.jar

not

java -jar target/demo-0.0.1-SNAPSHOT.jar

Comment From: wilkinsona

Thanks. The root cause is that the jar is being repackaged twice. Once to creating demo-0.0.1-SNAPSHOT.jar and then again creating demo-0.0.1-SNAPSHOT-exec.jar. This results in a Start-Class in the exec jar that points to the launcher and the stack overflow results. This is being tracked by https://github.com/spring-projects/spring-boot/issues/16828.

You probably don't want to repackage the jar twice. You can avoid that by specifying the <id> when configuring the execution of the repackage goal:

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
                <executions>
                    <execution>
                        <id>repackage</id>
                        <goals>
                            <goal>repackage</goal>
                        </goals>
                        <configuration>
                            <classifier>exec</classifier>
                        </configuration>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>

This will customize the execution inherited from spring-boot-starter-parent rather than creating another one.

Comment From: snicoll

For completeness, this is also documented in the 2.1 release notes.