Bug 1497424 - Live merge fails - delete snapshot fails , images merged but volume removal failed.
Summary: Live merge fails - delete snapshot fails , images merged but volume removal f...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: BLL.Storage
Version: 4.2.0
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ovirt-4.2.0
: ---
Assignee: Ala Hino
QA Contact: Raz Tamir
URL:
Whiteboard:
Depends On: 1168327
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-09-30 09:52 UTC by Avihai
Modified: 2017-12-20 10:56 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-12-20 10:56:14 UTC
oVirt Team: Storage
Embargoed:
rule-engine: ovirt-4.2+
rule-engine: blocker+

Attachments (Terms of Use)
engine , vdsm log (1.26 MB, application/x-gzip)
2017-09-30 09:52 UTC, Avihai 		no flags Details
engine , vdsm log (1.64 MB, application/x-gzip)
2017-10-26 08:43 UTC, Avihai 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 83218 0 'None' MERGED core: Update ReduceVolumeSupported to false up to version 4.2 2021-01-13 11:38:27 UTC

Description Avihai 2017-09-30 09:52:49 UTC 
Created attachment 1332644 [details]
engine , vdsm  log

Description of problem:
Live merge fails - delete snapshot fails , images merged but volume removal failed.

Version-Release number of selected component (if applicable):
Engine:
ovirt-engine-4.2.0-0.0.master.20170925172449.git9d850a9.el7.centos.noarch

VDSM:
4.20.3-95.git0813890

How reproducible:
Reproduced for 2/2 times so far.

Steps to Reproduce:

Automation TestCase18346 description:

    1. Create DC + cluster on v3
    2. Create a VM with thin disk & start VM
    3. Write data (file1) and Create snapshots s1
    4. Write data (file2) and Create snapshots s2
    5. Upgrade the cluster+DC from v3 to v4
    4. Verify that the snapshot images are version 0.10
    5. Write data (file3)
    6. Create snapshot s3 & verify the snapshot image is version 0.10
    7. Create snapshot s4 & verify the snapshot image is version 1.1
    8. Deleted snapshot s3 and verify that the live merge is successful

Actual results:
Delete snapshot s3 names 'snap_test_live_merge_old_ver_30114630523' fails.

As engine stated (see all ERRORs below):
Snapshot 'd7e2769d-2991-482f-ae4f-6dfdd426a732' images '1c19ab35-123d-4c64-8d04-6427b4803620'..'de55e853-6691-408c-9cc0-0a3d3d337cbe' merged, but volume removal failed.
Some or all of the following volumes may be orphaned: [1c19ab35-123d-4c64-8d04-6427b4803620]. Please retry Live Merge on the snapshot to complete the operation.

Expected results:


Additional info:

Event:
Sep 30, 2017, 11:54:54 AM
Failed to delete snapshot 'snap_test_live_merge_old_ver_30114630523' for VM 'vm_TestCase18346_REST_ISCS_3011380717'.

Engine:
017-09-30 11:53:45,520+03 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-95) [snapshots_delete_878b9fe9-b20d-4508] Command 'RemoveSnapshot
SingleDiskLive' id: '7b4a9df9-7f8e-47ef-8665-9e2b4407d2dc' failed when attempting to perform the next operation, marking as FAILED '[bc4ffe05-d7fc-4915-b4f8-d60144bbbd91, ebee9e01-eeea-4f0a-98da-51bba81f54cb, 3f
d5d67a-830b-4c8d-81d7-f1fd82e1f375, 913370cf-057a-46c2-84ec-693c0be42c72]'
2017-09-30 11:53:45,520+03 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-95) [snapshots_delete_878b9fe9-b20d-4508] Command id: '7b4a9df9-7f8e-47ef-8665-9e2b4407d2dc failed child command status for step 'DESTROY_IMAGE_CHECK'
2017-09-30 11:53:45,520+03 INFO  [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommandCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-95) [snapshots_delete_878b9fe9-b20d-4508] Command 'RemoveSnapshotSingleDiskLive' id: '7b4a9df9-7f8e-47ef-8665-9e2b4407d2dc' child commands '[bc4ffe05-d7fc-4915-b4f8-d60144bbbd91, ebee9e01-eeea-4f0a-98da-51bba81f54cb, 3fd5d67a-830b-4c8d-81d7-f1fd82e1f375, 913370cf-057a-46c2-84ec-693c0be42c72]' executions were completed, status 'FAILED'
2017-09-30 11:53:47,984+03 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-50) [snapshots_delete_878b9fe9-b20d-4508] Snapshot 'd7e2769d-2991-482f-ae4f-6dfdd426a732' images '1c19ab35-123d-4c64-8d04-6427b4803620'..'de55e853-6691-408c-9cc0-0a3d3d337cbe' merged, but volume removal failed. Some or all of the following volumes may be orphaned: [1c19ab35-123d-4c64-8d04-6427b4803620]. Please retry Live Merge on the snapshot to complete the operation.
2017-09-30 11:53:48,002+03 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-50) [snapshots_delete_878b9fe9-b20d-4508] Ending command 'org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand' with failure.
2017-09-30 11:54:50,528+03 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-65) [snapshots_delete_878b9fe9-b20d-4508] Command id: 'e3aa4b8a-7bd5-4a39-b6ce-03d55d46bd05 failed child command status for step 'DESTROY_IMAGE_CHECK'
2017-09-30 11:54:50,528+03 INFO  [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommandCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-65) [snapshots_delete_878b9fe9-b20d-4508] Command 'RemoveSnapshotSingleDiskLive' id: 'e3aa4b8a-7bd5-4a39-b6ce-03d55d46bd05' child commands '[2dd3ed36-f846-49a4-9c3e-f31c5eb5edae, acd7db82-5143-433c-9d27-64c55cba3c80, 36fd5633-5f61-4380-ae91-7d855b538a95, dc0f183a-6ca9-4c9d-9224-915606fd3a51]' executions were completed, status 'FAILED'
2017-09-30 11:54:51,543+03 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [snapshots_delete_878b9fe9-b20d-4508] START, GetImageInfoVDSCommand( GetImageInfoVDSCommandParameters:{storagePoolId='a69d57eb-a2d5-49ae-b6ed-a35e92f337c9', ignoreFailoverLimit='false', storageDomainId='940de508-9dbe-4783-b8a3-972a70896268', imageGroupId='7ed90031-09f0-4792-ab24-8c56a9a67c73', imageId='327a1d80-a201-4f3d-ba33-128d14b04098'}), log id: 36e300c4
2017-09-30 11:54:51,546+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [snapshots_delete_878b9fe9-b20d-4508] START, GetVolumeInfoVDSCommand(HostName = host_mixed_1, GetVolumeInfoVDSCommandParameters:{hostId='17757855-76ac-4a16-8ee2-e40ac5909cd3', storagePoolId='a69d57eb-a2d5-49ae-b6ed-a35e92f337c9', storageDomainId='940de508-9dbe-4783-b8a3-972a70896268', imageGroupId='7ed90031-09f0-4792-ab24-8c56a9a67c73', imageId='327a1d80-a201-4f3d-ba33-128d14b04098'}), log id: 7568e757
2017-09-30 11:54:51,828+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [snapshots_delete_878b9fe9-b20d-4508] FINISH, GetVolumeInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@1a0915d0, log id: 7568e757
2017-09-30 11:54:51,829+03 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [snapshots_delete_878b9fe9-b20d-4508] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@1a0915d0, log id: 36e300c4
2017-09-30 11:54:52,362+03 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [snapshots_delete_878b9fe9-b20d-4508] Snapshot 'd7e2769d-2991-482f-ae4f-6dfdd426a732' images 'aba0307b-0610-4546-8c01-bb02eebef4dc'..'327a1d80-a201-4f3d-ba33-128d14b04098' merged, but volume removal failed. Some or all of the following volumes may be orphaned: [aba0307b-0610-4546-8c01-bb02eebef4dc]. Please retry Live Merge on the snapshot to complete the operation.
2017-09-30 11:54:52,379+03 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [snapshots_delete_878b9fe9-b20d-4508] Ending command 'org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand' with failure.
2017-09-30 11:54:53,406+03 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-74) [snapshots_delete_878b9fe9-b20d-4508] Command 'RemoveSnapshot' id: '0ace7741-f120-46cd-b531-572b1629a35e' child commands '[7b4a9df9-7f8e-47ef-8665-9e2b4407d2dc, e3aa4b8a-7bd5-4a39-b6ce-03d55d46bd05]' executions were completed, status 'FAILED'
2017-09-30 11:54:54,464+03 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-69) [snapshots_delete_878b9fe9-b20d-4508] Ending command 'org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand' with failure.
2017-09-30 11:54:54,519+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-69) [snapshots_delete_878b9fe9-b20d-4508] EVENT_ID: USER_REMOVE_SNAPSHOT_FINISHED_FAILURE(357), Failed to delete snapshot 'snap_test_live_merge_old_ver_30114630523' for VM 'vm_TestCase18346_REST_ISCS_3011380717'.


