Bug 36725 - webkit-patch: Enable Python logging fully (was "test-webkitpy: Eliminate spurious output")
Summary: webkit-patch: Enable Python logging fully (was "test-webkitpy: Eliminate spur...
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Tools / Tests (show other bugs)
Version: 528+ (Nightly build)
Hardware: All All
: P2 Normal
Assignee: Chris Jerdonek
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-03-28 10:35 PDT by Chris Jerdonek
Modified: 2010-03-31 20:59 PDT (History)
5 users (show)

See Also:


Attachments
Proposed patch (13.14 KB, patch)
2010-03-28 16:19 PDT, Chris Jerdonek
abarth: review+
cjerdonek: commit-queue-
Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Chris Jerdonek 2010-03-28 10:35:33 PDT
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.
Comment 1 Eric Seidel (no email) 2010-03-28 10:37:53 PDT
This is a recent regression from some test.  It didn't used to have this output as of Friday.
Comment 2 Chris Jerdonek 2010-03-28 10:47:42 PDT
(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).
Comment 3 Chris Jerdonek 2010-03-28 12:00:05 PDT
(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).
Comment 4 Adam Barth 2010-03-28 12:13:39 PDT
Go ahead and change networktransaction to use Python logging.  We should just remove depricated_logging whenever we can.
Comment 5 Chris Jerdonek 2010-03-28 12:18:20 PDT
(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.
Comment 6 Adam Barth 2010-03-28 12:21:35 PDT
> 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.
Comment 7 Chris Jerdonek 2010-03-28 12:35:26 PDT
(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.
Comment 8 Chris Jerdonek 2010-03-28 12:36:25 PDT
Fixed the typo: http://trac.webkit.org/changeset/56699
Comment 9 Adam Barth 2010-03-28 13:07:43 PDT
I think we should use it for everything.  We have deprecated logging because we didn't know any better at the time.
Comment 10 Chris Jerdonek 2010-03-28 13:22:23 PDT
(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.
Comment 11 Adam Barth 2010-03-28 13:47:02 PDT
Let's start with webkit-patch.
Comment 12 Chris Jerdonek 2010-03-28 16:19:34 PDT
Created attachment 51870 [details]
Proposed patch
Comment 13 Adam Barth 2010-03-31 20:27:53 PDT
Comment on attachment 51870 [details]
Proposed patch

Great!
Comment 14 Chris Jerdonek 2010-03-31 20:33:14 PDT
(In reply to comment #13)
> (From update of attachment 51870 [details])
> Great!

Thanks again, Adam!
Comment 15 Chris Jerdonek 2010-03-31 20:59:01 PDT
Committed:

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