[PATCH] run-command.c: print env vars when GIT_TRACE is set

[PATCH] run-command.c: print env vars when GIT_TRACE is set

[Nguyễn Thái Ngọc Duy]

Occasionally submodule code could execute new commands with GIT_DIR set
to some submodule. GIT_TRACE prints just the command line which makes it
hard to tell that it's not really executed on this repository.

Print env variables in this case. Note that the code deliberately ignore
variables unsetting because there are so many of them (to keep git
environment clean for the next process) and really hard to read.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 A minor thing that I ignored in this patch is quoting the environment
 variables. For me it's meh. Perhaps I should just dumb the env
 without quoting at all.

 run-command.c |  3 ++-
 trace.c       | 38 +++++++++++++++++++++++++++++++++++---
 trace.h       | 18 +++++++++++++++---
 3 files changed, 52 insertions(+), 7 deletions(-)

diff --git a/run-command.c b/run-command.c
index 31fc5ea86e..235367087d 100644
--- a/run-command.c
+++ b/run-command.c
@@ -624,7 +624,8 @@ int start_command(struct child_process *cmd)
 		cmd->err = fderr[0];
 	}
 
-	trace_argv_printf(cmd->argv, "trace: run_command:");
+	trace_env_argv_printf(cmd->env, cmd->argv, "trace: run_command:");
+
 	fflush(NULL);
 
 #ifndef GIT_WINDOWS_NATIVE
diff --git a/trace.c b/trace.c
index b7530b51a9..d8967b66e8 100644
--- a/trace.c
+++ b/trace.c
@@ -146,7 +146,26 @@ static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
 	print_trace_line(key, &buf);
 }
 
+static void concatenate_env(struct strbuf *dst, const char *const *env)
+{
+	int i;
+
+	/* Copy into destination buffer. */
+	strbuf_grow(dst, 255);
+	for (i = 0; env[i]; ++i) {
+		/*
+		 * the main interesting is setting new vars
+		 * e.g. GIT_DIR, ignore the unsetting to reduce noise.
+		 */
+		if (!strchr(env[i], '='))
+			continue;
+		strbuf_addch(dst, ' ');
+		sq_quote_buf(dst, env[i]);
+	}
+}
+
 static void trace_argv_vprintf_fl(const char *file, int line,
+				  const char *const *env,
 				  const char **argv, const char *format,
 				  va_list ap)
 {
@@ -157,6 +176,9 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	strbuf_vaddf(&buf, format, ap);
 
+	if (env)
+		concatenate_env(&buf, env);
+
 	sq_quote_argv(&buf, argv, 0);
 	print_trace_line(&trace_default_key, &buf);
 }
@@ -214,7 +236,16 @@ void trace_argv_printf(const char **argv, const char *format, ...)
 {
 	va_list ap;
 	va_start(ap, format);
-	trace_argv_vprintf_fl(NULL, 0, argv, format, ap);
+	trace_argv_vprintf_fl(NULL, 0, NULL, argv, format, ap);
+	va_end(ap);
+}
+
+void trace_env_argv_printf(const char *const *env, const char **argv,
+			   const char *format, ...)
+{
+	va_list ap;
+	va_start(ap, format);
+	trace_argv_vprintf_fl(NULL, 0, env, argv, format, ap);
 	va_end(ap);
 }
 
@@ -251,12 +282,13 @@ void trace_printf_key_fl(const char *file, int line, struct trace_key *key,
 	va_end(ap);
 }
 
-void trace_argv_printf_fl(const char *file, int line, const char **argv,
+void trace_argv_printf_fl(const char *file, int line,
+			  const char *const *env, const char **argv,
 			  const char *format, ...)
 {
 	va_list ap;
 	va_start(ap, format);
-	trace_argv_vprintf_fl(file, line, argv, format, ap);
+	trace_argv_vprintf_fl(file, line, env, argv, format, ap);
 	va_end(ap);
 }
 
diff --git a/trace.h b/trace.h
index 88055abef7..830d9dcd19 100644
--- a/trace.h
+++ b/trace.h
@@ -34,6 +34,10 @@ extern void trace_printf_key(struct trace_key *key, const char *format, ...);
 __attribute__((format (printf, 2, 3)))
 extern void trace_argv_printf(const char **argv, const char *format, ...);
 
+__attribute__((format (printf, 3, 4)))
+extern void trace_env_argv_printf(const char * const*env, const char **argv,
+				  const char *format, ...);
+
 extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);
 
 /* Prints elapsed time (in nanoseconds) if GIT_TRACE_PERFORMANCE is enabled. */
@@ -93,7 +97,14 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);
 	do {								    \
 		if (trace_pass_fl(&trace_default_key))			    \
 			trace_argv_printf_fl(TRACE_CONTEXT, __LINE__,	    \
-					    argv, __VA_ARGS__);		    \
+					     NULL, argv, __VA_ARGS__);	    \
+	} while (0)
+
+#define trace_env_argv_printf(env, argv, ...)				    \
+	do {								    \
+		if (trace_pass_fl(&trace_default_key))			    \
+			trace_argv_printf_fl(TRACE_CONTEXT, __LINE__, 	    \
+					     env, argv, __VA_ARGS__); 	    \
 	} while (0)
 
 #define trace_strbuf(key, data)						    \
@@ -121,8 +132,9 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);
 __attribute__((format (printf, 4, 5)))
 extern void trace_printf_key_fl(const char *file, int line, struct trace_key *key,
 				const char *format, ...);
-__attribute__((format (printf, 4, 5)))
-extern void trace_argv_printf_fl(const char *file, int line, const char **argv,
+__attribute__((format (printf, 5, 6)))
+extern void trace_argv_printf_fl(const char *file, int line,
+				 const char *const *env, const char **argv,
 				 const char *format, ...);
 extern void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
 			    const struct strbuf *data);
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH] run-command.c: print env vars when GIT_TRACE is set

[Brandon Williams]

On 01/10, Nguyễn Thái Ngọc Duy wrote:
> Occasionally submodule code could execute new commands with GIT_DIR set
> to some submodule. GIT_TRACE prints just the command line which makes it
> hard to tell that it's not really executed on this repository.
> 
> Print env variables in this case. Note that the code deliberately ignore
> variables unsetting because there are so many of them (to keep git
> environment clean for the next process) and really hard to read.
> 
> Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
> ---
>  A minor thing that I ignored in this patch is quoting the environment
>  variables. For me it's meh. Perhaps I should just dumb the env
>  without quoting at all.

A patch like this would have been very helpful to me on some previous
occasions, so thanks for writing it up.

> 
>  run-command.c |  3 ++-
>  trace.c       | 38 +++++++++++++++++++++++++++++++++++---
>  trace.h       | 18 +++++++++++++++---
>  3 files changed, 52 insertions(+), 7 deletions(-)
> 
> diff --git a/run-command.c b/run-command.c
> index 31fc5ea86e..235367087d 100644
> --- a/run-command.c
> +++ b/run-command.c
> @@ -624,7 +624,8 @@ int start_command(struct child_process *cmd)
>  		cmd->err = fderr[0];
>  	}
>  
> -	trace_argv_printf(cmd->argv, "trace: run_command:");
> +	trace_env_argv_printf(cmd->env, cmd->argv, "trace: run_command:");
> +
>  	fflush(NULL);
>  
>  #ifndef GIT_WINDOWS_NATIVE
> diff --git a/trace.c b/trace.c
> index b7530b51a9..d8967b66e8 100644
> --- a/trace.c
> +++ b/trace.c
> @@ -146,7 +146,26 @@ static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
>  	print_trace_line(key, &buf);
>  }
>  
> +static void concatenate_env(struct strbuf *dst, const char *const *env)
> +{
> +	int i;
> +
> +	/* Copy into destination buffer. */
> +	strbuf_grow(dst, 255);
> +	for (i = 0; env[i]; ++i) {
> +		/*
> +		 * the main interesting is setting new vars
> +		 * e.g. GIT_DIR, ignore the unsetting to reduce noise.
> +		 */

I think you're missing a word, maybe:
  'The main interesting part is setting new vars'

> +		if (!strchr(env[i], '='))
> +			continue;
> +		strbuf_addch(dst, ' ');
> +		sq_quote_buf(dst, env[i]);
> +	}

At first when i read this I was under the impression that the whole
environment was going to be printed out...but i now realize that this
tracing  will only print out the delta's or the additions to the
environment that the child will see.  Maybe this should be called out
more clearly in the commit message?

> +}
> +
>  static void trace_argv_vprintf_fl(const char *file, int line,
> +				  const char *const *env,
>  				  const char **argv, const char *format,
>  				  va_list ap)
>  {
> @@ -157,6 +176,9 @@ static void trace_argv_vprintf_fl(const char *file, int line,
>  
>  	strbuf_vaddf(&buf, format, ap);
>  
> +	if (env)
> +		concatenate_env(&buf, env);
> +
>  	sq_quote_argv(&buf, argv, 0);
>  	print_trace_line(&trace_default_key, &buf);
>  }
> @@ -214,7 +236,16 @@ void trace_argv_printf(const char **argv, const char *format, ...)
>  {
>  	va_list ap;
>  	va_start(ap, format);
> -	trace_argv_vprintf_fl(NULL, 0, argv, format, ap);
> +	trace_argv_vprintf_fl(NULL, 0, NULL, argv, format, ap);
> +	va_end(ap);
> +}
> +
> +void trace_env_argv_printf(const char *const *env, const char **argv,
> +			   const char *format, ...)
> +{
> +	va_list ap;
> +	va_start(ap, format);
> +	trace_argv_vprintf_fl(NULL, 0, env, argv, format, ap);
>  	va_end(ap);
>  }
>  
> @@ -251,12 +282,13 @@ void trace_printf_key_fl(const char *file, int line, struct trace_key *key,
>  	va_end(ap);
>  }
>  
> -void trace_argv_printf_fl(const char *file, int line, const char **argv,
> +void trace_argv_printf_fl(const char *file, int line,
> +			  const char *const *env, const char **argv,
>  			  const char *format, ...)
>  {
>  	va_list ap;
>  	va_start(ap, format);
> -	trace_argv_vprintf_fl(file, line, argv, format, ap);
> +	trace_argv_vprintf_fl(file, line, env, argv, format, ap);
>  	va_end(ap);
>  }
>  
> diff --git a/trace.h b/trace.h
> index 88055abef7..830d9dcd19 100644
> --- a/trace.h
> +++ b/trace.h
> @@ -34,6 +34,10 @@ extern void trace_printf_key(struct trace_key *key, const char *format, ...);
>  __attribute__((format (printf, 2, 3)))
>  extern void trace_argv_printf(const char **argv, const char *format, ...);
>  
> +__attribute__((format (printf, 3, 4)))
> +extern void trace_env_argv_printf(const char * const*env, const char **argv,
> +				  const char *format, ...);
> +
>  extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);
>  
>  /* Prints elapsed time (in nanoseconds) if GIT_TRACE_PERFORMANCE is enabled. */
> @@ -93,7 +97,14 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);
>  	do {								    \
>  		if (trace_pass_fl(&trace_default_key))			    \
>  			trace_argv_printf_fl(TRACE_CONTEXT, __LINE__,	    \
> -					    argv, __VA_ARGS__);		    \
> +					     NULL, argv, __VA_ARGS__);	    \
> +	} while (0)
> +
> +#define trace_env_argv_printf(env, argv, ...)				    \
> +	do {								    \
> +		if (trace_pass_fl(&trace_default_key))			    \
> +			trace_argv_printf_fl(TRACE_CONTEXT, __LINE__, 	    \
> +					     env, argv, __VA_ARGS__); 	    \
>  	} while (0)
>  
>  #define trace_strbuf(key, data)						    \
> @@ -121,8 +132,9 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);
>  __attribute__((format (printf, 4, 5)))
>  extern void trace_printf_key_fl(const char *file, int line, struct trace_key *key,
>  				const char *format, ...);
> -__attribute__((format (printf, 4, 5)))
> -extern void trace_argv_printf_fl(const char *file, int line, const char **argv,
> +__attribute__((format (printf, 5, 6)))
> +extern void trace_argv_printf_fl(const char *file, int line,
> +				 const char *const *env, const char **argv,
>  				 const char *format, ...);
>  extern void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
>  			    const struct strbuf *data);
> -- 
> 2.15.1.600.g899a5f85c6
> 

-- 
Brandon Williams

Re: [PATCH] run-command.c: print env vars when GIT_TRACE is set

[Stefan Beller]

On Wed, Jan 10, 2018 at 10:09 AM, Brandon Williams <bmwill@google.com> wrote:
> On 01/10, Nguyễn Thái Ngọc Duy wrote:
>> Occasionally submodule code could execute new commands with GIT_DIR set
>> to some submodule. GIT_TRACE prints just the command line which makes it
>> hard to tell that it's not really executed on this repository.

Speaking of GIT_DIR, we may also want to print the dir that the command is
executed in as the GIT_DIR for submodules usually is only ".git" assuming the
run-command struct set the .dir to the submodules worktree. I think I had a
patch for printing the cwd of a process on the list once upon a time, but
I am unable to find it again. Maybe we'd want to include the cwd of a spawned
process if it differs from the current process?

>>
>> Print env variables in this case. Note that the code deliberately ignore
>> variables unsetting because there are so many of them (to keep git
>> environment clean for the next process) and really hard to read.
>>
>> Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
>> ---
>>  A minor thing that I ignored in this patch is quoting the environment
>>  variables. For me it's meh. Perhaps I should just dumb the env
>>  without quoting at all.
>
> A patch like this would have been very helpful to me on some previous
> occasions, so thanks for writing it up.

The patch I mentioned above (very similar though less powerful than this one)
was carried by locally for some time, so I definitely see value in this patch.
Thanks for writing it!

>
>>
>>  run-command.c |  3 ++-
>>  trace.c       | 38 +++++++++++++++++++++++++++++++++++---
>>  trace.h       | 18 +++++++++++++++---
>>  3 files changed, 52 insertions(+), 7 deletions(-)
>>
>> diff --git a/run-command.c b/run-command.c
>> index 31fc5ea86e..235367087d 100644
>> --- a/run-command.c
>> +++ b/run-command.c
>> @@ -624,7 +624,8 @@ int start_command(struct child_process *cmd)
>>               cmd->err = fderr[0];
>>       }
>>
>> -     trace_argv_printf(cmd->argv, "trace: run_command:");
>> +     trace_env_argv_printf(cmd->env, cmd->argv, "trace: run_command:");
>> +
>>       fflush(NULL);
>>
>>  #ifndef GIT_WINDOWS_NATIVE
>> diff --git a/trace.c b/trace.c
>> index b7530b51a9..d8967b66e8 100644
>> --- a/trace.c
>> +++ b/trace.c
>> @@ -146,7 +146,26 @@ static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
>>       print_trace_line(key, &buf);
>>  }
>>
>> +static void concatenate_env(struct strbuf *dst, const char *const *env)
>> +{
>> +     int i;
>> +
>> +     /* Copy into destination buffer. */
>> +     strbuf_grow(dst, 255);
>> +     for (i = 0; env[i]; ++i) {
>> +             /*
>> +              * the main interesting is setting new vars
>> +              * e.g. GIT_DIR, ignore the unsetting to reduce noise.
>> +              */
>
> I think you're missing a word, maybe:
>   'The main interesting part is setting new vars'
>
>> +             if (!strchr(env[i], '='))
>> +                     continue;
>> +             strbuf_addch(dst, ' ');
>> +             sq_quote_buf(dst, env[i]);
>> +     }
>
> At first when i read this I was under the impression that the whole
> environment was going to be printed out...but i now realize that this
> tracing  will only print out the delta's or the additions to the
> environment that the child will see.  Maybe this should be called out
> more clearly in the commit message?

It only adds newly set variables, I wonder why deletions are noisy?
I could not find an example of a removal of environment variables
specific to submodules that would be noisy.

Stefan

Re: [PATCH] run-command.c: print env vars when GIT_TRACE is set

[Brandon Williams]

On 01/10, Stefan Beller wrote:
> On Wed, Jan 10, 2018 at 10:09 AM, Brandon Williams <bmwill@google.com> wrote:
> > At first when i read this I was under the impression that the whole
> > environment was going to be printed out...but i now realize that this
> > tracing  will only print out the delta's or the additions to the
> > environment that the child will see.  Maybe this should be called out
> > more clearly in the commit message?
> 
> It only adds newly set variables, I wonder why deletions are noisy?
> I could not find an example of a removal of environment variables
> specific to submodules that would be noisy.

Deletions are noisy because we append local_repo_env anytime we kick
off a child process (ok maybe not all the time, but a lot of the time)
which is just a list of ~15 deletions.

-- 
Brandon Williams

Re: [PATCH] run-command.c: print env vars when GIT_TRACE is set

[Stefan Beller]

On Wed, Jan 10, 2018 at 11:26 AM, Brandon Williams <bmwill@google.com> wrote:
> On 01/10, Stefan Beller wrote:
>> On Wed, Jan 10, 2018 at 10:09 AM, Brandon Williams <bmwill@google.com> wrote:
>> > At first when i read this I was under the impression that the whole
>> > environment was going to be printed out...but i now realize that this
>> > tracing  will only print out the delta's or the additions to the
>> > environment that the child will see.  Maybe this should be called out
>> > more clearly in the commit message?
>>
>> It only adds newly set variables, I wonder why deletions are noisy?
>> I could not find an example of a removal of environment variables
>> specific to submodules that would be noisy.
>
> Deletions are noisy because we append local_repo_env anytime we kick
> off a child process (ok maybe not all the time, but a lot of the time)
> which is just a list of ~15 deletions.

Oh, I see. I'm fine with that.

Though to further the discussion, maybe we want to check if such a variable
is set and if so actually show the deletion? I have the impression that most
of the variables are not set, and yet we unconditionally delete them, "just to
be sure". Maybe we'd only want to delete them if we actually have them
set in the superproject, and then we can show the diff in env vars
more faithful?

[PATCH v2] run-command.c: print env vars when GIT_TRACE is set

[Nguyễn Thái Ngọc Duy]

Occasionally submodule code could execute new commands with GIT_DIR set
to some submodule. GIT_TRACE prints just the command line which makes it
hard to tell that it's not really executed on this repository.

Print modified env variables (compared to parent environment) in this
case. Actually only modified or new variables are printed. Variable
deletion is suppressed because they are often used to clean up
repo-specific variables that git passes around between processes. When
submodule code executes commands on another repo, it clears all these
variables, _many_ of these, that make the output really noisy.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 v2 fixes up commit message to clarify about "env delta" and why var
 deletion is not printed.

 It also keeps child_process tracing in one place/function, this
 should make it easier to trace more e.g. cwd and stuff.

 Though, Stefan, while i'm not opposed to trace every single setting
 in child_process, including variable deletion, cwd and even more, it
 may be not that often needed for a "casual" developer.
 
 I suggest we have something like $GIT_TRACE_EXEC instead that could
 be super verbose when we need it and leave $GIT_TRACE with a
 reasonable subset.

 run-command.c |  3 ++-
 trace.c       | 39 +++++++++++++++++++++++++++++++++++++++
 trace.h       |  3 +++
 3 files changed, 44 insertions(+), 1 deletion(-)

diff --git a/run-command.c b/run-command.c
index 31fc5ea86e..002074b128 100644
--- a/run-command.c
+++ b/run-command.c
@@ -624,7 +624,8 @@ int start_command(struct child_process *cmd)
 		cmd->err = fderr[0];
 	}
 
-	trace_argv_printf(cmd->argv, "trace: run_command:");
+	trace_run_command(cmd);
+
 	fflush(NULL);
 
 #ifndef GIT_WINDOWS_NATIVE
diff --git a/trace.c b/trace.c
index b7530b51a9..e5e46e2a09 100644
--- a/trace.c
+++ b/trace.c
@@ -23,6 +23,7 @@
 
 #include "cache.h"
 #include "quote.h"
+#include "run-command.h"
 
 struct trace_key trace_default_key = { "GIT_TRACE", 0, 0, 0 };
 struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
@@ -272,6 +273,44 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 #endif /* HAVE_VARIADIC_MACROS */
 
 
+static void concatenate_env(struct strbuf *dst, const char *const *env)
+{
+	int i;
+
+	/* Copy into destination buffer. */
+	strbuf_grow(dst, 255);
+	for (i = 0; env[i]; ++i) {
+		/*
+		 * the main interesting is setting new vars
+		 * e.g. GIT_DIR, ignore the unsetting to reduce noise.
+		 */
+		if (!strchr(env[i], '='))
+			continue;
+		strbuf_addch(dst, ' ');
+		sq_quote_buf(dst, env[i]);
+	}
+}
+
+void trace_run_command(const struct child_process *cp)
+{
+	struct strbuf buf = STRBUF_INIT;
+
+	if (!prepare_trace_line(NULL, 0, &trace_default_key, &buf))
+		return;
+
+	strbuf_addf(&buf, "trace: run_command:");
+
+	/*
+	 * caller is responsible for setting this if the main source
+	 * is actually in cp->env_array
+	 */
+	if (cp->env)
+		concatenate_env(&buf, cp->env);
+
+	sq_quote_argv(&buf, cp->argv, 0);
+	print_trace_line(&trace_default_key, &buf);
+}
+
 static const char *quote_crnl(const char *path)
 {
 	static struct strbuf new_path = STRBUF_INIT;
diff --git a/trace.h b/trace.h
index 88055abef7..e54c687f26 100644
--- a/trace.h
+++ b/trace.h
@@ -4,6 +4,8 @@
 #include "git-compat-util.h"
 #include "strbuf.h"
 
+struct child_process;
+
 struct trace_key {
 	const char * const key;
 	int fd;
@@ -17,6 +19,7 @@ extern struct trace_key trace_default_key;
 extern struct trace_key trace_perf_key;
 
 extern void trace_repo_setup(const char *prefix);
+extern void trace_run_command(const struct child_process *cp);
 extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
 extern uint64_t getnanotime(void);
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v2] run-command.c: print env vars when GIT_TRACE is set

[Duy Nguyen]

On Thu, Jan 11, 2018 at 4:47 PM, Nguyễn Thái Ngọc Duy <pclouds@gmail.com> wrote:
>  Though, Stefan, while i'm not opposed to trace every single setting
>  in child_process, including variable deletion, cwd and even more, it

Another thing I forgot to add, s/ and even more/, redirection&/. At
some point I think I was checking the git-pack-objects command from
GIT_TRACE and didn't realize it was taking input from stdin (I was
naive :D). At least on linux we could even take advantage of
/proc/<pid>/fd to show path names and stuff in addition to plain file
descriptors.

