Hi Lucie,
On 5/16/19 6:27 PM, Lucie Leistnerova wrote:
>
> Hi Rik,
>
> On 5/14/19 2:21 PM, Rik Theys wrote:
>>
>> Hi,
>>
>> It seems VM pools are completely broken since our upgrade to 4.3. Is
>> anybody else also experiencing this issue?
>>
> I've tried to reproduce this issue. And I can use pool VMs as
> expected, no problem. I've tested clean install and also upgrade from
> 4.2.8.7.
> Version: ovirt-engine-4.3.3.7-0.1.el7.noarch with
> ovirt-web-ui-1.5.2-1.el7ev.noarch
That is strange. I will try to create a new pool to verify if I also
have the problem with the new pool. Currently we are having this issue
with two different pools. Both pools were created in August or September
of last year. I believe it was on 4.2 but could still have been 4.1.
>>
>> Only a single instance from a pool can be used. Afterwards the pool
>> becomes unusable due to a lock not being released. Once ovirt-engine
>> is restarted, another (single) VM from a pool can be used.
>>
> What users are running the VMs? What are the permissions?
The users are taking VM's from the pools using the user portal. They are
all member of a group that has the UserRole permission on the pools.
> Each VM is running by other user? Were already some VMs running before
> the upgrade?
A user can take at most 1 VM from each pool. So it's possible a user has
two VM's running (but not from the same pool). It doesn't matter which
user is taking a VM from the pool. Once a user has taken a VM from the
pool, no other user can take a VM. If the user that was able to take a
VM powers it down and tries to run a new VM, it will also fail.
During the upgrade of the host, no VM's were running.
> Please provide exact steps.
1. ovirt-engine is restarted.
2. User A takes a VM from the pool and can work.
3. User B can not take a VM from that pool.
4. User A powers off the VM it was using. Once the VM is down, (s)he
tries to take a new VM, which also fails now.
It seems the VM pool is locked when the first user takes a VM and the
lock is never released.
In our case, there are no prestarted VM's. I can try to see if that
makes a difference.
Are there any more steps I can take to debug this issue regarding the locks?
Regards,
Rik
>> I've added my findings to bug 1462236, but I'm no longer sure the
>> issue is the same as the one initially reported.
>>
>> When the first VM of a pool is started:
>>
>> 2019-05-14 13:26:46,058+02 INFO
>> [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] START,
>> IsVmDuringInitiatingVDSCommand(
>> IsVmDuringInitiatingVDSCommandParameters:{vmId='d8a99676-d520-425e-9974-1b1efe6da8a5'}),
>> log id: 2fb4f7f5
>> 2019-05-14 13:26:46,058+02 INFO
>> [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] FINISH,
>> IsVmDuringInitiatingVDSCommand, return: false, log id: 2fb4f7f5
>> 2019-05-14 13:26:46,208+02 INFO [org.ovirt.engine.core.bll.VmPoolHandler]
>> (default task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] Lock Acquired to
>> object
>> 'EngineLock:{exclusiveLocks='[d8a99676-d520-425e-9974-1b1efe6da8a5=VM]',
>> sharedLocks=''}'
>>
>> -> it has acquired a lock (lock1)
>>
>> 2019-05-14 13:26:46,247+02 INFO
>> [org.ovirt.engine.core.bll.AttachUserToVmFromPoolAndRunCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] Lock Acquired to object
>> 'EngineLock:{exclusiveLocks='[a5bed59c-d2fe-4fe4-bff7-52efe089ebd6=USER_VM_POOL]',
>> sharedLocks=''}'
>>
>> -> it has acquired another lock (lock2)
>>
>> 2019-05-14 13:26:46,352+02 INFO
>> [org.ovirt.engine.core.bll.AttachUserToVmFromPoolAndRunCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] Running command:
>> AttachUserToVmFromPoolAndRunCommand internal: false. Entities affected :
>> ID: 4c622213-e5f4-4032-8639-643174b698cc Type: VmPoolAction group
>> VM_POOL_BASIC_OPERATIONS with role type USER
>> 2019-05-14 13:26:46,393+02 INFO
>> [org.ovirt.engine.core.bll.AddPermissionCommand] (default task-6)
>> [e3c5745c-e593-4aed-ba67-b173808140e8] Running command: AddPermissionCommand
>> internal: true. Entities affected : ID:
>> d8a99676-d520-425e-9974-1b1efe6da8a5 Type: VMAction group
>> MANIPULATE_PERMISSIONS with role type USER
>> 2019-05-14 13:26:46,433+02 INFO
>> [org.ovirt.engine.core.bll.AttachUserToVmFromPoolAndRunCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] Succeeded giving user
>> 'a5bed59c-d2fe-4fe4-bff7-52efe089ebd6' permission to Vm
>> 'd8a99676-d520-425e-9974-1b1efe6da8a5'
>> 2019-05-14 13:26:46,608+02 INFO
>> [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] START,
>> IsVmDuringInitiatingVDSCommand(
>> IsVmDuringInitiatingVDSCommandParameters:{vmId='d8a99676-d520-425e-9974-1b1efe6da8a5'}),
>> log id: 67acc561
>> 2019-05-14 13:26:46,608+02 INFO
>> [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] FINISH,
>> IsVmDuringInitiatingVDSCommand, return: false, log id: 67acc561
>> 2019-05-14 13:26:46,719+02 INFO [org.ovirt.engine.core.bll.RunVmCommand]
>> (default task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] Running
>> command:RunVmCommand internal: true. Entities affected : ID:
>> d8a99676-d520-425e-9974-1b1efe6da8a5 Type: VMAction group RUN_VM with role
>> type USER
>> 2019-05-14 13:26:46,791+02 INFO
>> [org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] START,
>> UpdateVmDynamicDataVDSCommand(
>> UpdateVmDynamicDataVDSCommandParameters:{hostId='null',
>> vmId='d8a99676-d520-425e-9974-1b1efe6da8a5',
>> vmDynamic='org.ovirt.engine.core.common.businessentities.VmDynamic@6db8c94d'}),
>> log id: 2c110e4
>> 2019-05-14 13:26:46,795+02 INFO
>> [org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] FINISH,
>> UpdateVmDynamicDataVDSCommand, return: , log id: 2c110e4
>> 2019-05-14 13:26:46,804+02 INFO
>> [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (default task-6)
>> [e3c5745c-e593-4aed-ba67-b173808140e8] START,CreateVDSCommand(
>> CreateVDSCommandParameters:{hostId='eec7ec2b-cae1-4bb9-b933-4dff47a70bdb',
>> vmId='d8a99676-d520-425e-9974-1b1efe6da8a5', vm='VM [stud-c7-1]'}), log id:
>> 71d599f2
>> 2019-05-14 13:26:46,809+02 INFO
>> [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] START,
>> CreateBrokerVDSCommand(HostName = studvirt1,
>> CreateVDSCommandParameters:{hostId='eec7ec2b-cae1-4bb9-b933-4dff47a70bdb',
>> vmId='d8a99676-d520-425e-9974-1b1efe6da8a5', vm='VM [stud-c7-1]'}), log id:
>> 3aa6b5ff
>> 2019-05-14 13:26:46,836+02 INFO
>> [org.ovirt.engine.core.vdsbroker.builder.vminfo.VmInfoBuildUtils] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] Kernel FIPS - Guid:
>> eec7ec2b-cae1-4bb9-b933-4dff47a70bdb fips: false
>> 2019-05-14 13:26:46,903+02 INFO
>> [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] VM <?xml version="1.0"
>> encoding="UTF-8"?><domain type="kvm"
>> xmlns:ovirt-tune="http://ovirt.org/vm/tune/1.0";
>> xmlns:ovirt-vm="http://ovirt.org/vm/1.0";>
>> [domain xml stripped]
>> 2019-05-14 13:26:46,928+02 INFO
>> [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] FINISH,
>> CreateBrokerVDSCommand, return: , log id: 3aa6b5ff
>> 2019-05-14 13:26:46,932+02 INFO
>> [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (default task-6)
>> [e3c5745c-e593-4aed-ba67-b173808140e8] FINISH, CreateVDSCommand, return:
>> WaitForLaunch, log id: 71d599f2
>> 2019-05-14 13:26:46,932+02 INFO [org.ovirt.engine.core.bll.RunVmCommand]
>> (default task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] Lock freed to object
>> 'EngineLock:{exclusiveLocks='[a5bed59c-d2fe-4fe4-bff7-52efe089ebd6=USER_VM_POOL]',
>> sharedLocks=''}'
>>
>> -> it has released lock2
>>
>> 2019-05-14 13:26:47,004+02 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (default task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] EVENT_ID:
>> VDS_INITIATED_RUN_VM(506), Trying to restart VM stud-c7-1 on Host studvirt1
>> 2019-05-14 13:26:47,094+02 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (default task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] EVENT_ID:
>> USER_ATTACH_USER_TO_VM_FROM_POOL(316), Attaching User u0045469 to VM
>> stud-c7-1 in VM Pool stud-c7-? was initiated by
>> u0045...@esat.kuleuven.be-authz <mailto:u0045...@esat.kuleuven.be-authz>.
>> 2019-05-14 13:26:47,098+02 WARN
>> [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (default task-6)
>> [e3c5745c-e593-4aed-ba67-b173808140e8] Trying to release exclusive lock
>> which does not exist, lock key:
>> 'a5bed59c-d2fe-4fe4-bff7-52efe089ebd6USER_VM_POOL'
>>
>> -> it's trying to release the same lock2 as above and failing
>>
>> 2019-05-14 13:26:47,098+02 INFO
>> [org.ovirt.engine.core.bll.AttachUserToVmFromPoolAndRunCommand] (default
>> task-6) [e3c5745c-e593-4aed-ba67-b173808140e8] Lock freed to object
>> 'EngineLock:{exclusiveLocks='[a5bed59c-d2fe-4fe4-bff7-52efe089ebd6=USER_VM_POOL]',
>> sharedLocks=''}'
>>
>> -> now it's indicating that it released/freed the lock (lock2)
>>
>> 2019-05-14 13:26:48,518+02 INFO
>> [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback]
>> (EE-ManagedThreadFactory-engineScheduled-Thread-3)
>> [e3c5745c-e593-4aed-ba67-b173808140e8] Command
>> 'AttachUserToVmFromPoolAndRun' id: '0148c91d-b053-4dc9-960c-f10bf0d3f343'
>> child commands '[0470802d-09fa-4579-b95b-3d9603feff7b,
>> 47dbfc58-3bae-4229-96eb-d1fc08911237]' executions were completed, status
>> 'SUCCEEDED'
>> 2019-05-14 13:26:49,584+02 INFO
>> [org.ovirt.engine.core.bll.AttachUserToVmFromPoolAndRunCommand]
>> (EE-ManagedThreadFactory-engineScheduled-Thread-14)
>> [e3c5745c-e593-4aed-ba67-b173808140e8] Ending command
>> 'org.ovirt.engine.core.bll.AttachUserToVmFromPoolAndRunCommand' successfully.
>> 2019-05-14 13:26:49,650+02 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (EE-ManagedThreadFactory-engineScheduled-Thread-14)
>> [e3c5745c-e593-4aed-ba67-b173808140e8] EVENT_ID:
>> USER_ATTACH_USER_TO_VM_FROM_POOL_FINISHED_SUCCESS(318), User u0045469
>> successfully attached to VM stud-c7-1 in VM Pool stud-c7-?.
>> 2019-05-14 13:26:50,584+02 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (ForkJoinPool-1-worker-2) [] EVENT_ID: VM_CONSOLE_DISCONNECTED(168), User
>> <UNKNOWN> got disconnected from VM stud-c7-1.
>> 2019-05-14 13:26:50,585+02 INFO
>> [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer]
>> (ForkJoinPool-1-worker-2) [] VM
>> 'd8a99676-d520-425e-9974-1b1efe6da8a5'(stud-c7-1) moved from 'WaitForLaunch'
>> --> 'PoweringUp'
>>
>>
>> The first lock (on the pool itself) is never released. It seems this lock
>> should also be released? Maybe it's this lock that should be released the
>> second time (instead of the second lock twice)?
>>
>>
>>
>> When we start to launch another instance of the pool it fails:
>>
>> 2019-05-14 13:49:32,656+02 INFO
>> [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (default
>> task-11) [55cc0796-4f53-49cd-8739-3b7e7dd2d95b] START,
>> IsVmDuringInitiatingVDSCommand(
>> IsVmDuringInitiatingVDSCommandParameters:{vmId='d8a99676-d520-425e-9974-1b1efe6da8a5'}),
>> log id: 7db2f4fc
>> 2019-05-14 13:49:32,656+02 INFO
>> [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (default
>> task-11) [55cc0796-4f53-49cd-8739-3b7e7dd2d95b] FINISH,
>> IsVmDuringInitiatingVDSCommand, return: false, log id: 7db2f4fc
>> 2019-05-14 13:49:32,688+02 INFO [org.ovirt.engine.core.bll.VmPoolHandler]
>> (default task-11) [55cc0796-4f53-49cd-8739-3b7e7dd2d95b] Failed to Acquire
>> Lock to object
>> 'EngineLock:{exclusiveLocks='[d8a99676-d520-425e-9974-1b1efe6da8a5=VM]',
>> sharedLocks=''}'
>> 2019-05-14 13:49:32,700+02 INFO
>> [org.ovirt.engine.core.bll.AttachUserToVmFromPoolAndRunCommand] (default
>> task-11) [55cc0796-4f53-49cd-8739-3b7e7dd2d95b] Lock Acquired to object
>> 'EngineLock:{exclusiveLocks='[a5bed59c-d2fe-4fe4-bff7-52efe089ebd6=USER_VM_POOL]',
>> sharedLocks=''}'
>> 2019-05-14 13:49:32,700+02 WARN
>> [org.ovirt.engine.core.bll.AttachUserToVmFromPoolAndRunCommand] (default
>> task-11) [55cc0796-4f53-49cd-8739-3b7e7dd2d95b] Validation of action
>> 'AttachUserToVmFromPoolAndRun' failed for user
>> u0045...@esat.kuleuven.be-authz <mailto:u0045...@esat.kuleuven.be-authz>.
>> Reasons:
>> VAR__ACTION__ALLOCATE_AND_RUN,VAR__TYPE__VM_FROM_VM_POOL,ACTION_TYPE_FAILED_NO_AVAILABLE_POOL_VMS
>> 2019-05-14 13:49:32,700+02 INFO
>> [org.ovirt.engine.core.bll.AttachUserToVmFromPoolAndRunCommand] (default
>> task-11) [55cc0796-4f53-49cd-8739-3b7e7dd2d95b] Lock freed to object
>> 'EngineLock:{exclusiveLocks='[a5bed59c-d2fe-4fe4-bff7-52efe089ebd6=USER_VM_POOL]',
>> sharedLocks=''}'
>> 2019-05-14 13:49:32,706+02 ERROR
>> [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default
>> task-11) [] Operation Failed: [Cannot allocate and run VM from VM-Pool.
>> There are no available VMs in the VM-Pool.]
>>
>>
>> Regards,
>> Rik
>>
>>
>> --
>> Rik Theys
>> System Engineer
>> KU Leuven - Dept. Elektrotechniek (ESAT)
>> Kasteelpark Arenberg 10 bus 2440 - B-3001 Leuven-Heverlee
>> +32(0)16/32.11.07
>> ----------------------------------------------------------------
>> <<Any errors in spelling, tact or fact are transmission errors>>
>>
>> _______________________________________________
>> Users mailing list -- users@ovirt.org
>> To unsubscribe send an email to users-le...@ovirt.org
>> Privacy Statement: https://www.ovirt.org/site/privacy-policy/
>> oVirt Code of Conduct:
>> https://www.ovirt.org/community/about/community-guidelines/
>> List Archives:
>> https://lists.ovirt.org/archives/list/users@ovirt.org/message/3IASEV7U7DIDVHAGAR2E2WQVFTCFH7QU/
> Thank you
> Lucie
> --
> Lucie Leistnerova
> Quality Engineer, QE Cloud, RHVM
> Red Hat EMEA
>
> IRC: lleistne @ #rhev-qe
--
Rik Theys
System Engineer
KU Leuven - Dept. Elektrotechniek (ESAT)
Kasteelpark Arenberg 10 bus 2440 - B-3001 Leuven-Heverlee
+32(0)16/32.11.07
----------------------------------------------------------------
<<Any errors in spelling, tact or fact are transmission errors>>
_______________________________________________
Users mailing list -- users@ovirt.org
To unsubscribe send an email to users-le...@ovirt.org
Privacy Statement: https://www.ovirt.org/site/privacy-policy/
oVirt Code of Conduct:
https://www.ovirt.org/community/about/community-guidelines/
List Archives:
https://lists.ovirt.org/archives/list/users@ovirt.org/message/M64SNKU72CSHFBKTTMUHRPSDHVTZVORG/
