Logging in worker threads spawned from a pylons application does not seem to work

Question

I have a pylons application where, under certain cirumstances I want to spawn multiple worker threads to process items in a queue. Right now we aren't making use of a ThreadPool (would be ideal, but we'll add that in later). The main problem is that the worker threads logging does not get written to the log files.

When I run the code outside of the pylons application the logging works fine. So I think its something to do with the pylons log handler but not sure what.

Here is a basic example of the code (trimmed down):

import logging
log = logging.getLogger(__name__)

import sys
from Queue import Queue
from threading import Thread, activeCount

def run(input, worker, args = None, simulteneousWorkerLimit = None):
    queue = Queue()
    threads = []

    if args is not None:
        if len(args) > 0:
            args = list(args)
            args = [worker, queue] + args
            args = tuple(args)
        else:
            args = (worker, queue)

    # start threads
    for i in range(4):
        t = Thread(target = __thread, args = args)
        t.daemon = True
        t.start()
        threads.append(t)

    # add ThreadTermSignal
    inputData = list(input)
    inputData.extend([ThreadTermSignal] * 4)

    # put in the queue
    for data in inputData:
        queue.put(data)

    # block until all contents are downloaded
    queue.join()
    log.critical("** A log line that appears fine **")

    del queue
    for thread in threads:
        del thread
    del threads

class ThreadTermSignal(object):
    pass

def __thread(worker, queue, *args):
    try:
        while True:
            data = queue.get()
            if data is ThreadTermSignal:
                sys.exit()
            try:
                log.critical("** I don't appear when run under pylons **")
            finally:
                queue.task_done()
    except SystemExit:
        queue.task_done()
        pass

Take note, that the log lin within the RUN method will show up in the log files, but the log line within the worker method (which is run in a spawned thread), does not appear. Any help would be appreciated. Thanks

** EDIT: I should mention that I tried passing in the "log" variable to the worker thread as well as redefining a new "log" variable within the thread and neither worked.

** EDIT: Adding the configuration used for the pylons application (which comes out of the INI file). So the snippet below is from the INI file.

[loggers]
keys = root

[handlers]
keys = wsgierrors

[formatters]
keys = generic

[logger_root]
level = WARNING
handlers = wsgierrors

[handler_console]
class = StreamHandler
args = (sys.stderr,)
level = WARNING
formatter = generic

[handler_wsgierrors]
class = pylons.log.WSGIErrorsHandler
args = ()
level = WARNING
format = generic

Answer 1

You can try to pass a log variable to the thread through the arguments(args).

Answer 2

One thing to note about logging is that if an exception occurs while emitting a log event (for whatever reason) the exception is typically swallowed, and not allowed to potentially bring down an application just because of a logging error. (It depends on the handlers used and the value of logging.raiseExceptions). So there are a couple of things to check:

• That your formatting of log messages is dead simple, perhaps just using %(message)s until you find the problem.
• Check that Pylons hasn't turned logging off or messed with the handlers for whatever reason. You haven't posted your logging initialization code so I'm not sure what handlers, etc. you're using. You can print log.getEffectiveLevel() to see if logging verbosity has been turned right down (unlikely for CRITICAL, but you never know).

If you put in print statements alongside your log statements, do they produce output how you'd expect them to?

Update: I'm aware of the restriction about mod_wsgi and printing, but that only applies to sys.stdout. You can e.g.

print >> sys.stderr, some_data

or

print >> open('/tmp/somefile', 'a'), some_data

without any problem.

Also: you should be aware that a call to logging.config.fileConfig() (which is presumably how the configuration you described is implemented) disables any existing loggers unless they are explicitly named in, or are descendants of loggers explicitly named in, the configuration file. While this might seem odd, it's because a configuration is intended to replace any existing configuration rather than augment it; and since threads might be pointing to existing loggers, they're disabled rather than deleted. You can check a logger's disabled attribute to see if fileConfig() has disabled the logger - that could be your problem.