[OPENDJ-3507] After upgrading a 2.6.2 server to 3.5.1 server is spinning at 93% CPU Created: 17/Nov/16  Updated: 08/Nov/19  Resolved: 03/Jul/17

Status: Done
Project: OpenDJ
Component/s: replication
Affects Version/s: 4.0.0, 3.5.1, 3.5.0, 3.0.0
Fix Version/s: 5.5.0

Type: Bug Priority: Major
Reporter: patrick diligent Assignee: Fabio Pistolesi
Resolution: Fixed Votes: 0
Labels: Verified, release-notes

Attachments: Zip Archive add-matching-rule.zip     File backendstat-bad.out     File backendstat-bad2.out    
Issue Links:
Backport
is backported by OPENDJ-4137 Backport OPENDJ-3507: After upgrading... Done
is backported by OPENDJ-4146 Backport OPENDJ-3507: After upgrading... Done
is backported by OPENDJ-4238 Backport OPENDJ-3507: After upgrading... Done
QA Assignee: Christophe Sovant
Support Ticket IDs:
Backports: OPENDJ-4137 (4.0.1) OPENDJ-4146 (3.5.3) OPENDJ-4238 (3.0.1)

 Description   

This is issue has been observed in a customer environment, after upgrading 6 replicated servers to 3.5.1. The server has 2M entries, the backend occupancy around 23G. After upgrade, one of the server is spinning(?) at 93%, and do not seem to end. Other servers in the topology are impacted, causing long delays in starting, and timeouts with replication connections.The sequence they used to upgrade is not clear, but there is some evidence that it was performed live, taking one instance out at a time. The server that is spinning is an OpenAM external idStore. The jstack reveals that there is a single thread at high CPU :

"Replica DS(18981) missing change publisher for domain "dc=example,dc=com""  prio=10 tid=0x00007f0aa8ed8800 nid=0x533b runnable [0x00007f0a8f5f3000]
  java.lang.Thread.State: RUNNABLE
        at  org.forgerock.opendj.ldap.schema.ObjectIdentifierEqualityMatchingRuleImpl$2.<init>(ObjectIdentifierEqualityMatchingRuleImpl.java:157)

It seems the issue can be reproduced following the steps described below. I currently have an instance spinning at hight CPU, likely to be the same issue observed by the customer. Unfortunately, having tested on OSX, I am not able to gather the thread statistics. A jstack fails to connect to the instance (therefore it has to be forced), neither attaching a debugger succeeds. Though the thread name is not displayed, the stack is probably related :

