issue was resolved by Ala's patch. Thanks :) Dafna
On 11/23/2017 06:52 PM, Dafna Ron wrote: > I am still seeing an exception in latest failure: > > http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4064/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-004_basic_sanity.py/lago-basic-suite-master-engine/_var_log/ovirt-engine/engine.log > > > 2017-11-23 13:36:14,868-05 ERROR > [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] > (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] EVENT_ID: > USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM vm1 creation. > 2017-11-23 13:36:14,868-05 ERROR > [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] > (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Failed invoking > callback end method 'onSucceeded' for command > '923052a8-acc1-47a8-adcf-d4591c > a751c1' with exception 'null', the callback is marked for end method > retries but max number of retries have been attempted. The command > will be marked as Failed. > 2017-11-23 13:36:14,869-05 ERROR > [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] > (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Error invoking > callback method 'onSucceeded' for 'SUCCEEDED' command > '923052a8-acc1-47a8-adcf > -d4591ca751c1' > 2017-11-23 13:36:14,869-05 ERROR > [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] > (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Exception: > javax.ejb.EJBTransactionRolledbackException > at > org.jboss.as.ejb3.tx.CMTTxInterceptor.handleInCallerTx(CMTTxInterceptor.java:160) > [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] > at > org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:257) > [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] > at > org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:381) > [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] > at > org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:244) > [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) > at > org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) > at > org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73) > [weld-core-impl-2.4.3.Final.jar:2.4.3.Final] > ] > : > > > On 11/23/2017 06:04 PM, Dafna Ron wrote: >> Thanks, >> I am not sure the exception is what cause the failure but I will >> monitor to see if that resolves the issue for us before skipping the >> test. >> >> On 11/23/2017 02:49 PM, Ala Hino wrote: >>> Fix (cf502720b4cf7bc09694ee0821f3e7f73d6e6e0f) to the following >>> exception just merged: >>> >>>> Caused by: java.lang.NullPointerException >>>> at java.util.Objects.requireNonNull(Objects.java:203) [rt.jar:1.8.0_151] >>>> at java.util.Optional.<init>(Optional.java:96) [rt.jar:1.8.0_151] >>>> at java.util.Optional.of(Optional.java:108) [rt.jar:1.8.0_151] >>>> at java.util.stream.FindOps$FindSink$OfRef.get(FindOps.java:193) >>>> [rt.jar:1.8.0_151] >>>> at java.util.stream.FindOps$FindSink$OfRef.get(FindOps.java:190) >>>> [rt.jar:1.8.0_151] >>>> at java.util.stream.FindOps$FindOp.evaluateSequential(FindOps.java:152) >>>> [rt.jar:1.8.0_151] >>>> at >>>> java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) >>>> [rt.jar:1.8.0_151] >>>> at >>>> java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:464) >>>> [rt.jar:1.8.0_151] >>>> at >>>> org.ovirt.engine.core.bll.storage.disk.image.BaseImagesCommand.setQcowCompatByQemuImageInfo(BaseImagesCommand.java:432) >>>> [bll.jar:] >>>> at >>>> org.ovirt.engine.core.bll.storage.disk.image.BaseImagesCommand.endSuccessfully(BaseImagesCommand.java:393) >>>> [bll.jar:] >>>> at >>>> org.ovirt.engine.core.bll.CommandBase.internalEndSuccessfully(CommandBase.java:751) >>>> [bll.jar:] >>>> at >>>> org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:709) >>>> [bll.jar:] >>>> at >>>> org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1989) >>>> [bll.jar:] >>>> at org.ovirt.engine.core.utils.tr >>>> <http://org.ovirt.engine.core.utils.tr>ansaction.TransactionSupport.executeInRequired(TransactionSupport.java:139) >>>> [utils.jar:] >>>> at org.ovirt.engine.core.utils.tr >>>> <http://org.ovirt.engine.core.utils.tr>ansaction.TransactionSupport.executeInScope(TransactionSupport.java:105) >>>> [utils.jar:] >>>> at >>>> org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:574) >>>> [bll.jar:] >>>> at org.ovirt.engine.core.bll.Backend.endAction(Backend.java:536) >>>> [bll.jar:] >>> >>> On Thu, Nov 23, 2017 at 4:44 PM, Allon Mureinik <[email protected] >>> <mailto:[email protected]>> wrote: >>> >>> >>> ---------- Forwarded message ---------- >>> From: *Dafna Ron* <[email protected] <mailto:[email protected]>> >>> Date: Thu, Nov 23, 2017 at 1:32 PM >>> Subject: Re: [ovirt-devel] [ OST Failure Report ] [ oVirt master >>> ] [ 22-11-2017 ] [ 004_basic_sanity.verify_add_vm_template ] >>> To: Yaniv Kaul <[email protected] <mailto:[email protected]>>, Nir >>> Soffer <[email protected] <mailto:[email protected]>> >>> Cc: aos-scalability <[email protected] >>> <mailto:[email protected]>>, devel <[email protected] >>> <mailto:[email protected]>>, infra <[email protected] >>> <mailto:[email protected]>> >>> >>> >>> I opened a bug on the error: >>> https://bugzilla.redhat.com/show_bug.cgi?id=1516780 >>> <https://bugzilla.redhat.com/show_bug.cgi?id=1516780> >>> >>> This test seems to be catching something since we are failing on >>> it randomly so I will review the logs today to see if I can find >>> the true cause of failure and update my findings. >>> >>> On 11/22/2017 07:05 PM, Yaniv Kaul wrote: >>>> >>>> >>>> On Wed, Nov 22, 2017 at 7:55 PM, Nir Soffer <[email protected] >>>> <mailto:[email protected]>> wrote: >>>> >>>> >>>> >>>> On Wed, Nov 22, 2017 at 7:15 PM Dafna Ron <[email protected] >>>> <mailto:[email protected]>> wrote: >>>> >>>> Hi, >>>> >>>> we have a failure in >>>> 004_basic_sanity.verify_add_vm_template. >>>> >>>> The error seems to be a failure from the api request >>>> since although I am seeing errors in the logs I am not >>>> sure they are the cause. >>>> >>>> >>>> ** >>>> >>>> *Link and headline ofto suspected patches: * >>>> >>>> * >>>> >>>> core: Cleanup BaseImagesCommand code - >>>> https://gerrit.ovirt.org/#/c/83812/ >>>> <https://gerrit.ovirt.org/#/c/83812/>* >>>> >>>> * >>>> * >>>> >>>> *Link to Job:* >>>> >>>> >>>> *http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989 >>>> >>>> <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989>* >>>> >>>> >>>> * >>>> * >>>> >>>> *Link to all logs:* >>>> >>>> >>>> *http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact >>>> >>>> <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact>* >>>> >>>> >>>> >>>> Relevant logs start here >>>> - >>>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-004_basic_sanity.py/ >>>> >>>> <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-004_basic_sanity.py/> >>>> >>>> Specifically, server.log >>>> >>>> (http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-004_basic_sanity.py/lago-basic-suite-master-engine/_var_log/ovirt-engine/server.log >>>> >>>> <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-004_basic_sanity.py/lago-basic-suite-master-engine/_var_log/ovirt-engine/server.log> >>>> ): >>>> >>>> 2017-11-22 10:40:14,334-05 ERROR [org.jboss.as.ejb3.invocation] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-29) >>>> WFLYEJB0034: EJB Invocation failed on component Backend for >>>> method public abstract >>>> org.ovirt.engine.core.common.action.ActionReturnValue >>>> >>>> org.ovirt.engine.core.bll.interfaces.BackendInternal.endAction(org.ovirt.engine.core.common.action.ActionType,org.ovirt.engine.core.common.action.ActionParametersBase,org.ovirt.engine.core.bll.context.CommandContext): >>>> javax.ejb.EJBTransactionRolledbackException >>>> at >>>> >>>> org.jboss.as.ejb3.tx.CMTTxInterceptor.handleInCallerTx(CMTTxInterceptor.java:160) >>>> [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] >>>> at >>>> >>>> org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:257) >>>> [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] >>>> at >>>> >>>> org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:381) >>>> [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] >>>> at >>>> >>>> org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:244) >>>> [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] >>>> at >>>> >>>> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) >>>> at >>>> >>>> org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) >>>> at >>>> >>>> org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73) >>>> [weld-core-impl-2.4.3.Final.jar:2.4.3.Final] >>>> at >>>> >>>> org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89) >>>> at >>>> >>>> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) >>>> at org.jboss.as.ejb3.component.in >>>> >>>> <http://org.jboss.as.ejb3.component.in>terceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) >>>> [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] >>>> at >>>> >>>> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) >>>> at org.jboss.as.ejb3.component.in >>>> >>>> <http://org.jboss.as.ejb3.component.in>vocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) >>>> [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] >>>> at >>>> >>>> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) >>>> at >>>> >>>> org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) >>>> [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] >>>> at >>>> >>>> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) >>>> at >>>> >>>> org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) >>>> [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] >>>> at >>>> >>>> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) >>>> >>>> ... >>>> Caused by: java.lang.NullPointerException >>>> at java.util.Objects.requireNonNull(Objects.java:203) >>>> [rt.jar:1.8.0_151] >>>> at java.util.Optional.<init>(Optional.java:96) >>>> [rt.jar:1.8.0_151] >>>> at java.util.Optional.of(Optional.java:108) [rt.jar:1.8.0_151] >>>> at >>>> java.util.stream.FindOps$FindSink$OfRef.get(FindOps.java:193) >>>> [rt.jar:1.8.0_151] >>>> at >>>> java.util.stream.FindOps$FindSink$OfRef.get(FindOps.java:190) >>>> [rt.jar:1.8.0_151] >>>> at >>>> java.util.stream.FindOps$FindOp.evaluateSequential(FindOps.java:152) >>>> [rt.jar:1.8.0_151] >>>> at >>>> java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) >>>> [rt.jar:1.8.0_151] >>>> at >>>> java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:464) >>>> [rt.jar:1.8.0_151] >>>> at >>>> org.ovirt.engine.core.bll.storage.disk.image.BaseImagesCommand.setQcowCompatByQemuImageInfo(BaseImagesCommand.java:432) >>>> [bll.jar:] >>>> at >>>> org.ovirt.engine.core.bll.storage.disk.image.BaseImagesCommand.endSuccessfully(BaseImagesCommand.java:393) >>>> [bll.jar:] >>>> at >>>> org.ovirt.engine.core.bll.CommandBase.internalEndSuccessfully(CommandBase.java:751) >>>> [bll.jar:] >>>> at >>>> org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:709) >>>> [bll.jar:] >>>> at >>>> org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1989) >>>> [bll.jar:] >>>> at org.ovirt.engine.core.utils.tr >>>> >>>> <http://org.ovirt.engine.core.utils.tr>ansaction.TransactionSupport.executeInRequired(TransactionSupport.java:139) >>>> [utils.jar:] >>>> at org.ovirt.engine.core.utils.tr >>>> >>>> <http://org.ovirt.engine.core.utils.tr>ansaction.TransactionSupport.executeInScope(TransactionSupport.java:105) >>>> [utils.jar:] >>>> at >>>> org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:574) >>>> [bll.jar:] >>>> at >>>> org.ovirt.engine.core.bll.Backend.endAction(Backend.java:536) [bll.jar:] >>>> Y. >>>> >>>> * >>>> * >>>> >>>> *(Relevant) error snippet from the log: * >>>> >>>> * >>>> >>>> <error> >>>> >>>> ** >>>> >>>> lago log: >>>> >>>> * >>>> >>>> >>>> >>>> >>>> * >>>> >>>> >>>> * >>>> >>>> File "/usr/lib64/python2.7/unittest/case.py", line 369, in run >>>> testMethod() >>>> File "/usr/lib/python2.7/site-packages/nose/case.py", line >>>> 197, in runTest >>>> self.test(*self.arg) >>>> File >>>> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 129, in >>>> wrapped_test >>>> test() >>>> File >>>> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 59, in >>>> wrapper >>>> return func(get_test_prefix(), *args, **kwargs) >>>> File >>>> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 68, in >>>> wrapper >>>> return func(prefix.virt_env.engine_vm().get_api(), *args, >>>> **kwargs) >>>> File >>>> "/home/jenkins/workspace/ovirt-master_change-queue-tester/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py", >>>> line 500, in verify_add_vm_template >>>> lambda: api.vms.get(VM1_NAME).status.state == 'down', >>>> File >>>> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 271, in >>>> assert_true_within_long >>>> assert_equals_within_long(func, True, allowed_exceptions) >>>> File >>>> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 258, in >>>> assert_equals_within_long >>>> func, value, LONG_TIMEOUT, >>>> allowed_exceptions=allowed_exceptions >>>> File >>>> "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 219, in >>>> assert_equals_within >>>> res = func() >>>> File >>>> "/home/jenkins/workspace/ovirt-master_change-queue-tester/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py", >>>> line 500, in <lambda> >>>> lambda: api.vms.get(VM1_NAME).status.state == 'down', >>>> '\'NoneType\' object has no attribute >>>> \'status\'\n-------------------- >> begin captured logging << >>>> --------------------\novirtlago.testlib: ERROR: * Unhandled exception >>>> in <function <lambda> at 0x4bafb90>\nTraceback (most recent call last):\n >>>> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 219, in >>>> assert_equals_within\n res = func()\n File >>>> "/home/jenkins/workspace/ovirt-master_change-queue-tester/ovirt-system-tests/basic-suite-master/test-scenarios/004_basic_sanity.py", >>>> line 500, in <lambda>\n lambda: api.vms.get(VM1_NAME).status.state == >>>> \'down\',\nAttributeError: \'NoneType\' object has no attribute >>>> \'status\'\n--------------------- >> end captured logging << >>>> ---------------------' >>>> >>>> >>>> This is a test error - code like this is always wrong: >>>> >>>> api.vms.get(VM1_NAME).status.state == something >>>> >>>> In this case, api.vms.get() returned None. The test code >>>> should handle None and fail with meaningfull error, or maybe >>>> retry the call. >>>> >>>> >>>> It doesn't matter - if api.vms.get(VM1_NAME) return None, we'll >>>> fail the test. So we can add an assert here, but still fail in >>>> exactly the same manner. >>>> Gracefully with 'VM1_NAME was not found' ? Perhaps. >>>> >>>> >>>> >>>> >>>> engine log: ** >>>> ** >>>> >>>> {"jsonrpc": "2.0", "id": >>>> "32bfeb29-e70f-48b2-84c7-91cf22ea408c", "result": {"status": "OK", >>>> "domain": "2d776fb7-eba8-4ee2-97b6-4350c28ddb39", "voltype": "LEAF", >>>> "description": "", "parent": "a1192fcc-4660-41a7-a1a5-a221808f603b", >>>> "format": "COW", "generation": 0, "image": >>>> "dc033235-ab4b-4ef0-be79-6e8a22bfb0bc", "ctime": "1511365200", "disktype": >>>> "DATA", "legality": "LEGAL", "mtime": "0", "apparentsize": "1073741824", >>>> "children": [], "pool": "", "capacity": "41126400", "uuid": >>>> "6a354b93-86af-41fb-a68b-10897ae3562f", "truesize": "1073741824", "type": >>>> "SPARSE", "lease": {"owners": [], "version": null}}}� >>>> 2017-11-22 10:40:39,454-05 DEBUG >>>> [org.ovirt.vdsm.jsonrpc.client.internal.ResponseWorker] (ResponseWorker) >>>> [] Message received: {"jsonrpc": "2.0", "id": >>>> "32bfeb29-e70f-48b2-84c7-91cf22ea408c", "result": {"status": "OK", >>>> "domain": "2d776fb7-eba8-4ee2-97b6-4350c28ddb39", "voltype": "LEAF", >>>> "description": "", "parent": "a1192fcc-4660-41a7-a1a5-a221808f603b", >>>> "format": "COW", "generation": 0, "image": >>>> "dc033235-ab4b-4ef0-be79-6e8a22bfb0bc", "ctime": "1511365200", "disktype": >>>> "DATA", "legality": "LEGAL", "mtime": "0", "apparentsize": "1073741824", >>>> "children": [], "pool": "", "capacity": "41126400", "uuid": >>>> "6a354b93-86af-41fb-a68b-10897ae3562f", "truesize": "1073741824", "type": >>>> "SPARSE", "lease": {"owners": [], "version": null}}} >>>> 2017-11-22 10:40:39,454-05 INFO >>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) >>>> [c90b2f35-7a80-476f-9b23-78beecef7c37] FINISH, GetVolumeInfoVDSCommand, >>>> return: >>>> org.ovirt.engine.core.common.businessentities.storage.DiskImage@6903fdd6, >>>> log id: 85b379d >>>> 2017-11-22 10:40:39,455-05 INFO >>>> [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) >>>> [c90b2f35-7a80-476f-9b23-78beecef7c37] FINISH, GetImageInfoVDSCommand, >>>> return: >>>> org.ovirt.engine.core.common.businessentities.storage.DiskImage@6903fdd6, >>>> log id: 75d29166 >>>> 2017-11-22 10:40:39,455-05 DEBUG >>>> [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) >>>> [c90b2f35-7a80-476f-9b23-78beecef7c37] method: runVdsCommand, params: >>>> [GetImageInfo, >>>> GetImageInfoVDSCommandParameters:{storagePoolId='0762073b-b0ab-4ee2-8af9-dafa930a5fd4', >>>> ignoreFailoverLimit='false', >>>> storageDomainId='2d776fb7-eba8-4ee2-97b6-4350c28ddb39', >>>> imageGroupId='dc033235-ab4b-4ef0-be79-6e8a22bfb0bc', >>>> imageId='6a354b93-86af-41fb-a68b-10897ae3562f'}], timeElapsed: 165ms >>>> 2017-11-22 10:40:39,528-05 DEBUG >>>> [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) >>>> [c90b2f35-7a80-476f-9b23-78beecef7c37] method: getVmsWithPlugInfo, params: >>>> [dc033235-ab4b-4ef0-be79-6e8a22bfb0bc], timeElapsed: 68ms >>>> 2017-11-22 10:40:39,543-05 INFO >>>> [org.ovirt.engine.core.utils.transaction.TransactionSupport] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) [] transaction rolled >>>> back >>>> 2017-11-22 10:40:39,543-05 WARN >>>> [org.ovirt.engine.core.bll.lock.InMemoryLockManager] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) [] Trying to release a >>>> shared lock for key: '93d271d5-e0af-4795-b800-55465c7b8826TEMPLATE' , but >>>> lock does not exist >>>> 2017-11-22 10:40:39,543-05 WARN >>>> [org.ovirt.engine.core.bll.lock.InMemoryLockManager] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) [] Trying to release a >>>> shared lock for key: 'fb76119e-9283-4c8b-9185-5d79e2481bc7DISK' , but lock >>>> does not exist >>>> 2017-11-22 10:40:39,543-05 WARN >>>> [org.ovirt.engine.core.bll.lock.InMemoryLockManager] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) [] Trying to release >>>> exclusive lock which does not exist, lock key: 'vm1VM_NAME' >>>> 2017-11-22 10:40:39,543-05 INFO >>>> [org.ovirt.engine.core.bll.AddVmCommand] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) [] Lock freed to >>>> object 'EngineLock:{exclusiveLocks='[vm1=VM_NAME]', >>>> sharedLocks='[93d271d5-e0af-4795-b800-55465c7b8826=TEMPLATE, >>>> fb76119e-9283-4c8b-9185-5d79e2481bc7=DISK]'}' >>>> 2017-11-22 10:40:39,556-05 ERROR >>>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) [] EVENT_ID: >>>> USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM vm1 creation. >>>> 2017-11-22 10:40:39,556-05 ERROR >>>> [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-34) [] Failed invoking >>>> callback end method 'onSucceeded' for command >>>> '2760a62f-e4ee-4dd2-b13a-1bb548e3e62d' with exception 'null', the callback >>>> is marked for end method retries >>>> 2017-11-22 10:40:39,935-05 DEBUG >>>> [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-35) [] method: get, >>>> params: [d25423f6-34bc-4cde-82fa-c0eedfc85386], timeElapsed: 3ms >>>> 2017-11-22 10:40:39,949-05 DEBUG >>>> [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] >>>> (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] method: get, >>>> params: [7c9ec3eb-2838-4b06-9408-326b67869bdc], timeElapsed: 2ms >>>> 2017-11-22 10:40:40,606-05 DEBUG >>>> [org.ovirt.engine.core.aaa.filters.SsoRestApiAuthFilter] (default task-22) >>>> [] Entered SsoRestApiAuthFilter >>>> >>>> vdsm log: >>>> 2017-11-22 10:36:11,973-0500 ERROR (jsonrpc/7) >>>> [storage.TaskManager.Task] (Task='5b6ab546-b560-41fc-9b56-de465aa55eee') >>>> Unexpected error (task:875) >>>> Traceback (most recent call last): >>>> File >>>> "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run >>>> return fn(*args, **kargs) >>>> File "<string>", line 2, in getAllTasksInfo >>>> File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", >>>> line 48, in method >>>> ret = func(*args, **kwargs) >>>> File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", >>>> line 2216, in getAllTasksInfo >>>> allTasksInfo = self._pool.getAllTasksInfo() >>>> File >>>> "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line 77, in >>>> wrapper >>>> raise SecureError("Secured object is not in safe state") >>>> SecureError: Secured object is not in safe state >>>> 2017-11-22 10:36:11,975-0500 INFO (jsonrpc/7) >>>> [storage.TaskManager.Task] (Task='5b6ab546-b560-41fc-9b56-de465aa55eee') >>>> aborting: Task is aborted: u'Secured object is not in safe state' - code >>>> 100 (task:1181) >>>> 2017-11-22 10:36:11,976-0500 ERROR (jsonrpc/7) >>>> [storage.Dispatcher] FINISH getAllTasksInfo error=Secured object is not in >>>> safe state (dispatcher:86) >>>> Traceback (most recent call last): >>>> File >>>> "/usr/lib/python2.7/site-packages/vdsm/storage/dispatcher.py", line 73, in >>>> wrapper >>>> result = ctask.prepare(func, *args, **kwargs) >>>> File >>>> "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 108, in >>>> wrapper >>>> return m(self, *a, **kw) >>>> File >>>> "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 1189, in >>>> prepare >>>> raise self.error >>>> SecureError: Secured object is not in safe state >>>> 2017-11-22 10:36:11,976-0500 INFO (jsonrpc/7) >>>> [jsonrpc.JsonRpcServer] RPC call Host.getAllTasksInfo failed (error 654) >>>> in 0.01 seconds (__init__:573) >>>> 2017-11-22 10:36:11,979-0500 INFO (jsonrpc/2) [vdsm.api] >>>> START getAllTasksStatuses(spUUID=None, options=None) from=::1,52728, >>>> task_id=172b5528-cc76-426a-81d3-43143b49a878 (api:46) >>>> 2017-11-22 10:36:11,979-0500 INFO (jsonrpc/2) [vdsm.api] >>>> FINISH getAllTasksStatuses error=Secured object is not in safe state >>>> from=::1,52728, task_id=172b5528-cc76-426a-81d3-43143b49a878 (api:50) >>>> >>>> >>>> This is https://bugzilla.redhat.com/1426429 >>>> <https://bugzilla.redhat.com/1426429> >>>> >>>> Not related to the real error. >>>> >>>> 2017-11-22 10:36:11,980-0500 ERROR (jsonrpc/2) >>>> [storage.TaskManager.Task] (Task='172b5528-cc76-426a-81d3-43143b49a878') >>>> Unexpected error (task:875) >>>> Traceback (most recent call last): >>>> File >>>> "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run >>>> return fn(*args, **kargs) >>>> File "<string>", line 2, in getAllTasksStatuses >>>> File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", >>>> line 48, in method >>>> ret = func(*args, **kwargs) >>>> File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", >>>> line 2176, in getAllTasksStatuses >>>> allTasksStatus = self._pool.getAllTasksStatuses() >>>> File >>>> "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line 77, in >>>> wrapper >>>> raise SecureError("Secured object is not in safe state") >>>> SecureError: Secured object is not in safe state >>>> 2017-11-22 10:36:11,980-0500 INFO (jsonrpc/2) >>>> [storage.TaskManager.Task] (Task='172b5528-cc76-426a-81d3-43143b49a878') >>>> aborting: Task is aborted: u'Secured object is not in safe state' - code >>>> 100 (task:1181) >>>> 2017-11-22 10:36:11,981-0500 ERROR (jsonrpc/2) >>>> [storage.Dispatcher] FINISH getAllTasksStatuses error=Secured object is >>>> not in safe state (dispatcher:86) >>>> Traceback (most recent call last): >>>> File >>>> "/usr/lib/python2.7/site-packages/vdsm/storage/dispatcher.py", line 73, in >>>> wrapper >>>> result = ctask.prepare(func, *args, **kwargs) >>>> File >>>> "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 108, in >>>> wrapper >>>> return m(self, *a, **kw) >>>> File >>>> "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 1189, in >>>> prepare >>>> raise self.error >>>> SecureError: Secured object is not in safe state >>>> >>>> >>>> The way to find the relevant errors is to find the entry >>>> point of this flow >>>> in engine.log, and then follow this in vdsm.log using >>>> flow_id=xxx. >>>> >>>> Ideally we would send a uuid to engine for every operation, >>>> and be >>>> able to query the operation status using the uuid. This is >>>> the way >>>> storage jobs are managed in vdsm side since 4.1. >>>> >>>> If we had this every test would generate a uuids and debugging >>>> failing test would be much faster. >>>> >>>> Nir >>>> >>>> * >>>> >>>> * >>>> >>>> *</error>* >>>> >>>> ** >>>> >>>> >>>> _______________________________________________ >>>> Devel mailing list >>>> [email protected] <mailto:[email protected]> >>>> http://lists.ovirt.org/mailman/listinfo/devel >>>> <http://lists.ovirt.org/mailman/listinfo/devel> >>>> >>>> >>>> _______________________________________________ >>>> Devel mailing list >>>> [email protected] <mailto:[email protected]> >>>> http://lists.ovirt.org/mailman/listinfo/devel >>>> <http://lists.ovirt.org/mailman/listinfo/devel> >>>> >>>> >>> >>> >>> _______________________________________________ >>> Infra mailing list >>> [email protected] <mailto:[email protected]> >>> http://lists.ovirt.org/mailman/listinfo/infra >>> <http://lists.ovirt.org/mailman/listinfo/infra> >>> >>> >>> >>> >>> >>> _______________________________________________ >>> Devel mailing list >>> [email protected] >>> http://lists.ovirt.org/mailman/listinfo/devel >> >> >> >> >> _______________________________________________ >> Devel mailing list >> [email protected] >> http://lists.ovirt.org/mailman/listinfo/devel > > > > > _______________________________________________ > Devel mailing list > [email protected] > http://lists.ovirt.org/mailman/listinfo/devel
_______________________________________________ Devel mailing list [email protected] http://lists.ovirt.org/mailman/listinfo/devel
