Hide Forgot
Created attachment 511460 [details] vdsm log Description: When prepareVolume fails - for example with "VolumeDoesNotExist", the image lock is not released. when trying to run this vm again it acquires the vmConatinerLock and waiting forever for the image resource that was never released. result: deadlock in vmContainer. Version-Release number of selected component (if applicable): vdsm-4.9-80.el6.x86_64 How reproducible: Steps to Reproduce: 1. 2. 3. Actual results: creation of vms stuck forever in waitForLaunch. Expected results: image lock should be released if prepareVolume fails. Additional info: log attached
http://gerrit.usersys.redhat.com/#change,665
Bug report changed to ON_QA status by me since Errata System refused to do so. A QE request has been submitted for advisory RHEA-2011:11186-01 http://errata.devel.redhat.com/errata/show/11186
Thread-2386::DEBUG::2011-07-18 10:27:39,193::resourceManager::508::ResourceManager::(registerResource) Resource 'Storage.10e67a7f-a434-478e-9e83-a724566523ce' is free. Now locking as 'shared' (1 active user) Thread-2386::DEBUG::2011-07-18 10:27:39,194::resourceManager::191::ResourceManager.Request::(grant) ResName=`Storage.10e67a7f-a434-478e-9e83-a724566523ce`ReqID=`12aee50c-5a15-4b22-ba66-f9f5f091d4e6`::Granted request VolumeDoesNotExist: Volume does not exist: ('a2040e9f-7b22-443e-a25f-41a39d3cd257',) Thread-2386::DEBUG::2011-07-18 10:27:39,804::task::492::TaskManager.Task::(_debug) Task 915fdc5d-c480-4143-b723-127ef4533fb4: Task._run: 915fdc5d-c480-4143-b723-127ef4533fb4 ('10e67a7f-a434-478e-9e83-a724566523ce', '6a38970f-5596-4437-ba 8c-1093e1b48afc', '87e8b198-1cbb-43b3-a137-894d9287daa1', 'a2040e9f-7b22-443e-a25f-41a39d3cd257') {} failed - stopping task Thread-2388::INFO::2011-07-18 10:27:39,806::dispatcher::94::Storage.Dispatcher.Protect::(run) Run and protect: repoStats, args: () Thread-2386::DEBUG::2011-07-18 10:27:39,806::task::492::TaskManager.Task::(_debug) Task 915fdc5d-c480-4143-b723-127ef4533fb4: stopping in state preparing (force False) Thread-2388::DEBUG::2011-07-18 10:27:39,807::task::492::TaskManager.Task::(_debug) Task b7ae8125-5b9b-4318-a1e5-b7bdac7f1eb7: moving from state init -> state preparing Thread-2386::DEBUG::2011-07-18 10:27:39,807::task::492::TaskManager.Task::(_debug) Task 915fdc5d-c480-4143-b723-127ef4533fb4: ref 1 aborting True Thread-2388::DEBUG::2011-07-18 10:27:39,808::task::492::TaskManager.Task::(_debug) Task b7ae8125-5b9b-4318-a1e5-b7bdac7f1eb7: finished: {u'ea48f4b2-7cee-4669-94af-33131b0eaab9': {'delay': '0.00293016433716', 'lastCheck': 1310974059.34768 61, 'valid': True, 'code': 0}, u'7fea1def-0290-4279-9f52-341ff3c4a508': {'delay': '0.00362586975098', 'lastCheck': 1310974053.2883849, 'valid': True, 'code': 0}, u'10e67a7f-a434-478e-9e83-a724566523ce': {'delay': '0.00401496887207', 'las tCheck': 1310974050.259624, 'valid': True, 'code': 0}} Thread-2386::INFO::2011-07-18 10:27:39,808::task::1177::TaskManager.Task::(prepare) aborting: Task is aborted: 'Volume does not exist' - code 201 Thread-2388::DEBUG::2011-07-18 10:27:39,809::task::492::TaskManager.Task::(_debug) Task b7ae8125-5b9b-4318-a1e5-b7bdac7f1eb7: moving from state preparing -> state finished Thread-2386::DEBUG::2011-07-18 10:27:39,809::task::492::TaskManager.Task::(_debug) Task 915fdc5d-c480-4143-b723-127ef4533fb4: Prepare: aborted: Volume does not exist Thread-2388::DEBUG::2011-07-18 10:27:39,809::resourceManager::786::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-2386::DEBUG::2011-07-18 10:27:39,810::task::492::TaskManager.Task::(_debug) Task 915fdc5d-c480-4143-b723-127ef4533fb4: ref 0 aborting True Thread-2388::DEBUG::2011-07-18 10:27:39,810::resourceManager::821::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-2386::DEBUG::2011-07-18 10:27:39,811::task::492::TaskManager.Task::(_debug) Task 915fdc5d-c480-4143-b723-127ef4533fb4: Task._doAbort: force False Thread-2388::DEBUG::2011-07-18 10:27:39,811::task::492::TaskManager.Task::(_debug) Task b7ae8125-5b9b-4318-a1e5-b7bdac7f1eb7: ref 0 aborting False Thread-2386::DEBUG::2011-07-18 10:27:39,812::resourceManager::821::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-2388::INFO::2011-07-18 10:27:39,812::dispatcher::100::Storage.Dispatcher.Protect::(run) Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, u'ea48f4b2-7cee-4669-94af-33131b0eaab9': {'delay': '0.00 293016433716', 'lastCheck': 1310974059.3476861, 'valid': True, 'code': 0}, u'7fea1def-0290-4279-9f52-341ff3c4a508': {'delay': '0.00362586975098', 'lastCheck': 1310974053.2883849, 'valid': True, 'code': 0}, u'10e67a7f-a434-478e-9e83-a7245 66523ce': {'delay': '0.00401496887207', 'lastCheck': 1310974050.259624, 'valid': True, 'code': 0}} Thread-2386::DEBUG::2011-07-18 10:27:39,812::task::492::TaskManager.Task::(_debug) Task 915fdc5d-c480-4143-b723-127ef4533fb4: moving from state preparing -> state aborting Thread-2386::DEBUG::2011-07-18 10:27:39,813::task::492::TaskManager.Task::(_debug) Task 915fdc5d-c480-4143-b723-127ef4533fb4: _aborting: recover policy none Thread-2386::DEBUG::2011-07-18 10:27:39,814::task::492::TaskManager.Task::(_debug) Task 915fdc5d-c480-4143-b723-127ef4533fb4: moving from state aborting -> state failed Thread-2386::DEBUG::2011-07-18 10:27:39,817::resourceManager::786::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.10e67a7f-a434-478e-9e83-a724566523ce': < ResourceRef 'Storage.10e67a7f-a434-478e-9e83-a724566523ce', isValid: 'True' obj: 'None'>} Thread-2386::DEBUG::2011-07-18 10:27:39,817::resourceManager::821::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-2386::DEBUG::2011-07-18 10:27:39,824::resourceManager::517::ResourceManager::(releaseResource) Trying to release resource 'Storage.10e67a7f-a434-478e-9e83-a724566523ce' Thread-2386::DEBUG::2011-07-18 10:27:39,824::resourceManager::532::ResourceManager::(releaseResource) Released resource 'Storage.10e67a7f-a434-478e-9e83-a724566523ce' (0 active users) Thread-2386::DEBUG::2011-07-18 10:27:39,825::resourceManager::537::ResourceManager::(releaseResource) Resource 'Storage.10e67a7f-a434-478e-9e83-a724566523ce' is free, finding out if anyone is waiting for it. Thread-2386::DEBUG::2011-07-18 10:27:39,825::resourceManager::544::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.10e67a7f-a434-478e-9e83-a724566523ce', Clearing records. Resource released Verified. vdsm-4.9-82.el6
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. http://rhn.redhat.com/errata/RHEA-2011-1782.html