tdb2: clean up logging

Logged errors should always set tdb->ecode before they are called, and
there's little reason to have a sprintf-style logging function since
we can do the formatting internally.

Change the tdb_log attribute to just take a "const char *", and create
a new tdb_logerr() helper which sets ecode and calls it.  As a bonus,
mark it COLD so the compiler can optimize appropriately knowing that
it's unlikely to be invoked.

ccan/tdb2/free.c

@@ -118,8 +118,8 @@ static int remove_from_list(struct tdb_context *tdb,
 
 #ifdef DEBUG
 	if (tdb_read_off(tdb, off) != r_off) {
-		tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-			 "remove_from_list: %llu bad prev in list %llu\n",
+		tdb_logerr(tdb, TDB_ERR_CORRUPT, TDB_DEBUG_FATAL,
+			 "remove_from_list: %llu bad prev in list %llu",
 			 (long long)r_off, (long long)b_off);
 		return -1;
 	}
@@ -136,9 +136,9 @@ static int remove_from_list(struct tdb_context *tdb,
 
 #ifdef DEBUG
 		if (tdb_read_off(tdb, off) & TDB_OFF_MASK != r_off) {
-			tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-				 "remove_from_list: %llu bad list %llu\n",
-				 (long long)r_off, (long long)b_off);
+			tdb_logerr(tdb, TDB_ERR_CORRUPT, TDB_DEBUG_FATAL,
+				   "remove_from_list: %llu bad list %llu",
+				   (long long)r_off, (long long)b_off);
 			return -1;
 		}
 #endif
@@ -176,9 +176,10 @@ static int enqueue_in_free(struct tdb_context *tdb,
 				 new.next + offsetof(struct tdb_free_record,
 						     magic_and_prev))
 		    != magic) {
-			tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-				 "enqueue_in_free: %llu bad head prev %llu\n",
-				 (long long)new.next, (long long)b_off);
+			tdb_logerr(tdb, TDB_ERR_CORRUPT, TDB_DEBUG_FATAL,
+				   "enqueue_in_free: %llu bad head"
+				   " prev %llu",
+				   (long long)new.next, (long long)b_off);
 			return -1;
 		}
 #endif
@@ -331,10 +332,9 @@ static int coalesce(struct tdb_context *tdb,
 		goto err;
 
 	if (frec_len(&rec) != data_len) {
-		tdb->ecode = TDB_ERR_CORRUPT;
-		tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-			 "coalesce: expected data len %llu not %llu\n",
-			 (long long)data_len, (long long)frec_len(&rec));
+		tdb_logerr(tdb, TDB_ERR_CORRUPT, TDB_DEBUG_FATAL,
+			   "coalesce: expected data len %zu not %zu",
+			   (size_t)data_len, (size_t)frec_len(&rec));
 		goto err;
 	}
 
