Closed Bug 1605886 Opened 6 years ago Closed 6 years ago

Intermittent Bustage mozdevice.adb.ADBProcessError: args: adb wait-for-device shell su -c "am force-stop org.mozilla.geckoview_example", exitcode: 224, stdout: cmd: Failure calling service activity: Broken pipe (32)

Categories

(Testing :: Condprofile, defect)

Product:
Testing
Component:
Condprofile
Version:
Version 3
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1608604

People

(Reporter: intermittent-bug-filer, Assigned: tarek)

References

Details

(Keywords: intermittent-failure)

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=282524078&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/f0J5A2BbQx-u7DtrXfDBvw/runs/0/artifacts/public/logs/live_backing.log

[task 2019-12-24T18:27:08.798Z] [2019-12-24T18:12:02.036368] Writing geckodriver logs in /builds/task_1577210378/archive/geckodriver-heavy-expert.log
[task 2019-12-24T18:27:08.798Z] [2019-12-24T18:12:02.046934] Running Webdriver on port 53679
[task 2019-12-24T18:27:08.798Z] [2019-12-24T18:12:02.047139] Running Marionette on port 2828
[task 2019-12-24T18:27:08.798Z] [2019-12-24T18:12:02.047199] Connecting on Android device
[task 2019-12-24T18:27:08.798Z] [2019-12-24T18:12:02.207265] Running the heavy scenario
[task 2019-12-24T18:27:08.798Z] 1/150 https://search.yahoo.com/yhs/search?p=hardboard
[task 2019-12-24T18:27:08.798Z] 2/150 https://www.bing.com/search?q=create+list+of+nounsforgery
...
[task 2019-12-24T18:27:10.583Z] 118/150 https://www.google.com/search?q=conclusion
[task 2019-12-24T18:27:10.583Z] 119/150 https://www.google.com/search?q=appendix
[task 2019-12-24T18:27:10.583Z] 120/150 https://www.google.com/search?q=corner
[task 2019-12-24T18:27:10.583Z] 121/150 https://www.youtube.com/results?search_query=reparation
[task 2019-12-24T18:27:10.583Z] 2019-12-24 18:27.08 error data={'error': 'unknown error', 'message': 'Failed to decode response from marionette', 'stacktrace': ''} message=Failed to decode response from marionette stacktrace= status=500 type=<class 'arsenic.errors.UnknownError'>
[task 2019-12-24T18:27:10.583Z] --- Logging error ---
[task 2019-12-24T18:27:10.583Z] Traceback (most recent call last):
[task 2019-12-24T18:27:10.583Z] File "condprof/../condprof/creator.py", line 62, in run
[task 2019-12-24T18:27:10.583Z] metadata = await self.build_profile(device, headless)
[task 2019-12-24T18:27:10.583Z] File "condprof/../condprof/creator.py", line 131, in build_profile
[task 2019-12-24T18:27:10.583Z] self.env.stop_browser()
[task 2019-12-24T18:27:10.583Z] File "condprof/../condprof/android.py", line 257, in stop_browser
[task 2019-12-24T18:27:10.583Z] self.device.stop_browser()
[task 2019-12-24T18:27:10.583Z] File "condprof/../condprof/android.py", line 145, in stop_browser
[task 2019-12-24T18:27:10.583Z] self.device.stop_application(self.app_name, root=True)
[task 2019-12-24T18:27:10.583Z] File "/builds/task_1577210378/fetches/condprofile/lib/python3.6/site-packages/mozdevice/adb.py", line 3370, in stop_application
[task 2019-12-24T18:27:10.583Z] timeout=timeout, root=root)
[task 2019-12-24T18:27:10.583Z] File "/builds/task_1577210378/fetches/condprofile/lib/python3.6/site-packages/mozdevice/adb.py", line 1623, in shell_output
[task 2019-12-24T18:27:10.583Z] raise ADBProcessError(adb_process)
[task 2019-12-24T18:27:10.583Z] mozdevice.adb.ADBProcessError: args: adb wait-for-device shell su -c "am force-stop org.mozilla.geckoview_example", exitcode: 224, stdout: cmd: Failure calling service activity: Broken pipe (32)
[task 2019-12-24T18:27:10.583Z]
[task 2019-12-24T18:27:10.583Z] During handling of the above exception, another exception occurred:
[task 2019-12-24T18:27:10.583Z]
[task 2019-12-24T18:27:10.583Z] Traceback (most recent call last):
[task 2019-12-24T18:27:10.583Z] File "/usr/lib/python3.6/logging/init.py", line 996, in emit
[task 2019-12-24T18:27:10.583Z] stream.write(msg)
[task 2019-12-24T18:27:10.583Z] UnicodeEncodeError: 'ascii' codec can't encode character '\u201c' in position 182458: ordinal not in range(128)
[task 2019-12-24T18:27:10.583Z] Call stack:
[task 2019-12-24T18:27:10.583Z] File "condprof/runner.py", line 186, in <module>
[task 2019-12-24T18:27:10.583Z] main()
[task 2019-12-24T18:27:10.583Z] File "condprof/runner.py", line 178, in main
[task 2019-12-24T18:27:10.583Z] loop.run_until_complete(run_all(args))
[task 2019-12-24T18:27:10.583Z] File "/usr/lib/python3.6/asyncio/base_events.py", line 471, in run_until_complete
[task 2019-12-24T18:27:10.583Z] self.run_forever()
[task 2019-12-24T18:27:10.583Z] File "/usr/lib/python3.6/asyncio/base_events.py", line 438, in run_forever
[task 2019-12-24T18:27:10.583Z] self._run_once()
[task 2019-12-24T18:27:10.583Z] File "/usr/lib/python3.6/asyncio/base_events.py", line 1451, in _run_once
[task 2019-12-24T18:27:10.583Z] handle._run()
[task 2019-12-24T18:27:10.583Z] File "/usr/lib/python3.6/asyncio/events.py", line 145, in _run
[task 2019-12-24T18:27:10.583Z] self._callback(*self._args)
[task 2019-12-24T18:27:10.583Z] File "condprof/runner.py", line 170, in run_all
...

