Python LoggerAdapter is making duplicate log entries to STDOUT

Question

I'm trying to add contextual information to the logging output of my python script. Essentially, I'm using the SocketServer class to handle incoming network connections, and when a client sends a message to the server I want to make a log entry to STDOUT and a file with the time, log level, ip of the client and the message received.

I've tried implementing this using filters (which I couldn't get working, but I'm open to suggestions) and a LoggerAdapter: http://pastebin.com/peT0rjA7

class ConnInfo:
    def __getitem__(self, name):
        if name == "ip":
            result = tlocal.ip
        if name == "cmd":
            result = tlocal.msg
        return result
    def __iter__(self):
        keys = ['ip', 'cmd']
        keys.extend(self.__dict__.keys())
        return keys.__iter__()

logging.basicConfig(level=logging.DEBUG,
                    format="%(asctime)s %(name)-12s %(levelname)-8s %(message)s",
                    datefmt="%d-%m %H:%M:%S",
                    filename="distpovadmin.log",
                    filemode="w")
console = logging.StreamHandler()
console.setLevel(logging.INFO)
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
nodeCommsConFormatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(ip)-4s %(cmd)-8s %(message)s')
console.setFormatter(formatter)

#nodeCommsConLogging = logging.LoggerAdapter(logging.getLogger('NodeCommsConnection').addHandler(console.setFormatter(nodeCommsConFormatter())), ConnInfo())
CommsConConsole = logging.StreamHandler()
CommsConConsole.setLevel(logging.INFO)
CommsConConsole.setFormatter(nodeCommsConFormatter)
nodeCommsConLogging = logging.LoggerAdapter(logging.getLogger('NodeCommsConnection'), ConnInfo())
logging.getLogger('NodeCommsConnection').removeHandler(console)
logging.getLogger('NodeCommsConnection').addHandler(CommsConConsole)

logging.getLogger('').addHandler(console)

When I make a call to nodeCommsConLogging like this:

nodeCommsConLogging.info("Message Received")

I get duplicate entries in the STDOUT log

NodeCommsConnection: INFO     192.168.1.8 REQ;     Message Received
NodeCommsConnection: INFO     Message Received

Thanks in advance for any help and suggestions!

EDIT: Added code example

Answer 1

Loggers are hierarchical. So you have a root logger (named '', i.e. blank). Every other logger is a child of the root logger - eventually.

In your case, you have this hierarchy:

 root
   +-- NodeCommsConnection

If you log something on the child, it will try to handle it and then pass the log message to the parent logger unless you set propagate to False.

Since you add an appender to NodeCommsConnection, it will log its messages using this appender and then call root which will log using its appender -> two outputs on the console.

So either add your appender to the root logger (and remove the default console logger) or set propagate to False:

logging.getLogger('NodeCommsConnection').propagate = False