threads / patch / 47584

patchrun-command.c: print env vars when GIT_TRACE is set

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

## tl;dr

74 messages between Jan 10, 2018 and Jan 19, 2018. Diffs are folded; open one to read it.

replies: 73people: 6as markdown or json

Nguyễn Thái Ngọc Duy· Jan 10, 2018, 10:48 UTC · lore

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(-)
Show changes to 3 files +52 −7

run-command.c, trace.c, trace.h

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
Brandon Williams· Jan 10, 2018, 18:09 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On 01/10, Nguyễn Thái Ngọc Duy wrote:
Show 13 quoted lines
> 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.

Show 39 quoted lines
> 
>  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'
Show 5 quoted lines
> +		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?

Show 97 quoted lines
> +}
> +
>  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
Stefan Beller· Jan 10, 2018, 19:14 UTC · re: Brandon Williams · lore

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

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?

Show 13 quoted lines
>>
>> 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!

Show 55 quoted lines
>
>>
>>  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
Brandon Williams· Jan 10, 2018, 19:26 UTC · re: Stefan Beller · lore

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

On 01/10, Stefan Beller wrote:
Show 10 quoted lines
> 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
Stefan Beller· Jan 10, 2018, 19:35 UTC · re: Brandon Williams · lore

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

On Wed, Jan 10, 2018 at 11:26 AM, Brandon Williams <bmwill@google.com> wrote:
Show 15 quoted lines
> 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?

Nguyễn Thái Ngọc Duy· Jan 11, 2018, 09:47 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to 3 files +44 −1

run-command.c, trace.c, trace.h

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
Duy Nguyen· Jan 11, 2018, 11:25 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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.

Show 5 quoted lines
>  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
Brandon Williams· Jan 11, 2018, 17:53 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On 01/11, Nguyễn Thái Ngọc Duy wrote:
Show 73 quoted lines
> 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.

Show 54 quoted lines
> +		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
Stefan Beller· Jan 11, 2018, 18:20 UTC · re: Brandon Williams · lore

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

On Thu, Jan 11, 2018 at 9:53 AM, Brandon Williams <bmwill@google.com> wrote:
Show 27 quoted lines
> 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

Junio C Hamano· Jan 11, 2018, 19:27 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

Nguyễn Thái Ngọc Duy  <pclouds@gmail.com> writes:
Show 7 quoted lines
> 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).

Show 9 quoted lines
> +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.
Show 6 quoted lines
> +		 * 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.
Duy Nguyen· Jan 12, 2018, 09:23 UTC · re: Junio C Hamano · lore

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

On Fri, Jan 12, 2018 at 2:27 AM, Junio C Hamano <gitster@pobox.com> wrote:
Show 5 quoted lines
> 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
Nguyễn Thái Ngọc Duy· Jan 12, 2018, 09:56 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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
Nguyễn Thái Ngọc Duy· Jan 12, 2018, 09:56 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to 3 files +20 −1

run-command.c, trace.c, trace.h

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
Jeff King· Jan 12, 2018, 13:05 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On Fri, Jan 12, 2018 at 04:56:04PM +0700, Nguyễn Thái Ngọc Duy wrote:
Show 8 quoted lines
> 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.
Show 13 quoted lines
> +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
Jeff King· Jan 12, 2018, 13:11 UTC · re: Jeff King · lore

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

