Grouper Users - Open Discussion List

[David Langenberg <>]

Typically when I've seen the PSP do this, the root cause is a configuration issue in the psp-resolver.xml.  The general issue is the attribute being pulled from LDAP vs the attribute being pulled from Grouper are just *slightly* different, thus causing grouper to think there's a change when in reality there isn't.  I'm not sure why it wants to do an Add/Delete in this case though as it clearly should be doing a replace and will probably need logs at TRACE to figure that one out.

Dave

On Mon, Jan 12, 2015 at 4:20 AM, Mark Cairney <> wrote:

Hi,

Has anyone had a chance to look at this issue? Another possible bug I've
noticed is with an attempted rename of the description field.
It looks like Grouper is interpreting this change as an "add" then a
"delete". This always fails because description is not a multi-valued
field. It should either be issuing an LDAP replace command or a delete
then add command. I'm not sure if this is an issue with our PSP
configuration or a bug:

2015-01-12 04:09:01,017: [main] INFO  BaseSpmlProvider.execute(351) -  -
Target 'ldap' - Modify ModifyRequest[ps
oID=PSOIdentifier[id='ou=VSCRDPAR01S2,ou=pos,ou=grouper2,dc=authorise-test,dc=ed,dc=ac,dc=uk',targetID=ldap,cont
ainerID=<null>],mod=DSMLModification[name=description,op=add],mod=DSMLModification[name=description,op=delete],r
eturnData=everything,requestID=2015/01/12-04:09:01.015]
2015-01-12 04:09:01,017: [main] INFO  BaseSpmlProvider.execute(355) -  -
Target 'ldap' - Modify XML:
<modifyRequest xmlns='urn:oasis:names:tc:SPML:2:0' entityName='stem'
requestID='2015/01/12-04:09:01.015' returnD
ata='everything'>
  <psoID
ID='ou=VSCRDPAR01S2,ou=pos,ou=grouper2,dc=authorise-test,dc=ed,dc=ac,dc=uk'
targetID='ldap'/>
  <modification modificationMode='add'>
    <dsml:modification xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core'
name='description' operation='add'>
      <dsml:value>NGU Semester 2 Courses for Parliamentary
Programme</dsml:value>
    </dsml:modification>
  </modification>
  <modification modificationMode='delete'>
    <dsml:modification xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core'
name='description' operation='delete'>
      <dsml:value>NGU Semester 2 Courses for Parliamentary Programme
</dsml:value>
    </dsml:modification>
  </modification>
</modifyRequest>

2015-01-12 04:09:01,018: [main] ERROR BaseSpmlProvider.execute(386) -  -
Target 'ldap' - Modify
ModifyResponse[pso=<null>,status=failure,error=customError,errorMessages={[LDAP:
error code 20 - modify/add: description: value #0 already
exists]},requestID=2015/01/12-04:09:01.015]
2015-01-12 04:09:01,019: [main] ERROR BaseSpmlProvider.execute(388) -  -
Target 'ldap' - Modify XML:
<modifyResponse xmlns='urn:oasis:names:tc:SPML:2:0' status='failure'
requestID='2015/01/12-04:09:01.015' error='customError'>
  <errorMessage>[LDAP: error code 20 - modify/add: description: value #0
already exists]</errorMessage>
</modifyResponse>

