GNOME Bugzilla – Bug 673334
Network manager fail to connect network when cloned-mac-address is set
Last modified: 2017-03-07 22:33:36 UTC
Bug-Debian: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=665439 When the "cloned-mac-address" is set, my computer cannot connect to the network anymore. Here is an example on a configuration that fail: [802-3-ethernet] duplex=full cloned-mac-address=0:90:f5:c1:c6:22 [connection] id=Connexion filaire auto uuid=9ec48ffe-38ac-410e-b267-9130d801720f type=802-3-ethernet timestamp=1332576355 [ipv6] method=ignore [ipv4] method=auto Removing the "cloned-mac-address=0:90:f5:c1:c6:22" enable the connection again. The connection will succeed if the cloned-mac-address is set to the card own mac address.
Mac cloning was implemented as an enhancement per this bug: https://bugzilla.redhat.com/show_bug.cgi?id=447827 As part of it, a patch updating MAC was suggested to wpa_supplicant. The patch is necessary for WPA to work (WEP works without patching it). However, the patch has never been committed to wpa_supplicant 0.7.x. Fortunately, recent wpa_supplicant 1.x adds a similar change that allows WPA with spoof MAC to work. You should check that your wpa_supplicant contains these two commits: http://w1.fi/gitweb/gitweb.cgi?p=hostap.git;a=commit;h=bfba8deb8bd990f711f762b2f47956efb3be2f03 http://w1.fi/gitweb/gitweb.cgi?p=hostap.git;a=commit;h=f98eb880eb6855d494c3dacf79e5344e9a8796b6 (or for hostap-1 http://w1.fi/gitweb/gitweb.cgi?p=hostap-1.git;a=commit;h=9e33d413fca479ee356d57cfd7e60eb90e36204c http://w1.fi/gitweb/gitweb.cgi?p=hostap-1.git;a=commit;h=e8c633d20d77f4b41b2d12858814d91fe795d4a1 )
(In reply to comment #1) > Mac cloning was implemented as an enhancement per this bug: > https://bugzilla.redhat.com/show_bug.cgi?id=447827 > > As part of it, a patch updating MAC was suggested to wpa_supplicant. The patch > is necessary for WPA to work (WEP works without patching it). However, the > patch has > never been committed to wpa_supplicant 0.7.x. The original bug reporter (in Debian) mentioned that this failed for type=802-3-ethernet connections. I don't think the wapsupplicant patches will help there.
I can confirm that I reproduce this bug on my wired connection.
> cloned-mac-address=0:90:f5:c1:c6:22 hm. does it work if you change the "0" to "00"? (the mac-parsing code changed recently to be able to cope with longer ip-over-infiniband mac addresses, so it's possible this broke)
This doesn’t change anything. If it help, it fail at Stage 4: NetworkManager[11336]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started... NetworkManager[11336]: <info> (eth0): device state change: config -> ip-config (reason 'none') [50 70 0] NetworkManager[11336]: <info> Activation (eth0) Beginning DHCPv4 transaction (timeout in 45 seconds) NetworkManager[11336]: <info> dhclient started with pid 25812 NetworkManager[11336]: <info> Activation (eth0) Stage 3 Apr 4 21:02:38 gobelin NetworkManager[11336]: <info> (eth0): DHCPv4 state changed preinit -> expire NetworkManager[11336]: <info> (eth0): DHCPv4 state changed expire -> preinit NetworkManager[11336]: <warn> (eth0): DHCPv4 request timed out. NetworkManager[11336]: <info> (eth0): canceled DHCP transaction, DHCP client pid 25812 Full log at https://gist.github.com/2304872
I've looked into it a bit and found out that sometimes the connection is established, sometimes not. There's a race in carrier changes. MAC change is performed like this: - the device is taken down - MAC is changed - and the device is bring up again However, before the device comes up again, set_carrier() could set the device state to unavailable and thus fail the connection. (There's a 4 seconds delay before the carrier change is applied). When the device comes up more quickly, all is right. It could be a regression caused by recent commits: 58227d0136e8ac57396ea375281a15aca06acc53 b44b0321a0d85225504e312264f8cce787a3ae84 (src/nm-device-wired.c) Nonetheless, a closer analysis is needed to figure out how to solve the issue.
*** Bug 682962 has been marked as a duplicate of this bug. ***
(In reply to comment #6) > I've looked into it a bit and found out that sometimes the connection is > established, sometimes not. > > There's a race in carrier changes. > > MAC change is performed like this: > - the device is taken down > - MAC is changed > - and the device is bring up again > > However, before the device comes up again, set_carrier() could set the device > state to unavailable and thus fail the connection. (There's a 4 seconds delay > before the carrier change is applied). > When the device comes up more quickly, all is right. Changing the MAC address might re-init the device firmware and require another autonegotiation with the peer. Sometimes that takes a while, and yeah, that might mean the device looses a carrier for longer than 4 seconds. I guess we probably need to increase that timeout if the device is in the middle of activating a connection where the MAC address is changed.
I'm experiencing the same issue. I have net-wireless/wpa_supplicant-0.7.3-r5 installed, though I use a LAN connection so that's probably irrelevant. I'll paste the bug report I submitted to the KDE bugzilla, forgive me for not filtering out the irrelevant parts: I use a wired connection and a cloned MAC to connect to the internet though the Network Management panel. When I close the laptop lid to put it to sleep and open it again, NetworkManager will try a few times to reconnect but fails. Reproducible: Always Steps to Reproduce: 1. Put computer to sleep. 2. Wake up. 3. Network Manager fails to reconnect Actual Results: Notifications: Networking Interface Connection wiredcloned1 failed kde-misc/networkmanagement-0.9.0.7 net-misc/networkmanager-0.9.6.4 net-misc/dhcpcd-5.6.4 sys-kernel/gentoo-sources-3.7.10 http://i.imgur.com/kBsdyzA.png http://i.imgur.com/8uScy8H.png After trying to reconnect a few times, failing each time, it gives up. From the /var/log/messages log file and from the output of ifconfig run immediately after waking up, it appears that my cloned MAC is still applied on the first reconnect attempt. After the first attempt, it appears that my cloned MAC is reset to the real MAC. The cloned MAC 66:66:66:66:66:66 is assigned the 192.168.1.10 address in my router, while the real MAC would get any free address, probably 192.168.1.13x. After NetworkManager resets my MAC to the real one, if I now re-set it to 66:66:66:66:66:66 and re-attempt a connection using Network Manager, it does work. I believe the problem lies somewhere in how Network Manager handles cloned MACs after waking up. grep -rnC1 66\:66\:66 /etc/ /etc/NetworkManager/system-connections/wiredcloned1-3-mac-address=00:AA:BB:12:34:56 /etc/NetworkManager/system-connections/wiredcloned1:4:cloned-mac-address=66:66:66:66:66:66 /etc/NetworkManager/system-connections/wiredcloned1-5- -- /etc/NetworkManager/nm-system-settings.conf-4- /etc/NetworkManager/nm-system-settings.conf:5:no-auto-default=66:66:66:66:66:66,00:aa:bb:12:34:56, /etc/NetworkManager/nm-system-settings.conf-6- Snippet of /var/log/messages from before sleep to after wakeup failed attempts: 17:45:37 NetworkManager[2398]: <info> sleep requested (sleeping: noenabled: yes) 17:45:37 NetworkManager[2398]: <info> sleeping or disabling... 17:45:37 dbus[2384]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper) 17:45:37 dbus[2384]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' 17:45:37 NetworkManager[2398]: <info> (wlp3s0): now unmanaged 17:45:37 NetworkManager[2398]: <info> (wlp3s0): device state change: unavailable -> unmanaged (reason 'sleeping') [20 10 37] 17:45:37 NetworkManager[2398]: <info> (enp7s0): now unmanaged 17:45:37 NetworkManager[2398]: <info> (enp7s0): device state change: activated -> unmanaged (reason 'sleeping') [100 10 37] 17:45:37 NetworkManager[2398]: <info> (enp7s0): deactivating device (reason 'sleeping') [37] 17:45:37 dhcpcd[2453]: received SIGTERM, stopping 17:45:37 dhcpcd[2453]: enp7s0: removing interface 17:45:37 NetworkManager[2398]: <info> (enp7s0): canceled DHCP transaction, DHCP client pid 2453 17:45:37 NetworkManager[2398]: <info> (enp7s0): taking down device. 17:45:37 NetworkManager[2398]: <info> (enp7s0): reset MAC address to 00:AA:BB:12:34:56 17:45:37 NetworkManager[2398]: <info> (enp7s0): bringing up device. 17:45:37 kernel: [157.485158] r8169 0000:07:00.0 enp7s0: link down 17:45:37 kernel: [157.485175] r8169 0000:07:00.0 enp7s0: link down 17:45:37 kernel: [157.485197] IPv6: ADDRCONF(NETDEV_UP): enp7s0: link is not ready 17:45:37 NetworkManager[2398]: <info> Clearing nscd hosts cache. 17:45:37 NetworkManager[2398]: <info> (enp7s0): cleaning up... 17:45:37 NetworkManager[2398]: <info> (enp7s0): taking down device. 17:45:37 NetworkManager[2398]: <warn> (pid 2453) unhandled DHCP event for interface enp7s0 17:45:37 /etc/init.d/NetworkManager[3290]: status: inactive 17:45:37 /etc/init.d/NetworkManager[3301]: status: inactive (...) 17:45:55 kernel: [ 162.174734] iwlwifi 0000:03:00.0: RF_KILL bit toggled to disable radio. (...) 17:45:55 kernel: [ 162.369121] iwlwifi 0000:03:00.0: RF_KILL bit toggled to enable radio. (...) 17:45:56 laptop-mode: Laptop mode 17:45:56 laptop-mode: disabled, not active (...) 17:45:58 kernel: [ 169.116964] pm-suspend (3308) used greatest stack depth: 3904 bytes left 17:45:58 NetworkManager[2398]: <info> wake requested (sleeping: yes enabled: yes) 17:45:58 NetworkManager[2398]: <info> waking up and re-enabling... 17:45:58 NetworkManager[2398]: <info> WWAN now enabled by management service 17:45:58 NetworkManager[2398]: <info> (wlp3s0): now managed 17:45:58 NetworkManager[2398]: <info> (wlp3s0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] 17:45:58 NetworkManager[2398]: <info> (wlp3s0): bringing up device. 17:45:58 NetworkManager[2398]: <info> (wlp3s0): deactivating device (reason 'managed') [2] 17:45:58 NetworkManager[2398]: <info> (enp7s0): now managed 17:45:58 NetworkManager[2398]: <info> (enp7s0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] 17:45:58 NetworkManager[2398]: <info> (enp7s0): bringing up device. 17:45:58 kernel: [ 169.186713] r8169 0000:07:00.0 enp7s0: link down 17:45:58 kernel: [ 169.186736] r8169 0000:07:00.0 enp7s0: link down 17:45:58 kernel: [ 169.186749] IPv6: ADDRCONF(NETDEV_UP): enp7s0: link is not ready 17:45:58 NetworkManager[2398]: <info> (enp7s0): preparing device. 17:45:58 NetworkManager[2398]: <info> (enp7s0): deactivating device (reason 'managed') [2] 17:45:59 kernel: [ 170.869838] r8169 0000:07:00.0 enp7s0: link up 17:45:59 kernel: [ 170.869851] IPv6: ADDRCONF(NETDEV_CHANGE): enp7s0: link becomes ready 17:45:59 NetworkManager[2398]: <info> (enp7s0): carrier now ON (device state 20) 17:45:59 NetworkManager[2398]: <info> (enp7s0): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40] 17:45:59 NetworkManager[2398]: <info> Auto-activating connection 'wiredcloned1'. 17:45:59 NetworkManager[2398]: <info> Activation (enp7s0) starting connection 'wiredcloned1' 17:45:59 NetworkManager[2398]: <info> (enp7s0): device state change: disconnected -> prepare (reason 'none') [30 40 0] 17:45:59 NetworkManager[2398]: <info> Activation (enp7s0) Stage 1 of 5 (Device Prepare) scheduled... 17:45:59 NetworkManager[2398]: <info> Activation (enp7s0) Stage 1 of 5 (Device Prepare) started... 17:45:59 NetworkManager[2398]: <info> (enp7s0): taking down device. 17:45:59 NetworkManager[2398]: <info> (enp7s0): set MAC address to 66:66:66:66:66:66 17:45:59 NetworkManager[2398]: <info> (enp7s0): bringing up device. 17:46:00 kernel: [ 170.967389] r8169 0000:07:00.0 enp7s0: link down 17:46:00 kernel: [ 170.967407] r8169 0000:07:00.0 enp7s0: link down 17:46:00 kernel: [ 170.967440] IPv6: ADDRCONF(NETDEV_UP): enp7s0: link is not ready 17:46:00 NetworkManager[2398]: <info> (enp7s0): carrier now OFF (device state 40, deferring action for 4 seconds) 17:46:00 NetworkManager[2398]: <info> Activation (enp7s0) Stage 2 of 5 (Device Configure) scheduled... 17:46:00 NetworkManager[2398]: <info> Activation (enp7s0) Stage 1 of 5 (Device Prepare) complete. 17:46:00 NetworkManager[2398]: <info> Activation (enp7s0) Stage 2 of 5 (Device Configure) starting... 17:46:00 NetworkManager[2398]: <info> (enp7s0): device state change: prepare -> config (reason 'none') [40 50 0] 17:46:00 NetworkManager[2398]: <info> Activation (enp7s0) Stage 2 of 5 (Device Configure) successful. 17:46:00 NetworkManager[2398]: <info> Activation (enp7s0) Stage 3 of 5 (IP Configure Start) scheduled. 17:46:00 NetworkManager[2398]: <info> Activation (enp7s0) Stage 2 of 5 (Device Configure) complete. 17:46:00 NetworkManager[2398]: <info> Activation (enp7s0) Stage 3 of 5 (IP Configure Start) started... 17:46:00 NetworkManager[2398]: <info> (enp7s0): device state change: config -> ip-config (reason 'none') [50 70 0] 17:46:00 NetworkManager[2398]: <info> Activation (enp7s0) Beginning DHCPv4 transaction (timeout in 45 seconds) 17:46:00 NetworkManager[2398]: <info> dhcpcd started with pid 4231 17:46:00 NetworkManager[2398]: <info> Activation (enp7s0) Beginning IP6 addrconf. 17:46:00 kernel: [ 170.971308] IPv6: ADDRCONF(NETDEV_UP): enp7s0: link is not ready 17:46:00 NetworkManager[2398]: <info> Activation (enp7s0) Stage 3 of 5 (IP Configure Start) complete. 17:46:00 dhcpcd[4231]: version 5.6.4 starting 17:46:00 dhcpcd[4231]: enp7s0: sending IPv6 Router Solicitation 17:46:00 dhcpcd[4231]: enp7s0: sendmsg: Network is unreachable 17:46:00 dhcpcd[4231]: enp7s0: rebinding lease of 192.168.1.10 17:46:00 NetworkManager[2398]: <info> (enp7s0): DHCPv4 state changed nbi -> preinit 17:46:01 kernel: [ 172.525009] r8169 0000:07:00.0 enp7s0: link up 17:46:01 kernel: [ 172.525021] IPv6: ADDRCONF(NETDEV_CHANGE): enp7s0: link becomes ready 17:46:01 NetworkManager[2398]: <info> (enp7s0): carrier now ON (device state 70) 17:46:04 dhcpcd[4231]: enp7s0: sending IPv6 Router Solicitation 17:46:05 dhcpcd[4231]: enp7s0: broadcasting for a lease 17:46:08 dhcpcd[4231]: enp7s0: sending IPv6 Router Solicitation 17:46:12 dhcpcd[4231]: enp7s0: sending IPv6 Router Solicitation 17:46:12 dhcpcd[4231]: enp7s0: no IPv6 Routers available 17:46:19 NetworkManager[2398]: <info> (enp7s0): IP6 addrconf timed out or failed. 17:46:19 NetworkManager[2398]: <info> Activation (enp7s0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled... 17:46:19 NetworkManager[2398]: <info> Activation (enp7s0) Stage 4 of 5 (IPv6 Configure Timeout) started... 17:46:19 NetworkManager[2398]: <info> Activation (enp7s0) Stage 4 of 5 (IPv6 Configure Timeout) complete. 17:46:30 dhcpcd[4231]: timed out 17:46:30 NetworkManager[2398]: <info> (enp7s0): DHCPv4 client pid 4231 exited with status 1 17:46:30 NetworkManager[2398]: <info> Activation (enp7s0) Stage 4 of 5 (IPv4 Configure Timeout) scheduled... 17:46:30 NetworkManager[2398]: <info> Activation (enp7s0) Stage 4 of 5 (IPv4 Configure Timeout) started... 17:46:30 NetworkManager[2398]: <info> (enp7s0): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5] 17:46:30 NetworkManager[2398]: <warn> Activation (enp7s0) failed for connection 'wiredcloned1' 17:46:30 NetworkManager[2398]: <info> Activation (enp7s0) Stage 4 of 5 (IPv4 Configure Timeout) complete. 17:46:30 NetworkManager[2398]: <info> (enp7s0): device state change: failed -> disconnected (reason 'none') [120 30 0] 17:46:30 NetworkManager[2398]: <info> (enp7s0): deactivating device (reason 'none') [0] 17:46:30 NetworkManager[2398]: <info> (enp7s0): taking down device. 17:46:30 NetworkManager[2398]: <info> (enp7s0): reset MAC address to 00:AA:BB:12:34:56 17:46:30 NetworkManager[2398]: <info> (enp7s0): bringing up device. 17:46:30 kernel: [ 201.054282] r8169 0000:07:00.0 enp7s0: link down 17:46:30 kernel: [ 201.054299] r8169 0000:07:00.0 enp7s0: link down 17:46:30 kernel: [ 201.054323] IPv6: ADDRCONF(NETDEV_UP): enp7s0: link is not ready 17:46:30 NetworkManager[2398]: <info> (enp7s0): carrier now OFF (device state 30, deferring action for 4 seconds)
if you run "ifconfig enp7s0" during the connection attempt, after NM has changed the MAC to 66, what do you get? I'm just trying to make sure the device has successfully changed MAC address. Next, can you tcpdump the outgoing traffic on the device while the connection is starting so we can see if the driver does actually change the MAC? tcpdump -i enp7s0 should give you the dumps.
Handling cloned-mac-address has been significantly reworked in the meantime. If this bug is about an issue where NetworkManager did something wrong, it's no longer relevant. Actually, I think as of current master, NM's handling of changing MAC addresses is quite correct. Some drivers still have issues, for example https://bugzilla.gnome.org/show_bug.cgi?id=770370#c4 is basically what dcbw says in comment 8. Also, the bug is on needinfo for a long time. I close this as obsolete. If you still have issues, please open a new bug. Thanks.
regarding comment 8, see bug 770370 which is likely the same issue.