yahoo-eng-team team mailing list archive
-
yahoo-eng-team team
-
Mailing list archive
-
Message #68884
[Bug 1727358] Re: cloud-init is slow to complete init on minimized images
I've tracked down the blocking use of randomness in cloud-init's python
module initialization. There are several nonblocking calls to
getrandom(), which I believe should be fine; then a blocking call in the
multiprocessing module.
# PYTHONHASHSEED=1 gdb --args /usr/bin/python3-dbg /usr/bin/cloud-init init
GNU gdb (Ubuntu 8.0.1-0ubuntu1) 8.0.1
[...]
(gdb) break getrandom
Breakpoint 1 at 0x420b90
(gdb) python
>import sys
>sys.path.append('/usr/share/doc/python3.6/examples/gdb')
>import libpython
>end
(gdb) run
Starting program: /usr/bin/python3-dbg /usr/bin/cloud-init init
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Breakpoint 1, getrandom (buffer=buffer@entry=0x7fffffff8140,
length=length@entry=2496, flags=flags@entry=1)
at ../sysdeps/unix/sysv/linux/getrandom.c:30
[...]
(gdb) cont 4
Will ignore next 3 crossings of breakpoint 1. Continuing.
[...]
-------+
ci-info: | Route | Destination | Gateway | Genmask | Interface |
Flags |
ci-info: +-------+---------------+---------------+-----------------+-----------+
-------+
ci-info: | 0 | 0.0.0.0 | 192.168.122.1 | 0.0.0.0 | ens3 |
UG |
ci-info: | 1 | 192.168.122.0 | 0.0.0.0 | 255.255.255.0 | ens3 |
U |
ci-info: | 2 | 192.168.122.1 | 0.0.0.0 | 255.255.255.255 | ens3 |
UH |
ci-info: +-------+---------------+---------------+-----------------+-----------+
-------+
/usr/lib/python3.6/logging/config.py:85: ResourceWarning: unclosed file <_io.Tex
tIOWrapper name='/var/log/cloud-init.log' mode='a' encoding='UTF-8'>
_install_loggers(cp, handlers, disable_existing_loggers)
Breakpoint 1, getrandom (buffer=buffer@entry=0x7ffff21b7340,
length=length@entry=32, flags=flags@entry=0)
at ../sysdeps/unix/sysv/linux/getrandom.c:30
30 in ../sysdeps/unix/sysv/linux/getrandom.c
(gdb) py-bt
Traceback (most recent call first):
0x7ffff6b66b20
File "/usr/lib/python3.6/multiprocessing/process.py", line 307, in __init__
self._config = {'authkey': AuthenticationString(os.urandom(32)),
File "/usr/lib/python3.6/multiprocessing/process.py", line 320, in <module>
_current_process = _MainProcess()
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
<built-in method __import__ of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap>", line 1017, in _handle_fromlist
File "/usr/lib/python3.6/multiprocessing/context.py", line 5, in <module>
from . import process
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
<built-in method __import__ of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap>", line 1017, in _handle_fromlist
File "/usr/lib/python3.6/multiprocessing/__init__.py", line 16, in <module>
from . import context
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
File "/usr/lib/python3.6/concurrent/futures/process.py", line 53, in <module>
import multiprocessing
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
File "/usr/lib/python3.6/concurrent/futures/__init__.py", line 17, in <module>
from concurrent.futures.process import ProcessPoolExecutor
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
File "/usr/lib/python3.6/asyncio/base_events.py", line 17, in <module>
import concurrent.futures
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
File "/usr/lib/python3.6/asyncio/__init__.py", line 21, in <module>
from .base_events import *
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
File "/usr/lib/python3/dist-packages/jinja2/asyncsupport.py", line 13, in <module>
import asyncio
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
File "/usr/lib/python3/dist-packages/jinja2/__init__.py", line 77, in _patch_async
from jinja2.asyncsupport import patch_all
File "/usr/lib/python3/dist-packages/jinja2/__init__.py", line 81, in <module>
_patch_async()
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
File "/usr/lib/python3/dist-packages/cloudinit/templater.py", line 23, in <module>
import jinja2
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
<built-in method __import__ of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap>", line 1017, in _handle_fromlist
File "/usr/lib/python3/dist-packages/cloudinit/config/cc_update_etc_hosts.py", line 52, in <module>
from cloudinit import templater
<built-in method exec of module object at remote 0x7ffff6bb9cd8>
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 678, in exec_module
File "<frozen importlib._bootstrap>", line 665, in _load_unlocked
File "<frozen importlib._bootstrap>", line 955, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 971, in _find_and_load
0x7ffff6bbf580
File "/usr/lib/python3/dist-packages/cloudinit/importer.py", line 15, in import_module
__import__(module_name)
File "/usr/lib/python3/dist-packages/cloudinit/importer.py", line 35, in find_module
mod = import_module(full_path)
File "/usr/lib/python3/dist-packages/cloudinit/stages.py", line 751, in _fixup_modules
mod_name, ['', type_utils.obj_name(config)], ['handle'])
File "/usr/lib/python3/dist-packages/cloudinit/stages.py", line 818, in run_section
mostly_mods = self._fixup_modules(raw_mods)
File "/usr/lib/python3/dist-packages/cloudinit/cmd/main.py", line 107, in run_module_section
(which_ran, failures) = mods.run_section(full_section_name)
File "/usr/lib/python3/dist-packages/cloudinit/cmd/main.py", line 416, in main_init
return (init.datasource, run_module_section(mods, name, name))
File "/usr/lib/python3/dist-packages/cloudinit/cmd/main.py", line 638, in status_wrapper
ret = functor(name, args)
File "/usr/lib/python3/dist-packages/cloudinit/util.py", line 2238, in log_time
ret = func(*args, **kwargs)
File "/usr/lib/python3/dist-packages/cloudinit/cmd/main.py", line 829, in main
get_uptime=True, func=functor, args=(name, args))
File "/usr/bin/cloud-init", line 11, in <module>
load_entry_point('cloud-init==17.1', 'console_scripts', 'cloud-init')()
(gdb)
We have the option to set the authkey to a different value post-
initialization, but there's no way to avoid using entropy when importing
this module.
** Also affects: python3.6 (Ubuntu)
Importance: Undecided
Status: New
** Changed in: python3.6 (Ubuntu)
Status: New => Triaged
** Changed in: cloud-init (Ubuntu)
Status: Incomplete => Triaged
--
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to cloud-init.
https://bugs.launchpad.net/bugs/1727358
Title:
cloud-init is slow to complete init on minimized images
Status in cloud-init:
Incomplete
Status in cloud-init package in Ubuntu:
Triaged
Status in python3.6 package in Ubuntu:
Triaged
Bug description:
http://paste.ubuntu.com/25816789/ for the full logs.
cloud-init is very slow to complete its initialization steps.
Specifically, the 'init' takes over 150 seconds.
Cloud-init v. 17.1 running 'init-local' at Wed, 25 Oct 2017 13:22:07 +0000. Up 2.39 seconds.
2017-10-25 13:22:07,157 - util.py[WARNING]: did not find either path /sys/class/dmi/id or dmidecode command
Cloud-init v. 17.1 running 'init' at Wed, 25 Oct 2017 13:22:16 +0000. Up 11.37 seconds.
ci-info: ++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++
ci-info: +--------+-------+-----------------+---------------+-------+-------------------+
ci-info: | Device | Up | Address | Mask | Scope | Hw-Address |
ci-info: +--------+-------+-----------------+---------------+-------+-------------------+
ci-info: | ens3: | True | 192.168.100.161 | 255.255.255.0 | . | 52:54:00:bb:ad:fb |
ci-info: | ens3: | True | . | . | d | 52:54:00:bb:ad:fb |
ci-info: | lo: | True | 127.0.0.1 | 255.0.0.0 | . | . |
ci-info: | lo: | True | . | . | d | . |
ci-info: | sit0: | False | . | . | . | . |
ci-info: +--------+-------+-----------------+---------------+-------+-------------------+
ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info++++++++++++++++++++++++++++++++
ci-info: +-------+---------------+---------------+-----------------+-----------+-------+
ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags |
ci-info: +-------+---------------+---------------+-----------------+-----------+-------+
ci-info: | 0 | 0.0.0.0 | 192.168.100.1 | 0.0.0.0 | ens3 | UG |
ci-info: | 1 | 192.168.100.0 | 0.0.0.0 | 255.255.255.0 | ens3 | U |
ci-info: | 2 | 192.168.100.1 | 0.0.0.0 | 255.255.255.255 | ens3 | UH |
ci-info: +-------+---------------+---------------+-----------------+-----------+-------+
2017-10-25 13:24:38,187 - util.py[WARNING]: Failed to resize filesystem (cmd=('resize2fs', '/dev/root'))
2017-10-25 13:24:38,193 - util.py[WARNING]: Running module resizefs (<module 'cloudinit.config.cc_resizefs' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_resizefs.py'>) failed
Generating public/private rsa key pair.
Your identification has been saved in /etc/ssh/ssh_host_rsa_key.
Your public key has been saved in /etc/ssh/ssh_host_rsa_key.pub.
The key fingerprint is:
SHA256:LKNlCqqOgPB8KBKGfPhFO5Rs6fDMnAvVet/W9i4vLxY root@cloudimg
The key's randomart image is:
+---[RSA 2048]----+
| |
| . + |
| . O . |
|o . % +. |
|++.o %=.S |
|+=ooo=+o. . .E |
|* +.+. . o o. |
|=. . . .=. |
|+. . B= |
+----[SHA256]-----+
Generating public/private dsa key pair.
Your identification has been saved in /etc/ssh/ssh_host_dsa_key.
Your public key has been saved in /etc/ssh/ssh_host_dsa_key.pub.
The key fingerprint is:
SHA256:dNWNyBHqTUCl820/vL0dEhOVDFYJzqr1WeuqV1PAmjk root@cloudimg
The key's randomart image is:
+---[DSA 1024]----+
| .oo=X==o|
| =* *+.|
| . = .B . |
| . o =E.. .|
| S .oo+o..|
| o ..*+.|
| . +.=o|
| .o *|
| .o..++|
+----[SHA256]-----+
Generating public/private ecdsa key pair.
Your identification has been saved in /etc/ssh/ssh_host_ecdsa_key.
Your public key has been saved in /etc/ssh/ssh_host_ecdsa_key.pub.
The key fingerprint is:
SHA256:N3RTlPa7KU5ryq6kJAO8Tiq90ub4P1DGSofn6jFkM3k root@cloudimg
The key's randomart image is:
+---[ECDSA 256]---+
| .o. |
| .o |
| o . o. . |
| +.* . . . .|
| .*XE S o .|
| oo++ . . . |
| oo= o . . . o|
|o.Oo. + o . .o.o |
|oB=+.. . .o++o. |
+----[SHA256]-----+
Generating public/private ed25519 key pair.
Your identification has been saved in /etc/ssh/ssh_host_ed25519_key.
Your public key has been saved in /etc/ssh/ssh_host_ed25519_key.pub.
The key fingerprint is:
SHA256:B6B/1SyUB/TFPfmU1ADIotnD+wjISO5L2JZkWe2lDUA root@cloudimg
The key's randomart image is:
+--[ED25519 256]--+
| .E . o++.o+++|
| + ...++...++|
| o o=o.o.+ .o|
| .o oo=+o . .|
| o+o .+ So. |
| =o.o .... |
|..= . o |
| o. . . |
| .. |
+----[SHA256]-----+
sudo: unable to resolve host cloudimg: Resource temporarily unavailable
Cloud-init v. 17.1 running 'modules:config' at Wed, 25 Oct 2017 13:24:39 +0000. Up 155.13 seconds.
2017-10-25 13:24:40,289 - util.py[WARNING]: Failed to run command to import ubuntu ssh ids
2017-10-25 13:24:40,291 - util.py[WARNING]: ssh-import-id failed for: ubuntu ['cyphermox']
2017-10-25 13:24:40,292 - util.py[WARNING]: Running module ssh-import-id (<module 'cloudinit.config.cc_ssh_import_id' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ssh_import_id.py'>) failed
Cloud-init v. 17.1 running 'modules:final' at Wed, 25 Oct 2017 13:24:41 +0000. Up 156.51 seconds.
ci-info: no authorized ssh keys fingerprints found for user ubuntu.
Cloud-init v. 17.1 finished at Wed, 25 Oct 2017 13:24:41 +0000. Datasource DataSourceNoCloud [seed=/dev/vdb][dsmode=net]. Up 156.83 seconds
This does not seem to be caused by ssh key generation (I tried to disable it, with no keytypes enabled there is still > 150 s delay), not does it seem to be related to the resizing operation.
I suspect some other step requiring randomness to generate some kind
of ID, but I don't know.
To manage notifications about this bug go to:
https://bugs.launchpad.net/cloud-init/+bug/1727358/+subscriptions
