Bug 1463245

Summary: setting ap_scan in wpa_supplicant.conf does not work
Product: [Fedora] Fedora Reporter: Don Swaner <Gecko8211>
Component: wpa_supplicantAssignee: Lubomir Rintel <lkundrak>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 25CC: bgalvani, blueowl, dcbw, Gecko8211, lkundrak
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: wpa_supplicant-2.6-3.fc25 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-07-25 21:28:17 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
Requested NetworkManager journal selection
none
Requested wpa_supplicant journal selection
none
Requested NetworkManager journal selection #2
none
Requested wpa_supplicant journal selection #2
none
NetworkManager journal selection #3
none
wpa_supplicant journal selection #3 none

Description Don Swaner 2017-06-20 12:27:39 UTC
Description of problem:
When using my PC as a wifi hotspot, there are messages in the journal:
"wpa_supplicant[1045]: Note: nl80211 driver interface is not designed to be used with ap_scan=2; this can result in connection failures" and "NetworkManager[885]: <info> [...] sup-iface[...,wlp2s0]: config: set interface ap_scan to 2".
I added the line "ap_scan=1" to /etc/wpa_supplicant/wpa_supplicant.conf, but the journal warning does not change, and still says "config: set interface ap_scan to 2". Connecting to the hotspot is erratic. After repeated tries, it eventually connects.

Version-Release number of selected component (if applicable):
wpa_supplicant-2.6-1.fc25.x86_64
NetworkManager-1.4.4-5.fc25.x86_64

How reproducible:
Always (for journal messages).
About 25% of the time, it will connect on the first try; 75% of the time, it requires repeated tries (turning wifi hotspot off/on; turning wifi on Amazon kindle off/on).

Steps to Reproduce:
1.  Add line "ap_scan=1" to /etc/wpa_supplicant/wpa_supplicant.conf
2.  Start hotspot.
3.  Check journal.

Actual results:
Journal still shows warning re ap_scan=2 and nl80211 and still show info message that ap_scan has been set to 2.

Expected results:
Journal no longer shows warning message re ap_scan=2 and nl80211, and instead only shows info message that ap_scan has been set to 1.  (And the connection works on the first try, hopefully.)

Additional info:
Network controller: Realtek Semiconductor Co., Ltd. RTL8723BE PCIe Wireless Network Adapter
Desktop: Fedora 25 Workstation (Wayland)
Connecting to hotspot using Amazon kindle.
I usually start the hotspot using nmcli instead of the GUI:
nmcli radio wifi on
nmcli con up id "Wi-Fi connection 1"

Comment 1 Beniamino Galvani 2017-06-27 13:37:38 UTC
Hi,

the journal message is harmless, because in AP mode we need ap_scan=2
to force the immediate creation of the network without a scan.

To debug the failed connections from clients, can you please do the
following:

 # Add '-dd' to OTHER_ARGS in /etc/sysconfig/wpa_supplicant

 systemctl restart wpa_supplicant
 nmcli general logging level TRACE
 nmcli connection up "Wi-Fi connection 1"

 # now try to connect the client and verify that the attempt fails

 journalctl -u NetworkManager --since='2 minutes ago' > nm.log
 journalctl -u wpa_supplicant --since='2 minutes ago' > wpas.log

and attach the two log files? Thanks!

Comment 2 Don Swaner 2017-06-27 14:15:06 UTC
Created attachment 1292362 [details]
Requested NetworkManager journal selection

Comment 3 Don Swaner 2017-06-27 14:16:30 UTC
Created attachment 1292363 [details]
Requested  wpa_supplicant journal selection

Comment 4 Don Swaner 2017-06-27 14:23:00 UTC
I am unable to recreate the problem at this time.  I tried 6 times, rebooting twice, and connected OK first time, every time.  However, for the final attempt I have attached the requested logs.  Note that I normally keep wifi turned off, only turning it on when needed.

