808696 - Robocop should not duplicate failure messages nor terminate a test due to a simple failure

Status: RESOLVED WONTFIX

(Testing :: Mochitest, defect)

Description

[Bob Clary [:bc] (inactive)]

When a non-fatal failure occurs during a single test, FennecMochitestAssert.java:_logMochitestResult will throw a  junit.framework.Assert.fail exception which will terminate the test which also results in a duplicate failure message in the log.

Example output for testAllPagesTab which does not have any failure:

FIRE PROC: '"MOZ_CRASHREPORTER=1,XPCOM_DEBUG_BREAK=stack,MOZ_CRASHREPORTER_NO_REPORT=1,NO_EM_RESTART=1,MOZ_PROCESS_LOG=/var/folders/n_/0fvyfv593r95cvpfgs06bn_r0000gn/T/tmpAysYKWpidlog,XPCOM_MEM_BLOAT_LOG=/var/folders/n_/0fvyfv593r95cvpfgs06bn_r0000gn/T/tmpEAs4Pt/runtests_leaks.log" am instrument -w -e deviceroot /mnt/sdcard/tests -e class org.mozilla.fennec.tests.testAllPagesTab org.mozilla.roboexample.test/org.mozilla.fennec.FennecInstrumentationTestRunner'
Robocop derived process name: org.mozilla.fennec
INFO | automation.py | Application pid: 0
0 INFO SimpleTest START
1 INFO TEST-START | testAllPagesTab
2 INFO TEST-PASS | testAllPagesTab | Awesomebar URL typed properly - http://mochi.test:8888/tests/robocop/robocop_big_link.html should equal http://mochi.test:8888/tests/robocop/robocop_big_link.html
3 INFO TEST-PASS | testAllPagesTab | checking that all pages list exists - android.widget.ListView@4043ed48
4 INFO TEST-PASS | testAllPagesTab | all pages list has 5 children (the default bookmarks) - 5 should equal 5
5 INFO TEST-PASS | testAllPagesTab | TextView is filled in - Firefox: Customize with add-ons
6 INFO TEST-PASS | testAllPagesTab | TextView is filled in - https://addons.mozilla.org/en-US/android/
7 INFO TEST-PASS | testAllPagesTab | Correct number of ImageViews visible - 2 should equal 2
8 INFO TEST-PASS | testAllPagesTab | TextView is filled in - Firefox: Support
9 INFO TEST-PASS | testAllPagesTab | TextView is filled in - http://support.mozilla.org/en-US/mobile
10 INFO TEST-PASS | testAllPagesTab | Correct number of ImageViews visible - 2 should equal 2
11 INFO TEST-PASS | testAllPagesTab | TextView is filled in - Firefox Start
12 INFO TEST-PASS | testAllPagesTab | TextView is filled in - about:home
13 INFO TEST-PASS | testAllPagesTab | Correct number of ImageViews visible - 2 should equal 2
14 INFO TEST-PASS | testAllPagesTab | TextView is filled in - Firefox: About your browser
15 INFO TEST-PASS | testAllPagesTab | TextView is filled in - about:firefox
16 INFO TEST-PASS | testAllPagesTab | Correct number of ImageViews visible - 2 should equal 2
17 INFO TEST-PASS | testAllPagesTab | TextView is filled in - Big Link
18 INFO TEST-PASS | testAllPagesTab | TextView is filled in - http://mochi.test:8888/tests/robocop/robocop_big_link.html
19 INFO TEST-PASS | testAllPagesTab | Correct number of ImageViews visible - 1 should equal 1
20 INFO TEST-PASS | testAllPagesTab | Awesomebar URL stayed the same - http://mochi.test:8888/tests/robocop/robocop_big_link.html should equal http://mochi.test:8888/tests/robocop/robocop_big_link.html
INFO | automation.py | Application ran for: 0:00:46.972720
INFO | automation.py | Reading PID log: /var/folders/n_/0fvyfv593r95cvpfgs06bn_r0000gn/T/tmpAysYKWpidlog

Example output for testAllPagesTab which does have a failure:

