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

Tue Aug 30 20:36:48 UTC 2016

On 28/08/16 00:39, Tomas Janousek wrote:
> Package: wpasupplicant
> Version: 2.5-2+v2.4-2
> Severity: normal

Martin, could you please have a look?

> 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)
> 

-- 
Cheers,
  Andrew