Thread 5891: (state = BLOCKED)
 - com.sleepycat.je.tree.INKeyRep$MaxKeySize.get(int) @bci=31, line=259 (Compiled frame)
 - com.sleepycat.je.tree.INKeyRep$MaxKeySize.get(int) @bci=2, line=201 (Compiled frame)
 - com.sleepycat.je.tree.IN.getKey(int) @bci=18, line=783 (Compiled frame)
 - com.sleepycat.je.dbi.CursorImpl.fetchCurrent(com.sleepycat.je.DatabaseEntry, com.sleepycat.je.DatabaseEntry, com.sleepycat.je.txn.LockType) @bci=299, line=2295 (Compiled frame)
 - com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(com.sleepycat.je.DatabaseEntry, com.sleepycat.je.DatabaseEntry, com.sleepycat.je.txn.LockType) @bci=58, line=1480 (Compiled frame)
 - com.sleepycat.je.dbi.CursorImpl.getNext(com.sleepycat.je.DatabaseEntry, com.sleepycat.je.DatabaseEntry, com.sleepycat.je.txn.LockType, boolean, boolean, com.sleepycat.je.dbi.RangeConstraint) @bci=199, line=1607 (Compiled frame)
 - com.sleepycat.je.Cursor.retrieveNextAllowPhantoms(com.sleepycat.je.DatabaseEntry, com.sleepycat.je.DatabaseEntry, com.sleepycat.je.txn.LockType, com.sleepycat.je.dbi.GetMode, com.sleepycat.je.dbi.RangeConstraint) @bci=66, line=3080 (Compiled frame)
 - com.sleepycat.je.Cursor.retrieveNextNoDups(com.sleepycat.je.DatabaseEntry, com.sleepycat.je.DatabaseEntry, com.sleepycat.je.LockMode, com.sleepycat.je.dbi.GetMode) @bci=87, line=2957 (Compiled frame)
 - com.sleepycat.je.Cursor.retrieveNext(com.sleepycat.je.DatabaseEntry, com.sleepycat.je.DatabaseEntry, com.sleepycat.je.LockMode, com.sleepycat.je.dbi.GetMode) @bci=26, line=2931 (Compiled frame)
 - com.sleepycat.je.Cursor.getNext(com.sleepycat.je.DatabaseEntry, com.sleepycat.je.DatabaseEntry, com.sleepycat.je.LockMode) @bci=62, line=1148 (Compiled frame)
 - org.opends.server.backends.jeb.JEStorage$CursorImpl.next() @bci=18, line=155 (Compiled frame)
 - org.opends.server.backends.pluggable.EntryContainer.searchNotIndexed(org.opends.server.backends.pluggable.spi.ReadableTransaction, org.opends.server.core.SearchOperation, org.opends.server.controls.PagedResultsControl) @bci=590, line=1193 (Compiled frame)
 - org.opends.server.backends.pluggable.EntryContainer.access$1700(org.opends.server.backends.pluggable.EntryContainer, org.opends.server.backends.pluggable.spi.ReadableTransaction, org.opends.server.core.SearchOperation, org.opends.server.controls.PagedResultsControl) @bci=4, line=112 (Interpreted frame)
 - org.opends.server.backends.pluggable.EntryContainer$3.run(org.opends.server.backends.pluggable.spi.ReadableTransaction) @bci=833, line=881 (Interpreted frame)
 - org.opends.server.backends.pluggable.EntryContainer$3.run(org.opends.server.backends.pluggable.spi.ReadableTransaction) @bci=2, line=667 (Interpreted frame)
 - org.opends.server.backends.jeb.JEStorage.read(org.opends.server.backends.pluggable.spi.ReadOperation) @bci=6, line=762 (Interpreted frame)
 - org.opends.server.backends.pluggable.TracedStorage.read(org.opends.server.backends.pluggable.spi.ReadOperation) @bci=26, line=496 (Interpreted frame)
 - org.opends.server.backends.pluggable.EntryContainer.search(org.opends.server.core.SearchOperation) @bci=13, line=666 (Interpreted frame)
 - org.opends.server.backends.pluggable.BackendImpl.search(org.opends.server.core.SearchOperation) @bci=23, line=565 (Interpreted frame)
 - org.opends.server.workflowelement.localbackend.LocalBackendSearchOperation.processSearch(java.util.concurrent.atomic.AtomicBoolean) @bci=248, line=224 (Interpreted frame)
 - org.opends.server.workflowelement.localbackend.LocalBackendSearchOperation.processLocalSearch(org.opends.server.workflowelement.localbackend.LocalBackendWorkflowElement) @bci=32, line=101 (Interpreted frame)
 - org.opends.server.workflowelement.localbackend.LocalBackendWorkflowElement.execute(org.opends.server.types.Operation) @bci=90, line=732 (Interpreted frame)
 - org.opends.server.workflowelement.localbackend.LocalBackendWorkflowElement.executeOnNonRootDSE(org.opends.server.types.Operation, org.opends.server.workflowelement.localbackend.LocalBackendWorkflowElement) @bci=2, line=1051 (Interpreted frame)
 - org.opends.server.workflowelement.localbackend.LocalBackendWorkflowElement.execute(org.opends.server.types.Operation, org.forgerock.opendj.ldap.DN) @bci=45, line=894 (Interpreted frame)
 - org.opends.server.core.SearchOperationBasis.run() @bci=293, line=1007 (Interpreted frame)
 - org.opends.server.protocols.internal.InternalClientConnection.processSearch(org.opends.server.protocols.internal.SearchRequest, org.opends.server.protocols.internal.InternalSearchListener) @bci=18, line=1686 (Interpreted frame)
 - org.opends.server.replication.plugin.LDAPReplicationDomain.searchForChangedEntries(org.forgerock.opendj.ldap.DN, org.opends.server.replication.common.CSN, org.opends.server.replication.common.CSN, org.opends.server.protocols.internal.InternalSearchListener) @bci=144, line=4182 (Interpreted frame)
 - org.opends.server.replication.plugin.LDAPReplicationDomain.searchForChangedEntries(org.forgerock.opendj.ldap.DN, org.opends.server.replication.common.CSN, org.opends.server.protocols.internal.InternalSearchListener) @bci=4, line=4203 (Interpreted frame)
 - org.opends.server.replication.plugin.PersistentServerState.checkAndUpdateServerState() @bci=38, line=328 (Interpreted frame)
 - org.opends.server.replication.plugin.PersistentServerState.loadState() @bci=24, line=145 (Interpreted frame)
 - org.opends.server.replication.plugin.PersistentServerState.<init>(org.forgerock.opendj.ldap.DN, int, org.opends.server.replication.common.ServerState) @bci=20, line=79 (Interpreted frame)
 - org.opends.server.replication.plugin.LDAPReplicationDomain.<init>(org.forgerock.opendj.server.config.server.ReplicationDomainCfg, java.util.concurrent.BlockingQueue, org.opends.server.replication.service.DSRSShutdownSync) @bci=251, line=577 (Interpreted frame)
 - org.opends.server.replication.plugin.MultimasterReplication.createNewDomain(org.forgerock.opendj.server.config.server.ReplicationDomainCfg) @bci=11, line=192 (Interpreted frame)
 - org.opends.server.replication.plugin.MultimasterReplication.initializeSynchronizationProvider(org.forgerock.opendj.server.config.server.ReplicationSynchronizationProviderCfg) @bci=101, line=274 (Interpreted frame)
 - org.opends.server.replication.plugin.MultimasterReplication.initializeSynchronizationProvider(org.forgerock.opendj.server.config.server.SynchronizationProviderCfg) @bci=5, line=85 (Interpreted frame)
 - org.opends.server.core.SynchronizationProviderConfigManager.getSynchronizationProvider(org.forgerock.opendj.server.config.server.SynchronizationProviderCfg) @bci=115, line=317 (Interpreted frame)
 - org.opends.server.core.SynchronizationProviderConfigManager.initializeSynchronizationProviders() @bci=80, line=111 (Interpreted frame)
 - org.opends.server.core.DirectoryServer.startServer() @bci=641, line=1593 (Interpreted frame)
 - org.opends.server.core.DirectoryServer.main(java.lang.String[]) @bci=1502, line=6277 (Interpreted frame)

