Debian Bug report logs - #822431
python3.5: regression in -11: always calls getrandom() at start, causing long hang after boot

Display info messages

Message #5 received at submit@bugs.debian.org (full text, mbox, reply):

From: Martin Pitt <mpitt@debian.org>

To: Debian BTS Submit <submit@bugs.debian.org>

Subject: python3.5: regression in -11: always calls getrandom() at start, causing long hang after boot

Date: Sun, 24 Apr 2016 13:49:33 +0200

[Message part 1 (text/plain, inline)]

Package: python3.5
Version: 3.5.1-11
Severity: important

I just debugged the adt-virt-qemu failure with python 3.5.1-11 and
tracked it down to python3.5 hanging for a long time when it gets
called before the kernel initializes its RNG (which can take a minute
in VMs which have low entropy sources).

With 3.5.1-10:

  $ strace -e getrandom python3 -c 'True'
  +++ exited with 0 +++

With -11:
  $ strace -e getrandom python3 -c 'True'
  getrandom("\300\0209\26&v\232\264\325\217\322\303:]\30\212Q\314\244\257t%\206\"", 24, 0) = 24
  +++ exited with 0 +++

When you do this with -11 right after booting a VM, the getrandom()
can block for a long time, until the kernel initializes its random
pool:

   11:21:36.118034 getrandom("/V#\200^O*HD+D_\32\345\223M\205a\336/\36x\335\246", 24, 0) = 24
   11:21:57.939999 ioctl(0, TCGETS, 0x7ffde1d152a0) = -1 ENOTTY (Inappropriate ioctl for device)

   [    1.549882] [TTM] Initializing DMA pool allocator
   [   39.586483] random: nonblocking pool is initialized

(Note the time stamps in the strace in the first paragraph)

This is really unfriendly -- it essentially means that you stop being
able to use python3 early in the boot process or even early after
booting. It would be better to initialize that random stuff lazily,
until/if things actually need it.

