Bug 414851 - SeparateVMTests has random failures
Summary: SeparateVMTests has random failures
Status: RESOLVED FIXED
Alias: None
Product: Platform
Classification: Eclipse Project
Component: Ant (show other bugs)
Version: 4.4   Edit
Hardware: All All
: P3 normal (vote)
Target Milestone: ---   Edit
Assignee: Platform-Ant-Inbox CLA
QA Contact:
URL:
Whiteboard:
Keywords: test
: 368457 421447 (view as bug list)
Depends on:
Blocks:
 
Reported: 2013-08-12 05:20 EDT by Dani Megert CLA
Modified: 2013-12-17 09:07 EST (History)
2 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Dani Megert CLA 2013-08-12 05:20:33 EDT
N20130811-2000.

http://download.eclipse.org/eclipse/downloads/drops4/N20130811-2000/testresults/html/org.eclipse.ant.tests.ui_win32.win32.x86_7.0.html


Incorrect number of messages logged for build. Should be 8. Was 4

junit.framework.AssertionFailedError: Incorrect number of messages logged for build. Should be 8. Was 4
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.testProperties(SeparateVMTests.java:74)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest.access$0(AbstractAntUIBuildTest.java:1)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest$1.run(AbstractAntUIBuildTest.java:44)
at java.lang.Thread.run(Thread.java:722)


Incorrect number of messages logged for build. Should be 6. Was 5

junit.framework.AssertionFailedError: Incorrect number of messages logged for build. Should be 6. Was 5
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.testBuild(SeparateVMTests.java:56)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest.access$0(AbstractAntUIBuildTest.java:1)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest$1.run(AbstractAntUIBuildTest.java:44)
at java.lang.Thread.run(Thread.java:722)


Incorrect number of messages logged for build. Should be 6. Was 5

junit.framework.AssertionFailedError: Incorrect number of messages logged for build. Should be 6. Was 5
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.testPropertySubstitution(SeparateVMTests.java:180)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest.access$0(AbstractAntUIBuildTest.java:1)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest$1.run(AbstractAntUIBuildTest.java:44)
at java.lang.Thread.run(Thread.java:722)
Comment 1 Dani Megert CLA 2013-08-19 04:38:02 EDT
SeparateVMTests.testPropertySubstitution failed again in N20130818-2000:

Incorrect number of messages logged for build. Should be 6. Was 4

junit.framework.AssertionFailedError: Incorrect number of messages logged for build. Should be 6. Was 4
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.testPropertySubstitution(SeparateVMTests.java:180)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest.access$0(AbstractAntUIBuildTest.java:1)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest$1.run(AbstractAntUIBuildTest.java:44)
at java.lang.Thread.run(Thread.java:722)
Comment 2 Dani Megert CLA 2013-08-20 04:17:59 EDT
And on Linux we just got:
http://download.eclipse.org/eclipse/downloads/drops4/N20130819-2000/testresults/html/org.eclipse.ant.tests.ui_linux.gtk.x86_6.0.html

Failed getting offset of line

junit.framework.AssertionFailedError: failed getting offset of line
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.testColor(SeparateVMTests.java:146)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest.access$0(AbstractAntUIBuildTest.java:1)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest$1.run(AbstractAntUIBuildTest.java:44)
at java.lang.Thread.run(Thread.java:662)
Comment 3 Michael Rennie CLA 2013-08-20 09:58:17 EDT
Could be related - just found this in the test logs:

!ENTRY org.eclipse.ant.core 4 1 2013-08-19 22:23:01.879
!MESSAGE Array index out of range: 0
!STACK 0
java.lang.ArrayIndexOutOfBoundsException: Array index out of range: 0
	at java.util.Vector.remove(Vector.java:777)
	at org.eclipse.ant.internal.launching.debug.AntDebugState.initializeBuildSequenceInformation(AntDebugState.java:560)
	at org.eclipse.ant.internal.launching.debug.AntDebugState.targetStarted(AntDebugState.java:301)
	at org.eclipse.ant.internal.launching.runtime.logger.AntProcessDebugBuildLogger.targetStarted(AntProcessDebugBuildLogger.java:266)
	at org.apache.tools.ant.Project.fireTargetStarted(Project.java:2140)
	at org.apache.tools.ant.Target.performTasks(Target.java:454)
	at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1393)
	at org.apache.tools.ant.Project.executeTarget(Project.java:1364)
	at org.apache.tools.ant.helper.DefaultExecutor.executeTargets(DefaultExecutor.java:41)
	at org.eclipse.ant.internal.core.ant.EclipseDefaultExecutor.executeTargets(EclipseDefaultExecutor.java:32)
	at org.apache.tools.ant.Project.executeTargets(Project.java:1248)
	at org.eclipse.ant.internal.core.ant.InternalAntRunner.run(InternalAntRunner.java:703)
	at org.eclipse.ant.internal.core.ant.InternalAntRunner.run(InternalAntRunner.java:525)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.eclipse.ant.core.AntRunner.run(AntRunner.java:368)
	at org.eclipse.ant.internal.launching.launchConfigurations.AntLaunchDelegate$1.run(AntLaunchDelegate.java:241)
	at java.lang.Thread.run(Thread.java:662)
