What is the most pythonic way of logging for multiple modules and multiple handlers with specified encoding?

Question

I'm looking for concrete advice about how the multiple module and multiple handler logging should be done. I have added my simplified code here, but I don't want to bias the answers - tell me what the best practice is.

I would like to log everything to a file, and warn and above to console.

This is my level0.py which I want it to log to the specified file:

import logging
from flask import Flask
from level1 import function1

app = Flask(__name__)

logger = logging.getLogger('logger0')
logger.setLevel(logging.DEBUG)

file_handler = logging.FileHandler('../logs/logger0','w','utf-8')
file_handler.setLevel(logging.DEBUG)
file_format = logging.Formatter('%(asctime)s %(levelname)s: %(message)s [in %(pathname)s:%(lineno)d in %(funcName)s]')
file_handler.setFormatter(file_format)
logger.addHandler(file_handler)

console_handler = logging.StreamHandler()
console_handler.setLevel(logging.INFO)
console_format = logging.Formatter('%(message)s')
console_handler.setFormatter(console_format)
logger.addHandler(console_handler)

@app.route('/', methods=['GET', 'POST'])
def function0(foo):
    bar = function1(foo)
    logger.debug('function0')
    ...

Also, level1 can be a standalone module, when called as a script. In that case I want it logged to another file. Below is the level1.py (has duplicated logging lines):

import logging
logger = logging.getLogger('level0.level1')

from level2 import function2

def function1(foo):
    bar = function2(foo)
    logger.debug('function1')
    ...

if __name__ == "__main__":
    logger = logging.getLogger('logger0')
    logger.setLevel(logging.DEBUG)

    file_handler = logging.FileHandler('../logs/logger1','w','utf-8')
    file_handler.setLevel(logging.DEBUG)
    file_format = logging.Formatter('%(asctime)s %(levelname)s: %(message)s [in %(pathname)s:%(lineno)d in %(funcName)s]')
    file_handler.setFormatter(file_format)
    logger.addHandler(file_handler)

    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.INFO)
    console_format = logging.Formatter('%(message)s')
    console_handler.setFormatter(console_format)
    logger.addHandler(console_handler)

    bar = function1('foo')
    logger.info('level1 main')
    ...

I've copied this logging chunk from level0, because I wanted the same logging and it seemed intuitive to put it in main. level2 is not standalone, so it only has:

import logging
logger = logging.getLogger('level0.level1.level2')

def function2(foo):
    logger.info('function2')
    ....

I started with logging.basicSetup, but couldn't set encoding for the file and kept getting UnicodeEncodeError when trying to log non-ascii strings:

logger.warn(u'foo bar {}'.format(NON_ASCII_STR))

(I still get the error as the logger passes the message to its parents)

So, what is the best log design for this case or more generally - multiple modules (with encoding selection - I want utf-8)

Answer 1

For modules consisting of many parts, I use the method recommended in the documentation, which just has one line per module, logger = logging.getLogger(__name__). As you point out, the module shouldn't know or care how or where its messages are going, it just passes it on to the logger that should have been set up by the main program.

To reduce cut-n-paste depending on which is your main program, make sure your modules have a hierarchy that makes sense, and have just one function somewhere that sets up your logging, which can then be called by any main you wish.

For example, make a logsetup.py:

import logging

def configure_log(level=None,name=None):
    logger = logging.getLogger(name)
    logger.setLevel(level)

    file_handler = logging.FileHandler('../logs/%s' % name,'w','utf-8')
    file_handler.setLevel(logging.DEBUG)
    file_format = logging.Formatter('%(asctime)s %(levelname)s: %(message)s [in %(pathname)s:%(lineno)d in %(funcName)s]')
    file_handler.setFormatter(file_format)
    logger.addHandler(file_handler)

    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.INFO)
    console_format = logging.Formatter('%(message)s')
    console_handler.setFormatter(console_format)
    logger.addHandler(console_handler)

To have your individual modules have a mode in which they behave as main, define a separate function, such as main.

In level0.py and/or level1.py:

def main():
  # do whatever

And in the very top level program, call that function:

import logging
from logsetup import configure_log
configure_log(logging.DEBUG,'level0') # or 'level1'
from level0 import main # or level1

if __name__ == "__main__"
  main()

You should still have the __name__ == "__main__" clause there, some modules (cough multiprocessing cough) have different behavior depending on whether or not the clause exists.

Answer 2

To kinda wrap this up, here is what I did; I've put the following two lines in every module/file:

import logging
logger = logging.getLogger(__name__)

This sets up the logging, but doesn't add any handlers. I then add handlers to the root logger in the main file I'm running the imported modules therefore pass their records to the root logger and everything gets saved and displayed. I do it like CaptainMurphy suggested, but with logger = logging.getLogger('') to work with the root logger

To address encoding - I had problems saving non-ascii strings to file. So I just added FileHandler to the root logger, where encoding can be specified. I couldn't do it with logging.basicConfig.

Thank you again @CaptainMurphy - I'm sorry I can't upvote you with my low reputation, but I've checkmarked the answer.