Dev Tools restart failures caused by a too short quiet period are hard to diagnose #31579

iranicus · 2022-07-06T11:46:29Z

Spring Boot Dev Tools 2.6.6
Spring Boot 2.6.6
Maven
Java 11

Could be related to #1106

I have an issue when trying to make changes against the application running inside a docker container, when I trigger a build in the IDE the running service throws the following:

org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'verificationService':
Resolution of declared constructors on bean Class [com.service.v2.VerificationService] from ClassLoader [org.springframework.boot.devtools.restart.classloader.RestartClassLoader@776edae1] failed; nested exception is java.lang.NoClassDefFoundError: com/service/v2/ChatService

at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.determineCandidateConstructors(AutowiredAnnotationBeanPostProcessor.java:309) ~[spring-beans-5.3.18.jar!/:5.3.18]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.determineConstructorsFromBeanPostProcessors(AbstractAutowireCapableBeanFactory.java:1302) ~[spring-beans-5.3.18.jar!/:5.3.18]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1219) ~[spring-beans-5.3.18.jar!/:5.3.18]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:582) ~[spring-beans-5.3.18.jar!/:5.3.18]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542) ~[spring-beans-5.3.18.jar!/:5.3.18]
at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335) ~[spring-beans-5.3.18.jar!/:5.3.18]
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234) ~[spring-beans-5.3.18.jar!/:5.3.18]
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333) ~[spring-beans-5.3.18.jar!/:5.3.18]
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208) ~[spring-beans-5.3.18.jar!/:5.3.18]
at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:953) ~[spring-beans-5.3.18.jar!/:5.3.18]
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918) ~[spring-context-5.3.18.jar!/:5.3.18]
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:583) ~[spring-context-5.3.18.jar!/:5.3.18]
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:740) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:415) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:303) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1312) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1301) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at com.ChatApplication.main(ChatApplication.java:24) ~[classes!/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
        at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49) ~[spring-boot-devtools-2.6.6.jar!/:2.6.6]
Caused by: java.lang.NoClassDefFoundError: com/service/v2/ChatService
	at java.base/java.lang.Class.getDeclaredConstructors0(Native Method) ~[na:na]
	at java.base/java.lang.Class.privateGetDeclaredConstructors(Class.java:3137) ~[na:na]
	at java.base/java.lang.Class.getDeclaredConstructors(Class.java:2357) ~[na:na]
	at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.determineCandidateConstructors(AutowiredAnnotationBeanPostProcessor.java:304) ~[spring-beans-5.3.18.jar!/:5.3.18]
Caused by: java.lang.ClassNotFoundException: com.service.v2.ChatService
	at org.springframework.boot.devtools.restart.classloader.RestartClassLoader.loadClass(RestartClassLoader.java:136) ~[spring-boot-devtools-2.6.6.jar!/:2.6.6]
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522) ~[na:na]

It appears to be a Class Loading issue, we use lombok annotations for our class dependency injections which might be the cause of this. I have tried replacing it in the VerificationService class with a constructor and it still throws the same issue.
Followed the instructions found on the spring boot dev tools docs - classloading issues with disabling the restart and this stopped the error but then changes made weren't applied after the LiveReload.

Instructions were followed for spring boot dev tools docs - remote application which I run before making any changes in the IDE.

The container isn't currently assigned to any network and has exposed port 8120

At the moment my workaround this issue is to instead not use the dev tools (removing it entirely) but use the native Remote JVM Debug of IntelliJ and connect to port 5005. I have been able to make changes which are reflected in the running service this way (though limited to no schema or method signature changes) but it would be nicer if this was working with dev tools.

Thanks now.

The text was updated successfully, but these errors were encountered:

wilkinsona · 2022-07-06T14:40:10Z

We're not aware of any problems in this area. Can you please provide a minimal sample and steps to reproduce the problem?

iranicus · 2022-07-06T16:33:32Z

chat-application.zip

Yeah sure, just created a sample web service using the same dependencies now with a single endpoint:
GET http://localhost:8120/v2/chat/

It includes a Dockerfile from which the image can be built so you will need to have docker running in the background.

Steps to reproduce:

In the project root, build the maven project: ./mvnw clean install
In the project root, build the docker image using: docker buildx build -t chat-application .
Start a new container using the built image: docker container run -p 8120:8120 --rm --name chat-application chat-application:latest
In the IDE (Using IntelliJ in this case): Create a new Application session with the following config:
- Main class: org.springframework.boot.devtools.RemoteSpringApplication
- Program arguments: http://localhost:8120
- Working directory: should not need changing, will already point to the project
Run the new application session (should start up fine with the LiveReload server running)
Call the GET http://localhost:8120/v2/chat/ endpoint to make sure the service is running fine
In the IDE: Change the value of the VERIFY_MSG constant found in the VerificationService
In the IDE: Build the project

