Thread-735868::DEBUG::2017-04-06 08:12:26,651::task::595::Storage.TaskManager.Task::(_updateState) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::moving from state init -> state preparing
Thread-735868::DEBUG::2017-04-06 08:12:26,673::task::752::Storage.TaskManager.Task::(_save) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::_save: orig /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac temp /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac.temp
Thread-735868::DEBUG::2017-04-06 08:12:26,678::taskManager::78::Storage.TaskManager::(scheduleJob) scheduled job downloadImageFromStream for task c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac 
Thread-735868::DEBUG::2017-04-06 08:12:26,678::task::1183::Storage.TaskManager.Task::(prepare) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::Prepare: 1 jobs exist, move to acquiring
Thread-735868::DEBUG::2017-04-06 08:12:26,679::task::595::Storage.TaskManager.Task::(_updateState) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::moving from state preparing -> state acquiring
Thread-735868::DEBUG::2017-04-06 08:12:26,680::task::752::Storage.TaskManager.Task::(_save) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::_save: orig /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac temp /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac.temp
Thread-735868::DEBUG::2017-04-06 08:12:26,686::task::595::Storage.TaskManager.Task::(_updateState) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::moving from state acquiring -> state queued
Thread-735868::DEBUG::2017-04-06 08:12:26,686::task::752::Storage.TaskManager.Task::(_save) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::_save: orig /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac temp /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac.temp
Thread-735868::DEBUG::2017-04-06 08:12:26,693::taskManager::56::Storage.TaskManager::(_queueTask) queuing task: c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,693::threadPool::194::Storage.ThreadPool.WorkerThread::(_processNextTask) Task: c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac running: <bound method Task.commit of <storage.task.Task instance at 0x7f6ba0827908>> with: None
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,693::task::1200::Storage.TaskManager.Task::(commit) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::committing task: c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,694::task::595::Storage.TaskManager.Task::(_updateState) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::moving from state queued -> state running
Thread-735868::DEBUG::2017-04-06 08:12:26,694::taskManager::64::Storage.TaskManager::(_queueTask) task queued: c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac
Thread-735868::DEBUG::2017-04-06 08:12:26,694::task::1188::Storage.TaskManager.Task::(prepare) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::returning
Thread-735868::DEBUG::2017-04-06 08:12:26,694::task::993::Storage.TaskManager.Task::(_decref) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::ref 1 aborting False
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,695::task::752::Storage.TaskManager.Task::(_save) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::_save: orig /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac temp /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac.temp
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,701::task::905::Storage.TaskManager.Task::(_runJobs) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::Task.run: running job 0: downloadImageFromStream: <bound method StoragePool.downloadImageFromStream of <storage.sp.StoragePool object at 0x7f6bac4bf090>> (args: ({'length': 1136640, 'fileObj': <socket._fileobject object at 0x7f6ba0619bd0>}, <function setCallback at 0x7f6bc05eb938>, '2c2e3b6c-7161-45c5-ae80-3639ab565961', 'ce8647c6-f936-4633-8a7b-e7dcb45d8ebb', '96be6a82-ab6a-4e38-b184-6dc65e57847c') kwargs: {})
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,702::task::329::Storage.TaskManager.Task::(run) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::Job.run: running downloadImageFromStream: <bound method StoragePool.downloadImageFromStream of <storage.sp.StoragePool object at 0x7f6bac4bf090>> (args: ({'length': 1136640, 'fileObj': <socket._fileobject object at 0x7f6ba0619bd0>}, <function setCallback at 0x7f6bc05eb938>, '2c2e3b6c-7161-45c5-ae80-3639ab565961', 'ce8647c6-f936-4633-8a7b-e7dcb45d8ebb', '96be6a82-ab6a-4e38-b184-6dc65e57847c') kwargs: {}) callback None
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,702::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`2c2e3b6c-7161-45c5-ae80-3639ab565961_imageNS.ce8647c6-f936-4633-8a7b-e7dcb45d8ebb`ReqID=`37746d73-091b-4286-9b5d-2a539dbfc8c7`::Request was made in '/usr/share/vdsm/storage/sp.py' line '1771' at 'downloadImageFromStream'
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,702::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_imageNS.ce8647c6-f936-4633-8a7b-e7dcb45d8ebb' for lock type 'exclusive'
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,703::lvm::427::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,703::lvm::290::Storage.Misc.excCmd::(cmd) /usr/bin/taskset --cpu-list 0-15 /usr/bin/sudo -n /usr/sbin/lvm lvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/36861a6ed9669ad1b4983b59b936d4d13|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 2c2e3b6c-7161-45c5-ae80-3639ab565961 (cwd None)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,789::lvm::290::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: Not using lvmetad because config setting use_lvmetad=0.\n  WARNING: To avoid corruption, rescan devices to make changes visible (pvscan --cache).\n'; <rc> = 0
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,794::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,795::lvm::462::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,795::blockVolume::631::Storage.Misc.excCmd::(getMetadata) /usr/bin/taskset --cpu-list 0-15 /usr/bin/dd iflag=direct skip=5 bs=512 if=/dev/2c2e3b6c-7161-45c5-ae80-3639ab565961/metadata count=1 (cwd None)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,823::blockVolume::631::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.00651756 s, 78.6 kB/s\n'; <rc> = 0
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,823::misc::261::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.00651756 s, 78.6 kB/s'], size: 512
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,824::blockVolume::631::Storage.Misc.excCmd::(getMetadata) /usr/bin/taskset --cpu-list 0-15 /usr/bin/dd iflag=direct skip=5 bs=512 if=/dev/2c2e3b6c-7161-45c5-ae80-3639ab565961/metadata count=1 (cwd None)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,855::blockVolume::631::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.00649076 s, 78.9 kB/s\n'; <rc> = 0
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,856::misc::261::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.00649076 s, 78.9 kB/s'], size: 512
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::INFO::2017-04-06 08:12:26,856::image::228::Storage.Image::(getChain) sdUUID=2c2e3b6c-7161-45c5-ae80-3639ab565961 imgUUID=ce8647c6-f936-4633-8a7b-e7dcb45d8ebb chain=[<storage.blockVolume.BlockVolume object at 0x7f6b7009bc10>] 
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,857::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`2c2e3b6c-7161-45c5-ae80-3639ab565961_volumeNS.96be6a82-ab6a-4e38-b184-6dc65e57847c`ReqID=`6a054f68-66b7-4b24-bb76-a75558b8a339`::Request was made in '/usr/share/vdsm/storage/resourceFactories.py' line '172' at '__getResourceCandidatesList'
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,857::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_volumeNS.96be6a82-ab6a-4e38-b184-6dc65e57847c' for lock type 'exclusive'
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,857::resourceManager::604::Storage.ResourceManager::(registerResource) Resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_volumeNS.96be6a82-ab6a-4e38-b184-6dc65e57847c' is free. Now locking as 'exclusive' (1 active user)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,857::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`2c2e3b6c-7161-45c5-ae80-3639ab565961_volumeNS.96be6a82-ab6a-4e38-b184-6dc65e57847c`ReqID=`6a054f68-66b7-4b24-bb76-a75558b8a339`::Granted request
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,858::resourceManager::604::Storage.ResourceManager::(registerResource) Resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_imageNS.ce8647c6-f936-4633-8a7b-e7dcb45d8ebb' is free. Now locking as 'exclusive' (1 active user)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,858::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`2c2e3b6c-7161-45c5-ae80-3639ab565961_imageNS.ce8647c6-f936-4633-8a7b-e7dcb45d8ebb`ReqID=`37746d73-091b-4286-9b5d-2a539dbfc8c7`::Granted request
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,858::blockVolume::631::Storage.Misc.excCmd::(getMetadata) /usr/bin/taskset --cpu-list 0-15 /usr/bin/dd iflag=direct skip=5 bs=512 if=/dev/2c2e3b6c-7161-45c5-ae80-3639ab565961/metadata count=1 (cwd None)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,882::blockVolume::631::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.00641695 s, 79.8 kB/s\n'; <rc> = 0
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,882::misc::261::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.00641695 s, 79.8 kB/s'], size: 512
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::INFO::2017-04-06 08:12:26,883::image::228::Storage.Image::(getChain) sdUUID=2c2e3b6c-7161-45c5-ae80-3639ab565961 imgUUID=ce8647c6-f936-4633-8a7b-e7dcb45d8ebb chain=[<storage.blockVolume.BlockVolume object at 0x7f6b7009b850>] 
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:26,883::lvm::290::Storage.Misc.excCmd::(cmd) /usr/bin/taskset --cpu-list 0-15 /usr/bin/sudo -n /usr/sbin/lvm lvchange --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/36861a6ed9669ad1b4983b59b936d4d13|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --autobackup n --available y 2c2e3b6c-7161-45c5-ae80-3639ab565961/96be6a82-ab6a-4e38-b184-6dc65e57847c (cwd None)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,092::lvm::290::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: Not using lvmetad because config setting use_lvmetad=0.\n  WARNING: To avoid corruption, rescan devices to make changes visible (pvscan --cache).\n'; <rc> = 0
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,092::lvm::513::Storage.OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,092::lvm::525::Storage.OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,093::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/2c2e3b6c-7161-45c5-ae80-3639ab565961/ce8647c6-f936-4633-8a7b-e7dcb45d8ebb mode: None
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,093::blockSD::1108::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/2c2e3b6c-7161-45c5-ae80-3639ab565961/96be6a82-ab6a-4e38-b184-6dc65e57847c to /var/run/vdsm/storage/2c2e3b6c-7161-45c5-ae80-3639ab565961/ce8647c6-f936-4633-8a7b-e7dcb45d8ebb/96be6a82-ab6a-4e38-b184-6dc65e57847c
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::INFO::2017-04-06 08:12:27,093::blockVolume::306::Storage.Volume::(extend) Request to extend LV 96be6a82-ab6a-4e38-b184-6dc65e57847c of image ce8647c6-f936-4633-8a7b-e7dcb45d8ebb in VG 2c2e3b6c-7161-45c5-ae80-3639ab565961 with size = 2220
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,094::lvm::290::Storage.Misc.excCmd::(cmd) /usr/bin/taskset --cpu-list 0-15 /usr/bin/sudo -n /usr/sbin/lvm lvextend --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/36861a6ed9669ad1b4983b59b936d4d13|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --autobackup n --size 2m 2c2e3b6c-7161-45c5-ae80-3639ab565961/96be6a82-ab6a-4e38-b184-6dc65e57847c (cwd None)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,168::lvm::290::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  WARNING: Not using lvmetad because config setting use_lvmetad=0.\n  WARNING: To avoid corruption, rescan devices to make changes visible (pvscan --cache).\n  New size (1 extents) matches existing size (1 extents).\n'; <rc> = 5
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,177::lvm::300::Storage.Misc.excCmd::(cmd) /usr/bin/taskset --cpu-list 0-15 /usr/bin/sudo -n /usr/sbin/lvm lvextend --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/36861a6ed96692d44e282359b936dadeb|/dev/mapper/36861a6ed9669ad1b4983b59b936d4d13|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --autobackup n --size 2m 2c2e3b6c-7161-45c5-ae80-3639ab565961/96be6a82-ab6a-4e38-b184-6dc65e57847c (cwd None)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,267::lvm::300::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  WARNING: Not using lvmetad because config setting use_lvmetad=0.\n  WARNING: To avoid corruption, rescan devices to make changes visible (pvscan --cache).\n  New size (1 extents) matches existing size (1 extents).\n'; <rc> = 5
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,267::fileUtils::124::Storage.fileUtils::(cleanupdir) Removing directory: /var/run/vdsm/storage/2c2e3b6c-7161-45c5-ae80-3639ab565961/ce8647c6-f936-4633-8a7b-e7dcb45d8ebb
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,268::lvm::427::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,268::lvm::290::Storage.Misc.excCmd::(cmd) /usr/bin/taskset --cpu-list 0-15 /usr/bin/sudo -n /usr/sbin/lvm lvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/36861a6ed9669ad1b4983b59b936d4d13|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 2c2e3b6c-7161-45c5-ae80-3639ab565961 (cwd None)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,353::lvm::290::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: Not using lvmetad because config setting use_lvmetad=0.\n  WARNING: To avoid corruption, rescan devices to make changes visible (pvscan --cache).\n'; <rc> = 0
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,358::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,358::lvm::462::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,362::lvm::290::Storage.Misc.excCmd::(cmd) /usr/bin/taskset --cpu-list 0-15 /usr/bin/sudo -n /usr/sbin/lvm lvchange --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/36861a6ed9669ad1b4983b59b936d4d13|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --autobackup n --available n 2c2e3b6c-7161-45c5-ae80-3639ab565961/96be6a82-ab6a-4e38-b184-6dc65e57847c (cwd None)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,455::lvm::290::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: Not using lvmetad because config setting use_lvmetad=0.\n  WARNING: To avoid corruption, rescan devices to make changes visible (pvscan --cache).\n'; <rc> = 0
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,456::lvm::513::Storage.OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,456::lvm::525::Storage.OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,456::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_imageNS.ce8647c6-f936-4633-8a7b-e7dcb45d8ebb'
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,457::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_imageNS.ce8647c6-f936-4633-8a7b-e7dcb45d8ebb' (0 active users)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,457::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_imageNS.ce8647c6-f936-4633-8a7b-e7dcb45d8ebb' is free, finding out if anyone is waiting for it.
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,457::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_volumeNS.96be6a82-ab6a-4e38-b184-6dc65e57847c'
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,457::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_volumeNS.96be6a82-ab6a-4e38-b184-6dc65e57847c' (0 active users)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,458::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_volumeNS.96be6a82-ab6a-4e38-b184-6dc65e57847c' is free, finding out if anyone is waiting for it.
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,458::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_volumeNS.96be6a82-ab6a-4e38-b184-6dc65e57847c', Clearing records.
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,458::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource '2c2e3b6c-7161-45c5-ae80-3639ab565961_imageNS.ce8647c6-f936-4633-8a7b-e7dcb45d8ebb', Clearing records.
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::ERROR::2017-04-06 08:12:27,458::task::866::Storage.TaskManager.Task::(_setError) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::Unexpected error
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,459::task::885::Storage.TaskManager.Task::(_run) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::Task._run: c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac () {} failed - stopping task
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,459::task::1246::Storage.TaskManager.Task::(stop) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::stopping in state running (force False)
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,459::task::993::Storage.TaskManager.Task::(_decref) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::ref 1 aborting True
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,459::task::919::Storage.TaskManager.Task::(_runJobs) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::aborting: Task is aborted: 'Logical Volume extend failed' - code 554
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,459::task::993::Storage.TaskManager.Task::(_decref) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::ref 0 aborting True
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,460::task::928::Storage.TaskManager.Task::(_doAbort) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::Task._doAbort: force False
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,460::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,460::task::595::Storage.TaskManager.Task::(_updateState) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::moving from state running -> state aborting
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,462::task::752::Storage.TaskManager.Task::(_save) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::_save: orig /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac temp /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac.temp
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,470::task::550::Storage.TaskManager.Task::(__state_aborting) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::_aborting: recover policy auto
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,470::task::595::Storage.TaskManager.Task::(_updateState) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::moving from state aborting -> state racquiring
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,470::task::752::Storage.TaskManager.Task::(_save) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::_save: orig /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac temp /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac.temp
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,477::task::595::Storage.TaskManager.Task::(_updateState) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::moving from state racquiring -> state recovering
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,478::task::752::Storage.TaskManager.Task::(_save) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::_save: orig /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac temp /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac.temp
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,485::task::798::Storage.TaskManager.Task::(_recover) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::_recover
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,485::task::805::Storage.TaskManager.Task::(_recover) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::running recovery None
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,485::task::786::Storage.TaskManager.Task::(_recoverDone) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::Recover Done: state recovering
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,485::task::595::Storage.TaskManager.Task::(_updateState) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::moving from state recovering -> state recovered
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,486::task::752::Storage.TaskManager.Task::(_save) Task=`c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac`::_save: orig /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac temp /rhev/data-center/00000002-0002-0002-0002-000000000336/mastersd/master/tasks/c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac.temp
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,493::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,493::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
c08b90ca-32dd-4c88-9f5c-7b2be5bf66ac::DEBUG::2017-04-06 08:12:27,493::threadPool::51::Storage.ThreadPool::(setRunningTask) Number of running tasks: 0