search

OpenLiberty / ci.maven

Maven plugins for managing Liberty profile servers #devops
Apache License 2.0
126 stars 90 forks source link

Server stopped after source code change in dev mode (Maven plugin) #1816

Open inad9300 opened 5 months ago

inad9300 commented 5 months ago

Describe the bug
While using the liberty:dev Maven plugin, a source code change that triggered a restart lead to the server being stopped. Here are the last log lines:

[INFO] [2024-04-16T09:54:49.054+0000] 00000035 id=         com.ibm.ws.webcontainer.servlet.ServletWrapper               I doDestroy SRVE0253I: [app] [/] [...RestApplication]: Destroy successful.
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R  Exception in thread "Thread-28" 
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R  java.util.concurrent.RejectedExecutionException: CWWKE1202E: A task cannot be submitted because the executor concurrencyPolicy[defaultConcurrencyPolicy] has been shut down.
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R       at com.ibm.ws.threading.internal.PolicyExecutorImpl.enqueue(PolicyExecutorImpl.java:611)
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R       at com.ibm.ws.threading.internal.PolicyExecutorImpl.submit(PolicyExecutorImpl.java:1422)
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R       at com.ibm.ws.concurrent.internal.ManagedCompletableFuture$FutureRefExecutor.execute(ManagedCompletableFuture.java:199)
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R       at com.ibm.ws.concurrent.internal.ManagedCompletableFuture.runAsync(ManagedCompletableFuture.java:472)
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R       at com.ibm.ws.concurrent.internal.ManagedExecutorServiceImpl.runAsync(ManagedExecutorServiceImpl.java:677)
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R       at ...Service.runAsync(Service.java:21)
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R       at ...Service$Proxy$_$$_WeldClientProxy.runAsync(Unknown Source)
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R       at ...
[INFO] [2024-04-16T09:54:49.065+0000] 000003ad id=                                                                      R       at java.base/java.lang.Thread.run(Thread.java:840)
[INFO] [2024-04-16T09:54:49.089+0000] 00000035 id=         com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0009I: The application app has stopped successfully.
[INFO] [2024-04-16T09:54:49.098+0000] 000003d9 id=         com.ibm.ws.webcontainer.servlet.ServletWrapper               I doDestroy SRVE0253I: [io.openliberty.microprofile.openapi.2.0.internal.servlet.jakarta] [/openapi] [ApplicationServlet]: Destroy successful.
[INFO] [2024-04-16T09:54:49.167+0000] 000003d9 id=         com.ibm.tx.jta.impl.FailureScopeController                   A WTRN0105I: The transaction service has shutdown successfully with no transactions requiring recovery.
[INFO] [2024-04-16T09:54:49.247+0000] 000003d9 id=         rty.security.mp.jwt.v21.config.impl.MpConfigProxyServiceImpl I CWWKS5788I: The MicroProfile JWT version 2.1 mpConfigProxy was deactivated successfully.
[INFO] [2024-04-16T09:54:49.249+0000] 000003d9 id=         com.ibm.ws.security.mp.jwt.impl.MicroProfileJwtConfigImpl    I CWWKS5502I: The MicroProfile JWT configuration [defaultMpJwt] was successfully deactivated.
[INFO] [2024-04-16T09:54:49.250+0000] 000003d9 id=         com.ibm.ws.security.mp.jwt.impl.MicroProfileJwtServiceImpl   I CWWKS5502I: The MicroProfile JWT configuration [MicroProfileJwtService] was successfully deactivated.
[INFO] [2024-04-16T09:54:49.391+0000] 000003d9 id=         ibm.ws.security.authentication.internal.jaas.JAASServiceImpl I CWWKS1124I: The collective authentication plugin with class name NullCollectiveAuthenticationPlugin has been deactivated. 
[INFO] [2024-04-16T09:54:49.395+0000] 000003d9 id=         com.ibm.ws.security.ready.internal.SecurityReadyServiceImpl  I CWWKS0009I: The security service has stopped.
[INFO] [2024-04-16T09:54:49.710+0000] 00000001 id=         com.ibm.ws.kernel.launch.internal.FrameworkManager           A CWWKE0036I: The server defaultServer stopped after 4 minutes, 41.521 seconds.
[INFO] Server defaultServer stopped.

And the code involved:

@ApplicationScoped
public class Service {

