Bug 1557902 - Unnecessary error in libvirtd log when veth interface is renaming to fast
Summary: Unnecessary error in libvirtd log when veth interface is renaming to fast
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux Advanced Virtualization
Classification: Red Hat
Component: libvirt
Version: 8.0
Hardware: x86_64
OS: Linux
medium
medium
Target Milestone: rc
: ---
Assignee: Michal Privoznik
QA Contact: Virtualization Bugs
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-03-19 08:41 UTC by Tomas Rusnak
Modified: 2024-03-25 15:03 UTC (History)
15 users (show)

Fixed In Version: libvirt-6.3.0-1.el8
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-11-17 17:44:45 UTC
Type: Bug
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)

Description Tomas Rusnak 2018-03-19 08:41:22 UTC
Description of problem:
error in log when veth is going quickly up and down or rename

Steps to Reproduce:
1. ip l add link enp0s31f6 name asdf type macvlan; ip l set asdf name fdsa
2. watch the log

Actual results:
2018-03-19 08:33:58.198+0000: 6779: error : virFileReadAll:1420 : Failed to open file '/sys/class/net/asdf/operstate': No such file or directory
2018-03-19 08:33:58.198+0000: 6779: error : virNetDevGetLinkInfo:2552 : unable to read: /sys/class/net/asdf/operstate: No such file or directory


Expected results:
no error

Comment 2 Martin Kletzander 2018-03-22 06:54:44 UTC
Errors when updating devices upon an event should not emit errors to logs, but rather just a warning.  That goes not only for the probing of the state of the device but any other probing in the callback handler.

Having said that we need to make sure libvirt knows about the new name of the device as well.

Comment 3 Laine Stump 2018-03-22 16:46:16 UTC
You need to be careful that when everything is finished and settled down, the nodedev driver has an up-to-date view of the new device in its cache. If we just issue a warning and continue on the same path as if the error hadn't occurred, that won't happen. Instead we need to retry after some amount of delay (implementing the delay in whatever way you think is "least bad" :-/).

This problem is similar to the one where sysfs isn't yet properly populated when we get the udev event from the kernel - we'll probably have to put in a similar hack.

