You are not logged in.

#1 2018-07-26 09:21:02

waldauf
Member
Registered: 2012-07-15
Posts: 102

[SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

Hello,

my NetworkManager was upgraded this month:

$ expac --timefmt='%F %T' '%l %n' | sort -n | grep -i network
2018-07-15 19:31:02 networkmanager
2018-07-16 09:16:12 networkmanager-qt

Since this upgrade I have had problem with ethernet connection where is used MSCHAPv2 protocol. After boot system I can connect in 95% of cases. But after disconnect ethernet cabel and connect in again NetworkManager is impossible to connect again.

Connection successful (profile KB) after boot:

~
Jul 26 08:28:38 jenpockej NetworkManager[567]: <info>  [1532586518.8734] manager: (enp0s31f6): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Jul 26 08:28:38 jenpockej NetworkManager[567]: <info>  [1532586518.8741] device (enp0s31f6): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Jul 26 08:28:42 jenpockej NetworkManager[567]: <info>  [1532586522.0664] device (enp0s31f6): carrier: link connected
Jul 26 08:28:42 jenpockej NetworkManager[567]: <info>  [1532586522.0669] device (enp0s31f6): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Jul 26 08:28:43 jenpockej NetworkManager[567]: <info>  [1532586523.1195] manager: startup complete
Jul 26 08:28:49 jenpockej NetworkManager[567]: <info>  [1532586529.5148] manager: NetworkManager state is now CONNECTED_LOCAL
Jul 26 08:28:49 jenpockej NetworkManager[567]: <info>  [1532586529.5192] manager: NetworkManager state is now CONNECTED_SITE
Jul 26 08:28:49 jenpockej NetworkManager[567]: <info>  [1532586529.8802] manager: NetworkManager state is now CONNECTED_GLOBAL
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.3531] policy: auto-activating connection 'KB' (4d243384-9688-4b86-8363-95f26e3ba941)
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.3539] device (enp0s31f6): Activation: starting connection 'KB' (4d243384-9688-4b86-8363-95f26e3ba941)
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.3541] device (enp0s31f6): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.4707] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.4712] device (enp0s31f6): Activation: (ethernet) connection 'KB' has security, but secrets are required.
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.4713] device (enp0s31f6): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.4751] device (enp0s31f6): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.4756] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.4759] device (enp0s31f6): Activation: (ethernet) connection 'KB' requires no security. No secrets needed.
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.5095] device (enp0s31f6): supplicant interface state: starting -> ready
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.5096] Config: added 'password' value '<hidden>'
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.5096] Config: added 'key_mgmt' value 'IEEE8021X'
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.5096] Config: added 'eapol_flags' value '0'
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.5096] Config: added 'eap' value 'PEAP'
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.5096] Config: added 'fragment_size' value '1266'
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.5096] Config: added 'phase2' value 'auth=MSCHAPV2'
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.5096] Config: added 'identity' value '<TOP_SECRET>'
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.5096] Config: added 'anonymous_identity' value '<TOP_SECRET>'
Jul 26 08:29:06 jenpockej NetworkManager[567]: <info>  [1532586546.5164] device (enp0s31f6): supplicant interface state: ready -> associated
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.1294] device (enp0s31f6): carrier: link connected
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.5919] device (enp0s31f6): supplicant interface state: associated -> completed
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.5919] device (enp0s31f6): Activation: (ethernet) Stage 2 of 5 (Device Configure) successful.
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.5921] device (enp0s31f6): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.5924] dhcp4 (enp0s31f6): activation: beginning transaction (timeout in 45 seconds)
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6270] dhcp4 (enp0s31f6):   address 10.88.14.147
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6270] dhcp4 (enp0s31f6):   plen 24
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6270] dhcp4 (enp0s31f6):   expires in 691200 seconds
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6270] dhcp4 (enp0s31f6):   nameserver '10.6.35.36'
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6270] dhcp4 (enp0s31f6):   nameserver '10.6.67.36'
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6270] dhcp4 (enp0s31f6):   nameserver '10.6.33.36'
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6270] dhcp4 (enp0s31f6):   nameserver '10.6.65.36'
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6271] dhcp4 (enp0s31f6):   domain name 'ds.kb.cz'
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6271] dhcp4 (enp0s31f6):   gateway 10.88.14.1
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6272] dhcp4 (enp0s31f6): state changed unknown -> bound
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6280] device (enp0s31f6): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6284] device (enp0s31f6): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6285] device (enp0s31f6): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Jul 26 08:29:10 jenpockej NetworkManager[567]: <info>  [1532586550.6364] device (enp0s31f6): Activation: successful, device activated.
Jul 26 08:39:50 jenpockej NetworkManager[567]: <info>  [1532587190.0898] policy: set 'KB' (enp0s31f6) as default for IPv4 routing and DNS

