9:52 p.m.
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/artifa...
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.exe...
[utils.jar:]
>> at org.ovirt.engine.core.utils.tr
<http://org.ovirt.engine.core.utils.tr>ansaction.TransactionSupport.exe...
[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(a)redhat.com
> <mailto:amureini@redhat.com>> wrote:
>
>
> ---------- Forwarded message ----------
> From: *Dafna Ron* <dron(a)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(a)redhat.com <mailto:ykaul@redhat.com>>, Nir
> Soffer <nsoffer(a)redhat.com <mailto:nsoffer@redhat.com>>
> Cc: aos-scalability <aos-scalability(a)redhat.com
> <mailto:aos-scalability@redhat.com>>, devel <devel(a)ovirt.org
> <mailto:devel@ovirt.org>>, infra <infra(a)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(a)redhat.com
>> <mailto:nsoffer@redhat.com>> wrote:
>>
>>
>>
>> On Wed, Nov 22, 2017 at 7:15 PM Dafna Ron <dron(a)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/artifa...
>>
>>
>>
>> Relevant logs start here
>> -
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifa...
>>
<http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifa...
>>
>> Specifically, server.log
>>
(http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifa...
>>
<http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3989/artifa...
>> ):
>>
>> 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.CurrentInvocationCont...
>> [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.WaitTimeIntercep...
>> [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.exe...
[utils.jar:]
>> at org.ovirt.engine.core.utils.tr
>>
<http://org.ovirt.engine.core.utils.tr>ansaction.TransactionSupport.exe...
[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(a)ovirt.org <mailto:Devel@ovirt.org>
>> http://lists.ovirt.org/mailman/listinfo/devel
>> <http://lists.ovirt.org/mailman/listinfo/devel>
>>
>>
>> _______________________________________________
>> Devel mailing list
>> Devel(a)ovirt.org <mailto:Devel@ovirt.org>
>> http://lists.ovirt.org/mailman/listinfo/devel
>> <http://lists.ovirt.org/mailman/listinfo/devel>
>>
>>
>
>
> _______________________________________________
> Infra mailing list
> Infra(a)ovirt.org <mailto:Infra@ovirt.org>
> http://lists.ovirt.org/mailman/listinfo/infra
> <http://lists.ovirt.org/mailman/listinfo/infra>
>
>
>
>
>
> _______________________________________________
> Devel mailing list
> Devel(a)ovirt.org
> http://lists.ovirt.org/mailman/listinfo/devel
_______________________________________________
Devel mailing list
Devel(a)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/...
<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(a)redhat.com</a>&gt;</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(a)redhat.com</a>&gt;</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(a)redhat.com</a>&gt;,
Nir Soffer <<a href="mailto:nsoffer@redhat.com"
target="_blank"
moz-do-not-send="true">nsoffer(a)redhat.com</a>&gt;<br>
Cc: aos-scalability <<a
href="mailto:aos-scalability@redhat.com"
target="_blank"
moz-do-not-send="true">aos-scalability(a)redhat.com</a>&gt;,
devel <<a href="mailto:devel@ovirt.org"
target="_blank"
moz-do-not-send="true">devel(a)ovirt.org</a>&gt;,
infra <<a href="mailto:infra@ovirt.org"
target="_blank"
moz-do-not-send="true">infra(a)ovirt.org</a>&gt;<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...
<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(a)redhat.com</a>&gt;</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(a)redhat.com</a>&gt;
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...
<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/...
target="_blank"
moz-do-not-send="true">http://jenkins.ovirt.org/job/o<wbr...
<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/...
target="_blank"
moz-do-not-send="true">http://jenkins.ovirt.org/job/o<wbr...
</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/...
target="_blank"
moz-do-not-send="true">http://jenkins.ovirt.org/job<wbr&g...
<div><br>
</div>
<div>Specifically, server.log (<a
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
target="_blank"
moz-do-not-send="true">http://jenkins.ovirt.org/job/<wbr&...
):</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(a)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...
</div>
</div>
<br>
______________________________<wbr>_________________<br>
Devel mailing list<br>
<a href="mailto:Devel@ovirt.org"
target="_blank"
moz-do-not-send="true">Devel(a)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...
</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(a)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...
<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(a)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/listin...
</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://...
</blockquote>
<p><br>
</p>
</body>
</html>
--------------967A64E08672635C5E52BC0D--