Bug 547417 - [test] 181 org.eclipse.jdt.core.tests.eval tests failed - NPE on EvaluationTest.context
Summary: [test] 181 org.eclipse.jdt.core.tests.eval tests failed - NPE on EvaluationTe...
Status: RESOLVED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Core (show other bugs)
Version: 4.12   Edit
Hardware: PC Linux
: P3 normal (vote)
Target Milestone: 4.13 M3   Edit
Assignee: Andrey Loskutov CLA
QA Contact: Manoj N Palat CLA
URL:
Whiteboard:
Keywords: test
Depends on:
Blocks:
 
Reported: 2019-05-17 04:40 EDT by Manoj N Palat CLA
Modified: 2019-08-22 12:30 EDT (History)
1 user (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Manoj N Palat CLA 2019-05-17 04:40:53 EDT
from here : https://download.eclipse.org/eclipse/downloads/drops4/I20190516-1800/testresults/html/org.eclipse.jdt.core.tests.compiler_ep412I-unit-cen64-gtk3-java12_linux.gtk.x86_64_12.html, there are 181 tests failing with NPE.

A sample st:
ava.lang.NullPointerException 
at org.eclipse.jdt.core.tests.eval.NegativeCodeSnippetTest.testUnusedImport(NegativeCodeSnippetTest.java:355) 
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 

While running on Java 12 locally on a windows machine, these tests passed.
Comment 1 Andrey Loskutov CLA 2019-05-17 05:16:15 EDT
I think this is not the first time we see ~180 test fails.

NPE happens because the test see null at org.eclipse.jdt.core.tests.eval.EvaluationTest.context.

It looks for me that we can't connect to the VM at some time, so that 
org.eclipse.jdt.core.tests.eval.EvaluationSetup.setUp() *silently* fails.

I only wonder where all the error logs are gone from the fails in EvaluationSetup.setUp().

The fail to connect is probably due not released socket in tearDown() before. Again, where are the logs???
Comment 2 Eclipse Genie CLA 2019-05-27 03:39:40 EDT
New Gerrit change created: https://git.eclipse.org/r/142840
Comment 3 Andrey Loskutov CLA 2019-05-27 07:53:55 EDT
Failed again in I20190524-1800: https://download.eclipse.org/eclipse/downloads/drops4/I20190524-1800/testResults.php
Comment 5 Andrey Loskutov CLA 2019-05-27 09:11:12 EDT
(In reply to Eclipse Genie from comment #4)
> Gerrit change https://git.eclipse.org/r/142840 was merged to [master].
> Commit:
> http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/
> ?id=75f3e352a42c492d320c07a30923f559c39bbf8c

Next time we *hopefully* will either:
1) Do not see any fail due increased timeout.
2) See *different* test fails (hopefully at setUp(), saying "cannot connect"). The stacks should in theory help to understand why.
3) See same fails but also some extra stacks printed to console with some interesting data what goes wrong.
4) See same fails but also some extra stacks printed to console with useless data.
5) None of the above...

Hope for 1) - I assume the unstable infrastructure could be responsible here.
Comment 6 Andrey Loskutov CLA 2019-06-02 01:23:13 EDT
Haven't seen again after the last patch.
Comment 7 Andrey Loskutov CLA 2019-06-04 02:42:21 EDT
(In reply to Andrey Loskutov from comment #6)
> Haven't seen again after the last patch.

Failed again, see https://download.eclipse.org/eclipse/downloads/drops4/I20190603-1800/testResults.php
Comment 8 Andrey Loskutov CLA 2019-06-04 03:01:09 EDT
(In reply to Andrey Loskutov from comment #5)
> (In reply to Eclipse Genie from comment #4)
> > Gerrit change https://git.eclipse.org/r/142840 was merged to [master].
> > Commit:
> > http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/
> > ?id=75f3e352a42c492d320c07a30923f559c39bbf8c
> 
> Next time we *hopefully* will either:
> 1) Do not see any fail due increased timeout.
> 2) See *different* test fails (hopefully at setUp(), saying "cannot
> connect"). The stacks should in theory help to understand why.
> 3) See same fails but also some extra stacks printed to console with some
> interesting data what goes wrong.
> 4) See same fails but also some extra stacks printed to console with useless
> data.
> 5) None of the above...

We have 5). I don't see *ANY* stack traces at all. The only output in https://download.eclipse.org/eclipse/downloads/drops4/I20190603-1800/testresults/ep412I-unit-cen64-gtk3-java12_linux.gtk.x86_64_12/org.eclipse.jdt.core.tests.eval.TestAll.txt

