This would help to get some insight on why we're getting timeouts.

I see these examples on our code: self.info(repr(dm.sendCMD(['exec su -c "logcat -d -v time *:W"']))) print dm._runCmds([{'cmd': 'exec su -c "logcat -d -v time *:W"'}]) log.info(dm._runCmds([{'cmd': 'exec su -c "logcat -d -v time *:W"'}], timeout=10)) I assume that is the way to go.

Yes, that should work.

Looking at this: https://tbpl.mozilla.org/?tree=Ash&jobname=b2g_

Comment on attachment 704076 [details] add logcat plus other improvements >--- a/mozharness/base/python.py >+++ b/mozharness/base/python.py >@@ -53,19 +53,19 @@ class VirtualenvMixin(object): > python_paths = {} > site_packages_path = None > > def query_virtualenv_path(self): > c = self.config > dirs = self.query_abs_dirs() > if 'abs_virtualenv_dir' in dirs: > return dirs['abs_virtualenv_dir'] >- if os.path.isabs(c['virtualenv_path']): >+ if os.path.isabs(c.get('virtualenv_path', "venv")): > return c['virtualenv_path'] "venv" will never be an an absolute path, so this change doesn't make a lot of sense. >- return os.path.join(dirs['abs_work_dir'], c['virtualenv_path']) >+ return os.path.join(dirs['abs_work_dir'], c.get('virtualenv_path', "venv")) We need to return an absolute path here. I think you need to include mozharness.base.python.virtualenv_config_options to your config_options. That will set your default virtualenv_path to 'venv' for you, and you won't need any of this. > [["--mozpool-b2gbase"], { >- "dest": "mozpool_b2gbase", >+ "dest": "installer_url", > "help": "Set b2gbase url", > }], Doesn't request_device() use mozpool_b2g_base? I think you need to s,mozpool_b2g_base,installer_url there too. >- self.mozpool_assignee = self.config.get('mozpool_assignee', \ >- self.foopyname) >+ self.mozpool_assignee = self.config.get('mozpool_assignee', socket.gethostname()) This default will be ok for our foopies, but may not be great if someone runs this from their desktop. Maybe our config should say 'mozpool_assignee': socket.gethostname() and this should default to $USER or something? (Not sure if that's cross-platform though.) >+ if self.config.get("mozpool_device", False): >+ self.mozpool_device = self.config["mozpool_device"] >+ if self.config.get("installer_url", False): >+ self.installer_url = self.config["installer_url"] >+ if self.config.get("test_url", False): >+ self.test_url = self.config["test_url"] You don't need the "False"s in .get(), since .get() will return None by default. > self.info("Read of file (%s) follows" % APP_INI_LOCATION) > self.info("===========================") > self.info(file_contents) >+ lines = dm.getLogcat() >+ for l in lines: >+ self.info(l) If this bit is all you need, r+. The rest of the changes need some fixing though.