>  may be not that often needed for a "casual" developer.
>
>  I suggest we have something like $GIT_TRACE_EXEC instead that could
>  be super verbose when we need it and leave $GIT_TRACE with a
>  reasonable subset.
-- 
Duy

Re: [PATCH v2] run-command.c: print env vars when GIT_TRACE is set

[Brandon Williams]

On 01/11, Nguyễn Thái Ngọc Duy wrote:
> Occasionally submodule code could execute new commands with GIT_DIR set
> to some submodule. GIT_TRACE prints just the command line which makes it
> hard to tell that it's not really executed on this repository.
> 
> Print modified env variables (compared to parent environment) in this
> case. Actually only modified or new variables are printed. Variable
> deletion is suppressed because they are often used to clean up
> repo-specific variables that git passes around between processes. When
> submodule code executes commands on another repo, it clears all these
> variables, _many_ of these, that make the output really noisy.
> 
> Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
> ---
>  v2 fixes up commit message to clarify about "env delta" and why var
>  deletion is not printed.
> 
>  It also keeps child_process tracing in one place/function, this
>  should make it easier to trace more e.g. cwd and stuff.
> 
>  Though, Stefan, while i'm not opposed to trace every single setting
>  in child_process, including variable deletion, cwd and even more, it
>  may be not that often needed for a "casual" developer.
>  
>  I suggest we have something like $GIT_TRACE_EXEC instead that could
>  be super verbose when we need it and leave $GIT_TRACE with a
>  reasonable subset.
> 
>  run-command.c |  3 ++-
>  trace.c       | 39 +++++++++++++++++++++++++++++++++++++++
>  trace.h       |  3 +++
>  3 files changed, 44 insertions(+), 1 deletion(-)
> 
> diff --git a/run-command.c b/run-command.c
> index 31fc5ea86e..002074b128 100644
> --- a/run-command.c
> +++ b/run-command.c
> @@ -624,7 +624,8 @@ int start_command(struct child_process *cmd)
>  		cmd->err = fderr[0];
>  	}
>  
> -	trace_argv_printf(cmd->argv, "trace: run_command:");
> +	trace_run_command(cmd);
> +
>  	fflush(NULL);
>  
>  #ifndef GIT_WINDOWS_NATIVE
> diff --git a/trace.c b/trace.c
> index b7530b51a9..e5e46e2a09 100644
> --- a/trace.c
> +++ b/trace.c
> @@ -23,6 +23,7 @@
>  
>  #include "cache.h"
>  #include "quote.h"
> +#include "run-command.h"
>  
>  struct trace_key trace_default_key = { "GIT_TRACE", 0, 0, 0 };
>  struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
> @@ -272,6 +273,44 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
>  #endif /* HAVE_VARIADIC_MACROS */
>  
>  
> +static void concatenate_env(struct strbuf *dst, const char *const *env)
> +{
> +	int i;
> +
> +	/* Copy into destination buffer. */
> +	strbuf_grow(dst, 255);
> +	for (i = 0; env[i]; ++i) {
> +		/*
> +		 * the main interesting is setting new vars
> +		 * e.g. GIT_DIR, ignore the unsetting to reduce noise.
> +		 */

Patch looks good to me! Only nit is this comment which reads funny which i
pointed out in v1.

> +		if (!strchr(env[i], '='))
> +			continue;
> +		strbuf_addch(dst, ' ');
> +		sq_quote_buf(dst, env[i]);
> +	}
> +}
> +
> +void trace_run_command(const struct child_process *cp)
> +{
> +	struct strbuf buf = STRBUF_INIT;
> +
> +	if (!prepare_trace_line(NULL, 0, &trace_default_key, &buf))
> +		return;
> +
> +	strbuf_addf(&buf, "trace: run_command:");
> +
> +	/*
> +	 * caller is responsible for setting this if the main source
> +	 * is actually in cp->env_array
> +	 */
> +	if (cp->env)
> +		concatenate_env(&buf, cp->env);
> +
> +	sq_quote_argv(&buf, cp->argv, 0);
> +	print_trace_line(&trace_default_key, &buf);
> +}
> +
>  static const char *quote_crnl(const char *path)
>  {
>  	static struct strbuf new_path = STRBUF_INIT;
> diff --git a/trace.h b/trace.h
> index 88055abef7..e54c687f26 100644
> --- a/trace.h
> +++ b/trace.h
> @@ -4,6 +4,8 @@
>  #include "git-compat-util.h"
>  #include "strbuf.h"
>  
> +struct child_process;
> +
>  struct trace_key {
>  	const char * const key;
>  	int fd;
> @@ -17,6 +19,7 @@ extern struct trace_key trace_default_key;
>  extern struct trace_key trace_perf_key;
>  
>  extern void trace_repo_setup(const char *prefix);
> +extern void trace_run_command(const struct child_process *cp);
>  extern int trace_want(struct trace_key *key);
>  extern void trace_disable(struct trace_key *key);
>  extern uint64_t getnanotime(void);
> -- 
> 2.15.1.600.g899a5f85c6
> 

-- 
Brandon Williams

Re: [PATCH v2] run-command.c: print env vars when GIT_TRACE is set

[Stefan Beller]

On Thu, Jan 11, 2018 at 9:53 AM, Brandon Williams <bmwill@google.com> wrote:
> On 01/11, Nguyễn Thái Ngọc Duy wrote:
>> Occasionally submodule code could execute new commands with GIT_DIR set
>> to some submodule. GIT_TRACE prints just the command line which makes it
>> hard to tell that it's not really executed on this repository.
>>
>> Print modified env variables (compared to parent environment) in this
>> case. Actually only modified or new variables are printed. Variable
>> deletion is suppressed because they are often used to clean up
>> repo-specific variables that git passes around between processes. When
>> submodule code executes commands on another repo, it clears all these
>> variables, _many_ of these, that make the output really noisy.
>>
>> Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
>> ---
>>  v2 fixes up commit message to clarify about "env delta" and why var
>>  deletion is not printed.
>>
>>  It also keeps child_process tracing in one place/function, this
>>  should make it easier to trace more e.g. cwd and stuff.
>>
>>  Though, Stefan, while i'm not opposed to trace every single setting
>>  in child_process, including variable deletion, cwd and even more, it
>>  may be not that often needed for a "casual" developer.
>>
>>  I suggest we have something like $GIT_TRACE_EXEC instead that could
>>  be super verbose when we need it and leave $GIT_TRACE with a
>>  reasonable subset.

Makes sense. Thanks for working on this!
Code&commit msg look good to me. I agree with Brandon on the
comments grammar to have a missing piece.

Thanks,
Stefan

Re: [PATCH v2] run-command.c: print env vars when GIT_TRACE is set

[Junio C Hamano]

Nguyễn Thái Ngọc Duy  <pclouds@gmail.com> writes:

> Occasionally submodule code could execute new commands with GIT_DIR set
> to some submodule. GIT_TRACE prints just the command line which makes it
> hard to tell that it's not really executed on this repository.
>
> Print modified env variables (compared to parent environment) in this
> case. Actually only modified or new variables are printed. Variable
> deletion is suppressed because ...

When I read the above, I imagined that you are reducing noise from
the output by showing only modified or new variables, but it appears
that the implementation of concatenate_env() just blindly copies the
variables without checking if they are setting the same value.

I wonder how common it would be to attempt exporting a variable with
the same value, and to attempt unsetting a variable that is not
exported, which might help you reduce the clutter by hiding stuff
that truly do not matter, while keeping what matters (possibly
including the "unset" part).

> +static void concatenate_env(struct strbuf *dst, const char *const *env)
> +{
> +	int i;
> +
> +	/* Copy into destination buffer. */
> +	strbuf_grow(dst, 255);
> +	for (i = 0; env[i]; ++i) {
> +		/*
> +		 * the main interesting is setting new vars

I'll do s/interesting/& part/ while queuing.

> +		 * e.g. GIT_DIR, ignore the unsetting to reduce noise.
> +		 */
> +		if (!strchr(env[i], '='))
> +			continue;
> +		strbuf_addch(dst, ' ');
> +		sq_quote_buf(dst, env[i]);

I think you'd tweak the quoting around here in a later iteration,
based on the distinction between the two:

	$ 'GIT_DIR=.git' git foo
	$ GIT_DIR='.git' git foo

that was pointed out in a near-by message.

Thanks.

Re: [PATCH v2] run-command.c: print env vars when GIT_TRACE is set

[Duy Nguyen]

On Fri, Jan 12, 2018 at 2:27 AM, Junio C Hamano <gitster@pobox.com> wrote:
> I wonder how common it would be to attempt exporting a variable with
> the same value, and to attempt unsetting a variable that is not
> exported, which might help you reduce the clutter by hiding stuff
> that truly do not matter, while keeping what matters (possibly
> including the "unset" part).

It looks pretty good actually. This is with 'git status' and a repo
with submodule 'foo'.

trace: run_command: cd 'foo'; unset GIT_PREFIX; git 'status' '--porcelain=2'

Thanks for the suggestion.
-- 
Duy

[PATCH v3 0/4] run-command.c: print env vars when GIT_TRACE is set

[Nguyễn Thái Ngọc Duy]

v3 turns a single patch into a series. Changes from v2

- env var quoting is now done correctly (from shell syntax perspective)
- the program name is prepended in git_cmd mode
- cwd is now printed too (because I have too, see 4/4)
- we don't blindly print the env delta anymore but print the actual
  differences compared to parent env
- which means we also print "unset XXX" statements in $GIT_TRACE

The new output on git.git looks like this

    trace: run_command: cd 'sha1collisiondetection'; unset GIT_PREFIX; GIT_DIR='.git' git 'status' '--porcelain=2'

a bit longer than I would like, but that's because of
sha1collisiondetection and it's not long enough for me to invent
$GIT_TRACE_EXEC.

I'm not adding "sh -c" back though because that looks like it should
be done in run_command.c itself, not just output tracing output.

Oh.. before anybody asks, I'm not adding git prefix to the "cd" part.
You're supposed to know that git moves back to worktree top dir when
you read $GIT_TRACE (or are welcome to improve the print out).

Nguyễn Thái Ngọc Duy (4):
  trace.c: introduce trace_run_command()
  trace.c: print program 'git' when child_process.git_cmd is set
  trace.c: print env vars in trace_run_command()
  trace.c: be smart about what env to print in trace_run_command()

 run-command.c |   3 +-
 trace.c       | 106 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 trace.h       |   3 ++
 3 files changed, 111 insertions(+), 1 deletion(-)

-- 
2.15.1.600.g899a5f85c6

[PATCH v3 1/4] trace.c: introduce trace_run_command()

[Nguyễn Thái Ngọc Duy]

This is the same as the old code that uses trace_argv_printf() in
run-command.c. This function will be improved in later patches to
print more information from struct child_process.

A slight regression: the old code would print run-command.c:xxx as the
trace location site while the new code prints trace.c:xxx. This should
be fine until the second call site is added, then we might need a macro
wrapper named trace_run_command() to capture the right source location.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 run-command.c |  3 ++-
 trace.c       | 15 +++++++++++++++
 trace.h       |  3 +++
 3 files changed, 20 insertions(+), 1 deletion(-)

diff --git a/run-command.c b/run-command.c
index 31fc5ea86e..002074b128 100644
--- a/run-command.c
+++ b/run-command.c
@@ -624,7 +624,8 @@ int start_command(struct child_process *cmd)
 		cmd->err = fderr[0];
 	}
 
-	trace_argv_printf(cmd->argv, "trace: run_command:");
+	trace_run_command(cmd);
+
 	fflush(NULL);
 
 #ifndef GIT_WINDOWS_NATIVE
diff --git a/trace.c b/trace.c
index b7530b51a9..f08c673b51 100644
--- a/trace.c
+++ b/trace.c
@@ -23,6 +23,7 @@
 
 #include "cache.h"
 #include "quote.h"
+#include "run-command.h"
 
 struct trace_key trace_default_key = { "GIT_TRACE", 0, 0, 0 };
 struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
@@ -272,6 +273,20 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 #endif /* HAVE_VARIADIC_MACROS */
 
 
+void trace_run_command(const struct child_process *cp)
+{
+	struct strbuf buf = STRBUF_INIT;
+
+	if (!prepare_trace_line(__FILE__, __LINE__,
+				&trace_default_key, &buf))
+		return;
+
+	strbuf_addf(&buf, "trace: run_command:");
+
+	sq_quote_argv(&buf, cp->argv, 0);
+	print_trace_line(&trace_default_key, &buf);
+}
+
 static const char *quote_crnl(const char *path)
 {
 	static struct strbuf new_path = STRBUF_INIT;
diff --git a/trace.h b/trace.h
index 88055abef7..e54c687f26 100644
--- a/trace.h
+++ b/trace.h
@@ -4,6 +4,8 @@
 #include "git-compat-util.h"
 #include "strbuf.h"
 
+struct child_process;
+
 struct trace_key {
 	const char * const key;
 	int fd;
@@ -17,6 +19,7 @@ extern struct trace_key trace_default_key;
 extern struct trace_key trace_perf_key;
 
 extern void trace_repo_setup(const char *prefix);
+extern void trace_run_command(const struct child_process *cp);
 extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
 extern uint64_t getnanotime(void);
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v3 1/4] trace.c: introduce trace_run_command()

[Jeff King]

On Fri, Jan 12, 2018 at 04:56:04PM +0700, Nguyễn Thái Ngọc Duy wrote:

> This is the same as the old code that uses trace_argv_printf() in
> run-command.c. This function will be improved in later patches to
> print more information from struct child_process.
> 
> A slight regression: the old code would print run-command.c:xxx as the
> trace location site while the new code prints trace.c:xxx. This should
> be fine until the second call site is added, then we might need a macro
> wrapper named trace_run_command() to capture the right source location.

I agree that's probably fine for now.

> +void trace_run_command(const struct child_process *cp)
> +{
> +	struct strbuf buf = STRBUF_INIT;
> +
> +	if (!prepare_trace_line(__FILE__, __LINE__,
> +				&trace_default_key, &buf))
> +		return;
> +
> +	strbuf_addf(&buf, "trace: run_command:");
> +
> +	sq_quote_argv(&buf, cp->argv, 0);
> +	print_trace_line(&trace_default_key, &buf);
> +}

It looks like this leaks "buf".

If prepare_trace_line() returns 0, I think it's safe to assume that
nothing was allocated. So we'd just need a strbuf_release() at the end.

Looking at the other trace functions, it looks like a bunch of them have
the same problem.

-Peff

Re: [PATCH v3 1/4] trace.c: introduce trace_run_command()

[Jeff King]

On Fri, Jan 12, 2018 at 08:05:22AM -0500, Jeff King wrote:

> > +void trace_run_command(const struct child_process *cp)
> > +{
> > +	struct strbuf buf = STRBUF_INIT;
> > +
> > +	if (!prepare_trace_line(__FILE__, __LINE__,
> > +				&trace_default_key, &buf))
> > +		return;
> > +
> > +	strbuf_addf(&buf, "trace: run_command:");
> > +
> > +	sq_quote_argv(&buf, cp->argv, 0);
> > +	print_trace_line(&trace_default_key, &buf);
> > +}
> 
> It looks like this leaks "buf".
> 
> If prepare_trace_line() returns 0, I think it's safe to assume that
> nothing was allocated. So we'd just need a strbuf_release() at the end.
> 
> Looking at the other trace functions, it looks like a bunch of them have
> the same problem.

Never mind, I got fooled by print_trace_line(), which does quite a bit
more than its name says. :)

This call (and the existing ones) are all fine.

[PATCH v3 2/4] trace.c: print program 'git' when child_process.git_cmd is set

[Nguyễn Thái Ngọc Duy]

We normally print full command line, including the program and its
argument. When git_cmd is set, we have a special code path to run the
right "git" program and child_process.argv[0] will not contain the
program name anymore. As a result, we print just the command
arguments.

I thought it was a regression when the code was refactored and git_cmd
added, but apparently it's not. git_cmd mode was introduced before
tracing was added in 8852f5d704 (run_command(): respect GIT_TRACE -
2008-07-07) so it's more like an oversight in 8852f5d704.

Fix it, print the program name "git" in git_cmd mode. It's nice to have
now. But it will be more important later when we start to print env
variables too, in shell syntax. The lack of a program name would look
confusing then.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 trace.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/trace.c b/trace.c
index f08c673b51..ed1f728021 100644
--- a/trace.c
+++ b/trace.c
@@ -283,6 +283,9 @@ void trace_run_command(const struct child_process *cp)
 
 	strbuf_addf(&buf, "trace: run_command:");
 
+	if (cp->git_cmd)
+		strbuf_addstr(&buf, " git");
+
 	sq_quote_argv(&buf, cp->argv, 0);
 	print_trace_line(&trace_default_key, &buf);
 }
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v3 2/4] trace.c: print program 'git' when child_process.git_cmd is set

[Jeff King]

On Fri, Jan 12, 2018 at 04:56:05PM +0700, Nguyễn Thái Ngọc Duy wrote:

> We normally print full command line, including the program and its
> argument. When git_cmd is set, we have a special code path to run the
> right "git" program and child_process.argv[0] will not contain the
> program name anymore. As a result, we print just the command
> arguments.
> 
> I thought it was a regression when the code was refactored and git_cmd
> added, but apparently it's not. git_cmd mode was introduced before
> tracing was added in 8852f5d704 (run_command(): respect GIT_TRACE -
> 2008-07-07) so it's more like an oversight in 8852f5d704.
> 
> Fix it, print the program name "git" in git_cmd mode. It's nice to have
> now. But it will be more important later when we start to print env
> variables too, in shell syntax. The lack of a program name would look
> confusing then.

Makes sense. Note that "git" isn't quoted here, but the rest of the
arguments are. More on that in a minute. :)

-Peff

[PATCH v3 3/4] trace.c: print env vars in trace_run_command()

[Nguyễn Thái Ngọc Duy]

Occasionally submodule code could execute new commands with GIT_DIR set
to some submodule. GIT_TRACE prints just the command line which makes it
hard to tell that it's not really executed on this repository.

Print modified env variables (compared to parent environment) in this
case. Actually only modified or new variables (*) are printed. Variable
deletion is suppressed because they are often used to clean up
repo-specific variables that git passes around between processes. When
submodule code executes commands on another repo, it clears all these
variables, _many_ of these, that make the output really noisy.

(*) sort of. More on this in the next patch.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 trace.c | 27 +++++++++++++++++++++++++++
 1 file changed, 27 insertions(+)

diff --git a/trace.c b/trace.c
index ed1f728021..e499074d39 100644
--- a/trace.c
+++ b/trace.c
@@ -273,6 +273,24 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 #endif /* HAVE_VARIADIC_MACROS */
 
 
+static void concatenate_env(struct strbuf *dst, const char *const *envs)
+{
+	int i;
+
+	for (i = 0; envs[i]; i++) {
+		const char *env = envs[i];
+		const char *p = strchr(env, '=');
+
+		if (!p) /* ignore var deletion for now */
+			continue;
+		p++;
+
+		strbuf_addch(dst, ' ');
+		strbuf_add(dst, env, p - env);
+		sq_quote_buf(dst, p);
+	}
+}
+
 void trace_run_command(const struct child_process *cp)
 {
 	struct strbuf buf = STRBUF_INIT;
@@ -281,8 +299,17 @@ void trace_run_command(const struct child_process *cp)
 				&trace_default_key, &buf))
 		return;
 
+	strbuf_grow(&buf, 255);
+
 	strbuf_addf(&buf, "trace: run_command:");
 
+	/*
+	 * The caller is responsible for initializing cp->env from
+	 * cp->env_array if needed. We only check one place.
+	 */
+	if (cp->env)
+		concatenate_env(&buf, cp->env);
+
 	if (cp->git_cmd)
 		strbuf_addstr(&buf, " git");
 
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v3 3/4] trace.c: print env vars in trace_run_command()

[Jeff King]

On Fri, Jan 12, 2018 at 04:56:06PM +0700, Nguyễn Thái Ngọc Duy wrote:

> Occasionally submodule code could execute new commands with GIT_DIR set
> to some submodule. GIT_TRACE prints just the command line which makes it
> hard to tell that it's not really executed on this repository.
> 
> Print modified env variables (compared to parent environment) in this
> case. Actually only modified or new variables (*) are printed. Variable
> deletion is suppressed because they are often used to clean up
> repo-specific variables that git passes around between processes. When
> submodule code executes commands on another repo, it clears all these
> variables, _many_ of these, that make the output really noisy.
> 
> (*) sort of. More on this in the next patch.

OK. I think we could probably just squash patches 3 and 4, but I'm OK
with them separate, too.

The code looks fine, though I have one nit:

> @@ -281,8 +299,17 @@ void trace_run_command(const struct child_process *cp)
>  				&trace_default_key, &buf))
>  		return;
>  
> +	strbuf_grow(&buf, 255);
> +

