[ovirt-devel] [ OST Failure Report ] [ oVirt master ] [ 22-11-2017 ] [ 004_basic_sanity.verify_add_vm_template ]

Wednesday, 22 November 2017

This is a multi-part message in MIME format.
--------------70B5D9DCF02902B2CC172A45
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit

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/*

*
*

*Link to Job:*

*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*

*
*

*(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 <<
---------------------'

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)
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

*

*

*</error>*

**

--------------70B5D9DCF02902B2CC172A45
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">
    <p>Hi, <br>
    </p>
    <p>we have a failure in 004_basic_sanity.verify_add_vm_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="docs-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:#000000;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></p>
        <p dir="ltr"
          style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;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="moz-txt-link-freetext"
href="https://gerrit.ovirt.org/#/c/83812/">https://gerrit.ov...
    <p><b style="font-weight:normal;"

id="docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br>
        <p dir="ltr"
          style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;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></p>
<a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
    <p><b style="font-weight:normal;"

id="docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br>
        <p dir="ltr"
          style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;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></p>
<a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
    <p><b style="font-weight:normal;"

id="docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br>
        <p dir="ltr"
          style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;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></p>
        <p dir="ltr"
          style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">&lt;error&gt;</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:#000000;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="docs-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:#000000;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>
        <p dir="ltr"
          style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;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></p>
    <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; orphans: 2; text-align: start; text-indent: 0px; text-transform:
none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style:
initial; text-decoration-color: initial;"> 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 &lt;lambda&gt;
    lambda: api.vms.get(VM1_NAME).status.state == 'down',
'\'NoneType\' object has no attribute \'status\'\n--------------------
&gt;&gt; begin captured logging &lt;&lt;
--------------------\novirtlago.testlib: ERROR:     * Unhandled exception in
&lt;function &lt;lambda&gt; at 0x4bafb90&gt;\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 &lt;lambda&gt;\n    lambda: api.vms.get(VM1_NAME).status.state ==
\'down\',\nAttributeError: \'NoneType\' object has no attribute
\'status\'\n--------------------- &gt;&gt; end captured logging
&lt;&lt; ---------------------'</pre>
    <p><span style="font-weight:normal;">engine log:
</span><b
        style="font-weight:normal;"

id="docs-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; orphans:
2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing:
0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial;
text-decoration-color: initial;">{"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 "&lt;string&gt;", 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)
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 "&lt;string&gt;", 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</pre>
    <p><b style="font-weight:normal;"

id="docs-internal-guid-5859b7a1-e4a5-ffe9-fc92-59c9c5a7be25"><br>
        <br>
        <p dir="ltr"
          style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">&lt;/error&gt;</span></p>
      </b><br class="Apple-interchange-newline">
    </p>
    <p><br>
    </p>
  </body>
</html>

--------------70B5D9DCF02902B2CC172A45--

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

[ovirt-devel] [ OST Failure Report ] [ oVirt master ] [ 22-11-2017 ] [ 004_basic_sanity.verify_add_vm_template ]