[Pkg-utopia-maintainers] Bug#863463:

[Marc Bevand]

network-manager's MAC randomization causes issues even on Intel's very
popular Dual Band Wireless-AC 8265. I have a Lenovo Thinkpad X1 Carbon 5th
gen with this adapter and I wasted a few hours tracking down an issue
caused by randomization. On my machine, when network-manager is already
connected to wifi, re-opening the list of wifi networks and reclicking on
my network's SSID forces a reconnection which takes ~30 seconds during
which wpa_supplicant cycles through my 4 BSSIDs advertising the same SSID:

"wpa_supplicant -t" output:
1522285915.798062: wlp4s0: CTRL-EVENT-DISCONNECTED bssid=f2:9f:c2:22:24:4d
reason=3 locally_generated=1  <========== attempt to reconnect
1522285917.494361: wlp4s0: SME: Trying to authenticate with
f2:9f:c2:22:24:4d (SSID='Bevand Guest' freq=5180 MHz)
1522285922.857478: wlp4s0: SME: Trying to authenticate with
f0:9f:c2:21:24:4d (SSID='Bevand Guest' freq=2412 MHz)
1522285928.113198: wlp4s0: SME: Trying to authenticate with
82:2a:a8:4b:da:e2 (SSID='Bevand Guest' freq=5745 MHz)
1522285928.538433: wlp4s0: SME: Trying to authenticate with
80:2a:a8:4a:da:e2 (SSID='Bevand Guest' freq=2437 MHz)
1522285933.552821: wlp4s0: SME: Deauth request to the driver failed
1522285936.749782: wlp4s0: SME: Trying to authenticate with
f2:9f:c2:22:24:4d (SSID='Bevand Guest' freq=5180 MHz)
1522285940.695917: wlp4s0: CTRL-EVENT-DISCONNECTED bssid=f2:9f:c2:22:24:4d
reason=3 locally_generated=1
1522285942.719984: wlp4s0: SME: Trying to authenticate with
f2:9f:c2:22:24:4d (SSID='Bevand Guest' freq=5180 MHz)
1522285942.729991: wlp4s0: Trying to associate with f2:9f:c2:22:24:4d
(SSID='Bevand Guest' freq=5180 MHz)
1522285942.736596: wlp4s0: Associated with f2:9f:c2:22:24:4d
1522285942.744274: wlp4s0: WPA: Key negotiation completed with
f2:9f:c2:22:24:4d [PTK=CCMP GTK=CCMP]
1522285942.744320: wlp4s0: CTRL-EVENT-CONNECTED - Connection to
f2:9f:c2:22:24:4d completed [id=0 id_str=]
(total time: 26.9 seconds)

However with randomization disabled (wifi.scan-rand-mac-address=no), the
long reconnection issue disappears, reconnecting takes only 2 seconds:

"wpa_supplicant -t" output:
1522286014.158020: wlp4s0: CTRL-EVENT-DISCONNECTED bssid=f2:9f:c2:22:24:4d
reason=3 locally_generated=1  <========== attempt to reconnect
1522286015.839514: wlp4s0: SME: Trying to authenticate with
f2:9f:c2:22:24:4d (SSID='Bevand Guest' freq=5180 MHz)
1522286015.853940: wlp4s0: Trying to associate with f2:9f:c2:22:24:4d
(SSID='Bevand Guest' freq=5180 MHz)
1522286015.862127: wlp4s0: Associated with f2:9f:c2:22:24:4d
1522286015.869183: wlp4s0: WPA: Key negotiation completed with
f2:9f:c2:22:24:4d [PTK=CCMP GTK=CCMP]
1522286015.869621: wlp4s0: CTRL-EVENT-CONNECTED - Connection to
f2:9f:c2:22:24:4d completed [id=0 id_str=]
(total time: 1.7 seconds)

When doing the reconnection like this, network-manager calls a series of
D-Bus methods into wpa_supplicant (Disconnect, RemoveNetwork, Scan,
AddNetwork, SelectNetwork...) When I attempt to simulate this series of
actions through wpa_cli[1], I am unable to reproduce the issue. Also, when
I strace network-manager or wpa_supplicant the problem tends to disappear.
This suggests the issue is timing-related.

Looking at verbose logs ("wpa_supplicant -tdd"), I noticed that MAC
randomization causes many "SME: Authentication timeout" errors. See
attached logs:
- log.wpa_sup-dd.full.failure is the wpa_supplicant log when
network-manager's MAC randomization is enabled
(wifi.scan-rand-mac-address=yes)
- log.wpa_sup-dd.full.success is the wpa_supplicant log when
network-manager's MAC randomization is disabled
(wifi.scan-rand-mac-address=no)

System info:
Debian 9.3 (stretch)
network-manager 1.6.2-3
wpasupplicant 2:2.4-1+deb9u1

Adapter info:
$ ethtool -i wlp4s0
driver: iwlwifi
version: 4.9.0-6-amd64
firmware-version: 22.361476.0

[1] I tried:
   $ for cmd in 'disconnect' 'remove_network 0' 'scan' 'add_network'
'set_network 0 ssid "my_ssid"' 'set_network 0 psk "my_passphrase"'
'enable_network 0' 'reconnect'; do wpa_cli -i wlp4s0 $cmd; done

-Marc
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.alioth.debian.org/pipermail/pkg-utopia-maintainers/attachments/20180328/faea8985/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: log.wpa_sup-dd.full.failure
Type: application/octet-stream
Size: 155142 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/pkg-utopia-maintainers/attachments/20180328/faea8985/attachment-0002.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: log.wpa_sup-dd.full.success
Type: application/octet-stream
Size: 98276 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/pkg-utopia-maintainers/attachments/20180328/faea8985/attachment-0003.obj>