Connection faild (profile KB) after unplug/plug ethernet cabel:

# Unplug ethernet
Jul 26 11:06:48 jenpockej NetworkManager[567]: <info>  [1532596008.6759] device (enp0s31f6): state change: activated -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')
Jul 26 11:06:48 jenpockej NetworkManager[567]: <info>  [1532596008.6760] dhcp4 (enp0s31f6): canceled DHCP transaction
Jul 26 11:06:48 jenpockej NetworkManager[567]: <info>  [1532596008.6760] dhcp4 (enp0s31f6): state changed bound -> done
Jul 26 11:06:48 jenpockej NetworkManager[567]: <info>  [1532596008.6926] manager: NetworkManager state is now DISCONNECTED
# Plug ethernet
Jul 26 11:06:53 jenpockej NetworkManager[567]: <info>  [1532596013.9488] device (enp0s31f6): carrier: link connected
Jul 26 11:06:53 jenpockej NetworkManager[567]: <info>  [1532596013.9490] device (enp0s31f6): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Jul 26 11:06:53 jenpockej NetworkManager[567]: <info>  [1532596013.9500] policy: auto-activating connection 'KB' (4d243384-9688-4b86-8363-95f26e3ba941)
Jul 26 11:06:53 jenpockej NetworkManager[567]: <info>  [1532596013.9510] device (enp0s31f6): Activation: starting connection 'KB' (4d243384-9688-4b86-8363-95f26e3ba941)
Jul 26 11:06:53 jenpockej NetworkManager[567]: <info>  [1532596013.9511] device (enp0s31f6): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 26 11:06:53 jenpockej NetworkManager[567]: <info>  [1532596013.9515] manager: NetworkManager state is now CONNECTING
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.0760] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.0765] device (enp0s31f6): Activation: (ethernet) connection 'KB' has security, but secrets are required.
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.0765] device (enp0s31f6): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.0799] device (enp0s31f6): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.0802] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.0805] device (enp0s31f6): Activation: (ethernet) connection 'KB' requires no security. No secrets needed.
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.1355] device (enp0s31f6): supplicant interface state: starting -> ready
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.1356] Config: added 'password' value '<hidden>'
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.1356] Config: added 'key_mgmt' value 'IEEE8021X'
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.1356] Config: added 'eapol_flags' value '0'
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.1356] Config: added 'eap' value 'PEAP'
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.1356] Config: added 'fragment_size' value '1266'
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.1356] Config: added 'phase2' value 'auth=MSCHAPV2'
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.1356] Config: added 'identity' value '<TOP_SECRET>'
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.1356] Config: added 'anonymous_identity' value '<TOP_SECRET>'
Jul 26 11:06:54 jenpockej NetworkManager[567]: <info>  [1532596014.1423] device (enp0s31f6): supplicant interface state: ready -> associated
Jul 26 11:07:00 jenpockej NetworkManager[567]: <info>  [1532596020.0775] device (enp0s31f6): state change: config -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')
Jul 26 11:07:00 jenpockej NetworkManager[567]: <info>  [1532596020.0785] manager: NetworkManager state is now DISCONNECTED
Jul 26 11:07:01 jenpockej NetworkManager[567]: <info>  [1532596021.9488] device (enp0s31f6): carrier: link connected
Jul 26 11:07:01 jenpockej NetworkManager[567]: <info>  [1532596021.9490] device (enp0s31f6): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Jul 26 11:07:01 jenpockej NetworkManager[567]: <info>  [1532596021.9498] policy: auto-activating connection 'KB' (4d243384-9688-4b86-8363-95f26e3ba941)
Jul 26 11:07:01 jenpockej NetworkManager[567]: <info>  [1532596021.9506] device (enp0s31f6): Activation: starting connection 'KB' (4d243384-9688-4b86-8363-95f26e3ba941)
Jul 26 11:07:01 jenpockej NetworkManager[567]: <info>  [1532596021.9507] device (enp0s31f6): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 26 11:07:01 jenpockej NetworkManager[567]: <info>  [1532596021.9510] manager: NetworkManager state is now CONNECTING
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.0760] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.0765] device (enp0s31f6): Activation: (ethernet) connection 'KB' has security, but secrets are required.
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.0765] device (enp0s31f6): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.0791] device (enp0s31f6): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.0795] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.0798] device (enp0s31f6): Activation: (ethernet) connection 'KB' requires no security. No secrets needed.
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.1191] device (enp0s31f6): supplicant interface state: starting -> ready
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.1191] Config: added 'password' value '<hidden>'
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.1192] Config: added 'key_mgmt' value 'IEEE8021X'
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.1192] Config: added 'eapol_flags' value '0'
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.1192] Config: added 'eap' value 'PEAP'
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.1192] Config: added 'fragment_size' value '1266'
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.1192] Config: added 'phase2' value 'auth=MSCHAPV2'
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.1192] Config: added 'identity' value '<TOP_SECRET>'
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.1192] Config: added 'anonymous_identity' value '<TOP_SECRET>'
Jul 26 11:07:02 jenpockej NetworkManager[567]: <info>  [1532596022.1268] device (enp0s31f6): supplicant interface state: ready -> associated
Jul 26 11:07:05 jenpockej NetworkManager[567]: <info>  [1532596025.7122] device (enp0s31f6): carrier: link connected
Jul 26 11:07:27 jenpockej NetworkManager[567]: <warn>  [1532596047.0191] device (enp0s31f6): Activation: (ethernet) association took too long.
Jul 26 11:07:27 jenpockej NetworkManager[567]: <info>  [1532596047.0194] device (enp0s31f6): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Jul 26 11:07:27 jenpockej NetworkManager[567]: <warn>  [1532596047.0207] device (enp0s31f6): Activation: (ethernet) asking for new secrets
Jul 26 11:07:27 jenpockej NetworkManager[567]: <info>  [1532596047.0225] device (enp0s31f6): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 26 11:07:27 jenpockej NetworkManager[567]: <info>  [1532596047.1507] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 26 11:07:27 jenpockej NetworkManager[567]: <info>  [1532596047.1516] device (enp0s31f6): Activation: (ethernet) connection 'KB' requires no security. No secrets needed.
Jul 26 11:07:27 jenpockej NetworkManager[567]: <info>  [1532596047.2133] device (enp0s31f6): supplicant interface state: starting -> ready

