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.

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);

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);

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 
  */

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)
 	{

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);

ldap/servers/slapd/csngen.c

@@ -60,6 +60,9 @@
 #define STATE_FORMAT			 "%8x%8x%8x%4hx%4hx"
 #define STATE_LENGTH			 32
 #define MAX_VAL(x,y)			 ((x)>(y)?(x):(y))
+#define CSN_CALC_TSTAMP(gen)     ((gen)->state.sampled_time + \
+                                  (gen)->state.local_offset + \
+                                  (gen)->state.remote_offset)
 
 /*
  * **************************************************************************
@@ -273,8 +276,7 @@ csngen_new_csn (CSNGen *gen, CSN **csn, PRBool notify)
         gen->state.seq_num = 0;
     }
 
-    (*csn)->tstamp = gen->state.sampled_time + gen->state.local_offset + 
-                     gen->state.remote_offset;
+    (*csn)->tstamp = CSN_CALC_TSTAMP(gen);
     (*csn)->seqnum = gen->state.seq_num ++;
     (*csn)->rid = gen->state.rid;
 	(*csn)->subseqnum = 0;
@@ -308,8 +310,9 @@ void csngen_abort_csn (CSNGen *gen, const CSN *csn)
    of time so that it does not generate smaller csns */
 int csngen_adjust_time (CSNGen *gen, const CSN* csn)
 {
-    time_t remote_time, remote_offset;
+    time_t remote_time, remote_offset, cur_time;
 	PRUint16 remote_seqnum;
+    int rc;
 
     if (gen == NULL || csn == NULL)
         return CSN_INVALID_PARAMETER;
@@ -319,21 +322,38 @@ int csngen_adjust_time (CSNGen *gen, const CSN* csn)
 
     PR_RWLock_Wlock (gen->lock);
 
-	if (remote_seqnum > gen->state.seq_num )
-	{
-		if (remote_seqnum < CSN_MAX_SEQNUM)
-		{
-			gen->state.seq_num = remote_seqnum + 1;
-		}
-		else
-		{
-			remote_time++;
-		}
-	}
+    /* make sure we have the current time */
+    csngen_update_time();
+    cur_time = g_sampled_time;
+
+    /* make sure sampled_time is current */
+    /* must only call adjust_local_time if the current time is greater than
+       the generator state time */
+    if ((cur_time > gen->state.sampled_time) &&
+        (CSN_SUCCESS != (rc = _csngen_adjust_local_time(gen, cur_time))))
+    {
+        /* _csngen_adjust_local_time will log error */
+        PR_RWLock_Unlock (gen->lock);
+        csngen_dump_state(gen);
+        return rc;
+    }
 
-    if (remote_time >= gen->state.sampled_time)
+    cur_time = CSN_CALC_TSTAMP(gen);
+    if (remote_time >= cur_time)
     {
-        remote_offset = remote_time - gen->state.sampled_time;
+        if (remote_seqnum > gen->state.seq_num )
+        {
+            if (remote_seqnum < CSN_MAX_SEQNUM)
+            {
+                gen->state.seq_num = remote_seqnum + 1;
+            }
+            else
+            {
+                remote_time++;
+            }
+        }
+
+        remote_offset = remote_time - cur_time;
 		if (remote_offset > gen->state.remote_offset)
 		{
 			if (remote_offset <= CSN_MAX_TIME_ADJUST)
@@ -346,10 +366,18 @@ int csngen_adjust_time (CSNGen *gen, const CSN* csn)
                             "adjustment limit exceeded; value - %ld, limit - %ld\n",
                              remote_offset, (long)CSN_MAX_TIME_ADJUST);
 				PR_RWLock_Unlock (gen->lock);
+				csngen_dump_state(gen);
 				return CSN_LIMIT_EXCEEDED;
 			}
 		}
-    }
+	}
+	else if (gen->state.remote_offset > 0)
+	{
+		/* decrease remote offset? */
+		/* how to decrease remote offset but ensure that we don't
+		   generate a duplicate CSN, or a CSN smaller than one we've already
+		   generated? */
+	}
 
     PR_RWLock_Unlock (gen->lock);
 
@@ -576,7 +604,14 @@ _csngen_adjust_local_time (CSNGen *gen, time_t cur_time)
 {
     time_t time_diff = cur_time - gen->state.sampled_time;
 
-    if (time_diff > 0)
+    if (time_diff == 0) {
+        /* This is a no op - _csngen_adjust_local_time should never be called
+           in this case, because there is nothing to adjust - but just return
+           here to protect ourselves
+        */
+        return CSN_SUCCESS;
+    }
+    else if (time_diff > 0)
     {
         gen->state.sampled_time = cur_time;
         if (time_diff > gen->state.local_offset)
@@ -588,7 +623,7 @@ _csngen_adjust_local_time (CSNGen *gen, time_t cur_time)
 
         return CSN_SUCCESS;
     }
-    else   /* time was turend back */
+    else   /* time was turned back */
     {
         if (abs (time_diff) > CSN_MAX_TIME_ADJUST)
         {