Bug 1791255

This is obviously not a great title for an RFE. And, if it were 100% reproducible in a production release, we'd have seen it before (with tickets)

Scheduler weights for hyperthreaded CPUs were changed, and this may be affecting an environment as limited as CI. Andrej, any ideas from the log?

It shouldn’t be an error in engine.log, it’s just a “normal” scheduling condition, and should be reported the same way as when this happen with regular VMs when they can’t move

(In reply to Michal Skrivanek from comment #2)
> It shouldn’t be an error in engine.log, it’s just a “normal” scheduling
> condition, and should be reported the same way as when this happen with
> regular VMs when they can’t move

Fine. Ss there a way to get this reporting via the SDK, so that we can add it to CI? I am not claiming that the log is the only way, but there should be some automation-friendly way to get this info, IMO. Feel free to move the bug to API/SDK if more suitable.

This error is not because the HE VM failed to schedule. 
The command that puts the host to maintenance 'MaintenanceNumberOfVdssCommand' does a basic check if there is another host in the cluster to run HE VM.

For each host it checks:
1. If it is in Up status
2. If it is not being put to maintenance
3. If it is a HE host and the ha-agent and ha-broker are active
4. If it is not in local maintenance mode
5. If its HE score is > 0

This error is shown if there is no host that satisfies all conditions.


I will look to the logs to see why this happens.

I think I found the issue. The core problem is that ha-agent does not recognize that the HE VM failed to start locally because it is already running elsewhere and the sanlock could not be not acquired.

When a VM fails to start, the he-agent compares the error message with a hard-coded strings to detect if the failure is because of sanlock. In a new version of qemu, the error message has changed.

The error from the vdsm.log is:


2020-01-15 02:03:05,652-0500 ERROR (vm/7fe45704) [virt.vm] (vmId='7fe45704-ef24-40e9-bbf4-07ee97e27fd8') The vm start process failed (vm:933)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 867, in _startUnderlyingVm
    self._run()
  File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2891, in _run
    dom.createWithFlags(flags)
  File "/usr/lib/python2.7/site-packages/vdsm/common/libvirtconnection.py", line 131, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/common/function.py", line 94, in wrapper
    return func(inst, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1110, in createWithFlags
    if ret == -1: raise libvirtError ('virDomainCreateWithFlags() failed', dom=self)
libvirtError: internal error: qemu unexpectedly closed the monitor: 2020-01-15T07:03:01.973092Z qemu-kvm: warning: All CPU(s) up to maxcpus should be described in NUMA config, ability to start up with partial NU
MA mappings is obsoleted and will be removed in future
2020-01-15T07:03:02.108044Z qemu-kvm: -device virtio-blk-pci,iothread=iothread1,scsi=off,bus=pci.0,addr=0x7,drive=drive-ua-f1a839b6-74ca-41f2-bd58-463f3e9a1c75,id=ua-f1a839b6-74ca-41f2-bd58-463f3e9a1c75,bootinde
x=1,write-cache=on: Failed to get shared "write" lock
Is another process using the image [/var/run/vdsm/storage/4e23d2a7-de42-48f6-b68e-ca2409411889/f1a839b6-74ca-41f2-bd58-463f3e9a1c75/4ba0300c-df8d-43e9-857f-f0e2bc62572d]?



The ha-agent expects the error message to end with on of:
- 'Failed to acquire lock: error -243',
- 'Failed to acquire lock: Lease is held by another host',
- 'Is another process using the image?'


The ha-agent sets the state to 'EngineUnexpectedlyDown' and sets the score to 0. Which is the reason why the HE VM cannot be migrated back to Host 0.

(In reply to Andrej Krejcir from comment #5)
> I think I found the issue. The core problem is that ha-agent does not
> recognize that the HE VM failed to start locally because it is already
> running elsewhere and the sanlock could not be not acquired.
> 
> When a VM fails to start, the he-agent compares the error message with a
> hard-coded strings to detect if the failure is because of sanlock. In a new
> version of qemu, the error message has changed.

Very nice catch, but can you please open another bug for it? I still think that
a better answer to 'Why?', as I asked originally, is useful. In current case,
can be something like 'host-0 has score 0, ...'. Thanks!

Ok, I have opened another bug: Bug 1794089.

alma03 ~]# top
top - 13:21:43 up 19 days, 23:55,  2 users,  load average: 101.79, 52.84, 21.25
Tasks: 282 total, 105 running, 177 sleeping,   0 stopped,   0 zombie
%Cpu(s): 51.0 us, 48.6 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.3 hi,  0.1 si,  0.0 st
MiB Mem :  32017.3 total,  14986.7 free,  13989.6 used,   3041.0 buff/cache
MiB Swap:   2048.0 total,   2048.0 free,      0.0 used.  17501.1 avail Mem 

Set to maintenance alma04 which was running HE-VM. Engine got migrated to loaded alma03.
No error observed.


Migration completed (VM: HostedEngine, Source: alma04.qa.lab.tlv.redhat.com, Destination: alma03.qa.lab.tlv.redhat.com, Duration: 1 minute 55 seconds, Total: 2 minutes 6 seconds, Actual downtime: (N/A))
5/11/201:21:36 PM

Storage Pool Manager runs on Host alma03.qa.lab.tlv.redhat.com (Address: alma03.qa.lab.tlv.redhat.com), Data Center Default.
5/11/201:19:37 PM

Invalid status on Data Center Default. Setting status to Non Responsive.
5/11/201:19:36 PM

Host alma04.qa.lab.tlv.redhat.com was switched to Maintenance mode by admin@internal-authz.
5/11/201:19:31 PM

Migration initiated by system (VM: HostedEngine, Source: alma04.qa.lab.tlv.redhat.com, Destination: alma03.qa.lab.tlv.redhat.com, Reason: ).
5/11/201:19:31 PM

Used CPU of host alma03.qa.lab.tlv.redhat.com [99%] exceeded defined threshold [95%].
5/11/201:18:55 PM


Tested on:
rhvm-4.4.0-0.33.master.el8ev.noarch
ovirt-hosted-engine-ha-2.4.2-1.el8ev.noarch
ovirt-hosted-engine-setup-2.4.4-1.el8ev.noarch
Linux 4.18.0-193.el8.x86_64 #1 SMP Fri Mar 27 14:35:58 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
Red Hat Enterprise Linux release 8.2 (Ootpa)

alma04 ~]# hosted-engine --vm-status


--== Host alma04.qa.lab.tlv.redhat.com (id: 1) status ==--

Host ID                            : 1
Host timestamp                     : 1733070
Score                              : 0
Engine status                      : {"vm": "down", "health": "bad", "detail": "unknown", "reason": "vm not running on this host"}
Hostname                           : alma04.qa.lab.tlv.redhat.com
Local maintenance                  : True
stopped                            : False
crc32                              : 127da8bc
conf_on_shared_storage             : True
local_conf_timestamp               : 1733070
Status up-to-date                  : True
Extra metadata (valid at timestamp):
        metadata_parse_version=1
        metadata_feature_version=1
        timestamp=1733070 (Mon May 11 13:26:16 2020)
        host-id=1
        score=0
        vm_conf_refresh_time=1733070 (Mon May 11 13:26:16 2020)
        conf_on_shared_storage=True
        maintenance=True
        state=LocalMaintenance
        stopped=False


--== Host alma03.qa.lab.tlv.redhat.com (id: 2) status ==--

Host ID                            : 2
Host timestamp                     : 1727996
Score                              : 3249
Engine status                      : {"vm": "up", "health": "good", "detail": "Up"}
Hostname                           : alma03.qa.lab.tlv.redhat.com
Local maintenance                  : False
stopped                            : False
crc32                              : c4ffb90a
conf_on_shared_storage             : True
local_conf_timestamp               : 1727996
Status up-to-date                  : True
Extra metadata (valid at timestamp):
        metadata_parse_version=1
        metadata_feature_version=1
        timestamp=1727996 (Mon May 11 13:26:13 2020)
        host-id=2
        score=3249
        vm_conf_refresh_time=1727996 (Mon May 11 13:26:14 2020)
        conf_on_shared_storage=True
        maintenance=False
        state=EngineUp
        stopped=False


Score on loaded alma03 went down from 3400 points to 2400 points, while being decreased by 22 penalty points, as long as host's CPU remained loaded.

This bugzilla is included in oVirt 4.4.0 release, published on May 20th 2020.

Since the problem described in this bug report should be
resolved in oVirt 4.4.0 release, it has been closed with a resolution of CURRENT RELEASE.

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