Closed
Bug 1093137
Opened 10 years ago
Closed 10 years ago
Exceptions thrown during Robocop test not always fully logged
Categories
(Firefox for Android Graveyard :: Testing, defect)
Tracking
(Not tracked)
RESOLVED
FIXED
Firefox 37
People
(Reporter: gbrown, Assigned: gbrown)
References
Details
Attachments
(1 file)
(deleted),
patch
|
chmanchester
:
review+
|
Details | Diff | Splinter Review |
In http://ftp.mozilla.org/pub/mozilla.org/mobile/tinderbox-builds/mozilla-beta-android/1414934018/mozilla-beta_panda_android_test-robocop-2-bm100-tests1-panda-build70.txt.gz, the robocop test fails due to a NullPointerException, but there is no stack trace shown anywhere:
06:51:50 INFO - TEST-START | testLoad
06:51:50 INFO - TEST-PASS | testLoad | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready
06:51:50 INFO - EventExpecter: no longer listening for Gecko:Ready
06:51:50 INFO - 0 ERROR Exception caught during test! - java.lang.NullPointerException
06:51:50 WARNING - TEST-UNEXPECTED-FAIL | testLoad | Exception caught - java.lang.NullPointerException
06:51:50 INFO - TEST-OK | testLoad | took 6275ms
06:51:50 INFO - TEST-START | Shutdown
06:51:50 INFO - Passed: 1
06:51:50 INFO - Failed: 1
06:51:52 INFO - 11-02 06:51:47.109 D/GeckoToolbar( 4481): onTabChanged: STOP
06:51:52 INFO - 11-02 06:51:47.109 D/GeckoBrowserApp( 4481): BrowserApp.onTabChanged: 0: STOP
06:51:52 INFO - 11-02 06:51:47.156 I/Robocop ( 4481): {"action":"log","message":"Exception caught during test! - java.lang.NullPointerException","time":1414911107128,"pid":null,"level":"error","source":"robocop","thread":null}
06:51:52 INFO - 11-02 06:51:47.156 I/Robocop ( 4481): {"message":"java.lang.NullPointerException","time":1414911107165,"expected":"PASS","source":"robocop","status":"FAIL","test":"testLoad","thread":null,"subtest":"Exception caught","action":"test_status","pid":null}
06:51:52 INFO - 11-02 06:51:47.156 I/Robocop ( 4481): {"message":"finished in 6274ms","time":1414911107167,"source":"robocop","status":"OK","test":"testLoad","thread":null,"action":"test_end","pid":null}
I have not seen this before (but I haven't looked closely at many robocop logs lately) -- I wonder if this only happens on mozilla-beta, or if it only happens in this test, or something like that.
Comment 1•10 years ago
|
||
It looks like this comes from: http://hg.mozilla.org/mozilla-central/annotate/0b81c10a9074/mobile/android/base/tests/BaseTest.java#l169
Throwable's toString doesn't look like it includes a stack trace, is this usually picked up somewhere after it's re-thrown?
Assignee | ||
Comment 2•10 years ago
|
||
I think this changed with bug 1034267 (structured logging for Robocop).
Previously, FennecMochitestAssert.dumpLog(String, Throwable) called FennecNativeDriver.log(LogLevel, String, Throwable), which calls Throwable.printStackTrace(). Now we just call Throwable.toString().
Assignee | ||
Comment 3•10 years ago
|
||
btw, we still log some stacks to logcat. For example:
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): ----- begin exception -----
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045):
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): junit.framework.AssertionFailedError: TEST-UNEXPECTED-FAIL | testLinkContextMenu | Exception caught - junit.framework.AssertionFailedError: Click can not be completed!
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at junit.framework.Assert.fail(Assert.java:50)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:122)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:144)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:170)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at junit.framework.TestCase.runBare(TestCase.java:134)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at junit.framework.TestResult$1.protect(TestResult.java:115)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at junit.framework.TestResult.runProtected(TestResult.java:133)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at junit.framework.TestResult.run(TestResult.java:118)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at junit.framework.TestCase.run(TestCase.java:124)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:190)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:175)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:555)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1661)
05:01:51 INFO - 11-05 12:28:46.815 I/TestRunner( 2045): ----- end exception -----
See http://hg.mozilla.org/mozilla-central/annotate/a458860efad7/build/mobile/robocop/FennecMochitestAssert.java#l122
Assignee | ||
Updated•10 years ago
|
Assignee | ||
Comment 4•10 years ago
|
||
This transforms:
TEST-PASS | testAboutHomeVisibility | The toolbar is in the editing state -
1 ERROR Exception caught during test! - java.lang.ClassCastException: org.mozilla.gecko.widget.ThemedImageView cannot be cast to android.widget.ImageButton
TEST-UNEXPECTED-FAIL | testAboutHomeVisibility | Exception caught - java.lang.ClassCastException: org.mozilla.gecko.widget.ThemedImageView cannot be cast to android.widget.ImageButton
Into:
TEST-PASS | testAboutHomeVisibility | The toolbar is in the editing state -
1 ERROR Exception caught during test! - java.lang.ClassCastException: org.mozilla.gecko.widget.ThemedImageView cannot be cast to android.widget.ImageButton
at org.mozilla.gecko.tests.components.ToolbarComponent.getEditCancelButton(ToolbarComponent.java:116)
at org.mozilla.gecko.tests.components.ToolbarComponent.dismissEditingMode(ToolbarComponent.java:178)
at org.mozilla.gecko.tests.testAboutHomeVisibility.testAboutHomeVisibility(testAboutHomeVisibility.java:38)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:511)
at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:214)
at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:199)
at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
at org.mozilla.gecko.tests.UITest.runTest(UITest.java:102)
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:537)
at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1551)
TEST-UNEXPECTED-FAIL | testAboutHomeVisibility | Exception caught - java.lang.ClassCastException: org.mozilla.gecko.widget.ThemedImageView cannot be cast to android.widget.ImageButton
Attachment #8529831 -
Flags: review?(cmanchester)
Comment 5•10 years ago
|
||
Comment on attachment 8529831 [details] [diff] [review]
log stack traces on exception
Review of attachment 8529831 [details] [diff] [review]:
-----------------------------------------------------------------
::: build/mobile/robocop/FennecMochitestAssert.java
@@ +39,5 @@
> public void dumpLog(String message, Throwable t) {
> + Writer sw = new StringWriter();
> + PrintWriter pw = new PrintWriter(sw);
> + t.printStackTrace(pw);
> + mLogger.error(message + " - " + sw.toString());
Ideally the stack would end up in the test_status message logged for the failure so we can associate it with a test later, but I'm not sure exactly how to do that, and this looks like it fixes the regression, so this is fine.
Attachment #8529831 -
Flags: review?(cmanchester) → review+
Assignee | ||
Comment 6•10 years ago
|
||
Comment 7•10 years ago
|
||
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 37
Updated•4 years ago
|
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in
before you can comment on or make changes to this bug.
Description
•