Python logging over multiple files

Question

I've read through the logging module documentation and whilst I may have missed something obvious, the code I've got doesn't appear to be working as intended. I'm using Python 2.6.4.

My program consists of several different python files, from which I want to send logging messages to a text file and, potentially, the screen. I imagine this is a common thing to do so I'm messing this up somewhere.

What my code is doing at the minute is logging to the text file correctly, kinda. But logging to the screen is being duplicated, one with the specified formatting, and one without. Also, when I turn off the screen output, I'm still getting the text printed once, which I don't want - I just want it to be logged to the file.

Anyway, some code:

#logger.py
import logging
from logging.handlers import RotatingFileHandler
import os

def setup_logging(logdir=None, scrnlog=True, txtlog=True, loglevel=logging.DEBUG):        
    logdir = os.path.abspath(logdir)

    if not os.path.exists(logdir):
        os.mkdir(logdir)

    log = logging.getLogger('stumbler')
    log.setLevel(loglevel)

    log_formatter = logging.Formatter("%(asctime)s - %(levelname)s :: %(message)s")

    if txtlog:
        txt_handler = RotatingFileHandler(os.path.join(logdir, "Stumbler.log"), backupCount=5)
        txt_handler.doRollover()
        txt_handler.setFormatter(log_formatter)
        log.addHandler(txt_handler)
        log.info("Logger initialised.")

    if scrnlog:
        console_handler = logging.StreamHandler()
        console_handler.setFormatter(log_formatter)
        log.addHandler(console_handler)

Nothing unusual there.

#core.py
import logging
corelog = logging.getLogger('stumbler.core')  # From what I understand of the docs, this should work :/

class Stumbler:
    [...]

    corelog.debug("Messages and rainbows...")

The screen output shows how this is being duplicated:

2010-01-08 22:57:07,587 - DEBUG :: SCANZIP: Checking zip contents, file: testscandir/testdir1/music.mp3
DEBUG:stumbler.core:SCANZIP: Checking zip contents, file: testscandir/testdir1/music.mp3
2010-01-08 22:57:07,587 - DEBUG :: SCANZIP: Checking zip contents, file: testscandir/testdir2/subdir/executable.exe
DEBUG:stumbler.core:SCANZIP: Checking zip contents, file: testscandir/testdir2/subdir/executable.exe

Although the textfile is getting the correctly formatted output, turning the screen logging off in logger.py still has the incorrectly formatted output displayed.

From what I understand of the docs, calling corelog.debug(), seeing as corelog is a child of the "stumbler" logger, it should use that formatting and output the logs as such.

Apologies for the essay over such a trivial issue.

TL;DR: How do I do logging from multiple files?

Answer 1

Are you sure no other logging setup is being done in anything you import.

The incorrect output in your console logs look like the default configuration for a logger, so something else may be setting that up.

Running this quick test script:

import logging
from logging.handlers import RotatingFileHandler
import os

def setup_logging(logdir=None, scrnlog=True, txtlog=True, loglevel=logging.DEBUG):
    logdir = os.path.abspath(logdir)

    if not os.path.exists(logdir):
        os.mkdir(logdir)

    log = logging.getLogger('stumbler')
    log.setLevel(loglevel)

    log_formatter = logging.Formatter("%(asctime)s - %(levelname)s :: %(message)s")

    if txtlog:
        txt_handler = RotatingFileHandler(os.path.join(logdir, "Stumbler.log"), backupCount=5)
        txt_handler.doRollover()
        txt_handler.setFormatter(log_formatter)
        log.addHandler(txt_handler)
        log.info("Logger initialised.")

    if scrnlog:
        console_handler = logging.StreamHandler()
        console_handler.setFormatter(log_formatter)
        log.addHandler(console_handler)



setup_logging('/tmp/logs')
corelog = logging.getLogger('stumbler.core')
corelog.debug("Messages and rainbows...")

yields this result:

2010-01-08 15:39:25,335 - DEBUG :: Messages and rainbows...

and in my /tmp/logs/Stumbler.log

2010-01-08 15:39:25,335 - INFO :: Logger initialised. 2010-01-08 15:39:25,335 - DEBUG :: Messages and rainbows...

This worked as expected when I ran it in python 2.4, 2.5, and 2.6.4