I'm not sure why I didn't see this before, but it seems to be a "known
problem". Searching for
"wpa_supplicant crng" yields some helpful information. e.g.:
https://forums.gentoo.org/viewtopic-t-1081710-start-0.html
Proposed solution to gentoo:
"To solve this, one should merge sys-apps/rng-tools and add rngd to
sysinit boot level to utilize hardware rng."
Uhm...not quite sure how to translate that into "debian". But one part
is obvious:
apt-get install rng-tools
but that "failed" in the install because this device doesn't export a
HW Random Number Generator. :/
...
Selecting previously unselected package rng-tools.
(Reading database ... 35727 files and directories currently installed.)
Preparing to unpack .../rng-tools_2-unofficial-mt.14-1+b2_amd64.deb ...
Unpacking rng-tools (2-unofficial-mt.14-1+b2) ...
Setting up rng-tools (2-unofficial-mt.14-1+b2) ...
Job for rng-tools.service failed because the control process exited
with error code.
See "systemctl status rng-tools.service" and "journalctl -xe" for details.
invoke-rc.d: initscript rng-tools, action "start" failed.
● rng-tools.service
Loaded: loaded (/etc/init.d/rng-tools; generated)
Active: failed (Result: exit-code) since Fri 2018-11-23 14:02:41 PST; 9ms ago
Docs: man:systemd-sysv-generator(8)
Process: 1398 ExecStart=/etc/init.d/rng-tools start (code=exited,
status=1/FAILURE)
Nov 23 14:02:41 stoke systemd[1]: Starting rng-tools.service...
Nov 23 14:02:41 stoke rng-tools[1398]: Starting Hardware RNG entropy
gatherer daemon: (Hardware RNG device inode not found)
Nov 23 14:02:41 stoke rng-tools[1398]: /etc/init.d/rng-tools: Cannot
find a hardware RNG device to use.
Nov 23 14:02:41 stoke systemd[1]: rng-tools.service: Control process
exited, code=exited status=1
Nov 23 14:02:41 stoke systemd[1]: rng-tools.service: Failed with
result 'exit-code'.
Nov 23 14:02:41 stoke systemd[1]: Failed to start rng-tools.service.
Processing triggers for systemd (239-13) ...
Processing triggers for man-db (2.8.4-3) ...
Anyway, My guess is this report should be assigned to wpa_supplicant,
not ifupdown package.
On Fri, Nov 23, 2018 at 12:57 PM Grant Grundler <grantgrund...@gmail.com> wrote:
>
> Package: ifupdown
> Version: 0.8.32
> Severity: important
>
> Dear Maintainer,
>
> *** Reporter, please consider answering these questions, where appropriate ***
>
> * What led up to the situation?
> * What exactly did you do (or not do) that was effective (or
> ineffective)?
> * What was the outcome of this action?
> * What outcome did you expect instead?
>
> *** End of the template - remove these template lines ***
>
>
> -- System Information:
> Debian Release: buster/sid
> APT prefers testing
> APT policy: (500, 'testing')
> Architecture: amd64 (x86_64)
>
> Kernel: Linux 4.18.0-2-amd64 (SMP w/2 CPU cores)
> Locale: LANG=en_US.utf8, LC_CTYPE=en_US.utf8 (charmap=locale: Cannot set
> LC_CTYPE to default locale: No such file or directory
> locale: Cannot set LC_MESSAGES to default locale: No such file or directory
> locale: Cannot set LC_ALL to default locale: No such file or directory
> ANSI_X3.4-1968), LANGUAGE=en_US.utf8 (charmap=locale: Cannot set LC_CTYPE to
> default locale: No such file or directory
> locale: Cannot set LC_MESSAGES to default locale: No such file or directory
> locale: Cannot set LC_ALL to default locale: No such file or directory
> ANSI_X3.4-1968)
> Shell: /bin/sh linked to /bin/dash
> Init: systemd (via /run/systemd/system)
>
> Versions of packages ifupdown depends on:
> ii adduser 3.118
> ii iproute2 4.18.0-2
> ii libc6 2.27-8
> ii lsb-base 9.20170808
>
> Versions of packages ifupdown recommends:
> ii isc-dhcp-client [dhcp-client] 4.3.5-4+b1
>
> Versions of packages ifupdown suggests:
> pn ppp <none>
> pn rdnssd <none>
>
> -- Configuration Files:
> /etc/default/networking changed [not included]
>
>
> Note: Two NICs: PCIe r8169 configured statically and PCIe ath9k configured
> via dhclient
>
> # cat /etc/network/interfaces
> source /etc/network/interfaces.d/*
>
> # The loopback network interface
> auto lo
> iface lo inet loopback
>
> auto enp1s0
> iface enp1s0 inet static
> address 192.168.100.1/24
>
> auto wlp2s0
> iface wlp2s0 inet dhcp
> wpa-ssid kroleks warren
> wpa-psk PASSWORD
>
> enp1s0 is configured but networking.service times out (5 minutes).
> But after logging in from console, networking comes up in < 20 seconds
> by running:
> systemctl stop networking.service
> systemctl start networking.service
>
> I've looked at a bunch of other ifupdown reports and this one seems the
> closest:
> #832074 networking.service: Start operation timed out
>
> One theory presented in this bug is "problem with ifupdown <-> dhclient
> interaction".
>
> My theory is dependency on /dev/crng since running the same commands
> later works fine. I installed ifupdown2 and that suceeded after 7-8
> minutes (no timeout?!!!).
>
> Here is directly related snippets of daemon.log from the last run with
> ifupdown2 installed:
> Nov 22 23:39:35 stoke systemd[1]: Starting ifupdown2 networking
> initialization...
> ...
> Nov 22 23:39:35 stoke systemd[1]: Started Load/Save RF Kill Switch Status.
> ...
> Nov 22 23:39:35 stoke wpa_supplicant[302]: Successfully initialized
> wpa_supplicant
> Nov 22 23:39:35 stoke networking[308]: networking: Configuring network
> interfaces
> Nov 22 23:39:36 stoke wpa_supplicant[425]: Successfully initialized
> wpa_supplicant
> Nov 22 23:47:15 stoke dhclient[446]: DHCPREQUEST of 192.168.86.23 on wlp2s0
> to 255.255.255.255 port 67
> Nov 22 23:47:18 stoke wpa_supplicant[437]: wlp2s0: CTRL-EVENT-REGDOM-CHANGE
> init=BEACON_HINT type=UNKNOWN
> Nov 22 23:47:19 stoke wpa_supplicant[437]: wlp2s0: CTRL-EVENT-REGDOM-CHANGE
> init=BEACON_HINT type=UNKNOWN
> Nov 22 23:47:19 stoke wpa_supplicant[437]: wlp2s0: SME: Trying to
> authenticate with f4:f2:6d:a9:1d:91 (SSID='kroleks warren' freq=5745 MHz)
> Nov 22 23:47:19 stoke wpa_supplicant[437]: wlp2s0: Trying to associate with
> f4:f2:6d:a9:1d:91 (SSID='kroleks warren' freq=5745 MHz)
> Nov 22 23:47:19 stoke wpa_supplicant[437]: wlp2s0: Associated with
> f4:f2:6d:a9:1d:91
> Nov 22 23:47:19 stoke wpa_supplicant[437]: wlp2s0:
> CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
> Nov 22 23:47:19 stoke wpa_supplicant[437]: wlp2s0: WPA: Key negotiation
> completed with f4:f2:6d:a9:1d:91 [PTK=CCMP GTK=CCMP]
> Nov 22 23:47:19 stoke wpa_supplicant[437]: wlp2s0: CTRL-EVENT-CONNECTED -
> Connection to f4:f2:6d:a9:1d:91 completed [id=0 id_str=]
> Nov 22 23:47:21 stoke dhclient[446]: DHCPREQUEST of 192.168.86.23 on wlp2s0
> to 255.255.255.255 port 67
> Nov 22 23:47:21 stoke dhclient[446]: DHCPACK of 192.168.86.23 from
> 192.168.86.1
> Nov 22 23:47:21 stoke dhclient[446]: bound to 192.168.86.23 -- renewal in
> 36571 seconds.
> Nov 22 23:47:21 stoke systemd[1]: Started ifupdown2 networking initialization.
> Nov 22 23:47:21 stoke systemd[1]: Reached target Network.
>
> OBVIOUS QUESTION: What caused 7:39 delay between wpa_supplicant successfully
> starting and sending out DHCPREQUEST?
> I suspect if I had increased the networking.service timeout to 10 minutes,
> it likely would have "succeeded" as well.
>
> Around the same time, kern.log has:
> ...
> Nov 22 23:39:36 stoke kernel: [ 5.026394] r8169 0000:01:00.0: firmware:
> direct-loading firmware rtl_nic/rtl8168g-2.fw
> Nov 22 23:39:36 stoke kernel: [ 5.098167] r8169 0000:01:00.0 enp1s0: link
> down
> Nov 22 23:39:36 stoke kernel: [ 5.098178] r8169 0000:01:00.0 enp1s0: link
> down
> Nov 22 23:39:36 stoke kernel: [ 5.098256] IPv6: ADDRCONF(NETDEV_UP):
> enp1s0: link is not ready
> Nov 22 23:39:36 stoke kernel: [ 5.149185] IPv6: ADDRCONF(NETDEV_UP):
> wlp2s0: link is not ready
> Nov 22 23:39:39 stoke kernel: [ 7.973459] r8169 0000:01:00.0 enp1s0: link
> up
> Nov 22 23:39:39 stoke kernel: [ 7.973476] IPv6: ADDRCONF(NETDEV_CHANGE):
> enp1s0: link becomes ready
> Nov 22 23:47:15 stoke kernel: [ 464.564477] random: crng init done
> Nov 22 23:47:15 stoke kernel: [ 464.564483] random: 7 urandom warning(s)
> missed due to ratelimiting
> Nov 22 23:47:17 stoke kernel: [ 466.316402] sysrq: SysRq : HELP :
> loglevel(0-9) reboot(b) crash(c) terminate-all-tasks(e)
> memory-full-oom-kill(f) kill-all-tasks(i) thaw-filesystems(j) sak(k)
> show-backtrace-all-active-cpus(l) show-memory-usage(m) nice-all-RT-tasks(n)
> poweroff(o) show-registers(p) show-all-timers(q) unraw(r) sync(s)
> show-task-states(t) unmount(u) force-fb(V) show-blocked-tasks(w)
> dump-ftrace-buffer(z)
> Nov 22 23:47:19 stoke kernel: [ 468.333330] wlp2s0: authenticate with
> f4:f2:6d:a9:1d:91
> Nov 22 23:47:19 stoke kernel: [ 468.347454] wlp2s0: send auth to
> f4:f2:6d:a9:1d:91 (try 1/3)
> Nov 22 23:47:19 stoke kernel: [ 468.349994] wlp2s0: authenticated
> Nov 22 23:47:19 stoke kernel: [ 468.352170] wlp2s0: associate with
> f4:f2:6d:a9:1d:91 (try 1/3)
> Nov 22 23:47:19 stoke kernel: [ 468.361567] wlp2s0: RX AssocResp from
> f4:f2:6d:a9:1d:91 (capab=0x1011 status=0 aid=4)
> Nov 22 23:47:19 stoke kernel: [ 468.361715] wlp2s0: associated
> Nov 22 23:47:19 stoke kernel: [ 468.385673] wlp2s0: Limiting TX power to 30
> (30 - 0) dBm as advertised by f4:f2:6d:a9:1d:91
> Nov 22 23:47:19 stoke kernel: [ 468.403739] IPv6: ADDRCONF(NETDEV_CHANGE):
> wlp2s0: link becomes ready
>
> Is the whole delay due to crng taking minutes to initialize?
> Does wpa_supplicant (or other networking service) stall until crng is
> available?
> If so, please reassign this report to kernel team since I believe crng is
> entirely a kernel driver.
>
> The host in this failure is an Asus Chromebox with
> [ 0.000000] microcode: microcode updated early to revision 0x24, date =
> 2018-04-02
> [ 0.000000] Linux version 4.18.0-2-amd64 (debian-ker...@lists.debian.org)
> (gcc version 7.3.0 (Debian 7.3.0-30)) #1 SMP Debian 4.18.10-2 (2018-11-02)
> [ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.18.0-2-amd64
> root=UUID=45978301-0b49-40b0-961d-e292b57dc659 ro quiet
> ...
> [ 0.000000] DMI: Google Panther/Panther, BIOS MattDevo 04/18/2016
>
>
> I'm running the same release (Debian testing; and thus same ifupdown and
> kernel) on an Intel NUC (full desktop) and it's not seeing this problem.
> I don't know if it's because something in the desktop packages avoids this
> or if it's something specific to /dev/crng on the NUC initializes quickly.
> Kernel output from the most recent boot:
> Nov 20 19:55:33 gggnuc6 kernel: [ 2.931611] random: crng init done
> Nov 20 19:55:33 gggnuc6 kernel: [ 2.931613] random: 7 urandom warning(s)
> missed due to ratelimiting
>
> This suggests wpa_supplicant depends on /dev/crng and thus networking.service
> can't complete until /dec/crng is available.