At this point the docker container logs for the running service should throw the following exception which I have managed to replicate on this simplified example:

2022-07-06 16:08:32.387  WARN 1 --- [  restartedMain] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'otherService': Resolution of declared constructors on bean Class [com.chatapplication.service.v2.OtherService] from ClassLoader [org.springframework.boot.devtools.restart.classloader.RestartClassLoader@7adf428a] failed; nested exception is java.lang.NoClassDefFoundError: com/chatapplication/service/v2/VerificationService
2022-07-06 16:08:32.388  INFO 1 --- [  restartedMain] o.apache.catalina.core.StandardService   : Stopping service [Tomcat]
2022-07-06 16:08:32.397  INFO 1 --- [  restartedMain] ConditionEvaluationReportLoggingListener : 

Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2022-07-06 16:08:32.422 ERROR 1 --- [  restartedMain] o.s.boot.SpringApplication               : Application run failed

org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'otherService': Resolution of declared constructors on bean Class [com.chatapplication.service.v2.OtherService] from ClassLoader [org.springframework.boot.devtools.restart.classloader.RestartClassLoader@7adf428a] failed; nested exception is java.lang.NoClassDefFoundError: com/chatapplication/service/v2/VerificationService
	at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.determineCandidateConstructors(AutowiredAnnotationBeanPostProcessor.java:309) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.determineConstructorsFromBeanPostProcessors(AbstractAutowireCapableBeanFactory.java:1302) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1219) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:582) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:953) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918) ~[spring-context-5.3.18.jar!/:5.3.18]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:583) ~[spring-context-5.3.18.jar!/:5.3.18]
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:740) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:415) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:303) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1312) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1301) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at com.chatapplication.ChatApplication.main(ChatApplication.java:10) ~[classes!/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
	at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49) ~[spring-boot-devtools-2.6.6.jar!/:2.6.6]
Caused by: java.lang.NoClassDefFoundError: com/chatapplication/service/v2/VerificationService
	at java.base/java.lang.Class.getDeclaredConstructors0(Native Method) ~[na:na]
	at java.base/java.lang.Class.privateGetDeclaredConstructors(Class.java:3137) ~[na:na]
	at java.base/java.lang.Class.getDeclaredConstructors(Class.java:2357) ~[na:na]
	at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.determineCandidateConstructors(AutowiredAnnotationBeanPostProcessor.java:304) ~[spring-beans-5.3.18.jar!/:5.3.18]
	... 23 common frames omitted
Caused by: java.lang.ClassNotFoundException: com.chatapplication.service.v2.VerificationService
	at org.springframework.boot.devtools.restart.classloader.RestartClassLoader.loadClass(RestartClassLoader.java:136) ~[spring-boot-devtools-2.6.6.jar!/:2.6.6]
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522) ~[na:na]
	... 27 common frames omitted

Hopefully that will help 👍

wilkinsona · 2022-07-21T16:01:50Z

Thanks for the sample, @iranicus. I've tried to reproduce the problem and have thus far been unable to do so. I used Eclipse to make the change to the application code. This resulted in the following logging:

2022-07-21 16:57:19.063  INFO 68207 --- [   File Watcher] o.s.b.d.r.c.ClassPathChangeUploader      : Uploaded 1 class resource
2022-07-21 16:57:20.072  INFO 68207 --- [pool-1-thread-1] o.s.b.d.r.c.DelayedLiveReloadTrigger     : Remote server has changed, triggering LiveReload

On the remote side, this triggered the expected restart which was successful:

