| Message ID | 20240523043806.1223032-3-iwienand@redhat.com (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | [v3,1/3] Documentation: alias: rework notes into points | expand |
Ian Wienand <iwienand@redhat.com> writes: > This adds a trace point in prepare_cmd, so we can see the actual > command being run without having to resort to strace/code inspection. > > e.g. "test = !echo" when run under GIT_TRACE will show: > > $ GIT_TRACE=1 git test hello > 10:58:56.877234 git.c:755 trace: exec: git-test hello > 10:58:56.877382 run-command.c:657 trace: run_command: git-test hello > 10:58:56.878655 run-command.c:657 trace: run_command: echo hello > 10:58:56.878747 run-command.c:437 trace: prepare_cmd: /usr/bin/echo hello > hello Nice. > A "split" alias, e.g. test = "!echo $*" will show the shell wrapping > and appending of "$@". > > $ GIT_TRACE=1 git test hello > 11:00:45.959420 git.c:755 trace: exec: git-test hello > 11:00:45.959737 run-command.c:657 trace: run_command: git-test hello > 11:00:45.961424 run-command.c:657 trace: run_command: 'echo $*' hello > 11:00:45.961528 run-command.c:437 trace: prepare_cmd: /bin/sh -c 'echo $* "$@"' 'echo $*' hello > hello hello Nice again. But ... > For example, this can be very helpful when an alias is giving you an > unexpected syntax error that is very difficult figure out from only > the run_command trace point, e.g. > > test = "!for i in 1 2 3; do echo $i; done" > > will fail if there is an argument given, we can see why from the > output. ... if the reader truly understands "the alias gives the command and its leading arguments, to which the invocation can supply even more arguments", the reader wouldn't be writing such a command line to begin with, no? So I find the example a bit suboptimal. Hopefully additional explanation in patch 2/3 stressed on that point well enough with much more stress than it talks about the implementation detail of using "sh -c" and "$@", so that readers who read it would not even dream of writing such an alias in the first place. > diff --git a/run-command.c b/run-command.c > index 1b821042b4..36b2b2f194 100644 > --- a/run-command.c > +++ b/run-command.c > @@ -435,6 +435,7 @@ static int prepare_cmd(struct strvec *out, const struct child_process *cmd) > } > } > > + trace_argv_printf(&out->v[1], "trace: prepare_cmd:"); > return 0; > } Nice addition that is obviously correct. > diff --git a/t/t0014-alias.sh b/t/t0014-alias.sh > index 95568342be..75c8763a6c 100755 > --- a/t/t0014-alias.sh > +++ b/t/t0014-alias.sh > @@ -44,4 +44,11 @@ test_expect_success 'run-command formats empty args properly' ' > test_cmp expect actual > ' > > +test_expect_success 'tracing a shell alias with arguments shows full prepared command' ' > + git config alias.echo "!echo \$*" && > + env GIT_TRACE=1 git echo argument 2>output && > + cp output /tmp/output && > + test_grep "^trace: prepare_cmd: /bin/sh -c '\''echo \$\* \"\$@\"" output > +' This is probably too specific search string, I suspect, given that runcommand.c:prepare_shell_cmd() uses SHELL_PATH or "sh" so if your SHELL_PATH is anything but /bin/sh (or if you are unlucky enough to be running this test on Windows), the pattern would not match. You'd want to loosen it a bit, perhaps with "/bin/sh" -> ".*", as the rest of the output are expected to stay constant. By the way, common to this step and also to the previous step, you'd want to use echo "$@" instead of echo $* to encourage better variable reference hygiene. It makes difference when any arguments given to "e" has whitespace, i.e. $ sh -c 'echo $*' - a 'b c' a b c $ sh -c 'echo "$@"' - a 'b c' a b c Thanks.
Junio C Hamano <gitster@pobox.com> writes: >> + git config alias.echo "!echo \$*" && >> + env GIT_TRACE=1 git echo argument 2>output && >> + cp output /tmp/output && >> + test_grep "^trace: prepare_cmd: /bin/sh -c '\''echo \$\* \"\$@\"" output >> +' > > This is probably too specific search string, ... And of course, 'seen' no longer passes the test with this topic merged when run with SHELL_PATH=/bin/dash for obvious reasons. I've added the following band-aid to help 'seen' pass CI, but this has to be fixed in the main patch by squashing it in. Thanks. --- >8 --- Subject: [PATCH] fixup! run-command: show prepared command Do not assume everybody sets SHELL_PATH to /bin/sh --- t/t0014-alias.sh | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/t/t0014-alias.sh b/t/t0014-alias.sh index 75c8763a6c..0d42d2b454 100755 --- a/t/t0014-alias.sh +++ b/t/t0014-alias.sh @@ -48,7 +48,8 @@ test_expect_success 'tracing a shell alias with arguments shows full prepared co git config alias.echo "!echo \$*" && env GIT_TRACE=1 git echo argument 2>output && cp output /tmp/output && - test_grep "^trace: prepare_cmd: /bin/sh -c '\''echo \$\* \"\$@\"" output + # ".*" can be "sh", or SHELL_PATH (not always "/bin/sh") + test_grep "^trace: prepare_cmd: .* -c '\''echo \$\* \"\$@\"" output ' test_done
On Thu, May 23, 2024 at 08:29:21AM -0700, Junio C Hamano wrote: > > For example, this can be very helpful when an alias is giving you an > > unexpected syntax error that is very difficult figure out from only > > the run_command trace point, e.g. > > > > test = "!for i in 1 2 3; do echo $i; done" > > > > will fail if there is an argument given, we can see why from the > > output. > > ... if the reader truly understands "the alias gives the command and > its leading arguments, to which the invocation can supply even more > arguments", the reader wouldn't be writing such a command line to > begin with, no? > > So I find the example a bit suboptimal. Hopefully additional > explanation in patch 2/3 stressed on that point well enough with > much more stress than it talks about the implementation detail of > using "sh -c" and "$@", so that readers who read it would not even > dream of writing such an alias in the first place. Right; I was seeing this in a more convoluted way via our tool but essentially the same issue. I was just looking for the simplest thing that also gave the syntax error output, which I thought was something people might search for (the "unexpected "$@" stuff). Should I just leave as is? > > +test_expect_success 'tracing a shell alias with arguments shows full prepared command' ' > > + git config alias.echo "!echo \$*" && > > + env GIT_TRACE=1 git echo argument 2>output && > > + cp output /tmp/output && > > + test_grep "^trace: prepare_cmd: /bin/sh -c '\''echo \$\* \"\$@\"" output > > +' > > This is probably too specific search string, I suspect, given that > runcommand.c:prepare_shell_cmd() uses SHELL_PATH or "sh" so if your > SHELL_PATH is anything but /bin/sh (or if you are unlucky enough to > be running this test on Windows), the pattern would not match. > You'd want to loosen it a bit, perhaps with "/bin/sh" -> ".*", as > the rest of the output are expected to stay constant. OK, should this perhaps just look for '^trace: prepare_cmd.*'? My initial thinking was to enforce seeing the "$@" appended, but perhaps that is implementation details that don't really need to be covered; the interesting thing is we show the person tracing the full command as constructed, so this is useful just to ensure the tracepoint remains in place? -i
Junio C Hamano <gitster@pobox.com> writes: > Subject: [PATCH] fixup! run-command: show prepared command > > Do not assume everybody sets SHELL_PATH to /bin/sh > --- > t/t0014-alias.sh | 3 ++- > 1 file changed, 2 insertions(+), 1 deletion(-) > > diff --git a/t/t0014-alias.sh b/t/t0014-alias.sh > index 75c8763a6c..0d42d2b454 100755 > --- a/t/t0014-alias.sh > +++ b/t/t0014-alias.sh > @@ -48,7 +48,8 @@ test_expect_success 'tracing a shell alias with arguments shows full prepared co > git config alias.echo "!echo \$*" && > env GIT_TRACE=1 git echo argument 2>output && > cp output /tmp/output && > - test_grep "^trace: prepare_cmd: /bin/sh -c '\''echo \$\* \"\$@\"" output > + # ".*" can be "sh", or SHELL_PATH (not always "/bin/sh") > + test_grep "^trace: prepare_cmd: .* -c '\''echo \$\* \"\$@\"" output > ' So with this applied on top of the topic, 'seen' does pass with SHELL_PATH set to say /bin/dash, but this still fails CI jobs on Windows. A sample run that failed (you'd probably need to be logged in as a github user there): https://github.com/git/git/actions/runs/9216303673/job/25360383492#step:5:237 With the lack of "trace: prepare_cmd:" in the "output" file, on the platform, perhaps the code is failing to find an executable for "echo" on the $PATH and taking the early return codepath that sets errno to ENOENT and returns -1? Or it is that even prepare_cmd() is not called? I do not do Windows, so I'll stop here. Oh by the way, I just noticed that there is an apparent leftover debugging statement that accesses outside the test playpen. When you reroll the patch, please make sure that "cp output /tmp/output" is removed. Thanks.
On Thu, May 23, 2024 at 11:09:01PM -0700, Junio C Hamano wrote: > So with this applied on top of the topic, 'seen' does pass with > SHELL_PATH set to say /bin/dash, but this still fails CI jobs on > Windows. Sigh, it looks like windows uses prepare_shell_cmd() instead. I think it's still probably valid to dump the full command there for the same reasons, which I'll add in v4. I've reduced to the check to just look for the trace prefix. This is enough to ensure we don't regress by removing it; the exact details of what comes out really isn't the main point -- it's that the log is there at all to help you debug what is being run. > Oh by the way, I just noticed that there is an apparent leftover > debugging statement that accesses outside the test playpen. When > you reroll the patch, please make sure that "cp output /tmp/output" > is removed. Done -i
Ian Wienand <iwienand@redhat.com> writes: > On Thu, May 23, 2024 at 11:09:01PM -0700, Junio C Hamano wrote: >> So with this applied on top of the topic, 'seen' does pass with >> SHELL_PATH set to say /bin/dash, but this still fails CI jobs on >> Windows. > > Sigh, it looks like windows uses prepare_shell_cmd() instead. I think > it's still probably valid to dump the full command there for the same > reasons, which I'll add in v4. Ahh, it's the large conditional compilation in start_command(). On non-Windows side, we just do if (prepare_cmd(&argv, cmd) < 0) { failed_errno = errno; ... goto end_of_spawn; } ... pipe(), fork(), and exec() ... but on Windows side, we have if (cmd->git_cmd) cmd->args.v = prepare_git_cmd(&nargv, sargv); else if (cmd->use_shell) cmd->args.v = prepare_shell_cmd(&nargv, sargv); cmd->pid = mingw_spawnvpe(cmd->args.v[0], cmd->args.v, (char**) cmd->env.v, cmd->dir, fhin, fhout, fherr); And the thing is, prepare_cmd() already has if (cmd->git_cmd) { prepare_git_cmd(out, cmd->args.v); } else if (cmd->use_shell) { prepare_shell_cmd(out, cmd->args.v); } else { strvec_pushv(out, cmd->args.v); } I am wondering (and not suggesting to do this as a part of this series, but to decide if we should leave a left-over-bits note here) if the Windows side can be updated to also use prepare_cmd(). Do folks a lot more familiar with Windows than I (cc'ed j6t and dscho) have comments on this? Anyway. If you unconditionally add the printf's to both prepare_cmd() and prepare_shell_cmd(), you'll see two printf output on a non-Windows platform if we are spawning a shell cmd. It appears that the best place to "show the prepared command" is *NOT* in any of these prepare_* helper functions, but after these two callers in start_command() receives the prepared command from these helpers, namely: diff --git c/run-command.c w/run-command.c index 1b821042b4..9d0fa6afe4 100644 --- c/run-command.c +++ w/run-command.c @@ -745,6 +745,7 @@ int start_command(struct child_process *cmd) error_errno("cannot run %s", cmd->args.v[0]); goto end_of_spawn; } + /* Here show argv in the trace */ if (pipe(notify_pipe)) notify_pipe[0] = notify_pipe[1] = -1; @@ -912,6 +913,7 @@ int start_command(struct child_process *cmd) cmd->args.v = prepare_git_cmd(&nargv, sargv); else if (cmd->use_shell) cmd->args.v = prepare_shell_cmd(&nargv, sargv); + /* Here show cmd->args.v in the trace */ cmd->pid = mingw_spawnvpe(cmd->args.v[0], cmd->args.v, (char**) cmd->env.v, We would not have to do so and instead have trace-printf(s) only in prepare_cmd() if/when the Windows side is updated to stop switching between the prepare_git/prepare_shell and instead let prepare_cmd() do the switching, (which may require an update to prepare_cmd() if needed). But until that happens, logging at the caller seems to be the best approach among equally bad ones. Thanks.
Ian Wienand <iwienand@redhat.com> writes: > On Thu, May 23, 2024 at 08:29:21AM -0700, Junio C Hamano wrote: >> ... if the reader truly understands "the alias gives the command and >> its leading arguments, to which the invocation can supply even more >> arguments", the reader wouldn't be writing such a command line to >> begin with, no? >> >> So I find the example a bit suboptimal. Hopefully additional >> explanation in patch 2/3 stressed on that point well enough with >> much more stress than it talks about the implementation detail of >> using "sh -c" and "$@", so that readers who read it would not even >> dream of writing such an alias in the first place. > > Right; I was seeing this in a more convoluted way via our tool but > essentially the same issue. I was just looking for the simplest thing > that also gave the syntax error output, which I thought was something > people might search for (the "unexpected "$@" stuff). > > Should I just leave as is? If I found as-is would be good enough, I wouldn't have been commenting on this. Even in this third iteration, I still didn't see the added documentation talk about the principle behind the design, i.e. what you write after the "git your-alias" are appended to the command line to be used as additional arguments.
On Fri, May 24, 2024 at 10:50:33AM -0700, Junio C Hamano wrote: > > Should I just leave as is? > > If I found as-is would be good enough, I wouldn't have been > commenting on this. I think this "for ... done" example from me is perhaps too specific and weird, and not being helpful. I'll trim all this out as I think the point can be made clearer. > Even in this third iteration, I still didn't see the added > documentation talk about the principle behind the design, i.e. what > you write after the "git your-alias" are appended to the command > line to be used as additional arguments. I'll send an update that makes it clearer in a separate point that for simple arguments, the added "$@" just passes through arguments as additional positional arguments. -i
diff --git a/run-command.c b/run-command.c index 1b821042b4..36b2b2f194 100644 --- a/run-command.c +++ b/run-command.c @@ -435,6 +435,7 @@ static int prepare_cmd(struct strvec *out, const struct child_process *cmd) } } + trace_argv_printf(&out->v[1], "trace: prepare_cmd:"); return 0; } diff --git a/t/t0014-alias.sh b/t/t0014-alias.sh index 95568342be..75c8763a6c 100755 --- a/t/t0014-alias.sh +++ b/t/t0014-alias.sh @@ -44,4 +44,11 @@ test_expect_success 'run-command formats empty args properly' ' test_cmp expect actual ' +test_expect_success 'tracing a shell alias with arguments shows full prepared command' ' + git config alias.echo "!echo \$*" && + env GIT_TRACE=1 git echo argument 2>output && + cp output /tmp/output && + test_grep "^trace: prepare_cmd: /bin/sh -c '\''echo \$\* \"\$@\"" output +' + test_done
This adds a trace point in prepare_cmd, so we can see the actual command being run without having to resort to strace/code inspection. e.g. "test = !echo" when run under GIT_TRACE will show: $ GIT_TRACE=1 git test hello 10:58:56.877234 git.c:755 trace: exec: git-test hello 10:58:56.877382 run-command.c:657 trace: run_command: git-test hello 10:58:56.878655 run-command.c:657 trace: run_command: echo hello 10:58:56.878747 run-command.c:437 trace: prepare_cmd: /usr/bin/echo hello hello A "split" alias, e.g. test = "!echo $*" will show the shell wrapping and appending of "$@". $ GIT_TRACE=1 git test hello 11:00:45.959420 git.c:755 trace: exec: git-test hello 11:00:45.959737 run-command.c:657 trace: run_command: git-test hello 11:00:45.961424 run-command.c:657 trace: run_command: 'echo $*' hello 11:00:45.961528 run-command.c:437 trace: prepare_cmd: /bin/sh -c 'echo $* "$@"' 'echo $*' hello hello hello For example, this can be very helpful when an alias is giving you an unexpected syntax error that is very difficult figure out from only the run_command trace point, e.g. test = "!for i in 1 2 3; do echo $i; done" will fail if there is an argument given, we can see why from the output. $ GIT_TRACE=1 test hello 11:02:39.813030 git.c:755 trace: exec: git-test hello 11:02:39.813233 run-command.c:657 trace: run_command: git-test hello 11:02:39.814384 run-command.c:657 trace: run_command: 'for i in 1 2 3; do echo $i; done' hello 11:02:39.814468 run-command.c:437 trace: prepare_cmd: /bin/sh -c 'for i in 1 2 3; do echo $i; done "$@"' 'for i in 1 2 3; do echo $i; done' hello for i in 1 2 3; do echo $i; done: -c: line 1: syntax error near unexpected token `"$@"' for i in 1 2 3; do echo $i; done: -c: line 1: `for i in 1 2 3; do echo $i; done "$@"' A test case is added. Signed-off-by: Ian Wienand <iwienand@redhat.com> --- run-command.c | 1 + t/t0014-alias.sh | 7 +++++++ 2 files changed, 8 insertions(+)