On Fri, Jan 12, 2018 at 08:05:22AM -0500, Jeff King wrote:
Show 21 quoted lines
> > +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.
Nguyễn Thái Ngọc Duy· Jan 12, 2018, 09:56 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to trace.c +3 −0
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
Jeff King· Jan 12, 2018, 13:05 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On Fri, Jan 12, 2018 at 04:56:05PM +0700, Nguyễn Thái Ngọc Duy wrote:
Show 15 quoted lines
> 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
Nguyễn Thái Ngọc Duy· Jan 12, 2018, 09:56 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to trace.c +27 −0
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
Jeff King· Jan 12, 2018, 13:13 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On Fri, Jan 12, 2018 at 04:56:06PM +0700, Nguyễn Thái Ngọc Duy wrote:
Show 12 quoted lines
> 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:
Show 6 quoted lines
> @@ -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
Nguyễn Thái Ngọc Duy· Jan 12, 2018, 09:56 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to trace.c +69 −8
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
Jeff King· Jan 12, 2018, 13:33 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On Fri, Jan 12, 2018 at 04:56:07PM +0700, Nguyễn Thái Ngọc Duy wrote:
Show 8 quoted lines
> 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.
Show 11 quoted lines
> 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.
Show 7 quoted lines
> +		/*
> +		 * 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
Junio C Hamano· Jan 12, 2018, 18:24 UTC · re: Jeff King · lore

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

Jeff King <peff@peff.net> writes:
Show 10 quoted lines
>> +		/*
>> +		 * 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.

Jeff King· Jan 12, 2018, 18:45 UTC · re: Junio C Hamano · lore

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

On Fri, Jan 12, 2018 at 10:24:28AM -0800, Junio C Hamano wrote:
Show 15 quoted lines
> 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.
Show 6 quoted lines
> 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.
Show 12 quoted lines
> 
> > 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
Junio C Hamano· Jan 12, 2018, 19:19 UTC · re: Jeff King · lore

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

Jeff King <peff@peff.net> writes:
Show 9 quoted lines
> 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.

Jeff King· Jan 12, 2018, 19:23 UTC · re: Junio C Hamano · lore

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

On Fri, Jan 12, 2018 at 11:19:44AM -0800, Junio C Hamano wrote:
Show 23 quoted lines
> 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
Brandon Williams· Jan 12, 2018, 20:28 UTC · re: Jeff King · lore

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

On 01/12, Jeff King wrote:
Show 31 quoted lines
> 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
Junio C Hamano· Jan 12, 2018, 22:54 UTC · re: Jeff King · lore

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

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(-)
Show changes to trace.c +21 −47
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);
 }
Duy Nguyen· Jan 13, 2018, 04:54 UTC · re: Junio C Hamano · lore

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

On Sat, Jan 13, 2018 at 5:54 AM, Junio C Hamano <gitster@pobox.com> wrote:
Show 18 quoted lines
> 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
Duy Nguyen· Jan 13, 2018, 06:47 UTC · re: Duy Nguyen · lore

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

On Sat, Jan 13, 2018 at 11:54 AM, Duy Nguyen <pclouds@gmail.com> wrote:
Show 21 quoted lines
> 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
Jeff King· Jan 12, 2018, 13:36 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On Fri, Jan 12, 2018 at 04:56:03PM +0700, Nguyễn Thái Ngọc Duy wrote:
Show 8 quoted lines
> 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.
Show 7 quoted lines
> 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
Jeff King· Jan 12, 2018, 13:38 UTC · re: Jeff King · lore

[PATCH 5/4] sq_quote_argv: drop maxlen parameter

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(-)
Show changes to 5 files +8 −10

builtin/am.c, builtin/rev-parse.c, quote.c, quote.h, trace.c

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
Junio C Hamano· Jan 12, 2018, 23:20 UTC · re: Jeff King · lore

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

Jeff King <peff@peff.net> writes:
Show 9 quoted lines
> 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 ;-)..

Jeff King· Jan 12, 2018, 13:39 UTC · re: Jeff King · lore

[PATCH 6/4] trace: avoid unnecessary quoting

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(-)
Show changes to 3 files +39 −5

quote.c, quote.h, trace.c

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
Stefan Beller· Jan 12, 2018, 18:06 UTC · re: Jeff King · lore

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

On Fri, Jan 12, 2018 at 5:36 AM, Jeff King <peff@peff.net> wrote:
Show 28 quoted lines
> 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

Stefan Beller· Jan 12, 2018, 17:19 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On Fri, Jan 12, 2018 at 1:56 AM, Nguyễn Thái Ngọc Duy <pclouds@gmail.com> wrote:
Show 19 quoted lines
> 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?)

Duy Nguyen· Jan 13, 2018, 06:54 UTC · re: Stefan Beller · lore

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

On Sat, Jan 13, 2018 at 12:19 AM, Stefan Beller <sbeller@google.com> wrote:
Show 8 quoted lines
>> 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
Nguyễn Thái Ngọc Duy· Jan 13, 2018, 06:49 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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':
Show changes to 3 files +50 −14

t/helper/test-run-command.c, t/t0061-run-command.sh, trace.c

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
Nguyễn Thái Ngọc Duy· Jan 13, 2018, 06:49 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to 5 files +7 −9

builtin/am.c, builtin/rev-parse.c, quote.c, quote.h, trace.c

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
Nguyễn Thái Ngọc Duy· Jan 13, 2018, 06:49 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to 3 files +36 −2

quote.c, quote.h, trace.c

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
Nguyễn Thái Ngọc Duy· Jan 13, 2018, 06:49 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to trace.c +4 −1
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
Jeff King· Jan 13, 2018, 07:14 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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.

Show 10 quoted lines
> 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
Nguyễn Thái Ngọc Duy· Jan 13, 2018, 06:49 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to 3 files +20 −1

run-command.c, trace.c, trace.h

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
Nguyễn Thái Ngọc Duy· Jan 13, 2018, 06:49 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to trace.c +3 −0
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
Nguyễn Thái Ngọc Duy· Jan 13, 2018, 06:49 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to 3 files +89 −0

t/helper/test-run-command.c, t/t0061-run-command.sh, trace.c

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
Jeff King· Jan 13, 2018, 07:25 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On Sat, Jan 13, 2018 at 01:49:48PM +0700, Nguyễn Thái Ngọc Duy wrote:
Show 13 quoted lines
> 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 = ...;
Show 22 quoted lines
> 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).

Show 16 quoted lines
> +	/* "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.
Show 18 quoted lines
> +	/* ... 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
Junio C Hamano· Jan 16, 2018, 22:13 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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".
Show 5 quoted lines
> +	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.
Show 7 quoted lines
> +}
> +
> +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.

Show 7 quoted lines
> +	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.
Show changes to t/t0061-run-command.sh +24 −9
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
Stefan Beller· Jan 16, 2018, 22:20 UTC · re: Junio C Hamano · lore

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

On Tue, Jan 16, 2018 at 2:13 PM, Junio C Hamano <gitster@pobox.com> wrote:
Show 17 quoted lines
> 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'.

Junio C Hamano· Jan 17, 2018, 01:32 UTC · re: Stefan Beller · lore

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

Stefan Beller <sbeller@google.com> writes:
Show 21 quoted lines
> 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.

Nguyễn Thái Ngọc Duy· Jan 13, 2018, 06:49 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to trace.c +6 −0
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
Jeff King· Jan 13, 2018, 07:26 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On Sat, Jan 13, 2018 at 01:49:42PM +0700, Nguyễn Thái Ngọc Duy wrote:
Show 8 quoted lines
> 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
Nguyễn Thái Ngọc Duy· Jan 15, 2018, 10:59 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

v5 
 - makes test-run-command safer
 - deletes a dead line
 - fixes an embarassing memory leak
Interdiff
Show changes to 2 files +7 −1

t/helper/test-run-command.c, trace.c

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
Nguyễn Thái Ngọc Duy· Jan 15, 2018, 10:59 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to 5 files +7 −9

builtin/am.c, builtin/rev-parse.c, quote.c, quote.h, trace.c

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
Nguyễn Thái Ngọc Duy· Jan 15, 2018, 10:59 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to 3 files +36 −2

quote.c, quote.h, trace.c

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
Nguyễn Thái Ngọc Duy· Jan 15, 2018, 10:59 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to trace.c +4 −1
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
Brandon Williams· Jan 16, 2018, 18:24 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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
Nguyễn Thái Ngọc Duy· Jan 15, 2018, 10:59 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to 3 files +21 −1

run-command.c, trace.c, trace.h

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
Jeff King· Jan 17, 2018, 22:21 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On Mon, Jan 15, 2018 at 05:59:46PM +0700, Nguyễn Thái Ngọc Duy wrote:
Show 23 quoted lines
> 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
Junio C Hamano· Jan 17, 2018, 22:41 UTC · re: Jeff King · lore

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

Jeff King <peff@peff.net> writes:
Show 11 quoted lines
>> +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 ;-)
Show 20 quoted lines
> 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.
Nguyễn Thái Ngọc Duy· Jan 15, 2018, 10:59 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to trace.c +3 −0
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
Nguyễn Thái Ngọc Duy· Jan 15, 2018, 10:59 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to 3 files +94 −0

t/helper/test-run-command.c, t/t0061-run-command.sh, trace.c

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
Brandon Williams· Jan 16, 2018, 18:32 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On 01/15, Nguyễn Thái Ngọc Duy wrote:
Show 6 quoted lines
> 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
Nguyễn Thái Ngọc Duy· Jan 15, 2018, 10:59 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to trace.c +6 −0
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
Nguyễn Thái Ngọc Duy· Jan 18, 2018, 09:45 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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
Nguyễn Thái Ngọc Duy· Jan 18, 2018, 09:45 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to 5 files +7 −9

builtin/am.c, builtin/rev-parse.c, quote.c, quote.h, trace.c

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
Nguyễn Thái Ngọc Duy· Jan 18, 2018, 09:45 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to 3 files +36 −2

quote.c, quote.h, trace.c

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
Nguyễn Thái Ngọc Duy· Jan 18, 2018, 09:45 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to trace.c +4 −1
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
Nguyễn Thái Ngọc Duy· Jan 18, 2018, 09:45 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(-)
Show changes to run-command.c +17 −1
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
Nguyễn Thái Ngọc Duy· Jan 18, 2018, 09:45 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to run-command.c +2 −0
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
Nguyễn Thái Ngọc Duy· Jan 18, 2018, 09:45 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to 3 files +109 −0

run-command.c, t/helper/test-run-command.c, t/t0061-run-command.sh

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
Nguyễn Thái Ngọc Duy· Jan 18, 2018, 09:45 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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(+)
Show changes to run-command.c +5 −0
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
Jeff King· Jan 19, 2018, 21:39 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

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
Jeff King· Jan 11, 2018, 10:07 UTC · re: Nguyễn Thái Ngọc Duy · lore

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

On Wed, Jan 10, 2018 at 05:48:35PM +0700, Nguyễn Thái Ngọc Duy wrote:
Show 7 quoted lines
> 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
Duy Nguyen· Jan 11, 2018, 11:13 UTC · re: Jeff King · lore

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

On Thu, Jan 11, 2018 at 5:07 PM, Jeff King <peff@peff.net> wrote:
Show 34 quoted lines
> 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.

Show 16 quoted lines
> 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
Johannes Sixt· Jan 11, 2018, 18:21 UTC · re: Jeff King · lore

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

Am 11.01.2018 um 11:07 schrieb Jeff King:
Show 10 quoted lines
> 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

← back to recent threads