Bug 804388
| Summary: | [ovirt] [vdsm] pool upgrade: upgrade from 3.0 to 3.1 corrupts disk metadata | ||
|---|---|---|---|
| Product: | [Retired] oVirt | Reporter: | Haim <hateya> |
| Component: | vdsm | Assignee: | Saggi Mizrahi <smizrahi> |
| Status: | CLOSED WONTFIX | QA Contact: | |
| Severity: | unspecified | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | unspecified | CC: | abaron, acathrow, amureini, bazulay, iheim, mgoldboi, yeylon, ykaul |
| Target Milestone: | --- | ||
| Target Release: | 3.3.4 | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | storage | ||
| Fixed In Version: | Doc Type: | Bug Fix | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2013-02-17 06:23:45 UTC | Type: | --- |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | Storage | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
why would an upgrade even start in this case? So much has changed that I doubt this is still relevant. If reproducible, please reopen. |
Description of problem: - have pool with 3.0 compatibility version - have domains with metadata version 2 attached to it - from web-admin, change data-center compatibility version from 3.0 to 3.1 domains metadata looks as follows: Domain upgrade process starts. VG #PV #LV #SN Attr VSize VFree VG Tags 45290416-1dd4-494d-8ac9-29471752bd21 2 109 0 wz--n- 299.25g 171.12g RHAT_storage_domain,MDT__SHA_CKSUM=da39a3ee5e6b4b0d3255bfef95601890afd80709 924a8d2b-9fc1-4d20-9652-e6d72377b884 1 14 0 wz--n- 149.62g 99.75g RHAT_storage_domain,MDT__SHA_CKSUM=da39a3ee5e6b4b0d3255bfef95601890afd80709 metadata is corrupted. [root@nott-vds2 ~]# xzgrep "Thread-10835::" /var/log/vdsm/vdsm.log.1.xz Thread-10835::DEBUG::2012-03-18 15:44:45,142::BindingXMLRPC::167::vds::(wrapper) [10.35.97.30] Thread-10835::DEBUG::2012-03-18 15:44:45,142::task::588::TaskManager.Task::(_updateState) Task=`a3d726a8-e4a2-4376-9d03-089a702cc298`::moving from state init -> state preparing Thread-10835::INFO::2012-03-18 15:44:45,143::logUtils::37::dispatcher::(wrapper) Run and protect: upgradeStoragePool(spUUID='711a080f-4702-450c-9f5f-bf54f1e99383', targetDomVersion='3') Thread-10835::DEBUG::2012-03-18 15:44:45,144::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_711a080f-4702-450c-9f5f-bf54f1e99383`ReqID=`bcba1e20-081f-4677-ab2f-966ed6bfed80`::Request was made in '/usr/share/vdsm/storage/sp.py' line '402' at '_upgradePool' Thread-10835::DEBUG::2012-03-18 15:44:45,144::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_711a080f-4702-450c-9f5f-bf54f1e99383' for lock type 'exclusive' Thread-10835::DEBUG::2012-03-18 15:44:45,145::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.upgrade_711a080f-4702-450c-9f5f-bf54f1e99383' is free. Now locking as 'exclusive' (1 active user) Thread-10835::DEBUG::2012-03-18 15:44:45,145::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.upgrade_711a080f-4702-450c-9f5f-bf54f1e99383`ReqID=`bcba1e20-081f-4677-ab2f-966ed6bfed80`::Granted request Thread-10835::INFO::2012-03-18 15:44:45,145::sp::407::Storage.StoragePool::(_upgradePool) Trying to upgrade master domain `924a8d2b-9fc1-4d20-9652-e6d72377b884` Thread-10835::DEBUG::2012-03-18 15:44:45,146::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.924a8d2b-9fc1-4d20-9652-e6d72377b884`ReqID=`2f26baea-89cd-4867-9a05-b04dce8ef8da`::Request was made in '/usr/share/vdsm/storage/sp.py' line '408' at '_upgradePool' Thread-10835::DEBUG::2012-03-18 15:44:45,146::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.924a8d2b-9fc1-4d20-9652-e6d72377b884' for lock type 'exclusive' Thread-10835::DEBUG::2012-03-18 15:44:45,146::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.924a8d2b-9fc1-4d20-9652-e6d72377b884' is free. Now locking as 'exclusive' (1 active user) Thread-10835::DEBUG::2012-03-18 15:44:45,147::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.924a8d2b-9fc1-4d20-9652-e6d72377b884`ReqID=`2f26baea-89cd-4867-9a05-b04dce8ef8da`::Granted request Thread-10835::DEBUG::2012-03-18 15:44:45,147::lvm::464::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,147::lvm::466::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,148::lvm::475::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,148::lvm::487::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,148::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,149::lvm::284::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1locking-type-lun1-rami-5|1rami-upstream-lun1-500G4|1rami-upstream-lun2-500G4|1rami-upstream-lun3-500G4|3514f0c51afe00013|3514f0c51afe00014%\\", \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free 924a8d2b-9fc1-4d20-9652-e6d72377b884' (cwd None) Thread-10835::DEBUG::2012-03-18 15:44:45,276::lvm::284::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00014 was disabled\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00013 was disabled\n'; <rc> = 0 Thread-10835::DEBUG::2012-03-18 15:44:45,279::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,279::persistentDict::216::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=[u'VERSION=2', u'TYPE=ISCSI', u'LOGBLKSIZE=512', u'LEASERETRIES=3', u'LOCKRENEWALINTERVALSEC=5', u'LOCKPOLICY=', u'PHYBLKSIZE=512', u'CLASS=Data', u'VGUUID=oSuk1D-71j1-O1eR-0c0X-1kdF-VHSl-iJvopy', u'DESCRIPTION=rami-upstream-lun-1-onLion', u'SDUUID=924a8d2b-9fc1-4d20-9652-e6d72377b884', u'PV0=pv:1rami-upstream-lun1-500G4,uuid:fYA3XF-2Mgb-IeOu-od2I-lnrG-7oBS-2icaoH,pestart:0,pecount:1197,mapoffset:0', u'LEASETIMESEC=60', u'IOOPTIMEOUTSEC=10', u'POOL_UUID=711a080f-4702-450c-9f5f-bf54f1e99383', u'POOL_DESCRIPTION=iScSi-Dc', u'ROLE=Master', u'MASTER_VERSION=175', u'POOL_DOMAINS=c37e94b2-b130-49b4-a7aa-b30e8a372878:Attached,f3b51630-dacc-4a33-afc0-1d105e2104f8:Attached,45290416-1dd4-494d-8ac9-29471752bd21:Active,924a8d2b-9fc1-4d20-9652-e6d72377b884:Active,2beeea66-866d-4d3e-a1ef-1e1d9c1e124d:Active', u'_SHA_CKSUM=315e3ea368058945ac9cb294ca6fc5ac881ec808', u'POOL_SPM_ID=2', u'POOL_SPM_LVER=0'] Thread-10835::DEBUG::2012-03-18 15:44:45,280::blockSD::646::Storage.StorageDomain::(upgrade) Trying to upgrade domain `924a8d2b-9fc1-4d20-9652-e6d72377b884` from version 2 to version 3 Thread-10835::DEBUG::2012-03-18 15:44:45,281::blockSD::655::Storage.StorageDomain::(upgrade) Upgrading domain `924a8d2b-9fc1-4d20-9652-e6d72377b884` Thread-10835::DEBUG::2012-03-18 15:44:45,281::blockSD::660::Storage.StorageDomain::(upgrade) Upgrading domain `924a8d2b-9fc1-4d20-9652-e6d72377b884` to tag based metadata Thread-10835::DEBUG::2012-03-18 15:44:45,282::persistentDict::175::Storage.PersistentDict::(__init__) Created a persistant dict with VGTagMetadataRW backend Thread-10835::DEBUG::2012-03-18 15:44:45,282::lvm::464::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,283::lvm::466::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,283::lvm::475::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,284::lvm::487::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,284::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,285::lvm::284::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1locking-type-lun1-rami-5|1rami-upstream-lun1-500G4|1rami-upstream-lun2-500G4|1rami-upstream-lun3-500G4|3514f0c51afe00013|3514f0c51afe00014%\\", \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free 924a8d2b-9fc1-4d20-9652-e6d72377b884' (cwd None) Thread-10835::DEBUG::2012-03-18 15:44:45,416::lvm::284::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00014 was disabled\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00013 was disabled\n'; <rc> = 0 Thread-10835::DEBUG::2012-03-18 15:44:45,419::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,419::persistentDict::216::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=[u'VERSION=2', u'TYPE=ISCSI', u'LOGBLKSIZE=512', u'LEASERETRIES=3', u'LOCKRENEWALINTERVALSEC=5', u'LOCKPOLICY=', u'PHYBLKSIZE=512', u'CLASS=Data', u'VGUUID=oSuk1D-71j1-O1eR-0c0X-1kdF-VHSl-iJvopy', u'DESCRIPTION=rami-upstream-lun-1-onLion', u'SDUUID=924a8d2b-9fc1-4d20-9652-e6d72377b884', u'PV0=pv:1rami-upstream-lun1-500G4,uuid:fYA3XF-2Mgb-IeOu-od2I-lnrG-7oBS-2icaoH,pestart:0,pecount:1197,mapoffset:0', u'LEASETIMESEC=60', u'IOOPTIMEOUTSEC=10', u'POOL_UUID=711a080f-4702-450c-9f5f-bf54f1e99383', u'POOL_DESCRIPTION=iScSi-Dc', u'ROLE=Master', u'MASTER_VERSION=175', u'POOL_DOMAINS=c37e94b2-b130-49b4-a7aa-b30e8a372878:Attached,f3b51630-dacc-4a33-afc0-1d105e2104f8:Attached,45290416-1dd4-494d-8ac9-29471752bd21:Active,924a8d2b-9fc1-4d20-9652-e6d72377b884:Active,2beeea66-866d-4d3e-a1ef-1e1d9c1e124d:Active', u'_SHA_CKSUM=315e3ea368058945ac9cb294ca6fc5ac881ec808', u'POOL_SPM_ID=2', u'POOL_SPM_LVER=0'] Thread-10835::DEBUG::2012-03-18 15:44:45,420::persistentDict::152::Storage.PersistentDict::(transaction) Starting transaction Thread-10835::DEBUG::2012-03-18 15:44:45,421::persistentDict::158::Storage.PersistentDict::(transaction) Flushing changes Thread-10835::DEBUG::2012-03-18 15:44:45,421::persistentDict::277::Storage.PersistentDict::(flush) about to write lines (VGTagMetadataRW)=[u'CLASS=Data', u'DESCRIPTION=rami-upstream-lun-1-onLion', u'IOOPTIMEOUTSEC=10', u'LEASERETRIES=3', u'LEASETIMESEC=60', u'LOCKPOLICY=', u'LOCKRENEWALINTERVALSEC=5', u'LOGBLKSIZE=512', u'MASTER_VERSION=175', u'PHYBLKSIZE=512', u'POOL_DESCRIPTION=iScSi-Dc', u'POOL_DOMAINS=c37e94b2-b130-49b4-a7aa-b30e8a372878:Attached,f3b51630-dacc-4a33-afc0-1d105e2104f8:Attached,45290416-1dd4-494d-8ac9-29471752bd21:Active,924a8d2b-9fc1-4d20-9652-e6d72377b884:Active,2beeea66-866d-4d3e-a1ef-1e1d9c1e124d:Active', u'POOL_SPM_ID=2', u'POOL_SPM_LVER=0', u'POOL_UUID=711a080f-4702-450c-9f5f-bf54f1e99383', u'PV0=pv:1rami-upstream-lun1-500G4,uuid:fYA3XF-2Mgb-IeOu-od2I-lnrG-7oBS-2icaoH,pestart:0,pecount:1197,mapoffset:0', u'ROLE=Master', u'SDUUID=924a8d2b-9fc1-4d20-9652-e6d72377b884', u'TYPE=ISCSI', u'VERSION=3', u'VGUUID=oSuk1D-71j1-O1eR-0c0X-1kdF-VHSl-iJvopy', '_SHA_CKSUM=b374652aff94ed73085cc407117b5b5dae8df4cb'] Thread-10835::DEBUG::2012-03-18 15:44:45,422::lvm::464::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,422::lvm::466::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,423::lvm::475::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,424::lvm::487::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,424::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,425::lvm::284::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1locking-type-lun1-rami-5|1rami-upstream-lun1-500G4|1rami-upstream-lun2-500G4|1rami-upstream-lun3-500G4|3514f0c51afe00013|3514f0c51afe00014%\\", \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free 924a8d2b-9fc1-4d20-9652-e6d72377b884' (cwd None) Thread-10835::DEBUG::2012-03-18 15:44:45,552::lvm::284::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00014 was disabled\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00013 was disabled\n'; <rc> = 0 Thread-10835::DEBUG::2012-03-18 15:44:45,555::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:45,555::blockSD::158::storage.Metadata.VGTagMetadataRW::(writelines) Updating metadata adding=MDT_VERSION=3, MDT__SHA_CKSUM=b374652aff94ed73085cc407117b5b5dae8df4cb removing=MDT_VERSION=2, MDT__SHA_CKSUM=315e3ea368058945ac9cb294ca6fc5ac881ec808 Thread-10835::DEBUG::2012-03-18 15:44:45,556::lvm::284::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1locking-type-lun1-rami-5|1rami-upstream-lun1-500G4|1rami-upstream-lun2-500G4|1rami-upstream-lun3-500G4|3514f0c51afe00013|3514f0c51afe00014%\\", \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --deltag MDT__SHA_CKSUM=315e3ea368058945ac9cb294ca6fc5ac881ec808 --deltag MDT_VERSION=2 --addtag MDT__SHA_CKSUM=b374652aff94ed73085cc407117b5b5dae8df4cb --addtag MDT_VERSION=3 924a8d2b-9fc1-4d20-9652-e6d72377b884' (cwd None) Thread-10835::DEBUG::2012-03-18 15:44:46,730::lvm::284::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00014 was disabled\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00013 was disabled\n'; <rc> = 0 Thread-10835::DEBUG::2012-03-18 15:44:46,731::lvm::464::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:46,731::lvm::466::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:46,732::persistentDict::160::Storage.PersistentDict::(transaction) Finished transaction Thread-10835::DEBUG::2012-03-18 15:44:46,733::persistentDict::152::Storage.PersistentDict::(transaction) Starting transaction Thread-10835::DEBUG::2012-03-18 15:44:46,733::persistentDict::158::Storage.PersistentDict::(transaction) Flushing changes Thread-10835::DEBUG::2012-03-18 15:44:46,734::persistentDict::277::Storage.PersistentDict::(flush) about to write lines (VGTagMetadataRW)=['_SHA_CKSUM=da39a3ee5e6b4b0d3255bfef95601890afd80709'] Thread-10835::DEBUG::2012-03-18 15:44:46,734::lvm::464::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:46,735::lvm::466::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:46,735::lvm::475::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:46,736::lvm::487::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:46,736::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:46,737::lvm::284::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1locking-type-lun1-rami-5|1rami-upstream-lun1-500G4|1rami-upstream-lun2-500G4|1rami-upstream-lun3-500G4|3514f0c51afe00013|3514f0c51afe00014%\\", \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free 924a8d2b-9fc1-4d20-9652-e6d72377b884' (cwd None) Thread-10835::DEBUG::2012-03-18 15:44:46,868::lvm::284::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00014 was disabled\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00013 was disabled\n'; <rc> = 0 Thread-10835::DEBUG::2012-03-18 15:44:46,871::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:46,872::blockSD::158::storage.Metadata.VGTagMetadataRW::(writelines) Updating metadata adding=MDT__SHA_CKSUM=da39a3ee5e6b4b0d3255bfef95601890afd80709 removing=MDT_PHYBLKSIZE=512, MDT__SHA_CKSUM=b374652aff94ed73085cc407117b5b5dae8df4cb, MDT_PV0=pv:1rami-upstream-lun1-500G4&44&uuid:fYA3XF-2Mgb-IeOu-od2I-lnrG-7oBS-2icaoH&44&pestart:0&44&pecount:1197&44&mapoffset:0, MDT_LOGBLKSIZE=512, MDT_DESCRIPTION=rami-upstream-lun-1-onLion, MDT_SDUUID=924a8d2b-9fc1-4d20-9652-e6d72377b884, MDT_MASTER_VERSION=175, MDT_POOL_DESCRIPTION=iScSi-Dc, MDT_CLASS=Data, MDT_TYPE=ISCSI, MDT_POOL_DOMAINS=c37e94b2-b130-49b4-a7aa-b30e8a372878:Attached&44&f3b51630-dacc-4a33-afc0-1d105e2104f8:Attached&44&45290416-1dd4-494d-8ac9-29471752bd21:Active&44&924a8d2b-9fc1-4d20-9652-e6d72377b884:Active&44&2beeea66-866d-4d3e-a1ef-1e1d9c1e124d:Active, MDT_VERSION=3, MDT_LOCKPOLICY=, MDT_POOL_SPM_LVER=0, MDT_ROLE=Master, MDT_LEASERETRIES=3, MDT_POOL_SPM_ID=2, MDT_IOOPTIMEOUTSEC=10, MDT_LOCKRENEWALINTERVALSEC=5, MDT_VGUUID=oSuk1D-71j1-O1eR-0c0X-1kdF-VHSl-iJvopy, MDT_LEASETIMESEC=60, MDT_POOL_UUID=711a080f-4702-450c-9f5f-bf54f1e99383 Thread-10835::DEBUG::2012-03-18 15:44:46,873::lvm::284::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1locking-type-lun1-rami-5|1rami-upstream-lun1-500G4|1rami-upstream-lun2-500G4|1rami-upstream-lun3-500G4|3514f0c51afe00013|3514f0c51afe00014%\\", \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --deltag MDT_VERSION=3 --deltag MDT_ROLE=Master --deltag MDT_POOL_DOMAINS=c37e94b2-b130-49b4-a7aa-b30e8a372878:Attached&44&f3b51630-dacc-4a33-afc0-1d105e2104f8:Attached&44&45290416-1dd4-494d-8ac9-29471752bd21:Active&44&924a8d2b-9fc1-4d20-9652-e6d72377b884:Active&44&2beeea66-866d-4d3e-a1ef-1e1d9c1e124d:Active --deltag MDT_LOCKPOLICY= --deltag MDT_MASTER_VERSION=175 --deltag MDT_IOOPTIMEOUTSEC=10 --deltag MDT_CLASS=Data --deltag MDT_LEASETIMESEC=60 --deltag MDT__SHA_CKSUM=b374652aff94ed73085cc407117b5b5dae8df4cb --deltag MDT_LOCKRENEWALINTERVALSEC=5 --deltag MDT_POOL_UUID=711a080f-4702-450c-9f5f-bf54f1e99383 --deltag MDT_VGUUID=oSuk1D-71j1-O1eR-0c0X-1kdF-VHSl-iJvopy --deltag MDT_DESCRIPTION=rami-upstream-lun-1-onLion --deltag MDT_SDUUID=924a8d2b-9fc1-4d20-9652-e6d72377b884 --deltag MDT_POOL_SPM_ID=2 --deltag MDT_POOL_DESCRIPTION=iScSi-Dc --deltag MDT_TYPE=ISCSI --deltag MDT_LOGBLKSIZE=512 --deltag MDT_LEASERETRIES=3 --deltag MDT_PHYBLKSIZE=512 --deltag MDT_POOL_SPM_LVER=0 --deltag MDT_PV0=pv:1rami-upstream-lun1-500G4&44&uuid:fYA3XF-2Mgb-IeOu-od2I-lnrG-7oBS-2icaoH&44&pestart:0&44&pecount:1197&44&mapoffset:0 --addtag MDT__SHA_CKSUM=da39a3ee5e6b4b0d3255bfef95601890afd80709 924a8d2b-9fc1-4d20-9652-e6d72377b884' (cwd None) Thread-10835::DEBUG::2012-03-18 15:44:47,132::lvm::284::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00014: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00014 was disabled\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368643584: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 5368700928: Input/output error\n /dev/mapper/3514f0c51afe00013: read failed after 0 of 4096 at 0: Input/output error\n WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c51afe00013 was disabled\n'; <rc> = 0 Thread-10835::DEBUG::2012-03-18 15:44:47,133::lvm::464::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:47,134::lvm::466::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex Thread-10835::DEBUG::2012-03-18 15:44:47,135::persistentDict::160::Storage.PersistentDict::(transaction) Finished transaction Thread-10835::DEBUG::2012-03-18 15:44:47,136::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.924a8d2b-9fc1-4d20-9652-e6d72377b884' Thread-10835::DEBUG::2012-03-18 15:44:47,136::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.924a8d2b-9fc1-4d20-9652-e6d72377b884' (0 active users) Thread-10835::DEBUG::2012-03-18 15:44:47,136::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.924a8d2b-9fc1-4d20-9652-e6d72377b884' is free, finding out if anyone is waiting for it. Thread-10835::DEBUG::2012-03-18 15:44:47,137::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.924a8d2b-9fc1-4d20-9652-e6d72377b884', Clearing records. Thread-10835::DEBUG::2012-03-18 15:44:47,137::sp::411::Storage.StoragePool::(_upgradePool) Marking all domains for upgrade Thread-10835::DEBUG::2012-03-18 15:44:47,137::sp::418::Storage.StoragePool::(_upgradePool) Registering with state change event Thread-10835::DEBUG::2012-03-18 15:44:47,138::sp::420::Storage.StoragePool::(_upgradePool) Running initial domain upgrade threads Thread-10835::DEBUG::2012-03-18 15:44:47,140::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_711a080f-4702-450c-9f5f-bf54f1e99383' Thread-10835::DEBUG::2012-03-18 15:44:47,143::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_711a080f-4702-450c-9f5f-bf54f1e99383' (0 active users) Thread-10835::DEBUG::2012-03-18 15:44:47,145::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.upgrade_711a080f-4702-450c-9f5f-bf54f1e99383' is free, finding out if anyone is waiting for it. Thread-10835::DEBUG::2012-03-18 15:44:47,145::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_711a080f-4702-450c-9f5f-bf54f1e99383', Clearing records. Thread-10835::INFO::2012-03-18 15:44:47,147::logUtils::39::dispatcher::(wrapper) Run and protect: upgradeStoragePool, Return response: {'upgradeStatus': 'started'} Thread-10835::DEBUG::2012-03-18 15:44:47,148::task::1172::TaskManager.Task::(prepare) Task=`a3d726a8-e4a2-4376-9d03-089a702cc298`::finished: {'upgradeStatus': 'started'} Thread-10835::DEBUG::2012-03-18 15:44:47,149::task::588::TaskManager.Task::(_updateState) Task=`a3d726a8-e4a2-4376-9d03-089a702cc298`::moving from state preparing -> state finished Thread-10835::DEBUG::2012-03-18 15:44:47,151::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-10835::DEBUG::2012-03-18 15:44:47,153::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-10835::DEBUG::2012-03-18 15:44:47,156::task::978::TaskManager.Task::(_decref) Task=`a3d726a8-e4a2-4376-9d03-089a702cc298`::ref 0 aborting False