Python logger prints the same output several times in multithreaded environment

Question

In my code, somehow the logger prints out events twice, but conventional print shows correct number of events.

select 1,2
select 1,2
2013-04-19 18:37:30,618:4561354752 - SQLLogger - DEBUG - select 1,2
2013-04-19 18:37:30,618:4561354752 - SQLLogger - DEBUG - select 1,2
2013-04-19 18:37:30,618:4565561344 - SQLLogger - DEBUG - select 1,2
2013-04-19 18:37:30,618:4565561344 - SQLLogger - DEBUG - select 1,2

It is not clear to me why the same message is being published mutliple times in multithreaded situations.

import logging
from threading import Thread

class SQLEngine(object):
    def __init__(self, DB_PATH):
        ch = logging.StreamHandler()
        ch.setLevel(logging.DEBUG)
        formatter = logging.Formatter('%(asctime)s:%(thread)d - %(name)s - %(levelname)s - %(message)s')
        ch.setFormatter(formatter)
        self.logger = logging.getLogger('SQLLogger')
        self.logger.setLevel(logging.DEBUG)
        self.logger.addHandler(ch)

    def execute(self,SQL,):
            self.logger.debug(SQL)
            print SQL

class DBWorker(Thread):
    def __init__(self, name):
        Thread.__init__(self)
        self.name = name

    def run(self):
        db = SQLEngine('')
        db.execute('select 1,2')

if __name__ == '__main__':
    DBWorker('thread 1').start()
    DBWorker('thread 2').start()

score 6 · Accepted Answer · answered Apr 19 '13 at 23:06

Looking at the logger documentation:

Loggers are never instantiated directly, but always through the module-level function logging.getLogger(name). Multiple calls to getLogger() with the same name will always return a reference to the same Logger object.

Now your constructor is calling the following code:

ch = logging.StreamHandler()
self.logger = logging.getLogger('SQLLogger')
self.logger.addHandler(ch)

Note you don't create a new logger for every SQLEngine object, but always get a reference to the same logger instance. It means you're always adding handler to one and the same logger, hence after creating the second object your logger has two handlers, each of them printing to the screen.

You we'll need either register only one handler (for example outside of the SQLEngine constructor) or call getLogger in the __init__ with a different name for every SQLEngine instance.

score 1 · Answer 2 · answered Apr 19 '13 at 23:09

You have started two threads and each has its own SQLEngine attribute object that gets executed when the respective threads are run. If you want to share the logger among multiple threads, then it would be a better option to create a single logger object that you could pass around. GIL would take care of the rest.

import logging
from threading import Thread

class SQLEngine(object):
    def __init__(self, DB_PATH):
        ch = logging.StreamHandler()
        ch.setLevel(logging.DEBUG)
        formatter = logging.Formatter('%(asctime)s:%(thread)d - %(name)s - %(levelname)s - %(message)s')
        ch.setFormatter(formatter)
        self.logger = logging.getLogger('SQLLogger')
        self.logger.setLevel(logging.DEBUG)
        self.logger.addHandler(ch) 

    def execute(self,SQL,): 
        self.logger.debug(SQL)
        print (SQL)

class DBWorker(Thread):
    def __init__(self, name, logengine):
        Thread.__init__(self)
        self.name = name
        self.logger = logengine

    def run(self):
        #db = SQLEngine('')
        self.logger.execute('select 1,2')

if __name__ == '__main__':
    logger = SQLEngine('')
    DBWorker('thread 1', logger).start()
    DBWorker('thread 2', logger).start()

This is just one example. As @tomasz mentioned, you can handle this logger object depending on your requirements

Python logger prints the same output several times in multithreaded environment

2 Answers2