Joblib: Standard logging using `loky` backend

[mlisovyi]

I fail to use logging in parallel processing using loky backend.

Example code trying out 3 different backends:

import logging
import time

from joblib import Parallel, delayed

logger = logging.getLogger("mylogger")
logger.setLevel(logging.INFO)
sh = logging.StreamHandler()
sh.setFormatter(logging.Formatter("%(asctime)s %(levelname)-8s %(message)s"))
fh = logging.FileHandler('out.log', mode='w')
fh.setFormatter(logging.Formatter("%(asctime)s %(levelname)-8s %(message)s"))
logger.addHandler(sh)
logger.addHandler(fh)

def func(i, t):
    logger.info(f"Call {i} using {t} parallelisation")
    time.sleep(0.2)

for t in ["threading", "multiprocessing", "loky"]:
    with Parallel(n_jobs=2, backend=t) as parallel:
        parallel(delayed(func)(i,t) for i in range(4))

The output in std and in the log file is

2020-02-27 10:41:49,304 INFO     Call 0 using threading parallelisation
2020-02-27 10:41:49,304 INFO     Call 1 using threading parallelisation
2020-02-27 10:41:49,505 INFO     Call 2 using threading parallelisation
2020-02-27 10:41:49,505 INFO     Call 3 using threading parallelisation
2020-02-27 10:41:49,817 INFO     Call 0 using multiprocessing parallelisation
2020-02-27 10:41:49,818 INFO     Call 1 using multiprocessing parallelisation
2020-02-27 10:41:50,019 INFO     Call 2 using multiprocessing parallelisation
2020-02-27 10:41:50,019 INFO     Call 3 using multiprocessing parallelisation

I have found this workaround: https://github.com/joblib/joblib/issues/634#issuecomment-367321025, but it doesn't seem to work well in the case of a file handler to dump logs on disk.

I'm using joblib v0.14.1

[Phylliade]

:+1: ;
I seem to also have the same issue

[tomMoral]

The issue is that the logger is not automatically propagated to the child workers. This would be quite hard to do as this requires sending the module global state and we are discussing how to do this for joblib but it is not easy (see #1071).

Another way to do this proprely for loky would be to have a worker initializer but it is not exposed in the joblib API. A potential workaround would be:

import logging
import time

from joblib import Parallel, delayed


def start_logger_if_necessary():
    logger = logging.getLogger("mylogger")
    if len(logger.handlers) == 0:
        logger.setLevel(logging.INFO)
        sh = logging.StreamHandler()
        sh.setFormatter(logging.Formatter("%(asctime)s %(levelname)-8s %(message)s"))
        fh = logging.FileHandler('out.log', mode='w')
        fh.setFormatter(logging.Formatter("%(asctime)s %(levelname)-8s %(message)s"))
        logger.addHandler(sh)
        logger.addHandler(fh)
    return logger

def func(i, t):
    logger = start_logger_if_necessary()
    logger.info(f"Call {i} using {t} parallelisation")
    time.sleep(0.2)

start_logger_if_necessary()
for t in ["threading", "multiprocessing", "loky"]:
    with Parallel(n_jobs=2, backend=t) as parallel:
        parallel(delayed(func)(i,t) for i in range(4))

This gives the right results but I don't know if this is satisfactory for your application.

[jpmaterial]

@tomMoral I'd also be interested in why this works.