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.
I used the following articles to help me build the logging to database capability in Flask.
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},)
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.
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.
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:
Name: ghyst
Creation Date: 2018-05-28
How about using a second database schema and writing logs into that one. This way one would need to create two session objects and the state of the first db.session1 (used by app) would not change (if that is desired after an WARN/ERROR/CRITICAL anyhow?) and the logger would write to db.session2 (of the logger)? How to implement this?