Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Dev mode runs ITs exercising Health Check endpoints before they are available #766

Open
scottkurz opened this issue Apr 3, 2020 · 4 comments

Comments

@scottkurz
Copy link
Member

Let me note right upfront that I haven't proven that I'm seeing what I described in the issue title.

However, when I look at: appsody/stacks#724, which I've recreated but without a complete set of logs..... it seems like, when you run with -DhotTests=true then you can get failures (404 and others).

I assume what's happening is that the thing dev mode is watching to indicate it's ready to run the tests says the app has been started although these endpoints aren't available. yet.

@scottkurz
Copy link
Member Author

In a normal app start, it looks like the health endpoints start first:

[�[1;34mINFO�[m] [AUDIT ] CWWKT0016I: Web application available (default_host): http://host.docker.internal:9080/health/
[�[1;34mINFO�[m] [AUDIT ] CWWKT0016I: Web application available (default_host): http://host.docker.internal:9080/metrics/
[�[1;34mINFO�[m] [AUDIT ] CWWKT0016I: Web application available (default_host): http://host.docker.internal:9080/ibm/api/
[�[1;34mINFO�[m] [AUDIT ] CWWKT0016I: Web application available (default_host): http://host.docker.internal:9080/
[�[1;34mINFO�[m] [AUDIT ] CWWKZ0001I: Application starter-app started in 8.847 seconds.

so something seems to be going wrong here.

@NottyCode
Copy link
Member

We recently changed Liberty so the ports do not open until much later in startup, essentially just before the server started message. So if the logs are being monitored for the app started message and then a connection is attempted it would fail because the port would not be open. I'm not sure if that is relevant here, but maybe it is.

@ericglau
Copy link
Contributor

Reproduced this in the given stack (but without skipping tests), logs are below. Looks like a timing issue. The sequence of events in this case are:

  1. Server started but app has not started yet
  2. Dev mode recompiles the app (due to issue Dev mode recompiles upon startup #699)
  3. Dev mode waits for app started or app updated message before running tests
  4. App finished first startup (without the latest recompile) and the app started message appears
  5. Dev mode detects the app started message, so runs tests
  6. Liberty detects the app has changed, so redeploys the app. This may happen while the tests are running, causing them to fail.
[Container] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://ac6cf19fcf7c:9080/metrics/
[Container] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://ac6cf19fcf7c:9080/openapi/ui/
[Container] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://ac6cf19fcf7c:9080/ibm/api/
[Container] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://ac6cf19fcf7c:9080/health/
[Container] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://ac6cf19fcf7c:9080/jwt/
[Container] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://ac6cf19fcf7c:9080/openapi/
[Container] [INFO] [AUDIT   ] CWPKI0803A: SSL certificate created in 3.306 seconds. SSL key file: /opt/ol/wlp/usr/servers/defaultServer/resources/security/key.p12
[Container] [INFO] [AUDIT   ] CWWKZ0022W: Application starter-app has not started in 30.002 seconds.
[Container] [INFO] [AUDIT   ] CWWKF0012I: The server installed the following features: [appSecurity-2.0, cdi-2.0, concurrent-1.0, distributedMap-1.0, jaxrs-2.1, jaxrsClient-2.1, jndi-1.0, json-1.0, jsonb-1.0, jsonp-1.1, jwt-1.0, microProfile-3.2, mpConfig-1.3, mpFaultTolerance-2.0, mpHealth-2.1, mpJwt-1.1, mpMetrics-2.2, mpOpenAPI-1.1, mpOpenTracing-1.3, mpRestClient-1.3, opentracing-1.3, servlet-4.0, ssl-1.0].
[Container] [INFO] [AUDIT   ] CWWKF0011I: The defaultServer server is ready to run a smarter planet. The defaultServer server started in 34.511 seconds.
[Container] [INFO] CWWKM2015I: Match number: 1 is [4/24/20 16:36:16:304 UTC] 0000002e com.ibm.ws.kernel.feature.internal.FeatureManager            A CWWKF0011I: The defaultServer server is ready to run a smarter planet. The defaultServer server started in 34.511 seconds..
[Container] [INFO] Tests will run automatically when changes are detected.
[Container] [INFO] Source compilation was successful.
[Container] [INFO] Running unit tests...
[Container] [INFO] Tests compilation was successful.
[Container] [INFO] Unit tests finished.
[Container] [INFO] Changes were detected while tests were running. Restarting tests.
[Container] [INFO] Running unit tests...
[Container] [INFO] Unit tests finished.
[Container] [INFO] Waiting up to 30 seconds for the application to start up...
[Container] [INFO] CWWKM2010I: Searching for CWWKZ0001I.* in /opt/ol/wlp/usr/servers/defaultServer/logs/messages.log. This search will timeout after 30 seconds.
[Container] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://ac6cf19fcf7c:9080/
[Container] [INFO] [AUDIT   ] CWWKZ0001I: Application starter-app started in 46.161 seconds.
[Container] [INFO] CWWKM2015I: Match number: 1 is [4/24/20 16:36:32:358 UTC] 00000033 com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0001I: Application starter-app started in 46.161 seconds..
[Container] [INFO] Running integration tests...
[Container] [INFO] [AUDIT   ] CWWKT0017I: Web application removed (default_host): http://ac6cf19fcf7c:9080/
[Container] [INFO] init succeeded
[Container] [INFO] local host: false
[Container] [INFO] 
[Container] [INFO] -------------------------------------------------------
[Container] [INFO]  T E S T S
[Container] [INFO] -------------------------------------------------------
[Container] [INFO] Running it.dev.appsody.starter.HealthEndpointTest
[Container] [INFO] [AUDIT   ] CWWKZ0009I: The application starter-app has stopped successfully.
[Container] [INFO] [ERROR   ] CWMH0050E: The class dev.appsody.starter.health.StarterLivenessCheck$Proxy$_$$_WeldClientProxy HealthCheck method in the starter-app application from the starter-app.war module threw exception org.jboss.weld.exceptions.IllegalStateException: WELD-000229: Contextual reference of Managed Bean [class dev.appsody.starter.health.StarterLivenessCheck] with qualifiers [@Liveness @Any] is not valid after container starter-app shutdown with the following message: org.jboss.weld.exceptions.IllegalStateException: WELD-000229: Contextual reference of Managed Bean [class dev.appsody.starter.health.StarterLivenessCheck] with qualifiers [@Liveness @Any] is not valid after container starter-app shutdown
[Container] [ERROR] Tests run: 2, Failures: 1, Errors: 1, Skipped: 0, Time elapsed: 3.559 s <<< FAILURE! - in it.dev.appsody.starter.HealthEndpointTest
[Container] [ERROR] testLivenessEndpoint  Time elapsed: 3.372 s  <<< FAILURE!
[Container] org.opentest4j.AssertionFailedError: Incorrect response code from http://localhost:9080/health/live ==> expected: <200> but was: <500>
[Container] 	at it.dev.appsody.starter.HealthEndpointTest.assertResponse(HealthEndpointTest.java:96)
[Container] 	at it.dev.appsody.starter.HealthEndpointTest.checkHealthEndpoint(HealthEndpointTest.java:59)
[Container] 	at it.dev.appsody.starter.HealthEndpointTest.testLivenessEndpoint(HealthEndpointTest.java:46)
[Container] 
[Container] [ERROR] testReadinessEndpoint  Time elapsed: 0.154 s  <<< ERROR!
[Container] java.lang.IndexOutOfBoundsException: Index: 0
[Container] 	at it.dev.appsody.starter.HealthEndpointTest.checkHealthEndpoint(HealthEndpointTest.java:67)
[Container] 	at it.dev.appsody.starter.HealthEndpointTest.testReadinessEndpoint(HealthEndpointTest.java:52)
[Container] 
[Container] [INFO] 
[Container] [INFO] Results:
[Container] [INFO] 
[Container] [ERROR] Failures: 
[Container] [ERROR]   HealthEndpointTest.testLivenessEndpoint:46->checkHealthEndpoint:59->assertResponse:96 Incorrect response code from http://localhost:9080/health/live ==> expected: <200> but was: <500>
[Container] [ERROR] Errors: 
[Container] [ERROR]   HealthEndpointTest.testReadinessEndpoint:52->checkHealthEndpoint:67 ? IndexOutOfBounds
[Container] [INFO] 
[Container] [ERROR] Tests run: 2, Failures: 1, Errors: 1, Skipped: 0
[Container] [INFO] 
[Container] [ERROR] Integration tests failed: There are test failures.
[Container] 
[Container] Please refer to /project/user-app/target/test-reports/it for the individual test results.
[Container] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[Container] [INFO] [AUDIT   ] CWWKZ0022W: Application starter-app has not started in 30.001 seconds.
[Container] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://ac6cf19fcf7c:9080/
[Container] [INFO] [AUDIT   ] CWWKZ0003I: The application starter-app updated in 42.100 seconds.
[Container] [INFO] init succeeded
[Container] [INFO] local host: false

@rzgry
Copy link

rzgry commented Apr 24, 2020

I was able to reproduce something similar when not using appsody. Just running dev mode with the hot tests enabled with the demo-devmode project.

mvn liberty:dev -DhotTests=true
[INFO] Scanning for projects...
[INFO]
[INFO] -----------------< io.openliberty:demo-devmode-maven >------------------
[INFO] Building demo-devmode-maven 1.0-SNAPSHOT
[INFO] --------------------------------[ war ]---------------------------------
[INFO]
[INFO] --- liberty-maven-plugin:3.2:dev (default-cli) @ demo-devmode-maven ---
[INFO] CWWKM2102I: Using artifact based assembly archive : com.ibm.websphere.appserver.runtime:wlp-kernel:null:20.0.0.4:zip.
[INFO] CWWKM2102I: Using installDirectory : /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp.
[INFO] CWWKM2102I: Using serverName : defaultServer.
[INFO] CWWKM2102I: Using serverDirectory : /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer.
[INFO] Running maven-compiler-plugin:compile
[INFO] Nothing to compile - all classes are up to date
[INFO] Running maven-resources-plugin:resources
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /Users/rzegray/Developer/github.com/openliberty/demo-devmode/src/main/resources
[INFO] Running maven-compiler-plugin:testCompile
[INFO] Nothing to compile - all classes are up to date
[INFO] Running maven-resources-plugin:testResources
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /Users/rzegray/Developer/github.com/openliberty/demo-devmode/src/test/resources
[INFO] Running liberty:create
[INFO] CWWKM2102I: Using artifact based assembly archive : com.ibm.websphere.appserver.runtime:wlp-kernel:null:20.0.0.4:zip.
[INFO] CWWKM2102I: Using installDirectory : /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp.
[INFO] CWWKM2102I: Using serverName : defaultServer.
[INFO] CWWKM2102I: Using serverDirectory : /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer.
[INFO] CWWKM2185I: The liberty-maven-plugin configuration parameter "appsDirectory" value defaults to "apps".
[INFO] CWWKM2112I: Re-using previously installed assembly.
[INFO] Copying 2 files to /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer
[INFO] CWWKM2144I: Update server configuration file server.xml from /Users/rzegray/Developer/github.com/openliberty/demo-devmode/src/main/liberty/config/server.xml.
[INFO] CWWKM2144I: Update server configuration file bootstrap.properties from /Users/rzegray/Developer/github.com/openliberty/demo-devmode/src/main/liberty/config/bootstrap.properties.
[INFO] Running liberty:install-feature
[INFO] CWWKM2102I: Using artifact based assembly archive : com.ibm.websphere.appserver.runtime:wlp-kernel:null:20.0.0.4:zip.
[INFO] CWWKM2102I: Using installDirectory : /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp.
[INFO] CWWKM2102I: Using serverName : defaultServer.
[INFO] CWWKM2102I: Using serverDirectory : /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer.
[INFO] Installing features: [mpconfig-1.3, cdi-2.0, jsonp-1.1, mpmetrics-2.0, mphealth-2.1, jaxrs-2.1]

[INFO] CWWKF1250I: The following assets already exist: [cdi-2.0, jaxrs-2.1, jsonp-1.1, mpConfig-1.3, mpHealth-2.1, mpMetrics-2.0]. They will not be reinstalled. To modify an existing feature, you must manually uninstall it first.
[INFO] The features are already installed, so no action is needed.
[INFO] Running liberty:deploy
[INFO] CWWKM2102I: Using artifact based assembly archive : com.ibm.websphere.appserver.runtime:wlp-kernel:null:20.0.0.4:zip.
[INFO] CWWKM2102I: Using installDirectory : /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp.
[INFO] CWWKM2102I: Using serverName : defaultServer.
[INFO] CWWKM2102I: Using serverDirectory : /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer.
[INFO] Copying 2 files to /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer
[INFO] CWWKM2144I: Update server configuration file server.xml from /Users/rzegray/Developer/github.com/openliberty/demo-devmode/src/main/liberty/config/server.xml.
[INFO] CWWKM2144I: Update server configuration file bootstrap.properties from /Users/rzegray/Developer/github.com/openliberty/demo-devmode/src/main/liberty/config/bootstrap.properties.
[INFO] CWWKM2185I: The liberty-maven-plugin configuration parameter "appsDirectory" value defaults to "apps".
[INFO] CWWKM2160I: Installing application demo-devmode-maven.war.xml.
[INFO] Copying 2 files to /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer
[INFO] CWWKM2144I: Update server configuration file server.xml from /Users/rzegray/Developer/github.com/openliberty/demo-devmode/src/main/liberty/config/server.xml.
[INFO] CWWKM2144I: Update server configuration file bootstrap.properties from /Users/rzegray/Developer/github.com/openliberty/demo-devmode/src/main/liberty/config/bootstrap.properties.
[INFO] CWWKM2001I: Invoke command is [/Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/bin/server, debug, defaultServer].
[INFO]
[INFO] Listening for transport dt_socket at address: 7777
[INFO] Launching defaultServer (WebSphere Application Server 20.0.0.4/wlp-1.0.39.cl200420200401-1714) on Eclipse OpenJ9 VM, version 11.0.6+10 (en_CA)
[INFO] [AUDIT   ] CWWKE0001I: The server defaultServer has been launched.
[INFO] [AUDIT   ] CWWKE0100I: This product is licensed for development, and limited production use. The full license terms can be viewed here: https://public.dhe.ibm.com/ibmdl/export/pub/software/websphere/wasdev/license/base_ilan/ilan/20.0.0.4/lafiles/en.html
[INFO] [AUDIT   ] CWWKG0093A: Processing configuration drop-ins resource: /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer/configDropins/overrides/liberty-plugin-variable-config.xml
[INFO] [AUDIT   ] CWWKZ0058I: Monitoring dropins for applications.
[INFO] [AUDIT   ] CWPKI0820A: The default keystore has been created using the 'keystore_password' environment variable.
[INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://192.168.1.16:9080/metrics/
[INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://192.168.1.16:9080/ibm/api/
[INFO] CWWKM2010I: Searching for CWWKF0011I: in /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer/logs/messages.log. This search will timeout after 30 seconds.
[INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://192.168.1.16:9080/health/
[INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://192.168.1.16:9080/
[INFO] [AUDIT   ] CWWKZ0001I: Application demo-devmode-maven started in 2.061 seconds.
[INFO] [AUDIT   ] CWWKF0012I: The server installed the following features: [cdi-2.0, distributedMap-1.0, jaxrs-2.1, jaxrsClient-2.1, jndi-1.0, json-1.0, jsonp-1.1, mpConfig-1.3, mpHealth-2.1, mpMetrics-2.0, servlet-4.0, ssl-1.0].
[INFO] [AUDIT   ] CWWKF0011I: The defaultServer server is ready to run a smarter planet. The defaultServer server started in 11.590 seconds.
[INFO] CWWKM2015I: Match number: 1 is [2020-04-24, 14:39:23:183 EDT] 00000034 com.ibm.ws.kernel.feature.internal.FeatureManager            A CWWKF0011I: The defaultServer server is ready to run a smarter planet. The defaultServer server started in 11.590 seconds..
[INFO] Running unit tests...
[INFO] Unit tests finished.
[INFO] Waiting up to 30 seconds for the application to start up...
[INFO] CWWKM2010I: Searching for CWWKZ0001I.* in /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer/logs/messages.log. This search will timeout after 30 seconds.
[INFO] CWWKM2015I: Match number: 1 is [2020-04-24, 14:39:23:091 EDT] 00000035 com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0001I: Application demo-devmode-maven started in 2.061 seconds..
[INFO] Running integration tests...
[INFO] Source compilation was successful.
[INFO]
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Tests compilation was successful.
[INFO] Running it.io.openliberty.sample.PropertiesEndpointIT
[INFO] [AUDIT   ] CWWKT0017I: Web application removed (default_host): http://192.168.1.16:9080/
[INFO] [AUDIT   ] CWWKZ0009I: The application demo-devmode-maven has stopped successfully.
[INFO] [ERROR   ] SRVE0777E: Exception thrown by application class 'org.apache.cxf.transport.http.AbstractHTTPDestination.invoke:274'
[INFO] java.lang.NullPointerException
[INFO] 	at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:274)
[INFO] 	at [internal classes]
[INFO]
[INFO] [ERROR   ] SRVE0315E: An exception occurred: java.lang.Throwable: java.lang.NullPointerException
[INFO] 	at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:5079)
[INFO] 	at [internal classes]
[INFO] Caused by: java.lang.NullPointerException
[INFO] 	at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:274)
[INFO] 	... 1 more
[INFO]
[INFO] [ERROR   ] SRVE0095I: Servlet has become temporarily unavailable for service: /system/properties
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 1.211 s <<< FAILURE! - in it.io.openliberty.sample.PropertiesEndpointIT
[ERROR] testGetProperties(it.io.openliberty.sample.PropertiesEndpointIT)  Time elapsed: 1.187 s  <<< FAILURE!
java.lang.AssertionError: Incorrect response code from http://192.168.1.16:9080/ expected:<200> but was:<503>
	at it.io.openliberty.sample.PropertiesEndpointIT.testGetProperties(PropertiesEndpointIT.java:45)

[INFO] Running it.io.openliberty.sample.HealthEndpointIT
[INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://192.168.1.16:9080/
[INFO] [AUDIT   ] CWWKZ0003I: The application demo-devmode-maven updated in 0.517 seconds.
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.967 s - in it.io.openliberty.sample.HealthEndpointIT
[INFO]
[INFO] Results:
[INFO]
[ERROR] Failures:
[ERROR]   PropertiesEndpointIT.testGetProperties:45 Incorrect response code from http://192.168.1.16:9080/ expected:<200> but was:<503>
[INFO]
[ERROR] Tests run: 4, Failures: 1, Errors: 0, Skipped: 0
[INFO]
[ERROR] Integration tests failed: There are test failures.

Please refer to /Users/rzegray/Developer/github.com/openliberty/demo-devmode/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] Tests will run automatically when changes are detected. You can also press the Enter key to run tests on demand.
[INFO] Running unit tests...
[INFO] Unit tests finished.
[INFO] CWWKM2010I: Searching for CWWKZ0003I.*demo-devmode-maven in /Users/rzegray/Developer/github.com/openliberty/demo-devmode/target/liberty/wlp/usr/servers/defaultServer/logs/messages.log. This search will timeout after 30 seconds.
[INFO] CWWKM2015I: Match number: 1 is [2020-04-24, 14:39:26:357 EDT] 0000003c com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0003I: The application demo-devmode-maven updated in 0.517 seconds..
[INFO] Running integration tests...
[INFO]
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running it.io.openliberty.sample.PropertiesEndpointIT
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.151 s - in it.io.openliberty.sample.PropertiesEndpointIT
[INFO] Running it.io.openliberty.sample.HealthEndpointIT
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.098 s - in it.io.openliberty.sample.HealthEndpointIT
[INFO]
[INFO] Results:
[INFO]
[INFO] Tests run: 4, Failures: 0, Errors: 0, Skipped: 0
[INFO]
[INFO] Integration tests finished.
[INFO] Tests will run automatically when changes are detected. You can also press the Enter key to run tests on demand.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Development

No branches or pull requests

5 participants