Bug 35162 – Configure the root logging.logger globally for the Python scripts

• Component: Tools / Tests
• Status: RESOLVED WONTFIX

[Chris Jerdonek]

Currently, errors logged to the logging module inside autoinstall don't show up anywhere.  Instead, the following message gets logged:

No handlers could be found for logger "webkitpy.autoinstall"

This can be solved by configuring a root logger, say, in webkitpy's __init__.py.  This can be done, for example, by using code similar to the code at the bottom of autoinstall.py (though we probably want to pass sys.stderr explicitly to the logging.StreamHandler() constructor and set the level to WARNING or INFO rather than error):

    import logging
    #logging.basicConfig()
    logger = logging.getLogger()

    console = logging.StreamHandler()
    console.setLevel(logging.DEBUG)
    # set a format which is simpler for console use
    formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
    # tell the handler to use this format
    console.setFormatter(formatter)
    # add the handler to the root logger
    logger.addHandler(console)
    logger.setLevel(logging.INFO)

We may want to consider using the logging module more widely since it seems to have a lot of features:

http://docs.python.org/library/logging.html

[Eric Seidel (no email)]

Yes.  I would like to kill webkit_logging.py and use logging.py everywhere.

You're just noticing that I was (am?) clueless re: python when I wrote all this.

I still don't really understand logging.py or I would have fixed this long ago.  I'm *very* much looking forward to seeing someone fix our logging. :)

[Chris Jerdonek]

(In reply to comment #1)
> You're just noticing that I was (am?) clueless re: python when I wrote all
> this.

No, I wasn't noticing this. I wasn't really even aware of webkit_logging. :) I was just noticing that -- without a root logger configured -- autoinstall.py was swallowing the exception text when I attempted to autoinstall a *.tar.gz file.  So I couldn't see the underlying reason why my "import pep8" line was failing.
  
> I still don't really understand logging.py or I would have fixed this long ago.
>  I'm *very* much looking forward to seeing someone fix our logging. :)

Anyways, I'll at least configure the root logger.  The Python logging module seems to have an API similar to log4j, log4net, etc.  It's the kind of thing where it has way more flexibility than we'll ever need, and we can expand our use of the various options gradually (e.g. having special loggers specific to the needs of various scripts if necessary, supporting debug mode, etc).

[Eric Seidel (no email)]

One of the consequences of my not understanding logging.py and that both run-chromium-webkit-tests and autoinstall use it, is that all of a sudden run-chromium-webkit-tests is logging (needlessly) about autoinstall binding various modules.  I'm not sure the "best" way to fix it.  If we need to fix the logging statement in autoinstall, or if we need to better set up our loggers.

[Chris Jerdonek]

