Resolves: bug 233642

Bug Description: MMR breaks with time skew errors
Reviewed by: nhosoi, nkinder (Thanks!)
Fix Description: CSN remote offset generation seems broken.  We seem to accumulate a remote offset that keeps growing until we hit the limit of 1 day, then replication stops.  The idea behind the remote offset is that servers may be seconds or minutes off.  When replication starts, one of the itmes in the payload of the start extop is the latest CSN from the supplier.  The CSN timestamp field is (sampled_time + local offset + remote offset).  Sampled time comes from the time thread in the server that updates the time once per second.  This allows the consumer, if also a master, to adjust its CSN generation so as not to generate duplicates or CSNs less than those from the supplier.  However, the logic in csngen_adjust_time appears to be wrong:
       remote_offset = remote_time - gen->state.sampled_time;
That is, remote_offset = (remote sampled_time + remote local offset + remote remote offset) - gen->state.sampled_time
It should be
       remote_offset = remote_time - (sampled_time + local offset + remote offset)
Since the sampled time is not the actual current time, it may be off by 1 second.  So the new remote_offset will be at least 1 second more than it should be.  Since this is the same remote_offset used to generate the CSN to send back to the other master, this offset would keep increasing and increasing over time.  The script attached to the bug helps measure this effect.  The new code also attempts to refresh the sampled time while adjusting to make sure we have as current a sampled_time as possible.  In the old code, the remote_offset is "sent" back and forth between the masters, carried along in the CSN timestamp generation.  In the new code, this can happen too, but to a far less extent, and should max out at (real offset + N seconds) where N is the number of masters.
In the old code, you could only call csngen_adjust_time if you first made sure the remote timestamp >= local timestamp.  I have removed this restriction and moved that logic into csngen_adjust_time.  I also cleaned up the code in the consumer extop - I combined the checking of the CSN from the extop with the max CSN from the supplier RUV - now we only adjust the time once based on the max of all of these CSNs sent by the supplier.
Finally, I cleaned up the error handling in a few places that assumed all errors were time skew errors.
Follow up - I found a bug in my previous patch - _csngen_adjust_local_time must not be called when the sampled time == the current time.  So I fixed that where I was calling _csngen_adjust_local_time, and I also changed _csngen_adjust_local_time so that time_diff == 0 is a no-op.
Platforms tested: RHEL5, F8, F9
Flag Day: no
Doc impact: no
QA impact: Should test MMR and use the script to measure the offset effect.

5 files changed, 54 insertions, 55 deletions

diff --git a/ldap/servers/plugins/replication/repl5.h b/ldap/servers/plugins/replication/repl5.h
index ed27f4e7..4a7f0db9 100644
--- a/ldap/servers/plugins/replication/repl5.h
+++ b/ldap/servers/plugins/replication/repl5.h
@@ -486,6 +486,7 @@ void replica_flush(Replica *r);
 void replica_get_referrals(const Replica *r, char ***referrals);
 void replica_set_referrals(Replica *r,const Slapi_ValueSet *vs);
 int replica_update_csngen_state (Replica *r, const RUV *ruv);
+int replica_update_csngen_state_ext (Replica *r, const RUV *ruv, const CSN *extracsn);
 CSN *replica_get_purge_csn(const Replica *r);
 int replica_log_ruv_elements (const Replica *r);
 void replica_enumerate_replicas (FNEnumReplica fn, void *arg);
diff --git a/ldap/servers/plugins/replication/repl5_inc_protocol.c b/ldap/servers/plugins/replication/repl5_inc_protocol.c
index e0473438..b9290410 100644
--- a/ldap/servers/plugins/replication/repl5_inc_protocol.c
+++ b/ldap/servers/plugins/replication/repl5_inc_protocol.c
@@ -1100,13 +1100,20 @@ repl5_inc_run(Private_Repl_Protocol *prp)
 	    rc = replica_update_csngen_state (replica, ruv); 
 	    object_release (prp->replica_object);
 	    replica = NULL;
-	    if (rc != 0) /* too much skew */
+	    if (rc == CSN_LIMIT_EXCEEDED) /* too much skew */
 	      {
 		slapi_log_error(SLAPI_LOG_FATAL, repl_plugin_name,
 			"%s: Incremental protocol: fatal error - too much time skew between replicas!\n",
 			agmt_get_long_name(prp->agmt));
 		next_state = STATE_STOP_FATAL_ERROR;
 	      }   
