[JIRA] (OVIRT-2148) 005_network_by_label.assign_hosts_network_label

Thursday, 7 June 2018

    [
https://ovirt-jira.atlassian.net/browse/OVIRT-2148?page=com.atlassian.jir...
] 

Dafna Ron edited comment on OVIRT-2148 at 6/7/18 9:12 AM:
----------------------------------------------------------

This is a race inside engine when a command is sent for a locked object. 

here you can see that the lock was taken, another attempt to take the lock was made and
failed. then the lock was released

'018-06-06 10:25:50,334-04 INFO 
[org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (ForkJoinPool-1-worker-15)
[2180968c] Lock Acquired to object
'EngineLock:{exclusiveLocks='[HOST_NETWORKf44822d4-7967-44fb-b59e-23e73c7ba33c=HOST_
NETWORK, f44822d4-7967-44fb-b59e-23e73c7ba33c=VDS]', sharedLocks=''}'
2018-06-06 10:25:50,338-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [2180968c] method: get, params:
[f44822d4-7967-44fb-b59e-23e73c7ba33c], timeElapsed: 4ms
2018-06-06 10:25:50,341-04 INFO 
[org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (ForkJoinPool-1-worker-15)
[2180968c] Running command: RefreshHostCapabilitiesCommand internal: true. Entities
affected :  ID: f44822d4-7967-44fb-
b59e-23e73c7ba33c Type: VDSAction group MANIPULATE_HOST with role type ADMIN
2018-06-06 10:25:50,341-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [2180968c] method: getVdsManager, params:
[f44822d4-7967-44fb-b59e-23e73c7ba33c], timeElapsed: 0ms
2018-06-06 10:25:50,346-04 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetCapabilitiesVDSCommand]
(ForkJoinPool-1-worker-15) [2180968c] START, GetCapabilitiesVDSCommand(HostName =
lago-basic-suite-4-2-host-1, VdsIdAndVdsVDSCommandPar
ametersBase:{hostId='f44822d4-7967-44fb-b59e-23e73c7ba33c',
vds='Host[lago-basic-suite-4-2-host-1,f44822d4-7967-44fb-b59e-23e73c7ba33c]'}),
log id: 70ddbb6e
2018-06-06 10:25:50,487-04 INFO  [org.ovirt.engine.core.bll.network.host.LabelNicCommand]
(default task-3) [94ed8216-a9b8-4bb9-b5a3-90cb25196153] Running command: LabelNicCommand
internal: false. Entities affected :  ID: f44822d4-7967-44f
b-b59e-23e73c7ba33c Type: VDSAction group CONFIGURE_HOST_NETWORK with role type ADMIN
2018-06-06 10:25:50,496-04 INFO 
[org.ovirt.engine.core.bll.network.host.HostSetupNetworksCommand] (default task-3)
[74f07638] Failed to Acquire Lock to object
'EngineLock:{exclusiveLocks='[HOST_NETWORKf44822d4-7967-44fb-b59e-23e73c7ba33c
=HOST_NETWORK]', sharedLocks=''}'
2018-06-06 10:25:50,531-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-3)
[74f07638] method: get, params: [f44822d4-7967-44fb-b59e-23e73c7ba33c], timeElapsed: 2ms
2018-06-06 10:25:50,535-04 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStatusVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-32) [] START, SpmStatusVDSCommand(HostName
= lago-basic-suite-4-2-host-1, SpmStatusVDSCommand
Parameters:{hostId='f44822d4-7967-44fb-b59e-23e73c7ba33c',
storagePoolId='cae56770-d7bd-4d03-9d74-d3b44ce1c20d'}), log id: 5ef2db2c
2018-06-06 10:25:50,571-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-32) [] method: runVdsCommand, params:
[SpmStatus, SpmStatusVDSCommandParameters:{hostId
='f44822d4-7967-44fb-b59e-23e73c7ba33c',
storagePoolId='cae56770-d7bd-4d03-9d74-d3b44ce1c20d'}], timeElapsed: 38ms
2018-06-06 10:25:51,454-04 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetCapabilitiesVDSCommand]
(ForkJoinPool-1-worker-15) [2180968c] FINISH, GetCapabilitiesVDSCommand, return:
Host[lago-basic-suite-4-2-host-1,f44822d4-7967-44fb-b5
9e-23e73c7ba33c], log id: 70ddbb6e
2018-06-06 10:25:51,454-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [2180968c] method: runVdsCommand, params: [GetCapabilities,
VdsIdAndVdsVDSCommandParametersBase:{hostId='f44
822d4-7967-44fb-b59e-23e73c7ba33c',
vds='Host[lago-basic-suite-4-2-host-1,f44822d4-7967-44fb-b59e-23e73c7ba33c]'}],
timeElapsed: 1112ms
2018-06-06 10:25:51,458-04 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoAsyncVDSCommand]
(ForkJoinPool-1-worker-15) [2180968c] START, GetHardwareInfoAsyncVDSCommand(HostName =
lago-basic-suite-4-2-host-1, VdsIdAndVdsVDS
CommandParametersBase:{hostId='f44822d4-7967-44fb-b59e-23e73c7ba33c',
vds='Host[lago-basic-suite-4-2-host-1,f44822d4-7967-44fb-b59e-23e73c7ba33c]'}),
log id: 18a9c9f5
2018-06-06 10:25:51,458-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [2180968c] method: runVdsCommand, params:
[GetHardwareInfoAsync, VdsIdAndVdsVDSCommandParametersBase:{hostId
='f44822d4-7967-44fb-b59e-23e73c7ba33c',
vds='Host[lago-basic-suite-4-2-host-1,f44822d4-7967-44fb-b59e-23e73c7ba33c]'}],
timeElapsed: 4ms
2018-06-06 10:25:51,521-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [21f11dbd] method: get, params:
[f44822d4-7967-44fb-b59e-23e73c7ba33c], timeElapsed: 3ms
2018-06-06 10:25:51,524-04 INFO 
[org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedCommand]
(ForkJoinPool-1-worker-15) [21f11dbd] Running command:
HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities affected :  ID:
 f44822d4-7967-44fb-b59e-23e73c7ba33c Type: VDS
