Entropy on Autobuilders - Revision history

Rpurdie at 18:06, 10 November 2017

2017-11-10T18:06:19Z

Rpurdie at 18:05, 10 November 2017

2017-11-10T18:05:53Z

← Older revision		Revision as of 18:05, 10 November 2017
Line 66:		Line 66:

	With a larger pool of entropy on the hosts, we should be better placed for more predictable builds. I also believe we could drop rng-tools from our images.		With a larger pool of entropy on the hosts, we should be better placed for more predictable builds. I also believe we could drop rng-tools from our images.

			The delay at clocksource when entropy is low is caused by the rng_virtio driver:

			[ 3.844026] 3 initcall mod_init+0x0/0x188 returned -19 after 1 usecs
			[ 3.844580] 3 calling mod_init+0x0/0x49 @ 1
			[ 3.844993] 3 initcall mod_init+0x0/0x49 returned -19 after 0 usecs
			[ 3.845543] 3 calling virtio_rng_driver_init+0x0/0x12 @ 1
			[ 23.211133] 3 initcall virtio_rng_driver_init+0x0/0x12 returned 0 after 18911181 usecs
			[ 23.212170] 3 calling agp_init+0x0/0x27 @ 1
			[ 23.212609] 3 Linux agpgart interface v0.103
			[ 23.213080] 3 initcall agp_init+0x0/0x27 returned 0 after 459 usecs
			[ 23.213659] 3 calling agp_intel_init+0x0/0x2a @ 1


			(setting initcall_debug and looking at KERN_DEBUG messages as per init/main.c in the kernel)

MichaelHalstead: line wraps

2017-11-10T01:51:59Z

line wraps

← Older revision		Revision as of 01:51, 10 November 2017
Line 13:		Line 13:

	Useful notes:		Useful notes:
	a) Setting VERBOSE=very in /etc/default/rcS makes the boot logs more		a) Setting VERBOSE=very in /etc/default/rcS makes the boot logs more useful
	useful		b) The kernel has two rng init messages, "random: fast init done" happens first. "random: crng init done" happens later once the system has at least 128 bits of entropy.
	b) The kernel has two rng init messages, "random: fast init done"		c) You can check available entropy with
	happens first. "random: crng init done" happens later once the		'cat /proc/sys/kernel/random/entropy_avail'.
	system has at least 128 bits of entropy.
	c) You can check available entropy with 'cat
	/proc/sys/kernel/random/entropy_avail'.
	d) You can check if the virtio rng is being used with		d) You can check if the virtio rng is being used with
	'cat /sys/class/misc/hw_random/rng_current'		'cat /sys/class/misc/hw_random/rng_current'
	e) You can eat all the entropy on the host with "dd if=/dev/random		e) You can eat all the entropy on the host with
	of=/dev/null bs=1"		"dd if=/dev/random of=/dev/null bs=1"

	Using the dd command whilst booting an image in parallel I could make the images hang. They appear to hang not at host key generation but when launching rngd from rng-tools. This is because it opens /dev/hwrng and reads from it to perform some tests of randomness mandated by FIPS. The process will not deamonise until this has completed. Until that happens it blocks the boot, meaning we don't reach the login prompt which is shown later in the init process.		Using the dd command whilst booting an image in parallel I could make the images hang. They appear to hang not at host key generation but when launching rngd from rng-tools. This is because it opens /dev/hwrng and reads from it to perform some tests of randomness mandated by FIPS. The process will not deamonise until this has completed. Until that happens it blocks the boot, meaning we don't reach the login prompt which is shown later in the init process.

Rpurdie: Created page with "Entropy in our image testing on our autobuilders When you run "bitbake -c testimage", the system boots that image under qemu and runs tests against it. We've noticed ..."

2017-11-10T00:08:29Z

Created page with "Entropy in our image testing on our autobuilders When you run "bitbake <image> -c testimage", the system boots that image under qemu and runs tests against it. We've noticed ..."

New page

Entropy in our image testing on our autobuilders

When you run "bitbake <image> -c testimage", the system boots that image under qemu and runs tests against it. We've noticed occasional hangs of these images. A while ago we realised there was an entropy issue, particularly on qemuppc but also sometimes on qemux86 and others.

We therefore made sure that:
a) We enabled CONFIG_HW_RANDOM_VIRTIO in the kernels
b) We add "-device virtio-rng-pci" to the qemu commandline
c) We add rng-tools to the qemu images

This means that entropy from the host can pass through to the VMs. That entropy is used more heavily at machine startup, by the kernel itself and for the generation of ssh keys for the image amongst other things.

We were still seeing occasional hangs.

Useful notes:
a) Setting VERBOSE=very in /etc/default/rcS makes the boot logs more
useful
b) The kernel has two rng init messages, "random: fast init done"
happens first. "random: crng init done" happens later once the
system has at least 128 bits of entropy.
c) You can check available entropy with 'cat
/proc/sys/kernel/random/entropy_avail'.
d) You can check if the virtio rng is being used with
'cat /sys/class/misc/hw_random/rng_current'
e) You can eat all the entropy on the host with "dd if=/dev/random
of=/dev/null bs=1"

Using the dd command whilst booting an image in parallel I could make the images hang. They appear to hang not at host key generation but when launching rngd from rng-tools. This is because it opens /dev/hwrng and reads from it to perform some tests of randomness mandated by FIPS. The process will not deamonise until this has completed. Until that happens it blocks the boot, meaning we don't reach the login prompt which is shown later in the init process.

I also tweaked a kernel to add the entropy value to printk. To do this, I added:

int random_get_ent_count(void)
{
int ent_count = ENTROPY_BITS(&input_pool);
return ent_count;
}

to drivers/char/random.c and then tweaked the code in kernel/printk/printk.c to:

extern int random_get_ent_count(void);
[...]
if (!buf)
return snprintf(NULL, 0, "[%5lu.000000] %d ", (unsigned long)ts, random_get_ent_count());

return sprintf(buf, "[%5lu.%06lu] %d ",
(unsigned long)ts, rem_nsec / 1000, random_get_ent_count());

which is a touch evil but effective.

With this change I could clearly see the crng message isn't shown until the system entropy raises. I could also see that the rng-tools userspace isn't needed to pass the hwrng to the kernel as its clearly being effective much earlier in the boot process. This is done by the "hwrng" kernel thread which you can see in "ps".

I found that the kernel will block early in the boot process when entropy is restricted, e.g.:

[ 2.137765] 47 00:06: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
[ 2.731526] 47 tsc: Refined TSC clocksource calibration: 2194.931 MHz
[ 2.732341] 47 clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x1fa37e3a27f, max_idle_ns: 440795212633 ns
[ 73.870555] 47 Linux agpgart interface v0.103
[ 73.905820] 47 brd: module loaded
[ 74.013546] 47 loop: module loaded
[ 74.017805] 47 Uniform Multi-Platform E-IDE driver
[...]
[ 76.464840] 47 Freeing unused kernel memory: 1496K
[ 76.588870] 47 random: fast init done

so early boot hangs can be an entropy restriction problem until the first "fast init done" message appears.

The "crng init done" message controls when /dev/random becomes accessible. That is used by connman/wpa_supplicant in our images.

The conclusion I've reached from all of this is that the hosts we run the builds on are actually where we're running out of entropy and we need run haveged or rng-tools there.

With a larger pool of entropy on the hosts, we should be better placed for more predictable builds. I also believe we could drop rng-tools from our images.

← Older revision		Revision as of 18:06, 10 November 2017
Line 4:		Line 4:

	We therefore made sure that:		We therefore made sure that:
	a) We enabled CONFIG_HW_RANDOM_VIRTIO in the kernels		a) We enabled CONFIG_HW_RANDOM_VIRTIO in the kernels
	b) We add "-device virtio-rng-pci" to the qemu commandline		b) We add "-device virtio-rng-pci" to the qemu commandline
	c) We add rng-tools to the qemu images		c) We add rng-tools to the qemu images

	This means that entropy from the host can pass through to the VMs. That entropy is used more heavily at machine startup, by the kernel itself and for the generation of ssh keys for the image amongst other things.		This means that entropy from the host can pass through to the VMs. That entropy is used more heavily at machine startup, by the kernel itself and for the generation of ssh keys for the image amongst other things.
Line 13:		Line 13:

	Useful notes:		Useful notes:
	a) Setting VERBOSE=very in /etc/default/rcS makes the boot logs more useful		a) Setting VERBOSE=very in /etc/default/rcS makes the boot logs more useful
	b) The kernel has two rng init messages, "random: fast init done" happens first. "random: crng init done" happens later once the system has at least 128 bits of entropy.		b) The kernel has two rng init messages, "random: fast init done" happens first. "random: crng init done" happens later once the system has at least 128 bits of entropy.
	c) You can check available entropy with		c) You can check available entropy with
	'cat /proc/sys/kernel/random/entropy_avail'.		'cat /proc/sys/kernel/random/entropy_avail'.
	d) You can check if the virtio rng is being used with		d) You can check if the virtio rng is being used with
	'cat /sys/class/misc/hw_random/rng_current'		'cat /sys/class/misc/hw_random/rng_current'
	e) You can eat all the entropy on the host with		e) You can eat all the entropy on the host with
	"dd if=/dev/random of=/dev/null bs=1"		"dd if=/dev/random of=/dev/null bs=1"

Line 69:		Line 69:
	The delay at clocksource when entropy is low is caused by the rng_virtio driver:		The delay at clocksource when entropy is low is caused by the rng_virtio driver:

	[ 3.844026] 3 initcall mod_init+0x0/0x188 returned -19 after 1 usecs		[ 3.844026] 3 initcall mod_init+0x0/0x188 returned -19 after 1 usecs
	[ 3.844580] 3 calling mod_init+0x0/0x49 @ 1		[ 3.844580] 3 calling mod_init+0x0/0x49 @ 1
	[ 3.844993] 3 initcall mod_init+0x0/0x49 returned -19 after 0 usecs		[ 3.844993] 3 initcall mod_init+0x0/0x49 returned -19 after 0 usecs
	[ 3.845543] 3 calling virtio_rng_driver_init+0x0/0x12 @ 1		[ 3.845543] 3 calling virtio_rng_driver_init+0x0/0x12 @ 1
	[ 23.211133] 3 initcall virtio_rng_driver_init+0x0/0x12 returned 0 after 18911181 usecs		[ 23.211133] 3 initcall virtio_rng_driver_init+0x0/0x12 returned 0 after 18911181 usecs
	[ 23.212170] 3 calling agp_init+0x0/0x27 @ 1		[ 23.212170] 3 calling agp_init+0x0/0x27 @ 1
	[ 23.212609] 3 Linux agpgart interface v0.103		[ 23.212609] 3 Linux agpgart interface v0.103
	[ 23.213080] 3 initcall agp_init+0x0/0x27 returned 0 after 459 usecs		[ 23.213080] 3 initcall agp_init+0x0/0x27 returned 0 after 459 usecs
	[ 23.213659] 3 calling agp_intel_init+0x0/0x2a @ 1		[ 23.213659] 3 calling agp_intel_init+0x0/0x2a @ 1


	(setting initcall_debug and looking at KERN_DEBUG messages as per init/main.c in the kernel)		(setting initcall_debug and looking at KERN_DEBUG messages as per init/main.c in the kernel)