Decorator for elapsed time flask

Question

Trying to log the amount of time it takes to run a function using decorators but I'm misunderstanding something. It refuses to write to log in the decorator.

When you reverse the order of the decorators, it causes build-errors on the template (like as if information is lost).

In my init py:

if app.debug is not True:   
    import logging
    from logging.handlers import RotatingFileHandler
    file_handler = RotatingFileHandler('python.log', maxBytes=1024 * 1024 * 100, backupCount=20)
    file_handler.setLevel(logging.ERROR)
    formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
    file_handler.setFormatter(formatter)
    app.logger.addHandler(file_handler)

In my views.py:

def print_elapsed_time(func):
        from time import clock
        def wrapper(**kwargs):
            tic = clock()
            result = func(**kwargs) # this function fails to log the error below
            app.logger.error("\tElapsed time for function: %.1f s" % (clock() - tic))
            return result
        return wrapper


@print_elapsed_time
@app.route('/index', methods=['GET','POST'])
@app.route('/index/<int:page>', methods=['GET','POST'])
def ListPosts(page = 1):    
    app.logger.error("got user") # works
    # posts = query
    return render_template('index.html', post=posts)

Answer 1

With the print_elapsed_time decorator above Flask's route decorators, the function registered by route has not yet been modified by print_elapsed_time, as decorators are applied from bottom to top. The solution is to put @print_elapsed_time below both route decorators. However, Flask keeps track of its registered functions by their name, and for everything wrapped by print_elapsed_time this is wrapper. See my answer to another StackOverflow question for ways around that.

Answer 2

Here is a code snippet based on Abe's insight:

from functools import wraps     # ADD THIS

# ...

def print_elapsed_time(func):
    @wraps(func)                # ADD THIS
    from time import clock
    def wrapper(**kwargs):
        tic = clock()
        result = func(**kwargs) 
        app.logger.error("\tElapsed time for function: %.1f s" % (clock() - tic))
        return result
    return wrapper

# ...

@app.route('/index', methods=['GET','POST'])
@app.route('/index/<int:page>', methods=['GET','POST'])
@print_elapsed_time             # MOVE FUNCTION TO HERE
def ListPosts(page = 1):    
    app.logger.error("got user") # works
    # posts = query
    return render_template('index.html', post=posts)