Comment 5 Don Swaner 2017-07-16 13:50:12 UTC
I am still experiencing intermittent connect problems.  But so far every time I turn on debugging mode, I get a connection.  I turn off debugging mode unless I'm trying to capture this error.

Comment 6 Don Swaner 2017-07-18 11:09:18 UTC
Created attachment 1300427 [details]
Requested NetworkManager journal selection #2

This log captures the problem.

Comment 7 Don Swaner 2017-07-18 11:10:44 UTC
Created attachment 1300428 [details]
Requested  wpa_supplicant journal selection #2

This log captures the problem.

Comment 8 Don Swaner 2017-07-18 11:12:58 UTC
The logs capture a failed connect attempt, followed by a successful connect.

Comment 9 Dan Williams 2017-07-18 15:32:00 UTC
Beniamino: I do see in the NM logs that the MAC address of the wifi device is getting changed, and that the MAC that NM sets:

Jul 18 06:44:43 gecko1.bugbane-hollow NetworkManager[885]: <trace> [1500374683.8084] device[0x557b99dba400] (wlp2s0): set-hw-addr: setting MAC address to '94:E9:79:DF:CD:79' (set-cloned, permanent)...

is not the same MAC as the one the supplicant thinks the interface has a few seconds later:

Jul 18 06:44:48 gecko1.bugbane-hollow wpa_supplicant[2843]: nl80211: MLME event 59 (NL80211_CMD_FRAME) on wlp2s0(6e:31:b5:6c:76:26) A1=ff:ff:ff:ff:ff:ff A2=ac:18:26:4e:d2:47

so I think the intermittency here is because the supplicant isn't correctly tracking the MAC address change.

I guess f25's supplicant doesn't have 290834df69556b903b49f2a45671cc62b44f13bb "nl80211: Fix race condition in detecting MAC change" ?

Comment 10 Beniamino Galvani 2017-07-18 16:29:36 UTC
(In reply to Dan Williams from comment #9)
> Beniamino: I do see in the NM logs that the MAC address of the wifi device
> is getting changed, and that the MAC that NM sets:
> ...
> I guess f25's supplicant doesn't have
> 290834df69556b903b49f2a45671cc62b44f13bb "nl80211: Fix race condition in
> detecting MAC change" ?

Correct, that commit probably fixes the issue.

Don, can you please try the RPM from this build which includes the mentioned patch:

  https://koji.fedoraproject.org/koji/taskinfo?taskID=20598092

?

Comment 11 Don Swaner 2017-07-18 17:42:51 UTC
Created attachment 1300578 [details]
NetworkManager journal selection #3

Log after upgrading to wpa_supplicant-2.6-2.1.fc25.x86_64.rpm.

Comment 12 Don Swaner 2017-07-18 17:44:16 UTC
Created attachment 1300579 [details]
wpa_supplicant journal selection #3

Log after upgrading to wpa_supplicant-2.6-2.1.fc25.x86_64.rpm.

Comment 13 Don Swaner 2017-07-18 17:47:08 UTC
I made 3 connection attempts with the upgraded wpa_supplicant.  All were successful.  The logs cover the first attempt, plus some spill over into the second attempt.

Comment 14 Beniamino Galvani 2017-07-19 07:55:17 UTC
Yeah, the fix seems effective:

Jul 18 13:32:02 gecko1.bugbane-hollow wpa_supplicant[2521]: nl80211: Own MAC address on ifindex 3 (wlp2s0) changed from 12:35:5e:84:8e:cc to 94:e9:79:df:cd:79

I'll push an updated package with the patch.

Comment 15 Fedora Update System 2017-07-19 08:14:02 UTC
wpa_supplicant-2.6-3.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2017-56704c88b6

Comment 16 Fedora Update System 2017-07-20 06:52:56 UTC
wpa_supplicant-2.6-3.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-56704c88b6

Comment 17 Fedora Update System 2017-07-25 21:28:17 UTC
wpa_supplicant-2.6-3.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.