Bug 46635 – test-webkitpy should have logging configured differently

• Status: RESOLVED
• Resolution: FIXED
• Component: Tools / Tests

[Eric Seidel (no email)]

webkitpy.layout_tests.layout_package.printing_unittest.TestUtilityFunctions.test_configure_logging should use OutputCapture

Right now it's logging to the console directly, which is less than ideal:

test_configure_logging (webkitpy.layout_tests.layout_package.printing_unittest.TestUtilityFunctions) ... root: INFO     this should be logged
ok

[Mihai Parparita]

The logging handler that logs to the console seems to bypass OutputCapture, so I'm not sure how to best suppress this.

[Eric Seidel (no email)]

Interesting.  OutputCapture replaces stderr/stdout with a tee() (see deprecatedlogging.py).  It's possible that the logging handler installs its own tee of sorts after OutputCapture does.

Eventually the plan is to get rid of all uses of log() and error() from deprecatedlogging.py.  Those were written by me long before I had even heard of python's logging infrastructure.  Unfortunately I don't really understand python's logging stuff yet, or I would have done the replacements already.

When we eventually move to using python's built-in logging.py then we may have to re-think how OutputCapture works, or how we go about testing logging at all in the unit tests.  OutputCapture tests have proven *hugely* useful in the past.  Particularly for ease of dealing with mocks.  (Making a Mock call log("MOCK: method_name") is an easy to way to see what methods were called across all mocks duringthe invocation of your method under test.)

[Dirk Pranke]

I spent far more time than I would like to recall looking at this a few weeks ago when I was revamping the way the NRWT logging works (incl. printing.py).

The problem is that test-webkitpy is installing its own logger and logging that message (see test-webkitpy:69). That logger prints anything that comes in at LOG_INFO to stderr. If you don't want LOG_INFO messages to get printed, you should change this behavior (I don't know what you want the behavior to be).

At this point I understand python's logging stuff pretty well, so if you can decide what you want test-webkitpy to do, I should be able to implement it.

[Dirk Pranke]

changing subject accordingly; original subject line was:

webkitpy.layout_tests.layout_package.printing_unittest.TestUtilityFunctions.test_configure_logging should use OutputCapture

[Eric Seidel (no email)]

Chris added our minimal existing logging.  I don't really know how it's designed to work.

[Eric Seidel (no email)]

So when we move all logging to go through logging.py instead of deprecatedlogging.py, how will we capture the logging output on a per-test basis for testing?  Can tests install their own handlers?  Should tests be disabling some global handlers?  Should OutputCapture?

[Dirk Pranke]

(In reply to comment #6)
> So when we move all logging to go through logging.py instead of deprecatedlogging.py, how will we capture the logging output on a per-test basis for testing?  Can tests install their own handlers?  Should tests be disabling some global handlers?  Should OutputCapture?

I'm not sure how to answer that question, since it depends on what you want to try and do. Tests can certainly install their own handlers (that's what printing.py is doing), so if you wanted to test specific output recorded through logging calls, that would be the way to go.

On the other hand, if you want to test what, if anything, is being printed to stdout/stderr, you need to do something like OutputCapture, or change the code to take streams as input parameters (like new-run-webkit-tests does).

There isn't a good way for one subsystem to alter another subsystems' logging configuration safely; that's what I spent a lot of time trying to do in the previously mentioned task.

I don't quite know what Chris's original intent in test-webkitpy was, although I think it was intended to suppress logging during the initial phase of setup and then go back to normal. One option would be for it to remove its logging handler in the last step before it actually tries to run the tests.

[Dirk Pranke]

Created attachment 68988 [details]
Patch

[Dirk Pranke]

I've uploaded a patch that changes the level on the default logger to only log ERRORs or worse; this makes the "This should be logged" message go away, but will still log weirdness.

If this is what you want, we can probably land this.

[Dirk Pranke]

Eric, what do you want to do with this?

[Adam Barth]