I had to set new netctl connection using manual set wpa_supplicant which works:

Jul 26 11:12:59 jenpockej systemd[1]: Starting Networking for netctl profile kb_mschapv2_ethernet...
Jul 26 11:12:59 jenpockej network[20787]: Starting network profile 'kb_mschapv2_ethernet'...
Jul 26 11:13:02 jenpockej systemd[1]: Started Networking for netctl profile kb_mschapv2_ethernet.
Jul 26 11:13:02 jenpockej dhcpcd[20873]: DUID 00:01:00:01:22:ec:23:8d:00:1e:10:1f:00:00
Jul 26 11:13:02 jenpockej dhcpcd[20873]: enp0s31f6: IAID ad:d4:34:81
Jul 26 11:13:02 jenpockej dhcpcd[20873]: enp0s31f6: rebinding lease of 10.88.14.180
Jul 26 11:13:06 jenpockej dhcpcd[20873]: enp0s31f6: probing address 10.88.14.180/24
Jul 26 11:13:11 jenpockej dhcpcd[20873]: enp0s31f6: leased 10.88.14.180 for 691200 seconds
Jul 26 11:13:11 jenpockej dhcpcd[20873]: enp0s31f6: adding route to 10.88.14.0/24
Jul 26 11:13:11 jenpockej dhcpcd[20873]: enp0s31f6: adding default route via 10.88.14.1
Jul 26 11:13:11 jenpockej dhcpcd[20873]: forked to background, child pid 21097
Jul 26 11:13:11 jenpockej network[20787]: Started network profile 'kb_mschapv2_ethernet'