2018-06-06 10:25:51,536-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [5a2c025e] method: get, params:
[f44822d4-7967-44fb-b59e-23e73c7ba33c], timeElapsed: 3ms
2018-06-06 10:25:51,539-04 INFO  [org.ovirt.engine.core.bll.HandleVdsVersionCommand]
(ForkJoinPool-1-worker-15) [5a2c025e] Running command: HandleVdsVersionCommand internal:
true. Entities affected :  ID: f44822d4-7967-44fb-b59e-23e73c7ba
33c Type: VDS
2018-06-06 10:25:51,551-04 INFO 
[org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (ForkJoinPool-1-worker-15)
[5a2c025e] Lock freed to object
'EngineLock:{exclusiveLocks='[HOST_NETWORKf44822d4-7967-44fb-b59e-23e73c7ba33c=HOST_NET
WORK, f44822d4-7967-44fb-b59e-23e73c7ba33c=VDS]', sharedLocks=''}'
ed: '

was (Author: dron):
This is a race inside engine when a command is sent for a locked object. 

' here you can see that the lock was taken, another attempt to take the lock was made
and failed. then the lock was releas018-06-06 10:25:50,334-04 INFO 
[org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (ForkJoinPool-1-worker-15)
[2180968c] Lock Acquired to object
'EngineLock:{exclusiveLocks='[HOST_NETWORKf44822d4-7967-44fb-b59e-23e73c7ba33c=HOST_
NETWORK, f44822d4-7967-44fb-b59e-23e73c7ba33c=VDS]', sharedLocks=''}'
2018-06-06 10:25:50,338-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [2180968c] method: get, params:
[f44822d4-7967-44fb-b59e-23e73c7ba33c], timeElapsed: 4ms
2018-06-06 10:25:50,341-04 INFO 
[org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (ForkJoinPool-1-worker-15)
[2180968c] Running command: RefreshHostCapabilitiesCommand internal: true. Entities
affected :  ID: f44822d4-7967-44fb-
b59e-23e73c7ba33c Type: VDSAction group MANIPULATE_HOST with role type ADMIN
2018-06-06 10:25:50,341-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [2180968c] method: getVdsManager, params:
[f44822d4-7967-44fb-b59e-23e73c7ba33c], timeElapsed: 0ms
2018-06-06 10:25:50,346-04 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetCapabilitiesVDSCommand]
(ForkJoinPool-1-worker-15) [2180968c] START, GetCapabilitiesVDSCommand(HostName =
lago-basic-suite-4-2-host-1, VdsIdAndVdsVDSCommandPar
ametersBase:{hostId='f44822d4-7967-44fb-b59e-23e73c7ba33c',
vds='Host[lago-basic-suite-4-2-host-1,f44822d4-7967-44fb-b59e-23e73c7ba33c]'}),
log id: 70ddbb6e
2018-06-06 10:25:50,487-04 INFO  [org.ovirt.engine.core.bll.network.host.LabelNicCommand]
(default task-3) [94ed8216-a9b8-4bb9-b5a3-90cb25196153] Running command: LabelNicCommand
internal: false. Entities affected :  ID: f44822d4-7967-44f
b-b59e-23e73c7ba33c Type: VDSAction group CONFIGURE_HOST_NETWORK with role type ADMIN
2018-06-06 10:25:50,496-04 INFO 
[org.ovirt.engine.core.bll.network.host.HostSetupNetworksCommand] (default task-3)
[74f07638] Failed to Acquire Lock to object
'EngineLock:{exclusiveLocks='[HOST_NETWORKf44822d4-7967-44fb-b59e-23e73c7ba33c
=HOST_NETWORK]', sharedLocks=''}'
2018-06-06 10:25:50,531-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-3)
[74f07638] method: get, params: [f44822d4-7967-44fb-b59e-23e73c7ba33c], timeElapsed: 2ms
2018-06-06 10:25:50,535-04 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStatusVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-32) [] START, SpmStatusVDSCommand(HostName
= lago-basic-suite-4-2-host-1, SpmStatusVDSCommand
Parameters:{hostId='f44822d4-7967-44fb-b59e-23e73c7ba33c',
storagePoolId='cae56770-d7bd-4d03-9d74-d3b44ce1c20d'}), log id: 5ef2db2c
2018-06-06 10:25:50,571-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-32) [] method: runVdsCommand, params:
[SpmStatus, SpmStatusVDSCommandParameters:{hostId
='f44822d4-7967-44fb-b59e-23e73c7ba33c',
storagePoolId='cae56770-d7bd-4d03-9d74-d3b44ce1c20d'}], timeElapsed: 38ms
2018-06-06 10:25:51,454-04 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetCapabilitiesVDSCommand]
(ForkJoinPool-1-worker-15) [2180968c] FINISH, GetCapabilitiesVDSCommand, return:
Host[lago-basic-suite-4-2-host-1,f44822d4-7967-44fb-b5
9e-23e73c7ba33c], log id: 70ddbb6e
2018-06-06 10:25:51,454-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [2180968c] method: runVdsCommand, params: [GetCapabilities,
VdsIdAndVdsVDSCommandParametersBase:{hostId='f44
822d4-7967-44fb-b59e-23e73c7ba33c',
vds='Host[lago-basic-suite-4-2-host-1,f44822d4-7967-44fb-b59e-23e73c7ba33c]'}],
timeElapsed: 1112ms
2018-06-06 10:25:51,458-04 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoAsyncVDSCommand]
(ForkJoinPool-1-worker-15) [2180968c] START, GetHardwareInfoAsyncVDSCommand(HostName =
lago-basic-suite-4-2-host-1, VdsIdAndVdsVDS
CommandParametersBase:{hostId='f44822d4-7967-44fb-b59e-23e73c7ba33c',
vds='Host[lago-basic-suite-4-2-host-1,f44822d4-7967-44fb-b59e-23e73c7ba33c]'}),
log id: 18a9c9f5
2018-06-06 10:25:51,458-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [2180968c] method: runVdsCommand, params:
[GetHardwareInfoAsync, VdsIdAndVdsVDSCommandParametersBase:{hostId
='f44822d4-7967-44fb-b59e-23e73c7ba33c',
vds='Host[lago-basic-suite-4-2-host-1,f44822d4-7967-44fb-b59e-23e73c7ba33c]'}],
timeElapsed: 4ms
2018-06-06 10:25:51,521-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [21f11dbd] method: get, params:
[f44822d4-7967-44fb-b59e-23e73c7ba33c], timeElapsed: 3ms
2018-06-06 10:25:51,524-04 INFO 
[org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedCommand]
(ForkJoinPool-1-worker-15) [21f11dbd] Running command:
HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities affected :  ID:
 f44822d4-7967-44fb-b59e-23e73c7ba33c Type: VDS
