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.
