cloud-init is slow to complete init on minimized images

Could you run
  cloud-init collect-logs
And then attach the cloud-init.tar.gz

Also, Can you provide some information on what you were running?
 " cloud-init is slow to complete init on minimized images "
How can I recreate this?

One curious thing there is:
 2017-10-25 13:22:07,157 - util.py[WARNING]: did not find either path /sys/class/dmi/id or dmidecode command

I suspect you have a kernel without CONFIG_DMI, which seems unfortunate or
possibly you're not on intel or arm64.

For large jumps in your log, it took ~ 9 seconds (13:22:07,337 -> 13:22:16,112) from the exit of cloud-init-local.service to get to 'cloud-init.service' printing its hello message. That is basically the time it took the network to come up.

Then we have a big jump (122 seconds):
 13:22:16,264 main.py[DEBUG]: no di_report found in config.
 13:24:38,088 stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.ubuntu.Distro'>

Those two lines in a vm I have on a openstack look like this:
2017-10-11 15:08:26,685 - main.py[DEBUG]: no di_report found in config.
2017-10-11 15:08:27,031 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2017-10-11 15:08:27,032 - stages.py[DEBUG]: Running module migrator (<module 'cloudinit.config.cc_migrator' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_migrator.py'>) with frequency always

That is ~ .5 seconds, which is not fast, but not 120 seconds either.

This is running on *minimized* images, with linux-kvm kernel; so there might well not be CONFIG_DMI. This is however not the issue (or most likely not). Tests are done in qemu, to simulate running the images in openstack for now (but they are meant to start in openstack without issues). It's simply more convient to test quickly.

An important point is that if I add a qemu RNG to the VM, the cloud-init 'init' steo takes only 2.071 seconds. It appears as though some part of the initialization might depend on sufficient entropy being available.

I will attach the log tarball shortly.

Please explain how you did this.
What did you download, what qemu commands did you run.

Thanks.

possibly related, but was fixed:
 https://bugs.python.org/issue25420

On Thu, Oct 26, 2017 at 01:43:12AM -0000, Scott Moser wrote:
> possibly related, but was fixed:
> https://bugs.python.org/issue25420

Does cloud-init itself consume entropy when it runs?

Only via 'import random' and light usage.

On Oct 25, 2017 11:21 PM, "Steve Langasek" <email address hidden>
wrote:

> On Thu, Oct 26, 2017 at 01:43:12AM -0000, Scott Moser wrote:
> > possibly related, but was fixed:
> > https://bugs.python.org/issue25420
>
> Does cloud-init itself consume entropy when it runs?
>
> --
> You received this bug notification because you are a member of Canonical
> Cloudware, which is subscribed to cloud-init.
> Matching subscriptions: cloud-init bugs
> 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:
> Incomplete
>
> 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/...

On Thu, Oct 26, 2017 at 10:37:37AM -0000, Scott Moser wrote:
> Only via 'import random' and light usage.

Even "light" usage is going to block at this point in the boot; can you give
me a pointer into where this is in the code, so I can try to assess if this
should be avoided?

You can grep through, the onlyi real function taht uses it is 'rand_str'.
and i'm not sure really why that would be called at the point that you're
seeing the slow down.

I think it more valuable for you to figure out why your environment is
causing this issue and fixing that rather than fixing cloud-init (and
subsequently all users of entropy).

Also, information about how you've come across this bug would be good.

On Thu, Oct 26, 2017 at 11:24 AM, Steve Langasek <
<email address hidden>> wrote:

> On Thu, Oct 26, 2017 at 10:37:37AM -0000, Scott Moser wrote:
> > Only via 'import random' and light usage.
>
> Even "light" usage is going to block at this point in the boot; can you
> give
> me a pointer into where this is in the code, so I can try to assess if this
> should be avoided?
>
> --
> You received this bug notification because you are a member of Canonical
> Cloudware, which is subscribed to cloud-init.
> Matching subscriptions: cloud-init bugs
> 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:
> Incomplete
>
> 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 ...

You can grep through, the onlyi real function taht uses it is 'rand_str'. and i'm not sure really why that would be called at the point that you're seeing the slow down.

I think it more valuable for you to figure out why your environment is causing this issue and fixing that rather than fixing cloud-init (and subsequently all users of entropy).

Also, information about how you've come across this bug would be good.

On Thu, Oct 26, 2017 at 03:56:24PM -0000, Scott Moser wrote:
> You can grep through, the onlyi real function taht uses it is
> 'rand_str'. and i'm not sure really why that would be called at the
> point that you're seeing the slow down.

> I think it more valuable for you to figure out why your environment is
> causing this issue and fixing that rather than fixing cloud-init (and
> subsequently all users of entropy).

We know that Ubuntu Cloud images must function in entropy-poor environments;
that's why we ship pollinate by default. If this particular delay is due to
cloud-init (or something it invoked) consuming entropy in early boot and
blocking, that is a problem, even if we do resolve the lack of an in-kernel
entropy source for this particular image and use case.

> Also, information about how you've come across this bug would be good.

I don't think I have ever seen the boot delay Mathieu is reporting, even
using the same image. So we're dependent on him to provide a reproducer.

You can easily reproduce this by running the following image in virt-manager with a default setup (and optionally add a RNG device if necessary):

https://launchpad.net/~cyphermox/+livefs/ubuntu/artful/ubuntu-cpc/+build/113428/+files/livecd.ubuntu-cpc.img

You'll want to add an additional disk to provide the metadata for cloud-init too. The exact iso file I have used is attached.

On Thu, Oct 26, 2017 at 06:07:57PM -0000, Mathieu Trudel-Lapierre wrote:
> You can easily reproduce this by running the following image in virt-
> manager with a default setup (and optionally add a RNG device if
> necessary):

The defaults in both virt-manager and libvirt change over time. For
reproducibility, it's helpful to have either a libvirt xml, or for maximum
reproducibility, a full qemu commandline from a running instance.

It really is *defaults* though, because you don't want to have any extra devices included that could throw off the boot (such as a RNG, which should not be added by default). In any case, I'll attach the xml I use as well, but I reproduce the build on a typical artful install.

The only important piece is to make sure the disks are VirtIO instead of IDE.

Libvirt XML for the VM.

this does also reproduce:
 qemu-system-x86_64 -enable-kvm \
    -device virtio-scsi-pci,id=virtio-scsi-xkvm \
    -device virtio-net-pci,netdev=net00 -netdev type=user,id=net00 \
    -drive file=my.img,id=disk00,if=none,format=qcow2,index=0 \
    -device virtio-blk,drive=disk00,serial=my.img \
    -drive file=my-seed.img,id=disk01,if=none,format=raw,index=1 \
    -device virtio-blk,drive=disk01,serial=my-seed.img \
    -snapshot -nographic -m 768

I don't plan on spending any more time on this unless there is some indication that cloud-init is doing something wrong. It really does seem to me to be entropy related, and some optimization in this image has broken what was functional elsewhere.

I've taken your kernel (vmlinuz-4.4.0-1009-kvm) and booted a "normal" cloud image with that kernel.
It hangs similarly (but for noticibly shorter time).

http://cloud-images.ubuntu.com/daily/server/artful/20171026.1/artful-server-cloudimg-amd64.img

I did have to disable the UEFI partition (vfat) since there were modules for your kernel in /lib.

$ qemu-img create -f qcow2 -b artful-cloud-image.img my.img
$ sudo mount-image-callback -vv my.img -- mchroot sed -i "/LABEL=UEFI/s/^/#/" /etc/fstab

$ xkvm --netdev=user --disk=my.img --disk=my-seed.img
-- -snapshot -m 768 -nographic -echr 0x05 -smp 2 -kernel vmlinuz-4.4.0-1009-kv
m -append "root=PARTUUID=9697fbdd-a35d-46d6-a51c-08bfab833468 console=ttyS0 syst
emd.log_target=console systemd.log_level=info systemd.log_target=console"

 qemu-system-x86_64 -enable-kvm -device virtio-scsi-pci,id=virtio-scsi-xkvm -device virtio-net-pci,netdev=net00 -netdev type=user,id=net00 -drive file=my.img,id=disk00,if=none,format=qcow2,index=0 -device virtio-blk,drive=disk00,serial=my.img -drive file=my-seed.img,id=disk01,if=none,format=raw,index=1 -device virtio-blk,drive=disk01,serial=my-seed.img -snapshot -m 768 -nographic -echr 0x05 -smp 2 -kernel vmlinuz-4.4.0-1009-kvm -append "root=PARTUUID=9697fbdd-a35d-46d6-a51c-08bfab833468 console=ttyS0 systemd.log_target=console systemd.log_level=info systemd.log_target=console"

...

log looks like this, and hangs there.
 http://paste.ubuntu.com/25832616/

Heres a diff of configs for the not working kernel and the working kernel.
$ diff -u config-4.4.0-59-generic config-4.4.0-1009-kvm |
   pastebinit -f diff
http://paste.ubuntu.com/25825403/

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

This looks like a chain of decisions that are all locally reasonable but when put together may not give a sensible result. cloud-init uses jinja2 as a sensible templating engine. jinja2 has async handling, which relies on asyncio. asyncio uses the multiprocessing module, which has both thread and process models; and the process model sets up a secure (true random) key to use for IPC.

Possible options for eliminating this use of urandom() include:
 - making jinja2 configurable to avoid asyncio and changing cloud-init to select this.
 - adjusting asyncio to only lazily import concurrent.futures.
 - adjusting asyncio to import concurrent.futures.thread.ThreadPoolExecutor directly, avoiding the side-effect of importing concurrent.futures.process.ProcessPoolExecutor.
 - make multiprocessing configurable to knowingly preseed an insecure auth key, and have cloud-init initialize multiprocessing directly before importing jinja2.

It may or may not be worth making any changes to at all, if the problem only manifests with current linux-kvm kernel config and can be fixed there by enabling in-kernel entropy sources. This should be measured on other clouds to see if there's any benefit to boot speed at large.

With python3-dbg and python3.6-examples installed, here's a commandline for getting to the problematic getrandom() call.

# PYTHONPATH=/usr/share/doc/python3.6/examples/gdb PYTHONHASHSEED=1 gdb -ex 'break getrandom' -ex run -ex 'cont 4' -ex "python import libpython" -ex py-bt --args /usr/bin/python3-dbg /usr/bin/cloud-init init

So far I've tested in GCE and Azure, and both platforms show no delays at all due to lack of entropy at boot. Unless someone identifies a platform where this actually causes boot delays other than linux-kvm, which is presumed due to a missing kernel option, there's no point in changing anything in cloud-init or python.

Marking as wont-fix for cloud-init for now as that would be a workaround for the base problem that is not desired right now. Adding linux-kvm to evaluate why this difference exists between linux-generic and linux-kvm

Status changed to 'Confirmed' because the bug affects multiple users.

In Openstack Newton (linux-kvm) with Centos 7 (latest cloud-image) with cloud-init 19.3, the delay is observed. I think this is due to the version that Centos ships with for python (2.7.5).

The problem is at the init-local stage. https://github.com/canonical/cloud-init/pull/103

here is the attached cloud-init.log

Ok, I got a question for all the interested folks out there;

What is we were to have a test case that run init-local and fails if random gets imported?

I'm looking at how this could be done, but that test could link to this bug and have people realise that they need to be careful about the random import.

Is it a good idea or a bad idea? I honestly cannot tell and I have the tendency to think it's a good idea...

Eric, this bug is about the linux-kvm kernel _in Ubuntu_. If you're seeing a cloud-init issue on Centos, then please file a separate bug.

Thanks!

Tracked in Github Issues as https://github.com/canonical/cloud-init/issues/3042