VDSM:

2017-09-30 11:52:42,545+0300 ERROR (jsonrpc/2) [storage.TaskManager.Task] (Task='82e14c19-5af3-4b1f-8b40-b98c0f79b9ac') Unexpected error (task:872)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 879, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in teardownImage
  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 3189, in teardownImage
    dom.deactivateImage(imgUUID)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 1283, in deactivateImage
    lvm.deactivateLVs(self.sdUUID, volUUIDs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 1310, in deactivateLVs
    _setLVAvailability(vgName, toDeactivate, "n")
  File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 842, in _setLVAvailability
    raise error(str(e))
CannotDeactivateLogicalVolume: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume 940de508-9dbe-4783-b8a3-972a70896268/bcca67e2-4be2-44cf-9f7a-c91e07fc0ee4 in use.\', \'  Logical volume 940de508-9dbe-4783-b8a3-972a70896268/1128ee72-e9d9-48dc-b43f-167b7970d09e in use.\', \'  Logical volume 940de508-9dbe-4783-b8a3-972a70896268/327a1d80-a201-4f3d-ba33-128d14b04098 in use.\', \'  Logical volume 940de508-9dbe-4783-b8a3-972a70896268/aba0307b-0610-4546-8c01-bb02eebef4dc in use.\', \'  Logical volume 940de508-9dbe-4783-b8a3-972a70896268/c876e298-cb03-4cbc-9dad-6dde0d1e425c in use.\']\\n940de508-9dbe-4783-b8a3-972a70896268/[\'1128ee72-e9d9-48dc-b43f-167b7970d09e\', \'bcca67e2-4be2-44cf-9f7a-c91e07fc0ee4\', \'327a1d80-a201-4f3d-ba33-128d14b04098\', \'aba0307b-0610-4546-8c01-bb02eebef4dc\', \'c876e298-cb03-4cbc-9dad-6dde0d1e425c\']",)',)

2017-09-30 11:52:42,556+0300 ERROR (jsonrpc/2) [storage.Dispatcher] FINISH teardownImage error=Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume 940de508-9dbe-4783-b8a3-97
2a70896268/bcca67e2-4be2-44cf-9f7a-c91e07fc0ee4 in use.\', \'  Logical volume 940de508-9dbe-4783-b8a3-972a70896268/1128ee72-e9d9-48dc-b43f-167b7970d09e in use.\', \'  Logical volume 940de508-9dbe-4783-b8a3-972a7
0896268/327a1d80-a201-4f3d-ba33-128d14b04098 in use.\', \'  Logical volume 940de508-9dbe-4783-b8a3-972a70896268/aba0307b-0610-4546-8c01-bb02eebef4dc in use.\', \'  Logical volume 940de508-9dbe-4783-b8a3-972a7089
6268/c876e298-cb03-4cbc-9dad-6dde0d1e425c in use.\']\\n940de508-9dbe-4783-b8a3-972a70896268/[\'1128ee72-e9d9-48dc-b43f-167b7970d09e\', \'bcca67e2-4be2-44cf-9f7a-c91e07fc0ee4\', \'327a1d80-a201-4f3d-ba33-128d14b0
4098\', \'aba0307b-0610-4546-8c01-bb02eebef4dc\', \'c876e298-cb03-4cbc-9dad-6dde0d1e425c\']",)',) (dispatcher:82)
2017-09-30 11:52:42,557+0300 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Image.teardown failed (error 552) in 48.76 seconds (__init__:630)

Time line:

