please enable level=TRACE logging and attach the logfile of NetworkManager.

see https://cgit.freedesktop.org/NetworkManager/NetworkManager/plain/contrib/fedora/rpm/NetworkManager.conf?id=c90ec2d8c8a12b44c908bf7f80b23059c29f68fa

Thanks

Created attachment 334987 [details]
log file attached

does it workaround the issue to configure

[device]
wifi.scan-rand-mac-address=0

in /etc/NetworkManager/NetworkManager.conf. Then restart NetworkManager and re-test.

Does it the failure to connect happen every time?

I take it you meant:

[device]
wifi.scan-rand-mac-address=0

and not:

[wlan0]
wifi.scan-rand-mac-address=0

..but I tried both and neither helped.

Note that I also have the following (I recall it was required to fix something a while back):

$ cat /usr/local/etc/NetworkManager/nm-system-settings.conf
[main]
plugins=keyfile
# [logging]
# level=DEBUG

I've tried to connect tens of times, but it fails to connect every time :(

As compared to my wpa_supplicant config that works with udhcpc, I see the following differences with the networkmanager config:

$ sudo cat /usr/local/etc/NetworkManager/system-connections/myhiddenssidwifi

[wifi-security]
group=[ccmp]
key-mgmt=wpa-psk
pairwise= [ccmp]
proto= [wpa2]
psk=blahblah

..where the entries [*] are blank in networkmanager. However adding them does not make things work.

Are there a number of commands I can enter at the command prompt to attempt to connect?

(In reply to john.frankish@outlook.com from comment #4)
> I take it you meant:
> 
> [device]
> wifi.scan-rand-mac-address=0

yes, this is described in `man NetworkManager.conf`.




Can you obtain logfiles from wpa-supplicant?

An instruction is here: https://wiki.gnome.org/Projects/NetworkManager/Debugging#Debugging_WiFi_Connections (although this howto didn't work for me recently, in that case you might need something more to get the logs).

Unfortunately, even though the dbus commands do not return errors, I am unable to get a log from wpa_supplicant.

BTW, if I change my WAP settings to broadcast the SSID, networkmanager still fails to connect.

Got it - it appears you have to modify the dbus service file before the dbus daemon is first started.

Successfully initialized wpa_supplicant
wlan0: CTRL-EVENT-SCAN-STARTED 
wlan0: Reject scan trigger since one is already pending
wlan0: CTRL-EVENT-SCAN-STARTED 
wlan0: CTRL-EVENT-SCAN-STARTED 
wlan0: CTRL-EVENT-SCAN-STARTED 
wlan0: CTRL-EVENT-SCAN-STARTED 
wlan0: CTRL-EVENT-SCAN-STARTED 
wlan0: SME: Trying to authenticate with c4:7d:4f:88:a9:b9 (SSID='******' freq=2462 MHz)
wlan0: SME: Deauth request to the driver failed
wlan0: CTRL-EVENT-SCAN-STARTED 
wlan0: SME: Trying to authenticate with c4:7d:4f:88:a9:b9 (SSID='******' freq=2462 MHz)
wlan0: CTRL-EVENT-SCAN-STARTED 
wlan0: SME: Trying to authenticate with c4:7d:4f:88:a9:b9 (SSID='******' freq=2462 MHz)
wlan0: CTRL-EVENT-DISCONNECTED bssid=c4:7d:4f:88:a9:b9 reason=3 locally_generated=1
wlan0: CTRL-EVENT-SCAN-STARTED 
wlan0: Reject scan trigger since one is already pending
wlan0: CTRL-EVENT-SCAN-STARTED 
wlan0: CTRL-EVENT-SCAN-STARTED

I had another go at this (networkmanager and wpa_supplicant logs attached below).

From this snippet, maybe there is a timing issue?

daemon.info NetworkManager[25032]: <info>  [1473588881.2697] device (wlan0): supplicant interface state: disconnected -> scanning
user.info kernel: wlan0: authenticate with c4:7d:4f:88:a9:b9
user.info kernel: wlan0: send auth to c4:7d:4f:88:a9:b9 (try 1/3)
user.info kernel: wlan0: authenticated
daemon.info NetworkManager[25032]: <info>  [1473588884.6824] device (wlan0): supplicant interface state: scanning -> authenticating
user.err kernel: iwlwifi 0000:02:00.0: No association and the time event is over already...
user.info kernel: wlan0: Connection to AP c4:7d:4f:88:a9:b9 lost
user.info kernel: wlan0: aborting authentication with c4:7d:4f:88:a9:b9 by local choice (Reason: 3=DEAUTH_LEAVING)
daemon.info NetworkManager[25032]: <info>  [1473588889.6963] device (wlan0): supplicant interface state: authenticating -> disconnected
daemon.info NetworkManager[25032]: <info>  [1473588890.1970] device (wlan0): supplicant interface state: disconnected -> scanning
user.info kernel: wlan0: authenticate with c4:7d:4f:88:a9:b9
user.info kernel: wlan0: send auth to c4:7d:4f:88:a9:b9 (try 1/3)
user.info kernel: wlan0: authenticated
daemon.info NetworkManager[25032]: <info>  [1473588893.6082] device (wlan0): supplicant interface state: scanning -> authenticating
daemon.warn NetworkManager[25032]: <warn>  [1473588893.7556] device (wlan0): Activation: (wifi) association took too long, failing activation
daemon.info NetworkManager[25032]: <info>  [1473588893.7556] device (wlan0): state change: config -> failed (reason 'ssid-not-found') [50 120 53]
daemon.info NetworkManager[25032]: <info>  [1473588893.7558] manager: NetworkManager state is now DISCONNECTED
daemon.warn NetworkManager[25032]: <warn>  [1473588893.7570] device (wlan0): Activation: failed for connection '******'
daemon.info NetworkManager[25032]: <info>  [1473588893.7576] device (wlan0): state change: failed -> disconnected (reason 'none') [120 30 0]
user.info kernel: wlan0: aborting authentication with c4:7d:4f:88:a9:b9 by local choice (Reason: 3=DEAUTH_LEAVING)

Created attachment 335292 [details]
networkmanager and wpa_supplicant error logs

I updated networkmanager to the latest git, which did not help.

I then updated wpa_supplicant from 2.1 -> 2,5 and things work :)

