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.

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.

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

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 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 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.

(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.

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()

How does this approach look to you? I think this is much cleaner than without mozprocess.

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

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

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

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.

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

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.

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.

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

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

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

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

(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.

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 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

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

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.

(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). :)

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 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

It will require full try coverage. Local testing works.

Doing full run of the cert suite.

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 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 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.

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

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 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.

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

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).

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 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)

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

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 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.

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

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

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.

Using jgraham's branch and running runcertsuite webapi:idle You can check under webapi/webapi_structuredidle.log and the mozdevice's output.

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 on attachment 8459639 [details] [diff] [review] [checked-in] log messages as mozdevice instead of DeviceManager https://hg.mozilla.org/integration/mozilla-inbound/rev/ad750acfe3fc

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.

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 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 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

(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

(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

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

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

I believe this is fixed.