Flakiness in StandardStagingDelegateTest

[briandealwis]

Seen in tests:

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running com.google.cloud.tools.eclipse.appengine.deploy.standard.StandardStagingDelegateTest
log4j:WARN No appenders could be found for logger (freemarker.cache).
log4j:WARN Please initialize the log4j system properly.
!SESSION 2017-04-21 21:29:05.936 -----------------------------------------------
eclipse.buildId=unknown
java.version=1.8.0_31
java.vendor=Oracle Corporation
BootLoader constants: OS=linux, ARCH=x86_64, WS=gtk, NL=en_US
Framework arguments:  -application org.eclipse.tycho.surefire.osgibooter.headlesstest -testproperties /home/travis/build/GoogleCloudPlatform/google-cloud-eclipse/plugins/com.google.cloud.tools.eclipse.appengine.deploy.test/target/surefire.properties
Command-line arguments:  -debug -consolelog -data /home/travis/build/GoogleCloudPlatform/google-cloud-eclipse/plugins/com.google.cloud.tools.eclipse.appengine.deploy.test/target/work/data -application org.eclipse.tycho.surefire.osgibooter.headlesstest -testproperties /home/travis/build/GoogleCloudPlatform/google-cloud-eclipse/plugins/com.google.cloud.tools.eclipse.appengine.deploy.test/target/surefire.properties
!ENTRY org.eclipse.core.jobs 4 2 2017-04-21 21:29:43.958
!MESSAGE An internal error occurred during: "Install App Engine runtimes in "test0.2863270227907232"".
!STACK 0
java.lang.NullPointerException: Could not find App Engine Standard runtime type
	at com.google.cloud.tools.eclipse.appengine.facets.AppEngineStandardFacet.createAppEngineServerRuntime(AppEngineStandardFacet.java:255)
	at com.google.cloud.tools.eclipse.appengine.facets.AppEngineStandardFacet.createAppEngineFacetRuntime(AppEngineStandardFacet.java:267)
	at com.google.cloud.tools.eclipse.appengine.facets.AppEngineStandardFacet.installAllAppEngineRuntimes(AppEngineStandardFacet.java:237)
	at com.google.cloud.tools.eclipse.appengine.facets.StandardFacetInstallDelegate$AppEngineRuntimeInstallJob.run(StandardFacetInstallDelegate.java:115)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:56)
Apr 21, 2017 9:29:46 PM com.google.cloud.tools.appengine.cloudsdk.CloudSdk logCommand
INFO: submitting command: /usr/lib/jvm/java-8-oracle/jre/bin/java -cp /home/travis/google-cloud-sdk/platform/google_appengine/google/appengine/tools/java/lib/appengine-tools-api.jar com.google.appengine.tools.admin.AppCfg --disable_update_check --enable_jar_splitting stage /home/travis/build/GoogleCloudPlatform/google-cloud-eclipse/plugins/com.google.cloud.tools.eclipse.appengine.deploy.test/target/work/data/test0.2863270227907232/safe-work-directory /home/travis/build/GoogleCloudPlatform/google-cloud-eclipse/plugins/com.google.cloud.tools.eclipse.appengine.deploy.test/target/work/data/test0.2863270227907232/staging-result
!ENTRY org.eclipse.core.jobs 4 2 2017-04-21 21:29:56.318
!MESSAGE An internal error occurred during: "Install App Engine runtimes in "test0.03477744480158751"".
!STACK 0
java.lang.NullPointerException: Could not find App Engine Standard runtime type
	at com.google.cloud.tools.eclipse.appengine.facets.AppEngineStandardFacet.createAppEngineServerRuntime(AppEngineStandardFacet.java:255)
	at com.google.cloud.tools.eclipse.appengine.facets.AppEngineStandardFacet.createAppEngineFacetRuntime(AppEngineStandardFacet.java:267)
	at com.google.cloud.tools.eclipse.appengine.facets.AppEngineStandardFacet.installAllAppEngineRuntimes(AppEngineStandardFacet.java:237)
	at com.google.cloud.tools.eclipse.appengine.facets.StandardFacetInstallDelegate$AppEngineRuntimeInstallJob.run(StandardFacetInstallDelegate.java:115)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:56)
