Unable to use Python Logging in sub-modules in Flask

Question

My Flask project layout has two folders - fro and back. Fro is my Flask app and "back" is the service layer that contains files/modules that my Flask app invokes.

My problem is that while the log statements in the functions written in Fro are being logged on the output console, the log statements in the functions written in the service layer do not show up in the log output.

I have tried disabling the default flask.logger but that does not seem to help.

app.logger.disabled = True
logger = logging.getLogger('werkzeug')
logger.disabled = True

Here is how the code looks like in app.py -

import os
from flask import Flask
import click
import logging
log = logging.getLogger(__name__)

def create_app(test_config=None):
    # create and configure the app
    app = Flask(__name__, instance_relative_config=True)
    app.logger.info("This gets printed")
    configure(app)
    app.logger.info("This also gets printed")
    # bunch of code
    # ...
    return app

Here is how a route method looks like -

import logging
from back.services import request_service
log = logging.getLogger(__name__)


@bp.route('/install', methods=('GET', 'POST'))
def install():
    log.info("This gets printed")
    is_valid_request = request_service.check_request_authenticity(request)
    return str(is_hmac_valid)

The check_request_authenticity function in the request_service looks like this -

import logging
log = logging.getLogger(__name__)
def check_request_authenticity():
        log.info("However this DOES NOT get printed")

I want to be able to log in the functions in my service layer using the native python logging without having to pass the flask app.logger to the function in my service layer.

Any pointers please?

Answer 1

I got you fam.

Why it works

The problem lies in the loggers, in app.py, your logging works because:

log = logging.getLogger(__name__)

def create_app(test_config=None):
    # create and configure the app
    app = Flask(__name__, instance_relative_config=True)
    app.logger.info("This gets printed")
    configure(app)
    app.logger.info("This also gets printed")
    # bunch of code
    # ...
    return app

log and app.logger are the same logger, because you're passing the same __name__ to both the logger and the Flask object.

When you do app.logger, Flask will use the __name__ it has been instantiated with to create that logger. However since you've created that logger before, when doing: log = logging.getLogger(__name__), Flask will see it exists and will only fetch that existing logger, and add handlers to it, and a nice format with the date, time and filename, resulting in a log of the form:

[2019-09-15 12:51:47,534] INFO in app: This gets printed

Flask also sets the level of that logger to logging.DEBUG, which is why your .info() calls work.

If you were to do log.info('Whats poppin cuz') before calling app.logger.info() you will see that it won't print anything to the console, because the default logging level used will be that of the root level which is WARNING (remember this as it will be valuable info further down in this explanation).

---

The problem

Moving on, when you're in back.services and you do log = logging.getLogger(__name__), you create a different logger, of the name back.services, which has nothing to do with fro.app logger created above (so disabling that logger won't impact this logger).

What this means is that, when you do:

log.info("However this DOES NOT get printed") it will propagate this message all the way to the root logger, which has, a default level of, you guessed it from above, WARNING, and only messages greater than or equal to WARNING will be logged out. See all the logging levels here.

If you were to replace log.info() with log.warning() you will see that it will get printed out. But, unlike the flask logger, you won't have a nice format with the message, you'll have just a basic print of the message.

---

Solutions

Solution 1

Now I understand that you don't want to pass the app.logger object in all the modules, but you don't have to. All you have to do to take advantage of that logger is just to fetch it, without passing any objects, and you'll use the python native logging machinery and the flask object with a nice format, because that's how the python logging machinery works. Once a logger has been created, any other calls with that name will just fetch that logger, instead of creating it again.

So instead of doing

log = logging.getLogger(__name__) in back.services

just do

log = logging.getLogger('fro.app') (or whatever the value __name__ has where you instantiate the Flask object in the create_app function) and you'll see how nicely your messages get formatted and printed.

Make sure tho' that you call app.logger early on (basically like you did above, after you've created the Flask object or somewhere in your app.py) so that Flask can set up that logger properly.

Solution 2

If you don't want to use the app.logger at all, anywhere, just do a logging.basicConfig(level=DEBUG) call early on and you'll see all your messages in the entire app, at all levels.

And you can continue to instantiate loggers based on modules name like you're doing now, i.e log = logging.getLogger(__name__).

Your create_app can be something like:

def create_app(test_config=None):
    # create and configure the app
    app = Flask(__name__, instance_relative_config=True)
    logging.basicConfig(level=logging.DEBUG)  # this added here
    app.logger.info("This gets printed")
    app.logger.info("This also gets printed")
    # more code below
    return app

and your install function and loggers across the application can remain as they are, and the logs will be of the form:

INFO:fro.app:This gets printed
INFO:fro.app:This also gets printed
INFO:back.services:However this DOES get printed

Solution 3

This is the more advanced stuff, where you create a logging configuration (via either dictConfig, or fileConfig), and load it very early on, when the application starts, but this is beyond the scope of this ticket. You can find the information for that in the docs here and in other answers on this forum.