1048889 - Allow mozdevice.adb to work with structured logging

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[James Graham [:jgraham]]

Just need to make the _logger property a structured logger where appropriate.

Comment 1

[James Graham [:jgraham]]

Attachment: Make mozdevice.adb work with structured logging

Comment 2

[Bob Clary [:bc] (inactive)]

Comment on attachment 8467763 [details] [diff] [review]
Make mozdevice.adb work with structured logging

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

I'm going to r- solely on the inability to filter the debug output. If adding levels to structured logging is not an option, then we must remove the debug statements in command_output and shell_output.

I know structured logging is the new standard in our code, and I will defer on all issues related to its use but it definitely doesn't play well with others.

::: testing/mozbase/mozdevice/mozdevice/adb.py
@@ +8,5 @@
>  import subprocess
>  import tempfile
>  import time
> +import traceback
> +

I would say the lack of exception on structured logging is a bug.

I think it would be useful to add a comment here to the effect that since structured logging does not support the exception method, it is required that exception not be used and that error('...\n%s' % traceback.format_exc()) be used in its stead. Or we could just add exception to structured logging.

@@ +21,1 @@
>  

I'm not thrilled with having to depend on mozlog being available. I realize this is part of mozbase and that mozlog is part of mozbase as well, but I've been keeping a clone of this in autophone's repo so that it can diverge if necessary. I can live with the requirement if that is the preferred mode of logging in mozbase.

I think the loss in readability in having this one-off function out of sequence in the code out weighs the benefit of small functions. Can we just put this inline in the constructor?

What do you think of just passing a logger instance to the relevant constructors instead of the logger name and logging level? This would hide the entire standard logging vs. mozlog/structured logging issue.