+	    else if (rc != 0) /* internal error */
+	      {
+		slapi_log_error(SLAPI_LOG_FATAL, repl_plugin_name,
+			"%s: Incremental protocol: fatal internal error updating the CSN generator!\n",
+			agmt_get_long_name(prp->agmt));
+		next_state = STATE_STOP_FATAL_ERROR;
+	      }   
 	    else
 	      {
 		rc = send_updates(prp, ruv, &num_changes_sent);
diff --git a/ldap/servers/plugins/replication/repl5_replica.c b/ldap/servers/plugins/replication/repl5_replica.c
index 702754e3..87b8b6d3 100644
--- a/ldap/servers/plugins/replication/repl5_replica.c
+++ b/ldap/servers/plugins/replication/repl5_replica.c
@@ -1043,7 +1043,7 @@ replica_set_referrals(Replica *r,const Slapi_ValueSet *vs)
 }
 
 int 
-replica_update_csngen_state (Replica *r, const RUV *ruv)
+replica_update_csngen_state_ext (Replica *r, const RUV *ruv, const CSN *extracsn)
 {
     int rc = 0;
     CSNGen *gen;
@@ -1057,34 +1057,42 @@ replica_update_csngen_state (Replica *r, const RUV *ruv)
         return -1;
     }
 
-    if (csn == NULL) /* ruv contains no csn - we are done */
+    if ((csn == NULL) && (extracsn == NULL)) /* ruv contains no csn and no extra - we are done */
     {
         return 0;
     }
 
+    if (csn_compare(extracsn, csn) > 0) /* extracsn > csn */
+    {
+        csn_free (&csn); /* free */
+        csn = (CSN*)extracsn; /* use this csn to do the update */
+    }
+
     PR_Lock(r->repl_lock);
 
     gen = (CSNGen *)object_get_data (r->repl_csngen);
     PR_ASSERT (gen);
 
     rc = csngen_adjust_time (gen, csn);
-    if (rc != CSN_SUCCESS)
-    {
-        rc = -1;
-        goto done;
-    }
-            
-    rc = 0;
+    /* rc will be either CSN_SUCCESS (0) or clock skew */
 
 done:
 
     PR_Unlock(r->repl_lock);
-    if (csn)
+    if (csn != extracsn) /* do not free the given csn */
+    {
         csn_free (&csn);
+    }
 
     return rc;  
 }
 
+int 
+replica_update_csngen_state (Replica *r, const RUV *ruv)
+{
+    return replica_update_csngen_state_ext(r, ruv, NULL);
+}
+
 /* 
  * dumps replica state for debugging purpose 
  */
diff --git a/ldap/servers/plugins/replication/repl_extop.c b/ldap/servers/plugins/replication/repl_extop.c
index 0abc6417..0cdba759 100644
--- a/ldap/servers/plugins/replication/repl_extop.c
+++ b/ldap/servers/plugins/replication/repl_extop.c
@@ -550,7 +550,6 @@ multimaster_extop_StartNSDS50ReplicationRequest(Slapi_PBlock *pb)
 	Replica *replica = NULL;
 	void *conn;
 	consumer_connection_extension *connext = NULL;
-	CSN *mycsn = NULL;
 	char *replicacsnstr = NULL;
 	CSN *replicacsn = NULL;
 	int zero = 0;
