service urandom-seed takes too long on boot

Open

Details

7 participants

Alex Sassmannshausen
Brice Waegeneire
Leo Famulari
Ludovic Courtès
raid5atemyhomework
Robert Vollmert
Stefan

Owner: unassigned

Submitted by: Robert Vollmert

Severity: important

Debbugs page

Robert Vollmert wrote on 25 Jun 2019 11:12

Recipients:(address . bug-guix@gnu.org)

Message-ID:F88CEF04-9BFA-4886-8A2D-AD84AE278D07@vllmrt.net

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: file

Attachment: Screenshot 2019-06-25 at 19.55.12.png

Alex Sassmannshausen wrote on 26 Jun 2019 02:41

Recipients:(address . bug-guix@gnu.org)(address . 36380@debbugs.gnu.org)

Message-ID:871rzg3cpw.fsf@gmail.com

Hi Robert,

Robert Vollmert <rob@vllmrt.net> writes:

Toggle quote (9 lines)

> 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

Leo Famulari wrote on 26 Jun 2019 08:47

Recipients:(name . Robert Vollmert)(address . rob@vllmrt.net)(address . 36380@debbugs.gnu.org)

Message-ID:20190626154721.GA2999@jasmine.lan

On Tue, Jun 25, 2019 at 08:12:28PM +0200, Robert Vollmert wrote:

Toggle quote (4 lines)

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

Toggle quote (5 lines)

> 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

Robert Vollmert wrote on 26 Jun 2019 09:02

Recipients:(name . Leo Famulari)(address . leo@famulari.name)(address . 36380@debbugs.gnu.org)

Message-ID:51B21C84-982D-4DC0-AEA7-A32EA0F855B8@vllmrt.net

Toggle quote (9 lines)

> 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

Ludovic Courtès wrote on 27 Jun 2019 08:20

Recipients:(name . Leo Famulari)(address . leo@famulari.name)

Message-ID:87zhm3xdfu.fsf@gnu.org

Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

Toggle quote (7 lines)

> 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

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

Ludovic Courtès wrote on 27 Jun 2019 08:20

control message for bug #36380

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87y31nxdfe.fsf@gnu.org

severity 36380 important

quit

Leo Famulari wrote on 27 Jun 2019 12:03

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

Recipients:(name . Ludovic Courtès)(address . ludo@gnu.org)

Message-ID:20190627190314.GA7403@jasmine.lan

On Thu, Jun 27, 2019 at 05:20:21PM +0200, Ludovic Courtès wrote:

Toggle quote (9 lines)

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

Leo Famulari wrote on 27 Jun 2019 12:19

Recipients:(name . Robert Vollmert)(address . rob@vllmrt.net)(address . 36380@debbugs.gnu.org)

Message-ID:20190627191915.GA9591@jasmine.lan

On Wed, Jun 26, 2019 at 06:02:03PM +0200, Robert Vollmert wrote:

Toggle quote (4 lines)

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

Ludovic Courtès wrote on 27 Jun 2019 13:00

Recipients:(name . Leo Famulari)(address . leo@famulari.name)

Message-ID:87r27evlwa.fsf@gnu.org

Leo Famulari <leo@famulari.name> skribis:

Toggle quote (14 lines)> 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.

Toggle quote (2 lines)

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

Still, what else could be taking this long?

Thanks,

Ludo’.

Robert Vollmert wrote on 27 Jun 2019 23:47

Recipients:(name . Leo Famulari)(address . leo@famulari.name)

Message-ID:EA773339-2CC9-486E-99B8-A2E71B34467E@vllmrt.net

Toggle quote (6 lines)

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

Leo Famulari wrote on 28 Jun 2019 10:24

Recipients:(name . Robert Vollmert)(address . rob@vllmrt.net)

Message-ID:20190628172401.GA17073@jasmine.lan

On Fri, Jun 28, 2019 at 08:47:35AM +0200, Robert Vollmert wrote:

Toggle quote (7 lines)

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

Leo Famulari wrote on 11 Jul 2019 10:44

