Opened 11 years ago

Last modified 7 weeks ago

#2365 defect new

trial should completely manage its output stream

Reported by: Glyph Owned by:
Priority: high Milestone:
Component: trial Keywords:
Cc: Jonathan Lange Branch:
Author:

Description (last modified by Glyph)

Right now warnings from tests and output from tests simply interrupt the reporter's reporting of success and failure, causing the output to not line up.

With the default reporter - whose output is not intended to be parsed - this is in principle simply aesthetic, but things (like buildbot) do actually parse. With other reporter plug-ins that emit structured output that is not newline-delimited though, random test output in the middle of the output stream would be even worse. (For example, an XML reporter where a test printed a '<'.)

There are related problems which are more technical. For example, trial knows to use untilConcludes but test cases aren't going to.

Trial should generally be aware of output from tests, and visually distinguish between stdout stderr so that warnings are clearly visible.

In the reporters packaged within trial, this should look something like this:

# verbose
some.test.module
  SomeTestCase
    test_something ...                                                 [OUTPUT]
      """
      a value was printed
      """
    test_something ...                                                     [OK]

===============================================================================
[OUTPUT]

  a value was printed

some.test.module.SomeTestCase.test_something

# bwverbose
some.test.module.SomeTestCase.test_something ... [OUTPUT]
  """
  a value was printed
  """
some.test.module.SomeTestCase.test_something ... [OK]

Change History (23)

comment:1 Changed 11 years ago by jknight

I would be very sad if print "asdf" in a test method became less reliable than it is now (that is, got delayed, eaten, etc).

comment:2 Changed 11 years ago by Jonathan Lange

Me too.

comment:3 Changed 11 years ago by Jonathan Lange

Cc: Jonathan Lange added

glyph, I claim review rights on this one.

comment:4 Changed 11 years ago by Glyph

So would I. IMHO, trial should print failing tracebacks immediately, too. This change won't eat or delay output though, it will simply prevent them from breaking the reporter's idea of what's going on.

comment:5 Changed 11 years ago by Glyph

Status: newassigned

comment:6 Changed 11 years ago by Jean-Paul Calderone

This is good functionality. It may not be good default functionality until it's bullet proof, though. I'd like to see some of the default reporter's more advanced features moved into a _different_ reporter, simplifying the default. When the more advanced one has seen some usage and is relatively bug free, then we could consider making it the default.

We could also do something with config files to let people persistently specify their default preferences.

Note also that trial installs its own warning printer currently. It is quite round-about to prevent these from being displayed by capturing stdout. The warning printer it installs could just do the right thing.

comment:7 Changed 11 years ago by Glyph

jml: please review this in trialout-2365

I seriously doubt this will pass your scrutiny, but I'm a bit stuck on where to take it next and how to test the changes I've made, so I'd like some feedback. I am pretty sure they work, because the entire trial suite failed whenever I disturbed anything minor.

comment:8 Changed 11 years ago by Glyph

Keywords: review added
Owner: changed from Glyph to Jonathan Lange
Priority: normalhighest
Status: assignednew

comment:9 in reply to:  6 Changed 11 years ago by Glyph

Replying to exarkun:

This is good functionality. It may not be good default functionality until it's bullet proof, though.

I only agree if you have some clear metric for "bullet proof" that goes beyond having tests, working on buildbot, and passing review. If that isn't good enough, then we need a way to make it good enough that is specific. Otherwise, the feature will languish in an optional switch that nobody will use for years. One of the XP values is "courage" for this reason: if you leave features out for ill-defined fears about their stability, then there's no way they'll ever be good enough because there's no test that they're actually failing.

Also, this is as much a feature as it is a bugfix. Right now, the reporter is buggy. Tests scribble on the same output stream it does, which makes it completely impossible to parse. Effectively, "print"ing from a test is a supported operation in trial and it should have well-defined behavior. That is to say, the motivation for using untilConcludes in trial itself seems sufficient to propagate it to that "supported" feature of tests.

comment:10 in reply to:  4 Changed 11 years ago by Jonathan Lange

Replying to glyph:

So would I. IMHO, trial should print failing tracebacks immediately, too. This change won't eat or delay output though, it will simply prevent them from breaking the reporter's idea of what's going on.

I haven't looked at the ticket yet (waiting for chbranch now), but if you are thinking about things like this, then you should look at #2270

comment:11 Changed 11 years ago by Jonathan Lange

Keywords: review removed
Owner: changed from Jonathan Lange to Glyph

Initial thoughts:

  • test_log.LogPublisherTestCaseMixin should have docstrings explaining what it does. Cursing Python isn't specific enough.
  • There is a commented-out assertion in test_reporter. Why is the color assertion no longer appropriate?
  • Distinguishing between errors and cleanup errors is not a good idea, I think. In any case, it's not germane to this branch.
  • If you are adding new public methods to the reporter interface, then you will need to extend IReporter.

