Why Eliot?

Suppose we turn from outside estimates of a man, to wonder, with keener interest, what is the report of his own consciousness about his doings or capacity: with what hindrances he is carrying on his daily labors; what fading of hopes, or what deeper fixity of self-delusion the years are marking off within him; and with what spirit he wrestles against universal pressure, which will one day be too heavy for him, and bring his heart to its final pause.

— George Eliot, Middlemarch

The log messages generated by a piece of software tell a story: what, where, when, even why and how if you’re lucky. The readers of this story are more often than not other programs: monitoring systems, performance tools, or just filtering the messages down to something a human can actually comprehend. Unfortunately the output of most logging systems is ill-suited to being read by programs. Even worse, most logging systems omit critical information that both humans and their programs need.

Problem #2: Referring to Entities

Every time a log message is written out you need to decide how to refer to the objects being logged. In the messages we saw above “Dorothea” and “Miss Brooke” are in fact different identifiers for the same person. Having structured messages doesn’t help us find all messages about a specific entity if the object is referred to inconsistently. What you need is infrastructure for converting specific kinds of objects in your code to fields in your structured log messages. Then you can just say “log a message that refers to this Person” and that reusable code will make sure the correct identifier is generated.

Problem #3: Actions

Most log messages in your program are going to involve actions:

Not long after that dinner-party she had become Mrs. Casaubon, and was on her way to Rome.

A marriage has a beginning and eventually an end. The end may be successful, presuming “until death do us part” is a form of success, or a failure. The same is true of all actions, much like function calls in Python are started and eventually return a result or throw an exception. Actions may of course span multiple function calls or extended periods of time.

Actions also generate other actions: a marriage leads to a trip to Rome, the trip to Rome might lead to a visit to the Vatican Museum, and so on. Other unrelated actions are occurring at the same time, resulting in a forest of actions, with root actions that grow a tree of child actions.

You might want to trace an action from beginning to end, e.g. to measure how long it took to run. You might want to know what high-level action caused a particular unexpected low-level action. You might want to know what actions a specific entity was involved with. None of these are possible in most logging systems since they have no concept of actions to begin with.

The Solution: Eliot

Eliot is designed to solve all of these problems. For simplicity’s sake this example focuses on problems 1 and 3; problem 2 is covered by the serialization layer discussed later in the documentation.

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, start_action, start_task

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 start_action(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 start_task(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.