legacy-wiki
Lab RHEV exporting vms
Recovered from the older tannerjc.net wiki snapshot dated January 23, 2016.
RHEV VM export troubleshooting
The purpose of this Lab is to document what the logging looks like for this procedure when everything works successfully:
- export a vm
- delete said export
- export the same vm
- check the export creation time stamp and it should be the most recent export
-
- not the original one which was deleted
first export operation
task beginning
vdc-log.txt
28Sep 17:42:03 [2472] INFO - Running command: ExportVmCommand
28Sep 17:42:03 [2472] INFO - Running command: MoveOrCopyImageGroupCommand
28Sep 17:42:03 [2472] INFO - EntityAsyncTask::Adding EntityMultiAsyncTasks object for entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5'
28Sep 17:42:03 [2472] INFO - EntityMultiAsyncTasks::AttachTask: Attaching task 'b8b6eed5-2007-4f9a-a85c-2c8fb4358d80' to entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5'.
28Sep 17:42:03 [2472] INFO - AsyncTaskManager::AddTask: Adding task 'b8b6eed5-2007-4f9a-a85c-2c8fb4358d80' (Parent Command ExportVm, Parameters Type AsyncTaskParameters), polling hasn't started yet..
28Sep 17:42:03 [2472] INFO - BaseAsyncTask::StartPollingTask: Starting to poll task 'b8b6eed5-2007-4f9a-a85c-2c8fb4358d80'.
28Sep 17:42:03 [2472] INFO - EntityMultiAsyncTasks::StartPollingTask: Current Action Type for entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5' is 'ExportVm' (determined by task 'b8b6eed5-2007-4f9a-a85c-2c8fb4358d80')
vdsm.log.1
Thread-936174::DEBUG::2010-09-29 00:41:41,967::resource::661::irs::Owner.releaseAll requests [] resources []
Thread-936174::INFO::2010-09-29 00:41:41,967::dispatcher::95::irs::Run and protect: moveImage, args: ( spUUID=b2252e5b-70b9-428c-bd5e-474008b44982 srcDomUUID=7f888454-f103-4af3-b3ea-29e027c9d638 dstDomUUID=7f42188b-4b03-47e2-adeb-9fd05b3c532f imgUUID=d6a97837-f986-4cfe-ad94-f2b96571b910 vmUUID=a0225c9c-eb09-4549-9bd0-df50360dc9f5 op=1 postZero=false force=false)
Thread-936174::DEBUG::2010-09-29 00:41:41,968::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: moving from state init - state preparing
Thread-936174::DEBUG::2010-09-29 00:41:41,968::resource::289::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: b8b6eed5-2007-4f9a-a85c-2c8fb4358d80 acquire shared (60000)
Thread-936174::DEBUG::2010-09-29 00:41:41,968::resource::295::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982 - lockstate free
Thread-936174::DEBUG::2010-09-29 00:41:41,968::resource::236::irs::Resource 'Storage/b2252e5b-70b9-428c-bd5e-474008b44982': __granted shared to 'b8b6eed5-2007-4f9a-a85c-2c8fb4358d80'
Thread-936174::DEBUG::2010-09-29 00:41:41,968::resource::515::irs::Owner b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: _acquired Storage/b2252e5b-70b9-428c-bd5e-474008b44982
Thread-936174::DEBUG::2010-09-29 00:41:41,968::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: _resourcesAcquired: Storage.b2252e5b-70b9-428c-bd5e-474008b44982 (shared)
Thread-936174::DEBUG::2010-09-29 00:41:41,969::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: ref 1 aborting False
Thread-936174::DEBUG::2010-09-29 00:41:42,008::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: _save: orig /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80 temp /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80.temp
Thread-936174::DEBUG::2010-09-29 00:41:42,055::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80.backup
Thread-936174::DEBUG::2010-09-29 00:41:42,056::taskManager::57::irs::(TaskManager:scheduleJob) scheduled job moveImage for task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80
Thread-936174::DEBUG::2010-09-29 00:41:42,056::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: Prepare: 1 jobs exist, move to acquiring
Thread-936174::DEBUG::2010-09-29 00:41:42,056::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: moving from state preparing - state acquiring
Thread-936174::DEBUG::2010-09-29 00:41:42,057::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: _save: orig /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80 temp /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80.temp
Thread-936174::DEBUG::2010-09-29 00:41:42,063::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80.backup
Thread-936174::DEBUG::2010-09-29 00:41:42,066::task::474::irs::TaskResourcesList.allGranted: check for {'Storage!b2252e5b-70b9-428c-bd5e-474008b44982': storage.task.TaskResource object at 0x2aefdd5e85d0} owned {'Storage!b2252e5b-70b9-428c-bd5e-474008b44982': ('Storage', 'b2252e5b-70b9-428c-bd5e-474008b44982', 'shared')}
Thread-936174::DEBUG::2010-09-29 00:41:42,066::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: moving from state acquiring - state queued
Thread-936174::DEBUG::2010-09-29 00:41:42,066::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: _save: orig /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80 temp /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80.temp
Thread-936174::DEBUG::2010-09-29 00:41:42,072::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80.backup
Thread-936174::DEBUG::2010-09-29 00:41:42,075::taskManager::38::irs::(TaskManager:queue) queueing task: b8b6eed5-2007-4f9a-a85c-2c8fb4358d80
Thread-936174::DEBUG::2010-09-29 00:41:42,076::taskManager::45::irs::(TaskManager:queue) task queued: b8b6eed5-2007-4f9a-a85c-2c8fb4358d80
Thread-936174::DEBUG::2010-09-29 00:41:42,076::task::1287::irs::(task:prepare) returning
Thread-936174::DEBUG::2010-09-29 00:41:42,076::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: ref 0 aborting False
Thread-936174::INFO::2010-09-29 00:41:42,076::dispatcher::101::irs::Run and protect: moveImage, Return response: {'status': {'message': 'OK', 'code': 0}, 'uuid': 'b8b6eed5-2007-4f9a-a85c-2c8fb4358d80'}
task ending
vdc-log.txt
28Sep 17:55:57 [1792] WARN - SPMAsyncTask::PollTask: Polling task 'b8b6eed5-2007-4f9a-a85c-2c8fb4358d80' (Parent Command ExportVm, Parameters Type AsyncTaskParameters) returned status 'finished', result 'success'.
28Sep 17:55:57 [1792] INFO - BaseAsyncTask::OnTaskEndSuccess: Task 'b8b6eed5-2007-4f9a-a85c-2c8fb4358d80' (Parent Command ExportVm, Parameters Type AsyncTaskParameters) ended successfully.
28Sep 17:55:57 [1792] INFO - EntityAsyncTask::EndAction: Ending action for 1 tasks (entity ID: 'a0225c9c-eb09-4549-9bd0-df50360dc9f5'): calling EndAction for action type 'ExportVm'.
28Sep 17:55:57 [1792] INFO - AsyncTaskManager::_timer_Elapsed: Finished polling Tasks, no tasks left to poll.
28Sep 17:55:57 [1792] INFO - EntityAsyncTask::EndCommandAction [within thread]: Attempting to EndAction 'ExportVm'
28Sep 17:55:57 [1792] INFO - Ending command successfully: ExportVmCommand
28Sep 17:55:57 [1792] INFO - Ending command successfully: MoveOrCopyImageGroupCommand
28Sep 17:55:57 [1792] INFO - EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type 'ExportVm' completed, handling the result.
28Sep 17:55:57 [1792] INFO - EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type ExportVm succeeded, clearing tasks.
28Sep 17:55:57 [1792] INFO - SPMAsyncTask::ClearAsyncTask: Attempting to clear task 'b8b6eed5-2007-4f9a-a85c-2c8fb4358d80'
28Sep 17:55:57 [1792] INFO - EntityAsyncTask::HandleEndActionResult [within thread]: Removing EntityMultiAsyncTasks object for entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5'
vdsm.log.1
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,316::misc::167::irs::SUCCESS: err = '10240+0 records in\n10240+0 records out\n10737418240 bytes (11 GB) copied, 831.201 seconds, 12.9 MB/s\n'; rc = 0
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,316::misc::268::irs::(validateDDBytes) err: ['10240+0 records in', '10240+0 records out', '10737418240 bytes (11 GB) copied, 831.201 seconds, 12.9 MB/s'], size: 10737418240
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::INFO::2010-09-29 00:55:34,316::volume::518::irs::Volume: tearing down volume 7f888454-f103-4af3-b3ea-29e027c9d638/94f88c11-a665-4a5c-bfb3-0c36af2b661f justme True
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::INFO::2010-09-29 00:55:34,317::volume::518::irs::Volume: tearing down volume 7f42188b-4b03-47e2-adeb-9fd05b3c532f/94f88c11-a665-4a5c-bfb3-0c36af2b661f justme True
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,317::resource::661::irs::Owner.releaseAll requests [] resources []
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::INFO::2010-09-29 00:55:34,317::image::538::irs::(Image.move) COPY task on image d6a97837-f986-4cfe-ad94-f2b96571b910 was successfully finished
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,317::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: moving from state running - state finished
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,318::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: _save: orig /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80 temp /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80.temp
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,325::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/b8b6eed5-2007-4f9a-a85c-2c8fb4358d80.backup
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,335::resource::661::irs::Owner.releaseAll requests [] resources [storage.resource.Resource object at 0x2aefdd5e8a10]
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,335::resource::332::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: b8b6eed5-2007-4f9a-a85c-2c8fb4358d80 releasing
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,335::resource::339::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: owners after release []
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,335::resource::342::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: requests after release []
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,335::resource::361::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: free lock
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,335::resource::494::irs::Owner b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: _released Storage/b2252e5b-70b9-428c-bd5e-474008b44982/storage.resource.Resource object at 0x2aefdd5e8a10 (['Storage/b2252e5b-70b9-428c-bd5e-474008b44982/storage.resource.Resource object at 0x2aefdd5e8a10'])
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,336::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: resourceReleased: Storage.b2252e5b-70b9-428c-bd5e-474008b44982
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,336::resource::176::irs::resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982 after decref ref 0
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,336::task::1012::irs::Task.run: exit - success: result
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,336::task::573::irs::Task b8b6eed5-2007-4f9a-a85c-2c8fb4358d80: ref 0 aborting False
b8b6eed5-2007-4f9a-a85c-2c8fb4358d80::DEBUG::2010-09-29 00:55:34,336::threadPool::51::irs::(threadPool:setRunningTask) Number of running tasks: 0
Delete Original export vm
vdc-log.txt
28Sep 18:17:48 [1792] INFO - Running command: RemoveVmFromImportExportCommand
28Sep 18:17:48 [1792] INFO - Running command: RemoveAllVmImagesCommand
28Sep 18:17:48 [1792] INFO - Running command: RemoveImageCommand
28Sep 18:17:48 [1792] INFO - EntityAsyncTask::Adding EntityMultiAsyncTasks object for entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5'
28Sep 18:17:48 [1792] INFO - EntityMultiAsyncTasks::AttachTask: Attaching task '693a327a-98a1-48ac-8c49-1fd4203f8188' to entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5'.
28Sep 18:17:48 [1792] INFO - AsyncTaskManager::AddTask: Adding task '693a327a-98a1-48ac-8c49-1fd4203f8188' (Parent Command RemoveVmFromImportExport, Parameters Type AsyncTaskParameters), polling hasn't started yet..
28Sep 18:17:48 [1792] INFO - BaseAsyncTask::StartPollingTask: Starting to poll task '693a327a-98a1-48ac-8c49-1fd4203f8188'.
28Sep 18:17:48 [1792] INFO - EntityMultiAsyncTasks::StartPollingTask: Current Action Type for entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5' is 'RemoveVmFromImportExport' (determined by task '693a327a-98a1-48ac-8c49-1fd4203f8188')
28Sep 18:17:57 [1552] WARN - ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds = 3 : rhevh-3.gsslab.rdu.redhat.com, VDS Network Error, continuing.
VDSNetworkException:
28Sep 18:17:57 [1552] WARN - SPMAsyncTask::PollTask: Polling task '693a327a-98a1-48ac-8c49-1fd4203f8188' (Parent Command RemoveVmFromImportExport, Parameters Type AsyncTaskParameters) returned status 'finished', result 'success'.
28Sep 18:17:57 [1552] INFO - BaseAsyncTask::OnTaskEndSuccess: Task '693a327a-98a1-48ac-8c49-1fd4203f8188' (Parent Command RemoveVmFromImportExport, Parameters Type AsyncTaskParameters) ended successfully.
28Sep 18:17:57 [1552] INFO - EntityAsyncTask::EndAction: Ending action for 1 tasks (entity ID: 'a0225c9c-eb09-4549-9bd0-df50360dc9f5'): calling EndAction for action type 'RemoveVmFromImportExport'.
28Sep 18:17:57 [1552] INFO - AsyncTaskManager::_timer_Elapsed: Finished polling Tasks, no tasks left to poll.
28Sep 18:17:57 [1552] INFO - EntityAsyncTask::EndCommandAction [within thread]: Attempting to EndAction 'RemoveVmFromImportExport'
28Sep 18:17:57 [1552] INFO - Ending command successfully: RemoveVmFromImportExportCommand
28Sep 18:17:57 [1552] INFO - EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type 'RemoveVmFromImportExport' completed, handling the result.
28Sep 18:17:57 [1552] INFO - EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type RemoveVmFromImportExport succeeded, clearing tasks.
28Sep 18:17:57 [1552] INFO - SPMAsyncTask::ClearAsyncTask: Attempting to clear task '693a327a-98a1-48ac-8c49-1fd4203f8188'
28Sep 18:17:57 [1552] INFO - EntityAsyncTask::HandleEndActionResult [within thread]: Removing EntityMultiAsyncTasks object for entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5'
vdsm.log
Thread-937956::DEBUG::2010-09-29 01:17:27,482::resource::661::irs::Owner.releaseAll requests [] resources []
Thread-937956::INFO::2010-09-29 01:17:27,482::dispatcher::95::irs::Run and protect: deleteImage, args: ( sdUUID=7f42188b-4b03-47e2-adeb-9fd05b3c532f spUUID=b2252e5b-70b9-428c-bd5e-474008b44982 imgUUID=d6a97837-f986-4cfe-ad94-f2b96571b910 postZero=False force=false)
Thread-937956::DEBUG::2010-09-29 01:17:27,482::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: moving from state init - state preparing
Thread-937956::DEBUG::2010-09-29 01:17:27,482::resource::289::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: 693a327a-98a1-48ac-8c49-1fd4203f8188 acquire shared (60000)
Thread-937956::DEBUG::2010-09-29 01:17:27,483::resource::295::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982 - lockstate free
Thread-937956::DEBUG::2010-09-29 01:17:27,483::resource::236::irs::Resource 'Storage/b2252e5b-70b9-428c-bd5e-474008b44982': __granted shared to '693a327a-98a1-48ac-8c49-1fd4203f8188'
Thread-937956::DEBUG::2010-09-29 01:17:27,483::resource::515::irs::Owner 693a327a-98a1-48ac-8c49-1fd4203f8188: _acquired Storage/b2252e5b-70b9-428c-bd5e-474008b44982
Thread-937956::DEBUG::2010-09-29 01:17:27,483::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: _resourcesAcquired: Storage.b2252e5b-70b9-428c-bd5e-474008b44982 (shared)
Thread-937956::DEBUG::2010-09-29 01:17:27,483::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: ref 1 aborting False
Thread-937956::DEBUG::2010-09-29 01:17:27,485::fileVolume::431::irs::validate image d6a97837-f986-4cfe-ad94-f2b96571b910 path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
Thread-937956::DEBUG::2010-09-29 01:17:27,485::fileVolume::467::irs::validate path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
Thread-937956::DEBUG::2010-09-29 01:17:27,516::fileVolume::431::irs::validate image d6a97837-f986-4cfe-ad94-f2b96571b910 path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
Thread-937956::DEBUG::2010-09-29 01:17:27,516::fileVolume::467::irs::validate path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
Thread-937956::DEBUG::2010-09-29 01:17:27,518::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: _save: orig /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188 temp /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.temp
Thread-937956::DEBUG::2010-09-29 01:17:27,524::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.backup
Thread-937956::DEBUG::2010-09-29 01:17:27,525::taskManager::57::irs::(TaskManager:scheduleJob) scheduled job deleteImage for task 693a327a-98a1-48ac-8c49-1fd4203f8188
Thread-937956::DEBUG::2010-09-29 01:17:27,526::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: Prepare: 1 jobs exist, move to acquiring
Thread-937956::DEBUG::2010-09-29 01:17:27,526::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: moving from state preparing - state acquiring
Thread-937956::DEBUG::2010-09-29 01:17:27,526::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: _save: orig /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188 temp /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.temp
Thread-937956::DEBUG::2010-09-29 01:17:27,532::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.backup
Thread-937956::DEBUG::2010-09-29 01:17:27,535::task::474::irs::TaskResourcesList.allGranted: check for {'Storage!b2252e5b-70b9-428c-bd5e-474008b44982': storage.task.TaskResource object at 0x2aefdd5e8ad0} owned {'Storage!b2252e5b-70b9-428c-bd5e-474008b44982': ('Storage', 'b2252e5b-70b9-428c-bd5e-474008b44982', 'shared')}
/693a327a-98a1-48ac-8c49-1fd4203f8188
Thread-937956::DEBUG::2010-09-29 01:17:27,535::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: moving from state acquiring - state queued
Thread-937956::DEBUG::2010-09-29 01:17:27,535::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: _save: orig /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188 temp /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.temp
Thread-937956::DEBUG::2010-09-29 01:17:27,542::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.backup
Thread-937956::DEBUG::2010-09-29 01:17:27,544::taskManager::38::irs::(TaskManager:queue) queueing task: 693a327a-98a1-48ac-8c49-1fd4203f8188
Thread-937956::DEBUG::2010-09-29 01:17:27,545::taskManager::45::irs::(TaskManager:queue) task queued: 693a327a-98a1-48ac-8c49-1fd4203f8188
Thread-937956::DEBUG::2010-09-29 01:17:27,545::task::1287::irs::(task:prepare) returning
Thread-937956::DEBUG::2010-09-29 01:17:27,545::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: ref 0 aborting False
Thread-937956::INFO::2010-09-29 01:17:27,545::dispatcher::101::irs::Run and protect: deleteImage, Return response: {'status': {'message': 'OK', 'code': 0}, 'uuid': '693a327a-98a1-48ac-8c49-1fd4203f8188'}
5f09e892-ef67-4a82-8490-dc8d34526782::DEBUG::2010-09-29 01:17:27,553::threadPool::51::irs::(threadPool:setRunningTask) Number of running tasks: 1
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,553::threadPool::195::irs::Task: 693a327a-98a1-48ac-8c49-1fd4203f8188 running: bound method Task.commit of storage.task.Task instance at 0x2aefdd5ec9e0 with: None
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,553::task::1299::irs::(task:commit) Commiting task: 693a327a-98a1-48ac-8c49-1fd4203f8188
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,554::resource::661::irs::Owner.releaseAll requests [] resources []
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,554::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: moving from state queued - state running
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,554::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: _save: orig /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188 temp /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.temp
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,560::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.backup
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,563::task::1004::irs::Task.run: running job 0: deleteImage: bound method Secure.run of storage.spm.Secure instance at 0x2aefdd5cad88 (args: ('7f42188b-4b03-47e2-adeb-9fd05b3c532f', 'b2252e5b-70b9-428c-bd5e-474008b44982', 'd6a97837-f986-4cfe-ad94-f2b96571b910', False, False) kwargs: {})
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,563::task::317::irs::Job.run: running deleteImage: bound method Secure.run of storage.spm.Secure instance at 0x2aefdd5cad88 (args: ('7f42188b-4b03-47e2-adeb-9fd05b3c532f', 'b2252e5b-70b9-428c-bd5e-474008b44982', 'd6a97837-f986-4cfe-ad94-f2b96571b910', False, False) kwargs: {}) callback None
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,564::fileVolume::431::irs::validate image d6a97837-f986-4cfe-ad94-f2b96571b910 path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,564::fileVolume::467::irs::validate path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,565::fileVolume::431::irs::validate image d6a97837-f986-4cfe-ad94-f2b96571b910 path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,565::fileVolume::467::irs::validate path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,566::fileVolume::431::irs::validate image d6a97837-f986-4cfe-ad94-f2b96571b910 path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,566::fileVolume::467::irs::validate path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::INFO::2010-09-29 01:17:27,567::image::291::irs::(Image.getChain) spUUID=b2252e5b-70b9-428c-bd5e-474008b44982 sdUUID=7f42188b-4b03-47e2-adeb-9fd05b3c532f imgUUID=d6a97837-f986-4cfe-ad94-f2b96571b910 chain=[storage.fileVolume.FileVolume instance at 0x2aaaaaad20e0]
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,568::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: _save: orig /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188 temp /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.temp
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,575::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.backup
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,578::fileVolume::431::irs::validate image d6a97837-f986-4cfe-ad94-f2b96571b910 path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,578::fileVolume::467::irs::validate path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,580::fileVolume::431::irs::validate image d6a97837-f986-4cfe-ad94-f2b96571b910 path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,580::fileVolume::467::irs::validate path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,580::fileVolume::431::irs::validate image d6a97837-f986-4cfe-ad94-f2b96571b910 path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,581::fileVolume::467::irs::validate path for 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::INFO::2010-09-29 01:17:27,581::fileVolume::138::irs::(FileVolume.delete) Request to delete volume 94f88c11-a665-4a5c-bfb3-0c36af2b661f
693a327a-98a1-48ac-8c49-1fd4203f8188::INFO::2010-09-29 01:17:27,582::volume::358::irs::(Volume.setLegality) sdUUID=7f42188b-4b03-47e2-adeb-9fd05b3c532f spUUID=b2252e5b-70b9-428c-bd5e-474008b44982 imgUUID=d6a97837-f986-4cfe-ad94-f2b96571b910 volUUID = 94f88c11-a665-4a5c-bfb3-0c36af2b661f legality = ILLEGAL
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:27,703::volume::898::irs::filelist ['/rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/7f42188b-4b03-47e2-adeb-9fd05b3c532f/images/d6a97837-f986-4cfe-ad94-f2b96571b910/94f88c11-a665-4a5c-bfb3-0c36af2b661f']
Thread-937957::DEBUG::2010-09-29 01:17:27,822::resource::339::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: owners after release ['693a327a-98a1-48ac-8c49-1fd4203f8188']
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,569::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/7f42188b-4b03-47e2-adeb-9fd05b3c532f/images/.remove_me_d6a97837-f986-4cfe-ad94-f2b96571b910
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,571::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: moving from state running - state finished
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,572::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: _save: orig /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188 temp /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.temp
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,581::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188.backup
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,585::resource::661::irs::Owner.releaseAll requests [] resources [storage.resource.Resource object at 0x2aefdd5e8bd0]
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,585::resource::332::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: 693a327a-98a1-48ac-8c49-1fd4203f8188 releasing
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,585::resource::339::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: owners after release []
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,585::resource::342::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: requests after release []
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,585::resource::361::irs::Resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982: free lock
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,585::resource::494::irs::Owner 693a327a-98a1-48ac-8c49-1fd4203f8188: _released Storage/b2252e5b-70b9-428c-bd5e-474008b44982/storage.resource.Resource object at 0x2aefdd5e8bd0 (['Storage/b2252e5b-70b9-428c-bd5e-474008b44982/storage.resource.Resource object at 0x2aefdd5e8bd0'])
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,585::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: resourceReleased: Storage.b2252e5b-70b9-428c-bd5e-474008b44982
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,586::resource::176::irs::resource Storage/b2252e5b-70b9-428c-bd5e-474008b44982 after decref ref 0
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,586::task::1012::irs::Task.run: exit - success: result
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,586::task::573::irs::Task 693a327a-98a1-48ac-8c49-1fd4203f8188: ref 0 aborting False
693a327a-98a1-48ac-8c49-1fd4203f8188::DEBUG::2010-09-29 01:17:30,586::threadPool::51::irs::(threadPool:setRunningTask) Number of running tasks: 0
Thread-937966::INFO::2010-09-29 01:17:36,443::dispatcher::95::irs::Run and protect: getTaskStatus, args: ( taskID=693a327a-98a1-48ac-8c49-1fd4203f8188)
Thread-937966::DEBUG::2010-09-29 01:17:36,443::taskManager::78::irs::(TaskManager:getTaskStatus) Entry. taskID: 693a327a-98a1-48ac-8c49-1fd4203f8188
Thread-937966::DEBUG::2010-09-29 01:17:36,443::taskManager::81::irs::(TaskManager:getTaskStatus) Return. Response: {'code': 0, 'message': '1 jobs completed successfuly', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '693a327a-98a1-48ac-8c49-1fd4203f8188'}
Thread-937966::DEBUG::2010-09-29 01:17:36,443::task::573::irs::Task c66dee03-9278-42da-9c1d-249dd9e77bb2: finished: {'taskStatus': {'code': 0, 'message': '1 jobs completed successfuly', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '693a327a-98a1-48ac-8c49-1fd4203f8188'}}
Thread-937966::INFO::2010-09-29 01:17:36,444::dispatcher::101::irs::Run and protect: getTaskStatus, Return response: {'status': {'message': 'OK', 'code': 0}, 'taskStatus': {'code': 0, 'message': '1 jobs completed successfuly', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '693a327a-98a1-48ac-8c49-1fd4203f8188'}}
Thread-937967::INFO::2010-09-29 01:17:36,494::dispatcher::95::irs::Run and protect: clearTask, args: ( taskID=693a327a-98a1-48ac-8c49-1fd4203f8188)
Thread-937967::DEBUG::2010-09-29 01:17:36,494::taskManager::142::irs::(TaskManager:clearTask) Entry. taskID: 693a327a-98a1-48ac-8c49-1fd4203f8188
Thread-937967::DEBUG::2010-09-29 01:17:36,494::misc::231::irs::(misc.cleanup) Cleaning up dir /rhev/data-center/b2252e5b-70b9-428c-bd5e-474008b44982/tasks/693a327a-98a1-48ac-8c49-1fd4203f8188
second export operation
task beginning
vdc-log.txt
28Sep 18:18:20 [1552] INFO - Running command: ExportVmCommand
28Sep 18:18:20 [1552] INFO - Running command: MoveOrCopyImageGroupCommand
28Sep 18:18:20 [1552] INFO - EntityAsyncTask::Adding EntityMultiAsyncTasks object for entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5'
28Sep 18:18:20 [1552] INFO - EntityMultiAsyncTasks::AttachTask: Attaching task 'a1a452bf-09f0-4c47-a2be-e8ba330ab04a' to entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5'.
28Sep 18:18:20 [1552] INFO - AsyncTaskManager::AddTask: Adding task 'a1a452bf-09f0-4c47-a2be-e8ba330ab04a' (Parent Command ExportVm, Parameters Type AsyncTaskParameters), polling hasn't started yet..
28Sep 18:18:20 [1552] INFO - BaseAsyncTask::StartPollingTask: Starting to poll task 'a1a452bf-09f0-4c47-a2be-e8ba330ab04a'.
28Sep 18:18:20 [1552] INFO - EntityMultiAsyncTasks::StartPollingTask: Current Action Type for entity 'a0225c9c-eb09-4549-9bd0-df50360dc9f5' is 'ExportVm' (determined by task 'a1a452bf-09f0-4c47-a2be-e8ba330ab04a')