2017-09-30 11:33:27,304 - MainThread - pytest.art.matrix - INFO - The storage type switched to iscsi
2017-09-30 11:33:27,327 - MainThread - root - INFO - Get SPM host from the list of hosts host_mixed_1, host_mixed_2, host_mixed_3
2017-09-30 11:33:27,338 - MainThread - root - INFO - Checking Storage Pool Manager (SPM) status of the host host_mixed_1.
2017-09-30 11:33:27,342 - MainThread - root - INFO - Get host object by host_name host_mixed_1. with {'attribute': 'name'}
2017-09-30 11:33:27,553 - MainThread - art.ll_lib.hosts - INFO - check_host_spm_status - SPM Status of host host_mixed_1 is: none
2017-09-30 11:33:27,555 - MainThread - root - ERROR - Failed to checking storage pool manager (spm) status of the host host_mixed_1.
2017-09-30 11:33:27,562 - MainThread - root - INFO - Checking Storage Pool Manager (SPM) status of the host host_mixed_2.
2017-09-30 11:33:27,567 - MainThread - root - INFO - Get host object by host_name host_mixed_2. with {'attribute': 'name'}
2017-09-30 11:33:27,758 - MainThread - art.ll_lib.hosts - INFO - check_host_spm_status - SPM Status of host host_mixed_2 is: none
2017-09-30 11:33:27,760 - MainThread - root - ERROR - Failed to checking storage pool manager (spm) status of the host host_mixed_2.
2017-09-30 11:33:27,768 - MainThread - root - INFO - Checking Storage Pool Manager (SPM) status of the host host_mixed_3.
2017-09-30 11:33:27,773 - MainThread - root - INFO - Get host object by host_name host_mixed_3. with {'attribute': 'name'}
2017-09-30 11:33:27,978 - MainThread - art.ll_lib.hosts - INFO - check_host_spm_status - SPM Status of host host_mixed_3 is: spm
2017-09-30 11:33:27,990 - MainThread - root - INFO - Get any not SPM host from the list of hosts host_mixed_1, host_mixed_2, host_mixed_3 in the expected state with {'cluster_name': 'golden_env_mixed_1'}
2017-09-30 11:33:27,996 - MainThread - root - INFO - Get host object by host_name host_mixed_1. with {'attribute': 'name'}
2017-09-30 11:33:28,200 - MainThread - root - INFO - Get host object by host_name host_mixed_2. with {'attribute': 'name'}
2017-09-30 11:33:28,396 - MainThread - root - INFO - Get host object by host_name host_mixed_3. with {'attribute': 'name'}
2017-09-30 11:33:28,920 - MainThread - root - INFO - Checking Storage Pool Manager (SPM) status of the host host_mixed_1.
2017-09-30 11:33:28,925 - MainThread - root - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:33:29,153 - MainThread - art.ll_lib.hosts - INFO - check_host_spm_status - SPM Status of host host_mixed_1 is: none
2017-09-30 11:33:29,154 - MainThread - root - ERROR - Failed to checking storage pool manager (spm) status of the host host_mixed_1.
2017-09-30 11:33:29,156 - MainThread - art.ll_lib.dcs - INFO - Add datacenter dc_TestCase18346_REST_ISCS_3011332890 with {'version': '4.0', 'name': 'dc_TestCase18346_REST_ISCS_3011332890'}
2017-09-30 11:33:29,158 - MainThread - datacenters - INFO - Using Correlation-Id: datacenters_create_f3623b3c-d457-4518
2017-09-30 11:33:29,522 - MainThread - datacenters - INFO - New entity was added
2017-09-30 11:33:29,528 - MainThread - datacenters - INFO - Property 'data_center->name' has correct value: dc_TestCase18346_REST_ISCS_3011332890
2017-09-30 11:33:29,530 - MainThread - datacenters - INFO - Property 'data_center->local' has correct value: false
2017-09-30 11:33:29,532 - MainThread - datacenters - INFO - Property 'data_center->version->major' has correct value: 4
2017-09-30 11:33:29,533 - MainThread - datacenters - INFO - Property 'data_center->version->minor' has correct value: 0
2017-09-30 11:33:29,676 - MainThread - datacenters - INFO - Validated supported versions of data center dc_TestCase18346_REST_ISCS_3011332890
2017-09-30 11:33:29,678 - MainThread - art.rhevm_api.tests_lib.low_level.clusters - INFO - Create cluster cl_TestCase18346_REST_ISCS_3011332890 with {'data_center': 'dc_TestCase18346_REST_ISCS_3011332890', 'name': 'cl_TestCase18346_REST_ISCS_3011332890', 'version': '4.0', 'cpu': 'Intel Conroe Family'}
2017-09-30 11:33:29,832 - MainThread - clusters - INFO - Using Correlation-Id: clusters_create_3216ed20-d1e2-404e
2017-09-30 11:33:30,426 - MainThread - clusters - INFO - New entity was added
2017-09-30 11:33:30,431 - MainThread - clusters - INFO - Property 'cluster->data_center->id' has correct value: a69d57eb-a2d5-49ae-b6ed-a35e92f337c9
2017-09-30 11:33:30,432 - MainThread - clusters - INFO - Property 'cluster->cpu->type_' has correct value: Intel Conroe Family
2017-09-30 11:33:30,432 - MainThread - clusters - INFO - Property 'cluster->version->major' has correct value: 4
2017-09-30 11:33:30,433 - MainThread - clusters - INFO - Property 'cluster->version->minor' has correct value: 0
2017-09-30 11:33:30,433 - MainThread - clusters - INFO - Property 'cluster->name' has correct value: cl_TestCase18346_REST_ISCS_3011332890
2017-09-30 11:33:30,440 - MainThread - root - INFO - Switch host host_mixed_1 to different cluster cl_TestCase18346_REST_ISCS_3011332890 with {'activate': True}
2017-09-30 11:33:30,442 - MainThread - root - INFO - Checks if host host_mixed_1 is in maintenance state
2017-09-30 11:33:30,445 - MainThread - root - INFO - Returns host host_mixed_1 status
2017-09-30 11:33:30,450 - MainThread - root - INFO - Get host object by host_name host_mixed_1. with {'attribute': 'name'}
2017-09-30 11:33:30,701 - MainThread - root - INFO - Deactivate the host host_mixed_1. with {'expected_status': 'maintenance'}
2017-09-30 11:33:30,705 - MainThread - root - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:33:30,919 - MainThread - root - INFO - Get host hosted-engine object with {'host_name': 'host_mixed_1'}
2017-09-30 11:33:31,083 - MainThread - root - ERROR - Failed to get host hosted-engine object with {'host_name': 'host_mixed_1'}
2017-09-30 11:33:31,087 - MainThread - hosts - INFO - Using Correlation-Id: hosts_syncAction_b5bc0aa3-a25c-4277
2017-09-30 11:33:41,993 - MainThread - hosts - INFO - host status is 'maintenance'
2017-09-30 11:33:42,011 - MainThread - root - INFO - Update properties of host host_mixed_1 (provided in parameters) with {'cluster': 'cl_TestCase18346_REST_ISCS_3011332890'}
2017-09-30 11:33:42,018 - MainThread - root - INFO - Get host object by host_name host_mixed_1. with {'attribute': 'name'}
2017-09-30 11:33:42,381 - MainThread - hosts - INFO - Using Correlation-Id: hosts_update_0c0a5c01-bc8e-4e54
2017-09-30 11:33:43,250 - MainThread - hosts - INFO - host was updated
2017-09-30 11:33:43,265 - MainThread - hosts - INFO - Property 'host->cluster->id' has correct value: bbce0f16-dcde-426e-aa40-3982bbac9465
2017-09-30 11:33:43,284 - MainThread - root - INFO - Activate host host_mixed_1 (set status to UP) with {'wait': True}
2017-09-30 11:33:43,287 - MainThread - root - INFO - Get host object by host_name host_mixed_1. with {'attribute': 'name'}
2017-09-30 11:33:43,514 - MainThread - hosts - INFO - Using Correlation-Id: hosts_syncAction_0dca1982-705f-46f0
2017-09-30 11:33:54,018 - MainThread - hosts - INFO - host status is 'up'
2017-09-30 11:33:54,038 - MainThread - root - INFO - Get SPM host from the list of hosts host_mixed_1, host_mixed_2, host_mixed_3
2017-09-30 11:33:54,046 - MainThread - root - INFO - Checking Storage Pool Manager (SPM) status of the host host_mixed_1.
2017-09-30 11:33:54,051 - MainThread - root - INFO - Get host object by host_name host_mixed_1. with {'attribute': 'name'}
2017-09-30 11:33:54,262 - MainThread - art.ll_lib.hosts - INFO - check_host_spm_status - SPM Status of host host_mixed_1 is: none
2017-09-30 11:33:54,262 - MainThread - root - ERROR - Failed to checking storage pool manager (spm) status of the host host_mixed_1.
2017-09-30 11:33:54,267 - MainThread - root - INFO - Checking Storage Pool Manager (SPM) status of the host host_mixed_2.
2017-09-30 11:33:54,274 - MainThread - root - INFO - Get host object by host_name host_mixed_2. with {'attribute': 'name'}
2017-09-30 11:33:54,488 - MainThread - art.ll_lib.hosts - INFO - check_host_spm_status - SPM Status of host host_mixed_2 is: none
2017-09-30 11:33:54,489 - MainThread - root - ERROR - Failed to checking storage pool manager (spm) status of the host host_mixed_2.
2017-09-30 11:33:54,498 - MainThread - root - INFO - Checking Storage Pool Manager (SPM) status of the host host_mixed_3.
2017-09-30 11:33:54,503 - MainThread - root - INFO - Get host object by host_name host_mixed_3. with {'attribute': 'name'}
2017-09-30 11:33:54,714 - MainThread - art.ll_lib.hosts - INFO - check_host_spm_status - SPM Status of host host_mixed_3 is: spm
2017-09-30 11:33:54,923 - MainThread - hosts - INFO - Using Correlation-Id: hosts_syncAction_12a83744-8022-4552
2017-09-30 11:33:55,962 - MainThread - storagedomains - INFO - Log in to address 10.35.146.129, target iqn.2008-05.com.xtremio:xio00153500071-514f0c50023f6c00
2017-09-30 11:33:55,964 - MainThread - hosts - INFO - Using Correlation-Id: hosts_syncAction_04f70db9-e358-4404
2017-09-30 11:33:57,979 - MainThread - root - INFO - Get Host host_mixed_3 compatibility version
2017-09-30 11:33:57,984 - MainThread - root - INFO - Get host object by host_name host_mixed_3. with {'attribute': 'name'}
2017-09-30 11:33:58,334 - MainThread - root - INFO - Get Cluster golden_env_mixed_1 compatibility version
2017-09-30 11:33:58,475 - MainThread - storagedomains - INFO - Using Correlation-Id: storagedomains_create_c33df9a2-d443-4bb3
2017-09-30 11:34:19,634 - MainThread - storagedomains - INFO - New entity was added
2017-09-30 11:34:19,639 - MainThread - storagedomains - INFO - Property 'storage_domain->storage->type_' has correct value: iscsi
2017-09-30 11:34:19,640 - MainThread - storagedomains - INFO - Property 'storage_domain->storage_format' has correct value: v3
2017-09-30 11:34:19,640 - MainThread - storagedomains - INFO - Property 'storage_domain->name' has correct value: upgrade_4_0_to_4_1_TestCase18346_REST_ISCSI0
2017-09-30 11:34:19,641 - MainThread - storagedomains - INFO - Attribute: import___ changed to: import
2017-09-30 11:34:19,641 - MainThread - storagedomains - INFO - Property 'storage_domain->type_' has correct value: data
2017-09-30 11:34:20,236 - MainThread - storagedomains - INFO - Using Correlation-Id: storagedomains_create_b7dc555f-5a44-410a
2017-09-30 11:35:29,107 - MainThread - storagedomains - INFO - New entity was added
2017-09-30 11:35:29,109 - MainThread - storagedomains - INFO - Property 'storage_domain->id' has correct value: 940de508-9dbe-4783-b8a3-972a70896268
2017-09-30 11:35:29,110 - MainThread - storagedomains - INFO - Attribute: import___ changed to: import
2017-09-30 11:35:29,519 - MainThread - datacenters - INFO - data_center status is 'up'
2017-09-30 11:35:30,207 - MainThread - storagedomains - WARNING - Storage domain upgrade_4_0_to_4_1_TestCase18346_REST_ISCSI0 already activated
2017-09-30 11:35:30,207 - MainThread - art.ll_lib.jobs - INFO - Waiting for jobs ['Adding .* Storage Domain .*', 'Activating Storage Domain .* on Data Center .*']
2017-09-30 11:35:30,311 - MainThread - art.ll_lib.jobs - INFO - Active jobs: []
2017-09-30 11:35:30,415 - MainThread - art.ll_lib.jobs - INFO - JOB 'Adding SAN Storage Domain upgrade_4_0_to_4_1_TestCase18346_REST_ISCSI0' TOOK 18.06 seconds
2017-09-30 11:35:30,534 - MainThread - art.ll_lib.jobs - INFO - All jobs are gone
2017-09-30 11:35:32,788 - MainThread - test_utils - INFO - All tasks are gone
2017-09-30 11:35:32,789 - MainThread - storagedomains - INFO - Importing glance image from rhevm-qe-infra-glance
2017-09-30 11:35:36,697 - MainThread - storagedomains - INFO - Using Correlation-Id: storagedomains_syncAction_46506f45-6c63-4ac5
2017-09-30 11:35:38,447 - MainThread - art.ll_lib.disks - INFO - Waiting for status ok on disks ['disk_TestCase18346_REST_ISCS_3011353278']
2017-09-30 11:38:05,749 - MainThread - storagedomains - INFO - Disk disk_TestCase18346_REST_ISCS_3011353278 have been imported successfully
2017-09-30 11:38:05,750 - MainThread - art.ll_lib.jobs - INFO - Waiting for jobs ['Importing Disk .* to domain .*']
2017-09-30 11:38:05,868 - MainThread - art.ll_lib.jobs - INFO - Active jobs: []
2017-09-30 11:38:05,986 - MainThread - art.ll_lib.jobs - INFO - JOB 'Importing Disk disk_TestCase18346_REST_ISCS_3011353278 to domain upgrade_4_0_to_4_1_TestCase18346_REST_ISCSI0' TOOK 143.078 seconds
2017-09-30 11:38:05,987 - MainThread - art.ll_lib.jobs - INFO - All jobs are gone
2017-09-30 11:38:05,988 - MainThread - root - INFO - Getting all templates in cluster cl_TestCase18346_REST_ISCS_3011332890
2017-09-30 11:38:06,493 - MainThread - root - INFO - Templates in cluster: ['templ_TestCase18346_REST_ISCS_3011353278']
2017-09-30 11:38:07,610 - MainThread - rhevmtests.storage.helpers - INFO - Cloning vm vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:38:09,915 - MainThread - vms - INFO - Using Correlation-Id: vms_create_e74fddcc-2436-4d29
2017-09-30 11:38:11,897 - MainThread - vms - INFO - New entity was added
2017-09-30 11:38:11,905 - MainThread - vms - INFO - Property 'vm->virtio_scsi->enabled' has correct value: true
2017-09-30 11:38:11,905 - MainThread - vms - INFO - Property 'vm->name' has correct value: vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:38:11,905 - MainThread - vms - INFO - Property 'vm->display->type_' has correct value: spice
2017-09-30 11:38:11,906 - MainThread - vms - INFO - Property 'vm->cluster->id' has correct value: bbce0f16-dcde-426e-aa40-3982bbac9465
2017-09-30 11:38:11,908 - MainThread - vms - INFO - Property 'vm->type_' has correct value: desktop
2017-09-30 11:38:11,909 - MainThread - vms - INFO - Property 'vm->template->id' has correct value: 2e4e74a6-7061-4788-a020-667bfe816fcb
2017-09-30 11:38:11,911 - MainThread - vms - INFO - Property 'vm->os->type_' has correct value: rhel_6x64
2017-09-30 11:38:32,465 - MainThread - vms - INFO - vm status is 'down'
2017-09-30 11:38:34,216 - MainThread - diskattachments - INFO - Using Correlation-Id: diskattachments_update_27e53508-fd74-4792
2017-09-30 11:38:35,058 - MainThread - diskattachments - INFO - disk_attachment was updated
2017-09-30 11:38:35,061 - MainThread - diskattachments - INFO - Property 'disk_attachment->interface' has correct value: virtio
2017-09-30 11:38:35,064 - MainThread - diskattachments - INFO - Property 'disk_attachment->bootable' has correct value: true
2017-09-30 11:38:35,089 - MainThread - root - INFO - Add vNIC name nic_TestCase18346_REST_ISCS_3011383506 to VM vm_TestCase18346_REST_ISCS_3011380717 with {'linked': 'true', 'vnic_profile': 'ovirtmgmt', 'network': 'ovirtmgmt', 'plugged': 'true'}
2017-09-30 11:38:35,849 - MainThread - root - INFO - Get VNIC profile object. with {'cluster': 'cl_TestCase18346_REST_ISCS_3011332890', 'name': 'ovirtmgmt', 'network': 'ovirtmgmt'}
2017-09-30 11:38:35,855 - MainThread - root - INFO - Get all the VNIC profiles that belong to a certain network ovirtmgmt with {'cluster': 'cl_TestCase18346_REST_ISCS_3011332890'}
2017-09-30 11:38:35,860 - MainThread - root - INFO - Find desired network ovirtmgmt using cluster cl_TestCase18346_REST_ISCS_3011332890 or data center
2017-09-30 11:38:37,098 - MainThread - art.ll_lib.vms - INFO - Get NICs href from VM vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:38:37,274 - MainThread - nics - INFO - Using Correlation-Id: nics_create_d97e5e4b-14d3-49fc
2017-09-30 11:38:37,875 - MainThread - nics - INFO - New entity was added
2017-09-30 11:38:37,880 - MainThread - nics - INFO - Property 'nic->name' has correct value: nic_TestCase18346_REST_ISCS_3011383506
2017-09-30 11:38:37,882 - MainThread - nics - INFO - Property 'nic->linked' has correct value: true
2017-09-30 11:38:37,884 - MainThread - nics - INFO - Property 'nic->vnic_profile->id' has correct value: 821e5c06-a4ce-43e9-9ac5-f43d6131a139
2017-09-30 11:38:37,886 - MainThread - nics - INFO - Property 'nic->plugged' has correct value: true
2017-09-30 11:38:38,275 - MainThread - vms - INFO - vm status is 'down'
2017-09-30 11:38:38,289 - MainThread - root - INFO - Description : Adds disk to setup with {'provisioned_size': 1073741824, 'format': 'cow', 'bootable': False, 'wipe_after_delete': False, 'alias': 'disk_TestCase18346_REST_ISCS_3011383827', 'storagedomain': 'upgrade_4_0_to_4_1_TestCase18346_REST_ISCSI0', 'shareable': False, 'sparse': True, 'active': True, 'interface': 'virtio'}
2017-09-30 11:38:38,736 - MainThread - art.ll_lib.disks - INFO - Adding disk disk_TestCase18346_REST_ISCS_3011383827
2017-09-30 11:38:38,738 - MainThread - disks - INFO - Using Correlation-Id: disks_create_7c2666f5-9b55-4694
2017-09-30 11:38:39,656 - MainThread - disks - INFO - New entity was added
2017-09-30 11:38:39,659 - MainThread - disks - INFO - Property 'disk->storage_domains->storage_domain->id' has correct value: 940de508-9dbe-4783-b8a3-972a70896268
2017-09-30 11:38:39,660 - MainThread - disks - INFO - Attribute: import___ changed to: import
2017-09-30 11:38:39,661 - MainThread - disks - INFO - Property 'disk->wipe_after_delete' has correct value: false
2017-09-30 11:38:39,661 - MainThread - disks - INFO - Property 'disk->description' has correct value: 
2017-09-30 11:38:39,661 - MainThread - disks - INFO - Property 'disk->provisioned_size' has correct value: 1073741824
2017-09-30 11:38:39,661 - MainThread - disks - INFO - Property 'disk->format' has correct value: cow
2017-09-30 11:38:39,662 - MainThread - disks - INFO - Property 'disk->alias' has correct value: disk_TestCase18346_REST_ISCS_3011383827
2017-09-30 11:38:39,662 - MainThread - disks - INFO - Property 'disk->shareable' has correct value: false
2017-09-30 11:38:39,662 - MainThread - disks - INFO - Property 'disk->sparse' has correct value: true
2017-09-30 11:38:39,663 - MainThread - art.ll_lib.disks - INFO - Waiting for status ok on disks ['disk_TestCase18346_REST_ISCS_3011383827']
2017-09-30 11:38:50,872 - MainThread - art.ll_lib.disks - INFO - Attaching disk disk_TestCase18346_REST_ISCS_3011383827 to vm vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:38:50,873 - MainThread - diskattachments - INFO - Using Correlation-Id: diskattachments_create_b700bbbd-fdec-45b4
2017-09-30 11:38:51,259 - MainThread - diskattachments - INFO - New entity was added
2017-09-30 11:38:51,260 - MainThread - diskattachments - INFO - Property 'disk_attachment->interface' has correct value: virtio
2017-09-30 11:38:51,260 - MainThread - diskattachments - INFO - Property 'disk_attachment->disk->id' has correct value: 11aeb9f1-c5b8-4228-9c87-2ae3cbc2e5de
2017-09-30 11:38:51,261 - MainThread - diskattachments - INFO - Property 'disk_attachment->bootable' has correct value: false
2017-09-30 11:38:51,262 - MainThread - art.ll_lib.disks - INFO - Waiting for status ok on disks ['disk_TestCase18346_REST_ISCS_3011383827']
2017-09-30 11:38:51,749 - MainThread - root - INFO - Start VM vm_TestCase18346_REST_ISCS_3011380717 with {'wait_for_ip': True, 'pause': False, 'use_cloud_init': False, 'timeout': 600, 'wait_for_status': 'up'}
2017-09-30 11:38:52,121 - MainThread - art.ll_lib.vms - INFO - start VM vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:38:52,122 - MainThread - vms - INFO - Using Correlation-Id: vms_syncAction_b7b4cc9d-02dd-432d
2017-09-30 11:38:52,722 - MainThread - vms - INFO - Waiting for query `name=vm_TestCase18346_REST_ISCS_3011380717 and status=up or name=vm_TestCase18346_REST_ISCS_3011380717 and status=up` and event_id None up to 600 seconds,sampling every 10 second.
2017-09-30 11:40:04,660 - MainThread - art.ll_lib.vms - INFO - Get VM vm_TestCase18346_REST_ISCS_3011380717 host
2017-09-30 11:40:05,190 - MainThread - root - INFO - Get host host_mixed_1 IP from engine by host host_mixed_1 name
2017-09-30 11:40:05,194 - MainThread - root - INFO - Get host object by host_name host_mixed_1. with {'attribute': 'name'}
2017-09-30 11:40:06,623 - MainThread - art.ll_lib.vms - INFO - Waiting for IP from vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:40:11,457 - MainThread - VDS - INFO - [10.35.82.63] Executing command python -c from vdsm import client;cli = client.connect('localhost', 54321, use_tls=True);print cli.Host.getVMFullList(**{})
2017-09-30 11:40:19,026 - MainThread - VDS - INFO - [10.35.82.63] Executing command python -c from vdsm import client;cli = client.connect('localhost', 54321, use_tls=True);print cli.VM.getStats(**{'vmID': 'e60c05b6-a495-4e38-aaef-e9251b6b32de'})
2017-09-30 11:40:24,468 - MainThread - art.ll_lib.vms - ERROR - No interfaces found for VM vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:40:36,274 - MainThread - VDS - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:40:43,699 - MainThread - VDS - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:40:50,533 - MainThread - art.ll_lib.vms - ERROR - No IP was found for VM vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:41:15,048 - MainThread - art.ll_lib.vms - INFO - Send ICMP to 10.35.82.169
2017-09-30 11:41:22,209 - MainThread - rhevmtests.storage.helpers - INFO - Get IP from VM vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:41:22,211 - MainThread - art.ll_lib.vms - INFO - Get VM vm_TestCase18346_REST_ISCS_3011380717 host
2017-09-30 11:41:23,045 - MainThread - root - INFO - Get host host_mixed_1 IP from engine by host host_mixed_1 name
2017-09-30 11:41:23,050 - MainThread - root - INFO - Get host object by host_name host_mixed_1. with {'attribute': 'name'}
2017-09-30 11:41:23,307 - MainThread - art.ll_lib.vms - INFO - Waiting for IP from vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:41:27,827 - MainThread - VDS - INFO - [10.35.82.63] Executing command python -c from vdsm import client;cli = client.connect('localhost', 54321, use_tls=True);print cli.Host.getVMFullList(**{})
2017-09-30 11:41:35,086 - MainThread - VDS - INFO - [10.35.82.63] Executing command python -c from vdsm import client;cli = client.connect('localhost', 54321, use_tls=True);print cli.VM.getStats(**{'vmID': 'e60c05b6-a495-4e38-aaef-e9251b6b32de'})
2017-09-30 11:41:40,808 - MainThread - art.ll_lib.vms - INFO - Send ICMP to 10.35.82.169
2017-09-30 11:41:48,509 - MainThread - rhevmtests.storage.helpers - INFO - Create VM instance with root user from vm with ip 10.35.82.169
2017-09-30 11:41:48,846 - MainThread - rhevmtests.storage.helpers - INFO - Find disk logical name for disk with alias disk_TestCase18346_REST_ISCS_3011383827 on vm vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:41:48,846 - MainThread - art.ll_lib.vms - INFO - Get VM vm_TestCase18346_REST_ISCS_3011380717 host
2017-09-30 11:41:49,674 - MainThread - root - INFO - Get IP of a host host_mixed_1 with given name in RHEVM
2017-09-30 11:41:49,678 - MainThread - root - INFO - Get host object by host_name host_mixed_1. with {'attribute': 'name'}
2017-09-30 11:41:55,758 - MainThread - VDS - INFO - [10.35.82.63] Executing command python -c from vdsm import client;cli = client.connect('localhost', 54321, use_tls=True);print cli.VM.getStats(**{'vmID': 'e60c05b6-a495-4e38-aaef-e9251b6b32de'})
2017-09-30 11:42:01,235 - MainThread - rhevmtests.storage.helpers - INFO - The logical volume name for the requested disk is: '/dev/vdb'
2017-09-30 11:42:01,236 - MainThread - rhevmtests.storage.helpers - INFO - Creating label: /sbin/parted /dev/vdb --script -- mklabel gpt
2017-09-30 11:42:06,021 - MainThread - rhevmtests.storage.helpers - INFO - Output after creating disk label: 
2017-09-30 11:42:06,022 - MainThread - rhevmtests.storage.helpers - INFO - Creating partition /sbin/parted /dev/vdb --script -- mkpart primary ext4 0 100%
2017-09-30 11:42:10,034 - MainThread - rhevmtests.storage.helpers - INFO - Output after creating partition: 
2017-09-30 11:42:10,036 - MainThread - rhevmtests.storage.helpers - INFO - Creating a File-system on first partition
2017-09-30 11:42:22,966 - MainThread - rhevmtests.storage.helpers - INFO - Get IP from VM vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:42:22,967 - MainThread - art.ll_lib.vms - INFO - Get VM vm_TestCase18346_REST_ISCS_3011380717 host
2017-09-30 11:42:23,541 - MainThread - root - INFO - Get host host_mixed_1 IP from engine by host host_mixed_1 name
2017-09-30 11:42:23,545 - MainThread - root - INFO - Get host object by host_name host_mixed_1. with {'attribute': 'name'}
2017-09-30 11:42:23,824 - MainThread - art.ll_lib.vms - INFO - Waiting for IP from vm_TestCase18346_REST_ISCS_3011380717
2017-09-30 11:42:28,866 - MainThread - VDS - INFO - [10.35.82.63] Executing command python -c from vdsm import client;cli = client.connect('localhost', 54321, use_tls=True);print cli.Host.getVMFullList(**{})
2017-09-30 11:42:35,979 - MainThread - VDS - INFO - [10.35.82.63] Executing command python -c from vdsm import client;cli = client.connect('localhost', 54321, use_tls=True);print cli.VM.getStats(**{'vmID': 'e60c05b6-a495-4e38-aaef-e9251b6b32de'})
2017-09-30 11:42:42,532 - MainThread - art.ll_lib.vms - INFO - Send ICMP to 10.35.82.169
2017-09-30 11:42:49,832 - MainThread - rhevmtests.storage.helpers - INFO - Create VM instance with root user from vm with ip 10.35.82.169
2017-09-30 11:42:52,893 - MainThread - rhevmtests.storage.helpers - INFO - Checking full path /mount-point_3011421287/test_file0
2017-09-30 11:43:00,719 - MainThread - root - INFO - Add snapshot to VM vm_TestCase18346_REST_ISCS_3011380717 with {'description': 'snap_TestCase18346_REST_ISCS_30114300700', 'wait': True}
2017-09-30 11:43:01,239 - MainThread - snapshots - INFO - Using Correlation-Id: snapshots_create_876dcd49-9137-4d3f
2017-09-30 11:43:04,589 - MainThread - snapshots - INFO - New entity was added
2017-09-30 11:43:04,603 - MainThread - snapshots - INFO - Property 'snapshot->description' has correct value: snap_TestCase18346_REST_ISCS_30114300700
2017-09-30 11:43:04,611 - MainThread - art.ll_lib.jobs - INFO - Waiting for jobs ['Creating VM Snapshot .* for VM .*']
2017-09-30 11:43:04,761 - MainThread - art.ll_lib.jobs - INFO - Active jobs: ['Creating VM Snapshot snap_TestCase18346_REST_ISCS_30114300700 for VM vm_TestCase18346_REST_ISCS_3011380717']
2017-09-30 11:43:15,068 - MainThread - art.ll_lib.jobs - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:44:16,692 - MainThread - art.ll_lib.jobs - INFO - Active jobs: []
2017-09-30 11:44:16,808 - MainThread - art.ll_lib.jobs - INFO - JOB 'Creating VM Snapshot snap_TestCase18346_REST_ISCS_30114300700 for VM vm_TestCase18346_REST_ISCS_3011380717' TOOK 72.423 seconds
2017-09-30 11:44:16,808 - MainThread - art.ll_lib.jobs - INFO - All jobs are gone
2017-09-30 11:44:17,978 - MainThread - art.ll_lib.vms - INFO - Snapshots found: ['Active VM', 'snap_TestCase18346_REST_ISCS_30114300700']
2017-09-30 11:44:19,301 - MainThread - snapshots - INFO - snapshot status is 'ok'
2017-09-30 11:44:20,121 - MainThread - art.ll_lib.vms - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:44:20,122 - MainThread - art.ll_lib.vms - INFO - Waiting until snapshots: snap_TestCase18346_REST_ISCS_30114300700 of vm_TestCase18346_REST_ISCS_3011380717 vm are in one of following states: ['ok']
2017-09-30 11:44:20,882 - MainThread - art.ll_lib.jobs - INFO - Waiting for jobs ['Creating VM Snapshot .* for VM .*']
2017-09-30 11:44:21,000 - MainThread - art.ll_lib.jobs - INFO - Active jobs: []
2017-09-30 11:44:21,109 - MainThread - art.ll_lib.jobs - INFO - JOB 'Creating VM Snapshot snap_TestCase18346_REST_ISCS_30114300700 for VM vm_TestCase18346_REST_ISCS_3011380717' TOOK 72.423 seconds
2017-09-30 11:44:21,110 - MainThread - art.ll_lib.jobs - INFO - All jobs are gone
2017-09-30 11:44:24,480 - MainThread - rhevmtests.storage.helpers - INFO - Checking full path /mount-point_3011421287/test_file1
2017-09-30 11:44:30,167 - MainThread - root - INFO - Add snapshot to VM vm_TestCase18346_REST_ISCS_3011380717 with {'description': 'snap_TestCase18346_REST_ISCS_30114430161', 'wait': True}
2017-09-30 11:44:30,468 - MainThread - snapshots - INFO - Using Correlation-Id: snapshots_create_fa072481-1c16-451f
2017-09-30 11:44:35,092 - MainThread - snapshots - INFO - New entity was added
2017-09-30 11:44:35,095 - MainThread - snapshots - INFO - Property 'snapshot->description' has correct value: snap_TestCase18346_REST_ISCS_30114430161
2017-09-30 11:44:35,097 - MainThread - art.ll_lib.jobs - INFO - Waiting for jobs ['Creating VM Snapshot .* for VM .*']
2017-09-30 11:44:35,209 - MainThread - art.ll_lib.jobs - INFO - Active jobs: ['Creating VM Snapshot snap_TestCase18346_REST_ISCS_30114430161 for VM vm_TestCase18346_REST_ISCS_3011380717']
2017-09-30 11:44:45,480 - MainThread - art.ll_lib.jobs - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:46:07,591 - MainThread - art.ll_lib.jobs - INFO - Active jobs: []
2017-09-30 11:46:07,706 - MainThread - art.ll_lib.jobs - INFO - JOB 'Creating VM Snapshot snap_TestCase18346_REST_ISCS_30114430161 for VM vm_TestCase18346_REST_ISCS_3011380717' TOOK 95.351 seconds
2017-09-30 11:46:07,707 - MainThread - art.ll_lib.jobs - INFO - All jobs are gone
2017-09-30 11:46:09,598 - MainThread - art.ll_lib.vms - INFO - Snapshots found: ['Active VM', 'snap_TestCase18346_REST_ISCS_30114300700', 'snap_TestCase18346_REST_ISCS_30114430161']
2017-09-30 11:46:11,169 - MainThread - snapshots - INFO - snapshot status is 'ok'
2017-09-30 11:46:12,289 - MainThread - art.ll_lib.vms - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:46:12,290 - MainThread - art.ll_lib.vms - INFO - Waiting until snapshots: snap_TestCase18346_REST_ISCS_30114430161 of vm_TestCase18346_REST_ISCS_3011380717 vm are in one of following states: ['ok']
2017-09-30 11:46:13,464 - MainThread - art.ll_lib.jobs - INFO - Waiting for jobs ['Creating VM Snapshot .* for VM .*']
2017-09-30 11:46:13,583 - MainThread - art.ll_lib.jobs - INFO - Active jobs: []
2017-09-30 11:46:13,695 - MainThread - art.ll_lib.jobs - INFO - JOB 'Creating VM Snapshot snap_TestCase18346_REST_ISCS_30114430161 for VM vm_TestCase18346_REST_ISCS_3011380717' TOOK 95.351 seconds
2017-09-30 11:46:13,695 - MainThread - art.ll_lib.jobs - INFO - All jobs are gone
2017-09-30 11:46:13,700 - MainThread - art.logging - INFO - ================================================================================
2017-09-30 11:46:13,700 - MainThread - art.logging - INFO - Test Name: rhevmtests.storage.storage_qcow2_v3.test_qcow2_v3.TestCase18346_REST_ISCSI.test_live_merge_old_version_image_with_new_version_image
2017-09-30 11:46:13,701 - MainThread - art.logging - INFO - Iteration number: 1
2017-09-30 11:46:13,704 - MainThread - root - INFO - Update cluster cl_TestCase18346_REST_ISCS_3011332890 with {'version': '4.1'}
2017-09-30 11:46:13,823 - MainThread - clusters - INFO - Using Correlation-Id: clusters_update_5a0f4808-dabe-4341
2017-09-30 11:46:14,690 - MainThread - clusters - INFO - cluster was updated
2017-09-30 11:46:14,693 - MainThread - clusters - INFO - Property 'cluster->version->major' has correct value: 4
2017-09-30 11:46:14,693 - MainThread - clusters - INFO - Property 'cluster->version->minor' has correct value: 1
2017-09-30 11:46:14,875 - MainThread - art.ll_lib.dcs - INFO - Update datacenter dc_TestCase18346_REST_ISCS_3011332890 with {'version': '4.1'}
2017-09-30 11:46:14,875 - MainThread - datacenters - INFO - Using Correlation-Id: datacenters_update_59868267-3052-4e82
2017-09-30 11:46:23,986 - MainThread - datacenters - INFO - data_center was updated
2017-09-30 11:46:23,987 - MainThread - datacenters - INFO - Property 'data_center->version->major' has correct value: 4
2017-09-30 11:46:23,987 - MainThread - datacenters - INFO - Property 'data_center->version->minor' has correct value: 1
2017-09-30 11:46:24,902 - MainThread - rhevmtests.storage.storage_qcow2_v3.test_qcow2_v3 - INFO - Checking that upgrade_4_0_to_4_1_TestCase18346_REST_ISCSI0 was upgraded: True
2017-09-30 11:46:25,395 - MainThread - rhevmtests.storage.storage_qcow2_v3.test_qcow2_v3 - INFO - The following disks exist ['disk_TestCase18346_REST_ISCS_3011353278', 'snapshot_memory', 'disk_TestCase18346_REST_ISCS_3011383827', 'snapshot_memory', 'snapshot_metadata', 'vm_TestCase18346_REST_ISCS_3011380717_Disk_0', 'snapshot_metadata'] in storage domain upgrade_4_0_to_4_1_TestCase18346_REST_ISCSI0
2017-09-30 11:46:26,800 - MainThread - art.ll_lib.vms - INFO - Snapshots found: ['Active VM', 'snap_TestCase18346_REST_ISCS_30114300700', 'snap_TestCase18346_REST_ISCS_30114430161', 'Next Run configuration snapshot']
2017-09-30 11:46:27,718 - MainThread - rhevmtests.storage.storage_qcow2_v3.test_qcow2_v3 - INFO - Qcow version on snapshot snap_TestCase18346_REST_ISCS_30114300700 disks version before merge are: [None, None]
2017-09-30 11:46:28,537 - MainThread - rhevmtests.storage.storage_qcow2_v3.helpers - INFO - disk disk_TestCase18346_REST_ISCS_3011383827 was updated to qcow2_v2
2017-09-30 11:46:28,537 - MainThread - rhevmtests.storage.storage_qcow2_v3.helpers - INFO - disk vm_TestCase18346_REST_ISCS_3011380717_Disk_0 was updated to qcow2_v2
2017-09-30 11:46:29,113 - MainThread - rhevmtests.storage.storage_qcow2_v3.helpers - INFO - Snapshot disk vm_TestCase18346_REST_ISCS_3011380717_Disk_0 was upgraded to qcow version qcow2_v2
2017-09-30 11:46:29,113 - MainThread - rhevmtests.storage.storage_qcow2_v3.helpers - INFO - Snapshot disk disk_TestCase18346_REST_ISCS_3011383827 was upgraded to qcow version qcow2_v2
2017-09-30 11:46:30,528 - MainThread - root - INFO - Add snapshot to VM vm_TestCase18346_REST_ISCS_3011380717 with {'description': 'snap_test_live_merge_old_ver_30114630523', 'wait': True}
2017-09-30 11:46:30,819 - MainThread - snapshots - INFO - Using Correlation-Id: snapshots_create_b47b10cd-1021-440d
2017-09-30 11:46:34,136 - MainThread - snapshots - INFO - New entity was added
2017-09-30 11:46:34,138 - MainThread - snapshots - INFO - Property 'snapshot->description' has correct value: snap_test_live_merge_old_ver_30114630523
2017-09-30 11:46:34,140 - MainThread - art.ll_lib.jobs - INFO - Waiting for jobs ['Creating VM Snapshot .* for VM .*']
2017-09-30 11:46:34,254 - MainThread - art.ll_lib.jobs - INFO - Active jobs: ['Creating VM Snapshot snap_test_live_merge_old_ver_30114630523 for VM vm_TestCase18346_REST_ISCS_3011380717']
2017-09-30 11:46:44,505 - MainThread - art.ll_lib.jobs - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:49:19,097 - MainThread - art.ll_lib.jobs - INFO - Active jobs: []
2017-09-30 11:49:19,263 - MainThread - art.ll_lib.jobs - INFO - JOB 'Creating VM Snapshot snap_test_live_merge_old_ver_30114630523 for VM vm_TestCase18346_REST_ISCS_3011380717' TOOK 164.864 seconds
2017-09-30 11:49:19,263 - MainThread - art.ll_lib.jobs - INFO - All jobs are gone
2017-09-30 11:49:21,379 - MainThread - art.ll_lib.vms - INFO - Snapshots found: ['Active VM', 'snap_TestCase18346_REST_ISCS_30114300700', 'snap_TestCase18346_REST_ISCS_30114430161', 'Next Run configuration snapshot', 'snap_test_live_merge_old_ver_30114630523']
2017-09-30 11:49:23,645 - MainThread - snapshots - INFO - snapshot status is 'ok'
2017-09-30 11:49:25,423 - MainThread - art.ll_lib.vms - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:49:28,499 - MainThread - root - INFO - Add snapshot to VM vm_TestCase18346_REST_ISCS_3011380717 with {'description': 'snap_test_live_merge_old_ver_30114928484', 'wait': True}
2017-09-30 11:49:28,803 - MainThread - snapshots - INFO - Using Correlation-Id: snapshots_create_12dcd6ee-47b1-4fb7
2017-09-30 11:49:32,378 - MainThread - snapshots - INFO - New entity was added
2017-09-30 11:49:32,381 - MainThread - snapshots - INFO - Property 'snapshot->description' has correct value: snap_test_live_merge_old_ver_30114928484
2017-09-30 11:49:32,383 - MainThread - art.ll_lib.jobs - INFO - Waiting for jobs ['Creating VM Snapshot .* for VM .*']
2017-09-30 11:49:32,519 - MainThread - art.ll_lib.jobs - INFO - Active jobs: ['Creating VM Snapshot snap_test_live_merge_old_ver_30114928484 for VM vm_TestCase18346_REST_ISCS_3011380717']
2017-09-30 11:49:42,835 - MainThread - art.ll_lib.jobs - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:52:48,250 - MainThread - art.ll_lib.jobs - INFO - Active jobs: []
2017-09-30 11:52:48,373 - MainThread - art.ll_lib.jobs - INFO - JOB 'Creating VM Snapshot snap_test_live_merge_old_ver_30114928484 for VM vm_TestCase18346_REST_ISCS_3011380717' TOOK 195.509 seconds
2017-09-30 11:52:48,375 - MainThread - art.ll_lib.jobs - INFO - All jobs are gone
2017-09-30 11:52:51,095 - MainThread - art.ll_lib.vms - INFO - Snapshots found: ['Active VM', 'snap_TestCase18346_REST_ISCS_30114300700', 'snap_TestCase18346_REST_ISCS_30114430161', 'Next Run configuration snapshot', 'snap_test_live_merge_old_ver_30114630523', 'snap_test_live_merge_old_ver_30114928484']
2017-09-30 11:52:53,858 - MainThread - snapshots - INFO - snapshot status is 'ok'
2017-09-30 11:52:56,167 - MainThread - art.ll_lib.vms - DEBUG - Skipping duplicate log-messages...
2017-09-30 11:53:01,620 - MainThread - art.ll_lib.vms - INFO - Removing snapshot snap_test_live_merge_old_ver_30114630523
2017-09-30 11:53:01,620 - MainThread - snapshots - INFO - Using Correlation-Id: snapshots_delete_878b9fe9-b20d-4508
2017-09-30 11:53:02,555 - MainThread - art.ll_lib.vms - INFO - Waiting until snapshot: snap_test_live_merge_old_ver_30114630523 of vm: vm_TestCase18346_REST_ISCS_3011380717 is gone
Comment 1 Avihai 2017-09-30 10:42:09 UTC 
Regression as ~2-3 weeks ago same test ran without issues.

