Why do I get duplicated logging messages?

Question

I have a script which imports a logging module (based on logging) and another module (which in turn imports the same logging module as the main one -- to have consistent logging accorss the scripts and modules).

Everything works fine except that I get duplicated messages. Below are the scripts stripped down to the problematic part:

The main script. It sets a logging handler, used in a method of his

# the main script
# it is the one started

import dslogger
import mytestmodule

class MyClass():
    def __init__(self):
        self.log = dslogger.DSLogger().rootLogger

    def dosomething(self):
        self.log.debug("hello from dosomething")

mytestmodule.MyTestModule()
MyClass().dosomething()

The mytestmodule. Here stripped down to __init__:

# mytestmodule.py

import dslogger

class MyTestModule():
    def __init__(self):
        self.log = dslogger.DSLogger().rootLogger
        self.log.debug("hello from mytestmodule")

dslogger.py, the logging module:

import logging

class DSLogger():
    def __init__(self):
        logFormatter = logging.Formatter("%(asctime)s [%(funcName)s] [%(levelname)s]  %(message)s")
        self.rootLogger = logging.getLogger(__name__)
        consoleHandler = logging.StreamHandler()
        consoleHandler.setFormatter(logFormatter)
        self.rootLogger.setLevel(logging.DEBUG)
        self.rootLogger.addHandler(consoleHandler)

When running the main script I get:

2014-11-04 08:56:59,637 [__init__] [DEBUG]  hello from mytestmodule
2014-11-04 08:56:59,637 [dosomething] [DEBUG]  hello from dosomething
2014-11-04 08:56:59,637 [dosomething] [DEBUG]  hello from dosomething

The second and third line are duplicated, even though they are generated by the dosomething() method which is called only once, from the main script. Why is it so?

with this `dslogger.DSLogger().rootLogger` you are creating a new instance each time, why are you not using `logging.getLogger("DSLogger")` in each class for example? — badc0re, Nov 04 '14 at 08:20

score 1 · Accepted Answer · answered Nov 04 '14 at 08:23

1

What's happening here is that you're adding two StreamHandlers to the same logger.

You initialize DSLogger() twice. Each time you initialize it, you call self.rootLogger = logging.getLogger(__name__). But this does not get you two different logger instances, since they are called with same __name__:

import logging
x = logging.getLogger('x')
id(x)
Out[42]: 173704528L

y = logging.getLogger('x')
id(y)
Out[44]: 173704528L

So when you call self.log.debug("hello from mytestmodule"), this is after DSLogger() was initalized once, and thus only one StreamHandler was added to that logger. But when you initialize MyClass, another one is added, and thus the logger now has two StreamHandlers, and every log message is printed twice.

answered Nov 04 '14 at 08:23

Korem

11,383
7
55
72

Thank you, it is now clear. I thought that when you instantiate objects, they are always independent. I will rewrite `DSLogger`to accept in `__init__` a parameter, which I will pass upon initiating the logging in the main script and the modules (I will pass `__name__`) – WoJ Nov 04 '14 at 08:37
@WoJ Note that you're not instantiating self.rootLogger. you're calling a 'get' function. – Korem Nov 04 '14 at 08:42
Ahhhhh right! Now I really understand. I will have to think harder on the consequences of using the `get` call as I do it now (with the modifications from my comment above) vs. actually instantiating a logger object via `log = dslogger.DSLogger()` and adding `return rootLogger` to `__init__` in `DSLogger()` – WoJ Nov 04 '14 at 08:48

Why do I get duplicated logging messages?

1 Answers1

Linked