389-ds-base

#48211 Under write load on multiple backends, updates may be skipped from retroCL
Closed: wontfix Opened by tbordaz.

Closed: wontfix
Reopen Issue

Version: 389-ds 1.3.3.1 (freeipa 4.1)

The retroCL callback are POST_OP, so an update can be successful but its related record in the retroCL may be skipped (for example if repeated DB_DEADLOCK).

Reproducible testcase: a possible test case is to create several replicated backends and enabling retroCL. Then doing an intensive write load on all of them. In order to create deadlock we can add search load on 'cn=changelog'

The typical error will be:
[22/Jun/2015:08:30:53 +0000] - Operation error fetching Null DN (a-b-c-d), error -30993.
[22/Jun/2015:08:30:53 +0000] - dn2entry_ext: Failed to get id for changenumber=1195,cn=changelog from entryrdn index (-30993)
[22/Jun/2015:08:30:53 +0000] - Operation error fetching changenumber=1195,cn=changelog (null), error -30993.
[22/Jun/2015:08:30:53 +0000] DSRetroclPlugin - replog: an error occured while adding change number 1195, dn = changenumber=1195,cn=changelog: Operations error.

retroCL registers POST-OP plugins:

{{{
dn: cn=Retro Changelog Plugin,cn=plugins,cn=config
objectClass: top
objectClass: nsSlapdPlugin
objectClass: extensibleObject
cn: Retro Changelog Plugin
nsslapd-pluginPath: libretrocl-plugin
nsslapd-pluginInitfunc: retrocl_plugin_init
nsslapd-pluginType: object
nsslapd-pluginbetxn: on
nsslapd-pluginEnabled: on
nsslapd-pluginprecedence: 25
nsslapd-plugin-depends-on-type: database
nsslapd-plugin-depends-on-named: Class of Service
nsslapd-pluginId: retrocl
nsslapd-pluginVersion: 1.3.3.1
nsslapd-pluginVendor: 389 Project
nsslapd-pluginDescription: Retrocl Plugin
nsslapd-attribute: nsuniqueid:targetUniqueId
nsslapd-changelogmaxage: 2d
}}}

{{{
[22/Jun/2015:08:30:48 +0000] conn=19 fd=100 slot=100 connection from a.b.c to d.e.f
...
[22/Jun/2015:08:30:48 +0000] conn=19 op=1 BIND dn="cn=Replication Manager cloneAgreement1-xxxx-pki-tomcat,ou=csusers,cn=config" method=128 version=3
[22/Jun/2015:08:30:48 +0000] conn=19 op=1 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=replication manager cloneagreement1-xxxx-pki-tomcat,ou=csusers,cn=config"
...
}}}

<< Many replicated updates on o=ipaca >>

{{{
[22/Jun/2015:08:30:49 +0000] conn=19 op=9 MOD dn="cn=abc,ou=def,ou=ca,o=ipaca"
[22/Jun/2015:08:30:49 +0000] conn=19 op=9 RESULT err=0 tag=103 nentries=0 etime=0 csn=557b14bb000000600000
...
[22/Jun/2015:08:30:52 +0000] conn=19 op=465 MOD dn="cn=abc,ou=def,ou=ca,o=ipaca"
[22/Jun/2015:08:30:52 +0000] conn=19 op=465 RESULT err=0 tag=103 nentries=0 etime=0 csn=557fdc2b000000600000

}}}

<< While the updates on conn=19 continue, a replication session is opened conn=21 
   and updates from conn=19 and conn=21 are processed >>

