logging module and threading

[Ross Boylan]

I would like my different threads to log without stepping on each
other.

Past advice on this list (that I've found) mostly says to send the
messages to a Queue. That would work, but bypasses the logging
module's facilities.

The logging module itself is "thread-safe", but I think that just
means that individual output is protected. If I have, in temporarly
sequence:
thread 1: warning("A")
thread 2: info("something")
thread 1: warning("B")
then I think I'll get them output in this order. It's thread-safe in
that the log will not end up with an entry like
A
some
B
thing
(I think). But I want to get, for example,
A
B
something

What I would like is for each thread to emit a chunk of log messages
when it finishes a unit of work.

It looks as if I might be able to use a MemoryHandler to accumulate
the log locally and then flush it into the main log (I'd like to send
it to the main logger, but it looks as if I must send it to a specific
handler). Would something like the following work?

class MyThread (threading.Thread):
def __init__(self):
# do I need the next line?
threading.Thread.__init__(self)
self._log = logging.getLogger(self.getName())
# flush into main log
self._log = logging.MemoryHandler(9999999,
, # default flushlevel
logging.getLogger().handlers[1] )

def run(self):
j = getjob()
while j:
# do stuff
# log like this
self._log.info("some message")
# when done
self._log.flush()
j = getjob()


I'm also puzzled by how the logger hierarchy works. The docs say that
everything that is logged by the kids is also logged by the parent.
That would seem to defeat what I'm trying to do above, since the
parent would get each logged event right away. However,
logging.getLogger("a").error("test")
produces only a single log message indicating an associated object of "a".
The docs lead me to expect that I'd see one message from "a" and
another from root.

When I add handlers (e.g., FileHandlers) I do get the message recorded
by each.

Can anyone explain what's going on?

Thanks.
Ross Boylan

 

[Vinay Sajip]

I'm also puzzled by how the logger hierarchy works. The docs say that
everything that is logged by the kids is also logged by the parent.
That would seem to defeat what I'm trying to do above, since the
parent would get each logged event right away. However,logging.getLogger("a").error("test")
produces only a single log message indicating an associated object of "a".
The docs lead me to expect that I'd see one message from "a" and
another from root.

When I add handlers (e.g., FileHandlers) I do get the message recorded
by each.

Can anyone explain what's going on?

The Logger hierarchy works, in a nutshell, as follows: events passed
to a logger propagate up the hierarchy until either the root, or a
logger whose propagate attribute is set to a false value, is reached.
At each step (i.e. logger) in the propagation, any handlers attached
to that logger are offered the chance to handle the message - which
means different things depending on the handler. If you add e.g. a
FileHandler to the root logger and another to a logger named "a.b.c"
and then log something to "a.b.c", then two handlers will each handle
the message, leading to multiple output of the same event. You also
don't need to buffer up messages in different threads - if your
messages contain both the log event time and the thread id (which can
be achieved by having %(asctime)s or %(relativeCreated)d and %
(thread)d or %(threadName)s in your format string), then you can
simply sort the output to group your messages together. (And since
threads sometimes interact, it's often useful to see the raw output in
time order.) If you do want to buffer events, MemoryHandler will do
the trick. And it takes a target handler rather than logger, because
it's acting as a buffer for another handler, for events which have
already been entered into the system.

If you're new to logging, you need to separate the ideas behind
loggers and handlers in the scheme of things. Loggers are things which
application developers use to register events of interest in their
application, with an indication of importance (level) and an ability
to filter on that. Handlers are things used by developers or admins to
send information about the events to different audiences - e.g.
critical errors might be emailed to someone while less critical errors
are sent to console or log files.

Best regards,

Vinay Sajip

 

[James T. Dennis]

I would like my different threads to log without stepping on each
other.

Past advice on this list (that I've found) mostly says to send the
messages to a Queue. That would work, but bypasses the logging
module's facilities.

The logging module itself is "thread-safe", but I think that just
means that individual output is protected. If I have, in temporarly
sequence:
thread 1: warning("A")
thread 2: info("something")
thread 1: warning("B")
then I think I'll get them output in this order. It's thread-safe in
that the log will not end up with an entry like
A
some
B
thing
(I think). But I want to get, for example,
A
B
something

What I would like is for each thread to emit a chunk of log messages
when it finishes a unit of work.

This sounds like a job for the Queue class/module to me.
Could you create a Queue such that all your worker threads
are producers to it and you have one dedicated thread as a
consumer that relays log entries from the Queue into your loggers?

 

[Vinay Sajip]

This sounds like a job for the Queue class/module to me.
Could you create a Queue such that all your worker threads
are producers to it and you have one dedicated thread as a
consumer that relays log entries from the Queue into your loggers?

Or, use a SocketHandler to serialize the events over a socket, and de-
mux them on the receiving end. The docs have an example:

http://docs.python.org/lib/network-logging.html

Regards,

Vinay Sajip