The data in the changelog does not evolve at all. Letting the server indefinitely running ends up in a crash.

Note that in order for it to start, I had to configure a larger heap (going from 1G to 4G after upgrade), otherwise it ends up in Out Of Memory straight away.

Below, the console traces when starting the server :

[17/Nov/2016:09:19:32 +1100] category=com.forgerock.opendj.ldap.config.config severity=NOTICE msgID=571 msg=Loaded extension from file '/Users/patrickdiligent/opendj/server/2.6.2/2M/dj1/lib/extensions/snmp-mib2605.jar' (build 3.5.1, revision 23b322a7502f029b6d3725212c162de36f038122)
[17/Nov/2016:09:19:32 +1100] category=CORE severity=NOTICE msgID=134 msg=OpenDJ Server 3.5.1 (build 20161018085632, revision number 23b322a7502f029b6d3725212c162de36f038122) starting up
[17/Nov/2016:09:19:33 +1100] category=JVM severity=NOTICE msgID=21 msg=Installation Directory:  /Users/patrickdiligent/opendj/server/2.6.2/2M/dj1
[17/Nov/2016:09:19:33 +1100] category=JVM severity=NOTICE msgID=23 msg=Instance Directory:      /Users/patrickdiligent/opendj/server/2.6.2/2M/dj1
[17/Nov/2016:09:19:33 +1100] category=JVM severity=NOTICE msgID=17 msg=JVM Information: 1.7.0_75-b13 by Oracle Corporation, 64-bit architecture, 4116709376 bytes heap size
[17/Nov/2016:09:19:33 +1100] category=JVM severity=NOTICE msgID=18 msg=JVM Host: 192.168.0.11, running Mac OS X 10.11.6 x86_64, 17179869184 bytes physical memory size, number of processors available 8
[17/Nov/2016:09:19:33 +1100] category=JVM severity=NOTICE msgID=19 msg=JVM Arguments: "-Djava.awt.headless=true", "-Xms4096m", "-Xmx4096m", "-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=8000", "-Dorg.opends.server.scriptName=start-ds"
[17/Nov/2016:09:19:35 +1100] category=BACKEND severity=NOTICE msgID=513 msg=The database backend userRoot containing 2000002 entries has started
[17/Nov/2016:09:19:35 +1100] category=EXTENSIONS severity=NOTICE msgID=221 msg=DIGEST-MD5 SASL mechanism using a server fully qualified domain name of: patricks-MacBook-Pro.local
[17/Nov/2016:09:19:35 +1100] category=SYNC severity=NOTICE msgID=204 msg=Replication server RS(10077) started listening for new connections on address 0.0.0.0 port 8989
[17/Nov/2016:09:19:40 +1100] category=SYNC severity=WARNING msgID=106 msg=Timed out waiting for monitor data for the domain "dc=example,dc=com" from replication server RS(9565)
[17/Nov/2016:09:20:40 +1100] category=SYNC severity=WARNING msgID=106 msg=Timed out waiting for monitor data for the domain "cn=admin data" from replication server RS(9565)
[17/Nov/2016:09:20:40 +1100] category=SYNC severity=WARNING msgID=106 msg=Timed out waiting for monitor data for the domain "cn=admin data" from replication server RS(16226)
[17/Nov/2016:09:20:40 +1100] category=SYNC severity=WARNING msgID=106 msg=Timed out waiting for monitor data for the domain "cn=schema" from replication server RS(9565)
[17/Nov/2016:09:20:40 +1100] category=SYNC severity=WARNING msgID=106 msg=Timed out waiting for monitor data for the domain "cn=schema" from replication server RS(16226)
[17/Nov/2016:09:20:45 +1100] category=SYNC severity=WARNING msgID=106 msg=Timed out waiting for monitor data for the domain "dc=example,dc=com" from replication server RS(16226)
The timeout of '200' seconds to start the server has been reached.  You can
use the argument '--timeout' to increase this timeout

