Welcome, guest | Sign In | My Account | Store | Cart

Logging asserts (Python recipe) by d.schlabing
ActiveState Code (http://code.activestate.com/recipes/577074/)

This tries to marry assert statements with logging. If you use asserts together with logging and the script stops because an assertion is not fulfilled, you will not find any information about this in the logs. Unless you do something like this:

meal = ["eggs", "bacon", "spam"]
try:
    assert "spam" not in meal, "But I don't like spam!"
except AssertionError:
    log.exception("But I don't like spam!")
    raise

With the proposed recipe a somewhat similar behaviour can be achieved by:

log_assert("spam" not in meal, "But I don't like spam!")
Python, 39 lines
Download
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
import logging
import sys
import inspect

def log_assert(bool_, message="", logger=None, logger_name="", verbose=False):
    """Use this as a replacement for assert if you want the failing of the
    assert statement to be logged."""
    if logger is None:
        logger = logging.getLogger(logger_name)
    try:
        assert bool_, message
    except AssertionError:
        # construct an exception message from the code of the calling frame
        last_stackframe = inspect.stack()[-2]
        source_file, line_no, func = last_stackframe[1:4]
        source = "Traceback (most recent call last):\n" + \
            '  File "%s", line %s, in %s\n    ' % (source_file, line_no, func)
        if verbose:
            # include more lines than that where the statement was made
            source_code = open(source_file).readlines()
            source += "".join(source_code[line_no - 3:line_no + 1])
        else:
            source += last_stackframe[-2][0].strip()
        logger.debug("%s\n%s" % (message, source))
        raise AssertionError("%s\n%s" % (message, source))

def mr_barnard():
    this = "an argument"
    log_assert(this is not "an argument", 
               "Yes it is. - No it isn't. It's just contradiction.",
               verbose=True) 

if __name__ == "__main__":
    logging.basicConfig(filename="argument_clinic", level=logging.DEBUG)
    
    try:
        mr_barnard()  # room 12
    finally:
        print "What a stupid concept."

This is far from being perfect. I would have liked to log a traceback beginning from where the log_assert-function was called. (Printing the line with the actual assert-statement would just give information that is too generic to be useful) Instead, the line(s) are appended as a message to the assert statement and the logging.exception-method.

Syntactically it would be really nice if one could use decorators here, like:

@log
assert "spam" not in meal, "But I don't like spam!"
Tags: logging

2 comments

Gabriel Genellina 14 years, 1 month ago  # | flag

A different approach is to replace sys.excepthook with a custom handler, so any uncaught exception gets logged (not just AssertionError):

def excepthook(*args):
  logging.getLogger().error('Uncaught exception:', exc_info=args)

sys.excepthook = excepthook

assert 1==2, 'Something went wrong'

(this seems easier and more robust in some circumstances, at least to me)

d.schlabing (author) 14 years, 1 month ago  # | flag

Thanks Gabriel! I expected that someone in the community would come up with a shorter, easier and generally more pythonic solution.