IMHO these magic-numbers grows detract from the readability (because you
wonder if they're meaningful), and I doubt if they provide any real
performance gain in practice.

-Peff

[PATCH v3 4/4] trace.c: be smart about what env to print in trace_run_command()

[Nguyễn Thái Ngọc Duy]

The previous concatenate_env() is kinda dumb. It receives a env delta
in child_process and blindly follows it. If the run_command() user
"adds" more vars of the same value, or deletes vars that do not exist
in parent env in the first place (*), then why bother to print them?

This patch checks child_process.env against parent environment and
only print the actual differences. The unset syntax (and later on cwd)
follows closely shell syntax for easy reading/guessing and copy/paste.

There is an interesting thing with this change. In the previous patch,
we unconditionally print new vars. With submodule code we may have
something like this

    trace: ... GIT_DIR='.git' git 'status' '--porcelain=2'

but since parent's GIT_DIR usually has the same value '.git' too, this
change suppress that, now we can't see that the above command runs in
a separate repo. This is the run for printing cwd. Now we have

    trace: ... cd foo; git 'status' '--porcelain=2'

Another equally interesting thing is, some caller can do "unset GIT_DIR;
set GIT_DIR=.git". Since parent env can have the same value '.git', we
don't re-print GIT_DIR=.git. In that case must NOT print "unset GIT_DIR"
or the user will be misled to think the new command has no GIT_DIR.

A note about performance. Yes we're burning a lot more cycles for
displaying something this nice. But because it's protected by
$GIT_TRACE, and run_command() should not happen often anyway, it should
not feel any slower than before.

(*) this is the case with submodule code where all local_repo_env[]
vars are to be deleted even though many of them do not exist in the
first place. Printing all these is too noisy and that leads to
ignoring variable deletion in the previous patch.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 trace.c | 77 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-------
 1 file changed, 69 insertions(+), 8 deletions(-)

diff --git a/trace.c b/trace.c
index e499074d39..a1f871e720 100644
--- a/trace.c
+++ b/trace.c
@@ -272,23 +272,78 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 
 #endif /* HAVE_VARIADIC_MACROS */
 
+static void sort_deltaenv(struct string_list *envs,
+			  const char *const *deltaenv)
+{
+	struct strbuf key = STRBUF_INIT;
+	const char *const *e;
+
+	for (e = deltaenv; e && *e; e++) {
+		char *equals = strchr(*e, '=');
+
+		if (equals) {
+			strbuf_reset(&key);
+			strbuf_add(&key, *e, equals - *e);
+			string_list_append(envs, key.buf)->util = equals + 1;
+		} else {
+			string_list_append(envs, *e)->util = NULL;
+		}
+	}
+	string_list_sort(envs);
+	strbuf_release(&key);
+}
 
-static void concatenate_env(struct strbuf *dst, const char *const *envs)
+
+static void concatenate_env(struct strbuf *dst, const char *const *deltaenv)
 {
+	struct string_list envs = STRING_LIST_INIT_DUP;
 	int i;
 
-	for (i = 0; envs[i]; i++) {
-		const char *env = envs[i];
-		const char *p = strchr(env, '=');
+	/*
+	 * Construct a sorted string list consisting of the delta
+	 * env. We need this to detect the case when the same var is
+	 * deleted first, then added again.
+	 */
+	sort_deltaenv(&envs, deltaenv);
+
+	/*
+	 * variable deletion first because it's printed like separate
+	 * shell commands
+	 */
+	for (i = 0; i < envs.nr; i++) {
+		const char *env = envs.items[i].string;
+		const char *p = envs.items[i].util;
+
+		if (p || !getenv(env))
+			continue;
 
-		if (!p) /* ignore var deletion for now */
+		/*
+		 * Do we have a sequence of "unset GIT_DIR; GIT_DIR=foo"?
+		 * Then don't bother with the unset thing.
+		 */
+		if (i + 1 < envs.nr &&
+		    !strcmp(env, envs.items[i + 1].string))
 			continue;
-		p++;
 
-		strbuf_addch(dst, ' ');
-		strbuf_add(dst, env, p - env);
+		strbuf_addf(dst, " unset %s;", env);
+	}
+
+	for (i = 0; i < envs.nr; i++) {
+		const char *env = envs.items[i].string;
+		const char *p = envs.items[i].util;
+		const char *old_value;
+
+		if (!p)
+			continue;
+
+		old_value = getenv(env);
+		if (old_value && !strcmp(old_value, p))
+			continue;
+
+		strbuf_addf(dst, " %s=", env);
 		sq_quote_buf(dst, p);
 	}
+	string_list_clear(&envs, 0);
 }
 
 void trace_run_command(const struct child_process *cp)
@@ -303,6 +358,12 @@ void trace_run_command(const struct child_process *cp)
 
 	strbuf_addf(&buf, "trace: run_command:");
 
+	if (cp->dir) {
+		strbuf_addstr(&buf, " cd ");
+		sq_quote_buf(&buf, cp->dir);
+		strbuf_addch(&buf, ';');
+	}
+
 	/*
 	 * The caller is responsible for initializing cp->env from
 	 * cp->env_array if needed. We only check one place.
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v3 4/4] trace.c: be smart about what env to print in trace_run_command()

[Jeff King]

On Fri, Jan 12, 2018 at 04:56:07PM +0700, Nguyễn Thái Ngọc Duy wrote:

> The previous concatenate_env() is kinda dumb. It receives a env delta
> in child_process and blindly follows it. If the run_command() user
> "adds" more vars of the same value, or deletes vars that do not exist
> in parent env in the first place (*), then why bother to print them?
> 
> This patch checks child_process.env against parent environment and
> only print the actual differences. The unset syntax (and later on cwd)
> follows closely shell syntax for easy reading/guessing and copy/paste.

I like it.

> There is an interesting thing with this change. In the previous patch,
> we unconditionally print new vars. With submodule code we may have
> something like this
> 
>     trace: ... GIT_DIR='.git' git 'status' '--porcelain=2'
> 
> but since parent's GIT_DIR usually has the same value '.git' too, this
> change suppress that, now we can't see that the above command runs in
> a separate repo. This is the run for printing cwd. Now we have
> 
>     trace: ... cd foo; git 'status' '--porcelain=2'

Makes sense (though s/run/reason/ in the last paragraph?).

> Another equally interesting thing is, some caller can do "unset GIT_DIR;
> set GIT_DIR=.git". Since parent env can have the same value '.git', we
> don't re-print GIT_DIR=.git. In that case must NOT print "unset GIT_DIR"
> or the user will be misled to think the new command has no GIT_DIR.

Interesting. I wonder if any callers actually do that. It seems like
kind of an odd thing, but maybe a caller sets GIT_DIR on top of the
clearing of local_repo_env.

> A note about performance. Yes we're burning a lot more cycles for
> displaying something this nice. But because it's protected by
> $GIT_TRACE, and run_command() should not happen often anyway, it should
> not feel any slower than before.

I'd agree that performance probably doesn't matter much here.

> +		/*
> +		 * Do we have a sequence of "unset GIT_DIR; GIT_DIR=foo"?
> +		 * Then don't bother with the unset thing.
> +		 */
> +		if (i + 1 < envs.nr &&
> +		    !strcmp(env, envs.items[i + 1].string))
>  			continue;

Are we guaranteed that "FOO" and "FOO=bar" appear next to each other in the
sorted list? I think "FOO123=bar" could come between.

I also think this is a special case of a more general problem. FOO could
appear any number of times in the "env" array, as a deletion or with
multiple values. Our prep_childenv() would treat that as "last one
wins", I think. Could we just do the same here?

-Peff

Re: [PATCH v3 4/4] trace.c: be smart about what env to print in trace_run_command()

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

>> +		/*
>> +		 * Do we have a sequence of "unset GIT_DIR; GIT_DIR=foo"?
>> +		 * Then don't bother with the unset thing.
>> +		 */
>> +		if (i + 1 < envs.nr &&
>> +		    !strcmp(env, envs.items[i + 1].string))
>>  			continue;
>
> Are we guaranteed that "FOO" and "FOO=bar" appear next to each other in the
> sorted list? I think "FOO123=bar" could come between.

At this point, envs is a string list whose key is FOO for both "FOO"
(unset) and "FOO=bar" (set); "FOO123=bar" would sort after these two.

But I did not see anything that attempts to guarantee that "FOO"
sorts before "FOO=bar" with string_list_sort().  If the sort used in
the function is stable, and if the case we care about is unset
followed by set, then the above would catch the case, but even if
that were the case, it is unclear what we want to do when a set of
FOO is followed by an unset of FOO.

And if the sort is not stable, then the above code is just simply
broken.

> I also think this is a special case of a more general problem. FOO could
> appear any number of times in the "env" array, as a deletion or with
> multiple values. Our prep_childenv() would treat that as "last one
> wins", I think. Could we just do the same here?

Yeah, if the last one is to set FOO=bar, then it feels sufficient to
just check if FOO is set to bar in the original and deciding to show
or hide; similarly if the last one is to unset FOO, it does not matter
if the caller sets it to some other value before unsetting, so it
feels sufficient to just check if FOO is set to anything in the
original environment.

Re: [PATCH v3 4/4] trace.c: be smart about what env to print in trace_run_command()

[Jeff King]

On Fri, Jan 12, 2018 at 10:24:28AM -0800, Junio C Hamano wrote:

> Jeff King <peff@peff.net> writes:
> 
> >> +		/*
> >> +		 * Do we have a sequence of "unset GIT_DIR; GIT_DIR=foo"?
> >> +		 * Then don't bother with the unset thing.
> >> +		 */
> >> +		if (i + 1 < envs.nr &&
> >> +		    !strcmp(env, envs.items[i + 1].string))
> >>  			continue;
> >
> > Are we guaranteed that "FOO" and "FOO=bar" appear next to each other in the
> > sorted list? I think "FOO123=bar" could come between.
> 
> At this point, envs is a string list whose key is FOO for both "FOO"
> (unset) and "FOO=bar" (set); "FOO123=bar" would sort after these two.

Ah, right, I didn't notice that we took just the key name.

> But I did not see anything that attempts to guarantee that "FOO"
> sorts before "FOO=bar" with string_list_sort().  If the sort used in
> the function is stable, and if the case we care about is unset
> followed by set, then the above would catch the case, but even if
> that were the case, it is unclear what we want to do when a set of
> FOO is followed by an unset of FOO.

The actual prep_childenv() code looks like it would always do
last-one-wins, so we should treat FOO as unset in that final case. But
that only kicks in on non-Windows.

On Windows we feed cmd->env straight to mingw_spawnvpe().  That ends up
in make_environment_block(), which looks like it does something similar.

It's too bad the prep code is not shared, since then we could probably
just ask _it_ which deltas it applied. I suspect it would be possible to
share it, since mingw_spawnvpe is our own compat thing (so we could
change its interface to take the whole prepared environment block). But
I won't blame Duy if he doesn't want to refactor all of the
cross-platform exec code. ;)

> And if the sort is not stable, then the above code is just simply
> broken.

Agreed.

> 
> > I also think this is a special case of a more general problem. FOO could
> > appear any number of times in the "env" array, as a deletion or with
> > multiple values. Our prep_childenv() would treat that as "last one
> > wins", I think. Could we just do the same here?
> 
> Yeah, if the last one is to set FOO=bar, then it feels sufficient to
> just check if FOO is set to bar in the original and deciding to show
> or hide; similarly if the last one is to unset FOO, it does not matter
> if the caller sets it to some other value before unsetting, so it
> feels sufficient to just check if FOO is set to anything in the
> original environment.

Yep, agreed again.

-Peff

Re: [PATCH v3 4/4] trace.c: be smart about what env to print in trace_run_command()

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> The actual prep_childenv() code looks like it would always do
> last-one-wins, so we should treat FOO as unset in that final case. But
> that only kicks in on non-Windows.
>
> On Windows we feed cmd->env straight to mingw_spawnvpe().  That ends up
> in make_environment_block(), which looks like it does something similar.
>
> It's too bad the prep code is not shared, since then we could probably
> just ask _it_ which deltas it applied.

Yeah, but that function does a lot more than computing delta.  

It's primary point, which comes from ae25394b ("run-command: prepare
child environment before forking", 2017-04-19), is to create a full
copy of the environment, not just a series of putenv/unsetenv that
describes what gets changed, and that is done to avoid any
allocation after fork before exec in the child process.

I guess prep_childenv() could take an extra and optional string-list
to report what "deltas" it applied to the tracing machinery.  I am
not sure if that is worth it, though.

Re: [PATCH v3 4/4] trace.c: be smart about what env to print in trace_run_command()

[Jeff King]

On Fri, Jan 12, 2018 at 11:19:44AM -0800, Junio C Hamano wrote:

> Jeff King <peff@peff.net> writes:
> 
> > The actual prep_childenv() code looks like it would always do
> > last-one-wins, so we should treat FOO as unset in that final case. But
> > that only kicks in on non-Windows.
> >
> > On Windows we feed cmd->env straight to mingw_spawnvpe().  That ends up
> > in make_environment_block(), which looks like it does something similar.
> >
> > It's too bad the prep code is not shared, since then we could probably
> > just ask _it_ which deltas it applied.
> 
> Yeah, but that function does a lot more than computing delta.  
> 
> It's primary point, which comes from ae25394b ("run-command: prepare
> child environment before forking", 2017-04-19), is to create a full
> copy of the environment, not just a series of putenv/unsetenv that
> describes what gets changed, and that is done to avoid any
> allocation after fork before exec in the child process.
> 
> I guess prep_childenv() could take an extra and optional string-list
> to report what "deltas" it applied to the tracing machinery.  I am
> not sure if that is worth it, though.

Yes, that's exactly what I meant. I think if it covered all platforms it
might be worth it (not so much for code de-duping, but because then we
would know our display logic always matched what we exec'd). But unless
somebody wants to refactor all of the Windows spawn code, it's
definitely not a good idea.

-Peff

Re: [PATCH v3 4/4] trace.c: be smart about what env to print in trace_run_command()

[Brandon Williams]

On 01/12, Jeff King wrote:
> On Fri, Jan 12, 2018 at 11:19:44AM -0800, Junio C Hamano wrote:
> 
> > Jeff King <peff@peff.net> writes:
> > 
> > > The actual prep_childenv() code looks like it would always do
> > > last-one-wins, so we should treat FOO as unset in that final case. But
> > > that only kicks in on non-Windows.
> > >
> > > On Windows we feed cmd->env straight to mingw_spawnvpe().  That ends up
> > > in make_environment_block(), which looks like it does something similar.
> > >
> > > It's too bad the prep code is not shared, since then we could probably
> > > just ask _it_ which deltas it applied.
> > 
> > Yeah, but that function does a lot more than computing delta.  
> > 
> > It's primary point, which comes from ae25394b ("run-command: prepare
> > child environment before forking", 2017-04-19), is to create a full
> > copy of the environment, not just a series of putenv/unsetenv that
> > describes what gets changed, and that is done to avoid any
> > allocation after fork before exec in the child process.
> > 
> > I guess prep_childenv() could take an extra and optional string-list
> > to report what "deltas" it applied to the tracing machinery.  I am
> > not sure if that is worth it, though.
> 
> Yes, that's exactly what I meant. I think if it covered all platforms it
> might be worth it (not so much for code de-duping, but because then we
> would know our display logic always matched what we exec'd). But unless
> somebody wants to refactor all of the Windows spawn code, it's
> definitely not a good idea.

And not having access to a windows box I didn't want to try and refactor
the windows-only code when I introduced prep_childenv() :)

-- 
Brandon Williams

Re: [PATCH v3 4/4] trace.c: be smart about what env to print in trace_run_command()

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> I also think this is a special case of a more general problem. FOO could
> appear any number of times in the "env" array, as a deletion or with
> multiple values. Our prep_childenv() would treat that as "last one
> wins", I think. Could we just do the same here?

Perhaps this should be squashed into the original 4/4 instead of
being a separate patch.  We'd probably want some sort of test, I
wonder?  Not tested at all beyond compiling...

-- >8 --
Subject: [PATCH 7/4] run-command.c: don't be too cute in concatenate_env()

Instead of relying on "sort" being stable to sort "unset VAR"
immediately before "VAR=VAL" to remove the former, just pick the
last manipulation for each VAR from the list of environment tweaks
and show them in the output.

Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 trace.c | 68 ++++++++++++++++++++---------------------------------------------
 1 file changed, 21 insertions(+), 47 deletions(-)

diff --git a/trace.c b/trace.c
index aba2825044..9f49bcdd03 100644
--- a/trace.c
+++ b/trace.c
@@ -272,76 +272,50 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 
 #endif /* HAVE_VARIADIC_MACROS */
 
-static void sort_deltaenv(struct string_list *envs,
-			  const char *const *deltaenv)
+static void concatenate_env(struct strbuf *dst, const char *const *deltaenv)
 {
-	struct strbuf key = STRBUF_INIT;
+	struct string_list envs = STRING_LIST_INIT_DUP;
 	const char *const *e;
+	int i;
 
+	/* Last one wins... */
 	for (e = deltaenv; e && *e; e++) {
+		struct strbuf key = STRBUF_INIT;
 		char *equals = strchr(*e, '=');
 
 		if (equals) {
 			strbuf_reset(&key);
 			strbuf_add(&key, *e, equals - *e);
-			string_list_append(envs, key.buf)->util = equals + 1;
+			string_list_insert(&envs, key.buf)->util = equals + 1;
 		} else {
-			string_list_append(envs, *e)->util = NULL;
+			string_list_insert(&envs, *e)->util = NULL;
 		}
 	}
-	string_list_sort(envs);
-	strbuf_release(&key);
-}
-
-
-static void concatenate_env(struct strbuf *dst, const char *const *deltaenv)
-{
-	struct string_list envs = STRING_LIST_INIT_DUP;
-	int i;
-
-	/*
-	 * Construct a sorted string list consisting of the delta
-	 * env. We need this to detect the case when the same var is
-	 * deleted first, then added again.
-	 */
-	sort_deltaenv(&envs, deltaenv);
 
-	/*
-	 * variable deletion first because it's printed like separate
-	 * shell commands
-	 */
+	/* series of "unset X; unset Y;..." */
 	for (i = 0; i < envs.nr; i++) {
-		const char *env = envs.items[i].string;
-		const char *p = envs.items[i].util;
+		const char *var = envs.items[i].string;
+		const char *val = envs.items[i].util;
 
-		if (p || !getenv(env))
+		if (val)
 			continue;
-
-		/*
-		 * Do we have a sequence of "unset GIT_DIR; GIT_DIR=foo"?
-		 * Then don't bother with the unset thing.
-		 */
-		if (i + 1 < envs.nr &&
-		    !strcmp(env, envs.items[i + 1].string))
-			continue;
-
-		strbuf_addf(dst, " unset %s;", env);
+		if (getenv(var))
+			strbuf_addf(dst, " unset %s;", var);
 	}
 
+	/* ... followed by "A=B C=D ..." */
 	for (i = 0; i < envs.nr; i++) {
-		const char *env = envs.items[i].string;
-		const char *p = envs.items[i].util;
+		const char *var = envs.items[i].string;
+		const char *val = envs.items[i].util;
 		const char *old_value;
 
-		if (!p)
+		if (!val)
 			continue;
-
-		old_value = getenv(env);
-		if (old_value && !strcmp(old_value, p))
+		old_value = getenv(var);
+		if (old_value && !strcmp(old_value, val))
 			continue;
-
-		strbuf_addf(dst, " %s=", env);
-		sq_quote_buf_pretty(dst, p);
+		strbuf_addf(dst, " %s=", var);
+		sq_quote_buf_pretty(dst, val);
 	}
 	string_list_clear(&envs, 0);
 }

Re: [PATCH v3 4/4] trace.c: be smart about what env to print in trace_run_command()

[Duy Nguyen]

On Sat, Jan 13, 2018 at 5:54 AM, Junio C Hamano <gitster@pobox.com> wrote:
> Jeff King <peff@peff.net> writes:
>
>> I also think this is a special case of a more general problem. FOO could
>> appear any number of times in the "env" array, as a deletion or with
>> multiple values. Our prep_childenv() would treat that as "last one
>> wins", I think. Could we just do the same here?
>
> Perhaps this should be squashed into the original 4/4 instead of
> being a separate patch.  We'd probably want some sort of test, I
> wonder?  Not tested at all beyond compiling...
>
> -- >8 --
> Subject: [PATCH 7/4] run-command.c: don't be too cute in concatenate_env()
>
> Instead of relying on "sort" being stable to sort "unset VAR"
> immediately before "VAR=VAL" to remove the former, just pick the
> last manipulation for each VAR from the list of environment tweaks
> and show them in the output.

This is not enough. Imagine we have GIT_DIR=foo in parent env, then a
sequence of "GIT_DIR", "GIT_DIR=foo" in deltaenv. Because we process
set/unset in two separate loops, the "last one wins" rule does not see
that "GIT_DIR=foo" wins over "unset GIT_DIR;". So we might print
"unset GIT_DIR; GIT_DIR=foo", which is fine even if it's redundant.
Except that we don't print that.

The problem comes from comparing with parent env. The new var has the
same value as parent env so we won't print "GIT_DIR=foo", just "unset
GIT_DIR;". This is wrong.

I'm tempted to just get the final child env from prep_childenv() then
compare with parent env and print the differences. It will not work
with Windows though, so Windows gets the old trace line without env
delta. I hope some Windows contributor will jump in at some point if
they want env tracing works for them too.
-- 
Duy

Re: [PATCH v3 4/4] trace.c: be smart about what env to print in trace_run_command()

[Duy Nguyen]

On Sat, Jan 13, 2018 at 11:54 AM, Duy Nguyen <pclouds@gmail.com> wrote:
> On Sat, Jan 13, 2018 at 5:54 AM, Junio C Hamano <gitster@pobox.com> wrote:
>> Jeff King <peff@peff.net> writes:
>>
>>> I also think this is a special case of a more general problem. FOO could
>>> appear any number of times in the "env" array, as a deletion or with
>>> multiple values. Our prep_childenv() would treat that as "last one
>>> wins", I think. Could we just do the same here?
>>
>> Perhaps this should be squashed into the original 4/4 instead of
>> being a separate patch.  We'd probably want some sort of test, I
>> wonder?  Not tested at all beyond compiling...
>>
>> -- >8 --
>> Subject: [PATCH 7/4] run-command.c: don't be too cute in concatenate_env()
>>
>> Instead of relying on "sort" being stable to sort "unset VAR"
>> immediately before "VAR=VAL" to remove the former, just pick the
>> last manipulation for each VAR from the list of environment tweaks
>> and show them in the output.
>
> This is not enough.

No it is. I misunderstood string_list_insert() and my tests proved me
wrong. Sorry for the noise.
-- 
Duy

Re: [PATCH v3 0/4] run-command.c: print env vars when GIT_TRACE is set

[Jeff King]

On Fri, Jan 12, 2018 at 04:56:03PM +0700, Nguyễn Thái Ngọc Duy wrote:

> v3 turns a single patch into a series. Changes from v2
> 
> - env var quoting is now done correctly (from shell syntax perspective)
> - the program name is prepended in git_cmd mode
> - cwd is now printed too (because I have too, see 4/4)
> - we don't blindly print the env delta anymore but print the actual
>   differences compared to parent env
> - which means we also print "unset XXX" statements in $GIT_TRACE

Overall I like it, though I raised on corner case in 4/4.

> The new output on git.git looks like this
> 
>     trace: run_command: cd 'sha1collisiondetection'; unset GIT_PREFIX; GIT_DIR='.git' git 'status' '--porcelain=2'
> 
> a bit longer than I would like, but that's because of
> sha1collisiondetection and it's not long enough for me to invent
> $GIT_TRACE_EXEC.

IMHO the unconditional single-quotes make this longer and uglier than it
needs to be. I've often been tempted to have them kick in only when
necessary. Here are some patches to do that (on top of yours).

  [5/4]: sq_quote_argv: drop maxlen parameter
  [6/4]: trace: avoid unnecessary quoting

 builtin/am.c        |  2 +-
 builtin/rev-parse.c |  4 ++--
 quote.c             | 30 +++++++++++++++++++++++++++---
 quote.h             | 10 +++++++++-
 trace.c             | 10 +++++-----
 5 files changed, 44 insertions(+), 12 deletions(-)

-Peff

[PATCH 5/4] sq_quote_argv: drop maxlen parameter

[Jeff King]

No caller passes anything but "0" for this parameter, which
requests that the function ignore it completely. In fact, in
all of history there was only one such caller, and it went
away in 7f51f8bc2b (alias: use run_command api to execute
aliases, 2011-01-07).

Signed-off-by: Jeff King <peff@peff.net>
---
Just a cleanup, though it touches the caller you just added, too.

 builtin/am.c        | 2 +-
 builtin/rev-parse.c | 4 ++--
 quote.c             | 4 +---
 quote.h             | 2 +-
 trace.c             | 6 +++---
 5 files changed, 8 insertions(+), 10 deletions(-)

diff --git a/builtin/am.c b/builtin/am.c
index acfe9d3c8c..5bdd2d7578 100644
--- a/builtin/am.c
+++ b/builtin/am.c
@@ -1061,7 +1061,7 @@ static void am_setup(struct am_state *state, enum patch_format patch_format,
 	}
 	write_state_text(state, "scissors", str);
 
-	sq_quote_argv(&sb, state->git_apply_opts.argv, 0);
+	sq_quote_argv(&sb, state->git_apply_opts.argv);
 	write_state_text(state, "apply-opt", sb.buf);
 
 	if (state->rebasing)
diff --git a/builtin/rev-parse.c b/builtin/rev-parse.c
index 74aa644cbb..96d06a5d01 100644
--- a/builtin/rev-parse.c
+++ b/builtin/rev-parse.c
@@ -516,7 +516,7 @@ static int cmd_parseopt(int argc, const char **argv, const char *prefix)
 			PARSE_OPT_SHELL_EVAL);
 
 	strbuf_addstr(&parsed, " --");
-	sq_quote_argv(&parsed, argv, 0);
+	sq_quote_argv(&parsed, argv);
 	puts(parsed.buf);
 	return 0;
 }
