Bug 173070 – webkitpy: By default, OutputCapture should capture all output which would be printed

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

[Jonathan Bedard]

Currently, a default OutputCaptureScope will not capture the debug stream, even if the debug stream would be printed.

[Jonathan Bedard]

Created attachment 312218 [details]
Patch

[Daniel Bates]

Comment on attachment 312218 [details]
Patch

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

> Tools/Scripts/webkitpy/common/system/outputcapture.py:115
> +        if self._output_capture:
> +            self._output_capture = OutputCapture()

r- because of this. We are overriding the specified output_capture object.

> Tools/Scripts/webkitpy/common/system/outputcapture.py:116
> +            self._output_capture.set_log_level(logging.getLogger().level)

It does not seem appropriate for this class to chose the log level to capture given that this class takes an OutputCapture object. The caller should instantiate an OutputCapture o, set the appropriate log level, and then pass o to OutputCaptureScope.

[Daniel Bates]

(In reply to Daniel Bates from comment #2)
> > Tools/Scripts/webkitpy/common/system/outputcapture.py:116
> > +            self._output_capture.set_log_level(logging.getLogger().level)
> 
> It does not seem appropriate for this class to chose the log level to

*choose

[Jonathan Bedard]

Created attachment 312247 [details]
Patch

[Jonathan Bedard]

(In reply to Daniel Bates from comment #2)
> Comment on attachment 312218 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=312218&action=review
> 
> > Tools/Scripts/webkitpy/common/system/outputcapture.py:115
> > +        if self._output_capture:
> > +            self._output_capture = OutputCapture()
> 
> r- because of this. We are overriding the specified output_capture object.
> 
> > Tools/Scripts/webkitpy/common/system/outputcapture.py:116
> > +            self._output_capture.set_log_level(logging.getLogger().level)
> 
> It does not seem appropriate for this class to chose the log level to
> capture given that this class takes an OutputCapture object. The caller
> should instantiate an OutputCapture o, set the appropriate log level, and
> then pass o to OutputCaptureScope.

My apologies, I didn't mean to put this patch up for review yet.

The intended effect (as seen in attachment 312247 [details]) is for the OutputCaptureScope to do this by default if no OutputCapture is used to construct an OutputCaptureScope. If an OutputCapture is specified, then the logging level of that scope will be used.

I don't think it's intuitive that the OutputCaptureScope only captures up to the INFO level by default. I think by default, OutputCaptureScope should capture whatever the current logging level is.

[Build Bot]

Comment on attachment 312247 [details]
Patch

Attachment 312247 [details] did not pass mac-wk2-ews (mac-wk2):
Output: http://webkit-queues.webkit.org/results/3890619

New failing tests:
imported/w3c/web-platform-tests/fetch/api/cors/cors-origin.any.html

[Build Bot]

Created attachment 312255 [details]
Archive of layout-test-results from ews104 for mac-elcapitan-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews104  Port: mac-elcapitan-wk2  Platform: Mac OS X 10.11.6

[Daniel Bates]

Comment on attachment 312247 [details]
Patch

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

> Tools/Scripts/webkitpy/common/system/outputcapture.py:116
> +        if not self._output_capture:
> +            self._output_capture = OutputCapture()
> +            self._output_capture.set_log_level(logging.getLogger().level)

I feel this is more surprising not less surprising. OuputCaptureScope should just be a context-manager for OutputCapture. I am not a fan that it instantiates an OutputCapture as a convenience though we did it. Given that it OutputCaptureScope instantiate an OutputCapture it is surprising that when OuputCaptureScope does this that it alters the default log level of the OutputCapture it instantiates.

[Jonathan Bedard]

Created attachment 312306 [details]
Patch

[Jonathan Bedard]

(In reply to Daniel Bates from comment #8)
> Comment on attachment 312247 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=312247&action=review
> 
> > Tools/Scripts/webkitpy/common/system/outputcapture.py:116
> > +        if not self._output_capture:
> > +            self._output_capture = OutputCapture()
> > +            self._output_capture.set_log_level(logging.getLogger().level)
> 
> I feel this is more surprising not less surprising. OuputCaptureScope should
> just be a context-manager for OutputCapture. I am not a fan that it
> instantiates an OutputCapture as a convenience though we did it. Given that
> it OutputCaptureScope instantiate an OutputCapture it is surprising that
> when OuputCaptureScope does this that it alters the default log level of the
> OutputCapture it instantiates.

Ok. I've just uploaded attachment 312306 [details], which does this on the OutputCapture level instead. Note that we still can't use default arguments since we need these to be evaluated at runtime because the logging level can change as the program is running.

[Daniel Bates]

Comment on attachment 312306 [details]
Patch

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

> Tools/Scripts/webkitpy/common/system/outputcapture.py:47
> -        self._log_level = logging.INFO
> +        self._log_level = log_level if log_level is not None else logging.getLogger().level

r-, this will cause test failures when you run the test using "test-webkitpy -vv".

OutputCapture is used almost exclusively in unit testing code. It seems error prone to have OutputCatpure use the current logger level instead of hardcoded log level as an unbalanced logger.getLogger().setLevel() can cause later code that uses OutputCapture to be affected. Although we would notice such an unbalanced logger.getLogger().setLevel() that affects current tests (as they would fail) it would be hard to notice such an unbalanced call to logger.getLogger().setLevel() added to new code tested with newly added tests (or future tests added long after the code that added the unbalanced logger.getLogger().setLevel() was committed) unless both patch writer and reviewer are extra vigilant. For patch writers that explicitly want to capture a logging level different from logging.INFO they can use OutputCapture.set_log_level() to explicitly opt-into capturing such log messages.

[Jonathan Bedard]

I still dislike the current implementation of OutputCapture, but given that Dan is correct about this breaking webkitpy-tests -vv, and given that this (currently) doesn't have any negative effect, I'm going to close this bug.  Any changes to OutputCapture should use a different approach.