    @Resource
    private ManagedExecutorService executor;

    public CompletableFuture<Void> runAsync(Runnable task) {
        return executor.runAsync(task);
    }
}

Expected behavior
The dev server should resist exceptions thrown during destruction.

Diagnostic information:

Azquelt commented 5 months ago

Hi, can you clarify what the problem is?

Reading your issue, I'm not sure which of the following you're saying is wrong:

inad9300 commented 5 months ago

Hi. Sure, it is the second point: Open Liberty's Maven plugin should restart the server.

scottkurz commented 5 months ago

a source code change that triggered a restart

Can you please explain a bit more about what led up to the restart? You changed the source..was it Java code, pom.xml, server.xml, some combination?

For your first set of errors in the log.. are these the original, first relevant log entries here? Or are you saying that there was some other condition prior, which led to these exceptions as a consequence?

[INFO] [2024-04-16T09:54:49.054+0000] 00000035 id= com.ibm.ws.webcontainer.servlet.ServletWrapper I doDestroy SRVE0253I: [app] [/] [...RestApplication]: Destroy successful. [INFO] [2024-04-16T09:54:49.065+0000] 000003ad id= R Exception in thread "Thread-28" [INFO] [2024-04-16T09:54:49.065+0000] 000003ad id= R java.util.concurrent.RejectedExecutionException: CWWKE1202E: A task cannot be submitted because the executor concurrencyPolicy[defaultConcurrencyPolicy] has been shut down.

inad9300 commented 5 months ago

I'm just using the liberty:dev command, you know? Which restarts the server every time it detects a change in the source code, does it not?

scottkurz commented 5 months ago

I'm just using the liberty:dev command, you know? Which restarts the server every time it detects a change in the source code, does it not?

Sorry.. I hit the button before I finished typing my comment. Please take another look.

In general, liberty:dev will only need to restart an application upon a Java source change. Upon a config change it may restart the server or just the app, depending on the change.

inad9300 commented 5 months ago

I was indeed changing Java code; specifically, code inside a method with an @Observes @Destroyed(ApplicationScoped.class) argument, though I don't really think this is relevant to the problem, just a coincidence.

As far as I can tell, these were the first relevant log entries, yes.

It isn't the first time I observe a mysterious server stop during development. It happens to me with some regularity, maybe once or twice a month, often without any exception in the vicinity. I'll post more details here when I see it again.

scottkurz commented 5 months ago

Thanks for clarifying. Are you able to share more details from the full messages.log (or ffdc logs) from this last time that the server crashed?

inad9300 commented 5 months ago

I couldn't see anything else of relevance in messages.log; I did not look into any other logs. They are gone now, unfortunately.

scottkurz commented 5 months ago

Ok, thanks for looking. Well, I don't think we want to expand dev mode to monitoring the server and introducing an automated restart around the server.

I think what we're left with then is understanding why did the original server crash to begin with ?

I think we would need to see the content of the logs directory to understand that better, either the full logs directory provided via a support case if that is an option for you or whatever you can share publicly if not (maybe some excerpts from the messages.log and maybe some of the FFDC logs would be helpful enough). It would also help to include the console log from your Maven session (executing dev mode) as well.

In any case, I'm going to close this for now, but please do reopen when you have more detail. Also going to transfer this back to the other repo since this has moved in the direction of more of a runtime issue than a liberty-maven-plugin issue.

Thank you.

inad9300 commented 5 months ago

It just happened again, as I was editing some test files. Please, have a look at a more complete messages.log. I have shortened it a bit (replaced a big chunk with "..."), and removed a few application-specific messages (which did not include exceptions). I would like to highlight how "The application app updated" was printed many times during the course of my development session (the last two of which can be seen) and, at one point, an unsolicited "Server shutdown requested" message is printed.

The last FFDC file was "ffdc/ffdc_24.04.17_11.13.59.1.log" and did not contain much: a single exception that occurred around the time indicated by the filename.

Azquelt commented 5 months ago

Do you have the output from the console where you ran mvn liberty:dev as well? That should show what the maven plugin was attempting to do when the server shut down.

inad9300 commented 5 months ago

My apologies, I don't anymore. (I thought the contents of messages.log were the same as the console's output, to be honest.)

inad9300 commented 5 months ago

Could we reopen this until dealt with?

inad9300 commented 4 months ago

