[PATCH v2] refs: add GIT_TRACE_REFS debugging mechanism

From: Han-Wen Nienhuys <hanwen@google.com>

When set in the environment, GIT_TRACE_REFS makes git print operations and results as they flow through the ref storage backend. This helps debug discrepancies between different ref backends.

Example:

    $ GIT_TRACE_REFS="1" ./git branch
    15:42:09.769631 refs/debug.c:26         ref_store for .git
    15:42:09.769681 refs/debug.c:249        read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0
    15:42:09.769695 refs/debug.c:249        read_raw_ref: refs/heads/ref-debug: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a (=> refs/heads/ref-debug) type 0: 0
    15:42:09.770282 refs/debug.c:233        ref_iterator_begin: refs/heads/ (0x1)
    15:42:09.770290 refs/debug.c:189        iterator_advance: refs/heads/b4 (0)
    15:42:09.770295 refs/debug.c:189        iterator_advance: refs/heads/branch3 (0)

Signed-off-by: Han-Wen Nienhuys <hanwen@google.com>
---
    refs: add GIT_TRACE_REFS debugging mechanism
    
    When set in the environment, GIT_TRACE_REFS makes git print operations
    and results as they flow through the ref storage backend. This helps
    debug discrepancies between different ref backends.
    
    Example:
    
        $ GIT_TRACE_REFS="1" ./git branch
        15:42:09.769631 refs/debug.c:26         ref_store for .git
        15:42:09.769681 refs/debug.c:249        read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0
        15:42:09.769695 refs/debug.c:249        read_raw_ref: refs/heads/ref-debug: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a (=> refs/heads/ref-debug) type 0: 0
        15:42:09.770282 refs/debug.c:233        ref_iterator_begin: refs/heads/ (0x1)
        15:42:09.770290 refs/debug.c:189        iterator_advance: refs/heads/b4 (0)
        15:42:09.770295 refs/debug.c:189        iterator_advance: refs/heads/branch3 (0)
    
    Signed-off-by: Han-Wen Nienhuys hanwen@google.com [hanwen@google.com]

Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-713%2Fhanwen%2Fdebug-refs-v2
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-713/hanwen/debug-refs-v2
Pull-Request: https://github.com/gitgitgadget/git/pull/713

