Bug 1254089

Summary: Netlink error at 'link_change' function when net interface dynamic plug out and plug in on Xen
Product: Red Hat Enterprise Linux 7 Reporter: Robin Lee <robinlee.sysu>
Component: NetworkManagerAssignee: Beniamino Galvani <bgalvani>
Status: CLOSED ERRATA QA Contact: Desktop QE <desktop-qa-list>
Severity: medium Docs Contact:
Priority: medium    
Version: 7.1CC: bgalvani, dcbw, jklimes, lrintel, rkhan, robinlee.sysu, thaller, tlavigne, vbenes
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: NetworkManager-1.0.6-6.el7 Doc Type: Bug Fix
Doc Text:
When an ethernet interface was added at runtime, NetworkManager did not create a default DHCP connection in some cases. This has been fixed and now NetworkManager always creates a default ethernet connection for new interfaces.
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-11-19 11:03:04 UTC 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:
Attachments:
Description Flags
[PATCH] device: retry creation of default connection after link is initialized
none
debug log of the error none

Description Robin Lee 2015-08-17 07:18:42 UTC
Description of problem:
Error log from NetworkManager shows when an Ethernet card plug out and plug in. And the new net interface is not set up by NetworkManager by default.

Restart NetworkManager will work around this issue.

Aug 17 02:35:14 localhost.localdomain dhclient[31449]: XMT: Solicit on eth0, interval 7170ms.
Aug 17 02:35:21 localhost.localdomain dhclient[31449]: XMT: Solicit on eth0, interval 13820ms.
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <info>  (eth1): carrier is OFF
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <info>  (eth1): new Ethernet device (driver: 'vif' ifindex: 6)
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <info>  (eth1): exported as /org/freedesktop/NetworkManager/Devices/3
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <info>  (eth1): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <info>  (eth1): link connected
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <info>  (eth1): preparing device
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <error> [1439793327.227160] [platform/nm-linux-platform.c:2352] link_change(): Netlink error changing link 6:  <DOWN> mtu 0 (1) driver 'vif' udi '/sys/devices/vif-1/net/eth1': Invalid address for specified address family
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <warn>  (eth1): failed to reset MAC address to 00:00:00:00:00:00
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <info>      read connection 'Wired connection 1'
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <info>  (eth1): created default wired connection 'Wired connection 1'
Aug 17 02:35:27 localhost.localdomain NetworkManager[25613]: <info>  (eth1): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Aug 17 02:35:35 localhost.localdomain dhclient[31449]: XMT: Solicit on eth0, interval 26530ms.
Aug 17 02:35:38 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 5 of 5 (IPv6 Commit) scheduled...
Aug 17 02:35:38 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 5 of 5 (IPv6 Commit) started...
Aug 17 02:35:38 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 5 of 5 (IPv6 Commit) complete.
Aug 17 02:35:52 localhost.localdomain NetworkManager[25613]: <warn>  (eth0): DHCPv6 request timed out.
Aug 17 02:35:52 localhost.localdomain NetworkManager[25613]: <info>  (eth0): DHCPv6 state changed unknown -> timeout
Aug 17 02:35:52 localhost.localdomain NetworkManager[25613]: <info>  (eth0): canceled DHCP transaction, DHCP client pid 31449
Aug 17 02:35:52 localhost.localdomain NetworkManager[25613]: <info>  (eth0): DHCPv6 state changed timeout -> done
Aug 17 02:40:25 localhost.localdomain NetworkManager[25613]: <info>  (eth1): device state change: disconnected -> unmanaged (reason 'removed') [30 10 36]
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth1): carrier is OFF
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth1): new Ethernet device (driver: 'vif' ifindex: 7)
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth1): exported as /org/freedesktop/NetworkManager/Devices/4
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth1): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <error> [1439793640.047694] [platform/nm-linux-platform.c:2352] link_change(): Netlink error changing link 7:  <UP> mtu 0 (1) driver 'vif' udi '/sys/devices/vif-1/net/eth1': Invalid address for specified address family
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth1): preparing device
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>      read connection 'Wired connection 1'
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth1): created default wired connection 'Wired connection 1'
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth0): device state change: activated -> deactivating (reason 'user-requested') [100 110 39]
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  NetworkManager state is now DISCONNECTING
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth0): device state change: deactivating -> disconnected (reason 'user-requested') [110 30 39]
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth0): deactivating device (reason 'user-requested') [39]
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth0): canceled DHCP transaction, DHCP client pid 31372
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (eth0): DHCPv4 state changed bound -> done
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  NetworkManager state is now DISCONNECTED
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  (lo): link disconnected
Aug 17 02:40:40 localhost.localdomain NetworkManager[25613]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Aug 17 02:40:41 localhost.localdomain NetworkManager[25613]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Aug 17 02:40:41 localhost.localdomain NetworkManager[25613]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Aug 17 02:40:41 localhost.localdomain NetworkManager[25613]: <info>  (lo): link connected
Aug 17 02:40:41 localhost.localdomain NetworkManager[25613]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Aug 17 02:40:41 localhost.localdomain NetworkManager[25613]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: starting connection 'eth0'
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 1 of 5 (Device Prepare) scheduled...
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 1 of 5 (Device Prepare) started...
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  NetworkManager state is now CONNECTING
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 2 of 5 (Device Configure) scheduled...
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 1 of 5 (Device Prepare) complete.
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 2 of 5 (Device Configure) starting...
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): device state change: prepare -> config (reason 'none') [40 50 0]
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 2 of 5 (Device Configure) successful.
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 2 of 5 (Device Configure) complete.
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 3 of 5 (IP Configure Start) scheduled.
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 3 of 5 (IP Configure Start) started...
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): device state change: config -> ip-config (reason 'none') [50 70 0]
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  Activation (eth0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  dhclient started with pid 747
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 3 of 5 (IP Configure Start) complete.
Aug 17 02:40:42 localhost.localdomain dhclient[747]: DHCPREQUEST on eth0 to 255.255.255.255 port 67 (xid=0x5343c405)
Aug 17 02:40:42 localhost.localdomain dhclient[747]: DHCPACK from 10.10.112.254 (xid=0x5343c405)
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>    address 10.10.112.144
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>    plen 24 (255.255.255.0)
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>    gateway 10.10.112.254
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>    server identifier 10.10.112.254
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>    lease time 86400
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>    nameserver '202.96.128.86'
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>    nameserver '202.96.128.68'
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): DHCPv4 state changed unknown -> bound
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Aug 17 02:40:42 localhost.localdomain dhclient[747]: bound to 10.10.112.144 -- renewal in 37621 seconds.
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 5 of 5 (IPv4 Commit) started...
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): device state change: ip-config -> ip-check (reason 'none') [70 80 0]
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 5 of 5 (IPv4 Commit) complete.
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): device state change: ip-check -> secondaries (reason 'none') [80 90 0]
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): device state change: secondaries -> activated (reason 'none') [90 100 0]
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  NetworkManager state is now CONNECTED_LOCAL
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  NetworkManager state is now CONNECTED_GLOBAL
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  Policy set 'eth0' (eth0) as default for IPv4 routing and DNS.
Aug 17 02:40:42 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: successful, device activated.
Aug 17 02:40:43 localhost.localdomain NetworkManager[25613]: <info>  (eth0): Activation: Stage 3 of 5 (IP Configure Start) starting DHCPv6 as requested by IPv6 router...
Aug 17 02:40:43 localhost.localdomain NetworkManager[25613]: <info>  Activation (eth0) Beginning DHCPv6 transaction (timeout in 45 seconds)
Aug 17 02:40:43 localhost.localdomain NetworkManager[25613]: <info>  dhclient started with pid 836
Aug 17 02:40:43 localhost.localdomain dhclient[836]: XMT: Solicit on eth0, interval 1090ms.
Aug 17 02:40:44 localhost.localdomain dhclient[836]: XMT: Solicit on eth0, interval 2100ms.
Aug 17 02:40:46 localhost.localdomain dhclient[836]: XMT: Solicit on eth0, interval 4340ms.
Aug 17 02:40:51 localhost.localdomain dhclient[836]: XMT: Solicit on eth0, interval 8280ms.
Aug 17 02:40:59 localhost.localdomain dhclient[836]: XMT: Solicit on eth0, interval 16240ms.
Aug 17 02:41:15 localhost.localdomain dhclient[836]: XMT: Solicit on eth0, interval 33740ms.
Aug 17 02:41:24 localhost.localdomain systemd[1]: Stopping Network Manager...
Aug 17 02:41:24 localhost.localdomain NetworkManager[25613]: <info>  caught signal 15, shutting down normally.
Aug 17 02:41:24 localhost.localdomain NetworkManager[25613]: <info>  (eth1): device state change: unavailable -> unmanaged (reason 'removed') [20 10 36]
Aug 17 02:41:24 localhost.localdomain systemd[1]: Starting Network Manager...
Aug 17 02:41:24 localhost.localdomain NetworkManager[985]: <info>  NetworkManager (version 1.0.0-16.git20150121.b4ea599c.el7_1) is starting...
Aug 17 02:41:24 localhost.localdomain NetworkManager[985]: <info>  Read config: /etc/NetworkManager/NetworkManager.conf and conf.d: 10-ibft-plugin.conf
Aug 17 02:41:24 localhost.localdomain NetworkManager[985]: <info>  WEXT support is disabled
Aug 17 02:41:24 localhost.localdomain NetworkManager[985]: <info>  Acquired D-Bus service com.redhat.ifcfgrh1
Aug 17 02:41:24 localhost.localdomain NetworkManager[985]: <info>  Loaded plugin ifcfg-rh: (c) 2007 - 2013 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Aug 17 02:41:24 localhost.localdomain NetworkManager[985]: <info>  Loaded plugin iBFT: (c) 2014 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Aug 17 02:41:24 localhost.localdomain NetworkManager[985]: <info>  Loaded plugin keyfile: (c) 2007 - 2013 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Aug 17 02:41:24 localhost.localdomain NetworkManager[985]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Aug 17 02:41:24 localhost.localdomain NetworkManager[985]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-eth0 ...


