Regression: Persistent net names via /etc/udev/rules.d/70-persistent-net.rules fail

I've done some further tests after boot-time.

$ cat /etc/udev/rules.d/70-persistent-net.rules
# This file was automatically generated by the /lib/udev/write_net_rules
# program, run by the persistent-net-generator.rules rules file.
#
# You can modify it, as long as you keep each rule on a single
# line, and change only the value of the NAME= key.

# PCI device 0x10de:0x03ef (forcedeth)
SUBSYSTEM=="net", ACTION=="add", DRIVERS=="?*", ATTR{address}=="00:25:22:75:e6:9e", ATTR{dev_id}=="0x0", ATTR{type}=="1", KERNEL=="eth*", NAME="eth0"

# PCI device 0x8086:0x10bc (e1000e)
SUBSYSTEM=="net", ACTION=="add", DRIVERS=="?*", ATTR{address}=="00:15:17:8f:99:c0", ATTR{dev_id}=="0x0", ATTR{type}=="1", KERNEL=="eth*", NAME="eth1"

# PCI device 0x8086:0x10bc (e1000e)
SUBSYSTEM=="net", ACTION=="add", DRIVERS=="?*", ATTR{address}=="00:15:17:8f:99:c1", ATTR{dev_id}=="0x0", ATTR{type}=="1", KERNEL=="eth*", NAME="eth2"

# PCI device 0x8086:0x10bc (e1000e)
SUBSYSTEM=="net", ACTION=="add", DRIVERS=="?*", ATTR{address}=="00:15:17:8f:99:c2", ATTR{dev_id}=="0x0", ATTR{type}=="1", KERNEL=="eth*", NAME="eth3"

# PCI device 0x8086:0x10bc (e1000e)
SUBSYSTEM=="net", ACTION=="add", DRIVERS=="?*", ATTR{address}=="00:15:17:8f:99:c3", ATTR{dev_id}=="0x0", ATTR{type}=="1", KERNEL=="eth*", NAME="eth4"

$ inotifywatch -m /etc/udev/rules.d/
$ service udev restart

/etc/udev/rules.d/ OPEN,ISDIR
/etc/udev/rules.d/ CLOSE_NOWRITE,CLOSE,ISDIR
/etc/udev/rules.d/ OPEN 70-persistent-net.rules
/etc/udev/rules.d/ ACCESS 70-persistent-net.rules
/etc/udev/rules.d/ CLOSE_NOWRITE,CLOSE 70-persistent-net.rules

$ ifconfig -a | grep '^eth'
eth0 Link encap:Ethernet HWaddr 00:15:17:8f:99:c1 # rules say eth2
eth1 Link encap:Ethernet HWaddr 00:15:17:8f:99:c0 # rules say eth1
eth2 Link encap:Ethernet HWaddr 00:25:22:75:e6:9e # rules say eth0
eth3 Link encap:Ethernet HWaddr 00:15:17:8f:99:c3 # rules say eth4
eth4 Link encap:Ethernet HWaddr 00:15:17:8f:99:c2 # rules say eth3

$ udevadm monitor --kernel --udev --property --subsystem-match=net | tee /tmp/udev.log
$udevadm trigger action=add subsystem-match=net

Attached "udev.log" containing monitor output.

Here's a reference in dmesg during boot about eth4 - but no mention of the other interfaces:

 systemd-udevd[1307]: error changing net interface name eth4 to eth3: File exists

