Logging Broke

[rhaarm]

I have logging in my @concurrent function and it doesn't seem to work, is it possible the logging level is not being changed for all the processes? When I do a print statement, it seems to work just fine with printing to screen. I'm using the logging module, I had the logger=logging.getLogger() as a global, then placed it into the function as well and it still doesn't work.

[alex-sherman]

If you could provide a more complete example I would really appreciate it, someone else had mentioned some issues using the logging module and I would like to see what's going on. I was actually able to get some logging working with the following:

from deco import *
import logging

logging.basicConfig()
logger = logging.getLogger()

@concurrent
def my_conc(i):
    logger.warning(i)


@synchronized
def sync():
    for i in range(10):
        my_conc(i)

if __name__ == '__main__':
    sync()

This actually does print stuff out, but I suspect your problem is more nuanced than this simple example. There are two things that I think could be going on with your program.

Logging Thread Safety vs. Process Safety
The logging module only claims that it is thread safe, not process safe. This could mean simply that some of your log lines might get interspersed, or something worse like the logging module's state becomes inconsistent.

Module Globals in Multiprocessing
When the multiprocessing module spawns new processes, module globals get recreated. The problem is that any changes that happen to the module globals in the parent process aren't necessarily reflected in the child process. At one point deco had a solution to this, but it turned out to contain some bugs and ultimately was discarded because of its complexity. I would be very interested in adding this back in if it fixes problems like these.

The easiest way to fix these is just use @concurrent.threaded instead of @concurrent so deco will use threads instead of processes. The obvious downside is if your concurrent function is compute bound, you won't see any performance increase. If it's IO bound like waiting on network resources etc, this would be a good choice.

TL;DR:
I'd be interested to see any example code you could provide, it could prove very useful.
In the near term you might consider using @concurrent.threaded instead of @concurrent to try to fix the issue with logging.

[rhaarm]

@alex-sherman

Thanks for the example, it did work for me, so I did a little playing and found that it's most likely the "Module Globals in Multiprocessing" problem. I'm passing into a script with argsparse to check for flagged options.

if __name__ == '__main__':
    import argparse

    parser = argparse.ArgumentParser()
    parser.add_argument('-v', '--verbose', dest='verbose', default=False, action='store_true')
    parser.add_argument('--debug', dest='debug', default=False, action='store_true')

    try:
        options = parser.parse_args()

        # logging setup
        if options.debug:
            logger.setLevel(logging.DEBUG)
        elif options.verbose:
            logger.setLevel(logging.INFO)
        else:
            logger.setLevel(logging.ERROR)

As you suggested using @concurrent.threaded does work with the newly set logLevel, but the issue with GIL & threads... So it looks like it'll just need to pass the logLevel along with the function call.

[rhaarm]

I just confirmed that passing the log level into the @concurrent function does work. Just have to setLevel everytime it's called.

[alex-sherman]

Thanks a lot for the code sample. I think that's pretty reasonable motivation to try and re-implement the previous functionality that supported this. I'll add an issue for doing that.