bug#36380: service urandom-seed takes too long on boot

bug#36380: service urandom-seed takes too long on boot

[Robert Vollmert]

[-- Attachment #1: Type: text/plain, Size: 430 bytes --]

On my VPS, booting takes forever (long enough that for a long
time I thought the install had failed). I just rebooted again,
and it took over 7 minutes, see attached screenshot.

I would suggest skipping the seeding from /dev/hwrng by default
if /var/lib/random-seed is available. I’m assuming here that my
problem is not too rare — if it is, an option to disable the
seeding from /dev/hwrng seems like a good idea.


[-- Attachment #2.1: Type: text/html, Size: 968 bytes --]

[-- Attachment #2.2: Screenshot 2019-06-25 at 19.55.12.png --]
[-- Type: image/png, Size: 43183 bytes --]

bug#36380: service urandom-seed takes too long on boot

[Alex Sassmannshausen]

Hi Robert,

Robert Vollmert <rob@vllmrt.net> writes:

> On my VPS, booting takes forever (long enough that for a long
> time I thought the install had failed). I just rebooted again,
> and it took over 7 minutes, see attached screenshot.
>
> I would suggest skipping the seeding from /dev/hwrng by default
> if /var/lib/random-seed is available. I’m assuming here that my
> problem is not too rare — if it is, an option to disable the
> seeding from /dev/hwrng seems like a good idea.

I'm not sure I'm qualified on best practices with regard to urandom, but
anecdotally, my servers are booting pretty fast, within a minute,
consistently.  This is even when booting a qemu virtual image rather
than a VPS.

Perhaps something else is going on here?

Alex

bug#36380: service urandom-seed takes too long on boot

[Leo Famulari]

[-- Attachment #1: Type: text/plain, Size: 1392 bytes --]

On Tue, Jun 25, 2019 at 08:12:28PM +0200, Robert Vollmert wrote:
> On my VPS, booting takes forever (long enough that for a long
> time I thought the install had failed). I just rebooted again,
> and it took over 7 minutes, see attached screenshot.

Yikes, that's way too long. Can you say what VPS it is?

> I would suggest skipping the seeding from /dev/hwrng by default
> if /var/lib/random-seed is available. I’m assuming here that my
> problem is not too rare — if it is, an option to disable the
> seeding from /dev/hwrng seems like a good idea.

Originally I added the HWRNG read specifically the for VM / VPS use case
[0], where the first boot environment is relatively deterministic. I
agree it's superfluous if the random-seed file is handled properly but
it's nice to unconditionally have this other entropy source that avoids
the pitfalls of file-based entropy seeding.

Ideally the hypervisor would seed the guest's HWRNG interface with the
host's /dev/urandom, which would avoid significant delays. It seems they
are using some other more limited resource instead.

Does anyone else have an opinion or experience with this issue? It would
be great to know how widespread it is.

[0]
https://git.savannah.gnu.org/cgit/guix.git/commit/?id=9a56cf2b5b4970843c215091ea9823a67e077310
https://lists.gnu.org/archive/html/guix-devel/2017-12/msg00096.html

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#36380: service urandom-seed takes too long on boot

[Robert Vollmert]

> On 26. Jun 2019, at 17:47, Leo Famulari <leo@famulari.name> wrote:
> 
> On Tue, Jun 25, 2019 at 08:12:28PM +0200, Robert Vollmert wrote:
>> On my VPS, booting takes forever (long enough that for a long
>> time I thought the install had failed). I just rebooted again,
>> and it took over 7 minutes, see attached screenshot.
> 
> Yikes, that's way too long. Can you say what VPS it is?

It’s with arpnetworks.com, their default “small" VPS. I don’t
really know more; here’s some dmesg output that might be relevant,
happy to provide more info.

[    0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1.1 04/01/2014
[    0.000000] Hypervisor detected: KVM
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000] kvm-clock: cpu 0, msr 2a782001, primary cpu clock
[    0.000000] kvm-clock: using sched offset of 1160634602574609 cycles
[    0.000002] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000004] tsc: Detected 3066.774 MHz processor

bug#36380: service urandom-seed takes too long on boot

[Leo Famulari]

[-- Attachment #1: Type: text/plain, Size: 419 bytes --]

On Wed, Jun 26, 2019 at 06:02:03PM +0200, Robert Vollmert wrote:
> It’s with arpnetworks.com, their default “small" VPS. I don’t
> really know more; here’s some dmesg output that might be relevant,
> happy to provide more info.

Okay, I've asked them about it on IRC:

http://irclogger.arpnetworks.com/irclogger_log/arpnetworks?date=2019-06-27,Thu

Let's wait and see what they think about the issue.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#36380: service urandom-seed takes too long on boot

[Ludovic Courtès]

Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

> On Tue, Jun 25, 2019 at 08:12:28PM +0200, Robert Vollmert wrote:
>> On my VPS, booting takes forever (long enough that for a long
>> time I thought the install had failed). I just rebooted again,
>> and it took over 7 minutes, see attached screenshot.
>
> Yikes, that's way too long. Can you say what VPS it is?

We had a “bug report” at
<https://distrowatch.com/weekly.php?issue=20190624#guixsd>, which may be
due to the same issue:

  The first time I loaded Guix the boot process took an unusually long
  time.  At one point the system appeared to lock up for about five
  minutes before continuing.  In the end, from boot menu to graphical
  login screen, the start-up time totalled about ten minutes.

The author says they were running Guix in VirtualBox.  I’m glad Robert’s
bug report has more info than that one.  :-)

What should we do?

Ludo’.

bug#36380: service urandom-seed takes too long on boot

[Leo Famulari]

[-- Attachment #1: Type: text/plain, Size: 945 bytes --]

On Thu, Jun 27, 2019 at 05:20:21PM +0200, Ludovic Courtès wrote:
> We had a “bug report” at
> <https://distrowatch.com/weekly.php?issue=20190624#guixsd>, which may be
> due to the same issue:
> 
>   The first time I loaded Guix the boot process took an unusually long
>   time.  At one point the system appeared to lock up for about five
>   minutes before continuing.  In the end, from boot menu to graphical
>   login screen, the start-up time totalled about ten minutes.

Perhaps, but if the reason for the slowness on their first boot was a
suboptimal /dev/hwrng source, I would expect it to be equally slow for
each boot, since we unconditionally read 64 bytes each time.

However, their next sentence says, "Curiously, after the first boot,
Guix started up considerably faster, generally taking less than a minute
to arrive at the login screen."

They are using an old machine with a spinning disk, so who knows...

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#36380: service urandom-seed takes too long on boot

[Ludovic Courtès]

Leo Famulari <leo@famulari.name> skribis:

> On Thu, Jun 27, 2019 at 05:20:21PM +0200, Ludovic Courtès wrote:
>> We had a “bug report” at
>> <https://distrowatch.com/weekly.php?issue=20190624#guixsd>, which may be
>> due to the same issue:
>> 
>>   The first time I loaded Guix the boot process took an unusually long
>>   time.  At one point the system appeared to lock up for about five
>>   minutes before continuing.  In the end, from boot menu to graphical
>>   login screen, the start-up time totalled about ten minutes.
>
> Perhaps, but if the reason for the slowness on their first boot was a
> suboptimal /dev/hwrng source, I would expect it to be equally slow for
> each boot, since we unconditionally read 64 bytes each time.

Perhaps VirtualBox behaves this way?  For instance, the VM was rebooted
but VirtualBox itself was still running, and thus it had a good random
seed to start from on the second boot (does that make sense?).  I guess
we should try.

> They are using an old machine with a spinning disk, so who knows...

Still, what else could be taking this long?

Thanks,
Ludo’.

bug#36380: service urandom-seed takes too long on boot

[Robert Vollmert]

> On 27. Jun 2019, at 21:03, Leo Famulari <leo@famulari.name> wrote:

> Perhaps, but if the reason for the slowness on their first boot was a
> suboptimal /dev/hwrng source, I would expect it to be equally slow for
> each boot, since we unconditionally read 64 bytes each time.

It’s 512 bytes, not that that should fundamentally change anything.

bug#36380: service urandom-seed takes too long on boot

[Leo Famulari]

[-- Attachment #1: Type: text/plain, Size: 781 bytes --]

On Fri, Jun 28, 2019 at 08:47:35AM +0200, Robert Vollmert wrote:
> > On 27. Jun 2019, at 21:03, Leo Famulari <leo@famulari.name> wrote:
> > Perhaps, but if the reason for the slowness on their first boot was a
> > suboptimal /dev/hwrng source, I would expect it to be equally slow for
> > each boot, since we unconditionally read 64 bytes each time.
> 
> It’s 512 bytes, not that that should fundamentally change anything.

Oh right, my bad. It's been a while...

Anyways, this should either work immediately or fail. Aside from
getrandom(2), which we aren't using here, nothing related to this stuff
should ever block, and if it does then it's a bug we need to work
around.

So, I suggest we add a 1 second timeout to this read.

I can work on that next week.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#36380: service urandom-seed takes too long on boot

[Leo Famulari]

[-- Attachment #1: Type: text/plain, Size: 504 bytes --]

On Fri, Jun 28, 2019 at 01:24:01PM -0400, Leo Famulari wrote:
> So, I suggest we add a 1 second timeout to this read.
> 
> I can work on that next week.

I did try working on this, after reading the code in (guix scripts
offload (call-with-timeout)).

But, I couldn't make it work at all — it always fails, with all the
services depending on urandom-seed-service failing, breaking the boot.

I don't know how to debug or work interactively in this part of the
system.

Can anybody help?

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#36380: service urandom-seed takes too long on boot

[Ludovic Courtès]

Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

> On Fri, Jun 28, 2019 at 01:24:01PM -0400, Leo Famulari wrote:
>> So, I suggest we add a 1 second timeout to this read.
>> 
>> I can work on that next week.
>
> I did try working on this, after reading the code in (guix scripts
> offload (call-with-timeout)).

The ‘start’ method of the ‘urandom-seed’ Shepherd service runs in PID 1,
so we certainly don’t want to fiddle with SIGALRM in that context, which
is what ‘call-with-timeout’ does.

Instead, I think we should use ‘select’ with a timeout:

  (call-with-input-file "/dev/hwrng"
    (lambda (port)
      (match (select (list port) '() '() 3)
        …)))

I think we can then use ‘get-bytevector-n!’, assuming it doesn’t block
if less than COUNT bytes are available (I’m not sure this is the case.)

HTH!

Ludo’.

bug#36380: related article (Debian)

[Robert Vollmert]

Just ran across this article about Debian dealing with similar issues.

https://daniel-lange.com/archives/152-hello-buster.html

One of the suggested work-arounds is to rely on virtio_rng on
virtual machines, but it seems Guix already uses that on my machine,
so perhaps it doesn’t help:

rob@garp ~$ cat /sys/devices/virtual/misc/hw_random/rng_available 
virtio_rng.0 
rob@garp ~$ cat /sys/devices/virtual/misc/hw_random/rng_current 
virtio_rng.0

bug#36380: service urandom-seed takes too long on boot

[Brice Waegeneire]

Hello,

It would be nice if we could reproduce this issue.

Robert Vollmert <rob@vllmrt.net> writes:
> Just ran across this article about Debian dealing with similar issues.
> 
> https://daniel-lange.com/archives/152-hello-buster.html

This article has been updated since then with a section[0] about a fix
authored by Linus[1][2] and merged in Linux 5.4. The gist of it that now
`getrandom()' will actively try to collect entropy in early boot, if it
is missing, by using the CPU jitter. The Debian wiki is saying the 
same[3].

Since we are using actually using Linux-libre 5.4 as the default kernel
this issue should probably be closed.

[0]: 
https://daniel-lange.com/archives/152-hello-buster.html#linustotherescue
[1]: 
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=3f2dc2798b81531fd93a3b9b7c39da47ec689e55
[2]: 
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=50ee7529ec4500c88f8664560770a7a1b65db72b
[3]: https://wiki.debian.org/BoottimeEntropyStarvation

Brice.

bug#36380: service urandom-seed takes too long on boot

[Leo Famulari]

On Sun, Mar 22, 2020 at 08:43:33AM +0000, Brice Waegeneire wrote:
> This article has been updated since then with a section[0] about a fix
> authored by Linus[1][2] and merged in Linux 5.4. The gist of it that now
> `getrandom()' will actively try to collect entropy in early boot, if it
> is missing, by using the CPU jitter. The Debian wiki is saying the same[3].

The issue here is not related to getrandom() or our kernel. I think the
bug is still relevant.

The Guix system unconditionally reads from /dev/hwrng if it exists, and
there is no reason for that to take a noticeable amount of time.

But this bug report revealed that some VPS providers have a broken
deployment that does cause delays. Who knows how they are feeding
/dev/hwrng... they would not reply to my questions.

It doesn't really matter though, the problem is ours to fix.

We need to make this read time out after a second, but in the past I
could not figure out how to do this without crashing the system (I'm not
a strong Schemer).

Help is still wanted!

bug#36380: service urandom-seed takes too long on boot

[Stefan]

Hi!

I’m running Guix in qemu on a NAS. The boot takes sometimes more than 30 minutes, probably waiting to start the urandom-seed service.

Guix is using virtio_rng:

stefan@guix ~$ cat /sys/devices/virtual/misc/hw_random/rng_available
virtio_rng.0 
stefan@guix ~$ cat /sys/devices/virtual/misc/hw_random/rng_current
virtio_rng.0
stefan@guix ~$ guix describe
Generation 1	26. Dezember 2020 15:06:11	(aktuell)
  guix 4969b51
    Repository-URL: https://git.savannah.gnu.org/git/guix.git
    Branch: master
    Commit: 4969b51d175497bfcc354c91803e9d70542b7113


This may be relevant information from dmesg:

[    0.194324] random: get_random_u64 called from __kmem_cache_create+0x30/0x460 with crng_init=0
…
[    3.271767] random: fast init done
…
[    3.497369] random: crng init done
…
[   21.228829] shepherd[1]: Service file-systems has been started.
[   21.243838] shepherd[1]: Service user-homes has been started.
[ 2182.735965] shepherd[1]: Service urandom-seed has been started.
[ 2182.737229] shepherd[1]: Service user-processes has been started.
…

Sometimes the urandom-seed service takes “just” 200 seconds – still a lot.

Interestingly during this time-out the system can’t be pinged, the networking with dhclient doesn't seem to be done.

The Guix installer iso is not using the urandom-seed service and does not suffer from this delay.


The host kernel and qemu are rather old:

~$ uname -a
Linux aaaaaaaa 4.4.59+ #25426 SMP PREEMPT Mon Dec 14 18:48:50 CST 2020 x86_64 GNU/Linux synology_apollolake
~$ /usr/local/bin/qemu-system-x86_64 --version
QEMU emulator version 2.12.1 (-dirty)
Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers


Qemu is invoked with these arguments concerning random:

-cpu host,+smap,+rdseed,+erms,+smep,+fsgsbase,+3dnowprefetch,+rdtscp,+pdpe1gb,+rdrand,+osxsave,+xsave,+tsc-deadline,+movbe,+x2apic,+pdcm,+xtpr,+tm2,+est,+vmx,+ds_cpl,+dtes64,+pclmuldq,+pbe,+tm,+ht,+ss,+acpi,+ds,+vme -object rng-random,id=objrng0,filename=/dev/random -device virtio-rng-pci,rng=objrng0,id=rng0,bus=pci.0,addr=0x1c

The full qemu command is huge. I can provide it on request.


Bye

Stefan

bug#36380: service urandom-seed takes too long on boot

[Leo Famulari]

On Sun, Dec 27, 2020 at 04:00:23PM +0100, Stefan wrote:
> Qemu is invoked with these arguments concerning random:
> 
> -cpu host,+smap,+rdseed,+erms,+smep,+fsgsbase,+3dnowprefetch,+rdtscp,+pdpe1gb,+rdrand,+osxsave,+xsave,+tsc-deadline,+movbe,+x2apic,+pdcm,+xtpr,+tm2,+est,+vmx,+ds_cpl,+dtes64,+pclmuldq,+pbe,+tm,+ht,+ss,+acpi,+ds,+vme -object rng-random,id=objrng0,filename=/dev/random -device virtio-rng-pci,rng=objrng0,id=rng0,bus=pci.0,addr=0x1c

What does the argument "filename=/dev/random" do? Does it use the host's
/dev/random to provide entropy to the QEMU guest?

bug#36380: service urandom-seed takes too long on boot

[Stefan]

Hi Leo!

> What does the argument "filename=/dev/random" do? Does it use the host's
> /dev/random to provide entropy to the QEMU guest?

Yes, see [1]:

“-object rng-random,id=id,filename=/dev/random
Creates a random number generator backend which obtains entropy from a device on the host. The id parameter is a unique ID that will be used to reference this entropy backend from the virtio-rng device. The filename parameter specifies which file to obtain entropy from and if omitted defaults to /dev/urandom.”


Bye

Stefan


[1] https://www.qemu.org/docs/master/system/invocation.html#hxtool-10

bug#36380: service urandom-seed takes too long on boot

[Leo Famulari]

On Mon, Dec 28, 2020 at 12:28:09AM +0100, Stefan wrote:
> “-object rng-random,id=id,filename=/dev/random
> Creates a random number generator backend which obtains entropy from a device on the host. The id parameter is a unique ID that will be used to reference this entropy backend from the virtio-rng device. The filename parameter specifies which file to obtain entropy from and if omitted defaults to /dev/urandom.”

I see, so there is the problem.

It should either be changed to "filename=/dev/urandom", or the QEMU
rng-random mechanism should be disabled.

We still need to implement a timeout to workaround this kind of
misconfiguration... help wanted :)

bug#36380: service urandom-seed takes too long on boot

[raid5atemyhomework via Bug reports for GNU Guix]

```scheme
(define (get-bytevector-n-timed port count max-time)
  "Read COUNT octets from PORT, blocking as necessary and return a
bytevector containing the octets read, and taking no more than
MAX-TIME seconds.  If fewer bytes are available, a bytevector
smaller than COUNT is returned."

  (define (get-time)
    (let* ((pair   (gettimeofday))
           (secs   (car pair))
           (usecs  (cdr pair)))
      (+ secs (* 0.000001 usecs))))

  (let* ((start-time  (get-time))
         (end-time    (+ start-time max-time))
         (buf         (make-bytevector count)))
    (let loop ((offset  0))
      (let ((current-time (get-time)))
        (cond
          ((= offset count)
            buf)
          ((>= current-time end-time)
            (let ((newbuf (make-bytevector offset)))
              (bytevector-copy! buf 0 newbuf 0 offset)
              newbuf))
          (else
            (let* ((result     (select (list port) '() '() (- end-time current-time)))
                   (readable?  (not (null? (car result)))))
              (if readable?
                (begin
                  ;; read only one byte at a time, as we cannot be sure
                  ;; that the given port will have more than one byte
                  ;; available and that ports will not block if we ask
                  ;; for more than one byte.
                  (get-bytevector-n! port buf offset 1)
                  (loop (+ offset 1)))
                (loop offset)))))))))
```