ci.maven icon indicating copy to clipboard operation
ci.maven copied to clipboard

Published 20 hours ago • verified publisher icon OpenLiberty

Dev integration test failure - DevTest.resourceFileChangeTest

Open kathrynkodama opened this issue 2 years ago • 0 comments

DevTest.resourceFileChangeTest intermittently fails on Ubuntu through GitHub actions:

Running net.wasdev.wlp.test.dev.it.DevTest
[INFO] Tests run: 11, Failures: 1, Errors: 0, Skipped: 1, Time elapsed: 96.757 sec <<< FAILURE! - in net.wasdev.wlp.test.dev.it.DevTest
[INFO] resourceFileChangeTest(net.wasdev.wlp.test.dev.it.DevTest)  Time elapsed: 16.93 sec  <<< FAILURE!
[INFO] java.lang.AssertionError: 
[INFO] Last 100 lines of log at /home/runner/work/ci.maven/ci.maven/liberty-maven-plugin/target/it/dev-it/target/../resources/basic-dev-project/logFile.txt:
[INFO] ===================== START =======================
[INFO] [INFO] CWWKM2185I: The liberty-maven-plugin configuration parameter "appsDirectory" value defaults to "dropins".
[INFO] [INFO] CWWKM2160I: Installing application dev-sample-proj-1.0-SNAPSHOT.war.xml.
[INFO] [INFO] CWWKM2001I: Invoke command is [/tmp/temp3019383149563133646/target/liberty/wlp/bin/server, debug, defaultServer].
[INFO] [INFO] 
[INFO] [INFO] Listening for transport dt_socket at address: 7777
[INFO] [INFO] Launching defaultServer (Open Liberty 22.0.0.3/wlp-1.0.62.cl220320220302-1100) on OpenJDK 64-Bit Server VM, version 1.8.0_332-b09 (en)
[INFO] [INFO] [AUDIT   ] CWWKE0001I: The server defaultServer has been launched.
[INFO] [INFO] [AUDIT   ] CWWKG0028A: Processing included configuration resource: /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/extraFeatures.xml
[INFO] [INFO] [AUDIT   ] CWWKG0093A: Processing configuration drop-ins resource: /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/configDropins/overrides/generated-features.xml
[INFO] [INFO] CWWKM2010I: Searching for CWWKF0011I: in /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/logs/messages.log. This search will timeout after 90 seconds.
[INFO] [INFO] [AUDIT   ] CWWKZ0058I: Monitoring dropins for applications.
[INFO] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://fv-az87-48.4kivlwiotu5upots2on2x2i0sd.bx.internal.cloudapp.net:9080/dev-sample-proj-1.0-SNAPSHOT/
[INFO] [INFO] [AUDIT   ] CWWKZ0001I: Application dev-sample-proj-1.0-SNAPSHOT started in 0.896 seconds.
[INFO] [INFO] [AUDIT   ] CWWKF0012I: The server installed the following features: [jaxrs-2.1, jaxrsClient-2.1, jsonp-1.1, servlet-4.0].
[INFO] [INFO] [AUDIT   ] CWWKF0011I: The defaultServer server is ready to run a smarter planet. The defaultServer server started in 2.781 seconds.
[INFO] [INFO] CWWKM2015I: Match number: 1 is {"type":"liberty_message","host":"fv-az87-48.4kivlwiotu5upots2on2x2i0sd.bx.internal.cloudapp.net","ibm_userDir":"\/tmp\/temp3019383149563133646\/target\/liberty\/wlp\/usr\/","ibm_serverName":"defaultServer","message":"CWWKF0011I: The defaultServer server is ready to run a smarter planet. The defaultServer server started in 2.781 seconds.","ibm_threadId":"0000001e","ibm_datetime":"2022-05-25T13:20:28.198+0000","ibm_messageId":"CWWKF0011I","module":"com.ibm.ws.kernel.feature.internal.FeatureManager","loglevel":"AUDIT","ibm_sequence":"1653484828198_0000000000015"}.
[INFO] [INFO] The server has been restarted.
[INFO] [INFO] ************************************************************************
[INFO] [INFO] *    Liberty is running in dev mode.
[INFO] [INFO] *        Automatic generation of features: [ On ]
[INFO] [INFO] *        To see the help menu for available actions, type 'h' and press Enter.
[INFO] [INFO] *        To stop the server and quit dev mode, press Ctrl-C or type 'q' and press Enter.
[INFO] [INFO] *        
[INFO] [INFO] *    Liberty server port information:
[INFO] [INFO] *        Liberty debug port: [ 7777 ]
[INFO] [INFO] ************************************************************************
[INFO] [INFO] Source compilation was successful.
[INFO] [INFO] Running liberty:generate-features
[INFO] [INFO] [AUDIT   ] CWWKT0017I: Web application removed (default_host): http://fv-az87-48.4kivlwiotu5upots2on2x2i0sd.bx.internal.cloudapp.net:9080/dev-sample-proj-1.0-SNAPSHOT/
[INFO] [INFO] [AUDIT   ] CWWKZ0009I: The application dev-sample-proj-1.0-SNAPSHOT has stopped successfully.
[INFO] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://fv-az87-48.4kivlwiotu5upots2on2x2i0sd.bx.internal.cloudapp.net:9080/dev-sample-proj-1.0-SNAPSHOT/
[INFO] [INFO] [AUDIT   ] CWWKZ0003I: The application dev-sample-proj-1.0-SNAPSHOT updated in 0.431 seconds.
[INFO] [INFO] Generated the following features: [servlet-4.0, batch-1.0]
[INFO] [INFO] Copied file: /tmp/temp3019383149563133646/src/main/liberty/config/configDropins/overrides/generated-features.xml to: /tmp/tempConfig7580547478352462817/configDropins/overrides/generated-features.xml
[INFO] [INFO] Configuration features have been added: [batch-1.0]
[INFO] [INFO] Running liberty:install-feature
[INFO] [INFO] CWWKM2102I: Using artifact based assembly archive : io.openliberty:openliberty-kernel:null:22.0.0.3:zip.
[INFO] [INFO] CWWKM2102I: Using installDirectory : /tmp/temp3019383149563133646/target/liberty/wlp.
[INFO] [INFO] CWWKM2102I: Using serverName : defaultServer.
[INFO] [INFO] CWWKM2102I: Using serverDirectory : /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer.
[INFO] [INFO] Parsing the server file for features and includes: tempConfig7580547478352462817/server.xml
[INFO] [INFO] Parsing the server file for features and includes: tempConfig7580547478352462817/extraFeatures.xml
[INFO] [INFO] Parsing the server file for features and includes: tempConfig7580547478352462817/configDropins/overrides/generated-features.xml
[INFO] [INFO] Installing features: [servlet-4.0, mpRestClient-1.2, batch-1.0, cdi-2.0, jsonp-1.1, mpConfig-1.3, jaxrs-2.1]
[INFO] 
[INFO] [INFO] Product validation completed successfully.
[INFO] [INFO] The following features have been installed: servlet-3.1 batch-1.0 jdbc-4.1 
[INFO] [INFO] Copied file: /tmp/temp3019383149563133646/src/main/liberty/config/configDropins/overrides/generated-features.xml to: /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/configDropins/overrides/generated-features.xml
[INFO] [INFO] [AUDIT   ] CWWKG0016I: Starting server configuration update.
[INFO] [INFO] [AUDIT   ] CWWKG0028A: Processing included configuration resource: /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/extraFeatures.xml
[INFO] [INFO] [AUDIT   ] CWWKG0093A: Processing configuration drop-ins resource: /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/configDropins/overrides/generated-features.xml
[INFO] [INFO] [AUDIT   ] CWWKT0017I: Web application removed (default_host): http://fv-az87-48.4kivlwiotu5upots2on2x2i0sd.bx.internal.cloudapp.net:9080/dev-sample-proj-1.0-SNAPSHOT/
[INFO] [INFO] [AUDIT   ] CWWKZ0009I: The application dev-sample-proj-1.0-SNAPSHOT has stopped successfully.
[INFO] [INFO] Source compilation had errors.
[INFO] [INFO] Source compilation was successful.
[INFO] [INFO] Setting automatic generation of features to: [ Off ]
[INFO] [INFO] Setting automatic generation of features to: [ On ]
[INFO] [INFO] Running liberty:generate-features
[INFO] [INFO] [AUDIT   ] CWWKG0017I: The server configuration was successfully updated in 1.072 seconds.
[INFO] [INFO] [AUDIT   ] CWWKF0012I: The server installed the following features: [batch-1.0, jdbc-4.1, jndi-1.0].
[INFO] [INFO] [AUDIT   ] CWWKF0008I: Feature update completed in 1.071 seconds.
[INFO] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://fv-az87-48.4kivlwiotu5upots2on2x2i0sd.bx.internal.cloudapp.net:9080/dev-sample-proj-1.0-SNAPSHOT/
[INFO] [INFO] The java class /tmp/temp3019383149563133646/target/classes/com/demo/HelloBatch.class was deleted.
[INFO] [INFO] [AUDIT   ] CWWKZ0003I: The application dev-sample-proj-1.0-SNAPSHOT updated in 0.471 seconds.
[INFO] [INFO] Generated the following features: [servlet-4.0]
[INFO] [INFO] Copied file: /tmp/temp3019383149563133646/src/main/liberty/config/configDropins/overrides/generated-features.xml to: /tmp/tempConfig2945023462484637574/configDropins/overrides/generated-features.xml
[INFO] [INFO] Configuration features have been removed: [servlet-4.0, batch-1.0]
[INFO] [INFO] Copied file: /tmp/temp3019383149563133646/src/main/liberty/config/configDropins/overrides/generated-features.xml to: /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/configDropins/overrides/generated-features.xml
[INFO] [INFO] Running liberty:generate-features
[INFO] [INFO] Copied file: /tmp/temp3019383149563133646/src/main/liberty/config/configDropins/overrides/generated-features.xml to: /tmp/tempConfig5892387885192702731/configDropins/overrides/generated-features.xml
[INFO] [INFO] Configuration features have been added: [servlet-4.0]
[INFO] [INFO] Running liberty:install-feature
[INFO] [INFO] CWWKM2102I: Using artifact based assembly archive : io.openliberty:openliberty-kernel:null:22.0.0.3:zip.
[INFO] [INFO] CWWKM2102I: Using installDirectory : /tmp/temp3019383149563133646/target/liberty/wlp.
[INFO] [INFO] CWWKM2102I: Using serverName : defaultServer.
[INFO] [INFO] CWWKM2102I: Using serverDirectory : /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer.
[INFO] [INFO] Parsing the server file for features and includes: tempConfig5892387885192702731/server.xml
[INFO] [INFO] Parsing the server file for features and includes: tempConfig5892387885192702731/extraFeatures.xml
[INFO] [INFO] Parsing the server file for features and includes: tempConfig5892387885192702731/configDropins/overrides/generated-features.xml
[INFO] [INFO] Installing features: [servlet-4.0, mpRestClient-1.2, cdi-2.0, jsonp-1.1, mpConfig-1.3, jaxrs-2.1]
[INFO] [INFO] [AUDIT   ] CWWKT0017I: Web application removed (default_host): http://fv-az87-48.4kivlwiotu5upots2on2x2i0sd.bx.internal.cloudapp.net:9080/dev-sample-proj-1.0-SNAPSHOT/
[INFO] [INFO] [AUDIT   ] CWWKZ0009I: The application dev-sample-proj-1.0-SNAPSHOT has stopped successfully.
[INFO] [INFO] [AUDIT   ] CWWKG0016I: Starting server configuration update.
[INFO] [INFO] [AUDIT   ] CWWKG0028A: Processing included configuration resource: /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/extraFeatures.xml
[INFO] [INFO] [AUDIT   ] CWWKG0093A: Processing configuration drop-ins resource: /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/configDropins/overrides/generated-features.xml
[INFO] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://fv-az87-48.4kivlwiotu5upots2on2x2i0sd.bx.internal.cloudapp.net:9080/dev-sample-proj-1.0-SNAPSHOT/
[INFO] 
[INFO] [INFO] [ERROR   ] CWWKG0014E: The configuration parser detected an XML syntax error while parsing the root of the configuration and the referenced configuration documents. Error: Premature end of file. File: file:/tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/configDropins/overrides/generated-features.xml Line: 1 Column: 1
[INFO] [INFO] [AUDIT   ] CWWKZ0003I: The application dev-sample-proj-1.0-SNAPSHOT updated in 0.441 seconds.
[INFO] [INFO] [AUDIT   ] CWWKT0017I: Web application removed (default_host): http://fv-az87-48.4kivlwiotu5upots2on2x2i0sd.bx.internal.cloudapp.net:9080/dev-sample-proj-1.0-SNAPSHOT/
[INFO] [INFO] [AUDIT   ] CWWKZ0009I: The application dev-sample-proj-1.0-SNAPSHOT has stopped successfully.
[INFO] [INFO] [AUDIT   ] CWWKG0017I: The server configuration was successfully updated in 0.780 seconds.
[INFO] [INFO] [AUDIT   ] CWWKF0013I: The server removed the following features: [batch-1.0, jdbc-4.1, jndi-1.0].
[INFO] [INFO] [AUDIT   ] CWWKF0008I: Feature update completed in 0.492 seconds.
[INFO] [INFO] [AUDIT   ] CWWKT0016I: Web application available (default_host): http://fv-az87-48.4kivlwiotu5upots2on2x2i0sd.bx.internal.cloudapp.net:9080/dev-sample-proj-1.0-SNAPSHOT/
[INFO] [INFO] [AUDIT   ] CWWKZ0003I: The application dev-sample-proj-1.0-SNAPSHOT updated in 0.541 seconds.
[INFO] [INFO] Regenerated the following features: [servlet-4.0]
[INFO] [INFO] The features are already installed, so no action is needed.
[INFO] [INFO] Copied file: /tmp/temp3019383149563133646/src/main/liberty/config/configDropins/overrides/generated-features.xml to: /tmp/temp3019383149563133646/target/liberty/wlp/usr/servers/defaultServer/configDropins/overrides/generated-features.xml
[INFO] [INFO] Copied file: /tmp/temp3019383149563133646/src/main/resources/microprofile-config.properties to: /tmp/temp3019383149563133646/target/classes/microprofile-config.properties
[INFO] ====================== END ========================
[INFO] 
[INFO] 	at org.junit.Assert.fail(Assert.java:89)
[INFO] 	at org.junit.Assert.assertTrue(Assert.java:42)
[INFO] 	at net.wasdev.wlp.test.dev.it.DevTest.resourceFileChangeTest(DevTest.java:114)

Best guess is that a previous call to generate-features is interfering with this resource file change depending on the order the tests are running (a previous test is not finished before this one starts). Here is the output when the test fails vs succeeds: devtest-resourcefilechange-fails.txt

devtest-resourcefilechange-succeeds.txt

kathrynkodama avatar May 25 '22 15:05 kathrynkodama