This worked both on Ash and locally. mozpool_assignee works for both the foopies and my local machine. b2gbase it can be either mozpool_b2gbase (if specified manually) or self.installer_url (which is what download_and_extract uses. On buildbot we use self.installer_url through read_buildbot_configs. This is how I run the command locally: python scripts/b2g_panda.py --mozpool-device panda-0082 --mozpool-b2gbase http://pvtbuilds.pvt.build.mozilla.org//pub/mozilla.org/b2g/tinderbox-builds/cedar-panda/20130121062718 --test-url http://pvtbuilds.pvt.build.mozilla.org//pub/mozilla.org/b2g/tinderbox-builds/cedar-panda/20130121062718/gaia-tests.zip On another note, the only test that I have failing is this (Mercurial): http://pastebin.mozilla.org/2075898 How can I fix it?

(In reply to Armen Zambrano G. [:armenzg] from comment #7) > On another note, the only test that I have failing is this (Mercurial): > http://pastebin.mozilla.org/2075898 > How can I fix it? I think you need Mercurial 1.7.3 in your venv til bug 828029 is fixed. pip install mercurial==1.7.3

Also, pastebin isn't a great tool to use when you need something to stick around more than a day or two.

Comment on attachment 704558 [details] [diff] [review] add logcat plus other improvements It looks like this patch is bitrotted, so I wasn't able to apply and view in place. >diff --git a/mozharness/base/python.py b/mozharness/base/python.py >--- a/mozharness/base/python.py >+++ b/mozharness/base/python.py >@@ -53,19 +53,23 @@ class VirtualenvMixin(object): > python_paths = {} > site_packages_path = None > > def query_virtualenv_path(self): > c = self.config > dirs = self.query_abs_dirs() > if 'abs_virtualenv_dir' in dirs: > return dirs['abs_virtualenv_dir'] >- if os.path.isabs(c['virtualenv_path']): >- return c['virtualenv_path'] >- return os.path.join(dirs['abs_work_dir'], c['virtualenv_path']) >+ if 'virtualenv_path' in c: >+ if os.path.isabs(c['virtualenv_path']): >+ return c['virtualenv_path'] >+ else: >+ return os.path.join(dirs['abs_work_dir'], c['virtualenv_path']) >+ else: >+ return os.path.join(dirs['abs_work_dir'], 'venv') Sure, though you could simply diff --git a/scripts/b2g_panda.py b/scripts/b2g_panda.py --- a/scripts/b2g_panda.py +++ b/scripts/b2g_panda.py @@ -17,1 +17,1 @@ from mozharness.base.log import INFO, ER -from mozharness.base.python import VirtualenvMixin +from mozharness.base.python import VirtualenvMixin, virtualenv_config_options @@ -51,1 +51,1 @@ class PandaTest(TestingMixin, BaseScript - ] + ] + virtualenv_config_options and this would be unnecessary. Either way's fine with me. >- self.foopyname = self.query_env()["HOSTNAME"].split(".")[0] >- self.mozpool_assignee = self.config.get('mozpool_assignee', \ >- self.foopyname) >+ self.mozpool_assignee = self.config.get('mozpool_assignee', socket.gethostname()) Comment 6 still stands here. I'd be ok with a followup bug for this, though. >- b2gbase = self.config.get('mozpool_b2g_base', \ >- self.installer_url) >+ b2gbase = self.config.get('mozpool_b2g_base', self.installer_url) I'm not sure what we're getting by looking at both config options? Is there an advantage here? >+ def _device_manager(self): >+ sys.path.append(self.query_python_site_packages_path()) >+ from mozdevice.devicemanagerSUT import DeviceManagerSUT >+ dm = None >+ try: >+ self.info("Connecting to: %s" % self.mozpool_device) >+ dm = DeviceManagerSUT(self.mozpool_device) >+ # No need for 300 second SUT socket timeouts here >+ dm.default_timeout = 30 >+ return dm >+ except Exception, e: >+ self._retry_an_close_request("ERROR: Unable to properly connect to SUT Port on device.", e) It looks like you're rewriting http://hg.mozilla.org/build/mozharness/file/8f27c572e501/mozharness/mozilla/testing/device.py#l444 here. Do we need to be able to call this multiple times and get different dm's every time? If not, I think we should set self.devicemanager and use that like in http://hg.mozilla.org/build/mozharness/file/8f27c572e501/mozharness/mozilla/testing/device.py#l444 . That approach: a) prevents us from re-importing and re-creating new dm's every time we call this method b) prevents us from creating multiple dm's that are both talking to the same device, which can cause bustage (intermittent and otherwise) and debugging headaches. You call this method twice, so please cache the dm as self.dm or self.devicemanager. Bonus points for reusing DeviceMixin. I think my main concern is multiple dm's here. Could you attach an unbitrotted patch that addresses that?

I will postpone the other improvements to another bug and get the logcat part out. I was not sure if dm would be OK after running tests for 10-20 minutes. I thought it could get into a weird state and have to re-instantiate it. I'm testing this patch with: https://tbpl.mozilla.org/?tree=Ash&jobname=b2g_panda&rev=e9f39220b8e7

For some ridicolous reason that I fail to comprehend. The logcat function can pass: https://tbpl.mozilla.org/php/getParsedLog.php?id=19058096&tree=Ash&full=1 or fail: https://tbpl.mozilla.org/php/getParsedLog.php?id=19054183&tree=Ash&full=1#error0 08:32:05 INFO - Output logcat... Traceback (most recent call last): File "scripts/scripts/b2g_panda.py", line 229, in <module> pandaTest.run() File "/builds/panda-0125/test/scripts/mozharness/base/script.py", line 728, in run self._possibly_run_method(method_name, error_if_missing=True) File "/builds/panda-0125/test/scripts/mozharness/base/script.py", line 687, in _possibly_run_method return getattr(self, method_name)() File "scripts/scripts/b2g_panda.py", line 177, in run_test lines = dm.getLogcat() File "/builds/panda-0125/test/build/venv/lib/python2.7/site-packages/mozdevice/devicemanager.py", line 508, in getLogcat root=self._logcatNeedsRoot).split('\r') File "/builds/panda-0125/test/build/venv/lib/python2.7/site-packages/mozdevice/devicemanager.py", line 61, in shellCheckOutput retval = self.shell(cmd, buf, env=env, cwd=cwd, timeout=timeout, root=root) File "/builds/panda-0125/test/build/venv/lib/python2.7/site-packages/mozdevice/devicemanagerSUT.py", line 295, in shell haveExecSu = (StrictVersion(self.agentVersion) >= StrictVersion('1.13')) File "/tools/python27/lib/python2.7/distutils/version.py", line 40, in __init__ self.parse(vstring) File "/tools/python27/lib/python2.7/distutils/version.py", line 107, in parse raise ValueError, "invalid version number '%s'" % vstring ValueError: invalid version number 'SUTAgentNegatus Version 1.1' This is where it fails: 100 version_re = re.compile(r'^(\d+) \. (\d+) (\. (\d+))? ([ab](\d+))?$', 101 re.VERBOSE) 102 104 def parse (self, vstring): 105 match = self.version_re.match(vstring) 106 if not match: 107 raise ValueError, "invalid version number '%s'" % vstring I wonder if I should just call _runCmd

Could DeviceManager get into a weird state after not sending commands for 10-15 minutes? I think that the problem is that it would not get self.agentProductName and self.agentVersion properly set. haveExecSu = (self.agentProductName == 'SUTAgentNegatus' or StrictVersion(self.agentVersion) >= StrictVersion('1.13')) I will land a change to print the version first and try to get the logcat the old way. http://hg.mozilla.org/users/asasaki_mozilla.com/ash-mozharness/rev/7ad6473689d4 I will trigger 10 jobs and see what happens. 1.12 + print dm._runCmds([{ 'cmd': 'ver'}]) 1.13 + lines = dm._runCmds([{ 'cmd': 'exec su -c "logcat -d -v time *:W"'}]) 1.14 + for l in lines: 1.15 + self.info(l) 1.16 if tbpl_status != TBPL_SUCCESS: 1.17 - self.info("Output logcat...") 1.18 - lines = dm.getLogcat() 1.19 - for l in lines: 1.20 - self.info(l) 1.21 + self.info("Output logcat...") 1.22 + lines = dm.getLogcat() 1.23 + for l in lines: 1.24 + self.info(l)

Tested on staging few more times. I'm preventing logcat from messing up our results if the initial problem were to happen again (my last 14 runs did not hit the issue).

Comment on attachment 705838 [details] [diff] [review] add logcat >+ except Exception, e: >+ self.info("We failed to run logcat: str(%s)" % str(e)) Maybe self.warning() instead of info() ?

Comment on attachment 705838 [details] [diff] [review] add logcat Unfortunately I don't think this will help with bug 834266 as we can't reach SUT anymore. Nevertheless, this is done. I landed with warning.