Logging SqlAlchemy to Database

Question

I'm coding a small application which is supposed to log everything to a database using sqlalchemy. Inspired by this:

python logging to database

and this:

https://docs.pylonsproject.org/projects/pyramid-cookbook/en/latest/logging/sqlalchemy_logger.html I came up with a solution that works fine for all log messages of all involved libraries besides those generated by sqlalchemy (!) itself.

Here is a minimal example, reproducing my problem:

import logging
import datetime
from sqlalchemy import Column, DateTime, String, create_engine
from sqlalchemy.ext.declarative import declarative_base
from sqlalchemy.orm import sessionmaker

Base = declarative_base()


 # define table
class TblLog(Base):
    __tablename__ = 'Tbl_Log'

    LOG_TIME = Column(DateTime, primary_key=True)
    LOG_NAME = Column(String(100))
    LOG_LEVEL = Column(String(100))
    LOG_MSG = Column(String(2000))

    def __init__(self, time, name, lvl, msg):
        self.LOG_TIME = time
        self.LOG_NAME = name
        self.LOG_LEVEL = lvl
        self.LOG_MSG = msg

# custom log handler that emits to the database
class DatabaseHandler(logging.Handler):

    def __init__(self, session):
        super().__init__()
        self.session = session
        self.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s'))
        self.setLevel(logging.DEBUG)

    def emit(self, record):

        self.format(record)

        log_time = datetime.datetime.strptime(record.__dict__['asctime'], "%Y-%m-%d %H:%M:%S,%f")

        log_record = TblLog(log_time, record.__dict__['name'], record.__dict__['levelname'], record.__dict__['message'])

        self.session.add(log_record)
        self.session.commit()

testing this with sqlalchemy (!) logs enabled:

if __name__ == '__main__':
    # simple logging config
    logging.basicConfig(
        format='%(asctime)s : %(name)s : %(levelname)s : %(message)s',
        level=logging.DEBUG,
    )
    logger_sqlalchemy = logging.getLogger('sqlalchemy')
    logger_sqlalchemy.setLevel(logging.INFO)


    # test with sqlite in memory database
    DB_STRING = 'sqlite:///:memory:'
    engine = create_engine(DB_STRING, echo=False)
    Base.metadata.create_all(engine)
    Session = sessionmaker()
    session = Session(bind=engine)

    # adding custom handler:
    logger_sqlalchemy.addHandler(DatabaseHandler(session))

    logger_sqlalchemy.info('this is a test message')

This raises

AttributeError: 'NoneType' object has no attribute 'set'

I can paste the whole traceback if necessary. I suspect that the issue arises because the TblLog(...) call produces a log record and thus the handler emits records to itself?!

What would be the best solution for this problem, i.e. can I write sqlalchemy log messages to a database using sqlalchemy in the handler??

I'm kind of stuck here, thanks for any help...

Answer 1

I suspect that the issue arises because the TblLog(...) call produces a log record and thus the handler emits records to itself?!

That's not the immediate issue. The reason for the failure is that SQLAlchemy is emitting log messages while it is configuring the mapper, the first of those is sent before TblLog's mapper is fully configured and hence, your error.

If you add a StreamHandler to your logger_sqlalchemy instance before the DatabaseHandler you'll be able to see the log messages logger_sqlalchemy is receiving right up to the crash. The log message that's tripping it up is (TblLog|Tbl_Log) _post_configure_properties() started, which is coming from the _post_configure_properties() method. The docstring for that method includes:

This is a deferred configuration step which is intended to execute once all mappers have been constructed.

So that's a clue that the config of the mapper for TblLog isn't finished.

If you then, remove the DatabaseHandler from the logger and just leave the StreamHandler you'll see what that method goes on to do (I also removed your basicConfig() for clarity):

(TblLog|Tbl_Log) _post_configure_properties() started
# this is where your code crashed originally
(TblLog|Tbl_Log) initialize prop LOG_TIME
(TblLog|Tbl_Log) initialize prop LOG_NAME
(TblLog|Tbl_Log) initialize prop LOG_LEVEL
(TblLog|Tbl_Log) initialize prop LOG_MSG
(TblLog|Tbl_Log) _post_configure_properties() complete

So as you can see, some initialisation of the column descriptors seems to be happening after that first log message is emitted. Which is why you get the error, the ORM isn't ready by the time you're trying to use it.

You could instantiate a dummy TblLog instance to force the mapper to configure before you add the handler, e.g.:

# ensure TblLog mapper configured
TblLog(time=None, name=None, lvl=None, msg=None)
logger_sqlalchemy.addHandler(DatabaseHandler(session))
logger_sqlalchemy.info('this is a test message')

But you'll then encounter a new problem: SQLAlchemy emits logs throughout the flush/commit process. So then as the first log message is flushed to the datbase it generates a new log message which itself generates a new log message etc etc..... infinite recursion.

So my answer to:

What would be the best solution for this problem, i.e. can I write sqlalchemy log messages to a database using sqlalchemy in the handler??

The answer would be no, if you are trying to also capture sqlalchemy logging the logging.

Some possible solutions:

• Don't use SQLAlchemy to write the log messages to the database. Assuming that you use SQLAlchemy in other parts of your application, use the dpapi client direcly to write the logs to the db and explicitly don't write the client's log messages to the database (otherwise you'll end up with the same recursion issue).
• send your log messages to a webservice using a HTTPHandler which writes the log messages to a database.
• Have sqlalchemy log to a file, while everything else logs to the database. You could even setup a cron job to periodically write the sqlalchemy logs from the file to the database in a separate process.
• Logging as a service