Locks in the standard library should be sanitized on fork

@rhettinger

BPO	6721
Nosy	@rhettinger, @gpshead, @vsajip, @jcea, @nirs, @pitrou, @vstinner, @applio, @cagney, @Birne94, @ochedru, @kevans91, @jessefarnham, @rojer, @koubaa
PRs	bpo-6721: Sanitize logging locks while forking #4071 [3.7] bpo-6721: Hold logging locks across fork() (GH-4071) #9291 bpo-1635741 port _curses_panel to multi-phase init (PEP 489) #21986 Update all Python Cookbook links after migration to GitHub #22205 bpo-40423: Optimization: use close_range(2) if available #22651
Files	lock_fork_thread_deadlock_demo.py forklocktests.patch reinit_locks.diff: patch adding locks reinitialization upon fork emit_warning_on_fork.patch atfork.patch reinit_locks_2.diff

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2009-08-17.23:06:17.321>
labels = ['3.7', 'type-feature', 'library']
title = 'Locks in the standard library should be sanitized on fork'
updated_at = <Date 2020-10-11.20:42:06.563>
user = 'https://github.com/gpshead'

bugs.python.org fields:

activity = <Date 2020-10-11.20:42:06.563>
actor = 'kevans'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2009-08-17.23:06:17.321>
creator = 'gregory.p.smith'
dependencies = []
files = ['14740', '21874', '22005', '22525', '24303', '25776']
hgrepos = []
issue_num = 6721
keywords = ['patch']
message_count = 133.0
messages = ['91674', '91936', '92766', '94102', '94115', '94133', '94135', '128282', '128307', '128311', '128316', '128369', '135012', '135067', '135069', '135079', '135083', '135095', '135096', '135143', '135157', '135173', '135543', '135857', '135866', '135897', '135899', '135948', '135965', '135984', '136003', '136039', '136045', '136047', '136120', '136147', '139084', '139245', '139470', '139474', '139480', '139485', '139488', '139489', '139509', '139511', '139521', '139522', '139584', '139599', '139608', '139800', '139808', '139850', '139852', '139858', '139869', '139897', '139929', '140215', '140402', '140550', '140658', '140659', '140668', '140689', '140690', '140691', '141286', '143174', '143274', '143279', '151168', '151266', '151267', '151845', '151846', '151853', '161019', '161029', '161389', '161405', '161470', '161953', '162019', '162031', '162034', '162036', '162038', '162039', '162040', '162041', '162053', '162054', '162063', '162113', '162114', '162115', '162117', '162120', '162137', '162160', '270015', '270017', '270018', '270019', '270020', '270021', '270022', '270023', '270028', '289716', '294726', '294834', '304714', '304716', '304722', '304723', '314983', '325326', '327267', '329474', '339369', '339371', '339393', '339418', '339454', '339458', '339473', '365169', '367528', '367702', '368882']
nosy_count = 29.0
nosy_names = ['rhettinger', 'gregory.p.smith', 'vinay.sajip', 'jcea', 'nirs', 'pitrou', 'vstinner', 'nirai', 'forest_atq', 'ionelmc', 'bobbyi', 'neologix', 'Giovanni.Bajo', 'sdaoden', 'tshepang', 'sbt', 'lesha', 'dan.oreilly', 'davin', 'Connor.Wolf', 'Winterflower', 'cagney', 'Birne94', 'ochedru', 'kevans', 'jesse.farnham', 'hugh', 'rojer', 'koubaa']
pr_nums = ['4071', '9291', '21986', '22205', '22651']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue6721'
versions = ['Python 3.7']

The python logging module uses a lock to surround many operations, in
particular. This causes deadlocks in programs that use logging, fork
and threading simultaneously.

spawn one or more threads in your program
have at least one of those threads make logging calls that will be
emitted.
have your main thread or another thread use os.fork() to run some
python code in a child process.
If the fork happened while one of your threads was within the
logging.Handler.handle() critical section (or anywhere else where
handler.lock is acquired), your child process will deadlock as soon as
it tries to log anything. It inherited a held lock.

The deadlock is more likely to happen on a highly loaded system which
tends to widen the deadlock opportunity window due to context switching.

A demo of the problem simplified into one file is attached.

The Python standard library should not be the cause of these deadlocks.
We need a way for all standard library locks to be cleaned up when
forking. By doing one of the following:

A) acquire all locks before forking, release them immediately after.
B) forceably release all standard library locks after forking in the
child process.

Code was added to call some cleanups after forking in
http://bugs.python.org/issue874900 but there are more things that also
need this same sort of cleanup (logging for example).

Rather than having to manually add after fork code hooks into every file
in the standard library that uses locks, a more general solution to
track and manage locks across fork would be a good idea.

I've started a project to patch this and similar messes up for Python
2.4 and later here:

http://code.google.com/p/python-atfork/

I'd like to take ideas or implementations from that when possible for
future use in the python standard library.

bpo-6923 has been opened to provide a C API for an atfork mechanism for
use by extension modules.

Rather than having a kind of global module registry, locks could keep
track of what was the last PID, and reinitialize themselves if it changed.
This is assuming getpid() is fast :-)

Antoine Pitrou <pitrou@free.fr> added the comment:

Rather than having a kind of global module registry, locks could keep
track of what was the last PID, and reinitialize themselves if it changed.
This is assuming getpid() is fast :-)

Locks can't blindly release themselves because they find themselves
running in another process.

If anything if a lock is held and finds itself running in a new
process any attempt to use the lock should raise an exception so that
the bug is noticed.

I'm not sure a PID check is good enough. old linux using linuxthreads
had a different pid for every thread, current linux with NPTL is more
like other oses with the same pid for all threads.

I was suggesting "reinitialize", rather than "release". That is, create
a new lock (mutex, semaphore, etc.) and let the old one die (or occupy
some tiny bit of memory).

no need for that. the problem is that they're held by a thread that
does not exist in the newly forked child process so they will never be
released in the new process.

example: if you fork while another thread is in the middle of logging
something and then try to log something yourself in the child, your
child process will deadlock on the logging module's lock.

locks are not shared between processes so reinitializing them with a new
object wouldn't do anything.

I'm not sure that releasing the mutex is enough, it can still lead to a segfault, as is probably the case in this issue :
http://bugs.python.org/issue11148

Quoting pthread_atfork man page :

To understand the purpose of pthread_atfork, recall that fork duplicates the whole memory space, including mutexes in their current locking state, but only the calling thread: other threads are not running in the child process. The mutexes are not usable after the fork and must be initialized with pthread_mutex_init in the child process. This is a limitation of the current implementation and might or might not be present in future versions.

To avoid this, install handlers with pthread_atfork as follows: have the prepare handler lock the mutexes (in locking order), and the parent handler unlock the mutexes. The child handler should reset the mutexes using pthread_mutex_init, as well as any other synchronization objects such as condition variables.

Locking the global mutexes before the fork ensures that all other threads are locked out of the critical regions of code protected by those mutexes. Thus when fork takes a snapshot of the parent's address space, that snapshot will copy valid, stable data. Resetting the synchronization objects in the child process will ensure they are properly cleansed of any artifacts from the threading subsystem of the parent process. For example, a mutex may inherit a wait queue of threads waiting for the lock; this wait queue makes no sense in the child process. Initializing the mutex takes care of this.

pthread_atfork might be worth looking into

fwiw http://bugs.python.org/issue6643 recently fixed on issue where a mutex was being closed instead of reinitialized after a fork. more are likely needed.

Are you suggesting to use pthread_atfork to call pthread_mutex_init on all mutexes created by Python in the child after a fork? I'll have to ponder that some more. Given the mutexes are all useless post fork it does not strike me as a bad idea.

Are you suggesting to use pthread_atfork to call pthread_mutex_init on > all mutexes created by Python in the child after a fork? I'll have to > ponder that some more. Given the mutexes are all useless post fork it > does not strike me as a bad idea.

I don't really understand. It's quite similar to the idea you shot down in msg94135. Or am I missing something?

Yeah, I'm trying to figure out what I was thinking then or if I was just plain wrong. :)

I was clearly wrong about a release being done in the child being the right thing to do (bpo-6643 proved that, the state held by a lock is not usable to another process on all platforms such that release even works).

Part of it looks like I wanted a way to detect it was happening as any lock that is held during a fork indicates a _potential_ bug (the lock wasn't registered anywhere to be released before the fork) but not everything needs to care about that.

I was clearly wrong about a release being done in the child being the right thing to do (bpo-6643 proved that, the state held by a lock is not usable to another process on all platforms such that release even works).

Yeah, apparently OS-X is one of them, the reporter in bpo-11148 is
experiencing segfaults under OS-X.

Are you suggesting to use pthread_atfork to call pthread_mutex_init on all mutexes created by Python in the child after a fork? I'll have to ponder that some more. Given the mutexes are all useless post fork it does not strike me as a bad idea.

Yes, that's what I was thinking. Instead of scattering the
lock-reclaiming code all over the place, try to use a more standard
API specifically designed with that in mind.
Note the base issue is that we're authorizing things which are
forbidden : in a multi-threaded process, only sync-safe calls are
authorized between fork and exec.

2011/2/10 Gregory P. Smith <report@bugs.python.org>:

Gregory P. Smith <greg@krypto.org> added the comment:

Yeah, I'm trying to figure out what I was thinking then or if I was just plain wrong. :)

I was clearly wrong about a release being done in the child being the right thing to do (bpo-6643 proved that, the state held by a lock is not usable to another process on all platforms such that release even works).

Part of it looks like I wanted a way to detect it was happening as any lock that is held during a fork indicates a _potential_ bug (the lock wasn't registered anywhere to be released before the fork) but not everything needs to care about that.

----------
versions: +Python 3.3

Python tracker <report@bugs.python.org>
<http://bugs.python.org/issue6721\>

acquiring locks before fork in the thread doing the forking and releasing them afterwards is always the safe thing to do.

It's also an easy way to cause a deadlock:

register_at_fork() et.al. will cause per-logger locks to be acquired before the global lock (this isn't immediately obvious from the code)

If a thread were to grab its logging lock before the global lock then it would deadlock. I'm guessing this isn't allowed - however I didn't see any comments to this effect?

Can I suggest documenting this, and also merging the two callbacks so that the ordering of these two acquires is made explicit.

the per-logger locks are acquired in a random order

If a thread were to acquire two per-logger locks in a different order then things would deadlock.

Below is a backtrace from the deadlock.

It happens because the logging code is trying to acquire two per-logger locks; and in an order different to the random order used by the fork() handler.

The code in question has a custom class DebugHandler(logging.Handler). The default logging.Handler.handle() method grabs its lock and calls .emit() vis:

        if rv:
            self.acquire()
            try:
                self.emit(record)
            finally:
                self.release()

the custom .emit() then sends the record to a sub-logger stream vis:

    def emit(self, record):
        for stream_handler in self.stream_handlers:
            stream_handler.emit(record)
        if _DEBUG_STREAM:
            _DEBUG_STREAM.emit(record)

and one of these emit() functions calls flush() which tries to acquire a further lock.

Thread 0x00007f976b7fe700 (most recent call first):
File "/usr/lib64/python3.7/logging/init.py", line 854 in acquire
File "/usr/lib64/python3.7/logging/init.py", line 1015 in flush

    def flush(self):
        """
        Flushes the stream.
        """
        self.acquire() <

    try:
        if self.stream and hasattr(self.stream, "flush"):
            self.stream.flush()
    finally:
        self.release()

File "/usr/lib64/python3.7/logging/init.py", line 1038 in emit

        self.flush() <\----

File "/home/build/libreswan-web/master/testing/utils/fab/logutil.py", line 163 in emit

    def emit(self, record):
        for stream_handler in self.stream_handlers:
            stream_handler.emit(record) <---
        if _DEBUG_STREAM:
            _DEBUG_STREAM.emit(record)

File "/usr/lib64/python3.7/logging/init.py", line 905 in handle

    def handle(self, record):
        """
        Conditionally emit the specified logging record.

    Emission depends on filters which may have been added to the handler.
    Wrap the actual emission of the record with acquisition/release of
    the I/O thread lock. Returns whether the filter passed the record for
    emission.
    """
    rv = self.filter(record)
    if rv:
        self.acquire()
        try:
            self.emit(record) <\---
        finally:
            self.release()
    return rv

File "/usr/lib64/python3.7/logging/init.py", line 1591 in callHandlers

                    hdlr.handle(record)

File "/usr/lib64/python3.7/logging/init.py", line 1529 in handle

            self.callHandlers(record)

File "/usr/lib64/python3.7/logging/init.py", line 1519 in _log

        self.handle(record)

File "/usr/lib64/python3.7/logging/init.py", line 1449 in log

        self._log(level, msg, args, **kwargs)

File "/usr/lib64/python3.7/logging/init.py", line 1768 in log

            self.logger.log(level, msg, *args, **kwargs)

File "/usr/lib64/python3.7/logging/init.py", line 1724 in debug

        self.log(DEBUG, msg, *args, **kwargs)

File "/home/build/libreswan-web/master/testing/utils/fab/shell.py", line 110 in write

        self.logger.debug(self.message, ascii(text))

Thanks for the debugging details! I've filed https://bugs.python.org/issue36533 to specifically track this potential regression in the 3.7 stable branch. lets carry on there where the discussion thread isn't too long for bug tracker sanity.

I created bpo-40089: Add _at_fork_reinit() method to locks.

Related issue:
https://bugs.python.org/issue40399
"""
IO streams locking can be broken after fork() with threads
"""

https://bugs.python.org/issue40442 is a fresh instance of this, entirely self-inflicted.

See also bpo-25920: PyOS_AfterFork should reset socketmodule's lock.

While it's true that "Locks in the standard library should be sanitized on fork", IMO having such "meta-issue" to track the issue in the 300+ stdlib modules is a bad idea, since it's hard to track how many modules got fixed and how many modules should still be fixed. Multiple modules have been fixed. I suggest to open more specific issues for remaining ones. I close the issue. Thanks for anyone who was involved in fixing issues! Good luck for people volunteers to fix remaining issues :-) Also, avoid fork without exec, it's no longer supported on macOS, it was never supported on Windows, and it causes tons of very complex bugs on Linux :-)

fix: give a forked worker its own stdout, not the parent's locked one

Navigation Menu

Repository navigation

Locks in the standard library should be sanitized on fork #50970

119 remaining items

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Locks in the standard library should be sanitized on fork #50970

Description

Activity

gpshead commented on Aug 17, 2009

gpshead commented on Aug 24, 2009

gpshead commented on Sep 17, 2009

pitrou commented on Oct 15, 2009

gpshead commented on Oct 16, 2009

pitrou commented on Oct 16, 2009

gpshead commented on Oct 16, 2009

neologix commented on Feb 10, 2011

gpshead commented on Feb 10, 2011

pitrou commented on Feb 10, 2011

gpshead commented on Feb 10, 2011

neologix commented on Feb 11, 2011

119 remaining items

cagney commented on Apr 4, 2019

cagney commented on Apr 4, 2019

gpshead commented on Apr 5, 2019

vstinner commented on Mar 27, 2020

pitrou commented on Apr 28, 2020

rojer commented on Apr 29, 2020

vstinner commented on May 14, 2020

vstinner commented on Jun 6, 2022

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions