Bug 35194 – new-run-webkit-tests: should log to non-root loggers

• Component: Tools / Tests
• Status: RESOLVED FIXED

[Chris Jerdonek]

Currently, run-chromium-webkit-tests logs directly to the root logger.  For example--

    def __del__(self):
        logging.debug("flushing stdout")
        sys.stdout.flush()
        logging.debug("flushing stderr")
        sys.stderr.flush()

This means that logging for run-chromium-webkit-tests can't be configured independently of other modules (i.e. without also changing the logging behavior of other modules).

A better practice for larger bodies of code is for each module (or at least each application) to log to its own logger.  See this documentation, for example:

"The logging module supports a hierarchy of loggers with different names. An easy way to tell where a specific log message comes from is to use a separate logger object for each of your modules. Each new logger “inherits” the configuration of its parent, and log messages sent to a logger include the name of that logger..."

(from http://docs.python.org/library/logging.html#simple-examples ) 

For example, the autoinstall module does this by writing the following towards the beginning--

_logger = logging.getLogger(__name__)

This automatically gives the logger the hierarchical name of its module, e.g.

webkitpy.autoinstall: INFO     Getting 'http://pypi.python.org/packages/source/C/ClientForm/ClientForm-0.2.10.zip' from cache.

With this change, the code at the top would look something like this instead--

    def __del__(self):
        log.debug("flushing stdout")
        sys.stdout.flush()
        log.debug("flushing stderr")
        sys.stderr.flush()

(I personally prefer log.debug, etc. over logger.debug, etc. since the construct will be used frequently, and it is shorter to read and type.)

[Chris Jerdonek]

I have a patch for this.  I'll submit it later tonight probably.

[Dirk Pranke]

The new-run-webkit-tests code is very careful about log output, so if we do change something please ensure that the actual logged text is preserved.

Apart from that, I agree that the patch is good in theory but I'm less clear that it's needed in practice. What do you expect to gain from this in the short term, if anything?

[Chris Jerdonek]

(In reply to comment #2)
> The new-run-webkit-tests code is very careful about log output, so if we do
> change something please ensure that the actual logged text is preserved.

All log output will be identical.  It just changes the logging code from logging to the root logger e.g. logger.info(...) to logging to module-specific loggers e.g. _log.info(...).

I made a similar change to another part of webkitpy here:

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

> Apart from that, I agree that the patch is good in theory but I'm less clear
> that it's needed in practice. What do you expect to gain from this in the short
> term, if anything?

The original reason was to address issues like the following, so that you could throttle/configure the autoinstall logging independently of the run-chromium-webkit-tests logging:

https://bugs.webkit.org/show_bug.cgi?id=35162#c3

But perhaps this is no longer an issue in practice, since it doesn't look like run-chromium-webkit-tests executes webkitpy/__init__.py.

However, in general it can only help to use module-specific loggers.  It will be easier to make the switch earlier than later, and it will help to educate other WebKit contributors going forward as to what logging practices we should use throughout our code.

[Dirk Pranke]

I do fully understand the desire to log different modules at different levels. I'm never actually looked at what would be necessary to make that work using python's logging apis. The --log flag to new-run-webkit-tests is a poor man's attempt at doing something simple along those lines.

I look forward to the patch if it makes this easier to do.

[Chris Jerdonek]

Created attachment 49652 [details]
Proposed patch

[Chris Jerdonek]

(In reply to comment #5)
> Created an attachment (id=49652) [details]
> Proposed patch

FYI, this is nearly all a search and replace: "logging." -> "_log.".

[Dirk Pranke]

The change itself looks mostly fine, although I don't quite understand how logger inheritance works. 

If we make this change, how would I configure the different loggers to log at different levels? Right now in run_chromium_webkit_tests.py, we set the level in the default/root logger using logging.basicConfig(). Is there a call we can use to modify the levels for each child logger programmatically without having references to each variable?

[Chris Jerdonek]

(In reply to comment #7)
> The change itself looks mostly fine, although I don't quite understand how
> logger inheritance works.
> 
> If we make this change, how would I configure the different loggers to log at
> different levels? Right now in run_chromium_webkit_tests.py, we set the level
> in the default/root logger using logging.basicConfig(). Is there a call we can
> use to modify the levels for each child logger programmatically without having
> references to each variable?

Here's a quick tutorial.

logging.basicConfig() is a short-cut way of configuring the root (i.e. default) logger.

A more flexible and powerful way to configure a logger is to configure the logger explicitly using code like the following.  You can use this technique to configure both root and non-root loggers:

formatter = logging.Formatter('%(name)s: [%(levelname)s] %(message)s')

console_log_handler = logging.StreamHandler(sys.stderr)
console_log_handler.setFormatter(formatter)

logger = logging.getLogger("webkitpy.layout_tests")
logger.setLevel(logging.INFO)
logger.addHandler(console_log_handler)

Logger inheritance works as follows:

If you log to a logger with a particular name, that log message will also get passed along to all parents of the logger.  A parent is a logger with a name that matches an initial substring.  For example, if you log to a logger with name "webkitpy.layout_tests", that log message will also get passed to the "webkitpy" logger and the root logger (if they exist).

You can prevent messages from getting passed along by setting the logger.propagate data attribute on a logger to False.

There is a lot more than this that you can do.  The logging module also supports things like setting a logging level on handlers and also defining filters.  The Python logging documentation has more info:

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

[Chris Jerdonek]

Any volunteers? :)  Dirk said it looks mostly fine in comment 7, but he doesn't have r+.

[Chris Jerdonek]

Comment on attachment 49652 [details]
Proposed patch

cq- in case this needs to be updated/rebased (it's been a week).

[Eric Seidel (no email)]

Comment on attachment 49652 [details]
Proposed patch

OK. Seems we should have a slicker way of getting these per-file loggers.

[Chris Jerdonek]

(In reply to comment #11)

 Thanks for the review, Eric!

> (From update of attachment 49652 [details])
> OK. Seems we should have a slicker way of getting these per-file loggers.

Great idea -- agreed.  I'll file a report once I land this.

[Chris Jerdonek]

Manually committed:

http://trac.webkit.org/changeset/55603

[Chris Jerdonek]

(In reply to comment #12)
> (In reply to comment #11)
> 
>  Thanks for the review, Eric!
> 
> > (From update of attachment 49652 [details] [details])
> > OK. Seems we should have a slicker way of getting these per-file loggers.
> 
> Great idea -- agreed.  I'll file a report once I land this.

Bug filed here: https://bugs.webkit.org/show_bug.cgi?id=35821