Bug 2124955

Summary: Failing to connect to network, no error message
Product: [Fedora] Fedora Reporter: thestroyer <thestroyer>
Component: wpa_supplicantAssignee: Lubomir Rintel <lkundrak>
Status: NEW --- QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 39CC: acabral, bgalvani, blueowl, dcaratti, dcbw, francesco.giudici, gnome-sig, liangwen12year, lkundrak, mclasen, rstrode, sandmann, thaller, vbubela
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 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:

Description thestroyer@cock.li 2022-09-07 14:39:51 UTC 
Description of problem:
When trying to connect to some networks, specifically a WPA2 enterprise PEAP network with apparently outdated crypto policies, networkmanager fails to connect to the network. This is fixed by setting the crypto policies to legacy.

Version-Release number of selected component (if applicable):
NetworkManager-1.38.4-1.fc36.x86_64
wpa_supplicant-2.10-4.fc36.x86_64

How reproducible:
Always

Steps to Reproduce:
1. Connect to the network
2. It opens the network setings page for that network
3. Fill in username and password and don't change any other settings

Actual results:
After a few seconds, it asks for the password again. When giving the password, it waits a few seconds before asking it again. No connection can be made.

Expected results:
There should be an error message saying that the network has outdated crypto policies, and the command to update your crypto policies:

update-crypto-policies --set LEGACY

Additional info:
partial journalctl output:

sep 06 13:54:09 student-laptop NetworkManager[2028]: <info>  [1662465249.7381] device (wlp0s20f3): Activation: starting connection '...')
sep 06 13:54:09 student-laptop NetworkManager[2028]: <info>  [1662465249.7417] device (wlp0s20f3): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
sep 06 13:54:09 student-laptop NetworkManager[2028]: <info>  [1662465249.8523] device (wlp0s20f3): set-hw-addr: reset MAC address to ... (preserve)
sep 06 13:54:09 student-laptop NetworkManager[2028]: <info>  [1662465249.8558] device (wlp0s20f3): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
sep 06 13:54:09 student-laptop NetworkManager[2028]: <info>  [1662465249.8560] device (wlp0s20f3): Activation: (wifi) access point '...' has security, but secrets are required.
sep 06 13:54:09 student-laptop NetworkManager[2028]: <info>  [1662465249.8561] device (wlp0s20f3): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
sep 06 13:54:09 student-laptop NetworkManager[2028]: <info>  [1662465249.8785] device (wlp0s20f3): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
sep 06 13:54:09 student-laptop NetworkManager[2028]: <info>  [1662465249.8793] device (wlp0s20f3): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
sep 06 13:54:09 student-laptop NetworkManager[2028]: <info>  [1662465249.8799] device (wlp0s20f3): Activation: (wifi) connection '...' has security, and secrets exist.  No new secrets needed.
sep 06 13:54:09 student-laptop NetworkManager[2028]: <info>  [1662465249.8939] device (wlp0s20f3): supplicant interface state: disconnected -> scanning
sep 06 13:54:12 student-laptop NetworkManager[2028]: <info>  [1662465252.1118] device (wlp0s20f3): supplicant interface state: scanning -> authenticating
sep 06 13:54:12 student-laptop NetworkManager[2028]: <info>  [1662465252.1487] device (wlp0s20f3): supplicant interface state: authenticating -> associating
sep 06 13:54:12 student-laptop NetworkManager[2028]: <info>  [1662465252.1613] device (wlp0s20f3): supplicant interface state: associating -> associated
sep 06 13:54:16 student-laptop NetworkManager[2028]: <info>  [1662465256.0240] device (wlp0s20f3): supplicant interface state: associated -> disconnected
sep 06 13:54:16 student-laptop NetworkManager[2028]: <info>  [1662465256.1242] device (wlp0s20f3): supplicant interface state: disconnected -> scanning
sep 06 13:54:18 student-laptop NetworkManager[2028]: <info>  [1662465258.3683] device (wlp0s20f3): disconnecting for new activation request.
Comment 1 Thomas Haller 2022-09-07 17:56:34 UTC 
> device (wlp0s20f3): disconnecting for new activation request.

seems like another activation was done?