Comment 6 Dani Megert CLA 2013-09-02 06:01:16 EDT
And again:
http://download.eclipse.org/eclipse/downloads/drops4/I20130901-2000/testresults/html/org.eclipse.ant.tests.ui_win32.win32.x86_7.0.html

Please make that test more stable or disable it.
Comment 7 Michael Rennie CLA 2013-09-03 11:54:33 EDT
pushed changes to prevent the AIOOBE and ESE while processing an Ant project: http://git.eclipse.org/c/platform/eclipse.platform.git/commit/?id=5e00d44462d9116b13bb4d52004efa5e7b0794c9

I also added some logging to dump out the lines that were tracked, since these tests never fail locally perhaps this will help track down what is happening: 

http://git.eclipse.org/c/platform/eclipse.platform.git/commit/?id=44b10012e79f4f03e5d867c329f24397328128ea
Comment 8 Dani Megert CLA 2013-09-09 08:27:17 EDT
(In reply to Michael Rennie from comment #7)
> I also added some logging to dump out the lines that were tracked, since
> these tests never fail locally perhaps this will help track down what is
> happening: 
> 
> http://git.eclipse.org/c/platform/eclipse.platform.git/commit/
> ?id=44b10012e79f4f03e5d867c329f24397328128ea

Maybe you can use it to figure out the latest failure:
http://download.eclipse.org/eclipse/downloads/drops4/I20130908-2000/testresults/html/org.eclipse.ant.tests.ui_win32.win32.x86_7.0.html
Comment 9 Michael Rennie CLA 2013-09-09 10:24:50 EDT
(In reply to Dani Megert from comment #8)

> Maybe you can use it to figure out the latest failure:
> http://download.eclipse.org/eclipse/downloads/drops4/I20130908-2000/
> testresults/html/org.eclipse.ant.tests.ui_win32.win32.x86_7.0.html

Perhaps I could.

Its seems that for some reason the build status bits are not written out sometimes. For example, when the test passes, the following is written to the console:

Buildfile: C:\Users\mrennie\workspaces\runtime-3.8.x\P\extensionPointTypeSepVM.xml
Extension Point Type:
     [echo] Ensure that an extension point defined type is present
BUILD SUCCESSFUL
Total time: 556 milliseconds

when it "fails", the following is written:

Buildfile: C:\Users\mrennie\workspaces\runtime-3.8.x\P\extensionPointTypeSepVM.xml
Extension Point Type:
     [echo] Ensure that an extension point defined type is present

So it both cases the build file is executing and completing normally, but the console output is not making it. I'll have to check our default logger, perhaps there is a race condition that has a check like 'if(!targetIsDone) logMessage(msg)'

The other option (if it is not a timing problem) is to just remove the line number check from the tests - they (the tests) do not use the last status bits of the output anyway.

Sounds similar to bug 293043.
Comment 10 Michael Rennie CLA 2013-09-09 21:08:49 EDT
I added in a call to our line tracker sync'ing as I didn't find anything obvious wrt timing issues, so we'll see if adding some sync'ing to the tests helps.

http://git.eclipse.org/c/platform/eclipse.platform.git/commit/?id=065d399052efa4845e0f05f2fa48592ae347a99d
Comment 12 Dani Megert CLA 2013-09-11 04:28:23 EDT
(In reply to Dani Megert from comment #11)
> Another of those VM tests failed:
> http://download.eclipse.org/eclipse/downloads/drops4/I20130910-0800/
> testresults/html/org.eclipse.ant.tests.ui_win32.win32.x86_7.0.html

Sorry, that was before your change. Let's wait for the next builds.
Comment 14 Michael Rennie CLA 2013-10-01 10:03:59 EDT
(In reply to Dani Megert from comment #13)
> Again:
> http://download.eclipse.org/eclipse/downloads/drops4/I20130918-0800/
> testresults/html/org.eclipse.ant.tests.ui_win32.win32.x86_7.0.html

Failures are happening less frequently, but still happening. We should update the tests even further to ask specific questions about the console output rather than just "how many lines do you have"
Comment 15 Dani Megert CLA 2013-10-03 06:43:48 EDT
SeparateVMTests.testExtensionPointTask failed in N20131002-2000:

Incorrect number of messages logged for build - should be 7 but was 5

junit.framework.AssertionFailedError: Incorrect number of messages logged for build - should be 7 but was 5
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.assertLines(SeparateVMTests.java:66)
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.testExtensionPointTask(SeparateVMTests.java:103)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest.access$0(AbstractAntUIBuildTest.java:1)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest$1.run(AbstractAntUIBuildTest.java:44)
at java.lang.Thread.run(Thread.java:722)
Comment 16 Dani Megert CLA 2013-10-11 04:13:53 EDT
Another one in N20131010-2000 (Linux):

Incorrect number of messages logged for build - should be 6 but was 2

junit.framework.AssertionFailedError: Incorrect number of messages logged for build - should be 6 but was 2
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.assertLines(SeparateVMTests.java:66)
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.testAntHome(SeparateVMTests.java:237)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest.access$0(AbstractAntUIBuildTest.java:1)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest$1.run(AbstractAntUIBuildTest.java:44)
at java.lang.Thread.run(Thread.java:662)
Comment 17 Dani Megert CLA 2013-10-22 06:29:54 EDT
N20131021-2000.


N/A

org.eclipse.jface.text.BadLocationException
at org.eclipse.jface.text.TreeLineTracker.fail(TreeLineTracker.java:1055)
at org.eclipse.jface.text.TreeLineTracker.getLineInformationOfOffset(TreeLineTracker.java:1151)
at org.eclipse.jface.text.AbstractLineTracker.getLineInformationOfOffset(AbstractLineTracker.java:145)
at org.eclipse.jface.text.AbstractDocument.getLineInformationOfOffset(AbstractDocument.java:936)
at org.eclipse.ui.internal.console.ConsoleDocument.getLineInformationOfOffset(ConsoleDocument.java:57)
at org.eclipse.ant.tests.ui.testplugin.AbstractAntUITest.getColorAtOffset(AbstractAntUITest.java:546)
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.testColor(SeparateVMTests.java:167)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest.access$0(AbstractAntUIBuildTest.java:1)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest$1.run(AbstractAntUIBuildTest.java:44)
at java.lang.Thread.run(Thread.java:662)
Comment 18 Dani Megert CLA 2013-10-29 05:18:13 EDT
At least one of the SeparateVMTests fails almost every time.
Comment 19 Dani Megert CLA 2013-11-04 09:25:58 EST
http://download.eclipse.org/eclipse/downloads/drops4/N20131103-2000/testresults/html/org.eclipse.ant.tests.ui_win32.win32.x86_7.0.html


Incorrect number of messages logged for build - should be 6 but was 4

junit.framework.AssertionFailedError: Incorrect number of messages logged for build - should be 6 but was 4
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.assertLines(SeparateVMTests.java:66)
at org.eclipse.ant.tests.ui.separateVM.SeparateVMTests.testBuild(SeparateVMTests.java:75)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest.access$0(AbstractAntUIBuildTest.java:1)
at org.eclipse.ant.tests.ui.AbstractAntUIBuildTest$1.run(AbstractAntUIBuildTest.java:44)
at java.lang.Thread.run(Thread.java:722)
Comment 20 Michael Rennie CLA 2013-11-12 13:03:16 EST
*** Bug 421447 has been marked as a duplicate of this bug. ***
Comment 21 Michael Rennie CLA 2013-11-12 13:03:58 EST
*** Bug 368457 has been marked as a duplicate of this bug. ***
Comment 22 Michael Rennie CLA 2013-11-12 13:08:29 EST
(In reply to Dani Megert from comment #19)
> http://download.eclipse.org/eclipse/downloads/drops4/N20131103-2000/
> testresults/html/org.eclipse.ant.tests.ui_win32.win32.x86_7.0.html
> 
> 
> Incorrect number of messages logged for build - should be 6 but was 4

I extended our TestAgainException to the separate VM tests, this should prevent these annoying transient failures: http://git.eclipse.org/c/platform/eclipse.platform.git/commit/?id=589f34731650a857e669beeded94659e7a003377
Comment 23 Dani Megert CLA 2013-11-18 11:06:26 EST
(In reply to Michael Rennie from comment #22)
> (In reply to Dani Megert from comment #19)
> > http://download.eclipse.org/eclipse/downloads/drops4/N20131103-2000/
> > testresults/html/org.eclipse.ant.tests.ui_win32.win32.x86_7.0.html
> > 
> > 
> > Incorrect number of messages logged for build - should be 6 but was 4
> 
> I extended our TestAgainException to the separate VM tests, this should
> prevent these annoying transient failures:
> http://git.eclipse.org/c/platform/eclipse.platform.git/commit/
> ?id=589f34731650a857e669beeded94659e7a003377

This didn't really help :-(
Comment 25 Michael Rennie CLA 2013-11-18 14:05:05 EST
(In reply to Dani Megert from comment #23)

> This didn't really help :-(

http://git.eclipse.org/c/platform/eclipse.platform.git/commit/?id=d1093d927c10e6428eaad1bd5e9b3e2e34c0af84
Comment 26 Dani Megert CLA 2013-11-20 04:15:12 EST
(In reply to Michael Rennie from comment #25)
> > This didn't really help :-(
> 
> http://git.eclipse.org/c/platform/eclipse.platform.git/commit/
> ?id=d1093d927c10e6428eaad1bd5e9b3e2e34c0af84

Looks better now!
Comment 27 Michael Rennie CLA 2013-12-17 09:07:55 EST
The tests have been very stable for quite a few builds now. I am going to mark this fixed (fingers crossed!).