{{{
[22/Jun/2015:08:30:52 +0000] conn=21 fd=126 slot=126 connection from aa.bb.cc to d.e.f
[22/Jun/2015:08:30:52 +0000] conn=21 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[22/Jun/2015:08:30:52 +0000] conn=21 op=2 RESULT err=0 tag=97 nentries=0 etime=0 dn="krbprincipalname=ldap/xxx@mydomain..net,cn=services,cn=accounts,SUFFIX"
....
[22/Jun/2015:08:30:52 +0000] conn=21 op=10 ADD dn="ipaUniqueID=a-b-c-d-e,cn=hbac,SUFFIX"
[22/Jun/2015:08:30:52 +0000] conn=19 op=531 RESULT err=0 tag=103 nentries=0 etime=0 csn=5580b623000000600000
[22/Jun/2015:08:30:52 +0000] conn=19 op=532 MOD dn="cn=xxxx,ou=yyyy,ou=ca,o=ipaca"
[22/Jun/2015:08:30:52 +0000] conn=21 op=10 RESULT err=0 tag=105 nentries=0 etime=0 csn=5579a3bf000100040000
[22/Jun/2015:08:30:52 +0000] conn=21 op=11 MOD dn="ipaUniqueID=a-b-c-d-e,cn=hbac,SUFFIX"
[22/Jun/2015:08:30:52 +0000] conn=19 op=532 RESULT err=0 tag=103 nentries=0 etime=0 csn=5580b9a7000000600000
[22/Jun/2015:08:30:52 +0000] conn=19 op=533 MOD dn="cn=xxx,ou=yyyy,ou=ca,o=ipaca"
[22/Jun/2015:08:30:52 +0000] conn=21 op=11 RESULT err=0 tag=103 nentries=0 etime=0 csn=5579a423000100040000
[22/Jun/2015:08:30:52 +0000] conn=21 op=12 ADD dn="uid=abcd,cn=users,cn=accounts,SUFFIX"
[22/Jun/2015:08:30:52 +0000] conn=19 op=533 RESULT err=0 tag=103 nentries=0 etime=0 csn=5580bd2b000000600000
}}}

<soon after we see periodic DEADLOCK on the retroCL>

{{{
[22/Jun/2015:08:30:53 +0000] - Operation error fetching Null DN (a-b-c-d), error -30993.
[22/Jun/2015:08:30:53 +0000] - dn2entry_ext: Failed to get id for changenumber=1195,cn=changelog from entryrdn index (-30993)
[22/Jun/2015:08:30:53 +0000] - Operation error fetching changenumber=1195,cn=changelog (null), error -30993.
[22/Jun/2015:08:30:53 +0000] DSRetroclPlugin - replog: an error occured while adding change number 1195, dn = changenumber=1195,cn=changelog: Operations error.
[22/Jun/2015:08:30:53 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:53 +0000] - ldbm_back_seq deadlock retry BAD 1601, err=0 BDB0062 Successful return: 0
[22/Jun/2015:08:30:54 +0000] - Operation error fetching Null DN (a-b-c-d), error -30993.
[22/Jun/2015:08:30:54 +0000] - dn2entry_ext: Failed to get id for changenumber=1202,cn=changelog from entryrdn index (-30993)
[22/Jun/2015:08:30:54 +0000] - Operation error fetching changenumber=1202,cn=changelog (null), error -30993.
[22/Jun/2015:08:30:54 +0000] DSRetroclPlugin - replog: an error occured while adding change number 1202, dn = changenumber=1202,cn=changelog: Operations error.
[22/Jun/2015:08:30:54 +0000] retrocl-plugin - retrocl_postob: operation failure [1]

}}}

but the config says:

nsslapd-pluginbetxn: on

and a quick lookup shows that in this case SLAPI_PLUGIN_BE_TXN_POST_ is used

You are right Ludwig this was a betxn_postop and in fact DB_DEADLOCK failures trigger related operation failure:

{{{
grep '2015:08:3' access.20150622-082913 | grep RESULT| grep -v err=0
[22/Jun/2015:08:30:53 +0000] conn=19 op=539 RESULT err=1 tag=103 nentries=0 etime=0 csn=5580cebf000000600000
[22/Jun/2015:08:30:54 +0000] conn=19 op=543 RESULT err=1 tag=103 nentries=0 etime=0 csn=5580dcd0000000600000
[22/Jun/2015:08:30:55 +0000] conn=19 op=549 RESULT err=1 tag=103 nentries=0 etime=1 csn=5580f1e8000000600000
[22/Jun/2015:08:30:55 +0000] conn=19 op=551 RESULT err=1 tag=103 nentries=0 etime=0 csn=5580f8f0000000600000
[22/Jun/2015:08:30:56 +0000] conn=19 op=555 RESULT err=1 tag=103 nentries=0 etime=1 csn=5581037b000000600000
[22/Jun/2015:08:30:56 +0000] conn=19 op=561 RESULT err=1 tag=103 nentries=0 etime=0 csn=55811894000000600000
[22/Jun/2015:08:30:57 +0000] conn=19 op=564 RESULT err=1 tag=103 nentries=0 etime=0 csn=55812320000000600000
[22/Jun/2015:08:30:58 +0000] conn=19 op=571 RESULT err=1 tag=103 nentries=0 etime=1 csn=55813837000000600000
[22/Jun/2015:08:30:58 +0000] conn=19 op=575 RESULT err=1 tag=103 nentries=0 etime=0 csn=55814647000000600000
[22/Jun/2015:08:30:59 +0000] conn=19 op=582 RESULT err=1 tag=103 nentries=0 etime=0 csn=55815ee4000000600000
[22/Jun/2015:08:30:59 +0000] conn=19 op=584 RESULT err=1 tag=103 nentries=0 etime=0 csn=558165ec000000600000
[22/Jun/2015:08:31:00 +0000] conn=19 op=586 RESULT err=1 tag=103 nentries=0 etime=1 csn=55816cf4000000600000

grep 'retrocl_postob: operation failure' errors
[22/Jun/2015:08:30:53 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:54 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:55 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:55 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:56 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:56 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:57 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:58 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:58 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:59 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:30:59 +0000] retrocl-plugin - retrocl_postob: operation failure [1]
[22/Jun/2015:08:31:00 +0000] retrocl-plugin - retrocl_postob: operation failure [1]

}}}

So this ticket is invalid as all successful op are correctly recorded in the retroCL. I am closing it.

Note: the logs also show that we hit https://fedorahosted.org/389/ticket/47788 because failing updates (for example
5580cebf000000600000) are not later replayed by the supplier

{{{
[22/Jun/2015:08:30:53 +0000] conn=19 op=539 MOD dn="cn=a,ou=b,ou=ca,o=ipaca"
[22/Jun/2015:08:30:53 +0000] conn=19 op=539 RESULT err=1 tag=103 nentries=0 etime=0 csn=5580cebf000000600000
[22/Jun/2015:08:30:53 +0000] conn=19 op=540 MOD dn="cn=a,ou=b,ou=ca,o=ipaca"
[22/Jun/2015:08:30:53 +0000] conn=21 op=17 RESULT err=0 tag=103 nentries=0 etime=0 csn=5579a456000600040000
[22/Jun/2015:08:30:53 +0000] conn=21 op=18 MOD dn="uid=xxx,cn=users,cn=accounts,SUFFIX"
[22/Jun/2015:08:30:53 +0000] conn=19 op=540 RESULT err=0 tag=103 nentries=0 etime=0 csn=5580d243000000600000
[22/Jun/2015:08:30:53 +0000] conn=19 op=541 MOD dn="cn=a,ou=b,ou=ca,o=ipaca"
[22/Jun/2015:08:30:53 +0000] conn=21 op=18 RESULT err=0 tag=103 nentries=0 etime=0 csn=5579a4ab000100040000
[22/Jun/2015:08:30:53 +0000] conn=21 op=19 MOD dn="cn=yyy,cn=groups,cn=accounts,SUFFIX"
[22/Jun/2015:08:30:54 +0000] conn=19 op=541 RESULT err=0 tag=103 nentries=0 etime=1 csn=5580d5c7000000600000
[22/Jun/2015:08:30:54 +0000] conn=19 op=542 MOD dn="cn=a,ou=b,ou=ca,o=ipaca"
[22/Jun/2015:08:30:54 +0000] conn=21 op=19 RESULT err=0 tag=103 nentries=0 etime=1 csn=5579a4ab000200040000
[22/Jun/2015:08:30:54 +0000] conn=21 op=20 MOD dn="ipaUniqueID=a-b-c-d-e-f,cn=hbac,SUFFIX
[22/Jun/2015:08:30:54 +0000] conn=19 op=542 RESULT err=0 tag=103 nentries=0 etime=0 csn=5580d94c000000600000
...
}}}

Metadata Update from @tbordaz:
- Issue set to the milestone: N/A

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/1542

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: Invalid)
Metadata
None
None
None
None
Normal
IPA
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.