Bug 511607 - [Test] Failed to await output testWaitForOutput and testDelay
Summary: [Test] Failed to await output testWaitForOutput and testDelay
Status: REOPENED
Alias: None
Product: Platform
Classification: Eclipse Project
Component: Debug (show other bugs)
Version: 4.7   Edit
Hardware: PC Windows 7
: P3 normal (vote)
Target Milestone: ---   Edit
Assignee: Markus Duft CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-02-03 00:03 EST by Sarika Sinha CLA
Modified: 2020-03-13 02:59 EDT (History)
3 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Sarika Sinha CLA 2017-02-03 00:03:28 EST
Seeing first time
http://download.eclipse.org/eclipse/downloads/drops4/Y20170202-1000/testresults/html/org.eclipse.debug.tests_ep47Y-unit-cen64-gtk2_linux.gtk.x86_64_8.0.html

testWaitForOutput	Error	

Failed to await output 'TestOutput' on the console of 'Test1'.

java.lang.RuntimeException: Failed to await output 'TestOutput' on the console of 'Test1'.
at org.eclipse.debug.internal.core.groups.GroupLaunchConfigurationDelegate.postLaunchAction(GroupLaunchConfigurationDelegate.java:208)
at org.eclipse.debug.internal.core.groups.GroupLaunchConfigurationDelegate.launchChild(GroupLaunchConfigurationDelegate.java:173)
at org.eclipse.debug.internal.core.groups.GroupLaunchConfigurationDelegate.launch(GroupLaunchConfigurationDelegate.java:123)
at org.eclipse.debug.internal.core.LaunchConfiguration.launch(LaunchConfiguration.java:885)
at org.eclipse.debug.internal.core.LaunchConfiguration.launch(LaunchConfiguration.java:739)
at org.eclipse.debug.internal.core.LaunchConfiguration.launch(LaunchConfiguration.java:731)
at org.eclipse.debug.tests.launching.LaunchGroupTests.testWaitForOutput(LaunchGroupTests.java:265)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:749)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:350)
at org.eclipse.test.UITestApplication.lambda$0(UITestApplication.java:195)
at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:37)
at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:182)
at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:4468)
at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:4081)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$4.run(PartRenderingEngine.java:1133)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1022)
at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:153)
at org.eclipse.ui.internal.Workbench.lambda$3(Workbench.java:679)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:593)
at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:148)
at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:138)
at org.eclipse.test.UITestApplication.runApplication(UITestApplication.java:139)
at org.eclipse.test.UITestApplication.run(UITestApplication.java:61)
at org.eclipse.test.UITestApplication.start(UITestApplication.java:210)
at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:134)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:104)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:388)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:243)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:653)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:590)
at org.eclipse.equinox.launcher.Main.run(Main.java:1499)
at org.eclipse.equinox.launcher.Main.main(Main.java:1472)
at org.eclipse.core.launcher.Main.main(Main.java:34)
Comment 1 Sarika Sinha CLA 2017-02-06 00:12:17 EST
2 tests failed, we need to make the tests more robust.
http://download.eclipse.org/eclipse/downloads/drops4/I20170203-2000/testresults/html/org.eclipse.debug.tests_ep47I-unit-win32_win32.win32.x86_8.0.html
testWaitForOutput	Failure	output was not awaited

junit.framework.AssertionFailedError: output was not awaited
at org.eclipse.debug.tests.launching.LaunchGroupTests.testWaitForOutput(LaunchGroupTests.java:268)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:749)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:350)
at org.eclipse.test.UITestApplication.lambda$0(UITestApplication.java:195)
at org.eclipse.test.UITestApplication$$Lambda$277/32220244.run(Unknown Source)
at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:37)
at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:182)
at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:4216)
at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3823)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$4.run(PartRenderingEngine.java:1145)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1034)
at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:153)
at org.eclipse.ui.internal.Workbench.lambda$3(Workbench.java:679)
at org.eclipse.ui.internal.Workbench$$Lambda$13/28511378.run(Unknown Source)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:593)
at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:148)
at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:138)
at org.eclipse.test.UITestApplication.runApplication(UITestApplication.java:139)
at org.eclipse.test.UITestApplication.run(UITestApplication.java:61)
at org.eclipse.test.UITestApplication.start(UITestApplication.java:210)
at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:134)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:104)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:388)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:243)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:653)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:590)
at org.eclipse.equinox.launcher.Main.run(Main.java:1499)
at org.eclipse.equinox.launcher.Main.main(Main.java:1472)
at org.eclipse.core.launcher.Main.main(Main.java:34)