@@ -703,55 +702,37 @@ multimaster_extop_StartNSDS50ReplicationRequest(Slapi_PBlock *pb)
 		gen = object_get_data(gen_obj);
 		if (NULL != gen)
 		{
-			if (csngen_new_csn(gen, &mycsn, PR_FALSE /* notify */) == CSN_SUCCESS)
+			replicacsn = csn_new_by_string(replicacsnstr);
+			if (NULL != replicacsn)
 			{
-				replicacsn = csn_new_by_string(replicacsnstr);
-				if (NULL != replicacsn)
+				/* ONREPL - we used to manage clock skew here. However, csn generator
+				   code already does it. The csngen also manages local skew caused by
+				   system clock reset, so to keep it consistent, I removed code from here */
+				/* update the state of the csn generator */
+				rc = replica_update_csngen_state_ext (replica, supplier_ruv, replicacsn); /* too much skew */
+				if (rc == CSN_LIMIT_EXCEEDED)
 				{
-                    /* ONREPL - we used to manage clock skew here. However, csn generator
-                       code already does it. The csngen also manages local skew caused by
-                       system clock reset, so to keep it consistent, I removed code from here */
-					time_t diff = 0L;
-					diff = csn_time_difference(mycsn, replicacsn);
-					if (diff > 0)
-					{
-					    /* update the state of the csn generator */
-                        rc = csngen_adjust_time (gen, replicacsn);
-                        if (rc == CSN_LIMIT_EXCEEDED)   /* too much skew */
-                        {
-							response = NSDS50_REPL_EXCESSIVE_CLOCK_SKEW;
-							goto send_response;
-						}
-					}
-					else if (diff <= 0)
-					{
-						/* Supplier's clock is behind ours */
-						/* XXXggood check if CSN smaller than purge point */
-						/* response = NSDS50_REPL_BELOW_PURGEPOINT; */
-						/* goto send_response; */
-					}
+					response = NSDS50_REPL_EXCESSIVE_CLOCK_SKEW;
+					slapi_log_error(SLAPI_LOG_FATAL, repl_plugin_name,
+									"conn=%d op=%d repl=\"%s\": "
+									"Excessive clock skew from supplier RUV\n",
+									connid, opid, repl_root);
+					goto send_response;
 				}
-				else
+				else if (rc != 0)
 				{
-					/* Oops, csnstr couldn't be converted */
+					/* Oops, problem csn or ruv format, or memory, or .... */
 					response = NSDS50_REPL_INTERNAL_ERROR;
 					goto send_response;
 				}
+
 			}
 			else
 			{
-				/* Oops, csn generator failed */
+				/* Oops, csnstr couldn't be converted */
 				response = NSDS50_REPL_INTERNAL_ERROR;
 				goto send_response;
 			}
-
-            /* update csn generator's state from the supplier's ruv */
-            rc = replica_update_csngen_state (replica, supplier_ruv); /* too much skew */
-            if (rc != 0)
-            {
-                response = NSDS50_REPL_EXCESSIVE_CLOCK_SKEW;
-				goto send_response;
-            }
 		}
 		else
 		{
@@ -988,11 +969,6 @@ send_response:
 	{
 		object_release(gen_obj);
 	}
-	/* mycsn */
-	if (NULL != mycsn)
-	{
-		csn_free(&mycsn);
-	}
 	/* replicacsn */
 	if (NULL != replicacsn)
 	{
diff --git a/ldap/servers/plugins/replication/windows_inc_protocol.c b/ldap/servers/plugins/replication/windows_inc_protocol.c
index adcc417b..c02e6610 100644
--- a/ldap/servers/plugins/replication/windows_inc_protocol.c
+++ b/ldap/servers/plugins/replication/windows_inc_protocol.c
@@ -796,13 +796,20 @@ windows_inc_run(Private_Repl_Protocol *prp)
 	    rc = replica_update_csngen_state (replica, ruv); 
 	    object_release (prp->replica_object);
 	    replica = NULL;
-	    if (rc != 0) /* too much skew */
+	    if (rc == CSN_LIMIT_EXCEEDED) /* too much skew */
 	      {
-		slapi_log_error(SLAPI_LOG_FATAL, windows_repl_plugin_name,
+		slapi_log_error(SLAPI_LOG_FATAL, repl_plugin_name,
 			"%s: Incremental protocol: fatal error - too much time skew between replicas!\n",
 			agmt_get_long_name(prp->agmt));
 		next_state = STATE_STOP_FATAL_ERROR;
 	      }   
+	    else if (rc != 0) /* internal error */
+	      {
+		slapi_log_error(SLAPI_LOG_FATAL, repl_plugin_name,
+			"%s: Incremental protocol: fatal internal error updating the CSN generator!\n",
+			agmt_get_long_name(prp->agmt));
+		next_state = STATE_STOP_FATAL_ERROR;
+	      }   
 	    else
 	      {
 		rc = send_updates(prp, ruv, &num_changes_sent);