Bug 670814

Summary: 2.2.6 - vdsm22: "Could not update/change volume group permissions" when running reconstructMaster
Product: Red Hat Enterprise Linux 5 Reporter: RHEL Program Management <pm-rhel>
Component: vdsm22Assignee: Saggi Mizrahi <smizrahi>
Status: CLOSED ERRATA QA Contact: yeylon <yeylon>
Severity: high Docs Contact:
Priority: low    
Version: 5.6CC: abaron, bazulay, chetan, danken, djorm, dpaikov, ewarszaw, iheim, ohochman, plyons, pm-eus, smizrahi, srevivo, ykaul
Target Milestone: rcKeywords: Reopened, ZStream
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard: Storage
Fixed In Version: vdsm22-4.5-63.18 Doc Type: Bug Fix
Doc Text:
C: Add and attach two iSCSI sata storage domains in RHEL5.6 C: Could not update or change volume group permissions when running reconstructMaster F: The vdsm22-4.5-63.19.el5_6 update enables reconstructMaster to reactivate the logical volumes. R: reconstructMaster can now update volume group permissions. Previously, disconnectStoragePool would call "vgchange --available n" and disable reconstructMaster from changing or updating volume group permissions. This update enables reconstructMaster to reactivate the logical volumes, and as a result it can now edit volume group permissions.
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-03-10 09:19:16 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On: 670550    
Bug Blocks:    
Attachments:
Description Flags
vdsm log none

Description RHEL Program Management 2011-01-19 13:16:59 UTC
This bug has been copied from bug #670550 and has been proposed
to be backported to 5.6 z-stream (EUS).

Comment 4 Daniel Paikov 2011-01-23 10:31:21 UTC
Still reproduces on vdsm22-4.5-63.12.el5_6.

Comment 5 Daniel Paikov 2011-01-25 13:25:54 UTC
Couldn't reproduce more than once. Closing as Verified as of vdsm22-4.5-63.13.

Comment 6 Avi Tal 2011-02-08 13:44:57 UTC
reopen due to reproduction on vdsm22-4.5-63.15.el5_6
on navy-vds1.qa.lab.tlv.redhat.com

Comment 7 Avi Tal 2011-02-08 13:57:39 UTC
Created attachment 477613 [details]
vdsm log

Comment 8 Avi Tal 2011-02-08 14:26:22 UTC
note:
it doesn't reproduce easily. actually i can't reproduce it more than one time

Comment 9 Ayal Baron 2011-02-09 19:22:43 UTC
Issue is that disconnectStoragePool calls "vgchange --available n" and nothing reactivates the special LVs later (reconstruct should):

Thread-15094::DEBUG::2011-02-08 15:34:11,094::misc::100::irs::'/usr/bin/sudo -n /usr/sbin/vgchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] write_cache_state=0 filter = [ \\"a%/dev/mapper/1atal_data21|/dev/mapper/1atal_data22|/dev/mapper/1atal_data23|/dev/mapper/1atal_data25%\\", \\"r%.*%\\" ] }  backup {  retain_min = 50  retain_days = 0 } " --available n e144a741-8a99-439d-a16c-36cb1eb6afd6' (cwd None)
Thread-15094::DEBUG::2011-02-08 15:34:11,328::misc::123::irs::SUCCESS: <err> = ''; <rc> = 0

...

