Bug 1096072 - systemd hangs on initrd-switch-root.service for 1.5 minutes when booting
systemd hangs on initrd-switch-root.service for 1.5 minutes when booting
Status: RESOLVED FIXED
Classification: openSUSE
Product: openSUSE Distribution
Classification: openSUSE
Component: Basesystem
Leap 15.0
Other Other
: P5 - None : Normal (vote)
: ---
Assigned To: Pedro Monreal Gonzalez
E-mail List
:
Depends on:
Blocks: 1099634
  Show dependency treegraph
 
Reported: 2018-06-05 16:50 UTC by Antonio Larrosa
Modified: 2021-02-19 09:21 UTC (History)
11 users (show)

See Also:
Found By: ---
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---


Attachments
journalctl --system --since "1 hour ago" (138.57 KB, text/plain)
2018-06-05 16:50 UTC, Antonio Larrosa
Details
systemd-analyze blame (2.65 KB, text/plain)
2018-06-05 16:51 UTC, Antonio Larrosa
Details
journalctl -b (2.56 MB, text/x-log)
2018-06-19 22:01 UTC, Antonio Larrosa
Details
backtrace of gpt generator stuck waiting for available random data (2.96 KB, text/plain)
2018-06-21 13:39 UTC, Antonio Larrosa
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Antonio Larrosa 2018-06-05 16:50:15 UTC
Created attachment 772558 [details]
journalctl --system --since "1 hour ago"

After upgrading my Leap 42.3 system to Leap 15.0 it takes very long to boot up. Of that time, around 1.5 minutes (1:34) is spent on initrd-switch-root.service while it seems the system is doing nothing (at least the hard disk light stops blinking for all that time).

The system stops just after:

Jun 05 18:32:41 geeko systemd[1]: Switching root.
Jun 05 18:32:41 geeko systemd-journald[154]: Journal stopped

And then continues with:
Jun 05 18:34:16 geeko systemd-journald[154]: Received SIGTERM from PID 1 (systemd).
Jun 05 18:34:16 geeko kernel: systemd: 20 output lines suppressed due to ratelimiting
Jun 05 18:34:16 geeko kernel: EXT4-fs (sda6): re-mounted. Opts: acl,user_xattr
Jun 05 18:34:16 geeko systemd-journald[414]: Journal started
Jun 05 18:34:16 geeko systemd-journald[414]: Runtime journal (/run/log/journal/f7cb102c5d6c079fd36e51615215ef87) is 8.0M, max 383.4M, 375.4M free.
Jun 05 18:32:43 geeko systemd[1]: systemd 234 running in system mode. (+PAM -AUDIT +SELINUX -IMA +APPARMOR -SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT -GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN2 -IDN default-hierarchy=hybrid)
Jun 05 18:32:43 geeko systemd[1]: Detected architecture x86-64.
Jun 05 18:32:43 geeko systemd[1]: Set hostname to <geeko>.
Jun 05 18:34:13 geeko systemd[1]: system-generators terminated by signal ALRM.
Jun 05 18:34:16 geeko apparmor.systemd[420]: Restarting AppArmor
Jun 05 18:34:13 geeko systemd[1]: Execution failed: Protocol error

Note the systemd log from 18:32:43 being written after other logs from 18:34:16 and the "Execution failed: Protocol error" message which might be related.

I tried enabling debug-shell.service, but that is started after systemd unfreezes. I attach the full output of journalctl --system --since "1 hour ago". Btw, for some reason, in this system, journalctl only shows the journal logs from the current boot, never showing logs from previous boots. 

Also, just in case it rings a bell, I also have this problem on the same system: https://bugzilla.opensuse.org/show_bug.cgi?id=1096050
Comment 1 Antonio Larrosa 2018-06-05 16:51:37 UTC
Created attachment 772559 [details]
systemd-analyze blame

The output of systemd-analyze blame
Comment 2 Franck Bui 2018-06-19 09:45:17 UTC
Antonio, could you try to boot with the debug logs enabled (add "printk.devkmsg=on debug" to the kernel command line) and attach the logs (the output of "journalctl -b") ?

Thanks.
Comment 3 Antonio Larrosa 2018-06-19 22:01:21 UTC
Created attachment 774572 [details]
journalctl -b

Sure, this is the output of journalctl -b
Comment 4 Franck Bui 2018-06-20 09:52:08 UTC
Unfortunately there're no more info: one of the generator is failing but I can't see which one.

The list of the generators is:

