Re: [ovirt-devel] [ OST Failure Report ] [ oVirt master ] [ 22-11-2017 ] [ 004_basic_sanity.verify_add_vm_template ]
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.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:139) [utils.jar:] at org.ovirt.engine.core.utils.transaction.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 <amureini@redhat.com> wrote:
---------- Forwarded message ---------- From: Dafna Ron <dron@redhat.com> 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 <ykaul@redhat.com>, Nir Soffer <nsoffer@redhat.com> Cc: aos-scalability <aos-scalability@redhat.com>, devel <devel@ovirt.org>, infra <infra@ovirt.org>
I opened a bug on the error: https://bugzilla.redhat.com/sh ow_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 <nsoffer@redhat.com> wrote:
On Wed, Nov 22, 2017 at 7:15 PM Dafna Ron <dron@redhat.com> 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-art ifacts/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-arti facts/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.endActi on(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(InterceptorC ontext.java:422) at org.jboss.invocation.InterceptorContext$Invocation.proceed( InterceptorContext.java:509) at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationIntercep tor.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(InterceptorC ontext.java:422) at org.jboss.as.ejb3.component.interceptors.CurrentInvocationCo ntextInterceptor.processInvocation(CurrentInvoc ationContextInterceptor.java:41) [wildfly-ejb3-11.0.0.Final.jar :11.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorC ontext.java:422) at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterc eptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorC ontext.java:422) at org.jboss.as.ejb3.security.SecurityContextInterceptor.proces sInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorC ontext.java:422) at org.jboss.as.ejb3.deployment.processors.StartupAwaitIntercep tor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorC ontext.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.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:139) [utils.jar:] at org.ovirt.engine.core.utils.transaction.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
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 Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
_______________________________________________ Infra mailing list Infra@ovirt.org http://lists.ovirt.org/mailman/listinfo/infra
This is a multi-part message in MIME format. --------------0CF18CB787489ACBA8882429 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit 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 <amureini@redhat.com <mailto:amureini@redhat.com>> wrote:
---------- Forwarded message ---------- From: *Dafna Ron* <dron@redhat.com <mailto:dron@redhat.com>> 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 <ykaul@redhat.com <mailto:ykaul@redhat.com>>, Nir Soffer <nsoffer@redhat.com <mailto:nsoffer@redhat.com>> Cc: aos-scalability <aos-scalability@redhat.com <mailto:aos-scalability@redhat.com>>, devel <devel@ovirt.org <mailto:devel@ovirt.org>>, infra <infra@ovirt.org <mailto:infra@ovirt.org>>
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 <nsoffer@redhat.com <mailto:nsoffer@redhat.com>> wrote:
On Wed, Nov 22, 2017 at 7:15 PM Dafna Ron <dron@redhat.com <mailto:dron@redhat.com>> 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/... <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/... <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 Devel@ovirt.org <mailto:Devel@ovirt.org> http://lists.ovirt.org/mailman/listinfo/devel <http://lists.ovirt.org/mailman/listinfo/devel>
_______________________________________________ Devel mailing list Devel@ovirt.org <mailto:Devel@ovirt.org> http://lists.ovirt.org/mailman/listinfo/devel <http://lists.ovirt.org/mailman/listinfo/devel>
_______________________________________________ Infra mailing list Infra@ovirt.org <mailto:Infra@ovirt.org> http://lists.ovirt.org/mailman/listinfo/infra <http://lists.ovirt.org/mailman/listinfo/infra>
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
--------------0CF18CB787489ACBA8882429 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 8bit <html> <head> <meta http-equiv="Content-Type" content="text/html; charset=utf-8"> </head> <body text="#000000" bgcolor="#FFFFFF"> <div class="moz-cite-prefix">Thanks, <br> 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. <br> <br> On 11/23/2017 02:49 PM, Ala Hino wrote:<br> </div> <blockquote type="cite" cite="mid:CAPuOgO33Wz53x__X016+rhzh1i7w-TemOn0i7N8z6-BkhSmJDQ@mail.gmail.com"> <div dir="ltr">Fix (cf502720b4cf7bc09694ee0821f3e7f73d6e6e0f) to the following exception just merged: <div><br> </div> <div> <blockquote type="cite" style="font-size:12.8px"> <div dir="ltr"> <div class="gmail_extra"> <div class="gmail_quote"> <pre style="white-space:pre-wrap">Caused by: java.lang.NullPointerException at java.util.Objects.requireNonNu<wbr>ll(Objects.java:203) [rt.jar:1.8.0_151] at java.util.Optional.<init>(Opti<wbr>onal.java:96) [rt.jar:1.8.0_151] at java.util.Optional.of(Optional<wbr>.java:108) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>193) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>190) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindO<wbr>p.evaluateSequential(FindOps.<wbr>java:152) [rt.jar:1.8.0_151] at java.util.stream.AbstractPipel<wbr>ine.evaluate(AbstractPipeline.<wbr>java:234) [rt.jar:1.8.0_151] at java.util.stream.ReferencePipe<wbr>line.findFirst(ReferencePipeli<wbr>ne.java:464) [rt.jar:1.8.0_151] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.setQcowCompatByQemuImageInf<wbr>o(BaseImagesCommand.java:432) [bll.jar:] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.endSuccessfully(BaseImagesC<wbr>ommand.java:393) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.internalEndSuccessfull<wbr>y(CommandBase.java:751) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endActionInTransaction<wbr>Scope(CommandBase.java:709) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.runInTransaction(Comma<wbr>ndBase.java:1989) [bll.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInRequired(TransactionSu<wbr>pport.java:139) [utils.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInScope(TransactionSuppo<wbr>rt.java:105) [utils.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endAction(CommandBase.<wbr>java:574) [bll.jar:] at org.ovirt.engine.core.bll.Back<wbr>end.endAction(Backend.java:<wbr>536) [bll.jar:]</pre> </div> </div> </div> </blockquote> </div> </div> <div class="gmail_extra"><br> <div class="gmail_quote">On Thu, Nov 23, 2017 at 4:44 PM, Allon Mureinik <span dir="ltr"><<a href="mailto:amureini@redhat.com" target="_blank" moz-do-not-send="true">amureini@redhat.com</a>></span> wrote:<br> <blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"> <div dir="ltr"> <div class="gmail_default" style="font-family:monospace,monospace"><br> </div> <div class="gmail_quote">---------- Forwarded message ----------<br> From: <b class="gmail_sendername">Dafna Ron</b> <span dir="ltr"><<a href="mailto:dron@redhat.com" target="_blank" moz-do-not-send="true">dron@redhat.com</a>></span><br> Date: Thu, Nov 23, 2017 at 1:32 PM<br> Subject: Re: [ovirt-devel] [ OST Failure Report ] [ oVirt master ] [ 22-11-2017 ] [ 004_basic_sanity.verify_add_<wbr>vm_template ]<br> To: Yaniv Kaul <<a href="mailto:ykaul@redhat.com" target="_blank" moz-do-not-send="true">ykaul@redhat.com</a>>, Nir Soffer <<a href="mailto:nsoffer@redhat.com" target="_blank" moz-do-not-send="true">nsoffer@redhat.com</a>><br> Cc: aos-scalability <<a href="mailto:aos-scalability@redhat.com" target="_blank" moz-do-not-send="true">aos-scalability@redhat.com</a>>, devel <<a href="mailto:devel@ovirt.org" target="_blank" moz-do-not-send="true">devel@ovirt.org</a>>, infra <<a href="mailto:infra@ovirt.org" target="_blank" moz-do-not-send="true">infra@ovirt.org</a>><br> <br> <br> <div text="#000000" bgcolor="#FFFFFF"> <div class="m_-2904079716800439893m_7555078834308145571moz-cite-prefix">I opened a bug on the error: <a class="m_-2904079716800439893m_7555078834308145571moz-txt-link-freetext" href="https://bugzilla.redhat.com/show_bug.cgi?id=1516780" target="_blank" moz-do-not-send="true">https://bugzilla.redhat.com/sh<wbr>ow_bug.cgi?id=1516780</a><br> <br> 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. <br> <div> <div class="m_-2904079716800439893h5"> <br> On 11/22/2017 07:05 PM, Yaniv Kaul wrote:<br> </div> </div> </div> <div> <div class="m_-2904079716800439893h5"> <blockquote type="cite"> <div dir="ltr"><br> <div class="gmail_extra"><br> <div class="gmail_quote">On Wed, Nov 22, 2017 at 7:55 PM, Nir Soffer <span dir="ltr"><<a href="mailto:nsoffer@redhat.com" target="_blank" moz-do-not-send="true">nsoffer@redhat.com</a>></span> wrote:<br> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"><br> <br> <div class="gmail_quote"> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <div dir="ltr">On Wed, Nov 22, 2017 at 7:15 PM Dafna Ron <<a href="mailto:dron@redhat.com" target="_blank" moz-do-not-send="true">dron@redhat.com</a>> wrote:<br> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p>Hi, <br> </p> <p>we have a failure in 004_basic_sanity.verify_add_vm<wbr>_template. <br> </p> <p>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. <br> </p> <p><br> </p> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">Link and headline ofto suspected patches: </span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> core: Cleanup BaseImagesCommand code - <a class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286moz-txt-link-freetext" href="https://gerrit.ovirt.org/#/c/83812/" target="_blank" moz-do-not-send="true">https://gerrit.ovirt.org/#/c/8<wbr>3812/</a></b> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">Link to Job:</span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><a class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286moz-txt-link-freetext" href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989" target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job/o<wbr>virt-master_change-queue-teste<wbr>r/3989</a></b> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">Link to all logs:</span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><a class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286moz-txt-link-freetext" href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact" target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job/o<wbr>virt-master_change-queue-teste<wbr>r/3989/artifact</a></b></div> </blockquote> </div> </div> </div> </div> </blockquote> <div><br> </div> <div><br> </div> <div>Relevant logs start here - <a href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact/..." target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job<wbr>/ovirt-master_change-queue-tes<wbr>ter/3989/artifact/exported-art<wbr>ifacts/basic-suit-master-el7/<wbr>test_logs/basic-suite-master/<wbr>post-004_basic_sanity.py/</a></div> <div><br> </div> <div>Specifically, server.log (<a href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact/..." target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job/<wbr>ovirt-master_change-queue-test<wbr>er/3989/artifact/exported-arti<wbr>facts/basic-suit-master-el7/<wbr>test_logs/basic-suite-master/<wbr>post-004_basic_sanity.py/lago-<wbr>basic-suite-master-engine/_<wbr>var_log/ovirt-engine/server.<wbr>log</a> ):</div> <div><br> </div> <div> <div>2017-11-22 10:40:14,334-05 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-29) WFLYEJB0034: EJB Invocation failed on component Backend for method public abstract org.ovirt.engine.core.common.a<wbr>ction.ActionReturnValue org.ovirt.engine.core.bll.inte<wbr>rfaces.BackendInternal.endActi<wbr>on(org.ovirt.engine.core.<wbr>common.action.ActionType,org.<wbr>ovirt.engine.core.common.actio<wbr>n.ActionParametersBase,org.<wbr>ovirt.engine.core.bll.context.<wbr>CommandContext): javax.ejb.EJBTransactionRolled<wbr>backException</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.handleInCallerTx(CMTTx<wbr>Interceptor.java:160) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.invokeInCallerTx(CMTTx<wbr>Interceptor.java:257) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.supports(CMTTxIntercep<wbr>tor.java:381) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.processInvocation(CMTT<wbr>xInterceptor.java:244) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext$Invocation.proceed(<wbr>InterceptorContext.java:509)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.weld.ejb.AbstractEJB<wbr>RequestScopeActivationIntercep<wbr>tor.aroundInvoke(AbstractEJBRe<wbr>questScopeActivationIntercepto<wbr>r.java:73) [weld-core-impl-2.4.3.Final.ja<wbr>r:2.4.3.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.weld.ejb.EjbReque<wbr>stScopeActivationInterceptor.<wbr>processInvocation(EjbRequestSc<wbr>opeActivationInterceptor.java:<wbr>89)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at <a href="http://org.jboss.as.ejb3.component.in" moz-do-not-send="true">org.jboss.as.ejb3.component.in</a><wbr>terceptors.CurrentInvocationCo<wbr>ntextInterceptor.<wbr>processInvocation(CurrentInvoc<wbr>ationContextInterceptor.java:<wbr>41) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at <a href="http://org.jboss.as.ejb3.component.in" moz-do-not-send="true">org.jboss.as.ejb3.component.in</a><wbr>vocationmetrics.WaitTimeInterc<wbr>eptor.processInvocation(WaitTi<wbr>meInterceptor.java:47) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.security.Sec<wbr>urityContextInterceptor.proces<wbr>sInvocation(SecurityContextInt<wbr>erceptor.java:100) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.deployment.p<wbr>rocessors.StartupAwaitIntercep<wbr>tor.processInvocation(StartupA<wbr>waitInterceptor.java:22) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> </div> <div><br> </div> <div>...</div> <div> <pre style="color:rgb(0,0,0)">Caused by: java.lang.NullPointerException at java.util.Objects.requireNonNu<wbr>ll(Objects.java:203) [rt.jar:1.8.0_151] at java.util.Optional.<init>(Opti<wbr>onal.java:96) [rt.jar:1.8.0_151] at java.util.Optional.of(Optional<wbr>.java:108) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>193) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>190) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindO<wbr>p.evaluateSequential(FindOps.<wbr>java:152) [rt.jar:1.8.0_151] at java.util.stream.AbstractPipel<wbr>ine.evaluate(AbstractPipeline.<wbr>java:234) [rt.jar:1.8.0_151] at java.util.stream.ReferencePipe<wbr>line.findFirst(ReferencePipeli<wbr>ne.java:464) [rt.jar:1.8.0_151] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.setQcowCompatByQemuImageInf<wbr>o(BaseImagesCommand.java:432) [bll.jar:] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.endSuccessfully(BaseImagesC<wbr>ommand.java:393) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.internalEndSuccessfull<wbr>y(CommandBase.java:751) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endActionInTransaction<wbr>Scope(CommandBase.java:709) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.runInTransaction(Comma<wbr>ndBase.java:1989) [bll.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInRequired(TransactionSu<wbr>pport.java:139) [utils.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInScope(TransactionSuppo<wbr>rt.java:105) [utils.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endAction(CommandBase.<wbr>java:574) [bll.jar:] at org.ovirt.engine.core.bll.Back<wbr>end.endAction(Backend.java:<wbr>536) [bll.jar:]</pre> <pre style="color:rgb(0,0,0)">Y.</pre> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"> <div class="gmail_quote"> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">(Relevant) error snippet from the log: </span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"><error></span></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> </b><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">lago log: </span></p> </b></div> </blockquote> </div> </div> </div> </div> </blockquote> <div><br> </div> <div> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"> <div class="gmail_quote"> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><br> </p> </b> <pre style="box-sizing:border-box;white-space:pre-wrap;word-wrap:break-word;margin:0px;color:rgb(51,51,51);font-size:14px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:normal;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;word-spacing:0px;text-decoration-style:initial;text-decoration-color:initial"> File "/usr/lib64/python2.7/unittest<wbr>/case.py", line 369, in run testMethod() File "/usr/lib/python2.7/site-packa<wbr>ges/nose/case.py", line 197, in runTest self.test(*self.arg) File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 129, in wrapped_test test() File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 59, in wrapper return func(get_test_prefix(), *args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 68, in wrapper return func(prefix.virt_env.engine_vm<wbr>().get_api(), *args, **kwargs) File "/home/jenkins/workspace/ovirt<wbr>-master_change-queue-tester/ov<wbr>irt-system-tests/basic-suite-<wbr>master/test-scenarios/004_<wbr>basic_sanity.py", line 500, in verify_add_vm_template lambda: api.vms.get(VM1_NAME).status.s<wbr>tate == 'down', File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 271, in assert_true_within_long assert_equals_within_long(func<wbr>, True, allowed_exceptions) File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 258, in assert_equals_within_long func, value, LONG_TIMEOUT, allowed_exceptions=allowed_exc<wbr>eptions File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 219, in assert_equals_within res = func() File "/home/jenkins/workspace/ovirt<wbr>-master_change-queue-tester/ov<wbr>irt-system-tests/basic-suite-<wbr>master/test-scenarios/004_<wbr>basic_sanity.py", line 500, in <lambda> lambda: api.vms.get(VM1_NAME).status.s<wbr>tate == 'down', '\'NoneType\' object has no attribute \'status\'\n------------------<wbr>-- >> begin captured logging << --------------------\novirtlag<wbr>o.testlib: ERROR: * Unhandled exception in <function <lambda> at 0x4bafb90>\nTraceback (most recent call last):\n File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 219, in assert_equals_within\n res = func()\n File "/home/jenkins/workspace/ovirt<wbr>-master_change-queue-tester/ov<wbr>irt-system-tests/basic-suite-<wbr>master/test-scenarios/004_<wbr>basic_sanity.py", line 500, in <lambda>\n lambda: api.vms.get(VM1_NAME).status.s<wbr>tate == \'down\',\nAttributeError: \'NoneType\' object has no attribute \'status\'\n------------------<wbr>--- >> end captured logging << ---------------------'</pre> </div> </blockquote> <div><br> </div> </div> </div> <div>This is a test error - code like this is always wrong:</div> <div><br> </div> <div> api.vms.get(VM1_NAME).status.s<wbr>tate == something</div> <div><br> </div> <div>In this case, api.vms.get() returned None. The test code</div> <div>should handle None and fail with meaningfull error, or maybe</div> <div>retry the call.<br> </div> </div> </div> </blockquote> <div><br> </div> <div>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. </div> <div>Gracefully with 'VM1_NAME was not found' ? Perhaps.</div> <div> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"> <div class="gmail_quote"> <div> <br> </div> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p><span style="font-weight:normal">engine log: </span><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><b><br> </b></b></p> <pre style="color:rgb(0,0,0);font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:normal;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;word-spacing:0px;text-decoration-style:initial;text-decoration-color:initial">{"jsonrpc": "2.0", "id": "32bfeb29-e70f-48b2-84c7-91cf2<wbr>2ea408c", "result": {"status": "OK", "domain": "2d776fb7-eba8-4ee2-97b6-4350c<wbr>28ddb39", "voltype": "LEAF", "description": "", "parent": "a1192fcc-4660-41a7-a1a5-a2218<wbr>08f603b", "format": "COW", "generation": 0, "image": "dc033235-ab4b-4ef0-be79-6e8a2<wbr>2bfb0bc", "ctime": "1511365200", "disktype": "DATA", "legality": "LEGAL", "mtime": "0", "apparentsize": "1073741824", "children": [], "pool": "", "capacity": "41126400", "uuid": "6a354b93-86af-41fb-a68b-10897<wbr>ae3562f", "truesize": "1073741824", "type": "SPARSE", "lease": {"owners": [], "version": null}}}� 2017-11-22 10:40:39,454-05 DEBUG [org.ovirt.vdsm.jsonrpc.client<wbr>.internal.ResponseWorker] (ResponseWorker) [] Message received: {"jsonrpc": "2.0", "id": "32bfeb29-e70f-48b2-84c7-91cf2<wbr>2ea408c", "result": {"status": "OK", "domain": "2d776fb7-eba8-4ee2-97b6-4350c<wbr>28ddb39", "voltype": "LEAF", "description": "", "parent": "a1192fcc-4660-41a7-a1a5-a2218<wbr>08f603b", "format": "COW", "generation": 0, "image": "dc033235-ab4b-4ef0-be79-6e8a2<wbr>2bfb0bc", "ctime": "1511365200", "disktype": "DATA", "legality": "LEGAL", "mtime": "0", "apparentsize": "1073741824", "children": [], "pool": "", "capacity": "41126400", "uuid": "6a354b93-86af-41fb-a68b-10897<wbr>ae3562f", "truesize": "1073741824", "type": "SPARSE", "lease": {"owners": [], "version": null}}} 2017-11-22 10:40:39,454-05 INFO [org.ovirt.engine.core.vdsbrok<wbr>er.vdsbroker.GetVolumeInfoVDSC<wbr>ommand] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] FINISH, GetVolumeInfoVDSCommand, return: org.ovirt.engine.core.common.b<wbr>usinessentities.storage.DiskIm<wbr>age@6903fdd6, log id: 85b379d 2017-11-22 10:40:39,455-05 INFO [org.ovirt.engine.core.vdsbrok<wbr>er.irsbroker.GetImageInfoVDSCo<wbr>mmand] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.b<wbr>usinessentities.storage.DiskIm<wbr>age@6903fdd6, log id: 75d29166 2017-11-22 10:40:39,455-05 DEBUG [org.ovirt.engine.core.common.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] method: runVdsCommand, params: [GetImageInfo, GetImageInfoVDSCommandParamete<wbr>rs:{storagePoolId='0762073b-b0<wbr>ab-4ee2-8af9-dafa930a5fd4', ignoreFailoverLimit='false', storageDomainId='2d776fb7-eba8<wbr>-4ee2-97b6-4350c28ddb39', imageGroupId='dc033235-ab4b-4e<wbr>f0-be79-6e8a22bfb0bc', imageId='6a354b93-86af-41fb-a6<wbr>8b-10897ae3562f'}], timeElapsed: 165ms 2017-11-22 10:40:39,528-05 DEBUG [org.ovirt.engine.core.common.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] method: getVmsWithPlugInfo, params: [dc033235-ab4b-4ef0-be79-6e8a2<wbr>2bfb0bc], timeElapsed: 68ms 2017-11-22 10:40:39,543-05 INFO [org.ovirt.engine.core.utils.t<wbr>ransaction.TransactionSupport] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] transaction rolled back 2017-11-22 10:40:39,543-05 WARN [org.ovirt.engine.core.bll.loc<wbr>k.InMemoryLockManager] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Trying to release a shared lock for key: '93d271d5-e0af-4795-b800-55465<wbr>c7b8826TEMPLATE' , but lock does not exist 2017-11-22 10:40:39,543-05 WARN [org.ovirt.engine.core.bll.loc<wbr>k.InMemoryLockManager] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Trying to release a shared lock for key: 'fb76119e-9283-4c8b-9185-5d79e<wbr>2481bc7DISK' , but lock does not exist 2017-11-22 10:40:39,543-05 WARN [org.ovirt.engine.core.bll.loc<wbr>k.InMemoryLockManager] (EE-ManagedThreadFactory-engin<wbr>eScheduled-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.Add<wbr>VmCommand] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Lock freed to object 'EngineLock:{exclusiveLocks='[<wbr>vm1=VM_NAME]', sharedLocks='[93d271d5-e0af-47<wbr>95-b800-55465c7b8826=TEMPLATE, fb76119e-9283-4c8b-9185-5d79e2<wbr>481bc7=DISK]'}' 2017-11-22 10:40:39,556-05 ERROR [org.ovirt.engine.core.dal.dbb<wbr>roker.auditloghandling.AuditLo<wbr>gDirector] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(6<wbr>0), Failed to complete VM vm1 creation. 2017-11-22 10:40:39,556-05 ERROR [org.ovirt.engine.core.bll.tas<wbr>ks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Failed invoking callback end method 'onSucceeded' for command '2760a62f-e4ee-4dd2-b13a-1bb54<wbr>8e3e62d' 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.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-35) [] method: get, params: [d25423f6-34bc-4cde-82fa-c0eed<wbr>fc85386], timeElapsed: 3ms 2017-11-22 10:40:39,949-05 DEBUG [org.ovirt.engine.core.common.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-71) [] method: get, params: [7c9ec3eb-2838-4b06-9408-326b6<wbr>7869bdc], timeElapsed: 2ms 2017-11-22 10:40:40,606-05 DEBUG [org.ovirt.engine.core.aaa.fil<wbr>ters.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<wbr>-de465aa55eee') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "<string>", line 2, in getAllTasksInfo File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/hsm.py", line 2216, in getAllTasksInfo allTasksInfo = self._pool.getAllTasksInfo() File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/securable.py"<wbr>, 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<wbr>-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-packa<wbr>ges/vdsm/storage/dispatcher.py<wbr>", line 73, in wrapper result = ctask.prepare(func, *args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 108, in wrapper return m(self, *a, **kw) File "/usr/lib/python2.7/site-packa<wbr>ges/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=Non<wbr>e, options=None) from=::1,52728, task_id=172b5528-cc76-426a-81d<wbr>3-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-81d<wbr>3-43143b49a878 (api:50)</pre> </div> </blockquote> <div><br> </div> </div> </div> <div>This is <a href="https://bugzilla.redhat.com/1426429" target="_blank" moz-do-not-send="true">https://bugzilla.redhat.com<wbr>/1426429</a><br> </div> <div><br> </div> <div>Not related to the real error.</div> <span class="m_-2904079716800439893m_7555078834308145571gmail-"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <pre style="color:rgb(0,0,0);font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:normal;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;word-spacing:0px;text-decoration-style:initial;text-decoration-color:initial">2017-11-22 10:36:11,980-0500 ERROR (jsonrpc/2) [storage.TaskManager.Task] (Task='172b5528-cc76-426a-81d3<wbr>-43143b49a878') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "<string>", line 2, in getAllTasksStatuses File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/hsm.py", line 2176, in getAllTasksStatuses allTasksStatus = self._pool.getAllTasksStatuses<wbr>() File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/securable.py"<wbr>, 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<wbr>-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-packa<wbr>ges/vdsm/storage/dispatcher.py<wbr>", line 73, in wrapper result = ctask.prepare(func, *args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 108, in wrapper return m(self, *a, **kw) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 1189, in prepare raise self.error SecureError: Secured object is not in safe state</pre> </div> </blockquote> <div><br> </div> </span> <div>The way to find the relevant errors is to find the entry point of this flow</div> <div>in engine.log, and then follow this in vdsm.log using flow_id=xxx.</div> <div><br> </div> <div>Ideally we would send a uuid to engine for every operation, and be</div> <div>able to query the operation status using the uuid. This is the way</div> <div>storage jobs are managed in vdsm side since 4.1.</div> <div><br> </div> <div>If we had this every test would generate a uuids and debugging</div> <div>failing test would be much faster.</div> <div><br> </div> <div>Nir</div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> <br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"></error></span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> </b><br class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286Apple-interchange-newline"> <p><br> </p> </div> ______________________________<wbr>_________________<br> Devel mailing list<br> <a href="mailto:Devel@ovirt.org" target="_blank" moz-do-not-send="true">Devel@ovirt.org</a><br> <a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank" moz-do-not-send="true">http://lists.ovirt.org/mailman<wbr>/listinfo/devel</a></blockquote> </div> </div> <br> ______________________________<wbr>_________________<br> Devel mailing list<br> <a href="mailto:Devel@ovirt.org" target="_blank" moz-do-not-send="true">Devel@ovirt.org</a><br> <a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank" moz-do-not-send="true">http://lists.ovirt.org/mailman<wbr>/listinfo/devel</a><br> </blockquote> </div> <br> </div> </div> </blockquote> <p><br> </p> </div> </div> </div> <br> ______________________________<wbr>_________________<br> Infra mailing list<br> <a href="mailto:Infra@ovirt.org" target="_blank" moz-do-not-send="true">Infra@ovirt.org</a><br> <a href="http://lists.ovirt.org/mailman/listinfo/infra" rel="noreferrer" target="_blank" moz-do-not-send="true">http://lists.ovirt.org/mailman<wbr>/listinfo/infra</a><br> <br> </div> <br> </div> </blockquote> </div> <br> </div> <br> <fieldset class="mimeAttachmentHeader"></fieldset> <br> <pre wrap="">_______________________________________________ Devel mailing list <a class="moz-txt-link-abbreviated" href="mailto:Devel@ovirt.org">Devel@ovirt.org</a> <a class="moz-txt-link-freetext" href="http://lists.ovirt.org/mailman/listinfo/devel">http://lists.ovirt.org/mailman/listinfo/devel</a></pre> </blockquote> <p><br> </p> </body> </html> --------------0CF18CB787489ACBA8882429--
This is a multi-part message in MIME format. --------------967A64E08672635C5E52BC0D Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit I am still seeing an exception in latest failure: http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4064/artifact/... 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 <amureini@redhat.com <mailto:amureini@redhat.com>> wrote:
---------- Forwarded message ---------- From: *Dafna Ron* <dron@redhat.com <mailto:dron@redhat.com>> 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 <ykaul@redhat.com <mailto:ykaul@redhat.com>>, Nir Soffer <nsoffer@redhat.com <mailto:nsoffer@redhat.com>> Cc: aos-scalability <aos-scalability@redhat.com <mailto:aos-scalability@redhat.com>>, devel <devel@ovirt.org <mailto:devel@ovirt.org>>, infra <infra@ovirt.org <mailto:infra@ovirt.org>>
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 <nsoffer@redhat.com <mailto:nsoffer@redhat.com>> wrote:
On Wed, Nov 22, 2017 at 7:15 PM Dafna Ron <dron@redhat.com <mailto:dron@redhat.com>> 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/... <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/... <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 Devel@ovirt.org <mailto:Devel@ovirt.org> http://lists.ovirt.org/mailman/listinfo/devel <http://lists.ovirt.org/mailman/listinfo/devel>
_______________________________________________ Devel mailing list Devel@ovirt.org <mailto:Devel@ovirt.org> http://lists.ovirt.org/mailman/listinfo/devel <http://lists.ovirt.org/mailman/listinfo/devel>
_______________________________________________ Infra mailing list Infra@ovirt.org <mailto:Infra@ovirt.org> http://lists.ovirt.org/mailman/listinfo/infra <http://lists.ovirt.org/mailman/listinfo/infra>
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
--------------967A64E08672635C5E52BC0D Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 8bit <html> <head> <meta http-equiv="Content-Type" content="text/html; charset=utf-8"> </head> <body text="#000000" bgcolor="#FFFFFF"> <div class="moz-cite-prefix">I am still seeing an exception in latest failure: <br> <br> <a class="moz-txt-link-freetext" href="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">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</a><br> <br> <br> 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.<br> 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<br> 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.<br> 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<br> -d4591ca751c1'<br> 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<br> at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleInCallerTx(CMTTxInterceptor.java:160) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final]<br> at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:257) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final]<br> at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:381) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final]<br> at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:244) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final]<br> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)<br> at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)<br> at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73) [weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br> ]<br> :<br> <br> <br> On 11/23/2017 06:04 PM, Dafna Ron wrote:<br> </div> <blockquote type="cite" cite="mid:cdcc6aa6-ea6b-2e9c-c7df-be1db8844598@redhat.com"> <meta http-equiv="Content-Type" content="text/html; charset=utf-8"> <div class="moz-cite-prefix">Thanks, <br> 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. <br> <br> On 11/23/2017 02:49 PM, Ala Hino wrote:<br> </div> <blockquote type="cite" cite="mid:CAPuOgO33Wz53x__X016+rhzh1i7w-TemOn0i7N8z6-BkhSmJDQ@mail.gmail.com"> <div dir="ltr">Fix (cf502720b4cf7bc09694ee0821f3e7f73d6e6e0f) to the following exception just merged: <div><br> </div> <div> <blockquote type="cite" style="font-size:12.8px"> <div dir="ltr"> <div class="gmail_extra"> <div class="gmail_quote"> <pre style="white-space:pre-wrap">Caused by: java.lang.NullPointerException at java.util.Objects.requireNonNu<wbr>ll(Objects.java:203) [rt.jar:1.8.0_151] at java.util.Optional.<init>(Opti<wbr>onal.java:96) [rt.jar:1.8.0_151] at java.util.Optional.of(Optional<wbr>.java:108) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>193) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>190) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindO<wbr>p.evaluateSequential(FindOps.<wbr>java:152) [rt.jar:1.8.0_151] at java.util.stream.AbstractPipel<wbr>ine.evaluate(AbstractPipeline.<wbr>java:234) [rt.jar:1.8.0_151] at java.util.stream.ReferencePipe<wbr>line.findFirst(ReferencePipeli<wbr>ne.java:464) [rt.jar:1.8.0_151] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.setQcowCompatByQemuImageInf<wbr>o(BaseImagesCommand.java:432) [bll.jar:] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.endSuccessfully(BaseImagesC<wbr>ommand.java:393) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.internalEndSuccessfull<wbr>y(CommandBase.java:751) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endActionInTransaction<wbr>Scope(CommandBase.java:709) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.runInTransaction(Comma<wbr>ndBase.java:1989) [bll.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInRequired(TransactionSu<wbr>pport.java:139) [utils.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInScope(TransactionSuppo<wbr>rt.java:105) [utils.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endAction(CommandBase.<wbr>java:574) [bll.jar:] at org.ovirt.engine.core.bll.Back<wbr>end.endAction(Backend.java:<wbr>536) [bll.jar:]</pre> </div> </div> </div> </blockquote> </div> </div> <div class="gmail_extra"><br> <div class="gmail_quote">On Thu, Nov 23, 2017 at 4:44 PM, Allon Mureinik <span dir="ltr"><<a href="mailto:amureini@redhat.com" target="_blank" moz-do-not-send="true">amureini@redhat.com</a>></span> wrote:<br> <blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"> <div dir="ltr"> <div class="gmail_default" style="font-family:monospace,monospace"><br> </div> <div class="gmail_quote">---------- Forwarded message ----------<br> From: <b class="gmail_sendername">Dafna Ron</b> <span dir="ltr"><<a href="mailto:dron@redhat.com" target="_blank" moz-do-not-send="true">dron@redhat.com</a>></span><br> Date: Thu, Nov 23, 2017 at 1:32 PM<br> Subject: Re: [ovirt-devel] [ OST Failure Report ] [ oVirt master ] [ 22-11-2017 ] [ 004_basic_sanity.verify_add_<wbr>vm_template ]<br> To: Yaniv Kaul <<a href="mailto:ykaul@redhat.com" target="_blank" moz-do-not-send="true">ykaul@redhat.com</a>>, Nir Soffer <<a href="mailto:nsoffer@redhat.com" target="_blank" moz-do-not-send="true">nsoffer@redhat.com</a>><br> Cc: aos-scalability <<a href="mailto:aos-scalability@redhat.com" target="_blank" moz-do-not-send="true">aos-scalability@redhat.com</a>>, devel <<a href="mailto:devel@ovirt.org" target="_blank" moz-do-not-send="true">devel@ovirt.org</a>>, infra <<a href="mailto:infra@ovirt.org" target="_blank" moz-do-not-send="true">infra@ovirt.org</a>><br> <br> <br> <div text="#000000" bgcolor="#FFFFFF"> <div class="m_-2904079716800439893m_7555078834308145571moz-cite-prefix">I opened a bug on the error: <a class="m_-2904079716800439893m_7555078834308145571moz-txt-link-freetext" href="https://bugzilla.redhat.com/show_bug.cgi?id=1516780" target="_blank" moz-do-not-send="true">https://bugzilla.redhat.com/sh<wbr>ow_bug.cgi?id=1516780</a><br> <br> 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. <br> <div> <div class="m_-2904079716800439893h5"> <br> On 11/22/2017 07:05 PM, Yaniv Kaul wrote:<br> </div> </div> </div> <div> <div class="m_-2904079716800439893h5"> <blockquote type="cite"> <div dir="ltr"><br> <div class="gmail_extra"><br> <div class="gmail_quote">On Wed, Nov 22, 2017 at 7:55 PM, Nir Soffer <span dir="ltr"><<a href="mailto:nsoffer@redhat.com" target="_blank" moz-do-not-send="true">nsoffer@redhat.com</a>></span> wrote:<br> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"><br> <br> <div class="gmail_quote"> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <div dir="ltr">On Wed, Nov 22, 2017 at 7:15 PM Dafna Ron <<a href="mailto:dron@redhat.com" target="_blank" moz-do-not-send="true">dron@redhat.com</a>> wrote:<br> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p>Hi, <br> </p> <p>we have a failure in 004_basic_sanity.verify_add_vm<wbr>_template. <br> </p> <p>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. <br> </p> <p><br> </p> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">Link and headline ofto suspected patches: </span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> core: Cleanup BaseImagesCommand code - <a class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286moz-txt-link-freetext" href="https://gerrit.ovirt.org/#/c/83812/" target="_blank" moz-do-not-send="true">https://gerrit.ovirt.org/#/c/8<wbr>3812/</a></b> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">Link to Job:</span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><a class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286moz-txt-link-freetext" href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989" target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job/o<wbr>virt-master_change-queue-teste<wbr>r/3989</a></b> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">Link to all logs:</span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><a class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286moz-txt-link-freetext" href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact" target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job/o<wbr>virt-master_change-queue-teste<wbr>r/3989/artifact</a></b></div> </blockquote> </div> </div> </div> </div> </blockquote> <div><br> </div> <div><br> </div> <div>Relevant logs start here - <a href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact/..." target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job<wbr>/ovirt-master_change-queue-tes<wbr>ter/3989/artifact/exported-art<wbr>ifacts/basic-suit-master-el7/<wbr>test_logs/basic-suite-master/<wbr>post-004_basic_sanity.py/</a></div> <div><br> </div> <div>Specifically, server.log (<a href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact/..." target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job/<wbr>ovirt-master_change-queue-test<wbr>er/3989/artifact/exported-arti<wbr>facts/basic-suit-master-el7/<wbr>test_logs/basic-suite-master/<wbr>post-004_basic_sanity.py/lago-<wbr>basic-suite-master-engine/_<wbr>var_log/ovirt-engine/server.<wbr>log</a> ):</div> <div><br> </div> <div> <div>2017-11-22 10:40:14,334-05 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-29) WFLYEJB0034: EJB Invocation failed on component Backend for method public abstract org.ovirt.engine.core.common.a<wbr>ction.ActionReturnValue org.ovirt.engine.core.bll.inte<wbr>rfaces.BackendInternal.endActi<wbr>on(org.ovirt.engine.core.<wbr>common.action.ActionType,org.<wbr>ovirt.engine.core.common.actio<wbr>n.ActionParametersBase,org.<wbr>ovirt.engine.core.bll.context.<wbr>CommandContext): javax.ejb.EJBTransactionRolled<wbr>backException</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.handleInCallerTx(CMTTx<wbr>Interceptor.java:160) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.invokeInCallerTx(CMTTx<wbr>Interceptor.java:257) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.supports(CMTTxIntercep<wbr>tor.java:381) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.processInvocation(CMTT<wbr>xInterceptor.java:244) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext$Invocation.proceed(<wbr>InterceptorContext.java:509)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.weld.ejb.AbstractEJB<wbr>RequestScopeActivationIntercep<wbr>tor.aroundInvoke(AbstractEJBRe<wbr>questScopeActivationIntercepto<wbr>r.java:73) [weld-core-impl-2.4.3.Final.ja<wbr>r:2.4.3.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.weld.ejb.EjbReque<wbr>stScopeActivationInterceptor.<wbr>processInvocation(EjbRequestSc<wbr>opeActivationInterceptor.java:<wbr>89)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at <a href="http://org.jboss.as.ejb3.component.in" moz-do-not-send="true">org.jboss.as.ejb3.component.in</a><wbr>terceptors.CurrentInvocationCo<wbr>ntextInterceptor.<wbr>processInvocation(CurrentInvoc<wbr>ationContextInterceptor.java:<wbr>41) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at <a href="http://org.jboss.as.ejb3.component.in" moz-do-not-send="true">org.jboss.as.ejb3.component.in</a><wbr>vocationmetrics.WaitTimeInterc<wbr>eptor.processInvocation(WaitTi<wbr>meInterceptor.java:47) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.security.Sec<wbr>urityContextInterceptor.proces<wbr>sInvocation(SecurityContextInt<wbr>erceptor.java:100) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.deployment.p<wbr>rocessors.StartupAwaitIntercep<wbr>tor.processInvocation(StartupA<wbr>waitInterceptor.java:22) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> </div> <div><br> </div> <div>...</div> <div> <pre style="color:rgb(0,0,0)">Caused by: java.lang.NullPointerException at java.util.Objects.requireNonNu<wbr>ll(Objects.java:203) [rt.jar:1.8.0_151] at java.util.Optional.<init>(Opti<wbr>onal.java:96) [rt.jar:1.8.0_151] at java.util.Optional.of(Optional<wbr>.java:108) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>193) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>190) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindO<wbr>p.evaluateSequential(FindOps.<wbr>java:152) [rt.jar:1.8.0_151] at java.util.stream.AbstractPipel<wbr>ine.evaluate(AbstractPipeline.<wbr>java:234) [rt.jar:1.8.0_151] at java.util.stream.ReferencePipe<wbr>line.findFirst(ReferencePipeli<wbr>ne.java:464) [rt.jar:1.8.0_151] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.setQcowCompatByQemuImageInf<wbr>o(BaseImagesCommand.java:432) [bll.jar:] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.endSuccessfully(BaseImagesC<wbr>ommand.java:393) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.internalEndSuccessfull<wbr>y(CommandBase.java:751) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endActionInTransaction<wbr>Scope(CommandBase.java:709) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.runInTransaction(Comma<wbr>ndBase.java:1989) [bll.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInRequired(TransactionSu<wbr>pport.java:139) [utils.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInScope(TransactionSuppo<wbr>rt.java:105) [utils.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endAction(CommandBase.<wbr>java:574) [bll.jar:] at org.ovirt.engine.core.bll.Back<wbr>end.endAction(Backend.java:<wbr>536) [bll.jar:]</pre> <pre style="color:rgb(0,0,0)">Y.</pre> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"> <div class="gmail_quote"> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">(Relevant) error snippet from the log: </span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"><error></span></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> </b><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">lago log: </span></p> </b></div> </blockquote> </div> </div> </div> </div> </blockquote> <div><br> </div> <div> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"> <div class="gmail_quote"> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><br> </p> </b> <pre style="box-sizing:border-box;white-space:pre-wrap;word-wrap:break-word;margin:0px;color:rgb(51,51,51);font-size:14px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:normal;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;word-spacing:0px;text-decoration-style:initial;text-decoration-color:initial"> File "/usr/lib64/python2.7/unittest<wbr>/case.py", line 369, in run testMethod() File "/usr/lib/python2.7/site-packa<wbr>ges/nose/case.py", line 197, in runTest self.test(*self.arg) File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 129, in wrapped_test test() File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 59, in wrapper return func(get_test_prefix(), *args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 68, in wrapper return func(prefix.virt_env.engine_vm<wbr>().get_api(), *args, **kwargs) File "/home/jenkins/workspace/ovirt<wbr>-master_change-queue-tester/ov<wbr>irt-system-tests/basic-suite-<wbr>master/test-scenarios/004_<wbr>basic_sanity.py", line 500, in verify_add_vm_template lambda: api.vms.get(VM1_NAME).status.s<wbr>tate == 'down', File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 271, in assert_true_within_long assert_equals_within_long(func<wbr>, True, allowed_exceptions) File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 258, in assert_equals_within_long func, value, LONG_TIMEOUT, allowed_exceptions=allowed_exc<wbr>eptions File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 219, in assert_equals_within res = func() File "/home/jenkins/workspace/ovirt<wbr>-master_change-queue-tester/ov<wbr>irt-system-tests/basic-suite-<wbr>master/test-scenarios/004_<wbr>basic_sanity.py", line 500, in <lambda> lambda: api.vms.get(VM1_NAME).status.s<wbr>tate == 'down', '\'NoneType\' object has no attribute \'status\'\n------------------<wbr>-- >> begin captured logging << --------------------\novirtlag<wbr>o.testlib: ERROR: * Unhandled exception in <function <lambda> at 0x4bafb90>\nTraceback (most recent call last):\n File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 219, in assert_equals_within\n res = func()\n File "/home/jenkins/workspace/ovirt<wbr>-master_change-queue-tester/ov<wbr>irt-system-tests/basic-suite-<wbr>master/test-scenarios/004_<wbr>basic_sanity.py", line 500, in <lambda>\n lambda: api.vms.get(VM1_NAME).status.s<wbr>tate == \'down\',\nAttributeError: \'NoneType\' object has no attribute \'status\'\n------------------<wbr>--- >> end captured logging << ---------------------'</pre> </div> </blockquote> <div><br> </div> </div> </div> <div>This is a test error - code like this is always wrong:</div> <div><br> </div> <div> api.vms.get(VM1_NAME).status.s<wbr>tate == something</div> <div><br> </div> <div>In this case, api.vms.get() returned None. The test code</div> <div>should handle None and fail with meaningfull error, or maybe</div> <div>retry the call.<br> </div> </div> </div> </blockquote> <div><br> </div> <div>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. </div> <div>Gracefully with 'VM1_NAME was not found' ? Perhaps.</div> <div> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"> <div class="gmail_quote"> <div> <br> </div> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p><span style="font-weight:normal">engine log: </span><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><b><br> </b></b></p> <pre style="color:rgb(0,0,0);font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:normal;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;word-spacing:0px;text-decoration-style:initial;text-decoration-color:initial">{"jsonrpc": "2.0", "id": "32bfeb29-e70f-48b2-84c7-91cf2<wbr>2ea408c", "result": {"status": "OK", "domain": "2d776fb7-eba8-4ee2-97b6-4350c<wbr>28ddb39", "voltype": "LEAF", "description": "", "parent": "a1192fcc-4660-41a7-a1a5-a2218<wbr>08f603b", "format": "COW", "generation": 0, "image": "dc033235-ab4b-4ef0-be79-6e8a2<wbr>2bfb0bc", "ctime": "1511365200", "disktype": "DATA", "legality": "LEGAL", "mtime": "0", "apparentsize": "1073741824", "children": [], "pool": "", "capacity": "41126400", "uuid": "6a354b93-86af-41fb-a68b-10897<wbr>ae3562f", "truesize": "1073741824", "type": "SPARSE", "lease": {"owners": [], "version": null}}}� 2017-11-22 10:40:39,454-05 DEBUG [org.ovirt.vdsm.jsonrpc.client<wbr>.internal.ResponseWorker] (ResponseWorker) [] Message received: {"jsonrpc": "2.0", "id": "32bfeb29-e70f-48b2-84c7-91cf2<wbr>2ea408c", "result": {"status": "OK", "domain": "2d776fb7-eba8-4ee2-97b6-4350c<wbr>28ddb39", "voltype": "LEAF", "description": "", "parent": "a1192fcc-4660-41a7-a1a5-a2218<wbr>08f603b", "format": "COW", "generation": 0, "image": "dc033235-ab4b-4ef0-be79-6e8a2<wbr>2bfb0bc", "ctime": "1511365200", "disktype": "DATA", "legality": "LEGAL", "mtime": "0", "apparentsize": "1073741824", "children": [], "pool": "", "capacity": "41126400", "uuid": "6a354b93-86af-41fb-a68b-10897<wbr>ae3562f", "truesize": "1073741824", "type": "SPARSE", "lease": {"owners": [], "version": null}}} 2017-11-22 10:40:39,454-05 INFO [org.ovirt.engine.core.vdsbrok<wbr>er.vdsbroker.GetVolumeInfoVDSC<wbr>ommand] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] FINISH, GetVolumeInfoVDSCommand, return: org.ovirt.engine.core.common.b<wbr>usinessentities.storage.DiskIm<wbr>age@6903fdd6, log id: 85b379d 2017-11-22 10:40:39,455-05 INFO [org.ovirt.engine.core.vdsbrok<wbr>er.irsbroker.GetImageInfoVDSCo<wbr>mmand] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.b<wbr>usinessentities.storage.DiskIm<wbr>age@6903fdd6, log id: 75d29166 2017-11-22 10:40:39,455-05 DEBUG [org.ovirt.engine.core.common.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] method: runVdsCommand, params: [GetImageInfo, GetImageInfoVDSCommandParamete<wbr>rs:{storagePoolId='0762073b-b0<wbr>ab-4ee2-8af9-dafa930a5fd4', ignoreFailoverLimit='false', storageDomainId='2d776fb7-eba8<wbr>-4ee2-97b6-4350c28ddb39', imageGroupId='dc033235-ab4b-4e<wbr>f0-be79-6e8a22bfb0bc', imageId='6a354b93-86af-41fb-a6<wbr>8b-10897ae3562f'}], timeElapsed: 165ms 2017-11-22 10:40:39,528-05 DEBUG [org.ovirt.engine.core.common.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] method: getVmsWithPlugInfo, params: [dc033235-ab4b-4ef0-be79-6e8a2<wbr>2bfb0bc], timeElapsed: 68ms 2017-11-22 10:40:39,543-05 INFO [org.ovirt.engine.core.utils.t<wbr>ransaction.TransactionSupport] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] transaction rolled back 2017-11-22 10:40:39,543-05 WARN [org.ovirt.engine.core.bll.loc<wbr>k.InMemoryLockManager] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Trying to release a shared lock for key: '93d271d5-e0af-4795-b800-55465<wbr>c7b8826TEMPLATE' , but lock does not exist 2017-11-22 10:40:39,543-05 WARN [org.ovirt.engine.core.bll.loc<wbr>k.InMemoryLockManager] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Trying to release a shared lock for key: 'fb76119e-9283-4c8b-9185-5d79e<wbr>2481bc7DISK' , but lock does not exist 2017-11-22 10:40:39,543-05 WARN [org.ovirt.engine.core.bll.loc<wbr>k.InMemoryLockManager] (EE-ManagedThreadFactory-engin<wbr>eScheduled-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.Add<wbr>VmCommand] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Lock freed to object 'EngineLock:{exclusiveLocks='[<wbr>vm1=VM_NAME]', sharedLocks='[93d271d5-e0af-47<wbr>95-b800-55465c7b8826=TEMPLATE, fb76119e-9283-4c8b-9185-5d79e2<wbr>481bc7=DISK]'}' 2017-11-22 10:40:39,556-05 ERROR [org.ovirt.engine.core.dal.dbb<wbr>roker.auditloghandling.AuditLo<wbr>gDirector] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(6<wbr>0), Failed to complete VM vm1 creation. 2017-11-22 10:40:39,556-05 ERROR [org.ovirt.engine.core.bll.tas<wbr>ks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Failed invoking callback end method 'onSucceeded' for command '2760a62f-e4ee-4dd2-b13a-1bb54<wbr>8e3e62d' 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.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-35) [] method: get, params: [d25423f6-34bc-4cde-82fa-c0eed<wbr>fc85386], timeElapsed: 3ms 2017-11-22 10:40:39,949-05 DEBUG [org.ovirt.engine.core.common.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-71) [] method: get, params: [7c9ec3eb-2838-4b06-9408-326b6<wbr>7869bdc], timeElapsed: 2ms 2017-11-22 10:40:40,606-05 DEBUG [org.ovirt.engine.core.aaa.fil<wbr>ters.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<wbr>-de465aa55eee') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "<string>", line 2, in getAllTasksInfo File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/hsm.py", line 2216, in getAllTasksInfo allTasksInfo = self._pool.getAllTasksInfo() File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/securable.py"<wbr>, 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<wbr>-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-packa<wbr>ges/vdsm/storage/dispatcher.py<wbr>", line 73, in wrapper result = ctask.prepare(func, *args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 108, in wrapper return m(self, *a, **kw) File "/usr/lib/python2.7/site-packa<wbr>ges/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=Non<wbr>e, options=None) from=::1,52728, task_id=172b5528-cc76-426a-81d<wbr>3-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-81d<wbr>3-43143b49a878 (api:50)</pre> </div> </blockquote> <div><br> </div> </div> </div> <div>This is <a href="https://bugzilla.redhat.com/1426429" target="_blank" moz-do-not-send="true">https://bugzilla.redhat.com<wbr>/1426429</a><br> </div> <div><br> </div> <div>Not related to the real error.</div> <span class="m_-2904079716800439893m_7555078834308145571gmail-"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <pre style="color:rgb(0,0,0);font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:normal;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;word-spacing:0px;text-decoration-style:initial;text-decoration-color:initial">2017-11-22 10:36:11,980-0500 ERROR (jsonrpc/2) [storage.TaskManager.Task] (Task='172b5528-cc76-426a-81d3<wbr>-43143b49a878') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "<string>", line 2, in getAllTasksStatuses File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/hsm.py", line 2176, in getAllTasksStatuses allTasksStatus = self._pool.getAllTasksStatuses<wbr>() File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/securable.py"<wbr>, 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<wbr>-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-packa<wbr>ges/vdsm/storage/dispatcher.py<wbr>", line 73, in wrapper result = ctask.prepare(func, *args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 108, in wrapper return m(self, *a, **kw) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 1189, in prepare raise self.error SecureError: Secured object is not in safe state</pre> </div> </blockquote> <div><br> </div> </span> <div>The way to find the relevant errors is to find the entry point of this flow</div> <div>in engine.log, and then follow this in vdsm.log using flow_id=xxx.</div> <div><br> </div> <div>Ideally we would send a uuid to engine for every operation, and be</div> <div>able to query the operation status using the uuid. This is the way</div> <div>storage jobs are managed in vdsm side since 4.1.</div> <div><br> </div> <div>If we had this every test would generate a uuids and debugging</div> <div>failing test would be much faster.</div> <div><br> </div> <div>Nir</div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> <br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"></error></span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> </b><br class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286Apple-interchange-newline"> <p><br> </p> </div> ______________________________<wbr>_________________<br> Devel mailing list<br> <a href="mailto:Devel@ovirt.org" target="_blank" moz-do-not-send="true">Devel@ovirt.org</a><br> <a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank" moz-do-not-send="true">http://lists.ovirt.org/mailman<wbr>/listinfo/devel</a></blockquote> </div> </div> <br> ______________________________<wbr>_________________<br> Devel mailing list<br> <a href="mailto:Devel@ovirt.org" target="_blank" moz-do-not-send="true">Devel@ovirt.org</a><br> <a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank" moz-do-not-send="true">http://lists.ovirt.org/mailman<wbr>/listinfo/devel</a><br> </blockquote> </div> <br> </div> </div> </blockquote> <p><br> </p> </div> </div> </div> <br> ______________________________<wbr>_________________<br> Infra mailing list<br> <a href="mailto:Infra@ovirt.org" target="_blank" moz-do-not-send="true">Infra@ovirt.org</a><br> <a href="http://lists.ovirt.org/mailman/listinfo/infra" rel="noreferrer" target="_blank" moz-do-not-send="true">http://lists.ovirt.org/mailman<wbr>/listinfo/infra</a><br> <br> </div> <br> </div> </blockquote> </div> <br> </div> <br> <fieldset class="mimeAttachmentHeader"></fieldset> <br> <pre wrap="">_______________________________________________ Devel mailing list <a class="moz-txt-link-abbreviated" href="mailto:Devel@ovirt.org" moz-do-not-send="true">Devel@ovirt.org</a> <a class="moz-txt-link-freetext" href="http://lists.ovirt.org/mailman/listinfo/devel" moz-do-not-send="true">http://lists.ovirt.org/mailman/listinfo/devel</a></pre> </blockquote> <p><br> </p> <br> <fieldset class="mimeAttachmentHeader"></fieldset> <br> <pre wrap="">_______________________________________________ Devel mailing list <a class="moz-txt-link-abbreviated" href="mailto:Devel@ovirt.org">Devel@ovirt.org</a> <a class="moz-txt-link-freetext" href="http://lists.ovirt.org/mailman/listinfo/devel">http://lists.ovirt.org/mailman/listinfo/devel</a></pre> </blockquote> <p><br> </p> </body> </html> --------------967A64E08672635C5E52BC0D--
This is a multi-part message in MIME format. --------------5035A41E9AA9EE7C4328E562 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit 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/...
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 <amureini@redhat.com <mailto:amureini@redhat.com>> wrote:
---------- Forwarded message ---------- From: *Dafna Ron* <dron@redhat.com <mailto:dron@redhat.com>> 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 <ykaul@redhat.com <mailto:ykaul@redhat.com>>, Nir Soffer <nsoffer@redhat.com <mailto:nsoffer@redhat.com>> Cc: aos-scalability <aos-scalability@redhat.com <mailto:aos-scalability@redhat.com>>, devel <devel@ovirt.org <mailto:devel@ovirt.org>>, infra <infra@ovirt.org <mailto:infra@ovirt.org>>
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 <nsoffer@redhat.com <mailto:nsoffer@redhat.com>> wrote:
On Wed, Nov 22, 2017 at 7:15 PM Dafna Ron <dron@redhat.com <mailto:dron@redhat.com>> 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/... <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/... <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 Devel@ovirt.org <mailto:Devel@ovirt.org> http://lists.ovirt.org/mailman/listinfo/devel <http://lists.ovirt.org/mailman/listinfo/devel>
_______________________________________________ Devel mailing list Devel@ovirt.org <mailto:Devel@ovirt.org> http://lists.ovirt.org/mailman/listinfo/devel <http://lists.ovirt.org/mailman/listinfo/devel>
_______________________________________________ Infra mailing list Infra@ovirt.org <mailto:Infra@ovirt.org> http://lists.ovirt.org/mailman/listinfo/infra <http://lists.ovirt.org/mailman/listinfo/infra>
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
--------------5035A41E9AA9EE7C4328E562 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 8bit <html> <head> <meta http-equiv="Content-Type" content="text/html; charset=utf-8"> </head> <body text="#000000" bgcolor="#FFFFFF"> <div class="moz-cite-prefix">issue was resolved by Ala's patch. <br> Thanks :) <br> Dafna<br> <br> <br> On 11/23/2017 06:52 PM, Dafna Ron wrote:<br> </div> <blockquote type="cite" cite="mid:afdb65cc-f195-becd-496a-ea4ef0db4358@redhat.com"> <meta http-equiv="Content-Type" content="text/html; charset=utf-8"> <div class="moz-cite-prefix">I am still seeing an exception in latest failure: <br> <br> <a class="moz-txt-link-freetext" href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4064/artifact/..." moz-do-not-send="true">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</a><br> <br> <br> 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.<br> 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<br> 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.<br> 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<br> -d4591ca751c1'<br> 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<br> at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleInCallerTx(CMTTxInterceptor.java:160) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final]<br> at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:257) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final]<br> at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:381) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final]<br> at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:244) [wildfly-ejb3-11.0.0.Final.jar:11.0.0.Final]<br> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)<br> at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)<br> at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73) [weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br> ]<br> :<br> <br> <br> On 11/23/2017 06:04 PM, Dafna Ron wrote:<br> </div> <blockquote type="cite" cite="mid:cdcc6aa6-ea6b-2e9c-c7df-be1db8844598@redhat.com"> <meta http-equiv="Content-Type" content="text/html; charset=utf-8"> <div class="moz-cite-prefix">Thanks, <br> 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. <br> <br> On 11/23/2017 02:49 PM, Ala Hino wrote:<br> </div> <blockquote type="cite" cite="mid:CAPuOgO33Wz53x__X016+rhzh1i7w-TemOn0i7N8z6-BkhSmJDQ@mail.gmail.com"> <div dir="ltr">Fix (cf502720b4cf7bc09694ee0821f3e7f73d6e6e0f) to the following exception just merged: <div><br> </div> <div> <blockquote type="cite" style="font-size:12.8px"> <div dir="ltr"> <div class="gmail_extra"> <div class="gmail_quote"> <pre style="white-space:pre-wrap">Caused by: java.lang.NullPointerException at java.util.Objects.requireNonNu<wbr>ll(Objects.java:203) [rt.jar:1.8.0_151] at java.util.Optional.<init>(Opti<wbr>onal.java:96) [rt.jar:1.8.0_151] at java.util.Optional.of(Optional<wbr>.java:108) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>193) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>190) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindO<wbr>p.evaluateSequential(FindOps.<wbr>java:152) [rt.jar:1.8.0_151] at java.util.stream.AbstractPipel<wbr>ine.evaluate(AbstractPipeline.<wbr>java:234) [rt.jar:1.8.0_151] at java.util.stream.ReferencePipe<wbr>line.findFirst(ReferencePipeli<wbr>ne.java:464) [rt.jar:1.8.0_151] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.setQcowCompatByQemuImageInf<wbr>o(BaseImagesCommand.java:432) [bll.jar:] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.endSuccessfully(BaseImagesC<wbr>ommand.java:393) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.internalEndSuccessfull<wbr>y(CommandBase.java:751) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endActionInTransaction<wbr>Scope(CommandBase.java:709) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.runInTransaction(Comma<wbr>ndBase.java:1989) [bll.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInRequired(TransactionSu<wbr>pport.java:139) [utils.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInScope(TransactionSuppo<wbr>rt.java:105) [utils.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endAction(CommandBase.<wbr>java:574) [bll.jar:] at org.ovirt.engine.core.bll.Back<wbr>end.endAction(Backend.java:<wbr>536) [bll.jar:]</pre> </div> </div> </div> </blockquote> </div> </div> <div class="gmail_extra"><br> <div class="gmail_quote">On Thu, Nov 23, 2017 at 4:44 PM, Allon Mureinik <span dir="ltr"><<a href="mailto:amureini@redhat.com" target="_blank" moz-do-not-send="true">amureini@redhat.com</a>></span> wrote:<br> <blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"> <div dir="ltr"> <div class="gmail_default" style="font-family:monospace,monospace"><br> </div> <div class="gmail_quote">---------- Forwarded message ----------<br> From: <b class="gmail_sendername">Dafna Ron</b> <span dir="ltr"><<a href="mailto:dron@redhat.com" target="_blank" moz-do-not-send="true">dron@redhat.com</a>></span><br> Date: Thu, Nov 23, 2017 at 1:32 PM<br> Subject: Re: [ovirt-devel] [ OST Failure Report ] [ oVirt master ] [ 22-11-2017 ] [ 004_basic_sanity.verify_add_<wbr>vm_template ]<br> To: Yaniv Kaul <<a href="mailto:ykaul@redhat.com" target="_blank" moz-do-not-send="true">ykaul@redhat.com</a>>, Nir Soffer <<a href="mailto:nsoffer@redhat.com" target="_blank" moz-do-not-send="true">nsoffer@redhat.com</a>><br> Cc: aos-scalability <<a href="mailto:aos-scalability@redhat.com" target="_blank" moz-do-not-send="true">aos-scalability@redhat.com</a>>, devel <<a href="mailto:devel@ovirt.org" target="_blank" moz-do-not-send="true">devel@ovirt.org</a>>, infra <<a href="mailto:infra@ovirt.org" target="_blank" moz-do-not-send="true">infra@ovirt.org</a>><br> <br> <br> <div text="#000000" bgcolor="#FFFFFF"> <div class="m_-2904079716800439893m_7555078834308145571moz-cite-prefix">I opened a bug on the error: <a class="m_-2904079716800439893m_7555078834308145571moz-txt-link-freetext" href="https://bugzilla.redhat.com/show_bug.cgi?id=1516780" target="_blank" moz-do-not-send="true">https://bugzilla.redhat.com/sh<wbr>ow_bug.cgi?id=1516780</a><br> <br> 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. <br> <div> <div class="m_-2904079716800439893h5"> <br> On 11/22/2017 07:05 PM, Yaniv Kaul wrote:<br> </div> </div> </div> <div> <div class="m_-2904079716800439893h5"> <blockquote type="cite"> <div dir="ltr"><br> <div class="gmail_extra"><br> <div class="gmail_quote">On Wed, Nov 22, 2017 at 7:55 PM, Nir Soffer <span dir="ltr"><<a href="mailto:nsoffer@redhat.com" target="_blank" moz-do-not-send="true">nsoffer@redhat.com</a>></span> wrote:<br> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"><br> <br> <div class="gmail_quote"> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <div dir="ltr">On Wed, Nov 22, 2017 at 7:15 PM Dafna Ron <<a href="mailto:dron@redhat.com" target="_blank" moz-do-not-send="true">dron@redhat.com</a>> wrote:<br> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p>Hi, <br> </p> <p>we have a failure in 004_basic_sanity.verify_add_vm<wbr>_template. <br> </p> <p>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. <br> </p> <p><br> </p> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">Link and headline ofto suspected patches: </span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> core: Cleanup BaseImagesCommand code - <a class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286moz-txt-link-freetext" href="https://gerrit.ovirt.org/#/c/83812/" target="_blank" moz-do-not-send="true">https://gerrit.ovirt.org/#/c/8<wbr>3812/</a></b> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">Link to Job:</span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><a class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286moz-txt-link-freetext" href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989" target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job/o<wbr>virt-master_change-queue-teste<wbr>r/3989</a></b> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">Link to all logs:</span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><a class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286moz-txt-link-freetext" href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact" target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job/o<wbr>virt-master_change-queue-teste<wbr>r/3989/artifact</a></b></div> </blockquote> </div> </div> </div> </div> </blockquote> <div><br> </div> <div><br> </div> <div>Relevant logs start here - <a href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact/..." target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job<wbr>/ovirt-master_change-queue-tes<wbr>ter/3989/artifact/exported-art<wbr>ifacts/basic-suit-master-el7/<wbr>test_logs/basic-suite-master/<wbr>post-004_basic_sanity.py/</a></div> <div><br> </div> <div>Specifically, server.log (<a href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifact/..." target="_blank" moz-do-not-send="true">http://jenkins.ovirt.org/job/<wbr>ovirt-master_change-queue-test<wbr>er/3989/artifact/exported-arti<wbr>facts/basic-suit-master-el7/<wbr>test_logs/basic-suite-master/<wbr>post-004_basic_sanity.py/lago-<wbr>basic-suite-master-engine/_<wbr>var_log/ovirt-engine/server.<wbr>log</a> ):</div> <div><br> </div> <div> <div>2017-11-22 10:40:14,334-05 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-29) WFLYEJB0034: EJB Invocation failed on component Backend for method public abstract org.ovirt.engine.core.common.a<wbr>ction.ActionReturnValue org.ovirt.engine.core.bll.inte<wbr>rfaces.BackendInternal.endActi<wbr>on(org.ovirt.engine.core.<wbr>common.action.ActionType,org.<wbr>ovirt.engine.core.common.actio<wbr>n.ActionParametersBase,org.<wbr>ovirt.engine.core.bll.context.<wbr>CommandContext): javax.ejb.EJBTransactionRolled<wbr>backException</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.handleInCallerTx(CMTTx<wbr>Interceptor.java:160) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.invokeInCallerTx(CMTTx<wbr>Interceptor.java:257) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.supports(CMTTxIntercep<wbr>tor.java:381) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.tx.CMTTxInte<wbr>rceptor.processInvocation(CMTT<wbr>xInterceptor.java:244) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext$Invocation.proceed(<wbr>InterceptorContext.java:509)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.weld.ejb.AbstractEJB<wbr>RequestScopeActivationIntercep<wbr>tor.aroundInvoke(AbstractEJBRe<wbr>questScopeActivationIntercepto<wbr>r.java:73) [weld-core-impl-2.4.3.Final.ja<wbr>r:2.4.3.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.weld.ejb.EjbReque<wbr>stScopeActivationInterceptor.<wbr>processInvocation(EjbRequestSc<wbr>opeActivationInterceptor.java:<wbr>89)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at <a href="http://org.jboss.as.ejb3.component.in" moz-do-not-send="true">org.jboss.as.ejb3.component.in</a><wbr>terceptors.CurrentInvocationCo<wbr>ntextInterceptor.<wbr>processInvocation(CurrentInvoc<wbr>ationContextInterceptor.java:<wbr>41) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at <a href="http://org.jboss.as.ejb3.component.in" moz-do-not-send="true">org.jboss.as.ejb3.component.in</a><wbr>vocationmetrics.WaitTimeInterc<wbr>eptor.processInvocation(WaitTi<wbr>meInterceptor.java:47) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.security.Sec<wbr>urityContextInterceptor.proces<wbr>sInvocation(SecurityContextInt<wbr>erceptor.java:100) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.as.ejb3.deployment.p<wbr>rocessors.StartupAwaitIntercep<wbr>tor.processInvocation(StartupA<wbr>waitInterceptor.java:22) [wildfly-ejb3-11.0.0.Final.jar<wbr>:11.0.0.Final]</div> <div><span style="white-space:pre-wrap"> </span>at org.jboss.invocation.Intercept<wbr>orContext.proceed(InterceptorC<wbr>ontext.java:422)</div> </div> <div><br> </div> <div>...</div> <div> <pre style="color:rgb(0,0,0)">Caused by: java.lang.NullPointerException at java.util.Objects.requireNonNu<wbr>ll(Objects.java:203) [rt.jar:1.8.0_151] at java.util.Optional.<init>(Opti<wbr>onal.java:96) [rt.jar:1.8.0_151] at java.util.Optional.of(Optional<wbr>.java:108) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>193) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindS<wbr>ink$OfRef.get(FindOps.java:<wbr>190) [rt.jar:1.8.0_151] at java.util.stream.FindOps$FindO<wbr>p.evaluateSequential(FindOps.<wbr>java:152) [rt.jar:1.8.0_151] at java.util.stream.AbstractPipel<wbr>ine.evaluate(AbstractPipeline.<wbr>java:234) [rt.jar:1.8.0_151] at java.util.stream.ReferencePipe<wbr>line.findFirst(ReferencePipeli<wbr>ne.java:464) [rt.jar:1.8.0_151] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.setQcowCompatByQemuImageInf<wbr>o(BaseImagesCommand.java:432) [bll.jar:] at org.ovirt.engine.core.bll.stor<wbr>age.disk.image.BaseImagesComma<wbr>nd.endSuccessfully(BaseImagesC<wbr>ommand.java:393) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.internalEndSuccessfull<wbr>y(CommandBase.java:751) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endActionInTransaction<wbr>Scope(CommandBase.java:709) [bll.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.runInTransaction(Comma<wbr>ndBase.java:1989) [bll.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInRequired(TransactionSu<wbr>pport.java:139) [utils.jar:] at <a href="http://org.ovirt.engine.core.utils.tr" moz-do-not-send="true">org.ovirt.engine.core.utils.tr</a><wbr>ansaction.TransactionSupport.e<wbr>xecuteInScope(TransactionSuppo<wbr>rt.java:105) [utils.jar:] at org.ovirt.engine.core.bll.Comm<wbr>andBase.endAction(CommandBase.<wbr>java:574) [bll.jar:] at org.ovirt.engine.core.bll.Back<wbr>end.endAction(Backend.java:<wbr>536) [bll.jar:]</pre> <pre style="color:rgb(0,0,0)">Y.</pre> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"> <div class="gmail_quote"> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">(Relevant) error snippet from the log: </span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"><error></span></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> </b><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap">lago log: </span></p> </b></div> </blockquote> </div> </div> </div> </div> </blockquote> <div><br> </div> <div> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"> <div class="gmail_quote"> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"> </span></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><br> </p> </b> <pre style="box-sizing:border-box;white-space:pre-wrap;word-wrap:break-word;margin:0px;color:rgb(51,51,51);font-size:14px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:normal;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;word-spacing:0px;text-decoration-style:initial;text-decoration-color:initial"> File "/usr/lib64/python2.7/unittest<wbr>/case.py", line 369, in run testMethod() File "/usr/lib/python2.7/site-packa<wbr>ges/nose/case.py", line 197, in runTest self.test(*self.arg) File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 129, in wrapped_test test() File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 59, in wrapper return func(get_test_prefix(), *args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 68, in wrapper return func(prefix.virt_env.engine_vm<wbr>().get_api(), *args, **kwargs) File "/home/jenkins/workspace/ovirt<wbr>-master_change-queue-tester/ov<wbr>irt-system-tests/basic-suite-<wbr>master/test-scenarios/004_<wbr>basic_sanity.py", line 500, in verify_add_vm_template lambda: api.vms.get(VM1_NAME).status.s<wbr>tate == 'down', File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 271, in assert_true_within_long assert_equals_within_long(func<wbr>, True, allowed_exceptions) File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 258, in assert_equals_within_long func, value, LONG_TIMEOUT, allowed_exceptions=allowed_exc<wbr>eptions File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 219, in assert_equals_within res = func() File "/home/jenkins/workspace/ovirt<wbr>-master_change-queue-tester/ov<wbr>irt-system-tests/basic-suite-<wbr>master/test-scenarios/004_<wbr>basic_sanity.py", line 500, in <lambda> lambda: api.vms.get(VM1_NAME).status.s<wbr>tate == 'down', '\'NoneType\' object has no attribute \'status\'\n------------------<wbr>-- >> begin captured logging << --------------------\novirtlag<wbr>o.testlib: ERROR: * Unhandled exception in <function <lambda> at 0x4bafb90>\nTraceback (most recent call last):\n File "/usr/lib/python2.7/site-packa<wbr>ges/ovirtlago/testlib.py", line 219, in assert_equals_within\n res = func()\n File "/home/jenkins/workspace/ovirt<wbr>-master_change-queue-tester/ov<wbr>irt-system-tests/basic-suite-<wbr>master/test-scenarios/004_<wbr>basic_sanity.py", line 500, in <lambda>\n lambda: api.vms.get(VM1_NAME).status.s<wbr>tate == \'down\',\nAttributeError: \'NoneType\' object has no attribute \'status\'\n------------------<wbr>--- >> end captured logging << ---------------------'</pre> </div> </blockquote> <div><br> </div> </div> </div> <div>This is a test error - code like this is always wrong:</div> <div><br> </div> <div> api.vms.get(VM1_NAME).status.s<wbr>tate == something</div> <div><br> </div> <div>In this case, api.vms.get() returned None. The test code</div> <div>should handle None and fail with meaningfull error, or maybe</div> <div>retry the call.<br> </div> </div> </div> </blockquote> <div><br> </div> <div>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. </div> <div>Gracefully with 'VM1_NAME was not found' ? Perhaps.</div> <div> </div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div dir="ltr"> <div class="gmail_quote"> <div> <br> </div> <div> <div class="m_-2904079716800439893m_7555078834308145571gmail-h5"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p><span style="font-weight:normal">engine log: </span><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><b><br> </b></b></p> <pre style="color:rgb(0,0,0);font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:normal;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;word-spacing:0px;text-decoration-style:initial;text-decoration-color:initial">{"jsonrpc": "2.0", "id": "32bfeb29-e70f-48b2-84c7-91cf2<wbr>2ea408c", "result": {"status": "OK", "domain": "2d776fb7-eba8-4ee2-97b6-4350c<wbr>28ddb39", "voltype": "LEAF", "description": "", "parent": "a1192fcc-4660-41a7-a1a5-a2218<wbr>08f603b", "format": "COW", "generation": 0, "image": "dc033235-ab4b-4ef0-be79-6e8a2<wbr>2bfb0bc", "ctime": "1511365200", "disktype": "DATA", "legality": "LEGAL", "mtime": "0", "apparentsize": "1073741824", "children": [], "pool": "", "capacity": "41126400", "uuid": "6a354b93-86af-41fb-a68b-10897<wbr>ae3562f", "truesize": "1073741824", "type": "SPARSE", "lease": {"owners": [], "version": null}}}� 2017-11-22 10:40:39,454-05 DEBUG [org.ovirt.vdsm.jsonrpc.client<wbr>.internal.ResponseWorker] (ResponseWorker) [] Message received: {"jsonrpc": "2.0", "id": "32bfeb29-e70f-48b2-84c7-91cf2<wbr>2ea408c", "result": {"status": "OK", "domain": "2d776fb7-eba8-4ee2-97b6-4350c<wbr>28ddb39", "voltype": "LEAF", "description": "", "parent": "a1192fcc-4660-41a7-a1a5-a2218<wbr>08f603b", "format": "COW", "generation": 0, "image": "dc033235-ab4b-4ef0-be79-6e8a2<wbr>2bfb0bc", "ctime": "1511365200", "disktype": "DATA", "legality": "LEGAL", "mtime": "0", "apparentsize": "1073741824", "children": [], "pool": "", "capacity": "41126400", "uuid": "6a354b93-86af-41fb-a68b-10897<wbr>ae3562f", "truesize": "1073741824", "type": "SPARSE", "lease": {"owners": [], "version": null}}} 2017-11-22 10:40:39,454-05 INFO [org.ovirt.engine.core.vdsbrok<wbr>er.vdsbroker.GetVolumeInfoVDSC<wbr>ommand] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] FINISH, GetVolumeInfoVDSCommand, return: org.ovirt.engine.core.common.b<wbr>usinessentities.storage.DiskIm<wbr>age@6903fdd6, log id: 85b379d 2017-11-22 10:40:39,455-05 INFO [org.ovirt.engine.core.vdsbrok<wbr>er.irsbroker.GetImageInfoVDSCo<wbr>mmand] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.b<wbr>usinessentities.storage.DiskIm<wbr>age@6903fdd6, log id: 75d29166 2017-11-22 10:40:39,455-05 DEBUG [org.ovirt.engine.core.common.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] method: runVdsCommand, params: [GetImageInfo, GetImageInfoVDSCommandParamete<wbr>rs:{storagePoolId='0762073b-b0<wbr>ab-4ee2-8af9-dafa930a5fd4', ignoreFailoverLimit='false', storageDomainId='2d776fb7-eba8<wbr>-4ee2-97b6-4350c28ddb39', imageGroupId='dc033235-ab4b-4e<wbr>f0-be79-6e8a22bfb0bc', imageId='6a354b93-86af-41fb-a6<wbr>8b-10897ae3562f'}], timeElapsed: 165ms 2017-11-22 10:40:39,528-05 DEBUG [org.ovirt.engine.core.common.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [c90b2f35-7a80-476f-9b23-78bee<wbr>cef7c37] method: getVmsWithPlugInfo, params: [dc033235-ab4b-4ef0-be79-6e8a2<wbr>2bfb0bc], timeElapsed: 68ms 2017-11-22 10:40:39,543-05 INFO [org.ovirt.engine.core.utils.t<wbr>ransaction.TransactionSupport] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] transaction rolled back 2017-11-22 10:40:39,543-05 WARN [org.ovirt.engine.core.bll.loc<wbr>k.InMemoryLockManager] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Trying to release a shared lock for key: '93d271d5-e0af-4795-b800-55465<wbr>c7b8826TEMPLATE' , but lock does not exist 2017-11-22 10:40:39,543-05 WARN [org.ovirt.engine.core.bll.loc<wbr>k.InMemoryLockManager] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Trying to release a shared lock for key: 'fb76119e-9283-4c8b-9185-5d79e<wbr>2481bc7DISK' , but lock does not exist 2017-11-22 10:40:39,543-05 WARN [org.ovirt.engine.core.bll.loc<wbr>k.InMemoryLockManager] (EE-ManagedThreadFactory-engin<wbr>eScheduled-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.Add<wbr>VmCommand] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Lock freed to object 'EngineLock:{exclusiveLocks='[<wbr>vm1=VM_NAME]', sharedLocks='[93d271d5-e0af-47<wbr>95-b800-55465c7b8826=TEMPLATE, fb76119e-9283-4c8b-9185-5d79e2<wbr>481bc7=DISK]'}' 2017-11-22 10:40:39,556-05 ERROR [org.ovirt.engine.core.dal.dbb<wbr>roker.auditloghandling.AuditLo<wbr>gDirector] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(6<wbr>0), Failed to complete VM vm1 creation. 2017-11-22 10:40:39,556-05 ERROR [org.ovirt.engine.core.bll.tas<wbr>ks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-34) [] Failed invoking callback end method 'onSucceeded' for command '2760a62f-e4ee-4dd2-b13a-1bb54<wbr>8e3e62d' 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.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-35) [] method: get, params: [d25423f6-34bc-4cde-82fa-c0eed<wbr>fc85386], timeElapsed: 3ms 2017-11-22 10:40:39,949-05 DEBUG [org.ovirt.engine.core.common.<wbr>di.interceptor.DebugLoggingInt<wbr>erceptor] (EE-ManagedThreadFactory-engin<wbr>eScheduled-Thread-71) [] method: get, params: [7c9ec3eb-2838-4b06-9408-326b6<wbr>7869bdc], timeElapsed: 2ms 2017-11-22 10:40:40,606-05 DEBUG [org.ovirt.engine.core.aaa.fil<wbr>ters.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<wbr>-de465aa55eee') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "<string>", line 2, in getAllTasksInfo File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/hsm.py", line 2216, in getAllTasksInfo allTasksInfo = self._pool.getAllTasksInfo() File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/securable.py"<wbr>, 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<wbr>-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-packa<wbr>ges/vdsm/storage/dispatcher.py<wbr>", line 73, in wrapper result = ctask.prepare(func, *args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 108, in wrapper return m(self, *a, **kw) File "/usr/lib/python2.7/site-packa<wbr>ges/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=Non<wbr>e, options=None) from=::1,52728, task_id=172b5528-cc76-426a-81d<wbr>3-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-81d<wbr>3-43143b49a878 (api:50)</pre> </div> </blockquote> <div><br> </div> </div> </div> <div>This is <a href="https://bugzilla.redhat.com/1426429" target="_blank" moz-do-not-send="true">https://bugzilla.redhat.com<wbr>/1426429</a><br> </div> <div><br> </div> <div>Not related to the real error.</div> <span class="m_-2904079716800439893m_7555078834308145571gmail-"> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <pre style="color:rgb(0,0,0);font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:normal;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;word-spacing:0px;text-decoration-style:initial;text-decoration-color:initial">2017-11-22 10:36:11,980-0500 ERROR (jsonrpc/2) [storage.TaskManager.Task] (Task='172b5528-cc76-426a-81d3<wbr>-43143b49a878') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "<string>", line 2, in getAllTasksStatuses File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/hsm.py", line 2176, in getAllTasksStatuses allTasksStatus = self._pool.getAllTasksStatuses<wbr>() File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/securable.py"<wbr>, 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<wbr>-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-packa<wbr>ges/vdsm/storage/dispatcher.py<wbr>", line 73, in wrapper result = ctask.prepare(func, *args, **kwargs) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 108, in wrapper return m(self, *a, **kw) File "/usr/lib/python2.7/site-packa<wbr>ges/vdsm/storage/task.py", line 1189, in prepare raise self.error SecureError: Secured object is not in safe state</pre> </div> </blockquote> <div><br> </div> </span> <div>The way to find the relevant errors is to find the entry point of this flow</div> <div>in engine.log, and then follow this in vdsm.log using flow_id=xxx.</div> <div><br> </div> <div>Ideally we would send a uuid to engine for every operation, and be</div> <div>able to query the operation status using the uuid. This is the way</div> <div>storage jobs are managed in vdsm side since 4.1.</div> <div><br> </div> <div>If we had this every test would generate a uuids and debugging</div> <div>failing test would be much faster.</div> <div><br> </div> <div>Nir</div> <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div bgcolor="#FFFFFF"> <p><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br> <br> </b></p> <p dir="ltr" style="line-height:1.38;margin-top:0pt;margin-bottom:0pt"><b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><span style="font-size:11pt;font-family:Arial;color:rgb(0,0,0);background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap"></error></span></b></p> <b style="font-weight:normal" id="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"> </b><br class="m_-2904079716800439893m_7555078834308145571gmail-m_5033699571211795255m_-8160106625429842286Apple-interchange-newline"> <p><br> </p> </div> ______________________________<wbr>_________________<br> Devel mailing list<br> <a href="mailto:Devel@ovirt.org" target="_blank" moz-do-not-send="true">Devel@ovirt.org</a><br> <a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank" moz-do-not-send="true">http://lists.ovirt.org/mailman<wbr>/listinfo/devel</a></blockquote> </div> </div> <br> ______________________________<wbr>_________________<br> Devel mailing list<br> <a href="mailto:Devel@ovirt.org" target="_blank" moz-do-not-send="true">Devel@ovirt.org</a><br> <a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank" moz-do-not-send="true">http://lists.ovirt.org/mailman<wbr>/listinfo/devel</a><br> </blockquote> </div> <br> </div> </div> </blockquote> <p><br> </p> </div> </div> </div> <br> ______________________________<wbr>_________________<br> Infra mailing list<br> <a href="mailto:Infra@ovirt.org" target="_blank" moz-do-not-send="true">Infra@ovirt.org</a><br> <a href="http://lists.ovirt.org/mailman/listinfo/infra" rel="noreferrer" target="_blank" moz-do-not-send="true">http://lists.ovirt.org/mailman<wbr>/listinfo/infra</a><br> <br> </div> <br> </div> </blockquote> </div> <br> </div> <br> <fieldset class="mimeAttachmentHeader"></fieldset> <br> <pre wrap="">_______________________________________________ Devel mailing list <a class="moz-txt-link-abbreviated" href="mailto:Devel@ovirt.org" moz-do-not-send="true">Devel@ovirt.org</a> <a class="moz-txt-link-freetext" href="http://lists.ovirt.org/mailman/listinfo/devel" moz-do-not-send="true">http://lists.ovirt.org/mailman/listinfo/devel</a></pre> </blockquote> <p><br> </p> <br> <fieldset class="mimeAttachmentHeader"></fieldset> <br> <pre wrap="">_______________________________________________ Devel mailing list <a class="moz-txt-link-abbreviated" href="mailto:Devel@ovirt.org" moz-do-not-send="true">Devel@ovirt.org</a> <a class="moz-txt-link-freetext" href="http://lists.ovirt.org/mailman/listinfo/devel" moz-do-not-send="true">http://lists.ovirt.org/mailman/listinfo/devel</a></pre> </blockquote> <p><br> </p> <br> <fieldset class="mimeAttachmentHeader"></fieldset> <br> <pre wrap="">_______________________________________________ Devel mailing list <a class="moz-txt-link-abbreviated" href="mailto:Devel@ovirt.org">Devel@ovirt.org</a> <a class="moz-txt-link-freetext" href="http://lists.ovirt.org/mailman/listinfo/devel">http://lists.ovirt.org/mailman/listinfo/devel</a></pre> </blockquote> <p><br> </p> </body> </html> --------------5035A41E9AA9EE7C4328E562--
participants (2)
-
Ala Hino -
Dafna Ron