Python – Flask + sqlalchemy advanced logging

Flask + sqlalchemy advanced logging… here is a solution to the problem.

Flask + sqlalchemy advanced logging

I’ve found some other posts about this, but none of them worked for me, so I’d like to get in touch and see if anyone can explain how to properly get/redirect/set handler sqlalchemy

Previous research couldn’t answer my question:

https://github.com/pallets/flask/issues/1359

http://flask.pocoo.org/docs/dev/logging/

https://gist.github.com/ibeex/3257877

My configuration:

Main .py

    ...

def init_app():
    """ Runs prior to app launching, contains initialization code """

# set logging level
    if not os.path.exists(settings. LOG_DIR):
        os.makedirs(settings. LOG_DIR)

# default level
    log_level = logging. CRITICAL

if settings. ENV == 'DEV':
        log_level = logging. DEBUG
    elif settings. ENV == 'TEST':
        log_level = logging. WARNING
    elif settings. ENV == 'PROD':
        log_level = logging. ERROR

log_formatter = logging. Formatter("[%(asctime)s] {%(pathname)s:%(lineno)d} %(levelname)s - %(message)s")
    api_logger = logging.getLogger()
    api_handler = TimedRotatingFileHandler(
            settings. API_LOG_FILE,
            when='midnight',
            backupCount=10
        )
    api_handler.setLevel(log_level)
    api_handler.setFormatter(log_formatter)
    api_logger.addHandler(api_handler)
    logging.getLogger('werkzeug').addHandler(api_handler)

db_logger = logging.getLogger('sqlalchemy')
    db_handler = TimedRotatingFileHandler(
            settings. DB_LOG_FILE,
            when='midnight',
            backupCount=10
        )
    db_handler.setLevel(log_level)
    db_handler.setFormatter(log_formatter)
    db_logger.addHandler(db_handler)
    logging.getLogger('sqlalchemy.engine').addHandler(db_handler)
    logging.getLogger('sqlalchemy.dialects').addHandler(db_handler)
    logging.getLogger('sqlalchemy.pool').addHandler(db_handler)
    logging.getLogger('sqlalchemy.orm').addHandler(db_handler)

# add endpoints

...

if __name__ == '__main__':
    init_app()
    app.run(host='0.0.0.0', port=7777)

I tried getting and

changing the settings on the logger in a couple of different ways, but I ended up still outputting werkzeug debug to the console instead of my logs, and I could see that logs were being created, but it didn’t look like the logger was actually output to them:

API .log (formatter writes to it).

2018-02-15 12:03:03,944] {/usr/local/lib/python3.5/dist-packages/werkzeug/_internal.py:88} WARNING -  * Debugger is active!

db.log (empty).

Any insight into this would be appreciated!

Update

I was able to get the werkzeug logger working using the long hand version, and it looks like the shorthand function call shown is returning an empty object. Although the sqlalchemy logger is still outputting to the console. Will the engine configuration overwrite my file handler?

Master .py

...

# close current file handlers
for handler in copy(logging.getLogger().handlers):
    logging.getLogger().removeHandler(handler)
    handler.close()
for handler in copy(logging.getLogger('werkzeug').handlers):
    logging.getLogger('werkzeug').removeHandler(handler)
    handler.close()
for handler in copy(logging.getLogger('sqlalchemy.engine').handlers):
    logging.getLogger('sqlalchemy.engine').removeHandler(handler)
    handler.close()
for handler in copy(logging.getLogger('sqlalchemy.dialects').handlers):
    logging.getLogger('sqlalchemy.dialects').removeHandler(handler)
    handler.close()
for handler in copy(logging.getLogger('sqlalchemy.pool').handlers):
    logging.getLogger('sqlalchemy.pool').removeHandler(handler)
    handler.close()
for handler in copy(logging.getLogger('sqlalchemy.orm').handlers):
    logging.getLogger('sqlalchemy.orm').removeHandler(handler)
    handler.close()

# create our own custom handlers
log_formatter = logging. Formatter("[%(asctime)s] {%(pathname)s:%(lineno)d} %(levelname)s - %(message)s")
api_handler = TimedRotatingFileHandler(
        settings. API_LOG_FILE,
        when='midnight',
        backupCount=10
    )
api_handler.setLevel(log_level)
api_handler.setFormatter(log_formatter)
logging.getLogger().setLevel(log_level)
logging.getLogger().addHandler(api_handler)
logging.getLogger('werkzeug').setLevel(log_level)
logging.getLogger('werkzeug').addHandler(api_handler)

db_handler = TimedRotatingFileHandler(
        settings. DB_LOG_FILE,
        when='midnight',
        backupCount=10
    )
db_handler.setLevel(log_level)
db_handler.setFormatter(log_formatter)
logging.getLogger('sqlalchemy.engine').addHandler(db_handler)
logging.getLogger('sqlalchemy.engine').setLevel(log_level)
logging.getLogger('sqlalchemy.dialects').addHandler(db_handler)
logging.getLogger('sqlalchemy.dialects').setLevel(log_level)
logging.getLogger('sqlalchemy.pool').addHandler(db_handler)
logging.getLogger('sqlalchemy.pool').setLevel(log_level)
logging.getLogger('sqlalchemy.orm').addHandler(db_handler)
logging.getLogger('sqlalchemy.orm').setLevel(log_level)

Database .py

...
engine = create_engine(getDBURI(), echo="debug", echo_pool=True, pool_recycle=10)

Answer

If anyone encounters this issue, for future reference, sqlalchemy engine configures echo=True|' debug' will overwrite your logger. Solved this problem by changing my engine config to the following:

engine = create_engine(getDBURI(), echo_pool=True, pool_recycle=10)

And then everything went well. Cheers! 😀

Solution

As I understand it, your werkzeug file-based log configuration is actually running=> it outputs to the api.log

The database log handler is also working (files are created, etc.) but there is no output.
This may be due to the log level of these loggers being in an error state by default. You need to set them manually at a lower level like this:

logging.getLogger('sqlalchemy.engine').setLevel(logging. DEBUG)
logging.getLogger('sqlalchemy.dialects').setLevel(logging. DEBUG)
logging.getLogger('sqlalchemy.pool').setLevel(logging. DEBUG)
logging.getLogger('sqlalchemy.orm').setLevel(logging. DEBUG)

Werkzeug is still outputting to the console, probably because the root logger is always defined. Before adding a new handler, you should do the following to remove all log handlers:

    for handler in copy(logging.getLogger().handlers):
        logging.getLogger().removeHandler(handler)
        handler.close()  # clean up used file handles

You can then also assign your application log handler as the root log handler

logging.getLogger().addHandler(api_handler)

If it is not the root logger, but just the werkzeug logger

that defines the default console logger, you can also remove all handlers from the werkzeug logger before adding your logger as follows:

    for handler in copy(logging.getLogger('werkzeug').handlers):
        logging.getLogger('werkzeug').removeHandler(handler)
        handler.close()  # clean up used file handles
    logging.getLogger('werkzeug').addHandler(api_handler)

Related Problems and Solutions