Spring-boot: Make it easier to tell that DevTools restart has been disabled due to HotSwapAgent being present

Created on 17 Sep 2018 · 10Comments · Source: spring-projects/spring-boot

Testing using a simple spring-boot starter generated by initializr: Download starter

With identical JDKs and maven versions, devtools works fine on Ubuntu 16.04 but does not work on macOS 10.13.6. The symptoms are:

The main thread is called main instead of restartedMain.
The application does not restart automatically (even though it should) upon changes to files in the classpath.

I have tested this going back to older versions and determined that the first version in which this broke is 1.5.3.

To reproduce:

Download starter
Unzip the starter and cd into the unzipped directory.
Run mvn spring-boot:run

Testcases below:
macOS

$ mvn -v
Apache Maven 3.5.4 (1edded0938998edf8bf061f1ceb3cfdeccf443fe; 2018-06-17T14:33:14-04:00)
Maven home: /usr/local/Cellar/maven/3.5.4/libexec
Java version: 1.8.0_181, vendor: Oracle Corporation, runtime: /Library/Java/JavaVirtualMachines/jdk1.8.0_181.jdk/Contents/Home/jre
Default locale: en_CA, platform encoding: UTF-8
OS name: "mac os x", version: "10.13.6", arch: "x86_64", family: "mac"

[INFO] --- spring-boot-maven-plugin:1.5.16.RELEASE:run (default-cli) @ demo ---
[INFO] Attaching agents: []
09:24:58.767 [main] DEBUG org.springframework.boot.devtools.settings.DevToolsSettings - Included patterns for restart : []
09:24:58.770 [main] DEBUG org.springframework.boot.devtools.settings.DevToolsSettings - Excluded patterns for restart : [/spring-boot-starter/target/classes/, /spring-boot-autoconfigure/target/classes/, /spring-boot-starter-[\w-]+/, /spring-boot/target/classes/, /spring-boot-actuator/target/classes/, /spring-boot-devtools/target/classes/]
09:24:58.771 [main] DEBUG org.springframework.boot.devtools.restart.ChangeableUrls - Matching URLs for reloading : [file:/Users/danielgross/volatile/Downloads/demo-1516/demo/target/classes/]

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

2018-09-17 09:24:59.169  INFO 7807 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication on daniel with PID 7807 (/Users/danielgross/volatile/Downloads/demo-1516/demo/target/classes started by danielgross in /Users/danielgross/volatile/Downloads/demo-1516/demo)
2018-09-17 09:24:59.170  INFO 7807 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2018-09-17 09:24:59.217  INFO 7807 --- [           main] s.c.a.AnnotationConfigApplicationContext : Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@49c43f4e: startup date [Mon Sep 17 09:24:59 EDT 2018]; root of context hierarchy
2018-09-17 09:24:59.694  INFO 7807 --- [           main] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2018-09-17 09:24:59.717  INFO 7807 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-09-17 09:24:59.730  INFO 7807 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 0.989 seconds (JVM running for 1.268)
2018-09-17 09:24:59.731  INFO 7807 --- [       Thread-6] s.c.a.AnnotationConfigApplicationContext : Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@49c43f4e: startup date [Mon Sep 17 09:24:59 EDT 2018]; root of context hierarchy
2018-09-17 09:24:59.733  INFO 7807 --- [       Thread-6] o.s.j.e.a.AnnotationMBeanExporter        : Unregistering JMX-exposed beans on shutdown

Ubuntu

$ mvn -v
Apache Maven 3.5.4 (1edded0938998edf8bf061f1ceb3cfdeccf443fe; 2018-06-17T18:33:14Z)
Maven home: /opt/apache-maven
Java version: 1.8.0_181, vendor: Oracle Corporation, runtime: /usr/lib/jvm/java-8-oracle/jre
Default locale: en_US, platform encoding: ANSI_X3.4-1968
OS name: "linux", version: "4.4.0-1065-aws", arch: "amd64", family: "unix"

[INFO] --- spring-boot-maven-plugin:1.5.16.RELEASE:run (default-cli) @ demo ---
[INFO] Attaching agents: []
13:28:13.786 [main] DEBUG org.springframework.boot.devtools.settings.DevToolsSettings - Included patterns for restart : []
13:28:13.795 [main] DEBUG org.springframework.boot.devtools.settings.DevToolsSettings - Excluded patterns for restart : [/spring-boot-starter/target/classes/, /spring-boot-autoconfigure/target/classes/, /spring-boot-starter-[\w-]+/, /spring-boot/target/classes/, /spring-boot-actuator/target/classes/, /spring-boot-devtools/target/classes/]
13:28:13.795 [main] DEBUG org.springframework.boot.devtools.restart.ChangeableUrls - Matching URLs for reloading : [file:/home/ubuntu/demo/target/classes/]

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