I reverted networkmanager from git -> 1.4.0 and things still worked with wpa_supplicant-2.5 - although it did take two attempts to connect.

..so it seems networkmanager-1.4.0 requires wpa_supplicant > 2.1 (although I have not tested 2.2, 2.3 or 2.4)

please attach full logfiles of both NetworkManager and wpa_supplicant, that show the issue.

For NetworkManager, make sure to enable "level=TRACE" in NetworkManager.conf. For wpa_supplicant, make sure that the supplicant is started with "-dddt" to get a high logging verbosity and timestamps.

Thanks.

Do you mean the logfiles from it failing with wpa_supplicant-2.1 or succeeding with wpa_supplicant-2.5?

Should I use networkmanager-1.4.0 or git?

sorry for being unclear.

If I understand correctly "NM-master+supplicant-2.5" works, but "NM-master+supplicant-2.1" does not work.

Most interesting would be an fail-example of "NM-master" with a supplicant version that has the issue (2.1?).

Reason being, that NM-master is supposed to work with various versions of wpa_supplicant.

Created attachment 335486 [details]
nm-git and wpa-supplicant-2.1 logs

Hi John. Thanks for the logfile.
Note that you didn't enable level=TRACE logging for NetworkManager. You can see that, because there are only messages with <info> level, no <debug> or <trace>. Anyway... it's good for the moment. Thanks.


NetworkManager first sets a random MAC address during scanning:

<info>  [1473850841.5517] device (wlan0): set-hw-addr: set MAC address to 0A:71:C1:62:73:AD (scanning)

which also supplicant confirms:

1473850841.836320: wlan0: Own MAC address: 0a:71:c1:62:73:ad


during activation, NM resets the previous MAC address:

<info>  [1473850886.3566] device (wlan0): set-hw-addr: reset MAC address to A0:A8:CD:2C:3E:13 (preserve)

but supplicant misses that change. Which is interesting, because https://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=32f7c1d4b9aba597a99128631f07c2985149f303 is supposed to work-around that.


John, when you say, you tested "nm-git", which commit was that? It should at least be 32f7c1d4b9aba597a99128631f07c2985149f303 or newer.



This issue seems to be a duplicate of https://bugzilla.gnome.org/show_bug.cgi?id=770504#c12

Ah - sorry, I set things up like this:

$ cat /usr/local/etc/NetworkManager/NetworkManager.conf

[main]
plugins=keyfile

[logging]
level=TRACE
domains=ALL

..but maybe I also need "level=DEBUG"?

Note also, I needed:

$ cat /usr/local/share/dbus-1/system-services/fi.epitest.hostap.WPASupplicant.service
[D-BUS Service]
Name=fi.epitest.hostap.WPASupplicant
Exec=/usr/local/sbin/wpa_supplicant -u -f /var/log/wpa_supplicant.log -dddt
User=root
SystemdService=wpa_supplicant.service

..which seems to contradict the info given in the above comments (since wpa_supplicant > 0.6).

I cloned nm git after the commit labelled "device: cleanup _hw_addr_set()"