@@ -526,7 +526,7 @@ static int cmd_sq_quote(int argc, const char **argv)
 	struct strbuf buf = STRBUF_INIT;
 
 	if (argc)
-		sq_quote_argv(&buf, argv, 0);
+		sq_quote_argv(&buf, argv);
 	printf("%s\n", buf.buf);
 	strbuf_release(&buf);
 
diff --git a/quote.c b/quote.c
index de2922ddd6..b2970da627 100644
--- a/quote.c
+++ b/quote.c
@@ -56,7 +56,7 @@ void sq_quotef(struct strbuf *dst, const char *fmt, ...)
 	strbuf_release(&src);
 }
 
-void sq_quote_argv(struct strbuf *dst, const char** argv, size_t maxlen)
+void sq_quote_argv(struct strbuf *dst, const char **argv)
 {
 	int i;
 
@@ -65,8 +65,6 @@ void sq_quote_argv(struct strbuf *dst, const char** argv, size_t maxlen)
 	for (i = 0; argv[i]; ++i) {
 		strbuf_addch(dst, ' ');
 		sq_quote_buf(dst, argv[i]);
-		if (maxlen && dst->len > maxlen)
-			die("Too many or long arguments");
 	}
 }
 
diff --git a/quote.h b/quote.h
index 66f5644aa2..48a75a416b 100644
--- a/quote.h
+++ b/quote.h
@@ -30,7 +30,7 @@ struct strbuf;
  */
 
 extern void sq_quote_buf(struct strbuf *, const char *src);
-extern void sq_quote_argv(struct strbuf *, const char **argv, size_t maxlen);
+extern void sq_quote_argv(struct strbuf *, const char **argv);
 extern void sq_quotef(struct strbuf *, const char *fmt, ...);
 
 /* This unwraps what sq_quote() produces in place, but returns
diff --git a/trace.c b/trace.c
index a1f871e720..973e462a2c 100644
--- a/trace.c
+++ b/trace.c
@@ -158,7 +158,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	strbuf_vaddf(&buf, format, ap);
 
-	sq_quote_argv(&buf, argv, 0);
+	sq_quote_argv(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
 }
 
@@ -374,7 +374,7 @@ void trace_run_command(const struct child_process *cp)
 	if (cp->git_cmd)
 		strbuf_addstr(&buf, " git");
 
-	sq_quote_argv(&buf, cp->argv, 0);
+	sq_quote_argv(&buf, cp->argv);
 	print_trace_line(&trace_default_key, &buf);
 }
 
@@ -532,6 +532,6 @@ void trace_command_performance(const char **argv)
 		atexit(print_command_performance_atexit);
 
 	strbuf_reset(&command_line);
-	sq_quote_argv(&command_line, argv, 0);
+	sq_quote_argv(&command_line, argv);
 	command_start_time = getnanotime();
 }
-- 
2.16.0.rc1.459.g7b9f90244d

Re: [PATCH 5/4] sq_quote_argv: drop maxlen parameter

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> No caller passes anything but "0" for this parameter, which
> requests that the function ignore it completely. In fact, in
> all of history there was only one such caller, and it went
> away in 7f51f8bc2b (alias: use run_command api to execute
> aliases, 2011-01-07).
>
> Signed-off-by: Jeff King <peff@peff.net>
> ---
> Just a cleanup, though it touches the caller you just added, too.

Yup.  This is a good change in the longer term.  I needed an evil
merge for a stalled topic in 'pu' to adjust a couple of new callers,
though ;-)..

[PATCH 6/4] trace: avoid unnecessary quoting

[Jeff King]

Trace output which contains arbitrary strings (e.g., the
arguments to commands which we are running) is always passed
through sq_quote_buf(). That function always adds
single-quotes, even if the output consists of vanilla
characters. This can make the output a bit hard to read.

Let's avoid the quoting if there are no characters which a
shell would interpret. Trace output doesn't necessarily need
to be shell-compatible, but:

  - the shell language is a good ballpark for what humans
    consider readable (well, humans versed in command line
    tools)

  - the run_command bits can be cut-and-pasted to a shell,
    and we'll keep that property

  - it covers any cases which would make the output
    visually ambiguous (e.g., embedded whitespace or quotes)

Signed-off-by: Jeff King <peff@peff.net>
---
 quote.c | 26 ++++++++++++++++++++++++++
 quote.h |  8 ++++++++
 trace.c | 10 +++++-----
 3 files changed, 39 insertions(+), 5 deletions(-)

diff --git a/quote.c b/quote.c
index b2970da627..37d2686865 100644
--- a/quote.c
+++ b/quote.c
@@ -43,6 +43,22 @@ void sq_quote_buf(struct strbuf *dst, const char *src)
 	free(to_free);
 }
 
+void sq_quote_buf_pretty(struct strbuf *dst, const char *src)
+{
+	static const char ok_punct[] = "+,-./:=@_^";
+	const char *p;
+
+	for (p = src; *p; p++) {
+		if (!isalpha(*p) && !isdigit(*p) && !strchr(ok_punct, *p)) {
+			sq_quote_buf(dst, src);
+			return;
+		}
+	}
+
+	/* if we get here, we did not need quoting */
+	strbuf_addstr(dst, src);
+}
+
 void sq_quotef(struct strbuf *dst, const char *fmt, ...)
 {
 	struct strbuf src = STRBUF_INIT;
@@ -68,6 +84,16 @@ void sq_quote_argv(struct strbuf *dst, const char **argv)
 	}
 }
 
+void sq_quote_argv_pretty(struct strbuf *dst, const char **argv)
+{
+	int i;
+
+	for (i = 0; argv[i]; i++) {
+		strbuf_addch(dst, ' ');
+		sq_quote_buf_pretty(dst, argv[i]);
+	}
+}
+
 static char *sq_dequote_step(char *arg, char **next)
 {
 	char *dst = arg;
diff --git a/quote.h b/quote.h
index 48a75a416b..ea992dcc91 100644
--- a/quote.h
+++ b/quote.h
@@ -33,6 +33,14 @@ extern void sq_quote_buf(struct strbuf *, const char *src);
 extern void sq_quote_argv(struct strbuf *, const char **argv);
 extern void sq_quotef(struct strbuf *, const char *fmt, ...);
 
+/*
+ * These match their non-pretty variants, except that they avoid
+ * quoting when there are no exotic characters. These should only be used for
+ * human-readable output, as sq_dequote() is not smart enough to dequote it.
+ */
+void sq_quote_buf_pretty(struct strbuf *, const char *src);
+void sq_quote_argv_pretty(struct strbuf *, const char **argv);
+
 /* This unwraps what sq_quote() produces in place, but returns
  * NULL if the input does not look like what sq_quote would have
  * produced.
diff --git a/trace.c b/trace.c
index 973e462a2c..aba2825044 100644
--- a/trace.c
+++ b/trace.c
@@ -158,7 +158,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	strbuf_vaddf(&buf, format, ap);
 
-	sq_quote_argv(&buf, argv);
+	sq_quote_argv_pretty(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
 }
 
@@ -341,7 +341,7 @@ static void concatenate_env(struct strbuf *dst, const char *const *deltaenv)
 			continue;
 
 		strbuf_addf(dst, " %s=", env);
-		sq_quote_buf(dst, p);
+		sq_quote_buf_pretty(dst, p);
 	}
 	string_list_clear(&envs, 0);
 }
@@ -360,7 +360,7 @@ void trace_run_command(const struct child_process *cp)
 
 	if (cp->dir) {
 		strbuf_addstr(&buf, " cd ");
-		sq_quote_buf(&buf, cp->dir);
+		sq_quote_buf_pretty(&buf, cp->dir);
 		strbuf_addch(&buf, ';');
 	}
 
@@ -374,7 +374,7 @@ void trace_run_command(const struct child_process *cp)
 	if (cp->git_cmd)
 		strbuf_addstr(&buf, " git");
 
-	sq_quote_argv(&buf, cp->argv);
+	sq_quote_argv_pretty(&buf, cp->argv);
 	print_trace_line(&trace_default_key, &buf);
 }
 
@@ -532,6 +532,6 @@ void trace_command_performance(const char **argv)
 		atexit(print_command_performance_atexit);
 
 	strbuf_reset(&command_line);
-	sq_quote_argv(&command_line, argv);
+	sq_quote_argv_pretty(&command_line, argv);
 	command_start_time = getnanotime();
 }
-- 
2.16.0.rc1.459.g7b9f90244d

Re: [PATCH v3 0/4] run-command.c: print env vars when GIT_TRACE is set

[Stefan Beller]

On Fri, Jan 12, 2018 at 5:36 AM, Jeff King <peff@peff.net> wrote:
> On Fri, Jan 12, 2018 at 04:56:03PM +0700, Nguyễn Thái Ngọc Duy wrote:
>
>> v3 turns a single patch into a series. Changes from v2
>>
>> - env var quoting is now done correctly (from shell syntax perspective)
>> - the program name is prepended in git_cmd mode
>> - cwd is now printed too (because I have too, see 4/4)
>> - we don't blindly print the env delta anymore but print the actual
>>   differences compared to parent env
>> - which means we also print "unset XXX" statements in $GIT_TRACE
>
> Overall I like it, though I raised on corner case in 4/4.
>
>> The new output on git.git looks like this
>>
>>     trace: run_command: cd 'sha1collisiondetection'; unset GIT_PREFIX; GIT_DIR='.git' git 'status' '--porcelain=2'
>>
>> a bit longer than I would like, but that's because of
>> sha1collisiondetection and it's not long enough for me to invent
>> $GIT_TRACE_EXEC.
>
> IMHO the unconditional single-quotes make this longer and uglier than it
> needs to be. I've often been tempted to have them kick in only when
> necessary. Here are some patches to do that (on top of yours).
>
>   [5/4]: sq_quote_argv: drop maxlen parameter
>   [6/4]: trace: avoid unnecessary quoting
>

I have reviewed the whole series 6/4 and think they can be applied as-is,
though I have not thought about the corner case you mentioned.

Thanks for this series!
Stefan

Re: [PATCH v3 0/4] run-command.c: print env vars when GIT_TRACE is set

[Stefan Beller]

On Fri, Jan 12, 2018 at 1:56 AM, Nguyễn Thái Ngọc Duy <pclouds@gmail.com> wrote:
> v3 turns a single patch into a series. Changes from v2
>
> - env var quoting is now done correctly (from shell syntax perspective)
> - the program name is prepended in git_cmd mode
> - cwd is now printed too (because I have too, see 4/4)
> - we don't blindly print the env delta anymore but print the actual
>   differences compared to parent env
> - which means we also print "unset XXX" statements in $GIT_TRACE
>
> The new output on git.git looks like this
>
>     trace: run_command: cd 'sha1collisiondetection'; unset GIT_PREFIX; GIT_DIR='.git' git 'status' '--porcelain=2'
>
> a bit longer than I would like, but that's because of
> sha1collisiondetection and it's not long enough for me to invent
> $GIT_TRACE_EXEC.
>
> I'm not adding "sh -c" back though because that looks like it should
> be done in run_command.c itself, not just output tracing output.

Wow! This is really cool. Thanks for your effort.
(Also I learned today that I can just copy the command, up to now I always
dequoted the commands when rerunning it for debugging as I assumed I had to)

>
> Oh.. before anybody asks, I'm not adding git prefix to the "cd" part.
> You're supposed to know that git moves back to worktree top dir when
> you read $GIT_TRACE (or are welcome to improve the print out).

Heh. Would appending  "; cd -" solve the issue? (Though I would argue
we don't need or want to add that actually, as you'd want to copy and run
the command and surely want to run more tests in that directory afterwards.
I mean you're debugging, right?)

Re: [PATCH v3 0/4] run-command.c: print env vars when GIT_TRACE is set

[Duy Nguyen]

On Sat, Jan 13, 2018 at 12:19 AM, Stefan Beller <sbeller@google.com> wrote:
>> Oh.. before anybody asks, I'm not adding git prefix to the "cd" part.
>> You're supposed to know that git moves back to worktree top dir when
>> you read $GIT_TRACE (or are welcome to improve the print out).
>
> Heh. Would appending  "; cd -" solve the issue? (Though I would argue
> we don't need or want to add that actually, as you'd want to copy and run
> the command and surely want to run more tests in that directory afterwards.
> I mean you're debugging, right?)

The problem is if you are tracing in a subdir foo/bar and the trace
output says "cd xyz". You can' just copy and execute that command and
have to do "cd ../../xyz". I don't see how "cd -" would solve that.
Printing "cd $(git rev-parse --show-cdup)/xyz" could solve it without
passing the prefix down to this trace function. I guess. But then that
command depends on $GIT_DIR. If your $GIT_DIR is being changed (i.e.
submodules), it gets ugly again.
-- 
Duy

[PATCH v4 0/7] Trace env variables in run_command()

[Nguyễn Thái Ngọc Duy]

v4:

- incorporates Jeff patches and moves them on top
- removes strbuf release from print_trace_line
- prints 'unset a b c' instead of 'unset a; unset b; unset c'
- squashes v3 3/4 and 4/4 and Junio's patch into 6/7
- adds tests
- cwd is separated in 7/7

interdiff with what's on 'pu':

diff --git a/t/helper/test-run-command.c b/t/helper/test-run-command.c
index d24d157379..0ab71f14fb 100644
--- a/t/helper/test-run-command.c
+++ b/t/helper/test-run-command.c
@@ -56,6 +56,10 @@ int cmd_main(int argc, const char **argv)
 
 	if (argc < 3)
 		return 1;
+	while (!strcmp(argv[1], "env")) {
+		argv_array_push(&proc.env_array, argv[2]);
+		argv += 2;
+	}
 	proc.argv = (const char **)argv + 2;
 
 	if (!strcmp(argv[1], "start-command-ENOENT")) {
diff --git a/t/t0061-run-command.sh b/t/t0061-run-command.sh
index e4739170aa..e6208316c3 100755
--- a/t/t0061-run-command.sh
+++ b/t/t0061-run-command.sh
@@ -141,4 +141,26 @@ test_expect_success 'run_command outputs ' '
 	test_cmp expect actual
 '
 
+test_trace() {
+	local expected="$1"
+	shift
+	GIT_TRACE=1 test-run-command "$@" run-command true 2>&1 >/dev/null | \
+		sed 's/.* run_command: //' >actual &&
+	echo "$expected true" >expected &&
+	test_cmp expected actual
+}
+
+test_expect_success 'GIT_TRACE with environment variables' '
+	test_trace "abc=1 def=2" env abc=1 env def=2 &&
+	test_trace "abc=2" env abc env abc=1 env abc=2 &&
+	test_trace "abc=2" env abc env abc=2 &&
+	abc=1 test_trace "def=1" env abc=1 env def=1 &&
+	abc=1 test_trace "def=1" env abc env abc=1 env def=1 &&
+	test_trace "def=1" env non-exist env def=1 &&
+	test_trace "abc=2" env abc=1 env abc env abc=2 &&
+	abc=1 def=2 test_trace "unset abc def;" env abc env def &&
+	abc=1 def=2 test_trace "unset def; abc=3" env abc env def env abc=3 &&
+	abc=1 test_trace "unset abc;" env abc=2 env abc
+'
+
 test_done
diff --git a/trace.c b/trace.c
index 9f49bcdd03..4bfd3fce10 100644
--- a/trace.c
+++ b/trace.c
@@ -132,7 +132,6 @@ static void print_trace_line(struct trace_key *key, struct strbuf *buf)
 {
 	strbuf_complete_line(buf);
 	trace_write(key, buf->buf, buf->len);
-	strbuf_release(buf);
 }
 
 static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
@@ -145,6 +144,7 @@ static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
 
 	strbuf_vaddf(&buf, format, ap);
 	print_trace_line(key, &buf);
+	strbuf_release(&buf);
 }
 
 static void trace_argv_vprintf_fl(const char *file, int line,
@@ -160,6 +160,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	sq_quote_argv_pretty(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
+	strbuf_release(&buf);
 }
 
 void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
@@ -172,6 +173,7 @@ void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
 
 	strbuf_addbuf(&buf, data);
 	print_trace_line(key, &buf);
+	strbuf_release(&buf);
 }
 
 static void trace_performance_vprintf_fl(const char *file, int line,
@@ -191,6 +193,7 @@ static void trace_performance_vprintf_fl(const char *file, int line,
 	}
 
 	print_trace_line(&trace_perf_key, &buf);
+	strbuf_release(&buf);
 }
 
 #ifndef HAVE_VARIADIC_MACROS
@@ -272,17 +275,17 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 
 #endif /* HAVE_VARIADIC_MACROS */
 
-static void concatenate_env(struct strbuf *dst, const char *const *deltaenv)
+static void add_env(struct strbuf *dst, const char *const *deltaenv)
 {
 	struct string_list envs = STRING_LIST_INIT_DUP;
 	const char *const *e;
 	int i;
+	int printed_unset = 0;
 
-	/* Last one wins... */
+	/* Last one wins, see run-command.c:prep_childenv() for context */
 	for (e = deltaenv; e && *e; e++) {
 		struct strbuf key = STRBUF_INIT;
 		char *equals = strchr(*e, '=');
-
 		if (equals) {
 			strbuf_reset(&key);
 			strbuf_add(&key, *e, equals - *e);
@@ -290,30 +293,39 @@ static void concatenate_env(struct strbuf *dst, const char *const *deltaenv)
 		} else {
 			string_list_insert(&envs, *e)->util = NULL;
 		}
+		strbuf_release(&key);
 	}
 
-	/* series of "unset X; unset Y;..." */
+	/* "unset X Y...;" */
 	for (i = 0; i < envs.nr; i++) {
 		const char *var = envs.items[i].string;
 		const char *val = envs.items[i].util;
 
-		if (val)
+		if (val || !getenv(var))
 			continue;
-		if (getenv(var))
-			strbuf_addf(dst, " unset %s;", var);
+
+		if (!printed_unset) {
+			strbuf_addstr(dst, " unset");
+			printed_unset = 1;
+		}
+		strbuf_addf(dst, " %s", var);
 	}
+	if (printed_unset)
+		strbuf_addch(dst, ';');
 
 	/* ... followed by "A=B C=D ..." */
 	for (i = 0; i < envs.nr; i++) {
 		const char *var = envs.items[i].string;
 		const char *val = envs.items[i].util;
-		const char *old_value;
+		const char *oldval;
 
 		if (!val)
 			continue;
-		old_value = getenv(var);
-		if (old_value && !strcmp(old_value, val))
+
+		oldval = getenv(var);
+		if (oldval && !strcmp(val, oldval))
 			continue;
+
 		strbuf_addf(dst, " %s=", var);
 		sq_quote_buf_pretty(dst, val);
 	}
@@ -328,8 +340,6 @@ void trace_run_command(const struct child_process *cp)
 				&trace_default_key, &buf))
 		return;
 
