Joblib: New backend fails if logger set up with additional handlers

Created on 20 Feb 2018  路  5Comments  路  Source: joblib/joblib

Consider this code:

import logging
import time
import sys

# from sklearn.externals.joblib import Parallel, delayed
from joblib import Parallel, delayed

logger = logging.getLogger()
formatter = logging.Formatter(
    '%(asctime)s %(levelname)s: %(message)s '
    '[in %(pathname)s:%(lineno)d]')
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(formatter)
logger.addHandler(handler)


def func(i):
    logger.warning(f"Function calling {i}")
    time.sleep(0.5)


with Parallel(n_jobs=4) as parallel:
    parallel(delayed(func)(i) for i in range(10))

When running with the sklearn version of joblib it produces the following output:

2018-02-20 16:30:50,960 WARNING: Function calling 0 [in log_test.py:18]
2018-02-20 16:30:50,963 WARNING: Function calling 1 [in log_test.py:18]
2018-02-20 16:30:50,963 WARNING: Function calling 2 [in log_test.py:18]
2018-02-20 16:30:50,965 WARNING: Function calling 3 [in log_test.py:18]
2018-02-20 16:30:51,461 WARNING: Function calling 4 [in log_test.py:18]
2018-02-20 16:30:51,464 WARNING: Function calling 5 [in log_test.py:18]
2018-02-20 16:30:51,464 WARNING: Function calling 6 [in log_test.py:18]
2018-02-20 16:30:51,466 WARNING: Function calling 7 [in log_test.py:18]
2018-02-20 16:30:51,962 WARNING: Function calling 8 [in log_test.py:18]
2018-02-20 16:30:51,965 WARNING: Function calling 9 [in log_test.py:18]

If running it on the current git head, it fails:

joblib.externals.loky.process_executor._RemoteTraceback: 
"""
Traceback (most recent call last):
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/loky/backend/queues.py", line 150, in _feed
    obj, reducers=reducers)
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/loky/backend/reduction.py", line 145, in dumps
    p.dump(obj)
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/parallel.py", line 140, in __getstate__
    for func, args, kwargs in self.items]
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/parallel.py", line 140, in <listcomp>
    for func, args, kwargs in self.items]
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/cloudpickle/cloudpickle.py", line 881, in dumps
    cp.dump(obj)
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/cloudpickle/cloudpickle.py", line 268, in dump
    return Pickler.dump(self, obj)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 409, in dump
    self.save(obj)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/cloudpickle/cloudpickle.py", line 405, in save_function
    self.save_function_tuple(obj)
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/cloudpickle/cloudpickle.py", line 553, in save_function_tuple
    save(state)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 821, in save_dict
    self._batch_setitems(obj.items())
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 847, in _batch_setitems
    save(v)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 821, in save_dict
    self._batch_setitems(obj.items())
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 847, in _batch_setitems
    save(v)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 521, in save
    self.save_reduce(obj=obj, *rv)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 634, in save_reduce
    save(state)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 821, in save_dict
    self._batch_setitems(obj.items())
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 847, in _batch_setitems
    save(v)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 781, in save_list
    self._batch_appends(obj)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 808, in _batch_appends
    save(tmp[0])
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 521, in save
    self.save_reduce(obj=obj, *rv)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 634, in save_reduce
    save(state)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 821, in save_dict
    self._batch_setitems(obj.items())
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 847, in _batch_setitems
    save(v)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 496, in save
    rv = reduce(self.proto)
TypeError: can't pickle _thread.RLock objects
"""

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "log_test.py", line 24, in <module>
    parallel(delayed(func)(i) for i in range(10))
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/parallel.py", line 813, in __call__
    self.retrieve()
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/parallel.py", line 714, in retrieve
    self._output.extend(job.get(timeout=self.timeout))
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/_parallel_backends.py", line 468, in wrap_future_result
    return future.result(timeout=timeout)
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/loky/_base.py", line 424, in result
    return self.__get_result()
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/loky/_base.py", line 382, in __get_result
    raise self._exception
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/loky/backend/queues.py", line 150, in _feed
    obj, reducers=reducers)
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/loky/backend/reduction.py", line 145, in dumps
    p.dump(obj)
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/parallel.py", line 140, in __getstate__
    for func, args, kwargs in self.items]
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/parallel.py", line 140, in <listcomp>
    for func, args, kwargs in self.items]
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/cloudpickle/cloudpickle.py", line 881, in dumps
    cp.dump(obj)
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/cloudpickle/cloudpickle.py", line 268, in dump
    return Pickler.dump(self, obj)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 409, in dump
    self.save(obj)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/cloudpickle/cloudpickle.py", line 405, in save_function
    self.save_function_tuple(obj)
  File "/home/javier/anaconda3/lib/python3.6/site-packages/joblib/externals/cloudpickle/cloudpickle.py", line 553, in save_function_tuple
    save(state)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 821, in save_dict
    self._batch_setitems(obj.items())
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 847, in _batch_setitems
    save(v)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 821, in save_dict
    self._batch_setitems(obj.items())
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 847, in _batch_setitems
    save(v)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 521, in save
    self.save_reduce(obj=obj, *rv)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 634, in save_reduce
    save(state)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 821, in save_dict
    self._batch_setitems(obj.items())
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 847, in _batch_setitems
    save(v)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 781, in save_list
    self._batch_appends(obj)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 808, in _batch_appends
    save(tmp[0])
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 521, in save
    self.save_reduce(obj=obj, *rv)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 634, in save_reduce
    save(state)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 476, in save
    f(self, obj) # Call unbound method with explicit self
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 821, in save_dict
    self._batch_setitems(obj.items())
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 847, in _batch_setitems
    save(v)
  File "/home/javier/anaconda3/lib/python3.6/pickle.py", line 496, in save
    rv = reduce(self.proto)
