1156422 - Android 4.3 DMError: Non-zero return code for command: ['/system/bin/logcat'

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Geoff Brown [:gbrown]]

http://ftp.mozilla.org/pub/mozilla.org/mobile/try-builds/[e-mail]-13c7ad7a0047/try-android-api-11/try_ubuntu64_vm_armv7_mobile_test-robocop-2-bm123-tests1-linux64-build5.txt.gz

11:35:55     INFO -  Traceback (most recent call last):
11:35:55     INFO -    File "/builds/slave/test/build/tests/mochitest/runtests.py", line 2266, in doTests
11:35:55     INFO -      quiet=options.quiet
11:35:55     INFO -    File "/builds/slave/test/build/tests/mochitest/runtestsremote.py", line 461, in runApp
11:35:55     INFO -      return self._automation.runApp(*args, **kwargs)
11:35:55     INFO -    File "/builds/slave/test/build/tests/mochitest/automation.py", line 850, in runApp
11:35:55     INFO -      crashed = self.checkForCrashes(os.path.join(profileDir, "minidumps"), symbolsPath)
11:35:55     INFO -    File "/builds/slave/test/build/tests/mochitest/remoteautomation.py", line 183, in checkForCrashes
11:35:55     INFO -      logcat = self._devicemanager.getLogcat(filterOutRegexps=fennecLogcatFilters)
11:35:55     INFO -    File "/builds/slave/test/build/tests/mochitest/devicemanager.py", line 159, in getLogcat
11:35:55     INFO -      root=self._logcatNeedsRoot).split('\r')
11:35:55     INFO -    File "/builds/slave/test/build/tests/mochitest/devicemanager.py", line 397, in shellCheckOutput
11:35:55     INFO -      raise DMError("Non-zero return code for command: %s (output: '%s', retval: '%s')" % (cmd, output, retval))
11:35:55     INFO -  DMError: Non-zero return code for command: ['/system/bin/logcat', '-v', 'time', '-d', 'dalvikvm:I', 'ConnectivityService:S', 'WifiMonitor:S', 'WifiStateTracker:S', 'wpa_supplicant:S', 'NetworkStateTracker:S'] (output: '', retval: 'None')
11:35:55     INFO -  0 ERROR Automation Error: Received unexpected exception while running application

This is a DMError while retrieving the logcat in order to check for Java exceptions. The associated "full logcat" was retrieved, and shows nothing amiss.

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/c95af64ca69cd0047f54fe24be255581fb8ca140eb0bb559376c6fe0ec0e6a25e8016d7315aa4f35d81b21ddda6664d6d116f3ecba791e9358381ae711a2a38b

I have not seen many of these, but I think I have seen it before.

Comment 1

[Geoff Brown [:gbrown]]

Another instance:

http://ftp.mozilla.org/pub/mozilla.org/mobile/try-builds/[e-mail]-bed957753749/try-android-api-11/try_ubuntu64_vm_armv7_mobile_test-robocop-4-bm115-tests1-linux64-build10.txt.gz

Comment 2

[Geoff Brown [:gbrown]]

Attachment: re-try getLogcat in checkForCrashes

I cannot think of what could be going wrong here. :bc -- do you have any ideas? In my experience, "adb logcat" just works. Maybe something to do with timing relative to the previous operations (checking for anrs and tombstones?)? Maybe a problem with the Android 4.3 emulator environment?

Anyway, here's a speculative fix where I'm hoping this is a temporary condition that will go away if I just try again.

Comment 3

[Bob Clary [:bc] (inactive)]

This is an emulator with the standard android su? The devicemanagerADB, defines the _logcatNeedsRoot as True which means when the command is executed, it will attempt to use the su -c form. Does your emulator contain a version of su that supports su -c command or is does it support the android su 0 command form?

Perhaps I should have finished bug 1148395

If this is a su related issue the patch won't help. Can you check which version of su you have?

You could also try to over-ride the default logcatNeedsRoot = True to be False so su isn't invoked for logcat.

Comment 4

[Geoff Brown [:gbrown]]

This is the su from an AOSP engineering build of 4.3. su -c seems to work.

gbrown@mozpad:~/src$ adb shell id
uid=0(root) gid=0(root)
gbrown@mozpad:~/src$ adb shell su -c id
uid=0(root) gid=0(root)
gbrown@mozpad:~/src$ adb shell /system/bin/logcat -d | tail
D/dalvikvm(   88): GC_CONCURRENT freed 523K, 13% free 4902K/5604K, paused 5ms+5ms, total 55ms
D/dalvikvm(   88): GC_CONCURRENT freed 490K, 13% free 4902K/5604K, paused 3ms+4ms, total 45ms
D/dalvikvm(   88): GC_CONCURRENT freed 491K, 13% free 4901K/5604K, paused 3ms+4ms, total 45ms
D/dalvikvm(   88): GC_CONCURRENT freed 522K, 13% free 4902K/5604K, paused 4ms+4ms, total 54ms
D/ConnectivityService(   88): [CheckMp] isMobileOk: X result=1
D/ConnectivityService(   88): [CheckMp] onPostExecute: result=1
D/ConnectivityService(   88): CheckMp.onComplete: result=1
D/ConnectivityService(   88): CheckMp.onComplete: ignore, connected or no connection
W/SystemClock(   88): Unable to set rtc to 1429638542: Invalid argument
D/SystemClock(   88): Setting time of day to sec=1429638542
gbrown@mozpad:~/src$ adb shell su -c /system/bin/logcat -d | tail
D/dalvikvm(   88): GC_CONCURRENT freed 523K, 13% free 4902K/5604K, paused 5ms+5ms, total 55ms
D/dalvikvm(   88): GC_CONCURRENT freed 490K, 13% free 4902K/5604K, paused 3ms+4ms, total 45ms
D/dalvikvm(   88): GC_CONCURRENT freed 491K, 13% free 4901K/5604K, paused 3ms+4ms, total 45ms
D/dalvikvm(   88): GC_CONCURRENT freed 522K, 13% free 4902K/5604K, paused 4ms+4ms, total 54ms
D/ConnectivityService(   88): [CheckMp] isMobileOk: X result=1
D/ConnectivityService(   88): [CheckMp] onPostExecute: result=1
D/ConnectivityService(   88): CheckMp.onComplete: result=1
D/ConnectivityService(   88): CheckMp.onComplete: ignore, connected or no connection
W/SystemClock(   88): Unable to set rtc to 1429638542: Invalid argument
D/SystemClock(   88): Setting time of day to sec=1429638542

Although logcatNeedsRoot, I think we also _haveRootShell, so I suspect su -c is not being used (but I'm not sure). Also, note that this is an infrequent intermittent failure -- I would not expect su to be flaky (but I don't know what is flaky...so anything is possible!)

Comment 5

[Bob Clary [:bc] (inactive)]

Comment on attachment 8595001 [details] [diff] [review]
re-try getLogcat in checkForCrashes

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

too bad this file doesn't dump more information when you get a DMError, but this is consistent with previous error reporting.

Looks ok. Let's try it and see if it help you.

Comment 6

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/25f042163963

Comment 7

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/25f042163963