Since my last message, I have found this problem two more times, as far as I can remember. This is what mvn liberty:dev outputted last:

...
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.934 s -- in ...
[INFO]
[INFO] Results:
[INFO]
[ERROR] Errors:
[ERROR]   ...
[INFO]
[ERROR] Tests run: ..., Failures: 0, Errors: 2, Skipped: 0
[INFO]
[ERROR] Integration tests failed:

Please refer to /app/target/failsafe-reports for the individual test results.
Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[INFO] To run tests on demand, press Enter.
[INFO] [2024-05-30T10:54:25.276+0000] 00000036 id=         ...
[INFO] ! EntityNotFoundException: ...
[INFO] [2024-05-30T12:09:38.756+0000] 0000015b id=         com.ibm.ws.http.internal.VirtualHostImpl                     A CWWKT0017I: Web application removed (default_host): http://e8e514c8928a:9080/
[INFO] [2024-05-30T12:09:38.757+0000] 0000015b id=         com.ibm.ws.webcontainer.servlet.ServletWrapper               I doDestroy SRVE0253I: [app] [/] [App]: Destroy successful.
[INFO] [2024-05-30T12:09:38.761+0000] 00000139 id=         ...
[INFO] ! InterruptedException: sleep interrupted ...
[INFO] [2024-05-30T12:09:38.763+0000] 00000104 id=         ...
[INFO] ! RuntimeException: ...
[INFO] [2024-05-30T12:09:38.777+0000] 000000aa id=         ...
[INFO] [2024-05-30T12:09:38.790+0000] 0000015b id=         com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0009I: The application app has stopped successfully.
[INFO] [2024-05-30T12:09:38.797+0000] 0000015b id=         com.ibm.ws.app.manager.AppMessageHelper                      I CWWKZ0018I: Starting application app.
[INFO] [2024-05-30T12:09:38.798+0000] 0000015b id=         bm.ws.app.manager.war.internal.WARDeployedAppInfoFactoryImpl I CWWKZ0134I: The app application is using the loose application definition at the /app/target/liberty/wlp/usr/servers/defaultServer/apps/app.war.xml location.
[INFO] [2024-05-30T12:09:38.827+0000] 00000132 id=         com.ibm.ws.webcontainer.osgi.mbeans.PluginGenerator          I SRVE9103I: A configuration file for a web server plugin was automatically generated for this server at /app/target/liberty/wlp/usr/servers/defaultServer/logs/state/plugin-cfg.xml.
[INFO] [2024-05-30T12:09:39.826+0000] 0000015b id=         eclipselink                                                  I CWWJP9990I: [eclipselink] EclipseLink, version: Eclipse Persistence Services - 4.0.2.v202306161219
Note: Recompile with -Xlint:deprecation for details.
Note: Some input files use unchecked or unsafe operations.
Note: Recompile with -Xlint:unchecked for details.
[INFO] Source compilation was successful.
Note: Recompile with -Xlint:deprecation for details.
Note: Some input files use unchecked or unsafe operations.
Note: Recompile with -Xlint:unchecked for details.
[INFO] Tests compilation was successful.
[INFO] [2024-05-30T12:09:46.454+0000] 0000015b id=         io.smallrye.openapi.runtime.scanner.OpenApiDataObjectScanner W process SROAP04005: Could not find schema class in index: com.ibm.websphere.jaxrs20.multipart.IAttachment
[INFO] [2024-05-30T12:09:46.482+0000] 0000015b id=         io.smallrye.openapi.runtime.scanner.OpenApiDataObjectScanner W process SROAP04005: Could not find schema class in index: com.ibm.websphere.jaxrs20.multipart.IAttachment
[INFO] [2024-05-30T12:09:46.517+0000] 0000015b id=         liberty.microprofile.openapi20.internal.ApplicationProcessor I CWWKO1660I: The application app was processed and an OpenAPI document was produced.
[INFO] [2024-05-30T12:09:46.518+0000] 0000015b id=         com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: app.
[INFO] [2024-05-30T12:09:46.518+0000] 0000015b id=         com.ibm.ws.webcontainer.osgi.DynamicVirtualHost              I addWebApplication SRVE0250I: Web Module app has been bound to default_host.
[INFO] [2024-05-30T12:09:46.518+0000] 0000015b id=         com.ibm.ws.http.internal.VirtualHostImpl                     A CWWKT0016I: Web application available (default_host): http://e8e514c8928a:9080/
[INFO] [2024-05-30T12:09:46.519+0000] 00000155 id=         SessionContextRegistryImpl                                   I getSessionContext SESN0176I: A new session context will be created for application key default_host/
[INFO] [2024-05-30T12:09:46.519+0000] 00000155 id=         IDGeneratorImpl                                              I IDGeneratorImpl SESN0172I: The session manager is using the Java default SecureRandom implementation for session ID generation.
[INFO] [2024-05-30T12:09:46.548+0000] 00000148 id=         com.ibm.ws.webcontainer.osgi.mbeans.PluginGenerator          I SRVE9103I: A configuration file for a web server plugin was automatically generated for this server at /app/target/liberty/wlp/usr/servers/defaultServer/logs/state/plugin-cfg.xml.
[INFO] [2024-05-30T12:09:46.628+0000] 00000155 id=                                                                      R  SLF4J(W): No SLF4J providers were found.
[INFO] [2024-05-30T12:09:46.628+0000] 00000155 id=                                                                      R  SLF4J(W): Defaulting to no-operation (NOP) logger implementation
[INFO] [2024-05-30T12:09:46.628+0000] 00000155 id=                                                                      R  SLF4J(W): See https://www.slf4j.org/codes.html#noProviders for further details.
[INFO] [2024-05-30T12:09:46.883+0000] 00000155 id=         ...
[INFO] [2024-05-30T12:09:47.091+0000] 00000155 id=         com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0003I: The application app updated in 8.293 seconds.
[INFO] [2024-05-30T12:09:47.104+0000] 00000157 id=         com.ibm.ws.http.internal.VirtualHostImpl                     A CWWKT0017I: Web application removed (default_host): http://e8e514c8928a:9080/
[INFO] [2024-05-30T12:09:47.245+0000] 00000155 id=         org.jboss.resteasy.core.ResteasyDeploymentImpl               I processApplication RESTEASY002225: Deploying jakarta.ws.rs.core.Application: class App$Proxy$_$$_WeldClientProxy
[INFO] [2024-05-30T12:09:47.275+0000] 00000155 id=         com.ibm.ws.webcontainer.servlet.ServletWrapper               I init SRVE0242I: [app] [/] [App]: Initialization successful.
[INFO] [2024-05-30T12:09:47.276+0000] 00000157 id=         com.ibm.ws.webcontainer.servlet.ServletWrapper               I doDestroy SRVE0253I: [app] [/] [App]: Destroy successful.
[INFO] [2024-05-30T12:09:47.347+0000] 00000157 id=         com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0009I: The application app has stopped successfully.
[INFO] [2024-05-30T12:09:47.354+0000] 00000157 id=         com.ibm.ws.app.manager.AppMessageHelper                      I CWWKZ0018I: Starting application app.
[INFO] [2024-05-30T12:09:47.355+0000] 00000157 id=         bm.ws.app.manager.war.internal.WARDeployedAppInfoFactoryImpl I CWWKZ0134I: The app application is using the loose application definition at the /app/target/liberty/wlp/usr/servers/defaultServer/apps/app.war.xml location.
[INFO] [2024-05-30T12:09:47.369+0000] 00000148 id=         com.ibm.ws.webcontainer.osgi.mbeans.PluginGenerator          I SRVE9103I: A configuration file for a web server plugin was automatically generated for this server at /app/target/liberty/wlp/usr/servers/defaultServer/logs/state/plugin-cfg.xml.
[INFO] [2024-05-30T12:09:47.738+0000] 00000157 id=         eclipselink                                                  I CWWJP9990I: [eclipselink] EclipseLink, version: Eclipse Persistence Services - 4.0.2.v202306161219
[INFO] [2024-05-30T12:09:53.009+0000] 00000157 id=         io.smallrye.openapi.runtime.scanner.OpenApiDataObjectScanner W process SROAP04005: Could not find schema class in index: com.ibm.websphere.jaxrs20.multipart.IAttachment
[INFO] [2024-05-30T12:09:53.035+0000] 00000157 id=         io.smallrye.openapi.runtime.scanner.OpenApiDataObjectScanner W process SROAP04005: Could not find schema class in index: com.ibm.websphere.jaxrs20.multipart.IAttachment
[INFO] [2024-05-30T12:09:53.077+0000] 00000157 id=         liberty.microprofile.openapi20.internal.ApplicationProcessor I CWWKO1660I: The application app was processed and an OpenAPI document was produced.
[INFO] [2024-05-30T12:09:53.078+0000] 00000157 id=         com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: app.
[INFO] [2024-05-30T12:09:53.078+0000] 00000157 id=         com.ibm.ws.webcontainer.osgi.DynamicVirtualHost              I addWebApplication SRVE0250I: Web Module app has been bound to default_host.
[INFO] [2024-05-30T12:09:53.078+0000] 00000157 id=         com.ibm.ws.http.internal.VirtualHostImpl                     A CWWKT0016I: Web application available (default_host): http://e8e514c8928a:9080/
[INFO] [2024-05-30T12:09:53.079+0000] 0000013f id=         SessionContextRegistryImpl                                   I getSessionContext SESN0176I: A new session context will be created for application key default_host/
[INFO] [2024-05-30T12:09:53.079+0000] 0000013f id=         IDGeneratorImpl                                              I IDGeneratorImpl SESN0172I: The session manager is using the Java default SecureRandom implementation for session ID generation.
[INFO] [2024-05-30T12:09:53.102+0000] 00000156 id=         com.ibm.ws.webcontainer.osgi.mbeans.PluginGenerator          I SRVE9103I: A configuration file for a web server plugin was automatically generated for this server at /app/target/liberty/wlp/usr/servers/defaultServer/logs/state/plugin-cfg.xml.
[INFO] [2024-05-30T12:09:53.234+0000] 0000013f id=                                                                      R  SLF4J(W): No SLF4J providers were found.
[INFO] [2024-05-30T12:09:53.235+0000] 0000013f id=                                                                      R  SLF4J(W): Defaulting to no-operation (NOP) logger implementation
[INFO] [2024-05-30T12:09:53.235+0000] 0000013f id=                                                                      R  SLF4J(W): See https://www.slf4j.org/codes.html#noProviders for further details.
[INFO] [2024-05-30T12:09:53.669+0000] 0000013f id=         com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0003I: The application app updated in 6.314 seconds.
[INFO] [2024-05-30T12:09:53.698+0000] 0000013f id=         org.jboss.resteasy.core.ResteasyDeploymentImpl               I processApplication RESTEASY002225: Deploying jakarta.ws.rs.core.Application: class App$Proxy$_$$_WeldClientProxy
[INFO] [2024-05-30T12:09:53.724+0000] 0000013f id=         com.ibm.ws.webcontainer.servlet.ServletWrapper               I init SRVE0242I: [app] [/] [App]: Initialization successful.
[INFO] java.nio.file.NoSuchFileException: /app/src/test/java/.../TestUtils.java~
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  02:00 h
[INFO] Finished at: 2024-05-30T12:15:03Z
[INFO] ------------------------------------------------------------------------
[INFO] CWWKM2001I: Invoke command is [/app/target/liberty/wlp/bin/server, stop, defaultServer].
[INFO]
[INFO] Stopping server defaultServer.
[INFO] [2024-05-30T12:15:03.728+0000] 00000018 id=         com.ibm.ws.kernel.launch.internal.ServerCommandListener      A CWWKE0055I: Server shutdown requested on Thursday, May 30, 2024 at 12:15 PM. The server defaultServer is shutting down.
[INFO] [2024-05-30T12:15:03.733+0000] 000001d4 id=         com.ibm.ws.runtime.update.internal.RuntimeUpdateManagerImpl  A CWWKE1100I: Waiting for up to 30 seconds for the server to quiesce.
[INFO] [2024-05-30T12:15:03.738+0000] 00000157 id=         com.ibm.ws.tcpchannel.internal.TCPChannel                    I CWWKO0220I: TCP Channel defaultHttpEndpoint-ssl has stopped listening for requests on host *  (IPv6) port 9443.
[INFO] [2024-05-30T12:15:03.740+0000] 00000157 id=         com.ibm.ws.tcpchannel.internal.TCPChannel                    I CWWKO0220I: TCP Channel defaultHttpEndpoint has stopped listening for requests on host *  (IPv6) port 9080.
[INFO] [2024-05-30T12:15:03.740+0000] 00000157 id=         com.ibm.ws.http.internal.VirtualHostImpl                     A CWWKT0017I: Web application removed (default_host): http://e8e514c8928a:9080/api/docs/spec/
[INFO] [2024-05-30T12:15:03.741+0000] 00000157 id=         com.ibm.ws.http.internal.VirtualHostImpl                     A CWWKT0017I: Web application removed (default_host): http://e8e514c8928a:9080/jwt/
[INFO] [2024-05-30T12:15:03.741+0000] 00000157 id=         com.ibm.ws.http.internal.VirtualHostImpl                     A CWWKT0017I: Web application removed (default_host): http://e8e514c8928a:9080/api/docs/
[INFO] [2024-05-30T12:15:03.741+0000] 00000157 id=         com.ibm.ws.http.internal.VirtualHostImpl                     A CWWKT0017I: Web application removed (default_host): http://e8e514c8928a:9080/
[INFO] [2024-05-30T12:15:04.745+0000] 000001d4 id=         com.ibm.ws.runtime.update.internal.RuntimeUpdateManagerImpl  I CWWKE1101I: Server quiesce complete.
[INFO] [2024-05-30T12:15:04.779+0000] 00000146 id=         com.ibm.ws.webcontainer.servlet.ServletWrapper               I doDestroy SRVE0253I: [app] [/] [App]: Destroy successful.
[INFO] [2024-05-30T12:15:04.786+0000] 000001a2 id=         ...
[INFO] ! InterruptedException: sleep interrupted ...
[INFO] [2024-05-30T12:15:04.791+0000] 000001a2 id=                                                                      R  Exception in thread "Thread-47"
[INFO] [2024-05-30T12:15:04.791+0000] 000001a2 id=                                                                      R  java.util.concurrent.RejectedExecutionException: CWWKE1202E: A task cannot be submitted because the executor concurrencyPolicy[defaultConcurrencyPolicy] has been shut down.
[INFO] [2024-05-30T12:15:04.791+0000] 000001a2 id=                                                                      R       at com.ibm.ws.threading.internal.PolicyExecutorImpl.enqueue(PolicyExecutorImpl.java:611)
[INFO] [2024-05-30T12:15:04.791+0000] 000001a2 id=                                                                      R       at com.ibm.ws.threading.internal.PolicyExecutorImpl.submit(PolicyExecutorImpl.java:1422)
[INFO] [2024-05-30T12:15:04.791+0000] 000001a2 id=                                                                      R       at com.ibm.ws.concurrent.internal.ManagedCompletableFuture$FutureRefExecutor.execute(ManagedCompletableFuture.java:199)
[INFO] [2024-05-30T12:15:04.791+0000] 000001a2 id=                                                                      R       at com.ibm.ws.concurrent.internal.ManagedCompletableFuture.runAsync(ManagedCompletableFuture.java:472)
[INFO] [2024-05-30T12:15:04.791+0000] 000001a2 id=                                                                      R       at com.ibm.ws.concurrent.internal.ManagedExecutorServiceImpl.runAsync(ManagedExecutorServiceImpl.java:677)
[INFO] [2024-05-30T12:15:04.791+0000] 000001a2 id=                                                                      R       at ...
[INFO] [2024-05-30T12:15:04.791+0000] 000001a2 id=                                                                      R       at java.base/java.lang.Thread.run(Thread.java:840)
[INFO] [2024-05-30T12:15:04.796+0000] 000001a3 id=         ...
[INFO] ! RuntimeException: ...
[INFO] [2024-05-30T12:15:04.815+0000] 00000146 id=         com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0009I: The application app has stopped successfully.
[INFO] [2024-05-30T12:15:04.832+0000] 000001d4 id=         com.ibm.ws.webcontainer.servlet.ServletWrapper               I doDestroy SRVE0253I: [io.openliberty.microprofile.openapi.2.0.internal.servlet.jakarta] [/api/docs/spec] [ApplicationServlet]: Destroy successful.
[INFO] [2024-05-30T12:15:04.923+0000] 000001d4 id=         com.ibm.tx.jta.impl.FailureScopeController                   A WTRN0105I: The transaction service has shutdown successfully with no transactions requiring recovery.
[INFO] [2024-05-30T12:15:04.993+0000] 000001d4 id=         rty.security.mp.jwt.v21.config.impl.MpConfigProxyServiceImpl I CWWKS5788I: The MicroProfile JWT version 2.1 mpConfigProxy was deactivated successfully.
[INFO] [2024-05-30T12:15:04.996+0000] 000001d4 id=         com.ibm.ws.security.mp.jwt.impl.MicroProfileJwtConfigImpl    I CWWKS5502I: The MicroProfile JWT configuration [defaultMpJwt] was successfully deactivated.
[INFO] [2024-05-30T12:15:04.996+0000] 000001d4 id=         com.ibm.ws.security.mp.jwt.impl.MicroProfileJwtServiceImpl   I CWWKS5502I: The MicroProfile JWT configuration [MicroProfileJwtService] was successfully deactivated.
[INFO] [2024-05-30T12:15:05.095+0000] 000001d4 id=         ibm.ws.security.authentication.internal.jaas.JAASServiceImpl I CWWKS1124I: The collective authentication plugin with class name NullCollectiveAuthenticationPlugin has been deactivated.
[INFO] [2024-05-30T12:15:05.099+0000] 000001d4 id=         com.ibm.ws.security.ready.internal.SecurityReadyServiceImpl  I CWWKS0009I: The security service has stopped.
[INFO] [2024-05-30T12:15:05.358+0000] 00000001 id=         com.ibm.ws.kernel.launch.internal.FrameworkManager           A CWWKE0036I: The server defaultServer stopped after 2 hours, 41.764 seconds.
[INFO] Server defaultServer stopped.
scottkurz commented 4 months ago

