{"thread":{"id":"54152","subject":"[PATCH] RFC: refs: add GIT_DEBUG_REFS debugging mechanism","startedAt":"2020-08-28T15:29:07Z","lastAt":"2020-09-16T21:10:11Z","messageCount":10,"participants":["Han-Wen Nienhuys via GitGitGadget","Jonathan Tan","Jonathan Nieder","Jeff King","Han-Wen Nienhuys","Junio C Hamano"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"404700","messageId":"pull.713.git.1598628529512.gitgitgadget@gmail.com","threadId":"54152","inReplyTo":null,"subject":"[PATCH] RFC: refs: add GIT_DEBUG_REFS debugging mechanism","fromName":"Han-Wen Nienhuys via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-08-28T15:28:49Z","receivedAt":"2020-08-28T15:29:07Z","isPatch":true,"sender":{"key":"hanwen@google.com","avatar":"https://avatars.githubusercontent.com/u/31547?v=4"},"body":"From: Han-Wen Nienhuys \n\nWhen set in the environment, GIT_DEBUG_REFS makes git print operations and\nresults as they flow through the ref storage backend. This helps debug\ndiscrepancies between different ref backends.\n\nThis should be integrated with the trace2 sub-system, and I would appreciate\npointers on how to start.\n\nExample:\n\n $ GIT_DEBUG_REFS=1 ./git branch\n ref_store for .git\n read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0\n read_raw_ref: refs/heads/ref-debug: b0728cf8cb9dfd395bea41c646f48108c99230c0 (=> refs/heads/ref-debug) type 0: 0\n ref_iterator_begin: refs/heads/ (0x1)\n iterator_advance before: refs/heads/b4\n iterator_advance before: refs/heads/bla\n ...\n\nSigned-off-by: Han-Wen Nienhuys \n---\n RFC: refs: add GIT_DEBUG_REFS debugging mechanism\n \n When set in the environment, GIT_DEBUG_REFS makes git print operations\n and results as they flow through the ref storage backend. This helps\n debug discrepancies between different ref backends.\n \n This should be integrated with the trace2 sub-system, and I would\n appreciate pointers on how to start.\n \n Example:\n \n $ GIT_DEBUG_REFS=1 ./git branch\n ref_store for .git\n read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0\n read_raw_ref: refs/heads/ref-debug: b0728cf8cb9dfd395bea41c646f48108c99230c0 (=> refs/heads/ref-debug) type 0: 0\n ref_iterator_begin: refs/heads/ (0x1)\n iterator_advance before: refs/heads/b4\n iterator_advance before: refs/heads/bla\n ...\n \n Signed-off-by: Han-Wen Nienhuys hanwen@google.com [hanwen@google.com]\n\nPublished-As: https://github.com/gitgitgadget/git/releases/tag/pr-713%2Fhanwen%2Fdebug-refs-v1\nFetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-713/hanwen/debug-refs-v1\nPull-Request: https://github.com/gitgitgadget/git/pull/713\n\n Makefile | 1 +\n refs.c | 4 +\n refs/debug.c | 387 +++++++++++++++++++++++++++++++++++++++++++\n refs/refs-internal.h | 6 +\n 4 files changed, 398 insertions(+)\n create mode 100644 refs/debug.c\n\ndiff --git a/Makefile b/Makefile\nindex 65f8cfb236..51408fe453 100644\n--- a/Makefile\n+++ b/Makefile\n@@ -957,6 +957,7 @@ LIB_OBJS += rebase.o\n LIB_OBJS += ref-filter.o\n LIB_OBJS += reflog-walk.o\n LIB_OBJS += refs.o\n+LIB_OBJS += refs/debug.o\n LIB_OBJS += refs/files-backend.o\n LIB_OBJS += refs/iterator.o\n LIB_OBJS += refs/packed-backend.o\ndiff --git a/refs.c b/refs.c\nindex cf91711968..06726f7544 100644\n--- a/refs.c\n+++ b/refs.c\n@@ -1748,6 +1748,10 @@ struct ref_store *get_main_ref_store(struct repository *r)\n \t\tBUG(\"attempting to get main_ref_store outside of repository\");\n \n \tr->refs_private = ref_store_init(r->gitdir, REF_STORE_ALL_CAPS);\n+\tif (getenv(\"GIT_DEBUG_REFS\")) {\n+\t\t// XXX - how to hook this up with the trace2 framework?\n+\t\tr->refs_private = debug_wrap(r->gitdir, r->refs_private);\n+\t}\n \treturn r->refs_private;\n }\n \ndiff --git a/refs/debug.c b/refs/debug.c\nnew file mode 100644\nindex 0000000000..1482c5bd5f\n--- /dev/null\n+++ b/refs/debug.c\n@@ -0,0 +1,387 @@\n+\n+#include \"refs-internal.h\"\n+\n+struct debug_ref_store {\n+\tstruct ref_store base;\n+\tstruct ref_store *refs;\n+};\n+\n+extern struct ref_storage_be refs_be_debug;\n+struct ref_store *debug_wrap(const char *gitdir, struct ref_store *store);\n+\n+struct ref_store *debug_wrap(const char *gitdir, struct ref_store *store)\n+{\n+\tstruct debug_ref_store *res = malloc(sizeof(struct debug_ref_store));\n+\tstruct ref_storage_be *be_copy = malloc(sizeof(*be_copy));\n+\t*be_copy = refs_be_debug;\n+\tbe_copy->name = store->be->name;\n+\tfprintf(stderr, \"ref_store for %s\\n\", gitdir);\n+\tres->refs = store;\n+\tbase_ref_store_init((struct ref_store *)res, be_copy);\n+\treturn (struct ref_store *)res;\n+}\n+\n+static int debug_init_db(struct ref_store *refs, struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res = drefs->refs->be->init_db(drefs->refs, err);\n+\tfprintf(stderr, \"init_db: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_transaction_prepare(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_prepare(drefs->refs, transaction,\n+\t\t\t\t\t\t err);\n+\tfprintf(stderr, \"transaction_prepare: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static void print_update(int i, const char *refname,\n+\t\t\t const struct object_id *old_oid,\n+\t\t\t const struct object_id *new_oid, unsigned int flags,\n+\t\t\t unsigned int type, const char *msg)\n+{\n+\tchar o[200] = \"null\";\n+\tchar n[200] = \"null\";\n+\tif (old_oid)\n+\t\toid_to_hex_r(o, old_oid);\n+\tif (new_oid)\n+\t\toid_to_hex_r(n, new_oid);\n+\n+\ttype &= 0xf; /* see refs.h REF_* */\n+\tflags &= REF_HAVE_NEW | REF_HAVE_OLD | REF_NO_DEREF |\n+\t\tREF_FORCE_CREATE_REFLOG; // XXX: LOG_ONLY\n+\tfprintf(stderr, \"%d: %s %s -> %s (F=0x%x, T=0x%x) \\\"%s\\\"\\n\", i, refname,\n+\t\to, n, flags, type, msg);\n+}\n+\n+static void print_transaction(struct ref_transaction *transaction)\n+{\n+\tfprintf(stderr, \"transaction {\\n\");\n+\tfor (int i = 0; i < transaction->nr; i++) {\n+\t\tstruct ref_update *u = transaction->updates[i];\n+\t\tprint_update(i, u->refname, &u->old_oid, &u->new_oid, u->flags,\n+\t\t\t u->type, u->msg);\n+\t}\n+\tfprintf(stderr, \"}\\n\");\n+}\n+\n+static int debug_transaction_finish(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_finish(drefs->refs, transaction,\n+\t\t\t\t\t\t err);\n+\tprint_transaction(transaction);\n+\tfprintf(stderr, \"finish: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_transaction_abort(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_abort(drefs->refs, transaction, err);\n+\treturn res;\n+}\n+\n+static int debug_initial_transaction_commit(struct ref_store *refs,\n+\t\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->initial_transaction_commit(drefs->refs,\n+\t\t\t\t\t\t\t transaction, err);\n+\treturn res;\n+}\n+\n+static int debug_pack_refs(struct ref_store *ref_store, unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->pack_refs(drefs->refs, flags);\n+\tfprintf(stderr, \"pack_refs: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_create_symref(struct ref_store *ref_store,\n+\t\t\t const char *ref_name, const char *target,\n+\t\t\t const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->create_symref(drefs->refs, ref_name, target,\n+\t\t\t\t\t\t logmsg);\n+\tfprintf(stderr, \"create_symref: %s -> %s \\\"%s\\\": %d\\n\", ref_name,\n+\t\ttarget, logmsg, res);\n+\treturn res;\n+}\n+\n+static int debug_delete_refs(struct ref_store *ref_store, const char *msg,\n+\t\t\t struct string_list *refnames, unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res =\n+\t\tdrefs->refs->be->delete_refs(drefs->refs, msg, refnames, flags);\n+\tint i = 0;\n+\tfprintf(stderr, \"delete_refs {\\n\");\n+\tfor (i = 0; i < refnames->nr; i++)\n+\t\tfprintf(stderr, \"%s\\n\", refnames->items[i].string);\n+\tfprintf(stderr, \"}: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_rename_ref(struct ref_store *ref_store, const char *oldref,\n+\t\t\t const char *newref, const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->rename_ref(drefs->refs, oldref, newref,\n+\t\t\t\t\t logmsg);\n+\tfprintf(stderr, \"rename_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n+\t\tlogmsg, res);\n+\treturn res;\n+}\n+\n+static int debug_copy_ref(struct ref_store *ref_store, const char *oldref,\n+\t\t\t const char *newref, const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res =\n+\t\tdrefs->refs->be->copy_ref(drefs->refs, oldref, newref, logmsg);\n+\tfprintf(stderr, \"copy_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n+\t\tlogmsg, res);\n+\treturn res;\n+}\n+\n+struct debug_ref_iterator {\n+\tstruct ref_iterator base;\n+\tstruct ref_iterator *iter;\n+};\n+\n+static int debug_ref_iterator_advance(struct ref_iterator *ref_iterator)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->advance(diter->iter);\n+\tif (res)\n+\t\tfprintf(stderr, \"iterator_advance: %d\\n\", res);\n+\telse\n+\t\tfprintf(stderr, \"iterator_advance before: %s\\n\",\n+\t\t\tditer->iter->refname);\n+\n+\tditer->base.ordered = diter->iter->ordered;\n+\tditer->base.refname = diter->iter->refname;\n+\tditer->base.oid = diter->iter->oid;\n+\tditer->base.flags = diter->iter->flags;\n+\treturn res;\n+}\n+static int debug_ref_iterator_peel(struct ref_iterator *ref_iterator,\n+\t\t\t\t struct object_id *peeled)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->peel(diter->iter, peeled);\n+\tfprintf(stderr, \"iterator_peel: %s: %d\\n\", diter->iter->refname, res);\n+\treturn res;\n+}\n+\n+static int debug_ref_iterator_abort(struct ref_iterator *ref_iterator)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->abort(diter->iter);\n+\tfprintf(stderr, \"iterator_abort: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static struct ref_iterator_vtable debug_ref_iterator_vtable = {\n+\tdebug_ref_iterator_advance, debug_ref_iterator_peel,\n+\tdebug_ref_iterator_abort\n+};\n+\n+static struct ref_iterator *\n+debug_ref_iterator_begin(struct ref_store *ref_store, const char *prefix,\n+\t\t\t unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct ref_iterator *res =\n+\t\tdrefs->refs->be->iterator_begin(drefs->refs, prefix, flags);\n+\tstruct debug_ref_iterator *diter = xcalloc(1, sizeof(*diter));\n+\tbase_ref_iterator_init(&diter->base, &debug_ref_iterator_vtable, 1);\n+\tditer->iter = res;\n+\tfprintf(stderr, \"ref_iterator_begin: %s (0x%x)\\n\", prefix, flags);\n+\treturn &diter->base;\n+}\n+\n+static int debug_read_raw_ref(struct ref_store *ref_store, const char *refname,\n+\t\t\t struct object_id *oid, struct strbuf *referent,\n+\t\t\t unsigned int *type)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = 0;\n+\n+\toidcpy(oid, &null_oid);\n+\tres = drefs->refs->be->read_raw_ref(drefs->refs, refname, oid, referent,\n+\t\t\t\t\t type);\n+\n+\tif (res == 0) {\n+\t\tfprintf(stderr, \"read_raw_ref: %s: %s (=> %s) type %x: %d\\n\",\n+\t\t\trefname, oid_to_hex(oid), referent->buf, *type, res);\n+\t} else {\n+\t\tfprintf(stderr, \"read_raw_ref: %s err %d\\n\", refname, res);\n+\t}\n+\treturn res;\n+}\n+\n+static struct ref_iterator *\n+debug_reflog_iterator_begin(struct ref_store *ref_store)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct ref_iterator *res =\n+\t\tdrefs->refs->be->reflog_iterator_begin(drefs->refs);\n+\tfprintf(stderr, \"for_each_reflog_iterator_begin\\n\");\n+\treturn res;\n+}\n+\n+struct debug_reflog {\n+\tconst char *refname;\n+\teach_reflog_ent_fn *fn;\n+\tvoid *cb_data;\n+};\n+\n+static int debug_print_reflog_ent(struct object_id *old_oid,\n+\t\t\t\t struct object_id *new_oid,\n+\t\t\t\t const char *committer, timestamp_t timestamp,\n+\t\t\t\t int tz, const char *msg, void *cb_data)\n+{\n+\tstruct debug_reflog *dbg = (struct debug_reflog *)cb_data;\n+\tint ret;\n+\tchar o[100] = \"null\";\n+\tchar n[100] = \"null\";\n+\tif (old_oid)\n+\t\toid_to_hex_r(o, old_oid);\n+\tif (new_oid)\n+\t\toid_to_hex_r(n, new_oid);\n+\n+\tret = dbg->fn(old_oid, new_oid, committer, timestamp, tz, msg,\n+\t\t dbg->cb_data);\n+\tfprintf(stderr, \"reflog_ent %s (ret %d): %s -> %s, %s %ld \\\"%s\\\"\\n\",\n+\t\tdbg->refname, ret, o, n, committer, (long int)timestamp, msg);\n+\treturn ret;\n+}\n+\n+static int debug_for_each_reflog_ent(struct ref_store *ref_store,\n+\t\t\t\t const char *refname, each_reflog_ent_fn fn,\n+\t\t\t\t void *cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct debug_reflog dbg = {\n+\t\t.refname = refname,\n+\t\t.fn = fn,\n+\t\t.cb_data = cb_data,\n+\t};\n+\n+\tint res = drefs->refs->be->for_each_reflog_ent(\n+\t\tdrefs->refs, refname, &debug_print_reflog_ent, &dbg);\n+\tfprintf(stderr, \"for_each_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_for_each_reflog_ent_reverse(struct ref_store *ref_store,\n+\t\t\t\t\t const char *refname,\n+\t\t\t\t\t each_reflog_ent_fn fn,\n+\t\t\t\t\t void *cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct debug_reflog dbg = {\n+\t\t.refname = refname,\n+\t\t.fn = fn,\n+\t\t.cb_data = cb_data,\n+\t};\n+\tint res = drefs->refs->be->for_each_reflog_ent_reverse(\n+\t\tdrefs->refs, refname, &debug_print_reflog_ent, &dbg);\n+\tfprintf(stderr, \"for_each_reflog_reverse: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_reflog_exists(struct ref_store *ref_store, const char *refname)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->reflog_exists(drefs->refs, refname);\n+\tfprintf(stderr, \"reflog_exists: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_create_reflog(struct ref_store *ref_store, const char *refname,\n+\t\t\t int force_create, struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->create_reflog(drefs->refs, refname,\n+\t\t\t\t\t\t force_create, err);\n+\tfprintf(stderr, \"create_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_delete_reflog(struct ref_store *ref_store, const char *refname)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->delete_reflog(drefs->refs, refname);\n+\tfprintf(stderr, \"delete_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_reflog_expire(struct ref_store *ref_store, const char *refname,\n+\t\t\t const struct object_id *oid, unsigned int flags,\n+\t\t\t reflog_expiry_prepare_fn prepare_fn,\n+\t\t\t reflog_expiry_should_prune_fn should_prune_fn,\n+\t\t\t reflog_expiry_cleanup_fn cleanup_fn,\n+\t\t\t void *policy_cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->reflog_expire(drefs->refs, refname, oid,\n+\t\t\t\t\t\t flags, prepare_fn,\n+\t\t\t\t\t\t should_prune_fn, cleanup_fn,\n+\t\t\t\t\t\t policy_cb_data);\n+\tfprintf(stderr, \"reflog_expire: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+struct ref_storage_be refs_be_debug = {\n+\tNULL,\n+\t\"debug\",\n+\tNULL,\n+\tdebug_init_db,\n+\tdebug_transaction_prepare,\n+\tdebug_transaction_finish,\n+\tdebug_transaction_abort,\n+\tdebug_initial_transaction_commit,\n+\n+\tdebug_pack_refs,\n+\tdebug_create_symref,\n+\tdebug_delete_refs,\n+\tdebug_rename_ref,\n+\tdebug_copy_ref,\n+\n+\tdebug_ref_iterator_begin,\n+\tdebug_read_raw_ref,\n+\n+\tdebug_reflog_iterator_begin,\n+\tdebug_for_each_reflog_ent,\n+\tdebug_for_each_reflog_ent_reverse,\n+\tdebug_reflog_exists,\n+\tdebug_create_reflog,\n+\tdebug_delete_reflog,\n+\tdebug_reflog_expire,\n+};\ndiff --git a/refs/refs-internal.h b/refs/refs-internal.h\nindex 357359a0be..ec28ae5d86 100644\n--- a/refs/refs-internal.h\n+++ b/refs/refs-internal.h\n@@ -681,4 +681,10 @@ struct ref_store {\n void base_ref_store_init(struct ref_store *refs,\n \t\t\t const struct ref_storage_be *be);\n \n+/*\n+ * Print out ref operations as they occur. Useful for debugging alternate ref\n+ * backends.\n+ */\n+struct ref_store *debug_wrap(const char *gitdir, struct ref_store *store);\n+\n #endif /* REFS_REFS_INTERNAL_H */\n\nbase-commit: 675a4aaf3b226c0089108221b96559e0baae5de9\n-- \ngitgitgadget\n"},{"id":"404924","messageId":"20200902174939.3391882-1-jonathantanmy@google.com","threadId":"54152","inReplyTo":"pull.713.git.1598628529512.gitgitgadget@gmail.com","subject":"Re: [PATCH] RFC: refs: add GIT_DEBUG_REFS debugging mechanism","fromName":"Jonathan Tan","fromEmail":"jonathantanmy@google.com","sentAt":"2020-09-02T17:49:39Z","receivedAt":"2020-09-02T17:49:50Z","isPatch":true,"sender":{"key":"jonathantanmy@fastmail.com","avatar":null},"body":"> This should be integrated with the trace2 sub-system, and I would appreciate\n> pointers on how to start.\n\nThe trace2 subsystem seems to be designed to detect errors coarsely\n(e.g. by looking at process invocations) and log timings. It currently\ndoesn't seem to be made for this kind of fine debugging information -\nand perhaps this is by design, because such logging information would\nnot be useful to most users and would just clutter up the logs.\n\nBut I think there is a place for this in Git - in particular, we have\npacket tracing (GIT_TRACE_PACKET), and this has been useful both in\nautomated tests (t/????-*.sh) and in manual tests. Ref backend tracing\nseems to be similar. But this would be best if we had an additional\noption that could control whether ref backend tracing was on or off,\nindependent from other things like the trace2 target.\n\nIs the plan to migrate all usages of \"trace\" to \"trace2\" or for both to\nexist simultaneously? If the latter, then ref backend tracing could just\nuse \"trace\", but if the former, we'd have to designing this additional\noption.\n"},{"id":"404955","messageId":"20200903054422.GG4035286@google.com","threadId":"54152","inReplyTo":"20200902174939.3391882-1-jonathantanmy@google.com","subject":"Re: [PATCH] RFC: refs: add GIT_DEBUG_REFS debugging mechanism","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2020-09-03T05:44:22Z","receivedAt":"2020-09-03T05:44:27Z","isPatch":true,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"(+Peff and Josh, trace experts)\nJonathan Tan wrote:\n> Han-Wen Nienhuys wrote:\n\n>> This should be integrated with the trace2 sub-system, and I would appreciate\n>> pointers on how to start.\n>\n> The trace2 subsystem seems to be designed to detect errors coarsely\n> (e.g. by looking at process invocations) and log timings. It currently\n> doesn't seem to be made for this kind of fine debugging information -\n> and perhaps this is by design, because such logging information would\n> not be useful to most users and would just clutter up the logs.\n>\n> But I think there is a place for this in Git - in particular, we have\n> packet tracing (GIT_TRACE_PACKET), and this has been useful both in\n> automated tests (t/????-*.sh) and in manual tests. Ref backend tracing\n> seems to be similar. But this would be best if we had an additional\n> option that could control whether ref backend tracing was on or off,\n> independent from other things like the trace2 target.\n>\n> Is the plan to migrate all usages of \"trace\" to \"trace2\" or for both to\n> exist simultaneously? If the latter, then ref backend tracing could just\n> use \"trace\", but if the former, we'd have to designing this additional\n> option.\n\nHere's my not-completely-thought-through take:\n\ntrace.h defines a convenient and simple API for unstructured traces.\nYou can define a key\n\n\tstatic struct trace_key trace_refs = TRACE_KEY_INIT(REFS);\n\nand then you have available\n\n\ttrace_want(&trace_refs)\n\ttrace_printf_key(&trace_refs, fmt, args...)\n\ttrace_strbuf(&trace_refs, data)\n\nand so on.\n\nOne use of trace_printf (i.e. tracing without a key) is to print lines\nfor important events like starting a subprocess. For those, trace2 is a\nnatural replacement, with the advantage that the resulting event is\nassociated with any enclosing trace2 regions.\n\nOne design goal of trace2 was to be able to replace the original trace\nsubsystem completely. Its output routines are flexible that it should\nbe able to produce GIT_TRACE style output. It should be possible to\nimplement a trace_printf style API on top of trace2.\n\nFor ref tracing, do we care much about the human-friendliness of the\noutput? Do we expect this to be useful for debugging once reftable is\nmore established? Is it something we'd want to extract timing regions\nfrom and use for performance improvements?\n\nFor ad hoc debugging, the structured tracing features of trace2 are\nnot all that important. So if using the trace_key API is simpler,\nthen for that application I'd say go for it. Some day we could\nreimplement that same API on top of trace2 (or use a coccinelle\ntransform to a similar API) and your could would still work. :)\n\nFor producing logs that get aggregated, the structured output of\ntrace2 tends to be quite useful. Event tracing doesn't have a notion\nof setting which subsystems to trace on but it would be a natural\nthing to add. See TR2_SYSENV_CFG_PARAM for an example of configurable\n\"what to trace\" information used by GIT_TRACE2_EVENT. Happy to\nprovide more advice if this seems applicable for the problem at hand.\n\nSummary:\n\n- if this is only going to be used for tests and for ad hoc debugging,\n I'd suggest sticking to the simple trace_key based unstructured\n tracing API\n\n- if we expect it to be something we want to aggregate over many runs\n and query, then structure becomes more important and trace2 starts\n to pull its weight\n\nThanks,\nJonathan\n"},{"id":"404957","messageId":"20200903061931.GA2055118@coredump.intra.peff.net","threadId":"54152","inReplyTo":"20200903054422.GG4035286@google.com","subject":"Re: [PATCH] RFC: refs: add GIT_DEBUG_REFS debugging mechanism","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-09-03T06:19:31Z","receivedAt":"2020-09-03T06:19:36Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Sep 02, 2020 at 10:44:22PM -0700, Jonathan Nieder wrote:\n\n> Summary:\n> \n> - if this is only going to be used for tests and for ad hoc debugging,\n> I'd suggest sticking to the simple trace_key based unstructured\n> tracing API\n\nYeah, from my look at the debug patch, this seems sensible.\n\nAs clever as the \"debug\" ref-backend wrapper object is, I also wonder if\nit might be simpler to just add trace calls to all of the outer\nfunctions (e.g., ref_transaction_prepare(), etc). Unlike a \"real\" OO\nsystem, we're not typically passing around the polymorphic ref_store\ntype, but always access it through those type-agnostic wrappers. But\nmaybe that would end up just as long. I dunno.\n\n-Peff\n"},{"id":"404964","messageId":"CAFQ2z_P9dRKX-O3MGFWj1TaYciCLHBboP0jAvROYyn5QaPngYw@mail.gmail.com","threadId":"54152","inReplyTo":"CAFQ2z_M_2mmL1LXcgR5cv3Ac1AJ363jaejZz3p6AcV6b3DftTQ@mail.gmail.com","subject":"Fwd: [PATCH] RFC: refs: add GIT_DEBUG_REFS debugging mechanism","fromName":"Han-Wen Nienhuys","fromEmail":"hanwen@google.com","sentAt":"2020-09-03T10:10:32Z","receivedAt":"2020-09-03T10:10:58Z","isPatch":true,"sender":{"key":"hanwen@google.com","avatar":"https://avatars.githubusercontent.com/u/31547?v=4"},"body":"On Thu, Sep 3, 2020 at 8:19 AM Jeff King wrote:\n>\n> > - if this is only going to be used for tests and for ad hoc debugging,\n> > I'd suggest sticking to the simple trace_key based unstructured\n> > tracing API\n>\n> Yeah, from my look at the debug patch, this seems sensible.\n\n\nthanks, I'll rework it to use the traditional trace API.\n\n> As clever as the \"debug\" ref-backend wrapper object is, I also wonder if\n> it might be simpler to just add trace calls to all of the outer\n> functions (e.g., ref_transaction_prepare(), etc). Unlike a \"real\" OO\n> system, we're not typically passing around the polymorphic ref_store\n> type, but always access it through those type-agnostic wrappers. But\n> maybe that would end up just as long. I dunno.\n\nThe ref backend supports callbacks, so it will always require some\namount of wrapping. The advantage of this approach is that the debug\nsupport stays very neatly separate from the actual logic, and that the\ncompiler enforces that we add debug support if a new ref backend\nmethod is added.\n\n-- \nHan-Wen Nienhuys - Google Munich\nI work 80%. Don't expect answers from me on Fridays.\n--\n\nGoogle Germany GmbH, Erika-Mann-Strasse 33, 80636 Munich\n\nRegistergericht und -nummer: Hamburg, HRB 86891\n\nSitz der Gesellschaft: Hamburg\n\nGeschäftsführer: Paul Manicle, Halimah DeLaine Prado\n\n\n\n-- \nHan-Wen Nienhuys - Google Munich\nI work 80%. Don't expect answers from me on Fridays.\n"},{"id":"405124","messageId":"pull.713.v2.git.1599492274909.gitgitgadget@gmail.com","threadId":"54152","inReplyTo":"pull.713.git.1598628529512.gitgitgadget@gmail.com","subject":"[PATCH v2] refs: add GIT_TRACE_REFS debugging mechanism","fromName":"Han-Wen Nienhuys via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-09-07T15:24:34Z","receivedAt":"2020-09-07T15:25:44Z","isPatch":true,"sender":{"key":"hanwen@google.com","avatar":"https://avatars.githubusercontent.com/u/31547?v=4"},"body":"From: Han-Wen Nienhuys \n\nWhen set in the environment, GIT_TRACE_REFS makes git print operations and\nresults as they flow through the ref storage backend. This helps debug\ndiscrepancies between different ref backends.\n\nExample:\n\n $ GIT_TRACE_REFS=\"1\" ./git branch\n 15:42:09.769631 refs/debug.c:26 ref_store for .git\n 15:42:09.769681 refs/debug.c:249 read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0\n 15:42:09.769695 refs/debug.c:249 read_raw_ref: refs/heads/ref-debug: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a (=> refs/heads/ref-debug) type 0: 0\n 15:42:09.770282 refs/debug.c:233 ref_iterator_begin: refs/heads/ (0x1)\n 15:42:09.770290 refs/debug.c:189 iterator_advance: refs/heads/b4 (0)\n 15:42:09.770295 refs/debug.c:189 iterator_advance: refs/heads/branch3 (0)\n\nSigned-off-by: Han-Wen Nienhuys \n---\n refs: add GIT_TRACE_REFS debugging mechanism\n \n When set in the environment, GIT_TRACE_REFS makes git print operations\n and results as they flow through the ref storage backend. This helps\n debug discrepancies between different ref backends.\n \n Example:\n \n $ GIT_TRACE_REFS=\"1\" ./git branch\n 15:42:09.769631 refs/debug.c:26 ref_store for .git\n 15:42:09.769681 refs/debug.c:249 read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0\n 15:42:09.769695 refs/debug.c:249 read_raw_ref: refs/heads/ref-debug: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a (=> refs/heads/ref-debug) type 0: 0\n 15:42:09.770282 refs/debug.c:233 ref_iterator_begin: refs/heads/ (0x1)\n 15:42:09.770290 refs/debug.c:189 iterator_advance: refs/heads/b4 (0)\n 15:42:09.770295 refs/debug.c:189 iterator_advance: refs/heads/branch3 (0)\n \n Signed-off-by: Han-Wen Nienhuys hanwen@google.com [hanwen@google.com]\n\nPublished-As: https://github.com/gitgitgadget/git/releases/tag/pr-713%2Fhanwen%2Fdebug-refs-v2\nFetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-713/hanwen/debug-refs-v2\nPull-Request: https://github.com/gitgitgadget/git/pull/713\n\nRange-diff vs v1:\n\n 1: 4d045e35be ! 1: 19330e894c RFC: refs: add GIT_DEBUG_REFS debugging mechanism\n @@ Metadata\n Author: Han-Wen Nienhuys \n \n ## Commit message ##\n - RFC: refs: add GIT_DEBUG_REFS debugging mechanism\n + refs: add GIT_TRACE_REFS debugging mechanism\n \n - When set in the environment, GIT_DEBUG_REFS makes git print operations and\n + When set in the environment, GIT_TRACE_REFS makes git print operations and\n results as they flow through the ref storage backend. This helps debug\n discrepancies between different ref backends.\n \n - This should be integrated with the trace2 sub-system, and I would appreciate\n - pointers on how to start.\n -\n Example:\n \n - $ GIT_DEBUG_REFS=1 ./git branch\n - ref_store for .git\n - read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0\n - read_raw_ref: refs/heads/ref-debug: b0728cf8cb9dfd395bea41c646f48108c99230c0 (=> refs/heads/ref-debug) type 0: 0\n - ref_iterator_begin: refs/heads/ (0x1)\n - iterator_advance before: refs/heads/b4\n - iterator_advance before: refs/heads/bla\n - ...\n + $ GIT_TRACE_REFS=\"1\" ./git branch\n + 15:42:09.769631 refs/debug.c:26 ref_store for .git\n + 15:42:09.769681 refs/debug.c:249 read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0\n + 15:42:09.769695 refs/debug.c:249 read_raw_ref: refs/heads/ref-debug: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a (=> refs/heads/ref-debug) type 0: 0\n + 15:42:09.770282 refs/debug.c:233 ref_iterator_begin: refs/heads/ (0x1)\n + 15:42:09.770290 refs/debug.c:189 iterator_advance: refs/heads/b4 (0)\n + 15:42:09.770295 refs/debug.c:189 iterator_advance: refs/heads/branch3 (0)\n \n Signed-off-by: Han-Wen Nienhuys \n \n + ## Documentation/git.txt ##\n +@@ Documentation/git.txt: of clones and fetches.\n + \ttime of each Git command.\n + \tSee `GIT_TRACE` for available trace output options.\n + \n ++`GIT_TRACE_REFS`::\n ++\tEnables trace messages for operations on the ref database.\n ++\tSee `GIT_TRACE` for available trace output options.\n ++\n + `GIT_TRACE_SETUP`::\n + \tEnables trace messages printing the .git, working tree and current\n + \tworking directory after Git has completed its setup phase.\n +\n ## Makefile ##\n @@ Makefile: LIB_OBJS += rebase.o\n LIB_OBJS += ref-filter.o\n @@ refs.c: struct ref_store *get_main_ref_store(struct repository *r)\n \t\tBUG(\"attempting to get main_ref_store outside of repository\");\n \n \tr->refs_private = ref_store_init(r->gitdir, REF_STORE_ALL_CAPS);\n -+\tif (getenv(\"GIT_DEBUG_REFS\")) {\n -+\t\t// XXX - how to hook this up with the trace2 framework?\n -+\t\tr->refs_private = debug_wrap(r->gitdir, r->refs_private);\n -+\t}\n ++\tr->refs_private = maybe_debug_wrap_ref_store(r->gitdir, r->refs_private);\n \treturn r->refs_private;\n }\n \n @@ refs/debug.c (new)\n @@\n +\n +#include \"refs-internal.h\"\n ++#include \"trace.h\"\n ++\n ++static struct trace_key trace_refs = TRACE_KEY_INIT(REFS);\n +\n +struct debug_ref_store {\n +\tstruct ref_store base;\n @@ refs/debug.c (new)\n +};\n +\n +extern struct ref_storage_be refs_be_debug;\n -+struct ref_store *debug_wrap(const char *gitdir, struct ref_store *store);\n +\n -+struct ref_store *debug_wrap(const char *gitdir, struct ref_store *store)\n ++struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store)\n +{\n -+\tstruct debug_ref_store *res = malloc(sizeof(struct debug_ref_store));\n -+\tstruct ref_storage_be *be_copy = malloc(sizeof(*be_copy));\n ++\tstruct debug_ref_store *res;\n ++\tstruct ref_storage_be *be_copy;\n ++\n ++\tif (!trace_want(&trace_refs)) {\n ++\t\treturn store;\n ++\t}\n ++\tres = malloc(sizeof(struct debug_ref_store));\n ++\tbe_copy = malloc(sizeof(*be_copy));\n +\t*be_copy = refs_be_debug;\n +\tbe_copy->name = store->be->name;\n -+\tfprintf(stderr, \"ref_store for %s\\n\", gitdir);\n ++\ttrace_printf_key(&trace_refs, \"ref_store for %s\\n\", gitdir);\n +\tres->refs = store;\n +\tbase_ref_store_init((struct ref_store *)res, be_copy);\n +\treturn (struct ref_store *)res;\n @@ refs/debug.c (new)\n +{\n +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n +\tint res = drefs->refs->be->init_db(drefs->refs, err);\n -+\tfprintf(stderr, \"init_db: %d\\n\", res);\n ++\ttrace_printf_key(&trace_refs, \"init_db: %d\\n\", res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +\ttransaction->ref_store = drefs->refs;\n +\tres = drefs->refs->be->transaction_prepare(drefs->refs, transaction,\n +\t\t\t\t\t\t err);\n -+\tfprintf(stderr, \"transaction_prepare: %d\\n\", res);\n ++\ttrace_printf_key(&trace_refs, \"transaction_prepare: %d\\n\", res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +\n +\ttype &= 0xf; /* see refs.h REF_* */\n +\tflags &= REF_HAVE_NEW | REF_HAVE_OLD | REF_NO_DEREF |\n -+\t\tREF_FORCE_CREATE_REFLOG; // XXX: LOG_ONLY\n -+\tfprintf(stderr, \"%d: %s %s -> %s (F=0x%x, T=0x%x) \\\"%s\\\"\\n\", i, refname,\n ++\t\tREF_FORCE_CREATE_REFLOG;\n ++\ttrace_printf_key(&trace_refs, \"%d: %s %s -> %s (F=0x%x, T=0x%x) \\\"%s\\\"\\n\", i, refname,\n +\t\to, n, flags, type, msg);\n +}\n +\n +static void print_transaction(struct ref_transaction *transaction)\n +{\n -+\tfprintf(stderr, \"transaction {\\n\");\n ++\ttrace_printf_key(&trace_refs, \"transaction {\\n\");\n +\tfor (int i = 0; i < transaction->nr; i++) {\n +\t\tstruct ref_update *u = transaction->updates[i];\n +\t\tprint_update(i, u->refname, &u->old_oid, &u->new_oid, u->flags,\n +\t\t\t u->type, u->msg);\n +\t}\n -+\tfprintf(stderr, \"}\\n\");\n ++\ttrace_printf_key(&trace_refs, \"}\\n\");\n +}\n +\n +static int debug_transaction_finish(struct ref_store *refs,\n @@ refs/debug.c (new)\n +\tres = drefs->refs->be->transaction_finish(drefs->refs, transaction,\n +\t\t\t\t\t\t err);\n +\tprint_transaction(transaction);\n -+\tfprintf(stderr, \"finish: %d\\n\", res);\n ++\ttrace_printf_key(&trace_refs, \"finish: %d\\n\", res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +{\n +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n +\tint res = drefs->refs->be->pack_refs(drefs->refs, flags);\n -+\tfprintf(stderr, \"pack_refs: %d\\n\", res);\n ++\ttrace_printf_key(&trace_refs, \"pack_refs: %d\\n\", res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n +\tint res = drefs->refs->be->create_symref(drefs->refs, ref_name, target,\n +\t\t\t\t\t\t logmsg);\n -+\tfprintf(stderr, \"create_symref: %s -> %s \\\"%s\\\": %d\\n\", ref_name,\n ++\ttrace_printf_key(&trace_refs, \"create_symref: %s -> %s \\\"%s\\\": %d\\n\", ref_name,\n +\t\ttarget, logmsg, res);\n +\treturn res;\n +}\n @@ refs/debug.c (new)\n +\tint res =\n +\t\tdrefs->refs->be->delete_refs(drefs->refs, msg, refnames, flags);\n +\tint i = 0;\n -+\tfprintf(stderr, \"delete_refs {\\n\");\n ++\ttrace_printf_key(&trace_refs, \"delete_refs {\\n\");\n +\tfor (i = 0; i < refnames->nr; i++)\n -+\t\tfprintf(stderr, \"%s\\n\", refnames->items[i].string);\n -+\tfprintf(stderr, \"}: %d\\n\", res);\n ++\t\ttrace_printf_key(&trace_refs, \"%s\\n\", refnames->items[i].string);\n ++\ttrace_printf_key(&trace_refs, \"}: %d\\n\", res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n +\tint res = drefs->refs->be->rename_ref(drefs->refs, oldref, newref,\n +\t\t\t\t\t logmsg);\n -+\tfprintf(stderr, \"rename_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n ++\ttrace_printf_key(&trace_refs, \"rename_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n +\t\tlogmsg, res);\n +\treturn res;\n +}\n @@ refs/debug.c (new)\n +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n +\tint res =\n +\t\tdrefs->refs->be->copy_ref(drefs->refs, oldref, newref, logmsg);\n -+\tfprintf(stderr, \"copy_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n ++\ttrace_printf_key(&trace_refs, \"copy_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n +\t\tlogmsg, res);\n +\treturn res;\n +}\n @@ refs/debug.c (new)\n +\t\t(struct debug_ref_iterator *)ref_iterator;\n +\tint res = diter->iter->vtable->advance(diter->iter);\n +\tif (res)\n -+\t\tfprintf(stderr, \"iterator_advance: %d\\n\", res);\n ++\t\ttrace_printf_key(&trace_refs, \"iterator_advance: (%d)\\n\", res);\n +\telse\n -+\t\tfprintf(stderr, \"iterator_advance before: %s\\n\",\n ++\t\ttrace_printf_key(&trace_refs, \"iterator_advance: %s (0)\\n\",\n +\t\t\tditer->iter->refname);\n +\n +\tditer->base.ordered = diter->iter->ordered;\n @@ refs/debug.c (new)\n +\tditer->base.flags = diter->iter->flags;\n +\treturn res;\n +}\n ++\n +static int debug_ref_iterator_peel(struct ref_iterator *ref_iterator,\n +\t\t\t\t struct object_id *peeled)\n +{\n +\tstruct debug_ref_iterator *diter =\n +\t\t(struct debug_ref_iterator *)ref_iterator;\n +\tint res = diter->iter->vtable->peel(diter->iter, peeled);\n -+\tfprintf(stderr, \"iterator_peel: %s: %d\\n\", diter->iter->refname, res);\n ++\ttrace_printf_key(&trace_refs, \"iterator_peel: %s: %d\\n\", diter->iter->refname, res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +\tstruct debug_ref_iterator *diter =\n +\t\t(struct debug_ref_iterator *)ref_iterator;\n +\tint res = diter->iter->vtable->abort(diter->iter);\n -+\tfprintf(stderr, \"iterator_abort: %d\\n\", res);\n ++\ttrace_printf_key(&trace_refs, \"iterator_abort: %d\\n\", res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +\tstruct debug_ref_iterator *diter = xcalloc(1, sizeof(*diter));\n +\tbase_ref_iterator_init(&diter->base, &debug_ref_iterator_vtable, 1);\n +\tditer->iter = res;\n -+\tfprintf(stderr, \"ref_iterator_begin: %s (0x%x)\\n\", prefix, flags);\n ++\ttrace_printf_key(&trace_refs, \"ref_iterator_begin: %s (0x%x)\\n\", prefix, flags);\n +\treturn &diter->base;\n +}\n +\n @@ refs/debug.c (new)\n +\t\t\t\t\t type);\n +\n +\tif (res == 0) {\n -+\t\tfprintf(stderr, \"read_raw_ref: %s: %s (=> %s) type %x: %d\\n\",\n ++\t\ttrace_printf_key(&trace_refs, \"read_raw_ref: %s: %s (=> %s) type %x: %d\\n\",\n +\t\t\trefname, oid_to_hex(oid), referent->buf, *type, res);\n +\t} else {\n -+\t\tfprintf(stderr, \"read_raw_ref: %s err %d\\n\", refname, res);\n ++\t\ttrace_printf_key(&trace_refs, \"read_raw_ref: %s: %d\\n\", refname, res);\n +\t}\n +\treturn res;\n +}\n @@ refs/debug.c (new)\n +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n +\tstruct ref_iterator *res =\n +\t\tdrefs->refs->be->reflog_iterator_begin(drefs->refs);\n -+\tfprintf(stderr, \"for_each_reflog_iterator_begin\\n\");\n ++\ttrace_printf_key(&trace_refs, \"for_each_reflog_iterator_begin\\n\");\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +\n +\tret = dbg->fn(old_oid, new_oid, committer, timestamp, tz, msg,\n +\t\t dbg->cb_data);\n -+\tfprintf(stderr, \"reflog_ent %s (ret %d): %s -> %s, %s %ld \\\"%s\\\"\\n\",\n ++\ttrace_printf_key(&trace_refs, \"reflog_ent %s (ret %d): %s -> %s, %s %ld \\\"%s\\\"\\n\",\n +\t\tdbg->refname, ret, o, n, committer, (long int)timestamp, msg);\n +\treturn ret;\n +}\n @@ refs/debug.c (new)\n +\n +\tint res = drefs->refs->be->for_each_reflog_ent(\n +\t\tdrefs->refs, refname, &debug_print_reflog_ent, &dbg);\n -+\tfprintf(stderr, \"for_each_reflog: %s: %d\\n\", refname, res);\n ++\ttrace_printf_key(&trace_refs, \"for_each_reflog: %s: %d\\n\", refname, res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +\t};\n +\tint res = drefs->refs->be->for_each_reflog_ent_reverse(\n +\t\tdrefs->refs, refname, &debug_print_reflog_ent, &dbg);\n -+\tfprintf(stderr, \"for_each_reflog_reverse: %s: %d\\n\", refname, res);\n ++\ttrace_printf_key(&trace_refs, \"for_each_reflog_reverse: %s: %d\\n\", refname, res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +{\n +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n +\tint res = drefs->refs->be->reflog_exists(drefs->refs, refname);\n -+\tfprintf(stderr, \"reflog_exists: %s: %d\\n\", refname, res);\n ++\ttrace_printf_key(&trace_refs, \"reflog_exists: %s: %d\\n\", refname, res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n +\tint res = drefs->refs->be->create_reflog(drefs->refs, refname,\n +\t\t\t\t\t\t force_create, err);\n -+\tfprintf(stderr, \"create_reflog: %s: %d\\n\", refname, res);\n ++\ttrace_printf_key(&trace_refs, \"create_reflog: %s: %d\\n\", refname, res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +{\n +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n +\tint res = drefs->refs->be->delete_reflog(drefs->refs, refname);\n -+\tfprintf(stderr, \"delete_reflog: %s: %d\\n\", refname, res);\n ++\ttrace_printf_key(&trace_refs, \"delete_reflog: %s: %d\\n\", refname, res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +\t\t\t\t\t\t flags, prepare_fn,\n +\t\t\t\t\t\t should_prune_fn, cleanup_fn,\n +\t\t\t\t\t\t policy_cb_data);\n -+\tfprintf(stderr, \"reflog_expire: %s: %d\\n\", refname, res);\n ++\ttrace_printf_key(&trace_refs, \"reflog_expire: %s: %d\\n\", refname, res);\n +\treturn res;\n +}\n +\n @@ refs/debug.c (new)\n +};\n \n ## refs/refs-internal.h ##\n -@@ refs/refs-internal.h: struct ref_store {\n +@@ refs/refs-internal.h: int parse_loose_ref_contents(const char *buf, struct object_id *oid,\n void base_ref_store_init(struct ref_store *refs,\n \t\t\t const struct ref_storage_be *be);\n \n +/*\n -+ * Print out ref operations as they occur. Useful for debugging alternate ref\n -+ * backends.\n ++ * Support GIT_TRACE_REFS by optionally wrapping the given ref_store instance.\n + */\n -+struct ref_store *debug_wrap(const char *gitdir, struct ref_store *store);\n ++struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store);\n +\n #endif /* REFS_REFS_INTERNAL_H */\n\n\n Documentation/git.txt | 4 +\n Makefile | 1 +\n refs.c | 1 +\n refs/debug.c | 396 ++++++++++++++++++++++++++++++++++++++++++\n refs/refs-internal.h | 5 +\n 5 files changed, 407 insertions(+)\n create mode 100644 refs/debug.c\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex 2f72b10224..c463b937a8 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -722,6 +722,10 @@ of clones and fetches.\n \ttime of each Git command.\n \tSee `GIT_TRACE` for available trace output options.\n \n+`GIT_TRACE_REFS`::\n+\tEnables trace messages for operations on the ref database.\n+\tSee `GIT_TRACE` for available trace output options.\n+\n `GIT_TRACE_SETUP`::\n \tEnables trace messages printing the .git, working tree and current\n \tworking directory after Git has completed its setup phase.\ndiff --git a/Makefile b/Makefile\nindex 86e5411f39..583b8c526e 100644\n--- a/Makefile\n+++ b/Makefile\n@@ -950,6 +950,7 @@ LIB_OBJS += rebase.o\n LIB_OBJS += ref-filter.o\n LIB_OBJS += reflog-walk.o\n LIB_OBJS += refs.o\n+LIB_OBJS += refs/debug.o\n LIB_OBJS += refs/files-backend.o\n LIB_OBJS += refs/iterator.o\n LIB_OBJS += refs/packed-backend.o\ndiff --git a/refs.c b/refs.c\nindex 156fdcd459..5febfe2281 100644\n--- a/refs.c\n+++ b/refs.c\n@@ -1774,6 +1774,7 @@ struct ref_store *get_main_ref_store(struct repository *r)\n \t\tBUG(\"attempting to get main_ref_store outside of repository\");\n \n \tr->refs_private = ref_store_init(r->gitdir, REF_STORE_ALL_CAPS);\n+\tr->refs_private = maybe_debug_wrap_ref_store(r->gitdir, r->refs_private);\n \treturn r->refs_private;\n }\n \ndiff --git a/refs/debug.c b/refs/debug.c\nnew file mode 100644\nindex 0000000000..68ae531b45\n--- /dev/null\n+++ b/refs/debug.c\n@@ -0,0 +1,396 @@\n+\n+#include \"refs-internal.h\"\n+#include \"trace.h\"\n+\n+static struct trace_key trace_refs = TRACE_KEY_INIT(REFS);\n+\n+struct debug_ref_store {\n+\tstruct ref_store base;\n+\tstruct ref_store *refs;\n+};\n+\n+extern struct ref_storage_be refs_be_debug;\n+\n+struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store)\n+{\n+\tstruct debug_ref_store *res;\n+\tstruct ref_storage_be *be_copy;\n+\n+\tif (!trace_want(&trace_refs)) {\n+\t\treturn store;\n+\t}\n+\tres = malloc(sizeof(struct debug_ref_store));\n+\tbe_copy = malloc(sizeof(*be_copy));\n+\t*be_copy = refs_be_debug;\n+\tbe_copy->name = store->be->name;\n+\ttrace_printf_key(&trace_refs, \"ref_store for %s\\n\", gitdir);\n+\tres->refs = store;\n+\tbase_ref_store_init((struct ref_store *)res, be_copy);\n+\treturn (struct ref_store *)res;\n+}\n+\n+static int debug_init_db(struct ref_store *refs, struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res = drefs->refs->be->init_db(drefs->refs, err);\n+\ttrace_printf_key(&trace_refs, \"init_db: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_transaction_prepare(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_prepare(drefs->refs, transaction,\n+\t\t\t\t\t\t err);\n+\ttrace_printf_key(&trace_refs, \"transaction_prepare: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static void print_update(int i, const char *refname,\n+\t\t\t const struct object_id *old_oid,\n+\t\t\t const struct object_id *new_oid, unsigned int flags,\n+\t\t\t unsigned int type, const char *msg)\n+{\n+\tchar o[200] = \"null\";\n+\tchar n[200] = \"null\";\n+\tif (old_oid)\n+\t\toid_to_hex_r(o, old_oid);\n+\tif (new_oid)\n+\t\toid_to_hex_r(n, new_oid);\n+\n+\ttype &= 0xf; /* see refs.h REF_* */\n+\tflags &= REF_HAVE_NEW | REF_HAVE_OLD | REF_NO_DEREF |\n+\t\tREF_FORCE_CREATE_REFLOG;\n+\ttrace_printf_key(&trace_refs, \"%d: %s %s -> %s (F=0x%x, T=0x%x) \\\"%s\\\"\\n\", i, refname,\n+\t\to, n, flags, type, msg);\n+}\n+\n+static void print_transaction(struct ref_transaction *transaction)\n+{\n+\ttrace_printf_key(&trace_refs, \"transaction {\\n\");\n+\tfor (int i = 0; i < transaction->nr; i++) {\n+\t\tstruct ref_update *u = transaction->updates[i];\n+\t\tprint_update(i, u->refname, &u->old_oid, &u->new_oid, u->flags,\n+\t\t\t u->type, u->msg);\n+\t}\n+\ttrace_printf_key(&trace_refs, \"}\\n\");\n+}\n+\n+static int debug_transaction_finish(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_finish(drefs->refs, transaction,\n+\t\t\t\t\t\t err);\n+\tprint_transaction(transaction);\n+\ttrace_printf_key(&trace_refs, \"finish: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_transaction_abort(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_abort(drefs->refs, transaction, err);\n+\treturn res;\n+}\n+\n+static int debug_initial_transaction_commit(struct ref_store *refs,\n+\t\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->initial_transaction_commit(drefs->refs,\n+\t\t\t\t\t\t\t transaction, err);\n+\treturn res;\n+}\n+\n+static int debug_pack_refs(struct ref_store *ref_store, unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->pack_refs(drefs->refs, flags);\n+\ttrace_printf_key(&trace_refs, \"pack_refs: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_create_symref(struct ref_store *ref_store,\n+\t\t\t const char *ref_name, const char *target,\n+\t\t\t const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->create_symref(drefs->refs, ref_name, target,\n+\t\t\t\t\t\t logmsg);\n+\ttrace_printf_key(&trace_refs, \"create_symref: %s -> %s \\\"%s\\\": %d\\n\", ref_name,\n+\t\ttarget, logmsg, res);\n+\treturn res;\n+}\n+\n+static int debug_delete_refs(struct ref_store *ref_store, const char *msg,\n+\t\t\t struct string_list *refnames, unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res =\n+\t\tdrefs->refs->be->delete_refs(drefs->refs, msg, refnames, flags);\n+\tint i = 0;\n+\ttrace_printf_key(&trace_refs, \"delete_refs {\\n\");\n+\tfor (i = 0; i < refnames->nr; i++)\n+\t\ttrace_printf_key(&trace_refs, \"%s\\n\", refnames->items[i].string);\n+\ttrace_printf_key(&trace_refs, \"}: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_rename_ref(struct ref_store *ref_store, const char *oldref,\n+\t\t\t const char *newref, const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->rename_ref(drefs->refs, oldref, newref,\n+\t\t\t\t\t logmsg);\n+\ttrace_printf_key(&trace_refs, \"rename_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n+\t\tlogmsg, res);\n+\treturn res;\n+}\n+\n+static int debug_copy_ref(struct ref_store *ref_store, const char *oldref,\n+\t\t\t const char *newref, const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res =\n+\t\tdrefs->refs->be->copy_ref(drefs->refs, oldref, newref, logmsg);\n+\ttrace_printf_key(&trace_refs, \"copy_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n+\t\tlogmsg, res);\n+\treturn res;\n+}\n+\n+struct debug_ref_iterator {\n+\tstruct ref_iterator base;\n+\tstruct ref_iterator *iter;\n+};\n+\n+static int debug_ref_iterator_advance(struct ref_iterator *ref_iterator)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->advance(diter->iter);\n+\tif (res)\n+\t\ttrace_printf_key(&trace_refs, \"iterator_advance: (%d)\\n\", res);\n+\telse\n+\t\ttrace_printf_key(&trace_refs, \"iterator_advance: %s (0)\\n\",\n+\t\t\tditer->iter->refname);\n+\n+\tditer->base.ordered = diter->iter->ordered;\n+\tditer->base.refname = diter->iter->refname;\n+\tditer->base.oid = diter->iter->oid;\n+\tditer->base.flags = diter->iter->flags;\n+\treturn res;\n+}\n+\n+static int debug_ref_iterator_peel(struct ref_iterator *ref_iterator,\n+\t\t\t\t struct object_id *peeled)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->peel(diter->iter, peeled);\n+\ttrace_printf_key(&trace_refs, \"iterator_peel: %s: %d\\n\", diter->iter->refname, res);\n+\treturn res;\n+}\n+\n+static int debug_ref_iterator_abort(struct ref_iterator *ref_iterator)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->abort(diter->iter);\n+\ttrace_printf_key(&trace_refs, \"iterator_abort: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static struct ref_iterator_vtable debug_ref_iterator_vtable = {\n+\tdebug_ref_iterator_advance, debug_ref_iterator_peel,\n+\tdebug_ref_iterator_abort\n+};\n+\n+static struct ref_iterator *\n+debug_ref_iterator_begin(struct ref_store *ref_store, const char *prefix,\n+\t\t\t unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct ref_iterator *res =\n+\t\tdrefs->refs->be->iterator_begin(drefs->refs, prefix, flags);\n+\tstruct debug_ref_iterator *diter = xcalloc(1, sizeof(*diter));\n+\tbase_ref_iterator_init(&diter->base, &debug_ref_iterator_vtable, 1);\n+\tditer->iter = res;\n+\ttrace_printf_key(&trace_refs, \"ref_iterator_begin: %s (0x%x)\\n\", prefix, flags);\n+\treturn &diter->base;\n+}\n+\n+static int debug_read_raw_ref(struct ref_store *ref_store, const char *refname,\n+\t\t\t struct object_id *oid, struct strbuf *referent,\n+\t\t\t unsigned int *type)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = 0;\n+\n+\toidcpy(oid, &null_oid);\n+\tres = drefs->refs->be->read_raw_ref(drefs->refs, refname, oid, referent,\n+\t\t\t\t\t type);\n+\n+\tif (res == 0) {\n+\t\ttrace_printf_key(&trace_refs, \"read_raw_ref: %s: %s (=> %s) type %x: %d\\n\",\n+\t\t\trefname, oid_to_hex(oid), referent->buf, *type, res);\n+\t} else {\n+\t\ttrace_printf_key(&trace_refs, \"read_raw_ref: %s: %d\\n\", refname, res);\n+\t}\n+\treturn res;\n+}\n+\n+static struct ref_iterator *\n+debug_reflog_iterator_begin(struct ref_store *ref_store)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct ref_iterator *res =\n+\t\tdrefs->refs->be->reflog_iterator_begin(drefs->refs);\n+\ttrace_printf_key(&trace_refs, \"for_each_reflog_iterator_begin\\n\");\n+\treturn res;\n+}\n+\n+struct debug_reflog {\n+\tconst char *refname;\n+\teach_reflog_ent_fn *fn;\n+\tvoid *cb_data;\n+};\n+\n+static int debug_print_reflog_ent(struct object_id *old_oid,\n+\t\t\t\t struct object_id *new_oid,\n+\t\t\t\t const char *committer, timestamp_t timestamp,\n+\t\t\t\t int tz, const char *msg, void *cb_data)\n+{\n+\tstruct debug_reflog *dbg = (struct debug_reflog *)cb_data;\n+\tint ret;\n+\tchar o[100] = \"null\";\n+\tchar n[100] = \"null\";\n+\tif (old_oid)\n+\t\toid_to_hex_r(o, old_oid);\n+\tif (new_oid)\n+\t\toid_to_hex_r(n, new_oid);\n+\n+\tret = dbg->fn(old_oid, new_oid, committer, timestamp, tz, msg,\n+\t\t dbg->cb_data);\n+\ttrace_printf_key(&trace_refs, \"reflog_ent %s (ret %d): %s -> %s, %s %ld \\\"%s\\\"\\n\",\n+\t\tdbg->refname, ret, o, n, committer, (long int)timestamp, msg);\n+\treturn ret;\n+}\n+\n+static int debug_for_each_reflog_ent(struct ref_store *ref_store,\n+\t\t\t\t const char *refname, each_reflog_ent_fn fn,\n+\t\t\t\t void *cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct debug_reflog dbg = {\n+\t\t.refname = refname,\n+\t\t.fn = fn,\n+\t\t.cb_data = cb_data,\n+\t};\n+\n+\tint res = drefs->refs->be->for_each_reflog_ent(\n+\t\tdrefs->refs, refname, &debug_print_reflog_ent, &dbg);\n+\ttrace_printf_key(&trace_refs, \"for_each_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_for_each_reflog_ent_reverse(struct ref_store *ref_store,\n+\t\t\t\t\t const char *refname,\n+\t\t\t\t\t each_reflog_ent_fn fn,\n+\t\t\t\t\t void *cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct debug_reflog dbg = {\n+\t\t.refname = refname,\n+\t\t.fn = fn,\n+\t\t.cb_data = cb_data,\n+\t};\n+\tint res = drefs->refs->be->for_each_reflog_ent_reverse(\n+\t\tdrefs->refs, refname, &debug_print_reflog_ent, &dbg);\n+\ttrace_printf_key(&trace_refs, \"for_each_reflog_reverse: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_reflog_exists(struct ref_store *ref_store, const char *refname)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->reflog_exists(drefs->refs, refname);\n+\ttrace_printf_key(&trace_refs, \"reflog_exists: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_create_reflog(struct ref_store *ref_store, const char *refname,\n+\t\t\t int force_create, struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->create_reflog(drefs->refs, refname,\n+\t\t\t\t\t\t force_create, err);\n+\ttrace_printf_key(&trace_refs, \"create_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_delete_reflog(struct ref_store *ref_store, const char *refname)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->delete_reflog(drefs->refs, refname);\n+\ttrace_printf_key(&trace_refs, \"delete_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_reflog_expire(struct ref_store *ref_store, const char *refname,\n+\t\t\t const struct object_id *oid, unsigned int flags,\n+\t\t\t reflog_expiry_prepare_fn prepare_fn,\n+\t\t\t reflog_expiry_should_prune_fn should_prune_fn,\n+\t\t\t reflog_expiry_cleanup_fn cleanup_fn,\n+\t\t\t void *policy_cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->reflog_expire(drefs->refs, refname, oid,\n+\t\t\t\t\t\t flags, prepare_fn,\n+\t\t\t\t\t\t should_prune_fn, cleanup_fn,\n+\t\t\t\t\t\t policy_cb_data);\n+\ttrace_printf_key(&trace_refs, \"reflog_expire: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+struct ref_storage_be refs_be_debug = {\n+\tNULL,\n+\t\"debug\",\n+\tNULL,\n+\tdebug_init_db,\n+\tdebug_transaction_prepare,\n+\tdebug_transaction_finish,\n+\tdebug_transaction_abort,\n+\tdebug_initial_transaction_commit,\n+\n+\tdebug_pack_refs,\n+\tdebug_create_symref,\n+\tdebug_delete_refs,\n+\tdebug_rename_ref,\n+\tdebug_copy_ref,\n+\n+\tdebug_ref_iterator_begin,\n+\tdebug_read_raw_ref,\n+\n+\tdebug_reflog_iterator_begin,\n+\tdebug_for_each_reflog_ent,\n+\tdebug_for_each_reflog_ent_reverse,\n+\tdebug_reflog_exists,\n+\tdebug_create_reflog,\n+\tdebug_delete_reflog,\n+\tdebug_reflog_expire,\n+};\ndiff --git a/refs/refs-internal.h b/refs/refs-internal.h\nindex 527b0a6e2e..fecde40baf 100644\n--- a/refs/refs-internal.h\n+++ b/refs/refs-internal.h\n@@ -690,4 +690,9 @@ int parse_loose_ref_contents(const char *buf, struct object_id *oid,\n void base_ref_store_init(struct ref_store *refs,\n \t\t\t const struct ref_storage_be *be);\n \n+/*\n+ * Support GIT_TRACE_REFS by optionally wrapping the given ref_store instance.\n+ */\n+struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store);\n+\n #endif /* REFS_REFS_INTERNAL_H */\n\nbase-commit: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a\n-- \ngitgitgadget\n"},{"id":"405203","messageId":"xmqq7dt4x957.fsf@gitster.c.googlers.com","threadId":"54152","inReplyTo":"pull.713.v2.git.1599492274909.gitgitgadget@gmail.com","subject":"Re: [PATCH v2] refs: add GIT_TRACE_REFS debugging mechanism","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-09-08T21:15:32Z","receivedAt":"2020-09-08T21:15:41Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"\"Han-Wen Nienhuys via GitGitGadget\" writes:\n\n> diff --git a/refs.c b/refs.c\n> index 156fdcd459..5febfe2281 100644\n> --- a/refs.c\n> +++ b/refs.c\n> @@ -1774,6 +1774,7 @@ struct ref_store *get_main_ref_store(struct repository *r)\n> \t\tBUG(\"attempting to get main_ref_store outside of repository\");\n> \n> \tr->refs_private = ref_store_init(r->gitdir, REF_STORE_ALL_CAPS);\n> +\tr->refs_private = maybe_debug_wrap_ref_store(r->gitdir, r->refs_private);\n\nSo the idea is to capture calls to backend, emit tracing events and\ndefer to the real backend?\n\nCute. I like it.\n\n> diff --git a/refs/debug.c b/refs/debug.c\n> new file mode 100644\n> index 0000000000..68ae531b45\n> --- /dev/null\n> +++ b/refs/debug.c\n> @@ -0,0 +1,396 @@\n> +\n> +#include \"refs-internal.h\"\n> +#include \"trace.h\"\n> +\n> +static struct trace_key trace_refs = TRACE_KEY_INIT(REFS);\n> +\n> +struct debug_ref_store {\n> +\tstruct ref_store base;\n> +\tstruct ref_store *refs;\n> +};\n> +\n> +extern struct ref_storage_be refs_be_debug;\n> +\n> +struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store)\n> +{\n> +\tstruct debug_ref_store *res;\n> +\tstruct ref_storage_be *be_copy;\n> +\n> +\tif (!trace_want(&trace_refs)) {\n> +\t\treturn store;\n> +\t}\n> +\tres = malloc(sizeof(struct debug_ref_store));\n> +\tbe_copy = malloc(sizeof(*be_copy));\n\nNot xmalloc() and friends?\n\n> +\t*be_copy = refs_be_debug;\n> +\tbe_copy->name = store->be->name;\n\nI guess we never destroy the ref-store instances so it is OK to\nassume that it would not cause problems later by sharing pieces of\nmemory with underlying \"real\" thing like this.\n\n> +\ttrace_printf_key(&trace_refs, \"ref_store for %s\\n\", gitdir);\n> +\tres->refs = store;\n> +\tbase_ref_store_init((struct ref_store *)res, be_copy);\n> +\treturn (struct ref_store *)res;\n> +}\n> + ...\n> +static void print_update(int i, const char *refname,\n> +\t\t\t const struct object_id *old_oid,\n> +\t\t\t const struct object_id *new_oid, unsigned int flags,\n> +\t\t\t unsigned int type, const char *msg)\n> +{\n> +\tchar o[200] = \"null\";\n> +\tchar n[200] = \"null\";\n\nI thought we had better constant than 200 (later you use 100 in the\nsame patch). I am not sure how I feel about \"null\"; all places in\nGit, we tend to use 0{length-of-the-hash} for \"no object name on\nthis side\", I think.\n\n> +\tif (old_oid)\n> +\t\toid_to_hex_r(o, old_oid);\n> +\tif (new_oid)\n> +\t\toid_to_hex_r(n, new_oid);\n> +\n> +\ttype &= 0xf; /* see refs.h REF_* */\n> +\tflags &= REF_HAVE_NEW | REF_HAVE_OLD | REF_NO_DEREF |\n> +\t\tREF_FORCE_CREATE_REFLOG;\n> +\ttrace_printf_key(&trace_refs, \"%d: %s %s -> %s (F=0x%x, T=0x%x) \\\"%s\\\"\\n\", i, refname,\n> +\t\to, n, flags, type, msg);\n> +}\n> +\n> +static void print_transaction(struct ref_transaction *transaction)\n> +{\n> +\ttrace_printf_key(&trace_refs, \"transaction {\\n\");\n> +\tfor (int i = 0; i < transaction->nr; i++) {\n\nWe still do not allow variable decl inside the set-up part of a\nfor(;;) statement, if I recall Documentation/CodingGuidelines\ncorrectly.\n\n> +static int debug_delete_refs(struct ref_store *ref_store, const char *msg,\n> +\t\t\t struct string_list *refnames, unsigned int flags)\n> +{\n> +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n> +\tint res =\n> +\t\tdrefs->refs->be->delete_refs(drefs->refs, msg, refnames, flags);\n> +\tint i = 0;\n\nNo need to initialize 'i' here.\n\n> +\ttrace_printf_key(&trace_refs, \"delete_refs {\\n\");\n> +\tfor (i = 0; i < refnames->nr; i++)\n> +\t\ttrace_printf_key(&trace_refs, \"%s\\n\", refnames->items[i].string);\n> +\ttrace_printf_key(&trace_refs, \"}: %d\\n\", res);\n> +\treturn res;\n> +}\n\nThanks.\n"},{"id":"405238","messageId":"CAFQ2z_OOCvFH-+FNdPWjQ=vGwgeBdVzMjt8avm6AkX=H81kPdQ@mail.gmail.com","threadId":"54152","inReplyTo":"xmqq7dt4x957.fsf@gitster.c.googlers.com","subject":"Re: [PATCH v2] refs: add GIT_TRACE_REFS debugging mechanism","fromName":"Han-Wen Nienhuys","fromEmail":"hanwen@google.com","sentAt":"2020-09-09T09:43:34Z","receivedAt":"2020-09-09T09:44:08Z","isPatch":true,"sender":{"key":"hanwen@google.com","avatar":"https://avatars.githubusercontent.com/u/31547?v=4"},"body":"On Tue, Sep 8, 2020 at 11:15 PM Junio C Hamano wrote:\n> Cute. I like it.\n\nthanks :)\n\n> > + res = malloc(sizeof(struct debug_ref_store));\n> > + be_copy = malloc(sizeof(*be_copy));\n>\n> Not xmalloc() and friends?\n\ndone.\n\n>\n> > + *be_copy = refs_be_debug;\n> > + be_copy->name = store->be->name;\n>\n> I guess we never destroy the ref-store instances so it is OK to\n> assume that it would not cause problems later by sharing pieces of\n> memory with underlying \"real\" thing like this.\n\ncorrect. But changed to xstrdup to avoid confusion.\n\n> > + char o[200] = \"null\";\n> > + char n[200] = \"null\";\n>\n> I thought we had better constant than 200 (later you use 100 in the\n\ndone.\n\n> same patch). I am not sure how I feel about \"null\"; all places in\n> Git, we tend to use 0{length-of-the-hash} for \"no object name on\n> this side\", I think.\n\nSome functions take NULL as a legitimate parameter, eg. a transaction\nupdate with NULL as old OID (don't check old OID) is different from an\nupdate with 0{40} as old OID. (ref must not exist yet).\n\n> > + for (int i = 0; i < transaction->nr; i++) {\n>\n> We still do not allow variable decl inside the set-up part of a\n> for(;;) statement, if I recall Documentation/CodingGuidelines\n> correctly.\n\nFixed.\n\n> > +static int debug_delete_refs(struct ref_store *ref_store, const char *msg,\n> > + struct string_list *refnames, unsigned int flags)\n> > +{\n> > + struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n> > + int res =\n> > + drefs->refs->be->delete_refs(drefs->refs, msg, refnames, flags);\n> > + int i = 0;\n>\n> No need to initialize 'i' here.\n\nFixed.\n\n-- \nHan-Wen Nienhuys - Google Munich\nI work 80%. Don't expect answers from me on Fridays.\n--\n\nGoogle Germany GmbH, Erika-Mann-Strasse 33, 80636 Munich\n\nRegistergericht und -nummer: Hamburg, HRB 86891\n\nSitz der Gesellschaft: Hamburg\n\nGeschäftsführer: Paul Manicle, Halimah DeLaine Prado\n"},{"id":"405240","messageId":"pull.713.v3.git.1599646508673.gitgitgadget@gmail.com","threadId":"54152","inReplyTo":"pull.713.v2.git.1599492274909.gitgitgadget@gmail.com","subject":"[PATCH v3] refs: add GIT_TRACE_REFS debugging mechanism","fromName":"Han-Wen Nienhuys via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-09-09T10:15:08Z","receivedAt":"2020-09-09T10:15:21Z","isPatch":true,"sender":{"key":"hanwen@google.com","avatar":"https://avatars.githubusercontent.com/u/31547?v=4"},"body":"From: Han-Wen Nienhuys \n\nWhen set in the environment, GIT_TRACE_REFS makes git print operations and\nresults as they flow through the ref storage backend. This helps debug\ndiscrepancies between different ref backends.\n\nExample:\n\n $ GIT_TRACE_REFS=\"1\" ./git branch\n 15:42:09.769631 refs/debug.c:26 ref_store for .git\n 15:42:09.769681 refs/debug.c:249 read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0\n 15:42:09.769695 refs/debug.c:249 read_raw_ref: refs/heads/ref-debug: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a (=> refs/heads/ref-debug) type 0: 0\n 15:42:09.770282 refs/debug.c:233 ref_iterator_begin: refs/heads/ (0x1)\n 15:42:09.770290 refs/debug.c:189 iterator_advance: refs/heads/b4 (0)\n 15:42:09.770295 refs/debug.c:189 iterator_advance: refs/heads/branch3 (0)\n\nSigned-off-by: Han-Wen Nienhuys \n---\n refs: add GIT_TRACE_REFS debugging mechanism\n \n When set in the environment, GIT_TRACE_REFS makes git print operations\n and results as they flow through the ref storage backend. This helps\n debug discrepancies between different ref backends.\n \n Example:\n \n $ GIT_TRACE_REFS=\"1\" ./git branch\n 15:42:09.769631 refs/debug.c:26 ref_store for .git\n 15:42:09.769681 refs/debug.c:249 read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0\n 15:42:09.769695 refs/debug.c:249 read_raw_ref: refs/heads/ref-debug: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a (=> refs/heads/ref-debug) type 0: 0\n 15:42:09.770282 refs/debug.c:233 ref_iterator_begin: refs/heads/ (0x1)\n 15:42:09.770290 refs/debug.c:189 iterator_advance: refs/heads/b4 (0)\n 15:42:09.770295 refs/debug.c:189 iterator_advance: refs/heads/branch3 (0)\n \n Signed-off-by: Han-Wen Nienhuys hanwen@google.com [hanwen@google.com]\n\nPublished-As: https://github.com/gitgitgadget/git/releases/tag/pr-713%2Fhanwen%2Fdebug-refs-v3\nFetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-713/hanwen/debug-refs-v3\nPull-Request: https://github.com/gitgitgadget/git/pull/713\n\nRange-diff vs v2:\n\n 1: 19330e894c ! 1: e19e2a3433 refs: add GIT_TRACE_REFS debugging mechanism\n @@ refs/debug.c (new)\n +\tif (!trace_want(&trace_refs)) {\n +\t\treturn store;\n +\t}\n -+\tres = malloc(sizeof(struct debug_ref_store));\n -+\tbe_copy = malloc(sizeof(*be_copy));\n ++\tres = xmalloc(sizeof(struct debug_ref_store));\n ++\tbe_copy = xmalloc(sizeof(*be_copy));\n +\t*be_copy = refs_be_debug;\n ++\t/* we never deallocate backends, so safe to copy the pointer. */\n +\tbe_copy->name = store->be->name;\n +\ttrace_printf_key(&trace_refs, \"ref_store for %s\\n\", gitdir);\n +\tres->refs = store;\n @@ refs/debug.c (new)\n +\t\t\t const struct object_id *new_oid, unsigned int flags,\n +\t\t\t unsigned int type, const char *msg)\n +{\n -+\tchar o[200] = \"null\";\n -+\tchar n[200] = \"null\";\n ++\tchar o[GIT_MAX_HEXSZ + 1] = \"null\";\n ++\tchar n[GIT_MAX_HEXSZ + 1] = \"null\";\n +\tif (old_oid)\n +\t\toid_to_hex_r(o, old_oid);\n +\tif (new_oid)\n @@ refs/debug.c (new)\n +\n +static void print_transaction(struct ref_transaction *transaction)\n +{\n ++\tint i;\n +\ttrace_printf_key(&trace_refs, \"transaction {\\n\");\n -+\tfor (int i = 0; i < transaction->nr; i++) {\n ++\tfor (i = 0; i < transaction->nr; i++) {\n +\t\tstruct ref_update *u = transaction->updates[i];\n +\t\tprint_update(i, u->refname, &u->old_oid, &u->new_oid, u->flags,\n +\t\t\t u->type, u->msg);\n @@ refs/debug.c (new)\n +\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n +\tint res =\n +\t\tdrefs->refs->be->delete_refs(drefs->refs, msg, refnames, flags);\n -+\tint i = 0;\n ++\tint i;\n +\ttrace_printf_key(&trace_refs, \"delete_refs {\\n\");\n +\tfor (i = 0; i < refnames->nr; i++)\n +\t\ttrace_printf_key(&trace_refs, \"%s\\n\", refnames->items[i].string);\n @@ refs/debug.c (new)\n +{\n +\tstruct debug_reflog *dbg = (struct debug_reflog *)cb_data;\n +\tint ret;\n -+\tchar o[100] = \"null\";\n -+\tchar n[100] = \"null\";\n ++\tchar o[GIT_MAX_HEXSZ + 1] = \"null\";\n ++\tchar n[GIT_MAX_HEXSZ + 1] = \"null\";\n +\tif (old_oid)\n +\t\toid_to_hex_r(o, old_oid);\n +\tif (new_oid)\n\n\n Documentation/git.txt | 4 +\n Makefile | 1 +\n refs.c | 1 +\n refs/debug.c | 398 ++++++++++++++++++++++++++++++++++++++++++\n refs/refs-internal.h | 5 +\n 5 files changed, 409 insertions(+)\n create mode 100644 refs/debug.c\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex 2f72b10224..c463b937a8 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -722,6 +722,10 @@ of clones and fetches.\n \ttime of each Git command.\n \tSee `GIT_TRACE` for available trace output options.\n \n+`GIT_TRACE_REFS`::\n+\tEnables trace messages for operations on the ref database.\n+\tSee `GIT_TRACE` for available trace output options.\n+\n `GIT_TRACE_SETUP`::\n \tEnables trace messages printing the .git, working tree and current\n \tworking directory after Git has completed its setup phase.\ndiff --git a/Makefile b/Makefile\nindex 86e5411f39..583b8c526e 100644\n--- a/Makefile\n+++ b/Makefile\n@@ -950,6 +950,7 @@ LIB_OBJS += rebase.o\n LIB_OBJS += ref-filter.o\n LIB_OBJS += reflog-walk.o\n LIB_OBJS += refs.o\n+LIB_OBJS += refs/debug.o\n LIB_OBJS += refs/files-backend.o\n LIB_OBJS += refs/iterator.o\n LIB_OBJS += refs/packed-backend.o\ndiff --git a/refs.c b/refs.c\nindex 156fdcd459..5febfe2281 100644\n--- a/refs.c\n+++ b/refs.c\n@@ -1774,6 +1774,7 @@ struct ref_store *get_main_ref_store(struct repository *r)\n \t\tBUG(\"attempting to get main_ref_store outside of repository\");\n \n \tr->refs_private = ref_store_init(r->gitdir, REF_STORE_ALL_CAPS);\n+\tr->refs_private = maybe_debug_wrap_ref_store(r->gitdir, r->refs_private);\n \treturn r->refs_private;\n }\n \ndiff --git a/refs/debug.c b/refs/debug.c\nnew file mode 100644\nindex 0000000000..922e64fa6a\n--- /dev/null\n+++ b/refs/debug.c\n@@ -0,0 +1,398 @@\n+\n+#include \"refs-internal.h\"\n+#include \"trace.h\"\n+\n+static struct trace_key trace_refs = TRACE_KEY_INIT(REFS);\n+\n+struct debug_ref_store {\n+\tstruct ref_store base;\n+\tstruct ref_store *refs;\n+};\n+\n+extern struct ref_storage_be refs_be_debug;\n+\n+struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store)\n+{\n+\tstruct debug_ref_store *res;\n+\tstruct ref_storage_be *be_copy;\n+\n+\tif (!trace_want(&trace_refs)) {\n+\t\treturn store;\n+\t}\n+\tres = xmalloc(sizeof(struct debug_ref_store));\n+\tbe_copy = xmalloc(sizeof(*be_copy));\n+\t*be_copy = refs_be_debug;\n+\t/* we never deallocate backends, so safe to copy the pointer. */\n+\tbe_copy->name = store->be->name;\n+\ttrace_printf_key(&trace_refs, \"ref_store for %s\\n\", gitdir);\n+\tres->refs = store;\n+\tbase_ref_store_init((struct ref_store *)res, be_copy);\n+\treturn (struct ref_store *)res;\n+}\n+\n+static int debug_init_db(struct ref_store *refs, struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res = drefs->refs->be->init_db(drefs->refs, err);\n+\ttrace_printf_key(&trace_refs, \"init_db: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_transaction_prepare(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_prepare(drefs->refs, transaction,\n+\t\t\t\t\t\t err);\n+\ttrace_printf_key(&trace_refs, \"transaction_prepare: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static void print_update(int i, const char *refname,\n+\t\t\t const struct object_id *old_oid,\n+\t\t\t const struct object_id *new_oid, unsigned int flags,\n+\t\t\t unsigned int type, const char *msg)\n+{\n+\tchar o[GIT_MAX_HEXSZ + 1] = \"null\";\n+\tchar n[GIT_MAX_HEXSZ + 1] = \"null\";\n+\tif (old_oid)\n+\t\toid_to_hex_r(o, old_oid);\n+\tif (new_oid)\n+\t\toid_to_hex_r(n, new_oid);\n+\n+\ttype &= 0xf; /* see refs.h REF_* */\n+\tflags &= REF_HAVE_NEW | REF_HAVE_OLD | REF_NO_DEREF |\n+\t\tREF_FORCE_CREATE_REFLOG;\n+\ttrace_printf_key(&trace_refs, \"%d: %s %s -> %s (F=0x%x, T=0x%x) \\\"%s\\\"\\n\", i, refname,\n+\t\to, n, flags, type, msg);\n+}\n+\n+static void print_transaction(struct ref_transaction *transaction)\n+{\n+\tint i;\n+\ttrace_printf_key(&trace_refs, \"transaction {\\n\");\n+\tfor (i = 0; i < transaction->nr; i++) {\n+\t\tstruct ref_update *u = transaction->updates[i];\n+\t\tprint_update(i, u->refname, &u->old_oid, &u->new_oid, u->flags,\n+\t\t\t u->type, u->msg);\n+\t}\n+\ttrace_printf_key(&trace_refs, \"}\\n\");\n+}\n+\n+static int debug_transaction_finish(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_finish(drefs->refs, transaction,\n+\t\t\t\t\t\t err);\n+\tprint_transaction(transaction);\n+\ttrace_printf_key(&trace_refs, \"finish: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_transaction_abort(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_abort(drefs->refs, transaction, err);\n+\treturn res;\n+}\n+\n+static int debug_initial_transaction_commit(struct ref_store *refs,\n+\t\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->initial_transaction_commit(drefs->refs,\n+\t\t\t\t\t\t\t transaction, err);\n+\treturn res;\n+}\n+\n+static int debug_pack_refs(struct ref_store *ref_store, unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->pack_refs(drefs->refs, flags);\n+\ttrace_printf_key(&trace_refs, \"pack_refs: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_create_symref(struct ref_store *ref_store,\n+\t\t\t const char *ref_name, const char *target,\n+\t\t\t const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->create_symref(drefs->refs, ref_name, target,\n+\t\t\t\t\t\t logmsg);\n+\ttrace_printf_key(&trace_refs, \"create_symref: %s -> %s \\\"%s\\\": %d\\n\", ref_name,\n+\t\ttarget, logmsg, res);\n+\treturn res;\n+}\n+\n+static int debug_delete_refs(struct ref_store *ref_store, const char *msg,\n+\t\t\t struct string_list *refnames, unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res =\n+\t\tdrefs->refs->be->delete_refs(drefs->refs, msg, refnames, flags);\n+\tint i;\n+\ttrace_printf_key(&trace_refs, \"delete_refs {\\n\");\n+\tfor (i = 0; i < refnames->nr; i++)\n+\t\ttrace_printf_key(&trace_refs, \"%s\\n\", refnames->items[i].string);\n+\ttrace_printf_key(&trace_refs, \"}: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_rename_ref(struct ref_store *ref_store, const char *oldref,\n+\t\t\t const char *newref, const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->rename_ref(drefs->refs, oldref, newref,\n+\t\t\t\t\t logmsg);\n+\ttrace_printf_key(&trace_refs, \"rename_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n+\t\tlogmsg, res);\n+\treturn res;\n+}\n+\n+static int debug_copy_ref(struct ref_store *ref_store, const char *oldref,\n+\t\t\t const char *newref, const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res =\n+\t\tdrefs->refs->be->copy_ref(drefs->refs, oldref, newref, logmsg);\n+\ttrace_printf_key(&trace_refs, \"copy_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n+\t\tlogmsg, res);\n+\treturn res;\n+}\n+\n+struct debug_ref_iterator {\n+\tstruct ref_iterator base;\n+\tstruct ref_iterator *iter;\n+};\n+\n+static int debug_ref_iterator_advance(struct ref_iterator *ref_iterator)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->advance(diter->iter);\n+\tif (res)\n+\t\ttrace_printf_key(&trace_refs, \"iterator_advance: (%d)\\n\", res);\n+\telse\n+\t\ttrace_printf_key(&trace_refs, \"iterator_advance: %s (0)\\n\",\n+\t\t\tditer->iter->refname);\n+\n+\tditer->base.ordered = diter->iter->ordered;\n+\tditer->base.refname = diter->iter->refname;\n+\tditer->base.oid = diter->iter->oid;\n+\tditer->base.flags = diter->iter->flags;\n+\treturn res;\n+}\n+\n+static int debug_ref_iterator_peel(struct ref_iterator *ref_iterator,\n+\t\t\t\t struct object_id *peeled)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->peel(diter->iter, peeled);\n+\ttrace_printf_key(&trace_refs, \"iterator_peel: %s: %d\\n\", diter->iter->refname, res);\n+\treturn res;\n+}\n+\n+static int debug_ref_iterator_abort(struct ref_iterator *ref_iterator)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->abort(diter->iter);\n+\ttrace_printf_key(&trace_refs, \"iterator_abort: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static struct ref_iterator_vtable debug_ref_iterator_vtable = {\n+\tdebug_ref_iterator_advance, debug_ref_iterator_peel,\n+\tdebug_ref_iterator_abort\n+};\n+\n+static struct ref_iterator *\n+debug_ref_iterator_begin(struct ref_store *ref_store, const char *prefix,\n+\t\t\t unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct ref_iterator *res =\n+\t\tdrefs->refs->be->iterator_begin(drefs->refs, prefix, flags);\n+\tstruct debug_ref_iterator *diter = xcalloc(1, sizeof(*diter));\n+\tbase_ref_iterator_init(&diter->base, &debug_ref_iterator_vtable, 1);\n+\tditer->iter = res;\n+\ttrace_printf_key(&trace_refs, \"ref_iterator_begin: %s (0x%x)\\n\", prefix, flags);\n+\treturn &diter->base;\n+}\n+\n+static int debug_read_raw_ref(struct ref_store *ref_store, const char *refname,\n+\t\t\t struct object_id *oid, struct strbuf *referent,\n+\t\t\t unsigned int *type)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = 0;\n+\n+\toidcpy(oid, &null_oid);\n+\tres = drefs->refs->be->read_raw_ref(drefs->refs, refname, oid, referent,\n+\t\t\t\t\t type);\n+\n+\tif (res == 0) {\n+\t\ttrace_printf_key(&trace_refs, \"read_raw_ref: %s: %s (=> %s) type %x: %d\\n\",\n+\t\t\trefname, oid_to_hex(oid), referent->buf, *type, res);\n+\t} else {\n+\t\ttrace_printf_key(&trace_refs, \"read_raw_ref: %s: %d\\n\", refname, res);\n+\t}\n+\treturn res;\n+}\n+\n+static struct ref_iterator *\n+debug_reflog_iterator_begin(struct ref_store *ref_store)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct ref_iterator *res =\n+\t\tdrefs->refs->be->reflog_iterator_begin(drefs->refs);\n+\ttrace_printf_key(&trace_refs, \"for_each_reflog_iterator_begin\\n\");\n+\treturn res;\n+}\n+\n+struct debug_reflog {\n+\tconst char *refname;\n+\teach_reflog_ent_fn *fn;\n+\tvoid *cb_data;\n+};\n+\n+static int debug_print_reflog_ent(struct object_id *old_oid,\n+\t\t\t\t struct object_id *new_oid,\n+\t\t\t\t const char *committer, timestamp_t timestamp,\n+\t\t\t\t int tz, const char *msg, void *cb_data)\n+{\n+\tstruct debug_reflog *dbg = (struct debug_reflog *)cb_data;\n+\tint ret;\n+\tchar o[GIT_MAX_HEXSZ + 1] = \"null\";\n+\tchar n[GIT_MAX_HEXSZ + 1] = \"null\";\n+\tif (old_oid)\n+\t\toid_to_hex_r(o, old_oid);\n+\tif (new_oid)\n+\t\toid_to_hex_r(n, new_oid);\n+\n+\tret = dbg->fn(old_oid, new_oid, committer, timestamp, tz, msg,\n+\t\t dbg->cb_data);\n+\ttrace_printf_key(&trace_refs, \"reflog_ent %s (ret %d): %s -> %s, %s %ld \\\"%s\\\"\\n\",\n+\t\tdbg->refname, ret, o, n, committer, (long int)timestamp, msg);\n+\treturn ret;\n+}\n+\n+static int debug_for_each_reflog_ent(struct ref_store *ref_store,\n+\t\t\t\t const char *refname, each_reflog_ent_fn fn,\n+\t\t\t\t void *cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct debug_reflog dbg = {\n+\t\t.refname = refname,\n+\t\t.fn = fn,\n+\t\t.cb_data = cb_data,\n+\t};\n+\n+\tint res = drefs->refs->be->for_each_reflog_ent(\n+\t\tdrefs->refs, refname, &debug_print_reflog_ent, &dbg);\n+\ttrace_printf_key(&trace_refs, \"for_each_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_for_each_reflog_ent_reverse(struct ref_store *ref_store,\n+\t\t\t\t\t const char *refname,\n+\t\t\t\t\t each_reflog_ent_fn fn,\n+\t\t\t\t\t void *cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct debug_reflog dbg = {\n+\t\t.refname = refname,\n+\t\t.fn = fn,\n+\t\t.cb_data = cb_data,\n+\t};\n+\tint res = drefs->refs->be->for_each_reflog_ent_reverse(\n+\t\tdrefs->refs, refname, &debug_print_reflog_ent, &dbg);\n+\ttrace_printf_key(&trace_refs, \"for_each_reflog_reverse: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_reflog_exists(struct ref_store *ref_store, const char *refname)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->reflog_exists(drefs->refs, refname);\n+\ttrace_printf_key(&trace_refs, \"reflog_exists: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_create_reflog(struct ref_store *ref_store, const char *refname,\n+\t\t\t int force_create, struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->create_reflog(drefs->refs, refname,\n+\t\t\t\t\t\t force_create, err);\n+\ttrace_printf_key(&trace_refs, \"create_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_delete_reflog(struct ref_store *ref_store, const char *refname)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->delete_reflog(drefs->refs, refname);\n+\ttrace_printf_key(&trace_refs, \"delete_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_reflog_expire(struct ref_store *ref_store, const char *refname,\n+\t\t\t const struct object_id *oid, unsigned int flags,\n+\t\t\t reflog_expiry_prepare_fn prepare_fn,\n+\t\t\t reflog_expiry_should_prune_fn should_prune_fn,\n+\t\t\t reflog_expiry_cleanup_fn cleanup_fn,\n+\t\t\t void *policy_cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->reflog_expire(drefs->refs, refname, oid,\n+\t\t\t\t\t\t flags, prepare_fn,\n+\t\t\t\t\t\t should_prune_fn, cleanup_fn,\n+\t\t\t\t\t\t policy_cb_data);\n+\ttrace_printf_key(&trace_refs, \"reflog_expire: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+struct ref_storage_be refs_be_debug = {\n+\tNULL,\n+\t\"debug\",\n+\tNULL,\n+\tdebug_init_db,\n+\tdebug_transaction_prepare,\n+\tdebug_transaction_finish,\n+\tdebug_transaction_abort,\n+\tdebug_initial_transaction_commit,\n+\n+\tdebug_pack_refs,\n+\tdebug_create_symref,\n+\tdebug_delete_refs,\n+\tdebug_rename_ref,\n+\tdebug_copy_ref,\n+\n+\tdebug_ref_iterator_begin,\n+\tdebug_read_raw_ref,\n+\n+\tdebug_reflog_iterator_begin,\n+\tdebug_for_each_reflog_ent,\n+\tdebug_for_each_reflog_ent_reverse,\n+\tdebug_reflog_exists,\n+\tdebug_create_reflog,\n+\tdebug_delete_reflog,\n+\tdebug_reflog_expire,\n+};\ndiff --git a/refs/refs-internal.h b/refs/refs-internal.h\nindex 527b0a6e2e..fecde40baf 100644\n--- a/refs/refs-internal.h\n+++ b/refs/refs-internal.h\n@@ -690,4 +690,9 @@ int parse_loose_ref_contents(const char *buf, struct object_id *oid,\n void base_ref_store_init(struct ref_store *refs,\n \t\t\t const struct ref_storage_be *be);\n \n+/*\n+ * Support GIT_TRACE_REFS by optionally wrapping the given ref_store instance.\n+ */\n+struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store);\n+\n #endif /* REFS_REFS_INTERNAL_H */\n\nbase-commit: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a\n-- \ngitgitgadget\n"},{"id":"405696","messageId":"pull.713.v4.git.1600271602620.gitgitgadget@gmail.com","threadId":"54152","inReplyTo":"pull.713.v3.git.1599646508673.gitgitgadget@gmail.com","subject":"[PATCH v4] refs: add GIT_TRACE_REFS debugging mechanism","fromName":"Han-Wen Nienhuys via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-09-16T15:53:22Z","receivedAt":"2020-09-16T21:10:11Z","isPatch":true,"sender":{"key":"hanwen@google.com","avatar":"https://avatars.githubusercontent.com/u/31547?v=4"},"body":"From: Han-Wen Nienhuys \n\nWhen set in the environment, GIT_TRACE_REFS makes git print operations and\nresults as they flow through the ref storage backend. This helps debug\ndiscrepancies between different ref backends.\n\nExample:\n\n $ GIT_TRACE_REFS=\"1\" ./git branch\n 15:42:09.769631 refs/debug.c:26 ref_store for .git\n 15:42:09.769681 refs/debug.c:249 read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0\n 15:42:09.769695 refs/debug.c:249 read_raw_ref: refs/heads/ref-debug: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a (=> refs/heads/ref-debug) type 0: 0\n 15:42:09.770282 refs/debug.c:233 ref_iterator_begin: refs/heads/ (0x1)\n 15:42:09.770290 refs/debug.c:189 iterator_advance: refs/heads/b4 (0)\n 15:42:09.770295 refs/debug.c:189 iterator_advance: refs/heads/branch3 (0)\n\nSigned-off-by: Han-Wen Nienhuys \n---\n refs: add GIT_TRACE_REFS debugging mechanism\n \n When set in the environment, GIT_TRACE_REFS makes git print operations\n and results as they flow through the ref storage backend. This helps\n debug discrepancies between different ref backends.\n \n cc: Jonathan Tan jonathantanmy@google.com [jonathantanmy@google.com]cc:\n Jonathan Nieder jrnieder@gmail.com [jrnieder@gmail.com]cc: Jeff King \n peff@peff.net [peff@peff.net]cc: Han-Wen Nienhuys hanwen@google.com\n [hanwen@google.com]\n \n v3: use xstrdup to copy backend name; I forgot to commit this bit in the\n last round.\n\nPublished-As: https://github.com/gitgitgadget/git/releases/tag/pr-713%2Fhanwen%2Fdebug-refs-v4\nFetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-713/hanwen/debug-refs-v4\nPull-Request: https://github.com/gitgitgadget/git/pull/713\n\nRange-diff vs v3:\n\n 1: e19e2a3433 ! 1: e73293f0f7 refs: add GIT_TRACE_REFS debugging mechanism\n @@ refs/debug.c (new)\n +\tres = xmalloc(sizeof(struct debug_ref_store));\n +\tbe_copy = xmalloc(sizeof(*be_copy));\n +\t*be_copy = refs_be_debug;\n -+\t/* we never deallocate backends, so safe to copy the pointer. */\n -+\tbe_copy->name = store->be->name;\n ++\tbe_copy->name = xstrdup(store->be->name);\n +\ttrace_printf_key(&trace_refs, \"ref_store for %s\\n\", gitdir);\n +\tres->refs = store;\n +\tbase_ref_store_init((struct ref_store *)res, be_copy);\n\n\n Documentation/git.txt | 4 +\n Makefile | 1 +\n refs.c | 1 +\n refs/debug.c | 397 ++++++++++++++++++++++++++++++++++++++++++\n refs/refs-internal.h | 5 +\n 5 files changed, 408 insertions(+)\n create mode 100644 refs/debug.c\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex 2f72b10224..c463b937a8 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -722,6 +722,10 @@ of clones and fetches.\n \ttime of each Git command.\n \tSee `GIT_TRACE` for available trace output options.\n \n+`GIT_TRACE_REFS`::\n+\tEnables trace messages for operations on the ref database.\n+\tSee `GIT_TRACE` for available trace output options.\n+\n `GIT_TRACE_SETUP`::\n \tEnables trace messages printing the .git, working tree and current\n \tworking directory after Git has completed its setup phase.\ndiff --git a/Makefile b/Makefile\nindex 86e5411f39..583b8c526e 100644\n--- a/Makefile\n+++ b/Makefile\n@@ -950,6 +950,7 @@ LIB_OBJS += rebase.o\n LIB_OBJS += ref-filter.o\n LIB_OBJS += reflog-walk.o\n LIB_OBJS += refs.o\n+LIB_OBJS += refs/debug.o\n LIB_OBJS += refs/files-backend.o\n LIB_OBJS += refs/iterator.o\n LIB_OBJS += refs/packed-backend.o\ndiff --git a/refs.c b/refs.c\nindex 156fdcd459..5febfe2281 100644\n--- a/refs.c\n+++ b/refs.c\n@@ -1774,6 +1774,7 @@ struct ref_store *get_main_ref_store(struct repository *r)\n \t\tBUG(\"attempting to get main_ref_store outside of repository\");\n \n \tr->refs_private = ref_store_init(r->gitdir, REF_STORE_ALL_CAPS);\n+\tr->refs_private = maybe_debug_wrap_ref_store(r->gitdir, r->refs_private);\n \treturn r->refs_private;\n }\n \ndiff --git a/refs/debug.c b/refs/debug.c\nnew file mode 100644\nindex 0000000000..6588a556d0\n--- /dev/null\n+++ b/refs/debug.c\n@@ -0,0 +1,397 @@\n+\n+#include \"refs-internal.h\"\n+#include \"trace.h\"\n+\n+static struct trace_key trace_refs = TRACE_KEY_INIT(REFS);\n+\n+struct debug_ref_store {\n+\tstruct ref_store base;\n+\tstruct ref_store *refs;\n+};\n+\n+extern struct ref_storage_be refs_be_debug;\n+\n+struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store)\n+{\n+\tstruct debug_ref_store *res;\n+\tstruct ref_storage_be *be_copy;\n+\n+\tif (!trace_want(&trace_refs)) {\n+\t\treturn store;\n+\t}\n+\tres = xmalloc(sizeof(struct debug_ref_store));\n+\tbe_copy = xmalloc(sizeof(*be_copy));\n+\t*be_copy = refs_be_debug;\n+\tbe_copy->name = xstrdup(store->be->name);\n+\ttrace_printf_key(&trace_refs, \"ref_store for %s\\n\", gitdir);\n+\tres->refs = store;\n+\tbase_ref_store_init((struct ref_store *)res, be_copy);\n+\treturn (struct ref_store *)res;\n+}\n+\n+static int debug_init_db(struct ref_store *refs, struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res = drefs->refs->be->init_db(drefs->refs, err);\n+\ttrace_printf_key(&trace_refs, \"init_db: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_transaction_prepare(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_prepare(drefs->refs, transaction,\n+\t\t\t\t\t\t err);\n+\ttrace_printf_key(&trace_refs, \"transaction_prepare: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static void print_update(int i, const char *refname,\n+\t\t\t const struct object_id *old_oid,\n+\t\t\t const struct object_id *new_oid, unsigned int flags,\n+\t\t\t unsigned int type, const char *msg)\n+{\n+\tchar o[GIT_MAX_HEXSZ + 1] = \"null\";\n+\tchar n[GIT_MAX_HEXSZ + 1] = \"null\";\n+\tif (old_oid)\n+\t\toid_to_hex_r(o, old_oid);\n+\tif (new_oid)\n+\t\toid_to_hex_r(n, new_oid);\n+\n+\ttype &= 0xf; /* see refs.h REF_* */\n+\tflags &= REF_HAVE_NEW | REF_HAVE_OLD | REF_NO_DEREF |\n+\t\tREF_FORCE_CREATE_REFLOG;\n+\ttrace_printf_key(&trace_refs, \"%d: %s %s -> %s (F=0x%x, T=0x%x) \\\"%s\\\"\\n\", i, refname,\n+\t\to, n, flags, type, msg);\n+}\n+\n+static void print_transaction(struct ref_transaction *transaction)\n+{\n+\tint i;\n+\ttrace_printf_key(&trace_refs, \"transaction {\\n\");\n+\tfor (i = 0; i < transaction->nr; i++) {\n+\t\tstruct ref_update *u = transaction->updates[i];\n+\t\tprint_update(i, u->refname, &u->old_oid, &u->new_oid, u->flags,\n+\t\t\t u->type, u->msg);\n+\t}\n+\ttrace_printf_key(&trace_refs, \"}\\n\");\n+}\n+\n+static int debug_transaction_finish(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_finish(drefs->refs, transaction,\n+\t\t\t\t\t\t err);\n+\tprint_transaction(transaction);\n+\ttrace_printf_key(&trace_refs, \"finish: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_transaction_abort(struct ref_store *refs,\n+\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->transaction_abort(drefs->refs, transaction, err);\n+\treturn res;\n+}\n+\n+static int debug_initial_transaction_commit(struct ref_store *refs,\n+\t\t\t\t\t struct ref_transaction *transaction,\n+\t\t\t\t\t struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)refs;\n+\tint res;\n+\ttransaction->ref_store = drefs->refs;\n+\tres = drefs->refs->be->initial_transaction_commit(drefs->refs,\n+\t\t\t\t\t\t\t transaction, err);\n+\treturn res;\n+}\n+\n+static int debug_pack_refs(struct ref_store *ref_store, unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->pack_refs(drefs->refs, flags);\n+\ttrace_printf_key(&trace_refs, \"pack_refs: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_create_symref(struct ref_store *ref_store,\n+\t\t\t const char *ref_name, const char *target,\n+\t\t\t const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->create_symref(drefs->refs, ref_name, target,\n+\t\t\t\t\t\t logmsg);\n+\ttrace_printf_key(&trace_refs, \"create_symref: %s -> %s \\\"%s\\\": %d\\n\", ref_name,\n+\t\ttarget, logmsg, res);\n+\treturn res;\n+}\n+\n+static int debug_delete_refs(struct ref_store *ref_store, const char *msg,\n+\t\t\t struct string_list *refnames, unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res =\n+\t\tdrefs->refs->be->delete_refs(drefs->refs, msg, refnames, flags);\n+\tint i;\n+\ttrace_printf_key(&trace_refs, \"delete_refs {\\n\");\n+\tfor (i = 0; i < refnames->nr; i++)\n+\t\ttrace_printf_key(&trace_refs, \"%s\\n\", refnames->items[i].string);\n+\ttrace_printf_key(&trace_refs, \"}: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static int debug_rename_ref(struct ref_store *ref_store, const char *oldref,\n+\t\t\t const char *newref, const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->rename_ref(drefs->refs, oldref, newref,\n+\t\t\t\t\t logmsg);\n+\ttrace_printf_key(&trace_refs, \"rename_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n+\t\tlogmsg, res);\n+\treturn res;\n+}\n+\n+static int debug_copy_ref(struct ref_store *ref_store, const char *oldref,\n+\t\t\t const char *newref, const char *logmsg)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res =\n+\t\tdrefs->refs->be->copy_ref(drefs->refs, oldref, newref, logmsg);\n+\ttrace_printf_key(&trace_refs, \"copy_ref: %s -> %s \\\"%s\\\": %d\\n\", oldref, newref,\n+\t\tlogmsg, res);\n+\treturn res;\n+}\n+\n+struct debug_ref_iterator {\n+\tstruct ref_iterator base;\n+\tstruct ref_iterator *iter;\n+};\n+\n+static int debug_ref_iterator_advance(struct ref_iterator *ref_iterator)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->advance(diter->iter);\n+\tif (res)\n+\t\ttrace_printf_key(&trace_refs, \"iterator_advance: (%d)\\n\", res);\n+\telse\n+\t\ttrace_printf_key(&trace_refs, \"iterator_advance: %s (0)\\n\",\n+\t\t\tditer->iter->refname);\n+\n+\tditer->base.ordered = diter->iter->ordered;\n+\tditer->base.refname = diter->iter->refname;\n+\tditer->base.oid = diter->iter->oid;\n+\tditer->base.flags = diter->iter->flags;\n+\treturn res;\n+}\n+\n+static int debug_ref_iterator_peel(struct ref_iterator *ref_iterator,\n+\t\t\t\t struct object_id *peeled)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->peel(diter->iter, peeled);\n+\ttrace_printf_key(&trace_refs, \"iterator_peel: %s: %d\\n\", diter->iter->refname, res);\n+\treturn res;\n+}\n+\n+static int debug_ref_iterator_abort(struct ref_iterator *ref_iterator)\n+{\n+\tstruct debug_ref_iterator *diter =\n+\t\t(struct debug_ref_iterator *)ref_iterator;\n+\tint res = diter->iter->vtable->abort(diter->iter);\n+\ttrace_printf_key(&trace_refs, \"iterator_abort: %d\\n\", res);\n+\treturn res;\n+}\n+\n+static struct ref_iterator_vtable debug_ref_iterator_vtable = {\n+\tdebug_ref_iterator_advance, debug_ref_iterator_peel,\n+\tdebug_ref_iterator_abort\n+};\n+\n+static struct ref_iterator *\n+debug_ref_iterator_begin(struct ref_store *ref_store, const char *prefix,\n+\t\t\t unsigned int flags)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct ref_iterator *res =\n+\t\tdrefs->refs->be->iterator_begin(drefs->refs, prefix, flags);\n+\tstruct debug_ref_iterator *diter = xcalloc(1, sizeof(*diter));\n+\tbase_ref_iterator_init(&diter->base, &debug_ref_iterator_vtable, 1);\n+\tditer->iter = res;\n+\ttrace_printf_key(&trace_refs, \"ref_iterator_begin: %s (0x%x)\\n\", prefix, flags);\n+\treturn &diter->base;\n+}\n+\n+static int debug_read_raw_ref(struct ref_store *ref_store, const char *refname,\n+\t\t\t struct object_id *oid, struct strbuf *referent,\n+\t\t\t unsigned int *type)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = 0;\n+\n+\toidcpy(oid, &null_oid);\n+\tres = drefs->refs->be->read_raw_ref(drefs->refs, refname, oid, referent,\n+\t\t\t\t\t type);\n+\n+\tif (res == 0) {\n+\t\ttrace_printf_key(&trace_refs, \"read_raw_ref: %s: %s (=> %s) type %x: %d\\n\",\n+\t\t\trefname, oid_to_hex(oid), referent->buf, *type, res);\n+\t} else {\n+\t\ttrace_printf_key(&trace_refs, \"read_raw_ref: %s: %d\\n\", refname, res);\n+\t}\n+\treturn res;\n+}\n+\n+static struct ref_iterator *\n+debug_reflog_iterator_begin(struct ref_store *ref_store)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct ref_iterator *res =\n+\t\tdrefs->refs->be->reflog_iterator_begin(drefs->refs);\n+\ttrace_printf_key(&trace_refs, \"for_each_reflog_iterator_begin\\n\");\n+\treturn res;\n+}\n+\n+struct debug_reflog {\n+\tconst char *refname;\n+\teach_reflog_ent_fn *fn;\n+\tvoid *cb_data;\n+};\n+\n+static int debug_print_reflog_ent(struct object_id *old_oid,\n+\t\t\t\t struct object_id *new_oid,\n+\t\t\t\t const char *committer, timestamp_t timestamp,\n+\t\t\t\t int tz, const char *msg, void *cb_data)\n+{\n+\tstruct debug_reflog *dbg = (struct debug_reflog *)cb_data;\n+\tint ret;\n+\tchar o[GIT_MAX_HEXSZ + 1] = \"null\";\n+\tchar n[GIT_MAX_HEXSZ + 1] = \"null\";\n+\tif (old_oid)\n+\t\toid_to_hex_r(o, old_oid);\n+\tif (new_oid)\n+\t\toid_to_hex_r(n, new_oid);\n+\n+\tret = dbg->fn(old_oid, new_oid, committer, timestamp, tz, msg,\n+\t\t dbg->cb_data);\n+\ttrace_printf_key(&trace_refs, \"reflog_ent %s (ret %d): %s -> %s, %s %ld \\\"%s\\\"\\n\",\n+\t\tdbg->refname, ret, o, n, committer, (long int)timestamp, msg);\n+\treturn ret;\n+}\n+\n+static int debug_for_each_reflog_ent(struct ref_store *ref_store,\n+\t\t\t\t const char *refname, each_reflog_ent_fn fn,\n+\t\t\t\t void *cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct debug_reflog dbg = {\n+\t\t.refname = refname,\n+\t\t.fn = fn,\n+\t\t.cb_data = cb_data,\n+\t};\n+\n+\tint res = drefs->refs->be->for_each_reflog_ent(\n+\t\tdrefs->refs, refname, &debug_print_reflog_ent, &dbg);\n+\ttrace_printf_key(&trace_refs, \"for_each_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_for_each_reflog_ent_reverse(struct ref_store *ref_store,\n+\t\t\t\t\t const char *refname,\n+\t\t\t\t\t each_reflog_ent_fn fn,\n+\t\t\t\t\t void *cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tstruct debug_reflog dbg = {\n+\t\t.refname = refname,\n+\t\t.fn = fn,\n+\t\t.cb_data = cb_data,\n+\t};\n+\tint res = drefs->refs->be->for_each_reflog_ent_reverse(\n+\t\tdrefs->refs, refname, &debug_print_reflog_ent, &dbg);\n+\ttrace_printf_key(&trace_refs, \"for_each_reflog_reverse: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_reflog_exists(struct ref_store *ref_store, const char *refname)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->reflog_exists(drefs->refs, refname);\n+\ttrace_printf_key(&trace_refs, \"reflog_exists: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_create_reflog(struct ref_store *ref_store, const char *refname,\n+\t\t\t int force_create, struct strbuf *err)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->create_reflog(drefs->refs, refname,\n+\t\t\t\t\t\t force_create, err);\n+\ttrace_printf_key(&trace_refs, \"create_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_delete_reflog(struct ref_store *ref_store, const char *refname)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->delete_reflog(drefs->refs, refname);\n+\ttrace_printf_key(&trace_refs, \"delete_reflog: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+static int debug_reflog_expire(struct ref_store *ref_store, const char *refname,\n+\t\t\t const struct object_id *oid, unsigned int flags,\n+\t\t\t reflog_expiry_prepare_fn prepare_fn,\n+\t\t\t reflog_expiry_should_prune_fn should_prune_fn,\n+\t\t\t reflog_expiry_cleanup_fn cleanup_fn,\n+\t\t\t void *policy_cb_data)\n+{\n+\tstruct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;\n+\tint res = drefs->refs->be->reflog_expire(drefs->refs, refname, oid,\n+\t\t\t\t\t\t flags, prepare_fn,\n+\t\t\t\t\t\t should_prune_fn, cleanup_fn,\n+\t\t\t\t\t\t policy_cb_data);\n+\ttrace_printf_key(&trace_refs, \"reflog_expire: %s: %d\\n\", refname, res);\n+\treturn res;\n+}\n+\n+struct ref_storage_be refs_be_debug = {\n+\tNULL,\n+\t\"debug\",\n+\tNULL,\n+\tdebug_init_db,\n+\tdebug_transaction_prepare,\n+\tdebug_transaction_finish,\n+\tdebug_transaction_abort,\n+\tdebug_initial_transaction_commit,\n+\n+\tdebug_pack_refs,\n+\tdebug_create_symref,\n+\tdebug_delete_refs,\n+\tdebug_rename_ref,\n+\tdebug_copy_ref,\n+\n+\tdebug_ref_iterator_begin,\n+\tdebug_read_raw_ref,\n+\n+\tdebug_reflog_iterator_begin,\n+\tdebug_for_each_reflog_ent,\n+\tdebug_for_each_reflog_ent_reverse,\n+\tdebug_reflog_exists,\n+\tdebug_create_reflog,\n+\tdebug_delete_reflog,\n+\tdebug_reflog_expire,\n+};\ndiff --git a/refs/refs-internal.h b/refs/refs-internal.h\nindex 527b0a6e2e..fecde40baf 100644\n--- a/refs/refs-internal.h\n+++ b/refs/refs-internal.h\n@@ -690,4 +690,9 @@ int parse_loose_ref_contents(const char *buf, struct object_id *oid,\n void base_ref_store_init(struct ref_store *refs,\n \t\t\t const struct ref_storage_be *be);\n \n+/*\n+ * Support GIT_TRACE_REFS by optionally wrapping the given ref_store instance.\n+ */\n+struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store);\n+\n #endif /* REFS_REFS_INTERNAL_H */\n\nbase-commit: 3a238e539bcdfe3f9eb5010fd218640c1b499f7a\n-- \ngitgitgadget\n"}]}