(In reply to comment #10)
> Eric, what do you want to do with this?

Eric has been on vacation.  He should be back Tuesday or Wed.

[Eric Seidel (no email)]

I really don't know what to recommend here.  I still don't feel like I understand python logging.

Ideally we would move away from deprecatedlogging.py long-term.  We'd replace it with a logging.py solution.  But we'd like to not lose OutputCapture-style testing coverage.

Maybe we should use a custom level "MOCK" which we can capture special in our handlers.

Once we move to full logging.py usage (or make deprecatedlogging.py use logging.py under the covers), then OutputCapture can just install a special set of handlers?  Or remove any other handlers?

I don't think test-webkitpy needs global handlers.  At least not ones we don't replace inside the unit tests themselves.  Logging w/o explicitly using OutputCapture should be an "error" in our testing.

I'll look at your patch now.

[Eric Seidel (no email)]

I think the right solution is instead for OutputCapture to register its own handler and disable all other handlers.

[Dirk Pranke]

Registering its own handler doesn't help, I don't think (since we're already capturing stdout and stderr). Note that if you change test_configure_logging to use OutputCapture(), you'll still get the message printed to stderr (since test-webkitpy installed its own logger that keeps its own reference to the original stderr).

So, as you say, you could change OutputCapture.capture_output() to remove any installed handlers and restore them during restore_output(). I'm not a big fan of that change, because it has OutputCapture messing with stuff it doesn't own, and the logging modules are not really designed to enable this, so the code has to poke at internals to accomplish its mission. Note that printer.configure_logging() actually originally did what you are suggesting, but it proved to be really fragile, possibly because I wasn't being aggressive enough about removing *all* handlers. 

So, we're really looking at different things here.

1) capturing anything that is logged to stdout/stderr by test code. OutputCapture does this just fine today.

2) preventing anything from actually getting logged to stdout/stderr during a test that is using OutputCapture.

3) treating anything getting logged to stdout/stderr if a test isn't using OutputCapture as an error

I think (2) and (3) are somewhat at odds with each other. The only comprehensive way to prevent logging outside of stdout/stderr would be to capture stdout/stderr at the beginning of the test run, but somehow still allow the unittest framework itself to log stuff. But, if you do that, you would also have to somehow inject code after each test to see if anything did get incorrectly logged to stdout/stderr.

As an alternative, if you leave stdout/stderr alone at the beginning, then you don't have to do anything special to the unittest subsystem, and you can rely on us actually seeing garbage in the test-webkitpy output to detect bugs. But, you still need my patch to turn off the channel through the initial webkitpy handler. 

And, you need *some* handler to be installed, or you'll get spurious "no handlers found for module x.y.z" messages when things do call into the logging system.

So, I think my patch is the right way to get what you're looking for. Does that make sense?

[Dirk Pranke]

Created attachment 71834 [details]
Patch

[Dirk Pranke]

Created attachment 71836 [details]
Patch

[Dirk Pranke]

Okay, here's a revised patch to test-webkitpy that removes the logging handler that we install during the bootstrapping process.

With this patch, any time a routine calls _log.X() and the method isn't filtered, we will get a "no handlers could be found for logger "XXX" message. 

This means we can play whack-a-mole trying to find all the places that are trying to log things and we're not expecting them, but if everything is doing things correctly, we won't log anything. Note that the proper way to catch these messages is to install a logger, so we should probably modify outputcapture to do this and use outputcapture accordingly.

Note that this patch suppresses debug() messages for the default logger (at main.py:138). If we want to see the "no handler found" message and whack even the debug messages, we can change this line to logging.NOTSET, but I don't think we should try to be that aggressive.

[Eric Seidel (no email)]

Comment on attachment 71836 [details]
Patch

I think I like this patch?  But I can't really tell what all is going on here.  Maybe it needs a more descriptive ChagneLog?

[Eric Seidel (no email)]

Comment on attachment 71836 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=71836&action=review

I think I understand what this does now.  It would be better to move off modifying the root logger.

> WebKitTools/Scripts/test-webkitpy:80
> -    logger.setLevel(logging.NOTSET)
> +    logger.setLevel(logging_level)

I think this is what caused your later unit test to need to modify the root logger.  I would leave this code for now.  You probably don't need to even use the root logger in your tests.

> WebKitTools/Scripts/webkitpy/layout_tests/layout_package/metered_stream_unittest.py:106
>          logger = logging.getLogger()
>          handler = logging.StreamHandler(b)
>          logger.addHandler(handler)
> +        level = logger.level
> +        logger.setLevel(logging.NOTSET)
>          m.update("bar")

Seems we should use an intermediate logger instead of modifying the root.

[Dirk Pranke]

I'm not planning on working on this any time soon, so I'm disclaiming ownership. Eric, you filed the bug, so you can decide if you still want to leave this open.

[Dirk Pranke]

I cleaned this up a while ago. closing.