Bug#904726: wpasupplicant: Problem switching wireless/WIFI networks: No beacon heard and the time event is over already...

classic Classic list List threaded Threaded
1 message Options
Reply | Threaded
Open this post in threaded view
|

Bug#904726: wpasupplicant: Problem switching wireless/WIFI networks: No beacon heard and the time event is over already...

Darshaka Pathirana-2
Package: wpasupplicant
Version: 2:2.4-1+deb9u1
Severity: normal

Dear Maintainer,

"Sometimes" I have problems switching the wireless networks.
(Sometimes means, that this problem does not occur every time but I
could not figure out when it happens).

For example, when connecting from SSID: Debconf18 to DebConf18-TP-5GHz:

  % nmcli c show | grep DebConf
  DebConf18-TP-5GHz                   6c9c0d46-4c94-4d8f-a03f-86c8d36416f5  802-11-wireless  --
  Auto DebConf18                      a6ec957f-425c-4f3f-a9b5-5e14abfeb0a9  802-11-wireless  wlp59s0
  DebConf18-1                         836e3919-070a-4fc1-8b5e-4e2cb66c511a  802-11-wireless  --

  % nmcli c up 6c9c0d46-4c94-4d8f-a03f-86c8d36416f5

The log shows me the following lines:

  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.5910] manager: NetworkManager state is now DISCONNECTED
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.5912] device (wlp59s0): Activation: starting connection 'DebConf18-TP-5GHz' (6c9c0d46-4c94-4d8f-a03f-86c8d
  36416f5)
  Jul 27 08:08:09 executor kernel: IPv6: ADDRCONF(NETDEV_UP): wlp59s0: link is not ready
  Jul 27 08:08:09 executor nm-dispatcher[8676]: req:6 'down' [wlp59s0]: new request (1 scripts)
  Jul 27 08:08:09 executor nm-dispatcher[8676]: req:6 'down' [wlp59s0]: start running ordered scripts...
  Jul 27 08:08:09 executor NetworkManager[4720]: <warn>  [1532671689.5980] sup-iface[0x7fb6a4004f10,wlp59s0]: connection disconnected (reason -3)
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.5981] device (wlp59s0): supplicant interface state: completed -> disconnected
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.5999] device (wlp59s0): state change:disconnected -> prepare (reason 'none') [30 40 0]
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6000] manager: NetworkManager state is now CONNECTING
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6038] device (wlp59s0): set-hw-addr: reset MAC address to A0:C5:89:A4:36:DE (preserve)
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6085] device (wlp59s0): state change:prepare -> config (reason 'none') [40 50 0]
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6086] device (wlp59s0): Activation: (wifi) access point 'DebConf18-TP-5GHz' has security, but secrets are
  required.
  Jul 27 08:08:09 executor kernel: IPv6: ADDRCONF(NETDEV_UP): wlp59s0: link is not ready
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6086] device (wlp59s0): state change:config -> need-auth (reason 'none') [50 60 0]
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6122] device (wlp59s0): state change:need-auth -> prepare (reason 'none') [60 40 0]
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6135] device (wlp59s0): state change:prepare -> config (reason 'none') [40 50 0]
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6137] device (wlp59s0): Activation: (wifi) connection 'DebConf18-TP-5GHz' has security, and secrets exist.
    No new secrets needed.
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6137] Config: added 'ssid' value 'DebConf18-TP-5GHz'
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6137] Config: added 'scan_ssid' value'1'
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6137] Config: added 'key_mgmt' value 'WPA-PSK'
  Jul 27 08:08:09 executor NetworkManager[4720]: <info>  [1532671689.6137] Config: added 'psk' value '<hidden>'
  --- [3x the following] ---
  Jul 27 08:08:27 executor kernel: iwlwifi 0000:3b:00.0: No beacon heard and the time event is over already...
  Jul 27 08:08:27 executor kernel: wlp59s0: Connection to AP d4:6e:0e:65:ab:70 lost
  Jul 27 08:08:32 executor kernel: wlp59s0: aborting authentication with d4:6e:0e:65:ab:70 by local choice(Reason: 3=DEAUTH_LEAVING)
  Jul 27 08:08:32 executor NetworkManager[4720]: <info>  [1532671712.2425] device (wlp59s0): supplicant interface state: authenticating -> disconnected
  Jul 27 08:08:32 executor NetworkManager[4720]: <info>  [1532671712.3425] device (wlp59s0): supplicant interface state: disconnected -> scanning
  Jul 27 08:08:34 executor wpa_supplicant[950]: wlp59s0: SME: Trying to authenticate with d4:6e:0e:65:ae:bb (SSID='DebConf18-TP-5GHz' freq=5500 MHz)
  Jul 27 08:08:34 executor kernel: wlp59s0: authenticate with d4:6e:0e:65:ae:bb
  Jul 27 08:08:34 executor kernel: wlp59s0: send auth to d4:6e:0e:65:ae:bb (try 1/3)
  Jul 27 08:08:34 executor kernel: wlp59s0: authenticated
  Jul 27 08:08:34 executor NetworkManager[4720]: <info>  [1532671714.4895] device (wlp59s0): supplicant interface state: scanning -> authenticating
  ---
  Jul 27 08:08:35 executor NetworkManager[4720]: <warn>  [1532671715.0616] device (wlp59s0): Activation: (wifi) association took too long, failing activation
  Jul 27 08:08:35 executor NetworkManager[4720]: <info>  [1532671715.0616] device (wlp59s0): state change:config -> failed (reason 'ssid-not-found') [50 120 53]
  Jul 27 08:08:35 executor NetworkManager[4720]: <info>  [1532671715.0619] manager: NetworkManager state is now DISCONNECTED
  Jul 27 08:08:35 executor NetworkManager[4720]: <warn>  [1532671715.0628] device (wlp59s0): Activation: failed for connection 'DebConf18-TP-5GHz'
  Jul 27 08:08:35 executor NetworkManager[4720]: <info>  [1532671715.0633] device (wlp59s0): state change:failed -> disconnected (reason 'none') [120 30 0]
  Jul 27 08:08:35 executor kernel: wlp59s0: aborting authentication with d4:6e:0e:65:ae:bb by local choice(Reason: 3=DEAUTH_LEAVING)
  Jul 27 08:08:35 executor wpa_supplicant[950]: wlp59s0: CTRL-EVENT-DISCONNECTED bssid=d4:6e:0e:65:ae:bb reason=3 locally_generated=1
  Jul 27 08:08:35 executor NetworkManager[4720]: <info>  [1532671715.0767] device (wlp59s0): set-hw-addr: set MAC address to 1A:23:56:36:CF:E8 (scanning)
  Jul 27 08:08:35 executor kernel: IPv6: ADDRCONF(NETDEV_UP): wlp59s0: link is not ready
  Jul 27 08:08:35 executor kernel: IPv6: ADDRCONF(NETDEV_UP): wlp59s0: link is not ready
  Jul 27 08:08:35 executor NetworkManager[4720]: <warn>  [1532671715.0947] sup-iface[0x7fb6a4004f10,wlp59s0]: connection disconnected (reason -3)
  Jul 27 08:08:35 executor NetworkManager[4720]: <info>  [1532671715.0948] device (wlp59s0): supplicant interface state: authenticating -> disconnected
  Jul 27 08:08:35 executor NetworkManager[4720]: <info>  [1532671715.0948] device (wlp59s0): supplicant interface state: disconnected -> disabled
  Jul 27 08:08:35 executor NetworkManager[4720]: <info>  [1532671715.1540] device (wlp59s0): supplicant interface state: disabled -> disconnected
  Jul 27 08:08:37 executor NetworkManager[4720]: <info>  [1532671717.3302] policy: auto-activating connection 'DebConf18-1'

