Troubles with wired 802.1x security

dr-yak · September 23, 2019, 2:22pm

Hello,

I’m at a loss about how to debug problems I’m having with the Wired 802.1x security.

At my university (ETHZ) in addition to the usual Wifi (eduroam and similar) 802.1x security is also deployed on the wired network for non institutional devices.
Basically, you get the same network situation security-wise as if you were connecting a private device to the eduroam Wifi, except you’re connecting it to a cable and thus get slightly better wired bandwidth.
(As an unrelated node, instituion-provided devices are detected based on MAC addresses and automatically accepted on the institution network, no 802.1x login required for those. Unrecognized devices that don’t have a registered MAC address AND don’t log-in through 802.1x neither, will be put into yet another network, with a captive web portal asking users to either log-in or use their institution VPN).

Up until August 9th (according to last success /var/log/wpa_supplicant.log) I’ve been successfully using NetworkManager with a separate connection settings profile setup, which has the “802.1x Security” pane filled accordingly.

When coming back from vacations I did an upgrade (2019-08-23 according to zypp history), but apparently some of the update (Network Manager 1.18.2 ? something else ?) broke my setup. Since then NetworkManager systematically fails to setup the 802.1x security channel.

If I run wpa_supplicant manually on the command line using a hand-made ‘/etc/wpa_supplicant/wpa_supplicant-wired-eth0.conf’ file with the necessary informations, it successfully handshakes, and then I can run the standard “Auto eth0” NetworkManager connection settings profile atop to fetch the corresponding address.

I don’t have any further idea how to test/debug the connection to see where the problem is happening.

Here’s my manual config file :

ctrl_interface=/var/run/wpa_supplicant
eapol_version=2
ap_scan=0

network={
        key_mgmt=WPA-EAP
        eap=PEAP
        phase1="peaplabel=0"
        phase2="auth=MSCHAPV2"
        identity="{USERNAME}@{INSTITUTION}"
        password="{PASSWORD}"
}

Anyone has any idea how to further debug the situation ?

Thank you !

malcolmlewis · September 23, 2019, 2:48pm

Hi
Before anything can really be done you need to get to the latest snapshot… 20190921, then see if it continues.

tsu2 · September 23, 2019, 7:12pm

Agree, it’s probably advisable to always “dup” your TW every time you boot up.

Whenever I’m troubleshooting an event I can control, ie invoke on demand,
It’s useful to view the system events being written as your problem is happening.

To do this, before you try to connect open a window, run the following command and leave the window open

journalctl -f

You should see some useful error messages as your system connects.

TSU

dr-yak · October 15, 2019, 10:52am

Sorry for the long time between replies (been busy at work).

I do regularily dup. (I only went so long before update because I was away for vacations). And practice exactly that (dup on boot up) with my workstations.
Though I tend to suspend the laptop between work and home, so instead I just dedicate a little bit of time for update+reboot once per week.

My troubles still persist as of the latest Tumbleweed.

Here are my sudo journalctl --follow log outputs