2018-09-17 13:28:14.384  INFO 11885 --- [  restartedMain] com.example.demo.DemoApplication         : Starting DemoApplication on demo with PID 11885 (/home/ubuntu/demo/target/classes started by ubuntu in /home/ubuntu/demo)
2018-09-17 13:28:14.388  INFO 11885 --- [  restartedMain] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2018-09-17 13:28:14.541  INFO 11885 --- [  restartedMain] s.c.a.AnnotationConfigApplicationContext : Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@3832139c: startup date [Mon Sep 17 13:28:14 UTC 2018]; root of context hierarchy
2018-09-17 13:28:15.815  INFO 11885 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2018-09-17 13:28:15.871  INFO 11885 --- [  restartedMain] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-09-17 13:28:15.909  INFO 11885 --- [  restartedMain] com.example.demo.DemoApplication         : Started DemoApplication in 2.081 seconds (JVM running for 2.643)
2018-09-17 13:28:15.918  INFO 11885 --- [       Thread-8] s.c.a.AnnotationConfigApplicationContext : Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@3832139c: startup date [Mon Sep 17 13:28:14 UTC 2018]; root of context hierarchy
2018-09-17 13:28:15.923  INFO 11885 --- [       Thread-8] o.s.j.e.a.AnnotationMBeanExporter        : Unregistering JMX-exposed beans on shutdown

superseded enhancement

Source

danielpgross

Most helpful comment

@eiselems My feeling that INFO is the correct level. Warning seems a little too much.

philwebb on 28 Sep 2018

👍2

All 10 comments

I'm also running macOS 10.13.6 and it works fine.

I've just tried with my local maven version as well as the wrapper:

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

2018-09-17 15:55:01.329  INFO 3677 --- [  restartedMain] com.example.demo.DemoApplication         : Starting DemoApplication on Brians-MacBook-Pro.local with PID 3677 (/Users/bclozel/workspace/demo/target/classes started by bclozel in /Users/bclozel/workspace/demo)
2018-09-17 15:55:01.330  INFO 3677 --- [  restartedMain] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2018-09-17 15:55:01.382  INFO 3677 --- [  restartedMain] s.c.a.AnnotationConfigApplicationContext : Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@1f905801: startup date [Mon Sep 17 15:55:01 CEST 2018]; root of context hierarchy
2018-09-17 15:55:01.938  INFO 3677 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2018-09-17 15:55:01.958  INFO 3677 --- [  restartedMain] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-09-17 15:55:01.969  INFO 3677 --- [  restartedMain] com.example.demo.DemoApplication         : Started DemoApplication in 1.009 seconds (JVM running for 1.323)
2018-09-17 15:55:01.976  INFO 3677 --- [       Thread-8] s.c.a.AnnotationConfigApplicationContext : Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@1f905801: startup date [Mon Sep 17 15:55:01 CEST 2018]; root of context hierarchy
2018-09-17 15:55:01.979  INFO 3677 --- [       Thread-8] o.s.j.e.a.AnnotationMBeanExporter        : Unregistering JMX-exposed beans on shutdown

➜  demo java -version
openjdk version "1.8.0_181"
OpenJDK Runtime Environment (Zulu 8.31.0.1-macosx) (build 1.8.0_181-b02)
OpenJDK 64-Bit Server VM (Zulu 8.31.0.1-macosx) (build 25.181-b02, mixed mode)

Could you try a couple of things:

./mvnw dependency:purge-local-repository
then ./mvnw spring-boot:run

bclozel on 17 Sep 2018

Thanks for the quick response!
Just tried that, but the result is the same as before:

$ ./mvnw dependency:purge-local-repository
/Users/danielgross/Downloads/demo-1516/demo
Downloading https://repo1.maven.org/maven2/org/apache/maven/apache-maven/3.5.4/apache-maven-3.5.4-bin.zip

... (snip) ...

