Closed Bug 993813 Opened 7 years ago Closed 5 years ago

Android robocop-2 after testUITelemetry, "DMError: Automation Error: Error processing command 'kill org.mozilla.fennec'; err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'"

Categories

(Firefox for Android :: Testing, defect)

ARM
Android
defect
Not set
normal

Tracking

()

RESOLVED WONTFIX
Tracking Status
firefox30 --- unaffected
firefox31 --- disabled
firefox32 --- disabled
firefox-esr24 --- unaffected

People

(Reporter: philor, Unassigned)

Details

(Keywords: intermittent-failure)

I'm not quite sure, but I think the error message in the summary is saying something about some sort of difficulty with a task that might or might not have to do with killing org.mozilla.fennec.

This goes back several days, maybe a week, because nobody wants to actually have to file it. Might be possible to get a random guess at the start time by looking at misstars in bug 975867, since we don't always have enough shame to stop us from starring an Android failure as a bug with b2g as the second word in the summary.

https://tbpl.mozilla.org/php/getParsedLog.php?id=37476312&tree=Mozilla-Central
Android 2.2 Armv6 Tegra mozilla-central opt test robocop-2 on 2014-04-08 16:42:18 PDT for push 5811efc11011
slave: tegra-270

38 INFO TEST-INFO | testUITelemetry | (xpcshell/head.js) - exiting test
EventExpecter: no longer listening for Robocop:JS
Unregistered listener for Robocop:JS
39 INFO TEST-END | testUITelemetry | finished in 10050ms
40 INFO TEST-START | Shutdown
41 INFO Passed: 24
42 INFO Failed: 0
43 INFO Todo: 0
44 INFO SimpleTest FINISHED

Traceback (most recent call last):
  File "/builds/tegra-270/test/build/tests/mochitest/runtests.py", line 1158, in runTests
    hide_subtests=options.hide_subtests
  File "mochitest/runtestsremote.py", line 549, in runApp
  File "/builds/tegra-270/test/build/tests/mochitest/automation.py", line 860, in runApp
    status = self.waitForFinish(proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath)
  File "/builds/tegra-270/test/build/tests/mochitest/remoteautomation.py", line 86, in waitForFinish
    proc.kill()
  File "/builds/tegra-270/test/build/tests/mochitest/remoteautomation.py", line 290, in kill
    self.dm.killProcess(self.procName)
  File "/builds/tegra-270/test/build/tests/mochitest/devicemanagerSUT.py", line 550, in killProcess
    raise err
DMError: Automation Error: Error processing command 'kill org.mozilla.fennec'; err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'
Automation Error: Received unexpected exception while running application
Logcat suggests that org.mozilla.fennec will not die, neither on normal quit/end-of-test, nor on kill:

