[pkg-wpa-devel] Bug#835648: wpasupplicant: suspend takes very long due to problematic system-sleep hook

Sat Aug 27 22:39:36 UTC 2016

Package: wpasupplicant
Version: 2.5-2+v2.4-2
Severity: normal

I recently upgraded the wpasupplicant package and my system started taking a
LONG time to suspend. My journal contains:

Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.2710] manager: sleep requested (sleeping: no  enabled: yes)
Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.2710] manager: sleeping...
Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.2711] device (eth0): state change: unavailable -> unmanaged (reason 'sleeping') [20 10 37]
Aug 27 23:40:53 notes kernel: e1000e: eth0 NIC Link is Down
Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.3941] manager: NetworkManager state is now ASLEEP
Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.3974] device (wlan1): state change: activated -> deactivating (reason 'sleeping') [100 110 37]
Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.4048] device (wlan1): state change: deactivating -> disconnected (reason 'sleeping') [110 30 37]
Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.4232] dhcp4 (wlan1): canceled DHCP transaction, DHCP client pid 18447
Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.4233] dhcp4 (wlan1): state changed bound -> done
Aug 27 23:40:53 notes kernel: wlan1: deauthenticating from c4:27:95:77:a6:b8 by local choice (Reason: 3=DEAUTH_LEAVING)
Aug 27 23:40:53 notes wpa_supplicant[2812]: wlan1: CTRL-EVENT-DISCONNECTED bssid=c4:27:95:77:a6:b8 reason=3 locally_generated=1
Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.4548] dns-mgr: Writing DNS information to /sbin/resolvconf
Aug 27 23:40:53 notes wpa_supplicant[2812]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Aug 27 23:40:53 notes NetworkManager[1904]: <warn>  [1472334053.5079] sup-iface[0x9947a98,wlan1]: connection disconnected (reason -3)
Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.5080] device (wlan1): supplicant interface state: completed -> disconnected
Aug 27 23:40:53 notes NetworkManager[1904]: <info>  [1472334053.5091] device (wlan1): state change: disconnected -> unmanaged (reason 'sleeping') [30 10 37]
Aug 27 23:40:53 notes systemd[1]: Reached target Sleep.
Aug 27 23:40:53 notes systemd[1]: Starting Suspend...
Aug 27 23:40:54 notes wpa_supplicant[2812]: nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Aug 27 23:41:04 notes systemd-sleep[18924]: Selected interface 'wlan1'
Aug 27 23:41:04 notes systemd-sleep[18924]: 'SUSPEND' command timed out.
Aug 27 23:41:04 notes systemd-sleep[18928]: /lib/systemd/system-sleep/wpasupplicant failed with error code 254.
Aug 27 23:41:04 notes systemd-sleep[18924]: Suspending system...

Disabling the /lib/systemd/system-sleep/wpasupplicant script fixes the problem
for me. From what NetworkManagers prints to the journal it seems to me that
the /lib/systemd/system-sleep/wpasupplicant script is unnecessary, and since
it makes suspend take 10 seconds longer, it is actually not just unnecessary,
but harmful.

I suspend the system by invoking "systemctl suspend" via acpid.

I tried to research this a bit. If I manually invoke

    dbus-send --print-reply --system --dest=org.freedesktop.NetworkManager /org/freedesktop/NetworkManager org.freedesktop.NetworkManager.Sleep boolean:true

and then try to "/sbin/wpa_cli suspend", I always get:

    Failed to connect to non-global ctrl_ifname: (nil)  error: No such file or directory

Seems to me then that the 10s delay I'm getting is a race condition between NM
sleeping and wpa_cli attempting to suspend. It's also interesting that on my
hardware (ThinkPad T420, Intel(R) Centrino(R) Advanced-N 6205 AGN, REV=0xB0)
wpa_cli suspend does nothing at all -- after invoking it and getting OK, wifi
stays connected and pings.

I also looked into dbus-monitor output and in my case NM drops the inhibitor
only after putting both eth and wlan devices offline, unlike in the launchpad
issue that the /lib/systemd/system-sleep/wpasupplicant is trying to fix.

-- System Information:
Debian Release: stretch/sid
  APT prefers testing
  APT policy: (980, 'testing'), (980, 'stable'), (500, 'unstable-debug'), (500, 'testing-debug'), (500, 'unstable'), (500, 'stable'), (200, 'experimental'), (1, 'experimental-debug')
Architecture: i386 (x86_64)
Foreign Architectures: amd64

Kernel: Linux 4.4.19-lis64+ (SMP w/4 CPU cores; PREEMPT)
Locale: LANG=cs_CZ.UTF-8, LC_CTYPE=cs_CZ.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/bash
Init: systemd (via /run/systemd/system)

Versions of packages wpasupplicant depends on:
ii  adduser           3.115
ii  libc6             2.23-4
ii  libdbus-1-3       1.10.10-1
ii  libnl-3-200       3.2.27-1
ii  libnl-genl-3-200  3.2.27-1
ii  libpcsclite1      1.8.18-1
ii  libreadline6      6.3-8+b4
ii  libssl1.0.2       1.0.2h-1
ii  lsb-base          9.20160629

wpasupplicant recommends no packages.

Versions of packages wpasupplicant suggests:
pn  libengine-pkcs11-openssl  <none>
ii  wpagui                    2.5-2+v2.4-2

-- no debconf information

-- debsums errors found:
debsums: changed file /lib/systemd/system-sleep/wpasupplicant (from wpasupplicant package)

-- 
Tomáš Janoušek, a.k.a. Pivník, a.k.a. Liskni_si, http://work.lisk.in/