4000x "wpa_supplicant[1885]: random: Cannot read from /dev/random: Resource temporarily unavailable" log message when booting

Question

I recently added Linux Mint (19.3) as my new main OS on my Sony Vaio notebook.

Sometimes booting takes a bit of time and I found in jounrnalctl:

Feb 11 10:45:11 notebook kernel: microcode: microcode updated early to revision 0x2f, date = 2019-02-17
Feb 11 10:45:11 notebook kernel: Linux version 5.3.0-28-generic (buildd@lcy01-amd64-009) (gcc version 7.4.0 (Ubuntu 7.4.0-1ubuntu1~18.04.1)) #30~18.04.1-Ubuntu SMP Fri Jan 17 06:14:09 UT
Feb 11 10:45:11 notebook kernel: Command line: BOOT_IMAGE=/@/boot/vmlinuz-5.3.0-28-generic root=UUID=8d4f6dfa-1d63-4507-b9e1-37d639dca309 ro rootflags=subvol=@ quiet splash vt.handoff=1
[...]
Feb 11 10:45:14 notebook dbus-daemon[1080]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.12' (
Feb 11 10:45:14 notebook systemd[1]: Starting Hostname Service...
[...]
Feb 11 10:45:18 notebook systemd[1]: Started Update Manager automatic upgrades.
Feb 11 10:45:24 notebook wpa_supplicant[1085]: random: Cannot read from /dev/random: Resource temporarily unavailable
Feb 11 10:45:39 notebook dbus-daemon[1080]: [system] Failed to activate service 'org.freedesktop.hostname1': timed out (service_start_timeout=25000ms)
Feb 11 10:45:39 notebook NetworkManager[1086]: <info>  [1581414339.4088] hostname: hostname: hostnamed not used as proxy creation failed with: Fehler beim Aufruf von StartServiceByName f
Feb 11 10:45:39 notebook NetworkManager[1086]: <info>  [1581414339.4091] hostname: hostname changed from (none) to "notebook"
Feb 11 10:45:39 notebook NetworkManager[1086]: <info>  [1581414339.4104] dns-mgr[0x555fc095e1a0]: init: dns=systemd-resolved, rc-manager=symlink, plugin=systemd-resolved
Feb 11 10:45:39 notebook NetworkManager[1086]: <info>  [1581414339.4143] rfkill0: found WiFi radio killswitch (at /sys/devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/device:00/SNY5001:00/rfk
Feb 11 10:45:39 notebook NetworkManager[1086]: <info>  [1581414339.4155] rfkill2: found WiFi radio killswitch (at /sys/devices/pci0000:00/0000:00:1c.0/0000:02:00.0/ieee80211/phy0/rfkill2
Feb 11 10:45:39 notebook NetworkManager[1086]: <info>  [1581414339.4199] manager[0x555fc0968060]: rfkill: WiFi hardware radio set enabled
Feb 11 10:45:39 notebook NetworkManager[1086]: <info>  [1581414339.4200] manager[0x555fc0968060]: rfkill: WWAN hardware radio set enabled
Feb 11 10:45:39 notebook systemd[1]: Started Network Manager.
[...]
Feb 11 10:45:44 notebook dbus-daemon[1418]: [session uid=113 pid=1418] Successfully activated service 'ca.desrt.dconf'
Feb 11 10:45:44 notebook wpa_supplicant[1085]: random: Cannot read from /dev/random: Resource temporarily unavailable
Feb 11 10:45:44 notebook wpa_supplicant[1085]: random: Cannot read from /dev/random: Resource temporarily unavailable
Feb 11 10:45:44 notebook wpa_supplicant[1085]: random: Cannot read from /dev/random: Resource temporarily unavailable
Feb 11 10:45:44 notebook wpa_supplicant[1085]: random: Cannot read from /dev/random: Resource temporarily unavailable

... and this goes on from line 1448 to 5199!

After booting finished, I can get data when reading /dev/random, the init of random seems to finish much later:

Feb 11 10:46:27 notebook kernel: random: crng init done
Feb 11 10:46:27 notebook kernel: random: 7 urandom warning(s) missed due to ratelimiting

Any idea what is happening there?

There are just 2 log messages from 10:45:14 to 10:45:39 - could this be related?

Answer 1

There's an awful lot written on this subject on the World Wide Web. Simply put, Linux's /dev/random device is rather odd, and badly documented, compared to other operating systems. There's been an enormous amount of to-and-fro trying to fix it. The latest round, in this 28-year-old operating system kernel, was just last month.

the reason for the delay

The time that it takes to first seed the pseudo-random number generator in Linux, after bootstrap, is entirely dependent from how much hardware randomness the kernel can suck in from sources like the keyboard, network interfaces, and hardware random number generators. (This is notoriously difficult on virtual machines, where the virtual hardware devices have far fewer random inputs from the "outside world". Then there's the availability and trustworthiness of a hardware random number generator and side-effects of making the bootstrap quicker.)

It can be improved by utilities that pre-prepare some seed data in /var/lib/systemd/random-seed (on systemd operating systems) or /var/lib/urandom/random-seed (on non-systemd operating systems) at the preceding shutdown, and load those data at bootstrap.

Such utilities require that the volume containing these seed files be writable when the utilities run, however; since it is vital that the seed data be deleted/replaced immediately after they are used, to prevent the pseudo-random number generator from ever being re-seeded with the same seed data twice. Unfortunately, this means that the utilities cannot run really early in the bootstrap sequence.

the reason for the log messages

This means that there's a window, of about 1¼ minutes in your case, during which

• using /dev/urandom will obtain pseudo-random data that have been generated from a fixed known seed, which makes the randomness predictable;
• using /dev/random in blocking mode will block, stopping process execution; and
• using /dev/random in non-blocking mode will cause it to return the EAGAIN error code, the string for which is "Resource temporarily unavailable".

wpa_supplicant is clearly doing the third of those. Repeatedly. But less obvious from your logs is the "urandom warnings", where the kernel has warned about some program using /dev/urandom before it was usable. So some programs in your system are getting predictable random numbers, which may be a huge problem depending from what those programs are.

making things better

The people who built Linux for your operating system (which is a "generic" configuration of Linux 5.3.0-28 according to your log) can turn on a configuration option that makes life a lot better on x86-64 processors (apart from some older AMD processors where the underlying processor instruction is faulty). The CONFIG_RANDOM_TRUST_CPU configuration option makes the kernel trust the processor as a source of hardware randomness, which far more quickly seeds the pseudo-random number generator.

Debian's Linux kernels had this option turned on for Debian 10 last year. I don't know about Linux in Ubuntu and Mint off the top of my head, however.

Further reading

• https://unix.stackexchange.com/a/388823/5132
• When I log in, it hangs until crng init done
• When to use /dev/random vs /dev/urandom
• Jake Edge (2019-09-27). Fixing getrandom(). LWN.
• Jake Edge (2020-01-07). Removing the Linux /dev/random blocking pool. LWN.