Can I ask you for help please?

Last edited by waldauf (2018-11-13 11:25:19)

Offline

#2 2018-07-26 10:52:58

seth
Member
Registered: 2012-09-03
Posts: 11,248

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

Offline

#3 2018-07-26 12:55:16

waldauf
Member
Registered: 2012-07-15
Posts: 102

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

@seth: Thx for your answer it works now! :]

Offline

#4 2018-07-26 12:56:01

seth
Member
Registered: 2012-09-03
Posts: 11,248

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

Cool.
Please always remember to mark resolved threads by editing your initial posts subject - so others will know that there's no task left, but maybe a solution to find.
Thanks.

Offline

#5 2018-07-26 15:26:21

waldauf
Member
Registered: 2012-07-15
Posts: 102

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

I have to take back [SOLVED] status. Now it again doesn't work. In log I see again these lines:

~
Jul 26 17:19:25 jenpockej NetworkManager[8940]: <warn>  [1532618365.0122] device (enp0s31f6): Activation: (ethernet) association took too long.
~
Jul 26 17:19:25 jenpockej NetworkManager[8940]: <warn>  [1532618365.0147] device (enp0s31f6): Activation: (ethernet) asking for new secrets
~

I have switched to netctl and now run on it.

Offline

#6 2018-07-26 20:49:27

seth
Member
Registered: 2012-09-03
Posts: 11,248

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

If it's nondeterministic, it's possibly really just timing related, try to raise auth-timeout of the connection (default is 25s what somewhat fits the log)

Offline

#7 2018-07-27 11:51:03

waldauf
Member
Registered: 2012-07-15
Posts: 102

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

It's really strange... today it's working alright. Never the less I set /etc/dhclient.conf and I'll see what I'll see - I hope it will work. :]

May be somebody will be curious how I set dhclient.conf:

cat /etc/dhclient.conf
# Source: https://calomel.org/dhclient.html
# initial-interval 1; The initial-interval statement sets the amount of time between the first attempt to reach a server and the second attempt to reach a server. Each time a message is sent, the interval between messages is incremented by twice the current interval multiplied by a random number between zero and one. If it is greater than the backoff-cutoff amount, it is set to that amount. It defaults to ten seconds.
# 
# link-timeout 10; The link-timeout statement sets the amount of time to wait for an interface link before timing out. The default value is 10 seconds, but the special value 0 requests that dhclient not wait for a link state change before timing out.
link-timeout 10;
# 
# reboot 0; When the client is restarted, it first tries to reacquire the last address it had. This is called the INIT-REBOOT state. If it is still attached to the same network it was attached to when it last ran, this is the quickest way to get started. The reboot statement sets the time that must elapse after the client first tries to reacquire its old address before it gives up and tries to discover a new address. By default, the reboot timeout is ten seconds.
reboot 0;
# 
# retry 10; The retry statement determines the time that must pass after the client has determined that there is no DHCP server present before it tries again to contact a DHCP server. By default, this is five minutes (300).
retry 10;
# 
# select-timeout 0; The select-timeout is the time after the client sends its first lease discovery request at which it stops waiting for offers from servers, assuming that it has received at least one such offer. If no offers have been received by the time the select-timeout has expired, the client will accept the first offer that arrives. By default, the select-timeout is zero seconds - that is, the client will take the first offer it sees.
select-timeout 0;
# 
# timeout 30; The timeout statement determines the amount of time that must pass between the time that the client begins to try to determine its address and the time that it decides that it's not going to be able to contact a server. By default, this timeout is sixty seconds. After the timeout has passed, if there are any static leases defined in the configuration file, or any leases remaining in the lease database that have not yet expired, the client will loop through these leases attempting to validate them, and if it finds one that appears to be valid, it will use that lease's address. If there are no valid static leases or unexpired leases in the lease database, the client will restart the protocol after the defined retry interval.
timeout 40;

Offline

#8 2018-09-06 14:50:04

waldauf
Member
Registered: 2012-07-15
Posts: 102

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

Maybe I found out the problem. I have spoofed my MAC address on ethernet. I have it permanently via systemd:

cat /etc/systemd/network/00-mac-spoof.link
[Match]
MACAddress=AA:AA:AA:AA:AA:AA

[Link]
MACAddress=BB:BB:BB:BB:BB:BB
NamePolicy=kernel database onboard slot path

But in NetworkManager I still see my old MAC when it's trying to getting IP. I found out these solutions on the internet and it seems to working now:
1. NetworkManager GUI setting: In my ethernet profile I spoofed MAC to BB:BB:BB:BB:BB:BB.

2. Dhclient setting: Added this line into config file:

# Problem with getting an IP 
# https://wiki.archlinux.org/index.php/NetworkManager#DHCP_problems_with_dhclient
 interface "enp0s31f6" {
   send dhcp-client-identifier BB:BB:BB:BB:BB:BB;
 }

3. Adding this line in NetworkManager.conf file:

# Preserve cloned MAC addres
[connection]
#ethernet.cloned-mac-address=preserve
ethernet.cloned-mac-address=permanent

In NetworkManager's log I see this error. But NetworkManager works (for now) and I checked this file and there aren't any missing semicolon.

Sep 06 16:44:34 jenpockej dhclient[18019]: /var/lib/NetworkManager/dhclient-enp0s31f6.conf line 8: semicolon expected.
Sep 06 16:44:34 jenpockej dhclient[18019]: link-timeout 10;
Sep 06 16:44:34 jenpockej dhclient[18019]:               ^
Sep 06 16:44:34 jenpockej dhclient[18019]: /var/lib/NetworkManager/dhclient-enp0s31f6.conf line 11: semicolon expected.
Sep 06 16:44:34 jenpockej dhclient[18019]: reboot
Sep 06 16:44:34 jenpockej dhclient[18019]: ^

Connect/disconnect works just for 2-4 times. If it stops working I restart NetworkManager and I'm connected again.

EDIT: One day after it stops working again and I have to use netctl for connecting.

Hope it helps to someone one time. :]

Last edited by waldauf (2018-09-07 08:54:32)

Offline

#9 2018-09-12 13:33:20

seth
Member
Registered: 2012-09-03
Posts: 11,248

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

Hi, sorry for the delay.
I rather meant auth-timeout as a NM setting, see https://developer.gnome.org/NetworkMana … tings.html (you'll probably *have* to use nmcli)

Offline

#10 2018-09-19 06:36:04

waldauf
Member
Registered: 2012-07-15
Posts: 102

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

Hi seth,

I tried to set auth-timeout to 40 seconds and used nmcli to connect but without success:

nmcli connection up id KB
Error: Connection activation failed: The base network connection was interrupted

NetworkManager logs:

Sep 19 08:32:47 jenpockej NetworkManager[18378]: <info>  [1537338767.9540] agent-manager: req[0x564b31857680, :1.9084/nmcli-connect/1000]: agent registered
Sep 19 08:32:47 jenpockej NetworkManager[18378]: <info>  [1537338767.9583] device (enp0s31f6): Activation: starting connection 'KB' (4d243384-9688-4b86-8363-95f26e3ba941)
Sep 19 08:32:47 jenpockej NetworkManager[18378]: <info>  [1537338767.9584] audit: op="connection-activate" uuid="4d243384-9688-4b86-8363-95f26e3ba941" name="KB" pid=30219 uid=1000 result="success"
Sep 19 08:32:47 jenpockej NetworkManager[18378]: <info>  [1537338767.9586] device (enp0s31f6): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.0819] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.0828] device (enp0s31f6): Activation: (ethernet) connection 'KB' has security, but secrets are required.
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.0829] device (enp0s31f6): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.0872] device (enp0s31f6): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.0877] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.0881] device (enp0s31f6): Activation: (ethernet) connection 'KB' requires no security. No secrets needed.
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.1244] device (enp0s31f6): supplicant interface state: starting -> ready
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.1244] Config: added 'password' value '<hidden>'
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.1244] Config: added 'key_mgmt' value 'IEEE8021X'
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.1244] Config: added 'eapol_flags' value '0'
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.1244] Config: added 'eap' value 'PEAP'
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.1245] Config: added 'fragment_size' value '1266'
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.1245] Config: added 'phase2' value 'auth=MSCHAPV2'
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.1245] Config: added 'identity' value 'ds\e_jvalno'
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.1245] Config: added 'anonymous_identity' value 'ds\e_jvalno'
Sep 19 08:32:48 jenpockej NetworkManager[18378]: <info>  [1537338768.1319] device (enp0s31f6): supplicant interface state: ready -> associated
Sep 19 08:32:54 jenpockej NetworkManager[18378]: <info>  [1537338774.0850] device (enp0s31f6): state change: config -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')
Sep 19 08:33:14 jenpockej NetworkManager[18378]: <info>  [1537338794.5513] device (enp0s31f6): carrier: link connected
Sep 19 08:33:14 jenpockej NetworkManager[18378]: <info>  [1537338794.5516] device (enp0s31f6): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Sep 19 08:33:53 jenpockej NetworkManager[18378]: <info>  [1537338833.8769] device (wlp3s0): set-hw-addr: set MAC address to BA:E5:B2:3E:69:EB (scanning)
Sep 19 08:33:53 jenpockej NetworkManager[18378]: <info>  [1537338833.9256] device (wlp3s0): supplicant interface state: inactive -> disconnected
Sep 19 08:33:53 jenpockej NetworkManager[18378]: <info>  [1537338833.9309] device (wlp3s0): supplicant interface state: disconnected -> inactive

