Repository: jonathanj/eliottree

Issue:
Support outputting timestamps in local timezone
UTC can sometimes be harder to interpret than local time, so would be nice if there was way to output in local timezone as well.

Original issue: https://github.com/itamarst/eliot/issues/428

Discussion:

Patch:
diff --git a/README.rst b/README.rst
index 8b656f0..4a581d4 100644
--- a/README.rst
+++ b/README.rst
@@ -97,6 +97,7 @@ Usage from the command-line
                            standard keys.
      --raw                 Do not format some task values (such as UTC
                            timestamps) as human-readable
+     --local-timezone      Convert timestamps to the local timezone.
      --color {always,auto,never}
                            Color the output. Defaults based on whether the output
                            is a TTY.
diff --git a/src/eliottree/_cli.py b/src/eliottree/_cli.py
index 1c62b58..2f17c8e 100644
--- a/src/eliottree/_cli.py
+++ b/src/eliottree/_cli.py
@@ -92,7 +92,7 @@ def setup_platform(colorize):
             colorama.init()
 
 
-def display_tasks(tasks, color, ignored_fields, field_limit, human_readable):
+def display_tasks(tasks, color, ignored_fields, field_limit, human_readable, utc_timestamps):
     """
     Render Eliot tasks, apply any command-line-specified behaviour and render
     the task trees to stdout.
@@ -113,7 +113,8 @@ def display_tasks(tasks, color, ignored_fields, field_limit, human_readable):
         ignored_fields=set(ignored_fields) or None,
         field_limit=field_limit,
         human_readable=human_readable,
-        colorize=colorize)
+        colorize=colorize,
+        utc_timestamps=utc_timestamps)
 
 
 def _decode_command_line(value, encoding='utf-8'):
@@ -137,7 +138,7 @@ def main():
                         dest='task_uuid',
                         metavar='UUID',
                         type=_decode_command_line,
-                        help='''Select a specific task by UUID''')
+                        help='''Select a specific task by UUID.''')
     parser.add_argument('-i', '--ignore-task-key',
                         action='append',
                         default=[],
@@ -151,7 +152,11 @@ def main():
                         action='store_false',
                         dest='human_readable',
                         help='''Do not format some task values (such as
-                        UTC timestamps) as human-readable''')
+                        UTC timestamps) as human-readable.''')
+    parser.add_argument('--local-timezone',
+                        action='store_false',
+                        dest='utc_timestamps',
+                        help='''Convert timestamps to the local timezone.''')
     parser.add_argument('--color',
                         default='auto',
                         choices=['always', 'auto', 'never'],
@@ -199,7 +204,8 @@ def main():
             color=args.color,
             ignored_fields=args.ignored_fields,
             field_limit=args.field_limit,
-            human_readable=args.human_readable)
+            human_readable=args.human_readable,
+            utc_timestamps=args.utc_timestamps)
     except JSONParseError as e:
         stderr.write(u'JSON parse error, file {}, line {}:\n{}\n\n'.format(
             e.file_name,
diff --git a/src/eliottree/_render.py b/src/eliottree/_render.py
index 96554f2..d346a56 100644
--- a/src/eliottree/_render.py
+++ b/src/eliottree/_render.py
@@ -51,7 +51,12 @@ def _no_color(text, *a, **kw):
     return text
 
 
-def _default_value_formatter(human_readable, field_limit, encoding='utf-8'):
+def _default_value_formatter(
+        human_readable,
+        field_limit,
+        utc_timestamps=True,
+        encoding='utf-8',
+):
     """
     Create a value formatter based on several user-specified options.
     """
@@ -59,7 +64,8 @@ def _default_value_formatter(human_readable, field_limit, encoding='utf-8'):
     if human_readable:
         fields = {
             eliot_ns(u'timestamp'): format.timestamp(
-                include_microsecond=False),
+                include_microsecond=False,
+                utc_timestamps=utc_timestamps),
             eliot_ns(u'duration'): format.duration(),
         }
     return compose(
@@ -220,7 +226,7 @@ def track_exceptions(f, caught, default=None):
 
 def render_tasks(write, tasks, field_limit=0, ignored_fields=None,
                  human_readable=False, colorize=False, write_err=None,
-                 format_node=format_node, format_value=None):
+                 format_node=format_node, format_value=None, utc_timestamps=True):
     """
     Render Eliot tasks as an ASCII tree.
 
