[ OST Failure Report ] [ oVirt Master (cockpit-ovirt) ] [ 15-03-2018 ] [ 098_ovirt_provider_ovn.use_ovn_provider ]
Hi, We have a failure on master for test 098_ovirt_provider_ovn.use_ovn_provider in project cockpit-ovirt. This seems to be a race because object is locked. also, the actual failure is logged as WARN and not ERROR. I don't think the patch is actually related to the failure but I think the test should be fixed. can you please review to make sure we do not have an actual regression and let me know if we need to open a bz to fix the test? *Link and headline of suspected patches: * *https://gerrit.ovirt.org/#/c/89020/2 <https://gerrit.ovirt.org/#/c/89020/2> - * *wizard: Enable scroll on start page for low-res screensLink to Job:http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6374 <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6374>Link to all logs:http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6374/artifacts <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6374/artifacts>(Relevant) error snippet from the log: <error>2018-03-15 10:05:00,160-04 DEBUG [org.ovirt.engine.core.sso.servlets.OAuthTokenInfoServlet] (default task-10) [] Sending json response2018-03-15 10:05:00,160-04 DEBUG [org.ovirt.engine.core.sso.utils.TokenCleanupUtility] (default task-10) [] Not cleaning up expired tokens2018-03-15 10:05:00,169-04 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [789edb23] Lock Acquired to object 'EngineLock:{exclusiveLocks='[c38a67ec-0b48-4e6f-be85-70c700df5483=PROVIDER]', sharedLocks=''}'2018-03-15 10:05:00,184-04 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [789edb23] Running command: SyncNetworkProviderCommand internal: true.2018-03-15 10:05:00,228-04 DEBUG [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] Compiled stored procedure. Call string is [{call getdcidbyexternalnetworkid(?)}]2018-03-15 10:05:00,228-04 DEBUG [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] SqlCall for procedure [GetDcIdByExternalNetworkId] compiled2018-03-15 10:05:00,229-04 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] method: runQuery, params: [GetAllExternalNetworksOnProvider, IdQueryParameters:{refresh='false', filtered='false'}], timeElapsed: 353ms2018-03-15 10:05:00,239-04 INFO [org.ovirt.engine.core.bll.network.dc.AddNetworkCommand] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] Failed to Acquire Lock to object 'EngineLock:{exclusiveLocks='[network_1=NETWORK, c38a67ec-0b48-4e6f-be85-70c700df5483=PROVIDER]', sharedLocks=''}'2018-03-15 10:05:00,239-04 WARN [org.ovirt.engine.core.bll.network.dc.AddNetworkCommand] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] Validation of action 'AddNetwork' failed for user admin@internal-authz. Reasons: VAR__TYPE__NETWORK,VAR__ACTION__ADD,ACTION_TYPE_FAILED_PROVIDER_LOCKED,$providerId c38a67ec-0b48-4e6f-be85-70c700df54832018-03-15 10:05:00,240-04 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] method: runAction, params: [AddNetwork, AddNetworkStoragePoolParameters:{commandId='61b365ec-27c1-49af-ad72-f907df8befcd', user='null', commandType='Unknown'}], timeElapsed: 10ms2018-03-15 10:05:00,250-04 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-13) [] Operation Failed: [Cannot add Network. Related operation on provider with the id c38a67ec-0b48-4e6f-be85-70c700df5483 is currently in progress. Please try again later.]2018-03-15 10:05:00,254-04 DEBUG [org.ovirt.engine.core.utils.servlet.LocaleFilter] (default task-14) [] Incoming locale 'en-US'. Filter determined locale to be 'en-US'2018-03-15 10:05:00,254-04 DEBUG [org.ovirt.engine.core.sso.servlets.OAuthTokenServlet] (default task-14) [] Entered OAuthTokenServlet Query String: null, Parameters : password = ***, grant_type = password, scope = ovirt-app-api ovirt-ext=token-info:validate, username = admin@internal, </error>*
On Thu, 15 Mar 2018 16:24:10 +0000 Dafna Ron <dron@redhat.com> wrote:
Hi,
We have a failure on master for test 098_ovirt_provider_ovn.use_ovn_provider in project cockpit-ovirt. This seems to be a race because object is locked. also, the actual failure is logged as WARN and not ERROR.
I don't think the patch is actually related to the failure but I think the test should be fixed. can you please review to make sure we do not have an actual regression and let me know if we need to open a bz to fix the test?
*Link and headline of suspected patches: * *https://gerrit.ovirt.org/#/c/89020/2 <https://gerrit.ovirt.org/#/c/89020/2> - *
*wizard: Enable scroll on start page for low-res screensLink to Job:http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6374 <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6374>Link to all logs:http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6374/artifacts <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6374/artifacts>(Relevant) error snippet from the log: <error>2018-03-15 10:05:00,160-04 DEBUG [org.ovirt.engine.core.sso.servlets.OAuthTokenInfoServlet] (default task-10) [] Sending json response2018-03-15 10:05:00,160-04 DEBUG [org.ovirt.engine.core.sso.utils.TokenCleanupUtility] (default task-10) [] Not cleaning up expired tokens2018-03-15 10:05:00,169-04 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [789edb23] Lock Acquired to object 'EngineLock:{exclusiveLocks='[c38a67ec-0b48-4e6f-be85-70c700df5483=PROVIDER]', sharedLocks=''}'2018-03-15 10:05:00,184-04 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [789edb23] Running command: SyncNetworkProviderCommand internal: true.2018-03-15 10:05:00,228-04 DEBUG [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] Compiled stored procedure. Call string is [{call getdcidbyexternalnetworkid(?)}]2018-03-15 10:05:00,228-04 DEBUG [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] SqlCall for procedure [GetDcIdByExternalNetworkId] compiled2018-03-15 10:05:00,229-04 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] method: runQuery, params: [GetAllExternalNetworksOnProvider, IdQueryParameters:{refresh='false', filtered='false'}], timeElapsed: 353ms2018-03-15 10:05:00,239-04 INFO [org.ovirt.engine.core.bll.network.dc.AddNetworkCommand] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] Failed to Acquire Lock to object 'EngineLock:{exclusiveLocks='[network_1=NETWORK, c38a67ec-0b48-4e6f-be85-70c700df5483=PROVIDER]', sharedLocks=''}'2018-03-15 10:05:00,239-04 WARN [org.ovirt.engine.core.bll.network.dc.AddNetworkCommand] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] Validation of action 'AddNetwork' failed for user admin@internal-authz. Reasons: VAR__TYPE__NETWORK,VAR__ACTION__ADD,ACTION_TYPE_FAILED_PROVIDER_LOCKED,$providerId c38a67ec-0b48-4e6f-be85-70c700df54832018-03-15 10:05:00,240-04 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] method: runAction, params: [AddNetwork, AddNetworkStoragePoolParameters:{commandId='61b365ec-27c1-49af-ad72-f907df8befcd', user='null', commandType='Unknown'}], timeElapsed: 10ms2018-03-15 10:05:00,250-04 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-13) [] Operation Failed: [Cannot add Network. Related operation on provider with the id c38a67ec-0b48-4e6f-be85-70c700df5483 is currently in progress. Please try again later.]2018-03-15 10:05:00,254-04 DEBUG [org.ovirt.engine.core.utils.servlet.LocaleFilter] (default task-14) [] Incoming locale 'en-US'. Filter determined locale to be 'en-US'2018-03-15 10:05:00,254-04 DEBUG [org.ovirt.engine.core.sso.servlets.OAuthTokenServlet] (default task-14) [] Entered OAuthTokenServlet Query String: null, Parameters : password = ***, grant_type = password, scope = ovirt-app-api ovirt-ext=token-info:validate, username = admin@internal, </error>*
I will care about this. The problem is that SyncNetworkProviderCommand is running in the background and locking the provider, which blocks the lock for the tested AddNetworkCommand. The related changes are core: Add locking for Add and RemoveNetworkCommand https://gerrit.ovirt.org/#/c/85480/ and core: Add SyncNetworkProviderCommand https://gerrit.ovirt.org/#/c/85134/
Thank you for the fast reply and help. On Thu, Mar 15, 2018 at 8:21 PM, Dominik Holler <dholler@redhat.com> wrote:
On Thu, 15 Mar 2018 16:24:10 +0000 Dafna Ron <dron@redhat.com> wrote:
Hi,
We have a failure on master for test 098_ovirt_provider_ovn.use_ovn_provider in project cockpit-ovirt. This seems to be a race because object is locked. also, the actual failure is logged as WARN and not ERROR.
I don't think the patch is actually related to the failure but I think the test should be fixed. can you please review to make sure we do not have an actual regression and let me know if we need to open a bz to fix the test?
*Link and headline of suspected patches: * *https://gerrit.ovirt.org/#/c/89020/2 <https://gerrit.ovirt.org/#/c/89020/2> - *
*wizard: Enable scroll on start page for low-res screensLink to Job:http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6374 <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6374>Link to all logs:http://jenkins.ovirt.org/job/ovirt-master_change-queue- tester/6374/artifacts <http://jenkins.ovirt.org/job/ovirt-master_change-queue- tester/6374/artifacts>(Relevant) error snippet from the log: <error>2018-03-15 10:05:00,160-04 DEBUG [org.ovirt.engine.core.sso.servlets.OAuthTokenInfoServlet] (default task-10) [] Sending json response2018-03-15 10:05:00,160-04 DEBUG [org.ovirt.engine.core.sso.utils.TokenCleanupUtility] (default task-10) [] Not cleaning up expired tokens2018-03-15 10:05:00,169-04 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [789edb23] Lock Acquired to object 'EngineLock:{exclusiveLocks='[c38a67ec-0b48-4e6f-be85- 70c700df5483=PROVIDER]', sharedLocks=''}'2018-03-15 10:05:00,184-04 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [789edb23] Running command: SyncNetworkProviderCommand internal: true.2018-03-15 10:05:00,228-04 DEBUG [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$ PostgresSimpleJdbcCall] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] Compiled stored procedure. Call string is [{call getdcidbyexternalnetworkid(?)}]2018-03-15 10:05:00,228-04 DEBUG [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$ PostgresSimpleJdbcCall] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] SqlCall for procedure [GetDcIdByExternalNetworkId] compiled2018-03-15 10:05:00,229-04 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] method: runQuery, params: [GetAllExternalNetworksOnProvider, IdQueryParameters:{refresh='false', filtered='false'}], timeElapsed: 353ms2018-03-15 10:05:00,239-04 INFO [org.ovirt.engine.core.bll.network.dc.AddNetworkCommand] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] Failed to Acquire Lock to object 'EngineLock:{exclusiveLocks='[network_1=NETWORK, c38a67ec-0b48-4e6f-be85-70c700df5483=PROVIDER]', sharedLocks=''}'2018-03-15 10:05:00,239-04 WARN [org.ovirt.engine.core.bll.network.dc.AddNetworkCommand] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] Validation of action 'AddNetwork' failed for user admin@internal-authz. Reasons: VAR__TYPE__NETWORK,VAR__ACTION__ADD,ACTION_TYPE_FAILED_PROVIDER_LOCKED,$ providerId c38a67ec-0b48-4e6f-be85-70c700df54832018-03-15 10:05:00,240-04 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-13) [e1328379-17b7-49f8-beb2-cf8331784828] method: runAction, params: [AddNetwork, AddNetworkStoragePoolParameters:{commandId='61b365ec-27c1- 49af-ad72-f907df8befcd', user='null', commandType='Unknown'}], timeElapsed: 10ms2018-03-15 10:05:00,250-04 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-13) [] Operation Failed: [Cannot add Network. Related operation on provider with the id c38a67ec-0b48-4e6f-be85-70c700df5483 is currently in progress. Please try again later.]2018-03-15 10:05:00,254-04 DEBUG [org.ovirt.engine.core.utils.servlet.LocaleFilter] (default task-14) [] Incoming locale 'en-US'. Filter determined locale to be 'en-US'2018-03-15 10:05:00,254-04 DEBUG [org.ovirt.engine.core.sso.servlets.OAuthTokenServlet] (default task-14) [] Entered OAuthTokenServlet Query String: null, Parameters : password = ***, grant_type = password, scope = ovirt-app-api ovirt-ext=token-info:validate, username = admin@internal, </error>*
I will care about this. The problem is that SyncNetworkProviderCommand is running in the background and locking the provider, which blocks the lock for the tested AddNetworkCommand. The related changes are core: Add locking for Add and RemoveNetworkCommand https://gerrit.ovirt.org/#/c/85480/ and core: Add SyncNetworkProviderCommand https://gerrit.ovirt.org/#/c/85134/
participants (2)
-
Dafna Ron -
Dominik Holler