1026710 - Add comprehensive logging to DeviceManagerADB

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Jonathan Griffin (:jgriffin)]

In the B2G cert suite, we sometimes get failures that presumably occur because an adb command didn't work as we expected it to.

In fact, silent adb errors have been a constant source of debugging headaches for quite some time across multiple harnesses.

I think it's time to instrument DeviceManagerADB.py so that we (optionally) log every adb command we execute, and the output from that command.  We can then hook this up to the B2G cert suite so that our detailed logs contain this information, which should make debugging certain problems easier.

Probably the way to go here is to add a logger instance to the DeviceManagerADB constructor, and if present, call logger.info on all the adb command executions.

http://mxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py#34

cc'ing wlach, jgraham, ted and dminor in case they have any input.

Comment 1

[William Lachance (:wlach)]

This sounds like a smart idea. DeviceManager already has a logger instance, so we could just that: http://hg.mozilla.org/mozilla-central/file/c4cf1181993e/testing/mozbase/mozdevice/mozdevice/devicemanager.py#l52

It might be nice to switch over to using structured logging here at the same time -- the functionality added in bug 1021943 would be useful here for getting a default logging object -- though I guess strictly that's a separate issue.

Comment 2

[Armen [:armenzg]]

Attachment: [wip] logging.diff

This is wip.

I have a script which I'm aiming to cover every public method on devicemanagerADB.py

There are two main things I'm doing:
* Create helper function called _raise to help log exceptions before raising them
** I have not yet figured out how to log the traceback
*** I looked for a solution (using the module traceback), however, I have not able to make it work - TODO
* Create a wrapper function before calling _runCmd
** It logs the output of the commands
** I have to think of a clean way to deal with caller expecting to iterate [1][2]
** Perhaps creating a helper iterable output class

[1] http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py#173
[2] http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py#296

Comment 3

[Armen [:armenzg]]

On another note, what is a good way of turning the script I'm writing into a unit test for this module?

I see some tests under here [1] but they all seem to be using MockAgent and are specifically for sut.

If it's not worthy please let me know.

[1] http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/tests

Comment 4

[Armen [:armenzg]]

Comment on attachment 8445416 [details] [diff] [review]
[wip] logging.diff

No request review. No rush.

I just want to know if from your POV I'm at least going in the right direction.

Comment 5

[William Lachance (:wlach)]

Comment on attachment 8445416 [details] [diff] [review]
[wip] logging.diff

Review of attachment 8445416 [details] [diff] [review]:
-----------------------------------------------------------------

So I think this isn't really what we want. It would be better to use structured logging's default logger (which I think was just landing when this bug was filed, so :jgriffin didn't know about it) instead of passing one in. Also, I don't think we want to create a custom _raise method for exceptions; it's kind of non-idiomatic and it's usually very obvious when an exception has been triggered. I think for the purposes of this bug we can switch to structured logging (see below), add the extra logging inside _runCmd and _checkCmd, and then call it a day. :)

