Lock around more ulog operations

Always lock the ulog when accessing it.  We can currently get away
with some laxness on iprop slaves because they are mostly synchronous,
but hierarchical iprop will allow master and slave operations to take
place concurrently, requiring more strict locking.

Add new functions ulog_get_last and ulog_set_last, which access the
ulog header with locking, and use them in kdb5_util and kpropd.  Add
locking to ulog_replay and ulog_init_header.

ulog_lock and ulog_sync_header are no longer used outside of kdb_log.c
after these changes, so make them static functions and remove the
ulog_ prefix.  Add an unlock_ulog function for clarity.

8 files changed, 150 insertions, 67 deletions

diff --git a/src/include/kdb_log.h b/src/include/kdb_log.h
index 35b9d55655..7f35eb7c86 100644
--- a/src/include/kdb_log.h
+++ b/src/include/kdb_log.h
@@ -69,7 +69,7 @@ extern "C" {
  */
 krb5_error_code ulog_map(krb5_context context, const char *logname,
                          uint32_t entries, int caller, char **db_args);
-void ulog_init_header(krb5_context context);
+krb5_error_code ulog_init_header(krb5_context context);
 krb5_error_code ulog_add_update(krb5_context context, kdb_incr_update_t *upd);
 krb5_error_code ulog_get_entries(krb5_context context, const kdb_last_t *last,
                                  kdb_incr_result_t *ulog_handle);
@@ -81,9 +81,10 @@ krb5_error_code ulog_conv_2dbentry(krb5_context context, krb5_db_entry **entry,
                                    kdb_incr_update_t *update);
 void ulog_free_entries(kdb_incr_update_t *updates, int no_of_updates);
 krb5_error_code ulog_set_role(krb5_context ctx, iprop_role role);
-krb5_error_code ulog_lock(krb5_context ctx, int mode);
 update_status_t ulog_get_sno_status(krb5_context context,
                                     const kdb_last_t *last);
+krb5_error_code ulog_get_last(krb5_context context, kdb_last_t *last_out);
+krb5_error_code ulog_set_last(krb5_context context, const kdb_last_t *last);
 
 typedef struct kdb_hlog {
     uint32_t        kdb_hmagic;     /* Log header magic # */
@@ -97,8 +98,6 @@ typedef struct kdb_hlog {
     uint16_t        kdb_block;      /* Block size of each element */
 } kdb_hlog_t;
 
-void ulog_sync_header(kdb_hlog_t *);
-
 typedef struct kdb_ent_header {
     uint32_t        kdb_umagic;     /* Update entry magic # */
     kdb_sno_t       kdb_entry_sno;  /* Serial # of entry */
diff --git a/src/kadmin/dbutil/dump.c b/src/kadmin/dbutil/dump.c
index a94fb31303..def1d6a6ba 100644
--- a/src/kadmin/dbutil/dump.c
+++ b/src/kadmin/dbutil/dump.c
@@ -1231,6 +1231,7 @@ dump_db(int argc, char **argv)
     unsigned int ipropx_version = IPROPX_VERSION_0;
     krb5_kvno kt_kvno;
     krb5_boolean conditional = FALSE;
+    kdb_last_t last;
 
     /* Parse the arguments. */
     dump = &r1_11_version;
@@ -1404,11 +1405,16 @@ dump_db(int argc, char **argv)
     }
 
     if (dump_sno) {
+        ret = ulog_get_last(util_context, &last);
+        if (ret) {
+            com_err(progname, ret, _("while reading update log header"));
+            goto error;
+        }
         if (ipropx_version)
             fprintf(f, " %u", IPROPX_VERSION);
-        fprintf(f, " %u", log_ctx->ulog->kdb_last_sno);
-        fprintf(f, " %u", log_ctx->ulog->kdb_last_time.seconds);
-        fprintf(f, " %u", log_ctx->ulog->kdb_last_time.useconds);
+        fprintf(f, " %u", last.last_sno);
+        fprintf(f, " %u", last.last_time.seconds);
+        fprintf(f, " %u", last.last_time.useconds);
     }
 
     if (dump->header[strlen(dump->header)-1] != '\n')
@@ -1639,8 +1645,13 @@ load_db(int argc, char **argv)
     if (!update) {
         /* Initialize the ulog header before promoting so we can't leave behind
          * the pre-load ulog state if we are killed just after promoting. */
-        if (log_ctx != NULL && log_ctx->iproprole)
-            ulog_init_header(util_context);
+        if (log_ctx != NULL && log_ctx->iproprole) {
+            ret = ulog_init_header(util_context);
+            if (ret) {
+                com_err(progname, ret, _("while reinitializing update log"));
+                goto error;
+            }
+        }
 
         ret = krb5_db_promote(util_context, db5util_db_args);
         /* Ignore a not supported error since there is nothing to do about it
@@ -1654,11 +1665,18 @@ load_db(int argc, char **argv)
         if (log_ctx != NULL && log_ctx->iproprole) {
             /* Reinitialize the ulog header since we replaced the DB, and
              * record the iprop state if we received it. */
-            ulog_init_header(util_context);
+            ret = ulog_init_header(util_context);
+            if (ret) {
+                com_err(progname, ret, _("while reinitializing update log"));
+                goto error;
+            }
             if (iprop_load) {
-                log_ctx->ulog->kdb_last_sno = last.last_sno;
-                log_ctx->ulog->kdb_last_time = last.last_time;
-                ulog_sync_header(log_ctx->ulog);
+                ret = ulog_set_last(util_context, &last);
+                if (ret) {
+                    com_err(progname, ret,
+                            _("while writing update log header"));
+                    goto error;
+                }
             }
         }
     }
diff --git a/src/kadmin/dbutil/kdb5_create.c b/src/kadmin/dbutil/kdb5_create.c
index 31b3c6efb0..f6df9923e4 100644
--- a/src/kadmin/dbutil/kdb5_create.c
+++ b/src/kadmin/dbutil/kdb5_create.c
@@ -300,7 +300,12 @@ void kdb5_create(argc, argv)
          * We're reinitializing the update log in case one already
          * existed, but this should never happen.
          */
-        ulog_init_header(util_context);
+        retval = ulog_init_header(util_context);
+        if (retval) {
+            com_err(argv[0], retval, _("while initializing update log"));
+            exit_status++;
+            return;
+        }
 
         /*
          * Since we're creating a new db we shouldn't worry about
diff --git a/src/lib/kdb/kdb5.c b/src/lib/kdb/kdb5.c
index b35d9ca5b7..8233a48ccc 100644
--- a/src/lib/kdb/kdb5.c
+++ b/src/lib/kdb/kdb5.c
@@ -2266,7 +2266,7 @@ krb5_db_create_policy(krb5_context kcontext, osa_policy_ent_t policy)
     status = v->create_policy(kcontext, policy);
     /* iprop does not support policy mods; force full resync. */
     if (!status && logging(kcontext))
-        ulog_init_header(kcontext);
+        status = ulog_init_header(kcontext);
     return status;
 }
 
@@ -2299,7 +2299,7 @@ krb5_db_put_policy(krb5_context kcontext, osa_policy_ent_t policy)
     status = v->put_policy(kcontext, policy);
     /* iprop does not support policy mods; force full resync. */
     if (!status && logging(kcontext))
-        ulog_init_header(kcontext);
+        status = ulog_init_header(kcontext);
     return status;
 }
 
@@ -2333,7 +2333,7 @@ krb5_db_delete_policy(krb5_context kcontext, char *policy)
     status = v->delete_policy(kcontext, policy);
     /* iprop does not support policy mods; force full resync. */
     if (!status && logging(kcontext))
-        ulog_init_header(kcontext);
+        status = ulog_init_header(kcontext);
     return status;
 }
 
diff --git a/src/lib/kdb/kdb_log.c b/src/lib/kdb/kdb_log.c
index dcc1bcf447..378a497a31 100644
--- a/src/lib/kdb/kdb_log.c
+++ b/src/lib/kdb/kdb_log.c
@@ -72,15 +72,15 @@ sync_update(kdb_hlog_t *ulog, kdb_ent_header_t *upd)
 }
 
 /* Sync memory to disk for the update log header. */
-void
-ulog_sync_header(kdb_hlog_t *ulog)
+static void
+sync_header(kdb_hlog_t *ulog)
 {
     if (!pagesize)
         pagesize = getpagesize();
 
     if (msync((caddr_t)ulog, pagesize, MS_SYNC)) {
         /* Couldn't sync to disk, let's panic. */
-        syslog(LOG_ERR, _("ulog_sync_header: could not sync to disk"));
+        syslog(LOG_ERR, _("could not sync ulog header to disk"));
         abort();
     }
 }