Engine build that the same test passed :
ovirt-engine-4.2.0-0.0.master.20170907100709.git14accac.el7.centos.noarch

Link to the run that passed:
https://rhv-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/job/rhv-4.2-ge-runner-storage/535
Comment 2 Ala Hino 2017-10-25 21:37:10 UTC 
Avihai,

Can you please retry same scenario on build 4.1.7.4?
Comment 3 Ala Hino 2017-10-25 21:39:42 UTC 
(In reply to Ala Hino from comment #2)
> Avihai,
> 
> Can you please retry same scenario on build 4.1.7.4?

I mean on a latest build.
Comment 4 Avihai 2017-10-26 08:43:28 UTC 
Checked on vdsm 4.20.3-224.gitef2ce48 & Engine ovirt-engine-4.2.0-0.0.master.20171025204923.git6f4cbc5 .

Test failed live merge with the following Engine Errors (Errors were not seen in vdsm log - see logs attached):

Engine
2017-10-26 10:41:02,936+03 ERROR [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-10) [snapshots_delete_8aa0b09e-cdc0-4855] The following images were not removed: [cb2fe2bc-4c18-497d-ab14-ef594a924292]
2017-10-26 10:41:06,353+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-1) [snapshots_delete_8aa0b09e-cdc0-4855] Failed in 'GetVolumeInfoVDS' method

