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.20018 +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=5b2a297c00090004
[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 5b2a297c00050004 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 5b2a297c00050004 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 5b2a297c00050004 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 5b2a297c00050004 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 5b2a297c00050004 in the changelog (DB rc=-30988).
If replication stops, the consumer may need to be reinitialized.
[20/Jun/2018:12:16:31.91449 +0200] - ERR -
agmt="cn=meToipa2.example.de" (ipa2:389) - clcache_load_buffer - Can't
locate CSN 5b2a297c00050004 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 5b2a297c00050004 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 5b2a297c00050004 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