[389-users] Referral errors ....

Thu May 5 14:36:07 UTC 2011

On 05/05/2011 06:41 AM, Reinhard Nappert wrote:
> This is actually what I thought, too. It logs looked fine to me as well.
>
> Guess what, a restart of the LDAP server did get rid of the issue!
>
> For sure it would be nice to figure out how the system can get into this state!
Yes, this is an odd problem.
> -Reinhard
>
> -----Original Message-----
> From: Rich Megginson [mailto:rmeggins at redhat.com]
> Sent: Wednesday, May 04, 2011 6:28 PM
> To: General discussion list for the 389 Directory server project.
> Cc: Reinhard Nappert
> Subject: Re: [389-users] Referral errors ....
>
> On 05/04/2011 03:59 PM, Reinhard Nappert wrote:
>> I actually tried even a bit more 1+2+4+65536=65543.
>>
>> I tried to add the object uid=stibbons,ou=admins,o=operator s,o=UMC.
>>
>> I tried to add it at (from access file):
>> [04/May/2011:17:40:32 -0400] conn=83 op=51 SRCH
>> base="uid=stibbons,ou=admins,o=o perators,o=UMC" scope=0
>> filter="(objectClass=*)" attrs=ALL
>> [04/May/2011:17:40:32 -0400] conn=83 op=51 RESULT err=32 tag=101
>> nentries=0 etim e=0
>> [04/May/2011:17:40:32 -0400] conn=83 op=52 ADD
>> dn="uid=stibbons,ou=admins,o=oper ators,o=UMC"
>> [04/May/2011:17:40:32 -0400] conn=83 op=52 RESULT err=1 tag=105
>> nentries=0 etime =0
>>
>> Here is what you see in errors:
>>
>> [04/May/2011:17:40:32 -0400] - mapping tree release backend : userRoot
>> [04/May/2011:17:40:32 -0400] - do_search
>> [04/May/2011:17:40:32 -0400] - SRCH
>> base="uid=stibbons,ou=admins,o=operators,o=UMC" scope=0 deref=3
>> sizelimit=0 timelimit=0 attrsonly=0 filter="(objectClass=*)" attrs=ALL
>> [04/May/2011:17:40:32 -0400] - =>   get_ldapmessage_controls
>> [04/May/2011:17:40:32 -0400] -<= get_ldapmessage_controls no controls
>> [04/May/2011:17:40:32 -0400] - =>   slapi_control_present (looking for
>> 2.16.840.1.113730.3.4.3)
>> [04/May/2011:17:40:32 -0400] -<= slapi_control_present 0 (NO CONTROLS)
>> [04/May/2011:17:40:32 -0400] - mtn_lock : lock count : 1
>> [04/May/2011:17:40:32 -0400] - mapping tree selected backend :
>> userRoot
>> [04/May/2011:17:40:32 -0400] - mtn_unlock : lock count : 0
>> [04/May/2011:17:40:32 -0400] - =>   slapi_reslimit_get_integer_limit()
>> conn=0xfd42c678, handle=2
>> [04/May/2011:17:40:32 -0400] -<= slapi_reslimit_get_integer_limit()
>> returning NO VALUE
>> [04/May/2011:17:40:32 -0400] - =>   slapi_reslimit_get_integer_limit()
>> conn=0xfd42c678, handle=1
>> [04/May/2011:17:40:32 -0400] -<= slapi_reslimit_get_integer_limit()
>> returning NO VALUE
>> [04/May/2011:17:40:32 -0400] - =>   compute_limits: sizelimit=2000,
>> timelimit=3600
>> [04/May/2011:17:40:32 -0400] - Calling plugin 'ACL preoperation' #1
>> type 403
>> [04/May/2011:17:40:32 -0400] - =>   slapi_control_present (looking for
>> 2.16.840.1.113730.3.4.12)
>> [04/May/2011:17:40:32 -0400] -<= slapi_control_present 0 (NO CONTROLS)
>> [04/May/2011:17:40:32 -0400] - =>   slapi_control_present (looking for
>> 2.16.840.1.113730.3.4.18)
>> [04/May/2011:17:40:32 -0400] -<= slapi_control_present 0 (NO CONTROLS)
>> [04/May/2011:17:40:32 -0400] - Calling plugin 'Legacy replication
>> preoperation plugin' #3 type 403
>> [04/May/2011:17:40:32 -0400] - Calling plugin 'Multimaster replication
>> preoperation plugin' #4 type 403
>> [04/May/2011:17:40:32 -0400] - =>   slapi_reslimit_get_integer_limit()
>> conn=0xfd42c678, handle=0
>> [04/May/2011:17:40:32 -0400] -<= slapi_reslimit_get_integer_limit()
>> returning NO VALUE
>> [04/May/2011:17:40:32 -0400] - =>   find_entry_internal
>> (dn=uid=stibbons,ou=admins,o=operators,o=umc) lock 0
>> [04/May/2011:17:40:32 -0400] - =>   dn2entry "uid=stibbons,ou=admins,o=operators,o=umc"
>> [04/May/2011:17:40:32 -0400] - =>   index_read( "entrydn" = "uid=stibbons,ou=admins,o=operators,o=umc" )
>> [04/May/2011:17:40:32 -0400] -    indextype: "eq" indexmask: 0x2
>> [04/May/2011:17:40:32 -0400] -<= index_read 0 candidates
>> [04/May/2011:17:40:32 -0400] -<= dn2entry 0
>> [04/May/2011:17:40:32 -0400] - =>   dn2ancestor "uid=stibbons,ou=admins,o=operators,o=umc"
>> [04/May/2011:17:40:32 -0400] - =>   dn2entry "ou=admins,o=operators,o=umc"
>> [04/May/2011:17:40:32 -0400] -<= dn2entry f0cdb0
>> [04/May/2011:17:40:32 -0400] -<= dn2ancestor f0cdb0
>> [04/May/2011:17:40:32 -0400] -<= find_entry_internal_dn not found
>> (uid=stibbons,ou=admins,o=operators,o=umc)
>> [04/May/2011:17:40:32 -0400] - =>   send_ldap_result 32:ou=admins,o=operators,o=umc:
>> [04/May/2011:17:40:32 -0400] -<= send_ldap_result
>> [04/May/2011:17:40:32 -0400] - mapping tree release backend : userRoot
>> [04/May/2011:17:40:32 -0400] - do_add
>> [04/May/2011:17:40:32 -0400] -     do_add: dn (uid=stibbons,ou=admins,o=operators,o=UMC)
>> [04/May/2011:17:40:32 -0400] - slapi_entry_add_values: using an AVL
>> tree to detect duplicate values
>> [04/May/2011:17:40:32 -0400] - =>   get_ldapmessage_controls
>> [04/May/2011:17:40:32 -0400] -<= get_ldapmessage_controls no controls
>> [04/May/2011:17:40:32 -0400] - mtn_lock : lock count : 1
>> [04/May/2011:17:40:32 -0400] - mtn_unlock : lock count : 0
>> [04/May/2011:17:40:32 -0400] - =>   send_ldap_result 1::Mapping tree
>> node for o=umc is set to return a referral, but no referral is
>> configured for it
>> [04/May/2011:17:40:32 -0400] -<= send_ldap_result
>> [04/May/2011:17:40:33 -0400] - =>   slapi_reslimit_get_integer_limit()
>> conn=0xfd42c8a8, handle=3
>> [04/May/2011:17:40:33 -0400] -<= slapi_reslimit_get_integer_limit()
>> returning NO VALUE
>> [04/May/2011:17:40:33 -0400] - =>   slapi_reslimit_get_integer_limit()
>> conn=0xfd42c790, handle=3
>> [04/May/2011:17:40:33 -0400] -<= slapi_reslimit_get_integer_limit()
>> returning NO VALUE
>> [04/May/2011:17:40:33 -0400] - =>   slapi_reslimit_get_integer_limit()
>> conn=0xfd42c678, handle=3
>>
>>
>> Let me know what you see.....
> I don't see anything unusual.  Does this problem persist after a server restart?
>> Thanks,
>> -Reinhard
>>
>> -----Original Message-----
>> From: 389-users-bounces at lists.fedoraproject.org
>> [mailto:389-users-bounces at lists.fedoraproject.org] On Behalf Of
>> Reinhard Nappert
>> Sent: Wednesday, May 04, 2011 5:32 PM
>> To: General discussion list for the 389 Directory server project.
>> Subject: Re: [389-users] Referral errors ....
>>
>> Rich,
>>
>> I was able to get one box in this situation (not sure, how though). Do you want me do change some accesslog-levels or errorlog-levels?
>>
>> Now would be a good time to gather more information
>>
>> -Reinhard
>>
>> -----Original Message-----
>> From: 389-users-bounces at lists.fedoraproject.org
>> [mailto:389-users-bounces at lists.fedoraproject.org] On Behalf Of
>> Richard Megginson
>> Sent: Wednesday, May 04, 2011 11:57 AM
>> To: General discussion list for the 389 Directory server project.
>> Subject: Re: [389-users] Referral errors ....
>>
>>> No replies so far. Does this mean nobody has seen this issue before?
>> I have not seen this.
>>
>> Any errors in the errors log?
>>
>>> -Reinhard
>>>
>>>
>>> From: 389-users-bounces at lists.fedoraproject.org
>>> [mailto:389-users-bounces at lists.fedoraproject.org] On Behalf Of
>>> Reinhard Nappert
>>> Sent: Friday, April 29, 2011 9:44 AM
>>> To: 389-users at lists.fedoraproject.org
>>> Subject: [389-users] Referral errors ....
>>>
>>>
>>>
>>> Hi,
>>>
>>> I have the following setup:
>>>
>>> I have a 2 multimaster replication setup, where both masters also
>>> have a number of shadowing agreements to other consumers. The data
>>> gets replicated to all boxes and there are no issues. When I try to
>>> perform an update on the slaves, it works on all, but one. Meaning,
>>> the server sends back err=10, with the referral to one of the masters
>>> and the client automatically follows the referrals. Unfortunately, it
>>> does not works with one box:
>>>
>>> When there is an attempt to write to the db, the server returns an
>>> error-code 1, with the following message:
>>> javax.naming.NamingException: [LDAP: error code 1 - Mapping tree node
>>> for o=base is set to return a referral, but no referral is configured
>>> for it];
>>>
>>> This can also be seen in the access file:
>>>
>>>
>>> [ 26/Apr/2011:05:35:45 -0300] conn=3418 op=13256 ADD dn="o u = test
>>> ,o= base "
>>> [26/Apr/2011:05:35:45 -0300] conn=3418 op=13256 RESULT err=1 tag=105
>>> nentries=0 etime=0
>>>
>>> When I have a look at the configuration, it looks exactly like the
>>> others: dn: cn="o=Base",cn=mapping tree,cn=config objectClass: top
>>> objectClass: extensibleObject objectClass: nsMappingTree cn: "o=Base"
>>> nsslapd-state: referral on update nsslapd-backend: userRoot
>>> modifiersName: cn=server,cn=plugins,cn=config modifyTimestamp:
>>> 20100721202730Z nsslapd-referral: ldap://master-ld01:389/o=Base
>>> nsslapd-referral : ldap://master-ld02:389/o=Base numSubordinates : 1
>>> dn: cn=replica,cn="o=Base",cn=mapping tree,cn=config
>>> nsDS5ReplicaBindDN: cn=replication,cn=config nsDS5ReplicaRoot: o=Base
>>> nsDS5Flags: 0 nsDS5ReplicaType: 2 nsds5ReplicaPurgeDelay: 43200
>>> objectClass: top objectClass: nsDS5Replica cn: replica modifiersName:
>>> cn=Multimaster Replication Plugin,cn=plugins,cn=config
>>> modifyTimestamp: 20110421052744Z nsDS5ReplicaId: 65535 nsState::
>>> //8AAAAAAADLv69NAAAAAAAAAAAAAAAALSoAAAAAAAAIAAAAAAAAAA==
>>> nsDS5ReplicaName: 59480b7e-94fb11df-9df8eeea-774385c0
>>> nsDS5ReplicaReferral: ldap://master-ld01:389/o=Base
>>> nsDS5ReplicaReferral : ldap://master-ld02:389/o=Base   I was wondering
>>> if someone has seen this kind of issue. Everything looks fine to me
>>> and I can not explain this behavior.   Right now, I can not reproduce
>>> this issue. I only see it in this one setup.   Thanks, -Reinhard
>>> --
>>> 389 users mailing list
>>> 389-users at lists.fedoraproject.org
>>> https://admin.fedoraproject.org/mailman/listinfo/389-users
>> --
>> 389 users mailing list
>> 389-users at lists.fedoraproject.org
>> https://admin.fedoraproject.org/mailman/listinfo/389-users
>> --
>> 389 users mailing list
>> 389-users at lists.fedoraproject.org
>> https://admin.fedoraproject.org/mailman/listinfo/389-users
>> --
>> 389 users mailing list
>> 389-users at lists.fedoraproject.org
>> https://admin.fedoraproject.org/mailman/listinfo/389-users