How setup Python logging in unit tests

Question

How do I set up logging in a Python package and the supporting unit tests so that I get a logging file out that I can look at when things go wrong?

Currently package logging seems to be getting captured by nose/unittest and is thrown to the console if there is a failed test; only unit test logging makes it into file.

In both the package and unit test source files, I'm currently getting a logger using:

import logging
import package_under_test

log = logging.getLogger(__name__)

In the unit test script I have been trying to set up log handlers using the basic FileHandler, either directly in-line or via the setUp()/setUpClass() TestCase methods

And the logging config, currently set in the Unit test script setUp() method.

root, ext = os.path.splitext(__file__)
log_filename = root + '.log'
log_format = (
    '%(asctime)8.8s %(filename)-12.12s %(lineno)5.5s:' 
    ' %(funcName)-32.32s %(message)s')
datefmt = "%H:%M:%S"
log_fmt = logging.Formatter(log_format, datefmt)
log_handler = logging.FileHandler(log_filename, mode='w') 
log_handler.setFormatter(log_fmt)
log.addHandler(log_handler)
log_format = '%(message)s'

log.setLevel(logging.DEBUG)

log.debug('test logging enabled: %s' % log_filename)

The log in the last line does end up in the file but this configuration clearly doesn't filter back into the imported package being tested.

Without a more concrete example, this is hard to answer. We don't know anything about how you have configured your logging, for example. — Martijn Pieters
– Martijn Pieters, Commented Jun 14, 2018 at 14:16
Logging in both the package source and the unit test source uses: #import logging log = logging.getLogger(name) — Paul D Smith
– Paul D Smith, Commented Jun 14, 2018 at 15:44
Right, but you didn't set up any configuration? logging.basicConfig() or explicit configuration set? — Martijn Pieters
– Martijn Pieters, Commented Jun 14, 2018 at 16:26
Sorry - I'll add the config into the question - the formatting gets lost in a comment. — Paul D Smith
– Paul D Smith, Commented Jun 15, 2018 at 8:24

Martijn Pieters · Accepted Answer · 2018-06-15 12:49:21Z

2

Logging objects operate in a hierarchy, and log messages 'bubble up' the hierarchy chain and are passed to any handlers along the way (provided the log level of the message is at or exceeds the minimal threshold of the logger object you are logging on). Ignoring filtering and global log-level configurations, in pseudo code this is what happens:

if record.level < current_logger.level:
    return
for logger_object in (current_logger + current_logger.parents_reversed):
    for handler in logger_object.handlers:
        if record.level >= handler.level:
            handler.handle(record)
    if not logger_object.propagate:
        # propagation disabled, the buck stops here.
        break

Where handlers are actually responsible for putting a log message into a file or write it to the console, etc.

The problem you have is that you added your log handlers to the __name__ logger, where __name__ is the current package identifier. The . separator in the package name are hierarchy separators, so if you run this in, say, acme.tests then only the loggers in acme.tests and contained modules are being sent to this handler. Any code outside of acme.tests will never reach these handlers.

Your log object hierarchy is something akin to this:

- acme
    - frobnars
    - tests
        # logger object
        - test1
        - test2
    - widgets

then only log objects in test1 and test2 will see the same handlers.

You can move your logger to the root logger instead, with logging.root or logger.getLogger() (no name argument or the name set to None). All loggers are child nodes of the root logger, and as long as they don't set the propagate attribute to False, log messages will reach the root handlers.

The other options are to get the acme logger object explicitly, with logging.getLogger('acme'), or always use a single, explicit logger name throughout your code that is the same in your tests and in your library.

Do take into account that Nose also configures handlers on the root logger.

answered Jun 15, 2018 at 12:49

Martijn Pieters

1.1m326 gold badges4.2k silver badges3.4k bronze badges

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

3 Comments

Paul D Smith Over a year ago

Perfect - thanks to everyone's help and your patience as I formulated the question correctly.

Paul D Smith Over a year ago

Done - I didn't even know there WAS an accept - so thanks for pointing this out. I should go back and take a look at my other questions when I have a few moments.

Martijn Pieters Over a year ago

@PaulDSmith: glad I took the leap then to ask! :-) Just remember, accepting is never mandatory, and entirely your choice. You can only ever mark at most one of the answers to a question as accepted.

Collectives™ on Stack Overflow

How setup Python logging in unit tests

1 Answer 1

3 Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

3 Comments

Your Answer

Sign up or log in

Post as a guest

Related