Closed Bug 1171445 Opened 11 years ago Closed 9 years ago

Android "INFRA-ERROR: Unable to start emulator after 3 attempts" | "INFRA-ERROR: Unable to start emulator after 5 attempts"

Categories

(Firefox for Android Graveyard :: Testing, defect)

Product:
Firefox for Android Graveyard
Component:
Testing
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: RyanVM, Assigned: gbrown)

References

Details

(Keywords: intermittent-failure)

Attachments

(3 files)

improve emulator startup diagnostics
8.60 KB, patch
kmoir
: review+
Details | Diff | Splinter Review
trigger retry on emulator startup failure
1.62 KB, patch
RyanVM
: review+
Details | Diff | Splinter Review
possible improvements to emulator restart
8.38 KB, patch
kmoir
: review+
Details | Diff | Splinter Review
These have been happening for at least a couple days now, being starred away w/o comment. 02:12:29 INFO - emulator: autoconfig: -scale 1 02:12:29 INFO - emulator: Could not open file: (null)/system/build.prop: No such file or directory 02:12:29 INFO - emulator: control console listening on port 5554, ADB on port 5555 02:12:29 INFO - emulator: sent '0012host:emulator:5555' to ADB server 02:12:29 INFO - emulator: ping program: /builds/slave/test/build/android-sdk18/tools/ddms 02:12:29 INFO - emulator: ping command: /builds/slave/test/build/android-sdk18/tools/ddms ping emulator 22.0.5.0 "VMware, Inc." "Gallium 0.4 on llvmpipe (LLVM 0x300)" "2.1 Mesa 8.0.4" 02:12:29 INFO - goldfish_fb_get_pixel_format:167: display surface,pixel format: 02:12:29 INFO - bits/pixel: 16 02:12:29 INFO - bytes/pixel: 2 02:12:29 INFO - depth: 16 02:12:29 INFO - red: bits=5 mask=0xf800 shift=11 max=0x1f 02:12:29 INFO - green: bits=6 mask=0x7e0 shift=5 max=0x3f 02:12:29 INFO - blue: bits=5 mask=0x1f shift=0 max=0x1f 02:12:29 INFO - alpha: bits=0 mask=0x0 shift=0 max=0x0 02:12:29 INFO - failed to create drawable 02:12:29 INFO - Renderer error: failed to create/resize pbuffer!! 02:12:29 INFO - ##### test-1 emulator log ends 02:12:29 INFO - Created temp file /tmp/tmpGP0P_O. 02:12:29 INFO - Trying to start the emulator with this command: emulator -avd test-1 -port 5554 -debug init,console,gles,memcheck,adbserver,adbclient,adb,avd_config,socket -qemu -m 1024 -cpu cortex-a9 02:12:29 FATAL - Unable to start emulator after 3 attempts 02:12:29 FATAL - Running post_fatal callback... 02:12:29 FATAL - Exiting -1
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #0) > These have been happening for at least a couple days now, being starred away > w/o comment. I am interested in seeing at least a few more examples.
Assignee: nobody → gbrown
Note that comment 4 and comment 3 are from the same machine, with comment 3 running just after comment 4. In both cases, as in comment 1, the emulator is started, adb can see the emulator, but android is not booted. It would be interesting to try to pull a logcat in this circumstance. The host process list includes x-session-manager and other processes that we need, but somehow the process list looks wrong to me.
(In reply to Geoff Brown [:gbrown] from comment #5) > Note that comment 4 and comment 3 are from the same machine, with comment 3 > running just after comment 4. Similar cases: - Comment 18 and 19 - Comment 22 and 24 - Comment 26 and 27 - Comment 28 and 29 ...but there is no sign of a "pair" for the other failures. Missing data or a different failure mode?
Component: General → Testing
I don't expect this patch to eliminate the failures in this bug, but it may help and it should give us more information. This is a group of small changes related to emulator startup: - add "-show-kernel" to emulator command line to get more startup info in the emulator log - take a screenshot of the whole desktop after starting the emulator; save to blobber - dump host information (process list, netstat) on success as well as failure so that comparisons can be made - adb kill-server/start-server before starting the emulator - check the output of "adb devices" and wait for the emulator to be listed and online Here's a sample log: http://ftp.mozilla.org/pub/mozilla.org/mobile/try-builds/gbrown@mozilla.com-cc970136ff89/try-android-api-11/try_ubuntu64_vm_armv7_mobile_test-cppunit-bm122-tests1-linux64-build256.txt.gz and screenshot: http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/9697d1b3030cf66a314d788300c384def5a2803b2ef8f0d619cc6e82bdb4c2d7844d308c7356ac35f259ba81811fef6cdb0de4d138714e59caac3bdba377b351
Attachment #8623164 - Flags: review?(kmoir)
Comment on attachment 8623164 [details] [diff] [review] improve emulator startup diagnostics This is very cool. All the work you're doing to fix the android on emulators is great!
Attachment #8623164 - Flags: review?(kmoir) → review+
With the latest diagnostics, most Android 4.3 failures here have: 11:34:02 INFO - SELinux: Could not mount selinuxfs: No such device 11:34:02 INFO - init: Timed out waiting for /dev/.coldboot_done 11:34:02 INFO - init: cannot open '/initlogo.rle' 11:34:02 INFO - init: Unable to open persistent property directory /data/property errno: 2 11:34:02 INFO - init: cannot find '/system/bin/servicemanager', disabling 'servicemanager' 11:34:02 INFO - init: cannot find '/system/bin/vold', disabling 'vold' 11:34:02 INFO - init: cannot find '/system/bin/qemu-props', disabling 'qemu-props' 11:34:02 INFO - init: cannot find '/system/bin/netd', disabling 'netd' 11:34:02 INFO - init: cannot find '/system/bin/debuggerd', disabling 'debuggerd' 11:34:02 INFO - init: cannot find '/system/bin/rild', disabling 'ril-daemon' 11:34:02 INFO - init: cannot find '/system/bin/surfaceflinger', disabling 'surfaceflinger' 11:34:02 INFO - init: cannot find '/system/bin/app_process', disabling 'zygote' 11:34:02 INFO - init: cannot find '/system/bin/drmserver', disabling 'drm' 11:34:02 INFO - init: cannot find '/system/bin/mediaserver', disabling 'media' 11:34:02 INFO - init: cannot find '/system/bin/installd', disabling 'installd' 11:34:02 INFO - init: cannot find '/system/etc/install-recovery.sh', disabling 'flash_recovery' 11:34:02 INFO - init: cannot find '/system/bin/keystore', disabling 'keystore' 11:34:02 INFO - init: cannot find '/system/bin/qemud', disabling 'qemud' 11:34:02 INFO - init: cannot find '/system/bin/logcat', disabling 'goldfish-logcat' 11:34:02 INFO - init: cannot find '/system/etc/init.goldfish.sh', disabling 'goldfish-setup' 11:34:02 INFO - init: cannot find '/system/bin/sh', disabling 'console'
This has some similarity to https://code.google.com/p/android-on-freerunner/issues/detail?id=16 and http://forum.odroid.com/viewtopic.php?f=60&t=5286, suggesting a problem with system.img. Could the AVD package be corrupt? Running out of space on the aws host?
This is a fascinating bug (well, it is for me). Its sporadic nature makes me suspect that there is something different about certain hosts that affects the emulator...but I cannot seem to find the difference. There may also be some sort of race condition in the emulator (but if it is normally triggered with very low frequency, why does it happen 3 times in a row sometimes...just chance?). I don't have any good leads on determining the root cause here, and I suspect that the fix would be difficult, so I am admitting defeat and triggering a job retry when the emulator won't start.
Attachment #8629997 - Flags: review?(ryanvm)
Attachment #8629997 - Flags: review?(ryanvm) → review+
(In reply to Treeherder Robot from comment #56) > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=11425467 In this log, two of the startup screenshots show Android running, but with the screen lock active. The other screenshot has the Android startup screen in the background but an error box in the foreground with "Process system is not responding! (Force close / Cancel)"
(In reply to Treeherder Robot from comment #52) > https://treeherder.mozilla.org/logviewer.html#?repo=fx-team&job_id=3641774 These screenshots all show the Android boot screen (often seen in successful logs also).
This should be treated as a retry on mozilla-central now and seems to be quite low-frequency.
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → WONTFIX
Depends on: 1280570
Summary: Intermittent Android 4.3 "FATAL - Unable to start emulator after 3 attempts" → Intermittent Android 4.3 "INFRA-ERROR: Unable to start emulator after 3 attempts"
This seems to be happening again.
Status: RESOLVED → REOPENED
Resolution: WONTFIX → ---
Thus the dependency on bug 1280570.
Right. We know that the emulator may crash or hang on startup. Our mozharness script kills and restarts the emulator in those cases, but if the same thing keeps happening, we report INFRA-ERROR to trigger a restart of the whole job. That has worked fine on buildbot, but isn't yet supported on taskcluster -- bug 1280570. Recent failures here are all from taskcluster-initiated jobs. It is also worth noting that most of them are for Android x86. On buildbot, we've run the x86 emulator on ix hardware; on taskcluster, we are running on aws. Some of the logs show an emulator crash explicitly: 17:28:18 INFO - Trying to start the emulator with this command: emulator -avd test-1 -port 5554 -show-kernel -debug init,console,gles,memcheck,adbserver,adbclient,adb,avd_config,socket -qemu -m 1024 17:28:18 INFO - Sleeping 30 seconds *** glibc detected *** /home/worker/workspace/build/android-sdk18/tools/emulator64-x86: free(): invalid pointer: 0x00007fee94880018 *** ======= Backtrace: ========= /lib/x86_64-linux-gnu/libc.so.6(+0x7da26)[0x7fef250b6a26] /usr/lib/x86_64-linux-gnu/libLLVM-3.3.so.1(_ZN4llvm15SmallPtrSetImpl4GrowEj+0x8f)[0x7fef203c71cf] /usr/lib/x86_64-linux-gnu/libLLVM-3.3.so.1(_ZN4llvm15SmallPtrSetImpl10insert_impEPKv+0x8b)[0x7fef203c72bb] /usr/lib/x86_64-linux-gnu/libLLVM-3.3.so.1(_ZN4llvm17PMTopLevelManager25initializeAllAnalysisInfoEv+0x4a2)[0x7fef1fd35562] /usr/lib/x86_64-linux-gnu/libLLVM-3.3.so.1(_ZN4llvm23FunctionPassManagerImpl3runERNS_8FunctionE+0x28)[0x7fef1fd37808] /usr/lib/x86_64-linux-gnu/libLLVM-3.3.so.1(_ZN4llvm19FunctionPassManager3runERNS_8FunctionE+0x64)[0x7fef1fd37934] /usr/lib/x86_64-linux-gnu/libLLVM-3.3.so.1(_ZN4llvm3JIT14jitTheFunctionEPNS_8FunctionERKNS_10MutexGuardE+0x2e)[0x7fef1fea7d2e] /usr/lib/x86_64-linux-gnu/libLLVM-3.3.so.1(_ZN4llvm3JIT24runJITOnFunctionUnlockedEPNS_8FunctionERKNS_10MutexGuardE+0xf)[0x7fef1fea838f] /usr/lib/x86_64-linux-gnu/libLLVM-3.3.so.1(_ZN4llvm3JIT20getPointerToFunctionEPNS_8FunctionE+0x1b2)[0x7fef1fea8592] /usr/lib/x86_64-linux-gnu/libgallium.so.0(gallivm_jit_function+0x1a)[0x7fef2115365a] /usr/lib/x86_64-linux-gnu/libgallium.so.0(draw_llvm_create_variant+0xd5)[0x7fef21170155] /usr/lib/x86_64-linux-gnu/libgallium.so.0(+0x13fbc5)[0x7fef21171bc5] /usr/lib/x86_64-linux-gnu/libgallium.so.0(+0x55185)[0x7fef21087185] /usr/lib/x86_64-linux-gnu/libgallium.so.0(+0x4e0bd)[0x7fef210800bd] /usr/lib/x86_64-linux-gnu/libgallium.so.0(draw_vbo+0x19c)[0x7fef2108056c] /usr/lib/x86_64-linux-gnu/dri/swrast_dri.so(+0x3eb20)[0x7fef21c62b20] /usr/lib/x86_64-linux-gnu/libgallium.so.0(st_draw_vbo+0x247)[0x7fef21187797] /usr/lib/x86_64-linux-gnu/libdricore9.2.1.so.1(+0x158319)[0x7fef21786319] /home/worker/workspace/build/android-sdk18/tools/lib/../lib/lib64GLES_CM_translator.so(_Z12glDrawTexOESIiLj5124EEvT_S0_S0_S0_S0_+0x4ed)[0x7fef220f75ad] /home/worker/workspace/build/android-sdk18/tools/lib/lib64OpenglRender.so(_ZN20gl_decoder_context_t6decodeEPvmP8IOStream+0x25c7)[0x7fef2362fd17] /home/worker/workspace/build/android-sdk18/tools/lib/lib64OpenglRender.so(_ZN12RenderThread4MainEv+0x1b0)[0x7fef23621fe0] /home/worker/workspace/build/android-sdk18/tools/lib/lib64OpenglRender.so(_ZN7osUtils6Thread11thread_mainEPv+0x20)[0x7fef23636e60] /lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a)[0x7fef2602ee9a] /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fef2512c36d] ======= Memory map: ======== 00400000-0069e000 r-xp 00000000 fc:00 3697980 /home/worker/workspace/build/android-sdk18/tools/emulator64-x86 0089e000-008a5000 rw-p 0029e000 fc:00 3697980 /home/worker/workspace/build/android-sdk18/tools/emulator64-x86 008a5000-00c88000 rw-p 00000000 00:00 0 and the crash recurs each time the emulator is restarted.
Keywords: leave-open
I want to try some minor changes to see if they improve emulator restart: - waiting a few seconds between restarts - deleting /tmp files created by the emulator - making up to 5 attempts (instead of 3) to restart before giving up (I reduce some other wait times so that it doesn't take forever to fail) I couldn't help but clean up some sutagent code while I was here. https://treeherder.mozilla.org/#/jobs?repo=try&revision=e5076bf3985e has no INFRA-ERRORs but that's not conclusive since these failures are infrequent. I see some cases where the emulator crashes the first time and succeeds on the second attempt: https://public-artifacts.taskcluster.net/LcIWRusNT-SdLfcvj5RKFQ/0/public/logs/live_backing.log.
Attachment #8783563 - Flags: review?(kmoir)
Comment on attachment 8783563 [details] [diff] [review] possible improvements to emulator restart thanks for the code cleanup!
Attachment #8783563 - Flags: review?(kmoir) → review+
Pushed by gbrown@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/13ffb8bd2550 Try to improve reliability of android emulator startup; r=kmoir
Keywords: leave-open
Summary: Intermittent Android 4.3 "INFRA-ERROR: Unable to start emulator after 3 attempts" → Android "INFRA-ERROR: Unable to start emulator after 3 attempts" | "INFRA-ERROR: Unable to start emulator after 5 attempts"
To my surprise, it appears that latest change was effective. It is still possible to have non-recoverable problems starting the emulator, which will be reported the same way. I still think the best solution to those now-very-rare problems is to automatically retry the job: already works on buildbot, see bug 1280570 for taskcluster.
Status: REOPENED → RESOLVED
Closed: 11 years ago → 9 years ago
Resolution: --- → FIXED
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: