1973094 – start vm with cachetune or memorytune failed with "error: An error occurred, but the cause is unknown"

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1973094 - start vm with cachetune or memorytune failed with "error: An error occurred, but the cause is unknown"

Summary: start vm with cachetune or memorytune failed with "error: An error occurred, ...

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	None
Product:	Red Hat Enterprise Linux 9
Classification:	Red Hat
Component:	libvirt
Sub Component:
Version:	9.0
Hardware:	x86_64
OS:	Linux
Priority:	unspecified
Severity:	high
Target Milestone:	beta
Target Release:	---
Assignee:	Pavel Hrdina
QA Contact:	Jing Qi
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2021-06-17 09:13 UTC by Jing Qi
Modified:	2021-12-07 22:01 UTC (History)
CC List:	5 users (show)
Fixed In Version:	libvirt-7.5.0-1.el9
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2021-12-07 21:57:54 UTC
Type:	Bug
Target Upstream Version:	7.5.0
Embargoed:
Dependent Products:
Flags:	pm-rhel: mirror+

Attachments	(Terms of Use)

Description Jing Qi 2021-06-17 09:13:26 UTC

Description of problem:
start vm with cachetune or memorytune failed with "error: An error occurred, but the cause is unknown"

Version-Release number of selected component (if applicable):
libvirt-7.4.0-1.el9.x86_64
qemu-kvm-6.0.0-5.el9.x86_64
How reproducible:

always
Steps to Reproduce:
1.cat /proc/cmdline
BOOT_IMAGE=/vmlinuz-5.13.0-0.rc4.33.el9.x86_64 root=/dev/mapper/rhel_dell--per740xd--09-root ro resume=/dev/mapper/rhel_dell--per740xd--09-swap rd.lvm.lv=rhel_dell-per740xd-09/root rd.lvm.lv=rhel_dell-per740xd-09/swap console=ttyS0,115200n81 rdt=cmt,mbmtotal,mbmlocal,l3cat,l3cdp,mba

2. mount |grep resctrl
resctrl on /sys/fs/resctrl type resctrl (rw,relatime)

3. Tried to start vm with cachetune or memorytune -
 <cputune>
    <cachetune vcpus='0-1'>
      <cache id='0' level='3' type='both' size='3' unit='MiB'/>
      <cache id='1' level='3' type='both' size='3' unit='MiB'/>
      <monitor level='3' vcpus='1'/>
      <monitor level='3' vcpus='0'/>
    </cachetune>
    <memorytune vcpus='0-1'>
      <node id='0' bandwidth='60'/>
    </memorytune>
  </cputune>

# virsh start avocado-vt-vm1
error: Failed to start domain 'avocado-vt-vm1'
error: An error occurred, but the cause is unknown


Actual results:
vm start failed

Expected results:
vm start successfully

Comment 1 Pavel Hrdina 2021-06-17 11:18:54 UTC

Hi, can you please provide libvirt debug logs? For details how to enable libvirt debug logs see <https://libvirt.org/kbase/debuglogs.html>.

Comment 2 Jing Qi 2021-06-18 03:32:10 UTC

Seems there is an issue with the uploaded server.  I copy part of the log here -
 
