Closed Bug 1051908 Opened 10 years ago Closed 9 years ago

Intermittent Android 2.3 timeout during |adb -s emulator-5554 shell date| ("command timed out: 2400 seconds without output running ['/tools/buildbot/bin/python', 'scripts/scripts/android_emulator_unittest.py'...")

Categories

(Testing :: Mochitest, defect)

Product:
Testing
Component:
Mochitest
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1173120

People

(Reporter: emorley, Assigned: gbrown)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

wait for up to 8 intervals of 30 seconds, instead of 4 intervals
1.06 KB, patch
kmoir
: review+
Details | Diff | Splinter Review
Android 2.3 Emulator fx-team opt test robocop-1 on 2014-08-10 14:50:07 PDT for push eae2c3cb8a19 slave: tst-linux64-spot-320 https://tbpl.mozilla.org/php/getParsedLog.php?id=45634344&tree=Fx-Team { 14:56:29 INFO - Installing Robocop for test-1 14:56:29 INFO - Getting output from command: ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'shell', 'date'] 14:56:29 INFO - Copy/paste: /tools/android-sdk18/platform-tools/adb -s emulator-5554 shell date 14:56:30 INFO - Reading from file tmpfile_stdout 14:56:30 INFO - Output received: 14:56:30 INFO - Sun Aug 10 14:56:28 PDT 2014 14:56:30 INFO - Sun Aug 10 14:56:28 PDT 2014 14:56:30 INFO - Running command: ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'shell', 'date', '-s', '20140810.145629'] 14:56:30 INFO - Copy/paste: /tools/android-sdk18/platform-tools/adb -s emulator-5554 shell date -s 20140810.145629 14:56:30 INFO - Sun Aug 10 14:56:29 PDT 2014 14:56:30 INFO - Return code: 0 14:56:30 INFO - Getting output from command: ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'shell', 'date'] 14:56:30 INFO - Copy/paste: /tools/android-sdk18/platform-tools/adb -s emulator-5554 shell date command timed out: 2400 seconds without output running ['/tools/buildbot/bin/python', 'scripts/scripts/android_emulator_unittest.py', '--cfg', 'android/androidarm.py', '--test-suite', 'robocop-1', '--blob-upload-branch', 'fx-team', '--download-symbols', 'ondemand'], attempting to kill process killed by signal 9 program finished with exit code -1 elapsedTime=2776.883615 ========= Finished '/tools/buildbot/bin/python scripts/scripts/android_emulator_unittest.py ...' failed (results: 2, elapsed: 46 mins, 16 secs) (at 2014-08-10 15:36:30.409323) ========= }
See Also: → 993146
Most of these seem to happen in start-emulators and show: 01:43:47 WARNING - Unable to communicate with SUT agent on port 20701 We can connect to the emulator and it seems to be running: 01:43:47 INFO - Attempt #1 to connect to emulator on port 5554 01:43:47 INFO - Connected to port 5554 01:43:47 INFO - Android Console: type 'help' for a list of commands 01:43:47 INFO - OK 01:43:47 INFO - avd status: 01:43:47 INFO - virtual device is running Maybe sutagent is not starting?
I checked several logs for successful tests. For reftests, on the higher-powered emulator64-spot nodes, the sutagent connection is usually successful on the 4th (last) try. For mochitests, on linux64-spot nodes, the sutagent connection usually fails on the last try, but the test harness is able to connect shortly later. Maybe we should wait another minute or so for sutagent startup.
Assignee: nobody → gbrown
After starting the emulator, the android mozharness script waits for sutagent to start before running tests. Android launches sutagent once the OS has booted and certain checks (sdcard mounted?) have completed. It looks to me like the current wait - 4 intervals of 30 seconds each - is just barely sufficient most of the time. This patch doubles the wait to 8 intervals of 30 seconds each.
Attachment #8475982 - Flags: review?(kmoir)
Attachment #8475982 - Flags: review?(kmoir) → review+
That's already in production and seems to be helpful: https://tbpl.mozilla.org/php/getParsedLog.php?id=46381991&tree=Mozilla-Inbound&full=1 11:53:09 INFO - Attempt #4 to connect to SUT on port 20701 11:53:09 INFO - Connected to port 20701 11:53:09 INFO - Trying again after EOF 11:53:09 INFO - Sleeping 30 seconds 11:53:39 INFO - Attempt #5 to connect to SUT on port 20701 11:53:39 INFO - Connected to port 20701 11:53:39 INFO - SUT response: $> I still expect infrequent "2400 seconds without output" from other causes, such as bug 993146.
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
(In reply to TBPL Robot from comment #21) This connected: 11:53:42 INFO - Attempt #5 to connect to SUT on port 20701 11:53:42 INFO - Connected to port 20701 11:53:42 INFO - SUT response: $> and still timed out.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Comment 23 (and 26 and 27) ends with: 19:21:53 INFO - app_32 302 36 142740 22556 ffffffff afd0c51c S com.mozilla.SUTAgentAndroid 19:21:53 INFO - root 325 44 692 340 c00463c0 afd0c3ac S /system/bin/sh 19:21:53 INFO - root 326 325 848 324 00000000 afd0b45c R ps 19:21:53 INFO - 19:21:53 INFO - None 19:21:53 INFO - mkdir: /builds/slave/test/build/blobber_upload_dir 19:21:53 INFO - /tools/android-sdk18/platform-tools/adb -s emulator-5554 logcat -v time Trace:S StrictMode:S ExchangeService:S > /builds/slave/test/build/blobber_upload_dir/logcat-emulator-5554.log & command timed out: 2400 seconds without output running ['/tools/buildbot/bin/python', 'scripts/scripts/android_emulator_unittest.py', '--cfg', 'android/androidarm.py', '--test-suite', 'mochitest-15', '--blob-upload-branch', 'mozilla-inbound', '--download-symbols', 'ondemand'], attempting to kill A successful job typically reports: 10:05:01 INFO - app_27 291 36 128052 16216 ffffffff afd0c51c S com.android.music 10:05:01 INFO - app_32 301 36 142740 22556 ffffffff afd0c51c S com.mozilla.SUTAgentAndroid 10:05:01 INFO - root 324 44 692 340 c00463c0 afd0c3ac S /system/bin/sh 10:05:01 INFO - root 325 324 848 324 00000000 afd0b45c R ps 10:05:01 INFO - 10:05:01 INFO - None 10:05:01 INFO - mkdir: /builds/slave/test/build/blobber_upload_dir 10:05:01 INFO - /tools/android-sdk18/platform-tools/adb -s emulator-5554 logcat -v time Trace:S StrictMode:S ExchangeService:S > /builds/slave/test/build/blobber_upload_dir/logcat-emulator-5554.log & 10:05:01 INFO - ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'shell', 'mkdir', '/data/anr']: 10:05:01 INFO - 10:05:01 INFO - None 10:05:01 INFO - Running post-action listener: _resource_record_post_action 10:05:01 INFO - ##### 10:05:01 INFO - ##### Running download-and-extract step. 10:05:01 INFO - ##### Is something wrong with that mkdir? Would it be better to start android_emulator_unittest.py with "python -u"?
It looks like there was some kind of network outage on the weekend, causing lots of failures like this: https://tbpl.mozilla.org/php/getParsedLog.php?id=46671054&tree=Try&full=1. It makes me wonder if there is a more general problem with error handling in android_emulator_unittest.py.
Most of the many failures on 2014-08-27 and 2014-08-29 happened when downloading the AVD bundle from tooltool -- presumably a temporary network or server problem. 07:55:58 INFO - ##### Running download-cacheable-artifacts step. 07:55:58 INFO - ##### 07:55:58 INFO - Running pre-action listener: _resource_record_pre_action 07:55:58 INFO - Running main action method: download_cacheable_artifacts 07:55:58 INFO - mkdir: /builds/slave/talos-slave/cached 07:55:58 INFO - Downloading http://tooltool.pvt.build.mozilla.org/build/sha512/7140e026b7b747236545dc30e377a959b0bdf91bb4d70efd7f97f92fce12a9196042503124b8df8d30c2d97b7eb5f9df9556afdffa0b5d9625008aead305c32b to /builds/slave/talos-slave/cached/AVDs-armv7a-gingerbread-build-2014-01-23-ubuntu.tar.gz 07:55:58 INFO - retry: Calling <bound method AndroidEmulatorTest._download_file of <__main__.AndroidEmulatorTest object at 0x2324450>> with args: ('http://tooltool.pvt.build.mozilla.org/build/sha512/7140e026b7b747236545dc30e377a959b0bdf91bb4d70efd7f97f92fce12a9196042503124b8df8d30c2d97b7eb5f9df9556afdffa0b5d9625008aead305c32b', '/builds/slave/talos-slave/cached/AVDs-armv7a-gingerbread-build-2014-01-23-ubuntu.tar.gz'), kwargs: {}, attempt #1 command timed out: 2400 seconds without output running ['/tools/buildbot/bin/python', 'scripts/scripts/android_emulator_unittest.py', '--cfg', 'android/androidarm.py', '--test-suite', 'mochitest-16', '--blob-upload-branch', 'try', '--download-symbols', 'ondemand'], attempting to kill
It looks like this is happening on all branches and across 2.3/4.0/x86 now. There may be multiple causes, but I suspect there is a common weakness. I don't know what. Perhaps the structured logging changes have broken something?? I wonder if this is related to the Fennec hangs on Android 4.0 tests (bug 1059797). Hangs should be detected and reported by the harness, but if that sometimes fails, it might explain these timeouts. In any case, I don't think I will make much progress on this before my vacation, so un-assigning.
Assignee: gbrown → nobody
Some of the recent failures here are in mochitest-gl; I wonder if that is related to bug 1102402.
See also bug 1158206. In the failures in this bug which are 2400 seconds without output running android_emulator_unittest.py, why isn't android_emulator_unittest printing # every 5 minutes? Are we hanging before/after running tests, or is this some sort of communication problem?
Reviewing recent logs, it looks like most android_emulator_unittest.py hangs occur before running tests -- while installing or otherwise preparing to run a test harness.
(In reply to Treeherder Robot from comment #473) > log: > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla- > inbound&job_id=9281807 > repository: mozilla-inbound > start_time: 2015-04-24T12:24:15 > who: wkocher[at]mozilla[dot]com > machine: tst-linux64-spot-1957 > buildname: Android 4.3 armv7 API 11+ mozilla-inbound opt test robocop-2 > revision: b04704294a81 > > command timed out: 2400 seconds without output running > ['/tools/buildbot/bin/python', > 'scripts/scripts/android_emulator_unittest.py', '--cfg', > 'android/androidarm_4_3.py', '--test-suite', 'robocop-2', > '--blob-upload-branch', 'mozilla-inbound', '--download-symbols', > 'ondemand'], attempting to kill 12:29:47 INFO - Getting output from command: ['/builds/slave/test/build/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'shell', 'ls -d /data/data/org.mozilla.fennec'] 12:29:47 INFO - Copy/paste: /builds/slave/test/build/android-sdk18/platform-tools/adb -s emulator-5554 shell "ls -d /data/data/org.mozilla.fennec" 12:29:48 INFO - Reading from file tmpfile_stdout 12:29:48 INFO - Output received: 12:29:48 INFO - /data/data/org.mozilla.fennec: No such file or directory 12:29:48 INFO - Getting output from command: ['/builds/slave/test/build/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'install', '-r', '/builds/slave/test/build/fennec-40.0a1.en-US.android-arm.apk'] 12:29:48 INFO - Copy/paste: /builds/slave/test/build/android-sdk18/platform-tools/adb -s emulator-5554 install -r /builds/slave/test/build/fennec-40.0a1.en-US.android-arm.apk 12:31:42 INFO - Reading from file tmpfile_stdout 12:31:42 INFO - Output received: 12:31:42 INFO - Error: Could not access the Package Manager. Is the system running? 12:31:42 INFO - Reading from file tmpfile_stderr 12:31:42 WARNING - Failed to install /builds/slave/test/build/fennec-40.0a1.en-US.android-arm.apk 12:32:12 INFO - Getting output from command: ['/builds/slave/test/build/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'install', '-r', '/builds/slave/test/build/fennec-40.0a1.en-US.android-arm.apk'] 12:32:12 INFO - Copy/paste: /builds/slave/test/build/android-sdk18/platform-tools/adb -s emulator-5554 install -r /builds/slave/test/build/fennec-40.0a1.en-US.android-arm.apk command timed out: 2400 seconds without output running ['/tools/buildbot/bin/python', 'scripts/scripts/android_emulator_unittest.py', '--cfg', 'android/androidarm_4_3.py', '--test-suite', 'robocop-2', '--blob-upload-branch', 'mozilla-inbound', '--download-symbols', 'ondemand'], attempting to kill
In Comment 474 (473) it seems highly likely that "adb install" hung on the first retry. It might be worth updating mozharness' get_output_from_command to accept a timeout argument which could be passed to Popen.wait().
Depends on: 1158338
Depends on: 1160194
Assignee: nobody → gbrown
Following recent simplification in bug 1160194, Android 4.3 jobs no longer call "adb shell date" at install time, instead just checking "adb shell getprop ..." and then "adb install ..." Infrequent hangs during "adb install ..." continue. There is a new variant reported in comments 482, 485, and 486 in which "adb shell getprop" fails repeatedly, until that loop times out. I can't think of what might have changed to cause this variant (bug 1160194 seems independent...but the change seems too coincidental). Would a wait for "adb devices" provide any value?
Depends on: 1123828
I expect bug 1123828 will avoid, or at least alter, most of the 2.3 and 4.3 install-time hangs reported here. Those changes went into production on m-c after comment 530. Comment 531 is not at install time -- the harness seemed to hang. Comment 532 is not 2.3 or 4.3 -- it is a 4.0 install-time hang.
Comment 540 - comment 546 are mis-stars.
Depends on: 1170227
Depends on: 1172174
Depends on: 1173120
Bug 1172174 should translate the "Timeout exceeded for shell call" failures into simple DMErrors (no hang / 2400 seconds without output). Several of the other cases look like: 12:23:25 INFO - runtests.py | Running tests: start. 12:28:46 INFO - Robocop process name: org.mozilla.fennec command timed out: 2400 seconds without output ... which looks to me like we are stuck at: http://hg.mozilla.org/mozilla-central/annotate/e101c589c242/build/mobile/remoteautomation.py#l297 http://hg.mozilla.org/mozilla-central/annotate/b0315d00af9e/testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py#l312 ...which is bug 1173120. In other words, I think all, or nearly all "2400 seconds without output" failures can be traced to adb hangs. Now why is adb hanging, and what can be done about it?
(In reply to Treeherder Robot from comment #587) > log: > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=10611126 11:02:44 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/dom/xbl/crashtests/493123-1.xhtml | 616 / 1429 (43%) 11:08:46 INFO - mozdevice ERROR | Timeout exceeded for shell call 'adb shell dumpsys window windows; echo $?' command timed out: 2400 seconds without output running ['/tools/buildbot/bin/python', 'scripts/scripts/android_emulator_unittest.py', '--cfg', 'android/androidarm_4_3.py', '--test-suite', 'crashtest-1', '--blob-upload-branch', 'mozilla-inbound', '--download-symbols', 'ondemand'], attempting to kill process killed by signal 9 program finished with exit code -1 elapsedTime=3619.987145 Well, that's disappointing. At least the diagnostics are improved.
Bug 1172174 and bug 1173120 fixed the remaining frequent causes of harness hangs resulting in "2400 seconds without output". It appears that adb sometimes hangs; without appropriate timeout logic, the client (test harness) hangs as a result. With timeouts in place, adb hangs are now being reported in bug 1157948. For example, http://ftp.mozilla.org/pub/mozilla.org/mobile/tinderbox-builds/mozilla-inbound-android-api-11/1434152741/mozilla-inbound_ubuntu64_vm_armv7_mobile_test-mochitest-14-bm52-tests1-linux64-build213.txt.gz 17:55:31 INFO - 232 INFO TEST-OK | image/test/mochitest/test_bug671906.html | took 8430ms 17:55:31 INFO - 233 INFO TEST-START | image/test/mochitest/test_bug733553.html 18:01:12 INFO - mozdevice ERROR | Timeout exceeded for shell call 'adb shell dumpsys window windows; echo $?' 18:06:12 INFO - mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ls -a /sdcard/tests/logs/mochitest.log' 18:11:12 INFO - mozdevice ERROR | Timeout exceeded for shell call 'adb shell dumpsys window windows; echo $?' 18:11:12 INFO - INFO | automation.py | Application ran for: 0:35:48.442469 18:11:12 INFO - INFO | zombiecheck | Reading PID log: /tmp/tmpAnkJTDpidlog 18:16:12 INFO - mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ls -a /data/anr/traces.txt' 18:16:12 INFO - /data/anr/traces.txt not found 18:21:12 INFO - mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ls -a /data/tombstones/' 18:26:12 INFO - mozdevice ERROR | Timeout exceeded for shell call 'adb shell chmod 777 /data/tombstones; echo $?' 18:31:12 INFO - mozdevice ERROR | Timeout exceeded for shell call 'adb shell rm -r /data/tombstones; echo $?' 18:36:12 INFO - mozdevice ERROR | Timeout exceeded for shell call 'adb shell /system/bin/logcat -v time -d dalvikvm:I ConnectivityService:S WifiMonitor:S WifiStateTracker:S wpa_supplicant:S NetworkStateTracker:S; echo $?' 18:36:12 INFO - getLogcat threw DMError; re-trying just once... 18:41:13 INFO - mozdevice ERROR | Timeout exceeded for shell call 'adb shell /system/bin/logcat -v time -d dalvikvm:I ConnectivityService:S WifiMonitor:S WifiStateTracker:S wpa_supplicant:S NetworkStateTracker:S; echo $?' 18:41:13 INFO - Traceback (most recent call last): 18:41:13 INFO - File "/builds/slave/test/build/tests/mochitest/runtests.py", line 2296, in doTests 18:41:13 INFO - quiet=options.quiet 18:41:13 INFO - File "/builds/slave/test/build/tests/mochitest/runtestsremote.py", line 464, in runApp 18:41:13 INFO - return self._automation.runApp(*args, **kwargs) 18:41:13 INFO - File "/builds/slave/test/build/tests/mochitest/automation.py", line 844, in runApp 18:41:13 INFO - crashed = self.checkForCrashes(os.path.join(profileDir, "minidumps"), symbolsPath) 18:41:13 INFO - File "/builds/slave/test/build/tests/mochitest/remoteautomation.py", line 200, in checkForCrashes 18:41:13 INFO - logcat = self._devicemanager.getLogcat(filterOutRegexps=fennecLogcatFilters) 18:41:13 INFO - File "/builds/slave/test/build/tests/mochitest/devicemanager.py", line 160, in getLogcat 18:41:13 INFO - root=self._logcatNeedsRoot) 18:41:13 INFO - File "/builds/slave/test/build/tests/mochitest/devicemanager.py", line 399, in shellCheckOutput 18:41:13 INFO - raise DMError("Non-zero return code for command: %s (output: '%s', retval: '%s')" % (cmd, output, retval)) 18:41:13 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') 18:41:13 INFO - 234 ERROR Automation Error: Received unexpected exception while running application 18:41:13 INFO - Stopping web server 18:42:16 INFO - Stopping web socket server 18:42:16 INFO - Stopping ssltunnel 18:42:16 INFO - WARNING | leakcheck | refcount logging is off, so leaks can't be detected! 18:42:16 INFO - runtests.py | Running tests: end. 18:47:17 INFO - mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ls -a /sdcard/tests/logs/mochitest.log' 18:47:17 INFO - Unable to retrieve log file (/sdcard/tests/logs/mochitest.log) from remote device 18:52:17 INFO - mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ls -a /sdcard/tests/profile/' 18:57:17 INFO - mozdevice ERROR | Timeout exceeded for _checkCmd call 'adb shell rm -r /sdcard/tests/profile' 19:02:17 INFO - mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ls -a /sdcard/tests/chrome/' 19:07:17 INFO - mozdevice ERROR | Timeout exceeded for _checkCmd call 'adb shell rm -r /sdcard/tests/chrome' 19:12:17 INFO - mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ls -a /sdcard/tests/robotium.config' 19:17:17 INFO - mozdevice ERROR | Timeout exceeded for _runCmd call 'adb pull /sdcard/tests/nspr /builds/slave/test/build/blobber_upload_dir' 19:22:17 INFO - mozdevice ERROR | Timeout exceeded for shell call 'adb shell /system/bin/logcat -v time -d dalvikvm:I ConnectivityService:S WifiMonitor:S WifiStateTracker:S wpa_supplicant:S NetworkStateTracker:S; echo $?' 19:22:17 INFO - Error getting device information
"2400 seconds without output" is always a possibility; I expect it will happen again, but for different reasons. Let's close this bug now and open a new bug when/if needed.
Status: REOPENED → RESOLVED
Closed: 10 years ago → 9 years ago
Resolution: --- → DUPLICATE
(In reply to OrangeFactor Robot from comment #606) > 6 automation job failures were associated with this bug in the last 7 days. Hangs while fetching from tooltool, or shortly thereafter. Just infra?
Depends on: 1256300
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: