-
-
Notifications
You must be signed in to change notification settings - Fork 30.6k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
logging regression with threading + fork are mixed in 3.7.1rc2 (deadlock potential) #80714
Comments
I'm spawning a dicussion buried in the way too long thread of https://bugs.python.org/issue6721 over here into its own specific issue to treat as a 3.7 release blocker for a rollback or repair decision before 3.7.4. I believe that was released in 3.7.1 is leading to a behavior regression for an application (the Fedora installer's libreswan kvmrunner?). Full details can be found in the messages of the other issue starting with: TL;DR - logging.Handler instances each have their own threading.Rlock. So they've got a dependency between these two locks, the first's must be acquired before the second. But the logging module APIs have no concept of sub-handlers and lock ordering. I see many flaws with the libreswan code's design (I'm already ignoring the futility of threading + fork) but this still caused a behavior regression in the stable 3.7 release. (more comments coming as followups to avoid a wall of text with too many topics) |
That custom DebugHandler's emit() implementation that calls into one or more sub-handlers suggests that libreswan _might_ be able to fix it in the custom DebugHandler by implementing custom acquire() and release() methods... BUT that is a fundamentally flawed problem: It requires acquiring multiple locks in a single atomic operation OR guaranteeing that they will always be acquired in a single specific order. Given the logging module's fork-time code maintains no order, even implementing a custom acquire() and release() method in your custom DebugHandler would not be sufficient as sub-handler locks could be acquired first during fork. also, that would be assuming your sub-handlers are not also used directly elsewhere within all possible coexisting logger configurations. An implementable _gross workaround_ that libreswan or anything else in this boat could implement satisfying that constraint would be to force all potentially related handlers to share the same single RLock instance. :( |
Within the logging module we could go beyond using a WeakSet and maintain an ordering. But we'd need to allow a way for Handler subclasses to indicate what order matters; that'd require a new API (not suitable for 3.7) An ordering itself may be insufficient as code can implement arbitrary Handler code with cyclic graphs of handlers calling directly into other handlers such that no possible order could ever satisfy them all. This pulls us back into "stop having multiple locks" for any code that creates relationships between handlers. Which is good advice for Handler authors and something we should document if it isn't already. Side note: We should also document that Handler.emit() as an API MUST be called with the Handler's lock acquired via Handler.acquire() first. That is the undocumented contracted way logging.Logger.handle()'s code always calls into handler emit().... The libreswan code calling other handler's emit() methods without doing that smells wrong. But that has no relation to their current problem: Even if it did, it'd still deadlock, just sooner rather than within the other handler's emit()->flush()->acquire() call chain. Logging library users are better off never directly calling another handler. Put message onto queues with a dedicated thread processing those into the relevant handlers. Only block waiting for those queued items to have been processed _after_ releasing your own lock if you want to maintain the synchronicity of logging API calls returning only after the message has been handled. |
Now to back up: Why was this application using fork() in a threaded application at all? That is a fundamental flaw. Should we be doing work to support things that so far merely _happen_ to work on such broken designs? Another alternative for the DebugHandler implementation in whatever code implemented it is for it to de-register itself from the logging library's private WeakSet of handler locks to acquire at fork time from its own constructor. We don't have a public API for this so the workaround doing that on 3.7.1 - 3.7.3 would look like: def __init__(self, ...):
super().__init__(...)
if hasattr(logging, '_at_fork_acquire_release_weakset'):
logging._at_fork_acquire_release_weakset.discard(self) This means it'd still have the bug the code already had on all prior to versions of Python before this logging library "acquire the locks before fork" fix went in: Namely if the forked child tries to log it could deadlock due to forking while the inherited logging handler lock held. |
A stdlib alternative to this whole mess would be to avoid acquiring the logging locks before fork() as we currently do and just blindly re-initialize all of them afterwards under the assumption that they "can't" be protecting anything in a newly forked child process. Handlers that need specific resource synchronization around fork would then be required to deal with their own os.register_at_fork() calls. (ex: to avoid multiple processes writing to the same file or fd at once) |
On Fri, 5 Apr 2019 at 04:15, Gregory P. Smith <report@bugs.python.org> wrote:
Two separate applications have tripped up on this:
I don't know any further details.
kvmrunner uses pexpect
# Implement log-level inversion. # Ref: https://docs.python.org/2/howto/logging.html#logging-flow # By default, a parent (root) logger, regardless of its log-level, # This code allows DEBUG-level logging to a file, while simultaneously The logging.Handler's lock ensures that the two sub-streams are kept
Always first understand the problem.
|
On Fri, 5 Apr 2019 at 05:02, Gregory P. Smith <report@bugs.python.org> wrote:
FYI, below is a simpler, but related, test. Ignoring exception from logging atfork <Handler (NOTSET)> release Exception ignored in: <function _after_at_fork_weak_calls at 0x7f7307550378>
Traceback (most recent call last):
File "/home/python/v3.7.3/lib/python3.7/logging/__init__.py", line
269, in _after_at_fork_weak_calls
_at_fork_weak_calls('release')
File "/home/python/v3.7.3/lib/python3.7/logging/__init__.py", line
254, in _at_fork_weak_calls
for instance in _at_fork_acquire_release_weakset:
File "/home/python/v3.7.3/lib/python3.7/_weakrefset.py", line 60, in __iter__
for itemref in self.data:
RuntimeError: Set changed size during iteration
Exception in thread Thread-1:
Traceback (most recent call last):
File "/home/python/v3.7.3/lib/python3.7/threading.py", line 917, in
_bootstrap_inner
self.run()
File "/home/python/v3.7.3/lib/python3.7/threading.py", line 865, in run
self._target(*self._args, **self._kwargs)
File "./btc.py", line 11, in lockie
h = logging.Handler()
File "/home/python/v3.7.3/lib/python3.7/logging/__init__.py", line
824, in __init__
self.createLock()
File "/home/python/v3.7.3/lib/python3.7/logging/__init__.py", line
847, in createLock
_register_at_fork_acquire_release(self)
File "/home/python/v3.7.3/lib/python3.7/logging/__init__.py", line
250, in _register_at_fork_acquire_release
_at_fork_acquire_release_weakset.add(instance)
File "/home/python/v3.7.3/lib/python3.7/_weakrefset.py", line 83, in add
self._commit_removals()
File "/home/python/v3.7.3/lib/python3.7/_weakrefset.py", line 56, in
_commit_removals
discard(l.pop())
IndexError: pop from empty list import logging
import os
import sys
import threading
def lockie():
while True:
# this adds handle to _at_fork_acquire_release_weakset
#sys.stdout.write(".")
#sys.stdout.flush()
h = logging.Handler() threading.Thread(target=lockie).start() for n in range(0,100000):
if n % 100 == 0:
sys.stdout.write("%d" % n)
sys.stdout.flush()
pid = os.fork()
if pid != 0:
os.wait()
else:
os._exit(0) |
Here's a PR that goes the re-initialization route rather than attempting to acquire/release anything other than the single module _lock. |
I think the only pragmatic solution here is to add an optional parameter to logging.basicConfig() that specifies that the logger should use a single global lock; and then start documenting that thread locks and fork() don't work well together. And note that this solution is pragmatic, not correct (@dhr, when we discussed this off line, pointed out that since python's using threads then a "correct" solution would be to use some sort of inter-process lock). For instance, if I were to implement emit() as something contrived like: with lock:
s = record.to-string()
for i in 1 .. s'length:
b[i] = s[i]
for i in 1 .. b'length:
stdout.write(b[i]).flush()
b = [] then when fork() breaks 'lock' the guarantee that the code is atomic is also broken:
while a global lock would help mitigate the first case it really isn't a "correct" fix. |
The logging library has never guaranteed that it wouldn't interleave or duplicate buffered io output when fork() in involved. We should not start trying to claim that it does. Too complicated and fragile. It can't. Users who want that should implement their own single logging handler that is well behaved in whatever regards they need. there are a ton of options for them. A basicConfig setting to switch the mode of operation to a single lock instead of per-handler locks could only happen in 3.8 (new feature). I'll ponder if it is even feasible to add that after the re-init change goes in. Even with such a feature, library user authored Handler subclasses would always be free to violate that. We can't protect people from themselves. |
I pointed out two issues with breaking the locks. Your response addressed the less important issue:
Since the documentation seems to be silent the guarantee (or expectation) is implied - logging systems emit records atomically - if this isn't true across fork() then the exception should be documented. but it didn't address the more fundamental problem:
i.e., breaking the lock will allow the child to access data in an undefined state. This will result in either core dumps or hangs (presumably the motivation for the original change was to prevent this?). For instance, if the fork() happens while a thread is holding the <stdio.h> FILE lock on a log file, then the child trying to access that FILE will hang. |
We can add a note to the docs. As a general rule: documentation being silent means there are zero guarantees. Behavior of the existing implementations over time is the only source of truth.
i.e., breaking the lock will allow the child to access data in an undefined state. This will result in either core dumps or hangs (presumably the motivation for the original change was to prevent this?). nope. the contrived emit() pseudocode from msg339650 never defined b in the first place. that code, if massaged into python syntax would raise an UnboundLocalError no matter who executed it. a fork() from another thread would not change that. There is no concept of undefined/uninitialized state from the Python perspective. The motivation for the original fix was entirely deadlock avoidance in code that uses fork. It failed and introduced an alternate form of deadlock in code that had been lucky up until that point. Thus my new PR proposing to fix the regression by making that not fail yet still preventing locks from starting out held in the child process. |
Wow! It is pseudo code, right? (I figured using Ada like attributes was a bit of a giveaway). Nitpicking it achieves nothing (if you feel that your language needs 'b' pre-defined then, hey!, pre-define it; I'm pretty sure that won't fix the problem of operations such b[i] = 2 not being atomic yet alone thread-safe in Python). Lets instead focus on my point that breaking the locks won't fix the problem. For instance, above. Or "For instance, if the fork() happens while a thread is holding the <stdio.h> FILE lock on a log file, then the child trying to access that FILE will hang." |
BTW, non-visible change might be to use a global readers-writer lock where fork() is the writer. |
The problem i am fixing is merely making Python's logging library not the source of this deadlock because it was not the source in the past. I am solving a regression in CPython behavior between 3.7.0 and 3.7.1 that led to a logging.Handler lock related deadlock in two identified problematic applications. Breaking the logging.Handler owned locks does solve that unless someone has concrete proof from these specific applications that it does otherwise. It would be helpful if someone *willing to actually be constructive* would test them with my PR's patch applied to their 3.7.3 interpreter as confirmation. |
This deadlock is a release blocker for 3.8.0. FTR, I don't consider it blocking alphas and betas. |
The regression should be fixed. It'd be helpful if owners of applications that were running into this could test their applications with this specific change. |
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:
bugs.python.org fields:
The text was updated successfully, but these errors were encountered: