Fix iprop log reinitialization

If the master iprop log is reinitialized to serial number 0, slaves
will need to take a full dump--but after that happens, we need to know
whether the slave has taken that full dump, we we don't offering full
dumps indefinitely.

So, record a timestamp in kdb_last_time when we reinitialize the log
header, and compare the slave timestamp to kdb_last_time whenever it
has the current serial number, even if it's 0.  Test this by
performing a propagation with sno 0 in t_iprop.py and detecting
whether kpropd gets a second UPDATE_FULL_RESYNC_NEEDED response from
kadmind.

ticket: 7550 (new)

8 files changed, 50 insertions, 42 deletions

diff --git a/src/include/kdb_log.h b/src/include/kdb_log.h
index 14dbb25659..43d2fc41dd 100644
--- a/src/include/kdb_log.h
+++ b/src/include/kdb_log.h
@@ -71,6 +71,7 @@ extern krb5_error_code ulog_map(krb5_context context,
                                 const char *logname, uint32_t entries,
                                 int caller,
                                 char **db_args);
+extern void ulog_init_header(krb5_context context);
 extern krb5_error_code ulog_add_update(krb5_context context,
                                        kdb_incr_update_t *upd);
 extern krb5_error_code ulog_delete_update(krb5_context context,
diff --git a/src/kadmin/dbutil/dump.c b/src/kadmin/dbutil/dump.c
index 600f07f843..869724af68 100644
--- a/src/kadmin/dbutil/dump.c
+++ b/src/kadmin/dbutil/dump.c
@@ -2884,13 +2884,7 @@ load_db(argc, argv)
          *      no advantage in incr updates when entire db is replaced
          */
         if (!(flags & FLAG_UPDATE)) {
-            memset(log_ctx->ulog, 0, sizeof (kdb_hlog_t));
-
-            log_ctx->ulog->kdb_hmagic = KDB_ULOG_HDR_MAGIC;
-            log_ctx->ulog->db_version_num = KDB_VERSION;
-            log_ctx->ulog->kdb_state = KDB_STABLE;
-            log_ctx->ulog->kdb_block = ULOG_BLOCK;
-
+            ulog_init_header(util_context);
             log_ctx->iproprole = IPROP_NULL;
 
             if (!add_update) {
diff --git a/src/kadmin/dbutil/kdb5_create.c b/src/kadmin/dbutil/kdb5_create.c
index b34219b08e..cbdea16edc 100644
--- a/src/kadmin/dbutil/kdb5_create.c
+++ b/src/kadmin/dbutil/kdb5_create.c
@@ -301,12 +301,7 @@ void kdb5_create(argc, argv)
          * We're reinitializing the update log in case one already
          * existed, but this should never happen.
          */
-        (void) memset(log_ctx->ulog, 0, sizeof (kdb_hlog_t));
-
-        log_ctx->ulog->kdb_hmagic = KDB_ULOG_HDR_MAGIC;
-        log_ctx->ulog->db_version_num = KDB_VERSION;
-        log_ctx->ulog->kdb_state = KDB_STABLE;
-        log_ctx->ulog->kdb_block = ULOG_BLOCK;
+        ulog_init_header(util_context);
 
         /*
          * Since we're creating a new db we shouldn't worry about
diff --git a/src/lib/kdb/kdb_log.c b/src/lib/kdb/kdb_log.c
index f70d3fed3b..017c41ad14 100644
--- a/src/lib/kdb/kdb_log.c
+++ b/src/lib/kdb/kdb_log.c
@@ -36,6 +36,22 @@ static int pagesize = 0;
 
 static int extend_file_to(int fd, unsigned int new_size);
 
+static inline krb5_boolean
+time_equal(const kdbe_time_t *a, const kdbe_time_t *b)
+{
+    return a->seconds == b->seconds && a->useconds == b->useconds;
+}
+
+static void
+time_current(kdbe_time_t *out)
+{
+    struct timeval timestamp;
+
+    (void)gettimeofday(&timestamp, NULL);
+    out->seconds = timestamp.tv_sec;
+    out->useconds = timestamp.tv_usec;
+}
+
 krb5_error_code
 ulog_lock(krb5_context ctx, int mode)
 {
@@ -135,7 +151,6 @@ ulog_add_update(krb5_context context, kdb_incr_update_t *upd)
 {
     XDR xdrs;
     kdbe_time_t ktime;
-    struct timeval timestamp;
     kdb_ent_header_t *indx_log;
     unsigned int i, recsize;
     unsigned long upd_size;
@@ -153,9 +168,7 @@ ulog_add_update(krb5_context context, kdb_incr_update_t *upd)
     if (upd == NULL)
         return KRB5_LOG_ERROR;
 
-    (void)gettimeofday(&timestamp, NULL);
-    ktime.seconds = timestamp.tv_sec;
-    ktime.useconds = timestamp.tv_usec;
+    time_current(&ktime);
 
     upd_size = xdr_sizeof((xdrproc_t)xdr_kdb_incr_update_t, upd);
 
@@ -452,6 +465,19 @@ ulog_reset(kdb_hlog_t *ulog)
     ulog->db_version_num = KDB_VERSION;
     ulog->kdb_state = KDB_STABLE;
     ulog->kdb_block = ULOG_BLOCK;
+    time_current(&ulog->kdb_last_time);
+}
+
+/* Reinitialize the log header.  Locking is the caller's responsibility. */
+void
+ulog_init_header(krb5_context context)
+{
+    kdb_log_context *log_ctx;
+    kdb_hlog_t *ulog;
+
+    INIT_ULOG(context);
+    ulog_reset(ulog);
+    ulog_sync_header(ulog);
 }
 
 /*
@@ -669,10 +695,18 @@ ulog_get_entries(krb5_context context, kdb_last_t last,
         return retval;
     }
 
+    /* If we have the same sno and timestamp, return a nil update.  If a
+     * different timestamp, the sno was reused and we need a full resync. */
+    if (last.last_sno == ulog->kdb_last_sno) {
+        ulog_handle->ret = time_equal(&last.last_time, &ulog->kdb_last_time) ?
+            UPDATE_NIL : UPDATE_FULL_RESYNC_NEEDED;
+        goto cleanup;
+    }
+
     /* We may have overflowed the update log or shrunk the log, or the client
      * may have created its ulog. */
     if (last.last_sno > ulog->kdb_last_sno ||
-        last.last_sno < ulog->kdb_first_sno || last.last_sno == 0) {
+        last.last_sno < ulog->kdb_first_sno) {
         ulog_handle->lastentry.last_sno = ulog->kdb_last_sno;
         ulog_handle->ret = UPDATE_FULL_RESYNC_NEEDED;
         goto cleanup;
@@ -682,20 +716,13 @@ ulog_get_entries(krb5_context context, kdb_last_t last,
     indx = (sno - 1) % ulogentries;
     indx_log = (kdb_ent_header_t *)INDEX(ulog, indx);
 
-    if (indx_log->kdb_time.seconds != last.last_time.seconds ||
-        indx_log->kdb_time.useconds != last.last_time.useconds) {
+    if (!time_equal(&indx_log->kdb_time, &last.last_time)) {
         /* We have time stamp mismatch or we no longer have the slave's last
          * sno, so we brute force it. */
         ulog_handle->ret = UPDATE_FULL_RESYNC_NEEDED;
         goto cleanup;
     }
 
-    /* If we have the same sno we return success. */
-    if (last.last_sno == ulog->kdb_last_sno) {
-        ulog_handle->ret = UPDATE_NIL;
-        goto cleanup;
-    }
-
     count = ulog->kdb_last_sno - sno;
     upd = calloc(count, sizeof(kdb_incr_update_t));
     if (upd == NULL) {
diff --git a/src/lib/kdb/libkdb5.exports b/src/lib/kdb/libkdb5.exports
index 43a361d0c4..7f83ed2a9e 100644
--- a/src/lib/kdb/libkdb5.exports
+++ b/src/lib/kdb/libkdb5.exports
@@ -85,6 +85,7 @@ krb5_db_delete_policy
 krb5_db_free_policy
 krb5_def_store_mkey_list
 krb5_db_promote
+ulog_init_header
 ulog_map
 ulog_set_role
 ulog_free_entries
diff --git a/src/slave/kpropd.c b/src/slave/kpropd.c
index 627230232a..e0a8031b0e 100644
--- a/src/slave/kpropd.c
+++ b/src/slave/kpropd.c
@@ -834,6 +834,8 @@ reinit:
             now = time(NULL);
             if (frrequested &&
                 (now - frrequested) < params.iprop_resync_timeout) {
+                if (debug)
+                    fprintf(stderr, _("Still waiting for full resync\n"));
                 break;
             } else {
                 frrequested = now;
diff --git a/src/slave/kproplog.c b/src/slave/kproplog.c
index c6f244bbb3..fc4c559e47 100644
--- a/src/slave/kproplog.c
+++ b/src/slave/kproplog.c
@@ -566,17 +566,7 @@ main(int argc, char **argv)
     }
 
     if (reset) {
-        ulog->kdb_hmagic = KDB_ULOG_HDR_MAGIC;
-        ulog->db_version_num = KDB_VERSION;
-        ulog->kdb_state = KDB_STABLE;
-        ulog->kdb_block = ULOG_BLOCK;
-        ulog->kdb_first_sno = 0;
-        ulog->kdb_first_time.seconds = 0;
-        ulog->kdb_first_time.useconds = 0;
-        ulog->kdb_last_sno = 0;
-        ulog->kdb_last_time.seconds = 0;
-        ulog->kdb_last_time.useconds = 0;
-        ulog_sync_header(ulog);
+        ulog_init_header(context);
         printf(_("Reinitialized the ulog.\n"));
         exit(0);
     }
diff --git a/src/tests/t_iprop.py b/src/tests/t_iprop.py
index df97b9224c..08d3872b34 100644
--- a/src/tests/t_iprop.py
+++ b/src/tests/t_iprop.py
@@ -32,6 +32,8 @@ def wait_for_prop(kpropd, full_expected):
             kpropd.send_signal(signal.SIGUSR1)
 
         # Detect some failure conditions.
+        if 'Still waiting for full resync' in line:
+            fail('kadmind gave consecutive full resyncs')
         if 'Rejected connection' in line:
             fail('kpropd rejected kprop connection')
         if 'get updates failed' in line:
@@ -156,16 +158,12 @@ realm.run([kproplog, '-R'])
 out = realm.run([kproplog, '-h'])
 if 'Last serial # : None' not in out:
     fail('Reset of update log on master failed')
-realm.run_kadminl('modprinc -allow_tix w')
-out = realm.run([kproplog, '-h'])
-if 'Last serial # : 1' not in out:
-    fail('Update log on master has incorrect last serial number')
 
 # Get and check a full resync.
 kpropd.send_signal(signal.SIGUSR1)
 wait_for_prop(kpropd, True)
 out = realm.run([kproplog, '-h'], slave)
-if 'Last serial # : 1' not in out:
+if 'Last serial # : None' not in out:
     fail('Update log on slave has incorrect last serial number')
 
 success('iprop tests')