logging multithreading deadlock in python

Question

I run 10 processes with 10 threads per each, and they constantly and quite often write to 10 log file (one per process) using logging.info() & logging.debug() during 30 seconds.

Once, usually after 10 seconds, there happens a deadlock. Processes stops processing (all of them).

gdp python [pid] with py-bt & info threads shows that it stuck here:

  Id   Target Id                                 Frame 
* 1    Thread 0x7ff50f020740 (LWP 1622) "python" 0x00007ff50e8276d6 in futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, futex_word=0x564f17c8aa80)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
  2    Thread 0x7ff509636700 (LWP 1624) "python" 0x00007ff50eb57bb7 in epoll_wait (epfd=8, events=0x7ff5096351d0, maxevents=256, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
  3    Thread 0x7ff508e35700 (LWP 1625) "python" 0x00007ff50eb57bb7 in epoll_wait (epfd=12, events=0x7ff508e341d0, maxevents=256, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
  4    Thread 0x7ff503fff700 (LWP 1667) "python" 0x00007ff50e8276d6 in futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, futex_word=0x564f17c8aa80)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
...[threads 5-6 like 4]...
  7    Thread 0x7ff5027fc700 (LWP 1690) "python" 0x00007ff50eb46187 in __GI___libc_write (fd=2, buf=0x7ff50967bc24, nbytes=85) at ../sysdeps/unix/sysv/linux/write.c:27
...[threads 8-13 like 4]...

Stack of thread 7:

Traceback (most recent call first):
  File "/usr/lib/python2.7/logging/__init__.py", line 889, in emit
    stream.write(fs % msg)
...[skipped useless lines]...

And this code (I guess the code of logging __init__ function):

 884                                #the codecs module, but fail when writing to a
 885                                #terminal even when the codepage is set to cp1251.
 886                                #An extra encoding step seems to be needed.
 887                                stream.write((ufs % msg).encode(stream.encoding))
 888                        else:
>889                            stream.write(fs % msg)
 890                    except UnicodeError:
 891                        stream.write(fs % msg.encode("UTF-8"))
 892                self.flush()
 893            except (KeyboardInterrupt, SystemExit):
 894                raise

Stack of the rest threads is similar -- waiting for GIL:

Traceback (most recent call first):
  Waiting for the GIL
  File "/usr/lib/python2.7/threading.py", line 174, in acquire
    rc = self.__block.acquire(blocking)
  File "/usr/lib/python2.7/logging/__init__.py", line 715, in acquire
    self.lock.acquire()
...[skipped useless lines]...

Its written that package logging is multithreaded without additional locks. So why does package logging may deadlock? Does it open too many file descriptors or limit anything else?

That's how I initialize it (if it is important):

def get_logger(log_level, file_name='', log_name=''):
    if len(log_name) != 0:
        logger = logging.getLogger(log_name)
    else:
        logger = logging.getLogger()
    logger.setLevel(logger_state[log_level])
    formatter = logging.Formatter('%(asctime)s [%(levelname)s][%(name)s:%(funcName)s():%(lineno)s] - %(message)s')

    # file handler
    if len(file_name) != 0:
        fh = logging.FileHandler(file_name)
        fh.setLevel(logging.DEBUG)
        fh.setFormatter(formatter)
        logger.addHandler(fh)

    # console handler
    console_out = logging.StreamHandler()
    console_out.setLevel(logging.DEBUG)
    console_out.setFormatter(formatter)
    logger.addHandler(console_out)
    return logger

Arkady · Accepted Answer · 2019-02-20 07:54:00Z

1

Problem was because I've been writing output to console & to file, but all those processes were initialized with redirection to pipe, which was never listened.

            p = Popen(proc_params,
                      stdout=PIPE,
                      stderr=STDOUT,
                      close_fds=ON_POSIX,
                      bufsize=1
                      )

So it seems pipes in this case have it's buffer size limit, and after filling it deadlocks.

Here the explanation: https://docs.python.org/2/library/subprocess.html

Note

Do not use stdout=PIPE or stderr=PIPE with this function as that can deadlock based on the child process output volume. Use Popen with the communicate() method when you need pipes.

It's done for functions which I don't use, but it seems valid for Popen run, if then you don't read out the pipes.

answered Feb 20, 2019 at 7:54

Arkady

2,2473 gold badges28 silver badges49 bronze badges

Sign up to request clarification or add additional context in comments.

Collectives™ on Stack Overflow

logging multithreading deadlock in python

1 Answer 1

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

Comments

Your Answer

Sign up or log in

Post as a guest

Related