793202 - devicemanager should use mozlog

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Andrew Halberstadt [:ahal]]

https://github.com/mozilla/mozbase/tree/master/mozdevice/mozdevice

Devicemanager has a lot of statements like "if self.debug >= 3: print 'some message'".
It should use mozlog instead.

import mozlog
self.log = mozlog.getLogger("DEVICE MANAGER")
mozlog.setLevel(mozlog.INFO)
self.log.info("gets printed")
self.log.debug("doesn't get printed")
mozlog.shutdown()

Note that any other files that call mozlog.getLogger("DEVICE MANAGER") will get a reference to the same logger object.

Comment 1

[Mark Côté [:mcote]]

My preference for implementing this would, for backwards compatibility, have the logger default to printing to stdout without any formatting, as it does now (no dates, module names, etc.), but that it could also use an existing logger. I would love to have autophone's worker logs contain the devicemanager messages instead of requiring a separate stdout file that I have to dissect along with the log file.

Comment 2

[Mark Côté [:mcote]]

Rereading this, it seems that half the solution is switching autophone to use mozlog (as it should). But I'd still like to see it default to outputting exactly what it does now.

Comment 3

[Andrew Halberstadt [:ahal]]

In my opinion (In reply to Mark Côté ( :mcote ) from comment #1)
> My preference for implementing this would, for backwards compatibility, have
> the logger default to printing to stdout without any formatting, as it does
> now (no dates, module names, etc.), but that it could also use an existing
> logger.

Mozlog logs to stdout by default but can take a filename as a parameter as well. Adding the ability to use a different logger should be easy enough.

I disagree with the formatting though. Mozlog was created to enforce a standard formatting across all of our code bases. To be clear, the only difference would be the module name added to the beginning of the log (though I was also planning on trying to make the messages a bit more clear and verbose as well).

If you think this change would cause lots of things to break, then I'd recommend either marking this bug invalid or deferring until we know what will need to be updated.

Comment 4

[Mark Côté [:mcote]]

Yeah, tbpl requires the exact formatting we use now, at least for "Remove Device Error" (https://hg.mozilla.org/users/mstange_themasta.com/tinderboxpushlog/file/9c7f496beb97/php/inc/GeneralErrorFilter.php#l34). There may be other places; edmorley is checking.

Comment 5

[Ed Morley [:emorley]]

(In reply to Mark Côté ( :mcote ) from comment #4)
> Yeah, tbpl requires the exact formatting we use now, at least for "Remove
> Device Error"
> (https://hg.mozilla.org/users/mstange_themasta.com/tinderboxpushlog/file/
> 9c7f496beb97/php/inc/GeneralErrorFilter.php#l34). There may be other places;
> edmorley is checking.

No more found & I'm happy to have the TBPL regex adjusted to remove the '^'

Comment 6

[Ed Morley [:emorley]]

(In reply to Ed Morley [:edmorley UTC+1] from comment #5)
> I'm happy to have the TBPL regex adjusted to remove the '^'

And in fact, for the switch to mozharness, we'll need to anyway aiui...

Comment 7

[Mihnea Dobrescu-Balaur (:mihneadb)]

So, do we want this? :) I have some time so I could write the patch.

Comment 8

[Andrew Halberstadt [:ahal]]

Yep, that would be helpful :)

Comment 9

[Andrew Halberstadt [:ahal]]

In bug 841969 the message about using 'dd instead of cp' got removed. This bug should probably re-add it as a DEBUG message.

Comment 10

[William Lachance (:wlach)]

(In reply to Andrew Halberstadt [:ahal] from comment #9)
> In bug 841969 the message about using 'dd instead of cp' got removed. This
> bug should probably re-add it as a DEBUG message.

I'd rather just fix bug 842668, as this behaviour is undesirable in any case.

Comment 11

[Mihnea Dobrescu-Balaur (:mihneadb)]

Attachment: make dm* use mozlog

So I'm not sure about a couple of things:

I interpolated based on the context and on the "if debug == x" statements to decide which logger method to use, feel free to suggest improvements.

Also, as :wlach told me, there was no way to set the debug level. I added that. I feel the default mozlog.ERROR makes sense.

The base DM class seems to have some logging as well. I just used self.logger (since this is set up in the ctor of one of the classes that extend the base DM).

Comment 12

[Mihnea Dobrescu-Balaur (:mihneadb)]

// forgot an import mozlog statement in droid.py. Will remove it on the next iteration.

Comment 13

[William Lachance (:wlach)]

Comment on attachment 729221 [details] [diff] [review]
make dm* use mozlog

In general I'd say this looks good. I give it a f+. I wouldn't give it an r+ yet though. :)

First off, you'll need to add mozlog as a dependency of mozdevice here:

https://github.com/mozilla/mozbase/blob/master/mozdevice/setup.py

(see other mozbase modules for examples of this)

We also need to make sure that tbpl will still be able to parse error messages produced by mozlog, since they'll look slightly different. On the upside maybe this means we can finally take out the redundant "Automation Error:" strings out of mozdevice (since we might be able to search on something like "DeviceManager ERROR |").

Other comments:

>diff --git a/mozdevice/mozdevice/devicemanagerADB.py b/mozdevice/mozdevice/devicemanagerADB.py
>index c870d03..73a9f53 100644
>--- a/mozdevice/mozdevice/devicemanagerADB.py
>+++ b/mozdevice/mozdevice/devicemanagerADB.py
>@@ -2,6 +2,7 @@
> # License, v. 2.0. If a copy of the MPL was not distributed with this file,
> # You can obtain one at http://mozilla.org/MPL/2.0/.
> 
>+import mozlog
> import subprocess
> from devicemanager import DeviceManager, DMError, _pop_last_line
> import re
>@@ -29,7 +30,8 @@ class DeviceManagerADB(DeviceManager):
>     default_timeout = 300
> 
>     def __init__(self, host=None, port=5555, retryLimit=5, packageName='fennec',
>-                 adbPath='adb', deviceSerial=None, deviceRoot=None, **kwargs):
>+                 adbPath='adb', deviceSerial=None, deviceRoot=None,
>+                 debugLevel=mozlog.ERROR, **kwargs):
>         self.host = host
>         self.port = port
>         self.retryLimit = retryLimit
>@@ -50,6 +52,9 @@ class DeviceManagerADB(DeviceManager):
>         elif packageName:
>             self._packageName = packageName
> 
>+        self.logger = mozlog.getLogger("DEVICE MANAGER")
>+        self.logger.setLevel(debugLevel)
>+

Can we define the logger in devicemanager.py's __init__ and then call that from dmADB and dmSUT's constructors? Seems like a duplication of work to initialize in both dmADB and dmSUT.

Also, unless there's a compelling reason for using "DEVICE MANAGER" as a tag, could we use DeviceManager instead? The all caps make my eyes bleed. ;)

>@@ -85,6 +90,7 @@ class DeviceManagerADB(DeviceManager):
>     def __del__(self):
>         if self.host:
>             self._disconnectRemoteADB()
>+        mozlog.shutdown()


I don't see why we'd want to call shutdown() here:

http://docs.python.org/2/library/logging.html#logging.shutdown

I'd just take it out.

(actually I think we don't want this __del__ method either, nor the remote adb stuff... but that's another story)

>+    def __del__(self):
>+        mozlog.shutdown()
>+

Same as above, please take this out.

>diff --git a/mozdevice/mozdevice/droid.py b/mozdevice/mozdevice/droid.py
>index a1b86c2..42f843e 100644
>--- a/mozdevice/mozdevice/droid.py
>+++ b/mozdevice/mozdevice/droid.py
>@@ -2,6 +2,7 @@
> # License, v. 2.0. If a copy of the MPL was not distributed with this file,
> # You can obtain one at http://mozilla.org/MPL/2.0/.
> 
>+import mozlog

This isn't necessary.

Comment 14

[William Lachance (:wlach)]

(In reply to William Lachance (:wlach) from comment #13)

> We also need to make sure that tbpl will still be able to parse error
> messages produced by mozlog, since they'll look slightly different. On the
> upside maybe this means we can finally take out the redundant "Automation
> Error:" strings out of mozdevice (since we might be able to search on
> something like "DeviceManager ERROR |").

Wait, it looks like this was already addressed earlier. Sorry, forgot to check that. Disregard this comment.

Comment 15

[Andrew Halberstadt [:ahal]]

Comment on attachment 729221 [details] [diff] [review]
make dm* use mozlog

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

Looks good! Not much to add on top of Will's comments, I agree with all of them. I see what you mean that dmADB and dmSUT not calling the DeviceManager constructor, but having looked at the code I think you should just create a non-default constructor and make dmADB/SUT call it (in fact looking at them, there is a fair amount of other stuff we could also abstract into the super class constructor).

Comment 16

[Jeff Hammel]

(In reply to Andrew Halberstadt [:ahal] from comment #15)
> I see what you mean that dmADB and dmSUT not calling the DeviceManager
> constructor, but having looked at the code I think you should just create a
> non-default constructor and make dmADB/SUT call it (in fact looking at them,
> there is a fair amount of other stuff we could also abstract into the super
> class constructor).

What do you mean by "non-default constructor" here?

Comment 17

[Andrew Halberstadt [:ahal]]

(In reply to Jeff Hammel [:jhammel] from comment #16)
> What do you mean by "non-default constructor" here?

Just meant he should create a constructor

Comment 18

[Jeff Hammel]

Ah, cool. Clarified.

Comment 19

[Mihnea Dobrescu-Balaur (:mihneadb)]

Attachment: make dm* use mozlog

Not sure if I need to explicitly specify a version for mozlog in setup.py.

Also, :ahal, would you mind filing a bug regarding the dm.py ctor? I can take care of it,

Comment 20

[Andrew Halberstadt [:ahal]]

Comment on attachment 730899 [details] [diff] [review]
make dm* use mozlog

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

Sweet, thanks Mihnea! I think we can land this and let it ride the train until we update mozdevice for something else.

Comment 21

[William Lachance (:wlach)]

Comment on attachment 730899 [details] [diff] [review]
make dm* use mozlog

Excellent.

Comment 22

[William Lachance (:wlach)]

Attachment: Minor updates for dm utility, tests

Ok so when I went to apply this I noticed a few problems:

1. Unit tests were still trying to set the log level the old way (via setting a debug member)
2. Likewise with the "dm" utility

I guess this is a good reminder that harness code will likewise need to be updated whenever this lands in m-c. Meanwhile, here's a new version of the patch with the above changed as well.

Comment 23

[Andrew Halberstadt [:ahal]]

Comment on attachment 733471 [details] [diff] [review]
Minor updates for dm utility, tests

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

I'm not aware of any harnesses that set the log level like this (and couldn't find any from quick mxr'ing), but it's certainly possible. It'll get caught in try at any rate. Looks good, thanks!

Comment 24

[William Lachance (:wlach)]

(In reply to Andrew Halberstadt [:ahal] from comment #23)
> Comment on attachment 733471 [details] [diff] [review]
> Minor updates for dm utility, tests
> 
> Review of attachment 733471 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I'm not aware of any harnesses that set the log level like this (and
> couldn't find any from quick mxr'ing), but it's certainly possible. It'll
> get caught in try at any rate. Looks good, thanks!

Unfortunately it won't as setting the debug level won't trigger an error. You just won't see the debug logs. :/

At the very least sut_tools will have to be updated, whenever we up the version of mozdevice used by that... [ CCing people who might care about that ]

For now, I'll commit this patch as is. At the least it probably won't cause any huge explosions. And the new debugging output is a bit more readable I'd say!

Comment 25

[William Lachance (:wlach)]

Pushed: https://github.com/mozilla/mozbase/commit/5eb05474e47a000d018decd7bb8cf350d81e6328

Comment 26

[William Lachance (:wlach)]

Ok, I think we need/want to be able to reset the logLevel after the class is constructed. We could theoretically do this by modifying the logger variable directly, but it might be better/easier to make logLevel a class property that can be modified easily.

<Callek> wlach: ok, I have serious concerns then, since some of the sut code, *needs* a dm constructed much earlier and then hits a case where it *needs* to up to a debug log level
<wlach> Callek: so you want to reset the debug level later?
<Callek> wlach: yea, I want the ability to change the log level well after the devicemanager constructed
<wlach> Callek: ok, you should still be able to do that by using the logger's setLevel API
<Callek> wlach: sure, I'd prefer to be able to change it without needing to know the magic string mozdevice uses though
<wlach> Callek: how about a member function called setLogLevel(level)?
<Callek> wlach: making setLogLevel(level) working and getting rid of dm.debug at the same time would meet my use-case needs
<Callek> wlach: might be useful (but not required) to have .getLogLevel at the same time though
<Callek> and/or make logLevel a "property" that does both allowing actual assignment
<wlach> Callek: we could do that
<Callek> wlach: it sure isn't an urgent issue if I can set it manually with mozlogger, (since having seen mozlogger I want to make sut* code use that instead of the logging module anyway :-P -- though we have lots of cleanup/work to do in sut code as is)
<wlach> Callek: I like the property idea, let's do that

I'll do a followup patch for this when I get the chance.

Comment 27

[Mihnea Dobrescu-Balaur (:mihneadb)]

For tracking purposes: logLevel property bug#: https://bugzilla.mozilla.org/show_bug.cgi?id=858271

Comment 28

[William Lachance (:wlach)]

Re-resolving now that the issues above have been resolved in bug 858271.