-	strbuf_grow(&buf, 255);
-
 	strbuf_addf(&buf, "trace: run_command:");
 
 	if (cp->dir) {
@@ -343,7 +353,7 @@ void trace_run_command(const struct child_process *cp)
 	 * cp->env_array if needed. We only check one place.
 	 */
 	if (cp->env)
-		concatenate_env(&buf, cp->env);
+		add_env(&buf, cp->env);
 
 	if (cp->git_cmd)
 		strbuf_addstr(&buf, " git");
-- 
2.15.1.600.g899a5f85c6

[PATCH v4 1/7] sq_quote_argv: drop maxlen parameter

[Nguyễn Thái Ngọc Duy]

From: Jeff King <peff@peff.net>

No caller passes anything but "0" for this parameter, which
requests that the function ignore it completely. In fact, in
all of history there was only one such caller, and it went
away in 7f51f8bc2b (alias: use run_command api to execute
aliases, 2011-01-07).

Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 builtin/am.c        | 2 +-
 builtin/rev-parse.c | 4 ++--
 quote.c             | 4 +---
 quote.h             | 2 +-
 trace.c             | 4 ++--
 5 files changed, 7 insertions(+), 9 deletions(-)

diff --git a/builtin/am.c b/builtin/am.c
index acfe9d3c8c..5bdd2d7578 100644
--- a/builtin/am.c
+++ b/builtin/am.c
@@ -1061,7 +1061,7 @@ static void am_setup(struct am_state *state, enum patch_format patch_format,
 	}
 	write_state_text(state, "scissors", str);
 
-	sq_quote_argv(&sb, state->git_apply_opts.argv, 0);
+	sq_quote_argv(&sb, state->git_apply_opts.argv);
 	write_state_text(state, "apply-opt", sb.buf);
 
 	if (state->rebasing)
diff --git a/builtin/rev-parse.c b/builtin/rev-parse.c
index 74aa644cbb..96d06a5d01 100644
--- a/builtin/rev-parse.c
+++ b/builtin/rev-parse.c
@@ -516,7 +516,7 @@ static int cmd_parseopt(int argc, const char **argv, const char *prefix)
 			PARSE_OPT_SHELL_EVAL);
 
 	strbuf_addstr(&parsed, " --");
-	sq_quote_argv(&parsed, argv, 0);
+	sq_quote_argv(&parsed, argv);
 	puts(parsed.buf);
 	return 0;
 }
@@ -526,7 +526,7 @@ static int cmd_sq_quote(int argc, const char **argv)
 	struct strbuf buf = STRBUF_INIT;
 
 	if (argc)
-		sq_quote_argv(&buf, argv, 0);
+		sq_quote_argv(&buf, argv);
 	printf("%s\n", buf.buf);
 	strbuf_release(&buf);
 
diff --git a/quote.c b/quote.c
index de2922ddd6..b2970da627 100644
--- a/quote.c
+++ b/quote.c
@@ -56,7 +56,7 @@ void sq_quotef(struct strbuf *dst, const char *fmt, ...)
 	strbuf_release(&src);
 }
 
-void sq_quote_argv(struct strbuf *dst, const char** argv, size_t maxlen)
+void sq_quote_argv(struct strbuf *dst, const char **argv)
 {
 	int i;
 
@@ -65,8 +65,6 @@ void sq_quote_argv(struct strbuf *dst, const char** argv, size_t maxlen)
 	for (i = 0; argv[i]; ++i) {
 		strbuf_addch(dst, ' ');
 		sq_quote_buf(dst, argv[i]);
-		if (maxlen && dst->len > maxlen)
-			die("Too many or long arguments");
 	}
 }
 
diff --git a/quote.h b/quote.h
index 66f5644aa2..48a75a416b 100644
--- a/quote.h
+++ b/quote.h
@@ -30,7 +30,7 @@ struct strbuf;
  */
 
 extern void sq_quote_buf(struct strbuf *, const char *src);
-extern void sq_quote_argv(struct strbuf *, const char **argv, size_t maxlen);
+extern void sq_quote_argv(struct strbuf *, const char **argv);
 extern void sq_quotef(struct strbuf *, const char *fmt, ...);
 
 /* This unwraps what sq_quote() produces in place, but returns
diff --git a/trace.c b/trace.c
index b7530b51a9..fa9174fc4b 100644
--- a/trace.c
+++ b/trace.c
@@ -157,7 +157,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	strbuf_vaddf(&buf, format, ap);
 
-	sq_quote_argv(&buf, argv, 0);
+	sq_quote_argv(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
 }
 
@@ -426,6 +426,6 @@ void trace_command_performance(const char **argv)
 		atexit(print_command_performance_atexit);
 
 	strbuf_reset(&command_line);
-	sq_quote_argv(&command_line, argv, 0);
+	sq_quote_argv(&command_line, argv);
 	command_start_time = getnanotime();
 }
-- 
2.15.1.600.g899a5f85c6

[PATCH v4 2/7] trace: avoid unnecessary quoting

[Nguyễn Thái Ngọc Duy]

From: Jeff King <peff@peff.net>

Trace output which contains arbitrary strings (e.g., the
arguments to commands which we are running) is always passed
through sq_quote_buf(). That function always adds
single-quotes, even if the output consists of vanilla
characters. This can make the output a bit hard to read.

Let's avoid the quoting if there are no characters which a
shell would interpret. Trace output doesn't necessarily need
to be shell-compatible, but:

  - the shell language is a good ballpark for what humans
    consider readable (well, humans versed in command line
    tools)

  - the run_command bits can be cut-and-pasted to a shell,
    and we'll keep that property

  - it covers any cases which would make the output
    visually ambiguous (e.g., embedded whitespace or quotes)

Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 quote.c | 26 ++++++++++++++++++++++++++
 quote.h |  8 ++++++++
 trace.c |  4 ++--
 3 files changed, 36 insertions(+), 2 deletions(-)

diff --git a/quote.c b/quote.c
index b2970da627..37d2686865 100644
--- a/quote.c
+++ b/quote.c
@@ -43,6 +43,22 @@ void sq_quote_buf(struct strbuf *dst, const char *src)
 	free(to_free);
 }
 
+void sq_quote_buf_pretty(struct strbuf *dst, const char *src)
+{
+	static const char ok_punct[] = "+,-./:=@_^";
+	const char *p;
+
+	for (p = src; *p; p++) {
+		if (!isalpha(*p) && !isdigit(*p) && !strchr(ok_punct, *p)) {
+			sq_quote_buf(dst, src);
+			return;
+		}
+	}
+
+	/* if we get here, we did not need quoting */
+	strbuf_addstr(dst, src);
+}
+
 void sq_quotef(struct strbuf *dst, const char *fmt, ...)
 {
 	struct strbuf src = STRBUF_INIT;
@@ -68,6 +84,16 @@ void sq_quote_argv(struct strbuf *dst, const char **argv)
 	}
 }
 
