Bug 2160348

Jarda, it seems related to libvirt.

We might need the full libvirt debug logs for this. Seems like the device hasn't been re-created on the host of the detach. Some udev feature?

Laine, please have a look. Thanks.

Created attachment 1940836 [details]
libvirtd.log

This must be something out of libvirt's control. Here's a snippet from the logs:

2023-01-28 02:55:00.486+0000: 705217: debug : virDomainAttachDevice:8720 : dom=0x7f02d40028b0, (VM: name=lmn, uuid=ed0e603e-68fc-4bc6-9ac9-39e69759709e), xml=<interface type='direct'>
<mac address='7a:3d:d6:18:19:76'/>
<vlan>
        <tag id='50'/>
      </vlan>
<source dev='enp59s2f16v0' mode='passthrough'/>
      <address type='pci' domain='0x0000' bus='0x09' slot='0x00' function='0x0'/>
</interface>


2023-01-28 02:55:01.849+0000: 705217: debug : virNetDevSetMACInternal:282 : SIOCSIFHWADDR enp59s2f16v0 MAC=7a:3d:d6:18:19:76 - Success
2023-01-28 02:55:01.951+0000: 705217: debug : virNetDevSetVfVlan:1622 : RTM_SETLINK ens1f0 vf 0 vlanid=50 - Success
2023-01-28 02:55:01.958+0000: 705217: debug : virNetlinkNewLink:593 : Creating macvtap interface 'macvtap1'
2023-01-28 02:55:01.959+0000: 705217: info : virNetDevMacVLanCreate:122 : created device: 'macvtap1'
2023-01-28 02:55:01.959+0000: 705217: debug : virNetDevVPortProfileAssociate:1238 : profile:'(nil)' vmOp: create device: macvtap1@enp59s2f16v0 mac: 7a:3d:d6:18:19:76 uuid: ed0e603e-68fc-4bc6-9ac9-39e69759709e
2023-01-28 02:55:01.959+0000: 705217: info : virObjectUnref:378 : OBJECT_UNREF: obj=0x7f029802a0e0
2023-01-28 02:55:01.960+0000: 705217: info : virSecuritySELinuxFSetFilecon:1390 : Setting SELinux context on fd 24 to 'system_u:object_r:tun_tap_device_t:s0:c460,c791'
2023-01-28 02:55:01.960+0000: 705217: error : virNetDevSetIFFlag:616 : Cannot set interface flags on 'enp59s2f16v0': No such device
2023-01-28 02:55:01.972+0000: 705217: debug : virNetDevVPortProfileDisassociate:1304 : profile:'(nil)' vmOp: destroy device: macvtap1@enp59s2f16v0 mac: 7a:3d:d6:18:19:76
2023-01-28 02:55:01.972+0000: 705217: info : virNetDevMacVLanDelete:137 : delete device: 'macvtap1'

2023-01-28 02:55:02.039+0000: 705217: debug : virPCIGetVirtualFunctionsFull:2400 : Found 1 virtual functions for /sys/class/net/ens1f0/device
2023-01-28 02:55:02.040+0000: 705217: debug : virJSONValueFromString:1683 : string={
  "adminMac": "52:53:1e:59:e1:30",
  "vlanTag": 0,
  "mac": "52:53:1e:59:e1:30"
}


2023-01-28 02:55:02.040+0000: 705217: debug : virPCIGetVirtualFunctionsFull:2400 : Found 1 virtual functions for /sys/class/net/ens1f0/device
2023-01-28 02:55:02.049+0000: 705217: debug : virNetDevSetMACInternal:282 : SIOCSIFHWADDR enp59s2f16v0 MAC=52:53:1e:59:e1:30 - Success

(I've limited the output only to the thread that's executing the API)

So, firstly, at 02:55:01.849+0000 the MAC address is set on the device successfully. But when the device is brought online (virNetDevSetIFFlag()) the device suddenly disappears 02:55:01.960+0000 (i.e. 111ms later), only to reappear back again when its original MAC address is restored at 02:55:02.049+0000 (i.e. 89ms after the failure). I wonder whether us, creating a macvtap resulted in some udev actions, that maybe temporarily renamed the device.

Also, this is how virNetDevSetIFFlag() is implemented:

virNetDevSetIFFlag(const char *ifname, int flag, bool val)
{
    ...
    if ((fd = virNetDevSetupControl(ifname, &ifr)) < 0)
        return -1;

    if (ioctl(fd, SIOCGIFFLAGS, &ifr) < 0) {
        virReportSystemError(errno,
                             _("Cannot get interface flags on '%s'"),
                             ifname);
        return -1;
    }

    ...
    if (ioctl(fd, SIOCSIFFLAGS, &ifr) < 0) {
            virReportSystemError(errno,
                                 _("Cannot set interface flags on '%s'"),
                                 ifname);
            return -1;
        }
    }

    return 0;
}

And the error message we see comes from the SIOCSIFFLAGS, not SIOCGIFFLAGS. So the device was definitely accessible when getting the flags. Therefore I think we're just racing with something (I suspect udev). But placing 'udevadm settle' anywhere just doesn't feel right.

Issue migration from Bugzilla to Jira is in process at this time. This will be the last message in Jira copied from the Bugzilla bug.

This BZ has been automatically migrated to the issues.redhat.com Red Hat Issue Tracker. All future work related to this report will be managed there.

Due to differences in account names between systems, some fields were not replicated.  Be sure to add yourself to Jira issue's "Watchers" field to continue receiving updates and add others to the "Need Info From" field to continue requesting information.

To find the migrated issue, look in the "Links" section for a direct link to the new issue location. The issue key will have an icon of 2 footprints next to it, and begin with "RHEL-" followed by an integer.  You can also find this issue by visiting https://issues.redhat.com/issues/?jql= and searching the "Bugzilla Bug" field for this BZ's number, e.g. a search like:

"Bugzilla Bug" = 1234567

In the event you have trouble locating or viewing this issue, you can file an issue by sending mail to rh-issues. You can also visit https://access.redhat.com/articles/7032570 for general account information.