OK, so looking at this last log, you have what looks like a successful app update:

[INFO] [2024-05-30T12:09:53.669+0000] 0000013f id= com.ibm.ws.app.manager.AppMessageHelper A CWWKZ0003I: The application app updated in 6.314 seconds.

and then, 6 minutes later, we see the server stopping:

[INFO] java.nio.file.NoSuchFileException: /app/src/test/java/.../TestUtils.java~ [INFO] ------------------------------------------------------------------------ [INFO] BUILD SUCCESS [INFO] ------------------------------------------------------------------------ [INFO] Total time: 02:00 h [INFO] Finished at: 2024-05-30T12:15:03Z [INFO] ------------------------------------------------------------------------ [INFO] CWWKM2001I: Invoke command is [/app/target/liberty/wlp/bin/server, stop, defaultServer]. [INFO] [INFO] Stopping server defaultServer. [INFO] [2024-05-30T12:15:03.728+0000] 00000018 id= com.ibm.ws.kernel.launch.internal.ServerCommandListener A CWWKE0055I: Server shutdown requested on Thursday, May 30, 2024 at 12:15 PM. The server defaultServer is shutting down.

So it looks like the problem is that there was a change that cause dev mode to exit. Since dev mode registers a ShutdownHook which stops the server upon exit, this stopped the server as well.

