Bug 36725 – webkit-patch: Enable Python logging fully (was "test-webkitpy: Eliminate spurious output")

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

[Chris Jerdonek]

Running test-webkitpy shouldn't have spurious output like this:

...........................................Received HTTP status 500 from server.  Retrying in 0 seconds...
Received HTTP status 500 from server.  Retrying in 0.0 seconds...
................................................................................................................................................................................................................................................................................................
----------------------------------------------------------------------
Ran 331 tests in 0.799s

OK


This involves replacing deprecated_logging in networktransaction.py with Python logging.

To preserve existing behavior, I may need help in knowing where NetworkTransaction is being used.  I'm not sure whether Python logging has been enabled yet for the scripts currently using NetworkTransaction.

[Eric Seidel (no email)]

This is a recent regression from some test.  It didn't used to have this output as of Friday.

[Chris Jerdonek]

(In reply to comment #1)
> This is a recent regression from some test.  It didn't used to have this output
> as of Friday.

Running test-webkitpy with verbose output:

> test-webkitpy -v

...
test_trivial (webkitpy.common.net.irc.ircproxy_unittest.IRCProxyTest) ... ok
test_exception (webkitpy.common.net.networktransaction_unittest.NetworkTransactionTest) ... ok
test_retry (webkitpy.common.net.networktransaction_unittest.NetworkTransactionTest) ... Received HTTP status 500 from server.  Retrying in 0 seconds...
Received HTTP status 500 from server.  Retrying in 0.0 seconds...
ok
test_success (webkitpy.common.net.networktransaction_unittest.NetworkTransactionTest) ... ok
test_timeout (webkitpy.common.net.networktransaction_unittest.NetworkTransactionTest) ... ok
...

Is it possible it's related to the ordering of the tests (if some code shuts off rendering to the screen)? The ordering probably changed with the unit test auto-detection that was landed yesterday:

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

I seem to remember us noticing some order-dependent unit-test behavior when we met middle of the week (though probably not this specific behavior).

[Chris Jerdonek]

(In reply to comment #2)
> Is it possible it's related to the ordering of the tests (if some code shuts
> off rendering to the screen)? The ordering probably changed with the unit test
> auto-detection that was landed yesterday:
> 
> https://bugs.webkit.org/show_bug.cgi?id=36591

I looked into it, and yes, it's because of what I guessed above.

It turns out there is a bug in deprecated_logging_unittest.py that is shutting off sys.stderr:

class LoggingTest(unittest.TestCase):

    def assert_log_equals(self, log_input, expected_output):
        original_stderr = sys.stderr
        test_stderr = StringIO.StringIO()
        sys.stderr = test_stderr

        try:
            log(log_input)
            actual_output = test_stderr.getvalue()
        finally:
-->         original_stderr = original_stderr (should be sys.stderr = original_stderr)

http://trac.webkit.org/browser/trunk/WebKitTools/Scripts/webkitpy/common/system/deprecated_logging_unittest.py#L49

Before r56671, this test occurred towards the beginning.  But after r56671, this test occurred later -- unmasking the output.

Fixing this bug will cause the spurious output to remain.  (Actually, it will increase the spurious output slightly from another test or two.)  So the fix is still to replace deprecated_logging with Python's logging module.

test-webkitpy already has logic to filter out log messages from webkitpy so they don't get displayed to the screen (and without interfering with the unit tests' ability to test logging).

[Adam Barth]

Go ahead and change networktransaction to use Python logging.  We should just remove depricated_logging whenever we can.

[Chris Jerdonek]

(In reply to comment #4)
> Go ahead and change networktransaction to use Python logging.  We should just
> remove depricated_logging whenever we can.

I'll do that, but should we first enable Python logging for the calling scripts -- or do you not care about this particular message?  I wouldn't want my change to suppress errors the end-user should be seeing.

[Adam Barth]

> I'll do that, but should we first enable Python logging for the calling scripts
> -- or do you not care about this particular message?  I wouldn't want my change
> to suppress errors the end-user should be seeing.

Is there a downside to enabling logging for the calling scripts?  In any case, this is a message for folks looking at the raw output of the bots on the console, not normal users.

[Chris Jerdonek]

(In reply to comment #6)
> > I'll do that, but should we first enable Python logging for the calling scripts
> > -- or do you not care about this particular message?  I wouldn't want my change
> > to suppress errors the end-user should be seeing.
> 
> Is there a downside to enabling logging for the calling scripts?  In any case,
> this is a message for folks looking at the raw output of the bots on the
> console, not normal users.

The only downside is if we don't filter things correctly initially, there may be some annoying messages from things the user doesn't want to see (e.g. autoinstall log messages).  That part I can handle though.  Really the only thing I may need help with, as I said above, is knowing which scripts need to have logging enabled.  It might be good to know for--

(1) NetworkTransaction (for the present report), and
(2) everything else (to get rid of deprecated_logging entirely), e.g. webkit-patch

For doing this, I can probably put a standard configure_logging() method in common/system/logutils.py that should be good for most purposes, and that one can be used for the most part.

[Chris Jerdonek]

Fixed the typo: http://trac.webkit.org/changeset/56699

[Adam Barth]

I think we should use it for everything.  We have deprecated logging because we didn't know any better at the time.

[Chris Jerdonek]

(In reply to comment #9)
> I think we should use it for everything.

I was asking more the specific names of the scripts.  Are there any scripts you know of we should enable logging for aside from--

* check-webkit-style (already enabled)
* new-run-webkit-tests (already enabled)
* test-webkitpy (already enabled)
* validate-committer-lists (probably not)
* webkit-patch (not sure)

I don't think we should automatically turn on logging when a script imports from webkitpy because I'd rather the caller have control over when and how they're opted in.  And I'm sure it's a hackish process to remove or otherwise modify an existing logging configuration.  We can make opting in as simple as calling a configure_logging() method in a standard location.

[Adam Barth]

Let's start with webkit-patch.

[Chris Jerdonek]

Created attachment 51870 [details]
Proposed patch

[Adam Barth]

Comment on attachment 51870 [details]
Proposed patch

Great!

[Chris Jerdonek]

(In reply to comment #13)
> (From update of attachment 51870 [details])
> Great!

Thanks again, Adam!

[Chris Jerdonek]

Committed:

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