On 06/01/15 16:42, Mark Cairney wrote:
> Hi,
>
> I've been investigating why when attempting a bulksync some particular
> groups were throwing errors like:
>
> Jan  6 10:31:02 elm slapd[29204]: conn=2845205 op=0 BIND
> dn="uid=grouper,ou=peop
> le,ou=central,dc=authorise-test,dc=ed,dc=ac,dc=uk" method=128
> Jan  6 10:31:02 elm slapd[29204]: conn=2845205 op=0 BIND
> dn="uid=grouper,ou=peop
> le,ou=central,dc=authorise-test,dc=ed,dc=ac,dc=uk" mech=SIMPLE ssf=0
> Jan  6 10:31:02 elm slapd[29204]: conn=2845205 op=0 RESULT tag=97 err=0
> text=
> Jan  6 10:31:02 elm slapd[29204]: conn=2845205 op=1 MOD
> dn="cn=S2F,ou=S2F,ou=HSS3,ou=HSS,ou=UOE,ou=org,ou=grouper2,dc=authorise-test,dc=ed,dc=ac,dc=uk"
> Jan  6 10:31:02 elm slapd[29204]: conn=2845205 op=1 MOD attr=member member
> Jan  6 10:31:02 elm slapd[29204]: slap_queue_csn: queueing
> 0x7f6ce7ab7160 20150106103102.091564Z#000000#008#000000
> Jan  6 10:31:02 elm slapd[29204]: conn=2845205 op=1 RESULT tag=103
> err=20 text=modify/add: member: value #0 already exists
>
> On the Grouper side I see:
>
> 2015-01-06 10:31:01,992: [main] INFO  BaseSpmlProvider.execute(351) -  -
> Target
> 'ldap' - Modify
> ModifyRequest[psoID=PSOIdentifier[id='cn=S2F,ou=S2F,ou=HSS3,ou=H
> SS,ou=UOE,ou=org,ou=grouper2,dc=authorise-test,dc=ed,dc=ac,dc=uk',targetID=ldap,
> containerID=<null>],typeOfReference=member,typeOfReference=member,returnData=eve
> rything,requestID=2015/01/06-10:31:01.977]
> 2015-01-06 10:31:01,994: [main] INFO  BaseSpmlProvider.execute(355) -  -
> Target
> 'ldap' - Modify XML:
> <modifyRequest xmlns='urn:oasis:names:tc:SPML:2:0' entityName='group'
> requestID=
> '2015/01/06-10:31:01.977' returnData='everything'>
>   <psoID
> ID='cn=S2F,ou=S2F,ou=HSS3,ou=HSS,ou=UOE,ou=org,ou=grouper2,dc=authorise
> -test,dc=ed,dc=ac,dc=uk' targetID='ldap'/>
>   <modification modificationMode='add'>
>     <capabilityData mustUnderstand='true'
> capabilityURI='urn:oasis:names:tc:SPML
> :2:0:reference'>
>       <spmlref:reference xmlns='urn:oasis:names:tc:SPML:2:0'
> xmlns:spmlref='urn:
> oasis:names:tc:SPML:2:0:reference' typeOfReference='member'>
>         <spmlref:toPsoID
> ID='cn=NUST11058_SS1_2009/0_SB5\+,ou=2009/2010,ou=cours
> es,ou=grouper2,dc=authorise-test,dc=ed,dc=ac,dc=uk' targetID='ldap'/>
>       </spmlref:reference>
>     </capabilityData>
>   </modification>
>   <modification modificationMode='delete'>
>     <capabilityData mustUnderstand='true'
> capabilityURI='urn:oasis:names:tc:SPML
> :2:0:reference'>
>       <spmlref:reference xmlns='urn:oasis:names:tc:SPML:2:0'
> xmlns:spmlref='urn:
> oasis:names:tc:SPML:2:0:reference' typeOfReference='member'>
>         <spmlref:toPsoID
> ID='cn=NUST11058_SS1_2009/0_SB5\2B,ou=2009/2010,ou=cour
> ses,ou=grouper2,dc=authorise-test,dc=ed,dc=ac,dc=uk' targetID='ldap'/>
>       </spmlref:reference>
>       <spmlref:reference xmlns='urn:oasis:names:tc:SPML:2:0'
> xmlns:spmlref='urn:
> oasis:names:tc:SPML:2:0:reference' typeOfReference='member'>
>         <spmlref:toPsoID
> ID='uid=s0459972,ou=people,ou=central,dc=authorise-test
> ,dc=ed,dc=ac,dc=uk' targetID='ldap'/>
>       </spmlref:reference>
>       <spmlref:reference xmlns='urn:oasis:names:tc:SPML:2:0'
> xmlns:spmlref='urn:
> oasis:names:tc:SPML:2:0:reference' typeOfReference='member'>
>         <spmlref:toPsoID
> ID='uid=s0570825,ou=people,ou=central,dc=authorise-test
> ,dc=ed,dc=ac,dc=uk' targetID='ldap'/>
>       </spmlref:reference>
>       <spmlref:reference xmlns='urn:oasis:names:tc:SPML:2:0'
> xmlns:spmlref='urn:
> oasis:names:tc:SPML:2:0:reference' typeOfReference='member'>
>         <spmlref:toPsoID
> ID='uid=s0678327,ou=people,ou=central,dc=authorise-test
> ,dc=ed,dc=ac,dc=uk' targetID='ldap'/>
>       </spmlref:reference>
>       <spmlref:reference xmlns='urn:oasis:names:tc:SPML:2:0'
> xmlns:spmlref='urn:
> oasis:names:tc:SPML:2:0:reference' typeOfReference='member'>
>         <spmlref:toPsoID
> ID='uid=s0679838,ou=people,ou=central,dc=authorise-test
> ,dc=ed,dc=ac,dc=uk' targetID='ldap'/>
>       </spmlref:reference>
>
>
> <---- SNIP ------>
>
>
> 2015-01-06 10:31:02,095: [main] ERROR BaseSpmlProvider.execute(386) -  -
> Target
> 'ldap' - Modify
> ModifyResponse[pso=<null>,status=failure,error=customError,error
> Messages={[LDAP: error code 20 - modify/add: member: value #0 already
> exists]},r
> equestID=2015/01/06-10:31:01.977]
> 2015-01-06 10:31:02,096: [main] ERROR BaseSpmlProvider.execute(388) -  -
> Target
> 'ldap' - Modify XML:
> <modifyResponse xmlns='urn:oasis:names:tc:SPML:2:0' status='failure'
> requestID='
> 2015/01/06-10:31:01.977' error='customError'>
>   <errorMessage>[LDAP: error code 20 - modify/add: member: value #0
> already exis
> ts]</errorMessage>
> </modifyResponse>
>
>
> Looking at this it looks like the problematic entry is the first group:
> "cn=NUST11058_SS1_2009/0_SB5\+,ou=2009/2010,ou=courses,ou=grouper2,dc=authorise-test,dc=ed,dc=ac,dc=uk"
>
> However this group is already a member of the "S2F" group:
>
> bash-4.1$ testauthzsearch -b
> "cn=S2F,ou=S2F,ou=HSS3,ou=HSS,ou=UOE,ou=org,ou=grouper2,dc=authorise-test,dc=ed,dc=ac,dc=uk"
> member |grep 'NUST11058'
> Enter LDAP Password:
> member:
> cn=NUST11058_SS1_2009/0_SB5\2B,ou=2009/2010,ou=courses,ou=grouper2,dc=
>
> The group exists in the Grouper structure and does itself have members.
>
> I think the cause must be that the "+" symbol is treated as a special
> character in LDAP so the DN has "\2B" rather than "+" and this is
> throwing Grouper as I don't see this behaviour with groups that don't
> have a "+" in their cn/dn. (see
> http://www.openldap.org/lists/openldap-software/200307/msg00624.html)
>
> The group in question as deployed using Grouper is:
> dn:
> cn=NUST11058_SS1_2009/0_SB5\2B,ou=2009/2010,ou=courses,ou=grouper2,dc=auth
>  orise-test,dc=ed,dc=ac,dc=uk
> gidNumber: 4187827680
> objectClass: groupOfNames
> objectClass: posixGroup
> objectClass: top
> description: Dissertation (MSc Advancing Nursing Practice) (SS1 SB5+)
> member: <snip>
> cn: NUST11058_SS1_2009/0_SB5+
>
> Finally deleting that member and re-running a "sync" was successful,
> including adding the group in question.
>
> We're using Grouper V2.2.0 but I couldn't see anything that looked
> related to this issue in the changelog for 2.2.1.
>

--
/****************************

Mark Cairney
ITI UNIX Section
Information Services
University of Edinburgh

Tel: 0131 650 6565
Email:
PGP: 0x435A9621

*******************************/

The University of Edinburgh is a charitable body, registered in
Scotland, with registration number SC005336.

--

David Langenberg

Identity & Access Management

The University of Chicago