So basically it tries to connect three times and falls back to the previous wifi connection.

I am running a Debian/stretch with stretch-backports kernel and firmware-iwlwifi from backports on a Lenovo X280 with:

  % lspci -k -n -s 3b:00.0 -vv
  3b:00.0 0280: 8086:24fd (rev 78)
          Subsystem: 8086:0010
          Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping-SERR- FastB2B- DisINTx+
          Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
          Latency: 0
          Interrupt: pin A routed to IRQ 154
          Region 0: Memory at e8100000 (64-bit, non-prefetchable) [size=8K]
          Capabilities: <access denied>
          Kernel driver in use: iwlwifi
          Kernel modules: iwlwifi

The only useful thing I found regarding the issue was this:
https://bugzilla.redhat.com/show_bug.cgi?id=1599036

Workaround which works for me: I downloaded `wpasupplicant` from
buster which made the connection switch work.

I filed this bug in the hope this information helps someone and maybe
there is a better solution for that (at least until stretch-backports
is available for wpasupplicant).

Thank you for maintaining,
 - Darsha (from DebConf18 :))

-- System Information:
Debian Release: 9.5
  APT prefers stable-updates
  APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 4.16.0-0.bpo.2-amd64 (SMP w/8 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8) (ignored: LC_ALL set to en_US.UTF-8), LANGUAGE=en_US:en (charmap=UTF-8) (ignored: LC_ALL set to en_US.UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages wpasupplicant depends on:
ii  adduser           3.115
ii  libc6             2.24-11+deb9u3
ii  libdbus-1-3       1.10.26-0+deb9u1
ii  libnl-3-200       3.2.27-2
ii  libnl-genl-3-200  3.2.27-2
ii  libpcsclite1      1.8.20-1
ii  libreadline7      7.0-3
ii  libssl1.1         1.1.0f-3+deb9u2
ii  lsb-base          9.20161125

wpasupplicant recommends no packages.

Versions of packages wpasupplicant suggests:
pn  libengine-pkcs11-openssl  <none>
pn  wpagui                    <none>

-- no debconf information