assertHasAction fails with a failure opaque report

[exarkun]

Here's an example of a Trial report of a failing assertHasAction:

===============================================================================
[ERROR]
Traceback (most recent call last):
  File "eliot/testing.py", line 317, in wrapper
    return function(self, *args, **kwargs)
  File "eliot/testing.py", line 350, in wrapper
    return function(self, logger)
  File "tahoe-lafs/src/allmydata/test/test_eliotutil.py", line 298, in test_concurrent_generators
    u"2-d",
  File "tahoe-lafs/src/allmydata/test/test_eliotutil.py", line 82, in assert_expected_action_tree
    True,
  File "eliot/testing.py", line 427, in assertHasAction
    actions = LoggedAction.ofType(logger.messages, actionType)
  File "eliot/testing.py", line 173, in of_type
    messages))
  File "eliot/testing.py", line 142, in fromMessages
    uuid, message[TASK_LEVEL_FIELD], messages)
  File "eliot/testing.py", line 145, in fromMessages
    raise ValueError(uuid, level)
exceptions.ValueError: (u'58937e39-5896-43e9-86ba-893c71614037', [5, 1])

allmydata.test.test_eliotutil.EliotFriendlyGeneratorFunctionTests.test_concurrent_generators
-------------------------------------------------------------------------------

The stack is mostly unhelpful. It tells me where the failing assertion is, at least. The only other information I get is ValueError: (u'58937e39-5896-43e9-86ba-893c71614037', [5, 1]) which is pretty much meaningless until I read the implementation of fromMessages and see that this happens if the start or end message of an action isn't found and that two values included are the task uuid and level. The level might be helpful if I brush up on my understanding of Eliot's implementation. The task uuid isn't, since it's just some random uuid. And I don't get to see what messages were being searched so it's hard to put any of this in context.

It would be great to see more of what's going on. In some other tests I've written, I've made sure to include the complete list of messages under inspection (ie, captured by the logger). It's hard to say if this is generally appropriate since the list might be quite large. If Eliot can't figure out what's going on, though, I'm not sure what alternative there is but to give the human all of the information and let them figure it out.

A minimal improvement would be to at least report whether it was the start message or end message that wasn't found. If I actually manage to debug this failure then maybe the exact way it is failing will also suggest some other information the reporting of which would be useful (at least, useful to anyone who ends up having to debug exactly this same problem again ...)

It's pretty nice when this is what happens by default (of course I could edit my tests to report all of the messages) so that if I get a failure report from CI or another developer I have all the necessary information at hand.

[jonathanj]

An anecdote: I found myself writing ad hoc code to push logger.messages into an eliot-tree because it was more useful to see that as output in all my failure cases. So I wrote this this decorator to wrap capture_logging and add an eliot-tree as a text detail to my tests. Possibly only useful with testtools, I'm not sure if there is similar functionality in other test frameworks.

def capture_logging_with_detail(*a, **kw):
    """
    Wrapper around `eliot.testing.capture_logging` that adds a formatted Eliot
    tree as a `testtools.TestCase` detail.
    """
    def _capture_logging(f):
        @wraps(f)
        def _inner(self, logger, *ia, **ikw):
            try:
                return f(self, logger, *ia, **ikw)
            finally:
                if eliottree is not None:
                    self.addDetail(
                        'eliot-tree',
                        text_content(formatEliotTree(logger.messages)))
        return capture_logging(*a, **kw)(_inner)
    return _capture_logging

def formatEliotTree(messages):
    """
    Render messages as an Eliot tree to a unicode string.
    """
    if eliottree is None:
        raise RuntimeError('eliot-tree not installed')
    from io import StringIO
    io = StringIO(u'\n')
    render_tasks(io.write, tasks_from_iterable(messages), 0)
    return io.getvalue()

[itamarst]

@jonathanj I want to to something like that, yeah, see #369 (and I suspect there's another issue or two in the tracker about that).