1160351 - Java exception reporting fails with "Logcat is truncated" on adb (Android 4.3)

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Testing, defect)

Description

[Geoff Brown [:gbrown]]

+++ This bug was initially created as a clone of Bug #1160349 +++

http://ftp.mozilla.org/pub/mozilla.org/mobile/tinderbox-builds/fx-team-android-api-11/1430421556/fx-team_ubuntu64_vm_armv7_mobile_test-robocop-4-bm116-tests1-linux64-build12.txt.gz

14:03:53     INFO -  04-30 13:30:56.299 E/GeckoCrashHandler( 1514): >>> REPORTING UNCAUGHT EXCEPTION FROM THREAD 81 ("Thread-81")
14:03:53     INFO -  04-30 13:30:56.299 E/GeckoCrashHandler( 1514): java.lang.NullPointerException
14:03:53     INFO -  04-30 13:30:56.299 E/GeckoCrashHandler( 1514): 	at org.mozilla.gecko.gfx.GeckoLayerClient.setFirstPaintViewport(GeckoLayerClient.java:590)
14:03:53     INFO -  04-30 13:30:56.299 E/GeckoCrashHandler( 1514): 	at dalvik.system.NativeStart.run(Native Method)
14:03:53     INFO -  04-30 13:30:56.299 E/GeckoCrashHandler( 1514): Main thread (1) stack:
14:03:53     INFO -  04-30 13:30:56.299 E/GeckoCrashHandler( 1514):     android.os.MessageQueue.nativePollOnce(Native Method)
14:03:53     INFO -  04-30 13:30:56.329 E/GeckoCrashHandler( 1514):     android.os.MessageQueue.next(MessageQueue.java:132)
14:03:53     INFO -  04-30 13:30:56.329 E/GeckoCrashHandler( 1514):     android.os.Looper.loop(Looper.java:124)
14:03:53     INFO -  04-30 13:30:56.329 E/GeckoCrashHandler( 1514):     android.app.ActivityThread.main(ActivityThread.java:5103)
14:03:53     INFO -  04-30 13:30:56.339 E/GeckoCrashHandler( 1514):     java.lang.reflect.Method.invokeNative(Native Method)
14:03:53     INFO -  04-30 13:30:56.339 E/GeckoCrashHandler( 1514):     java.lang.reflect.Method.invoke(Method.java:525)
14:03:53     INFO -  04-30 13:30:56.339 E/GeckoCrashHandler( 1514):     com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
14:03:53     INFO -  04-30 13:30:56.349 E/GeckoCrashHandler( 1514):     com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
14:03:53     INFO -  04-30 13:30:56.349 E/GeckoCrashHandler( 1514):     dalvik.system.NativeStart.main(Native Method)


Why wasn't this reported as a Java exception in the test log?

http://hg.mozilla.org/mozilla-central/annotate/7723b15ea695/testing/mozbase/mozcrash/mozcrash/mozcrash.py#l299

Comment 1

[Geoff Brown [:gbrown]]

All these logs show "Logcat is truncated" from http://hg.mozilla.org/mozilla-central/annotate/7723b15ea695/testing/mozbase/mozcrash/mozcrash/mozcrash.py#l338.

Comment 2

[Geoff Brown [:gbrown]]

The sut version of dm.getLogcat returns an array of strings, one string per line of logcat content. The adb version returns a single string with newlines. check_for_java_exception is probably the only place this makes a difference.

Comment 3

[Geoff Brown [:gbrown]]

It turns out there is only one version of getLogcat, in devicemanager. The difference seems to be that sut shellCheckOutput("logcat") returns a string with \r line endings; adb with \n line endings.

Comment 4

[Geoff Brown [:gbrown]]

Attachment: improve newline handling in devicemanager getLogcat

Over sut, shell("logcat") returns a string with \r\n line endings; over adb, we get \n line endings. We need \n's to be returned from getLogcat, otherwise the logcat is dumped without line endings -- impossible to read.

This patch updates getLogcat to handle \r\n and \n: translate \r\n to \n if present, then split lines keeping line endings, so the \n is retained.

I also updated the "Logcat is truncated" message in mozcrash to be more descriptive; I found "Logcat is truncated" too easy to ignore/dismiss and generally unhelpful for failure diagnosis.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=91ac9f85ee0b

Comment 5

[Bob Clary [:bc] (inactive)]

Comment on attachment 8600902 [details] [diff] [review]
improve newline handling in devicemanager getLogcat

Review of attachment 8600902 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/mozbase/mozdevice/mozdevice/devicemanager.py
@@ +152,5 @@
>                    format="time",
>                    filterOutRegexps=[]):
>          """
> +        Returns the contents of the logcat file as a list of strings;
> +        each string ends in \n.

maybe:

Returns the contents of the logcat file as a list of '\n' terminated strings.

@@ +162,1 @@
>  

I got a little confused here. Originally lines was always a list, but with this patch it is first a string then a list. We could use a different variable for the string intermediate or it could be split by wrapping it in (), but it's kind of ugly.

lines = (self.shellCheckOutput(cmdline, root=self._logcatNeedsRoot).
         replace('\r\n', '\n').splitlines(True))

or

output = self.shellCheckOutput(cmdline, root=self._logcatNeedsRoot)
lines = output.replace('\r\n', '\n').splitlines(True)

This is ok the way it is, but if you do want to change it I'll leave the choice up to you.

What is the convention for single optional arguments? Should we use splitlines(keepends=True) ?

Comment 6

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/57c6c589cfa1

Comment 7

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/a6b50156107b

Comment 8

[Geoff Brown [:gbrown]]

Excellent improvement suggestions - thanks! I pushed with most comments addressed. 

keepends=True caused breakage:

10:32:08     INFO -  Traceback (most recent call last):
10:32:08     INFO -    File "/builds/slave/test/build/tests/mochitest/runtests.py", line 2275, in doTests
10:32:08     INFO -      quiet=options.quiet
10:32:08     INFO -    File "/builds/slave/test/build/tests/mochitest/runtestsremote.py", line 461, in runApp
10:32:08     INFO -      return self._automation.runApp(*args, **kwargs)
10:32:08     INFO -    File "/builds/slave/test/build/tests/mochitest/automation.py", line 844, in runApp
10:32:08     INFO -      crashed = self.checkForCrashes(os.path.join(profileDir, "minidumps"), symbolsPath)
10:32:08     INFO -    File "/builds/slave/test/build/tests/mochitest/remoteautomation.py", line 192, in checkForCrashes
10:32:08     INFO -      logcat = self._devicemanager.getLogcat(filterOutRegexps=fennecLogcatFilters)
10:32:08     INFO -    File "/builds/slave/test/build/tests/mochitest/devicemanager.py", line 161, in getLogcat
10:32:08     INFO -      lines = output.replace('\r\n', '\n').splitlines(keepends=True)
10:32:08     INFO -  TypeError: splitlines() takes no keyword arguments
10:32:08     INFO -  363 ERROR Automation Error: Received unexpected exception while running application

I pushed a bustage fix -- Comment 7.

Comment 9

[Bob Clary [:bc] (inactive)]

Crap, sorry about that. What version of Python are they running?

Comment 10

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/57c6c589cfa1
https://hg.mozilla.org/mozilla-central/rev/a6b50156107b