2022-07-21 15:54:20.423  INFO 1 --- [           main] com.chatapplication.ChatApplication      : Started ChatApplication in 2.12 seconds (JVM running for 2.574)
2022-07-21 15:57:08.267  INFO 1 --- [nio-8120-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-07-21 15:57:08.267  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-07-21 15:57:08.272  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 4 ms

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

2022-07-21 15:57:19.187  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Starting ChatApplication v0.0.1-SNAPSHOT using Java 11.0.16 on c6dfab6ed849 with PID 1 (/application/chat-app/chat-application.jar started by java_user in /application/chat-app)
2022-07-21 15:57:19.187  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : No active profile set, falling back to 1 default profile: "default"
2022-07-21 15:57:19.460  INFO 1 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8120 (http)
2022-07-21 15:57:19.461  INFO 1 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-07-21 15:57:19.461  INFO 1 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.60]
2022-07-21 15:57:19.463  INFO 1 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-07-21 15:57:19.464  INFO 1 --- [  restartedMain] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 274 ms
2022-07-21 15:57:19.492  WARN 1 --- [  restartedMain] .s.b.d.a.RemoteDevToolsAutoConfiguration : Listening for remote restart updates on /.~~spring-boot!~/restart
2022-07-21 15:57:19.576  INFO 1 --- [  restartedMain] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 1 endpoint(s) beneath base path '/actuator'
2022-07-21 15:57:19.586  INFO 1 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8120 (http) with context path ''
2022-07-21 15:57:19.591  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Started ChatApplication in 0.438 seconds (JVM running for 181.872)
2022-07-21 15:57:20.075  INFO 1 --- [nio-8120-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-07-21 15:57:20.075  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-07-21 15:57:20.076  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms

I have removed Lombok from the app as I don't have that Lombok plugin installed in Eclipse. I wouldn't expect that to make a difference though. I'll try with IntelliJ next.

wilkinsona · 2022-07-21T16:16:15Z

The restart was also successful using IntelliJ and with Lombok reinstated:

2022-07-21 15:57:19.591  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Started ChatApplication in 0.438 seconds (JVM running for 181.872)
2022-07-21 15:57:20.075  INFO 1 --- [nio-8120-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-07-21 15:57:20.075  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-07-21 15:57:20.076  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms

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

2022-07-21 16:08:42.203  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Starting ChatApplication v0.0.1-SNAPSHOT using Java 11.0.16 on c6dfab6ed849 with PID 1 (/application/chat-app/chat-application.jar started by java_user in /application/chat-app)
2022-07-21 16:08:42.204  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : No active profile set, falling back to 1 default profile: "default"
2022-07-21 16:08:42.427  INFO 1 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8120 (http)
2022-07-21 16:08:42.427  INFO 1 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-07-21 16:08:42.428  INFO 1 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.60]
2022-07-21 16:08:42.430  INFO 1 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-07-21 16:08:42.430  INFO 1 --- [  restartedMain] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 223 ms
2022-07-21 16:08:42.454  WARN 1 --- [  restartedMain] .s.b.d.a.RemoteDevToolsAutoConfiguration : Listening for remote restart updates on /.~~spring-boot!~/restart
2022-07-21 16:08:42.524  INFO 1 --- [  restartedMain] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 1 endpoint(s) beneath base path '/actuator'
2022-07-21 16:08:42.533  INFO 1 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8120 (http) with context path ''
2022-07-21 16:08:42.538  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Started ChatApplication in 0.361 seconds (JVM running for 865.295)
2022-07-21 16:08:43.101  INFO 1 --- [nio-8120-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-07-21 16:08:43.102  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-07-21 16:08:43.103  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms

I've also tried making changes to OtherService and ChatController and they were also successful.

I notice that the original error reported above is java.lang.ClassNotFoundException: com.service.v2.ChatService. There's no such class in the sample. I suspect that's due to changes made as part of producing the minimal sample, but just wanted to double-check that the sample does reproduce the failure for you.

iranicus · 2022-07-23T11:24:48Z

I will take another quick look this afternoon and see if I can replicate the problem again using the sample chat application then get back to you.

iranicus · 2022-07-23T12:07:37Z

The restart was also successful using IntelliJ and with Lombok reinstated:

2022-07-21 15:57:19.591  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Started ChatApplication in 0.438 seconds (JVM running for 181.872)
2022-07-21 15:57:20.075  INFO 1 --- [nio-8120-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-07-21 15:57:20.075  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-07-21 15:57:20.076  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms

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

2022-07-21 16:08:42.203  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Starting ChatApplication v0.0.1-SNAPSHOT using Java 11.0.16 on c6dfab6ed849 with PID 1 (/application/chat-app/chat-application.jar started by java_user in /application/chat-app)
2022-07-21 16:08:42.204  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : No active profile set, falling back to 1 default profile: "default"
2022-07-21 16:08:42.427  INFO 1 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8120 (http)
2022-07-21 16:08:42.427  INFO 1 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-07-21 16:08:42.428  INFO 1 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.60]
2022-07-21 16:08:42.430  INFO 1 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-07-21 16:08:42.430  INFO 1 --- [  restartedMain] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 223 ms
2022-07-21 16:08:42.454  WARN 1 --- [  restartedMain] .s.b.d.a.RemoteDevToolsAutoConfiguration : Listening for remote restart updates on /.~~spring-boot!~/restart
2022-07-21 16:08:42.524  INFO 1 --- [  restartedMain] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 1 endpoint(s) beneath base path '/actuator'
2022-07-21 16:08:42.533  INFO 1 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8120 (http) with context path ''
2022-07-21 16:08:42.538  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Started ChatApplication in 0.361 seconds (JVM running for 865.295)
2022-07-21 16:08:43.101  INFO 1 --- [nio-8120-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-07-21 16:08:43.102  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-07-21 16:08:43.103  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms

I've also tried making changes to OtherService and ChatController and they were also successful.

I notice that the original error reported above is java.lang.ClassNotFoundException: com.service.v2.ChatService. There's no such class in the sample. I suspect that's due to changes made as part of producing the minimal sample, but just wanted to double-check that the sample does reproduce the failure for you.

Yeah the names of the classes were changed for anonymity before the attached chat application was created for demo purposes. I have repeated the steps I mentioned before and have managed to run into the same problem when I changed the value of the VERIFY_MSG field in the VerificationService and rebuilt the service while it was running:

2022-07-23 12:50:18.541  INFO 45806 --- [           main] o.s.b.devtools.RemoteSpringApplication   : No active profile set, falling back to 1 default profile: "default"
2022-07-23 12:50:18.769  WARN 45806 --- [           main] o.s.b.d.r.c.RemoteClientConfiguration    : The connection to http://localhost:8120 is insecure. You should use a URL starting with 'https://'.
2022-07-23 12:50:18.823  INFO 45806 --- [           main] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2022-07-23 12:50:18.838  INFO 45806 --- [           main] o.s.b.devtools.RemoteSpringApplication   : Started RemoteSpringApplication in 0.737 seconds (JVM running for 1.266)
2022-07-23 12:52:24.084  INFO 45806 --- [   File Watcher] o.s.b.d.r.c.ClassPathChangeUploader      : Uploaded 1 class resource
2022-07-23 12:52:25.510  WARN 45806 --- [   File Watcher] o.s.b.d.r.c.ClassPathChangeUploader      : A failure occurred when uploading to http://localhost:8120/.~~spring-boot!~/restart. Upload will be retried in 2 seconds

The mentioned failure at the end of the logs was due to the service stopping, the docker container logs showing the following:

2022-07-23 11:49:36.594  INFO 1 --- [           main] com.chatapplication.ChatApplication      : Starting ChatApplication v0.0.1-SNAPSHOT using Java 11.0.15 on ce40804ee34d with PID 1 (/application/chat-app/chat-application.jar started by java_user in /application/chat-app)
2022-07-23 11:49:36.597  INFO 1 --- [           main] com.chatapplication.ChatApplication      : No active profile set, falling back to 1 default profile: "default"
2022-07-23 11:49:36.665  INFO 1 --- [           main] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
2022-07-23 11:49:36.666  INFO 1 --- [           main] .e.DevToolsPropertyDefaultsPostProcessor : For additional web related logging consider setting the 'logging.level.web' property to 'DEBUG'
2022-07-23 11:49:37.823  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8120 (http)
2022-07-23 11:49:37.836  INFO 1 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-07-23 11:49:37.837  INFO 1 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.60]
2022-07-23 11:49:37.901  INFO 1 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-07-23 11:49:37.901  INFO 1 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1234 ms
2022-07-23 11:49:38.089  WARN 1 --- [           main] .s.b.d.a.RemoteDevToolsAutoConfiguration : Listening for remote restart updates on /.~~spring-boot!~/restart
2022-07-23 11:49:38.493  INFO 1 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 1 endpoint(s) beneath base path '/actuator'
2022-07-23 11:49:38.551  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8120 (http) with context path ''
2022-07-23 11:49:38.570  INFO 1 --- [           main] com.chatapplication.ChatApplication      : Started ChatApplication in 2.519 seconds (JVM running for 2.965)
2022-07-23 11:51:17.156  INFO 1 --- [nio-8120-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-07-23 11:51:17.157  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-07-23 11:51:17.158  INFO 1 --- [nio-8120-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms

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

2022-07-23 11:52:24.242  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Starting ChatApplication v0.0.1-SNAPSHOT using Java 11.0.15 on ce40804ee34d with PID 1 (/application/chat-app/chat-application.jar started by java_user in /application/chat-app)
2022-07-23 11:52:24.243  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : No active profile set, falling back to 1 default profile: "default"
2022-07-23 11:52:24.665  INFO 1 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8120 (http)
2022-07-23 11:52:24.667  INFO 1 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-07-23 11:52:24.667  INFO 1 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.60]
2022-07-23 11:52:24.671  INFO 1 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-07-23 11:52:24.671  INFO 1 --- [  restartedMain] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 423 ms
2022-07-23 11:52:24.711  WARN 1 --- [  restartedMain] .s.b.d.a.RemoteDevToolsAutoConfiguration : Listening for remote restart updates on /.~~spring-boot!~/restart
2022-07-23 11:52:24.718  WARN 1 --- [  restartedMain] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'otherService': Resolution of declared constructors on bean Class [com.chatapplication.service.v2.OtherService] from ClassLoader [org.springframework.boot.devtools.restart.classloader.RestartClassLoader@105f7e57] failed; nested exception is java.lang.NoClassDefFoundError: com/chatapplication/service/v2/VerificationService
2022-07-23 11:52:24.719  INFO 1 --- [  restartedMain] o.apache.catalina.core.StandardService   : Stopping service [Tomcat]
2022-07-23 11:52:24.730  INFO 1 --- [  restartedMain] ConditionEvaluationReportLoggingListener : 

Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2022-07-23 11:52:24.757 ERROR 1 --- [  restartedMain] o.s.boot.SpringApplication               : Application run failed

org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'otherService': Resolution of declared constructors on bean Class [com.chatapplication.service.v2.OtherService] from ClassLoader [org.springframework.boot.devtools.restart.classloader.RestartClassLoader@105f7e57] failed; nested exception is java.lang.NoClassDefFoundError: com/chatapplication/service/v2/VerificationService
	at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.determineCandidateConstructors(AutowiredAnnotationBeanPostProcessor.java:309) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.determineConstructorsFromBeanPostProcessors(AbstractAutowireCapableBeanFactory.java:1302) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1219) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:582) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:953) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918) ~[spring-context-5.3.18.jar!/:5.3.18]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:583) ~[spring-context-5.3.18.jar!/:5.3.18]
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:740) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:415) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:303) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1312) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1301) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at com.chatapplication.ChatApplication.main(ChatApplication.java:10) ~[classes!/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
	at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49) ~[spring-boot-devtools-2.6.6.jar!/:2.6.6]
