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

From: Nguyễn Thái Ngọc Duy <[email-masked]>
Date: Thu, 11 Jan 2018 16:47:12 +0700

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 <[email-masked]>
---
 v2 fixes up commit message to clarify about "env delta" and why var
 deletion is not printed.

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

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

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

diff --git a/run-command.c b/run-command.c
index 31fc5ea86e..002074b128 100644
--- a/run-command.c
+++ b/run-command.c
@@ -624,7 +624,8 @@ int start_command(struct child_process *cmd)
 		cmd->err = fderr[0];
 	}
 
-	trace_argv_printf(cmd->argv, "trace: run_command:");
+	trace_run_command(cmd);
+
 	fflush(NULL);
 
 #ifndef GIT_WINDOWS_NATIVE
diff --git a/trace.c b/trace.c
index b7530b51a9..e5e46e2a09 100644
--- a/trace.c
+++ b/trace.c
@@ -23,6 +23,7 @@
 
 #include "cache.h"
 #include "quote.h"
+#include "run-command.h"
 
 struct trace_key trace_default_key = { "GIT_TRACE", 0, 0, 0 };
 struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
@@ -272,6 +273,44 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,
 #endif /* HAVE_VARIADIC_MACROS */

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