-- Logs begin at Mon 2019-05-13 10:38:07 CEST. --
Oct 15 10:27:14 argo.dxprod.sympato.ch kdeinit5[606]: plasma-nm: Unhandled active connection state change:  1
Oct 15 10:27:14 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128034.9220] device (eth0): supplicant interface state: starting -> ready
Oct 15 10:27:14 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128034.9221] Config: added 'password' value '<hidden>'
Oct 15 10:27:14 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128034.9221] Config: added 'key_mgmt' value 'IEEE8021X'
Oct 15 10:27:14 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128034.9221] Config: added 'eapol_flags' value '0'
Oct 15 10:27:14 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128034.9221] Config: added 'eap' value 'PEAP'
Oct 15 10:27:14 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128034.9221] Config: added 'fragment_size' value '1266'
Oct 15 10:27:14 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128034.9222] Config: added 'phase2' value 'auth=MSCHAPV2'
Oct 15 10:27:14 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128034.9222] Config: added 'identity' value 'ivanto@bsse.ethz.ch'
Oct 15 10:27:14 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128034.9345] device (eth0): supplicant interface state: ready -> associated
Oct 15 10:27:20 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128040.8463] device (eth0): state change: config -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')
Oct 15 10:27:20 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128040.8483] manager: NetworkManager state is now DISCONNECTED
Oct 15 10:27:21 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128041.9292] device (eth0): carrier: link connected
Oct 15 10:27:21 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128041.9310] device (eth0): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Oct 15 10:27:21 argo.dxprod.sympato.ch kernel: e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx
Oct 15 10:27:21 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128041.9381] policy: auto-activating connection 'ETHZ-lan' (004886a5-3f94-476b-b4d2-36c9df604677)
Oct 15 10:27:21 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128041.9396] device (eth0): Activation: starting connection 'ETHZ-lan' (004886a5-3f94-476b-b4d2-36c9df604677)
Oct 15 10:27:21 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128041.9399] device (eth0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 15 10:27:21 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128041.9406] manager: NetworkManager state is now CONNECTING
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.0423] device (eth0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.0440] device (eth0): Activation: (ethernet) connection 'ETHZ-lan' has security, but secrets are required.
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.0444] device (eth0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.0475] device (eth0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.0483] device (eth0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.0490] device (eth0): Activation: (ethernet) connection 'ETHZ-lan' requires no security. No secrets needed.
Oct 15 10:27:22 argo.dxprod.sympato.ch kdeinit5[606]: plasma-nm: Unhandled active connection state change:  1
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.1231] device (eth0): supplicant interface state: starting -> ready
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.1232] Config: added 'password' value '<hidden>'
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.1233] Config: added 'key_mgmt' value 'IEEE8021X'
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.1233] Config: added 'eapol_flags' value '0'
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.1233] Config: added 'eap' value 'PEAP'
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.1233] Config: added 'fragment_size' value '1266'
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.1234] Config: added 'phase2' value 'auth=MSCHAPV2'
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.1234] Config: added 'identity' value 'ivanto@bsse.ethz.ch'
Oct 15 10:27:22 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128042.1336] device (eth0): supplicant interface state: ready -> associated
Oct 15 10:27:24 argo.dxprod.sympato.ch PackageKit[19824]: daemon quit
Oct 15 10:27:24 argo.dxprod.sympato.ch systemd[1]: packagekit.service: Succeeded.
Oct 15 10:27:27 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128047.9771] device (eth0): carrier: link connected
Oct 15 10:27:27 argo.dxprod.sympato.ch kernel: e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx
Oct 15 10:27:47 argo.dxprod.sympato.ch NetworkManager[1732]: <warn>  [1571128067.5786] device (eth0): Activation: (ethernet) association took too long.
Oct 15 10:27:47 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128067.5792] device (eth0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Oct 15 10:27:47 argo.dxprod.sympato.ch NetworkManager[1732]: <warn>  [1571128067.5802] device (eth0): Activation: (ethernet) asking for new secrets
Oct 15 10:27:47 argo.dxprod.sympato.ch kdeinit5[606]: plasma-nm: virtual NMVariantMapMap SecretAgent::GetSecrets(const NMVariantMapMap&, const QDBusObjectPath&, const QString&, const QStringList&, uint)
Oct 15 10:27:47 argo.dxprod.sympato.ch kdeinit5[606]: plasma-nm: Path: "/org/freedesktop/NetworkManager/Settings/11"
Oct 15 10:27:47 argo.dxprod.sympato.ch kdeinit5[606]: plasma-nm: Setting name: "802-1x"
Oct 15 10:27:47 argo.dxprod.sympato.ch kdeinit5[606]: plasma-nm: Hints: ()
Oct 15 10:27:47 argo.dxprod.sympato.ch kdeinit5[606]: plasma-nm: Flags: 3
Oct 15 10:27:47 argo.dxprod.sympato.ch plasmashell[650]: qt.qpa.xcb: QXcbConnection: XCB error: 8 (BadMatch), sequence: 58447, resource id: 33554455, major code: 152 (Unknown), minor code: 11

^-- at this point NM does open a pop-up asking for the password despite it already being in the configuration.


Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.4412] settings-connection[0x558c84fde660,004886a5-3f94-476b-b4d2-36c9df604677]: write: successfully committed (keyfile: update /etc/NetworkManager/system-connections/ETHZ-lan.nmconnection (004886a5-3f94-476b-b4d2-36c9df604677,"ETHZ-lan"))
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.4417] device (eth0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.5634] device (eth0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.5645] device (eth0): Activation: (ethernet) connection 'ETHZ-lan' requires no security. No secrets needed.
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.6550] device (eth0): supplicant interface state: starting -> ready
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.6550] Config: added 'password' value '<hidden>'
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.6551] Config: added 'key_mgmt' value 'IEEE8021X'
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.6551] Config: added 'eapol_flags' value '0'
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.6551] Config: added 'eap' value 'PEAP'
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.6551] Config: added 'fragment_size' value '1266'
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.6551] Config: added 'phase2' value 'auth=MSCHAPV2'
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.6552] Config: added 'identity' value 'ivanto@bsse.ethz.ch'
Oct 15 10:28:09 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128089.6658] device (eth0): supplicant interface state: ready -> associated
Oct 15 10:28:15 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128095.5679] device (eth0): state change: config -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')
Oct 15 10:28:15 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128095.5700] manager: NetworkManager state is now DISCONNECTED
Oct 15 10:28:15 argo.dxprod.sympato.ch dbus-daemon[1731]: [system] Activating via systemd: service name='org.freedesktop.PackageKit' unit='packagekit.service' requested by ':1.46' (uid=1000 pid=650 comm="/usr/bin/plasmashell ")
Oct 15 10:28:15 argo.dxprod.sympato.ch systemd[1]: Starting PackageKit Daemon...
Oct 15 10:28:15 argo.dxprod.sympato.ch PackageKit[19869]: daemon start
Oct 15 10:28:15 argo.dxprod.sympato.ch dbus-daemon[1731]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Oct 15 10:28:15 argo.dxprod.sympato.ch systemd[1]: Started PackageKit Daemon.
Oct 15 10:28:15 argo.dxprod.sympato.ch plasmashell[650]: plasma-pk-updates: Is net mobile: false
Oct 15 10:28:15 argo.dxprod.sympato.ch plasmashell[650]: plasma-pk-updates: Is net online: false
Oct 15 10:28:15 argo.dxprod.sympato.ch plasmashell[650]: plasma-pk-updates: Daemon changed
Oct 15 10:28:16 argo.dxprod.sympato.ch plasmashell[650]: plasma-pk-updates: Is net mobile: false
Oct 15 10:28:16 argo.dxprod.sympato.ch plasmashell[650]: plasma-pk-updates: Is net online: false
Oct 15 10:28:16 argo.dxprod.sympato.ch plasmashell[650]: plasma-pk-updates: Daemon changed
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.3614] device (eth0): carrier: link connected
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.3627] device (eth0): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Oct 15 10:28:16 argo.dxprod.sympato.ch kernel: e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.3680] policy: auto-activating connection 'ETHZ-lan' (004886a5-3f94-476b-b4d2-36c9df604677)
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.3699] device (eth0): Activation: starting connection 'ETHZ-lan' (004886a5-3f94-476b-b4d2-36c9df604677)
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.3702] device (eth0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.3711] manager: NetworkManager state is now CONNECTING
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.4736] device (eth0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.4751] device (eth0): Activation: (ethernet) connection 'ETHZ-lan' has security, but secrets are required.
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.4755] device (eth0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.4788] device (eth0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.4799] device (eth0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.4809] device (eth0): Activation: (ethernet) connection 'ETHZ-lan' requires no security. No secrets needed.
Oct 15 10:28:16 argo.dxprod.sympato.ch kdeinit5[606]: plasma-nm: Unhandled active connection state change:  1
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.5539] device (eth0): supplicant interface state: starting -> ready
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.5540] Config: added 'password' value '<hidden>'
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.5540] Config: added 'key_mgmt' value 'IEEE8021X'
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.5541] Config: added 'eapol_flags' value '0'
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.5541] Config: added 'eap' value 'PEAP'
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.5541] Config: added 'fragment_size' value '1266'
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.5541] Config: added 'phase2' value 'auth=MSCHAPV2'
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.5541] Config: added 'identity' value 'ivanto@bsse.ethz.ch'
Oct 15 10:28:16 argo.dxprod.sympato.ch NetworkManager[1732]: <info>  [1571128096.5635] device (eth0): supplicant interface state: ready -> associated