2017-10-26 10:41:14,129+03 ERROR [org.ovirt.engine.core.bll.ReduceImageCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-2) [snapshots_delete_8aa0b09e-cdc0-4855] Command 'org.ovirt.engine.core.bll.ReduceImageCommand' failed: ReduceVolumeSupported has no value for version: 4.1
2017-10-26 10:41:14,129+03 ERROR [org.ovirt.engine.core.bll.ReduceImageCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-2) [snapshots_delete_8aa0b09e-cdc0-4855] Exception: java.lang.IllegalArgumentException: ReduceVolumeSupported has no value for version: 4.1
        at org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils.getValue(DBConfigUtils.java:65) [dal.jar:]
2017-10-26 10:41:24,296+03 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-88) [snapshots_delete_8aa0b09e-cdc0-4855] Command id: '284b7ee0-cc1a-48f2-a886-c1d7a0558e5b failed child command status for step 'REDUCE_IMAGE'
2017-10-26 10:41:24,296+03 INFO  [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommandCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-88) [snapshots_delete_8aa0b09e-cdc0-4855] Command 'RemoveSnapshotSingleDiskLive' id: '284b7ee0-cc1a-48f2-a886-c1d7a0558e5b' child commands '[f6a00f3c-3b5d-41b1-a3d7-7c4761793988, d7a938ca-7858-4887-8aa1-aa07359cfd03, 35cb7418-7da9-41dd-a387-397339359e2a, 78ba89e6-7ab8-4a60-97e5-086afab4bdbd, 9408f615-78e0-4d4c-a3a3-7e05e18fdc38, 4fc475df-42b7-4ecb-b154-5cb6a8fdf65b, ada1299e-72c8-4d30-89cb-f5f2df4a2f32]' executions were completed, status 'FAILED'
2017-10-26 10:41:25,345+03 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [snapshots_delete_8aa0b09e-cdc0-4855] Merging of snapshot 'dafda09c-6e92-4354-9359-1fc2ea7dc3f4' images '79fb8c86-e138-4634-a0ad-95d3cdbc5e54'..'cb2fe2bc-4c18-497d-ab14-ef594a924292' failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation.
2017-10-26 10:41:25,382+03 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [snapshots_delete_8aa0b09e-cdc0-4855] Ending command 'org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand' with failure.
Comment 5 Avihai 2017-10-26 08:43:58 UTC 
Created attachment 1343599 [details]
engine , vdsm  log
Comment 6 Ala Hino 2017-10-26 08:53:52 UTC 
This is a different error. This error is at reduce volume step, which means that merge succeeded.

