python - logging module - handlers.SysLogHandler - sending multiple lines instead of one

Question

I am having problems with the python logging module. This is using python 2.7 on a Solaris server and a MAC OSX desktop. I can recreate the issue on both computers, something is possibly up with how the syslog server is processing information or i have a bug in my code (what I am thinking).

When I send a message to a remote syslog server it seems to be sending the message multiple times, its easier to show the issue below:

A Python function I am using:

def log_something_to_syslog(thing_to_log):
    logger = logging.getLogger()
    logger.setLevel(logging.INFO)
    handler = logging.handlers.SysLogHandler(address=('MYSERVER', 514), socktype=socket.SOCK_DGRAM)
    formatter = logging.Formatter('Test_debug_python: %(message)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    logging.info(str(thing_to_log))

I called the function 4 times, here are the function calls:

>>> log_something_to_syslog("Hello World Test 1")
>>> log_something_to_syslog("Hello World Test 2")
>>> log_something_to_syslog("Hello World Test 3")
>>> log_something_to_syslog("Hello World Test 4")

Here is my output from the syslog server:

2015-06-09T14:24:50-04:00 10.134.122.71 Test_debug_python: Hello World Test 1
2015-06-09T14:25:06-04:00 10.134.122.71 Test_debug_python: Hello World Test 2
2015-06-09T14:25:06-04:00 10.134.122.71 Test_debug_python: Hello World Test 2
2015-06-09T14:25:16-04:00 10.134.122.71 Test_debug_python: Hello World Test 3
2015-06-09T14:25:16-04:00 10.134.122.71 Test_debug_python: Hello World Test 3
2015-06-09T14:25:16-04:00 10.134.122.71 Test_debug_python: Hello World Test 3
2015-06-09T14:25:18-04:00 10.134.122.71 Test_debug_python: Hello World Test 4
2015-06-09T14:25:18-04:00 10.134.122.71 Test_debug_python: Hello World Test 4
2015-06-09T14:25:18-04:00 10.134.122.71 Test_debug_python: Hello World Test 4
2015-06-09T14:25:18-04:00 10.134.122.71 Test_debug_python: Hello World Test 4

as you can see the first test shows once, the second two times, the third three times, and the fouth four times.

I'm puzzled as to what is happening ?

Answer 1

When you call logger = logging.getLogger() you get a reference to the same logger object stored somewhere in the logging module (id(logger) will be the same every time). Calling the log_something_to_syslog() adds a new handler (that does its job independently of all the other attached handlers) to the same logger. You are only supposed to set handlers once in the init phase of your program. So you should split this function.

From the docs: https://docs.python.org/2/library/logging.html#logging.getLogger

logging.getLogger([name])

All calls to this function with a given name return the same logger instance. This means that logger instances never need to be passed between different parts of an application.