Bug 804388 - [ovirt] [vdsm] pool upgrade: upgrade from 3.0 to 3.1 corrupts disk metadata
[ovirt] [vdsm] pool upgrade: upgrade from 3.0 to 3.1 corrupts disk metadata
Status: CLOSED WONTFIX
Product: oVirt
Classification: Community
Component: vdsm (Show other bugs)
unspecified
Unspecified Unspecified
unspecified Severity unspecified
: ---
: 3.3.4
Assigned To: Saggi Mizrahi
storage
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-03-18 11:20 EDT by Haim
Modified: 2016-02-10 11:58 EST (History)
8 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-02-17 01:23:45 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Storage
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Haim 2012-03-18 11:20:37 EDT
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
Comment 1 Itamar Heim 2012-03-19 09:40:28 EDT
why would an upgrade even start in this case?
Comment 2 Ayal Baron 2013-02-17 01:23:45 EST
So much has changed that I doubt this is still relevant.
If reproducible, please reopen.

Note You need to log in before you can comment on or make changes to this bug.