Caused by: java.lang.NoClassDefFoundError: com/chatapplication/service/v2/VerificationService
	at java.base/java.lang.Class.getDeclaredConstructors0(Native Method) ~[na:na]
	at java.base/java.lang.Class.privateGetDeclaredConstructors(Class.java:3137) ~[na:na]
	at java.base/java.lang.Class.getDeclaredConstructors(Class.java:2357) ~[na:na]
	at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.determineCandidateConstructors(AutowiredAnnotationBeanPostProcessor.java:304) ~[spring-beans-5.3.18.jar!/:5.3.18]
	... 23 common frames omitted
Caused by: java.lang.ClassNotFoundException: com.chatapplication.service.v2.VerificationService
	at org.springframework.boot.devtools.restart.classloader.RestartClassLoader.loadClass(RestartClassLoader.java:136) ~[spring-boot-devtools-2.6.6.jar!/:2.6.6]
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522) ~[na:na]
	... 27 common frames omitted

The service started up fine at 11:51, then mentioned changes were made whilst IntellIJ had the Remote Debug running on port 8120 and I triggered a manual build in the IDE. This sure enough caused the service to restart which you can see from 11:52 which lead to the eventual exception shown a couple of seconds later when the updated VerificationService dependency was being loaded for OtherService.

Could you try making the same changes to the VerificationService then do a rebuild?