Range-diff vs v1:

 1:  4d045e35be ! 1:  19330e894c RFC: refs: add GIT_DEBUG_REFS debugging mechanism
     @@ Metadata
      Author: Han-Wen Nienhuys <hanwen@google.com>
      
       ## Commit message ##
     -    RFC: refs: add GIT_DEBUG_REFS debugging mechanism
     +    refs: add GIT_TRACE_REFS debugging mechanism
      
     -    When set in the environment, GIT_DEBUG_REFS makes git print operations and
     +    When set in the environment, GIT_TRACE_REFS makes git print operations and
          results as they flow through the ref storage backend. This helps debug
          discrepancies between different ref backends.
      
     -    This should be integrated with the trace2 sub-system, and I would appreciate
     -    pointers on how to start.
     -
          Example:
      
     -        $ GIT_DEBUG_REFS=1 ./git branch
     -        ref_store for .git
     -        read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0
     -        read_raw_ref: refs/heads/ref-debug: b0728cf8cb9dfd395bea41c646f48108c99230c0 (=> refs/heads/ref-debug) type 0: 0
     -        ref_iterator_begin: refs/heads/ (0x1)
     -        iterator_advance before: refs/heads/b4
     -        iterator_advance before: refs/heads/bla
     -        ...
     +        $ GIT_TRACE_REFS="1" ./git branch
     +        15:42:09.769631 refs/debug.c:26         ref_store for .git
     +        15:42:09.769681 refs/debug.c:249        read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0
     +        15:42:09.769695 refs/debug.c:249        read_raw_ref: refs/heads/ref-debug: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a (=> refs/heads/ref-debug) type 0: 0
     +        15:42:09.770282 refs/debug.c:233        ref_iterator_begin: refs/heads/ (0x1)
     +        15:42:09.770290 refs/debug.c:189        iterator_advance: refs/heads/b4 (0)
     +        15:42:09.770295 refs/debug.c:189        iterator_advance: refs/heads/branch3 (0)
      
          Signed-off-by: Han-Wen Nienhuys <hanwen@google.com>
      
     + ## Documentation/git.txt ##
     +@@ Documentation/git.txt: of clones and fetches.
     + 	time of each Git command.
     + 	See `GIT_TRACE` for available trace output options.
     + 
     ++`GIT_TRACE_REFS`::
     ++	Enables trace messages for operations on the ref database.
     ++	See `GIT_TRACE` for available trace output options.
     ++
     + `GIT_TRACE_SETUP`::
     + 	Enables trace messages printing the .git, working tree and current
     + 	working directory after Git has completed its setup phase.
     +
       ## Makefile ##
      @@ Makefile: LIB_OBJS += rebase.o
       LIB_OBJS += ref-filter.o
     @@ refs.c: struct ref_store *get_main_ref_store(struct repository *r)
       		BUG("attempting to get main_ref_store outside of repository");
       
       	r->refs_private = ref_store_init(r->gitdir, REF_STORE_ALL_CAPS);
     -+	if (getenv("GIT_DEBUG_REFS")) {
     -+		// XXX - how to hook this up with the trace2 framework?
     -+		r->refs_private = debug_wrap(r->gitdir, r->refs_private);
     -+	}
     ++	r->refs_private = maybe_debug_wrap_ref_store(r->gitdir, r->refs_private);
       	return r->refs_private;
       }
       
     @@ refs/debug.c (new)
      @@
      +
      +#include "refs-internal.h"
     ++#include "trace.h"
     ++
     ++static struct trace_key trace_refs = TRACE_KEY_INIT(REFS);
      +
      +struct debug_ref_store {
      +	struct ref_store base;
     @@ refs/debug.c (new)
      +};
      +
      +extern struct ref_storage_be refs_be_debug;
     -+struct ref_store *debug_wrap(const char *gitdir, struct ref_store *store);
      +
     -+struct ref_store *debug_wrap(const char *gitdir, struct ref_store *store)
     ++struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store)
      +{
     -+	struct debug_ref_store *res = malloc(sizeof(struct debug_ref_store));
     -+	struct ref_storage_be *be_copy = malloc(sizeof(*be_copy));
     ++	struct debug_ref_store *res;
     ++	struct ref_storage_be *be_copy;
     ++
     ++	if (!trace_want(&trace_refs)) {
     ++		return store;
     ++	}
     ++	res = malloc(sizeof(struct debug_ref_store));
     ++	be_copy = malloc(sizeof(*be_copy));
      +	*be_copy = refs_be_debug;
      +	be_copy->name = store->be->name;
     -+	fprintf(stderr, "ref_store for %s\n", gitdir);
     ++	trace_printf_key(&trace_refs, "ref_store for %s\n", gitdir);
      +	res->refs = store;
      +	base_ref_store_init((struct ref_store *)res, be_copy);
      +	return (struct ref_store *)res;
     @@ refs/debug.c (new)
      +{
      +	struct debug_ref_store *drefs = (struct debug_ref_store *)refs;
      +	int res = drefs->refs->be->init_db(drefs->refs, err);
     -+	fprintf(stderr, "init_db: %d\n", res);
     ++	trace_printf_key(&trace_refs, "init_db: %d\n", res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +	transaction->ref_store = drefs->refs;
      +	res = drefs->refs->be->transaction_prepare(drefs->refs, transaction,
      +						   err);
     -+	fprintf(stderr, "transaction_prepare: %d\n", res);
     ++	trace_printf_key(&trace_refs, "transaction_prepare: %d\n", res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +
      +	type &= 0xf; /* see refs.h REF_* */
      +	flags &= REF_HAVE_NEW | REF_HAVE_OLD | REF_NO_DEREF |
     -+		REF_FORCE_CREATE_REFLOG; // XXX: LOG_ONLY
     -+	fprintf(stderr, "%d: %s %s -> %s (F=0x%x, T=0x%x) \"%s\"\n", i, refname,
     ++		REF_FORCE_CREATE_REFLOG;
     ++	trace_printf_key(&trace_refs, "%d: %s %s -> %s (F=0x%x, T=0x%x) \"%s\"\n", i, refname,
      +		o, n, flags, type, msg);
      +}
      +
      +static void print_transaction(struct ref_transaction *transaction)
      +{
     -+	fprintf(stderr, "transaction {\n");
     ++	trace_printf_key(&trace_refs, "transaction {\n");
      +	for (int i = 0; i < transaction->nr; i++) {
      +		struct ref_update *u = transaction->updates[i];
      +		print_update(i, u->refname, &u->old_oid, &u->new_oid, u->flags,
      +			     u->type, u->msg);
      +	}
     -+	fprintf(stderr, "}\n");
     ++	trace_printf_key(&trace_refs, "}\n");
      +}
      +
      +static int debug_transaction_finish(struct ref_store *refs,
     @@ refs/debug.c (new)
      +	res = drefs->refs->be->transaction_finish(drefs->refs, transaction,
      +						  err);
      +	print_transaction(transaction);
     -+	fprintf(stderr, "finish: %d\n", res);
     ++	trace_printf_key(&trace_refs, "finish: %d\n", res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +{
      +	struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
      +	int res = drefs->refs->be->pack_refs(drefs->refs, flags);
     -+	fprintf(stderr, "pack_refs: %d\n", res);
     ++	trace_printf_key(&trace_refs, "pack_refs: %d\n", res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +	struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
      +	int res = drefs->refs->be->create_symref(drefs->refs, ref_name, target,
      +						 logmsg);
     -+	fprintf(stderr, "create_symref: %s -> %s \"%s\": %d\n", ref_name,
     ++	trace_printf_key(&trace_refs, "create_symref: %s -> %s \"%s\": %d\n", ref_name,
      +		target, logmsg, res);
      +	return res;
      +}
     @@ refs/debug.c (new)
      +	int res =
      +		drefs->refs->be->delete_refs(drefs->refs, msg, refnames, flags);
      +	int i = 0;
     -+	fprintf(stderr, "delete_refs {\n");
     ++	trace_printf_key(&trace_refs, "delete_refs {\n");
      +	for (i = 0; i < refnames->nr; i++)
     -+		fprintf(stderr, "%s\n", refnames->items[i].string);
     -+	fprintf(stderr, "}: %d\n", res);
     ++		trace_printf_key(&trace_refs, "%s\n", refnames->items[i].string);
     ++	trace_printf_key(&trace_refs, "}: %d\n", res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +	struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
      +	int res = drefs->refs->be->rename_ref(drefs->refs, oldref, newref,
      +					      logmsg);
     -+	fprintf(stderr, "rename_ref: %s -> %s \"%s\": %d\n", oldref, newref,
     ++	trace_printf_key(&trace_refs, "rename_ref: %s -> %s \"%s\": %d\n", oldref, newref,
      +		logmsg, res);
      +	return res;
      +}
     @@ refs/debug.c (new)
      +	struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
      +	int res =
      +		drefs->refs->be->copy_ref(drefs->refs, oldref, newref, logmsg);
     -+	fprintf(stderr, "copy_ref: %s -> %s \"%s\": %d\n", oldref, newref,
     ++	trace_printf_key(&trace_refs, "copy_ref: %s -> %s \"%s\": %d\n", oldref, newref,
      +		logmsg, res);
      +	return res;
      +}
     @@ refs/debug.c (new)
      +		(struct debug_ref_iterator *)ref_iterator;
      +	int res = diter->iter->vtable->advance(diter->iter);
      +	if (res)
     -+		fprintf(stderr, "iterator_advance: %d\n", res);
     ++		trace_printf_key(&trace_refs, "iterator_advance: (%d)\n", res);
      +	else
     -+		fprintf(stderr, "iterator_advance before: %s\n",
     ++		trace_printf_key(&trace_refs, "iterator_advance: %s (0)\n",
      +			diter->iter->refname);
      +
      +	diter->base.ordered = diter->iter->ordered;
     @@ refs/debug.c (new)
      +	diter->base.flags = diter->iter->flags;
      +	return res;
      +}
     ++
      +static int debug_ref_iterator_peel(struct ref_iterator *ref_iterator,
      +				   struct object_id *peeled)
      +{
      +	struct debug_ref_iterator *diter =
      +		(struct debug_ref_iterator *)ref_iterator;
      +	int res = diter->iter->vtable->peel(diter->iter, peeled);
     -+	fprintf(stderr, "iterator_peel: %s: %d\n", diter->iter->refname, res);
     ++	trace_printf_key(&trace_refs, "iterator_peel: %s: %d\n", diter->iter->refname, res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +	struct debug_ref_iterator *diter =
      +		(struct debug_ref_iterator *)ref_iterator;
      +	int res = diter->iter->vtable->abort(diter->iter);
     -+	fprintf(stderr, "iterator_abort: %d\n", res);
     ++	trace_printf_key(&trace_refs, "iterator_abort: %d\n", res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +	struct debug_ref_iterator *diter = xcalloc(1, sizeof(*diter));
      +	base_ref_iterator_init(&diter->base, &debug_ref_iterator_vtable, 1);
      +	diter->iter = res;
     -+	fprintf(stderr, "ref_iterator_begin: %s (0x%x)\n", prefix, flags);
     ++	trace_printf_key(&trace_refs, "ref_iterator_begin: %s (0x%x)\n", prefix, flags);
      +	return &diter->base;
      +}
      +
     @@ refs/debug.c (new)
      +					    type);
      +
      +	if (res == 0) {
     -+		fprintf(stderr, "read_raw_ref: %s: %s (=> %s) type %x: %d\n",
     ++		trace_printf_key(&trace_refs, "read_raw_ref: %s: %s (=> %s) type %x: %d\n",
      +			refname, oid_to_hex(oid), referent->buf, *type, res);
      +	} else {
     -+		fprintf(stderr, "read_raw_ref: %s err %d\n", refname, res);
     ++		trace_printf_key(&trace_refs, "read_raw_ref: %s: %d\n", refname, res);
      +	}
      +	return res;
      +}
     @@ refs/debug.c (new)
      +	struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
      +	struct ref_iterator *res =
      +		drefs->refs->be->reflog_iterator_begin(drefs->refs);
     -+	fprintf(stderr, "for_each_reflog_iterator_begin\n");
     ++	trace_printf_key(&trace_refs, "for_each_reflog_iterator_begin\n");
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +
      +	ret = dbg->fn(old_oid, new_oid, committer, timestamp, tz, msg,
      +		      dbg->cb_data);
     -+	fprintf(stderr, "reflog_ent %s (ret %d): %s -> %s, %s %ld \"%s\"\n",
     ++	trace_printf_key(&trace_refs, "reflog_ent %s (ret %d): %s -> %s, %s %ld \"%s\"\n",
      +		dbg->refname, ret, o, n, committer, (long int)timestamp, msg);
      +	return ret;
      +}
     @@ refs/debug.c (new)
      +
      +	int res = drefs->refs->be->for_each_reflog_ent(
      +		drefs->refs, refname, &debug_print_reflog_ent, &dbg);
     -+	fprintf(stderr, "for_each_reflog: %s: %d\n", refname, res);
     ++	trace_printf_key(&trace_refs, "for_each_reflog: %s: %d\n", refname, res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +	};
      +	int res = drefs->refs->be->for_each_reflog_ent_reverse(
      +		drefs->refs, refname, &debug_print_reflog_ent, &dbg);
     -+	fprintf(stderr, "for_each_reflog_reverse: %s: %d\n", refname, res);
     ++	trace_printf_key(&trace_refs, "for_each_reflog_reverse: %s: %d\n", refname, res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +{
      +	struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
      +	int res = drefs->refs->be->reflog_exists(drefs->refs, refname);
     -+	fprintf(stderr, "reflog_exists: %s: %d\n", refname, res);
     ++	trace_printf_key(&trace_refs, "reflog_exists: %s: %d\n", refname, res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +	struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
      +	int res = drefs->refs->be->create_reflog(drefs->refs, refname,
      +						 force_create, err);
     -+	fprintf(stderr, "create_reflog: %s: %d\n", refname, res);
     ++	trace_printf_key(&trace_refs, "create_reflog: %s: %d\n", refname, res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +{
      +	struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
      +	int res = drefs->refs->be->delete_reflog(drefs->refs, refname);
     -+	fprintf(stderr, "delete_reflog: %s: %d\n", refname, res);
     ++	trace_printf_key(&trace_refs, "delete_reflog: %s: %d\n", refname, res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +						 flags, prepare_fn,
      +						 should_prune_fn, cleanup_fn,
      +						 policy_cb_data);
     -+	fprintf(stderr, "reflog_expire: %s: %d\n", refname, res);
     ++	trace_printf_key(&trace_refs, "reflog_expire: %s: %d\n", refname, res);
      +	return res;
      +}
      +
     @@ refs/debug.c (new)
      +};
      
       ## refs/refs-internal.h ##
     -@@ refs/refs-internal.h: struct ref_store {
     +@@ refs/refs-internal.h: int parse_loose_ref_contents(const char *buf, struct object_id *oid,
       void base_ref_store_init(struct ref_store *refs,
       			 const struct ref_storage_be *be);
       
      +/*
     -+ * Print out ref operations as they occur. Useful for debugging alternate ref
     -+ * backends.
     ++ * Support GIT_TRACE_REFS by optionally wrapping the given ref_store instance.
      + */
     -+struct ref_store *debug_wrap(const char *gitdir, struct ref_store *store);
     ++struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store);
      +
       #endif /* REFS_REFS_INTERNAL_H */

 Documentation/git.txt |   4 +
 Makefile              |   1 +
 refs.c                |   1 +
 refs/debug.c          | 396 ++++++++++++++++++++++++++++++++++++++++++
 refs/refs-internal.h  |   5 +
 5 files changed, 407 insertions(+)
 create mode 100644 refs/debug.c