Apr 21, 2017 9:29:58 PM com.google.cloud.tools.appengine.cloudsdk.CloudSdk logCommand
INFO: submitting command: /usr/lib/jvm/java-8-oracle/jre/bin/java -cp /home/travis/google-cloud-sdk/platform/google_appengine/google/appengine/tools/java/lib/appengine-tools-api.jar com.google.appengine.tools.admin.AppCfg --disable_update_check --enable_jar_splitting stage /home/travis/build/GoogleCloudPlatform/google-cloud-eclipse/plugins/com.google.cloud.tools.eclipse.appengine.deploy.test/target/work/data/test0.03477744480158751/safe-work-directory /home/travis/build/GoogleCloudPlatform/google-cloud-eclipse/plugins/com.google.cloud.tools.eclipse.appengine.deploy.test/target/work/data/test0.03477744480158751/staging-result
Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 37.511 sec <<< FAILURE! - in com.google.cloud.tools.eclipse.appengine.deploy.standard.StandardStagingDelegateTest
testStage(com.google.cloud.tools.eclipse.appengine.deploy.standard.StandardStagingDelegateTest)  Time elapsed: 27.951 sec  <<< FAILURE!
java.lang.AssertionError: null
	at org.junit.Assert.fail(Assert.java:86)
	at org.junit.Assert.assertTrue(Assert.java:41)
	at org.junit.Assert.assertTrue(Assert.java:52)
	at com.google.cloud.tools.eclipse.appengine.deploy.standard.StandardStagingDelegateTest.testStage(StandardStagingDelegateTest.java:66)

[chanseokoh]

The NullPointerExceptions are harmless. There have been a lot of these for a long time.

Any idea why the assertion fails? I thought about calling refreshLocal(), but that doesn't seem relevant.

[briandealwis]

I wondered if the runtime-type NPEs were the cause of the subsequent assertion failure; I've added some diagnostics to dump out more information.

The assertion failure is at the exists() call:

  @Test
  public void testStage() throws CoreException {
    StagingDelegate delegate = new StandardStagingDelegate();
    delegate.stage(project, stagingDirectory, safeWorkDirectory, cloudSdk,
        new NullProgressMonitor());

    assertTrue(stagingDirectory.append("WEB-INF").toFile().exists());

The expression deals with java.io.Files, so the Eclipse Workspace sync state should have no bearing.

[chanseokoh]

The NPEs are always reproducible, or at least it is happening in a lot of places very frequently. They are harmless though.

[chanseokoh]

I wondered if the runtime-type NPEs were the cause of the subsequent assertion failure; I've added some diagnostics to dump out more information.

There's no App Engine runtime at the first place:

May 01, 2017 1:23:11 PM com.google.cloud.tools.eclipse.appengine.facets.AppEngineStandardFacet createAppEngineServerRuntime
WARNING: RuntimeTypes: RuntimeType[org.eclipse.jst.server.core.runtimeType, J2EE Runtime Library]

I have been thinking these NPEs always happen for any test bundle other than .localserver.test, since .localserver is the bundle that defines the runtime. To me, the NPE seems unrelated to the assertion failure. I can't think of any connection. That said, this flaky test is still perplexing. We just shell out the staging work to the Cloud SDK, and it does execute the command:

INFO: submitting command: /usr/lib/jvm/java-8-oracle/jre/bin/java -cp /home/travis/google-cloud-sdk/platform/google_appengine/google/appengine/tools/java/lib/appengine-tools-api.jar com.google.appengine.tools.admin.AppCfg --disable_update_check --enable_jar_splitting stage /home/travis/build/GoogleCloudPlatform/google-cloud-eclipse/plugins/com.google.cloud.tools.eclipse.appengine.deploy.test/target/work/data/test0.03477744480158751/safe-work-directory /home/travis/build/GoogleCloudPlatform/google-cloud-eclipse/plugins/com.google.cloud.tools.eclipse.appengine.deploy.test/target/work/data/test0.03477744480158751/staging-result

[briandealwis]

Oh right: com.google.cloud.tools.eclipse.appengine.deploy doesn't have any dependency on .localserver, and so the runtime definition is never seen since Tycho runs with the minimal set of dependencies. But we can't add a dependency on .localserver in .deploy as it creates a cycle: .facets depends on .deploy for FlexDeployPreferences; and .localserver has a dependency on .facets. Seems like the flex preferences are more general than just deploy?

Re: the assertion failure. I've tried running the test 100 times repeatedly and haven't been able to reproduce it locally on OSX and Linux. I've tried to reproduce it by hand by invoking AppCfg on altered copies of the 'safe-working directory', but AppCfg always aborts with an error.

It actually reminds me of the errors I was encountering with #1529…

[diegomarquezp]

Closing as not planned.