Offline

#11 2018-09-19 13:47:31

seth
Member
Registered: 2012-09-03
Posts: 11,248

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

This one's different from the past: You get associated, then pull the cable, plug it back ~20 seconds later and the log ends w/o any further action on the ethernet interface, but the wifi gets disconnected about 40 seconds after the re-plug?
Is that all and nothing further happened??

Offline

#12 2018-09-20 09:32:43

waldauf
Member
Registered: 2012-07-15
Posts: 102

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

seth wrote:

This one's different from the past: You get associated, then pull the cable, plug it back ~20 seconds later and the log ends w/o any further action on the ethernet interface, but the wifi gets disconnected about 40 seconds after the re-plug?
Is that all and nothing further happened??

I disabled Wifi to cancel write its messages into sysmted's log. Today I did new complete test with connection. This is output from journalctl -f after run nmcli connection up id KB:

# DHCLIENT
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.7143] agent-manager: req[0x5630a2c5b120, :1.2120/nmcli-connect/1000]: agent registered
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.7192] device (enp0s31f6): Activation: starting connection 'KB' (4d243384-9688-4b86-8363-95f26e3ba941)
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.7195] audit: op="connection-activate" uuid="4d243384-9688-4b86-8363-95f26e3ba941" name="KB" pid=9445 uid=1000 result="success"
Sep 20 09:16:15 jenpockej audit[4485]: USYS_CONFIG pid=4485 uid=0 auid=4294967295 ses=4294967295 msg='op=connection-activate uuid=4d243384-9688-4b86-8363-95f26e3ba941 name="KB" pid=9445 uid=1000 result=success exe="/usr/bin/NetworkManager" hostname=? addr=? terminal=? res=success'
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.7196] device (enp0s31f6): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Sep 20 09:16:15 jenpockej kernel: audit: type=1111 audit(1537427775.716:74): pid=4485 uid=0 auid=4294967295 ses=4294967295 msg='op=connection-activate uuid=4d243384-9688-4b86-8363-95f26e3ba941 name="KB" pid=9445 uid=1000 result=success exe="/usr/bin/NetworkManager" hostname=? addr=? terminal=? res=success'
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.8424] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.8437] device (enp0s31f6): Activation: (ethernet) connection 'KB' has security, but secrets are required.
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.8438] device (enp0s31f6): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.8541] device (enp0s31f6): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.8552] device (enp0s31f6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.8563] device (enp0s31f6): Activation: (ethernet) connection 'KB' requires no security. No secrets needed.
Sep 20 09:16:15 jenpockej kdeinit5[1336]: plasma-nm: Unhandled active connection state change:  1
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.9109] device (enp0s31f6): supplicant interface state: starting -> ready
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.9109] Config: added 'password' value '<hidden>'
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.9109] Config: added 'key_mgmt' value 'IEEE8021X'
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.9110] Config: added 'eapol_flags' value '0'
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.9110] Config: added 'eap' value 'PEAP'
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.9110] Config: added 'fragment_size' value '1266'
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.9110] Config: added 'phase2' value 'auth=MSCHAPV2'
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.9110] Config: added 'identity' value 'ds\e_jvalno'
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.9110] Config: added 'anonymous_identity' value 'ds\e_jvalno'
Sep 20 09:16:15 jenpockej wpa_supplicant[1039]: enp0s31f6: Associated with 01:80:c2:00:00:03
Sep 20 09:16:15 jenpockej wpa_supplicant[1039]: WMM AC: Missing IEs
Sep 20 09:16:15 jenpockej wpa_supplicant[1039]: enp0s31f6: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Sep 20 09:16:15 jenpockej NetworkManager[4485]: <info>  [1537427775.9175] device (enp0s31f6): supplicant interface state: ready -> associated
Sep 20 09:16:21 jenpockej NetworkManager[4485]: <info>  [1537427781.8482] device (enp0s31f6): state change: config -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')
Sep 20 09:16:21 jenpockej wpa_supplicant[1039]: enp0s31f6: CTRL-EVENT-DISCONNECTED bssid=01:80:c2:00:00:03 reason=3 locally_generated=1
Sep 20 09:16:30 jenpockej kwin_x11[1402]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 63830, resource id: 83886147, major code: 15 (QueryTree), minor code: 0
Sep 20 09:16:42 jenpockej NetworkManager[4485]: <info>  [1537427802.6852] device (enp0s31f6): carrier: link connected
Sep 20 09:16:42 jenpockej NetworkManager[4485]: <info>  [1537427802.6857] device (enp0s31f6): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Sep 20 09:16:42 jenpockej kernel: e1000e: enp0s31f6 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx/Tx
Sep 20 09:16:42 jenpockej kernel: e1000e 0000:00:1f.6 enp0s31f6: 10/100 speed: disabling TSO

