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.

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?

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

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

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