2018-06-06 10:25:51,536-04 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(ForkJoinPool-1-worker-15) [5a2c025e] method: get, params:
[f44822d4-7967-44fb-b59e-23e73c7ba33c], timeElapsed: 3ms
2018-06-06 10:25:51,539-04 INFO  [org.ovirt.engine.core.bll.HandleVdsVersionCommand]
(ForkJoinPool-1-worker-15) [5a2c025e] Running command: HandleVdsVersionCommand internal:
true. Entities affected :  ID: f44822d4-7967-44fb-b59e-23e73c7ba
33c Type: VDS
2018-06-06 10:25:51,551-04 INFO 
[org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (ForkJoinPool-1-worker-15)
[5a2c025e] Lock freed to object
'EngineLock:{exclusiveLocks='[HOST_NETWORKf44822d4-7967-44fb-b59e-23e73c7ba33c=HOST_NET
WORK, f44822d4-7967-44fb-b59e-23e73c7ba33c=VDS]', sharedLocks=''}'
ed: '

...
 005_network_by_label.assign_hosts_network_label 
 ------------------------------------------------

                 Key: OVIRT-2148
                 URL: https://ovirt-jira.atlassian.net/browse/OVIRT-2148
             Project: oVirt - virtualization made easy
          Issue Type: Task
            Reporter: Dafna Ron
            Assignee: infra
              Labels: ost_failures, ost_race

 Change 91614,10 (ovirt-provider-ovn) is probably the reason behind recent
 system test failures in the "ovirt-4.2" change queue and needs to be fixed.
 This change had been removed from the testing queue. Artifacts build from this
 change will not be released until it is fixed.
 For further details about the change see:
 https://gerrit.ovirt.org/#/c/91614/10
 For failed test results see:
 http://jenkins.ovirt.org/job/ovirt-4.2_change-queue-tester/2312/
 Fault reason is "Operation Failed". Fault detail is "[Cannot add Label.
Another Setup Networks or Host Refresh process in progress on the host. Please try
later.]". HTTP response code is 409. 

--
This message was sent by Atlassian Jira
(v1001.0.0-SNAPSHOT#100087)

2025

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011