> systemd[414]: Spawned /usr/lib/systemd/system-generators/ibft-rule-generator as 415.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/lvm2-activation-generator as 416.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/nfs-server-generator as 417.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-cryptsetup-generator as 418.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-debug-generator as 419.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-fstab-generator as 420.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-getty-generator as 421.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-gpt-auto-generator as 422.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-hibernate-resume-generator as 423.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-insserv-generator as 424.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-openqa-generator as 425.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-rc-local-generator as 426.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-system-update-generator as 427.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-sysv-generator as 428.
> systemd[414]: Spawned /usr/lib/systemd/system-generators/systemd-veritysetup-generator as 429.

It would be interesting to figure out which one fails.

You can do so by masking one generator by one and run "systemctl daemon-reload" which should run all generators again assuming that the issue can be reproduced while reloading systemd configuration.

To mask one generator you can do for example:

$ ln -s /dev/null /etc/systemd/system-generators/ibft-rule-generator
Comment 5 Antonio Larrosa 2018-06-20 16:21:36 UTC
Thanks for the idea. I didn't know about those generators nor that they could be masked.

I tried running "systemctl daemon-reload" but that returns inmediately, so I have to reboot each time I want to test the generators.

After trying to mask a few of them, having no luck, masking a few more, having no luck, and then going one by one... I noticed something strange.

I masked all generators and the delay was gone. The system booted up fine.
Then I removed the mask for systemd-gpt-auto-generator (or said another way, I only enabled the systemd-gpt-auto-generator) and the delay returned.
I masked it again and the delay was gone.
Then I removed the mask for systemd-debug-generator and the delay returned again.
I masked it again and the delay was fixed once more.
Then I removed the mask for systemd-cryptsetup-generator and that one didn't influence the delay. The system boots up fine if only systemd-cryptsetup-generator is enabled.
I removed the mask for systemd-hibernate-resume-generator (so only systemd-cryptsetup-generator and this one are enabled) and the delay returned...

Does that behaviour say anything to you? I'll continue testing one by one and try to find out the set of generators that seem to introduce the delay if any of them is enabled, but the process is slow.

I guess there's no way to get a shell at that point of the boot process, is it?
Comment 6 Dr. Werner Fink 2018-06-21 08:58:45 UTC
Just an idea how to debug supposed the mkinitrd (compability) script is able to handle this ... a line in /usr/lib/systemd/system/initrd-switch-root.service like

  ExecStartPre=-/bin/bash -c "top -b -c -d .5 > /dev/shm/switch-root.log"

