https://bugs.openldap.org/show_bug.cgi?id=9538
Issue ID: 9538 Summary: Accesslog entryCSN ordering is not always monotonous Product: OpenLDAP Version: unspecified Hardware: All OS: All Status: UNCONFIRMED Severity: normal Priority: --- Component: overlays Assignee: bugs@openldap.org Reporter: ondra@mistotebe.net Target Milestone: ---
For delta-sync replication, we rely on CSN order being preserved at all times.
When logops includes anything more than "writes", we don't use li_op_rmutex to maintain serialisation. A concurrent write and another operation (like bind) can have the write have its csn assigned before the bind. But before the write finishes on the main DB and is logged, the bind has already hit accesslog.
This entry out of order doesn't match the usual filter, so non-persist sessions will not notice, however running persist sessions could get a new cookie sent, depending on how things are ordered when they hit syncprov.
A sample: ---- 8< ---- Apr 26 19:56:04 localhost slapd[43930]: conn=1003 op=41 ADD dn="uid=dm01-R1H2-41660,ou=People,dc=example,dc=com" Apr 26 19:56:04 localhost slapd[43930]: conn=1003 op=41 syncprov_matchops: recording uuid for dn=reqStart=20210426195604.000350Z,cn=accesslog on opc=0x7d3d2800dc50 Apr 26 19:56:04 localhost slapd[43930]: slap_get_csn: conn=1003 op=42 generated new csn=20210426195604.556053Z#000000#002#000000 manage=1 Apr 26 19:56:04 localhost slapd[43930]: slap_queue_csn: queueing 0x7d3d38148f60 20210426195604.556053Z#000000#002#000000 Apr 26 19:56:04 localhost slapd[43930]: conn=1005 op=1 BIND dn="dc=example,dc=com" method=128 Apr 26 19:56:04 localhost slapd[43930]: conn=1005 op=1 BIND dn="dc=example,dc=com" mech=SIMPLE bind_ssf=0 ssf=256 Apr 26 19:56:04 localhost slapd[43930]: conn=1003 op=41 RESULT tag=105 err=0 qtime=0.005874 etime=0.015182 text= Apr 26 19:56:04 localhost slapd[43930]: slap_get_csn: conn=1005 op=1 generated new csn=20210426195604.558683Z#000000#002#000000 manage=1 Apr 26 19:56:04 localhost slapd[43930]: slap_queue_csn: queueing 0x561f09113f80 20210426195604.558683Z#000000#002#000000 Apr 26 19:56:04 localhost slapd[43930]: conn=1005 op=1 syncprov_matchops: recording uuid for dn=reqStart=20210426195604.000364Z,cn=accesslog on opc=0x561f0900fcf0 Apr 26 19:56:04 localhost slapd[43930]: conn=1002 op=2 syncprov_qresp: set up a new syncres mode=4 csn=20210426195604.558683Z#000000#002#000000 Apr 26 19:56:04 localhost slapd[43930]: conn=1001 op=2 syncprov_qresp: set up a new syncres mode=4 csn=20210426195604.558683Z#000000#002#000000 Apr 26 19:56:04 localhost slapd[43930]: conn=1000 op=2 syncprov_qresp: set up a new syncres mode=4 csn=20210426195604.558683Z#000000#002#000000 Apr 26 19:56:04 localhost slapd[43930]: slap_graduate_commit_csn: removing 0x561f09113f80 20210426195604.558683Z#000000#002#000000 Apr 26 19:56:04 localhost slapd[43930]: conn=1005 op=1 RESULT tag=97 err=0 qtime=0.000020 etime=0.004297 text= Apr 26 19:56:04 localhost slapd[43930]: slap_queue_csn: queueing 0x7d3d38148250 20210426195604.556053Z#000000#002#000000 Apr 26 19:56:04 localhost slapd[43930]: slap_graduate_commit_csn: removing 0x7d3d38148250 20210426195604.556053Z#000000#002#000000 Apr 26 19:56:04 localhost slapd[43930]: slap_graduate_commit_csn: removing 0x7d3d38148f60 20210426195604.556053Z#000000#002#000000 ---- 8< ----
Example entries in the order slapcat sees them: ---- 8< ---- dn: reqStart=20210426195604.000364Z,cn=accesslog objectClass: auditBind reqStart: 20210426195604.000364Z reqEnd: 20210426195604.000365Z reqType: bind entryCSN: 20210426195604.558683Z#000000#002#000000
dn: reqStart=20210426195604.000351Z,cn=accesslog objectClass: auditAdd reqStart: 20210426195604.000351Z reqEnd: 20210426195604.000366Z reqType: add entryCSN: 20210426195604.556053Z#000000#002#000000 ---- 8< ----