traceback filtering of non-contiguous unittest frames is broken

[Leo Arias]

When an AssertionError is thrown during the fixture set up, then _count_relevant_tb_levels will return 1. Then, the traceback of the error will not be reported.

To reproduce:
Here I have two tests with wrong fixtures. One raises a ZeroDivisionError and the other one an AssertionError

import fixtures
import testtools

class WrongFixtureWithoutTrace(fixtures.Fixture):
   def setUp(self):
      super(WrongFixtureWithoutTrace, self).setUp()
      raise AssertionError('error')

class WrongFixtureWithTrace(fixtures.Fixture):
   def setUp(self):
      super(WrongFixtureWithTrace, self).setUp()
      1/0

class TestCase(testtools.TestCase):

    def test_without_trace(self):
        self.useFixture(WrongFixtureWithoutTrace())

    def test_with_trace(self):
        self.useFixture(WrongFixtureWithTrace())

When I run them, I get:

======================================================================
ERROR: test_with_trace (test.TestCase)
----------------------------------------------------------------------
_StringException: Traceback (most recent call last):
  File "/tmp/test.py", line 22, in test_with_trace
    self.useFixture(WrongFixtureWithTrace())
  File "/usr/lib/python2.7/dist-packages/testtools/testcase.py", line 579, in useFixture
    fixture.setUp()
  File "/tmp/test.py", line 13, in setUp
    1/0
ZeroDivisionError: integer division or modulo by zero

======================================================================
FAIL: test_without_trace (test.TestCase)
----------------------------------------------------------------------
_StringException: Traceback (most recent call last):
  File "/tmp/test.py", line 19, in test_without_trace
    self.useFixture(WrongFixtureWithoutTrace())
AssertionError: error

----------------------------------------------------------------------
Ran 2 tests in 5.854s

FAILED (failures=1, errors=1)

Note on the second test that there is only one line of the trace, hiding where and why the error occured.

[Robert Collins (lifeless)]

I breakpointed _count_relevant_tb_levels which interestingly is only hit from the failing case.

The issue is that self.useFixture shows up as a unittest method - which arguably it isn't. But we should show one more frame than we do. -> off by one error?

[Robert Collins (lifeless)]

count1:
======================================================================
FAIL: f.TestCase.test_without_trace
----------------------------------------------------------------------
Traceback (most recent call last):
  File "f.py", line 19, in test_without_trace
    self.useFixture(WrongFixtureWithoutTrace())
AssertionError: error

count2:
FAIL: f.TestCase.test_without_trace
----------------------------------------------------------------------
Traceback (most recent call last):
  File "f.py", line 19, in test_without_trace
    self.useFixture(WrongFixtureWithoutTrace())
  File "testtools/testcase.py", line 591, in useFixture
    fixture.setUp()
AssertionError: error

count3:
FAIL: f.TestCase.test_without_trace
----------------------------------------------------------------------
Traceback (most recent call last):
  File "f.py", line 19, in test_without_trace
    self.useFixture(WrongFixtureWithoutTrace())
  File "testtools/testcase.py", line 591, in useFixture
    fixture.setUp()
  File "f.py", line 8, in setUp
    raise AssertionError('error')
AssertionError: error

[Robert Collins (lifeless)]

4:
FAIL: f.TestCase.test_without_trace
----------------------------------------------------------------------
Traceback (most recent call last):
  File "f.py", line 19, in test_without_trace
    self.useFixture(WrongFixtureWithoutTrace())
  File "testtools/testcase.py", line 591, in useFixture
    fixture.setUp()
  File "f.py", line 8, in setUp
    raise AssertionError('error')
AssertionError: error

Note that this too stops at the testcase methods, which filtering is happening before the content object : we appear to have two traceback manipulating locations/routines, so we need to fix that too.

Of particular interest note that we're filtering the trace in precisely the wrong direction. low count - show top, not the bottom.

[Robert Collins (lifeless)]

Ok, so I think this is whats happening.

The filtering routine was designed to stop the plumbing of matchers and suchlike showing up, but the stack we have looks like this

user frame
test frame
user frame
user frame

The stack the first pass filter has looks like this
main()
test frame
test frame
test frame
user frame
test frame
user frame
user frame

and it's logic is to cut down to the first user frame, which it does successfully.

So we need to reevaluate what this second pass filtering is trying to do conceptually. I'm inclined to turn this second pass filter off by default until we address this, as I suspect it crops up subtlely at the moment and most people just go wtf.

[Dan Watkins (oddbloke)]

Am I right in thinking that this (specific) bug is fixed?

Is "all" that remains a more general conversation about traceback formatting?

My initial understanding of the intent of the secondary pass is that it should remove *all* internal traceback frames (with the possible exception of the bottom-most one). I've spent the afternoon playing around with something based on this at https://github.com/OddBloke/testtools/blob/traceback_filtering/testtools/content.py#L178-L237.

I could also see that the secondary pass might actually be undesirable; does it make it harder to work out why _your_ code has failed if you can't see how the internals of testtools (or other testing things) have been involved?

[Jonathan Lange (jml)]

The second pass filtering is definitely disabled, but I think the bug is being left open to decide what to do about it.

99% of the time the internal traceback frames are irrelevant. If they can be reliably elided, and it's easy to turn them back on, then I think we should do that. Others might disagree.

Thanks for the code, I haven't had a chance to get into it or your many other patches, but I will.

[Robert Collins (lifeless)]

IMO the bug is open to remind us to either a) delete the disabled code
or b) fix the feature and restore it.

At the time I thought the feature was broken by design, and not
recoverable, but Jono wasn't so sure: I'd be happy with a patch that
closes the bug and strips the second pass entirely - if Jono is.

-Rob

[Jonathan Lange (jml)]

I think the feature can be made to work, and that it's worth a try. Deleting the disabled code & opening a new wishlist bug would be a valid way of closing this one, I guess.