replication agreement does an unexpected pause at the beginning of a replication session

[tbordaz]

Issue Description
If multiple masters are competing to update a consumer, a master "winning" the access does an unexpected pause (2s) just after having sent the first update

[05/Oct/2020:17:47:05.972974138` +0200] conn=1 op=7 MOD dn="uid=demo_user,ou=people,dc=example,dc=com"
[05/Oct/2020:17:47:06.010024157 +0200] conn=1 op=7 RESULT err=0 tag=103 nentries=0 wtime=0.000777897 optime=0.037101040 etime=0.037874361 csn=5f7b3b46000100010000
[05/Oct/2020:17:47:06.011969067 +0200] conn=1 op=8 MOD dn="uid=demo_user,ou=people,dc=example,dc=com"
[05/Oct/2020:17:47:06.033348268 +0200] conn=1 op=8 RESULT err=0 tag=103 nentries=0 wtime=0.000089719 optime=0.021381232 etime=0.021466087 csn=5f7b3b46000200010000
[05/Oct/2020:17:47:06.492539290 +0200] conn=2 op=4 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[05/Oct/2020:17:47:06.508979948 +0200] conn=2 op=4 RESULT err=0 tag=120 nentries=0 wtime=0.000598178 optime=0.016505084 etime=0.017088737
[05/Oct/2020:17:47:08.192830926 +0200] conn=1 op=9 EXT oid="2.16.840.1.113730.3.5.5" name="replication-multimaster-extop"
[05/Oct/2020:17:47:08.204349617 +0200] conn=1 op=9 RESULT err=0 tag=120 nentries=0 wtime=0.000544121 optime=0.011581077 etime=0.012079180
[05/Oct/2020:17:47:09.675479297 +0200] conn=2 op=5 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[05/Oct/2020:17:47:09.693263125 +0200] conn=2 op=5 RESULT err=0 tag=120 nentries=0 wtime=0.000604568 optime=0.017868183 etime=0.018463724
[05/Oct/2020:17:47:09.710346408 +0200] conn=2 op=6 SRCH base="cn=replica,cn=dc\3Dexample\2Cdc\3Dcom,cn=mapping tree,cn=config" scope=0 filter="(objectClass=*)" attrs="nsDS5ReplicaId"
[05/Oct/2020:17:47:09.712016019 +0200] conn=2 op=6 RESULT err=0 tag=101 nentries=1 wtime=0.014678098 optime=0.001698312 etime=0.016370676
[05/Oct/2020:17:47:09.743523292 +0200] conn=2 op=7 MOD dn="uid=demo_user,ou=people,dc=example,dc=com"
[05/Oct/2020:17:47:09.766507787 +0200] conn=2 op=7 RESULT err=0 tag=103 nentries=0 wtime=0.030303409 optime=0.022999652 etime=0.053292525 csn=5f7b3bc3000000020000
[05/Oct/2020:17:47:11.400631377 +0200] conn=1 op=10 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[05/Oct/2020:17:47:11.421553625 +0200] conn=1 op=10 RESULT err=0 tag=120 nentries=0 wtime=0.000561572 optime=0.020985741 etime=0.021533600
[05/Oct/2020:17:47:11.748665124 +0200] conn=2 op=9 MOD dn="uid=demo_user,ou=people,dc=example,dc=com"
[05/Oct/2020:17:47:11.769272198 +0200] conn=2 op=9 RESULT err=0 tag=103 nentries=0 wtime=0.000172459 optime=0.020624271 etime=0.020789560 csn=5f7b3bc3000100020000

Here there is a pause of 2sec sharp between conn=2 op=7 and op=9. Note that the op=8 is missing.

Package Version and Platform:

• Platform: all
• Package and version: since flow control (1.2.x)

Steps to Reproduce
Should provide a testcase

Expected results
The replication session should not pause

[Firstyear]

Could the missing op id be from an internal search?

[tbordaz]

Could the missing op id be from an internal search?
Those are replicated updates with op/msgid provided by the client application (replication agreement). I do not know how this op_id got skipped but it is not related to internal operation.

[Firstyear]

I thought these op id's were internally allocated as part of the operation? Or am I missing something?