frame hiding cannot be disabled, interferes with debugging

[Robert Collins]

Our test frame hiding can't be disabled - the code meant to disable it is not sufficiently effective:

This is a hidden bt:
======================================================================
ERROR: testrepository.tests.repository.test_file.TestFileRepository.test_initialise
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/jml/src/testresources/trunk/lib/testresources/__init__.py", line 688, in tearDownResources
    tearDownResources(self, self.resources, _get_result())
  File "/home/jml/src/testresources/trunk/lib/testresources/__init__.py", line 710, in tearDownResources
    resource[1].finishedWith(getattr(test, resource[0]), result)
AttributeError: 'TestFileRepository' object has no attribute 'tempdir'

And this is the non hidden one:

----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/robertc/source/unittest/testtools/working/testtools/runtest.py", line 169, in _run_user
    return fn(*args, **kwargs)
  File "/usr/lib/pymodules/python2.7/testresources/__init__.py", line 648, in tearDownResources
    tearDownResources(self, self.resources, _get_result())
  File "/usr/lib/pymodules/python2.7/testresources/__init__.py", line 670, in tearDownResources
    resource[1].finishedWith(getattr(test, resource[0]), result)
AttributeError: 'TestCommand' object has no attribute 'tempdir'

But this is the pdb one:

  /usr/lib/python2.7/runpy.py(162)_run_module_as_main()
-> "__main__", fname, loader, pkg_name)
  /usr/lib/python2.7/runpy.py(72)_run_code()
-> exec code in run_globals
  /home/robertc/source/unittest/testtools/working/testtools/run.py(332)<module>()
-> main(sys.argv, sys.stdout)
  /home/robertc/source/unittest/testtools/working/testtools/run.py(329)main()
-> program = TestProgram(argv=argv, testRunner=runner, stdout=stdout)
  /home/robertc/source/unittest/testtools/working/testtools/run.py(173)__init__()
-> self.runTests()
  /home/robertc/source/unittest/testtools/working/testtools/run.py(322)runTests()
-> self.result = testRunner.run(self.test)
  /home/robertc/source/unittest/testtools/working/testtools/run.py(46)run()
-> return test.run(result)
  /usr/lib/python2.7/unittest/suite.py(103)run()
-> test(result)
  /usr/lib/python2.7/unittest/suite.py(65)__call__()
-> return self.run(*args, **kwds)
  /usr/lib/pymodules/python2.7/testresources/__init__.py(245)run()
-> test(result)
  /usr/lib/python2.7/unittest/case.py(385)__call__()
-> return self.run(*args, **kwds)
  /home/robertc/source/unittest/testtools/working/testtools/testcase.py(523)run()
-> return self.__RunTest(self, self.exception_handlers).run(result)
  /home/robertc/source/unittest/testtools/working/testtools/runtest.py(74)run()
-> return self._run_one(actual_result)
  /home/robertc/source/unittest/testtools/working/testtools/runtest.py(88)_run_one()
-> return self._run_prepared_result(ExtendedToOriginalDecorator(result))
  /home/robertc/source/unittest/testtools/working/testtools/runtest.py(100)_run_prepared_result()
-> self._run_core()
  /home/robertc/source/unittest/testtools/working/testtools/runtest.py(135)_run_core()
-> self._run_cleanups, self.result):
  /home/robertc/source/unittest/testtools/working/testtools/runtest.py(169)_run_user()
-> return fn(*args, **kwargs)
  /home/robertc/source/unittest/testtools/working/testtools/runtest.py(154)_run_cleanups()
-> function, *arguments, **keywordArguments)
  /home/robertc/source/unittest/testtools/working/testtools/runtest.py(173)_run_user()
-> return self._got_user_exception(sys.exc_info())
  /home/robertc/source/unittest/testtools/working/testtools/runtest.py(193)_got_user_exception()
-> self.case.onException(exc_info, tb_label=tb_label)
  /home/robertc/source/unittest/testtools/working/testtools/testcase.py(484)onException()
-> self._report_traceback(exc_info, tb_label=tb_label)
> /home/robertc/source/unittest/testtools/working/testtools/testcase.py(516)_report_traceback()
-> self.addDetail(tb_label, content.TracebackContent(exc_info, self))

Of the three, only the last is useful for debugging issues in the test environment. Now, I acknowledge that most users, most of the time, are happy with the first. Getting something approximately the second is essential for debugging testtools itself, and other similar environments.

I consider this a regression from when we didn't hide at all (even though the decision to hide some of the time was taken with eyes open, we didn't mean to cripple ourselves), so triaging critical.

[Jonathan Lange (jml)]

How did you get the non-hidden stack?

[Robert Collins (lifeless)]

On Mon, Oct 31, 2011 at 5:43 AM, Jonathan Lange <email address hidden> wrote:
> How did you get the non-hidden stack?

pdb

[Jonathan Lange (jml)]

Thanks but I meant the stack you label "non hidden" in your original report, not the one labelled "pdb".

[Robert Collins (lifeless)]

Oh?

Traceback (most recent call last):
  File "/home/jml/src/testresources/trunk/lib/testresources/__init__.py", line 688, in tearDownResources
    tearDownResources(self, self.resources, _get_result())
  File "/home/jml/src/testresources/trunk/lib/testresources/__init__.py", line 710, in tearDownResources
    resource[1].finishedWith(getattr(test, resource[0]), result)
AttributeError: 'TestFileRepository' object has no attribute 'tempdir'

-> I ran make check in testrepository after you reported the bug there.

[Jonathan Lange (jml)]

There are three stacks in the initial bug report. I am interested in how you obtained the second.

[Robert Collins (lifeless)]

I edited out all the __unittest lines in testtools, then ran make check

[Jonathan Lange (jml)]

This isn't actually a regression. I won't argue about whether or not this is a Critical bug, but it's not a regression. It's not that we've broken past functional behaviour, but rather that we've released something that doesn't quite do what it promises to do. We have always been using TestResult._exc_info_to_string from unittest for rendering tracebacks. That hides stack levels with __unittest set, and it has always hidden the unittest levels of the stack where __unittest is set. To show the *full* stack is right, but it's a new behaviour for us.

To enable this, and to fix bug 854769, I am currently leaning toward moving the implementation of _exc_info_to_string over to our code. This might also simplify some of our unicode handling.

PS. We have a facility for unhiding *our* levels of the stack (run_tests_with = FullStackRunTest). Bug 881780 points out how this could be better.

[Jonathan Lange (jml)]

Have just tried to fix this bug. I've come up with a branch that doesn't change the behaviour much but improves the code factoring a little.

The stack hiding controls in trunk mostly work, except that FullStackRunTest has a bug that causes any error in the test to not be caught. My branch fixes that. In particular, hide_testtools_stack() works the same in both trunk and my branch, and works "correctly".

The reason for the discrepancy between the pdb stack and the exception error message stack is unknown to me. I can confirm that this difference is also apparent in traceback.print_exc vs traceback.print_stack. Code http://paste.ubuntu.com/828997/, and output: http://paste.ubuntu.com/829001/ that demonstrate the difference.

I think the exc_info traceback stops (or starts, depending on your perspective) at the frame where the exception is caught.

Showing the full stack, as pdb or print_stack do, ranks as a feature request.