How to log to a Database with Flask

This post is part of a series. This list contains all of the posts:

For the Python Blog that I made to create this website, I wanted to log serious errors to a database so that I could see them in a UI on my website instead of having to read through log files.

Sources of inspiration

I used the following articles to help me build the logging to database capability in Flask.

Database Model

I'm using SQLAlchemy with Sqlite, but feel free to substitute your own ORM and databse.

class Log(db.Model):
    id = db.Column(db.Integer, primary_key=True)
    logger = db.Column(db.String)
    level = db.Column(db.String)
    trace = db.Column(db.String)
    message = db.Column(db.String)
    path = db.Column(db.String)
    method = db.Column(db.String)
    ip = db.Column(db.String)
    is_admin = db.Column(db.String)
    creation_date = db.Column(db.DateTime, nullable=False, 
        server_default=func.now())

    __table_args__ = ({'sqlite_autoincrement': True},)

Extending logging.Handler

We will be creating our own custom Handler by extending logging.Handler. The only method we need to override is emit.

from models import *
import logging

class SQLAlchemyHandler(logging.Handler):
    def emit(self, record):
        trace = None
        exc = record.__dict__['exc_info']
        if exc:
            trace = traceback.format_exc(exc)

        path = request.path
        method = request.method
        ip = request.remote_addr

        log = Log(logger=record.__dict__['name'],
                  level=record.__dict__['levelname'],
                  trace=trace,
                  message=record.__dict__['msg'],
                  path=path,
                  method=method,
                  ip=ip,
                  is_admin=is_admin
        )
        db.session.add(log)
        db.session.commit()

exc will be none unless our logger's exception method was called. path is the url that the log occurred.

Note how this issues a commit, of course, to store the log away. This can introduce a very serious, and subtle, bug. I'll explain at the end of this post.

Placing the code in the Flask App

I have a directory structure similar to the following

/blog/
    /blog
        __init__.py
        models.py
        views/
            ...

My __init__.py file looks similar to this:

from flask import Flask, request
from flask_sqlalchemy import SQLAlchemy
import logging
import traceback

app = Flask(__name__)
db = SQLAlchemy(app)

from blog.views import *
from blog.models import Log

# Define SQLAlchemyHandler here, AFTER importing views
class SQLAlchemyHandler(logging.Handler):
    ...

db_handler = SQLAlchemyHandler()
db_handler.setLevel(logging.WARN)  # Only serious messages
app.logger.addHandler(db_handler)

file_handler = RotatintFileHandler(...)
file_handler.setLevel(logging.INFO) # All messages
app.logger.addHandler(file_handler)

See how I defined the SQLAlchemyHandler after importing all my views? If I define it before, which I tried, I receive an ImportError due to how my project is set up. You may wish to try it both ways.

Dangerous Bug Alert

This bit me pretty hard. As mentioned previously, the emit method of the SQLAlchemyHandler class needs to commit its log message. This means that if the application throws an exception halfway through a transaction, but the developer does not roll it back before calling app.logger.warn or app.logger.exception, the transaction will be inadvertently saved, destroying the integrity of our database.

For example, here was a bug that I had:

try:
    db.session.query(Post) \
    # ...
except SQLAlchemyError as ex:
    app.logger.exception("Failed !")
    db.session.rollback()

Because I logged prior to rolling back, my logger was committing my transaction!

If you chose to implement your database logger in this fashion, you have to always make sure to rollback before making a call to the logger at a level the database logger is on.

For example, I'm setting my database logger level to logging.WARN. Therefore, it would be unacceptable to make a call to logger.warn unless the transaction was rolled back first, even under a circumstance where we didn't need to rollback.

This seems pretty serious. Are we really going to trust all of our devs to remember this? At least in my case, this is my blog and I am the sole author. I will remember this, especially because it took me a while to debug it the first time. However, at work or in any shared code base, I don't believe this would be a suitable solution.

This post is part of a series. This list contains all of the posts:


Comments

Add Comment

Name

Email

Comment

Are you human? - nine = -8