looks like I've missed that DebugEvaluationSetup extends EvaluationSetup and overrides setUp() and so all the extra output was added at the wrong place. Arrgh!!!!
Comment 9 Eclipse Genie CLA 2019-06-04 04:10:37 EDT
New Gerrit change created: https://git.eclipse.org/r/143244
Comment 11 Andrey Loskutov CLA 2019-06-27 04:31:11 EDT
(In reply to Eclipse Genie from comment #10)
> Gerrit change https://git.eclipse.org/r/143244 was merged to [master].
> Commit:
> http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/
> ?id=59bd1e5f10df5fa7f887ba396a5470afdfb5f80b

So now we see "real" fails, no NPE's:

https://download.eclipse.org/eclipse/downloads/drops4/I20190626-1800/testresults/html/org.eclipse.jdt.core.tests.compiler_ep413I-unit-cen64-gtk3-java11_linux.gtk.x86_64_11.html

Unfortunately the stack provided by JUnit is totally meaningless.

Multiple Failures (2 failures) Evaluation context is null, probably VM connection error <no message> in java.lang.IllegalArgumentException

org.opentest4j.MultipleFailuresError: Multiple Failures (2 failures)
Evaluation context is null, probably VM connection error
<no message> in java.lang.IllegalArgumentException
at org.junit.vintage.engine.execution.TestRun.getStoredResultOrSuccessful(TestRun.java:166)
at org.junit.vintage.engine.execution.RunListenerAdapter.fireExecutionFinished(RunListenerAdapter.java:202)
at org.junit.vintage.engine.execution.RunListenerAdapter.testFinished(RunListenerAdapter.java:160)
at org.junit.vintage.engine.execution.RunListenerAdapter.testFinished(RunListenerAdapter.java:76)
at org.junit.runner.notification.SynchronizedRunListener.testFinished(SynchronizedRunListener.java:56)
at org.junit.runner.notification.RunNotifier$7.notifyListener(RunNotifier.java:190)
at org.junit.runner.notification.RunNotifier$SafeNotifier.run(RunNotifier.java:72)
at org.junit.runner.notification.RunNotifier.fireTestFinished(RunNotifier.java:187)
at org.junit.internal.runners.JUnit38ClassRunner$OldTestClassAdaptingListener.endTest(JUnit38ClassRunner.java:33)
at junit.framework.TestResult.endTest(TestResult.java:82)
at junit.framework.TestResult.run(TestResult.java:127)
at junit.framework.TestCase.run(TestCase.java:129)
at junit.framework.TestSuite.runTest(TestSuite.java:252)
at junit.framework.TestSuite.run(TestSuite.java:247)
at junit.framework.TestSuite.runTest(TestSuite.java:252)
at junit.framework.TestSuite.run(TestSuite.java:247)
at org.eclipse.jdt.core.tests.util.CompilerTestSetup.run(CompilerTestSetup.java:59)
at junit.framework.TestSuite.runTest(TestSuite.java:252)
at junit.framework.TestSuite.run(TestSuite.java:247)
at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:86)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:40)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
at java.base/java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:80)
at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:71)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:229)
at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$6(DefaultLauncher.java:197)
at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:211)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:191)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:128)
at org.eclipse.test.EclipseTestRunner.runTests(EclipseTestRunner.java:291)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:267)
at org.eclipse.test.CoreTestApplication.runTests(CoreTestApplication.java:53)
at org.eclipse.test.CoreTestApplication.run(CoreTestApplication.java:36)
at org.eclipse.test.CoreTestApplication.start(CoreTestApplication.java:44)
at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:203)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:137)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:107)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:400)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:255)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:660)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:597)
at org.eclipse.equinox.launcher.Main.run(Main.java:1468)
at org.eclipse.equinox.launcher.Main.main(Main.java:1441)
at org.eclipse.core.launcher.Main.main(Main.java:44)

The log file doesn't say much, but differently to other builds with succeeded tests it contains a lot more "could not contact the JVM" lines:

https://download.eclipse.org/eclipse/downloads/drops4/I20190626-1800/testresults/ep413I-unit-cen64-gtk3-java11_linux.gtk.x86_64_11/org.eclipse.jdt.core.tests.eval.TestAll.txt