+void sq_quote_argv_pretty(struct strbuf *dst, const char **argv)
+{
+	int i;
+
+	for (i = 0; argv[i]; i++) {
+		strbuf_addch(dst, ' ');
+		sq_quote_buf_pretty(dst, argv[i]);
+	}
+}
+
 static char *sq_dequote_step(char *arg, char **next)
 {
 	char *dst = arg;
diff --git a/quote.h b/quote.h
index 48a75a416b..ea992dcc91 100644
--- a/quote.h
+++ b/quote.h
@@ -33,6 +33,14 @@ extern void sq_quote_buf(struct strbuf *, const char *src);
 extern void sq_quote_argv(struct strbuf *, const char **argv);
 extern void sq_quotef(struct strbuf *, const char *fmt, ...);
 
+/*
+ * These match their non-pretty variants, except that they avoid
+ * quoting when there are no exotic characters. These should only be used for
+ * human-readable output, as sq_dequote() is not smart enough to dequote it.
+ */
+void sq_quote_buf_pretty(struct strbuf *, const char *src);
+void sq_quote_argv_pretty(struct strbuf *, const char **argv);
+
 /* This unwraps what sq_quote() produces in place, but returns
  * NULL if the input does not look like what sq_quote would have
  * produced.
diff --git a/trace.c b/trace.c
index fa9174fc4b..9784915be1 100644
--- a/trace.c
+++ b/trace.c
@@ -157,7 +157,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	strbuf_vaddf(&buf, format, ap);
 
-	sq_quote_argv(&buf, argv);
+	sq_quote_argv_pretty(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
 }
 
@@ -426,6 +426,6 @@ void trace_command_performance(const char **argv)
 		atexit(print_command_performance_atexit);
 
 	strbuf_reset(&command_line);
-	sq_quote_argv(&command_line, argv);
+	sq_quote_argv_pretty(&command_line, argv);
 	command_start_time = getnanotime();
 }
-- 
2.15.1.600.g899a5f85c6

[PATCH v4 3/7] trace.c: move strbuf_release() out of print_trace_line()

[Nguyễn Thái Ngọc Duy]

The function is about printing a trace line, not releasing the buffer it
receives too. Move strbuf_release() back outside. This makes it easier
to see how strbuf is managed.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 trace.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/trace.c b/trace.c
index 9784915be1..7f3b08e148 100644
--- a/trace.c
+++ b/trace.c
@@ -131,7 +131,6 @@ static void print_trace_line(struct trace_key *key, struct strbuf *buf)
 {
 	strbuf_complete_line(buf);
 	trace_write(key, buf->buf, buf->len);
-	strbuf_release(buf);
 }
 
 static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
@@ -144,6 +143,7 @@ static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
 
 	strbuf_vaddf(&buf, format, ap);
 	print_trace_line(key, &buf);
+	strbuf_release(&buf);
 }
 
 static void trace_argv_vprintf_fl(const char *file, int line,
@@ -159,6 +159,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	sq_quote_argv_pretty(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
+	strbuf_release(&buf);
 }
 
 void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
@@ -171,6 +172,7 @@ void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
 
 	strbuf_addbuf(&buf, data);
 	print_trace_line(key, &buf);
+	strbuf_release(&buf);
 }
 
 static void trace_performance_vprintf_fl(const char *file, int line,
@@ -190,6 +192,7 @@ static void trace_performance_vprintf_fl(const char *file, int line,
 	}
 
 	print_trace_line(&trace_perf_key, &buf);
+	strbuf_release(&buf);
 }
 
 #ifndef HAVE_VARIADIC_MACROS
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v4 3/7] trace.c: move strbuf_release() out of print_trace_line()

[Jeff King]

On Sat, Jan 13, 2018 at 01:49:45PM +0700, Nguyễn Thái Ngọc Duy wrote:

> The function is about printing a trace line, not releasing the buffer it
> receives too. Move strbuf_release() back outside. This makes it easier
> to see how strbuf is managed.

This is kind of a funny refactor, in that it makes the code longer. :)
I think it does make things a bit more obvious, though.

> diff --git a/trace.c b/trace.c
> index 9784915be1..7f3b08e148 100644
> --- a/trace.c
> +++ b/trace.c
> @@ -131,7 +131,6 @@ static void print_trace_line(struct trace_key *key, struct strbuf *buf)
>  {
>  	strbuf_complete_line(buf);
>  	trace_write(key, buf->buf, buf->len);
> -	strbuf_release(buf);
>  }

One mental note: any print_trace_line() calls for topics in flight need
to be adjusted, or they will leak. Probably OK for a static function
(and I don't see any in pu, nor git-for-windows, nor do I have any in my
private stash of patches).

-Peff

[PATCH v4 4/7] trace.c: introduce trace_run_command()

[Nguyễn Thái Ngọc Duy]

This is the same as the old code that uses trace_argv_printf() in
run-command.c. This function will be improved in later patches to
print more information from struct child_process.

A slight regression: the old code would print run-command.c:xxx as the
trace location site while the new code prints trace.c:xxx. This should
be fine until the second call site is added, then we might need a macro
wrapper named trace_run_command() to capture the right source location.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 run-command.c |  3 ++-
 trace.c       | 15 +++++++++++++++
 trace.h       |  3 +++
 3 files changed, 20 insertions(+), 1 deletion(-)

diff --git a/run-command.c b/run-command.c
index 31fc5ea86e..002074b128 100644
--- a/run-command.c
+++ b/run-command.c
@@ -624,7 +624,8 @@ int start_command(struct child_process *cmd)
 		cmd->err = fderr[0];
 	}
 
-	trace_argv_printf(cmd->argv, "trace: run_command:");
+	trace_run_command(cmd);
+
 	fflush(NULL);
 
 #ifndef GIT_WINDOWS_NATIVE
diff --git a/trace.c b/trace.c
index 7f3b08e148..25c333709b 100644
--- a/trace.c
+++ b/trace.c
@@ -23,6 +23,7 @@
 
 #include "cache.h"
 #include "quote.h"
+#include "run-command.h"
 
 struct trace_key trace_default_key = { "GIT_TRACE", 0, 0, 0 };
 struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
@@ -275,6 +276,20 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 #endif /* HAVE_VARIADIC_MACROS */
 
 
+void trace_run_command(const struct child_process *cp)
+{
+	struct strbuf buf = STRBUF_INIT;
+
+	if (!prepare_trace_line(__FILE__, __LINE__,
+				&trace_default_key, &buf))
+		return;
+
+	strbuf_addf(&buf, "trace: run_command:");
+
+	sq_quote_argv_pretty(&buf, cp->argv);
+	print_trace_line(&trace_default_key, &buf);
+}
+
 static const char *quote_crnl(const char *path)
 {
 	static struct strbuf new_path = STRBUF_INIT;
diff --git a/trace.h b/trace.h
index 88055abef7..e54c687f26 100644
--- a/trace.h
+++ b/trace.h
@@ -4,6 +4,8 @@
 #include "git-compat-util.h"
 #include "strbuf.h"
 
+struct child_process;
+
 struct trace_key {
 	const char * const key;
 	int fd;
@@ -17,6 +19,7 @@ extern struct trace_key trace_default_key;
 extern struct trace_key trace_perf_key;
 
 extern void trace_repo_setup(const char *prefix);
+extern void trace_run_command(const struct child_process *cp);
 extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
 extern uint64_t getnanotime(void);
-- 
2.15.1.600.g899a5f85c6

[PATCH v4 5/7] trace.c: print program 'git' when child_process.git_cmd is set

[Nguyễn Thái Ngọc Duy]

We normally print full command line, including the program and its
argument. When git_cmd is set, we have a special code path to run the
right "git" program and child_process.argv[0] will not contain the
program name anymore. As a result, we print just the command
arguments.

I thought it was a regression when the code was refactored and git_cmd
added, but apparently it's not. git_cmd mode was introduced before
tracing was added in 8852f5d704 (run_command(): respect GIT_TRACE -
2008-07-07) so it's more like an oversight in 8852f5d704.

Fix it, print the program name "git" in git_cmd mode. It's nice to have
now. But it will be more important later when we start to print env
variables too, in shell syntax. The lack of a program name would look
confusing then.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 trace.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/trace.c b/trace.c
index 25c333709b..7f43da211a 100644
--- a/trace.c
+++ b/trace.c
@@ -286,6 +286,9 @@ void trace_run_command(const struct child_process *cp)
 
 	strbuf_addf(&buf, "trace: run_command:");
 
+	if (cp->git_cmd)
+		strbuf_addstr(&buf, " git");
+
 	sq_quote_argv_pretty(&buf, cp->argv);
 	print_trace_line(&trace_default_key, &buf);
 }
-- 
2.15.1.600.g899a5f85c6

[PATCH v4 6/7] trace.c: print env vars in trace_run_command()

[Nguyễn Thái Ngọc Duy]

Occasionally submodule code could execute new commands with GIT_DIR set
to some submodule. GIT_TRACE prints just the command line which makes it
hard to tell that it's not really executed on this repository.

Print the env delta (compared to parent environment) in this case.

Helped-by: Junio C Hamano <gitster@pobox.com>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 t/helper/test-run-command.c |  4 +++
 t/t0061-run-command.sh      | 22 ++++++++++++++++
 trace.c                     | 63 +++++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 89 insertions(+)

diff --git a/t/helper/test-run-command.c b/t/helper/test-run-command.c
index d24d157379..0ab71f14fb 100644
--- a/t/helper/test-run-command.c
+++ b/t/helper/test-run-command.c
@@ -56,6 +56,10 @@ int cmd_main(int argc, const char **argv)
 
 	if (argc < 3)
 		return 1;
+	while (!strcmp(argv[1], "env")) {
+		argv_array_push(&proc.env_array, argv[2]);
+		argv += 2;
+	}
 	proc.argv = (const char **)argv + 2;
 
 	if (!strcmp(argv[1], "start-command-ENOENT")) {
diff --git a/t/t0061-run-command.sh b/t/t0061-run-command.sh
index e4739170aa..e6208316c3 100755
--- a/t/t0061-run-command.sh
+++ b/t/t0061-run-command.sh
@@ -141,4 +141,26 @@ test_expect_success 'run_command outputs ' '
 	test_cmp expect actual
 '
 
+test_trace() {
+	local expected="$1"
+	shift
+	GIT_TRACE=1 test-run-command "$@" run-command true 2>&1 >/dev/null | \
+		sed 's/.* run_command: //' >actual &&
+	echo "$expected true" >expected &&
+	test_cmp expected actual
+}
+
+test_expect_success 'GIT_TRACE with environment variables' '
+	test_trace "abc=1 def=2" env abc=1 env def=2 &&
+	test_trace "abc=2" env abc env abc=1 env abc=2 &&
+	test_trace "abc=2" env abc env abc=2 &&
+	abc=1 test_trace "def=1" env abc=1 env def=1 &&
+	abc=1 test_trace "def=1" env abc env abc=1 env def=1 &&
+	test_trace "def=1" env non-exist env def=1 &&
+	test_trace "abc=2" env abc=1 env abc env abc=2 &&
+	abc=1 def=2 test_trace "unset abc def;" env abc env def &&
+	abc=1 def=2 test_trace "unset def; abc=3" env abc env def env abc=3 &&
+	abc=1 test_trace "unset abc;" env abc=2 env abc
+'
+
 test_done
diff --git a/trace.c b/trace.c
index 7f43da211a..ffa1cf9b91 100644
--- a/trace.c
+++ b/trace.c
@@ -275,6 +275,62 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 
 #endif /* HAVE_VARIADIC_MACROS */
 
+static void add_env(struct strbuf *dst, const char *const *deltaenv)
+{
+	struct string_list envs = STRING_LIST_INIT_DUP;
+	const char *const *e;
+	int i;
+	int printed_unset = 0;
+
+	/* Last one wins, see run-command.c:prep_childenv() for context */
+	for (e = deltaenv; e && *e; e++) {
+		struct strbuf key = STRBUF_INIT;
+		char *equals = strchr(*e, '=');
+		if (equals) {
+			strbuf_reset(&key);
+			strbuf_add(&key, *e, equals - *e);
+			string_list_insert(&envs, key.buf)->util = equals + 1;
+		} else {
+			string_list_insert(&envs, *e)->util = NULL;
+		}
+		strbuf_release(&key);
+	}
+
+	/* "unset X Y...;" */
+	for (i = 0; i < envs.nr; i++) {
+		const char *var = envs.items[i].string;
+		const char *val = envs.items[i].util;
+
+		if (val || !getenv(var))
+			continue;
+
+		if (!printed_unset) {
+			strbuf_addstr(dst, " unset");
+			printed_unset = 1;
+		}
+		strbuf_addf(dst, " %s", var);
+	}
+	if (printed_unset)
+		strbuf_addch(dst, ';');
+
+	/* ... followed by "A=B C=D ..." */
+	for (i = 0; i < envs.nr; i++) {
+		const char *var = envs.items[i].string;
+		const char *val = envs.items[i].util;
+		const char *oldval;
+
+		if (!val)
+			continue;
+
+		oldval = getenv(var);
+		if (oldval && !strcmp(val, oldval))
+			continue;
+
+		strbuf_addf(dst, " %s=", var);
+		sq_quote_buf_pretty(dst, val);
+	}
+	string_list_clear(&envs, 0);
+}
 
 void trace_run_command(const struct child_process *cp)
 {
@@ -286,6 +342,13 @@ void trace_run_command(const struct child_process *cp)
 
 	strbuf_addf(&buf, "trace: run_command:");
 
+	/*
+	 * The caller is responsible for initializing cp->env from
+	 * cp->env_array if needed. We only check one place.
+	 */
+	if (cp->env)
+		add_env(&buf, cp->env);
+
 	if (cp->git_cmd)
 		strbuf_addstr(&buf, " git");
 
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v4 6/7] trace.c: print env vars in trace_run_command()

[Jeff King]

On Sat, Jan 13, 2018 at 01:49:48PM +0700, Nguyễn Thái Ngọc Duy wrote:

> diff --git a/t/helper/test-run-command.c b/t/helper/test-run-command.c
> index d24d157379..0ab71f14fb 100644
> --- a/t/helper/test-run-command.c
> +++ b/t/helper/test-run-command.c
> @@ -56,6 +56,10 @@ int cmd_main(int argc, const char **argv)
>  
>  	if (argc < 3)
>  		return 1;
> +	while (!strcmp(argv[1], "env")) {
> +		argv_array_push(&proc.env_array, argv[2]);
> +		argv += 2;
> +	}
>  	proc.argv = (const char **)argv + 2;

Probably not super important for a test command, but do we want to make
sure we don't walk past the end of the array in our loop? E.g.:

  while (argv[1] && !strcmp(argv[1], "env")) {
	if (!argv[2]))
		die("env specifier without a value");
	argv_array_push(&proc.env_array, argv[2]);
	argv += 2;
	argc -= 2;
  }
  /* make sure we still have 2 args left */
  if (argc < 3)
	return 1;
  proc.argv = ...;

> diff --git a/trace.c b/trace.c
> index 7f43da211a..ffa1cf9b91 100644
> --- a/trace.c
> +++ b/trace.c
> @@ -275,6 +275,62 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
>  
>  #endif /* HAVE_VARIADIC_MACROS */
>  
> +static void add_env(struct strbuf *dst, const char *const *deltaenv)
> +{
> +	struct string_list envs = STRING_LIST_INIT_DUP;
> +	const char *const *e;
> +	int i;
> +	int printed_unset = 0;
> +
> +	/* Last one wins, see run-command.c:prep_childenv() for context */
> +	for (e = deltaenv; e && *e; e++) {
> +		struct strbuf key = STRBUF_INIT;
> +		char *equals = strchr(*e, '=');
> +		if (equals) {
> +			strbuf_reset(&key);
> +			strbuf_add(&key, *e, equals - *e);

This strbuf_reset() is unnecessary now, since the key strbuf is fresh in
each loop (alternatively, it could be moved out of the loop to avoid
repeated allocations, and move the corresponding release out of the
loop.

> +			string_list_insert(&envs, key.buf)->util = equals + 1;
> +		} else {
> +			string_list_insert(&envs, *e)->util = NULL;
> +		}

Note that this is quadratic in the size of deltaenv (inserting into a
sorted list). But it's the same technique that the actual
prep_childenv() uses, so it's probably OK (we simply don't add that
large a deltaenv in practice).

> +	/* "unset X Y...;" */
> +	for (i = 0; i < envs.nr; i++) {
> +		const char *var = envs.items[i].string;
> +		const char *val = envs.items[i].util;
> +
> +		if (val || !getenv(var))
> +			continue;
> +
> +		if (!printed_unset) {
> +			strbuf_addstr(dst, " unset");
> +			printed_unset = 1;
> +		}
> +		strbuf_addf(dst, " %s", var);
> +	}
> +	if (printed_unset)
> +		strbuf_addch(dst, ';');

Looks good.

> +	/* ... followed by "A=B C=D ..." */
> +	for (i = 0; i < envs.nr; i++) {
> +		const char *var = envs.items[i].string;
> +		const char *val = envs.items[i].util;
> +		const char *oldval;
> +
> +		if (!val)
> +			continue;
> +
> +		oldval = getenv(var);
> +		if (oldval && !strcmp(val, oldval))
> +			continue;
> +
> +		strbuf_addf(dst, " %s=", var);
> +		sq_quote_buf_pretty(dst, val);
> +	}
> +	string_list_clear(&envs, 0);
> +}

Looks good.

The loops in this one are much easier to follow, IMHO.

-Peff

Re: [PATCH v4 6/7] trace.c: print env vars in trace_run_command()

[Junio C Hamano]

Nguyễn Thái Ngọc Duy  <pclouds@gmail.com> writes:

> +test_trace() {
> +	local expected="$1"

Style: "test_trace () {" is how we start a shell function.
Portability: we do not use "local".

> +	shift
> +	GIT_TRACE=1 test-run-command "$@" run-command true 2>&1 >/dev/null | \
> +		sed 's/.* run_command: //' >actual &&
> +	echo "$expected true" >expected &&
> +	test_cmp expected actual

Consistency: everybody else in the test script contrasts "actual" vs
"expect" (they happen to be of the same length ;-); don't say
expectED just to be different.

> +}
> +
> +test_expect_success 'GIT_TRACE with environment variables' '
> +	test_trace "abc=1 def=2" env abc=1 env def=2 &&
> +	test_trace "abc=2" env abc env abc=1 env abc=2 &&
> +	test_trace "abc=2" env abc env abc=2 &&
> +	abc=1 test_trace "def=1" env abc=1 env def=1 &&

Portability: "VAR=VAL shell_function args..." does not work
everywhere, unlike "VAR=VAL command args..." that exports the set of
environment variables for just a single shot invocation of the
command.

Running this script with dash fails, even though bash does behave as
you expect.

> +	abc=1 test_trace "def=1" env abc env abc=1 env def=1 &&
> +	test_trace "def=1" env non-exist env def=1 &&
> +	test_trace "abc=2" env abc=1 env abc env abc=2 &&
> +	abc=1 def=2 test_trace "unset abc def;" env abc env def &&
> +	abc=1 def=2 test_trace "unset def; abc=3" env abc env def env abc=3 &&
> +	abc=1 test_trace "unset abc;" env abc=2 env abc
> +'

Taking them together, here is what I'll be queuing on top to make
today's push-out to pass the tests.

Thanks.

diff --git a/t/t0061-run-command.sh b/t/t0061-run-command.sh
index e6208316c3..24c92b6cd7 100755
--- a/t/t0061-run-command.sh
+++ b/t/t0061-run-command.sh
@@ -141,26 +141,41 @@ test_expect_success 'run_command outputs ' '
 	test_cmp expect actual
 '
 
-test_trace() {
-	local expected="$1"
+test_trace () {
+	expect="$1"
 	shift
 	GIT_TRACE=1 test-run-command "$@" run-command true 2>&1 >/dev/null | \
 		sed 's/.* run_command: //' >actual &&
-	echo "$expected true" >expected &&
-	test_cmp expected actual
+	echo "$expect true" >expect &&
+	test_cmp expect actual
 }
 
 test_expect_success 'GIT_TRACE with environment variables' '
 	test_trace "abc=1 def=2" env abc=1 env def=2 &&
 	test_trace "abc=2" env abc env abc=1 env abc=2 &&
 	test_trace "abc=2" env abc env abc=2 &&
-	abc=1 test_trace "def=1" env abc=1 env def=1 &&
-	abc=1 test_trace "def=1" env abc env abc=1 env def=1 &&
+	(
+		abc=1 && export abc &&
+		test_trace "def=1" env abc=1 env def=1
+	) &&
+	(
+		abc=1 && export abc &&
+		test_trace "def=1" env abc env abc=1 env def=1
+	) &&
 	test_trace "def=1" env non-exist env def=1 &&
 	test_trace "abc=2" env abc=1 env abc env abc=2 &&
-	abc=1 def=2 test_trace "unset abc def;" env abc env def &&
-	abc=1 def=2 test_trace "unset def; abc=3" env abc env def env abc=3 &&
-	abc=1 test_trace "unset abc;" env abc=2 env abc
+	(
+		abc=1 def=2 && export abc def &&
+		test_trace "unset abc def;" env abc env def
+	) &&
+	(
+		abc=1 def=2 && export abc def &&
+		test_trace "unset def; abc=3" env abc env def env abc=3
+	) &&
+	(
+		abc=1 && export abc &&
+		test_trace "unset abc;" env abc=2 env abc
+	)
 '
 
 test_done
-- 
2.16.0-rc2-179-g03f5267cd7

Re: [PATCH v4 6/7] trace.c: print env vars in trace_run_command()

[Stefan Beller]

On Tue, Jan 16, 2018 at 2:13 PM, Junio C Hamano <gitster@pobox.com> wrote:
> Nguyễn Thái Ngọc Duy  <pclouds@gmail.com> writes:
>
>> +test_trace() {
>> +     local expected="$1"
>
> Style: "test_trace () {" is how we start a shell function.
> Portability: we do not use "local".
>
>> +     shift
>> +     GIT_TRACE=1 test-run-command "$@" run-command true 2>&1 >/dev/null | \
>> +             sed 's/.* run_command: //' >actual &&
>> +     echo "$expected true" >expected &&
>> +     test_cmp expected actual
>
> Consistency: everybody else in the test script contrasts "actual" vs
> "expect" (they happen to be of the same length ;-); don't say
> expectED just to be different.

3491 entries in the t/ directory disagree with your imagination of
consistency. ;)
But I agree that we want to go for consistency, and most likely it's
best to go for 'expect'.

Re: [PATCH v4 6/7] trace.c: print env vars in trace_run_command()

[Junio C Hamano]

Stefan Beller <sbeller@google.com> writes:

> On Tue, Jan 16, 2018 at 2:13 PM, Junio C Hamano <gitster@pobox.com> wrote:
>> Nguyễn Thái Ngọc Duy  <pclouds@gmail.com> writes:
>>
>>> +test_trace() {
>>> +     local expected="$1"
>>
>> Style: "test_trace () {" is how we start a shell function.
>> Portability: we do not use "local".
>>
>>> +     shift
>>> +     GIT_TRACE=1 test-run-command "$@" run-command true 2>&1 >/dev/null | \
>>> +             sed 's/.* run_command: //' >actual &&
>>> +     echo "$expected true" >expected &&
>>> +     test_cmp expected actual
>>
>> Consistency: everybody else in the test script contrasts "actual" vs
>> "expect" (they happen to be of the same length ;-); don't say
>> expectED just to be different.
>
> 3491 entries in the t/ directory disagree with your imagination of
> consistency. ;)

Heh.  I thought it was clear enough from the context that I was
talking about matching the remainder of the same test script; I do
not have time time to count 'test_cmp expected' in all others in t/
;-)

> But I agree that we want to go for consistency, and most likely it's
> best to go for 'expect'.

It is unclear if you are volunteering, but do not change things for
the sake of making them consistent.  Not adding new ones and fixing
existing ones when they need to change anyway for some other reason
is the way to do this without unnecessary code churn.

[PATCH v4 7/7] trace.c: print new cwd in trace_run_command()

[Nguyễn Thái Ngọc Duy]

If a command sets a new env variable GIT_DIR=.git, we need more context
to know where that '.git' is related to.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 trace.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/trace.c b/trace.c
index ffa1cf9b91..4bfd3fce10 100644
--- a/trace.c
+++ b/trace.c
@@ -342,6 +342,12 @@ void trace_run_command(const struct child_process *cp)
 
 	strbuf_addf(&buf, "trace: run_command:");
 
+	if (cp->dir) {
+		strbuf_addstr(&buf, " cd ");
+		sq_quote_buf_pretty(&buf, cp->dir);
+		strbuf_addch(&buf, ';');
+	}
+
 	/*
 	 * The caller is responsible for initializing cp->env from
 	 * cp->env_array if needed. We only check one place.
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v4 0/7] Trace env variables in run_command()

[Jeff King]

On Sat, Jan 13, 2018 at 01:49:42PM +0700, Nguyễn Thái Ngọc Duy wrote:

> v4:
> 
> - incorporates Jeff patches and moves them on top
> - removes strbuf release from print_trace_line
> - prints 'unset a b c' instead of 'unset a; unset b; unset c'
> - squashes v3 3/4 and 4/4 and Junio's patch into 6/7
> - adds tests
> - cwd is separated in 7/7

Thanks. Aside from the minor nit about argument parsing in
test-run-command, this looks good to me.

-Peff

[PATCH v5 0/7] Trace env variables in run_command()

[Nguyễn Thái Ngọc Duy]

v5 

 - makes test-run-command safer
 - deletes a dead line
 - fixes an embarassing memory leak

Interdiff

diff --git a/t/helper/test-run-command.c b/t/helper/test-run-command.c
index 0ab71f14fb..153342e44d 100644
--- a/t/helper/test-run-command.c
+++ b/t/helper/test-run-command.c
@@ -57,9 +57,14 @@ int cmd_main(int argc, const char **argv)
 	if (argc < 3)
 		return 1;
 	while (!strcmp(argv[1], "env")) {
+		if (!argv[2])
+			die("env specifier without a value");
 		argv_array_push(&proc.env_array, argv[2]);
 		argv += 2;
+		argc -= 2;
 	}
+	if (argc < 3)
+		return 1;
 	proc.argv = (const char **)argv + 2;
 
 	if (!strcmp(argv[1], "start-command-ENOENT")) {
diff --git a/trace.c b/trace.c
index 4bfd3fce10..ad75d683bf 100644
--- a/trace.c
+++ b/trace.c
@@ -286,8 +286,8 @@ static void add_env(struct strbuf *dst, const char *const *deltaenv)
 	for (e = deltaenv; e && *e; e++) {
 		struct strbuf key = STRBUF_INIT;
 		char *equals = strchr(*e, '=');
+
 		if (equals) {
-			strbuf_reset(&key);
 			strbuf_add(&key, *e, equals - *e);
 			string_list_insert(&envs, key.buf)->util = equals + 1;
 		} else {
@@ -360,6 +360,7 @@ void trace_run_command(const struct child_process *cp)
 
 	sq_quote_argv_pretty(&buf, cp->argv);
 	print_trace_line(&trace_default_key, &buf);
+	strbuf_release(&buf);
 }
 
 static const char *quote_crnl(const char *path)

Jeff King (2):
  sq_quote_argv: drop maxlen parameter
  trace: avoid unnecessary quoting

Nguyễn Thái Ngọc Duy (5):
  trace.c: move strbuf_release() out of print_trace_line()
  trace.c: introduce trace_run_command()
  trace.c: print program 'git' when child_process.git_cmd is set
  trace.c: print env vars in trace_run_command()
  trace.c: print new cwd in trace_run_command()

 builtin/am.c                |  2 +-
 builtin/rev-parse.c         |  4 +-
 quote.c                     | 30 ++++++++++++--
 quote.h                     | 10 ++++-
 run-command.c               |  3 +-
 t/helper/test-run-command.c |  9 +++++
 t/t0061-run-command.sh      | 22 ++++++++++
 trace.c                     | 97 +++++++++++++++++++++++++++++++++++++++++++--
 trace.h                     |  3 ++
 9 files changed, 169 insertions(+), 11 deletions(-)

-- 
2.15.1.600.g899a5f85c6

[PATCH v5 1/7] sq_quote_argv: drop maxlen parameter

[Nguyễn Thái Ngọc Duy]

From: Jeff King <peff@peff.net>

No caller passes anything but "0" for this parameter, which
requests that the function ignore it completely. In fact, in
all of history there was only one such caller, and it went
away in 7f51f8bc2b (alias: use run_command api to execute
aliases, 2011-01-07).

Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 builtin/am.c        | 2 +-
 builtin/rev-parse.c | 4 ++--
 quote.c             | 4 +---
 quote.h             | 2 +-
 trace.c             | 4 ++--
 5 files changed, 7 insertions(+), 9 deletions(-)

diff --git a/builtin/am.c b/builtin/am.c
index acfe9d3c8c..5bdd2d7578 100644
--- a/builtin/am.c
+++ b/builtin/am.c
@@ -1061,7 +1061,7 @@ static void am_setup(struct am_state *state, enum patch_format patch_format,
 	}
 	write_state_text(state, "scissors", str);
 
-	sq_quote_argv(&sb, state->git_apply_opts.argv, 0);
+	sq_quote_argv(&sb, state->git_apply_opts.argv);
 	write_state_text(state, "apply-opt", sb.buf);
 
 	if (state->rebasing)
diff --git a/builtin/rev-parse.c b/builtin/rev-parse.c
index 74aa644cbb..96d06a5d01 100644
--- a/builtin/rev-parse.c
+++ b/builtin/rev-parse.c
@@ -516,7 +516,7 @@ static int cmd_parseopt(int argc, const char **argv, const char *prefix)
 			PARSE_OPT_SHELL_EVAL);
 
 	strbuf_addstr(&parsed, " --");
-	sq_quote_argv(&parsed, argv, 0);
+	sq_quote_argv(&parsed, argv);
 	puts(parsed.buf);
 	return 0;
 }
@@ -526,7 +526,7 @@ static int cmd_sq_quote(int argc, const char **argv)
 	struct strbuf buf = STRBUF_INIT;
 
 	if (argc)
-		sq_quote_argv(&buf, argv, 0);
+		sq_quote_argv(&buf, argv);
 	printf("%s\n", buf.buf);
 	strbuf_release(&buf);
 
diff --git a/quote.c b/quote.c
index de2922ddd6..b2970da627 100644
--- a/quote.c
+++ b/quote.c
@@ -56,7 +56,7 @@ void sq_quotef(struct strbuf *dst, const char *fmt, ...)
 	strbuf_release(&src);
 }
 
-void sq_quote_argv(struct strbuf *dst, const char** argv, size_t maxlen)
+void sq_quote_argv(struct strbuf *dst, const char **argv)
 {
 	int i;
 
@@ -65,8 +65,6 @@ void sq_quote_argv(struct strbuf *dst, const char** argv, size_t maxlen)
 	for (i = 0; argv[i]; ++i) {
 		strbuf_addch(dst, ' ');
 		sq_quote_buf(dst, argv[i]);
-		if (maxlen && dst->len > maxlen)
-			die("Too many or long arguments");
 	}
 }
 
diff --git a/quote.h b/quote.h
index 66f5644aa2..48a75a416b 100644
--- a/quote.h
+++ b/quote.h
@@ -30,7 +30,7 @@ struct strbuf;
  */
 
 extern void sq_quote_buf(struct strbuf *, const char *src);
-extern void sq_quote_argv(struct strbuf *, const char **argv, size_t maxlen);
+extern void sq_quote_argv(struct strbuf *, const char **argv);
 extern void sq_quotef(struct strbuf *, const char *fmt, ...);
 
 /* This unwraps what sq_quote() produces in place, but returns
diff --git a/trace.c b/trace.c
index b7530b51a9..fa9174fc4b 100644
--- a/trace.c
+++ b/trace.c
@@ -157,7 +157,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	strbuf_vaddf(&buf, format, ap);
 
-	sq_quote_argv(&buf, argv, 0);
+	sq_quote_argv(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
 }
 
@@ -426,6 +426,6 @@ void trace_command_performance(const char **argv)
 		atexit(print_command_performance_atexit);
 
 	strbuf_reset(&command_line);
-	sq_quote_argv(&command_line, argv, 0);
+	sq_quote_argv(&command_line, argv);
 	command_start_time = getnanotime();
 }
-- 
2.15.1.600.g899a5f85c6

[PATCH v5 2/7] trace: avoid unnecessary quoting

[Nguyễn Thái Ngọc Duy]

From: Jeff King <peff@peff.net>

Trace output which contains arbitrary strings (e.g., the
arguments to commands which we are running) is always passed
through sq_quote_buf(). That function always adds
single-quotes, even if the output consists of vanilla
characters. This can make the output a bit hard to read.

Let's avoid the quoting if there are no characters which a
shell would interpret. Trace output doesn't necessarily need
to be shell-compatible, but:

  - the shell language is a good ballpark for what humans
    consider readable (well, humans versed in command line
    tools)

  - the run_command bits can be cut-and-pasted to a shell,
    and we'll keep that property

  - it covers any cases which would make the output
    visually ambiguous (e.g., embedded whitespace or quotes)

Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 quote.c | 26 ++++++++++++++++++++++++++
 quote.h |  8 ++++++++
 trace.c |  4 ++--
 3 files changed, 36 insertions(+), 2 deletions(-)

diff --git a/quote.c b/quote.c
index b2970da627..37d2686865 100644
--- a/quote.c
+++ b/quote.c
@@ -43,6 +43,22 @@ void sq_quote_buf(struct strbuf *dst, const char *src)
 	free(to_free);
 }
 
+void sq_quote_buf_pretty(struct strbuf *dst, const char *src)
+{
+	static const char ok_punct[] = "+,-./:=@_^";
+	const char *p;
+
+	for (p = src; *p; p++) {
+		if (!isalpha(*p) && !isdigit(*p) && !strchr(ok_punct, *p)) {
+			sq_quote_buf(dst, src);
+			return;
+		}
+	}
+
+	/* if we get here, we did not need quoting */
+	strbuf_addstr(dst, src);
+}
+
 void sq_quotef(struct strbuf *dst, const char *fmt, ...)
 {
 	struct strbuf src = STRBUF_INIT;
@@ -68,6 +84,16 @@ void sq_quote_argv(struct strbuf *dst, const char **argv)
 	}
 }
 
+void sq_quote_argv_pretty(struct strbuf *dst, const char **argv)
+{
+	int i;
+
+	for (i = 0; argv[i]; i++) {
+		strbuf_addch(dst, ' ');
+		sq_quote_buf_pretty(dst, argv[i]);
+	}
+}
+
 static char *sq_dequote_step(char *arg, char **next)
 {
 	char *dst = arg;
diff --git a/quote.h b/quote.h
index 48a75a416b..ea992dcc91 100644
--- a/quote.h
+++ b/quote.h
@@ -33,6 +33,14 @@ extern void sq_quote_buf(struct strbuf *, const char *src);
 extern void sq_quote_argv(struct strbuf *, const char **argv);
 extern void sq_quotef(struct strbuf *, const char *fmt, ...);
 
+/*
+ * These match their non-pretty variants, except that they avoid
+ * quoting when there are no exotic characters. These should only be used for
+ * human-readable output, as sq_dequote() is not smart enough to dequote it.
+ */
+void sq_quote_buf_pretty(struct strbuf *, const char *src);
+void sq_quote_argv_pretty(struct strbuf *, const char **argv);
+
 /* This unwraps what sq_quote() produces in place, but returns
  * NULL if the input does not look like what sq_quote would have
  * produced.
diff --git a/trace.c b/trace.c
index fa9174fc4b..9784915be1 100644
--- a/trace.c
+++ b/trace.c
@@ -157,7 +157,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	strbuf_vaddf(&buf, format, ap);
 
-	sq_quote_argv(&buf, argv);
+	sq_quote_argv_pretty(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
 }
 
@@ -426,6 +426,6 @@ void trace_command_performance(const char **argv)
 		atexit(print_command_performance_atexit);
 
 	strbuf_reset(&command_line);
-	sq_quote_argv(&command_line, argv);
+	sq_quote_argv_pretty(&command_line, argv);
 	command_start_time = getnanotime();
 }
-- 
2.15.1.600.g899a5f85c6

[PATCH v5 3/7] trace.c: move strbuf_release() out of print_trace_line()

[Nguyễn Thái Ngọc Duy]

The function is about printing a trace line, not releasing the buffer it
receives too. Move strbuf_release() back outside. This makes it easier
to see how strbuf is managed.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 trace.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/trace.c b/trace.c
index 9784915be1..7f3b08e148 100644
--- a/trace.c
+++ b/trace.c
@@ -131,7 +131,6 @@ static void print_trace_line(struct trace_key *key, struct strbuf *buf)
 {
 	strbuf_complete_line(buf);
 	trace_write(key, buf->buf, buf->len);
-	strbuf_release(buf);
 }
 
 static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
@@ -144,6 +143,7 @@ static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
 
 	strbuf_vaddf(&buf, format, ap);
 	print_trace_line(key, &buf);
+	strbuf_release(&buf);
 }
 
 static void trace_argv_vprintf_fl(const char *file, int line,
@@ -159,6 +159,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	sq_quote_argv_pretty(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
+	strbuf_release(&buf);
 }
 
 void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
@@ -171,6 +172,7 @@ void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
 
 	strbuf_addbuf(&buf, data);
 	print_trace_line(key, &buf);
+	strbuf_release(&buf);
 }
 
 static void trace_performance_vprintf_fl(const char *file, int line,
@@ -190,6 +192,7 @@ static void trace_performance_vprintf_fl(const char *file, int line,
 	}
 
 	print_trace_line(&trace_perf_key, &buf);
+	strbuf_release(&buf);
 }
 
 #ifndef HAVE_VARIADIC_MACROS
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v5 3/7] trace.c: move strbuf_release() out of print_trace_line()

[Brandon Williams]

On 01/15, Nguyễn Thái Ngọc Duy wrote:
> The function is about printing a trace line, not releasing the buffer it
> receives too. Move strbuf_release() back outside. This makes it easier
> to see how strbuf is managed.

This makes the code much more readable.

-- 
Brandon Williams

[PATCH v5 4/7] trace.c: introduce trace_run_command()

[Nguyễn Thái Ngọc Duy]

This is the same as the old code that uses trace_argv_printf() in
run-command.c. This function will be improved in later patches to
print more information from struct child_process.

A slight regression: the old code would print run-command.c:xxx as the
trace location site while the new code prints trace.c:xxx. This should
be fine until the second call site is added, then we might need a macro
wrapper named trace_run_command() to capture the right source location.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 run-command.c |  3 ++-
 trace.c       | 16 ++++++++++++++++
 trace.h       |  3 +++
 3 files changed, 21 insertions(+), 1 deletion(-)

diff --git a/run-command.c b/run-command.c
index 31fc5ea86e..002074b128 100644
--- a/run-command.c
+++ b/run-command.c
@@ -624,7 +624,8 @@ int start_command(struct child_process *cmd)
 		cmd->err = fderr[0];
 	}
 
-	trace_argv_printf(cmd->argv, "trace: run_command:");
+	trace_run_command(cmd);
+
 	fflush(NULL);
 
 #ifndef GIT_WINDOWS_NATIVE
diff --git a/trace.c b/trace.c
index 7f3b08e148..da3db301e7 100644
--- a/trace.c
+++ b/trace.c
@@ -23,6 +23,7 @@
 
 #include "cache.h"
 #include "quote.h"
+#include "run-command.h"
 
 struct trace_key trace_default_key = { "GIT_TRACE", 0, 0, 0 };
 struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
@@ -275,6 +276,21 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 #endif /* HAVE_VARIADIC_MACROS */
 
 
+void trace_run_command(const struct child_process *cp)
+{
+	struct strbuf buf = STRBUF_INIT;
+
+	if (!prepare_trace_line(__FILE__, __LINE__,
+				&trace_default_key, &buf))
+		return;
+
+	strbuf_addf(&buf, "trace: run_command:");
+
+	sq_quote_argv_pretty(&buf, cp->argv);
+	print_trace_line(&trace_default_key, &buf);
+	strbuf_release(&buf);
+}
+
 static const char *quote_crnl(const char *path)
 {
 	static struct strbuf new_path = STRBUF_INIT;
diff --git a/trace.h b/trace.h
index 88055abef7..e54c687f26 100644
--- a/trace.h
+++ b/trace.h
@@ -4,6 +4,8 @@
 #include "git-compat-util.h"
 #include "strbuf.h"
 
+struct child_process;
+
 struct trace_key {
 	const char * const key;
 	int fd;
@@ -17,6 +19,7 @@ extern struct trace_key trace_default_key;
 extern struct trace_key trace_perf_key;
 
 extern void trace_repo_setup(const char *prefix);
+extern void trace_run_command(const struct child_process *cp);
 extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
 extern uint64_t getnanotime(void);
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v5 4/7] trace.c: introduce trace_run_command()

[Jeff King]

On Mon, Jan 15, 2018 at 05:59:46PM +0700, Nguyễn Thái Ngọc Duy wrote:

> diff --git a/trace.c b/trace.c
> index 7f3b08e148..da3db301e7 100644
> --- a/trace.c
> +++ b/trace.c
> @@ -23,6 +23,7 @@
>  
>  #include "cache.h"
>  #include "quote.h"
> +#include "run-command.h"
>  
>  struct trace_key trace_default_key = { "GIT_TRACE", 0, 0, 0 };
>  struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
> @@ -275,6 +276,21 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
>  #endif /* HAVE_VARIADIC_MACROS */
>  
>  
> +void trace_run_command(const struct child_process *cp)
> +{
> +	struct strbuf buf = STRBUF_INIT;
> +
> +	if (!prepare_trace_line(__FILE__, __LINE__,
> +				&trace_default_key, &buf))
> +		return;

I think technically this should be TRACE_CONTEXT instead of __FILE__,
though I wonder if anybody has ever set that (there is not even a
Makefile knob for it, so you'd have to -DTRACE_CONTEXT manually).

I actually wonder if it would be nicer to keep this whole thing in
run-command.c, and just prepare it all in a buffer. That's basically
what we're doing here anyway, and then we could get rid of the funny
__FILE__ stuff. I.e., something like:

  struct strbuf buf = STRBUF_INIT;

  if (!trace_want(&trace_default_key))
	return;

  strbuf_addf(&buf, "trace: run_command: ");
  sq_quote_argv_pretty(&buf, cp->argv);

  trace_printf("%s", buf.buf);
  strbuf_release(&buf);

AFAICT we aren't really using any internals of trace.c in our new
function.  That would get rid of this __FILE__ bit, it would eliminate
the need for trace.h to know about "struct child_process", and it would
mean the output still says "run-command.c" in it.

-Peff

Re: [PATCH v5 4/7] trace.c: introduce trace_run_command()

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

>> +void trace_run_command(const struct child_process *cp)
>> +{
>> +	struct strbuf buf = STRBUF_INIT;
>> +
>> +	if (!prepare_trace_line(__FILE__, __LINE__,
>> +				&trace_default_key, &buf))
>> +		return;
>
> I think technically this should be TRACE_CONTEXT instead of __FILE__,
> though I wonder if anybody has ever set that (there is not even a
> Makefile knob for it, so you'd have to -DTRACE_CONTEXT manually).

Oooh. Today I learned a new thing ;-)

> I actually wonder if it would be nicer to keep this whole thing in
> run-command.c, and just prepare it all in a buffer. That's basically
> what we're doing here anyway, and then we could get rid of the funny
> __FILE__ stuff. I.e., something like:
>
>   struct strbuf buf = STRBUF_INIT;
>
>   if (!trace_want(&trace_default_key))
> 	return;
>
>   strbuf_addf(&buf, "trace: run_command: ");
>   sq_quote_argv_pretty(&buf, cp->argv);
>
>   trace_printf("%s", buf.buf);
>   strbuf_release(&buf);
>
> AFAICT we aren't really using any internals of trace.c in our new
> function.  That would get rid of this __FILE__ bit, it would eliminate
> the need for trace.h to know about "struct child_process", and it would
> mean the output still says "run-command.c" in it.

Sounds nice.

[PATCH v5 5/7] trace.c: print program 'git' when child_process.git_cmd is set

[Nguyễn Thái Ngọc Duy]

We normally print full command line, including the program and its
argument. When git_cmd is set, we have a special code path to run the
right "git" program and child_process.argv[0] will not contain the
program name anymore. As a result, we print just the command
arguments.

I thought it was a regression when the code was refactored and git_cmd
added, but apparently it's not. git_cmd mode was introduced before
tracing was added in 8852f5d704 (run_command(): respect GIT_TRACE -
2008-07-07) so it's more like an oversight in 8852f5d704.

Fix it, print the program name "git" in git_cmd mode. It's nice to have
now. But it will be more important later when we start to print env
variables too, in shell syntax. The lack of a program name would look
confusing then.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 trace.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/trace.c b/trace.c
index da3db301e7..98bee2c259 100644
--- a/trace.c
+++ b/trace.c
@@ -286,6 +286,9 @@ void trace_run_command(const struct child_process *cp)
 
 	strbuf_addf(&buf, "trace: run_command:");
 
+	if (cp->git_cmd)
+		strbuf_addstr(&buf, " git");
+
 	sq_quote_argv_pretty(&buf, cp->argv);
 	print_trace_line(&trace_default_key, &buf);
 	strbuf_release(&buf);
-- 
2.15.1.600.g899a5f85c6

[PATCH v5 6/7] trace.c: print env vars in trace_run_command()

[Nguyễn Thái Ngọc Duy]

Occasionally submodule code could execute new commands with GIT_DIR set
to some submodule. GIT_TRACE prints just the command line which makes it
hard to tell that it's not really executed on this repository.

Print the env delta (compared to parent environment) in this case.

Helped-by: Junio C Hamano <gitster@pobox.com>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 t/helper/test-run-command.c |  9 +++++++
 t/t0061-run-command.sh      | 22 ++++++++++++++++
 trace.c                     | 63 +++++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 94 insertions(+)

diff --git a/t/helper/test-run-command.c b/t/helper/test-run-command.c
index d24d157379..153342e44d 100644
--- a/t/helper/test-run-command.c
+++ b/t/helper/test-run-command.c
@@ -54,6 +54,15 @@ int cmd_main(int argc, const char **argv)
 	struct child_process proc = CHILD_PROCESS_INIT;
 	int jobs;
 
+	if (argc < 3)
+		return 1;
+	while (!strcmp(argv[1], "env")) {
+		if (!argv[2])
+			die("env specifier without a value");
+		argv_array_push(&proc.env_array, argv[2]);
+		argv += 2;
+		argc -= 2;
+	}
 	if (argc < 3)
 		return 1;
 	proc.argv = (const char **)argv + 2;
diff --git a/t/t0061-run-command.sh b/t/t0061-run-command.sh
index e4739170aa..e6208316c3 100755
--- a/t/t0061-run-command.sh
+++ b/t/t0061-run-command.sh
@@ -141,4 +141,26 @@ test_expect_success 'run_command outputs ' '
 	test_cmp expect actual
 '
 
+test_trace() {
+	local expected="$1"
+	shift
+	GIT_TRACE=1 test-run-command "$@" run-command true 2>&1 >/dev/null | \
+		sed 's/.* run_command: //' >actual &&
+	echo "$expected true" >expected &&
+	test_cmp expected actual
+}
+
+test_expect_success 'GIT_TRACE with environment variables' '
+	test_trace "abc=1 def=2" env abc=1 env def=2 &&
+	test_trace "abc=2" env abc env abc=1 env abc=2 &&
+	test_trace "abc=2" env abc env abc=2 &&
+	abc=1 test_trace "def=1" env abc=1 env def=1 &&
+	abc=1 test_trace "def=1" env abc env abc=1 env def=1 &&
+	test_trace "def=1" env non-exist env def=1 &&
+	test_trace "abc=2" env abc=1 env abc env abc=2 &&
+	abc=1 def=2 test_trace "unset abc def;" env abc env def &&
+	abc=1 def=2 test_trace "unset def; abc=3" env abc env def env abc=3 &&
+	abc=1 test_trace "unset abc;" env abc=2 env abc
+'
+
 test_done
diff --git a/trace.c b/trace.c
index 98bee2c259..8db5bbf3c9 100644
--- a/trace.c
+++ b/trace.c
@@ -275,6 +275,62 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 
 #endif /* HAVE_VARIADIC_MACROS */
 
+static void add_env(struct strbuf *dst, const char *const *deltaenv)
+{
+	struct string_list envs = STRING_LIST_INIT_DUP;
+	const char *const *e;
+	int i;
+	int printed_unset = 0;
+
+	/* Last one wins, see run-command.c:prep_childenv() for context */
+	for (e = deltaenv; e && *e; e++) {
+		struct strbuf key = STRBUF_INIT;
+		char *equals = strchr(*e, '=');
+
+		if (equals) {
+			strbuf_add(&key, *e, equals - *e);
+			string_list_insert(&envs, key.buf)->util = equals + 1;
+		} else {
+			string_list_insert(&envs, *e)->util = NULL;
+		}
+		strbuf_release(&key);
+	}
+
+	/* "unset X Y...;" */
+	for (i = 0; i < envs.nr; i++) {
+		const char *var = envs.items[i].string;
+		const char *val = envs.items[i].util;
+
+		if (val || !getenv(var))
+			continue;
+
+		if (!printed_unset) {
+			strbuf_addstr(dst, " unset");
+			printed_unset = 1;
+		}
+		strbuf_addf(dst, " %s", var);
+	}
+	if (printed_unset)
+		strbuf_addch(dst, ';');
+
+	/* ... followed by "A=B C=D ..." */
+	for (i = 0; i < envs.nr; i++) {
+		const char *var = envs.items[i].string;
+		const char *val = envs.items[i].util;
+		const char *oldval;
+
+		if (!val)
+			continue;
+
+		oldval = getenv(var);
+		if (oldval && !strcmp(val, oldval))
+			continue;
+
+		strbuf_addf(dst, " %s=", var);
+		sq_quote_buf_pretty(dst, val);
+	}
+	string_list_clear(&envs, 0);
+}
 
 void trace_run_command(const struct child_process *cp)
 {
@@ -286,6 +342,13 @@ void trace_run_command(const struct child_process *cp)
 
 	strbuf_addf(&buf, "trace: run_command:");
 
+	/*
+	 * The caller is responsible for initializing cp->env from
+	 * cp->env_array if needed. We only check one place.
+	 */
+	if (cp->env)
+		add_env(&buf, cp->env);
+
 	if (cp->git_cmd)
 		strbuf_addstr(&buf, " git");
 
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v5 6/7] trace.c: print env vars in trace_run_command()

[Brandon Williams]

On 01/15, Nguyễn Thái Ngọc Duy wrote:
> Occasionally submodule code could execute new commands with GIT_DIR set
> to some submodule. GIT_TRACE prints just the command line which makes it
> hard to tell that it's not really executed on this repository.
> 
> Print the env delta (compared to parent environment) in this case.
> 

Code looks clean and very readable.  Also matches the last one wins
semantics in prep_childenv.

-- 
Brandon Williams

[PATCH v5 7/7] trace.c: print new cwd in trace_run_command()

[Nguyễn Thái Ngọc Duy]

If a command sets a new env variable GIT_DIR=.git, we need more context
to know where that '.git' is related to.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 trace.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/trace.c b/trace.c
index 8db5bbf3c9..ad75d683bf 100644
--- a/trace.c
+++ b/trace.c
@@ -342,6 +342,12 @@ void trace_run_command(const struct child_process *cp)
 
 	strbuf_addf(&buf, "trace: run_command:");
 
+	if (cp->dir) {
+		strbuf_addstr(&buf, " cd ");
+		sq_quote_buf_pretty(&buf, cp->dir);
+		strbuf_addch(&buf, ';');
+	}
+
 	/*
 	 * The caller is responsible for initializing cp->env from
 	 * cp->env_array if needed. We only check one place.
-- 
2.15.1.600.g899a5f85c6

[PATCH v6 0/7] Trace env variables in run_command()

[Nguyễn Thái Ngọc Duy]

v6 squashes Junio's changes in 6/7 and moves trace_run_command() from
trace.c to run-command.c.

Jeff King (2):
  sq_quote_argv: drop maxlen parameter
  trace: avoid unnecessary quoting

Nguyễn Thái Ngọc Duy (5):
  trace.c: move strbuf_release() out of print_trace_line()
  run-command.c: introduce trace_run_command()
  run-command.c: print program 'git' when tracing git_cmd mode
  run-command.c: print env vars in trace_run_command()
  run-command.c: print new cwd in trace_run_command()

 builtin/am.c                |  2 +-
 builtin/rev-parse.c         |  4 +--
 quote.c                     | 30 ++++++++++++++--
 quote.h                     | 10 +++++-
 run-command.c               | 88 ++++++++++++++++++++++++++++++++++++++++++++-
 t/helper/test-run-command.c |  9 +++++
 t/t0061-run-command.sh      | 37 +++++++++++++++++++
 trace.c                     |  9 +++--
 8 files changed, 178 insertions(+), 11 deletions(-)

-- 
2.15.1.600.g899a5f85c6

[PATCH v6 1/7] sq_quote_argv: drop maxlen parameter

[Nguyễn Thái Ngọc Duy]

From: Jeff King <peff@peff.net>

No caller passes anything but "0" for this parameter, which
requests that the function ignore it completely. In fact, in
all of history there was only one such caller, and it went
away in 7f51f8bc2b (alias: use run_command api to execute
aliases, 2011-01-07).

Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 builtin/am.c        | 2 +-
 builtin/rev-parse.c | 4 ++--
 quote.c             | 4 +---
 quote.h             | 2 +-
 trace.c             | 4 ++--
 5 files changed, 7 insertions(+), 9 deletions(-)

diff --git a/builtin/am.c b/builtin/am.c
index acfe9d3c8c..5bdd2d7578 100644
--- a/builtin/am.c
+++ b/builtin/am.c
@@ -1061,7 +1061,7 @@ static void am_setup(struct am_state *state, enum patch_format patch_format,
 	}
 	write_state_text(state, "scissors", str);
 
-	sq_quote_argv(&sb, state->git_apply_opts.argv, 0);
+	sq_quote_argv(&sb, state->git_apply_opts.argv);
 	write_state_text(state, "apply-opt", sb.buf);
 
 	if (state->rebasing)
diff --git a/builtin/rev-parse.c b/builtin/rev-parse.c
index 74aa644cbb..96d06a5d01 100644
--- a/builtin/rev-parse.c
+++ b/builtin/rev-parse.c
@@ -516,7 +516,7 @@ static int cmd_parseopt(int argc, const char **argv, const char *prefix)
 			PARSE_OPT_SHELL_EVAL);
 
 	strbuf_addstr(&parsed, " --");
-	sq_quote_argv(&parsed, argv, 0);
+	sq_quote_argv(&parsed, argv);
 	puts(parsed.buf);
 	return 0;
 }
@@ -526,7 +526,7 @@ static int cmd_sq_quote(int argc, const char **argv)
 	struct strbuf buf = STRBUF_INIT;
 
 	if (argc)
-		sq_quote_argv(&buf, argv, 0);
+		sq_quote_argv(&buf, argv);
 	printf("%s\n", buf.buf);
 	strbuf_release(&buf);
 
diff --git a/quote.c b/quote.c
index de2922ddd6..b2970da627 100644
--- a/quote.c
+++ b/quote.c
@@ -56,7 +56,7 @@ void sq_quotef(struct strbuf *dst, const char *fmt, ...)
 	strbuf_release(&src);
 }
 
-void sq_quote_argv(struct strbuf *dst, const char** argv, size_t maxlen)
+void sq_quote_argv(struct strbuf *dst, const char **argv)
 {
 	int i;
 
@@ -65,8 +65,6 @@ void sq_quote_argv(struct strbuf *dst, const char** argv, size_t maxlen)
 	for (i = 0; argv[i]; ++i) {
 		strbuf_addch(dst, ' ');
 		sq_quote_buf(dst, argv[i]);
-		if (maxlen && dst->len > maxlen)
-			die("Too many or long arguments");
 	}
 }
 
diff --git a/quote.h b/quote.h
index 66f5644aa2..48a75a416b 100644
--- a/quote.h
+++ b/quote.h
@@ -30,7 +30,7 @@ struct strbuf;
  */
 
 extern void sq_quote_buf(struct strbuf *, const char *src);
-extern void sq_quote_argv(struct strbuf *, const char **argv, size_t maxlen);
+extern void sq_quote_argv(struct strbuf *, const char **argv);
 extern void sq_quotef(struct strbuf *, const char *fmt, ...);
 
 /* This unwraps what sq_quote() produces in place, but returns
diff --git a/trace.c b/trace.c
index b7530b51a9..fa9174fc4b 100644
--- a/trace.c
+++ b/trace.c
@@ -157,7 +157,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	strbuf_vaddf(&buf, format, ap);
 
-	sq_quote_argv(&buf, argv, 0);
+	sq_quote_argv(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
 }
 
@@ -426,6 +426,6 @@ void trace_command_performance(const char **argv)
 		atexit(print_command_performance_atexit);
 
 	strbuf_reset(&command_line);
-	sq_quote_argv(&command_line, argv, 0);
+	sq_quote_argv(&command_line, argv);
 	command_start_time = getnanotime();
 }
-- 
2.15.1.600.g899a5f85c6

[PATCH v6 2/7] trace: avoid unnecessary quoting

[Nguyễn Thái Ngọc Duy]

From: Jeff King <peff@peff.net>

Trace output which contains arbitrary strings (e.g., the
arguments to commands which we are running) is always passed
through sq_quote_buf(). That function always adds
single-quotes, even if the output consists of vanilla
characters. This can make the output a bit hard to read.

Let's avoid the quoting if there are no characters which a
shell would interpret. Trace output doesn't necessarily need
to be shell-compatible, but:

  - the shell language is a good ballpark for what humans
    consider readable (well, humans versed in command line
    tools)

  - the run_command bits can be cut-and-pasted to a shell,
    and we'll keep that property

  - it covers any cases which would make the output
    visually ambiguous (e.g., embedded whitespace or quotes)

Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 quote.c | 26 ++++++++++++++++++++++++++
 quote.h |  8 ++++++++
 trace.c |  4 ++--
 3 files changed, 36 insertions(+), 2 deletions(-)

diff --git a/quote.c b/quote.c
index b2970da627..37d2686865 100644
--- a/quote.c
+++ b/quote.c
@@ -43,6 +43,22 @@ void sq_quote_buf(struct strbuf *dst, const char *src)
 	free(to_free);
 }
 
+void sq_quote_buf_pretty(struct strbuf *dst, const char *src)
+{
+	static const char ok_punct[] = "+,-./:=@_^";
+	const char *p;
+
+	for (p = src; *p; p++) {
+		if (!isalpha(*p) && !isdigit(*p) && !strchr(ok_punct, *p)) {
+			sq_quote_buf(dst, src);
+			return;
+		}
+	}
+
+	/* if we get here, we did not need quoting */
+	strbuf_addstr(dst, src);
+}
+
 void sq_quotef(struct strbuf *dst, const char *fmt, ...)
 {
 	struct strbuf src = STRBUF_INIT;
@@ -68,6 +84,16 @@ void sq_quote_argv(struct strbuf *dst, const char **argv)
 	}
 }
 
+void sq_quote_argv_pretty(struct strbuf *dst, const char **argv)
+{
+	int i;
+
+	for (i = 0; argv[i]; i++) {
+		strbuf_addch(dst, ' ');
+		sq_quote_buf_pretty(dst, argv[i]);
+	}
+}
+
 static char *sq_dequote_step(char *arg, char **next)
 {
 	char *dst = arg;
diff --git a/quote.h b/quote.h
index 48a75a416b..ea992dcc91 100644
--- a/quote.h
+++ b/quote.h
@@ -33,6 +33,14 @@ extern void sq_quote_buf(struct strbuf *, const char *src);
 extern void sq_quote_argv(struct strbuf *, const char **argv);
 extern void sq_quotef(struct strbuf *, const char *fmt, ...);
 
+/*
+ * These match their non-pretty variants, except that they avoid
+ * quoting when there are no exotic characters. These should only be used for
+ * human-readable output, as sq_dequote() is not smart enough to dequote it.
+ */
+void sq_quote_buf_pretty(struct strbuf *, const char *src);
+void sq_quote_argv_pretty(struct strbuf *, const char **argv);
+
 /* This unwraps what sq_quote() produces in place, but returns
  * NULL if the input does not look like what sq_quote would have
  * produced.
diff --git a/trace.c b/trace.c
index fa9174fc4b..9784915be1 100644
--- a/trace.c
+++ b/trace.c
@@ -157,7 +157,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	strbuf_vaddf(&buf, format, ap);
 
-	sq_quote_argv(&buf, argv);
+	sq_quote_argv_pretty(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
 }
 
@@ -426,6 +426,6 @@ void trace_command_performance(const char **argv)
 		atexit(print_command_performance_atexit);
 
 	strbuf_reset(&command_line);
-	sq_quote_argv(&command_line, argv);
+	sq_quote_argv_pretty(&command_line, argv);
 	command_start_time = getnanotime();
 }
-- 
2.15.1.600.g899a5f85c6

[PATCH v6 3/7] trace.c: move strbuf_release() out of print_trace_line()

[Nguyễn Thái Ngọc Duy]

The function is about printing a trace line, not releasing the buffer it
receives too. Move strbuf_release() back outside. This makes it easier
to see how strbuf is managed.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 trace.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/trace.c b/trace.c
index 9784915be1..7f3b08e148 100644
--- a/trace.c
+++ b/trace.c
@@ -131,7 +131,6 @@ static void print_trace_line(struct trace_key *key, struct strbuf *buf)
 {
 	strbuf_complete_line(buf);
 	trace_write(key, buf->buf, buf->len);
-	strbuf_release(buf);
 }
 
 static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
@@ -144,6 +143,7 @@ static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
 
 	strbuf_vaddf(&buf, format, ap);
 	print_trace_line(key, &buf);
+	strbuf_release(&buf);
 }
 
 static void trace_argv_vprintf_fl(const char *file, int line,
@@ -159,6 +159,7 @@ static void trace_argv_vprintf_fl(const char *file, int line,
 
 	sq_quote_argv_pretty(&buf, argv);
 	print_trace_line(&trace_default_key, &buf);
+	strbuf_release(&buf);
 }
 
 void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
@@ -171,6 +172,7 @@ void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
 
 	strbuf_addbuf(&buf, data);
 	print_trace_line(key, &buf);
+	strbuf_release(&buf);
 }
 
 static void trace_performance_vprintf_fl(const char *file, int line,
@@ -190,6 +192,7 @@ static void trace_performance_vprintf_fl(const char *file, int line,
 	}
 
 	print_trace_line(&trace_perf_key, &buf);
+	strbuf_release(&buf);
 }
 
 #ifndef HAVE_VARIADIC_MACROS
-- 
2.15.1.600.g899a5f85c6

[PATCH v6 4/7] run-command.c: introduce trace_run_command()

[Nguyễn Thái Ngọc Duy]

This is the same as the old code that uses trace_argv_printf() in
run-command.c. This function will be improved in later patches to
print more information from struct child_process.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 run-command.c | 18 +++++++++++++++++-
 1 file changed, 17 insertions(+), 1 deletion(-)

diff --git a/run-command.c b/run-command.c
index 31fc5ea86e..eadba8cb0d 100644
--- a/run-command.c
+++ b/run-command.c
@@ -6,6 +6,7 @@
 #include "thread-utils.h"
 #include "strbuf.h"
 #include "string-list.h"
+#include "quote.h"
 
 void child_process_init(struct child_process *child)
 {
@@ -556,6 +557,20 @@ static int wait_or_whine(pid_t pid, const char *argv0, int in_signal)
 	return code;
 }
 
+static void trace_run_command(const struct child_process *cp)
+{
+	struct strbuf buf = STRBUF_INIT;
+
+	if (!trace_want(&trace_default_key))
+		return;
+
+	strbuf_addf(&buf, "trace: run_command:");
+	sq_quote_argv_pretty(&buf, cp->argv);
+
+	trace_printf("%s", buf.buf);
+	strbuf_release(&buf);
+}
+
 int start_command(struct child_process *cmd)
 {
 	int need_in, need_out, need_err;
@@ -624,7 +639,8 @@ int start_command(struct child_process *cmd)
 		cmd->err = fderr[0];
 	}
 
-	trace_argv_printf(cmd->argv, "trace: run_command:");
+	trace_run_command(cmd);
+
 	fflush(NULL);
 
 #ifndef GIT_WINDOWS_NATIVE
-- 
2.15.1.600.g899a5f85c6

[PATCH v6 5/7] run-command.c: print program 'git' when tracing git_cmd mode

[Nguyễn Thái Ngọc Duy]

We normally print full command line, including the program and its
argument. When git_cmd is set, we have a special code path to run the
right "git" program and child_process.argv[0] will not contain the
program name anymore. As a result, we print just the command
arguments.

I thought it was a regression when the code was refactored and git_cmd
added, but apparently it's not. git_cmd mode was introduced before
tracing was added in 8852f5d704 (run_command(): respect GIT_TRACE -
2008-07-07) so it's more like an oversight in 8852f5d704.

Fix it, print the program name "git" in git_cmd mode. It's nice to have
now. But it will be more important later when we start to print env
variables too, in shell syntax. The lack of a program name would look
confusing then.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 run-command.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/run-command.c b/run-command.c
index eadba8cb0d..326c33e3cd 100644
--- a/run-command.c
+++ b/run-command.c
@@ -565,6 +565,8 @@ static void trace_run_command(const struct child_process *cp)
 		return;
 
 	strbuf_addf(&buf, "trace: run_command:");
+	if (cp->git_cmd)
+		strbuf_addstr(&buf, " git");
 	sq_quote_argv_pretty(&buf, cp->argv);
 
 	trace_printf("%s", buf.buf);
-- 
2.15.1.600.g899a5f85c6

[PATCH v6 6/7] run-command.c: print env vars in trace_run_command()

[Nguyễn Thái Ngọc Duy]

Occasionally submodule code could execute new commands with GIT_DIR set
to some submodule. GIT_TRACE prints just the command line which makes it
hard to tell that it's not really executed on this repository.

Print the env delta (compared to parent environment) in this case.

Helped-by: Junio C Hamano <gitster@pobox.com>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 run-command.c               | 63 +++++++++++++++++++++++++++++++++++++++++++++
 t/helper/test-run-command.c |  9 +++++++
 t/t0061-run-command.sh      | 37 ++++++++++++++++++++++++++
 3 files changed, 109 insertions(+)

diff --git a/run-command.c b/run-command.c
index 326c33e3cd..1301b878c7 100644
--- a/run-command.c
+++ b/run-command.c
@@ -557,6 +557,63 @@ static int wait_or_whine(pid_t pid, const char *argv0, int in_signal)
 	return code;
 }
 
+static void trace_add_env(struct strbuf *dst, const char *const *deltaenv)
+{
+	struct string_list envs = STRING_LIST_INIT_DUP;
+	const char *const *e;
+	int i;
+	int printed_unset = 0;
+
+	/* Last one wins, see run-command.c:prep_childenv() for context */
+	for (e = deltaenv; e && *e; e++) {
+		struct strbuf key = STRBUF_INIT;
+		char *equals = strchr(*e, '=');
+
+		if (equals) {
+			strbuf_add(&key, *e, equals - *e);
+			string_list_insert(&envs, key.buf)->util = equals + 1;
+		} else {
+			string_list_insert(&envs, *e)->util = NULL;
+		}
+		strbuf_release(&key);
+	}
+
+	/* "unset X Y...;" */
+	for (i = 0; i < envs.nr; i++) {
+		const char *var = envs.items[i].string;
+		const char *val = envs.items[i].util;
+
+		if (val || !getenv(var))
+			continue;
+
+		if (!printed_unset) {
+			strbuf_addstr(dst, " unset");
+			printed_unset = 1;
+		}
+		strbuf_addf(dst, " %s", var);
+	}
+	if (printed_unset)
+		strbuf_addch(dst, ';');
+
+	/* ... followed by "A=B C=D ..." */
+	for (i = 0; i < envs.nr; i++) {
+		const char *var = envs.items[i].string;
+		const char *val = envs.items[i].util;
+		const char *oldval;
+
+		if (!val)
+			continue;
+
+		oldval = getenv(var);
+		if (oldval && !strcmp(val, oldval))
+			continue;
+
+		strbuf_addf(dst, " %s=", var);
+		sq_quote_buf_pretty(dst, val);
+	}
+	string_list_clear(&envs, 0);
+}
+
 static void trace_run_command(const struct child_process *cp)
 {
 	struct strbuf buf = STRBUF_INIT;
@@ -565,6 +622,12 @@ static void trace_run_command(const struct child_process *cp)
 		return;
 
 	strbuf_addf(&buf, "trace: run_command:");
+	/*
+	 * The caller is responsible for initializing cp->env from
+	 * cp->env_array if needed. We only check one place.
+	 */
+	if (cp->env)
+		trace_add_env(&buf, cp->env);
 	if (cp->git_cmd)
 		strbuf_addstr(&buf, " git");
 	sq_quote_argv_pretty(&buf, cp->argv);
diff --git a/t/helper/test-run-command.c b/t/helper/test-run-command.c
index d24d157379..153342e44d 100644
--- a/t/helper/test-run-command.c
+++ b/t/helper/test-run-command.c
@@ -54,6 +54,15 @@ int cmd_main(int argc, const char **argv)
 	struct child_process proc = CHILD_PROCESS_INIT;
 	int jobs;
 
+	if (argc < 3)
+		return 1;
+	while (!strcmp(argv[1], "env")) {
+		if (!argv[2])
+			die("env specifier without a value");
+		argv_array_push(&proc.env_array, argv[2]);
+		argv += 2;
+		argc -= 2;
+	}
 	if (argc < 3)
 		return 1;
 	proc.argv = (const char **)argv + 2;
diff --git a/t/t0061-run-command.sh b/t/t0061-run-command.sh
index e4739170aa..24c92b6cd7 100755
--- a/t/t0061-run-command.sh
+++ b/t/t0061-run-command.sh
@@ -141,4 +141,41 @@ test_expect_success 'run_command outputs ' '
 	test_cmp expect actual
 '
 
+test_trace () {
+	expect="$1"
+	shift
+	GIT_TRACE=1 test-run-command "$@" run-command true 2>&1 >/dev/null | \
+		sed 's/.* run_command: //' >actual &&
+	echo "$expect true" >expect &&
+	test_cmp expect actual
+}
+
+test_expect_success 'GIT_TRACE with environment variables' '
+	test_trace "abc=1 def=2" env abc=1 env def=2 &&
+	test_trace "abc=2" env abc env abc=1 env abc=2 &&
+	test_trace "abc=2" env abc env abc=2 &&
+	(
+		abc=1 && export abc &&
+		test_trace "def=1" env abc=1 env def=1
+	) &&
+	(
+		abc=1 && export abc &&
+		test_trace "def=1" env abc env abc=1 env def=1
+	) &&
+	test_trace "def=1" env non-exist env def=1 &&
+	test_trace "abc=2" env abc=1 env abc env abc=2 &&
+	(
+		abc=1 def=2 && export abc def &&
+		test_trace "unset abc def;" env abc env def
+	) &&
+	(
+		abc=1 def=2 && export abc def &&
+		test_trace "unset def; abc=3" env abc env def env abc=3
+	) &&
+	(
+		abc=1 && export abc &&
+		test_trace "unset abc;" env abc=2 env abc
+	)
+'
+
 test_done
-- 
2.15.1.600.g899a5f85c6

[PATCH v6 7/7] run-command.c: print new cwd in trace_run_command()

[Nguyễn Thái Ngọc Duy]

If a command sets a new env variable GIT_DIR=.git, we need more context
to know where that '.git' is related to.

Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 run-command.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/run-command.c b/run-command.c
index 1301b878c7..a483d5904a 100644
--- a/run-command.c
+++ b/run-command.c
@@ -622,6 +622,11 @@ static void trace_run_command(const struct child_process *cp)
 		return;
 
 	strbuf_addf(&buf, "trace: run_command:");
+	if (cp->dir) {
+		strbuf_addstr(&buf, " cd ");
+		sq_quote_buf_pretty(&buf, cp->dir);
+		strbuf_addch(&buf, ';');
+	}
 	/*
 	 * The caller is responsible for initializing cp->env from
 	 * cp->env_array if needed. We only check one place.
-- 
2.15.1.600.g899a5f85c6

Re: [PATCH v6 0/7] Trace env variables in run_command()

[Jeff King]

On Thu, Jan 18, 2018 at 04:45:05PM +0700, Nguyễn Thái Ngọc Duy wrote:

> v6 squashes Junio's changes in 6/7 and moves trace_run_command() from
> trace.c to run-command.c.

Thanks, this version looks good to me.

-Peff

Re: [PATCH] run-command.c: print env vars when GIT_TRACE is set

[Jeff King]

On Wed, Jan 10, 2018 at 05:48:35PM +0700, Nguyễn Thái Ngọc Duy wrote:

> Occasionally submodule code could execute new commands with GIT_DIR set
> to some submodule. GIT_TRACE prints just the command line which makes it
> hard to tell that it's not really executed on this repository.
> 
> Print env variables in this case. Note that the code deliberately ignore
> variables unsetting because there are so many of them (to keep git
> environment clean for the next process) and really hard to read.

I like this, and I'm pretty sure it would have helped me debug at least
once in the past. I did notice one funny thing, though I think it was
largely there before.

The output for a single command is pretty shell-like due to the quoting:

  $ GIT_TRACE=1 ./git upload-pack . >/dev/null
  [...]run_command: 'git-upload-pack' '.'

You could copy and paste that to a shell if you wanted.  And with
environment variables, that remains so:

  $ GIT_TRACE=1 ./git ls-remote https://github.com/git/git >/dev/null
  [...]run_command: 'GIT_DIR=.git' 'git-remote-https' 'https://[...]'

But if we're actually running a command via the shell, it all gets
quoted as one argument:

  $ GIT_TRACE=1 GIT_PAGER='foo | bar' ./git log
  [...]run_command: 'LV=-c' 'foo | bar'

which is kind of weird, as that's not something that can be run in a
shell. This isn't introduced by your patch at all, but I noticed it more
because of the shell-like environment variable output.

We actually used to print a separate:

  exec: /bin/sh -c 'foo | bar'

line when we invoked a shell, which would arguably be the right place to
show the env variables for such a case. But that went away with
3967e25be1 (run-command: prepare command before forking, 2017-04-19).

I think it might be helpful if we added back in "/bin/sh -c" to the
run_command line when "use_shell" is in effect (and when we're not doing
our "skip the shell" trickery).  But that's totally orthogonal to your
patch.

And anyway, it's just tracing output, so I don't think it's incredibly
important either way. It was just something I noticed while looking at
your patch's output.

-Peff

Re: [PATCH] run-command.c: print env vars when GIT_TRACE is set

[Duy Nguyen]

On Thu, Jan 11, 2018 at 5:07 PM, Jeff King <peff@peff.net> wrote:
> On Wed, Jan 10, 2018 at 05:48:35PM +0700, Nguyễn Thái Ngọc Duy wrote:
>
>> Occasionally submodule code could execute new commands with GIT_DIR set
>> to some submodule. GIT_TRACE prints just the command line which makes it
>> hard to tell that it's not really executed on this repository.
>>
>> Print env variables in this case. Note that the code deliberately ignore
>> variables unsetting because there are so many of them (to keep git
>> environment clean for the next process) and really hard to read.
>
> I like this, and I'm pretty sure it would have helped me debug at least
> once in the past. I did notice one funny thing, though I think it was
> largely there before.
>
> The output for a single command is pretty shell-like due to the quoting:
>
>   $ GIT_TRACE=1 ./git upload-pack . >/dev/null
>   [...]run_command: 'git-upload-pack' '.'
>
> You could copy and paste that to a shell if you wanted.  And with
> environment variables, that remains so:
>
>   $ GIT_TRACE=1 ./git ls-remote https://github.com/git/git >/dev/null
>   [...]run_command: 'GIT_DIR=.git' 'git-remote-https' 'https://[...]'
>
> But if we're actually running a command via the shell, it all gets
> quoted as one argument:
>
>   $ GIT_TRACE=1 GIT_PAGER='foo | bar' ./git log
>   [...]run_command: 'LV=-c' 'foo | bar'
>
> which is kind of weird, as that's not something that can be run in a
> shell. This isn't introduced by your patch at all, but I noticed it more
> because of the shell-like environment variable output.

I think you just found an argument to change my "meh" with regards to
quoting to "need to fix" because I also often copy/paste these
commands. I thought about it and assumed shells would still recognize
'name=value' assignments without actually testing it.

> We actually used to print a separate:
>
>   exec: /bin/sh -c 'foo | bar'
>
> line when we invoked a shell, which would arguably be the right place to
> show the env variables for such a case. But that went away with
> 3967e25be1 (run-command: prepare command before forking, 2017-04-19).
>
> I think it might be helpful if we added back in "/bin/sh -c" to the
> run_command line when "use_shell" is in effect (and when we're not doing
> our "skip the shell" trickery).  But that's totally orthogonal to your
> patch.
>
> And anyway, it's just tracing output, so I don't think it's incredibly
> important either way. It was just something I noticed while looking at
> your patch's output.

Noted. I might do it if it's not super complex.
-- 
Duy

Re: [PATCH] run-command.c: print env vars when GIT_TRACE is set

[Johannes Sixt]

Am 11.01.2018 um 11:07 schrieb Jeff King:
> The output for a single command is pretty shell-like due to the quoting:
> 
>    $ GIT_TRACE=1 ./git upload-pack . >/dev/null
>    [...]run_command: 'git-upload-pack' '.'
> 
> You could copy and paste that to a shell if you wanted.  And with
> environment variables, that remains so:
> 
>    $ GIT_TRACE=1 ./git ls-remote https://github.com/git/git >/dev/null
>    [...]run_command: 'GIT_DIR=.git' 'git-remote-https' 'https://[...]'

Not quite, though. For variable assignments to be recognized as such, 
the name and equal sign must not be quoted:

   GIT_DIR='.git' 'git-remote-https' 'https://[...]'

-- Hannes