2021-06-18 03:24:32.493+0000: 507649: debug : qemuDomainSetupLoader:567 : Setting up loader
2021-06-18 03:24:32.493+0000: 507649: debug : qemuDomainSetupLoader:588 : Setup loader
2021-06-18 03:24:32.497+0000: 507649: debug : qemuProcessLaunch:7309 : Setting up domain cgroup (if required)
2021-06-18 03:24:32.525+0000: 507649: debug : qemuSetupImagePathCgroup:73 : Allow path /var/lib/avocado/data/avocado-vt/images/jeos-27-x86_64.qcow2, perms: rw
2021-06-18 03:24:32.526+0000: 507649: debug : qemuSetupRNGCgroup:670 : Setting Cgroup ACL for RNG device
2021-06-18 03:24:32.526+0000: 507649: debug : qemuProcessLaunch:7313 : Setting up domain perf (if required)
2021-06-18 03:24:32.526+0000: 507649: debug : qemuProcessLaunch:7322 : Setting emulator tuning/settings
2021-06-18 03:24:32.527+0000: 507649: debug : qemuProcessLaunch:7326 : Setting cgroup for external devices (if required)
2021-06-18 03:24:32.527+0000: 507649: debug : qemuProcessLaunch:7330 : Setting up resctrl
2021-06-18 03:24:32.551+0000: 507649: debug : virQEMUCapsCacheLookup:5659 : Returning caps 0x7f7ca402c130 for /usr/libexec/qemu-kvm
2021-06-18 03:24:32.551+0000: 507649: debug : virQEMUCapsCacheLookup:5659 : Returning caps 0x7f7ca402c130 for /usr/libexec/qemu-kvm
2021-06-18 03:24:32.551+0000: 507649: debug : virQEMUDriverCreateCapabilities:1364 : Initialized caps for security driver "selinux" with DOI "0"
2021-06-18 03:24:32.551+0000: 507649: debug : virQEMUDriverCreateCapabilities:1364 : Initialized caps for security driver "dac" with DOI "0"
2021-06-18 03:24:32.563+0000: 507649: debug : qemuDomainLogContextFinalize:452 : ctxt=0x7f7ca400e600
2021-06-18 03:24:32.563+0000: 507649: debug : qemuProcessStop:7819 : Shutting down vm=0x7f7ca40e0810 name=avocado-vt-vm1 id=1 pid=507741, reason=failed, asyncJob=start, flags=0x2
2021-06-18 03:24:32.563+0000: 507649: debug : qemuDomainObjBeginJobInternal:837 : Starting job: job=async nested agentJob=none asyncJob=none (vm=0x7f7ca40e0810 name=avocado-vt-vm1, current job=none agentJob=none async=start)
2021-06-18 03:24:32.563+0000: 507649: debug : qemuDomainObjBeginJobInternal:889 : Started job: async nested (async=start vm=0x7f7ca40e0810 name=avocado-vt-vm1)
2021-06-18 03:24:32.563+0000: 507649: debug : qemuDomainLogAppendMessage:6803 : Append log message (vm='avocado-vt-vm1' message='2021-06-18 03:24:32.563+0000: shutting down, reason=failed
) stdioLogD=0
2021-06-18 03:24:32.563+0000: 507649: debug : qemuProcessKill:7737 : vm=0x7f7ca40e0810 name=avocado-vt-vm1 pid=507741 flags=0x5
2021-06-18 03:24:32.763+0000: 507649: debug : qemuDomainCleanupRun:7382 : driver=0x7f7ca406ca10, vm=avocado-vt-vm1
2021-06-18 03:24:32.764+0000: 507649: debug : qemuProcessAutoDestroyRemove:8216 : vm=avocado-vt-vm1
2021-06-18 03:24:32.764+0000: 507649: debug : virConnectOpen:1203 : name=network:///system
2021-06-18 03:24:32.764+0000: 507649: debug : virConnectOpenInternal:959 : Split "network:///system" to URI components:
  scheme network
  server <null>
  user <null>
  port 0
  path /system

Any more information needed, please let me know.

Comment 3 Pavel Hrdina 2021-06-18 11:53:24 UTC

