Bug 1142141

Host 1de7fc5e-2f0f-4805-bcd7-5324fab52ffc (Affinity_VM_2) belongs to both positive and negative affinity list while scheduling VM 0c2d1394-6b74-4f94-9097-d570ca5b42c2 ({4})

CanDoAction of action RunVm failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,SCHEDULING_ALL_HOSTS_FILTERED_OUT,VAR__FILTERTYPE__INTERNAL,$hostName 10.35.160.57,$filterName VmAffinityGroups,$affinityRules ,VAR__DETAIL__AFFINITY_FAILED_NEGATIVE,SCHEDULING_HOST_FILTERED_REASON_WITH_DETAIL


Can you describe the affinity configuration in your setup? This talks about negative affinity..


Also:

2014-09-16 10:18:23,989 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-59) [228b146f] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: VM Affinity_VM_1 is down with error. Exit message: Lost connection with qemu process.
2014-09-16 10:18:23,989 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-59) [228b146f] Running on vds during rerun failed vm: null
2014-09-16 10:18:23,992 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-59) [228b146f] VM Affinity_VM_1 (0f9a0564-c002-4b7d-81d0-8cd8da477d83) is running in db and not running in VDS 10.35.160.49
2014-09-16 10:18:23,992 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-59) [228b146f] add VM Affinity_VM_1 to HA rerun treatment
2014-09-16 10:18:23,992 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-59) [228b146f] START, FullListVdsCommand(HostName = 10.35.160.49, HostId = 5c2ef4f0-52bb-4952-8ada-f7485d502cc8, vds=Host[10.35.160.49,5c2ef4f0-52bb-4952-8ada-f7485d502cc8], vmIds=[0f9a0564-c002-4b7d-81d0-8cd8da477d83]), log id: 7235ee05
2014-09-16 10:18:24,025 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-59) [228b146f] FINISH, FullListVdsCommand, return: [], log id: 7235ee05
2014-09-16 10:18:24,081 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-59) [228b146f] Rerun vm 0f9a0564-c002-4b7d-81d0-8cd8da477d83. Called from vds 10.35.160.49
2014-09-16 10:18:24,099 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-46) [228b146f] Correlation ID: vms_syncAction_9acbb754-f0db-47cc, Job ID: 3e6cb7b4-10c8-480a-81ae-0b0819c25572, Call Stack: null, Custom Event ID: -1, Message: Failed to run VM Affinity_VM_1 on Host 10.35.160.49.

Here the VM 1 actually tried to restart and failed.


I also found the place where a VM could not be started because both hosts were filtered out:

2014-09-16 10:18:24,144 WARN  [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-6-thread-46) [228b146f] CanDoAction of action RunVm failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,SCHEDULING_ALL_HOSTS_FILTERED_OUT,VAR__FILTERTYPE__INTERNAL,$hostName 10.35.160.59,$filterName VmAffinityGroups,$affinityRules ,VAR__DETAIL__AFFINITY_FAILED_POSITIVE,SCHEDULING_HOST_FILTERED_REASON_WITH_DETAIL,VAR__FILTERTYPE__INTERNAL,$hostName 10.35.160.57,$filterName VmAffinityGroups,$affinityRules ,VAR__DETAIL__AFFINITY_FAILED_POSITIVE,SCHEDULING_HOST_FILTERED_REASON_WITH_DETAIL

But I have no idea why at the moment. Was there anything else in the affinity group? Or some other configuration?

Also - how many hosts did you have there? And which hosts were part of the affinity group?

2014-09-16 10:18:24,099 WARN Message: Failed to run VM Affinity_VM_1 on Host 10.35.160.49.
2014-09-16 10:18:24,143 INFO Candidate host 10.35.160.57 was filtered out by VAR__FILTERTYPE__INTERNAL filter VmAffinityGroups
2014-09-16 10:18:24,144 INFO Candidate host 10.35.160.59 was filtered out by VAR__FILTERTYPE__INTERNAL filter VmAffinityGroups

Btw I also see that the engine tried to start the VM three times... and failed.

2014-09-16 10:34:56,797 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-31) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Host 10.35.160.49 will be switched to Error status for 30 minutes because it failed to run a VM.

Ok, I would like to know more about the setup (please include it in future bugs), but I think I found the issue.

This is what happened:

- VM A and VM B die, both were running at Host One
- engine founds out about VM A
- engine schedules restart of VM A
  * scheduler sees host One as available
  * VM B is still considered Up on host One
  * VM A belongs to the affinity group with VM B
  * scheduling correctly returns host One
- engine tries to launch VM A
- the start fails (cleanup is still in progress)
- engine schedules a retry (org/ovirt/engine/core/vdsbroker/VdsUpdateRunTimeInfo.java:583 - RerunFailedCommand)
- retry removes all previously failed hosts from the list of available hosts
- scheduler does not have host One in the list and fails the hard constraint affinity rule

- engine founds out about VM B
- all the steps above are performed, including the start failures
- the retry succeeds because VM A is not running and so VM B is free to choose whatever host is available, because it is the only running vm from the affinity group

In terms of code the issue is here:

org.ovirt.engine.core.bll.RunVmCommandBase#rerun
if (getRunVdssList().size() < Config.<Integer> getValue(ConfigValues.MaxRerunVmOnVdsCount)


- getRunVdssList contains the list of hosts where we tried to start the VM

org.ovirt.engine.core.bll.MigrateVmCommand#executeVmCommand
setSucceeded(initVdss() && perform());

org.ovirt.engine.core.bll.MigrateVmCommand#initVdss
SchedulingManager.getInstance().schedule(getVdsGroup(),
                        getVm(),
                        getVdsBlackList(),
                        getVdsWhiteList(),
                        getDestinationVdsId(),
                        new ArrayList<String>(),
                        new VdsFreeMemoryChecker(this),
                        getCorrelationId());

org.ovirt.engine.core.bll.MigrateVmCommand#getVdsBlackList
List<Guid> blackList = new ArrayList<Guid>(getRunVdssList());

And the first failed run gets to:

org.ovirt.engine.core.bll.MigrateVmCommand#initVdss
getRunVdssList().add(vdsToRunOn);

Which is used to construct the blacklist during the second attempt, filtering out the only host that can satisfy the affinity rule.

It happen in automation test so it many error lines not really connect to bug.
I have two vms in hard positive affinity group(no others vms are exist), also I have 3 hosts.
Failed run happen between:
2014-09-16 10:18:23,93 and 2014-09-16 10:33:29,556 - you can see that when it failed to run vm Affinity_VM_1 it's not try again in this gap of time. So starting vm in comment 3 is, when my other test run vm and it's not really connect to bug(gap 15 minutes(:)
It, seems that description in comment 4 is correct.

Removing from 3.5.z.  Will be fixed in 3.6.0.

This should be solved by the new pending resource manager.

Please move it ON_QA and add build id
Thanks

IIRC the errata tool should do that once this bug is added to the errata. And I do not know the build ID, I am not the maintainer.

Verified on rhevm-3.6.0-0.16.master.el6.noarch
Checked 10 times, vms started on the same host