Closed Bug 908268 Opened 11 years ago Closed 8 years ago

Intermittent B2G "DMError: Timeout exceeded for shell call"

Categories

(Release Engineering :: General, defect)

Product:
Release Engineering
Component:
General
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED WONTFIX

People

(Reporter: emorley, Unassigned)

Details

(Keywords: intermittent-failure) 

b2g_emulator_vm b2g-inbound opt test mochitest-9 on 2013-08-22 07:08:39 PDT for push b00e6cfeacd6

slave: tst-linux64-ec2-046

https://tbpl.mozilla.org/php/getParsedLog.php?id=26870673&tree=B2g-Inbound

{
07:10:13     INFO - #####
07:10:13     INFO - ##### Running run-tests step.
07:10:13     INFO - #####
07:10:13     INFO - Running pre-action listener: _resource_record_pre_action
07:10:13     INFO - Running main action method: run_tests
07:10:13     INFO - Getting output from command: ['/builds/slave/test/build/venv/bin/python', '-c', 'from distutils.sysconfig import get_python_lib; print(get_python_lib())']
07:10:13     INFO - Copy/paste: /builds/slave/test/build/venv/bin/python -c "from distutils.sysconfig import get_python_lib; print(get_python_lib())"
07:10:13     INFO - Reading from file tmpfile_stdout
07:10:13     INFO - Output received:
07:10:13     INFO -  /builds/slave/test/build/venv/lib/python2.7/site-packages
07:10:13     INFO - retry: Calling <built-in function remove> with args: ('tmpfile_stderr',), kwargs: {}, attempt #1
07:10:13     INFO - retry: Calling <built-in function remove> with args: ('tmpfile_stdout',), kwargs: {}, attempt #1
07:10:13     INFO - Running command: ['/builds/slave/test/build/venv/bin/python', 'runtestsb2g.py', '--adbpath=/builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb', '--b2gpath=/builds/slave/test/build/emulator/b2g-distro', '--console-level=INFO', '--emulator=arm', '--logcat-dir=/builds/slave/test/build', '--remote-webserver=10.0.2.2', '--test-manifest=b2g.json', '--xre-path=/builds/slave/test/build/xre/bin', '--symbols-path=http://pvtbuilds.pvt.build.mozilla.org//pub/mozilla.org/b2g/tinderbox-builds/b2g-inbound-generic/20130822051603/emulator.crashreporter-symbols.zip', '--busybox=/builds/slave/test/build/busybox', '--total-chunks=9', '--this-chunk=9'] in /builds/slave/test/build/tests/mochitest
07:10:13     INFO - Copy/paste: /builds/slave/test/build/venv/bin/python runtestsb2g.py --adbpath=/builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb --b2gpath=/builds/slave/test/build/emulator/b2g-distro --console-level=INFO --emulator=arm --logcat-dir=/builds/slave/test/build --remote-webserver=10.0.2.2 --test-manifest=b2g.json --xre-path=/builds/slave/test/build/xre/bin --symbols-path=http://pvtbuilds.pvt.build.mozilla.org//pub/mozilla.org/b2g/tinderbox-builds/b2g-inbound-generic/20130822051603/emulator.crashreporter-symbols.zip --busybox=/builds/slave/test/build/busybox --total-chunks=9 --this-chunk=9
07:10:13     INFO - Using env: {'COLORTERM': 'gnome-terminal',
07:10:13     INFO -  'DBUS_SESSION_BUS_ADDRESS': 'unix:abstract=/tmp/dbus-3p4BYaMMf9,guid=9e4b65f890de81f00c6c5f0600000061',
07:10:13     INFO -  'DEFAULTS_PATH': '/usr/share/gconf/ubuntu-2d.default.path',
07:10:13     INFO -  'DISPLAY': ':0',
07:10:13     INFO -  'GNOME_DESKTOP_SESSION_ID': 'this-is-deprecated',
07:10:13     INFO -  'GNOME_KEYRING_CONTROL': '/tmp/keyring-RccAKH',
07:10:13     INFO -  'GPG_AGENT_INFO': '/tmp/keyring-RccAKH/gpg:0:1',
07:10:13     INFO -  'HOME': '/home/cltbld',
07:10:13     INFO -  'LANG': 'en_US.UTF-8',
07:10:13     INFO -  'LANGUAGE': 'en_US:en',
07:10:13     INFO -  'LOGNAME': 'cltbld',
07:10:13     INFO -  'MAIL': '/var/mail/cltbld',
07:10:13     INFO -  'MANDATORY_PATH': '/usr/share/gconf/ubuntu-2d.mandatory.path',
07:10:13     INFO -  'MINIDUMP_STACKWALK': '/builds/slave/test/build/tools/breakpad/linux/minidump_stackwalk',
07:10:13     INFO -  'PATH': '/builds/slave/test/build/venv/bin:/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games',
07:10:13     INFO -  'PROPERTIES_FILE': '/builds/slave/test/buildprops.json',
07:10:13     INFO -  'PWD': '/builds/slave/test',
07:10:13     INFO -  'SESSION_MANAGER': 'local/tst-linux64-ec2-046.test.releng.use1.mozilla.com:@/tmp/.ICE-unix/1783,unix/tst-linux64-ec2-046.test.releng.use1.mozilla.com:/tmp/.ICE-unix/1783',
07:10:13     INFO -  'SHELL': '/bin/bash',
07:10:13     INFO -  'SHLVL': '1',
07:10:13     INFO -  'SSH_AGENT_PID': '1811',
07:10:13     INFO -  'SSH_AUTH_SOCK': '/tmp/keyring-RccAKH/ssh',
07:10:13     INFO -  'TERM': 'xterm',
07:10:13     INFO -  'UBUNTU_MENUPROXY': 'libappmenu.so',
07:10:13     INFO -  'USER': 'cltbld',
07:10:13     INFO -  'WINDOWID': '35651590',
07:10:13     INFO -  'XDG_CONFIG_DIRS': '/etc/xdg/xdg-ubuntu-2d:/etc/xdg',
07:10:13     INFO -  'XDG_CURRENT_DESKTOP': 'Unity',
07:10:13     INFO -  'XDG_DATA_DIRS': '/usr/share/ubuntu-2d:/usr/share/gnome:/usr/local/share/:/usr/share/',
07:10:13     INFO -  'XDG_SESSION_COOKIE': '9ca12473fbb1d023794ffd180000023c-1377180383.749513-699343634',
07:10:13     INFO -  '_': '/etc/X11/Xsession',
07:10:13     INFO -  '__GL_YIELD': 'NOTHING'}
07:10:14     INFO -  /builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozrunner/utils.py:20: UserWarning: Module manifestparser was already imported from /builds/slave/test/build/tests/mochitest/manifestparser.py, but /builds/slave/test/build/venv/lib/python2.7/site-packages is being added to sys.path
07:10:14     INFO -    import pkg_resources
07:11:45     INFO -  Mochitest INFO | runtests.py | Server pid: 2432
07:11:46     INFO -  Mochitest INFO | runtestsb2g.py | Running tests: start.
07:11:54     INFO -  remount succeeded
07:16:59     INFO -  Traceback (most recent call last):
07:16:59     INFO -    File "runtestsb2g.py", line 138, in run_tests
07:16:59     INFO -      self.runner.start(outputTimeout=timeout)
07:16:59     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozrunner/remote.py", line 134, in start
07:16:59     INFO -      self.dm.shellCheckOutput(['stop', 'b2g'])
07:16:59     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozdevice/devicemanager.py", line 371, in shellCheckOutput
07:16:59     INFO -      retval = self.shell(cmd, buf, env=env, cwd=cwd, timeout=timeout, root=root)
07:16:59     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozdevice/devicemanagerADB.py", line 141, in shell
07:16:59     INFO -      raise DMError("Timeout exceeded for shell call")
07:16:59     INFO -  DMError: Timeout exceeded for shell call
07:16:59     INFO -  Mochitest ERROR | runtests.py | Received unexpected exception while running application
07:18:02     INFO -  Mochitest INFO  | runtestsb2g.py | Running tests: end.
07:18:03     INFO -  pushing /system/bin/busybox
07:18:03     INFO -  waiting for system-message-listener-ready...
07:18:03     INFO -  done
07:18:03     INFO -  args: [u'/builds/slave/test/build/xre/bin/xpcshell', '-g', '/builds/slave/test/build/xre/bin', '-v', '170', '-f', '/builds/slave/test/build/xre/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpSVUgE8';const _SERVER_PORT = '8888'; const _SERVER_ADDR = '10.0.2.2';\n                     const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', './server.js']
07:18:04    ERROR - Return code: 256
}

Logcat:
{
07:18:04     INFO -  08-22 14:11:55.840   518   518 E Profiler: Registering start signal
07:18:04     INFO -  08-22 14:11:56.070    45    45 I Gonk    : Setting nice for pid 596 to 18
07:18:04     INFO -  08-22 14:11:56.070    45    45 I Gonk    : Changed nice for pid 596 from 1 to 18.
07:18:04     INFO -  08-22 14:12:00.490   518   518 E GeckoConsole: Could not read chrome manifest 'file:///system/b2g/chrome.manifest'.
07:18:04     INFO -  08-22 14:12:08.970   518   518 I Gecko   : ###################################### forms.js loaded
07:18:04     INFO -  08-22 14:12:09.120   518   518 I Gecko   : ############################### browserElementPanning.js loaded
07:18:04     INFO -  08-22 14:12:10.654   518   518 I Gecko   : ######################## BrowserElementChildPreload.js loaded
07:18:04     INFO -  08-22 14:12:16.882   518   518 E GeckoConsole: [JavaScript Warning: "Unknown property 'user-select'.  Declaration dropped." {file: "app://communications.gaiamobile.org/ftu/css/style.css" line: 9 column: 13 source: "  user-select: none;"}]
07:18:04     INFO -  08-22 14:12:18.980   518   518 I Gecko   : MobileConnection initialized
07:18:04     INFO -  08-22 14:12:29.450   518   518 I Gecko   : ###################################### forms.js loaded
07:18:04     INFO -  08-22 14:12:29.690   518   518 I Gecko   : ############################### browserElementPanning.js loaded
07:18:04     INFO -  08-22 14:12:30.083   518   518 I Gecko   : ######################## BrowserElementChildPreload.js loaded
07:18:04     INFO -  08-22 14:12:30.740   518   518 D         : HostConnection::get() New Host Connection established 0x445cf3f0, tid 518
07:18:04     INFO -  08-22 14:12:31.560   518   518 E GeckoConsole: [JavaScript Warning: "Error in parsing value for 'font'.  Declaration dropped." {file: "app://communications.gaiamobile.org/contacts/style/root.css" line: 44 column: 21 source: "  font: 1.1rem/1.3rem;"}]
07:18:04     INFO -  08-22 14:12:31.600   518   518 E GeckoConsole: [JavaScript Warning: "Error in parsing value for 'font'.  Declaration dropped." {file: "app://communications.gaiamobile.org/contacts/style/root.css" line: 56 column: 19 source: "  font: 1.3rem/4rem;"}]
07:18:04     INFO -  08-22 14:12:35.970   596   596 E Profiler: BEGIN mozilla_sampler_init
07:18:04     INFO -  08-22 14:12:36.003   596   596 E Profiler: BPUnw: [1 total] thread_register_for_profiling(me=0x40098488, stacktop=0xbec45a47)
07:18:04     INFO -  08-22 14:12:36.003   596   596 E Profiler: SPS:
07:18:04     INFO -  08-22 14:12:36.010   596   596 E Profiler: SPS: Unwind mode       = pseudo
07:18:04     INFO -  08-22 14:12:36.010   596   596 E Profiler: SPS: Sampling interval = 0 ms (zero means "platform default")
07:18:04     INFO -  08-22 14:12:36.010   596   596 E Profiler: SPS: Entry store size  = 0 (zero means "platform default")
07:18:04     INFO -  08-22 14:12:36.010   596   596 E Profiler: SPS: UnwindStackScan   = 0 (max dubious frames per unwind).
07:18:04     INFO -  08-22 14:12:36.010   596   596 E Profiler: SPS: Use env var MOZ_PROFILER_MODE=help for further information.
07:18:04     INFO -  08-22 14:12:36.023   596   596 E Profiler: SPS:
07:18:04     INFO -  08-22 14:12:36.023   596   596 E Profiler: Registering start signal
07:18:04     INFO -  08-22 10:12:44.110   596   596 E GeckoConsole: Could not read chrome manifest 'file:///system/b2g/chrome.manifest'.
07:18:04     INFO -  08-22 10:12:44.300    45    45 I Gonk    : Setting nice for pid 675 to 18
07:18:04     INFO -  08-22 10:12:44.300    45    45 I Gonk    : Changed nice for pid 675 from 0 to 18.
07:18:04     INFO -  08-22 10:12:45.950   675   675 E Profiler: BEGIN mozilla_sampler_init
07:18:04     INFO -  08-22 10:12:45.950   675   675 E Profiler: BPUnw: [1 total] thread_register_for_profiling(me=0x40098488, stacktop=0xbe8fda47)
07:18:04     INFO -  08-22 10:12:45.950   675   675 E Profiler: SPS:
07:18:04     INFO -  08-22 10:12:45.950   675   675 E Profiler: SPS: Unwind mode       = pseudo
07:18:04     INFO -  08-22 10:12:45.960   675   675 E Profiler: SPS: Sampling interval = 0 ms (zero means "platform default")
07:18:04     INFO -  08-22 10:12:45.960   675   675 E Profiler: SPS: Entry store size  = 0 (zero means "platform default")
07:18:04     INFO -  08-22 10:12:45.960   675   675 E Profiler: SPS: UnwindStackScan   = 0 (max dubious frames per unwind).
07:18:04     INFO -  08-22 10:12:45.960   675   675 E Profiler: SPS: Use env var MOZ_PROFILER_MODE=help for further information.
07:18:04     INFO -  08-22 10:12:45.960   675   675 E Profiler: SPS:
07:18:04     INFO -  08-22 10:12:45.960   675   675 E Profiler: Registering start signal
07:18:04     INFO -  08-22 10:12:46.490   675   675 E GeckoConsole: Could not read chrome manifest 'file:///system/b2g/chrome.manifest'.
07:18:04     INFO -  08-22 10:12:50.020   596   596 I Gecko   : ###################################### forms.js loaded
07:18:04     INFO -  08-22 10:12:50.150   596   596 I Gecko   : ############################### browserElementPanning.js loaded
07:18:04     INFO -  08-22 10:12:50.660   596   596 I Gecko   : ######################## BrowserElementChildPreload.js loaded
07:18:04     INFO -  08-22 10:12:51.650   675   675 I Gecko   : ###################################### forms.js loaded
07:18:04     INFO -  08-22 10:12:51.809   675   675 I Gecko   : ############################### browserElementPanning.js loaded
07:18:04     INFO -  08-22 10:12:52.360   675   675 I Gecko   : ######################## BrowserElementChildPreload.js loaded
07:18:04  WARNING -  08-22 10:12:53.770    45    45 E GeckoConsole: [JavaScript Error: "this.oncancel is not a function" {file: "app://system.gaiamobile.org/js/list_menu.js" line: 147}]
07:18:04     INFO -  08-22 10:13:02.390   596   596 E GeckoConsole: Content JS LOG at app://homescreen.gaiamobile.org/gaia_build_defer_index.js:316 in evmeMigration: [EVME migration] migrating from 1.0.1 to 1.1...
07:18:04     INFO -  08-22 10:13:02.390   596   596 E GeckoConsole: Content JS LOG at app://homescreen.gaiamobile.org/gaia_build_defer_index.js:317 in copyStorageToDB: [EVME migration] [userHistory]: retrieving...
07:18:04     INFO -  08-22 10:13:02.401   596   596 E GeckoConsole: Content JS LOG at app://homescreen.gaiamobile.org/gaia_build_defer_index.js:317 in copyStorageToDB: [EVME migration] [userHistory]: no value
07:18:04     INFO -  08-22 10:13:02.410   596   596 E GeckoConsole: Content JS LOG at app://homescreen.gaiamobile.org/gaia_build_defer_index.js:317 in copyStorageToDB: [EVME migration] [localShortcuts]: retrieving...
07:18:04     INFO -  08-22 10:13:02.410   596   596 E GeckoConsole: Content JS LOG at app://homescreen.gaiamobile.org/gaia_build_defer_index.js:317 in copyStorageToDB: [EVME migration] [localShortcuts]: no value
07:18:04     INFO -  08-22 10:13:02.420   596   596 E GeckoConsole: Content JS LOG at app://homescreen.gaiamobile.org/gaia_build_defer_index.js:317 in copyStorageToDB: [EVME migration] [localShortcutsIcons]: retrieving...
07:18:04     INFO -  08-22 10:13:02.420   596   596 E GeckoConsole: Content JS LOG at app://homescreen.gaiamobile.org/gaia_build_defer_index.js:317 in copyStorageToDB: [EVME migration] [localShortcutsIcons]: no value
07:18:04     INFO -  08-22 10:13:02.430   596   596 E GeckoConsole: Content JS LOG at app://homescreen.gaiamobile.org/gaia_build_defer_index.js:317 in evmeMigration: [EVME migration] complete successfully!
07:18:04     INFO -  08-22 10:13:02.440   596   596 E GeckoConsole: Content JS ERROR at app://homescreen.gaiamobile.org/gaia_build_defer_index.js:41 in onerror: error  while HTTP GET:  app://email.gaiamobile.org/style/icons/60/Email.png
}
I've spun off all the recent B2G debug xpcshell failures to bug 1068946.
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → WONTFIX
Component: General Automation → General
You need to log in before you can comment on or make changes to this bug.