threads / rfc / 26592

RFC patch, 8 partsrefactor trace code

Subject: [PATCH/RFC 0/8] refactor trace code

## tl;dr

32 messages between Feb 24, 2011 and Mar 8, 2011. Diffs are folded; open one to read it.

replies: 31people: 7as markdown or json

Jeff King· Feb 24, 2011, 14:23 UTC · lore
A few weeks ago in:
  http://article.gmane.org/gmane.comp.version-control.git/165496

we discussed the possibility of removing the repo setup trace lines. I mentioned that I had also recently done some debug code that would not be appropriate to show all the time with GIT_TRACE. So here is a series that jumbles it all together: refactors the trace code to handle multiple environment variables, adds packet-tracing code on its own variable, and puts the repo setup traces on their own variable.

With this, you can do:
  GIT_TRACE=1 \
  GIT_TRACE_PACKET=/tmp/packet.dump \
  GIT_TRACE_SETUP=0 \
  git whatever

There may be a few other places where it is worth either pushing some traces to their variable (I think the notes merge code has some debugging traces in it), or places where existing debugging code could be enabled (e.g., there is some diffcore debugging code that I sometimes turn on; it is not even compiled by default, but this would give a nice way of pushing that decision to runtime).

I have mixed feelings on adding a bunch of debugging code. On the one hand, it's mostly dead code that nobody runs. On the other hand, it is sometimes really helpful to be able to tell a user "run with this environment variable and tell us what it says" without having to get them to apply a custom patch.

  [1/8]: compat: provide a fallback va_copy definition
  [2/8]: strbuf: add strbuf_addv
  [3/8]: trace: add trace_vprintf
  [4/8]: trace: refactor to support multiple env variables
  [5/8]: trace: factor out "do we want to trace" logic
  [6/8]: trace: add trace_strbuf
  [7/8]: add packet tracing debug code
  [8/8]: trace: give repo_setup trace its own key
-Peff
Jeff King· Feb 24, 2011, 14:26 UTC · re: Jeff King · lore

[RFC/PATCH 1/8] compat: provide a fallback va_copy definition

va_copy is C99. Prior to this, the usual procedure was to simply copy the va_list by assignment.

Signed-off-by: Jeff King <peff@peff.net>
---
We have avoided using va_copy many times in the past, which has led to a
bunch of cut-and-paste. From everything I found searching the web,
implementations have historically either provided va_copy or just let
your code assume that simple assignment of worked. I couldn't find any
mention of any other alternatives.

So my guess is that this will be sufficient, but I we won't really know for sure until somebody reports a problem. :(

 git-compat-util.h |    4 ++++
 1 files changed, 4 insertions(+), 0 deletions(-)