TypeError: can't pickle _thread.RLock objects

The error originates from the assignment of a handler to the logger (code works if the handler is removed, obviously without the fancy formatting). This was the cause of the second error mentioned in https://github.com/joblib/joblib/issues/629#issuecomment-364158151

bug help wanted
Source
picture jlopezpena
👍1

Most helpful comment

As a work-around, your best bet is to define the logger in a helper function:

import logging
import time
import sys

# from sklearn.externals.joblib import Parallel, delayed
from joblib import Parallel, delayed

def get_logger():
    logger = logging.getLogger()
    formatter = logging.Formatter(
        '%(asctime)s %(levelname)s: %(message)s '
        '[in %(pathname)s:%(lineno)d]')
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    return logger


def func(i):
    logger = get_logger()
    logger.warning(f"Function calling {i}")
    time.sleep(0.5)


with Parallel(n_jobs=4) as parallel:
    parallel(delayed(func)(i) for i in range(10))

More details: another work-around is to give a name to the logger. cloudpickle seems to have a bug when pickling the root logger that it does not have when pickling other loggers. In this case though, the formatter is lost with the loky backend, so the get_logger function is probably the best thing to do.

picture lesteve on 21 Feb 2018
👍5

All 5 comments

Thanks for the stand-alone snippet reproducing the problem. I can reproduce indeed. Note that the same thing happens with backend='multiprocessing' so this is not backend-specific.

lesteve picture lesteve on 21 Feb 2018

Sorry, I meant pickling backend; in the dev version the old pickler got replaced by cloudpickle, didn't it?

jlopezpena picture jlopezpena on 21 Feb 2018

As a work-around, your best bet is to define the logger in a helper function:

import logging
import time
import sys

# from sklearn.externals.joblib import Parallel, delayed
from joblib import Parallel, delayed

def get_logger():
    logger = logging.getLogger()
    formatter = logging.Formatter(
        '%(asctime)s %(levelname)s: %(message)s '
        '[in %(pathname)s:%(lineno)d]')
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    return logger


def func(i):
    logger = get_logger()
    logger.warning(f"Function calling {i}")
    time.sleep(0.5)


with Parallel(n_jobs=4) as parallel:
    parallel(delayed(func)(i) for i in range(10))

More details: another work-around is to give a name to the logger. cloudpickle seems to have a bug when pickling the root logger that it does not have when pickling other loggers. In this case though, the formatter is lost with the loky backend, so the get_logger function is probably the best thing to do.

lesteve picture lesteve on 21 Feb 2018
👍5

FWIW I opened https://github.com/cloudpipe/cloudpickle/pull/160 about the root logger cloudpickle bug.

lesteve picture lesteve on 21 Feb 2018

Following from https://github.com/joblib/joblib/issues/634#issuecomment-367321025, I was still unable to get a StreamHandler working when using loky in a Jupyter notebook, but when naming the logger as suggested, as well as setting the level to the logger, the following works for writing a log file.

import logging
import time

from joblib import Parallel, delayed

def get_logger(name=None, userlevel=logging.DEBUG, fh_kwargs=dict(filename='parallel-logging.log')):
    logger = logging.getLogger(name)
    formatter = logging.Formatter(
        '%(asctime)s %(levelname)s: %(message)s '
        '[in %(pathname)s:%(lineno)d]')
    handler = logging.FileHandler(**fh_kwargs)
    handler.setLevel(userlevel)
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    logger.setLevel(userlevel)
    return logger   

def func(i):
    logger = get_logger(f'{i}_log')
    logger.warning(f"Function calling {i}")
    time.sleep(0.5)

with Parallel(n_jobs=4) as parallel:
    parallel(delayed(func)(i) for i in range(10))
tommct picture tommct on 18 Sep 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

pierreglaser picture pierreglaser  路  4Comments
EPinzuti picture EPinzuti  路  8Comments
aseyboldt picture aseyboldt  路  3Comments
mivade picture mivade  路  9Comments
Alessi0X picture Alessi0X  路  10Comments