Geoff, this bug and Bug 1606351 have the same line in the logcat just as https://bugzilla.mozilla.org/show_bug.cgi?id=1605644#c2 and by the looks of it happens often on central https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&searchStr=android%2C8.0%2Cpixel2%2Caarch64%2Copt%2Cconditioned%2Cprofile%2Cbuilder%2Ccondprof-android-hw-p2-8-0-android-aarch64-geckoview%2Ccondprof%28geckoview%29&fromchange=7c47e27e43c19a724a1353197f89a51298cad2fd&tochange=14ca7276922f986f08f803b28b6d0309f8a081c0&selectedJob=283135934
Should we have a bug tracking these kind of failures?

Logcat from Bug 1606351, https://firefoxci.taskcluster-artifacts.net/eSVIDoW5RvaNktj2UU0wbw/0/public/condprof/logcat.log:

12-30 18:49:04.288 F/DEBUG ( 9232): Abort message: 'Status.cpp:149] Failed HIDL return status not checked: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ''
12-30 18:49:04.289 F/DEBUG ( 9232): x0 0000000000000000 x1 000000000000025b x2 0000000000000006 x3 0000000000000008
12-30 18:49:04.289 F/DEBUG ( 9232): x4 0000000000000000 x5 0000000000000000 x6 0000000000000000 x7 7f7f7f7fff7f7f7f
12-30 18:49:04.289 F/DEBUG ( 9232): x8 0000000000000083 x9 0000000010000000 x10 0000007ff20b1730 x11 0000000000000001
12-30 18:49:04.289 F/DEBUG ( 9232): x12 00000073a480d688 x13 ffffffffffffffff x14 ff00000000000000 x15 ffffffffffffffff
12-30 18:49:04.289 F/DEBUG ( 9232): x16 0000005bd4afaf98 x17 00000073a523417c x18 00000000000053cd x19 000000000000025b
12-30 18:49:04.289 F/DEBUG ( 9232): x20 000000000000025b x21 0000000000000083 x22 00000073a0bd9b00 x23 00000073a6236a48
12-30 18:49:04.289 F/DEBUG ( 9232): x24 0000007ff20b1799 x25 0000000000000030 x26 0000000000000061 x27 000000000000005c
12-30 18:49:04.289 F/DEBUG ( 9232): x28 00000073a5b26008 x29 0000007ff20b1770 x30 00000073a51e9734
12-30 18:49:04.289 F/DEBUG ( 9232): sp 0000007ff20b1730 pc 00000073a51e975c pstate 0000000060000000
12-30 18:49:04.311 F/DEBUG ( 9232):
12-30 18:49:04.311 F/DEBUG ( 9232): backtrace:
12-30 18:49:04.311 F/DEBUG ( 9232): #00 pc 000000000001d75c /system/lib64/libc.so (abort+120)
12-30 18:49:04.311 F/DEBUG ( 9232): #01 pc 00000000000082a4 /system/lib64/libbase.so (android::base::DefaultAborter(char const*)+12)
12-30 18:49:04.311 F/DEBUG ( 9232): #02 pc 0000000000008fac /system/lib64/libbase.so (android::base::LogMessage::~LogMessage()+1004)
12-30 18:49:04.311 F/DEBUG ( 9232): #03 pc 0000000000007bac /system/lib64/libhidlbase.so (android::hardware::details::return_status::~return_status()+280)
12-30 18:49:04.311 F/DEBUG ( 9232): #04 pc 00000000000837a0 /system/lib64/libsurfaceflinger.so (android::Hwc2::Composer::execute()+604)
12-30 18:49:04.311 F/DEBUG ( 9232): #05 pc 000000000008347c /system/lib64/libsurfaceflinger.so (android::Hwc2::Composer::presentDisplay(unsigned long, int*)+224)
12-30 18:49:04.311 F/DEBUG ( 9232): #06 pc 000000000008e1e4 /system/lib64/libsurfaceflinger.so (HWC2::Display::present(android::sp<android::Fence>)+60)
12-30 18:49:04.311 F/DEBUG ( 9232): #07 pc 00000000000b75a4 /system/lib64/libsurfaceflinger.so (android::HWComposer::presentAndGetReleaseFences(int)+252)
12-30 18:49:04.311 F/DEBUG ( 9232): #08 pc 00000000000a165c /system/lib64/libsurfaceflinger.so (android::SurfaceFlinger::postFramebuffer()+168)
12-30 18:49:04.311 F/DEBUG ( 9232): #09 pc 00000000000a08d8 /system/lib64/libsurfaceflinger.so (android::SurfaceFlinger::doComposition()+312)
12-30 18:49:04.311 F/DEBUG ( 9232): #10 pc 000000000009f3d4 /system/lib64/libsurfaceflinger.so (android::SurfaceFlinger::handleMessageRefresh()+136)
12-30 18:49:04.311 F/DEBUG ( 9232): #11 pc 000000000009f328 /system/lib64/libsurfaceflinger.so (android::SurfaceFlinger::onMessageReceived(int)+496)
12-30 18:49:04.311 F/DEBUG ( 9232): #12 pc 0000000000016030 /system/lib64/libutils.so (android::Looper::pollInner(int)+332)
12-30 18:49:04.311 F/DEBUG ( 9232): #13 pc 0000000000015e54 /system/lib64/libutils.so (android::Looper::pollOnce(int, int, int*, void**)+108)
12-30 18:49:04.311 F/DEBUG ( 9232): #14 pc 000000000007bbb4 /system/lib64/libsurfaceflinger.so (android::MessageQueue::waitMessage()+92)
12-30 18:49:04.311 F/DEBUG ( 9232): #15 pc 000000000009e118 /system/lib64/libsurfaceflinger.so (android::SurfaceFlinger::run()+20)
12-30 18:49:04.311 F/DEBUG ( 9232): #16 pc 0000000000002c8c /system/bin/surfaceflinger (main+956)
12-30 18:49:04.311 F/DEBUG ( 9232): #17 pc 000000000001b5e4 /system/lib64/libc.so (__libc_init+88)
12-30 18:49:04.311 F/DEBUG ( 9232): #18 pc 0000000000002830 /system/bin/surfaceflinger (_start_main+80)

Flags: needinfo?(gbrown)

I closed bug 1605644 because I thought there was only one such failure and it might be a quirk of the device; I didn't realize it was a repeating intermittent. We should certainly track these failures and try to get them fixed.

Flags: needinfo?(gbrown)

Re-assigning component since all failures seem to be in condprofile tasks.

Assignee: nobody → tarek
Component: Raptor → Condprofile
Priority: P5 → --

As in bug 1605644, the ADBProcessError indicates that Android system services are non-responsive. Logcats show that many services have died, following a crash of surfaceflinger.

Was there a recent (around Dec 22?) change to condprofile that might be related?

See Also: → 1606351

I'll treat all those intermittents in 1608604

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.