$ grep eth /var/log/dmesg
[ 0.960091] forcedeth: Reverse Engineered nForce ethernet driver. Version 0.64.
[ 0.960379] forcedeth 0000:00:07.0: setting latency timer to 64
[ 1.132202] e1000e 0000:04:00.0 eth0: (PCI Express:2.5GT/s:Width x4) 00:15:17:8f:99:c1
[ 1.132281] e1000e 0000:04:00.0 eth0: Intel(R) PRO/1000 Network Connection
[ 1.132426] e1000e 0000:04:00.0 eth0: MAC: 0, PHY: 4, PBA No: D72468-003
[ 1.309738] e1000e 0000:04:00.1 eth1: (PCI Express:2.5GT/s:Width x4) 00:15:17:8f:99:c0
[ 1.309739] e1000e 0000:04:00.1 eth1: Intel(R) PRO/1000 Network Connection
[ 1.309815] e1000e 0000:04:00.1 eth1: MAC: 0, PHY: 4, PBA No: D72468-003
[ 1.482147] forcedeth 0000:00:07.0: ifname eth2, PHY OUI 0x732 @ 1, addr 00:25:22:75:e6:9e
[ 1.482227] forcedeth 0000:00:07.0: highdma pwrctl mgmt lnktim msi desc-v3
[ 1.486796] e1000e 0000:05:00.0 eth3: (PCI Express:2.5GT/s:Width x4) 00:15:17:8f:99:c3
[ 1.486891] e1000e 0000:05:00.0 eth3: Intel(R) PRO/1000 Network Connection
[ 1.487040] e1000e 0000:05:00.0 eth3: MAC: 0, PHY: 4, PBA No: D72468-003
[ 1.761606] e1000e 0000:05:00.1 eth4: (PCI Express:2.5GT/s:Width x4) 00:15:17:8f:99:c2
[ 1.761619] e1000e 0000:05:00.1 eth4: Intel(R) PRO/1000 Network Connection
[ 1.761704] e1000e 0000:05:00.1 eth4: MAC: 0, PHY: 4, PBA No: D72468-003
[ 17.115278] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 17.115285] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
[ 17.115289] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
[ 17.115294] IPv6: ADDRCONF(NETDEV_UP): eth3: link is not ready
[ 17.115298] IPv6: ADDRCONF(NETDEV_UP): eth4: link is not ready
[ 18.813099] systemd-udevd[1307]: error changing net interface name eth4 to eth3: File exists

Added to the kernel command-line: "udev.log-priority=7 udev.rdlog-priority=7"

/var/log/dmesg was flooded and lost some of the early messages since I didn't increase the log-buffer size but it did catch the systemd-udevd logging especially related to the 'net' subsystem:

$ grep -B 2 -A 2 eth /var/log/dmesg
[ 18.491927] EXT4-fs (dm-0): re-mounted. Opts: errors=remount-ro
[ 19.011059] EXT4-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null)
[ 19.251979] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 19.251985] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
[ 19.251990] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
[ 19.251995] IPv6: ADDRCONF(NETDEV_UP): eth3: link is not ready
[ 19.251999] IPv6: ADDRCONF(NETDEV_UP): eth4: link is not ready
[ 19.823143] EXT4-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null)
[ 19.868611] systemd-udevd[1283]: starting version 204
--
[ 21.828403] systemd-udevd[1348]: device 0x18d0530 filled with db file data
[ 21.828823] systemd-udevd[1348]: device 0x1812440 has devpath '/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.1'
[ 21.828884] systemd-udevd[1348]: NAME 'eth1' /etc/udev/rules.d/70-persistent-net.rules:11
[ 21.828980] systemd-udevd[1348]: device 0x1812440 filled with db file data
[ 21.828985] systemd-udevd[1348]: IMPORT builtin 'net_id' /lib/udev/rules.d/75-net-description.rules:6
--
[ 22.028940] systemd-udevd[1348]: device 0x18096a0 has devpath '/devices/pci0000:00'
[ 22.028980] systemd-udevd[1348]: IMPORT builtin 'hwdb' /lib/udev/rules.d/75-net-description.rules:12
[ 22.029065] systemd-udevd[1348]: changing net interface name from 'eth2' to 'eth1'
[ 22.029079] systemd-udevd[1348]: error changing net interface name eth2 to eth1: File exists
[ 22.029294] systemd-udevd[1348]: created db file '/run/udev/data/n4' for '/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.1/net/eth2'
[ 22.029316] systemd-udevd[1348]: passed -1 bytes to netlink monitor 0x18d1420
[ 22.029321] systemd-udevd[1348]: seq 2011 processed with -17

And this time, for the first time, the original 'eth2' that is supposed to become 'eth0' is actually 'eth1'. I attribute it to the udevd logging causing timing differences affecting kernel uevent arrival order.

$ ifconfig -a | grep '^eth'
eth0 Link encap:Ethernet HWaddr 00:15:17:8f:99:c1
eth1 Link encap:Ethernet HWaddr 00:25:22:75:e6:9e
eth2 Link encap:Ethernet HWaddr 00:15:17:8f:99:c0
eth3 Link encap:Ethernet HWaddr 00:15:17:8f:99:c3
eth4 Link encap:Ethernet HWaddr 00:15:17:8f:99:c2

The issue seems to be triggered by the code in src/udev/udev-event.c::rename_netif()