(In reply to comment #3)
> One of the consequences of my not understanding logging.py and that both
> run-chromium-webkit-tests and autoinstall use it, is that all of a sudden
> run-chromium-webkit-tests is logging (needlessly) about autoinstall binding
> various modules.  I'm not sure the "best" way to fix it.  If we need to fix the
> logging statement in autoinstall, or if we need to better set up our loggers.

I'll take a look at run-chromium-webkit-tests as well to see what might need to be done there.  Thanks!

[Chris Jerdonek]

(In reply to comment #4)
> (In reply to comment #3)
> > One of the consequences of my not understanding logging.py and that both
> > run-chromium-webkit-tests and autoinstall use it, is that all of a sudden
> > run-chromium-webkit-tests is logging (needlessly) about autoinstall binding
> > various modules.  I'm not sure the "best" way to fix it.  If we need to fix the
> > logging statement in autoinstall, or if we need to better set up our loggers.
> 
> I'll take a look at run-chromium-webkit-tests as well to see what might need to
> be done there.  Thanks!

I took a look at the run-chromium-webkit-tests code and made a report about it here:

https://bugs.webkit.org/show_bug.cgi?id=35194

[Chris Jerdonek]

Created attachment 49125 [details]
Proposed patch

I took the format string from sample code here:

 http://docs.python.org/library/logging.html#logging-to-multiple-destinations

We can change it later if we want.

[Chris Jerdonek]

Created attachment 49129 [details]
Proposed patch 2

After rebasing.  Also disabled unit test logging after noticing diff_parser log output in test-webkitpy's output.

[Eric Seidel (no email)]

Comment on attachment 49129 [details]
Proposed patch 2

 73     print "Logging disabled."
I would have written something like "Disabling logging while running the unit tests."

I'm also not sure that we want to disable logging in the unit tests. We've used logging in some of our unit tests to make sure that we execute all the code we expect to.  Yes, they're a little brittle, but useful! :)

Otherwise this looks OK.

[Chris Jerdonek]

(In reply to comment #8)
> (From update of attachment 49129 [details])
>  73     print "Logging disabled."
> I would have written something like "Disabling logging while running the unit
> tests."
> 
> I'm also not sure that we want to disable logging in the unit tests. We've used
> logging in some of our unit tests to make sure that we execute all the code we
> expect to.  Yes, they're a little brittle, but useful! :)
> 
> Otherwise this looks OK.

Thanks, Eric.  That suggested text sounds fine.

Below is what test-webkitpy looks like without disabling logging

> test-webkitpy
Logging disabled.
..............................................................................................................................................................................................................................root        : ERROR    Unexpected diff format when parsing a chunk: ''
............................................................
----------------------------------------------------------------------
Ran 282 tests in 0.803s

OK

Note that we're not disabling logging in the unit tests themselves -- just the test-webkitpy (and test-webit-scripts) wrapper scripts.  Perhaps test-webkitpy can have a --verbose option that doesn't do this.

In any case, we're just now starting to get the logging into shape.  We can continue to think about the right approach to take with respect to logging in the unit tests.  (For example, we may want to make a distinction between log messages made by the unit tests themselves and log messages made by the code the unit tests are executing.  We could perhaps do this with some convention with logger names, etc. that would allow us to configure one independently of the other.)

In the meantime, I'd say the most important thing for us to do is to make it so that our code is not logging to the root logger directly.  Otherwise we are limited as to how we can configure things.

The way to do this is to (at the top of each module doing logging) obtain a logger like so--

_log = logging.getLogger(<fully-qualified-module-name>")

and then log using methods on _log rather than calling the global logging.info, etc.

[Eric Seidel (no email)]

Many tests capture stderr/stdout to verify logging.  I'm worried that disabling logging as you've done may cause problems with those tests.

In the one case that you're having trouble with, we could capture the output and verify that it looks right. :)  Or we could disable logging as you originally suggested.

You might want to take a peak at outputcapture.py

[Chris Jerdonek]

(In reply to comment #10)
> Many tests capture stderr/stdout to verify logging.  I'm worried that disabling
> logging as you've done may cause problems with those tests.

Oh, okay.  I thought it was because there were log messages you wanted the person running the tests to see.

In that case, wouldn't the tests fail if there was a problem?  They all pass with the patch. :)

I'm not sure the logging was turned on for the unit tests before (this patch is what turned it on).  Otherwise, we would have seen that log output when running test-webkitpy before this patch.

I will take a look at outputcapture.py.  I will also think about other options short of disabling logging altogether.

By the way, in check-webkit-style, in cases where we want to check stderr (for example), we added a parameter to some methods that accepts an stderr_write.  It defaults to sys.stderr.write, and in the unit tests, we pass a mock stderr_write.  This lets us avoid this issue altogether.  I know the logging module accepts such an argument.  See the following from this patch--

# Add sys.stderr to the root logger.
 13 console = logging.StreamHandler(sys.stderr)

So if it was ever necessary, we could probably instantiate the logger with a mock sys_stderr when running unit tests.

> 
> In the one case that you're having trouble with, we could capture the output
> and verify that it looks right. :)  Or we could disable logging as you
> originally suggested.
> 
> You might want to take a peak at outputcapture.py

[Eric Seidel (no email)]

None of the webkit.org-written webkitpy code uses logging.py currently.  It all uses webkit_logging.py (which needs to die).  My "concern" (valid or not) about disabling logging for unit testing is that when we start to convert code away from webkit_logging.py to logging.py we'll lose our testing of log output.  Then again, that may not be a problem and we could always cross that bridge when we come to it.

[Eric Seidel (no email)]

There may be better ways to do things than our current outputcapture.py.  Again all of this code is written by a man who knows little about python. :)

[Chris Jerdonek]

(In reply to comment #12)
> None of the webkit.org-written webkitpy code uses logging.py currently.  It all
> uses webkit_logging.py (which needs to die).  My "concern" (valid or not) about
> disabling logging for unit testing is that when we start to convert code away
> from webkit_logging.py to logging.py we'll lose our testing of log output. 
> Then again, that may not be a problem and we could always cross that bridge
> when we come to it.

Gotcha.  Sounds good.  I expect that we'll have several options when the time comes.  And yes, disabling logging is probably overkill even now.  I'll look into weakening that.

[Chris Jerdonek]

(In reply to comment #13)
> There may be better ways to do things than our current outputcapture.py.  Again
> all of this code is written by a man who knows little about python. :)

At some point you're going to have to stop saying that! ;)

[Chris Jerdonek]

Created attachment 49254 [details]
Proposed patch 3

Rewrote so that logging is not disabled in test-webkitpy.  Also added a suggestion in the code comments as to how unit test modules can test logging.

[Chris Jerdonek]

Created attachment 49256 [details]
Proposed patch 4

Reordered import statements.

[Chris Jerdonek]

Comment on attachment 49256 [details]
Proposed patch 4

I am having second thoughts about this approach.  It is probably better for each script to be responsible for turning on its own logging (an opt-in approach), rather than turning on logging simply by importing from webkitpy.  This should also resolve the issue of having to turn off logging for the unit tests.