Comment 4 Martin Kletzander 2018-03-26 14:18:05 UTC
(In reply to Laine Stump from comment #3)
That's what I meant with "we need to make sure libvirt knows about the new name of the device".  Probably fits into similar category, yes.

Comment 9 Martin Kletzander 2019-11-13 14:47:08 UTC
Can anyone reproduce this on newer version of libvirt? I stopped getting these errors and I'm not sure if something changed in the setup.

Comment 10 Davide F Bragalone 2019-11-13 15:39:04 UTC
Hi Martin,

I've asked the customer in my ticket to test with newer version. Not sure if this is feasible though, I'll update this BZ as soon as I have any feedback from him.

Regards,
Davide

Comment 11 jiyan 2019-11-26 05:59:24 UTC
Hi I can reproduce this issue in the latest RHEL-7.8, and I will try RHEL-8 later.

Version:
libvirt-4.5.0-28.virtcov.el7.x86_64
qemu-kvm-rhev-2.12.0-38.el7.x86_64
kernel-3.10.0-1113.el7.x86_64

Steps:
Terminal 1:
# ifconfig em2
em2: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        ether 18:66:da:e6:89:09  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
        device interrupt 67 

# ip l add link em2 name asdf type macvlan; ip l set asdf name fdsa

Terminal 2:
# tail -f /var/log/libvirt/libvirtd.log
...
2019-11-26 05:55:43.411+0000: 13324: error : virFileReadAll:1460 : Failed to open file '/sys/class/net/asdf/operstate': No such file or directory
2019-11-26 05:55:43.411+0000: 13324: error : virNetDevGetLinkInfo:2552 : unable to read: /sys/class/net/asdf/operstate: No such file or directory

Comment 12 jiyan 2019-11-26 06:33:54 UTC
Same steps can hit this problem in RHEL-8.1 slow train also.

Version:
libvirt-4.5.0-35.module+el8.1.0+4227+b2722cb3.x86_64
qemu-kvm-2.12.0-88.module+el8.1.0+4233+bc44be3f.x86_64
kernel-4.18.0-147.0.3.el8_1.x86_64

Comment 13 Michal Privoznik 2020-04-20 13:33:06 UTC
I've merged patches upstream:

72d99b094b Avoid unnecessary error messages handling udev events
abbd3a3184 node_device_udev: handle move events

v6.2.0-189-g72d99b094b

Comment 16 jiyan 2020-05-13 07:12:03 UTC
Version:
libvirt-6.0.0-14.module+el8.3.0+6124+819ee737.x86_64
qemu-kvm-4.2.0-19.module+el8.3.0+6478+69f490bb.x86_64
kernel-4.18.0-196.el8.x86_64

Steps:
1: In terminal 1, operate the network
# ifconfig eno2
eno2: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        ether d4:c9:ef:ce:7e:1b  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
        device interrupt 89  

# ip l add link eno2 name asdf type macvlan; ip l set asdf name fdsa

2: In terminal 2, check the log info
# tail -f /var/log/libvirt/libvirtd.log > before_fix.log
^C

# cat before_fix.log 
2020-05-13 06:31:43.911+0000: 16815: info : virObjectUnref:350 : OBJECT_DISPOSE: obj=0x7f51300bc710
2020-05-13 06:31:43.911+0000: 16815: debug : virFileClose:110 : Closed fd 31
2020-05-13 06:31:43.911+0000: 16815: debug : virFileClose:110 : Closed fd 31
2020-05-13 06:31:43.911+0000: 16815: info : virObjectNew:251 : OBJECT_NEW: obj=0x7f5130176330 classname=virNodeDeviceObj
2020-05-13 06:31:43.911+0000: 16815: info : virObjectRef:386 : OBJECT_REF: obj=0x7f5130176330
2020-05-13 06:31:43.911+0000: 16815: info : virObjectNew:251 : OBJECT_NEW: obj=0x7f51300b9f90 classname=virNodeDeviceEventLifecycle
2020-05-13 06:31:43.911+0000: 16815: info : virObjectUnref:348 : OBJECT_UNREF: obj=0x7f5130176330
2020-05-13 06:31:43.911+0000: 16815: info : virObjectUnref:348 : OBJECT_UNREF: obj=0x7f51300b9f90
2020-05-13 06:31:43.911+0000: 16815: info : virObjectUnref:350 : OBJECT_DISPOSE: obj=0x7f51300b9f90
2020-05-13 06:31:43.915+0000: 16815: debug : virThreadJobClear:122 : Thread 16815 finished job nodeStateInitializeEnumerate with ret=0
2020-05-13 06:33:01.857+0000: 16747: debug : virNetlinkEventCallback:863 : dispatching to max 0 clients, called from event watch 7
2020-05-13 06:33:01.857+0000: 16747: debug : virNetlinkEventCallback:876 : event not handled.
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:863 : dispatching to max 0 clients, called from event watch 7
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:876 : event not handled.
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:863 : dispatching to max 0 clients, called from event watch 7
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:876 : event not handled.
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:863 : dispatching to max 0 clients, called from event watch 7
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:876 : event not handled.
2020-05-13 06:33:01.865+0000: 16747: debug : virNetlinkEventCallback:863 : dispatching to max 0 clients, called from event watch 7
2020-05-13 06:33:01.865+0000: 16747: debug : virNetlinkEventCallback:876 : event not handled.
2020-05-13 06:33:01.869+0000: 16814: error : virFileReadAll:1426 : Failed to open file '/sys/class/net/asdf/operstate': No such file or directory
2020-05-13 06:33:01.869+0000: 16814: error : virNetDevGetLinkInfo:2444 : unable to read: /sys/class/net/asdf/operstate: No such file or directory

3. Upgrade libvirt 
# yum upgrade libvirt* -y

# systemctl restart libvirtd

# rpm -qa libvirt
libvirt-6.3.0-1.module+el8.3.0+6478+69f490bb.x86_64

4. Repeat step-1 and step-2
In terminal 1
# ifconfig eno2
eno2: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        ether d4:c9:ef:ce:7e:1b  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
        device interrupt 121  

# ip l add link eno2 name asdf type macvlan; ip l set asdf name fdsa

In terminal 2
# tail -f /var/log/libvirt/libvirtd.log > after_fix.log
^C

# cat after_fix.log 
2020-05-13 06:55:30.492+0000: 1751: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x556e30b5e500
2020-05-13 06:55:30.492+0000: 1751: info : virObjectUnref:349 : OBJECT_DISPOSE: obj=0x556e30b5e500
2020-05-13 06:55:30.492+0000: 1751: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x556e30b5e470
2020-05-13 06:55:30.492+0000: 1751: info : virObjectUnref:349 : OBJECT_DISPOSE: obj=0x556e30b5e470
2020-05-13 06:55:30.493+0000: 1751: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x556e30b3cb80
2020-05-13 06:55:30.493+0000: 1751: info : virObjectUnref:349 : OBJECT_DISPOSE: obj=0x556e30b3cb80
2020-05-13 06:55:30.493+0000: 1751: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x556e30b66f30
2020-05-13 06:55:30.493+0000: 1751: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x556e30b59f00
2020-05-13 06:55:30.493+0000: 1751: info : virObjectUnref:349 : OBJECT_DISPOSE: obj=0x556e30b59f00
2020-05-13 06:55:30.493+0000: 1751: debug : virFileClose:134 : Closed fd 7


All the test results are as expected, move this bug to be verified.

Comment 17 jiyan 2020-05-13 07:32:43 UTC
Version:
libvirt-6.0.0-14.module+el8.3.0+6124+819ee737.x86_64
qemu-kvm-4.2.0-19.module+el8.3.0+6478+69f490bb.x86_64
kernel-4.18.0-196.el8.x86_64

Steps:
1: In terminal 1, operate the network
# ifconfig eno2
eno2: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        ether d4:c9:ef:ce:7e:1b  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
        device interrupt 89  

# ip l add link eno2 name asdf type macvlan; ip l set asdf name fdsa

2: In terminal 2, check the log info
# tail -f /var/log/libvirt/libvirtd.log > before_fix.log
^C

# cat before_fix.log 
2020-05-13 06:31:43.911+0000: 16815: info : virObjectUnref:350 : OBJECT_DISPOSE: obj=0x7f51300bc710
2020-05-13 06:31:43.911+0000: 16815: debug : virFileClose:110 : Closed fd 31
2020-05-13 06:31:43.911+0000: 16815: debug : virFileClose:110 : Closed fd 31
2020-05-13 06:31:43.911+0000: 16815: info : virObjectNew:251 : OBJECT_NEW: obj=0x7f5130176330 classname=virNodeDeviceObj
2020-05-13 06:31:43.911+0000: 16815: info : virObjectRef:386 : OBJECT_REF: obj=0x7f5130176330
2020-05-13 06:31:43.911+0000: 16815: info : virObjectNew:251 : OBJECT_NEW: obj=0x7f51300b9f90 classname=virNodeDeviceEventLifecycle
2020-05-13 06:31:43.911+0000: 16815: info : virObjectUnref:348 : OBJECT_UNREF: obj=0x7f5130176330
2020-05-13 06:31:43.911+0000: 16815: info : virObjectUnref:348 : OBJECT_UNREF: obj=0x7f51300b9f90
2020-05-13 06:31:43.911+0000: 16815: info : virObjectUnref:350 : OBJECT_DISPOSE: obj=0x7f51300b9f90
2020-05-13 06:31:43.915+0000: 16815: debug : virThreadJobClear:122 : Thread 16815 finished job nodeStateInitializeEnumerate with ret=0
2020-05-13 06:33:01.857+0000: 16747: debug : virNetlinkEventCallback:863 : dispatching to max 0 clients, called from event watch 7
2020-05-13 06:33:01.857+0000: 16747: debug : virNetlinkEventCallback:876 : event not handled.
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:863 : dispatching to max 0 clients, called from event watch 7
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:876 : event not handled.
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:863 : dispatching to max 0 clients, called from event watch 7
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:876 : event not handled.
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:863 : dispatching to max 0 clients, called from event watch 7
2020-05-13 06:33:01.858+0000: 16747: debug : virNetlinkEventCallback:876 : event not handled.
2020-05-13 06:33:01.865+0000: 16747: debug : virNetlinkEventCallback:863 : dispatching to max 0 clients, called from event watch 7
2020-05-13 06:33:01.865+0000: 16747: debug : virNetlinkEventCallback:876 : event not handled.
2020-05-13 06:33:01.869+0000: 16814: error : virFileReadAll:1426 : Failed to open file '/sys/class/net/asdf/operstate': No such file or directory
2020-05-13 06:33:01.869+0000: 16814: error : virNetDevGetLinkInfo:2444 : unable to read: /sys/class/net/asdf/operstate: No such file or directory

3. Upgrade libvirt 
# yum upgrade libvirt* -y

# systemctl restart libvirtd

# rpm -qa libvirt
libvirt-6.3.0-1.module+el8.3.0+6478+69f490bb.x86_64

4. Repeat step-1 and step-2
In terminal 1
# ifconfig eno2
eno2: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        ether d4:c9:ef:ce:7e:1b  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
        device interrupt 121  

# ip l add link eno2 name asdf type macvlan; ip l set asdf name fdsa

In terminal 2
# tail -f /var/log/libvirt/libvirtd.log > after_fix.log
^C

# cat after_fix.log 
2020-05-13 06:55:30.492+0000: 1751: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x556e30b5e500
2020-05-13 06:55:30.492+0000: 1751: info : virObjectUnref:349 : OBJECT_DISPOSE: obj=0x556e30b5e500
2020-05-13 06:55:30.492+0000: 1751: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x556e30b5e470
2020-05-13 06:55:30.492+0000: 1751: info : virObjectUnref:349 : OBJECT_DISPOSE: obj=0x556e30b5e470
2020-05-13 06:55:30.493+0000: 1751: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x556e30b3cb80
2020-05-13 06:55:30.493+0000: 1751: info : virObjectUnref:349 : OBJECT_DISPOSE: obj=0x556e30b3cb80
2020-05-13 06:55:30.493+0000: 1751: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x556e30b66f30
2020-05-13 06:55:30.493+0000: 1751: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x556e30b59f00
2020-05-13 06:55:30.493+0000: 1751: info : virObjectUnref:349 : OBJECT_DISPOSE: obj=0x556e30b59f00
2020-05-13 06:55:30.493+0000: 1751: debug : virFileClose:134 : Closed fd 7


All the test results are as expected, move this bug to be verified.

Comment 23 errata-xmlrpc 2020-11-17 17:44:45 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 (virt:8.3 bug fix and enhancement update), 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://access.redhat.com/errata/RHBA-2020:5137

Comment 24 Dan Zheng 2021-02-10 03:37:50 UTC
Covered in automated test:

$ sudo avocado run --vt-type libvirt iface_rename
JOB ID : 7170774117de85673d5d0c30da3571e98e483fff
JOB LOG : /root/avocado/job-results/job-2020-12-23T01.09-7170774/job.log
(1/1) type_specific.io-github-autotest-libvirt.virtual_network.iface_rename.check_log: PASS (11.36 s)
RESULTS : PASS 1 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0 | CANCEL 0
JOB TIME : 13.36 s


Note You need to log in before you can comment on or make changes to this bug.