Show changes to git-compat-util.h +4 −0
diff --git a/git-compat-util.h b/git-compat-util.h
index 9c23622..00d41e4 100644
--- a/git-compat-util.h
+++ b/git-compat-util.h
@@ -535,6 +535,10 @@ void git_qsort(void *base, size_t nmemb, size_t size,
 #define fstat_is_reliable() 1
 #endif
 
+#ifndef va_copy
+#define va_copy(dst,src) (dst) = (src)
+#endif
+
 /*
  * Preserves errno, prints a message, but gives no warning for ENOENT.
  * Always returns the return value of unlink(2).
-- 
1.7.2.5.25.g3bb93
Erik Faye-Lund· Feb 24, 2011, 15:57 UTC · re: Jeff King · lore

Re: [RFC/PATCH 1/8] compat: provide a fallback va_copy definition

On Thu, Feb 24, 2011 at 3:26 PM, Jeff King <peff@peff.net> wrote:
Show 29 quoted lines
> va_copy is C99. Prior to this, the usual procedure was to
> simply copy the va_list by assignment.
>
> Signed-off-by: Jeff King <peff@peff.net>
> ---
> We have avoided using va_copy many times in the past, which has led to a
> bunch of cut-and-paste. From everything I found searching the web,
> implementations have historically either provided va_copy or just let
> your code assume that simple assignment of worked. I couldn't find any
> mention of any other alternatives.
>
> So my guess is that this will be sufficient, but I we won't really know
> for sure until somebody reports a problem. :(
>
>  git-compat-util.h |    4 ++++
>  1 files changed, 4 insertions(+), 0 deletions(-)
>
> diff --git a/git-compat-util.h b/git-compat-util.h
> index 9c23622..00d41e4 100644
> --- a/git-compat-util.h
> +++ b/git-compat-util.h
> @@ -535,6 +535,10 @@ void git_qsort(void *base, size_t nmemb, size_t size,
>  #define fstat_is_reliable() 1
>  #endif
>
> +#ifndef va_copy
> +#define va_copy(dst,src) (dst) = (src)
> +#endif
> +

Wouldn't it be even more portable to fall back on use __va_copy (if present), as suggested by Junio in <7vbpip86q5.fsf@alter.siamese.dyndns.org>? He also suggested using memcpy instead of assignment in the same e-mail, due to a recommendation in the Autoconf manual.

There's already a va_copy fall-back in compat/msvc.h, perhaps this should be removed?

Jonathan Nieder· Mar 8, 2011, 08:33 UTC · re: Erik Faye-Lund · lore

[PATCH jk/strbuf-vaddf] compat: fall back on __va_copy if available

Since an obvious implementation of va_list is to make it a pointer into the stack frame, implementing va_copy as "dst = src" will work on many systems. Platforms that use something different (e.g., a size-1 array of structs, to be assigned with *(dst) = *(src)) will need some other compatibility macro, though.

Luckily, as the glibc manual hints, such systems tend to provide the __va_copy macro (introduced in GCC in March, 1997). By using that if it is available, we can cover our bases pretty well.

Discovered by building with CC="gcc -std=c89" on an amd64 machine:
 $ make CC=c89 strbuf.o
 [...]
 strbuf.c: In function ‘strbuf_vaddf’:
 strbuf.c:211:2: error: incompatible types when assigning to type ‘va_list’ from type ‘struct __va_list_tag *’
 make: *** [strbuf.o] Error 1
Explained-by: Junio C Hamano <gitster@pobox.com>
Signed-off-by: Jonathan Nieder <jrnieder@gmail.com>
---
Erik Faye-Lund wrote:
> Wouldn't it be even more portable to fall back on use __va_copy (if
> present), as suggested by Junio in
> <7vbpip86q5.fsf@alter.siamese.dyndns.org>?
Yes, it seems so.
 git-compat-util.h |   11 ++++++++++-
 1 files changed, 10 insertions(+), 1 deletions(-)
Show changes to git-compat-util.h +10 −1
diff --git a/git-compat-util.h b/git-compat-util.h
index 00d41e4..f4cb0a9 100644
--- a/git-compat-util.h
+++ b/git-compat-util.h
@@ -536,7 +536,16 @@ void git_qsort(void *base, size_t nmemb, size_t size,
 #endif
 
 #ifndef va_copy
-#define va_copy(dst,src) (dst) = (src)
+/*
+ * Since an obvious implementation of va_list would be to make it a
+ * pointer into the stack frame, a simple assignment will work on
+ * many systems.  But let's try to be more portable.
+ */
+#ifdef __va_copy
+#define va_copy(dst, src) __va_copy(dst, src)
+#else
+#define va_copy(dst, src) ((dst) = (src))
+#endif
 #endif
 
 /*
-- 
1.7.4.1
Junio C Hamano· Mar 8, 2011, 20:09 UTC · re: Jonathan Nieder · lore

Re: [PATCH jk/strbuf-vaddf] compat: fall back on __va_copy if available

Jonathan Nieder <jrnieder@gmail.com> writes:
> Discovered by building with CC="gcc -std=c89" on an amd64 machine:
>
>  $ make CC=c89 strbuf.o
>  [...]
>  strbuf.c: In function ‘strbuf_vaddf’:

This is a tangent but when you quote from compiler output could you be in C locale so that it would be easier for everybody to get the same result? It will have the added benefit that we won't have to deal with these fancy matching quotes I personally hate to see in commit log messages.

Thanks, the patch looks good.
Jonathan Nieder· Mar 8, 2011, 20:59 UTC · re: Junio C Hamano · lore

Re: [PATCH jk/strbuf-vaddf] compat: fall back on __va_copy if available

Junio C Hamano wrote:
> This is a tangent but when you quote from compiler output could you be in
> C locale so that it would be easier for everybody to get the same result?
Sure, that makes sense.
[...]
> Thanks, the patch looks good.
Thanks for looking it over.
Jonathan Nieder· Feb 24, 2011, 20:33 UTC · re: Jeff King · lore

Re: [RFC/PATCH 1/8] compat: provide a fallback va_copy definition

Jeff King wrote:
> So my guess is that this will be sufficient, but I we won't really know
> for sure until somebody reports a problem. :(
Sounds like a good approach to me.

The POSIX rationale hints that some historical implementations used arrays of size 1. Assignment would error out on such an implementation, which is not a big deal (since we could switch to memcpy then). I would be more worried about a historical implementation using dynamic allocation with va_list being a pointer but I haven't heard of any.

> +#ifndef va_copy
> +#define va_copy(dst,src) (dst) = (src)
> +#endif

The following (as Erik mentinoed) might be a nice cleanup on top. The duplicate va_copy definition is just redundant rather than causing compilation errors because it comes before git-compat-util's ifndef-guarded one.

Show changes to compat/msvc.h +0 −1
diff --git a/compat/msvc.h b/compat/msvc.h
index 023aba0..a33b01c 100644
--- a/compat/msvc.h
+++ b/compat/msvc.h
@@ -9,7 +9,6 @@
 #define inline __inline
 #define __inline__ __inline
 #define __attribute__(x)
-#define va_copy(dst, src)     ((dst) = (src))
 #define strncasecmp  _strnicmp
 #define ftruncate    _chsize
 
Jeff King· Feb 24, 2011, 14:27 UTC · re: Jeff King · lore

[PATCH 2/8] strbuf: add strbuf_addv

In a variable-args function, the code for writing into a strbuf is non-trivial. We ended up cutting and pasting it in several places because there was no vprintf-style function for strbufs (which in turn was held up by a lack of va_copy).

Now that we have a fallback va_copy, we can add strbuf_addv, the strbuf equivalent of vsprintf. And we can clean up the cut and paste mess.

Signed-off-by: Jeff King <peff@peff.net>
---
 fsck.c            |   14 +-------------
 merge-recursive.c |   15 +--------------
 strbuf.c          |   25 +++++++++++++++----------
 strbuf.h          |    1 +
 trace.c           |   32 ++++++--------------------------
 5 files changed, 24 insertions(+), 63 deletions(-)
Show changes to 5 files +24 −63

fsck.c, merge-recursive.c, strbuf.c, strbuf.h, trace.c

diff --git a/fsck.c b/fsck.c
index 3d05d4a..398b137 100644
--- a/fsck.c
+++ b/fsck.c
@@ -347,26 +347,14 @@ int fsck_object(struct object *obj, int strict, fsck_error error_func)
 int fsck_error_function(struct object *obj, int type, const char *fmt, ...)
 {
 	va_list ap;
-	int len;
 	struct strbuf sb = STRBUF_INIT;
 
 	strbuf_addf(&sb, "object %s:", obj->sha1?sha1_to_hex(obj->sha1):"(null)");
 
 	va_start(ap, fmt);
-	len = vsnprintf(sb.buf + sb.len, strbuf_avail(&sb), fmt, ap);
+	strbuf_addv(&sb, fmt, ap);
 	va_end(ap);
 
-	if (len < 0)
-		len = 0;
-	if (len >= strbuf_avail(&sb)) {
-		strbuf_grow(&sb, len + 2);
-		va_start(ap, fmt);
-		len = vsnprintf(sb.buf + sb.len, strbuf_avail(&sb), fmt, ap);
-		va_end(ap);
-		if (len >= strbuf_avail(&sb))
-			die("this should not happen, your snprintf is broken");
-	}
-
 	error("%s", sb.buf);
 	strbuf_release(&sb);
 	return 1;
diff --git a/merge-recursive.c b/merge-recursive.c
index 16c2dbe..b418d5b 100644
--- a/merge-recursive.c
+++ b/merge-recursive.c
@@ -137,7 +137,6 @@ static void flush_output(struct merge_options *o)
 __attribute__((format (printf, 3, 4)))
 static void output(struct merge_options *o, int v, const char *fmt, ...)
 {
-	int len;
 	va_list ap;
 
 	if (!show(o, v))
@@ -148,21 +147,9 @@ static void output(struct merge_options *o, int v, const char *fmt, ...)
 	strbuf_setlen(&o->obuf, o->obuf.len + o->call_depth * 2);
 
 	va_start(ap, fmt);
-	len = vsnprintf(o->obuf.buf + o->obuf.len, strbuf_avail(&o->obuf), fmt, ap);
+	strbuf_addv(&o->obuf, fmt, ap);
 	va_end(ap);
 
-	if (len < 0)
-		len = 0;
-	if (len >= strbuf_avail(&o->obuf)) {
-		strbuf_grow(&o->obuf, len + 2);
-		va_start(ap, fmt);
-		len = vsnprintf(o->obuf.buf + o->obuf.len, strbuf_avail(&o->obuf), fmt, ap);
-		va_end(ap);
-		if (len >= strbuf_avail(&o->obuf)) {
-			die("this should not happen, your snprintf is broken");
-		}
-	}
-	strbuf_setlen(&o->obuf, o->obuf.len + len);
 	strbuf_add(&o->obuf, "\n", 1);
 	if (!o->buffer_output)
 		flush_output(o);
diff --git a/strbuf.c b/strbuf.c
index 07e8883..7a2e17f 100644
--- a/strbuf.c
+++ b/strbuf.c
@@ -195,24 +195,29 @@ void strbuf_adddup(struct strbuf *sb, size_t pos, size_t len)
 
 void strbuf_addf(struct strbuf *sb, const char *fmt, ...)
 {
-	int len;
 	va_list ap;
+	va_start(ap, fmt);
+	strbuf_addv(sb, fmt, ap);
+	va_end(ap);
+}
+
+void strbuf_addv(struct strbuf *sb, const char *fmt, va_list ap)
+{
+	int len;
+	va_list cp;
 
 	if (!strbuf_avail(sb))
 		strbuf_grow(sb, 64);
-	va_start(ap, fmt);
-	len = vsnprintf(sb->buf + sb->len, sb->alloc - sb->len, fmt, ap);
-	va_end(ap);
+	va_copy(cp, ap);
+	len = vsnprintf(sb->buf + sb->len, sb->alloc - sb->len, fmt, cp);
+	va_end(cp);
 	if (len < 0)
-		die("your vsnprintf is broken");
+		die("BUG: your vsnprintf is broken (returned -1)");
 	if (len > strbuf_avail(sb)) {
 		strbuf_grow(sb, len);
-		va_start(ap, fmt);
 		len = vsnprintf(sb->buf + sb->len, sb->alloc - sb->len, fmt, ap);
-		va_end(ap);
-		if (len > strbuf_avail(sb)) {
-			die("this should not happen, your snprintf is broken");
-		}
+		if (len > strbuf_avail(sb))
+			die("BUG: your vsnprintf is broken (insatiable)");
 	}
 	strbuf_setlen(sb, sb->len + len);
 }
diff --git a/strbuf.h b/strbuf.h
index 675a91f..65b44a0 100644
--- a/strbuf.h
+++ b/strbuf.h
@@ -120,6 +120,7 @@ extern void strbuf_addbuf_percentquote(struct strbuf *dst, const struct strbuf *
 
 __attribute__((format (printf,2,3)))
 extern void strbuf_addf(struct strbuf *sb, const char *fmt, ...);
+extern void strbuf_addv(struct strbuf *sb, const char *fmt, va_list ap);
 
 extern size_t strbuf_fread(struct strbuf *, size_t, FILE *);
 /* XXX: if read fails, any partial read is undone */
diff --git a/trace.c b/trace.c
index 35d388d..745543c 100644
--- a/trace.c
+++ b/trace.c
@@ -64,28 +64,18 @@ static const char err_msg[] = "Could not trace into fd given by "
 
 void trace_printf(const char *fmt, ...)
 {
-	struct strbuf buf;
+	struct strbuf buf = STRBUF_INIT;
 	va_list ap;
-	int fd, len, need_close = 0;
+	int fd, need_close = 0;
 
 	fd = get_trace_fd(&need_close);
 	if (!fd)
 		return;
 
 	set_try_to_free_routine(NULL);	/* is never reset */
-	strbuf_init(&buf, 64);
 	va_start(ap, fmt);
-	len = vsnprintf(buf.buf, strbuf_avail(&buf), fmt, ap);
+	strbuf_addv(&buf, fmt, ap);
 	va_end(ap);
-	if (len >= strbuf_avail(&buf)) {
-		strbuf_grow(&buf, len - strbuf_avail(&buf) + 128);
-		va_start(ap, fmt);
-		len = vsnprintf(buf.buf, strbuf_avail(&buf), fmt, ap);
-		va_end(ap);
-		if (len >= strbuf_avail(&buf))
-			die("broken vsnprintf");
-	}
-	strbuf_setlen(&buf, len);
 
 	write_or_whine_pipe(fd, buf.buf, buf.len, err_msg);
 	strbuf_release(&buf);
@@ -96,28 +86,18 @@ void trace_printf(const char *fmt, ...)
 
 void trace_argv_printf(const char **argv, const char *fmt, ...)
 {
-	struct strbuf buf;
+	struct strbuf buf = STRBUF_INIT;
 	va_list ap;
-	int fd, len, need_close = 0;
+	int fd, need_close = 0;
 
 	fd = get_trace_fd(&need_close);
 	if (!fd)
 		return;
 
 	set_try_to_free_routine(NULL);	/* is never reset */
-	strbuf_init(&buf, 64);
 	va_start(ap, fmt);
-	len = vsnprintf(buf.buf, strbuf_avail(&buf), fmt, ap);
+	strbuf_addv(&buf, fmt, ap);
 	va_end(ap);
-	if (len >= strbuf_avail(&buf)) {
-		strbuf_grow(&buf, len - strbuf_avail(&buf) + 128);
-		va_start(ap, fmt);
-		len = vsnprintf(buf.buf, strbuf_avail(&buf), fmt, ap);
-		va_end(ap);
-		if (len >= strbuf_avail(&buf))
-			die("broken vsnprintf");
-	}
-	strbuf_setlen(&buf, len);
 
 	sq_quote_argv(&buf, argv, 0);
 	strbuf_addch(&buf, '\n');
-- 
1.7.2.5.25.g3bb93
Christian Couder· Feb 24, 2011, 15:05 UTC · re: Jeff King · lore

Re: [PATCH 2/8] strbuf: add strbuf_addv

Hi,
On Thu, Feb 24, 2011 at 3:27 PM, Jeff King <peff@peff.net> wrote:
Show 16 quoted lines
> +void strbuf_addv(struct strbuf *sb, const char *fmt, va_list ap)
> +{
> +       int len;
> +       va_list cp;
>
>        if (!strbuf_avail(sb))
>                strbuf_grow(sb, 64);
> -       va_start(ap, fmt);
> -       len = vsnprintf(sb->buf + sb->len, sb->alloc - sb->len, fmt, ap);
> -       va_end(ap);
> +       va_copy(cp, ap);
> +       len = vsnprintf(sb->buf + sb->len, sb->alloc - sb->len, fmt, cp);
> +       va_end(cp);
>        if (len < 0)
> -               die("your vsnprintf is broken");
> +               die("BUG: your vsnprintf is broken (returned -1)");
Minor nit: why not:
 +               die("BUG: your vsnprintf is broken (returned %d)", len);

Thanks, Christian.

Jeff King· Feb 24, 2011, 15:07 UTC · re: Christian Couder · lore

Re: [PATCH 2/8] strbuf: add strbuf_addv

On Thu, Feb 24, 2011 at 04:05:13PM +0100, Christian Couder wrote:
Show 9 quoted lines
> > +       len = vsnprintf(sb->buf + sb->len, sb->alloc - sb->len, fmt, cp);
> > +       va_end(cp);
> >        if (len < 0)
> > -               die("your vsnprintf is broken");
> > +               die("BUG: your vsnprintf is broken (returned -1)");
> 
> Minor nit: why not:
> 
>  +               die("BUG: your vsnprintf is broken (returned %d)", len);
No reason. I'll switch to yours in my re-roll.
-Peff
Jonathan Nieder· Feb 24, 2011, 20:51 UTC · re: Jeff King · lore

Re: [PATCH 2/8] strbuf: add strbuf_addv

Jeff King wrote:
Show 8 quoted lines
> In a variable-args function, the code for writing into a
> strbuf is non-trivial. We ended up cutting and pasting it in
> several places because there was no vprintf-style function
> for strbufs (which in turn was held up by a lack of
> va_copy).
>
> Now that we have a fallback va_copy, we can add strbuf_addv,
> the strbuf equivalent of vsprintf.

"strbuf_vaddf" would follow the vsnprintf scheme a little better. (I think strbuf_addv is just as intuitive, though.)

Thanks, I was looking for something like this.

And apparently it has been a wish for 2 years now. :) See http://thread.gmane.org/gmane.comp.version-control.git/75250/focus=76396 for amusement.

>  5 files changed, 24 insertions(+), 63 deletions(-)
Nice.
Show 7 quoted lines
> --- a/strbuf.h
> +++ b/strbuf.h
> @@ -120,6 +120,7 @@ extern void strbuf_addbuf_percentquote(struct strbuf *dst, const struct strbuf *
>  
>  __attribute__((format (printf,2,3)))
>  extern void strbuf_addf(struct strbuf *sb, const char *fmt, ...);
> +extern void strbuf_addv(struct strbuf *sb, const char *fmt, va_list ap);

"__attribute__(format (printf,2,0))" could tell gcc to check that the format string is well formed and give it a chance to carp if you try

	static inline void foo(struct strbuf *sb, const char *fmt, ...)
	{
		va_list ap;
		va_start(ap, fmt);
		strbuf_addv(sb, fmt, ap);
		va_end(ap);
	}
	...
		foo(some_user_supplied_string);
---
Show changes to strbuf.h +1 −0
diff --git a/strbuf.h b/strbuf.h
index 65b44a0..0c788d5 100644
--- a/strbuf.h
+++ b/strbuf.h
@@ -120,6 +120,7 @@ extern void strbuf_addbuf_percentquote(struct strbuf *dst, const struct strbuf *
 
 __attribute__((format (printf,2,3)))
 extern void strbuf_addf(struct strbuf *sb, const char *fmt, ...);
+__attribute__((format (printf,2,0)))
 extern void strbuf_addv(struct strbuf *sb, const char *fmt, va_list ap);
 
 extern size_t strbuf_fread(struct strbuf *, size_t, FILE *);
Jeff King· Feb 24, 2011, 14:28 UTC · re: Jeff King · lore

[PATCH 3/8] trace: add trace_vprintf

This is a necessary cleanup to adding new types of trace functions.

Signed-off-by: Jeff King <peff@peff.net>
---
 cache.h |    1 +
 trace.c |   14 +++++++++-----
 2 files changed, 10 insertions(+), 5 deletions(-)
Show changes to 2 files +10 −5

cache.h, trace.c

diff --git a/cache.h b/cache.h
index 4a758ba..08b23b2 100644
--- a/cache.h
+++ b/cache.h
@@ -1067,6 +1067,7 @@ extern void alloc_report(void);
 /* trace.c */
 __attribute__((format (printf, 1, 2)))
 extern void trace_printf(const char *format, ...);
+extern void trace_vprintf(const char *format, va_list ap);
 __attribute__((format (printf, 2, 3)))
 extern void trace_argv_printf(const char **argv, const char *format, ...);
 extern void trace_repo_setup(const char *prefix);
diff --git a/trace.c b/trace.c
index 745543c..6ad7788 100644
--- a/trace.c
+++ b/trace.c
@@ -62,10 +62,9 @@ static int get_trace_fd(int *need_close)
 static const char err_msg[] = "Could not trace into fd given by "
 	"GIT_TRACE environment variable";
 
-void trace_printf(const char *fmt, ...)
+void trace_vprintf(const char *fmt, va_list ap)
 {
 	struct strbuf buf = STRBUF_INIT;
-	va_list ap;
 	int fd, need_close = 0;
 
 	fd = get_trace_fd(&need_close);
@@ -73,10 +72,7 @@ void trace_printf(const char *fmt, ...)
 		return;
 
 	set_try_to_free_routine(NULL);	/* is never reset */
-	va_start(ap, fmt);
 	strbuf_addv(&buf, fmt, ap);
-	va_end(ap);
-
 	write_or_whine_pipe(fd, buf.buf, buf.len, err_msg);
 	strbuf_release(&buf);
 
@@ -84,6 +80,14 @@ void trace_printf(const char *fmt, ...)
 		close(fd);
 }
 
+void trace_printf(const char *fmt, ...)
+{
+	va_list ap;
+	va_start(ap, fmt);
+	trace_vprintf(fmt, ap);
+	va_end(ap);
+}
+
 void trace_argv_printf(const char **argv, const char *fmt, ...)
 {
 	struct strbuf buf = STRBUF_INIT;
-- 
1.7.2.5.25.g3bb93
Jonathan Nieder· Feb 24, 2011, 21:08 UTC · re: Jeff King · lore

Re: [PATCH 3/8] trace: add trace_vprintf

Jeff King wrote:
Show 7 quoted lines
> --- a/cache.h
> +++ b/cache.h
> @@ -1067,6 +1067,7 @@ extern void alloc_report(void);
>  /* trace.c */
>  __attribute__((format (printf, 1, 2)))
>  extern void trace_printf(const char *format, ...);
> +extern void trace_vprintf(const char *format, va_list ap);
Micronit.

Though now that I think of it, the format(printf, n, 0) attribute doesn't seem to be used anywhere in git currently. Is it unportable? ---

Show changes to cache.h +1 −0
diff --git a/cache.h b/cache.h
index 08b23b2..288d4d0 100644
--- a/cache.h
+++ b/cache.h
@@ -1067,6 +1067,7 @@ extern void alloc_report(void);
 /* trace.c */
 __attribute__((format (printf, 1, 2)))
 extern void trace_printf(const char *format, ...);
+__attribute__((format (printf, 1, 0)))
 extern void trace_vprintf(const char *format, va_list ap);
 __attribute__((format (printf, 2, 3)))
 extern void trace_argv_printf(const char **argv, const char *format, ...);
Jeff King· Feb 24, 2011, 14:28 UTC · re: Jeff King · lore

[PATCH 4/8] trace: refactor to support multiple env variables

Right now you turn all tracing off and on with GIT_TRACE. To support new types of tracing without forcing the user to see all of them, we will soon support turning each tracing area on with GIT_TRACE_*.

This patch lays the groundwork by providing an interface which does not assume GIT_TRACE. However, we still maintain the trace_printf interface so that existing callers do not need to be refactored.

Signed-off-by: Jeff King <peff@peff.net>
---
 cache.h |    2 +-
 trace.c |   28 ++++++++++++++++++----------
 2 files changed, 19 insertions(+), 11 deletions(-)
Show changes to 2 files +19 −11

cache.h, trace.c

diff --git a/cache.h b/cache.h
index 08b23b2..2ab1bf9 100644
--- a/cache.h
+++ b/cache.h
@@ -1067,7 +1067,7 @@ extern void alloc_report(void);
 /* trace.c */
 __attribute__((format (printf, 1, 2)))
 extern void trace_printf(const char *format, ...);
-extern void trace_vprintf(const char *format, va_list ap);
+extern void trace_vprintf(const char *key, const char *format, va_list ap);
 __attribute__((format (printf, 2, 3)))
 extern void trace_argv_printf(const char **argv, const char *format, ...);
 extern void trace_repo_setup(const char *prefix);
diff --git a/trace.c b/trace.c
index 6ad7788..a74f00e 100644
--- a/trace.c
+++ b/trace.c
@@ -25,10 +25,10 @@
 #include "cache.h"
 #include "quote.h"
 
-/* Get a trace file descriptor from GIT_TRACE env variable. */
-static int get_trace_fd(int *need_close)
+/* Get a trace file descriptor from "key" env variable. */
+static int get_trace_fd(const char *key, int *need_close)
 {
-	char *trace = getenv("GIT_TRACE");
+	char *trace = getenv(key);
 
 	if (!trace || !strcmp(trace, "") ||
 	    !strcmp(trace, "0") || !strcasecmp(trace, "false"))
@@ -50,10 +50,10 @@ static int get_trace_fd(int *need_close)
 		return fd;
 	}
 
-	fprintf(stderr, "What does '%s' for GIT_TRACE mean?\n", trace);
+	fprintf(stderr, "What does '%s' for %s mean?\n", trace, key);
 	fprintf(stderr, "If you want to trace into a file, "
-		"then please set GIT_TRACE to an absolute pathname "
-		"(starting with /).\n");
+		"then please set %s to an absolute pathname "
+		"(starting with /).\n", key);
 	fprintf(stderr, "Defaulting to tracing on stderr...\n");
 
 	return STDERR_FILENO;
@@ -62,12 +62,12 @@ static int get_trace_fd(int *need_close)
 static const char err_msg[] = "Could not trace into fd given by "
 	"GIT_TRACE environment variable";
 
-void trace_vprintf(const char *fmt, va_list ap)
+void trace_vprintf(const char *key, const char *fmt, va_list ap)
 {
 	struct strbuf buf = STRBUF_INIT;
 	int fd, need_close = 0;
 
-	fd = get_trace_fd(&need_close);
+	fd = get_trace_fd(key, &need_close);
 	if (!fd)
 		return;
 
@@ -80,11 +80,19 @@ void trace_vprintf(const char *fmt, va_list ap)
 		close(fd);
 }
 
+void trace_printf_key(const char *key, const char *fmt, ...)
+{
+	va_list ap;
+	va_start(ap, fmt);
+	trace_vprintf(key, fmt, ap);
+	va_end(ap);
+}
+
 void trace_printf(const char *fmt, ...)
 {
 	va_list ap;
 	va_start(ap, fmt);
-	trace_vprintf(fmt, ap);
+	trace_vprintf("GIT_TRACE", fmt, ap);
 	va_end(ap);
 }
 
@@ -94,7 +102,7 @@ void trace_argv_printf(const char **argv, const char *fmt, ...)
 	va_list ap;
 	int fd, need_close = 0;
 
-	fd = get_trace_fd(&need_close);
+	fd = get_trace_fd("GIT_TRACE", &need_close);
 	if (!fd)
 		return;
 
-- 
1.7.2.5.25.g3bb93
Junio C Hamano· Feb 24, 2011, 18:25 UTC · re: Jeff King · lore

Re: [PATCH 4/8] trace: refactor to support multiple env variables

Jeff King <peff@peff.net> writes:
Show 9 quoted lines
> Right now you turn all tracing off and on with GIT_TRACE. To
> support new types of tracing without forcing the user to see
> all of them, we will soon support turning each tracing area
> on with GIT_TRACE_*.
>
> This patch lays the groundwork by providing an interface
> which does not assume GIT_TRACE. However, we still maintain
> the trace_printf interface so that existing callers do not
> need to be refactored.

One thing I found missing in the patch description is a statement of the overall design and expected usage. It appears to me that the design is built around the idea to give each named/namable area to be traceable its own trace output file descriptor, so that different kinds of trace events are sent to different files.

I however expect that majority of "trace only areas A and B" users would want to see logs of events from these two areas in the same stream to see them in the order they happened. Perhaps you are envisioning that these users would use redirection from the command line to send GIT_TRACE_A and GIT_TRACE_B to the same place; that probably needs to be spelled out more explicitly somewhere in the documentation, as that would be a more common thing to do.

I think your [7/8] is kind of strange when viewed in that light. Imagine what would happen if you gave separate GIT_TRACE_* to each packet class, instead of giving them a single umbrella variable GIT_TRACE_PACKET. If the user wants to see them all in a single stream, the same redirection you would use to unify GIT_TRACE_A and GIT_TRACE_B can be used.

Instead, you have packet class prefix in the output so that later the different kinds of packet events can be sifted out from the unified output, even though they are forced to go to the same output stream. In a sense, you have two-tier classification system for traceable events (the top layer that can be separated or merged at the file descriptor level, and the bottom layer that can only be separated by looking at the prefix).

Is this necessarily a good thing (not a rhetorical question)?

To put it another and opposite way, I wonder if it would be better to instead use a single output stream named by GIT_TRACE and add trace event class prefix to the output for classes like SETUP and PACKET (again, not a rhetorical question).

Also instead of wasting environment variable names, it might be a more compact design from the user's point of view if we took a list of trace event classes in a single environment variable, e.g.

	GIT_TRACE_CLASS=setup,packet \
        GIT_TRACE=/tmp/tr \
        git push
I dunno.
Jeff King· Feb 24, 2011, 19:02 UTC · re: Junio C Hamano · lore

Re: [PATCH 4/8] trace: refactor to support multiple env variables

On Thu, Feb 24, 2011 at 10:25:04AM -0800, Junio C Hamano wrote:
Show 17 quoted lines
> Jeff King <peff@peff.net> writes:
> 
> > Right now you turn all tracing off and on with GIT_TRACE. To
> > support new types of tracing without forcing the user to see
> > all of them, we will soon support turning each tracing area
> > on with GIT_TRACE_*.
> >
> > This patch lays the groundwork by providing an interface
> > which does not assume GIT_TRACE. However, we still maintain
> > the trace_printf interface so that existing callers do not
> > need to be refactored.
> 
> One thing I found missing in the patch description is a statement of the
> overall design and expected usage.  It appears to me that the design is
> built around the idea to give each named/namable area to be traceable its
> own trace output file descriptor, so that different kinds of trace events
> are sent to different files.

The intent was that you _can_ do that if you want, but you can also just dump them all to the same fd (or the same file). Each trace statement is totally independent and written via write(), so there is no problem pushing them all to the same place. They'll arrive in chronological order.

> I however expect that majority of "trace only areas A and B" users would
> want to see logs of events from these two areas in the same stream to see
> them in the order they happened.

Right. And you can do GIT_TRACE_A=1 GIT_TRACE_B=1 if you want that (or put them both to fd 5, or /tmp/foo.out, or whatever).

> Perhaps you are envisioning that these users would use redirection
> from the command line to send GIT_TRACE_A and GIT_TRACE_B to the same
> place; that probably needs to be spelled out more explicitly somewhere
> in the documentation, as that would be a more common thing to do.

Yeah, sorry. There is no documentation at all with this series yet. For this round I was mainly trying to see how people felt about expanding the trace functions at all.

Show 5 quoted lines
> I think your [7/8] is kind of strange when viewed in that light.  Imagine
> what would happen if you gave separate GIT_TRACE_* to each packet class,
> instead of giving them a single umbrella variable GIT_TRACE_PACKET.  If
> the user wants to see them all in a single stream, the same redirection
> you would use to unify GIT_TRACE_A and GIT_TRACE_B can be used.

Yeah, you could break it down by packet type, though I don't know why anyone would want to (unless perhaps dumping the whole pack to some alternate location than the rest of it).

Show 8 quoted lines
> Instead, you have packet class prefix in the output so that later the
> different kinds of packet events can be sifted out from the unified
> output, even though they are forced to go to the same output stream.  In a
> sense, you have two-tier classification system for traceable events (the
> top layer that can be separated or merged at the file descriptor level,
> and the bottom layer that can only be separated by looking at the prefix).
> 
> Is this necessarily a good thing (not a rhetorical question)?

I don't see it as a problem. As a developer, I want to throw in some trace statements that are logically related to me. So I give them a name and put in the trace statements. The user can now have those statements turned on or off, and if on, can tell them where to go. No, they can't say "I want statement X but not statement Y" or "I want packet X and not packet Y". But what is the right degree of resolution? Too coarse, and they get a few traces they don't want. Too fine, and the syntax for addressing each individual trace statement gets cumbersome. At some point, you trust the developer's notion of a logical unit to be sensible.

So I guess I'm not sure what your complaint is. You don't like the GIT_TRACE_FOO versus GIT_TRACE_BAR syntax? Or you disagree with the logical unit I chose for packet traces? If the latter, then I welcome improvement patches.

> To put it another and opposite way, I wonder if it would be better to
> instead use a single output stream named by GIT_TRACE and add trace event
> class prefix to the output for classes like SETUP and PACKET (again, not a
> rhetorical question).

That was actually my original design (that I didn't submit to the list). But I rejected it because:

  1. Even though you generally want to see several trace types in
     chronological order, you might want the flexibility of putting
     different traces in different locations. The current packet code
     doesn't dump the pack at all, assuming it is uninteresting binary
     goo (because for my purposes, the logical unit was the
     negotiation). But let's say for example that you _do_ want to dump
     the pack. If I have (just making up names):
        GIT_TRACE=/tmp/foo
        GIT_TRACE_CLASS=packet,incoming-packfile
     then you get everything in /tmp/foo, and you are stuck sorting the
     trace lines from the binary goo yourself. It's more natural to do:
       GIT_TRACE_PACKET=1 ;# send to stderr
       GIT_TRACE_INCOMING_PACKFILE=/tmp/dump.pack
  2. Multiple variables made invoking a little more cumbersome. If the
     trace variables are reasonable logical units, you probably only want
     to see one at a time. If you're interested in debugging packet
     traces, you probably don't care about seeing the exec-tracing. It's
     useless cruft. So you do:
       GIT_TRACE_PACKET=<whatever> git ...
     which to my mind is much simpler than
       GIT_TRACE=<whatever> GIT_TRACE_CLASS=packet git ...
     It's less typing, and conceptually simpler. And I say this not just
     hypothetically, but because I had originally implemented it the
     other way and found it annoying.
     Now I do recognize that I am optimizing for one case I envision as
     the common case, and it's a trade-off. If your <whatever> is long,
     then putting multiple facilities to the same place is more
     cumbersome:
       GIT_TRACE_FOO=<whatever> GIT_TRACE_BAR=<whatever>
     but in my experience, <whatever> was usually "1".
You could do some hybrid like:
  GIT_TRACE=packet,exec:/path/to/dumpfile
but I didn't see any point in getting very complex with parsing.
Show 9 quoted lines
> Also instead of wasting environment variable names, it might be a more
> compact design from the user's point of view if we took a list of trace
> event classes in a single environment variable, e.g.
> 
> 	GIT_TRACE_CLASS=setup,packet \
>         GIT_TRACE=/tmp/tr \
>         git push
> 
> I dunno.

I think I covered that pretty well above, but you lose the flexibility of pushing different trace types to different places if you want to.

-Peff
Junio C Hamano· Feb 24, 2011, 19:44 UTC · re: Jeff King · lore

Re: [PATCH 4/8] trace: refactor to support multiple env variables

Jeff King <peff@peff.net> writes:
> On Thu, Feb 24, 2011 at 10:25:04AM -0800, Junio C Hamano wrote:
> ...
> So I guess I'm not sure what your complaint is.

There was no complaint. I wanted to see the reasoning behind the choices you made spelled out (and later copied into developer docs).

> I think I covered that pretty well above, but you lose the flexibility
> of pushing different trace types to different places if you want to.

That statement illustrates the inflexibility that all packet traces going to a same place rather clearly, doesn't it, though? That "two-tier" thing was my primary concern.

Jeff King· Feb 24, 2011, 19:48 UTC · re: Junio C Hamano · lore

Re: [PATCH 4/8] trace: refactor to support multiple env variables

On Thu, Feb 24, 2011 at 11:44:13AM -0800, Junio C Hamano wrote:
Show 8 quoted lines
> Jeff King <peff@peff.net> writes:
> 
> > On Thu, Feb 24, 2011 at 10:25:04AM -0800, Junio C Hamano wrote:
> > ...
> > So I guess I'm not sure what your complaint is.
> 
> There was no complaint. I wanted to see the reasoning behind the choices
> you made spelled out (and later copied into developer docs).

Oh. :) I'll write something up to go into Documentation/technical for my re-roll. And something should clearly go in Documentation/git.txt for users, too.

Show 6 quoted lines
> > I think I covered that pretty well above, but you lose the flexibility
> > of pushing different trace types to different places if you want to.
> 
> That statement illustrates the inflexibility that all packet traces going
> to a same place rather clearly, doesn't it, though?  That "two-tier" thing
> was my primary concern.
Sorry, I don't quite understand what you're saying here.
-Peff
Junio C Hamano· Feb 24, 2011, 20:50 UTC · re: Jeff King · lore

Re: [PATCH 4/8] trace: refactor to support multiple env variables

Jeff King <peff@peff.net> writes:
Show 8 quoted lines
>> > I think I covered that pretty well above, but you lose the flexibility
>> > of pushing different trace types to different places if you want to.
>> 
>> That statement illustrates the inflexibility that all packet traces going
>> to a same place rather clearly, doesn't it, though?  That "two-tier" thing
>> was my primary concern.
>
> Sorry, I don't quite understand what you're saying here.
I was contrasting these two and called that "two-tier thing":
 - GIT_TRACE_SETUP and GIT_TRACE_PACKET can be used to give you
   flexibility of sending their output to the same location or to
   different destination.  Nice and flexibile.
 - Even though the trace identities like "clone", "fetch-pack", etc. are
   clearly marked in the code, you cannot take advantage of the marking
   and send the output from these packet sources to different destination,
   because GIT_TRACE_PACKET is just one and single variable.
Clearer?

Not that I think the same flexibility in the latter is absolutely necessary, but it somewhat feels inconsistent to have these two classes.

Jonathan Nieder· Feb 24, 2011, 21:23 UTC · re: Jeff King · lore

Re: [PATCH 4/8] trace: refactor to support multiple env variables

Jeff King wrote:
> However, we still maintain
> the trace_printf interface so that existing callers do not
> need to be refactored.

Hmm, so trace_printf means "trace exec, notes_merge, and RUNTIME_PREFIX"?

Jeff King· Feb 24, 2011, 14:28 UTC · re: Jeff King · lore

[PATCH 5/8] trace: factor out "do we want to trace" logic

As we add more tracing areas, this will avoid repeated code.

Technically, trace_printf already checks this and will avoid printing if the trace key is not set. However, callers may want to find out early whether or not tracing is enabled so they can avoid doing work in the common non-trace case.

Signed-off-by: Jeff King <peff@peff.net>
---
 cache.h |    1 +
 trace.c |   14 +++++++++++---
 2 files changed, 12 insertions(+), 3 deletions(-)
Show changes to 2 files +12 −3

cache.h, trace.c

diff --git a/cache.h b/cache.h
index 2ab1bf9..211d7bb 100644
--- a/cache.h
+++ b/cache.h
@@ -1071,6 +1071,7 @@ extern void trace_vprintf(const char *key, const char *format, va_list ap);
 __attribute__((format (printf, 2, 3)))
 extern void trace_argv_printf(const char **argv, const char *format, ...);
 extern void trace_repo_setup(const char *prefix);
+extern int trace_want(const char *key);
 
 /* convert.c */
 /* returns 1 if *dst was used */
diff --git a/trace.c b/trace.c
index a74f00e..f00d98f 100644
--- a/trace.c
+++ b/trace.c
@@ -148,10 +148,8 @@ void trace_repo_setup(const char *prefix)
 {
 	const char *git_work_tree;
 	char cwd[PATH_MAX];
-	char *trace = getenv("GIT_TRACE");
 
-	if (!trace || !strcmp(trace, "") ||
-	    !strcmp(trace, "0") || !strcasecmp(trace, "false"))
+	if (!trace_want("GIT_TRACE"))
 		return;
 
 	if (!getcwd(cwd, PATH_MAX))
@@ -168,3 +166,13 @@ void trace_repo_setup(const char *prefix)
 	trace_printf("setup: cwd: %s\n", quote_crnl(cwd));
 	trace_printf("setup: prefix: %s\n", quote_crnl(prefix));
 }
+
+int trace_want(const char *key)
+{
+	const char *trace = getenv(key);
+
+	if (!trace || !strcmp(trace, "") ||
+	    !strcmp(trace, "0") || !strcasecmp(trace, "false"))
+		return 0;
+	return 1;
+}
-- 
1.7.2.5.25.g3bb93
Christian Couder· Feb 24, 2011, 15:07 UTC · re: Jeff King · lore

Re: [PATCH 5/8] trace: factor out "do we want to trace" logic

On Thu, Feb 24, 2011 at 3:28 PM, Jeff King <peff@peff.net> wrote:
Show 9 quoted lines
> +int trace_want(const char *key)
> +{
> +       const char *trace = getenv(key);
> +
> +       if (!trace || !strcmp(trace, "") ||
> +           !strcmp(trace, "0") || !strcasecmp(trace, "false"))
> +               return 0;
> +       return 1;
> +}

Other minor nit: calling it "trace_wanted()" or "want_trace()" looks better to me.

Thanks, Christian.

Jeff King· Feb 24, 2011, 14:29 UTC · re: Jeff King · lore

[PATCH 6/8] trace: add trace_strbuf

If you happen to have a strbuf, it is a little more readable and a little more efficient to be able to print it directly instead of jamming it through the trace_printf interface.

Signed-off-by: Jeff King <peff@peff.net>
---
 cache.h |    1 +
 trace.c |   23 ++++++++++++++++-------
 2 files changed, 17 insertions(+), 7 deletions(-)
Show changes to 2 files +17 −7

cache.h, trace.c

diff --git a/cache.h b/cache.h
index 211d7bb..3978112 100644
--- a/cache.h
+++ b/cache.h
@@ -1072,6 +1072,7 @@ __attribute__((format (printf, 2, 3)))
 extern void trace_argv_printf(const char **argv, const char *format, ...);
 extern void trace_repo_setup(const char *prefix);
 extern int trace_want(const char *key);
+extern void trace_strbuf(const char *key, const struct strbuf *buf);
 
 /* convert.c */
 /* returns 1 if *dst was used */
diff --git a/trace.c b/trace.c
index f00d98f..3f9f287 100644
--- a/trace.c
+++ b/trace.c
@@ -65,19 +65,14 @@ static const char err_msg[] = "Could not trace into fd given by "
 void trace_vprintf(const char *key, const char *fmt, va_list ap)
 {
 	struct strbuf buf = STRBUF_INIT;
-	int fd, need_close = 0;
 
-	fd = get_trace_fd(key, &need_close);
-	if (!fd)
+	if (!trace_want(key))
 		return;
 
 	set_try_to_free_routine(NULL);	/* is never reset */
 	strbuf_addv(&buf, fmt, ap);
-	write_or_whine_pipe(fd, buf.buf, buf.len, err_msg);
+	trace_strbuf(key, &buf);
 	strbuf_release(&buf);
-
-	if (need_close)
-		close(fd);
 }
 
 void trace_printf_key(const char *key, const char *fmt, ...)
@@ -96,6 +91,20 @@ void trace_printf(const char *fmt, ...)
 	va_end(ap);
 }
 
+void trace_strbuf(const char *key, const struct strbuf *buf)
+{
+	int fd, need_close = 0;
+
+	fd = get_trace_fd(key, &need_close);
+	if (!fd)
+		return;
+
+	write_or_whine_pipe(fd, buf->buf, buf->len, err_msg);
+
+	if (need_close)
+		close(fd);
+}
+
 void trace_argv_printf(const char **argv, const char *fmt, ...)
 {
 	struct strbuf buf = STRBUF_INIT;
-- 
1.7.2.5.25.g3bb93
Jeff King· Feb 24, 2011, 14:30 UTC · re: Jeff King · lore

[PATCH 7/8] add packet tracing debug code

This shows a trace of all packets coming in or out of a given program. This can help with debugging object negotiation or other protocol issues.

To keep the code changes simple, we operate at the lowest level, meaning we don't necessarily understand what's in the packets. The one exception is a packet starting with "PACK", which causes us to skip that packet and turn off tracing (since the gigantic pack data will not be interesting to read, at least not in the trace format).

We show both written and read packets. In the local case, this may mean you will see packets twice (written by the sender and read by the receiver). However, for cases where the other end is remote, this allows you to see the full conversation.

Packet tracing can be enabled with GIT_TRACE_PACKET=<foo>, where <foo> takes the same arguments as GIT_TRACE.

Signed-off-by: Jeff King <peff@peff.net>
---
 builtin/clone.c        |    1 +
 builtin/fetch-pack.c   |    2 +
 builtin/fetch.c        |    2 +
 builtin/push.c         |    1 +
 builtin/receive-pack.c |    2 +
 cache.h                |    2 +
 pkt-line.c             |   55 +++++++++++++++++++++++++++++++++++++++++++++++-
 upload-pack.c          |    1 +
 8 files changed, 65 insertions(+), 1 deletions(-)
Show changes to 8 files +65 −1

builtin/clone.c, builtin/fetch-pack.c, builtin/fetch.c, builtin/push.c, builtin/receive-pack.c, cache.h, pkt-line.c, upload-pack.c

diff --git a/builtin/clone.c b/builtin/clone.c
index 60d9a64..38b4b71 100644
--- a/builtin/clone.c
+++ b/builtin/clone.c
@@ -383,6 +383,7 @@ int cmd_clone(int argc, const char **argv, const char *prefix)
 
 	junk_pid = getpid();
 
+	packet_trace_identity("clone");
 	argc = parse_options(argc, argv, prefix, builtin_clone_options,
 			     builtin_clone_usage, 0);
 
diff --git a/builtin/fetch-pack.c b/builtin/fetch-pack.c
index b999413..272bc38 100644
--- a/builtin/fetch-pack.c
+++ b/builtin/fetch-pack.c
@@ -804,6 +804,8 @@ int cmd_fetch_pack(int argc, const char **argv, const char *prefix)
 	char **pack_lockfile_ptr = NULL;
 	struct child_process *conn;
 
+	packet_trace_identity("fetch-pack");
+
 	nr_heads = 0;
 	heads = NULL;
 	for (i = 1; i < argc; i++) {
diff --git a/builtin/fetch.c b/builtin/fetch.c
index 357f3cd..e94e001 100644
--- a/builtin/fetch.c
+++ b/builtin/fetch.c
@@ -906,6 +906,8 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)
 	struct remote *remote;
 	int result = 0;
 
+	packet_trace_identity("fetch");
+
 	/* Record the command line for the reflog */
 	strbuf_addstr(&default_rla, "fetch");
 	for (i = 1; i < argc; i++)
diff --git a/builtin/push.c b/builtin/push.c
index e655eb7..26171ff 100644
--- a/builtin/push.c
+++ b/builtin/push.c
@@ -228,6 +228,7 @@ int cmd_push(int argc, const char **argv, const char *prefix)
 		OPT_END()
 	};
 
+	packet_trace_identity("push");
 	git_config(git_default_config, NULL);
 	argc = parse_options(argc, argv, prefix, options, push_usage, 0);
 
diff --git a/builtin/receive-pack.c b/builtin/receive-pack.c
index 760817d..5fa4be8 100644
--- a/builtin/receive-pack.c
+++ b/builtin/receive-pack.c
@@ -778,6 +778,8 @@ int cmd_receive_pack(int argc, const char **argv, const char *prefix)
 	char *dir = NULL;
 	struct command *commands;
 
+	packet_trace_identity("receive-pack");
+
 	argv++;
 	for (i = 1; i < argc; i++) {
 		const char *arg = *argv++;
diff --git a/cache.h b/cache.h
index 3978112..2e59aae 100644
--- a/cache.h
+++ b/cache.h
@@ -1074,6 +1074,8 @@ extern void trace_repo_setup(const char *prefix);
 extern int trace_want(const char *key);
 extern void trace_strbuf(const char *key, const struct strbuf *buf);
 
+void packet_trace_identity(const char *prog);
+
 /* convert.c */
 /* returns 1 if *dst was used */
 extern int convert_to_git(const char *path, const char *src, size_t len,
diff --git a/pkt-line.c b/pkt-line.c
index 295ba2b..cd1bd26 100644
--- a/pkt-line.c
+++ b/pkt-line.c
@@ -1,6 +1,51 @@
 #include "cache.h"
 #include "pkt-line.h"
 
+const char *packet_trace_prefix = "git";
+static const char trace_key[] = "GIT_TRACE_PACKET";
+
+void packet_trace_identity(const char *prog)
+{
+	packet_trace_prefix = xstrdup(prog);
+}
+
+static void packet_trace(const char *buf, unsigned int len, int write)
+{
+	int i;
+	struct strbuf out;
+
+	if (!trace_want(trace_key))
+		return;
+
+	/* +32 is just a guess for header + quoting */
+	strbuf_init(&out, len+32);
+
+	strbuf_addf(&out, "packet: %12s%c ",
+		    packet_trace_prefix, write ? '>' : '<');
+
+	if ((len >= 4 && !prefixcmp(buf, "PACK")) ||
+	    (len >= 5 && !prefixcmp(buf+1, "PACK"))) {
+		strbuf_addstr(&out, "PACK ...");
+		unsetenv(trace_key);
+	}
+	else {
+		/* XXX we should really handle printable utf8 */
+		for (i = 0; i < len; i++) {
+			/* suppress newlines */
+			if (buf[i] == '\n')
+				continue;
+			if (buf[i] >= 0x20 && buf[i] <= 0x7e)
+				strbuf_addch(&out, buf[i]);
+			else
+				strbuf_addf(&out, "\\%o", buf[i]);
+		}
+	}
+
+	strbuf_addch(&out, '\n');
+	trace_strbuf(trace_key, &out);
+	strbuf_release(&out);
+}
+
 /*
  * Write a packetized stream, where each line is preceded by
  * its length (including the header) as a 4-byte hex number.
@@ -39,11 +84,13 @@ ssize_t safe_write(int fd, const void *buf, ssize_t n)
  */
 void packet_flush(int fd)
 {
+	packet_trace("0000", 4, 1);
 	safe_write(fd, "0000", 4);
 }
 
 void packet_buf_flush(struct strbuf *buf)
 {
+	packet_trace("0000", 4, 1);
 	strbuf_add(buf, "0000", 4);
 }
 
@@ -62,6 +109,7 @@ static unsigned format_packet(const char *fmt, va_list args)
 	buffer[1] = hex(n >> 8);
 	buffer[2] = hex(n >> 4);
 	buffer[3] = hex(n);
+	packet_trace(buffer+4, n-4, 1);
 	return n;
 }
 
@@ -130,13 +178,16 @@ int packet_read_line(int fd, char *buffer, unsigned size)
 	len = packet_length(linelen);
 	if (len < 0)
 		die("protocol error: bad line length character: %.4s", linelen);
-	if (!len)
+	if (!len) {
+		packet_trace("0000", 4, 0);
 		return 0;
+	}
 	len -= 4;
 	if (len >= size)
 		die("protocol error: bad line length %d", len);
 	safe_read(fd, buffer, len);
 	buffer[len] = 0;
+	packet_trace(buffer, len, 0);
 	return len;
 }
 
@@ -153,6 +204,7 @@ int packet_get_line(struct strbuf *out,
 	if (!len) {
 		*src_buf += 4;
 		*src_len -= 4;
+		packet_trace("0000", 4, 0);
 		return 0;
 	}
 	if (*src_len < len)
@@ -165,5 +217,6 @@ int packet_get_line(struct strbuf *out,
 	strbuf_add(out, *src_buf, len);
 	*src_buf += len;
 	*src_len -= len;
+	packet_trace(out->buf, out->len, 0);
 	return len;
 }
diff --git a/upload-pack.c b/upload-pack.c
index b40a43f..0c87bc0 100644
--- a/upload-pack.c
+++ b/upload-pack.c
@@ -682,6 +682,7 @@ int main(int argc, char **argv)
 	int i;
 	int strict = 0;
 
+	packet_trace_identity("upload-pack");
 	git_extract_argv0_path(argv[0]);
 	read_replace_refs = 0;
 
-- 
1.7.2.5.25.g3bb93
Jonathan Nieder· Feb 24, 2011, 21:44 UTC · re: Jeff King · lore

Re: [PATCH 7/8] add packet tracing debug code

Jeff King wrote:
> This shows a trace of all packets coming in or out of a given
> program. This can help with debugging object negotiation or
> other protocol issues.
Sounds handy.
> Packet tracing can be enabled with GIT_TRACE_PACKET=<foo>,
> where <foo> takes the same arguments as GIT_TRACE.
[...]
Show 7 quoted lines
> --- a/builtin/clone.c
> +++ b/builtin/clone.c
> @@ -383,6 +383,7 @@ int cmd_clone(int argc, const char **argv, const char *prefix)
>  
>  	junk_pid = getpid();
>  
> +	packet_trace_identity("clone");

My first thought on reading this was "identity operation" (= pass-through), which left me a little confused.

Maybe "packet_trace_set_identity" (or ...set_prefix) would be a little clearer?

> +++ b/pkt-line.c
> @@ -1,6 +1,51 @@
[...]
Show 6 quoted lines
> +	if ((len >= 4 && !prefixcmp(buf, "PACK")) ||
> +	    (len >= 5 && !prefixcmp(buf+1, "PACK"))) {
> +		strbuf_addstr(&out, "PACK ...");
> +		unsetenv(trace_key);
> +	}
> +	else {
Style: should be cuddled, I think.
> +		/* XXX we should really handle printable utf8 */
> +		for (i = 0; i < len; i++) {

Maybe using is_utf8, extended to take a length argument? (Assuming it's okay if non-ASCII is escaped in packets containing non-utf8 parts.)

[...]
Show 6 quoted lines
> @@ -39,11 +84,13 @@ ssize_t safe_write(int fd, const void *buf, ssize_t n)
>   */
>  void packet_flush(int fd)
>  {
> +	packet_trace("0000", 4, 1);
>  	safe_write(fd, "0000", 4);
... I wonder if it would make sense to do
 static void packet_writebuf(int fd, const char *buf, size_t buflen)
 {
	packet_trace(buf, buflen, 1);
	safe_write(fd, buf, buflen);
 }

Nah, that would include the size noise for even nonempty packets, which your implementation conveniently omits.

Thanks, looks useful.
Jeff King· Feb 24, 2011, 14:30 UTC · re: Jeff King · lore

[PATCH 8/8] trace: give repo_setup trace its own key

You no longer get this output with GIT_TRACE=1; instead, you can do GIT_TRACE_SETUP=1.

Signed-off-by: Jeff King <peff@peff.net>
---
 trace.c |   11 ++++++-----
 1 files changed, 6 insertions(+), 5 deletions(-)
Show changes to trace.c +6 −5
diff --git a/trace.c b/trace.c
index 3f9f287..262260f 100644
--- a/trace.c
+++ b/trace.c
@@ -155,10 +155,11 @@ static const char *quote_crnl(const char *path)
 /* FIXME: move prefix to startup_info struct and get rid of this arg */
 void trace_repo_setup(const char *prefix)
 {
+	static const char *key = "GIT_TRACE_SETUP";
 	const char *git_work_tree;
 	char cwd[PATH_MAX];
 
-	if (!trace_want("GIT_TRACE"))
+	if (!trace_want(key))
 		return;
 
 	if (!getcwd(cwd, PATH_MAX))
@@ -170,10 +171,10 @@ void trace_repo_setup(const char *prefix)
 	if (!prefix)
 		prefix = "(null)";
 
-	trace_printf("setup: git_dir: %s\n", quote_crnl(get_git_dir()));
-	trace_printf("setup: worktree: %s\n", quote_crnl(git_work_tree));
-	trace_printf("setup: cwd: %s\n", quote_crnl(cwd));
-	trace_printf("setup: prefix: %s\n", quote_crnl(prefix));
+	trace_printf_key(key, "setup: git_dir: %s\n", quote_crnl(get_git_dir()));
+	trace_printf_key(key, "setup: worktree: %s\n", quote_crnl(git_work_tree));
+	trace_printf_key(key, "setup: cwd: %s\n", quote_crnl(cwd));
+	trace_printf_key(key, "setup: prefix: %s\n", quote_crnl(prefix));
 }
 
 int trace_want(const char *key)
-- 
1.7.2.5.25.g3bb93
Andreas Ericsson· Feb 24, 2011, 15:59 UTC · re: Jeff King · lore

Re: [PATCH 8/8] trace: give repo_setup trace its own key

On 02/24/2011 03:30 PM, Jeff King wrote:
> You no longer get this output with GIT_TRACE=1; instead, you
> can do GIT_TRACE_SETUP=1.
> 

It would be beneficial if GIT_TRACE still turned on tracing globally so one doesn't have to know all flags to start tracing for errors.

I also imagine running GIT_TRACE=1 <command> as the first step would be quite useful for when one's not entirely certain where the problem lies and then use the specific tracing flag when trying to fix it.

-- 
Andreas Ericsson                   andreas.ericsson@op5.se
OP5 AB                             www.op5.se
Tel: +46 8-230225                  Fax: +46 8-230231

Considering the successes of the wars on alcohol, poverty, drugs and
terror, I think we should give some serious thought to declaring war
on peace.
Jeff King· Feb 24, 2011, 16:05 UTC · re: Andreas Ericsson · lore

Re: [PATCH 8/8] trace: give repo_setup trace its own key

On Thu, Feb 24, 2011 at 04:59:50PM +0100, Andreas Ericsson wrote:
Show 11 quoted lines
> On 02/24/2011 03:30 PM, Jeff King wrote:
> > You no longer get this output with GIT_TRACE=1; instead, you
> > can do GIT_TRACE_SETUP=1.
> > 
> 
> It would be beneficial if GIT_TRACE still turned on tracing globally
> so one doesn't have to know all flags to start tracing for errors.
> 
> I also imagine running GIT_TRACE=1 <command> as the first step would
> be quite useful for when one's not entirely certain where the problem
> lies and then use the specific tracing flag when trying to fix it.

Yeah, I considered that GIT_TRACE should become "trace everything" and the existing traces split up into specific keys. I had a few concerns:

  - Having this splitting mechanism gives us room to add debugging code
    that is probably not interesting, but may be if you are working on a
    specific problem, without having to worry about spamming people.
    Which means GIT_TRACE may eventually become unreadably verbose.
    Maybe GIT_TRACE should include some traces, but not others (like
    packet debugging, or giant diff state dumps).
  - I didn't want to change the meaning of GIT_TRACE too much, because
    it is advice that everybody knows (in docs, mailing list archives,
    etc).

But those are not strong objections. Just giving the rationale I used while writing the patches. I'd be curious what others think.

-Peff
Christian Couder· Feb 24, 2011, 20:01 UTC · re: Jeff King · lore

Re: [PATCH 8/8] trace: give repo_setup trace its own key

On Thu, Feb 24, 2011 at 5:05 PM, Jeff King <peff@peff.net> wrote:
>
> But those are not strong objections. Just giving the rationale I used
> while writing the patches. I'd be curious what others think.
I think the design is nice!

Thanks, Christian.

Jonathan Nieder· Feb 24, 2011, 21:49 UTC · re: Jeff King · lore

Re: [PATCH 8/8] trace: give repo_setup trace its own key

Jeff King wrote:
> You no longer get this output with GIT_TRACE=1; instead, you
> can do GIT_TRACE_SETUP=1.
Thank you. :)
Show 7 quoted lines
> --- a/trace.c
> +++ b/trace.c
> @@ -155,10 +155,11 @@ static const char *quote_crnl(const char *path)
>  /* FIXME: move prefix to startup_info struct and get rid of this arg */
>  void trace_repo_setup(const char *prefix)
>  {
> +	static const char *key = "GIT_TRACE_SETUP";
Micronit:
	static const char key[] = ...
Show 12 quoted lines
> @@ -170,10 +171,10 @@ void trace_repo_setup(const char *prefix)
>  	if (!prefix)
>  		prefix = "(null)";
>  
> -	trace_printf("setup: git_dir: %s\n", quote_crnl(get_git_dir()));
> -	trace_printf("setup: worktree: %s\n", quote_crnl(git_work_tree));
> -	trace_printf("setup: cwd: %s\n", quote_crnl(cwd));
> -	trace_printf("setup: prefix: %s\n", quote_crnl(prefix));
> +	trace_printf_key(key, "setup: git_dir: %s\n", quote_crnl(get_git_dir()));
> +	trace_printf_key(key, "setup: worktree: %s\n", quote_crnl(git_work_tree));
> +	trace_printf_key(key, "setup: cwd: %s\n", quote_crnl(cwd));
> +	trace_printf_key(key, "setup: prefix: %s\n", quote_crnl(prefix));
I wonder if it would make sense for this to be
	trace_printf("setup", "git_dir: %s\n", ...);
and:
 - automatically prefix each line with the key instead of "trace:"
 - enable or redirect based on the content of the GIT_TRACE_$(uc $key)
   variable
But what you have here already works, so:
Reviewed-by: Jonathan Nieder <jrnieder@gmail.com>
Nguyen Thai Ngoc Duy· Feb 25, 2011, 06:38 UTC · re: Jonathan Nieder · lore

Re: [PATCH 8/8] trace: give repo_setup trace its own key

On Fri, Feb 25, 2011 at 4:49 AM, Jonathan Nieder <jrnieder@gmail.com> wrote:
> Jeff King wrote:
>
>> You no longer get this output with GIT_TRACE=1; instead, you
>> can do GIT_TRACE_SETUP=1.

Minor note. GIT_TRACE warning in test-lib.sh will need improvement for checking GIT_TRACE_*

Show 22 quoted lines
>> @@ -170,10 +171,10 @@ void trace_repo_setup(const char *prefix)
>>       if (!prefix)
>>               prefix = "(null)";
>>
>> -     trace_printf("setup: git_dir: %s\n", quote_crnl(get_git_dir()));
>> -     trace_printf("setup: worktree: %s\n", quote_crnl(git_work_tree));
>> -     trace_printf("setup: cwd: %s\n", quote_crnl(cwd));
>> -     trace_printf("setup: prefix: %s\n", quote_crnl(prefix));
>> +     trace_printf_key(key, "setup: git_dir: %s\n", quote_crnl(get_git_dir()));
>> +     trace_printf_key(key, "setup: worktree: %s\n", quote_crnl(git_work_tree));
>> +     trace_printf_key(key, "setup: cwd: %s\n", quote_crnl(cwd));
>> +     trace_printf_key(key, "setup: prefix: %s\n", quote_crnl(prefix));
>
> I wonder if it would make sense for this to be
>
>        trace_printf("setup", "git_dir: %s\n", ...);
>
> and:
>
>  - automatically prefix each line with the key instead of "trace:"
>  - enable or redirect based on the content of the GIT_TRACE_$(uc $key)
>   variable

Yeah I think it's nice to have key = "setup", then env name becomes GIT_TRACE_$(uc $key) and prepend "$key: " in all trace messages.

-- 
Duy
Junio C Hamano· Feb 26, 2011, 08:34 UTC · re: Jeff King · lore

Re: [PATCH 8/8] trace: give repo_setup trace its own key

Jeff King <peff@peff.net> writes:
> You no longer get this output with GIT_TRACE=1; instead, you
> can do GIT_TRACE_SETUP=1.
>
> Signed-off-by: Jeff King <peff@peff.net>
Hence you would need this on top?
 t/t1510-repo-setup.sh |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)
Show changes to t/t1510-repo-setup.sh +1 −1
diff --git a/t/t1510-repo-setup.sh b/t/t1510-repo-setup.sh
index 15101d5..ec50a9a 100755
--- a/t/t1510-repo-setup.sh
+++ b/t/t1510-repo-setup.sh
@@ -57,7 +57,7 @@ test_repo () {
 			export GIT_WORK_TREE
 		fi &&
 		rm -f trace &&
-		GIT_TRACE="$(pwd)/trace" git symbolic-ref HEAD >/dev/null &&
+		GIT_TRACE_SETUP="$(pwd)/trace" git symbolic-ref HEAD >/dev/null &&
 		grep '^setup: ' trace >result &&
 		test_cmp expected result
 	)

← back to recent threads