reflectNestedClassUseDollar=true due to isJRE9Plus
1.3: could not contact the VM at localhost:36374. Retrying...
1.3: could not contact the VM at localhost:36374. Retrying...
1.3: could not contact the VM at localhost:36374. Retrying...
1.3: could not contact the VM at localhost:36374. Retrying...
1.3: could not contact the VM at localhost:36374. Retrying...
1.3: could not contact the VM at localhost:36374. Retrying...
1.3: could not contact the VM at localhost:36374. Retrying...
1.3: could not contact the VM at localhost:36374. Retrying...
1.3: could not contact the VM at localhost:36374. Retrying...
1.3: could not contact the VM at localhost:36374. Retrying...
Listening for transport dt_socket at address: 36374
1.4: could not contact the VM at localhost:56956. Retrying...
1.4: could not contact the VM at localhost:56956. Retrying...
1.4: could not contact the VM at localhost:56956. Retrying...
Listening for transport dt_socket at address: 56956
1.4: connected to VM using port 56956
1.4: connected to target using port 56956
1.5: could not contact the VM at localhost:40356. Retrying...
1.5: could not contact the VM at localhost:40356. Retrying...
1.5: could not contact the VM at localhost:40356. Retrying...
Listening for transport dt_socket at address: 40356
1.5: connected to VM using port 40356
1.5: connected to target using port 40356
1.6: could not contact the VM at localhost:41644. Retrying...
1.6: could not contact the VM at localhost:41644. Retrying...
1.6: could not contact the VM at localhost:41644. Retrying...
Listening for transport dt_socket at address: 41644
1.6: connected to VM using port 41644
1.6: connected to target using port 41644
1.7: could not contact the VM at localhost:49237. Retrying...
1.7: could not contact the VM at localhost:49237. Retrying...
1.7: could not contact the VM at localhost:49237. Retrying...
1.7: could not contact the VM at localhost:49237. Retrying...
1.7: could not contact the VM at localhost:49237. Retrying...
1.7: could not contact the VM at localhost:49237. Retrying...
1.7: could not contact the VM at localhost:49237. Retrying...
1.7: could not contact the VM at localhost:49237. Retrying...
1.7: could not contact the VM at localhost:49237. Retrying...
1.7: could not contact the VM at localhost:49237. Retrying...
Listening for transport dt_socket at address: 49237
1.8: could not contact the VM at localhost:52806. Retrying...
1.8: could not contact the VM at localhost:52806. Retrying...
1.8: could not contact the VM at localhost:52806. Retrying...
Listening for transport dt_socket at address: 52806
1.8: connected to VM using port 52806
1.8: connected to target using port 52806
9: could not contact the VM at localhost:33152. Retrying...
9: could not contact the VM at localhost:33152. Retrying...
9: could not contact the VM at localhost:33152. Retrying...
Listening for transport dt_socket at address: 33152
9: connected to VM using port 33152
9: connected to target using port 33152
10: could not contact the VM at localhost:39690. Retrying...
10: could not contact the VM at localhost:39690. Retrying...
10: could not contact the VM at localhost:39690. Retrying...
Listening for transport dt_socket at address: 39690
10: connected to VM using port 39690
10: connected to target using port 39690
11: could not contact the VM at localhost:43535. Retrying...
11: could not contact the VM at localhost:43535. Retrying...
11: could not contact the VM at localhost:43535. Retrying...
Listening for transport dt_socket at address: 43535
11: connected to VM using port 43535
11: connected to target using port 43535

I've checked few tests and it looks like they all failed for 1.7 JVM.

This matches to the output above: all VM's except 1.7 have lines:

Listening for transport dt_socket at address: XXX
<version>: connected to VM using port XXX
<version>: connected to target using port XXX

Only 1.7 JVM has 10 attempts to connect:

1.7: could not contact the VM at localhost:49237. Retrying...

followed by:
 
Listening for transport dt_socket at address: 49237

but not followed by 

1.7: connected to VM using port 49237
1.7: connected to target using port 49237

After that we don't see any output (but we should), most likely some exception is triggered but the stupid junit hides it from us, saying there were two errors. WHICH two errors, how idiotic the test framework could be designed by *not* providing stack traces of a fail???

Anyway, looks like we have just some server troubles - we see that JVM starts after a very long time (> 200 seconds).

I will increase timeout and attempts count once again.
Comment 12 Eclipse Genie CLA 2019-06-27 04:35:51 EDT
New Gerrit change created: https://git.eclipse.org/r/144976
Comment 14 Andrey Loskutov CLA 2019-08-22 12:30:30 EDT
Haven't seen this for a while now.