What engine version are you using?
Comment 7 Avihai 2017-10-26 08:58:40 UTC 
(In reply to Ala Hino from comment #6)
> This is a different error. This error is at reduce volume step, which means
> that merge succeeded.
> 
> What engine version are you using?

Engine ovirt-engine-4.2.0-0.0.master.20171025204923.git6f4cbc5
vdsm 4.20.3-224.gitef2ce48
Comment 8 Ala Hino 2017-10-26 09:03:13 UTC 
(In reply to Avihai from comment #7)
> (In reply to Ala Hino from comment #6)
> > This is a different error. This error is at reduce volume step, which means
> > that merge succeeded.
> > 
> > What engine version are you using?
> 
> Engine ovirt-engine-4.2.0-0.0.master.20171025204923.git6f4cbc5
> vdsm 4.20.3-224.gitef2ce48

And the Vm is running on 4.1 cluster?
Comment 9 Avihai 2017-10-26 09:24:48 UTC 
(In reply to Ala Hino from comment #8)
> (In reply to Avihai from comment #7)
> > (In reply to Ala Hino from comment #6)
> > > This is a different error. This error is at reduce volume step, which means
> > > that merge succeeded.
> > > 
> > > What engine version are you using?
> > 
> > Engine ovirt-engine-4.2.0-0.0.master.20171025204923.git6f4cbc5
> > vdsm 4.20.3-224.gitef2ce48
> 
> And the Vm is running on 4.1 cluster?

Yes, Its the same test as in original description.

Automation TestCase18346 description:

    1. Create DC + cluster on v3
    2. Create a VM with thin disk & start VM
    3. Write data (file1) and Create snapshots s1
    4. Write data (file2) and Create snapshots s2
    5. Upgrade the cluster+DC from v3 to v4 (4.0 -> 4.1 )
    4. Verify that the snapshot images are version 0.10
    5. Write data (file3)
    6. Create snapshot s3 & verify the snapshot image is version 0.10
    7. Create snapshot s4 & verify the snapshot image is version 1.1
    8. Deleted snapshot s3 and verify that the live merge is successful
Comment 10 Ala Hino 2017-10-26 10:04:44 UTC 
Can you please upload the result of the following SQL?

select * from vdc_options where option_name = 'ReduceVolumeSupported'
Comment 11 Avihai 2017-10-26 12:52:57 UTC 
(In reply to Ala Hino from comment #10)
> Can you please upload the result of the following SQL?
> 
> select * from vdc_options where option_name = 'ReduceVolumeSupported'

engine=# select * from vdc_options where option_name = 'ReduceVolumeSupported';
 option_id |      option_name      | option_value | version 
-----------+-----------------------+--------------+---------
       137 | ReduceVolumeSupported | true         | 4.2
(1 row)
Comment 12 Avihai 2017-10-29 16:21:31 UTC 
verified .

Engine: 4.2.0-0.0.master.20171027213842.gitded437c
VDSM: 4.20.4-12.git11d6d3d
Comment 13 Sandro Bonazzola 2017-12-20 10:56:14 UTC 
This bugzilla is included in oVirt 4.2.0 release, published on Dec 20th 2017.

Since the problem described in this bug report should be
resolved in oVirt 4.2.0 release, published on Dec 20th 2017, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.
Note You need to log in before you can comment on or make changes to this bug.