Author cagney
Recipients cagney, gregory.p.smith, ned.deily, vstinner
Date 2019-04-05.15:11:07
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <>
In-reply-to <>
On Fri, 5 Apr 2019 at 04:15, Gregory P. Smith <> wrote:
> New submission from Gregory P. Smith <>:
> I'm spawning a dicussion buried in the way too long thread of 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:

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:

> 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:
# 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 <>
> <>
> _______________________________________
Date User Action Args
2019-04-05 15:11:07cagneysetrecipients: + cagney, gregory.p.smith, vstinner, ned.deily
2019-04-05 15:11:07cagneylinkissue36533 messages
2019-04-05 15:11:07cagneycreate