[issue36533] logging regression with threading + fork are mixed in 3.7.1rc2 (deadlock potential)

[cagney]

cagney <andrew.cagney at gmail.com> added the comment:

On Fri, 5 Apr 2019 at 04:15, Gregory P. Smith <report at bugs.python.org> wrote:
>
>
> New submission from Gregory P. Smith <greg at krypto.org>:
>
> 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.
>
> https://github.com/python/cpython/commit/3b699932e5ac3e76031bbb6d700fbea07492641d
>
> 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:
>   https://bugs.python.org/issue6721#msg329474

Two separate applications have tripped up on this:

- Fedora's installer aka anaconda

I don't know any further details.

- libreswan's test framework aka kvmrunner

kvmrunner uses pexpect
pexpect uses ptyprocess
ptyprocess uses pty.fork() + os.exec*(); but, hey, who knew!  I didn't
until this week.
this seems to be a long standing concern:
https://github.com/pexpect/ptyprocess/issues/43

> TL;DR - logging.Handler instances each have their own threading.Rlock.
> libreswan implements at least one logging.Handler subclass.  That subclass's custom emit() implementation directly calls potentially many other sub-handlers emit() methods.  Some of those emit() methods (such as logging.StreamHandler) call flush() which acquires the handler's lock.

# 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,
# will log all the records logged by a child.  For instance, if a
# child logger is logging at DEBUG-level, then the parent will log
# (display on the console) those DEBUG-level records even when it has
# been configured to log only INFO-level records.  This is because the
# default log-level ("Logger enabled for level of call?") check is
# only applied once at record-creation.
#
# This code allows DEBUG-level logging to a file, while simultaneously
# (the inversion) restricting console log records to just INFO-level
# say.

The logging.Handler's lock ensures that the two sub-streams are kept
in ordered.  It prevents threads interleaving their writes.

> 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.

Always first understand the problem.

> (more comments coming as followups to avoid a wall of text with too many topics)
>
> ----------
> assignee: gregory.p.smith
> components: Library (Lib)
> keywords: 3.7regression
> messages: 339472
> nosy: cagney, gregory.p.smith, ned.deily, vstinner
> priority: release blocker
> severity: normal
> status: open
> title: logging regression with threading + fork are mixed in 3.7.1rc2 (deadlock potential)
> type: behavior
> versions: Python 3.7
>
> _______________________________________
> Python tracker <report at bugs.python.org>
> <https://bugs.python.org/issue36533>
> _______________________________________

----------

_______________________________________
Python tracker <report at bugs.python.org>
<https://bugs.python.org/issue36533>
_______________________________________