::: testing/mozbase/mozdevice/mozdevice/devicemanager.py
@@ +46,5 @@
>      """
>  
>      _logcatNeedsRoot = True
>  
> +    def __init__(self, logLevel=mozlog.ERROR, customLogger=None):

I don't think we actually need to pass in a logger to get the behaviour we want. Instead, we should use mozlog.structured's new "default" logger if possible.

http://mozbase.readthedocs.org/en/latest/mozlog_structured.html#mozlog.structured.structuredlog.get_default_logger

You could replace this chunk with something like:

self._logger = mozlog.getDefaultLogger(component="DeviceManager")
if not self._logger: # no global structured logger, fall back to reg logging
    self._logger = mozlog.getLogger("DeviceManager")
    self._logger.setLevel(logLevel)

@@ +215,5 @@
>      def validateDir(self, localDirname, remoteDirname):
>          """
>          Returns True if remoteDirname on device is same as localDirname on host.
>          """
> +        self._logger.debug("validating directory: %s to %s" % (localDirname, remoteDirname))

Was this change intentional?

::: testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py
@@ +62,5 @@
>  
>          if autoconnect:
>              self.connect()
>  
> +    def _raise(self, msg):

I don't think we need to do this. It's usually obvious when an exception is thrown, additional logging should not be necessary.

::: testing/mozbase/mozdevice/setup.py
@@ +4,5 @@
>  
>  from setuptools import setup
>  
>  PACKAGE_NAME = 'mozdevice'
> +PACKAGE_VERSION = '0.38'

We should bump the version separately from these kinds of changes.

Comment 6

[William Lachance (:wlach)]

(In reply to Armen Zambrano [:armenzg] (EDT/UTC-4) from comment #3)
> On another note, what is a good way of turning the script I'm writing into a
> unit test for this module?
> 
> I see some tests under here [1] but they all seem to be using MockAgent and
> are specifically for sut.
> 
> If it's not worthy please let me know.
> 
> [1]
> http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/tests

I personally think tests would be overkill for this; the existing testing we have inside mozdevice should be sufficient to exercise this functionality. I'd just do some thorough testing that this stuff works as expected and then land it.

Comment 7

[Armen [:armenzg]]

I believe that the right thing to do is to switch to use mozprocess which does the logging for us.
It works much cleaner than my current approach of logging (which I was not happy with).

devicemanageADB.py, as it is, deals in various diverse ways with the processes and the output out of those commands.

http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozprocess/mozprocess/processhandler.py#42
> :param processOutputLine: function or list of functions to be called for each line of output produced by the process (defaults to None).

A basic script that I wrote would look like this:
#!/usr/bin/env python
from mozprocess import ProcessHandler
import mozlog

if __name__ == '__main__':
    logger =  mozlog.getLogger("DeviceManager")
    def _foo(data):
        logger.info(data)

    command = ['cat', 'myfile.txt']
    p = ProcessHandler(command, processOutputLine=_foo)
    p.run()
    p.wait()

Comment 8

[Armen [:armenzg]]

Attachment: [wip] devicemanagerADB logging + mozprocess

How does this approach look to you?

I think this is much cleaner than without mozprocess.

Comment 9

[Armen [:armenzg]]

Attachment: adb_logging.diff

Before asking for review I will make sure that it works with Firefox cert suite.

Comment 10

[Armen [:armenzg]]

Attachment: test_adb_logging.py

This is the script I used to put my changes to the test.

Comment 11

[William Lachance (:wlach)]

Comment on attachment 8450218 [details] [diff] [review]
adb_logging.diff

Review of attachment 8450218 [details] [diff] [review]:
-----------------------------------------------------------------

Yes, this looks good like a good approach, thanks! Definitely want to run this through try to make sure it works.

::: testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py
@@ +7,5 @@
>  import shutil
>  import tempfile
>  import time
>  
>  from devicemanager import DeviceManager, DMError, _pop_last_line

Don't need _pop_last_line anymore.

@@ +191,5 @@
>      def _disconnectRemoteADB(self):
>          self._checkCmd(["disconnect", self.host + ":" + str(self.port)])
>  
>      def pushFile(self, localname, destname, retryLimit=None, createDir=True):
> +        ''' adb pushes to a directory not a file

Please leave the previous comment as-is

@@ +197,1 @@
>          retryLimit = retryLimit or self.retryLimit

Please don't remove this behaviour.

@@ +637,5 @@
>              elif deviceStatus != "device":
>                  raise DMError("bad status for device %s: %s" % (self._deviceSerial, deviceStatus))
>  
>          # Check to see if we can connect to device and run a simple command
> +        if self._checkCmd(["shell", "echo"]) == None:

== None -> is None

Comment 12

[Armen [:armenzg]]

Attachment: adb_logging.diff

I took your changes.
Pushing to try revealed a problem with the emulators' _verifyDevice.

I fixed it and pushed it again.

For now, I'm overwriting shellCheckOutput() on devicemanagerAdb.py
I would have to fix shell() on devicemanagerSUT.py to not have to.

Comment 13

[Armen [:armenzg]]

Attachment: update mozprocess to the latest for mozharness

Why do we have mozbase modules checked-in on mozharness instead of grabbing the latest from the test package or releng's pypi?

Comment 14

[Aki Sasaki (not active)]

Comment on attachment 8451706 [details] [diff] [review]
update mozprocess to the latest for mozharness

(In reply to Armen Zambrano [:armenzg] (EDT/UTC-4) from comment #13)
> Created attachment 8451706 [details] [diff] [review]
> update mozprocess to the latest for mozharness
> 
> Why do we have mozbase modules checked-in on mozharness instead of grabbing
> the latest from the test package or releng's pypi?

We need mozprocess for idle timeouts by default in mozharness.  By depending on grabbing it from pypi, then we have a significant portion of the script where we can't use idle timeouts, e.g. when we clone tools or create the virtualenv.  It also requires some ugliness like creating a virtualenv with mozprocess so we can clone talos + create the other portions of the virtualenv with idle timeouts later.  Mozbase is only in mozharness for idle timeout capability.  If we are using it for other things, we have problems.  Looks like that's happening for mozdevice.

a) Are you just dropping in a new version of mozbase into mozharness, or are you cherrypicking?  Please do the former.
b) Have you tested to make sure that these changes have not affected idle timeouts in the rest of mozharness?  A try push or Ash/Cypress run would be recommended.
(c) Have you tried creating a virtualenv with the appropriate mozbase module versions and using that when using devicemanager?  http://hg.mozilla.org/build/mozharness/file/411aed63044e/mozharness/mozilla/testing/device.py#l634 would have to change.

(c) is possibly the best fix here.  If you answer (a) and (b) in the way I want them answered, and (c) isn't plausible right now, then I can review this patch.  Please either reflag this patch for review (with answers to (a) and (b)) or flag a patch for (c) as appropriate.

Comment 15

[Armen [:armenzg]]

Attachment: [wip] site_packages.diff

This line of code adds site packages into sys.path (at this point is not there).

This has helped me locally but I will have to see what happens on Ash.

Comment 16

[Armen [:armenzg]]

Attachment: output.log

Tomorrow I will hope to be tackling this a bit deeper.

When I run the cert suite with the newer mozdevice I get exceptions.
See attached the output generated after running "runcertsuite webapi &> output.log"

I see this message on the page that opens up "Received unknown message from server: [object Object]".

The exceptions:
 0:38.38 LOG: MainThread DeviceManager DEBUG _checkCmd - command: adb version
 0:38.39 LOG: Thread-379 DeviceManager DEBUG Android Debug Bridge version 1.0.31
Exception in thread Thread-379:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 808, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 761, in run 
    self.__target(*self.__args, **self.__kwargs)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/mozprocess-0.19-py2.7.egg/mozprocess/processhandler.py", line 774, in _processOutput
    self.processOutputLine(line.rstrip())
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/mozprocess-0.19-py2.7.egg/mozprocess/processhandler.py", line 719, in processOutputLine
    handler(line)
  File "/home/armenzg/repos/branches/mozilla-central/testing/mozbase/mozdevice/mozdevice/devicemanager.py", line 67, in _log
    self._logger.debug(data)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/mozlog-2.0-py2.7.egg/mozlog/structured/structuredlog.py", line 223, in log 
    self._log_data("log", data)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/mozlog-2.0-py2.7.egg/mozlog/structured/structuredlog.py", line 123, in _log_data
    handler(log_data)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/fxos_certsuite-1.3.0.9-py2.7.egg/webapi_tests/semiauto/runner.py", line 20, in __call__
    self.transport.emit(data)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/fxos_certsuite-1.3.0.9-py2.7.egg/webapi_tests/semiauto/server.py", line 119, in emit
    self.write_message(payload)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/tornado-3.2.2-py2.7-linux-x86_64.egg/tornado/websocket.py", line 172, in write_message
    raise WebSocketClosedError()
WebSocketClosedError
 0:38.40 LOG: MainThread DeviceManager DEBUG _checkCmd - command: adb shell echo
 0:38.40 TEST_END: MainThread Harness status ERROR, expected PASS. Subtests passed 0/0. Unexpected 1
 0:38.40 SUITE_END: MainThread
Traceback (most recent call last):
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/bin/webapirunner", line 9, in <module>
    load_entry_point('fxos-certsuite==1.3.0.9', 'console_scripts', 'webapirunner')()
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/fxos_certsuite-1.3.0.9-py2.7.egg/webapi_tests/runner.py", line 110, in main
    verbosity=2 if args.verbose else 1)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/fxos_certsuite-1.3.0.9-py2.7.egg/webapi_tests/semiauto/main.py", line 112, in run 
    results = test_runner.run(suite)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/moztest-0.5-py2.7.egg/moztest/adapters/unit.py", line 131, in run 
    stopTestRun()
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/moztest-0.5-py2.7.egg/moztest/adapters/unit.py", line 46, in stopTestRun
    self.logger.suite_end()
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/mozlog-2.0-py2.7.egg/mozlog/structured/structuredlog.py", line 148, in suite_end
    self._log_data("suite_end")
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/mozlog-2.0-py2.7.egg/mozlog/structured/structuredlog.py", line 123, in _log_data
    handler(log_data)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/fxos_certsuite-1.3.0.9-py2.7.egg/webapi_tests/semiauto/runner.py", line 20, in __call__
    self.transport.emit(data)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/fxos_certsuite-1.3.0.9-py2.7.egg/webapi_tests/semiauto/server.py", line 119, in emit
    self.write_message(payload)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/tornado-3.2.2-py2.7-linux-x86_64.egg/tornado/websocket.py", line 172, in write_message
    raise WebSocketClosedError()
tornado.websocket.WebSocketClosedError
 0:58.45 LOG: MainThread DEBUG Process finished
 0:58.49 LOG: MainThread INFO Restoring device state
Results saved in firefox-os-certification_20140708163819.zip

Comment 17

[Armen [:armenzg]]

Attachment: adb_logging.diff

This patch makes the shell function to respect the original abstract definition.
Testing it now on try.

Comment 18

[Armen [:armenzg]]

Attachment: site_packages.diff

Comment 19

[Armen [:armenzg]]

aki, what about if we rename mozprocess within mozharness?
I'm not very fond of modifying sys.path.

Comment 20

[Aki Sasaki (not active)]

Comment on attachment 8453981 [details] [diff] [review]
site_packages.diff

This will be global; I don't think we want this.
We want it here: http://hg.mozilla.org/build/mozharness/file/650f5d4ce789/mozharness/mozilla/testing/device.py#l447

Comment 21

[Aki Sasaki (not active)]

(In reply to Armen Zambrano [:armenzg] (EDT/UTC-4) from comment #19)
> aki, what about if we rename mozprocess within mozharness?
> I'm not very fond of modifying sys.path.

I think we have a bunch of non-ideal solutions here.

renaming mozprocess: this makes dropping in a new copy of mozprocess more manual and error-prone.
modifying sys.path: already done in every mozharness script, and would only affect devicemanager if you change the location, but a bit hacky.
creating a devicemanager command line utility: this would allow us to call it from run_command() and not deal with sys.path at all, but someone needs to do it.

Comment 22

[Armen [:armenzg]]

Attachment: [checked-in] Use mozprocess for DeviceManagerADB to obtain logging of commands and output

A partial-coverage with all known platforms giving issues in Try showed successful results.

I will try now all platforms once again but with more confidence of success.

Comment 23

[William Lachance (:wlach)]

Comment on attachment 8454422 [details] [diff] [review]
[checked-in] Use mozprocess for DeviceManagerADB to obtain logging of commands and output

Review of attachment 8454422 [details] [diff] [review]:
-----------------------------------------------------------------

This looks good in principle -- what does the logging look like with this applied?

r+ assuming that looks reasonable and with nits addressed

::: testing/mozbase/mozdevice/mozdevice/devicemanager.py
@@ +54,5 @@
> +            self._logger = None
> +
> +        if not self._logger: # no global structured logger, fall back to reg logging
> +            self._logger = mozlog.getLogger("DeviceManager")
> +            self._logger.setLevel(logLevel)

You can just do this inside the exception handler.

::: testing/mozbase/mozprocess/mozprocess/processhandler.py
@@ +821,5 @@
>                  if timeout and count > timeout:
>                      return None
>  
> +        self.returncode = self.proc.wait()
> +        return self.returncode

I think we should leave this code the way it was before

Comment 24

[Armen [:armenzg]]

The reason I record the returncode in processhandler's wait() is because killProcess() checks on the p.returncode [1]
I believe this is what it would be required to meet your comment [2].

wlach, what do you think?

[1] http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py#389
[2] https://pastebin.mozilla.org/5544849

Comment 25

[Armen [:armenzg]]

aki, we might not need the sys.path patch as in my latest pushes to try I have not hit the issue.

Nevertheless, I will keep an eye for it as I get the feeling that is only hit on certain suites/test failures.

Comment 26

[William Lachance (:wlach)]

(In reply to Armen Zambrano [:armenzg] (EDT/UTC-4) from comment #24)
> The reason I record the returncode in processhandler's wait() is because
> killProcess() checks on the p.returncode [1]
> I believe this is what it would be required to meet your comment [2].
> 
> wlach, what do you think?
> 
> [1]
> http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/
> mozdevice/devicemanagerADB.py#389
> [2] https://pastebin.mozilla.org/5544849

Ah yes, I see. Sorry, you're right. Please commit as is (well, fix the other nit). :)

Comment 27

[Armen [:armenzg]]

IIUC I'm understanding a bit better what is going with the cert logging.

It seems that recording a message on the devicemanger is sent to the WebSocket as there are multiple handlers (comment 16):
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/mozprocess-0.19-py2.7.egg/mozprocess/processhandler.py", line 719, in processOutputLine
    handler(line)
  File "/home/armenzg/repos/branches/mozilla-central/testing/mozbase/mozdevice/mozdevice/devicemanager.py", line 67, in _log
    self._logger.debug(data)
...
File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/mozlog-2.0-py2.7.egg/mozlog/structured/structuredlog.py", line 123, in _log_data
    handler(log_data)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/fxos_certsuite-1.3.0.9-py2.7.egg/webapi_tests/semiauto/runner.py", line 20, in __call__
    self.transport.emit(data)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/fxos_certsuite-1.3.0.9-py2.7.egg/webapi_tests/semiauto/server.py", line 119, in emit
    self.write_message(payload)
  File "/home/armenzg/repos/fxos-certsuite/certsuite_venv/local/lib/python2.7/site-packages/tornado-3.2.2-py2.7-linux-x86_64.egg/tornado/websocket.py", line 172, in write_message
    raise WebSocketClosedError()

Comment 28

[Armen [:armenzg]]

Comment on attachment 8454422 [details] [diff] [review]
[checked-in] Use mozprocess for DeviceManagerADB to obtain logging of commands and output

https://hg.mozilla.org/integration/mozilla-inbound/rev/39f7ac6c97e3

Comment 29

[Armen [:armenzg]]

Attachment: Allow mozdevice to use an external logger and use structured logs properly

It will require full try coverage.
Local testing works.

Comment 30

[Armen [:armenzg]]

Attachment: [review-on-github] Specify to mozdevice to use harness.py's logger

Doing full run of the cert suite.

Comment 31

[Armen [:armenzg]]

Attachment: firefox-os-certification_20140715153753.zip

You can have a look inside of run.log and see that the devicemanager output is there. You can also see adb output on cert/cert_structured.log (different timestamps).

On a side note, I have noticed that the Marionette output shows while the cert suite runs, however, I don't know where it ends up.

Comment 32

[Armen [:armenzg]]

Comment on attachment 8456407 [details] [diff] [review]
[review-on-github] Specify to mozdevice to use harness.py's logger

Review request:
https://github.com/mozilla-b2g/fxos-certsuite/pull/145
https://critic.hoppipolla.co.uk/r/2055

Comment 33

[Armen [:armenzg]]

Attachment: test_adb_logging.py - It tests devicemangerADB.py

Comment 34

[Jonathan Griffin (:jgriffin)]

Comment on attachment 8456453 [details]
firefox-os-certification_20140715153753.zip

Nice, I think this extra level of detail will really be helpful when debugging partner reports.

Comment 35

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/39f7ac6c97e3

Comment 36

[Armen [:armenzg]]

Attachment: manual devicemanagerADB testing

This is to help in the future.
I don't think is worth investing a lot of time in here.

Comment 37

[William Lachance (:wlach)]

Comment on attachment 8456405 [details] [diff] [review]
Allow mozdevice to use an external logger and use structured logs properly

Review of attachment 8456405 [details] [diff] [review]:
-----------------------------------------------------------------

I don't think this behaviour is quite what we want, see comments.

::: testing/mozbase/mozdevice/mozdevice/devicemanager.py
@@ +52,5 @@
> +        if logger:
> +            self._logger = logger
> +        else:
> +            try:
> +                self._logger = structuredlog.StructuredLogger("DeviceManager")

As discussed earlier, I would rather use structured logging's default logger, as discussed in https://bugzilla.mozilla.org/show_bug.cgi?id=1026710#c5

This will use the mach formatter if we're running on an interactive terminal.

This should also make passing in a logger unnecessary.

::: testing/mozbase/mozdevice/setup.py
@@ +4,5 @@
>  
>  from setuptools import setup
>  
>  PACKAGE_NAME = 'mozdevice'
> +PACKAGE_VERSION = '0.40'

We should versionbump in a seperate bug.

Comment 38

[William Lachance (:wlach)]

Comment on attachment 8457046 [details] [diff] [review]
manual devicemanagerADB testing

Review of attachment 8457046 [details] [diff] [review]:
-----------------------------------------------------------------

The idea is good here but I think the shell script is overkill and I'd like some adjustments to the python part of this.

::: testing/mozbase/mozdevice/adb_tests/manual_test_devicemanagerADB.py
@@ +1,1 @@
> +#!/usr/bin/env python

The idea here looks good. I think it would be worth using python's unittest module here, as it's more idiomatic and the error messages generated would likely be a bit more comprehensible.

You can see a simple example of a simple test file using this library here:

https://github.com/mozilla/mozregression/blob/master/tests/test_utils.py

::: testing/mozbase/mozdevice/adb_tests/manual_test_devicemanagerADB.sh
@@ +1,1 @@
> +#!/bin/bash

I think this script is overkill. I think insisting that someone have a working virtualenv with mozdevice (https://wiki.mozilla.org/Auto-tools/Projects/MozBase#Installing_Mozbase_for_Development) is a reasonable requirement for running a manual testrun. 

People can run pyflakes manually if they want to run it. People occasionally do. ;)

I think just the python script should be fine.

Comment 39

[Armen [:armenzg]]

Attachment: Allow mozdevice to use an external logger

Unfortunately the get default logger did not go well with cert suite. [1]
DeviceManagerADB would log stuff that would be sent over the WebSocket.

Nevertheless, that piece of code is not needed to make this work.
It was mainly to add some code to manage the filtering of the logging.

I'm raising now to mozlog.DEBUG to see mozdevice's messages appear on the tbpl logs. If I recall correctly that was the reason to begin with.

[1] https://bugzilla.mozilla.org/show_bug.cgi?id=1026710#c16

Comment 40

[Armen [:armenzg]]

wlach, please disregard the comment with regards s/mozlog.ERROR/mozlog.DEBUG/.
It is unnecessary and too verbose.

I think that mozlog.INFO is the right level (filed bug 1040079 for it).

Comment 41

[Armen [:armenzg]]

I would not be surprised if what akachkach sees on the logs is related to having switched to get default logger:
https://tbpl.mozilla.org/php/getParsedLog.php?id=44006270&tree=Try&full=1#error1

Similar to what I saw on comment 16.

Comment 42

[Armen [:armenzg]]

Attachment: Testing of devicemanagerADB.py with device

Comment 43

[William Lachance (:wlach)]

Comment on attachment 8458715 [details] [diff] [review]
Testing of devicemanagerADB.py with device

Review of attachment 8458715 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good, just a few nits and suggestions.

::: testing/mozbase/mozdevice/adb_tests/test_devicemanagerADB.py
@@ +29,5 @@
> +# I assume these functions are only useful for Android
> +# - getAppRoot()
> +# - updateApp()
> +# - uninstallApp()
> +# - uninstallAppAndReboot()

Nit: Could you use

"""
<comment>
"""

here?

@@ +163,5 @@
> +    p = Popen(["adb", "devices"], stdout=PIPE)
> +    out, err = p.communicate()
> +    assert len(out.splitlines()) > 2, \
> +            "There are no devices connected -adb devices-"
> +

You could do something like:

dm = DeviceManagerADB()
if not dm.devices():
   print "There are no connected adb devices"
   sys.exit(1)

Comment 45

[William Lachance (:wlach)]

Attachment: [checked-in] Fix errors

I think this should fix up the problems we were seeing in bug 104082.

Comment 46

[William Lachance (:wlach)]

Doing up a quick try run to make sure the patch doesn't break stuff (only b2g uses dmADB): https://tbpl.mozilla.org/?tree=Try&rev=22e843f09064

Comment 47

[William Lachance (:wlach)]

Comment on attachment 8457614 [details] [diff] [review]
Allow mozdevice to use an external logger

Review of attachment 8457614 [details] [diff] [review]:
-----------------------------------------------------------------

Per discussion on irc, r-'ing this for now. It sounds like the solution we want is to fix the certsuite.

Comment 48

[Armen [:armenzg]]

Webapi tests create a logger and sets it as the default one in here [1][2]:
> logger = commandline.setup_logging("webapi", vars(args), {"raw": sys.stdout})

Later on, an extra handler for WebSockets is added [3]:
> logger.add_handler(runner.WSHandler(so))

That is why when mozdevice logs something, it ends up reaching the WSHandler [4]:
self.transport.emit(data)

I think the right fix is to not add that handler but that would require figure out another approach to send the messages to the web host.

[1] https://github.com/mozilla-b2g/fxos-certsuite/blob/master/webapi_tests/runner.py#L85
[2] http://hg.mozilla.org/integration/mozilla-inbound/file/ece3f69eb1b1/testing/mozbase/mozlog/mozlog/structured/commandline.py#l64
[3] https://github.com/mozilla-b2g/fxos-certsuite/blob/master/webapi_tests/semiauto/main.py#L84
[4] https://github.com/mozilla-b2g/fxos-certsuite/blob/master/webapi_tests/semiauto/runner.py#L13

From IRC:
<jgraham> The device manager logger should use the get_default_logger thing, set its component correctly, and then assume that the other software works
<jgraham> In this case trying to send messages when the server has been disconnected is just wrong, and should be fixed in that case
<jgraham> *code
<jgraham> We should probably also fix it to only emit messages with no component
<jgraham> I don't think either of those things are hard to do

Comment 49

[William Lachance (:wlach)]

Please check in 8458839. Try run passed fine: https://tbpl.mozilla.org/?tree=Try&rev=22e843f09064

Comment 50

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/c809edd9b1c3

Comment 51

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/c809edd9b1c3

Comment 52

[Armen [:armenzg]]

Attachment: [checked-in] log messages as mozdevice instead of DeviceManager

This patch is not to fix the code but to log things according to standards [1]

All of my issues are fixed with this:
https://critic.hoppipolla.co.uk/r/2098
It fixes how semiauto logs.
Once it is review and merged mozdevice's logging will work.

[1] From https://docs.python.org/2/library/logging.html
The name is potentially a period-separated hierarchical value, like foo.bar.baz (though it could also be just plain foo, for example). Loggers that are further down in the hierarchical list are children of loggers higher up in the list. For example, given a logger with a name of foo, loggers with names of foo.bar, foo.bar.baz, and foo.bam are all descendants of foo. The logger name hierarchy is analogous to the Python package hierarchy, and identical to it if you organise your loggers on a per-module basis using the recommended construction logging.getLogger(__name__). That’s because in a module, __name__ is the module’s name in the Python package namespace.

Comment 53

[Armen [:armenzg]]

Attachment: firefox-os-certification_20140721113020.zip

Using jgraham's branch and running runcertsuite webapi:idle

You can check under webapi/webapi_structuredidle.log and the mozdevice's output.

Comment 54

[William Lachance (:wlach)]

Comment on attachment 8459639 [details] [diff] [review]
[checked-in] log messages as mozdevice instead of DeviceManager

Review of attachment 8459639 [details] [diff] [review]:
-----------------------------------------------------------------

I have no problem with the change since I think mozdevice is slightly more descriptive, though I'm not sure what "standard" means in this case.

Comment 55

[Armen [:armenzg]]

Comment on attachment 8459639 [details] [diff] [review]
[checked-in] log messages as mozdevice instead of DeviceManager

https://hg.mozilla.org/integration/mozilla-inbound/rev/ad750acfe3fc

Comment 56

[Armen [:armenzg]]

Attachment: [checked-in] Testing of devicemanagerADB.py with device

I would have landed, however, I want to make sure I got right the comment wrt using """ for the comment.
I have not seen before a mixture of # and """ so close to each other; that's why the double check.

Comment 57

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/ad750acfe3fc

Comment 58

[Chris Manchester (limited bugmail, email directly)]

I think this was noted earlier, but I just noticed on a try run that, as a result of the way the default structured logger works, this results in lots of logging that wasn't there before for anybody using structured logging (the "setup_logging" method in particular).

Is this the intended effect, or should the additional logging only be turned on when requested?

Comment 59

[William Lachance (:wlach)]

Comment on attachment 8460213 [details] [diff] [review]
[checked-in] Testing of devicemanagerADB.py with device

Review of attachment 8460213 [details] [diff] [review]:
-----------------------------------------------------------------

r+ with the exit code documentation taken out and the "#" multiline comment replacing with """ ... """. As far as I know there is no rule about appropriate distances between # and '''. :) http://legacy.python.org/dev/peps/pep-0008/#comments

::: testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py
@@ +161,5 @@
>            localfilesystem:<unix domain socket name>
>            dev:<character device name>
>            jdwp:<process pid> (remote only)
> +
> +        Returns exit code

Please take this line out of the patch. I don't really want to document this behaviour, as I see no reason someone should be using the return code here for anything.

Comment 60

[Armen [:armenzg]]

Comment on attachment 8460213 [details] [diff] [review]
[checked-in] Testing of devicemanagerADB.py with device