In the diff between -10 and -11 I do seem some getrandom() fixes to
supply the correct buffer size (but that should be irrelevant as in
-10 getrandom() wasn't called in the first place), and a new call
which should apply to Solaris only (#ifdef sun), so it's not entirely
clear where that comes from or how to work around it.

It's very likely that this is the same cause as for #821877, but the
description of that is both completely different and also very vague,
so I file this separately for now.

Martin

-- 
Martin Pitt                        | http://www.piware.de
Ubuntu Developer (www.ubuntu.com)  | Debian Developer  (www.debian.org)

[signature.asc (application/pgp-signature, inline)]

Message #10 received at 822431@bugs.debian.org (full text, mbox, reply):

From: Matthias Klose <doko@debian.org>

To: Martin Pitt <mpitt@debian.org>, 822431@bugs.debian.org

Subject: Re: Bug#822431: python3.5: regression in -11: always calls getrandom() at start, causing long hang after boot

Date: Sun, 24 Apr 2016 22:47:02 +0200

Control: forwarded -1 http://bugs.python.org/issue26839
Control: tags -1 + upstream wontfix

On 24.04.2016 13:49, Martin Pitt wrote:
> In the diff between -10 and -11 I do seem some getrandom() fixes to
> supply the correct buffer size (but that should be irrelevant as in
> -10 getrandom() wasn't called in the first place), and a new call
> which should apply to Solaris only (#ifdef sun), so it's not entirely
> clear where that comes from or how to work around it.

not sure why this showed up only now, but upstream suggested two fixes how to 
avoid this issue.

Message #19 received at 822431@bugs.debian.org (full text, mbox, reply):

From: Martin Pitt <mpitt@debian.org>

To: Matthias Klose <doko@debian.org>

Cc: 822431@bugs.debian.org

Subject: Re: Bug#822431: python3.5: regression in -11: always calls getrandom() at start, causing long hang after boot

Date: Sun, 24 Apr 2016 23:42:50 +0200

Hello Matthias,

Matthias Klose [2016-04-24 22:47 +0200]:
> Control: forwarded -1 http://bugs.python.org/issue26839
> not sure why this showed up only now, but upstream suggested two fixes how
> to avoid this issue.

Thanks! This suggestion works fine indeed and it also explains why
this happens in the first place; I now committed a more proper
autopkgtest fix.

Martin

-- 
Martin Pitt                        | http://www.piware.de
Ubuntu Developer (www.ubuntu.com)  | Debian Developer  (www.debian.org)

Message #24 received at 822431@bugs.debian.org (full text, mbox, reply):

From: Alexandre Detiste <alexandre.detiste@gmail.com>

To: 823337@bugs.debian.org, 823346@bugs.debian.org, 822431@bugs.debian.org

Subject: Re: systemd: Boot stalls for 90 s at early boot (system-generators terminated by signal ALRM)

Date: Fri, 06 May 2016 20:12:12 +0200

Found it :-)

This is a Python bug: https://bugs.python.org/issue26839

Sorry for cross posting to the three bugs.

I don't know, how/wether these 3 bugs should those been merged.

Martin/Matthias, can you handle this ?

-----

How I found it:

The first line I get in dmesg after typing something at the keyboard is  "random: nonblocking pool is initialized"

systemd-cron does uses Python's hashlib to compute md5's; but that doesn't need any source of randomness at all.

Now I see even an empty python program
with only the shebang line would still trigger this delay;
so this had to be a python runtime related bug.


Alexandre

Message #35 received at 822431@bugs.debian.org (full text, mbox, reply):

From: Colm Buckley <colm@tuatha.org>

To: 822431@bugs.debian.org

Subject: Set PYTHONHASHSEED=0 when calling systemd-crontab-generator

Date: Tue, 7 Jun 2016 16:32:45 +0100

[Message part 1 (text/plain, inline)]

Given that the Python bug discussion is inclining against changing the
Python runtime behavior, a workaround would be to arrange for the
environment variable PYTHONHASHSEED to be set to the value "0" when calling
systemd-crontab-generator. This could be done dumbly by a shell script
which in turn calls the current crontab generator, but it strikes me that
there might be a more elegant way.

Any takers?

Colm


-- 
Colm Buckley / colm@tuatha.org / +353 87 2469146

[Message part 2 (text/html, inline)]

Message #36 received at 824379-close@bugs.debian.org (full text, mbox, reply):

From: Matthias Klose <doko@debian.org>

To: 824379-close@bugs.debian.org

Subject: Bug#824379: fixed in python3.5 3.5.1-14

Date: Thu, 09 Jun 2016 17:04:21 +0000

Source: python3.5
Source-Version: 3.5.1-14

We believe that the bug you reported is fixed in the latest version of
python3.5, which is due to be installed in the Debian FTP archive.

A summary of the changes between this version and the previous one is
attached.

Thank you for reporting the bug, which will now be closed.  If you
have further comments please address them to 824379@bugs.debian.org,
and the maintainer will reopen the bug report if appropriate.

Debian distribution maintenance software
pp.
Matthias Klose <doko@debian.org> (supplier of updated python3.5 package)

(This message was generated automatically at their request; if you
believe that there is a problem with it please contact the archive
administrators by mailing ftpmaster@ftp-master.debian.org)


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Format: 1.8
Date: Thu, 09 Jun 2016 17:41:54 +0200
Source: python3.5
Binary: python3.5 python3.5-venv libpython3.5-stdlib python3.5-minimal libpython3.5-minimal libpython3.5 python3.5-examples python3.5-dev libpython3.5-dev libpython3.5-testsuite idle-python3.5 python3.5-doc python3.5-dbg libpython3.5-dbg
Architecture: source
Version: 3.5.1-14
Distribution: unstable
Urgency: medium
Maintainer: Matthias Klose <doko@debian.org>
Changed-By: Matthias Klose <doko@debian.org>
Description:
 idle-python3.5 - IDE for Python (v3.5) using Tkinter
 libpython3.5 - Shared Python runtime library (version 3.5)
 libpython3.5-dbg - Debug Build of the Python Interpreter (version 3.5)
 libpython3.5-dev - Header files and a static library for Python (v3.5)
 libpython3.5-minimal - Minimal subset of the Python language (version 3.5)
 libpython3.5-stdlib - Interactive high-level object-oriented language (standard library
 libpython3.5-testsuite - Testsuite for the Python standard library (v3.5)
 python3.5  - Interactive high-level object-oriented language (version 3.5)
 python3.5-dbg - Debug Build of the Python Interpreter (version 3.5)
 python3.5-dev - Header files and a static library for Python (v3.5)
 python3.5-doc - Documentation for the high-level object-oriented language Python
 python3.5-examples - Examples for the Python language (v3.5)
 python3.5-minimal - Minimal subset of the Python language (version 3.5)
 python3.5-venv - Interactive high-level object-oriented language (pyvenv binary, v
Closes: 824379
Changes:
 python3.5 (3.5.1-14) unstable; urgency=medium
 .
   * Update to 20160609 from the 3.5 branch.
     - A new version of typing.py provides several new classes and
       features: @overload outside stubs, Reversible, DefaultDict, Text,
       ContextManager, Type[], NewType(), TYPE_CHECKING, and numerous bug
       fixes (note that some of the new features are not yet implemented in
       mypy or other static analyzers).  Also classes for PEP 492
       (Awaitable, AsyncIterable, AsyncIterator) have been added (in fact
       they made it into 3.5.1 but were never mentioned).
     - Issue #25738: Stop http.server.BaseHTTPRequestHandler.send_error() from
       sending a message body for 205 Reset Content.  Also, don't send Content
       header fields in responses that don't have a body.
     - Issue #21313: Fix the "platform" module to tolerate when sys.version
       contains truncated build information.
     - Issue #26839: On Linux, :func:`os.urandom` now calls ``getrandom()`` with
       ``GRND_NONBLOCK`` to fall back on reading ``/dev/urandom`` if the urandom
       entropy pool is not initialized yet. Closes: #824379.
     - Issue #27164: In the zlib module, allow decompressing raw Deflate streams
       with a predefined zdict.
     - Issue #24291: Fix wsgiref.simple_server.WSGIRequestHandler to completely
       write data to the client.  Previously it could do partial writes and
       truncate data.  Also, wsgiref.handler.ServerHandler can now handle stdout
       doing partial writes, but this is deprecated.
     - Issue #26809: Add ``__all__`` to :mod:`string`.
     - Issue #26373: subprocess.Popen.communicate now correctly ignores
       BrokenPipeError when the child process dies before .communicate()
       is called in more/all circumstances.
     - Issue #24759: Make clear in idlelib.idle_test.__init__ that the directory
       is a private implementation of test.test_idle and tool for maintainers.
     - Issue #27196: Stop 'ThemeChanged' warnings when running IDLE tests.
       These persisted after other warnings were suppressed in #20567.
     - Issue #20567: Revise idle_test/README.txt with advice about avoiding
       tk warning messages from tests.  Apply advice to several IDLE tests.
     - Issue #26884: Fix linking extension modules for cross builds.
     - Issue #26014: Update 3.x packaging documentation:
       * "See also" links to the new docs are now provided in the legacy pages
       * links to setuptools documentation have been updated
     - Issue #27229: Fix the cross-compiling pgen rule for in-tree builds.
   * Don't run multiprocessing tests during the profiling build.
Checksums-Sha1:
 eb952aa73473632b3eb17674222da20e4a14e8e6 3233 python3.5_3.5.1-14.dsc
 9f42aa6213777400c271398b788a3b35b59a56ce 663984 python3.5_3.5.1-14.debian.tar.xz
Checksums-Sha256:
 660d2174856cdf95358211eabe15c7d0439da4c06a9905d982e6e29fd75301ae 3233 python3.5_3.5.1-14.dsc
 3871f070b3c21d15aa85b2901719e066b7f4fd59c9dd5781c311a86e133bf4dc 663984 python3.5_3.5.1-14.debian.tar.xz
Files:
 3da5ca0d2f36030024437341b1724348 3233 python optional python3.5_3.5.1-14.dsc
 e6cd9d58d69f061931e6d633ffcb82a5 663984 python optional python3.5_3.5.1-14.debian.tar.xz

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1

iQIcBAEBCAAGBQJXWZMpAAoJEL1+qmB3j6b1qnoP/jlu86va/KqI7GmHiHd9wHEw
rsMbscOw726lnsd5w3dz5SrnIgxLcr12u0wA5fjDpM7neenvIhpkNH4w5clnbju1
8xYTlsqF53sOkPKT26/00JuKg2uX8fDSgkrnpjBlosJpJXHMzuKhChJYJraisl3V
VWRci03Ph2nMPBOGRab6dQySkvKYFzPdorKz3t7fQafT3mh6fsl2ue3cAeC9/gMX
yX5tcPB5u7naVKsUtJX/eIT9T5mvVGuJ/K0KNN9LmvB51A56UfpuQHPqMwN5U9BQ
FBiscosxKnKNN0wMqT4xa1RqM8Q2A1jRL4QJ6/2EbAkYfa/0sf5zU640XdRY7E7E
RnfyD7GyhkzW7EBhL9lFSJDz8Zvz6wfKuqX2fbBKf203R8H5Z6ibRhfRoOJBGHOs
kypce48ANwbkOEwOMq+7nVHbizGbZgUj9xfd4SVUlhfZS2vpu/mTxbAQgQSBAM1k
w7wIuenwUN2K41dJ8qVs2ifsy9Bfrgm7OPPtimDe8vYCqBrDnE1qM1RbDDqi5j+e
x1sbTqaeFJcsI1m4WdB2raMtmwLd5+vkFCBYq1uHdN+uo0b6sD5vpHBinut/iltE
kjlIbw6aKajafB+CaHgvsh/5vDZ5loUsNEO98ix4okYGknN+3fQHCGdlN/Ey9RDR
Y55/vf11gYTNO2XCDCCv
=IpF0
-----END PGP SIGNATURE-----

Send a report that this bug log contains spam.