Python logging module imported in different scripts

Question

In the python logging tutorial, there is an example with two python scripts : myapp.py, and mylib.py

The code is :

# myapp.py
import logging
import mylib

def main():
    logging.basicConfig(filename='myapp.log', level=logging.INFO)
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()

and

# mylib.py
import logging

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

What I don't get is how the fact that using basicConfig in myapp.py changes the logging behavior in mylib.py.

I thought that in Python, when you import the same module in two different scripts, they are completely disconnected because the first one becomes myapp.logging and the second one mylib.logging.

EDIT :

I changed mylib.py code to

# mylib.py
import logging


def do_something():
    logging.warning('Doing something')


do_something()

When I run myapp.py, the logs are now printed in the console and do not appear in the log file anymore. How is that possible?

Answer 1

There's a bug (if I can call it that) in your understanding of python's modules:

I thought that in Python, when you import the same module in two different scripts, they are completely disconnected because the first one becomes myapp.logging and the second one mylib.logging.

This is not the case.

The import statement is interpreted when it is encountered, and when you run python on your main program (python myapp.py or equivalent), that executes these lines:

import logging

(which imports the logging module),

import mylib

(which imports your library mylib.py),

def main():

(which binds the name main to the compiled bytecode of the function), and:

if __name__ == '__main__':
    main()

(which runs your main since the local name __name__ is in fact bound to a string that compares equal to the string __main__).

So far, this is probably not very surprising (except perhaps that def main() is run at the point it's encountered in the import of myapp.py).

The part that probably is surprising is what happens during the execution of the two import statements.

The import machinery has evolved a bit (and is somewhat different in Python3 than Python2) but in essence it does these various things:

• locate the file (using sys.path)
• if this is the first import of that file, run all the executable statements in the file
• use or modify sys.modules (see below)
• bind the resulting object(s) (something of <type 'module'>, or a name within that) to the name(s) you supply (implicitly with regular import, explicitly with from ... import ... as name).

One of the key items here is the italicized part above. The module is actually run on the first import. The result of a successful import is a module instance, which is added to the sys.modules dictionary:

$ python2
...
>>> import sys
>>> x = sys.modules['copy_reg']
>>> print x
<module 'copy_reg' from '/usr/local/lib/python2.7/copy_reg.pyc'>

If, at this point, you ask python to re-import the module, it will quietly do almost nothing:

>>> import copy_reg
>>> 

What happens here is that Python notices that the module is already loaded and in sys.modules so it simply extracts the already-loaded module entity (the one we also bound to symbol x above). Then it binds the name copy_reg to this already-existing module. If you import copy_reg as y:

>>> import copy_reg as y

the name is additionally bound to the symbol y:

>>> print x, y, copy_reg
<module 'copy_reg' from '/usr/local/lib/python2.7/copy_reg.pyc'> <module 'copy_reg' from '/usr/local/lib/python2.7/copy_reg.pyc'> <module 'copy_reg' from '/usr/local/lib/python2.7/copy_reg.pyc'>

To see that these are in fact the same module, we can use the id function, which prints the internal address of the underlying object:

>>> print id(x), id(y), id(copy_reg)
34367067648 34367067648 34367067648

(a different run of Python, or a different version, might produce a different set-of-3 address values here, but all three will match, because these all refer to the same module).

---

In any case, in your main in myapp, the symbol logging refers to the same logging module as the symbol logging in mylib.

In your original code, you call (from do_something in mylib) logging.warning to print a message after your main in myapp has already called the logging configuration code. The log message therefore goes as directed.

In your edit, you've changed mylib to unconditionally call (via do_something) the logging.warning function as soon as the import mylib statement loads myilb to create the module. That happens early on in myapp, before binding main to the code and before calling main. So that message comes out on the console.

It's up to the logging code to decide whether to obey the (later) basicConfig call, made from your main. As you can see from your own example, it does not honor an attempt to redirect the root configuration after printing a message (this is because it's set up its internal log handlers by then, as I recall).

Answer 2

I believe log levels work globally in Python if you set them with logging.basicConfig.

The simplest answer is probably (as jake77 suggested already):

logger = logging.getLogger(__name__)

Then set the level on that logger specifically:

logger.setLevel(logging.DEBUG)  # or whichever

There's a good article on best practices with logging here. It may or may not be relevant to your case, but the best piece of advice it gives is that

[...] libraries have no business configuring logging levels, formatters, or handlers.

There's also a good answer here.

Answer 3

According to reference logging module provides a interface for creating and storing loggers for future uses,

multiple calls to getLogger() with the same name will always return a reference to the same Logger object.

Also, using directly logging.info is equals to getting default named logger and using it. you can check source codes for more details about implementation of this mechanism.

Answer 4

I think you should create a logger instance in your module

logger = logging.getLogger(__name__)

and then use

logger.info('message')

to log stuff.

Edit, based on comments on other answers. Setting the level is not a necessity, unless you want to filter some messages, say log only abowe WARNING. You definitely want to start a new console after changing your code.