wilkinsona · 2022-07-25T07:34:03Z

Could you try making the same changes to the VerificationService then do a rebuild?

Unfortunately, this is exactly what I tried already. I changed the value of the VERIFY_MSG constant, the app restarted, and making a request to http://localhost:8120/v2/chat/ showed the new value being used.

Your logs above show Java 11.0.15 being used:

2022-07-23 11:52:24.242  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Starting ChatApplication v0.0.1-SNAPSHOT using Java 11.0.15 on ce40804ee34d with PID 1 (/application/chat-app/chat-application.jar started by java_user in /application/chat-app)

Whereas my logs show Java 11.0.16:

2022-07-21 16:08:42.203  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Starting ChatApplication v0.0.1-SNAPSHOT using Java 11.0.16 on c6dfab6ed849 with PID 1 (/application/chat-app/chat-application.jar started by java_user in /application/chat-app)

Given that the JVM is determined by the container, it's not immediately obvious to me why they're different. Perhaps this is (part of) the problem? It could also be the IDE. It works for me with IntelliJ IDEA 2021.2.2 Ultimate Edition. What version are you using?

iranicus · 2022-07-26T09:44:54Z

Could be, so I am using IntelliJ IDEA 2022.1.4 (Ultimate Edition) having recently updated but have re-tried and have got the same result.