@@ -121,5 @@
>  
>      def __init__(self,
>                   adb='adb',
>                   logger_name='adb',
> -                 log_level=logging.INFO,

wow. I never actually set it before did I? Autophone sets the level on the higher level loggers and that hid the omission.

I am concerned that structured logging is designed to emit log messages for all levels by default. Currently, adb uses debug to log the output of all invocations of command_output and shell_output. The use of ps and pm in loops can and does cause an extreme amount of output on the order of 10s of megabytes for relatively short runs and 100s or more for long running processes.

I think it is a bug that structured logging does not support levels. I would prefer that it did and that we just fix the setting of the log level rather than dropping the ability to filter by level altogether.

If we don't support log levels in structured logging, then I think the only choice is to remove the debug statements in command_output and shell_output that dump the output to the log.

@@ +143,5 @@
>          """
>          if self.__class__ == ADBCommand:
>              raise NotImplementedError
>  
> +        self._logger = get_logger(logger_name)

inline this.

Comment 3

[James Graham [:jgraham]]

> I'm going to r- solely on the inability to filter the debug output. If
> adding levels to structured logging is not an option, then we must remove
> the debug statements in command_output and shell_output.

So this seems like a somewhat orthogonal issue. It's not like we don't "support" log levels in structured logging; that concept does exist of course. And we can filter the output based on level, so it's quite possible to only write messages at "info-or-above" level if we want. So far I have tried to avoid that for the raw logs because it seems like a better idea to gather all the log data if there aren't concerns over e.g. performance. So far there haven't been. For the human-readable formatters we have already got patches to allow the desired log level to be set from the command line.

To the extent that change is needed here I don't think it should block this patch.

> ::: testing/mozbase/mozdevice/mozdevice/adb.py
> @@ +8,5 @@
> >  import subprocess
> >  import tempfile
> >  import time
> > +import traceback
> > +
> 
> I would say the lack of exception on structured logging is a bug.

I tend to disagree. I think that having a clear correspondence between the method name and the type of message that we produce in the output is good; greater than the value of having an exception method that actually logs as an error-level message. 

I would be more inclined to add support for the exc_info argument to all log-message-loggers, which would cause the exception to be added.

> @@ +21,1 @@
> >  
> 
> I'm not thrilled with having to depend on mozlog being available. I realize
> this is part of mozbase and that mozlog is part of mozbase as well, but I've
> been keeping a clone of this in autophone's repo so that it can diverge if
> necessary. I can live with the requirement if that is the preferred mode of
> logging in mozbase.

We don't have to introduce a hard dependency here, but I'm not sure why avoiding mozlog in mozdevice is desirable; it is indeed already a dependency for other parts of mozbase and an increading number of test harnesses.

> I think the loss in readability in having this one-off function out of
> sequence in the code out weighs the benefit of small functions. Can we just
> put this inline in the constructor?
> 
> What do you think of just passing a logger instance to the relevant
> constructors instead of the logger name and logging level? This would hide
> the entire standard logging vs. mozlog/structured logging issue.

I don't think that's better really. I think what I would actually prefer is that you don't pass anything to the constructor and it just uses a fixed (component) name for the logger e.g "mozdevice.adb". What's the use case for something more complicated?

> If we don't support log levels in structured logging, then I think the only
> choice is to remove the debug statements in command_output and shell_output
> that dump the output to the log.

As mentioned above; this is predicated on a false belief, and changes here will necessarily happen outside of this patch. For my use case having debug logging on and getting all the logs is desirable.

Comment 4

[Bob Clary [:bc] (inactive)]

Comment on attachment 8467763 [details] [diff] [review]
Make mozdevice.adb work with structured logging

I'll defer to Will then.

I don't believe my statements about the size of the logs with debug enabled is based on a false belief. Just this morning while testing a patch on Autophone for 5 builds and the S1S2Test and webappstartup test, I had the following log sizes:

-rw-rw-r--. 1 bclary bclary 463M Aug  6 09:54 autophone.log
-rw-rw-r--. 1 bclary bclary 237M Aug  6 09:54 autophone-samsung-gs3-1.log
-rw-rw-r--. 1 bclary bclary 226M Aug  6 09:54 autophone-samsung-gs3-2.log

Your mileage may vary.

Comment 5

[James Graham [:jgraham]]

I meant that the belief that structured logging can't filter out debug messages if needed.

To be clear, I'm very happy to make changes here. But I don't think this patch should be held up on changes to mozlog itself since it doesn't impose any actual requirement on existing consumers to move to mozlog.

Comment 6

[Bob Clary [:bc] (inactive)]

I r-d for the removal of the debug statements in command_output and shell_output not due to requested changes to mozlog which I didn't expect to happen.

Comment 7

[William Lachance (:wlach)]

Comment on attachment 8467763 [details] [diff] [review]
Make mozdevice.adb work with structured logging

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

I'm ok with this going in I guess since it's still possible to use old logging style, though I share bc's concern about debugging output. Can we make fixing that a priority so we can convert autophone and other things to use structured logging?

I don't really have a strong opinion about exception handling. It feels to me that with either implementation we have the information required to debug what's going on?

Comment 8

[Bob Clary [:bc] (inactive)]

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

> Can we
> make fixing that a priority so we can convert autophone and other things to
> use structured logging?

Adapting Autophone to use structured logging will be difficult as it stands now since it uses multi process logging and depends on behavior of standard logging which is not supported in structured logging. It is in need of a restructuring anyway, but I have a fork of adb* and am not directly affected by the version in m-c.

Comment 9

[James Graham [:jgraham]]

Attachment: Make mozdevice.adb work with structured logging

I have somewhat lost track of what changes were required here vs what we are defering to future mozlog changes vs what I just thought seemed like a good idea. I've 
moved get_logger to be a "private" method (putting it inline would, I think, have been too ugly), and made it fall back to stdlib logging if mozlog isn't avaliable. 
I've also added a verbose parameter on ADBCommand that's used to control whether all the extra logging is produced. 

Did I miss anything?

Comment 10

[Bob Clary [:bc] (inactive)]

Comment on attachment 8469272 [details] [diff] [review]
Make mozdevice.adb work with structured logging

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

r+ for me. It certainly handles the spew that comes from ps and pm. I didn't think of the verbose idea at all.

::: testing/mozbase/mozdevice/mozdevice/adb.py
@@ +1123,5 @@
>                                           root=root).split('\r\n')
>                  self._logger.debug('list_files: data: %s' % data)
>              except ADBError:
> +                self._logger.error('Ignoring exception in ADBDevice.list_files\n%s' %
> +                                   traceback.format_exc())

Since we are ignoring the exception, what do you think of using .warning or something lower in severity than error?

I guess some log parsers will still barf on the traceback but at least we won't have ERROR sticking its thumb in our eye.

Comment 11

[William Lachance (:wlach)]

Comment on attachment 8469272 [details] [diff] [review]
Make mozdevice.adb work with structured logging

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

Looks reasonable to me.

Comment 12

[Bob Clary [:bc] (inactive)]

During Autophone testing, I am running into a problem with the new approach to get the logger.

I do have mozbase installed since it is needed for mozprofile. The new code will automatically import mozlog.structured and use that. I had forgotten I had mozlog available and had thought that if there wasn't already a structured logger with the requested name structured.get_default_logger(logger_name) would return None and the logging module would be used instead but I was wrong.

Although Autophone uses multiprocessing and multiprocessinghandlers and logs from multiple processes, it *appears* to be working normally even though the structured logging docs imply that it won't. At least I haven't seen any problems yet. But the current approach doesn't allow me choose to use default logging if mozlog is available.

Can we pass a flag to the ADB{Command,Host,Device,..} constructors that allows us to specify whether we want structured logging or standard logging?

Comment 13

[William Lachance (:wlach)]

(In reply to Bob Clary [:bc:] from comment #12)
> During Autophone testing, I am running into a problem with the new approach
> to get the logger.
> 
> I do have mozbase installed since it is needed for mozprofile. The new code
> will automatically import mozlog.structured and use that. I had forgotten I
> had mozlog available and had thought that if there wasn't already a
> structured logger with the requested name
> structured.get_default_logger(logger_name) would return None and the logging
> module would be used instead but I was wrong.
> 
> Although Autophone uses multiprocessing and multiprocessinghandlers and logs
> from multiple processes, it *appears* to be working normally even though the
> structured logging docs imply that it won't. At least I haven't seen any
> problems yet. But the current approach doesn't allow me choose to use
> default logging if mozlog is available.
> 
> Can we pass a flag to the ADB{Command,Host,Device,..} constructors that
> allows us to specify whether we want structured logging or standard logging?

get_default_logger will only return a structured logger if it was set previously by set_default_logger. Also, the parameter you pass to get_default_logger is the *component*, not the name of the logger.

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

I don't think any mozbase modules are currently calling set_default_logger. If they are I'd argue that's a bug. I think it would be better not to specify whether or not you want structured logging to ADB... ideally that should be something you could infer automatically.

Comment 14

[James Graham [:jgraham]]

Yeah, as wlach says, although it imports mozlog it shouldn't use it. Generally libraries aren't expected to set the default logger, only top level programs.

Comment 15

[James Graham [:jgraham]]

Attachment: Make mozdevice.adb work with structured logging

Updated with ContextManager patch removed.

Comment 16

[James Graham [:jgraham]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/8501bdd8c565

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/8501bdd8c565