In order to reproduce :

  • Install 3 replicated servers, 2.6.2 with 2M entries.
  • Cause the backends to grow with historical data. For this I used JMeter with one thread randomly updating 2M users with sn, then givenName with a large value (1k+). I let it grow until userRoot reached 14G.Using one JMeter instance per server, had to let it run overnight.
  • Stop the JMeter test plan, and use modified test plan to moderately load the servers thru a load balancer (using haproxy). [ that's the step I followed, but it may not be a determining factor ].
  • Stop the first server, upgrade to 3.5.1, answer yes to all questions to perform post-upgrade tasks.
  • Start the server, spinning occurs, at first attempt.

Re-starting the server did not clear the issue. On the customer install, the server had to be taken down, re-installed, and initialised from another node.

I am keeping the data if it can be used for an investigation.



 Comments   
Comment by patrick diligent [ 29/Nov/16 ]

Also manifested after upgrading one 2.6.2 server to 4.0

Comment by Ludovic Poitou [ 13/Mar/17 ]

I believe that this is happening because when you upgrade a server from 2.6 to 3.x, the changelogDB is removed (as the service moved from BDB JE to file-based changelog).

Need to investigate why the Directory is scanning it's own DB to republish the changes that it can.

Comment by Matthew Swift [ 12/Jun/17 ]

It's interesting that the search is unindexed. The search is attempting to find any entries with a ds-sync-hist whose CSN is newer than the ds-sync-state. I suggest enabling logging of internal operations in order to determine the search filter that is being used and then analysing the ds-sync-hist index to find out why it is unindexed. For example, is there a record with more than 4000 values, or is the ds-sync-state for old for some reason?

 

 

Comment by Nicolas Capponi [ 14/Jun/17 ]

I found this request while searching in Hipchat, Lee Trujillo can you confirm is the one corresponding to this issue please ?

[30/Mar/2017:00:33:38 -0400] SEARCH REQ conn=-1 op=53 msgID=54 base="dc=example,dc=com" scope=sub filter="(&(ds-sync-hist>=dummy:0000015abac8065d76260000000d)(ds-sync-hist<=dummy:ffffffffffffffff7626ffffffff))" attrs="entryuuid,ds-sync-hist,*"
[30/Mar/2017:01:37:04 -0400] SEARCH RES conn=-1 op=53 msgID=54 result=0 nentries=557 unindexed etime=3805660
Comment by Nicolas Capponi [ 14/Jun/17 ]

I'm not sure to understand what should be the correct behavior in this case. Obviously, we don't expect the server to spin, but is it expected that the DS scans its own DB to republish the changes ? Otherwise, what should be the behavior ?

Comment by Nicolas Capponi [ 14/Jun/17 ]

Lee Trujillo would it be possible to publish the ds-sync-state index you get so that I can investigate why the search is unindexed ?

Comment by Ludovic Poitou [ 14/Jun/17 ]

I think I have a hint of what's going on... Not sure exactly why.

But I got intrigued by the search filter.

"(&(ds-sync-hist>=dummy:0000015abac8065d76260000000d)(ds-sync-hist<=dummy:ffffffffffffffff7626ffffffff))"

The upper bound is supposed to be LowerCSN + 10000 ms according to the comment in the method that calls the one that builds the filter:

// We can't do the search in one go because we need to store the results
// so that we are sure we send the operations in order and because the
// list might be large.
// So we search by interval of 10 seconds and store the results in the
// replayOperations list so that they are sorted before sending them.
long missingChangesDelta = currentStartCSN.getTime() + 10000;
CSN endCSN = new CSN(missingChangesDelta, 0xffffffff, getServerId());


ScanSearchListener listener = new ScanSearchListener(currentStartCSN, endCSN);
result = searchForChangedEntries(getBaseDN(), currentStartCSN, endCSN, listener);

The 0xffffffff is only supposed to be used for the seqNum, never for the Timestamp.
Could it be that we start with an invalid CSN for which getTime() returns -1 or a value that overflows long ?

Or could it be that the last CSN that was read on the previous loop happened to be one of a max CSN in the ChangelogDB ?

Comment by Matthew Swift [ 14/Jun/17 ]

Market CSN? Do you mean heartbeat or offline message CSNs?

This is indeed the only bit of code that seems to explicitly set a sequence number of -1, but I can't see how we can end up with a timestamp of -1. It seems highly coincidental that currentStartCSN would start with a value of -10001.

Regardless, is this discussion related to the original bug? I'm not sure it is. The original bug describes a problem occurring during initialization when the ds-sync-state attribute is checked and updated.

Comment by Yannick Lecaillez [ 14/Jun/17 ]

The 0xfffffff as timestamp value has been fixed by Jean-Noël Rouvignac in his cleanup

Comment by Ludovic Poitou [ 14/Jun/17 ]

Matt,
Damn autocorrector, i meant Max CSN.

Comment by Ludovic Poitou [ 14/Jun/17 ]

But your analysis is correct Matt, it's happening at initialization time. In 3.5, the timestamp was hardcoded to ffffffffffff as the "endCSN".

Could it be a change in the way we deal with range index cursoring with 3.x vs previous releases (with the new backend hierarchy) ?

Comment by Lee Trujillo [ 14/Jun/17 ]

Nicolas Capponi I have a good backendstat only, but will get a bad one now.  I've requested it.

Comment by Lee Trujillo [ 14/Jun/17 ]

Nicolas Capponi

I've added 2 backendstats.

  1. File 1 has Record Count 431381 for ds-sync-hist.
  2. File 2 has Record Count 61456501 for ds-sync-hist.
Comment by Ludovic Poitou [ 14/Jun/17 ]

After more investigation, I believe the issue is coming from the filter, and the fact that range filter and indexing has changed in 3.x with the new pluggable backend.

filter="(&(ds-sync-hist>=dummy:0000015abac8065d76260000000d)(ds-sync-hist<=dummy:ffffffffffffffff7626ffffffff))

There are still some questions in the air... Are we sure the ServerState is properly saved every second. And on shutdown ?

These customers all hit the issue after a high load, and they have millions of entries...

Can someone enlight me on how the ds-sync-hist index uses the ServerID part or the CSN ?

 

Comment by Ludovic Poitou [ 15/Jun/17 ]

Following up on this, the log messages pointed out by Nicolas are interesting:

[30/Mar/2017:00:33:38 -0400] SEARCH REQ conn=-1 op=53 msgID=54 base="dc=example,dc=com" scope=sub filter="(&(ds-sync-hist>=dummy:0000015abac8065d76260000000d)(ds-sync-hist<=dummy:ffffffffffffffff7626ffffffff))" attrs="entryuuid,ds-sync-hist,*" 
[30/Mar/2017:01:37:04 -0400] SEARCH RES conn=-1 op=53 msgID=54 result=0 nentries=557 unindexed etime=3805660

The log message is dated on March 30, but the CSN used in the filter, which represents the local server's data state, is dated from March 10. Which means that at startup the server tries to look for 20 days of changes, whereas the state should have been saved every second.

$ decodecsn 0000015abac8065d76260000000d
CSN 0000015abac8065d76260000000d
  ts=0000015abac8065d (1489192355421) Fri Mar 10 2017 19:32:35.421 EST
  id=7626 (30246)
  no=0000000d (13)

Comment by Matthew Swift [ 15/Jun/17 ]

Ludovic Poitou - remember that there are two searches performed during initialization. The first updates the DS's ds-sync-state and uses a filter based on the current ds-sync-state. The second is for replaying updates to an RS and uses a filter whose parameters are based on the RS's state. I think the search you are looking at corresponds to the second, RS recovery, search, not the first. The search described in this JIRA's description corresponds to the first type of search used for updating the ds-sync-state.

 To summarize, the reason for the large search filter range is more likely to be caused by an RS which has fallen very far behind, or which has been offline for a long time.

 

Comment by Fabio Pistolesi [ 15/Jun/17 ]

There has been a bit of brainstorming in here based on current code, whose results can be summarised as follows:

  • The search mentioned by Nicolas seems to come from an RS (as Matt pointed out) more than from server start where there should only be a "greater than" filter.
  • The point raised by Ludo about the server state being late could be the RS more than the state as written on disk, but it is to be verified.
  • ds-sync-state is multi-valued, meaning the search above is not a range search, even though it was meant to be... current code actually runs both elements of the search as separate searches, as per LDAP semantic.
  • The index for ds-sync-state uses a specific matching rule, rearranging a CSN components as <serverID, timestamp, seqnum>, effectively ordering by serverID. The impact is we're now not stopping the search when we encounter a key having a serverID different than the one we build the search with.
  • There is an issue about optimising searches on single valued attributes, as a side task. It would not help for ds-sync-hist, though.

Nevertheless, even though the search could be simplified to a simpler "greater than", for serverIDs at the beginning of the index, we're still looking at most of the index to be returned, so it is not a complete solution. Probably an extensible matching rule should be introduced, so that we can simulate a range search for a given serverID.

Nicolas Capponi, Matthew Swift please correct and add to above summary if you feel like it.

Comment by Nicolas Capponi [ 15/Jun/17 ]

In conclusion, we think there is a very slow and inefficient search performed due to the points mentioned by Fabio, and the fix would introduce an extensible matching rule to address them.

We are in the process of validating this with Fabio, using 2 replicated 2.6 servers both loaded with modrate. We will then perform the searches on ds-sync-hist on the 2.6 server and then on a 4.0 version to see if slow search explain the behavior.

Comment by Matthew Swift [ 15/Jun/17 ]

I agree with the comments made so far. Given two DS's one with server ID "1" and the other with server ID "2", both with changes ranging from t0 to tn, then a simple internal search in DS "1" to return all ds-sync-hist values greater than server ID "1" at time "tn" will return all of the ds-sync-hist records corresponding to DS ID "2" since "2" is greater than "1", and the server ID is the primary ordering key used by the ds-sync-hist index.

We need to constrain the search using an upper bound in order to ensure that only changes for a specific server ID are returned but, as Fabio points out, range queries are not possible with multi-valued attributes. Therefore we'll need an extensible matching rule to support this capability: effectively encapsulating the semantics of an AND range query but applied to a single value. We may want to consider defining an assertion syntax capable of supporting not only range queries but also "greater than" and "less than" queries, since these are not supported using standard LDAP filters.

Great investigation work Fabio Pistolesi & Nicolas Capponi!

Comment by Fabio Pistolesi [ 15/Jun/17 ]

It is apparently simpler to reproduce than we thought... 2 replicated 2.6.2 servers, run a modrate load, first on server one for an hour, then on server 2 for an hour. Servers have 2M entries.
Upgrade server one (as it happens its serverID is lower than the other) using OpenDj master. At start:

[15/Jun/2017:18:42:58 +0200] SEARCH REQ conn=-1 op=52 msgID=53 base="dc=example,dc=com" scope=sub filter="(ds-sync-hist>=dummy:0000015cac3e5b040daf041aceb0)" attrs="ds-sync-hist,entryuuid,*"

CSN 0000015cac3e5b040daf041aceb0
  ts=0000015cac3e5b04 (1497538386692) Thu Jun 15 2017 16:53:06.692 CEST
  id=0daf (3503)
  no=041aceb0 (68865712)

the other server's state CSN is

CSN 0000015cac74abd55fa9034add4b
  ts=0000015cac74abd5 (1497541946325) Thu Jun 15 2017 17:52:26.325 CEST
  id=5fa9 (24489)
  no=034add4b (55237963)

it takes 3:20 to start:

[15/Jun/2017:18:42:57 +0200] category=EXTENSIONS severity=NOTICE msgID=221 msg=DIGEST-MD5 SASL mechanism using a server fully qualified domain name of: brie.internal.forgerock.com
[15/Jun/2017:18:42:57 +0200] category=SYNC severity=NOTICE msgID=204 msg=Replication server RS(6026) started listening for new connections on address 0.0.0.0 port 8989
[15/Jun/2017:18:42:57 +0200] category=SYNC severity=NOTICE msgID=62 msg=Directory server DS(4601) has connected to replication server RS(6026) for domain "cn=schema" at 172.16.204.139:8989 with generation ID 8408
[15/Jun/2017:18:42:58 +0200] category=SYNC severity=NOTICE msgID=62 msg=Directory server DS(2888) has connected to replication server RS(6026) for domain "cn=admin data" at 172.16.204.139:8989 with generation ID 155242
[15/Jun/2017:18:46:20 +0200] category=SYNC severity=NOTICE msgID=62 msg=Directory server DS(3503) has connected to replication server RS(6026) for domain "dc=example,dc=com" at 172.16.204.139:8989 with generation ID 19449724
[15/Jun/2017:18:46:22 +0200] category=PROTOCOL severity=NOTICE msgID=276 msg=Started listening for new connections on Administration Connector 0.0.0.0 port 4444
[15/Jun/2017:18:46:22 +0200] category=PROTOCOL severity=NOTICE msgID=276 msg=Started listening for new connections on LDAP Connection Handler 0.0.0.0 port 1389
[15/Jun/2017:18:46:22 +0200] category=CORE severity=NOTICE msgID=135 msg=The Directory Server has started successfully
[15/Jun/2017:18:46:22 +0200] category=CORE severity=NOTICE msgID=139 msg=The Directory Server has sent an alert notification generated by class org.opends.server.core.DirectoryServer (alert type org.opends.server.DirectoryServerStarted, alert ID org.opends.messages.core-135): The Directory Server has started successfully

the stack is:

"main" #1 prio=5 os_prio=0 tid=0x00007f2b5c008800 nid=0x12237 runnable [0x00007f2b64a0a000]
   java.lang.Thread.State: RUNNABLE
        at java.io.RandomAccessFile.seek0(Native Method)
        at java.io.RandomAccessFile.seek(RandomAccessFile.java:557)
        at com.sleepycat.je.log.FileManager.readFromFileInternal(FileManager.java:1935)
        - locked <0x00000002047df440> (a com.sleepycat.je.log.FileManager$DefaultRandomAccessFile)
        at com.sleepycat.je.log.FileManager.readFromFile(FileManager.java:1890)
        at com.sleepycat.je.log.FileManager.readFromFile(FileManager.java:1827)
        at com.sleepycat.je.log.FileSource.getBytes(FileSource.java:71)
        at com.sleepycat.je.log.FileSource.getBytes(FileSource.java:60)
        at com.sleepycat.je.log.LogManager.getLogEntryFromLogSource(LogManager.java:1026)
        at com.sleepycat.je.log.LogManager.getLogEntry(LogManager.java:841)
        at com.sleepycat.je.log.LogManager.getLogEntryAllowInvisibleAtRecovery(LogManager.java:798)
        at com.sleepycat.je.tree.IN.fetchLN(IN.java:2784)
        at com.sleepycat.je.tree.IN.fetchLN(IN.java:2725)
        at com.sleepycat.je.dbi.CursorImpl.getCurrent(CursorImpl.java:2233)
        at com.sleepycat.je.Cursor.searchExact(Cursor.java:4207)
        at com.sleepycat.je.Cursor.searchNoDups(Cursor.java:4055)
        at com.sleepycat.je.Cursor.search(Cursor.java:3857)
        - locked <0x00000005da6f1988> (a com.sleepycat.je.Cursor)
        at com.sleepycat.je.Cursor.getInternal(Cursor.java:1284)
        at com.sleepycat.je.Database.get(Database.java:1271)
        at com.sleepycat.je.Database.get(Database.java:1330)
        at org.opends.server.backends.jeb.JEStorage$WriteableTransactionImpl.read(JEStorage.java:360)
        at org.opends.server.backends.pluggable.ID2Entry.get(ID2Entry.java:428)
        at org.opends.server.backends.pluggable.EntryContainer.getEntry(EntryContainer.java:1054)
        at org.opends.server.backends.pluggable.EntryContainer.searchNotIndexed(EntryContainer.java:992)
        at org.opends.server.backends.pluggable.EntryContainer.access$1800(EntryContainer.java:115)
        at org.opends.server.backends.pluggable.EntryContainer$3.run(EntryContainer.java:762)
        at org.opends.server.backends.pluggable.EntryContainer$3.run(EntryContainer.java:586)
        at org.opends.server.backends.jeb.JEStorage.read(JEStorage.java:680)
        at org.opends.server.backends.pluggable.TracedStorage.read(TracedStorage.java:419)
        at org.opends.server.backends.pluggable.EntryContainer.search(EntryContainer.java:586)
        at org.opends.server.backends.pluggable.BackendImpl.search(BackendImpl.java:481)
        at org.opends.server.workflowelement.localbackend.LocalBackendSearchOperation.processSearch(LocalBackendSearchOperation.java:159)
        at org.opends.server.workflowelement.localbackend.LocalBackendSearchOperation.processLocalSearch(LocalBackendSearchOperation.java:97)
        at org.opends.server.workflowelement.localbackend.LocalBackendWorkflowElement.executeOperation(LocalBackendWorkflowElement.java:411)
        at org.opends.server.workflowelement.localbackend.LocalBackendWorkflowElement.execute(LocalBackendWorkflowElement.java:533)
        at org.opends.server.core.SearchOperationBasis.run(SearchOperationBasis.java:778)
        at org.opends.server.protocols.internal.InternalClientConnection.handleRequest(InternalClientConnection.java:326)
        at org.opends.server.protocols.internal.InternalClientConnection.access$000(InternalClientConnection.java:110)
        at org.opends.server.protocols.internal.InternalClientConnection$1.subscribe(InternalClientConnection.java:314)
        at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:72)
        at io.reactivex.Flowable.subscribe(Flowable.java:12986)
        at io.reactivex.internal.operators.flowable.FlowableDoOnEach.subscribeActual(FlowableDoOnEach.java:49)
        at io.reactivex.Flowable.subscribe(Flowable.java:12986)
        at io.reactivex.internal.operators.flowable.FlowableDoOnEach.subscribeActual(FlowableDoOnEach.java:49)
        at io.reactivex.Flowable.subscribe(Flowable.java:12986)
        at io.reactivex.internal.operators.flowable.FlowableOnErrorNext.subscribeActual(FlowableOnErrorNext.java:39)
        at io.reactivex.Flowable.subscribe(Flowable.java:12986)
        at io.reactivex.internal.operators.flowable.FlowableToListSingle.subscribeActual(FlowableToListSingle.java:57)
        at io.reactivex.Single.subscribe(Single.java:2703)
        at io.reactivex.Single.blockingGet(Single.java:2156)
        at org.opends.server.protocols.internal.InternalClientConnection.search(InternalClientConnection.java:957)
        at org.opends.server.protocols.internal.InternalClientConnection.processSearch(InternalClientConnection.java:895)
        at org.opends.server.replication.plugin.LDAPReplicationDomain.searchForChangedEntries(LDAPReplicationDomain.java:3422)
        at org.opends.server.replication.plugin.LDAPReplicationDomain.searchForChangedEntries(LDAPReplicationDomain.java:3440)
        at org.opends.server.replication.plugin.PersistentServerState.checkAndUpdateServerState(PersistentServerState.java:262)
        - locked <0x000000009d08a2f0> (a org.opends.server.replication.plugin.PersistentServerState)
        at org.opends.server.replication.plugin.PersistentServerState.loadState(PersistentServerState.java:132)
        at org.opends.server.replication.plugin.PersistentServerState.<init>(PersistentServerState.java:76)
        at org.opends.server.replication.plugin.LDAPReplicationDomain.<init>(LDAPReplicationDomain.java:520)
        at org.opends.server.replication.plugin.MultimasterReplication.createNewDomain(MultimasterReplication.java:256)
        at org.opends.server.replication.plugin.MultimasterReplication.createNewDomain(MultimasterReplication.java:233)
        at org.opends.server.replication.plugin.MultimasterReplication.initializeSynchronizationProvider(MultimasterReplication.java:300)
        at org.opends.server.replication.plugin.MultimasterReplication.initializeSynchronizationProvider(MultimasterReplication.java:85)
        at org.opends.server.core.SynchronizationProviderConfigManager.getSynchronizationProvider(SynchronizationProviderConfigManager.java:263)
        at org.opends.server.core.SynchronizationProviderConfigManager.initializeSynchronizationProviders(SynchronizationProviderConfigManager.java:98)
        at org.opends.server.core.DirectoryServer.startServer(DirectoryServer.java:1325)
        - locked <0x000000008021b9f8> (a org.opends.server.core.DirectoryServer)
        at org.opends.server.core.DirectoryServer.main(DirectoryServer.java:4238)