@@ -190,7 +190,7 @@ resize(kdb_hlog_t *ulog, uint32_t ulogentries, int ulogfd,
     ulog->db_version_num = KDB_VERSION;
     ulog->kdb_state = KDB_STABLE;
     ulog->kdb_block = new_block;
-    ulog_sync_header(ulog);
+    sync_header(ulog);
 
     /* Expand log considering new block size. */
     if (extend_file_to(ulogfd, new_size) < 0)
@@ -210,19 +210,25 @@ reset_header(kdb_hlog_t *ulog)
     time_current(&ulog->kdb_last_time);
 }
 
-krb5_error_code
-ulog_lock(krb5_context ctx, int mode)
+/*
+ * If any database operations will be invoked while the ulog lock is held, the
+ * caller must explicitly lock the database before locking the ulog, or
+ * deadlock may result.
+ */
+static krb5_error_code
+lock_ulog(krb5_context context, int mode)
 {
     kdb_log_context *log_ctx = NULL;
     kdb_hlog_t *ulog = NULL;
 
-    if (ctx == NULL)
-        return KRB5_LOG_ERROR;
-    if (ctx->kdblog_context == NULL ||
-        ctx->kdblog_context->iproprole == IPROP_NULL)
-        return 0;
-    INIT_ULOG(ctx);
-    return krb5_lock_file(ctx, log_ctx->ulogfd, mode);
+    INIT_ULOG(context);
+    return krb5_lock_file(context, log_ctx->ulogfd, mode);
+}
+
+static void
+unlock_ulog(krb5_context context)
+{
+    (void)lock_ulog(context, KRB5_LOCKMODE_UNLOCK);
 }
 
 /*
@@ -246,7 +252,7 @@ ulog_add_update(krb5_context context, kdb_incr_update_t *upd)
     int ulogfd;
 
     INIT_ULOG(context);
-    retval = ulog_lock(context, KRB5_LOCKMODE_EXCLUSIVE);
+    retval = lock_ulog(context, KRB5_LOCKMODE_EXCLUSIVE);
     if (retval)
         return retval;
 
@@ -317,13 +323,12 @@ ulog_add_update(krb5_context context, kdb_incr_update_t *upd)
     ulog->kdb_state = KDB_STABLE;
 
 cleanup:
-    ulog_sync_header(ulog);
-    ulog_lock(context, KRB5_LOCKMODE_UNLOCK);
+    sync_header(ulog);
+    unlock_ulog(context);
     return retval;
 }
 
-/* Used by the slave to update its hash db from* the incr update log.  Must be
- * called with lock held. */
+/* Used by the slave to update its hash db from the incr update log. */
 krb5_error_code
 ulog_replay(krb5_context context, kdb_incr_result_t *incr_ret, char **db_args)
 {
@@ -339,6 +344,20 @@ ulog_replay(krb5_context context, kdb_incr_result_t *incr_ret, char **db_args)
 
     INIT_ULOG(context);
 
+    /* Lock the DB before the ulog to avoid deadlock. */
+    retval = krb5_db_open(context, db_args,
+                          KRB5_KDB_OPEN_RW | KRB5_KDB_SRV_TYPE_ADMIN);
+    if (retval)
+        return retval;
+    retval = krb5_db_lock(context, KRB5_DB_LOCKMODE_EXCLUSIVE);
+    if (retval)
+        return retval;
+    retval = lock_ulog(context, KRB5_LOCKMODE_EXCLUSIVE);
+    if (retval) {
+        krb5_db_unlock(context);
+        return retval;
+    }
+
     no_of_updates = incr_ret->updates.kdb_ulog_t_len;
     upd = incr_ret->updates.kdb_ulog_t_val;
     fupd = upd;
@@ -350,11 +369,6 @@ ulog_replay(krb5_context context, kdb_incr_result_t *incr_ret, char **db_args)
     errlast.last_time.useconds = (unsigned int)0;
     last = &errlast;
 
-    retval = krb5_db_open(context, db_args,
-                          KRB5_KDB_OPEN_RW | KRB5_KDB_SRV_TYPE_ADMIN);
-    if (retval)
-        goto cleanup;
-
     for (i = 0; i < no_of_updates; i++) {
         if (!upd->kdb_commit)
             continue;
@@ -401,21 +415,28 @@ cleanup:
     /* Record a new last serial number and timestamp in the ulog header. */
     ulog->kdb_last_sno = last->last_sno;
     ulog->kdb_last_time = last->last_time;
-    ulog_sync_header(ulog);
-
+    sync_header(ulog);
+    unlock_ulog(context);
+    krb5_db_unlock(context);
     return retval;
 }
 
-/* Reinitialize the log header.  Locking is the caller's responsibility. */
-void
+/* Reinitialize the log header. */
+krb5_error_code
 ulog_init_header(krb5_context context)
 {
+    krb5_error_code ret;
     kdb_log_context *log_ctx;
     kdb_hlog_t *ulog;
 
     INIT_ULOG(context);
+    ret = lock_ulog(context, KRB5_LOCKMODE_EXCLUSIVE);
+    if (ret)
+        return ret;
     reset_header(ulog);
-    ulog_sync_header(ulog);
+    sync_header(ulog);
+    unlock_ulog(context);
+    return 0;
 }
 
 /*
@@ -519,26 +540,26 @@ ulog_map(krb5_context context, const char *logname, uint32_t ulogentries,
     log_ctx->ulogentries = ulogentries;
     log_ctx->ulogfd = ulogfd;
 
-    retval = ulog_lock(context, KRB5_LOCKMODE_EXCLUSIVE);
+    retval = lock_ulog(context, KRB5_LOCKMODE_EXCLUSIVE);
     if (retval)
         return retval;
 
     if (ulog->kdb_hmagic != KDB_ULOG_HDR_MAGIC && ulog->kdb_hmagic != 0) {
-        ulog_lock(context, KRB5_LOCKMODE_UNLOCK);
+        unlock_ulog(context);
         return KRB5_LOG_CORRUPT;
     }
 
     if (ulog->kdb_hmagic != KDB_ULOG_HDR_MAGIC) {
         reset_header(ulog);
         if (caller != FKPROPLOG)
-            ulog_sync_header(ulog);
-        ulog_lock(context, KRB5_LOCKMODE_UNLOCK);
+            sync_header(ulog);
+        unlock_ulog(context);
         return 0;
     }
 
     if (caller == FKPROPLOG || caller == FKPROPD) {
         /* kproplog and kpropd don't need to do anything else. */
-        ulog_lock(context, KRB5_LOCKMODE_UNLOCK);
+        unlock_ulog(context);
         return 0;
     }
 
