Better error messages from @capture_logging and friends

[itamarst]

Fixes #365.

@exarkun

[exarkun]

• The test suite where I have been using Eliot recently passes against this branch.
• If I intentionally introduce errors into the logging under test I sometimes get a nice traceback ending with an exception eliot._validation.ValidationError: ([u''], u"Field u'relpath' requires type to be one of [<type 'unicode'>]") Unfortunately, other times the exception seems to disappear into the bowels of my application code and tests again. This seems to just be a result of the way exceptions are handling in this application: the new, unexpected exceptions from Eliot probably get interpreted as some retryable error (or just run afoul of some poorly implemented exception handling code, there's a lot of it here) and I never get to see them. This bums me out quite a bit. I'm not sure what conclusions can be drawn from it.

[itamarst]

An alternative approach is recording the traceback at message logging time, but only raising it at the end of the test. That way it's not caught by application logic.

[itamarst]

OK, I tried a different approach. Do you get better messages now?

[exarkun]

There's a trivial incompatibility with testtools.TestCase in the branch now. testtools.TestCase.addCleanup only takes one argument (a no-argument callable). If I fix that then I get a traceback that is better but still has some problems:

  MagicFolderDbTests
    test_create ...                                                     [ERROR]

===============================================================================
[ERROR]
Traceback (most recent call last):
Failure: testtools.testresult.real._StringException: Traceback (most recent call last):
  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 151, in maybeDeferred
    result = f(*args, **kw)
  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/testing.py", line 281, in check_for_errors
    logger.validate()
  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/_output.py", line 243, in exclusively_f
    return f(self, *a, **kw)
  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/_output.py", line 374, in validate
    raise e.__class__("\n\n".join(self._failed_validations))
eliot._validation.ValidationError: ([32], u"Field u'relpath' requires type to be one of [<type 'unicode'>]"):   File "/home/exarkun/Environments/tahoe-lafs/bin/trial", line 10, in <module>
    sys.exit(run())

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/scripts/trial.py", line 621, in run
    test_result = trialRunner.run(suite)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/runner.py", line 979, in run
    return self._runWithoutDecoration(test, self._forceGarbageCollection)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/runner.py", line 1006, in _runWithoutDecoration
    run()

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/runner.py", line 1001, in <lambda>
    run = lambda: suite.run(result)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/runner.py", line 253, in run
    TestSuite.run(self, result)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/_asyncrunner.py", line 38, in run
    test(result)

  File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
    return self.run(*args, **kwds)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/runner.py", line 212, in run
    super(LoggedSuite, self).run(result)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/_asyncrunner.py", line 38, in run
    test(result)

  File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
    return self.run(*args, **kwds)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/runner.py", line 185, in run
    test(result)

  File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
    return self.run(*args, **kwds)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/runner.py", line 185, in run
    test(result)

  File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
    return self.run(*args, **kwds)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/runner.py", line 185, in run
    test(result)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/_asyncrunner.py", line 59, in __call__
    return self.run(result)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/trial/_asyncrunner.py", line 69, in run
    reporter._AdaptedReporter(result, self.__class__))

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/testtools/testcase.py", line 671, in run
    return run_test.run(result)

  File "/home/exarkun/Work/LeastAuthority/python/tahoe-lafs/src/allmydata/test/eliotutil.py", line 113, in run_and_republish
    d = maybeDeferred(run, self)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 151, in maybeDeferred
    result = f(*args, **kw)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/testing.py", line 343, in wrapper
    return function(self, *args, **kwargs)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/testing.py", line 375, in wrapper
    return function(self, logger)

  File "/home/exarkun/Work/LeastAuthority/python/tahoe-lafs/src/allmydata/test/eliotutil.py", line 89, in run
    return f(self, *a, **kw)

  File "/home/exarkun/Work/LeastAuthority/python/tahoe-lafs/src/allmydata/test/eliotutil.py", line 165, in run
    ).run(result)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/testtools/runtest.py", line 80, in run
    return self._run_one(actual_result)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/testtools/runtest.py", line 94, in _run_one
    return self._run_prepared_result(ExtendedToOriginalDecorator(result))

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/testtools/runtest.py", line 108, in _run_prepared_result
    self._run_core()

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/testtools/runtest.py", line 144, in _run_core
    self.case._run_test_method, self.result):

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/testtools/twistedsupport/_runtest.py", line 76, in _run_user
    d = defer.maybeDeferred(function, *args)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 151, in maybeDeferred
    result = f(*args, **kw)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/testtools/testcase.py", line 719, in _run_test_method
    return self._get_test_method()()

  File "/home/exarkun/Work/LeastAuthority/python/tahoe-lafs/src/allmydata/test/test_magic_folder.py", line 446, in test_create
    pathinfo=get_pathinfo(self.temp),  # a directory, but should be fine for test

  File "/home/exarkun/Work/LeastAuthority/python/tahoe-lafs/src/allmydata/magicfolderdb.py", line 140, in did_upload_version
    pathinfo=pathinfo,

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/_validation.py", line 450, in __call__
    logger, self.action_type, self._serializers, **fields)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/_action.py", line 830, in start_action
    action._start(fields)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/_action.py", line 359, in _start
    Message(fields, serializer).write(self._logger, self)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/_message.py", line 147, in write
    logger.write(logged_dict, self._serializer)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/_output.py", line 243, in exclusively_f
    return f(self, *a, **kw)

  File "/home/exarkun/Environments/tahoe-lafs/local/lib/python2.7/site-packages/eliot/_output.py", line 308, in write
    "{}: {}".format(e, "\n".join(traceback.format_stack())))