checked-in with requested changes:
http://hg.mozilla.org/integration/mozilla-inbound/rev/80d5027d7ae6

Comment 61

[Armen [:armenzg]]

(In reply to Chris Manchester [:chmanchester] from comment #58)
> I think this was noted earlier, but I just noticed on a try run that, as a
> result of the way the default structured logger works, this results in lots
> of logging that wasn't there before for anybody using structured logging
> (the "setup_logging" method in particular).
> 
> Is this the intended effect, or should the additional logging only be turned
> on when requested?

Hi Chris, at the end we left it as mozlog.ERROR as the default value. [1]
I did not want to risk messing something up for someone.

Do you have try logs that we could inspect?

We log messages as debug messages, however, (as I learned later) IIUC we need to add filters to structured logging to not show every message. [2]

Even though the messages are debug level, the action is "log" hence being recorded.

We could make things more silent if it is getting on your way.

[1] http://hg.mozilla.org/mozilla-central/rev/39f7ac6c97e3#l1.11
[2] http://hg.mozilla.org/integration/mozilla-inbound/file/8f1296b0c7e4/testing/mozbase/mozlog/mozlog/structured/handlers/__init__.py#l25

Comment 62

[Chris Manchester (limited bugmail, email directly)]

(In reply to Armen Zambrano [:armenzg] (EDT/UTC-4) from comment #61)
> (In reply to Chris Manchester [:chmanchester] from comment #58)
> > I think this was noted earlier, but I just noticed on a try run that, as a
> > result of the way the default structured logger works, this results in lots
> > of logging that wasn't there before for anybody using structured logging
> > (the "setup_logging" method in particular).
> > 
> > Is this the intended effect, or should the additional logging only be turned
> > on when requested?
> 
> Hi Chris, at the end we left it as mozlog.ERROR as the default value. [1]
> I did not want to risk messing something up for someone.
> 
> Do you have try logs that we could inspect?

This is the run: https://tbpl.mozilla.org/?tree=Try&rev=8147ae138969

We still need to get our story straight on unicode/str in xpcshell, so the errors there aren't necessarily a result of this patch, but it made me notice the extra logging. I realized this was probably the case for anyone using structured logging and devicemanagerADB, which is the case in some marionette logs now: https://tbpl.mozilla.org/php/getParsedLog.php?id=44443046&tree=Mozilla-Central&full=1

> 
> We log messages as debug messages, however, (as I learned later) IIUC we
> need to add filters to structured logging to not show every message. [2]
> 
> Even though the messages are debug level, the action is "log" hence being
> recorded.

I see.

> 
> We could make things more silent if it is getting on your way.

This isn't necessarily in my way, but I wanted to make sure we understand the implications of the change because I had heard concerns over the size of logs in some cases.

> 
> [1] http://hg.mozilla.org/mozilla-central/rev/39f7ac6c97e3#l1.11
> [2]
> http://hg.mozilla.org/integration/mozilla-inbound/file/8f1296b0c7e4/testing/
> mozbase/mozlog/mozlog/structured/handlers/__init__.py#l25

Comment 63

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/80d5027d7ae6

Comment 64

[Armen [:armenzg]]

We released mozdevice 0.38 (bug 1037651) and mozlog 2.1 [1][2] which are needed for the cert suite to log mozdevice messages.

I'm now bumping the requirements in https://critic.hoppipolla.co.uk/r/2133

That will make run.sh update the cert suite's virtualenv since there's a published valid version.

[1] https://critic.hoppipolla.co.uk/r/2098
[2] http://hg.mozilla.org/integration/mozilla-inbound/rev/66ee8eae0ca4

Comment 65

[Armen [:armenzg]]

The new versions of mozdevice and mozlog have been merged:
https://github.com/mozilla-b2g/fxos-certsuite/pull/162

Comment 66

[Armen [:armenzg]]

I believe this is fixed.