Other things:

  • The test coverage needs to be improved. The new public functions have no explicit unit tests, there is no test to check that warnings go to stderr and there is no test to show what happens when a test prints to either stdout or stderr.
  • I haven't thought a great deal about how _I_ would solve this problem (although see below), but I don't think it would be by adding new public methods to the reporter interface.

Now I'm going to dump some related ideas:

  • exarkun is probably right about config files
  • This solution only touches on the default reporter, but the problem exists with all of the reporters.
  • The ways reporters interact with the command line tool sucks. So although this is probably an improvement, it feels a little like polishing a turd.

Please assign to me for re-review when you are done.

comment:12 Changed 11 years ago by Glyph

I'll try to trim down the number of changes in the branch and remove irrelevant junk.

Adding public methods to IReporter was a last resort - I could not find any other way that the reporter could discover when the test run was starting and when it had finished based on current methods. I guess a better way to achieve the "optional" effect I was looking for would be to provide another interface which you could implement, IStreamCapture, and then check for IStreamCapture.providedBy(reporter) rather than hasattr. Still, that smells pretty bad to me.

jml: Barring any brilliant inspiration on my part, I would really like to get some guidance from you on what the IReporter interface really means. If 'print during tests for debug output' is a supported operation then perhaps the runner needs to clean up stdout and stderr rather than leaving it to the reporter - but that still means more public methods for the reporter to be able to handle those streams.

comment:13 Changed 11 years ago by Glyph

Priority: highesthigh

comment:14 Changed 10 years ago by Glyph

Owner: changed from Glyph to Jonathan Lange

Well, there hasn't been any brilliant inspiration on my part since I asked the question - I probably should have reassigned it then.

Please reassign to me with a comment when you've had a chance to consider the request for guidance...

comment:15 Changed 10 years ago by Glyph

See related ticket #2820

comment:16 Changed 7 years ago by <automation>

Owner: Jonathan Lange deleted

comment:17 Changed 5 years ago by Tom Prince

A couple of ideas on this: There are at least a couple of use cases of running tests, that perhaps deserve separate treatment here:

  • Running tests interactively during development: output from tests probably wants to be displayed immediately. It does make sense to control this output, though, so that doesn't show up in the middle of a line of trial output, but rather delimited on its own lines, and with the reporter properly able to line up its output before vs. after.
  • Running test through buildbot, or some other automated system, when the result is going to be looked at only at the end: here collecting output and showing it at the end is probably most useful (and perhaps doesn't even want/need to be displayed by default).

comment:18 in reply to:  17 Changed 5 years ago by Glyph

Replying to tom.prince:

A couple of ideas on this: There are at least a couple of use cases of running tests, that perhaps deserve separate treatment here:

  • Running tests interactively during development: output from tests probably wants to be displayed immediately. It does make sense to control this output, though, so that doesn't show up in the middle of a line of trial output, but rather delimited on its own lines, and with the reporter properly able to line up its output before vs. after.
  • Running test through buildbot, or some other automated system, when the result is going to be looked at only at the end: here collecting output and showing it at the end is probably most useful (and perhaps doesn't even want/need to be displayed by default).

I disagree, in the sense that it's basically a bug that --rterrors isn't the default; everything should always be displayed immediately. However, you're on to something here, in the sense that test output from a test should also be displayed in the test summary, if errors from those tests are displayed in the test summary.

comment:19 Changed 5 years ago by Glyph

Description: modified (diff)

Updating the description with a proposed format for output.

comment:20 Changed 3 months ago by mark williams

What about mimicking unittest's buffering behavior?

Given this test:

from unittest import TestCase

class T(TestCase):

    def test_good(self):
        print("OK")

    def test_fail(self):
        print("NOT OK")
        raise Exception

You get this output with --buffer:

E
Stdout:
NOT OK
.
======================================================================
ERROR: test_fail (xz.What)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/xz.py", line 10, in test_fail
    raise Exception
Exception

Stdout:
NOT OK

----------------------------------------------------------------------
Ran 2 tests in 0.000s

FAILED (errors=1)

comment:21 Changed 3 months ago by Jean-Paul Calderone

Test output should appear on stdout in real time since "print out random garbage" is often the only effective debugging technique (given the large number of bugs in pdb, unusual execution environments where interactive debugging is not possible, and the multitude of incompatible logging systems/behaviors).

comment:22 in reply to:  21 Changed 3 months ago by Glyph

Replying to Jean-Paul Calderone:

Test output should appear on stdout in real time since "print out random garbage" is often the only effective debugging technique (given the large number of bugs in pdb, unusual execution environments where interactive debugging is not possible, and the multitude of incompatible logging systems/behaviors).

Yes, thanks for highlighting this. I very much want immediate feedback when a test prints something. I just want it to be transformed and formatted such that it doesn't just mangle the output of the test runner.

comment:23 Changed 7 weeks ago by Glyph

(See note on #9266)

Note: See TracTickets for help on using tickets.