before the actual ExecStart= line ... but mkinitrd/dracut has to detect that /usr/bin/top has to be added to initrd
Comment 7 Dr. Werner Fink 2018-06-21 10:45:51 UTC
(In reply to Dr. Werner Fink from comment #6)
> Just an idea how to debug supposed the mkinitrd (compability) script is able
> to handle this ... a line in
> /usr/lib/systemd/system/initrd-switch-root.service like
> 
>   ExecStartPre=-/bin/bash -c "top -b -c -d .5 > /dev/shm/switch-root.log"
> 
> before the actual ExecStart= line ... but mkinitrd/dracut has to detect that
> /usr/bin/top has to be added to initrd

I'vde added

  ExecStartPre=-/bin/bash -c "(exec -a '@top' /usr/bin/top -b -c -d .1 -w 512 > /dev/shm/switch-root.log )&"
  ExecStartPre=-/bin/bash -c "/usr/bin/sleep 2"

before the final ExecStart= ... and installed with

  dracut_args='--install /usr/bin/top' mkinitrd

...
Comment 8 Franck Bui 2018-06-21 12:31:01 UTC
Hi Werner,

Actually we did a debug session this morning with Antonio and it appears that all generators are blocked while reading from /dev/random.

So as you suspect there might be something wrong with haveged or the starvation of the entropy.

Antonio should post the backtrace of one of the generator so we have a clear picture why random bytes is needed at that point.
Comment 9 Antonio Larrosa 2018-06-21 13:39:24 UTC
Created attachment 774878 [details]
backtrace of gpt generator stuck waiting for available random data
Comment 10 Franck Bui 2018-06-21 13:49:56 UTC
hum, what's this thing:

#8  0x00007ffff64dd751 in _gcry_random_selftest (report=report@entry=0x7ffff642b2a0 <reporter>) at random.c:581
#9  0x00007ffff642c1ea in run_random_selftests () at fips.c:589
#10 _gcry_fips_run_selftests (extended=extended@entry=0) at fips.c:736

Werner any idea ?
Comment 11 Franck Bui 2018-06-21 15:44:07 UTC
Talked to Antonio privately and it appears that gcrypt run in fips mode for some *unknown* reasons. This has the side effect to run some self tests on each program linked to libgcrypt (I think) and those self tests exhaust /dev/urandom somehow.

The gcrypt fips mode is activated by the presence of /etc/gcrypt/fips_enabled file. And removing this file solves this issue as well as bug #1096050.

So I guess the question is now how was this file created at all.
Comment 12 Antonio Larrosa 2018-06-21 15:47:08 UTC
*** Bug 1096050 has been marked as a duplicate of this bug. ***
Comment 13 Franck Bui 2018-06-21 15:49:59 UTC
Since this started happening after upgrading 42.3 to 15.0, I guess this file was created during the upgrade process.

Ludwig any idea ?
Comment 14 Franck Bui 2018-06-21 15:53:25 UTC
OTOH not sure if running gcrypt in fips mode is supposed to cause troubles...

Pedro as you're one of libcgrypt maintainer perhaps you can shed some ligth ?
Comment 15 Dr. Werner Fink 2018-06-21 16:59:19 UTC
(In reply to Franck Bui from comment #10)
> hum, what's this thing:
> 
> #8  0x00007ffff64dd751 in _gcry_random_selftest
> (report=report@entry=0x7ffff642b2a0 <reporter>) at random.c:581
> #9  0x00007ffff642c1ea in run_random_selftests () at fips.c:589
> #10 _gcry_fips_run_selftests (extended=extended@entry=0) at fips.c:736
> 
> Werner any idea ?

Ahh .. yes, the FIPS tests do drain the current entropy of the system. This is a known problem of FIPS

I was not aware that FIPS had been enabled on Leap 15.  Also I've never understood why those FIPS tests done at first usage of FIPS do drain the entropy  of a system without restoring or refilling the entropy as not existin entropy make the system unusable ... no program can use real random numbers anymore upto the point where the entropy gets filled again. Now on switch root every program wich had not been rebased to the new root (by using chroot(2)) and protected with a leading `@' byte in its argv[0] will be killed by systemd and/or do removed name space.

To get this final solved the kernel has to collect entropy from any source it can use in initrd, e.g. using the jitter on the CPUs

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=bb5530e4082446aac3a3d69780cd4dbfa4520013
Comment 16 Dr. Werner Fink 2018-06-21 17:12:22 UTC
Adding security team as they know more about FIPS and haveged (which becomes useless in initrd at switcing root as not running at this point) ... and maybe they should be aware about the jitter entropy rng. Also Marcus as he is the maintainer of FIPS, and Daniel as it would be feature to restore/increase the the entropy aftger the FIPS tests done in dracut-fips
Comment 17 Antonio Larrosa 2018-06-21 17:51:13 UTC
Just (In reply to Franck Bui from comment #13)
> Since this started happening after upgrading 42.3 to 15.0, I guess this file
> was created during the upgrade process.
> 

Yes, the problems (both this and the sudo issue) started happening after upgrading to 15.0, but note that it seems the file wasn't created during the upgrade process. At least, it has an mtime of 2017-10-16 at 13:42:00 and the upgrade was done on 2018-06-03.

I checked old zypper logs and it seems on 2017-10-16 I ran "zypper in libgcrypt20-hmac" at 13:41:42 for some reason I can't remember. So it matches with probably the %post script of the package creating it, can it be? At least, the package description mentions FIPS. Just in case it matters, libgcrypt20-hmac-1.6.1-39.1 was the package installed at that time, from the openSUSE 42.3 Update repository, while I currently have libgcrypt20-hmac-1.8.2-lp150.4.2 .
Comment 18 Dr. Werner Fink 2018-06-22 06:25:30 UTC
(In reply to Franck Bui from comment #11)
> Talked to Antonio privately and it appears that gcrypt run in fips mode for
> some *unknown* reasons. This has the side effect to run some self tests on
> each program linked to libgcrypt (I think) and those self tests exhaust
> /dev/urandom somehow.
> 
> The gcrypt fips mode is activated by the presence of
> /etc/gcrypt/fips_enabled file. And removing this file solves this issue as
> well as bug #1096050.
> 
> So I guess the question is now how was this file created at all.

I don't have a /etc/gcrypt/fips_enabled nor /etc/gcrypt/ around here ... to which package does those belogn to?
Comment 19 Dr. Werner Fink 2018-06-22 06:59:13 UTC
Found this in my current Tumbleweed

 zgrep -i jitter /proc/config.gz 
 CONFIG_CRYPTO_JITTERENTROPY=y

hmm ... is this also available on Leap 15 / SLES 15 ?
Comment 20 Marcus Meissner 2018-06-22 07:11:02 UTC
it actually is on sle15 and leap 15.
Comment 21 Dr. Werner Fink 2018-06-22 07:19:29 UTC
(In reply to Marcus Meissner from comment #20)
> it actually is on sle15 and leap 15.

Hmm ... then the question rises: why do the fips test not restore the entropy level after the tests? It should be possible to save a copy of the current entropy and write it back after the tests, the kernel has an API exactly for this, see ioctl RNDADDENTROPY in man:random(4).  Drain the entropy makes the system unusable.
Comment 22 Dr. Werner Fink 2018-06-22 07:49:15 UTC
I'm not able to install the rng-tools for Tumbleweed ... the source pacakge seems to be there but the package is not installable ... also this package seems to miss a dracut part to be usable in initrd
Comment 23 Franck Bui 2018-06-22 07:49:26 UTC
(In reply to Dr. Werner Fink from comment #18).
> 
> I don't have a /etc/gcrypt/fips_enabled nor /etc/gcrypt/ around here ... to
> which package does those belogn to?

Perhaps /proc/sys/crypto/fips_enabled exists and contains a value different from 0 ?

Otherwise your issue is probably different.
Comment 24 Dr. Werner Fink 2018-06-22 07:52:15 UTC
(In reply to Franck Bui from comment #23)
> (In reply to Dr. Werner Fink from comment #18).
> > 
> > I don't have a /etc/gcrypt/fips_enabled nor /etc/gcrypt/ around here ... to
> > which package does those belogn to?
> 
> Perhaps /proc/sys/crypto/fips_enabled exists and contains a value different
> from 0 ?
> 
> Otherwise your issue is probably different.

noether:~ # cat /proc/sys/crypto/fips_enabled
cat: /proc/sys/crypto/fips_enabled: No such file or directory
noether:~ # cat /proc/sys/crypto/            
cat: /proc/sys/crypto/: No such file or directory
Comment 25 Ludwig Nussel 2018-06-22 08:10:07 UTC
fips is not expected to work on leap 15. Clearly a SLE feature. How could this activate itself?
Comment 26 Franck Bui 2018-06-22 08:30:22 UTC
Ok I'm re-assigning this bug to Pedro as he's the maintainer of libgcrypt.

So basically there're 2 issues here:

 - FIPS mode has been unexpectedly activated (via the creation 
   of /etc/gcrypt/fips_enabled). Would be interesting to figure out how IMHO.

 - When the FIPS mode is activated, it exhausts /dev/urandom pool which
   may lead to such issues during the boot process.
Comment 27 Dr. Werner Fink 2018-06-22 08:52:05 UTC
rpm -qf /etc/gcrypt/fips_enabled
Comment 28 Dr. Werner Fink 2018-06-22 08:53:38 UTC
(In reply to Ludwig Nussel from comment #25)
> fips is not expected to work on leap 15. Clearly a SLE feature. How could
> this activate itself?

IMHO this may lead to similar problems as I guess that fips test might also drain the entropy on a SLES 15
Comment 29 Franck Bui 2018-06-22 09:16:03 UTC
(In reply to Dr. Werner Fink from comment #28)
> IMHO this may lead to similar problems as I guess that fips test might also
> drain the entropy on a SLES 15

Agreed although in practice the HWs targeted by SLES might have their entropy pool initialized before it is needed.
Comment 30 Dr. Werner Fink 2018-06-26 13:13:40 UTC
On OBS there is below home:WernerFink:branches:security/haveged a haveged package simply hacked to survive the switch root.  That is it will not be killed by systemd and remain to fill the /dev/random during switch root.

Don't know if this would make a difference ... for my problem this seems not to help as the 10 seconds delay at switch root remains and seems to be an other problem.  Nevertheless it might help in this case.
Comment 31 Dr. Werner Fink 2018-06-28 12:04:18 UTC
(In reply to Dr. Werner Fink from comment #30)
> On OBS there is below home:WernerFink:branches:security/haveged a haveged
> package simply hacked to survive the switch root.  That is it will not be
> killed by systemd and remain to fill the /dev/random during switch root.
> 
> Don't know if this would make a difference ... for my problem this seems not
> to help as the 10 seconds delay at switch root remains and seems to be an
> other problem.  Nevertheless it might help in this case.

I've finished this version of haveged and it works flawless ... the haveged starts with `@usr/sbin/haveged' if a `/etc/initrd-release' exists as well as uses a signal handler on SIGIO to set an atomic variable which will then trigger a chroot followed by a execv(3) in the new /sysroot ... for this I have replaced the select(2) by pselect(2) system call as well as do control the signals by using sigprocmask(2) to be able to catch signals during and before pselect(2) ... this seems to work:

-- Reboot --
Jun 28 13:43:03 noether haveged[202]: Got Signal SIGIO
Jun 28 13:43:03 noether haveged[202]: haveged: restart in new root: /sysroot

ps aux  | grep haveged
root       202  0.0  0.0  12160  7452 ?        Ss   13:42   0:00 @usr/sbin/haveged -w 1024 -v 0 -F
root      3102  0.0  0.0   7116   924 pts/0    S+   13:58   0:00 grep --color=auto haveged

ls -l /proc/202/exe
lrwxrwxrwx 1 root root 0 Jun 28 13:43 /proc/202/exe -> /usr/sbin/haveged
Comment 32 Dr. Werner Fink 2018-06-29 07:24:18 UTC
As the OBS has finished the build my hacked version of haveged for Leap 15.0 x86_64 I'd like to ask if this makes a difference.  For this the binaries can be downloaded by

 osc getbinaries home:WernerFink:branches:security/haveged openSUSE_Leap_15.0 x86_64 haveged-1.9.2-lp150.134.1.x86_64.rpm

and installed with

 sudo rpm -Uhv binaries/haveged-1.9.2-lp150.134.1.x86_64.rpm
 sudo mkinitrd

the library package is not required as the change is only in the daemon its self.

Does this version of haveged makes a difference at (re)boot?
Comment 33 Antonio Larrosa 2018-06-29 10:49:47 UTC
I enabled fips again and rebooted to be sure the problem was reproduced again.
Then I installed the haveged package from your home, ran mkinitrd and rebooted. 
With your package, I can confirm the boot delay doesn't happen anymore.

Btw, the problem with sudo (bsc#1096050) still continues happening as I guess that's related to fips being enabled and not the the entropy pool being empty.
Comment 34 Dr. Werner Fink 2018-06-29 12:08:19 UTC
(In reply to Antonio Larrosa from comment #33)
> I enabled fips again and rebooted to be sure the problem was reproduced
> again.
> Then I installed the haveged package from your home, ran mkinitrd and
> rebooted. 
> With your package, I can confirm the boot delay doesn't happen anymore.
>

Thanks a lot ... that is now it makes sense to change the hack (currently using a signal handler instead a local socket to trigger the chroot/execv).
Comment 35 Dr. Werner Fink 2018-06-29 12:12:12 UTC
(In reply to Antonio Larrosa from comment #33)
> 
> Btw, the problem with sudo (bsc#1096050) still continues happening as I
> guess that's related to fips being enabled and not the the entropy pool
> being empty.

Then bsc#1096050 is not duplicate, isn't it?
Comment 36 Markos Chandras 2018-08-10 06:45:51 UTC
(In reply to Dr. Werner Fink from comment #35)
> (In reply to Antonio Larrosa from comment #33)
> > 
> > Btw, the problem with sudo (bsc#1096050) still continues happening as I
> > guess that's related to fips being enabled and not the the entropy pool
> > being empty.
> 
> Then bsc#1096050 is not duplicate, isn't it?

Any confirmation on that please?^
Comment 37 Antonio Larrosa 2018-10-24 09:34:09 UTC
I confirm what I stated in #c33: this bug is fixed by Werner's haveged package from #c32, while bsc#1096050 is not fixed by that package and just got fixed by disabling fips. So I would say they're not duplicates.
Comment 38 Pedro Monreal Gonzalez 2021-02-10 15:47:30 UTC
(In reply to Antonio Larrosa from comment #37)
> I confirm what I stated in #c33: this bug is fixed by Werner's haveged
> package from #c32, while bsc#1096050 is not fixed by that package and just
> got fixed by disabling fips. So I would say they're not duplicates.

This looks fixed! Is there anything left to do here or can we close it?
Comment 39 Antonio Larrosa 2021-02-10 17:19:53 UTC
(In reply to Pedro Monreal Gonzalez from comment #38)
> This looks fixed! Is there anything left to do here or can we close it?

If the question was addressed to me, yes, I think it can be closed.