dr-yak · October 15, 2019, 10:53am

For me the bit that look weird is :


Oct 15 10:27:14 argo.dxprod.sympato.ch NetworkManager[1732]:  <info>  [1571128034.9345] device (eth0): supplicant interface  state: ready -> associated
Oct 15 10:27:20 argo.dxprod.sympato.ch NetworkManager[1732]:  <info>  [1571128040.8463] device (eth0): state change: config  -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')
Oct 15 10:27:20 argo.dxprod.sympato.ch NetworkManager[1732]:  <info>  [1571128040.8483] manager: NetworkManager state is now  DISCONNECTED
Oct 15 10:27:21 argo.dxprod.sympato.ch NetworkManager[1732]:  <info>  [1571128041.9292] device (eth0): carrier: link connected
Oct 15 10:27:21 argo.dxprod.sympato.ch NetworkManager[1732]:  <info>  [1571128041.9310] device (eth0): state change: unavailable  -> disconnected (reason 'carrier-changed', sys-iface-state:  'managed')

Somehow, when NM is trying to do the 802.1x it’s losing carrier (approximately 6 seconds after associated)

Doesn’t happen when doing it manually:


Successfully initialized wpa_supplicant
eth0: Associated with 01:80:c2:00:00:03
WMM AC: Missing IEs
eth0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
eth0: CTRL-EVENT-EAP-STARTED EAP authentication started
eth0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
eth0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
eth0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=BM/O=QuoVadis  Limited/CN=QuoVadis Global SSL ICA G2'  hash=a4879ec0f36cf84b6f2ed87ae57ee3b94a0785c6862238cd45481084d152eb18
eth0: CTRL-EVENT-EAP-PEER-CERT depth=0  subject='/C=CH/ST=Zuerich/L=Zuerich/O=ETH Zuerich/OU=ID  ICT-Networks/CN=radius-service.ethz.ch'  hash=bcbcd53de87aa6f7a99b112a73a21952a791c96ff883a6cc2e45d2207b217765
eth0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:radius-service.ethz.ch
EAP-MSCHAPV2: Authentication succeeded
EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
eth0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully

I don’t have a clear idea how to investigate further.

tsu2 · October 15, 2019, 6:26pm

Main thing I’d recommend at this point is to disable Packagekit,
At the least, it’s confusing your output. It’s activating and perhaps since you haven’t connected for a long time, it’s trying to download an enormous amount of packages and failing.
At worst, it’s actually somehow causing your connection failure.

Otherwise, your output looks OK to me, I don’t see any errors thrown by a mis-configured wpa_supplicant.config, which is also verified by your invoking wpa_supplicant manually.

I’d recommend you submit a bug to https://bugzilla.opensuse.org,
Your troubleshooting seems to have narrowed the problem down to something that happened in NM
(Maybe there is a nmcli way to connect?)

TSU

Troubles with *wired* 802.1x security

Troubles with wired 802.1x security