(In reply to john.frankish@outlook.com from comment #18)
> Ah - sorry, I set things up like this:
> 
> $ cat /usr/local/etc/NetworkManager/NetworkManager.conf
> 
> [main]
> plugins=keyfile
> 
> [logging]
> level=TRACE
> domains=ALL

this looks very right. Maybe NM is not reading this file?
You can verify with

  /path/to/NetworkManager --print-config


> Note also, I needed:
> 
> $ cat
> /usr/local/share/dbus-1/system-services/fi.epitest.hostap.WPASupplicant.
> service
> [D-BUS Service]
> Name=fi.epitest.hostap.WPASupplicant
> Exec=/usr/local/sbin/wpa_supplicant -u -f /var/log/wpa_supplicant.log -dddt
> User=root
> SystemdService=wpa_supplicant.service
> 
> ..which seems to contradict the info given in the above comments (since
> wpa_supplicant > 0.6).

yeah, seems that howto is not working well... the -dddt is correct and the log you attached before was helpful. thanks.


> I cloned nm git after the commit labelled "device: cleanup _hw_addr_set()"

Too bad, this commit should have the fix...

I think this is a wpa_supplicant issue, but it would be strongly preferred that NM can workaround it.

Can you please reproduce the scenario from comment 16 again, this time with level=TRACE in NetworkManager. Because then in the NM log are all the netlink events visible, and there seems to be something special about their order (which probably depends on your driver)

Created attachment 335511 [details]
'seems the default is /usr/local/etc/NetworkManager/nm-system-settings.conf

Created attachment 335538 [details]
nm-log-2.txt

(In reply to john.frankish@outlook.com from comment #20)
> Created attachment 335511 [details]
> 'seems the default is /usr/local/etc/NetworkManager/nm-system-settings.conf

Thanks John. Here both files merged for easier review.

(In reply to Thomas Haller from comment #21)
> Created attachment 335538 [details]
> nm-log-2.txt

I think NetworkManager master does now everything correctly. With https://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=32f7c1d4b9aba597a99128631f07c2985149f303 , NM waits until the MAC address is fully changed before setting the interface up (to workaround brcmfmac).

There is still an supplicant issue, which is probably fixed upstream by https://w1.fi/cgit/hostap/commit/?id=3e0272ca00ce1df35b45e7d739dd7e935f13fd84 .

Although, as dcbw points out in https://bugzilla.gnome.org/show_bug.cgi?id=770504#c12 , supplicant still might have a race.

John, seeing that you are able to compile from source :)
Could you test supplicant 2.1 with commit e0272ca00ce1df35b45e7d739dd7e935f13fd84?

Hmm - maybe I've misunderstood something here, but I was already testing with networkmanager compiled from the git commit after that:

device: cleanup _hw_addr_set()  <-- I cloned git from here
device: wait for MAC address change to complete before setting interface up

If I have misunderstood, maybe you could pass me the appropriate git command to get what is required.

(In reply to john.frankish@outlook.com from comment #24)
> Hmm - maybe I've misunderstood something here, but I was already testing
> with networkmanager compiled from the git commit after that:

I meant to compile wpa_supplianct from source:

the combination
 - NetworkManager (git-master), as you did in comment 20
 - with wpa_supplicant 2.1 with commit https://w1.fi/cgit/hostap/commit/?id=3e0272ca00ce1df35b45e7d739dd7e935f13fd84

Sorry to be dense, but do you mean:

apply the commit 3e0272ca00ce1df35b45e7d739dd7e935f13fd84 as a patch to the wpa_supplicant-2.1 source (I have the tarball somewhere)?

or

issue several git commands to fetch hostap_2_1 and then update it with/to the commit 3e0272ca00ce1df35b45e7d739dd7e935f13fd84?

If the latter, you'll need to supply the relevent git commands to avoid confusion.

(In reply to john.frankish@outlook.com from comment #26)
> Sorry to be dense, but do you mean:

No problem :)


> apply the commit 3e0272ca00ce1df35b45e7d739dd7e935f13fd84 as a patch to the
> wpa_supplicant-2.1 source (I have the tarball somewhere)?
> 
> or
> 
> issue several git commands to fetch hostap_2_1 and then update it with/to
> the commit 3e0272ca00ce1df35b45e7d739dd7e935f13fd84?
> 
> If the latter, you'll need to supply the relevent git commands to avoid
> confusion.

probably it's best and simplest, if you recompile exactly the 2.1 supplicant that you are using now, with the single patch https://w1.fi/cgit/hostap/patch/?id=3e0272ca00ce1df35b45e7d739dd7e935f13fd84 applied. It should apply nicely.

It sounds like you previously build your 2.1 from the release tarball at https://w1.fi/releases/. Just rebuild it with the patch. Ok?

If I rebuild with the patch (which applies cleanly), make fails with:

  CC  ../src/l2_packet/l2_packet_linux.c
../src/drivers/driver_nl80211.o: In function `wpa_driver_nl80211_event_rtm_newlink':
driver_nl80211.c:(.text+0x25a8): undefined reference to `get_bss_ifindex'
collect2: error: ld returned 1 exit status
Makefile:1569: recipe for target 'wpa_supplicant' failed
make: *** [wpa_supplicant] Error 1

Note that it does not fail without the patch.

(In reply to john.frankish@outlook.com from comment #28)
> If I rebuild with the patch (which applies cleanly), make fails with:

sorry, my bad. You also need commit https://w1.fi/cgit/hostap/patch/?id=5dfbd725a95d50475c63ab3a2e85031afd68614b.


This works for me:


  git clone git://w1.fi/hostap.git
  cd ./hostap
  git checkout -b 2.1 hostap_2_1
  cp wpa_supplicant/defconfig wpa_supplicant/.config
  make -C wpa_supplicant
  git cherry-pick -x 5dfbd725a95d50475c63ab3a2e85031afd68614b
  git cherry-pick -x 3e0272ca00ce1df35b45e7d739dd7e935f13fd84
  make -C wpa_supplicant

It compiled without the first "make -C wpa_supplicant: :)

..but things still don't work.

Although I enter my wifi password as part of the "connect to a hidden network" dialogue (gnome-3.21.x), I continually get a pop-up with the message "authentification required by wireless network" that requests my wifi password again and again, but never connects.

Too bad. Could you show the logfiles please?

Created attachment 335640 [details]
latest log files

(In reply to john.frankish@outlook.com from comment #32)
> Created attachment 335640 [details]
> latest log files

Hi John. Very helpful. Could you please retry with
https://github.com/NetworkManager/hostap/commits/th/bgo771005

  git clone git://w1.fi/hostap.git
  cd ./hostap
  git remote add nm git@github.com:NetworkManager/hostap.git
  git fetch nm
  git checkout -t refs/remotes/nm/th/bgo771005
  cp wpa_supplicant/defconfig wpa_supplicant/.config
  make -C wpa_supplicant

should be:
  git remote add https://github.com/NetworkManager/hostap.git

That would be "git remote add nm https://github.com/NetworkManager/hostap.git", right :)

It works

logs to follow

Created attachment 335675 [details]
and more logs

Created attachment 335683 [details] [review]
[patch] for supplicant 2.1 to properly re-read the MAC address

Hi John,

thank you for all the effort with testing.
I think it was important to understand what the issue really is.


To summarize the finding:



With certain configuration, the issue could happen before 1.4.0 as well. However, issue is with 1.4.0 more apparent as NetworkManager now changes the MAC address much more frequently (and by default). One workaround for NetworkManager is to configure NetworkManager.conf with:

  [device]
  wifi.scan-rand-mac-address=0

and ensure that the per-connection setting wifi.cloned-mac-address is "preserve".
"permanent" would work too if the address is already the permanent MAC address so that no change is necessary.




Since 1.4.0 release, NetworkManager added a few workarounds for kernel drivers when changing the MAC address. So, you might have issues with 1.4.0 release, but NetworkManager's master seems fixed.
These workarounds are important especially if you use for example brcmfmac. That driver can first indicate the interface as IFF_UP, but only later actually change the MAC address. Probably there are bugs in wpa_supplicant's master about that, see for example:
  https://w1.fi/cgit/hostap/commit/?id=3e0272ca00ce1df35b45e7d739dd7e935f13fd84
which says:
  "Changing an interface's MAC address requires that the interface be down, the 
   change made, and then the interface brought back up."
that is true, but reading the MAC address when the interface just came up might still yield the wrong MAC address.

NetworkManager now works around that by waiting until the MAC address changed:
https://cgit.freedesktop.org/NetworkManager/NetworkManager/tree/src/devices/nm-device.c?id=2a391348b6906a728d68ef5758b6bf102318986a#n11843



wpa_supplicant must also properly re-read the MAC address. For one, it means you need https://w1.fi/cgit/hostap/commit/?id=3e0272ca00ce1df35b45e7d739dd7e935f13fd84 and https://w1.fi/cgit/hostap/commit/?id=c267753ba2cc006907c57cf11b06d658f783682f .
Actually, you don't need the entire commit c267753, but only the change to wpa_supplicant_update_mac_addr().
That means, supplicant >= 2.3 should work well enough.
The attached patch should fix the issue for 2.1 supplicant.

Probably 2.0 is mostly fine too, because it called wpa_sm_set_own_addr() from wpa_supplicant_update_mac_addr().
That was broken with 2.1 by https://w1.fi/cgit/hostap/commit/?id=c68f6200a72f2b33304f583859b09e57757b9d2a