Hi Harald,

Sorry to be back late.

The MODRDN failed

[20/Jun/2018:12:16:26.438676865 +0200] conn=2464250 fd=417 slot=417 connection from 172.19.96.3 to 172.19.96.3
[20/Jun/2018:12:16:26.444420018 +0200] conn=2464250 op=0 BIND dn="" method=sasl version=3 mech=GSS-SPNEGO
[20/Jun/2018:12:16:26.449637703 +0200] conn=2464250 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=admin,cn=users,cn=accounts,dc=example,dc=de"
[20/Jun/2018:12:16:26.451161509 +0200] conn=2464250 op=1 SRCH base="cn=ipaconfig,cn=etc,dc=example,dc=de" scope=0 filter="(objectClass=*)" attrs=ALL
[20/Jun/2018:12:16:26.451753066 +0200] conn=2464250 op=1 RESULT err=0 tag=101 nentries=1 etime=0
[20/Jun/2018:12:16:26.452751904 +0200] conn=2464250 op=2 SRCH base="uid=bobs,cn=users,cn=accounts,dc=example,dc=de" scope=0 filter="(objectClass=*)" attrs="distinguishedName"
[20/Jun/2018:12:16:26.452983629 +0200] conn=2464250 op=2 RESULT err=0 tag=101 nentries=1 etime=0
[20/Jun/2018:12:16:26.453499505 +0200] conn=2464250 op=3 SRCH base="uid=bobs,cn=users,cn=accounts,dc=example,dc=de" scope=0 filter="(objectClass=*)" attrs="krbPrincipalName krbCanonicalName"
[20/Jun/2018:12:16:26.453742775 +0200] conn=2464250 op=3 RESULT err=0 tag=101 nentries=1 etime=0
[20/Jun/2018:12:16:26.456729268 +0200] conn=2464250 op=4 MODRDN dn="uid=bobs,cn=users,cn=accounts,dc=example,dc=de" newrdn="uid=bobk" newsuperior="(null)"
[20/Jun/2018:12:16:31.890761679 +0200] conn=2464250 op=4 RESULT err=1 tag=109 nentries=0 etime=5 csn=5b2a297c000900040000
[20/Jun/2018:12:16:31.892091985 +0200] conn=2464250 op=5 UNBIND
[20/Jun/2018:12:16:31.892112732 +0200] conn=2464250 op=5 fd=417 closed - U1


While quite "intensive" read activity were around changelog

[20/Jun/2018:12:16:31.885644563 +0200] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE                                                                                                           
[20/Jun/2018:12:16:31.890841336 +0200] - ERR - agmt="cn=meToipabak.ac.example.de" (ipabak:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized.
[20/Jun/2018:12:16:31.895854088 +0200] - ERR - agmt="cn=meToipa2.example.de" (ipa2:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized.
[20/Jun/2018:12:16:31.899133027 +0200] - ERR - agmt="cn=meToipa3.example.de" (ipa3:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized.
[20/Jun/2018:12:16:31.910014989 +0200] - ERR - agmt="cn=meToipa4.example.de" (ipa4:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized.
[20/Jun/2018:12:16:31.918932212 +0200] - ERR - agmt="cn=meToipabak.ac.example.de" (ipabak:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized.
[20/Jun/2018:12:16:31.922221449 +0200] - ERR - agmt="cn=meToipa2.example.de" (ipa2:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized.
[20/Jun/2018:12:16:31.934273432 +0200] - ERR - agmt="cn=meToipa3.example.de" (ipa3:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized.
[20/Jun/2018:12:16:31.942328998 +0200] - ERR - agmt="cn=meToipa4.example.de" (ipa4:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized.

There is not enough detail to confirm but my feeling is that the MODRDN (write) failed to update the changelog because of many replication agreements (read) competing with it. It retried several times but without success so the full txn was aborted.

I think this can be mitigate with appropriate deadlock policy (nsslapd-db-deadlock-policy: 6 for example).

Now it broke the index and that is really unexpected (even after a db_deadlock). It worth to try to reproduce.

thanks for your help

best regards
thierry

On 06/20/2018 08:14 PM, Harald Dunkel via FreeIPA-users wrote:
Hi Thierry,

On 6/20/18 6:02 PM, thierry bordaz via FreeIPA-users wrote:
Hi Harald,

I wonder if error on ipa1 can not be part of the problem

[20/Jun/2018:12:16:31.885644563 +0200] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE

The MODRDN failed, that would explain why 'uid=bobs' remained in the index (and findable via search)
But this does not explain how RDN and entry itself was changed.

Could you provide the access logs (ipa1) around that time ?

Sure, see attachment. Hope this helps.


Regards
Harri


_______________________________________________
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org
To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org
Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives: https://lists.fedoraproject.org/archives/list/freeipa-users@lists.fedorahosted.org/message/YLZOPMZKWXV5CYJCI4C3XJDUAHHFRHFI/