Hi,
It seems VM pools are completely broken since our upgrade to 4.3. Is
anybody else also experiencing this issue?
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.
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.vdsbro