static int rename_netif(struct udev_event *event)
{
        struct udev_device *dev = event->dev;
        int sk;
        struct ifreq ifr;
        int err;

        log_debug("changing net interface name from '%s' to '%s'\n",
                  udev_device_get_sysname(dev), event->name);

        sk = socket(PF_INET, SOCK_DGRAM, 0);
        if (sk < 0) {
                err = -errno;
                log_error("error opening socket: %m\n");
                return err;
        }

        memset(&ifr, 0x00, sizeof(struct ifreq));
        strscpy(ifr.ifr_name, IFNAMSIZ, udev_device_get_sysname(dev));
        strscpy(ifr.ifr_newname, IFNAMSIZ, event->name);
        err = ioctl(sk, SIOCSIFNAME, &ifr);
        if (err >= 0) {
                print_kmsg("renamed network interface %s to %s\n", ifr.ifr_name, ifr.ifr_newname);
        } else {
                err = -errno;
                log_error("error changing net interface name %s to %s: %m\n", ifr.ifr_name, ifr.ifr_newname);
        }
        close(sk);
        return err;
}

It seems as if the call to ioctl(sk, SIOCSIFNAME, &ifr) returns error code -EEXIST (17, 0x11)).

$ man 7 netdevice | grep -A 2 SIOCSIFNAME
       SIOCSIFNAME
              Changes the name of the interface specified in ifr_name to ifr_newname. This is a privileged operation. It is
              only allowed when the interface is not up.

"It is only allowed when the interface is not up" but the dmesg log shows that the IPv6 protocol is already up on those interfaces

[ 19.251979] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 19.251985] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
[ 19.251990] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
[ 19.251995] IPv6: ADDRCONF(NETDEV_UP): eth3: link is not ready
[ 19.251999] IPv6: ADDRCONF(NETDEV_UP): eth4: link is not ready
[ 22.029079] systemd-udevd[1348]: error changing net interface name eth2 to eth1: File exists

Following "ioctl(sk, SIOCSIFNAME, &ifr)" through the kernel:

net/core/dev_ioctl::dev_ioctl()
 net/core/dev_ioctl.c::dev_ifsioc()
  net/core/dev.c::dev_change_name()
   net/core/dev.c::dev_get_valid_name()
    net/core/dev.c::__dev_get_by_name()

struct net_device *dev_get_by_name_rcu(struct net *net, const char *name)
{
        struct net_device *dev;
        struct hlist_head *head = dev_name_hash(net, name);

        hlist_for_each_entry_rcu(dev, head, name_hlist)
                if (!strncmp(dev->name, name, IFNAMSIZ))
                        return dev;

        return NULL;
}

static int dev_get_valid_name(struct net *net,
                              struct net_device *dev,
                              const char *name)
{
        BUG_ON(!net);

        if (!dev_valid_name(name))
                return -EINVAL;

        if (strchr(name, '%'))
                return dev_alloc_name_ns(net, dev, name);
        else if (__dev_get_by_name(net, name))
                return -EEXIST;
        else if (dev->name != name)
                strlcpy(dev->name, name, IFNAMSIZ);

        return 0;
}

So this seems to be where the IOCTL error originates, but there needs to be an explanation.

Looking at the 'git damage' and commit history for 'net/core/dev.c' in particular there are some control-group related changes that look like they may be implicated. They certainly seem to be in the appropriate time-frame since earlier kernels don't have the problem (I have another server with 12.04 LTS and Linux 3.2.0 which has 10 Ethernet ports which are renamed correctly).

This bug is missing log files that will aid in diagnosing the problem. From a terminal window please run:

apport-collect 1235162

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

This is confirmed as a systemd-udev regression.

Code that previously existed in rename_netif() to support a temporary interface name ("rename%u") has been removed. As a result, the '70-persistent-net.rules' actions that try to shuffle existing names will now fail.

systemd commit log:

commit 97595710b77aa162ca5e20da57d0a1ed7355eaad
Author: Kay Sievers <email address hidden>
Date: Thu Jul 5 17:40:50 2012 +0200

    udev: network device renaming - immediately give up if the target name isn't available

The systemd-udev commit first appears in Ubuntu 13.10.

git describe --contains 97595710b7
v187~162

Raring: udev (175-0ubuntu26)
Saucy: udev (204-0ubuntu15)

Nominated for Saucy since this will break multi-homed server upgrades in nasty ways especially if they're headless and remotely located.

I've linked a proposed patch which reverts commit 97595710b7. Revert doesn't apply cleanly so I massaged the patch to fit.

Here is confirmation that it works as expected:

$ egrep -A 2 'move.*(eth|rename)[[:digit:]]' /var/log/udev
KERNEL[19.167867] move /devices/pci0000:00/0000:00:07.0/net/rename4 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/rename4
--
KERNEL[19.449910] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/rename6 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/rename6
--
KERNEL[19.472417] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.0/net/eth2 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.0/net/eth2
--
KERNEL[19.488425] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.0/net/eth4 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.0/net/eth4
--
KERNEL[19.504160] move /devices/pci0000:00/0000:00:07.0/net/eth0 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/eth0
--
KERNEL[19.528341] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/eth3 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/eth3
--
UDEV [26.859211] move /devices/pci0000:00/0000:00:07.0/net/rename4 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/rename4
--
UDEV [26.878494] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/rename6 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/rename6
--
UDEV [26.880061] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.0/net/eth2 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.0/net/eth2
--
UDEV [26.881605] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.0/net/eth4 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.0/net/eth4
--
UDEV [26.883240] move /devices/pci0000:00/0000:00:07.0/net/eth0 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/eth0
--
UDEV [26.884382] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/eth3 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/eth3

$ ifconfig -a | grep '^eth'
eth0 Link encap:Ethernet HWaddr 00:25:22:75:e6:9e
eth1 Link encap:Ethernet HWaddr 00:15:17:8f:99:c0
eth2 Link encap:Ethernet HWaddr 00:15:17:8f:99:c1
eth3 Link encap:Ethernet HWaddr 00:15:17:8f:99:c2
eth4 Link encap:Ethernet HWaddr 00:15:17:8f:99:c3

$ sudo ifup -a 2>&1 | tee /tmp/ifup.log
Reading directory /etc/network/interfaces.d
Parsing file /etc/network/interfaces.d/eth0
Parsing file /etc/network/interfaces.d/eth1
Parsing file /etc/network/interfaces.d/eth2
Parsing file /etc/network/interfaces.d/eth3
Parsing file /etc/network/interfaces.d/eth4
Parsing file /etc/net...

Improved extract from udev.log showing the DEVPATH_OLD values:

$ egrep -A 3 'move.*(eth|rename)[[:digit:]]' /var/log/udev
KERNEL[19.167867] move /devices/pci0000:00/0000:00:07.0/net/rename4 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/rename4
DEVPATH_OLD=/devices/pci0000:00/0000:00:07.0/net/eth2
--
KERNEL[19.449910] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/rename6 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/rename6
DEVPATH_OLD=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/eth4
--
KERNEL[19.472417] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.0/net/eth2 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.0/net/eth2
DEVPATH_OLD=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.0/net/eth0
--
KERNEL[19.488425] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.0/net/eth4 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.0/net/eth4
DEVPATH_OLD=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.0/net/eth3
--
KERNEL[19.504160] move /devices/pci0000:00/0000:00:07.0/net/eth0 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/eth0
DEVPATH_OLD=/devices/pci0000:00/0000:00:07.0/net/rename4
--
KERNEL[19.528341] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/eth3 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/eth3
DEVPATH_OLD=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/rename6
--
UDEV [26.859211] move /devices/pci0000:00/0000:00:07.0/net/rename4 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/rename4
DEVPATH_OLD=/devices/pci0000:00/0000:00:07.0/net/eth2
--
UDEV [26.878494] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/rename6 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/rename6
DEVPATH_OLD=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.1/net/eth4
--
UDEV [26.880061] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.0/net/eth2 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.0/net/eth2
DEVPATH_OLD=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:00.0/0000:04:00.0/net/eth0
--
UDEV [26.881605] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.0/net/eth4 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.0/net/eth4
DEVPATH_OLD=/devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:05:00.0/net/eth3
--
UDEV [26.883240] move /devices/pci0000:00/0000:00:07.0/net/eth0 (net)
ACTION=move
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/eth0
DEVPATH_OLD=/devices/pci0000:00/0000:00:07.0/net/rename4
--
UDEV [26.884382] move /devices/pci0000:00/0000:00:09.0/0000:02:00.0/0000:03:01.0/0000:...

This bug was fixed in the package systemd - 204-0ubuntu16

---------------
systemd (204-0ubuntu16) saucy; urgency=low

  [ TJ ]
  * Add 0030-revert-removal-of-rename_netif-functionality.patch: Return the
    previous ability to postpone renaming until the target interface name
    is free. (LP: #1235162)

  [ Martin Pitt ]
  * Refresh debian/extra/60-keyboard.hwdb to fix Samsung models.
 -- Martin Pitt <email address hidden> Wed, 09 Oct 2013 16:16:50 +0200