Is it better to use root logger or named logger in Python

Question

I am trying to figure out the best practice for using logging in python across multiple modules. I see here: http://docs.python.org/2/howto/logging#logging-from-multiple-modules on how to use the root logger to log across multiple modules. As the link points out though, you can't tell where in your application your messages come from as they all show name "root."

It seems to me there are two options (this assumes my modules are NOT in a package structure, but are just a bunch of modules in the same folder):

1) Use the root logger as in the example, but change the log formatting to include the filename:

# myapp.py
import logging
import mylib

def main():
    logging.basicConfig(format='%(asctime)s %(filename)s %(levelname)s: %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p', level=logging.INFO)  #filename='myapp.log', 
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()

#mylib.py
import logging

def do_something():
    logging.info('Do something')




In [4]: import myapp

In [5]: myapp.main()
03/06/2014 12:22:07 PM myapp.py INFO: Started
03/06/2014 12:22:07 PM mylib.py INFO: Do something
03/06/2014 12:22:07 PM myapp.py INFO: Finished

2) Use a root logger in the main app but a named logger in the submodules, and use 'name' instead of 'filename' in the log format:

# myapp.py
import logging
import mylib

def main():
    #logging.basicConfig(format='%(asctime)s %(filename)s %(levelname)s: %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p', level=logging.INFO)  #filename='myapp.log', 
    logging.basicConfig(format='%(asctime)s %(name)s %(levelname)s: %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p', level=logging.INFO)  #filename='myapp.log', 
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()

#mylib.py
import logging

def do_something():
    #logging.info('Do something')
    logger = logging.getLogger(__name__)
    logger.info('Do something')



In [3]: import myapp

In [4]: myapp.main()
03/06/2014 12:27:29 PM root INFO: Started
03/06/2014 12:27:29 PM mylib INFO: Do something
03/06/2014 12:27:29 PM root INFO: Finished

Community · Accepted Answer · 2017-05-23 12:00:17Z

17

Vinay Sajip (maintainer of the logging module) makes a recommendation here which is similar to your option #2, except that you could use a named logger everywhere, even in myapp:

import logging
import mylib
logger = logging.getLogger(__name__)

def main():
    logging.basicConfig(format='%(asctime)s %(module)s %(levelname)s: %(message)s',
                        datefmt='%m/%d/%Y %I:%M:%S %p', level=logging.INFO)  
    logger.info('Started')
    mylib.do_something()
    logger.info('Finished')

if __name__ == '__main__':
    main()

which yields

03/06/2014 12:59:25 PM myapp INFO: Started
03/06/2014 12:59:25 PM mylib INFO: Do something
03/06/2014 12:59:25 PM myapp INFO: Finished

Note that if you use %(module)s instead of %(name)s, then you get myapp where before you got root or myapp.py, or __main__.

This symmetry -- of always using logger -- may be especially useful if myapp is sometimes called as a script and sometimes imported as a module.

edited May 23, 2017 at 12:00

CommunityBot

11 silver badge

answered Mar 6, 2014 at 17:55

unutbu

886k197 gold badges1.9k silver badges1.7k bronze badges

Sign up to request clarification or add additional context in comments.

8 Comments

bobo5645 Over a year ago

Thanks! I tried this, and it works, but I don't understand why. (Having both loggers in myapp and mylib named "_name_".) _name_ in myapp is "myapp" if myapp is imported like it is in my example. _name_ in mylib is "mylib" So in each file, when logger = logging.getLogger(_name_), aren't they creating two different loggers? Does it work because the output from each separate logger is still being passed up to the root logger, and then to the console?

bobo5645 Over a year ago

Also, can you elaborate on your last comment of always using "logger" being useful if myapp is sometimes called as a script or imported as a module. You mean using logger = logging.getLogger(..) is better for this than just using root logger directly: logging.info("..")?

unutbu Over a year ago

Yes, you are getting two different loggers. This flowchart shows loggers (by default) propagate records to parent loggers. So the root logger's handler(s) get a chance to handle the record.

unutbu Over a year ago

Suppose you were to use logging.info in the main script, myapp, but logger.info in modules. Suppose later you create a new script which imports myapp. Now the logging output would use root as the %(name)s whenever a logging message came from myapp, whereas for consistency you'd rather have it report myapp. If you instead always use logger.info, even in the main script, then you future-proof your code against the possibility that it may one day be used as a module.

bobo5645 Over a year ago

Thanks for the flowchart, and your explanation of the advantage of using logger. Both make sense to me now. Not sure if I should start a new question but: if in this example I want to have multiple handlers, i.e., INFO level goes to stdout and a file, and ERROR level is sent to an email address, is there a way to do that? I assume it's not logging.addHandler()? Maybe logging.config.fileConfig()?

|

Collectives™ on Stack Overflow

Is it better to use root logger or named logger in Python

1 Answer 1

8 Comments

Your Answer

Linked

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

8 Comments

Your Answer

Sign up or log in

Post as a guest

Linked

Related