Comment by Matthew Swift [ 15/Jun/17 ]

For inspiration regarding implementation of complex extensible matching rules I suggest looking at org.forgerock.opendj.rest2ldap.schema.JsonQueryEqualityMatchingRuleImpl

Note that the extensible matching rule can re-use the ordering index.

 I suggest an assertion syntax of the form: OP VALUE [, OP VALUE], e.g. ">2, <10"

Comment by Lee Trujillo [ 15/Jun/17 ]

Other customer info

[14/Jun/2017:14:44:45 -0400] SEARCH REQ conn=-1 op=53 msgID=54 base="dc=example2,dc=com" scope=sub filter="(&(ds-sync-hist>=dummy:0000015b3fc1f1861f3003d323c1)(ds-sync-hist<=dummy:ffffffffffffffff1f30ffffffff))" attrs="entryuuid,ds-sync-hist,*"
[14/Jun/2017:18:50:05 -0400] SEARCH RES conn=-1 op=53 msgID=54 result=0 nentries=623568 unindexed etime=14719867

 

dn: cn=debugsearch 
debugsearchindex: filter=(&(ds-sync-hist>=dummy:0000015b3fc1f1861f3003d323c1)[IN 
DEX:ds-sync-hist.ordering][LIMIT-EXCEEDED](ds-sync-hist<=dummy:ffffffffffffffff 
1f30ffffffff)[INDEX:ds-sync-hist.ordering][LIMIT-EXCEEDED])[NOT-INDEXED] scope= 
sub[NOT-INDEXED] final=[NOT-INDEXED]

 

  • This is their DR site that only gets updated from backups from their primary site
  • userRoot contains 34191820 entries

 

These servers were upgraded from 2.6.2 --> 3.5.2

This is our DR environment, and there is very little work actually processed here. We typically just restore PROD backups here. But when we do run it, it would be one server receiving the work and syncing to the other.

Comment by Christophe Sovant [ 13/Jul/17 ]

Verified with an automated tests using OpenDJ 4.1.0-SNAPSHOT (rev 12254571675)

Generated at Sat Oct 24 06:57:18 UTC 2020 using Jira 7.13.12#713012-sha1:6e07c38070d5191bbf7353952ed38f111754533a.