So the root cause would seem to be the problem that "crashed" dev mode. Because of this I'm going to transfer back to the liberty-maven-plugin repo. (Sorry for the back-and-forth here).

scottkurz commented 4 months ago

So @inad9300 it looks like the server is stopping because dev mode has exited. I'm guessing it "crashed" because of some unexpected error/event that it couldn't handle.

Can you confirm that dev mode too exits when this issue happens?

Does this log message suggest anything to you?

[INFO] java.nio.file.NoSuchFileException: /app/src/test/java/.../TestUtils.java~

Assuming the understanding so far is correct, we could probably see what is going on more running with debug output (mvn -X) but that's likely not something you're going to want to run with most of the time waiting for this to happen.

Will wait for your response to consider what the next step might be.

inad9300 commented 4 months ago

Can you confirm that dev mode too exits when this issue happens?

Indeed, everything exits, and I have to rerun mvn liberty:dev.

Does this log message suggest anything to you?

It does, I should have mentioned – TestUtils has been one of my test files for a long time and never ceased to exist, but I was modifying it around the time the shutdown occurred. (At the same time, it's worth mentioning that it is the first time I see such a message, I never have before when the server crashes.)

Azquelt commented 4 months ago

TestUtils.java~ looks like a backup file that some editors create while editing a file.

For example, when I save a file named file on my machine with vim, it will rename the existing file to file~, write the updated contents to file and then delete file~.

I think the idea is to ensure that the old file contents are still available if the editor crashes while writing the new file contents but I wonder if having that short-lived TestUtils.java~ file is tripping up the file change detection in dev mode?

scottkurz commented 3 months ago

OK, we're getting somewhere. Thanks for confirming.

Looking at the issue history, we actually added a filter in the past for excluding file patterns from dev mode: https://github.com/OpenLiberty/ci.common/pull/89/files. (it's fixed in the common library used by both the Liberty Maven & Gradle plugins).

It'd seem we could try updating this filter adding the ~ char at the end to see if that helps.

Unfortunately I don't think this is configurable, but rather hard-coded.

scottkurz commented 3 months ago

Actually I guess it's more complicated than my last comment, since this code is already ignoring files that end with ~.

scottkurz commented 3 months ago

@inad9300 what version of the liberty-maven-plugin have you been using? Apologies if you mentioned already but I'm not seeing it now.

inad9300 commented 3 months ago

I don't think I did, sorry. It's 3.10.2.

scottkurz commented 3 months ago

Hi @inad9300 still trying to think of how to make progress here, since I've been unable to recreate.

I'm wondering what OS you're running on?

As mentioned here, we have encountered problems on Linux with "devc" when using an editor (like 'vi') which does a delete and copy instead of updating the file in-place.

I can't think of why this would be a problem in regular 'dev' mode, but I wonder, if it would be convenient, if it would be worth running with set backupcopy=yes (if you are even using 'vi'). If you are encountering this frequently enough that you would probably notice a difference if this option were to improve things, that would be interesting.

Besides that another thing we might be able to do is to trigger some sort of thread dump from the NoSuchFileException. I'm not sure how sensitive this application is, since that would likely effect how much detail you'd be willing to share in public. (Or, if you have a support contract then you could share sensitive info through those channels).

If it seems like it might be something you'd be willing to do I can try to come up with a suggestion. Hopefully you would be willing too to use an Open J9-based JDKs which I'm more familiar with for this sort of thing.

inad9300 commented 3 months ago

Thanks for your persistence, despite how little there is to pull from. As an update, I experienced the problem again 2 or 3 times since my last message. Here are some more details about my setup, in case they help:

scottkurz commented 3 months ago

Thanks for the additional info.

So if we were able to come up with a strategy using dump agents to collect say something like the Open J9 javadump, would you be willing/able to run with that JDK and share that publicly? (Or would you be able to open a support case with IBM and share privately?)

inad9300 commented 3 months ago

Sorry for dodging your question earlier. Hmm... :thinking: No, I don't think so. We'll have to come up with an alternative way to debug this, sorry.

scottkurz commented 2 months ago

OK, a couple more questions:

  1. Have you detected any kind of pattern where editing certain kinds of files led to this error? E.g. was it always TestUtils? Always test classes? Always Java parts, etc?
  2. Can you describe your project setup a bit? Is it single-module or multi-module? If the latter, what module does this TestUtils class live within (is it the module with the Liberty server config or something else, like a "utility" JAR module, say)?

Thanks

inad9300 commented 2 months ago
  1. No, I have not. It happens in different contexts every time, I would say.
  2. It is a single module, where TestUtils lives. We do have a Git submodule which happens to be another Java project, though this is likely not relevant.
scottkurz commented 2 months ago

Hmm... you might try to run with mvn -X liberty:dev and at least see if it slows you down noticeably. If it isn't too slow, maybe you could try running with it regularly until you recreate the issue? At that point, even if you aren't willing to share the entire log maybe you could share enough of an excerpt to suggest the next step here.

If you do decide to try this, please remember to redirect the log to a different directory outside the current project, or else dev mode will watch and react to the log changes! E.g. something like mvn -X liberty:dev | tee ../mvn.log

inad9300 commented 2 weeks ago

I have been trying to use -X (formerly -Twitter :see_no_evil:) a lot for the past months, but I was not lucky to see the issue when using that setting. I have, again, seen it a few times since our last exchange, but always without -X (it really is verbose and slows things down, so I have been turning it on and off, I'd guess with a 50-50 balance).

scottkurz commented 2 weeks ago

I have been trying to use -X (formerly -Twitter 🙈) a lot for the past months,

Thanks for the update. One doesn't see a lot of humor in Maven plugin issue comments, so I tip my hat 👏 for that 😃 .

Yes, that's definitely a blunt instrument so not surprised it changes the timing and is hard to tolerate too often.

Will keep this open and see if we can think of anything.