@@ -412,8 +412,8 @@ again:
 
 		if (frec_magic(r) != TDB_FREE_MAGIC) {
 			tdb_access_release(tdb, r);
-			tdb->log(tdb, TDB_DEBUG_ERROR, tdb->log_priv,
-				 "lock_and_alloc: %llu non-free 0x%llx\n",
+			tdb_logerr(tdb, TDB_ERR_CORRUPT, TDB_DEBUG_FATAL,
+				 "lock_and_alloc: %llu non-free 0x%llx",
 				 (long long)off, (long long)r->magic_and_prev);
 			goto unlock_err;
 		}
@@ -566,9 +566,8 @@ int set_used_header(struct tdb_context *tdb,
 	if (rec_key_length(rec) != keylen
 	    || rec_data_length(rec) != datalen
 	    || rec_extra_padding(rec) != actuallen - (keylen + datalen)) {
-		tdb->ecode = TDB_ERR_IO;
-		tdb->log(tdb, TDB_DEBUG_ERROR, tdb->log_priv,
-			 "Could not encode k=%llu,d=%llu,a=%llu\n",
+		tdb_logerr(tdb, TDB_ERR_IO, TDB_DEBUG_ERROR,
+			 "Could not encode k=%llu,d=%llu,a=%llu",
 			 (long long)keylen, (long long)datalen,
 			 (long long)actuallen);
 		return -1;
@@ -588,8 +587,8 @@ static int tdb_expand(struct tdb_context *tdb, tdb_len_t size)
 	/* Need to hold a hash lock to expand DB: transactions rely on it. */
 	if (!(tdb->flags & TDB_NOLOCK)
 	    && !tdb->allrecord_lock.count && !tdb_has_hash_locks(tdb)) {
-		tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-			 "tdb_expand: must hold lock during expand\n");
+		tdb_logerr(tdb, TDB_ERR_LOCK, TDB_DEBUG_ERROR,
+			   "tdb_expand: must hold lock during expand");
 		return -1;
 	}
 

ccan/tdb2/hash.c

@@ -561,10 +561,11 @@ int next_in_hash(struct tdb_context *tdb, int ltype,
 				return -1;
 			}
 			if (rec_magic(&rec) != TDB_MAGIC) {
-				tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-					 "next_in_hash:"
-					 " corrupt record at %llu\n",
-					 (long long)off);
+				tdb_logerr(tdb, TDB_ERR_CORRUPT,
+					   TDB_DEBUG_FATAL,
+					   "next_in_hash:"
+					   " corrupt record at %llu",
+					   (long long)off);
 				return -1;
 			}
 

ccan/tdb2/io.c

@@ -56,9 +56,9 @@ void tdb_mmap(struct tdb_context *tdb)
 	 */
 	if (tdb->map_ptr == MAP_FAILED) {
 		tdb->map_ptr = NULL;
-		tdb->log(tdb, TDB_DEBUG_WARNING, tdb->log_priv,
-			 "tdb_mmap failed for size %lld (%s)\n", 
-			 (long long)tdb->map_size, strerror(errno));
+		tdb_logerr(tdb, TDB_SUCCESS, TDB_DEBUG_WARNING,
+			   "tdb_mmap failed for size %lld (%s)",
+			   (long long)tdb->map_size, strerror(errno));
 	}
 }
 
@@ -70,7 +70,6 @@ void tdb_mmap(struct tdb_context *tdb)
 static int tdb_oob(struct tdb_context *tdb, tdb_off_t len, bool probe)
 {
 	struct stat st;
-	int ret;
 
 	/* We can't hold pointers during this: we could unmap! */
 	assert(!tdb->direct_access
@@ -81,11 +80,9 @@ static int tdb_oob(struct tdb_context *tdb, tdb_off_t len, bool probe)
 		return 0;
 	if (tdb->flags & TDB_INTERNAL) {
 		if (!probe) {
-			/* Ensure ecode is set for log fn. */
-			tdb->ecode = TDB_ERR_IO;
-			tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
+			tdb_logerr(tdb, TDB_ERR_IO, TDB_DEBUG_FATAL,
 				 "tdb_oob len %lld beyond internal"
-				 " malloc size %lld\n",
+				 " malloc size %lld",
 				 (long long)len,
 				 (long long)tdb->map_size);
 		}
@@ -95,22 +92,20 @@ static int tdb_oob(struct tdb_context *tdb, tdb_off_t len, bool probe)
 	if (tdb_lock_expand(tdb, F_RDLCK) != 0)
 		return -1;
 
-	ret = fstat(tdb->fd, &st);
-
-	tdb_unlock_expand(tdb, F_RDLCK);
-
-	if (ret == -1) {
-		tdb->ecode = TDB_ERR_IO;
+	if (fstat(tdb->fd, &st) != 0) {
+		tdb_logerr(tdb, TDB_ERR_IO, TDB_DEBUG_FATAL,
+			   "Failed to fstat file: %s", strerror(errno));
+		tdb_unlock_expand(tdb, F_RDLCK);
 		return -1;
 	}
 
+	tdb_unlock_expand(tdb, F_RDLCK);
+
 	if (st.st_size < (size_t)len) {
 		if (!probe) {
-			/* Ensure ecode is set for log fn. */
-			tdb->ecode = TDB_ERR_IO;
-			tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-				 "tdb_oob len %lld beyond eof at %lld\n",
-				 (long long)len, (long long)st.st_size);
+			tdb_logerr(tdb, TDB_ERR_IO, TDB_DEBUG_FATAL,
+				   "tdb_oob len %zu beyond eof at %zu",
+				   (size_t)len, st.st_size);
 		}
 		return -1;
 	}
@@ -180,11 +175,7 @@ int zero_out(struct tdb_context *tdb, tdb_off_t off, tdb_len_t len)
 	char buf[8192] = { 0 };
 	void *p = tdb->methods->direct(tdb, off, len);
 
-	if (tdb->read_only) {
-		tdb->ecode = TDB_ERR_RDONLY;
-		return -1;
-	}
-
+	assert(!tdb->read_only);
 	if (p) {
 		memset(p, 0, len);
 		return 0;
@@ -275,15 +266,17 @@ bool tdb_read_all(int fd, void *buf, size_t len)
 static int tdb_write(struct tdb_context *tdb, tdb_off_t off, 
 		     const void *buf, tdb_len_t len)
 {
-	if (len == 0) {
-		return 0;
-	}
-
 	if (tdb->read_only) {
-		tdb->ecode = TDB_ERR_RDONLY;
+		tdb_logerr(tdb, TDB_ERR_RDONLY, TDB_DEBUG_WARNING,
+			   "Write to read-only database");
 		return -1;
 	}
 
+	/* FIXME: Bogus optimization? */
+	if (len == 0) {
+		return 0;
+	}
+
 	if (tdb->methods->oob(tdb, off + len, 0) != 0)
 		return -1;
 
@@ -291,11 +284,9 @@ static int tdb_write(struct tdb_context *tdb, tdb_off_t off,
 		memcpy(off + (char *)tdb->map_ptr, buf, len);
 	} else {
 		if (!tdb_pwrite_all(tdb->fd, buf, len, off)) {
-			tdb->ecode = TDB_ERR_IO;
-			tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-				 "tdb_write failed at %llu len=%llu (%s)\n",
-				 (long long)off, (long long)len,
-				 strerror(errno));
+			tdb_logerr(tdb, TDB_ERR_IO, TDB_DEBUG_FATAL,
+				   "tdb_write failed at %zu len=%zu (%s)",
+				   (size_t)off, (size_t)len, strerror(errno));
 			return -1;
 		}
 	}
@@ -314,14 +305,12 @@ static int tdb_read(struct tdb_context *tdb, tdb_off_t off, void *buf,
 		memcpy(buf, off + (char *)tdb->map_ptr, len);
 	} else {
 		if (!tdb_pread_all(tdb->fd, buf, len, off)) {
-			/* Ensure ecode is set for log fn. */
-			tdb->ecode = TDB_ERR_IO;
-			tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-				 "tdb_read failed at %lld "
-				 "len=%lld (%s) map_size=%lld\n",
-				 (long long)off, (long long)len,
+			tdb_logerr(tdb, TDB_ERR_IO, TDB_DEBUG_FATAL,
+				   "tdb_read failed at %zu "
+				   "len=%zu (%s) map_size=%zu",
+				 (size_t)off, (size_t)len,
 				 strerror(errno),
-				 (long long)tdb->map_size);
+				 (size_t)tdb->map_size);
 			return -1;
 		}
 	}
@@ -335,10 +324,9 @@ int tdb_write_convert(struct tdb_context *tdb, tdb_off_t off,
 	if (unlikely((tdb->flags & TDB_CONVERT))) {
 		void *conv = malloc(len);
 		if (!conv) {
-			tdb->ecode = TDB_ERR_OOM;
-			tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-				 "tdb_write: no memory converting %zu bytes\n",
-				 len);
+			tdb_logerr(tdb, TDB_ERR_OOM, TDB_DEBUG_FATAL,
+				   "tdb_write: no memory converting"
+				   " %zu bytes", len);
 			return -1;
 		}
 		memcpy(conv, rec, len);
@@ -362,7 +350,8 @@ int tdb_read_convert(struct tdb_context *tdb, tdb_off_t off,
 int tdb_write_off(struct tdb_context *tdb, tdb_off_t off, tdb_off_t val)
 {
 	if (tdb->read_only) {
-		tdb->ecode = TDB_ERR_RDONLY;
+		tdb_logerr(tdb, TDB_ERR_RDONLY, TDB_DEBUG_WARNING,
+			   "Write to read-only database");
 		return -1;
 	}
 
@@ -383,12 +372,12 @@ static void *_tdb_alloc_read(struct tdb_context *tdb, tdb_off_t offset,
 
 	/* some systems don't like zero length malloc */
 	buf = malloc(prefix + len ? prefix + len : 1);
-	if (unlikely(!buf)) {
-		tdb->ecode = TDB_ERR_OOM;
-		tdb->log(tdb, TDB_DEBUG_ERROR, tdb->log_priv,
-			 "tdb_alloc_read malloc failed len=%lld\n",
-			 (long long)prefix + len);
-	} else if (unlikely(tdb->methods->read(tdb, offset, buf+prefix, len))) {
+	if (!buf) {
+		tdb_logerr(tdb, TDB_ERR_OOM, TDB_DEBUG_ERROR,
+			   "tdb_alloc_read malloc failed len=%zu",
+			   (size_t)(prefix + len));
+	} else if (unlikely(tdb->methods->read(tdb, offset, buf+prefix,
+					       len) == -1)) {
 		free(buf);
 		buf = NULL;
 	}
@@ -409,9 +398,8 @@ static int fill(struct tdb_context *tdb,
 		size_t n = len > size ? size : len;
 
 		if (!tdb_pwrite_all(tdb->fd, buf, n, off)) {
-			tdb->ecode = TDB_ERR_IO;
-			tdb->log(tdb, TDB_DEBUG_FATAL, tdb->log_priv,
-				 "fill write failed: giving up!\n");
+			tdb_logerr(tdb, TDB_ERR_IO, TDB_DEBUG_FATAL,
+				 "fill write failed: giving up!");
 			return -1;
 		}
 		len -= n;
@@ -427,14 +415,16 @@ static int tdb_expand_file(struct tdb_context *tdb, tdb_len_t addition)
 	char buf[8192];
 
 	if (tdb->read_only) {
-		tdb->ecode = TDB_ERR_RDONLY;
+		tdb_logerr(tdb, TDB_ERR_RDONLY, TDB_DEBUG_WARNING,
+			   "Expand on read-only database");
 		return -1;
 	}
 
 	if (tdb->flags & TDB_INTERNAL) {
 		char *new = realloc(tdb->map_ptr, tdb->map_size + addition);
 		if (!new) {
-			tdb->ecode = TDB_ERR_OOM;
+			tdb_logerr(tdb, TDB_ERR_OOM, TDB_DEBUG_FATAL,
+				   "No memory to expand database");
 			return -1;
 		}
 		tdb->map_ptr = new;
@@ -495,7 +485,8 @@ void *tdb_access_write(struct tdb_context *tdb,
 	void *ret = NULL;
 
 	if (tdb->read_only) {
-		tdb->ecode = TDB_ERR_RDONLY;
+		tdb_logerr(tdb, TDB_ERR_RDONLY, TDB_DEBUG_WARNING,
+			   "Write to read-only database");
 		return NULL;
 	}
 

ccan/tdb2/private.h

@@ -36,6 +36,7 @@
 #include "config.h"
 #include <ccan/tdb2/tdb2.h>
 #include <ccan/likely/likely.h>
+#include <ccan/compiler/compiler.h>
 #ifdef HAVE_BYTESWAP_H
 #include <byteswap.h>
 #endif
@@ -308,8 +309,8 @@ struct tdb_context {
 	uint32_t flags;
 
 	/* Logging function */
-	tdb_logfn_t log;
-	void *log_priv;
+	tdb_logfn_t logfn;
+	void *log_private;
 
 	/* Hash function. */
 	tdb_hashfn_t khash;
@@ -328,7 +329,7 @@ struct tdb_context {
 
 	/* Lock information */
 	struct tdb_lock_type allrecord_lock;
-	uint64_t num_lockrecs;
+	size_t num_lockrecs;
 	struct tdb_lock_type *lockrecs;
 
 	struct tdb_attribute_stats *stats;
@@ -529,6 +530,12 @@ int next_in_hash(struct tdb_context *tdb, int ltype,
 int tdb_transaction_recover(struct tdb_context *tdb);
 bool tdb_needs_recovery(struct tdb_context *tdb);
 
+/* tdb.c: */
+void COLD tdb_logerr(struct tdb_context *tdb,
+		     enum TDB_ERROR ecode,
+		     enum tdb_debug_level level,
+		     const char *fmt, ...);
+
 #ifdef TDB_TRACE
 void tdb_trace(struct tdb_context *tdb, const char *op);
 void tdb_trace_seqnum(struct tdb_context *tdb, uint32_t seqnum, const char *op);

ccan/tdb2/summary.c

@@ -164,7 +164,8 @@ char *tdb_summary(struct tdb_context *tdb, enum tdb_summary_flags flags)
 	buckets = tally_new(HISTO_HEIGHT);
 	if (!flists || !hashes || !freet || !keys || !data || !extra
 	    || !uncoal || !buckets) {
-		tdb->ecode = TDB_ERR_OOM;
+		tdb_logerr(tdb, TDB_ERR_OOM, TDB_DEBUG_ERROR,
+			   "tdb_summary: failed to allocate tally structures");
 		goto unlock;
 	}
 

ccan/tdb2/tdb2.h

@@ -67,7 +67,7 @@ enum TDB_ERROR {TDB_SUCCESS=0, TDB_ERR_CORRUPT, TDB_ERR_IO, TDB_ERR_LOCK,
 /* flags for tdb_summary. Logical or to combine. */
 enum tdb_summary_flags { TDB_SUMMARY_HISTOGRAMS = 1 };
 
-/* debugging uses one of the following levels */
+/* logging uses one of the following levels */
 enum tdb_debug_level {TDB_DEBUG_FATAL = 0, TDB_DEBUG_ERROR, 
 		      TDB_DEBUG_WARNING, TDB_DEBUG_TRACE};
 
@@ -80,7 +80,7 @@ struct tdb_context;
 
 /* FIXME: Make typesafe */
 typedef int (*tdb_traverse_func)(struct tdb_context *, TDB_DATA, TDB_DATA, void *);
-typedef void (*tdb_logfn_t)(struct tdb_context *, enum tdb_debug_level, void *priv, const char *, ...) PRINTF_FMT(4, 5);
+typedef void (*tdb_logfn_t)(struct tdb_context *, enum tdb_debug_level, void *, const char *);
 typedef uint64_t (*tdb_hashfn_t)(const void *key, size_t len, uint64_t seed,
 				 void *priv);
 
@@ -161,8 +161,8 @@ int tdb_check(struct tdb_context *tdb,
 	      int (*check)(TDB_DATA key, TDB_DATA data, void *private_data),
 	      void *private_data);
 
-enum TDB_ERROR tdb_error(struct tdb_context *tdb);
-const char *tdb_errorstr(struct tdb_context *tdb);
+enum TDB_ERROR tdb_error(const struct tdb_context *tdb);
+const char *tdb_errorstr(const struct tdb_context *tdb);
 
 int tdb_transaction_start(struct tdb_context *tdb);
 void tdb_transaction_cancel(struct tdb_context *tdb);

ccan/tdb2/test/logging.c

-#define _GNU_SOURCE
 #include <stdio.h>
 #include <stdlib.h>
-#include <stdarg.h>
 #include <ccan/tap/tap.h>
 #include "logging.h"
 
@@ -16,24 +14,13 @@ union tdb_attribute tap_log_attr = {
 
 void tap_log_fn(struct tdb_context *tdb,
 		enum tdb_debug_level level, void *priv,
-		const char *fmt, ...)
+		const char *message)
 {
-	va_list ap;
-	char *p;
-
 	if (suppress_logging)
 		return;
 
-	va_start(ap, fmt);
-	if (vasprintf(&p, fmt, ap) == -1)
-		abort();
-	/* Strip trailing \n: diag adds it. */
-	if (p[strlen(p)-1] == '\n')
-		p[strlen(p)-1] = '\0';
-	diag("tdb log level %u: %s%s", level, log_prefix, p);
-	free(p);
+	diag("tdb log level %u: %s%s", level, log_prefix, message);
 	if (level != TDB_DEBUG_TRACE)
 		tap_log_messages++;
-	va_end(ap);
 }
 

ccan/tdb2/test/logging.h

@@ -11,7 +11,7 @@ extern union tdb_attribute tap_log_attr;
 
 void tap_log_fn(struct tdb_context *tdb,
 		enum tdb_debug_level level, void *priv,
-		const char *fmt, ...);
+		const char *message);
 
 static inline bool data_equal(struct tdb_data a, struct tdb_data b)
 {

ccan/tdb2/test/run-001-encode.c

@@ -12,7 +12,7 @@ int main(int argc, char *argv[])
 {
 	unsigned int i;
 	struct tdb_used_record rec;
-	struct tdb_context tdb = { .log = tap_log_fn, .log_priv = NULL };
+	struct tdb_context tdb = { .logfn = tap_log_fn };
 
 	plan_tests(64 + 32 + 48*6 + 1);
 

ccan/tdb2/test/run-seed.c

@@ -13,7 +13,7 @@ static int log_count = 0;
 /* Normally we get a log when setting random seed. */
 static void my_log_fn(struct tdb_context *tdb,
 		      enum tdb_debug_level level, void *priv,
-		      const char *fmt, ...)
+		      const char *message)
 {
 	log_count++;
 }

ccan/tdb2/test/run-traverse.c

@@ -120,7 +120,7 @@ int main(int argc, char *argv[])
 
 	hattr.base.next = &tap_log_attr;
 
-	plan_tests(sizeof(flags) / sizeof(flags[0]) * 50 + 1);
+	plan_tests(sizeof(flags) / sizeof(flags[0]) * 53 + 1);
 	for (i = 0; i < sizeof(flags) / sizeof(flags[0]); i++) {
 		tdb = tdb_open("run-traverse.tdb", flags[i],
 			       O_RDWR|O_CREAT|O_TRUNC, 0600, &hattr);
@@ -182,6 +182,7 @@ int main(int argc, char *argv[])
 		ok1(td.low <= NUM_RECORDS / 2);
 		ok1(td.high > NUM_RECORDS / 2);
 		ok1(tdb_check(tdb, NULL, NULL) == 0);
+		ok1(tap_log_messages == 0);
 
 		/* Growing traverse.  Expect failure on r/o traverse. */
 		tgd.calls = 0;
@@ -193,6 +194,8 @@ int main(int argc, char *argv[])
 		ok1(tgd.error == TDB_ERR_RDONLY);
 		ok1(tgd.calls == 1);
 		ok1(!tgd.mismatch);
+		ok1(tap_log_messages == 1);
+		tap_log_messages = 0;
 		ok1(tdb_check(tdb, NULL, NULL) == 0);
 
 		/* Deleting traverse.  Expect failure on r/o traverse. */
@@ -209,6 +212,8 @@ int main(int argc, char *argv[])
 		ok1(!td.mismatch);
 		ok1(td.calls == 1);
 		ok1(td.low == td.high);
+		ok1(tap_log_messages == 1);
+		tap_log_messages = 0;
 		ok1(tdb_check(tdb, NULL, NULL) == 0);
 
 		/* Deleting traverse (delete everything). */