Re: [PATCH 1/5] random: fix crng_ready() test

[Srivatsa S. Bhat]

On 4/13/18 10:00 AM, Theodore Y. Ts'o wrote:
> On Fri, Apr 13, 2018 at 03:05:01PM +0200, Stephan Mueller wrote:
>>
>> What I would like to point out that more and more folks change to 
>> getrandom(2). As this call will now unblock much later in the boot cycle, 
>> these systems see a significant departure from the current system behavior.
>>
>> E.g. an sshd using getrandom(2) would be ready shortly after the boot finishes 
>> as of now. Now it can be a matter minutes before it responds. Thus, is such 
>> change in the kernel behavior something for stable?

[...]

> I was a little worried that on VM's this could end up causing things
> to block for a long time, but an experiment on a GCE VM shows that
> isn't a problem:
> 
> [    0.000000] Linux version 4.16.0-rc3-ext4-00009-gf6b302ebca85 (tytso@cwcc) (gcc version 7.3.0 (Debian 7.3.0-15)) #16 SMP Thu Apr 12 16:57:17 EDT 2018
> [    1.282220] random: fast init done
> [    3.987092] random: crng init done
> [    4.376787] EXT4-fs (sda1): re-mounted. Opts: (null)
> 
> There are some desktops where the "crng_init done" report doesn't
> happen until 45-90 seconds into the boot.  I don't think I've seen
> reports where it takes _minutes_ however.  Can you give me some
> examples of such cases?

On a Photon OS VM running on VMware ESXi, this patch causes a boot speed
regression of 5 minutes :-( [ The VM doesn't have haveged or rng-tools
(rngd) installed. ]

[    1.420246] EXT4-fs (sda2): re-mounted. Opts: barrier,noacl,data=ordered
[    1.469722] tsc: Refined TSC clocksource calibration: 1900.002 MHz
[    1.470707] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x36c65c1a9e1, max_idle_ns: 881590695311 ns
[    1.474249] clocksource: Switched to clocksource tsc
[    1.584427] systemd-journald[216]: Received request to flush runtime journal from PID 1
[  346.620718] random: crng init done

Interestingly, the boot delay is exacerbated on VMs with large amounts
of RAM. For example, the delay is not so noticeable (< 30 seconds) on a
VM with 2GB memory, but goes up to 5 minutes on an 8GB VM.

Also, cloud-init-local.service seems to be the one blocking for entropy
here. systemd-analyze critical-chain shows:

The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

multi-user.target @6min 1.283s
ââvmtoolsd.service @6min 1.282s
  ââcloud-final.service @6min 366ms +914ms
    ââcloud-config.service @5min 59.174s +1.190s
      ââcloud-config.target @5min 59.172s
        ââcloud-init.service @5min 47.423s +11.744s
          ââsystemd-networkd-wait-online.service @5min 45.999s +1.420s
            ââsystemd-networkd.service @5min 45.975s +21ms
              âânetwork-pre.target @5min 45.973s
                ââcloud-init-local.service @241ms +5min 45.687s
                  ââsystemd-remount-fs.service @222ms +13ms
                    ââsystemd-fsck-root.service @193ms +26ms
                      ââsystemd-journald.socket @188ms
                        ââ-.mount @151ms
                          ââsystem.slice @161ms
                            ââ-.slice @151ms

It would be great if this CVE can be fixed somehow without causing boot speed
to spike from ~20 seconds to 5 minutes, as that makes the system pretty much
unusable. I can workaround this by installing haveged, but ideally an in-kernel
fix would be better. If you need any other info about my setup or if you have
a patch that I can test, please let me know!

Thank you very much!

Regards,
Srivatsa
VMware Photon OS