04-10 03:14:06.049 I/Robocop ( 7452): 39 INFO TEST-END | testUITelemetry | finished in 6757ms
04-10 03:14:06.049 I/Robocop ( 7452): 40 INFO TEST-START | Shutdown
04-10 03:14:06.049 I/Robocop ( 7452): 41 INFO Passed: 24
04-10 03:14:06.049 I/Robocop ( 7452): 42 INFO Failed: 0
04-10 03:14:06.049 I/Robocop ( 7452): 43 INFO Todo: 0
04-10 03:14:06.059 I/Robocop ( 7452): 44 INFO SimpleTest FINISHED
04-10 03:14:06.079 I/GeckoDump( 7452): Robocop:Quit received -- requesting quit
04-10 03:14:06.142 E/Profiler( 7452): BPUnw: [8 total] thread_register_for_profiling(me=0x2d9060, stacktop=0x578f9dcf)
04-10 03:14:06.409 D/GeckoThumbnailHelper( 7452): Using new thumbnail size: 242544 (width 326)
04-10 03:14:06.409 D/GeckoThumbnailHelper( 7452): Sending thumbnail event: 326, 186
04-10 03:14:06.792 E/Profiler( 7452): BPUnw: [7 total] thread_unregister_for_profiling(me=0x2d9060) 
04-10 03:16:10.749 I/global  ( 1482): Default buffer size used in BufferedInputStream constructor. It would be better to be explicit if an 8k buffer is required.
04-10 03:18:59.951 I/SUTAgentAndroid( 1482): 10.26.84.20 : ps
04-10 03:19:00.039 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:19:00.069 I/SUTAgentAndroid( 1482): 10.26.84.20 : isdir /mnt/sdcard/tests/logs
04-10 03:19:00.089 I/SUTAgentAndroid( 1482): 10.26.84.20 : cd /mnt/sdcard/tests/logs
04-10 03:19:00.109 I/SUTAgentAndroid( 1482): 10.26.84.20 : ls
04-10 03:19:00.129 I/SUTAgentAndroid( 1482): 10.26.84.20 : pull /mnt/sdcard/tests/logs/mochitest.log 0
04-10 03:19:20.149 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:19:40.175 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:20:00.199 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:20:00.249 I/SUTAgentAndroid( 1482): 10.26.84.20 : isdir /mnt/sdcard/tests/logs
04-10 03:20:00.269 I/SUTAgentAndroid( 1482): 10.26.84.20 : cd /mnt/sdcard/tests/logs
04-10 03:20:00.299 I/SUTAgentAndroid( 1482): 10.26.84.20 : ls
04-10 03:20:00.319 I/SUTAgentAndroid( 1482): 10.26.84.20 : pull /mnt/sdcard/tests/logs/mochitest.log 6397
04-10 03:20:20.389 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:20:40.415 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:21:00.443 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:21:00.499 I/SUTAgentAndroid( 1482): 10.26.84.20 : isdir /mnt/sdcard/tests/logs
04-10 03:21:00.529 I/SUTAgentAndroid( 1482): 10.26.84.20 : cd /mnt/sdcard/tests/logs
04-10 03:21:00.549 I/SUTAgentAndroid( 1482): 10.26.84.20 : ls
04-10 03:21:00.569 I/SUTAgentAndroid( 1482): 10.26.84.20 : pull /mnt/sdcard/tests/logs/mochitest.log 6397
04-10 03:21:19.171 I/global  ( 1482): Default buffer size used in BufferedInputStream constructor. It would be better to be explicit if an 8k buffer is required.
04-10 03:21:20.641 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:21:40.670 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:22:00.699 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:22:00.759 I/SUTAgentAndroid( 1482): 10.26.84.20 : isdir /mnt/sdcard/tests/logs
04-10 03:22:00.789 I/SUTAgentAndroid( 1482): 10.26.84.20 : cd /mnt/sdcard/tests/logs
04-10 03:22:00.809 I/SUTAgentAndroid( 1482): 10.26.84.20 : ls
04-10 03:22:00.829 I/SUTAgentAndroid( 1482): 10.26.84.20 : pull /mnt/sdcard/tests/logs/mochitest.log 6397
04-10 03:22:20.905 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:22:40.929 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:23:00.959 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:23:01.039 I/SUTAgentAndroid( 1482): 10.26.84.20 : isdir /mnt/sdcard/tests/logs
04-10 03:23:01.059 I/SUTAgentAndroid( 1482): 10.26.84.20 : cd /mnt/sdcard/tests/logs
04-10 03:23:01.079 I/SUTAgentAndroid( 1482): 10.26.84.20 : ls
04-10 03:23:01.109 I/SUTAgentAndroid( 1482): 10.26.84.20 : pull /mnt/sdcard/tests/logs/mochitest.log 6397
04-10 03:23:21.169 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:23:41.192 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:24:01.224 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:24:01.289 I/SUTAgentAndroid( 1482): 10.26.84.20 : isdir /mnt/sdcard/tests/logs
04-10 03:24:01.319 I/SUTAgentAndroid( 1482): 10.26.84.20 : cd /mnt/sdcard/tests/logs
04-10 03:24:01.339 I/SUTAgentAndroid( 1482): 10.26.84.20 : ls
04-10 03:24:01.359 I/SUTAgentAndroid( 1482): 10.26.84.20 : pull /mnt/sdcard/tests/logs/mochitest.log 6397
04-10 03:24:21.430 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:24:41.459 I/SUTAgentAndroid( 1482): 10.26.84.20 : isdir /mnt/sdcard/tests/logs
04-10 03:24:41.519 I/SUTAgentAndroid( 1482): 10.26.84.20 : cd /mnt/sdcard/tests/logs
04-10 03:24:41.549 I/SUTAgentAndroid( 1482): 10.26.84.20 : ls
04-10 03:24:41.569 I/SUTAgentAndroid( 1482): 10.26.84.20 : pull /mnt/sdcard/tests/logs/mochitest.log 6397
04-10 03:24:41.620 I/SUTAgentAndroid( 1482): 10.26.84.20 : activity
04-10 03:24:41.639 I/SUTAgentAndroid( 1482): 10.26.84.20 : ps
04-10 03:24:41.669 I/SUTAgentAndroid( 1482): 10.26.84.20 : kill org.mozilla.fennec
04-10 03:24:41.769 D/Zygote  (  939): Process 7533 terminated by signal (15)
04-10 03:24:41.769 I/ActivityManager( 1020): Process org.mozilla.fennec.UpdateService (pid 7533) has died.
04-10 03:24:43.909 I/SUTAgentAndroid( 1482): 10.26.84.20 : ps
04-10 03:24:43.939 I/SUTAgentAndroid( 1482): 10.26.84.20 : kill org.mozilla.fennec
04-10 03:24:46.089 I/SUTAgentAndroid( 1482): 10.26.84.20 : ps
04-10 03:24:46.119 I/SUTAgentAndroid( 1482): 10.26.84.20 : kill org.mozilla.fennec
04-10 03:24:48.279 I/SUTAgentAndroid( 1482): 10.26.84.20 : ps
04-10 03:24:48.309 I/SUTAgentAndroid( 1482): 10.26.84.20 : kill org.mozilla.fennec
04-10 03:24:50.459 I/SUTAgentAndroid( 1482): 10.26.84.20 : ps
04-10 03:24:50.489 I/SUTAgentAndroid( 1482): 10.26.84.20 : kill org.mozilla.fennec
04-10 03:24:52.649 I/SUTAgentAndroid( 1482): 10.26.84.20 : isdir /mnt/sdcard/tests/logs
04-10 03:24:52.679 I/SUTAgentAndroid( 1482): 10.26.84.20 : cd /mnt/sdcard/tests/logs
04-10 03:24:52.699 I/SUTAgentAndroid( 1482): 10.26.84.20 : ls
(In reply to Phil Ringnalda (:philor) from comment #0)
> This goes back several days, maybe a week, because nobody wants to actually

Maybe longer:

bholley
https://tbpl.mozilla.org/php/getParsedLog.php?id=35519435&tree=Try
Android 2.2 Tegra try opt test mochitest-2 on 2014-03-03 01:13:03
revision: 8d8b86542e25
slave: tegra-181

but that is on mochitest. 

The earliest I see on robocop-2 is:

edmorley
https://tbpl.mozilla.org/php/getParsedLog.php?id=37148864&tree=Mozilla-Inbound
Android 2.2 Tegra mozilla-inbound opt test robocop-2 on 2014-04-02 09:32:17
revision: 69b7bd12aa94
slave: tegra-192

DMError: Automation Error: Error processing command 'kill org.mozilla.fennec'; err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'
Automation Error: Received unexpected exception while running application
Mochi-Remote ERROR   | Automation Error: Missing end of test marker (process crashed?)

(This pre-dates the fix for bug 986738, which I would otherwise suspect as related.)
Possibly related...There are also many failures in bug 918759 ("Shutdown | application timed out after 330 seconds with no output") which follow testUITelemetry.

edmorley
https://tbpl.mozilla.org/php/getParsedLog.php?id=37580033&tree=Fx-Team
Android 4.0 Panda fx-team opt test robocop-5 on 2014-04-10 08:52:23
revision: c821c23327da
slave: panda-0499

TEST-UNEXPECTED-FAIL | Shutdown | application timed out after 330 seconds with no output
Return code: 2

edmorley
https://tbpl.mozilla.org/php/getParsedLog.php?id=37581276&tree=Mozilla-Inbound
Android 4.0 Panda mozilla-inbound opt test robocop-5 on 2014-04-10 09:09:50
revision: 22c2638791cf
slave: panda-0109

TEST-UNEXPECTED-FAIL | Shutdown | application timed out after 330 seconds with no output
Return code: 2

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=37598173&tree=Mozilla-Inbound
Android 4.0 Panda mozilla-inbound opt test robocop-5 on 2014-04-10 14:19:20
revision: f2b8543b60ab
slave: panda-0506

TEST-UNEXPECTED-FAIL | Shutdown | application timed out after 330 seconds with no output
Return code: 2

These often contain ANR reports and something like:

14:45:07     INFO -  04-10 14:41:08.921 I/Process ( 1402): Sending signal. PID: 1890 SIG: 3
14:45:07     INFO -  04-10 14:41:08.921 I/dalvikvm( 1890): threadid=3: reacting to signal 3
14:45:07     INFO -  04-10 14:41:08.921 I/dalvikvm( 1890): Wrote stack traces to '/data/anr/traces.txt'
14:45:07     INFO -  04-10 14:41:08.945 E/ActivityManager( 1402): ANR in org.mozilla.fennec
14:45:07     INFO -  04-10 14:41:08.945 E/ActivityManager( 1402): Reason: Executing service org.mozilla.fennec/org.mozilla.gecko.background.healthreport.upload.HealthReportUploadService
Chenxia, could you take a look at this?
Flags: needinfo?(liuche)
Since we're apparently going to merge this to aurora, I'll need to be able to star it there.
Summary: Android 2.2 robocop-2 after testUITelemetry, "DMError: Automation Error: Error processing command 'kill org.mozilla.fennec'; err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'" → Android 2.2 robocop-2 after testUITelemetry, "DMError: Automation Error: Error processing command 'kill org.mozilla.fennec' (or org.mozilla.fennec_aurora); err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'"
But alas, it won't be that easy, since it's a phrase search, so I'll need to clone this to an aurora bug next week.
Summary: Android 2.2 robocop-2 after testUITelemetry, "DMError: Automation Error: Error processing command 'kill org.mozilla.fennec' (or org.mozilla.fennec_aurora); err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'" → Android 2.2 robocop-2 after testUITelemetry, "DMError: Automation Error: Error processing command 'kill org.mozilla.fennec'; err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'"
I'm not sure what could be causing this, but looks like this goes back to at least 2/24 (unfortunately there are no logs for that revision - maybe something that got backed out?) : https://bugzilla.mozilla.org/show_bug.cgi?id=975867#c1

The two signatures I've seen are:
Automation Error: Missing end of test marker (process crashed?)
  - (just a few) after testPromptGridInput or testBookmarkFolders

Automation Error: Received unexpected exception while running application
  - (majority) after testUITelemetry
Flags: needinfo?(liuche)
Not backed out, just the way we delete logs both from tbpl and from ftp.m.o after 30 days.
Geoff, can you help with this by chance? Now that this is on Aurora too, this is going to be a manual star given the error message it gives. I'm honestly inclined to just disable the test at that point.
Flags: needinfo?(gbrown)
This is Tegra-only, right?

How about disabling this test on Tegras?

[testUITelemetry]
skip-if = android_version == "8"
Flags: needinfo?(gbrown)
Sold!

https://hg.mozilla.org/integration/fx-team/rev/95515135a1c4
Flags: needinfo?(ryanvm)
Whiteboard: [test disabled on Android 2.2][leave open]
Assignee: nobody → gbrown
After testUITelemetry was updated in bug 1004668, I could no longer reproduce this failure on Android 2.2, so re-enabled the test on 2.2.
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → DUPLICATE
Whiteboard: [test disabled on Android 2.2][leave open]
Duplicate of bug: 1004668
Status: RESOLVED → REOPENED
Resolution: DUPLICATE → ---
Hoping the frequency is reduced, I'll leave this enabled. 

I still think this has the same cause as bug 1004668, but I don't have hard evidence of that.
Assignee: gbrown → nobody
Summary: Android 2.2 robocop-2 after testUITelemetry, "DMError: Automation Error: Error processing command 'kill org.mozilla.fennec'; err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'" → Android 2.2 after testUITelemetry, "DMError: Automation Error: Error processing command 'kill org.mozilla.fennec'; err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'"
Summary: Android 2.2 after testUITelemetry, "DMError: Automation Error: Error processing command 'kill org.mozilla.fennec'; err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'" → Android robocop-2 after testUITelemetry, "DMError: Automation Error: Error processing command 'kill org.mozilla.fennec'; err='Unable to kill org.mozilla.fennec (couldn't kill org.mozilla.fennec)'"
This seems to only affect Pandas / Android 4.0.
Status: REOPENED → RESOLVED
Closed: 7 years ago5 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.