(In reply to Jing Qi from comment #2)
> Seems there is an issue with the uploaded server.  I copy part of the log
> here -
>  
> 2021-06-18 03:24:32.493+0000: 507649: debug : qemuDomainSetupLoader:567 :
> Setting up loader
> 2021-06-18 03:24:32.493+0000: 507649: debug : qemuDomainSetupLoader:588 :
> Setup loader
> 2021-06-18 03:24:32.497+0000: 507649: debug : qemuProcessLaunch:7309 :
> Setting up domain cgroup (if required)
> 2021-06-18 03:24:32.525+0000: 507649: debug : qemuSetupImagePathCgroup:73 :
> Allow path /var/lib/avocado/data/avocado-vt/images/jeos-27-x86_64.qcow2,
> perms: rw
> 2021-06-18 03:24:32.526+0000: 507649: debug : qemuSetupRNGCgroup:670 :
> Setting Cgroup ACL for RNG device
> 2021-06-18 03:24:32.526+0000: 507649: debug : qemuProcessLaunch:7313 :
> Setting up domain perf (if required)
> 2021-06-18 03:24:32.526+0000: 507649: debug : qemuProcessLaunch:7322 :
> Setting emulator tuning/settings
> 2021-06-18 03:24:32.527+0000: 507649: debug : qemuProcessLaunch:7326 :
> Setting cgroup for external devices (if required)
> 2021-06-18 03:24:32.527+0000: 507649: debug : qemuProcessLaunch:7330 :
> Setting up resctrl
> 2021-06-18 03:24:32.551+0000: 507649: debug : virQEMUCapsCacheLookup:5659 :
> Returning caps 0x7f7ca402c130 for /usr/libexec/qemu-kvm
> 2021-06-18 03:24:32.551+0000: 507649: debug : virQEMUCapsCacheLookup:5659 :
> Returning caps 0x7f7ca402c130 for /usr/libexec/qemu-kvm
> 2021-06-18 03:24:32.551+0000: 507649: debug :
> virQEMUDriverCreateCapabilities:1364 : Initialized caps for security driver
> "selinux" with DOI "0"
> 2021-06-18 03:24:32.551+0000: 507649: debug :
> virQEMUDriverCreateCapabilities:1364 : Initialized caps for security driver
> "dac" with DOI "0"
> 2021-06-18 03:24:32.563+0000: 507649: debug :
> qemuDomainLogContextFinalize:452 : ctxt=0x7f7ca400e600
> 2021-06-18 03:24:32.563+0000: 507649: debug : qemuProcessStop:7819 :
> Shutting down vm=0x7f7ca40e0810 name=avocado-vt-vm1 id=1 pid=507741,
> reason=failed, asyncJob=start, flags=0x2
> 2021-06-18 03:24:32.563+0000: 507649: debug :
> qemuDomainObjBeginJobInternal:837 : Starting job: job=async nested
> agentJob=none asyncJob=none (vm=0x7f7ca40e0810 name=avocado-vt-vm1, current
> job=none agentJob=none async=start)
> 2021-06-18 03:24:32.563+0000: 507649: debug :
> qemuDomainObjBeginJobInternal:889 : Started job: async nested (async=start
> vm=0x7f7ca40e0810 name=avocado-vt-vm1)
> 2021-06-18 03:24:32.563+0000: 507649: debug :
> qemuDomainLogAppendMessage:6803 : Append log message (vm='avocado-vt-vm1'
> message='2021-06-18 03:24:32.563+0000: shutting down, reason=failed
> ) stdioLogD=0
> 2021-06-18 03:24:32.563+0000: 507649: debug : qemuProcessKill:7737 :
> vm=0x7f7ca40e0810 name=avocado-vt-vm1 pid=507741 flags=0x5
> 2021-06-18 03:24:32.763+0000: 507649: debug : qemuDomainCleanupRun:7382 :
> driver=0x7f7ca406ca10, vm=avocado-vt-vm1
> 2021-06-18 03:24:32.764+0000: 507649: debug :
> qemuProcessAutoDestroyRemove:8216 : vm=avocado-vt-vm1
> 2021-06-18 03:24:32.764+0000: 507649: debug : virConnectOpen:1203 :
> name=network:///system
> 2021-06-18 03:24:32.764+0000: 507649: debug : virConnectOpenInternal:959 :
> Split "network:///system" to URI components:
>   scheme network
>   server <null>
>   user <null>
>   port 0
>   path /system
> 
> Any more information needed, please let me know.

Thanks for the quick reply but this part is not enough. Firstly it is only debug logs and no error in this part so I don't know when the error was triggered. Usually to fully understand what is going on the we need full log.

Usually if it's possible you enable debug logs, do the operation that is failing or behaving incorrectly, take the whole log and share it with us. In addition can you please share the content of `/var/log/libvirt/qemu/avocado-vt-vm1`? Good guide on how to report quality bugs is here <https://libvirt.org/bugs.html#quality>.

Comment 4 Jing Qi 2021-06-21 01:54:11 UTC

Pavel,
I am sending the whole libvirtd log & domain log to you by email. Please have look at them. If you still can't find the information, please let me know. Thanks.

Jing Qi

Comment 5 Pavel Hrdina 2021-06-21 09:21:23 UTC

(In reply to Jing Qi from comment #4)
> Pavel,
> I am sending the whole libvirtd log & domain log to you by email. Please
> have look at them. If you still can't find the information, please let me
> know. Thanks.
> 
> Jing Qi

Thanks for the debug info and mainly access to the machine where you discovered this issue. Using gdb and stepping through the code I managed to find exact place where this happens.

Broken by commit <7d2fd6ef0163a939adb7ce0f0fad3b7654c340de>.

I'll fix it in upstream and libvirt rebase will get the fix into RHEL-9 as well.

Comment 6 Pavel Hrdina 2021-06-21 11:19:40 UTC

Upstream commit:

36d6da4ebf virresctrl: fix starting VMs with cputune.memorytune specified

Comment 7 Jing Qi 2021-07-15 08:06:44 UTC

Verified with libvirt-7.5.0-1.el9.x86_64 & qemu-kvm-6.0.0-8.el9.x86_64

1. Config vm with cachetune or memorytune -
 <cputune>
    <cachetune vcpus='0-1'>
      <cache id='0' level='3' type='both' size='3' unit='MiB'/>
      <cache id='1' level='3' type='both' size='3' unit='MiB'/>
      <monitor level='3' vcpus='1'/>
      <monitor level='3' vcpus='0'/>
    </cachetune>
    <memorytune vcpus='0-1'>
      <node id='0' bandwidth='60'/>
    </memorytune>
  </cputune>

2. # virsh start avocado-vt-vm1
Domain 'avocado-vt-vm1' started

Comment 11 Jing Qi 2021-07-16 02:15:58 UTC

Set it to verified from comment 7 above.

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