[PATCH/RFC 0/8] refactor trace code

[PATCH/RFC 0/8] refactor trace code

[Jeff King]

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

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

[Jeff King]

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
+
 /*
  * 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

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

[Erik Faye-Lund]

On Thu, Feb 24, 2011 at 3:26 PM, Jeff King <peff@peff.net> wrote:
> 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?

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

[Jonathan Nieder]

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(-)

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

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

[Junio C Hamano]

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.

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

[Jonathan Nieder]

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.

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

[Jonathan Nieder]

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.

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
 

[PATCH 2/8] strbuf: add strbuf_addv

[Jeff King]

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(-)

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

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

[Christian Couder]

Hi,

On Thu, Feb 24, 2011 at 3:27 PM, Jeff King <peff@peff.net> wrote:
> +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.

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

[Jeff King]

On Thu, Feb 24, 2011 at 04:05:13PM +0100, Christian Couder wrote:

> > +       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

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

[Jonathan Nieder]

Jeff King wrote:

> 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.

> --- 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);
---
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 *);

[PATCH 3/8] trace: add trace_vprintf

[Jeff King]

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(-)

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

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

[Jonathan Nieder]

Jeff King wrote:

> --- 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?
---
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, ...);

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

[Jeff King]

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(-)

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

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

[Junio C Hamano]

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.

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.

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

[Jeff King]

On Thu, Feb 24, 2011 at 10:25:04AM -0800, Junio C Hamano wrote:

> 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.

> 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).

> 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.

> 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

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

[Junio C Hamano]

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.

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

[Jeff King]

On Thu, Feb 24, 2011 at 11:44:13AM -0800, Junio C Hamano wrote:

> 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.

> > 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

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

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

>> > 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.

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

[Jonathan Nieder]

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"?

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

[Jeff King]

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(-)

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

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

[Christian Couder]

On Thu, Feb 24, 2011 at 3:28 PM, Jeff King <peff@peff.net> wrote:

> +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.

[PATCH 6/8] trace: add trace_strbuf

[Jeff King]

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(-)

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

[PATCH 7/8] add packet tracing debug code

[Jeff King]

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(-)

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

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

[Jonathan Nieder]

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.
[...]
> --- 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 @@
[...]
> +	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.)

[...]
> @@ -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.

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

[Jeff King]

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(-)

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

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

[Andreas Ericsson]

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.

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

[Jeff King]

On Thu, Feb 24, 2011 at 04:59:50PM +0100, Andreas Ericsson wrote:

> 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

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

[Christian Couder]

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.

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

[Jonathan Nieder]

Jeff King wrote:

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

Thank you. :)

> --- 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[] = ...

> @@ -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>

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

[Nguyen Thai Ngoc Duy]

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_*

>> @@ -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

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

[Junio C Hamano]

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(-)

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
 	)