@@ -551,7 +572,7 @@ ulog_map(krb5_context context, const char *logname, uint32_t ulogentries,
             (ulog->kdb_last_sno > ulog->kdb_num ||
              ulog->kdb_num > ulogentries)) {
             reset_header(ulog);
-            ulog_sync_header(ulog);
+            sync_header(ulog);
         }
 
         /* Expand ulog if we have specified a greater size. */
@@ -559,12 +580,12 @@ ulog_map(krb5_context context, const char *logname, uint32_t ulogentries,
             ulog_filesize += ulogentries * ulog->kdb_block;
 
             if (extend_file_to(ulogfd, ulog_filesize) < 0) {
-                ulog_lock(context, KRB5_LOCKMODE_UNLOCK);
+                unlock_ulog(context);
                 return errno;
             }
         }
     }
-    ulog_lock(context, KRB5_LOCKMODE_UNLOCK);
+    unlock_ulog(context);
 
     return 0;
 }
@@ -587,7 +608,7 @@ ulog_get_entries(krb5_context context, const kdb_last_t *last,
     INIT_ULOG(context);
     ulogentries = log_ctx->ulogentries;
 
-    retval = ulog_lock(context, KRB5_LOCKMODE_SHARED);
+    retval = lock_ulog(context, KRB5_LOCKMODE_SHARED);
     if (retval)
         return retval;
 
@@ -637,7 +658,7 @@ ulog_get_entries(krb5_context context, const kdb_last_t *last,
     ulog_handle->ret = UPDATE_OK;
 
 cleanup:
-    (void)ulog_lock(context, KRB5_LOCKMODE_UNLOCK);
+    unlock_ulog(context);
     return retval;
 }
 
@@ -658,9 +679,44 @@ ulog_get_sno_status(krb5_context context, const kdb_last_t *last)
 {
     update_status_t status;
 
-    if (ulog_lock(context, KRB5_LOCKMODE_SHARED) != 0)
+    if (lock_ulog(context, KRB5_LOCKMODE_SHARED) != 0)
         return UPDATE_ERROR;
     status = get_sno_status(context->kdblog_context, last);
-    (void)ulog_lock(context, KRB5_LOCKMODE_UNLOCK);
+    unlock_ulog(context);
     return status;
 }
+
+krb5_error_code
+ulog_get_last(krb5_context context, kdb_last_t *last_out)
+{
+    krb5_error_code ret;
+    kdb_log_context *log_ctx;
+    kdb_hlog_t *ulog;
+
+    INIT_ULOG(context);
+    ret = lock_ulog(context, KRB5_LOCKMODE_SHARED);
+    if (ret)
+        return ret;
+    last_out->last_sno = log_ctx->ulog->kdb_last_sno;
+    last_out->last_time = log_ctx->ulog->kdb_last_time;
+    unlock_ulog(context);
+    return 0;
+}
+
+krb5_error_code
+ulog_set_last(krb5_context context, const kdb_last_t *last)
+{
+    krb5_error_code ret;
+    kdb_log_context *log_ctx;
+    kdb_hlog_t *ulog;
+
+    INIT_ULOG(context);
+    ret = lock_ulog(context, KRB5_LOCKMODE_EXCLUSIVE);
+    if (ret)
+        return ret;
+    ulog->kdb_last_sno = last->last_sno;
+    ulog->kdb_last_time = last->last_time;
+    sync_header(ulog);
+    unlock_ulog(context);
+    return 0;
+}
diff --git a/src/lib/kdb/libkdb5.exports b/src/lib/kdb/libkdb5.exports
index 67d4336ef1..cb4c3df55b 100644
--- a/src/lib/kdb/libkdb5.exports
+++ b/src/lib/kdb/libkdb5.exports
@@ -90,11 +90,12 @@ ulog_init_header
 ulog_map
 ulog_set_role
 ulog_free_entries
-ulog_sync_header
 xdr_kdb_last_t
 xdr_kdb_incr_result_t
 xdr_kdb_fullresync_result_t
 ulog_get_entries
+ulog_get_last
 ulog_get_sno_status
 ulog_replay
+ulog_set_last
 xdr_kdb_incr_update_t
diff --git a/src/slave/kpropd.c b/src/slave/kpropd.c
index afeb53fa3b..65fb3e84fc 100644
--- a/src/slave/kpropd.c
+++ b/src/slave/kpropd.c
@@ -147,7 +147,7 @@ static int db_args_size = 0;
 static void parse_args(char **argv);
 static void do_standalone(void);
 static void doit(int fd);
-static krb5_error_code do_iprop(kdb_log_context *log_ctx);
+static krb5_error_code do_iprop(void);
 static void kerberos_authenticate(krb5_context context, int fd,
                                   krb5_principal *clientp, krb5_enctype *etype,
                                   struct sockaddr_storage *my_sin);
@@ -321,7 +321,7 @@ main(int argc, char **argv)
         /* NOTREACHED */
         break;
     default:
-        retval = do_iprop(log_ctx);
+        retval = do_iprop();
         /* do_iprop() can return due to failures and runonce. */
         kill(fullprop_child, SIGHUP);
         wait(NULL);
@@ -606,7 +606,7 @@ full_resync(CLIENT *clnt)
  * Returns non-zero on failure due to errors.
  */
 krb5_error_code
-do_iprop(kdb_log_context *log_ctx)
+do_iprop()
 {
     kadm5_ret_t retval;
     krb5_principal iprop_svc_principal;
@@ -621,13 +621,10 @@ do_iprop(kdb_log_context *log_ctx)
     kdb_last_t mylast;
     kdb_fullresync_result_t *full_ret;
     kadm5_iprop_handle_t handle;
-    kdb_hlog_t *ulog;
 
     if (debug)
         fprintf(stderr, _("Incremental propagation enabled\n"));
 
-    ulog = log_ctx->ulog;
-
     pollin = params.iprop_poll_time;
     if (pollin == 0)
         pollin = 10;
@@ -771,8 +768,11 @@ reinit:
          * Get the most recent ulog entry sno + ts, which
          * we package in the request to the master KDC
          */
-        mylast.last_sno = ulog->kdb_last_sno;
-        mylast.last_time = ulog->kdb_last_time;
+        retval = ulog_get_last(kpropd_context, &mylast);
+        if (retval) {
+            com_err(progname, retval, _("reading update log header"));
+            goto done;
+        }
 
         /*
          * Loop continuously on an iprop_get_updates_1(),
diff --git a/src/slave/kproplog.c b/src/slave/kproplog.c
index b051279513..853aa0633f 100644
--- a/src/slave/kproplog.c
+++ b/src/slave/kproplog.c
@@ -480,7 +480,11 @@ main(int argc, char **argv)
     }
 
     if (reset) {
-        ulog_init_header(context);
+        if (ulog_init_header(context) != 0) {
+            fprintf(stderr, _("Couldn't reinitialize ulog file %s\n\n"),
+                    params.iprop_logfile);
+            exit(1);
+        }
         printf(_("Reinitialized the ulog.\n"));
         exit(0);
     }