Clean Code in Python

Incorrect handling of side-effects in a decorator

Let's imagine the case of a decorator that was created with the goal of logging when a function started running and then logging its running time:

def traced_function_wrong(function):
    logger.info("started execution of %s", function)
    start_time = time.time()

    @functools.wraps(function)
    def wrapped(*args, **kwargs):
        result = function(*args, **kwargs)
        logger.info(
            "function %s took %.2fs",
            function,
            time.time() - start_time
        )
        return result
    return wrapped

Now we will apply the decorator to a regular function, thinking that it will work just fine:

@traced_function_wrong
def process_with_delay(callback, delay=0):
    time.sleep(delay)
    return callback()

This decorator has a subtle, yet critical bug ...