Created attachment 1474289 [details] engine and VDSM logs Description of problem: VDSM host_mixed_3 : de97e1f6323 < 0faa3c05-2ebd-43db-8330-5ed4b85e4b7c < 1ced9bf3-5c67-4bd0-b45d-28cb1256317e < 5209ccf4-a55e-4175-b3c0-a5a9e0999f36 (top), disk='sdb', base='sdb[2]', top='sdb[1]', bandwidth=0, flags=8 (vm:5972) 2018-07-26 09:52:40,780+0300 ERROR (jsonrpc/1) [virt.vm] (vmId='fba3309d-6cf0-4cd2-b376-398a353f22f2') Live merge failed (job: 61c3d669-0a51-49e6-9d44-15f52dcd83f2) (vm:5978) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 5976, in merge bandwidth, flags) File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 98, in f ret = attr(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/common/libvirtconnection.py", line 130, in wrapper ret = f(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/common/function.py", line 92, in wrapper return func(inst, *args, **kwargs) File "/usr/lib64/python2.7/site-packages/libvirt.py", line 708, in blockCommit if ret == -1: raise libvirtError ('virDomainBlockCommit() failed', dom=self) libvirtError: internal error: child reported: Kernel does not provide mount namespace: No such file or directory Engine log: 2018-07-26 09:52:40,925+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-1) [snapshots_delete_6bbd2321-c827-4862] START, MergeVDSCommand(Hos tName = host_mixed_3, MergeVDSCommandParameters:{hostId='6fbf48e6-dbf1-4b5c-b04d-37e4a29a93e7', vmId='fba3309d-6cf0-4cd2-b376-398a353f22f2', storagePoolId='7a54dd4e-8fdb-11e8-b401-001a4a168bf8', storageDomainId= 'f878d3c9-0a1a-4c70-9b88-d70cda36e7ba', imageGroupId='4e38d201-3f04-4854-9089-b16345c6c807', imageId='f0c2d698-7a46-4f1c-a9e7-b907e7e68af6', baseImageId='3cfbaf99-0973-444b-95e6-970e3a80fe03', topImageId='e22a7270-8c51-40b3-b412-6455f2080bd7', bandwidth='0'}), log id: 6e8ae03d 2018-07-26 09:52:41,601+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-7) [snapshots_delete_6bbd2321-c827-4862] Failed in 'MergeVDS' method 2018-07-26 09:52:41,607+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-commandCoordinator-Thread-7) [snapshots_delete_6bbd2321-c827-4862] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_3 command MergeVDS failed: General Exception: ("VM 'fba3309d-6cf0-4cd2-b376-398a353f22f2' was not defined yet or was undefined",) 2018-07-26 09:52:41,607+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-7) [snapshots_delete_6bbd2321-c827-4862] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand' return value 'StatusOnlyReturn [status=Status [code=100, message=General Exception: ("VM 'fba3309d-6cf0-4cd2-b376-398a353f22f2' was not defined yet or was undefined",)]]' 2018-07-26 09:52:41,607+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-7) [snapshots_delete_6bbd2321-c827-4862] HostName = host_mixed_3 2018-07-26 09:52:41,607+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-7) [snapshots_delete_6bbd2321-c827-4862] Command 'MergeVDSCommand(HostName = host_mixed_3, MergeVDSCommandParameters:{hostId='6fbf48e6-dbf1-4b5c-b04d-37e4a29a93e7', vmId='fba3309d-6cf0-4cd2-b376-398a353f22f2', storagePoolId='7a54dd4e-8fdb-11e8-b401-001a4a168bf8', storageDomainId='f878d3c9-0a1a-4c70-9b88-d70cda36e7ba', imageGroupId='92a86cf9-4f69-45ac-a470-7c222b784599', imageId='5209ccf4-a55e-4175-b3c0-a5a9e0999f36', baseImageId='0faa3c05-2ebd-43db-8330-5ed4b85e4b7c', topImageId='1ced9bf3-5c67-4bd0-b45d-28cb1256317e', bandwidth='0'})' execution failed: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = General Exception: ("VM 'fba3309d-6cf0-4cd2-b376-398a353f22f2' was not defined yet or was undefined",), code = 100 2018-07-26 09:52:41,607+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-7) [snapshots_delete_6bbd2321-c827-4862] FINISH, MergeVDSCommand, log id: 175e7039 2018-07-26 09:52:41,607+03 ERROR [org.ovirt.engine.core.bll.MergeCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-7) [snapshots_delete_6bbd2321-c827-4862] Engine exception thrown while sending merge command: org.ovirt.engine.core.common.errors.EngineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = General Exception: ("VM 'fba3309d-6cf0-4cd2-b376-398a353f22f2' was not defined yet or was undefined",), code = 100 (Failed with error GeneralException and code 100) at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:118) [bll.jar:] at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:2045) [bll.jar:] at org.ovirt.engine.core.bll.MergeCommand.executeCommand(MergeCommand.java:45) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1133) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1285) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1934) [bll.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202) [utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137) [utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:] at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1345) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:400) [bll.jar:] at org.ovirt.engine.core.bll.executor.DefaultBackendActionExecutor.execute(DefaultBackendActionExecutor.java:13) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:468) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:714) [bll.jar:] : Version-Release number of selected component (if applicable): How reproducible: Happened once so far Steps to Reproduce: ================================================================================ 09:43:37 2018-07-26 09:43:37,387 INFO Test Setup 1: Creating VM vm_TestCase12215_2609433738 09:44:10 2018-07-26 09:44:10,845 INFO Test Setup 2: Starting VM vm_TestCase12215_2609433738 09:44:10 2018-07-26 09:44:10,849 INFO Test Setup 3: [class] Start VM vm_TestCase12215_2609433738 with {'wait_for_ip': True, 'pause': False, 'use_cloud_init': False, 'timeout': 600, 'wait_for_status': 'up'} 09:45:20 2018-07-26 09:45:20,840 INFO Test Setup 4: Creating disks with filesystem and attach to VM vm_TestCase12215_2609433738 09:46:17 2018-07-26 09:46:17,865 INFO 283: storage/rhevmtests.storage.storage_remove_snapshots.test_live_merge.TestCase12215.test_snapshot_deletion_of_all_snapshots[iscsi] 09:46:17 2018-07-26 09:46:17,865 INFO STORAGE: ISCSI 09:46:18 2018-07-26 09:46:18,457 INFO Test Step 5: Creating files on vm's 'vm_TestCase12215_2609433738' disks 09:46:18 2018-07-26 09:46:18,554 INFO Test Step 6: Creating file /mount-point_2609454605/test_file_0 09:46:20 2018-07-26 09:46:20,582 INFO Test Step 7: Creating file /mount-point_2609455580/test_file_0 09:46:22 2018-07-26 09:46:22,595 INFO Test Step 8: Creating file /mount-point_2609460545/test_file_0 09:46:24 2018-07-26 09:46:24,550 INFO Test Step 9: Creating file /mount-point_2609461508/test_file_0 09:46:27 2018-07-26 09:46:27,088 INFO Test Step 10: Creating snapshot of vm vm_TestCase12215_2609433738 09:46:39 2018-07-26 09:46:39,020 INFO Test Step 11: Before snapshot: 5 volumes 09:46:39 2018-07-26 09:46:39,204 INFO Test Step 12: Stop vm vm_TestCase12215_2609433738 with {'async': 'true'} 09:46:43 2018-07-26 09:46:43,617 INFO Test Step 13: Adding new snapshot to vm vm_TestCase12215_2609433738 09:46:43 2018-07-26 09:46:43,620 INFO Test Step 14: Add snapshot to VM vm_TestCase12215_2609433738 with {'description': 'snapshot_12215_iscsi_0', 'wait': True} 09:48:28 2018-07-26 09:48:28,906 INFO Test Step 15: After snapshot: 10 volumes 09:48:29 2018-07-26 09:48:29,011 INFO Test Step 16: Creating files on vm's 'vm_TestCase12215_2609433738' disks 09:48:29 2018-07-26 09:48:29,105 INFO Test Step 17: Creating file /mount-point_2609454605/test_file_1 09:48:31 2018-07-26 09:48:30,945 INFO Test Step 18: Creating file /mount-point_2609455580/test_file_1 09:48:32 2018-07-26 09:48:32,828 INFO Test Step 19: Creating file /mount-point_2609460545/test_file_1 09:48:34 2018-07-26 09:48:34,800 INFO Test Step 20: Creating file /mount-point_2609461508/test_file_1 09:48:37 2018-07-26 09:48:37,322 INFO Test Step 21: Creating snapshot of vm vm_TestCase12215_2609433738 09:48:49 2018-07-26 09:48:49,050 INFO Test Step 22: Before snapshot: 10 volumes 09:48:49 2018-07-26 09:48:49,238 INFO Test Step 23: Stop vm vm_TestCase12215_2609433738 with {'async': 'true'} 09:48:53 2018-07-26 09:48:53,855 INFO Test Step 24: Adding new snapshot to vm vm_TestCase12215_2609433738 09:48:53 2018-07-26 09:48:53,857 INFO Test Step 25: Add snapshot to VM vm_TestCase12215_2609433738 with {'description': 'snapshot_12215_iscsi_1', 'wait': True} 09:50:21 2018-07-26 09:50:20,970 INFO Test Step 26: After snapshot: 15 volumes 09:50:21 2018-07-26 09:50:21,075 INFO Test Step 27: Creating files on vm's 'vm_TestCase12215_2609433738' disks 09:50:21 2018-07-26 09:50:21,164 INFO Test Step 28: Creating file /mount-point_2609454605/test_file_2 09:50:23 2018-07-26 09:50:23,289 INFO Test Step 29: Creating file /mount-point_2609455580/test_file_2 09:50:25 2018-07-26 09:50:25,362 INFO Test Step 30: Creating file /mount-point_2609460545/test_file_2 09:50:27 2018-07-26 09:50:27,428 INFO Test Step 31: Creating file /mount-point_2609461508/test_file_2 09:50:30 2018-07-26 09:50:30,033 INFO Test Step 32: Creating snapshot of vm vm_TestCase12215_2609433738 09:50:41 2018-07-26 09:50:41,851 INFO Test Step 33: Before snapshot: 15 volumes 09:50:42 2018-07-26 09:50:42,041 INFO Test Step 34: Stop vm vm_TestCase12215_2609433738 with {'async': 'true'} 09:50:56 2018-07-26 09:50:56,828 INFO Test Step 35: Adding new snapshot to vm vm_TestCase12215_2609433738 09:50:56 2018-07-26 09:50:56,831 INFO Test Step 36: Add snapshot to VM vm_TestCase12215_2609433738 with {'description': 'snapshot_12215_iscsi_2', 'wait': True} 09:52:22 2018-07-26 09:52:22,554 INFO Test Step 37: After snapshot: 20 volumes 09:52:36 2018-07-26 09:52:36,285 INFO Test Step 38: Before live merge: 20 volumes 09:52:36 2018-07-26 09:52:36,507 INFO Test Step 39: Removing snapshot 'snapshot_12215_iscsi_1' of vm vm_TestCase12215_2609433738 Actual results: Snapshot live merge failed ! 10:32:40 2018-07-26 10:32:40,622 ERROR Result: FAILED Expected results: Additional info:
Adding missing info: Description of problem: Live merge fails with libvirtError: internal error: child reported: Kernel does not provide mount namespace: No such file or directory Version-Release number of selected component (if applicable): ovirt-engine-4.2.5.2-0.1.el7ev.noarch (hosted-engine) vdsm-4.20.35-1.el7ev.x86_64 libvirt-3.9.0-14.el7_5.6.x86_64
Eyal, can you please take a look? Thanks
Same flow as bug 1601212. The log seems to reflect the same issue as well (virDomainBlockCommit() failed) which is currently investigated by the QEMU teams. Close as duplication. *** This bug has been marked as a duplicate of bug 1601212 ***