testDelay	Failure	delay was not awaited

junit.framework.AssertionFailedError: delay was not awaited
at org.eclipse.debug.tests.launching.LaunchGroupTests.testDelay(LaunchGroupTests.java:132)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:749)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:350)
at org.eclipse.test.UITestApplication.lambda$0(UITestApplication.java:195)
at org.eclipse.test.UITestApplication$$Lambda$277/32220244.run(Unknown Source)
at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:37)
at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:182)
at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:4216)
at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3823)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$4.run(PartRenderingEngine.java:1145)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1034)
at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:153)
at org.eclipse.ui.internal.Workbench.lambda$3(Workbench.java:679)
at org.eclipse.ui.internal.Workbench$$Lambda$13/28511378.run(Unknown Source)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:593)
at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:148)
at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:138)
at org.eclipse.test.UITestApplication.runApplication(UITestApplication.java:139)
at org.eclipse.test.UITestApplication.run(UITestApplication.java:61)
at org.eclipse.test.UITestApplication.start(UITestApplication.java:210)
at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:134)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:104)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:388)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:243)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:653)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:590)
at org.eclipse.equinox.launcher.Main.run(Main.java:1499)
at org.eclipse.equinox.launcher.Main.main(Main.java:1472)
at org.eclipse.core.launcher.Main.main(Main.java:34)
Comment 2 Andrey Loskutov CLA 2017-02-06 01:14:20 EST
Sarika,  I think you wanted to assign this issue, not close?
Comment 3 Sarika Sinha CLA 2017-02-06 01:27:46 EST
(In reply to Andrey Loskutov from comment #2)
> Sarika,  I think you wanted to assign this issue, not close?

Yes, my mistake!! Thanks.
Comment 4 Sarika Sinha CLA 2017-03-07 00:18:40 EST
@Markus,
Hope you find some time in M7.
Comment 5 Markus Duft CLA 2017-03-07 01:35:43 EST
Hm, I honestly have no Idea where to start. The only way I could see the asserts being fired is that the machine time was adjusted while the test was running...?

Also the test never failed on my machine, and it did not fail for the last 12 I builds and also M5 is green. I don't know what to change.
Comment 6 Sarika Sinha CLA 2017-03-07 01:55:13 EST
@Andrey,
Any suggestion for Markus?
Comment 7 Andrey Loskutov CLA 2017-03-08 09:17:11 EST
(In reply to Sarika Sinha from comment #6)
> @Andrey,
> Any suggestion for Markus?

Looking on one failed test (org.eclipse.debug.tests.launching.LaunchGroupTests.testWaitForOutput()) I wonder if this condition can work as expected:

assertTrue("output was not awaited", (System.currentTimeMillis() - start) > 2000);

We expect here that time advances at least 2000 ms between long start = System.currentTimeMillis(); and the assert above. Why? The thread started one line *above* the start was taken could even already terminate before start time is recorded. There is no guarantee that system would *immediately* proceed with the current thread work after new Thread("Output Producer").start().

Here the fix would be to move this line "long start = System.currentTimeMillis()" *before* the line where the thread is started.

In both cases (current code and proposed change) to be sure the "Output Producer" actually did something, one need at least some kind of confirmation *before* trying to judge if we have waited enough time. So just create AtomicBoolean in the test case before starting the thread, let the thread *at the very end* set this flag to true and check it first, *before* assertTrue("output was not awaited" code, to be sure our execution happened at all.

The test itself is based on the hope that observing the time between measurements we can conclude that the time was spent in the group which should block until the output is produced. But this is not guaranteed. In case your test environment is a virtualized, there could be literally *minutes* between method calls. If the thread scheduler decides that current thread need to be blocked for a longer time (or virtual machine will be "paused" for some time), we will observe a delay but this observation is not a confirmation of the behavior we would like to test here. Ideally one could ask the ILaunchConfiguration group if the expected output was really observed.

I have not checked other tests, but if they are based on same assumptions as this one, they will most likely fail in same manner too and need to be changed accordingly.
Comment 8 Sarika Sinha CLA 2017-03-09 22:22:02 EST
Thanks Andrey for analysis and suggestions.
@Markus, It has failed again so I think it will be good to look into this.

http://download.eclipse.org/eclipse/downloads/drops4/Y20170309-1000/testresults/html/org.eclipse.debug.tests_ep47Y-unit-win32_win32.win32.x86_8.0.html
Comment 9 Eclipse Genie CLA 2017-03-10 01:19:41 EST
New Gerrit change created: https://git.eclipse.org/r/92744
Comment 10 Markus Duft CLA 2017-03-10 01:21:55 EST
Thanks for the suggestions. Also the output for the now again failed test helps: I now think that the problem is that the test machine is too fast xD I check the condition using '> 2000' but on a VERY fast run it could be '== 2000' - the time used by the failed delay test (2.00 s) seems to match that assumption.

Nevertheless I think Andreys suggestion makes the output test more robust, so I did it exactly as described :)

All the other tests use >= now to check elapsed time.
Comment 12 Sarika Sinha CLA 2017-04-12 00:50:25 EDT
Failed after a break :)
http://download.eclipse.org/eclipse/downloads/drops4/I20170409-2000/testresults/html/org.eclipse.debug.tests_ep47I-unit-cen64-gtk3_linux.gtk.x86_64_8.0.html

history should be size 3

junit.framework.AssertionFailedError: history should be size 3
at org.eclipse.debug.tests.launching.LaunchGroupTests.testWaitForOutput(LaunchGroupTests.java:282)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:749)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:350)
at org.eclipse.test.UITestApplication.lambda$0(UITestApplication.java:195)
at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:37)
at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:182)
at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:4472)
at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:4085)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$4.run(PartRenderingEngine.java:1146)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1035)
at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:153)
at org.eclipse.ui.internal.Workbench.lambda$3(Workbench.java:680)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:336)
at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:594)
at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:148)
at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:151)
at org.eclipse.test.UITestApplication.runApplication(UITestApplication.java:139)
at org.eclipse.test.UITestApplication.run(UITestApplication.java:61)
at org.eclipse.test.UITestApplication.start(UITestApplication.java:210)
at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:134)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:104)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:388)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:243)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:653)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:590)
at org.eclipse.equinox.launcher.Main.run(Main.java:1499)
at org.eclipse.equinox.launcher.Main.main(Main.java:1472)
at org.eclipse.core.launcher.Main.main(Main.java:34)
Comment 14 Eclipse Genie CLA 2017-04-26 04:54:37 EDT
New Gerrit change created: https://git.eclipse.org/r/95754
Comment 16 Andrey Loskutov CLA 2017-04-26 05:30:58 EDT
(In reply to Eclipse Genie from comment #15)
> Gerrit change https://git.eclipse.org/r/95754 was merged to [master].
> Commit:
> http://git.eclipse.org/c/platform/eclipse.platform.debug.git/commit/
> ?id=2bbe9def0b1520c359321e873d5abe1bb781ca19

Not a fix for the problem, but just a fix for the reporting, to see what is actually seen by the test.
Comment 17 Markus Duft CLA 2017-04-26 07:38:20 EDT
(In reply to Andrey Loskutov from comment #16)
> 
> Not a fix for the problem, but just a fix for the reporting, to see what is
> actually seen by the test.

Thank you very much! I'm completely locked down with other things right now :(
Comment 21 Markus Duft CLA 2017-07-04 01:27:46 EDT
I have near zero time for the next 4 to 5 weeks, but I will try to get it done.
Comment 22 Eclipse Genie CLA 2017-07-04 02:48:50 EDT
New Gerrit change created: https://git.eclipse.org/r/100587
Comment 23 Markus Duft CLA 2017-07-04 02:51:04 EDT
I'm 90% sure I found the last race condition ;) at least now I know that it is not a problem with LaunchGroups but really the test code :)
Comment 25 Sarika Sinha CLA 2017-07-04 05:28:13 EDT
Thanks Markus!! Let's observe for few weeks before resolving.
Comment 26 Markus Duft CLA 2017-08-28 04:08:33 EDT
did you observe any problems lately?
Comment 27 Sarika Sinha CLA 2017-08-28 06:05:20 EDT
Thanks for the reminder, not observing the failures now.
Comment 28 Sarika Sinha CLA 2017-11-15 06:31:52 EST
After l0ong time -
http://download.eclipse.org/eclipse/downloads/drops4/M20171114-1700/testresults/html/org.eclipse.debug.tests_ep47M-unit-win32_win32.win32.x86_8.0.html

testWaitForOutput
thread did not finish

junit.framework.AssertionFailedError: thread did not finish
at org.eclipse.debug.tests.launching.LaunchGroupTests.testWaitForOutput(LaunchGroupTests.java:278)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:749)