FIRE PROC: '"MOZ_CRASHREPORTER=1,XPCOM_DEBUG_BREAK=stack,MOZ_CRASHREPORTER_NO_REPORT=1,NO_EM_RESTART=1,MOZ_PROCESS_LOG=/var/folders/n_/0fvyfv593r95cvpfgs06bn_r0000gn/T/tmptF0Hnepidlog,XPCOM_MEM_BLOAT_LOG=/var/folders/n_/0fvyfv593r95cvpfgs06bn_r0000gn/T/tmpXHgRov/runtests_leaks.log" am instrument -w -e deviceroot /mnt/sdcard/tests -e class org.mozilla.fennec.tests.testAllPagesTab org.mozilla.roboexample.test/org.mozilla.fennec.FennecInstrumentationTestRunner'
Robocop derived process name: org.mozilla.fennec
INFO | automation.py | Application pid: 0
0 INFO SimpleTest START
1 INFO TEST-START | testAllPagesTab
2 INFO TEST-PASS | testAllPagesTab | Awesomebar URL typed properly - http://mochi.test:8888/tests/robocop/robocop_big_link.html should equal http://mochi.test:8888/tests/robocop/robocop_big_link.html
3 INFO TEST-PASS | testAllPagesTab | checking that all pages list exists - android.widget.ListView@40652348
4 INFO TEST-UNEXPECTED-FAIL | testAllPagesTab | all pages list has 5 children (the default bookmarks) - got 4, expected 5
Exception caught during test!
junit.framework.AssertionFailedError: 4 INFO TEST-UNEXPECTED-FAIL | testAllPagesTab | all pages list has 5 children (the default bookmarks) - got 4, expected 5
	at junit.framework.Assert.fail(Assert.java:47)
	at org.mozilla.fennec.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:107)
	at org.mozilla.fennec.FennecMochitestAssert.ok(FennecMochitestAssert.java:136)
	at org.mozilla.fennec.FennecMochitestAssert.is(FennecMochitestAssert.java:142)
	at org.mozilla.fennec.tests.testAllPagesTab.testList(testAllPagesTab.java:61)
	at org.mozilla.fennec.tests.testAllPagesTab.testAllPagesTab(testAllPagesTab.java:50)
	at java.lang.reflect.Method.invokeNative(Native Method)
	at java.lang.reflect.Method.invoke(Method.java:507)
	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
	at org.mozilla.fennec.tests.BaseTest.runTest(BaseTest.java:120)
	at junit.framework.TestCase.runBare(TestCase.java:127)
	at junit.framework.TestResult$1.protect(TestResult.java:106)
	at junit.framework.TestResult.runProtected(TestResult.java:124)
	at junit.framework.TestResult.run(TestResult.java:109)
	at junit.framework.TestCase.run(TestCase.java:118)
	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:529)
	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1448)
5 INFO TEST-UNEXPECTED-FAIL | testAllPagesTab | Exception caught - junit.framework.AssertionFailedError: 4 INFO TEST-UNEXPECTED-FAIL | testAllPagesTab | all pages list has 5 children (the default bookmarks) - got 4, expected 5
6 INFO TEST-END | testAllPagesTab | finished in 23285ms
7 INFO TEST-START | Shutdown
8 INFO Passed: 2
9 INFO Failed: 2
10 INFO Todo: 0
11 INFO SimpleTest FINISHED

Rather than doing 

106         if (isError) {
107             junit.framework.Assert.fail(message);
108         }

we should try to catch the exception thrown by the Assert and capture the stack in a string using http://docs.oracle.com/javase/1.4.2/docs/api/java/lang/Throwable.html#printStackTrace%28java.io.PrintStream%29 and outputting the stack to the log but without using a pattern which matches a failure pattern.

Comment 1

[Geoff Brown [:gbrown]]

(In reply to Bob Clary [:bc:] from comment #0)
> When a non-fatal failure occurs during a single test,
> FennecMochitestAssert.java:_logMochitestResult will throw a 
> junit.framework.Assert.fail exception which will terminate the test which
> also results in a duplicate failure message in the log.

I am not sure I understand what you mean by "non-fatal failure". I think all of the robocop tests have been written from the perspective that any failure is fatal: If any step in the test fails, it's time to log the failure, give up and end the test.

(I agree that the duplicate failure message is inappropriate -- I would like to see that cleaned up.)

Comment 2

[Bob Clary [:bc] (inactive)]

By non-fatal, I mean a condition that doesn't prevent the remaining tests from running. INFO TEST-UNEXPECTED-FAIL | testAllPagesTab | all pages list has 5 children (the default bookmarks) - got 4, expected 5 doesn't seem like an error that should stop the remaining tests to not run.

Comment 3

[Andrew Halberstadt [:ahal]]

Mass closing mochitest bugs that haven't had activity in the past 5 years. Please re-open or file a new bug with modern context if this is still relevant.