diff mbox series

[v5,3/3] run-command: show prepared command

Message ID 20240525012207.1415196-3-iwienand@redhat.com (mailing list archive)
State Superseded
Headers show
Series [v5,1/3] Documentation: alias: rework notes into points | expand

Commit Message

Ian Wienand May 25, 2024, 1:20 a.m. UTC
This adds a trace point in start_command so we can see the full
command invocation without having to resort to strace/code inspection.
For example:

 $ GIT_TRACE=1 git test foo
 git.c:755               trace: exec: git-test foo
 run-command.c:657       trace: run_command: git-test foo
 run-command.c:657       trace: run_command: 'echo $*' foo
 run-command.c:749       trace: start_command: /bin/sh -c 'echo $* "$@"' 'echo $*' foo

Prior changes have made the documentation around the internals of the
alias command execution clearer, but I have still found this detailed
view of the aliased command being run helpful for debugging purposes.

A test case is added.  This simply looks for the trace point output;
the details change depending on platform -- the important thing is
that we have a verbose log point, not so much the details of what
happens on each platform.

Signed-off-by: Ian Wienand <iwienand@redhat.com>
---
 run-command.c    | 3 +++
 t/t0014-alias.sh | 6 ++++++
 2 files changed, 9 insertions(+)

Comments

Junio C Hamano May 25, 2024, 5:44 a.m. UTC | #1
Ian Wienand <iwienand@redhat.com> writes:

> diff --git a/run-command.c b/run-command.c
> index 1b821042b4..9892c4421c 100644
> --- a/run-command.c
> +++ b/run-command.c
> @@ -746,6 +746,8 @@ int start_command(struct child_process *cmd)
>  		goto end_of_spawn;
>  	}
>  
> +	trace_argv_printf(&argv.v[1], "trace: start_command:");
> +
>  	if (pipe(notify_pipe))
>  		notify_pipe[0] = notify_pipe[1] = -1;

This side is OK ...

> @@ -913,6 +915,7 @@ int start_command(struct child_process *cmd)
>  	else if (cmd->use_shell)
>  		cmd->args.v = prepare_shell_cmd(&nargv, sargv);
>  
> +	trace_argv_printf(&cmd->args.v[1], "trace: start_command:");
>  	cmd->pid = mingw_spawnvpe(cmd->args.v[0], cmd->args.v,
>  				  (char**) cmd->env.v,
>  				  cmd->dir, fhin, fhout, fherr);

... but this side should pass "cmd->args.v" (i.e., the entire array,
without omitting the zeroth element) to be consistent with the other
side.  I made the same mistake in my "how about doing it this way"
draft, by the way.

It is because prepare_cmd() does this:

        static int prepare_cmd(struct strvec *out, const struct child_process *cmd)
        {
                ...
                /*
                 * Add SHELL_PATH so in the event exec fails with ENOEXEC we can
                 * attempt to interpret the command with 'sh'.
                 */
                strvec_push(out, SHELL_PATH);

                if (cmd->git_cmd) {
                        prepare_git_cmd(out, cmd->args.v);
                } else if (cmd->use_shell) {
                        prepare_shell_cmd(out, cmd->args.v);
                ...

So, the other side (i.e. non Windows, that used the result from
prepare_cmd()) skips the argv.v[0] element (which is the SHELL_PATH
pushed by prepare_cmd()), but because a bare use of
prepare_shell_cmd() done on the Windows side does not have that
excess element at the beginning.
Junio C Hamano May 25, 2024, 6:06 a.m. UTC | #2
Ian Wienand <iwienand@redhat.com> writes:

> +test_expect_success 'tracing a shell alias with arguments shows trace of prepared command' '
> +	git config alias.echo "!echo \$*" &&
> +	env GIT_TRACE=1 git echo argument 2>output &&
> +	test_grep "^trace: start_command:.*" output
> +'

This will succeed even if you have two or more instances of this
log, which will not help you avoid the mistake we saw in an earlier
iteration.

How about making sure that the prepared command looks reasonable
enough and we have only one, by doing something like this?

test_expect_success 'tracing a shell alias with arg shows trace of prepared command' '
	cat >expect <<-EOF &&
	trace: prepare_cmd: SHELL -c ${SQ}echo \$* "\$@"${SQ} ${SQ}echo \$*${SQ} arg
	EOF
	git config alias.echo "!echo \$*" &&
	env GIT_TRACE=1 git echo arg 2>output &&
	# redact platform differences
	sed -n -e "s/^\(trace: prepare_cmd:\) .* -c /\1 SHELL -c /p" output >actual &&
	test_cmp expect actual
'

A sample run of CI job with the above change (and others I sent on
the list) can be seen at:

    https://github.com/git/git/actions/runs/9233329671

You can fetch 'seen' and can find commit 05ebf54569, which is the
tip of your topic including a few "fixup" commits I made on top.

  $ git log --decorate --oneline master..05ebf54569
  05ebf54569 (iw/trace-argv-on-alias) fixup! run-command: show prepared command
  11056975bb fixup! run-command: show prepared command
  770dda8f2b run-command: show prepared command
  242b9d4d63 Documentation: alias: add notes on shell expansion
  e4331ad0d4 Documentation: alias: rework notes into points

It hasn't finished running yet, but all the windows tests have
passed, so I'll happily go to bed now ;-)

Thanks.
Ian Wienand May 25, 2024, 11:49 p.m. UTC | #3
On Fri, May 24, 2024 at 11:06:14PM -0700, Junio C Hamano wrote:
> A sample run of CI job with the above change (and others I sent on
> the list) can be seen at:
> 
>     https://github.com/git/git/actions/runs/9233329671

Thanks for this; I had in my head that the pipeline wouldn't run in a
personal fork, but after I enabled it, it does ... I don't know who's
ultimately paying for it but I'll take it :)

 https://github.com/ianw/git/actions/runs/9238552513

is for the v6 version; I'll make sure to run it through that from now
on!

-i
diff mbox series

Patch

diff --git a/run-command.c b/run-command.c
index 1b821042b4..9892c4421c 100644
--- a/run-command.c
+++ b/run-command.c
@@ -746,6 +746,8 @@  int start_command(struct child_process *cmd)
 		goto end_of_spawn;
 	}
 
+	trace_argv_printf(&argv.v[1], "trace: start_command:");
+
 	if (pipe(notify_pipe))
 		notify_pipe[0] = notify_pipe[1] = -1;
 
@@ -913,6 +915,7 @@  int start_command(struct child_process *cmd)
 	else if (cmd->use_shell)
 		cmd->args.v = prepare_shell_cmd(&nargv, sargv);
 
+	trace_argv_printf(&cmd->args.v[1], "trace: start_command:");
 	cmd->pid = mingw_spawnvpe(cmd->args.v[0], cmd->args.v,
 				  (char**) cmd->env.v,
 				  cmd->dir, fhin, fhout, fherr);
diff --git a/t/t0014-alias.sh b/t/t0014-alias.sh
index 95568342be..db747950c7 100755
--- a/t/t0014-alias.sh
+++ b/t/t0014-alias.sh
@@ -44,4 +44,10 @@  test_expect_success 'run-command formats empty args properly' '
     test_cmp expect actual
 '
 
+test_expect_success 'tracing a shell alias with arguments shows trace of prepared command' '
+	git config alias.echo "!echo \$*" &&
+	env GIT_TRACE=1 git echo argument 2>output &&
+	test_grep "^trace: start_command:.*" output
+'
+
 test_done