After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 673334 - Network manager fail to connect network when cloned-mac-address is set
Network manager fail to connect network when cloned-mac-address is set
Status: RESOLVED OBSOLETE
Product: NetworkManager
Classification: Platform
Component: general
0.9.x
Other Linux
: Normal normal
: ---
Assigned To: Dan Williams
NetworkManager maintainer(s)
: 682962 (view as bug list)
Depends on:
Blocks:
 
 
Reported: 2012-04-02 05:40 UTC by Michael Biebl
Modified: 2017-03-07 22:33 UTC
See Also:
GNOME target: ---
GNOME version: ---



Description Michael Biebl 2012-04-02 05:40:02 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.
Comment 1 Jiri Klimes 2012-04-04 10:21:04 UTC
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
)
Comment 2 Michael Biebl 2012-04-04 12:15:08 UTC
(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.
Comment 3 Rémi 2012-04-04 13:46:49 UTC
I can confirm that I reproduce this bug on my wired connection.
Comment 4 Dan Winship 2012-04-04 15:02:43 UTC
> 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)
Comment 5 Rémi 2012-04-04 19:18:19 UTC
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
Comment 6 Jiri Klimes 2012-04-12 15:02:21 UTC
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.
Comment 7 Jiri Klimes 2012-09-11 13:19:25 UTC
*** Bug 682962 has been marked as a duplicate of this bug. ***
Comment 8 Dan Williams 2013-02-12 17:16:51 UTC
(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.
Comment 9 BugsBunny 2013-04-14 22:34:10 UTC
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)
Comment 10 Dan Williams 2013-04-15 18:54:15 UTC
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.
Comment 11 Thomas Haller 2017-03-07 21:57:48 UTC
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.
Comment 12 Thomas Haller 2017-03-07 22:33:36 UTC
regarding comment 8, see bug 770370 which is likely the same issue.