... still the same result.

I tried to pull/plug ethernet with this result:

$ journalctl -f | grep -v sudo
# PULL ETHERNET
Sep 20 09:19:09 jenpockej NetworkManager[4485]: <info>  [1537427949.1332] device (enp0s31f6): state change: disconnected -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')
Sep 20 09:19:09 jenpockej kernel: e1000e: enp0s31f6 NIC Link is Down
# PLUGGED ETHERNET at 09:19:40
Sep 20 09:20:02 jenpockej kernel: e1000e: enp0s31f6 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx/Tx
Sep 20 09:20:02 jenpockej kernel: e1000e 0000:00:1f.6 enp0s31f6: 10/100 speed: disabling TSO
Sep 20 09:20:02 jenpockej NetworkManager[4485]: <info>  [1537428002.7378] device (enp0s31f6): carrier: link connected
Sep 20 09:20:02 jenpockej NetworkManager[4485]: <info>  [1537428002.7379] device (enp0s31f6): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')

Dmesg output during pull/plug:

[  519.821800] audit: type=1111 audit(1537427775.716:74): pid=4485 uid=0 auid=4294967295 ses=4294967295 msg='op=connection-activate uuid=4d243384-9688-4b86-8363-95f26e3ba941 name="KB" pid=9445 uid=1000 result=success exe="/usr/bin/NetworkManager" hostname=? addr=? terminal=? res=success'
[  546.786733] e1000e: enp0s31f6 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx/Tx
[  546.786741] e1000e 0000:00:1f.6 enp0s31f6: 10/100 speed: disabling TSO
[  589.907006] e1000e: enp0s31f6 NIC Link is Down
[  646.613279] e1000e: enp0s31f6 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx/Tx
[  646.613281] e1000e 0000:00:1f.6 enp0s31f6: 10/100 speed: disabling TSO
[  693.233658] e1000e: enp0s31f6 NIC Link is Down

... that's all what I see in log.

Offline

#13 2018-11-13 11:24:56

waldauf
Member
Registered: 2012-07-15
Posts: 102

Re: [SOLVED] NetworkManager: ethernet MSCHAPv2 repeated connection failed

Solved by deleting old connection and creating new one.

Offline

Board footer

Powered by FluxBB