[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 15.758 s
[INFO] Finished at: 2018-09-17T10:46:54-04:00
[INFO] ------------------------------------------------------------------------

$ ./mvnw spring-boot:run
/Users/danielgross/Downloads/demo-1516/demo
[INFO] Scanning for projects...
[INFO] 
[INFO] --------------------------< com.example:demo >--------------------------
[INFO] Building demo 0.0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO] 
[INFO] >>> spring-boot-maven-plugin:1.5.16.RELEASE:run (default-cli) > test-compile @ demo >>>
[INFO] 
[INFO] --- maven-resources-plugin:2.7:resources (default-resources) @ demo ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 1 resource
[INFO] Copying 0 resource
[INFO] 
[INFO] --- maven-compiler-plugin:3.1:compile (default-compile) @ demo ---
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 1 source file to /Users/danielgross/volatile/Downloads/demo-1516/demo/target/classes
[INFO] 
[INFO] --- maven-resources-plugin:2.7:testResources (default-testResources) @ demo ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /Users/danielgross/volatile/Downloads/demo-1516/demo/src/test/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.1:testCompile (default-testCompile) @ demo ---
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 1 source file to /Users/danielgross/volatile/Downloads/demo-1516/demo/target/test-classes
[INFO] 
[INFO] <<< spring-boot-maven-plugin:1.5.16.RELEASE:run (default-cli) < test-compile @ demo <<<
[INFO] 
[INFO] 
[INFO] --- spring-boot-maven-plugin:1.5.16.RELEASE:run (default-cli) @ demo ---
[INFO] Attaching agents: []
10:47:00.374 [main] DEBUG org.springframework.boot.devtools.settings.DevToolsSettings - Included patterns for restart : []
10:47:00.377 [main] DEBUG org.springframework.boot.devtools.settings.DevToolsSettings - Excluded patterns for restart : [/spring-boot-starter/target/classes/, /spring-boot-autoconfigure/target/classes/, /spring-boot-starter-[\w-]+/, /spring-boot/target/classes/, /spring-boot-actuator/target/classes/, /spring-boot-devtools/target/classes/]
10:47:00.377 [main] DEBUG org.springframework.boot.devtools.restart.ChangeableUrls - Matching URLs for reloading : [file:/Users/danielgross/volatile/Downloads/demo-1516/demo/target/classes/]

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

2018-09-17 10:47:00.750  INFO 8474 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication on daniel with PID 8474 (/Users/danielgross/volatile/Downloads/demo-1516/demo/target/classes started by danielgross in /Users/danielgross/volatile/Downloads/demo-1516/demo)
2018-09-17 10:47:00.751  INFO 8474 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2018-09-17 10:47:00.802  INFO 8474 --- [           main] s.c.a.AnnotationConfigApplicationContext : Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@49c43f4e: startup date [Mon Sep 17 10:47:00 EDT 2018]; root of context hierarchy
2018-09-17 10:47:01.329  INFO 8474 --- [           main] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2018-09-17 10:47:01.353  INFO 8474 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-09-17 10:47:01.365  INFO 8474 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 1.018 seconds (JVM running for 1.315)
2018-09-17 10:47:01.366  INFO 8474 --- [       Thread-6] s.c.a.AnnotationConfigApplicationContext : Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@49c43f4e: startup date [Mon Sep 17 10:47:00 EDT 2018]; root of context hierarchy
2018-09-17 10:47:01.367  INFO 8474 --- [       Thread-6] o.s.j.e.a.AnnotationMBeanExporter        : Unregistering JMX-exposed beans on shutdown
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 3.820 s
[INFO] Finished at: 2018-09-17T10:47:01-04:00
[INFO] ------------------------------------------------------------------------

danielpgross on 17 Sep 2018

It sounds like the Restarter has been disabled which can be done with a system property. If you can debug your application when it's launched, it would be interesting to know what's happening in this code: https://github.com/spring-projects/spring-boot/blob/c39bc3999d02cb67e3164ccb47a761ad67285c83/spring-boot-devtools/src/main/java/org/springframework/boot/devtools/restart/RestartApplicationListener.java#L59-L72

wilkinsona on 17 Sep 2018

I was able to run the debugger and from what I can see, the Restarter actually is being initialized (it is not disabled). See below:
spri 2018-09-17 12-45-26

danielpgross on 17 Sep 2018

This is a wild guess, but do you happen to have JRebel configured on that JVM?

In gh-3095, we've updated the restarter to not restart the application if you have a reloading agent like JRebel - but the livereload server is still available.

If that's the case, this is way older than v1.5.3 and is not OS-dependent; it's just your local setup.

bclozel on 17 Sep 2018

That was a good guess -- I don't have JRebel, but I do have HotSwapAgent installed (from a long time ago, that I forgot about...) at /Library/Java/Extensions/hotswap-agent.jar. I see that HotSwapAgent support was added in 1.5.3, so that totally explains why it's the first version that stopped working with automatic restart.

Removing the HotSwapAgent jar fixed the issue. Many thanks for your help!

danielpgross on 17 Sep 2018

Re-opening to consider logging something when the restarter has been disabled.

wilkinsona on 18 Sep 2018

👍1

@wilkinsona any suggestions on the log level of that message?
See two possibilities here:
INFO: Restarter is disabled.
WARN: Restarter disabled despite DevTools being on the Classpath.

What do you think about it?