Version-Release number of selected component (if applicable):
NetworkManager-1.0.0-16.git20150121.b4ea599c.el7_1.x86_64
xen 4.1.6

How reproducible:
Mostly.

Steps to Reproduce:
1.Install CentOS7 as a vm on Xen
2.add two Ethernet cards and use dhcp to set them up
3.remove the latter one eth1
4.and right after, re-add the card. With a different mac address, the issue will be more reproducible.

Actual results:


Expected results:


Additional info:

Comment 2 Thomas Haller 2015-08-17 10:27:34 UTC
What exactly is the problem?

Obviously, there is an error logging. Is that the only problem?
Apart from that, what does not work (not work as expected)?

You say also 
  "And the new net interface is not set up by NetworkManager by default.".
Could you elaborate on that: what do you expect to happen, and what is happening instead?


Thank you.

Comment 3 Robin Lee 2015-08-17 12:52:46 UTC
By default NetworkManager would enable any wired connection with DHCP. But the re-added interface is not set up, until manually restarting NetworkManager.

Comment 4 Jirka Klimes 2015-08-25 12:26:53 UTC
NetworkManager creates a default DHCP connection
<info>  (eth1): created default wired connection 'Wired connection 1'

But it may not be upped due to missing carrier or something. Would you get output of "ip a" command to see the state of the interfaces?