@@ -241,6 +247,7 @@ def render_tasks(write, tasks, field_limit=0, ignored_fields=None,
     :param format_node: See `format_node`.
     :type format_value: Callable[[Any], `text_type`]
     :param format_value: Callable to format a value.
+    :param bool utc_timestamps: Format timestamps as UTC?
     """
     if ignored_fields is None:
         ignored_fields = DEFAULT_IGNORED_KEYS
@@ -249,7 +256,8 @@ def render_tasks(write, tasks, field_limit=0, ignored_fields=None,
     if format_value is None:
         format_value = _default_value_formatter(
             human_readable=human_readable,
-            field_limit=field_limit)
+            field_limit=field_limit,
+            utc_timestamps=utc_timestamps)
     _format_value = track_exceptions(
         format_value,
         caught_exceptions,
diff --git a/src/eliottree/format.py b/src/eliottree/format.py
index ea32b43..0e7b25f 100644
--- a/src/eliottree/format.py
+++ b/src/eliottree/format.py
@@ -66,18 +66,21 @@ def fields(format_mapping):
     return _format_field_value
 
 
-def timestamp(include_microsecond=True):
+def timestamp(include_microsecond=True, utc_timestamps=True):
     """
     Create a formatter for POSIX timestamp values.
     """
     def _format_timestamp_value(value, field_name=None):
-        result = datetime.utcfromtimestamp(float(value))
+        from_timestamp = (
+            datetime.utcfromtimestamp
+            if utc_timestamps else datetime.fromtimestamp)
+        result = from_timestamp(float(value))
         if not include_microsecond:
             result = result.replace(microsecond=0)
         result = result.isoformat(' ')
         if isinstance(result, binary_type):
             result = result.decode('ascii')
-        return result
+        return result + (u'Z' if utc_timestamps else u'')
     return _format_timestamp_value
 
 


Test patch:
diff --git a/src/eliottree/test/test_cli.py b/src/eliottree/test/test_cli.py
index df25dbe..f0b5a6a 100644
--- a/src/eliottree/test/test_cli.py
+++ b/src/eliottree/test/test_cli.py
@@ -14,7 +14,7 @@ from eliottree.test.tasks import message_task, missing_uuid_task
 
 rendered_message_task = (
     u'cdeb220d-7605-4d5f-8341-1a170222e308\n'
-    u'\u2514\u2500\u2500 twisted:log/1 2015-03-03 04:25:00\n'
+    u'\u2514\u2500\u2500 twisted:log/1 2015-03-03 04:25:00Z\n'
     u'    \u251c\u2500\u2500 error: False\n'
     u'    \u2514\u2500\u2500 message: Main loop terminated.\n\n'
 ).replace('\n', os.linesep).encode('utf-8')
diff --git a/src/eliottree/test/test_format.py b/src/eliottree/test/test_format.py
index 83432ae..3190368 100644
--- a/src/eliottree/test/test_format.py
+++ b/src/eliottree/test/test_format.py
@@ -1,3 +1,4 @@
+import time
 from testtools import TestCase
 from testtools.matchers import Is
 
@@ -89,7 +90,7 @@ class TimestampTests(TestCase):
         """
         self.assertThat(
             format.timestamp()(u'1433631432'),
-            ExactlyEquals(u'2015-06-06 22:57:12'))
+            ExactlyEquals(u'2015-06-06 22:57:12Z'))
 
     def test_float(self):
         """
@@ -97,7 +98,17 @@ class TimestampTests(TestCase):
         """
         self.assertThat(
             format.timestamp()(1433631432.0),
-            ExactlyEquals(u'2015-06-06 22:57:12'))
+            ExactlyEquals(u'2015-06-06 22:57:12Z'))
+
+    def test_local(self):
+        """
+        Timestamps can be converted to local time.
+        """
+        timestamp = 1433631432.0
+        utc = format.timestamp(utc_timestamps=True)(timestamp)
+        local = format.timestamp(utc_timestamps=False)(timestamp + time.timezone)
+        # Strip the "Z" off the end.
+        self.assertThat(utc[:-1], ExactlyEquals(local))
 
 
 class AnythingTests(TestCase):
