[pkg-wpa-devel] Bug#838291: wpasupplicant: networking.service fails to bring up wlan interface, when VERBOSE set to yes
Dmitriy Matrosov
sgf.dma at gmail.com
Mon Sep 19 13:15:50 UTC 2016
Package: wpasupplicant
Version: 2.3-1+deb8u4
Severity: important
Tags: patch
Hi.
When verbose output is enabled:
# grep VERBOSE /etc/default/networking
VERBOSE=yes
`networking.service` fails to bring up wlan network interface, which uses
`wpa_action` (but `wpa_action` is not essential here):
# cat /etc/network/interfaces
# The loopback network interface
auto lo
iface lo inet loopback
auto wlan0
iface wlan0 inet manual
wpa-roam /etc/wpa_supplicant.conf
iface sgf.un inet static
address 192.168.2.7
netmask 255.255.255.0
network 192.168.2.0
broadcast 192.168.2.255
gateway 192.168.2.9
Let's start with:
# ip link show wlan0
3: wlan0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc mq state DOWN mode DEFAULT group default qlen 1000
link/ether e8:de:27:e8:47:b1 brd ff:ff:ff:ff:ff:ff
# ps -f -C wpa_supplicant
UID PID PPID C STIME TTY TIME CMD
# systemctl status networking.service
● networking.service - LSB: Raise network interfaces.
Loaded: loaded (/etc/init.d/networking)
Drop-In: /run/systemd/generator/networking.service.d
└─50-insserv.conf-$network.conf
/lib/systemd/system/networking.service.d
└─network-pre.conf
Active: inactive (dead) since Sun 2016-09-18 22:03:38 MSK; 44s ago
Process: 29629 ExecStop=/etc/init.d/networking stop (code=exited, status=0/SUCCESS)
Process: 26386 ExecStart=/etc/init.d/networking start (code=exited, status=0/SUCCESS)
Sep 18 22:03:38 reiji.sgf.un wpa_supplicant[26407]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Sep 18 22:03:38 reiji.sgf.un systemd[1]: Stopped LSB: Raise network interfaces..
Sep 18 22:03:38 reiji.sgf.un networking[29629]: wpa_supplicant: terminating wpa_supplicant daemon vi...pid
Sep 18 22:03:38 reiji.sgf.un networking[29629]: Stopped /sbin/wpa_supplicant (pid 26407).
Sep 18 22:03:38 reiji.sgf.un networking[29629]: run-parts --verbose /etc/network/if-post-down.d
Sep 18 22:03:38 reiji.sgf.un networking[29629]: run-parts: executing /etc/network/if-post-down.d/ava...mon
Sep 18 22:03:38 reiji.sgf.un networking[29629]: run-parts: executing /etc/network/if-post-down.d/wir...ols
Sep 18 22:03:38 reiji.sgf.un networking[29629]: run-parts: executing /etc/network/if-post-down.d/wpa...ant
Sep 18 22:03:38 reiji.sgf.un networking[29629]: done.
Sep 18 22:03:38 reiji.sgf.un wpa_supplicant[26407]: wlan0: CTRL-EVENT-TERMINATING
Hint: Some lines were ellipsized, use -l to show in full.
Then
# systemctl start networking.service
# journalctl -f _SYSTEMD_UNIT=networking.service
Sep 18 22:05:27 reiji.sgf.un networking[30162]: Configuring network interfaces...run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-pre-up.d/wireless-tools
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-pre-up.d/wpasupplicant
Sep 18 22:05:27 reiji.sgf.un networking[30162]: Configuring interface wlan0=wlan0 (inet)
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-pre-up.d/wireless-tools
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-pre-up.d/wpasupplicant
Sep 18 22:05:27 reiji.sgf.un networking[30162]: /etc/network/if-pre-up.d/wpasupplicant: 112: /etc/network/if-pre-up.d/wpasupplicant: cannot create /dev/stdout: No such device or address
Sep 18 22:05:27 reiji.sgf.un networking[30162]: /etc/network/if-pre-up.d/wpasupplicant: 112: /etc/network/if-pre-up.d/wpasupplicant: cannot create /dev/stdout: No such device or address
Sep 18 22:05:27 reiji.sgf.un networking[30162]: /etc/network/if-pre-up.d/wpasupplicant: 112: /etc/network/if-pre-up.d/wpasupplicant: cannot create /dev/stdout: No such device or address
Sep 18 22:05:27 reiji.sgf.un wpa_supplicant[30182]: Successfully initialized wpa_supplicant
Sep 18 22:05:27 reiji.sgf.un networking[30162]: /etc/network/if-pre-up.d/wpasupplicant: 112: /etc/network/if-pre-up.d/wpasupplicant: cannot create /dev/stdout: No such device or address
Sep 18 22:05:27 reiji.sgf.un networking[30162]: /etc/network/if-pre-up.d/wpasupplicant: 112: /etc/network/if-pre-up.d/wpasupplicant: cannot create /dev/stdout: No such device or address
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: /etc/network/if-pre-up.d/wpasupplicant exited with return code 1
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts --exit-on-error --verbose /etc/network/if-up.d
Sep 18 22:05:27 reiji.sgf.un networking[30162]: Failed to bring up wlan0.
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-up.d/000resolvconf
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-up.d/avahi-daemon
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-up.d/bind9
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-up.d/mountnfs
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-up.d/ntpdate
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-up.d/openssh-server
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-up.d/upstart
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: executing /etc/network/if-up.d/wpasupplicant
Sep 18 22:05:27 reiji.sgf.un networking[30162]: done.
Note the errors:
Sep 18 22:05:27 reiji.sgf.un networking[30162]: /etc/network/if-pre-up.d/wpasupplicant: 112: /etc/network/if-pre-up.d/wpasupplicant: cannot create /dev/stdout: No such device or address
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts: /etc/network/if-pre-up.d/wpasupplicant exited with return code 1
Sep 18 22:05:27 reiji.sgf.un networking[30162]: run-parts --exit-on-error --verbose /etc/network/if-up.d
Sep 18 22:05:27 reiji.sgf.un networking[30162]: Failed to bring up wlan0.
They're happening, because /dev/stdout is a socket (to journald, i suppose),
but shell (/bin/sh, i think) tries to open it like:
open("/proc/self/fd/1", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 ENXIO (No such device or address)
write(2, "sh: 1: sh: ", 11) = 11
write(2, "cannot create /proc/self/fd/1: N"..., 56) = 56
write(2, "\n", 1) = 1
exit_group(2) = ?
which is not possible [1]. The fix is to remove '>/dev/stdout' and use '1>&2'
instead of '>/dev/stderr' in '/etc/wpa_supplicant/functions.sh'. Let's try
again after the patch. Stop the service and kill wpa_supplicant process:
# systemctl stop networking.service
# systemctl status networking.service
● networking.service - LSB: Raise network interfaces.
Loaded: loaded (/etc/init.d/networking)
Drop-In: /run/systemd/generator/networking.service.d
└─50-insserv.conf-$network.conf
/lib/systemd/system/networking.service.d
└─network-pre.conf
Active: inactive (dead) since Sun 2016-09-18 22:09:07 MSK; 7s ago
Process: 31104 ExecStop=/etc/init.d/networking stop (code=exited, status=0/SUCCESS)
Process: 30162 ExecStart=/etc/init.d/networking start (code=exited, status=0/SUCCESS)
Sep 18 22:09:07 reiji.sgf.un networking[31104]: run-parts: executing /etc/network/if-down.d/bind9
Sep 18 22:09:07 reiji.sgf.un networking[31104]: run-parts: executing /etc/network/if-down.d/resolvconf
Sep 18 22:09:07 reiji.sgf.un networking[31104]: run-parts: executing /etc/network/if-down.d/upstart
Sep 18 22:09:07 reiji.sgf.un networking[31104]: run-parts: executing /etc/network/if-down.d/wpasupplicant
Sep 18 22:09:07 reiji.sgf.un networking[31104]: run-parts --verbose /etc/network/if-post-down.d
Sep 18 22:09:07 reiji.sgf.un networking[31104]: run-parts: executing /etc/network/if-post-down.d/ava...mon
Sep 18 22:09:07 reiji.sgf.un networking[31104]: run-parts: executing /etc/network/if-post-down.d/wir...ols
Sep 18 22:09:07 reiji.sgf.un systemd[1]: Stopped LSB: Raise network interfaces..
Sep 18 22:09:07 reiji.sgf.un networking[31104]: run-parts: executing /etc/network/if-post-down.d/wpa...ant
Sep 18 22:09:07 reiji.sgf.un networking[31104]: done.
Hint: Some lines were ellipsized, use -l to show in full.
# ps -f -C wpa_supplicant
UID PID PPID C STIME TTY TIME CMD
root 30183 1 0 22:05 ? 00:00:00 /sbin/wpa_supplicant -s -B -P /run/wpa_supplicant.wlan0.pid -i wlan0 -W -D nl80211,wext -c /etc/wpa_supplicant.conf
# pkill wpa_supplicant
# ps -f -C wpa_supplicant
UID PID PPID C STIME TTY TIME CMD
# ip link show wlan0
3: wlan0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc mq state DOWN mode DORMANT group default qlen 1000
link/ether e8:de:27:e8:47:b1 brd ff:ff:ff:ff:ff:ff
then start again:
# systemctl start networking.service
# systemctl status networking.service
● networking.service - LSB: Raise network interfaces.
Loaded: loaded (/etc/init.d/networking)
Drop-In: /run/systemd/generator/networking.service.d
└─50-insserv.conf-$network.conf
/lib/systemd/system/networking.service.d
└─network-pre.conf
Active: active (running) since Sun 2016-09-18 22:10:46 MSK; 48s ago
Process: 31104 ExecStop=/etc/init.d/networking stop (code=exited, status=0/SUCCESS)
Process: 31528 ExecStart=/etc/init.d/networking start (code=exited, status=0/SUCCESS)
CGroup: /system.slice/networking.service
├─31551 /sbin/wpa_supplicant -s -B -P /run/wpa_supplicant.wlan0.pid -i wlan0 -W -D nl80211,w...
└─31625 /sbin/wpa_cli -B -P /run/wpa_action.wlan0.pid -i wlan0 -p /var/run/wpa_supplicant -a...
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/wpasupplicant
Sep 18 22:10:46 reiji.sgf.un networking[31528]: done.
Sep 18 22:10:47 reiji.sgf.un wpa_supplicant[31551]: wlan0: SME: Trying to authenticate with 4c:5e:0c...Hz)
Sep 18 22:10:47 reiji.sgf.un wpa_supplicant[31551]: wlan0: Trying to associate with 4c:5e:0c:70:f9:b...Hz)
Sep 18 22:10:47 reiji.sgf.un wpa_supplicant[31551]: wlan0: Associated with 4c:5e:0c:70:f9:b4
Sep 18 22:10:47 reiji.sgf.un wpa_supplicant[31551]: wlan0: WPA: Key negotiation completed with 4c:5e...MP]
Sep 18 22:10:47 reiji.sgf.un wpa_supplicant[31551]: wlan0: CTRL-EVENT-CONNECTED - Connection to 4c:5...un]
Sep 18 22:10:47 reiji.sgf.un wpa_action[31753]: bssid=4c:5e:0c:70:f9:b4
Sep 18 22:10:47 reiji.sgf.un wpa_action[31753]: freq=2412
Sep 18 22:10:47 reiji.sgf.un wpa_action[31753]: ssid=sgf.un
Hint: Some lines were ellipsized, use -l to show in full.
# journalctl -f _SYSTEMD_UNIT=networking.service
Sep 18 22:10:46 reiji.sgf.un networking[31528]: Configuring network interfaces...run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-pre-up.d/wireless-tools
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-pre-up.d/wpasupplicant
Sep 18 22:10:46 reiji.sgf.un networking[31528]: Configuring interface wlan0=wlan0 (inet)
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-pre-up.d/wireless-tools
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-pre-up.d/wpasupplicant
Sep 18 22:10:46 reiji.sgf.un networking[31528]: wpa_supplicant: wait for wpa_cli to attach
Sep 18 22:10:46 reiji.sgf.un networking[31528]: wpa_supplicant: wpa-driver nl80211,wext (default)
Sep 18 22:10:46 reiji.sgf.un networking[31528]: wpa_supplicant: /sbin/wpa_supplicant -s -B -P /run/wpa_supplicant.wlan0.pid -i wlan0 -W -D nl80211,wext -c /etc/wpa_supplicant.conf
Sep 18 22:10:46 reiji.sgf.un wpa_supplicant[31550]: Successfully initialized wpa_supplicant
Sep 18 22:10:46 reiji.sgf.un networking[31528]: wpa_supplicant: creating sendsigs omission pidfile: /run/sendsigs.omit.d/wpasupplicant.wpa_supplicant.wlan0.pid
Sep 18 22:10:46 reiji.sgf.un networking[31528]: wpa_supplicant: ctrl_interface socket located at /var/run/wpa_supplicant/wlan0
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts --exit-on-error --verbose /etc/network/if-up.d
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/000resolvconf
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/avahi-daemon
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/bind9
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/mountnfs
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/ntpdate
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/openssh-server
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/upstart
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/wpasupplicant
Sep 18 22:10:46 reiji.sgf.un networking[31528]: wpa_supplicant: /sbin/wpa_cli -B -P /run/wpa_action.wlan0.pid -i wlan0 -p /var/run/wpa_supplicant -a /sbin/wpa_action
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts --exit-on-error --verbose /etc/network/if-up.d
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/000resolvconf
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/avahi-daemon
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/bind9
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/mountnfs
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/ntpdate
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/openssh-server
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/upstart
Sep 18 22:10:46 reiji.sgf.un networking[31528]: run-parts: executing /etc/network/if-up.d/wpasupplicant
Sep 18 22:10:46 reiji.sgf.un networking[31528]: done.
Sep 18 22:10:47 reiji.sgf.un wpa_supplicant[31551]: wlan0: SME: Trying to authenticate with 4c:5e:0c:70:f9:b4 (SSID='sgf.un' freq=2412 MHz)
Sep 18 22:10:47 reiji.sgf.un wpa_supplicant[31551]: wlan0: Trying to associate with 4c:5e:0c:70:f9:b4 (SSID='sgf.un' freq=2412 MHz)
Sep 18 22:10:47 reiji.sgf.un wpa_supplicant[31551]: wlan0: Associated with 4c:5e:0c:70:f9:b4
Sep 18 22:10:47 reiji.sgf.un wpa_supplicant[31551]: wlan0: WPA: Key negotiation completed with 4c:5e:0c:70:f9:b4 [PTK=CCMP GTK=CCMP]
Sep 18 22:10:47 reiji.sgf.un wpa_supplicant[31551]: wlan0: CTRL-EVENT-CONNECTED - Connection to 4c:5e:0c:70:f9:b4 completed [id=0 id_str=sgf.un]
Sep 18 22:10:47 reiji.sgf.un wpa_action[31753]: bssid=4c:5e:0c:70:f9:b4
Sep 18 22:10:47 reiji.sgf.un wpa_action[31753]: freq=2412
Sep 18 22:10:47 reiji.sgf.un wpa_action[31753]: ssid=sgf.un
# ip link show wlan0
3: wlan0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP mode DORMANT group default qlen 1000
link/ether e8:de:27:e8:47:b1 brd ff:ff:ff:ff:ff:ff
# ip addr show wlan0
3: wlan0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP group default qlen 1000
link/ether e8:de:27:e8:47:b1 brd ff:ff:ff:ff:ff:ff
inet 192.168.2.7/24 brd 192.168.2.255 scope global wlan0
valid_lft forever preferred_lft forever
Now it works.
[1]: https://lists.freedesktop.org/archives/systemd-devel/2015-April/031184.html
-- System Information:
Debian Release: 8.6
APT prefers stable-updates
APT policy: (990, 'stable-updates'), (990, 'stable'), (400, 'testing'), (300, 'unstable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386
Kernel: Linux 3.16.0-4-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
Versions of packages wpasupplicant depends on:
ii adduser 3.113+nmu3
ii libc6 2.19-18+deb8u6
ii libdbus-1-3 1.8.20-0+deb8u1
ii libnl-3-200 3.2.24-2
ii libnl-genl-3-200 3.2.24-2
ii libpcsclite1 1.8.13-1
ii libreadline6 6.3-8+b3
ii libssl1.0.0 1.0.1t-1+deb8u3
ii lsb-base 4.1+Debian13+nmu1
wpasupplicant recommends no packages.
Versions of packages wpasupplicant suggests:
pn libengine-pkcs11-openssl <none>
ii wpagui 2.3-1+deb8u4
-- no debconf information
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 1.patch
Type: text/x-diff
Size: 812 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/pkg-wpa-devel/attachments/20160919/5f49dc0b/attachment.patch>
More information about the Pkg-wpa-devel
mailing list