Recipients:(name . Robert Vollmert)(address . rob@vllmrt.net)

Message-ID:20190711174455.GA30457@jasmine.lan

On Fri, Jun 28, 2019 at 01:24:01PM -0400, Leo Famulari wrote:

Toggle quote (4 lines)

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

Ludovic Courtès wrote on 11 Jul 2019 14:33

Recipients:(name . Leo Famulari)(address . leo@famulari.name)

Message-ID:87k1contnw.fsf@gnu.org

Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

Toggle quote (8 lines)

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

Robert Vollmert wrote on 17 Jul 2019 14:04

related article (Debian)

Recipients:(address . 36380@debbugs.gnu.org)

Message-ID:B4E22190-D378-45C8-A2B8-DC7D59EF9B52@vllmrt.net

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

Brice Waegeneire wrote on 22 Mar 2020 01:43

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

Recipients:(address . 36380@debbugs.gnu.org)

Message-ID:a24b84c858011117fd9ea7129af7232c@waegenei.re

Hello,

It would be nice if we could reproduce this issue.

Robert Vollmert <rob@vllmrt.net> writes:

Toggle quote (4 lines)

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

Leo Famulari wrote on 22 Mar 2020 13:19

Recipients:(name . Brice Waegeneire)(address . brice@waegenei.re)(address . 36380@debbugs.gnu.org)

Message-ID:20200322201919.GC16716@jasmine.lan

On Sun, Mar 22, 2020 at 08:43:33AM +0000, Brice Waegeneire wrote:

Toggle quote (5 lines)

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

Stefan wrote on 27 Dec 2020 07:00

service urandom-seed takes too long on boot

Recipients:(address . 36380@debbugs.gnu.org)

Message-ID:2C14BF51-2755-4315-AC75-26F71F93884D@vodafonemail.de

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)

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

Leo Famulari wrote on 27 Dec 2020 15:09

Recipients:(name . Stefan)(address . stefan-guix@vodafonemail.de)(address . 36380@debbugs.gnu.org)

Message-ID:X+kURC9LmmFz5Ks7@jasmine.lan

On Sun, Dec 27, 2020 at 04:00:23PM +0100, Stefan wrote:

Toggle quote (4 lines)

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

Stefan wrote on 27 Dec 2020 15:28

Recipients:(name . Leo Famulari)(address . leo@famulari.name)(address . 36380@debbugs.gnu.org)

Message-ID:6A711ED5-B7D9-4276-88C4-08C7ADE2DFC0@vodafonemail.de

Hi Leo!

Toggle quote (3 lines)

> 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

Leo Famulari wrote on 28 Dec 2020 18:51

Recipients:(name . Stefan)(address . stefan-guix@vodafonemail.de)(address . 36380@debbugs.gnu.org)

Message-ID:X+qZp6UZ9db5yt19@jasmine.lan

On Mon, Dec 28, 2020 at 12:28:09AM +0100, Stefan wrote:

Toggle quote (3 lines)

> “-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 :)

raid5atemyhomework wrote on 7 Feb 2021 07:23

service urandom-seed takes too long on boot

Recipients:(name . 36380@debbugs.gnu.org)(address . 36380@debbugs.gnu.org)

Message-ID:WNVyEQuIt5aHwSlkxpYNZx49vGxO5K8ABy-Vd4_g98Pr5B-IHsJmu5qlsnAq2z_YSuJ8l5giKdR0NcuUMsQzUX6OJ6Hb7D-Bjcb3aR9WmuI=@protonmail.com

```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)))))))))
```

Your comment

Commenting via the web interface is currently disabled.

To comment on this conversation send an email to 36380@patchwise.org

To respond to this issue using the mumi CLI, first switch to it

mumi current 36380

Then, you may apply the latest patchset in this issue (with sign off)

mumi am -- -s

Or, compose a reply to this issue

mumi compose

Or, send patches to this issue

mumi send-email *.patch

is:open	open issues
is:done	closed issues
submitter:<who>	search issue submitter
author:<who>	search by message author
date:yesterday..now	search by issue date
mdate:3m..2d	search by message date