diff --git a/src/eliottree/test/test_render.py b/src/eliottree/test/test_render.py
new file mode 100644
index 0000000..8547ed9
--- /dev/null
+++ b/src/eliottree/test/test_render.py
@@ -0,0 +1,726 @@
+import time
+from eliot.parse import WrittenMessage
+from six import StringIO, text_type
+from termcolor import colored
+from testtools import ExpectedException, TestCase
+from testtools.matchers import AfterPreprocessing as After
+from testtools.matchers import (
+    Contains, Equals, HasLength, MatchesAll, MatchesListwise, StartsWith)
+
+from eliottree import (
+    render_tasks, tasks_from_iterable)
+from eliottree._render import (
+    COLORS, HOURGLASS, RIGHT_DOUBLE_ARROW, _default_value_formatter, _no_color,
+    format_node, get_children, message_fields, message_name)
+from eliottree._util import eliot_ns
+from eliottree.test.matchers import ExactlyEquals
+from eliottree.test.tasks import (
+    action_task, action_task_end, action_task_end_failed, dict_action_task,
+    janky_action_task, janky_message_task, list_action_task, message_task,
+    multiline_action_task, nested_action_task)
+
+
+class DefaultValueFormatterTests(TestCase):
+    """
+    Tests for ``eliottree.render._default_value_formatter``.
+    """
+    def test_unicode(self):
+        """
+        Pass ``unicode`` values straight through.
+        """
+        format_value = _default_value_formatter(
+            human_readable=False, field_limit=0)
+        self.assertThat(
+            format_value(u'\N{SNOWMAN}'),
+            ExactlyEquals(u'\N{SNOWMAN}'))
+
+    def test_unicode_control_characters(self):
+        """
+        Translate control characters to their Unicode "control picture"
+        equivalent, instead of destroying a terminal.
+        """
+        format_value = _default_value_formatter(
+            human_readable=False, field_limit=0)
+        self.assertThat(
+            format_value(u'hello\001world'),
+            ExactlyEquals(u'hello\u2401world'))
+
+    def test_bytes(self):
+        """
+        Decode ``bytes`` values as the specified encoding.
+        """
+        format_value = _default_value_formatter(
+            human_readable=False, field_limit=0, encoding='utf-8')
+        self.assertThat(
+            format_value(b'foo'),
+            ExactlyEquals(u'foo'))
+        self.assertThat(
+            format_value(b'\xe2\x98\x83'),
+            ExactlyEquals(u'\N{SNOWMAN}'))
+
+    def test_anything(self):
+        """
+        Pass unknown values to ``repr``.
+        """
+        class _Thing(object):
+            def __repr__(self):
+                return 'Hello'
+        format_value = _default_value_formatter(
+            human_readable=False, field_limit=0)
+        self.assertThat(
+            format_value(_Thing()),
+            ExactlyEquals(u'Hello'))
+
+    def test_timestamp_field(self):
+        """
+        Format Eliot ``timestamp`` fields as human-readable if the feature was
+        requested.
+        """
+        format_value = _default_value_formatter(
+            human_readable=True, field_limit=0)
+        # datetime(2015, 6, 6, 22, 57, 12)
+        now = 1433631432
+        self.assertThat(
+            format_value(now, eliot_ns(u'timestamp')),
+            ExactlyEquals(u'2015-06-06 22:57:12Z'))
+        self.assertThat(
+            format_value(str(now), eliot_ns(u'timestamp')),
+            ExactlyEquals(u'2015-06-06 22:57:12Z'))
+
+    def test_timestamp_field_local(self):
+        """
+        Format Eliot ``timestamp`` fields as human-readable local time if the
+        feature was requested.
+        """
+        format_value = _default_value_formatter(
+            human_readable=True, field_limit=0, utc_timestamps=False)
+        # datetime(2015, 6, 6, 22, 57, 12)
+        now = 1433631432 + time.timezone
+        self.assertThat(
+            format_value(now, eliot_ns(u'timestamp')),
+            ExactlyEquals(u'2015-06-06 22:57:12'))
+        self.assertThat(
+            format_value(str(now), eliot_ns(u'timestamp')),
+            ExactlyEquals(u'2015-06-06 22:57:12'))
+
+    def test_not_eliot_timestamp_field(self):
+        """
+        Do not format user fields named ``timestamp``.
+        """
+        format_value = _default_value_formatter(
+            human_readable=True, field_limit=0)
+        now = 1433631432
+        self.assertThat(
+            format_value(now, u'timestamp'),
+            ExactlyEquals(text_type(now)))
+        self.assertThat(
+            format_value(text_type(now), u'timestamp'),
+            ExactlyEquals(text_type(now)))
+
+    def test_timestamp_field_not_human(self):
+        """
+        Do not format ``timestamp`` fields as human-readable if the feature was
+        not requested.
+        """
+        format_value = _default_value_formatter(
+            human_readable=False, field_limit=0)
+        # datetime(2015, 6, 6, 22, 57, 12)
+        now = 1433631432
+        self.assertThat(
+            format_value(now, u'timestamp'),
+            ExactlyEquals(text_type(now)))
+
+
+colors = COLORS(colored)
+no_colors = COLORS(_no_color)
+
+
+def no_formatting(value, field_name=None):
+    return text_type(value)
+
+
+class MessageNameTests(TestCase):
+    """
+    Tests for `eliottree.render.message_name`.
+    """
+    def test_action_type(self):
+        """
+        Action types include their type name.
+        """
+        message = next(tasks_from_iterable([action_task])).root().start_message
+        self.assertThat(
+            message_name(colors, no_formatting, message),
+            StartsWith(colors.parent(message.contents.action_type)))
+
+    def test_action_task_level(self):
+        """
+        Action types include their task level.
+        """
+        message = next(tasks_from_iterable([action_task])).root().start_message
+        self.assertThat(
+            message_name(colors, no_formatting, message),
+            Contains(message.task_level.to_string()))
+
+    def test_action_status(self):
+        """
+        Action types include their status.
+        """
+        message = next(tasks_from_iterable([action_task])).root().start_message
+        self.assertThat(
+            message_name(colors, no_formatting, message),
+            Contains(u'started'))
+
+    def test_action_status_success(self):
+        """
+        Successful actions color their status.
+        """
+        message = next(tasks_from_iterable([
+            action_task, action_task_end,
+        ])).root().end_message
+        self.assertThat(
+            message_name(colors, no_formatting, message),
+            Contains(colors.success(u'succeeded')))
+
+    def test_action_status_failed(self):
+        """
+        Failed actions color their status.
+        """
+        message = next(tasks_from_iterable([
+            action_task, action_task_end_failed,
+        ])).root().end_message
+        self.assertThat(
+            message_name(colors, no_formatting, message),
+            Contains(colors.failure(u'failed')))
+
+    def test_message_type(self):
+        """
+        Message types include their type name.
+        """
+        message = WrittenMessage.from_dict(message_task)
+        self.assertThat(
+            message_name(colors, no_formatting, message),
+            StartsWith(colors.parent(message.contents.message_type)))
+
+    def test_message_task_level(self):
+        """
+        Message types include their task level.
+        """
+        message = WrittenMessage.from_dict(message_task)
+        self.assertThat(
+            message_name(colors, no_formatting, message),
+            Contains(message.task_level.to_string()))
+
+    def test_unknown(self):
+        """
+        None or messages with no identifiable information are rendered as
+        ``<unnamed>``.
+        """
+        self.assertThat(
+            message_name(colors, no_formatting, None),
+            ExactlyEquals(u'<unnamed>'))
+        message = WrittenMessage.from_dict({u'timestamp': 0})
+        self.assertThat(
+            message_name(colors, no_formatting, message),
+            ExactlyEquals(u'<unnamed>'))
+
+
+class FormatNodeTests(TestCase):
+    """
+    Tests for `eliottree.render.format_node`.
+    """
+    def format_node(self, node, format_value=None, colors=no_colors):
+        if format_value is None:
+            def format_value(value, field_name=None):
+                return value
+        return format_node(format_value, colors, node)
+
+    def test_task(self):
+        """
+        `Task`'s UUID is rendered.
+        """
+        node = next(tasks_from_iterable([action_task]))
+        self.assertThat(
+            self.format_node(node),
+            ExactlyEquals(node.root().task_uuid))
+
+    def test_written_action(self):
+        """
+        `WrittenAction`'s start message is rendered.
+        """
+        tasks = tasks_from_iterable([action_task, action_task_end])
+        node = next(tasks).root()
+        self.assertThat(
+            self.format_node(node),
+            ExactlyEquals(u'{}{} {} {} {} \u29d6 {}'.format(
+                node.start_message.contents.action_type,
+                node.start_message.task_level.to_string(),
+                RIGHT_DOUBLE_ARROW,
+                node.start_message.contents.action_status,
+                node.start_message.timestamp,
+                node.end_message.timestamp - node.start_message.timestamp)))
+
+    def test_tuple_list(self):
+        """
+        Tuples can be a key and list, in which case the value is not rendered
+        here.
+        """
+        node = (u'a\nb\x1bc', [u'x\n', u'y\x1b', u'z'])
+        self.assertThat(
+            self.format_node(node, colors=colors),
+            ExactlyEquals(u'{}: '.format(
+                colors.prop(u'a\u240ab\u241bc'))))
+
+    def test_tuple_dict(self):
+        """
+        Tuples can be a key and dict, in which case the value is not rendered
+        here.
+        """
+        node = (u'a\nb\x1bc', {u'x\n': u'y\x1b', u'z': u'zz'})
+        self.assertThat(
+            self.format_node(node, colors=colors),
+            ExactlyEquals(u'{}: '.format(
+                colors.prop(u'a\u240ab\u241bc'))))
+
+    def test_tuple_other(self):
+        """
+        Tuples can be a key and string, number, etc. rendered inline.
+        """
+        node = (u'a\nb\x1bc', u'hello')
+        self.assertThat(
+            self.format_node(node, colors=colors),
+            ExactlyEquals(u'{}: {}'.format(
+                colors.prop(u'a\u240ab\u241bc'),
+                u'hello')))
+
+        node = (u'a\nb\x1bc', 42)
+        self.assertThat(
+            self.format_node(node, colors=colors),
+            ExactlyEquals(u'{}: {}'.format(
+                colors.prop(u'a\u240ab\u241bc'),
+                42)))
+
+    def test_other(self):
+        """
+        Other types raise `NotImplementedError`.
+        """
+        node = object()
+        with ExpectedException(NotImplementedError):
+            self.format_node(node, colors=colors)
+
+
+class MessageFieldsTests(TestCase):
+    """
+    Tests for `eliottree.render.message_fields`.
+    """
+    def test_empty(self):
+        """
+        ``None`` or empty messages result in no fields.
+        """
+        self.assertThat(
+            message_fields(None, set()),
+            Equals([]))
+        message = WrittenMessage.from_dict({})
+        self.assertThat(
+            message_fields(message, set()),
+            Equals([]))
+
+    def test_fields(self):
+        """
+        Include all the message fields but not the timestamp.
+        """
+        message = WrittenMessage.from_dict({u'a': 1})
+        self.assertThat(
+            message_fields(message, set()),
+            Equals([(u'a', 1)]))
+        message = WrittenMessage.from_dict({u'a': 1, u'timestamp': 12345678})
+        self.assertThat(
+            message_fields(message, set()),
+            Equals([
+                (u'a', 1)]))
+
+    def test_ignored_fields(self):
+        """
+        Ignore any specified fields.
+        """
+        message = WrittenMessage.from_dict({u'a': 1, u'b': 2})
+        self.assertThat(
+            message_fields(message, {u'b'}),
+            Equals([(u'a', 1)]))
+
+
+class GetChildrenTests(TestCase):
+    """
+    Tests for `eliottree.render.get_children`.
+    """
+    def test_task_action(self):
+        """
+        The root message is the only child of a `Task`.
+        """
+        node = next(tasks_from_iterable([action_task]))
+        self.assertThat(
+            get_children(set(), node),
+            Equals([node.root()]))
+        node = next(tasks_from_iterable([message_task]))
+        self.assertThat(
+            get_children(set(), node),
+            Equals([node.root()]))
+
+    def test_written_action_ignored_fields(self):
+        """
+        Action fields can be ignored.
+        """
+        task = dict(action_task)
+        task.update({u'c': u'3'})
+        node = next(tasks_from_iterable([task])).root()
+        start_message = node.start_message
+        self.assertThat(
+            list(get_children({u'c'}, node)),
+            Equals([
+                (u'action_status', start_message.contents.action_status),
+                (u'action_type', start_message.contents.action_type)]))
+
+    def test_written_action_start(self):
+        """
+        The children of a `WrittenAction` begin with the fields of the start
+        message.
+        """
+        node = next(tasks_from_iterable([
+            action_task, nested_action_task, action_task_end])).root()
+        start_message = node.start_message
+        self.assertThat(
+            list(get_children({u'foo'}, node))[:2],
+            Equals([
+                (u'action_status', start_message.contents.action_status),
+                (u'action_type', start_message.contents.action_type)]))
+
+    def test_written_action_children(self):
+        """
+        The children of a `WrittenAction` contain child actions/messages.
+        """
+        node = next(tasks_from_iterable([
+            action_task, nested_action_task, action_task_end])).root()
+        self.assertThat(
+            list(get_children({u'foo'}, node))[2],
+            Equals(node.children[0]))
+
+    def test_written_action_no_children(self):
+        """
+        The children of a `WrittenAction` does not contain any child
+        actions/messages if there aren't any.
+        """
+        node = next(tasks_from_iterable([action_task])).root()
+        self.assertThat(
+            list(get_children({u'foo'}, node)),
+            HasLength(2))
+
+    def test_written_action_no_end(self):
+        """
+        If the `WrittenAction` has no end message, it is excluded.
+        """
+        node = next(tasks_from_iterable([
+            action_task, nested_action_task])).root()
+        self.assertThat(
+            list(get_children({u'foo'}, node))[4:],
+            Equals([]))
+
+    def test_written_action_end(self):
+        """
+        The last child of a `WrittenAction` is the end message.
+        """
+        node = next(tasks_from_iterable([
+            action_task, nested_action_task, action_task_end])).root()
+        self.assertThat(
+            list(get_children({u'foo'}, node))[3:],
+            Equals([node.end_message]))
+
+    def test_written_message(self):
+        """
+        The fields of `WrittenMessage`\\s are their children. Fields can also be
+        ignored.
+        """
+        node = WrittenMessage.from_dict({u'a': 1, u'b': 2, u'c': 3})
+        self.assertThat(
+            get_children({u'c'}, node),
+            Equals([
+                (u'a', 1),
+                (u'b', 2)]))
+
+    def test_tuple_dict(self):
+        """
+        The key/value pairs of dicts are their children.
+        """
+        node = (u'key', {u'a': 1, u'b': 2, u'c': 3})
+        self.assertThat(
+            # The ignores intentionally do nothing.
+            get_children({u'c'}, node),
+            Equals([
+                (u'a', 1),
+                (u'b', 2),
+                (u'c', 3)]))
+
+    def test_tuple_list(self):
+        """
+        The indexed items of lists are their children.
+        """
+        node = (u'key', [u'a', u'b', u'c'])
+        self.assertThat(
+            # The ignores intentionally do nothing.
+            get_children({2, u'c'}, node),
+            After(list,
+                  Equals([
+                      (0, u'a'),
+                      (1, u'b'),
+                      (2, u'c')])))
+
+    def test_other(self):
+        """
+        Other values are considered to have no children.
+        """
+        self.assertThat(get_children({}, None), Equals([]))
+        self.assertThat(get_children({}, 42), Equals([]))
+        self.assertThat(get_children({}, u'hello'), Equals([]))
+
+
+class RenderTasksTests(TestCase):
+    """
+    Tests for `eliottree.render.render_tasks`.
+    """
+    def render_tasks(self, iterable, **kw):
+        fd = StringIO()
+        err = StringIO(u'')
+        tasks = tasks_from_iterable(iterable)
+        render_tasks(write=fd.write, write_err=err.write, tasks=tasks, **kw)
+        if err.tell():
+            return fd.getvalue(), err.getvalue()
+        return fd.getvalue()
+
+    def test_format_node_failures(self):
+        """
+        Catch exceptions when formatting nodes and display a message without
+        interrupting the processing of tasks. List all caught exceptions to
+        stderr.
+        """
+        def bad_format_node(*a, **kw):
+            raise ValueError('Nope')
+        self.assertThat(
+            self.render_tasks([message_task],
+                              format_node=bad_format_node),
+            MatchesListwise([
+                Contains(u'<node formatting exception>'),
+                MatchesAll(
+                    Contains(u'Traceback (most recent call last):'),
+                    Contains(u'ValueError: Nope'))]))
+
+    def test_format_value_failures(self):
+        """
+        Catch exceptions when formatting node values and display a message
+        without interrupting the processing of tasks. List all caught
+        exceptions to stderr.
+        """
+        def bad_format_value(*a, **kw):
+            raise ValueError('Nope')
+        self.assertThat(
+            self.render_tasks([message_task],
+                              format_value=bad_format_value),
+            MatchesListwise([
+                Contains(u'message: <value formatting exception>'),
+                MatchesAll(
+                    Contains(u'Traceback (most recent call last):'),
+                    Contains(u'ValueError: Nope'))]))
+
+    def test_tasks(self):
+        """
+        Render two tasks of sequential levels, by default most standard Eliot
+        task keys are ignored.
+        """
+        self.assertThat(
+            self.render_tasks([action_task, action_task_end]),
+            ExactlyEquals(
+                u'f3a32bb3-ea6b-457c-aa99-08a3d0491ab4\n'
+                u'\u2514\u2500\u2500 app:action/1 \u21d2 started '
+                u'1425356800 \u29d6 2\n'
+                u'    \u2514\u2500\u2500 app:action/2 \u21d2 succeeded '
+                u'1425356802\n\n'))
+
+    def test_tasks_human_readable(self):
+        """
+        Render two tasks of sequential levels, by default most standard Eliot
+        task keys are ignored, values are formatted to be human readable.
+        """
+        self.assertThat(
+            self.render_tasks([action_task, action_task_end],
+                              human_readable=True),
+            ExactlyEquals(
+                u'f3a32bb3-ea6b-457c-aa99-08a3d0491ab4\n'
+                u'\u2514\u2500\u2500 app:action/1 \u21d2 started '
+                u'2015-03-03 04:26:40Z \u29d6 2.000s\n'
+                u'    \u2514\u2500\u2500 app:action/2 \u21d2 succeeded '
+                u'2015-03-03 04:26:42Z\n'
+                u'\n'))
+
+    def test_multiline_field(self):
+        """
+        When no field limit is specified for task values, multiple lines are
+        output for multiline tasks.
+        """
+        fd = StringIO()
+        tasks = tasks_from_iterable([multiline_action_task])
+        render_tasks(
+            write=fd.write,
+            tasks=tasks)
+        self.assertThat(
+            fd.getvalue(),
+            ExactlyEquals(
+                u'f3a32bb3-ea6b-457c-aa99-08a3d0491ab4\n'
+                u'\u2514\u2500\u2500 app:action/1 \u21d2 started '
+                u'1425356800\n'
+                u'    \u2514\u2500\u2500 message: this is a\u23ce\n'
+                u'        many line message\n\n'))
+
+    def test_multiline_field_limit(self):
+        """
+        When a field limit is specified for task values, only the first of
+        multiple lines is output.
+        """
+        self.assertThat(
+            self.render_tasks([multiline_action_task],
+                              field_limit=1000),
+            ExactlyEquals(
+                u'f3a32bb3-ea6b-457c-aa99-08a3d0491ab4\n'
+                u'\u2514\u2500\u2500 app:action/1 \u21d2 started '
+                u'1425356800\n'
+                u'    \u2514\u2500\u2500 message: this is a\u2026\n\n'))
+
+    def test_field_limit(self):
+        """
+        Truncate task values that are longer than the field_limit if specified.
+        """
+        self.assertThat(
+            self.render_tasks([message_task],
+                              field_limit=5),
+            ExactlyEquals(
+                u'cdeb220d-7605-4d5f-8341-1a170222e308\n'
+                u'\u2514\u2500\u2500 twisted:log/1 '
+                u'14253\u2026\n'
+                u'    \u251c\u2500\u2500 error: False\n'
+                u'    \u2514\u2500\u2500 message: Main \u2026\n\n'))
+
+    def test_ignored_keys(self):
+        """
+        Task keys can be ignored.
+        """
+        self.assertThat(
+            self.render_tasks([action_task],
+                              ignored_fields={u'action_type'}),
+            ExactlyEquals(
+                u'f3a32bb3-ea6b-457c-aa99-08a3d0491ab4\n'
+                u'\u2514\u2500\u2500 app:action/1 \u21d2 started '
+                u'1425356800\n'
+                u'    \u2514\u2500\u2500 action_status: started\n\n'))
+
+    def test_task_data(self):
+        """
+        Task data is rendered as tree elements.
+        """
+        self.assertThat(
+            self.render_tasks([message_task]),
+            ExactlyEquals(
+                u'cdeb220d-7605-4d5f-8341-1a170222e308\n'
+                u'\u2514\u2500\u2500 twisted:log/1 '
+                u'1425356700\n'
+                u'    \u251c\u2500\u2500 error: False\n'
+                u'    \u2514\u2500\u2500 message: Main loop terminated.\n\n'))
+
+    def test_dict_data(self):
+        """
+        Task values that are ``dict``s are rendered as tree elements.
+        """
+        self.assertThat(
+            self.render_tasks([dict_action_task]),
+            ExactlyEquals(
+                u'f3a32bb3-ea6b-457c-aa99-08a3d0491ab4\n'
+                u'\u2514\u2500\u2500 app:action/1 \u21d2 started '
+                u'1425356800\n'
+                u'    \u2514\u2500\u2500 some_data: \n'
+                u'        \u2514\u2500\u2500 a: 42\n\n'))
+
+    def test_list_data(self):
+        """
+        Task values that are ``list``s are rendered as tree elements.
+        """
+        self.assertThat(
+            self.render_tasks([list_action_task]),
+            ExactlyEquals(
+                u'f3a32bb3-ea6b-457c-aa99-08a3d0491ab4\n'
+                u'\u2514\u2500\u2500 app:action/1 \u21d2 started '
+                u'1425356800\n'
+                u'    \u2514\u2500\u2500 some_data: \n'
+                u'        \u251c\u2500\u2500 0: a\n'
+                u'        \u2514\u2500\u2500 1: b\n\n'))
+
+    def test_nested(self):
+        """
+        Render nested tasks in a way that visually represents that nesting.
+        """
+        self.assertThat(
+            self.render_tasks([action_task, nested_action_task]),
+            ExactlyEquals(
+                u'f3a32bb3-ea6b-457c-aa99-08a3d0491ab4\n'
+                u'\u2514\u2500\u2500 app:action/1 \u21d2 started '
+                u'1425356800\n'
+                u'    \u2514\u2500\u2500 app:action:nest/1/1 \u21d2 started '
+                u'1425356900\n\n'))
+
+    def test_janky_message(self):
+        """
+        Task names, UUIDs, keys and values in messages all have control
+        characters escaped.
+        """
+        self.assertThat(
+            self.render_tasks([janky_message_task]),
+            ExactlyEquals(
+                u'cdeb220d-7605-4d5f-\u241b(08341-1a170222e308\n'
+                u'\u2514\u2500\u2500 M\u241b(0/1 '
+                u'1425356700\n'
+                u'    \u251c\u2500\u2500 er\u241bror: False\n'
+                u'    \u2514\u2500\u2500 mes\u240asage: '
+                u'Main loop\u241b(0terminated.\n\n'))
+
+    def test_janky_action(self):
+        """
+        Task names, UUIDs, keys and values in actions all have control
+        characters escaped.
+        """
+        self.assertThat(
+            self.render_tasks([janky_action_task]),
+            ExactlyEquals(
+                u'f3a32bb3-ea6b-457c-\u241b(0aa99-08a3d0491ab4\n'
+                u'\u2514\u2500\u2500 A\u241b(0/1 \u21d2 started '
+                u'1425356800\u241b(0\n'
+                u'    \u251c\u2500\u2500 \u241b(0: \n'
+                u'    \u2502   \u2514\u2500\u2500 \u241b(0: nope\n'
+                u'    \u2514\u2500\u2500 mes\u240asage: hello\u241b(0world\n\n'
+            ))
+
+    def test_colorize(self):
+        """
+        Passing ``colorize=True`` will colorize the output.
+        """
+        self.assertThat(
+            self.render_tasks([action_task, action_task_end],
+                              colorize=True),
+            ExactlyEquals(
+                u'\n'.join([
+                    colors.root(u'f3a32bb3-ea6b-457c-aa99-08a3d0491ab4'),
+                    u'\u2514\u2500\u2500 {}/1 \u21d2 {} {} {} {}'.format(
+                        colors.parent(u'app:action'),
+                        colors.success(u'started'),
+                        colors.timestamp(u'1425356800'),
+                        HOURGLASS,
+                        colors.duration(u'2')),
+                    u'    \u2514\u2500\u2500 {}/2 \u21d2 {} {}'.format(
+                        colors.parent(u'app:action'),
+                        colors.success(u'succeeded'),
+                        colors.timestamp(u'1425356802')),
+                    u'\n',
+                ])))