Comment 5 Beniamino Galvani 2015-09-02 13:47:21 UTC
Ok, I think I can reproduce this. When the new link is detected NM
tries to generate a default "Wired connection #" in
nm_settings_device_added(). But if the link has not been initialized
by udev yet, the function returns early because priv->unmanaged_flags
= UNMANAGED_PLATFORM_INIT, and then the default connection is not
created.

Probably we should retry to generate the connection later, after the
link becomes fully initialized.

Robin, can you please attach NetworkManager logs with debug enabled so
that I can verify you're hitting the same problem? Just run 'nmcli
general logging level DEBUG', reproduce the issue and then post the
relevant part of 'journalctl -u NetworkManager -b'. Thanks.

Comment 6 Beniamino Galvani 2015-09-03 15:17:58 UTC
Created attachment 1069925 [details]
[PATCH] device: retry creation of default connection after link is initialized

Comment 7 Lubomir Rintel 2015-09-03 16:09:44 UTC
Patch LGTM

Comment 8 Thomas Haller 2015-09-03 17:19:56 UTC
(In reply to Beniamino Galvani from comment #6)
> Created attachment 1069925 [details]
> [PATCH] device: retry creation of default connection after link is
> initialized

patch merged to master: http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=b3b0b4625053d5647e2756bbe745652889684a21

Comment 11 Robin Lee 2015-09-17 08:50:24 UTC
Created attachment 1074357 [details]
debug log of the error

Sorry for my late response, this is debug log containing the error.

Comment 12 Vladimir Benes 2015-10-07 08:51:49 UTC
Creation of Wired connection for veth devices after uncommenting line ENV{ID_NET_DRIVER}=="veth", ENV{NM_UNMANAGED}="1" in  /usr/lib/udev/rules.d/85-nm-unmanaged.rules

works as expected.

Comment 13 errata-xmlrpc 2015-11-19 11:03:04 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2015-2315.html