Logging As Storytelling #2: Actions!

Logging should be like storytelling: you should be able to follow your heroes and the chain of actions they set in motion, cheering successes and jeering at failures. In this installment of my logging series I’ll be demonstrating a logging API designed to allow this, part of a new logging library called Eliot.

Let’s look at some code that uses simple structured logging. In a future installment I will talk about field serialization; for now I’m going to stick to simple values like strings.

    from __future__ import unicode_literals
    from eliot import Logger, Message

    logger = Logger()

    class Person(object):
        def __init__(self):
            self.seen = set()

        def look(self, thing):
            msg = Message.new(type="person:look",
                              person=unicode(self),
                              at=unicode(thing))
            msg.write(logger)
            self.seen.add(thing)


    class Place(object):
        def __init__(self, name):
            self.name = name
            self.contained = []

        def travel(self, person):
            msg = Message.new(type="place:travel",
                              person=unicode(person),
                              place=self.name)
            msg.write(logger)
            for thing in self.contained:
                if isinstance(thing, Place):
                    thing.travel(person)
                else:
                    person.look(thing)

        @classmethod
        def load(klass, name):
            # Load a Place from the database and return it...


    def honeymoon(family):
        msg = Message.new(type="honeymoon",
                          family=[unicode(person) for person in family])
        msg.write(logger)
        rome = Place.load("Rome, Italy")
        for person in family:
            rome.travel(person)
 

If we run the honeymoon function we get log messages that trace what happened (for clarity I’ve omitted some fields, e.g. timestamp):

     {type: "honeymoon", family: ["Mrs. Casaubon", "Mr. Casaubon"]}
     {type: "place:travel", person: "Mrs. Casaubon",
      place: "Rome, Italy"}
     {type: "place:travel", person: "Mrs. Casaubon",
      place: "Vatican Museum, Rome, Italy"}
     {type: "person:look", person: "Mrs. Casaubon", thing: "Statue #1"}
     {type: "person:look", person: "Mrs. Casaubon", thing: "Statue #2"}
     {type: "place:travel", person: "Mr. Casaubon",
      place: "Rome, Italy"}
     {type: "place:travel", person: "Mr. Casaubon",
      place: "Vatican Museum, Rome, Italy"}
     {type: "person:look", person: "Mr. Casaubon", thing: "Statue #1"}
     {type: "person:look", person: "Mr. Casaubon", thing: "Statue #2"}
 

We can see different messages are related insofar as they refer to the same person, or the same thing… but we can’t trace the relationship in terms of actions. Was looking at a statue the result of the honeymoon? There’s no way we can tell from the log messages. We could manually log start and finish messages but that won’t suffice when we have many interleaved actions involving the same objects. Which of twenty parallel HTTP request tried to insert a row into the database? Chronological messages simply cannot tell us that.

The solution is to introduce two new concepts: actions and tasks. An “action” is something with a start and an end; the end can be successful or it can fail due to an exception. Log messages, as well as log actions, know the log action whose context they are running in. The result is a tree of actions. A “task” is a top-level action, a basic entry point into the program which drives other actions. The task is therefore the root of the tree of actions. For example, an HTTP request received by a web server might be a task.

In our example we have one task (the honeymoon), an action (travel). We will leave looking as a normal log message because it always succeeds, and no other log message will ever need to run its context. Here’s how our code looks now:

    from __future__ import unicode_literals
    from eliot import Logger, Message, startAction, startTask

    logger = Logger()

    class Person(object):
        def __init__(self):
            self.seen = set()

        def look(self, thing):
            msg = Message.new(message_type="person:look",
                              person=unicode(self),
                              at=unicode(thing))
            msg.write(logger)
            self.seen.add(thing)


    class Place(object):
        # __init__ and load unchanged from above.

        def travel(self, person):
            with startAction(logger, "place:travel",
                             person=unicode(person),
                             place=self.name):
                for thing in self.contained:
                    if isinstance(thing, Place):
                        thing.travel(person)
                    else:
                        person.look(thing)


    def honeymoon(family):
        with startTask(logger, "honeymoon",
                       family=[unicode(person) for person in family]):
            rome = Place.load("Rome, Italy")
            for person in family:
                rome.travel(person)
 

Actions provide a Python context manager. When the action or task starts a start message is logged. If the block finishes successfully a success message is logged for the action; if an exception is thrown a failure message is logged for the action with the exception type and contents. Not shown here but supported by the API is the ability to add fields to the success or failure messages for an action. A similar API supports Twisted’s Deferreds.

Here’s how the log messages generated by the new code look; I’ve added some indentation to highlight the containment hierarchy which can be easily computed from the message contents.

     {task_uuid: "45352", task_level="/", action_status="started",
      action_type: "honeymoon", family: ["Mrs. Casaubon", "Mr. Casaubon"]}

         {task_uuid: "45352", task_level="/1/", action_status="started",
          action_type: "place:travel", person: "Mrs. Casaubon", place="Rome, Italy"}

             {task_uuid: "45352", task_level="/1/1/", action_status="started",
              action_type: "place:travel", person: "Mrs. Casaubon", place="Vatican Museum, Rome, Italy"}

                 {task_uuid: "45352", task_level="/1/1/",
                  message_type: "person:look", person: "Mrs. Casaubon", thing="Statue #1"}

                 {task_uuid: "45352", task_level="/1/1/",
                  message_type: "person:look", person: "Mrs. Casaubon", thing="Statue #2"}

             {task_uuid: "45352", task_level="/1/1/", action_status="succeeded",
              action_type: "place:travel"}

         {task_uuid: "45352", task_level="/1/", action_status="succeeded",
          action_type: "place:travel"}

         {task_uuid: "45352", task_level="/2/", action_status="started",
          action_type: "place:travel", person: "Mr. Casaubon", place="Rome, Italy"}

             {task_uuid: "45352", task_level="/2/1/", action_status="started",
              action_type: "place:travel", person: "Mr. Casaubon", place="Vatican Museum, Rome, Italy"}

                 {task_uuid: "45352", task_level="/2/1/",
                  message_type: "person:look", person: "Mr. Casaubon", thing="Statue #1"}

                 {task_uuid: "45352", task_level="/2/1/",
                  message_type: "person:look", person: "Mr. Casaubon", thing="Statue #2"}

             {task_uuid: "45352", task_level="/2/1/", action_status="succeeded",
              action_type: "place:travel"}

         {task_uuid: "45352", task_level="/2/", action_status="succeeded",
          action_type: "place:travel"}

     {task_uuid: "45352", task_level="/", action_status="succeeded",
      action_type: "honeymoon"}
 

No longer isolated fragments of meaning, our log messages are now a story. Log events have context, you can tell where they came from and what they led to without guesswork. Was looking at a statue the result of the honeymoon? It most definitely was.

We hope to open source Eliot at some point in the future. Meanwhile you’ll just have to make do with my next installment, where will I talk about types and serialization.


Follow us on Twitter for the next instalment of Logging as Storytelling!

HybridCluster uses Python and Twisted to build some of the most exciting distributed systems technology on the planet – our hosting platform adds a layer of resilience to unreliable dedicated or cloud infrastructure so that your apps can be deployed safe in the knowledge that they’re protected from software, hardware or even entire data center outages. Try it today!

Leave a Reply

Your email address will not be published. Required fields are marked *

— Back to top —