wilkinsona · 2022-07-27T10:39:19Z

I've upgraded to IntellIJ IDEA 2022.1.4 and I can now reproduce the problem. When I trigger a rebuild after changing the value of VERIFY_MSG it attempts to upload 1 class resource and it fails:

2022-07-27 11:35:25.686  INFO 62132 --- [   File Watcher] o.s.b.d.r.c.ClassPathChangeUploader      : Uploaded 1 class resource
2022-07-27 11:35:27.104  WARN 62132 --- [   File Watcher] o.s.b.d.r.c.ClassPathChangeUploader      : A failure occurred when uploading to http://localhost:8120/.~~spring-boot!~/restart. Upload will be retried in 2 seconds

At the time of this failure, the remote application logs the following:

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

2022-07-27 10:35:25.796  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : Starting ChatApplication v0.0.1-SNAPSHOT using Java 11.0.16 on a9533096f7e2 with PID 1 (/application/chat-app/chat-application.jar started by java_user in /application/chat-app)
2022-07-27 10:35:25.796  INFO 1 --- [  restartedMain] com.chatapplication.ChatApplication      : No active profile set, falling back to 1 default profile: "default"
2022-07-27 10:35:26.130  INFO 1 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8120 (http)
2022-07-27 10:35:26.131  INFO 1 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-07-27 10:35:26.131  INFO 1 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.60]
2022-07-27 10:35:26.134  INFO 1 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-07-27 10:35:26.134  INFO 1 --- [  restartedMain] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 334 ms
2022-07-27 10:35:26.161  WARN 1 --- [  restartedMain] .s.b.d.a.RemoteDevToolsAutoConfiguration : Listening for remote restart updates on /.~~spring-boot!~/restart
2022-07-27 10:35:26.168  WARN 1 --- [  restartedMain] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'chatController' defined in URL [jar:file:/application/chat-app/chat-application.jar!/BOOT-INF/classes!/com/chatapplication/controller/ChatController.class]: Unsatisfied dependency expressed through constructor parameter 0; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'otherService': Resolution of declared constructors on bean Class [com.chatapplication.service.v2.OtherService] from ClassLoader [org.springframework.boot.devtools.restart.classloader.RestartClassLoader@21436b81] failed; nested exception is java.lang.NoClassDefFoundError: com/chatapplication/service/v2/VerificationService
2022-07-27 10:35:26.168  INFO 1 --- [  restartedMain] o.apache.catalina.core.StandardService   : Stopping service [Tomcat]
2022-07-27 10:35:26.176  INFO 1 --- [  restartedMain] ConditionEvaluationReportLoggingListener : 

Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2022-07-27 10:35:26.203 ERROR 1 --- [  restartedMain] o.s.boot.SpringApplication               : Application run failed

org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'chatController' defined in URL [jar:file:/application/chat-app/chat-application.jar!/BOOT-INF/classes!/com/chatapplication/controller/ChatController.class]: Unsatisfied dependency expressed through constructor parameter 0; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'otherService': Resolution of declared constructors on bean Class [com.chatapplication.service.v2.OtherService] from ClassLoader [org.springframework.boot.devtools.restart.classloader.RestartClassLoader@21436b81] failed; nested exception is java.lang.NoClassDefFoundError: com/chatapplication/service/v2/VerificationService
	at org.springframework.beans.factory.support.ConstructorResolver.createArgumentArray(ConstructorResolver.java:800) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:229) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:1372) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1222) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:582) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:953) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918) ~[spring-context-5.3.18.jar!/:5.3.18]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:583) ~[spring-context-5.3.18.jar!/:5.3.18]
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:740) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:415) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:303) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1312) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1301) ~[spring-boot-2.6.6.jar!/:2.6.6]
	at com.chatapplication.ChatApplication.main(ChatApplication.java:10) ~[classes!/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
	at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49) ~[spring-boot-devtools-2.6.6.jar!/:2.6.6]
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'otherService': Resolution of declared constructors on bean Class [com.chatapplication.service.v2.OtherService] from ClassLoader [org.springframework.boot.devtools.restart.classloader.RestartClassLoader@21436b81] failed; nested exception is java.lang.NoClassDefFoundError: com/chatapplication/service/v2/VerificationService
	at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.determineCandidateConstructors(AutowiredAnnotationBeanPostProcessor.java:309) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.determineConstructorsFromBeanPostProcessors(AbstractAutowireCapableBeanFactory.java:1302) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1219) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:582) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.config.DependencyDescriptor.resolveCandidate(DependencyDescriptor.java:276) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.doResolveDependency(DefaultListableBeanFactory.java:1389) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveDependency(DefaultListableBeanFactory.java:1309) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.ConstructorResolver.resolveAutowiredArgument(ConstructorResolver.java:887) ~[spring-beans-5.3.18.jar!/:5.3.18]
	at org.springframework.beans.factory.support.ConstructorResolver.createArgumentArray(ConstructorResolver.java:791) ~[spring-beans-5.3.18.jar!/:5.3.18]
	... 24 common frames omitted