Check the complete level=TRACE logs. Read https://networkmanager.dev/docs/api/latest/NetworkManager.conf.html#id-1.2.3.10 for how to enable logging.
Comment 2 Thomas Haller 2022-09-07 17:58:24 UTC 
anyway, yes, the logging should be better.

For that it would be interesting to see what NetworkManager knows. It does log things at trace level, if it notices the cause for the problem, it is easier to just increase the logging level. If it doesn't understand the underlying reason why association fails, then it's harder...
Comment 3 thestroyer@cock.li 2022-09-13 14:02:58 UTC 
I changed the crypto policy back to DEFAULT and restarted Networkmanager, but it still connects. Only upon restarting wpa_supplicant, the connection doesn't work anymore. I'll send a log of both networkmanager and wpa_supplicant.
Comment 4 thestroyer@cock.li 2022-09-13 14:12:41 UTC 
The Networkmanager trace logs contain lots of private information (eg the names of all my stored access points), so I'd prefer to give that in a private way. The wpa_supplicant logs can be found below.

I did the following procedure. Restarted the system, while LEGACY mode is on. It connects to the access point. Then I changed the cyrpto mode to DEFAULT and restarted NetworkManager and wpa_supplicant. It then fails to connect to the access point. The logs since boot are provided.


sep 13 16:03:51 student-laptop systemd[1]: Starting wpa_supplicant.service - WPA supplicant...
sep 13 16:03:51 student-laptop wpa_supplicant[1381]: Successfully initialized wpa_supplicant
sep 13 16:03:51 student-laptop systemd[1]: Started wpa_supplicant.service - WPA supplicant.
sep 13 16:03:53 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=EU
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: SME: Trying to authenticate with 44:d9:e7:04:5c:03 (SSID='BolkNet' freq=5240 MHz)
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: Trying to associate with 44:d9:e7:04:5c:03 (SSID='BolkNet' freq=5240 MHz)
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: Associated with 44:d9:e7:04:5c:03
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-EAP-STARTED EAP authentication started
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=NL/ST=Zuid-Holland/L=Delft/O=De Bolk/CN=Bolknet/emailAddress=beheer' hash=d8abad2c9c4c38fd84933ce705c5012998284aca0b4fb04c8a7534b0ecb58ccd
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=NL/ST=Zuid-Holland/L=Delft/O=De Bolk/CN=Bolknet/emailAddress=beheer' hash=d8abad2c9c4c38fd84933ce705c5012998284aca0b4fb04c8a7534b0ecb58ccd
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: EAP-MSCHAPV2: Authentication succeeded
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: PMKSA-CACHE-ADDED 44:d9:e7:04:5c:03 0
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: WPA: Key negotiation completed with 44:d9:e7:04:5c:03 [PTK=CCMP GTK=CCMP]
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-CONNECTED - Connection to 44:d9:e7:04:5c:03 completed [id=0 id_str=]
sep 13 16:04:05 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-58 noise=9999 txrate=6000
sep 13 16:04:07 student-laptop wpa_supplicant[1381]: wlp0s20f3: PMKSA-CACHE-ADDED 44:d9:e7:03:5c:03 0
sep 13 16:04:40 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-57 noise=9999 txrate=400000
sep 13 16:04:42 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-57 noise=9999 txrate=270000
sep 13 16:04:56 student-laptop systemd[1]: Stopping wpa_supplicant.service - WPA supplicant...
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: p2p-dev-wlp0s20: CTRL-EVENT-DSCP-POLICY clear_all
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: p2p-dev-wlp0s20: CTRL-EVENT-DSCP-POLICY clear_all
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: nl80211: deinit ifname=p2p-dev-wlp0s20 disabled_11b_rates=0
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: p2p-dev-wlp0s20: CTRL-EVENT-TERMINATING
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-DISCONNECTED bssid=44:d9:e7:04:5c:03 reason=3 locally_generated=1
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-DSCP-POLICY clear_all
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: wlp0s20f3: PMKSA-CACHE-REMOVED 44:d9:e7:04:5c:03 0
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: wlp0s20f3: PMKSA-CACHE-REMOVED 44:d9:e7:03:5c:03 0
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-DSCP-POLICY clear_all
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: nl80211: deinit ifname=wlp0s20f3 disabled_11b_rates=0
sep 13 16:04:56 student-laptop wpa_supplicant[1381]: wlp0s20f3: CTRL-EVENT-TERMINATING
sep 13 16:04:56 student-laptop systemd[1]: wpa_supplicant.service: Deactivated successfully.
sep 13 16:04:56 student-laptop systemd[1]: Stopped wpa_supplicant.service - WPA supplicant.
sep 13 16:04:56 student-laptop systemd[1]: Starting wpa_supplicant.service - WPA supplicant...
sep 13 16:04:56 student-laptop wpa_supplicant[3223]: Successfully initialized wpa_supplicant
sep 13 16:04:56 student-laptop systemd[1]: Started wpa_supplicant.service - WPA supplicant.
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=NL
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: wlp0s20f3: SME: Trying to authenticate with 44:d9:e7:04:5c:03 (SSID='BolkNet' freq=5240 MHz)
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: wlp0s20f3: Trying to associate with 44:d9:e7:04:5c:03 (SSID='BolkNet' freq=5240 MHz)
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: wlp0s20f3: Associated with 44:d9:e7:04:5c:03
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-EAP-STARTED EAP authentication started
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: SSL: SSL3 alert: write (local SSL3 detected an error):fatal:protocol version
sep 13 16:05:00 student-laptop wpa_supplicant[3223]: OpenSSL: openssl_handshake - SSL_connect error:0A000102:SSL routines::unsupported protocol
sep 13 16:05:01 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-EAP-FAILURE EAP authentication failed
sep 13 16:05:01 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-DISCONNECTED bssid=44:d9:e7:04:5c:03 reason=23
sep 13 16:05:01 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="BolkNet" auth_failures=1 duration=10 reason=AUTH_FAILED
sep 13 16:05:01 student-laptop wpa_supplicant[3223]: BSSID 44:d9:e7:04:5c:03 ignore list count incremented to 2, ignoring for 10 seconds
sep 13 16:05:12 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-SSID-REENABLED id=0 ssid="BolkNet"
sep 13 16:05:12 student-laptop wpa_supplicant[3223]: wlp0s20f3: SME: Trying to authenticate with 44:d9:e7:04:5c:03 (SSID='BolkNet' freq=5240 MHz)
sep 13 16:05:13 student-laptop wpa_supplicant[3223]: wlp0s20f3: Trying to associate with 44:d9:e7:04:5c:03 (SSID='BolkNet' freq=5240 MHz)
sep 13 16:05:13 student-laptop wpa_supplicant[3223]: wlp0s20f3: Associated with 44:d9:e7:04:5c:03
sep 13 16:05:13 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-EAP-STARTED EAP authentication started
sep 13 16:05:13 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
sep 13 16:05:13 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK
sep 13 16:05:13 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
sep 13 16:05:13 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
sep 13 16:05:13 student-laptop wpa_supplicant[3223]: SSL: SSL3 alert: write (local SSL3 detected an error):fatal:protocol version
sep 13 16:05:13 student-laptop wpa_supplicant[3223]: OpenSSL: openssl_handshake - SSL_connect error:0A000102:SSL routines::unsupported protocol
sep 13 16:05:14 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-EAP-FAILURE EAP authentication failed
sep 13 16:05:14 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-DISCONNECTED bssid=44:d9:e7:04:5c:03 reason=23
sep 13 16:05:14 student-laptop wpa_supplicant[3223]: wlp0s20f3: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="BolkNet" auth_failures=2 duration=32 reason=AUTH_FAILED
sep 13 16:05:14 student-laptop wpa_supplicant[3223]: BSSID 44:d9:e7:04:5c:03 ignore list count incremented to 3, ignoring for 60 seconds
Comment 5 Ben Cotton 2023-04-25 17:53:44 UTC 
This message is a reminder that Fedora Linux 36 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 36 on 2023-05-16.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '36'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version. Note that the version field may be hidden.
Click the "Show advanced fields" button if you do not see it.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 36 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.
Comment 6 Fedora Release Engineering 2023-08-16 07:05:59 UTC 
This bug appears to have been reported against 'rawhide' during the Fedora Linux 39 development cycle.
Changing version to 39.