Thread-15094::INFO::2011-02-08 15:34:11,332::dispatcher::101::irs::Run and protect: disconnectStoragePool, Return response: {'status': {'message': 'OK', 'code': 0}}
Thread-15095::INFO::2011-02-08 15:34:11,361::dispatcher::95::irs::Run and protect: reconstructMaster, args: ( spUUID=453592dc-23d2-455f-aa80-394792123cd6 poolName=DCiscsi master
Dom=45aa390a-ce67-4357-a735-2f85beab6368 domDict={'1d426f7c-6676-48a3-baaa-6e04634783d1': 'active', '68a88486-b063-40ab-a823-81dd23f713d5': 'active', '4d7d508d-75dc-465b-81c3-22
88ab3d90b6': 'active', '21b9b0a4-d24c-4551-87b2-a498fdf43f1a': 'active', '45aa390a-ce67-4357-a735-2f85beab6368': 'active', '10a2d260-73a8-4eda-84b8-83d237360f7f': 'active', 'e14
4a741-8a99-439d-a16c-36cb1eb6afd6': 'active'} masterVersion=53 lockPolicy=ON lockRenewalIntervalSec=5 leaseTimeSec=60 ioOpTimeoutSec=10 leaseRetries=3)
Thread-15095::DEBUG::2011-02-08 15:34:11,361::task::577::irs::Task c5f9ac0e-37fc-43b4-8afe-d62039125742: moving from state init -> state preparing
Thread-15095::INFO::2011-02-08 15:34:11,362::hsm::649::irs::(HSM.reconstructMaster) spUUID=453592dc-23d2-455f-aa80-394792123cd6 master=45aa390a-ce67-4357-a735-2f85beab6368
Thread-15095::INFO::2011-02-08 15:34:11,362::blockSD::460::irs::(BlockStorageDomain.validate) sdUUID=45aa390a-ce67-4357-a735-2f85beab6368
Thread-15095::DEBUG::2011-02-08 15:34:11,363::misc::100::irs::'/usr/bin/sudo -n /bin/chown vdsm:kvm /dev/45aa390a-ce67-4357-a735-2f85beab6368 /dev/45aa390a-ce67-4357-a735-2f85be
ab6368/metadata /dev/45aa390a-ce67-4357-a735-2f85beab6368/leases /dev/45aa390a-ce67-4357-a735-2f85beab6368/ids /dev/45aa390a-ce67-4357-a735-2f85beab6368/inbox /dev/45aa390a-ce67
-4357-a735-2f85beab6368/outbox' (cwd None)
Thread-15095::WARNING::2011-02-08 15:34:11,407::misc::125::irs::FAILED: <err> = "/bin/chown: cannot access `/dev/45aa390a-ce67-4357-a735-2f85beab6368': No such file or directory
\n/bin/chown: cannot access `/dev/45aa390a-ce67-4357-a735-2f85beab6368/metadata': No such file or directory\n/bin/chown: cannot access `/dev/45aa390a-ce67-4357-a735-2f85beab6368
/leases': No such file or directory\n/bin/chown: cannot access `/dev/45aa390a-ce67-4357-a735-2f85beab6368/ids': No such file or directory\n/bin/chown: cannot access `/dev/45aa39
0a-ce67-4357-a735-2f85beab6368/inbox': No such file or directory\n/bin/chown: cannot access `/dev/45aa390a-ce67-4357-a735-2f85beab6368/outbox': No such file or directory\n"; <rc
> = 1

Comment 10 Omri Hochman 2011-02-15 15:31:36 UTC
reproduced vdsm22-4.5-63.17.el5_6,

reproducible Scenario:  
-add and attach two iSCSI data storage domains fast enough (one by one) 

LOG-VDSM
********
Thread-9989::DEBUG::2011-02-15 17:00:20,268::task::577::irs::Task 335bd4a2-a4ac-489c-8d4d-78f4707ebe94: stopping in state preparing (force False)
Thread-9475::DEBUG::2011-02-15 17:00:20,269::misc::123::irs::SUCCESS: <err> = ''; <rc> = 0
Thread-4440::DEBUG::2011-02-15 17:00:20,271::misc::100::irs::'/usr/bin/sudo -n /usr/sbin/vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] write_cache_state=0 filter = [ \\"a
%/dev/mapper/1Omri_lun1|/dev/mapper/1Omri_lun10|/dev/mapper/1Omri_lun2|/dev/mapper/1Omri_lun3|/dev/mapper/1Omri_lun4|/dev/mapper/1Omri_lun5|/dev/mapper/1Omri_lun6|/dev/mapper/1Omri_lun7|/de
v/mapper/1Omri_lun8|/dev/mapper/1Omri_lun9|/dev/mapper/3600144f0e90c870000004d2dd0d80002|/dev/mapper/3600144f0e90c870000004d2dd0fc0005|/dev/mapper/3600144f0e90c870000004d2dd168000e|/dev/map
per/3600144f0e90c870000004d2dd174000f|/dev/mapper/3600144f0e90c870000004d2dd1820010|/dev/mapper/3600144f0e90c870000004d2dd1a70013|/dev/mapper/3600144f0e90c870000004d2dd1b40014|/dev/mapper/3
600144f0e90c870000004d2dd201001a|/dev/mapper/3600144f0e90c870000004d357eab0005|/dev/mapper/3600144f0e90c870000004d357ed80007|/dev/mapper/3600144f0e90c870000004d357efa0009|/dev/mapper/360014
4f0e90c870000004d3585f70012|/dev/mapper/3600144f0e90c870000004d3586210014|/dev/mapper/3600144f0e90c870000004d3586740016|/dev/mapper/3600144f0e90c870000004d380c6b001e|/dev/mapper/3600144f0e9
0c870000004d525105004a%\\", \\"r%.*%\\" ] }  backup {  retain_min = 50  retain_days = 0 } " --noheadings -o pv_name cd7d864d-e87e-4721-af88-55e25c8e3da7' (cwd None)
Thread-9989::DEBUG::2011-02-15 17:00:20,276::task::577::irs::Task 335bd4a2-a4ac-489c-8d4d-78f4707ebe94: ref 1 aborting True
Thread-9880::DEBUG::2011-02-15 17:00:20,277::misc::100::irs::'/usr/bin/sudo -n /bin/chown vdsm:kvm /dev/7f9cb8b1-ac82-4fc5-90bd-d76e9c3a1da0 /dev/7f9cb8b1-ac82-4fc5-90bd-d76e9c3a1da0/metada
ta /dev/7f9cb8b1-ac82-4fc5-90bd-d76e9c3a1da0/leases /dev/7f9cb8b1-ac82-4fc5-90bd-d76e9c3a1da0/ids /dev/7f9cb8b1-ac82-4fc5-90bd-d76e9c3a1da0/inbox /dev/7f9cb8b1-ac82-4fc5-90bd-d76e9c3a1da0/o
utbox /dev/7f9cb8b1-ac82-4fc5-90bd-d76e9c3a1da0/master' (cwd None)
Thread-9475::DEBUG::2011-02-15 17:00:20,278::misc::100::irs::'/usr/bin/sudo -n /usr/sbin/vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] write_cache_state=0 filter = [ \\"a
%/dev/mapper/1Omri_lun1|/dev/mapper/1Omri_lun10|/dev/mapper/1Omri_lun2|/dev/mapper/1Omri_lun3|/dev/mapper/1Omri_lun4|/dev/mapper/1Omri_lun5|/dev/mapper/1Omri_lun6|/dev/mapper/1Omri_lun7|/de
v/mapper/1Omri_lun8|/dev/mapper/1Omri_lun9|/dev/mapper/3600144f0e90c870000004d2dd0d80002|/dev/mapper/3600144f0e90c870000004d2dd0fc0005|/dev/mapper/3600144f0e90c870000004d2dd168000e|/dev/map
per/3600144f0e90c870000004d2dd174000f|/dev/mapper/3600144f0e90c870000004d2dd1820010|/dev/mapper/3600144f0e90c870000004d2dd1a70013|/dev/mapper/3600144f0e90c870000004d2dd1b40014|/dev/mapper/3
600144f0e90c870000004d2dd201001a|/dev/mapper/3600144f0e90c870000004d357eab0005|/dev/mapper/3600144f0e90c870000004d357ed80007|/dev/mapper/3600144f0e90c870000004d357efa0009|/dev/mapper/360014
4f0e90c870000004d3585f70012|/dev/mapper/3600144f0e90c870000004d3586210014|/dev/mapper/3600144f0e90c870000004d3586740016|/dev/mapper/3600144f0e90c870000004d380c6b001e|/dev/mapper/3600144f0e9
0c870000004d525105004a%\\", \\"r%.*%\\" ] }  backup {  retain_min = 50  retain_days = 0 } " --noheadings -o pv_name 7f9cb8b1-ac82-4fc5-90bd-d76e9c3a1da0' (cwd None)
Thread-4430::DEBUG::2011-02-15 17:00:20,277::misc::123::irs::SUCCESS: <err> = ''; <rc> = 0
Thread-4430::DEBUG::2011-02-15 17:00:20,315::misc::100::irs::'/usr/bin/sudo -n /usr/sbin/vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] write_cache_state=0 filter = [ \\"a
%/dev/mapper/1Omri_lun4%\\", \\"r%.*%\\" ] }  backup {  retain_min = 50  retain_days = 0 } " --noheadings -o vg_uuid,vg_size,vg_fre
e,vg_extent_size,vg_extent_count,attr --nosuffix --units b 29ba5384-515b-4b9a-8db1-a2b7533aada7' (cwd None)
Thread-9989::INFO::2011-02-15 17:00:20,293::task::1281::irs::aborting: Task is aborted: "Could not update/change volume group permissions, UUID: '29ba5384-515b-4b9a-8db1-a2b7533aada7'" - code 100
Thread-9989::DEBUG::2011-02-15 17:00:20,338::task::577::irs::Task 335bd4a2-a4ac-489c-8d4d-78f4707ebe94: Prepare: aborted: Could not update/change volume group permissions, UUID: '29ba5384-515b-4b9a-8db1-a2b7533aada7'
Thread-9989::DEBUG::2011-02-15 17:00:20,339::task::577::irs::Task 335bd4a2-a4ac-489c-8d4d-78f4707ebe94: ref 0 aborting True
Thread-9989::DEBUG::2011-02-15 17:00:20,339::task::577::irs::Task 335bd4a2-a4ac-489c-8d4d-78f4707ebe94: Task._doAbort: force False
Thread-9989::DEBUG::2011-02-15 17:00:20,339::resource::678::irs::Owner.cancelAll requests []
Thread-9989::DEBUG::2011-02-15 17:00:20,340::task::577::irs::Task 335bd4a2-a4ac-489c-8d4d-78f4707ebe94: moving from state preparing -> state aborting
Thread-9989::DEBUG::2011-02-15 17:00:20,340::task::577::irs::Task 335bd4a2-a4ac-489c-8d4d-78f4707ebe94: _aborting: recover policy none
Thread-9989::DEBUG::2011-02-15 17:00:20,341::task::577::irs::Task 335bd4a2-a4ac-489c-8d4d-78f4707ebe94: moving from state aborting -> state failed
Thread-4438::DEBUG::2011-02-15 17:00:20,338::misc::123::irs::SUCCESS: <err> = ''; <rc> = 0
Thread-9989::DEBUG::2011-02-15 17:00:20,342::resource::670::irs::Owner.releaseAll requests [] resources []
Thread-9989::ERROR::2011-02-15 17:00:20,344::dispatcher::104::irs::{'status': {'message': "Could not update/change volume group permissions, UUID: '29ba5384-515b-4b9a-8db1-a2b7533aada7'", 'code': 501}, 'args': ['29ba5384-515b-4b9a-8db1-a2b7533aada7']}
Thread-9989::ERROR::2011-02-15 17:00:20,344::dispatcher::106::irs::Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 97, in run
    result = ctask.prepare(self.func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 1287, in prepare
    raise self.error
VolumeGroupPermissionsError: Could not update/change volume group permissions, UUID: '29ba5384-515b-4b9a-8db1-a2b7533aada7'

Comment 11 Omri Hochman 2011-02-17 09:31:17 UTC
verified vdsm22-4.5-63.19.el5_6.

Comment 12 Cheryn Tan 2011-03-01 04:22:57 UTC
    Technical note added. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    New Contents:
C: Add and attach two iSCSI sata storage domains in RHEL5.6
C: Could not update or change volume group permissions when running reconstructMaster
F: The vdsm22-4.5-63.19.el5_6 update enables reconstructMaster to reactivate the logical volumes. 
R: reconstructMaster can now update volume group permissions.

When adding and attaching two iSCSI data storage domains in Red Hat Enterprise Linux 5.6, reconstructMaster could not update or change the volume group permissions. The vdsm22-4.5-63.19.el5_6 update enables reconstructMaster to reactivate the logical volumes. As a result, reconstructMaster can now edit volume group permissions.

Comment 13 David Jorm 2011-03-03 04:16:36 UTC
    Technical note updated. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    Diffed Contents:
@@ -3,4 +3,4 @@
 F: The vdsm22-4.5-63.19.el5_6 update enables reconstructMaster to reactivate the logical volumes. 
 R: reconstructMaster can now update volume group permissions.
 
-When adding and attaching two iSCSI data storage domains in Red Hat Enterprise Linux 5.6, reconstructMaster could not update or change the volume group permissions. The vdsm22-4.5-63.19.el5_6 update enables reconstructMaster to reactivate the logical volumes. As a result, reconstructMaster can now edit volume group permissions.+Previously, disconnectStoragePool would call "vgchange --available n" and disable reconstructMaster from changing or updating volume group permissions. This update enables reconstructMaster to reactivate the logical volumes, and as a result it can now edit volume group permissions.

Comment 14 errata-xmlrpc 2011-03-10 09:19:16 UTC
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHBA-2011-0319.html