allmydata.test.test_magic_folder.MagicFolderDbTests.test_create
-------------------------------------------------------------------------------
Ran 7 tests in 0.104s

FAILED (errors=1, successes=6)

The extra blank line is a real part of the output, not a github comment or copy/paste artifact. It would be nice to eliminate that.

It also seems like the traceback could be chopped off a few frames before the end. The offending application code is at File "/home/exarkun/Work/LeastAuthority/python/tahoe-lafs/src/allmydata/magicfolderdb.py", line 140, in did_upload_version and then there are 6 more frames of Eliot implementation details being reported. It would be nice if the offending application code were at the bottom of the traceback for easy visual scanning.

Thanks!

[itamarst]

OK, how does it look now?

[exarkun]

The whitespace looks much better now. I don't think the frames you were trying to skip are being skipped though:

  File "/home/exarkun/Work/LeastAuthority/python/tahoe-lafs/src/allmydata/frontends/magic_folder.py", line 428, in _finish
    d1 = self.uploader.stop()
  File "/home/exarkun/Work/LeastAuthority/python/tahoe-lafs/src/allmydata/frontends/magic_folder.py", line 1192, in stop
    action = STOP_MONITORING(**self._log_fields)
  File "/home/exarkun/Work/LeastAuthority/python/eliot/eliot/_validation.py", line 450, in __call__
    logger, self.action_type, self._serializers, **fields)
  File "/home/exarkun/Work/LeastAuthority/python/eliot/eliot/_action.py", line 830, in start_action
    action._start(fields)
  File "/home/exarkun/Work/LeastAuthority/python/eliot/eliot/_action.py", line 359, in _start
    Message(fields, serializer).write(self._logger, self)
  File "/home/exarkun/Work/LeastAuthority/python/eliot/eliot/_message.py", line 147, in write
    logger.write(logged_dict, self._serializer)

It seems like a .py/.pyc mismatch. skip_filenames ends up like:

['.../eliot/eliot/_output.py', '.../eliot/eliot/_message.pyc', '.../eliot/eliot/_action.pyc']

which is weird enough but then the frame source files end up having disagreeing extensions, some with .py and some with .pyc, causing the trimming to abort prematurely.

[itamarst]

Mmm. Maybe I should do it prefix based, like I did in the sketch of #324.

[itamarst]

I imagine that might fail in certain packaging scenarios, though. On the other hand, failure isn't a big deal.

[itamarst]

So the trimming issue looks like it's Python 2 only: "In Python 3, when you import a module, its __file__ attribute points to its source py file" (https://www.python.org/dev/peps/pep-3147/#file). So I'm OK with merging this as is, and you'll just need to work a little harder on reading Python 2 tracebacks. Even for Python 2 this seems a lot better than master.