After upgrading an oVirt cluster from 3.5 to 3.6, I am getting the following error every hour:
Failed to update OVF disks ce8647c6-f936-4633-8a7b-e7dcb45d8ebb, OVF data isn't updated on those OVF stores (Data Center Middle-Earth, Storage Domain equallogic). Looking in the vdsm log on the SPM node, it looks like the problem is that an attempt was made to lvextend an LV to 2m, but the LV is already 128m, so the extend failed (not needed). I've attached the log entries for that task. Any suggestions, ideas how to fix, etc.? -- Chris Adams <c...@cmadams.net>
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
_______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users