Now that you've got some code emitting log messages (or even better, before you've written the code) you can write unit tests to verify it. Given good test coverage all code branches should already be covered by tests unrelated to logging. Logging can be considered just another aspect of testing those code branches. Rather than recreating all those tests as separate functions Eliot provides a decorator the allows adding logging assertions to existing tests.
Decorating a test function with eliot.testing.capture_logging
validation will ensure that:
- You haven't logged anything that isn't JSON serializable.
- There are no unexpected tracebacks, indicating a bug somewhere in your code.
from eliot.testing import capture_logging
class MyTest(unittest.TestCase):
@capture_logging(None)
def test_mytest(self, logger):
call_my_function()
You can also ensure the correct messages were logged.
from eliot import Message
class UserRegistration(object):
def __init__(self):
self.db = {}
def register(self, username, password, age):
self.db[username] = (password, age)
Message.log(message_type="user_registration",
username=username, password=password,
age=age)
Here's how we'd test it:
from unittest import TestCase
from eliot import MemoryLogger
from eliot.testing import assertContainsFields, capture_logging
from myapp.registration import UserRegistration
class LoggingTests(TestCase):
def assertRegistrationLogging(self, logger):
"""
Logging assertions for test_registration.
"""
self.assertEqual(len(logger.messages), 1)
msg = logger.messages[0]
assertContainsFields(self, msg,
{u"username": u"john",
u"password": u"password",
u"age": 12}))
@capture_logging(assertRegistrationLogging)
def test_registration(self, logger):
"""
Registration adds entries to the in-memory database.
"""
registry = UserRegistration()
registry.register(u"john", u"password", 12)
self.assertEqual(registry.db[u"john"], (u"passsword", 12))
Tests decorated with @capture_logging
will fail if there are any tracebacks logged (using write_traceback
or writeFailure
) on the theory that these are unexpected errors indicating a bug.
If you expected a particular traceback to be logged you can call MemoryLogger.flush_tracebacks
, after which it will no longer cause a test failure.
The result will be a list of traceback message dictionaries for the particular exception.
from unittest import TestCase
from eliot.testing import capture_logging
class MyTests(TestCase):
def assertMythingBadPathLogging(self, logger):
messages = logger.flush_tracebacks(OSError)
self.assertEqual(len(messages), 1)
@capture_logging(assertMythingBadPathLogging)
def test_mythingBadPath(self, logger):
mything = MyThing()
# Trigger an error that will cause a OSError traceback to be logged:
self.assertFalse(mything.load("/nonexistent/path"))
Eliot provides utilities for making assertions about the structure of individual messages and actions.
The simplest method is using the assertHasMessage
utility function which asserts that a message of a given message type has the given fields:
from eliot.testing import assertHasMessage, capture_logging
class LoggingTests(TestCase):
@capture_logging(assertHasMessage, "user_registration",
{u"username": u"john",
u"password": u"password",
u"age": 12})
def test_registration(self, logger):
"""
Registration adds entries to the in-memory database.
"""
registry = UserRegistration()
registry.register(u"john", u"password", 12)
self.assertEqual(registry.db[u"john"], (u"passsword", 12))
assertHasMessage
returns the found message and can therefore be used within more complex assertions. assertHasAction
provides similar functionality for actions (see example below).
More generally, eliot.testing.LoggedAction
and eliot.testing.LoggedMessage
are utility classes to aid such testing.
LoggedMessage.of_type
lets you find all messages of a specific message type.
A LoggedMessage
has an attribute message
which contains the logged message dictionary.
For example, we could rewrite the registration logging test above like so:
from eliot.testing import LoggedMessage, capture_logging
class LoggingTests(TestCase):
def assertRegistrationLogging(self, logger):
"""
Logging assertions for test_registration.
"""
logged = LoggedMessage.of_type(logger.messages, "user_registration")[0]
assertContainsFields(self, logged.message,
{u"username": u"john",
u"password": u"password",
u"age": 12}))
@capture_logging(assertRegistrationLogging)
def test_registration(self, logger):
"""
Registration adds entries to the in-memory database.
"""
registry = UserRegistration()
registry.register(u"john", u"password", 12)
self.assertEqual(registry.db[u"john"], (u"passsword", 12))
Similarly, LoggedAction.of_type
finds all logged actions of a specific action type.
A LoggedAction
instance has start_message
and end_message
containing the respective message dictionaries, and a children
attribute containing a list of child LoggedAction
and LoggedMessage
.
That is, a LoggedAction
knows about the messages logged within its context.
LoggedAction
also has a utility method descendants()
that returns an iterable of all its descendants.
We can thus assert that a particular message (or action) was logged within the context of another action.
For example, let's say we have some code like this:
from eliot import start_action, Message
class Search:
def search(self, servers, database, key):
with start_action(action_type="log_search", database=database, key=key):
for server in servers:
Message.log(message_type="log_check", server=server)
if server.check(database, key):
return True
return False
We want to assert that the "log_check" message was written in the context of the "log_search" action. The test would look like this:
from eliot.testing import LoggedAction, LoggedMessage, capture_logging
import searcher
class LoggingTests(TestCase):
@capture_logging(None)
def test_logging(self, logger):
searcher = Search()
servers = [buildServer(), buildServer()]
searcher.search(servers, "users", "theuser")
action = LoggedAction.of_type(logger.messages, "log_search")[0]
messages = LoggedMessage.of_type(logger.messages, "log_check")
# The action start message had the appropriate fields:
assertContainsFields(self, action.start_message,
{"database": "users", "key": "theuser"})
# Messages were logged in the context of the action
self.assertEqual(action.children, messages)
# Each message had the respective server set.
self.assertEqual(servers, [msg.message["server"] for msg in messages])
Or we can simplify further by using assertHasMessage
and assertHasAction
:
from eliot.testing import LoggedAction, LoggedMessage, capture_logging
import searcher
class LoggingTests(TestCase):
@capture_logging(None)
def test_logging(self, logger):
searcher = Search()
servers = [buildServer(), buildServer()]
searcher.search(servers, "users", "theuser")
action = assertHasAction(self, logger, "log_search", succeeded=True,
startFields={"database": "users",
"key": "theuser"})
# Messages were logged in the context of the action
messages = LoggedMessage.of_type(logger.messages, "log_check")
self.assertEqual(action.children, messages)
# Each message had the respective server set.
self.assertEqual(servers, [msg.message["server"] for msg in messages])
In some cases @capture_logging
may not do what you want.
You can achieve the same effect, but with more control, with some lower-level APIs:
from eliot import MemoryLogger
from eliot.testing import swap_logger, check_for_errors
def custom_capture_logging():
# Replace default logging setup with a testing logger:
test_logger = MemoryLogger()
original_logger = swap_logger(test_logger)
try:
run_some_code()
finally:
# Restore original logging setup:
swap_logger(original_logger)
# Validate log messages, check for tracebacks:
check_for_errors(test_logger)