Caused by: java.lang.NoClassDefFoundError: com/chatapplication/service/v2/VerificationService
	at java.base/java.lang.Class.getDeclaredConstructors0(Native Method) ~[na:na]
	at java.base/java.lang.Class.privateGetDeclaredConstructors(Class.java:3137) ~[na:na]
	at java.base/java.lang.Class.getDeclaredConstructors(Class.java:2357) ~[na:na]
	at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.determineCandidateConstructors(AutowiredAnnotationBeanPostProcessor.java:304) ~[spring-beans-5.3.18.jar!/:5.3.18]
	... 37 common frames omitted
Caused by: java.lang.ClassNotFoundException: com.chatapplication.service.v2.VerificationService
	at org.springframework.boot.devtools.restart.classloader.RestartClassLoader.loadClass(RestartClassLoader.java:136) ~[spring-boot-devtools-2.6.6.jar!/:2.6.6]
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522) ~[na:na]
	... 41 common frames omitted

Now to see if I can figure out why it only fails with a particular version of IntelliJ IDEA.

wilkinsona · 2022-07-27T11:24:13Z

The way that updates to class files are made appears to have changed in more recent versions of IntellIJ IDEA.

When I change VerificationService and trigger a rebuild, the VerificationService.class file is deleted. DevTools' file watcher notices this change and uploads a ClassLoaderFile.Kind.DELETED for VerificationService.class. The class is deleted on the receiving side and a restart is triggered. The restart then fails due to the missing class.

The problem can be avoided by tuning the quiet period that's required before a restart. The following works for me:

spring:
  devtools:
    remote:
      secret: mysecret
    restart:
      quiet-period: 800ms

There's a usability issue here as this wasn't easy to figure out. Perhaps we should log more about the change? Rather than just logging the number of class resources that have changed in some way, a break down by the kind of change would have helped.

I also wonder if the behavior when the restart triggered by the upload fails could be improved. At the moment, the restart failure causes the application to exit. RemoteSpringApplication then retries the upload indefinitely, unable to connect to the application. It isn't really the upload that's failed, but the application's response to that upload. Presumably, if it had kept running and RemoteSpringApplication was then able to upload an ADDED change for VerificationService, a subsequent restart may then have succeeded.

iranicus · 2022-07-27T11:57:16Z

Hmm, I did try messing around with setting the quiet-period before when following the documentation Spring Boot Docs - Configuring File System Watcher
I was unable to resolve the problem though at the time, I have tried setting it to 900ms now and this works having just tried 800ms and running into the same problem. My worry is that this seems to be IDE specific so adding it to the main configuration for the application permanently wouldn't be good practice.

In regards to the logging out of updated classes I do think it would be beneficial to have the breakdown for clarity. I was surprised the application exited since this would become a problem if the appropriate quiet-period isn't set to avoid this (chances are it will be different per machine unless a high value is set to try cover all cases). The service would therefore manually need to be restarted.

wilkinsona · 2022-07-27T12:51:15Z

Thanks for trying tuning of the quiet period. It's good to hear that increasing it resolves the problem for you too.

My worry is that this seems to be IDE specific so adding it to the main configuration for the application permanently wouldn't be good practice.

You may want to configure the quiet period in a global settings file that's appropriate for your local development environment (IDE, etc.).

bclozel · 2022-07-27T15:57:00Z

The team discussed this issue and we think we should add more log information - initially a single line stating how many adds/deletes/changes were pushed to the server. In this case, this would have been a nice clue about that class being deleted+added. We can always consider more detailed log messages in the future.

We also discussed changing the default value for the restart "quiet-period" but this looks very setup-specific and it's hard to think of a value that would fit in all cases.

wilkinsona · 2022-07-28T13:54:01Z

I've added some info-level logging that provides an overview of the changes that are going to be uploaded. When the quiet period is too short and a modification appears as a delete followed by an add, those messages look like this:

2022-07-28 14:06:27.242  INFO 17791 --- [   File Watcher] o.s.b.d.r.c.ClassPathChangeUploader      : Uploading 1 class path change (0 additions, 1 deletion, 0 modifications)
2022-07-28 14:06:28.672  INFO 17791 --- [   File Watcher] o.s.b.d.r.c.ClassPathChangeUploader      : Uploading 1 class path change (1 addition, 0 deletions, 0 modifications)

The second upload fails as the first triggered a restart which failed due to the missing class. As a result, we then see the existing warn-level logging:

2022-07-28 14:06:28.673  WARN 17791 --- [   File Watcher] o.s.b.d.r.c.ClassPathChangeUploader      : A failure occurred when uploading to http://localhost:8120/.~~spring-boot!~/restart. Upload will be retried in 2 seconds

I've also made a similar change to local dev tools which now logs messages like this when a restart is triggered:

2022-07-28 13:58:39.653  INFO 15625 --- [   File Watcher] rtingClassPathChangeChangedEventListener : Restarting due to 1 class path change (1 addition, 0 deletions, 0 modifications)

spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Jul 6, 2022

wilkinsona added the status: waiting-for-feedback We need additional information before we can continue label Jul 6, 2022

spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Jul 6, 2022

wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Jul 21, 2022

spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Jul 23, 2022

wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Jul 25, 2022

spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Jul 26, 2022

wilkinsona added the for: team-meeting An issue we'd like to discuss as a team to make progress label Jul 27, 2022

bclozel removed the for: team-meeting An issue we'd like to discuss as a team to make progress label Jul 27, 2022

wilkinsona changed the title ~~docker + spring-boot-devtools: NoClassDefFoundError thrown after changes are made during restart~~ Dev Tools restart failures caused by a too short quiet period are hard to diagnose Jul 27, 2022

wilkinsona removed status: waiting-for-triage An issue we've not yet triaged status: feedback-provided Feedback has been provided labels Jul 27, 2022

wilkinsona added the type: bug A general bug label Jul 27, 2022

wilkinsona added this to the 2.6.x milestone Jul 27, 2022

wilkinsona self-assigned this Jul 27, 2022

wilkinsona mentioned this issue Jul 28, 2022

Dev Tools restart failures caused by a too short quiet period are hard to diagnose #31906

Closed

wilkinsona closed this as completed in 348b2c2 Jul 28, 2022

wilkinsona modified the milestones: 2.6.x, 2.6.11 Jul 28, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Dev Tools restart failures caused by a too short quiet period are hard to diagnose #31579

Dev Tools restart failures caused by a too short quiet period are hard to diagnose #31579

iranicus commented Jul 6, 2022

wilkinsona commented Jul 6, 2022 •

edited

iranicus commented Jul 6, 2022 •

edited

wilkinsona commented Jul 21, 2022

wilkinsona commented Jul 21, 2022

iranicus commented Jul 23, 2022

iranicus commented Jul 23, 2022 •

edited

wilkinsona commented Jul 25, 2022 •

edited

iranicus commented Jul 26, 2022

wilkinsona commented Jul 27, 2022

wilkinsona commented Jul 27, 2022

iranicus commented Jul 27, 2022

wilkinsona commented Jul 27, 2022

bclozel commented Jul 27, 2022

wilkinsona commented Jul 28, 2022 •

edited

Dev Tools restart failures caused by a too short quiet period are hard to diagnose #31579

Dev Tools restart failures caused by a too short quiet period are hard to diagnose #31579

Comments

iranicus commented Jul 6, 2022

wilkinsona commented Jul 6, 2022 • edited

iranicus commented Jul 6, 2022 • edited

wilkinsona commented Jul 21, 2022

wilkinsona commented Jul 21, 2022

iranicus commented Jul 23, 2022

iranicus commented Jul 23, 2022 • edited

wilkinsona commented Jul 25, 2022 • edited

iranicus commented Jul 26, 2022

wilkinsona commented Jul 27, 2022

wilkinsona commented Jul 27, 2022

iranicus commented Jul 27, 2022

wilkinsona commented Jul 27, 2022

bclozel commented Jul 27, 2022

wilkinsona commented Jul 28, 2022 • edited

wilkinsona commented Jul 6, 2022 •

edited

iranicus commented Jul 6, 2022 •

edited

iranicus commented Jul 23, 2022 •

edited

wilkinsona commented Jul 25, 2022 •

edited

wilkinsona commented Jul 28, 2022 •

edited