1093137 - Exceptions thrown during Robocop test not always fully logged

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Testing, defect)

Description

[Geoff Brown [:gbrown]]

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

[Chris Manchester (limited bugmail, email directly)]

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?

Comment 2

[Geoff Brown [:gbrown]]

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().

Comment 3

[Geoff Brown [:gbrown]]

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

Comment 4

[Geoff Brown [:gbrown]]

Attachment: log stack traces on exception

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

Comment 5

[Chris Manchester (limited bugmail, email directly)]

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.

Comment 6

[Geoff Brown [:gbrown]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2aa5fe6a3393

Comment 7

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/2aa5fe6a3393