[PATCH] trace2: intercept all common signals

[PATCH] trace2: intercept all common signals

[Emily Shaffer]

From: Emily Shaffer <nasamuffin@google.com>

We already use trace2 to find out about unexpected pipe breakages, which
is nice for detecting bugs or system problems, by adding a handler for
SIGPIPE which simply writes a trace2 line. However, there are a handful
of other common signals which we might want to snoop on:

 - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in
   frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)
 - SIGHUP, when the network closes unexpectedly (indicating there may be
   a problem to solve)

There are lots more signals which we might find useful later, but at
least let's teach trace2 to report these egregious ones. Conveniently,
they're also already covered by the `_common` variants in sigchain.[ch].

Sigchain itself is already tested via helper/test-sigchain.c, and trace2
is tested in a number of places - let's also add tests demonstrating
that sigchain + trace2 works correctly.

Signed-off-by: Emily Shaffer <nasamuffin@google.com>
---
 t/helper/test-trace2.c   | 17 +++++++++++++++++
 t/t0210-trace2-normal.sh | 22 ++++++++++++++++++++++
 trace2.c                 |  2 +-
 3 files changed, 40 insertions(+), 1 deletion(-)

diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c
index 1adac29a57..8970956ea8 100644
--- a/t/helper/test-trace2.c
+++ b/t/helper/test-trace2.c
@@ -231,6 +231,22 @@ static int ut_010bug_BUG(int argc UNUSED, const char **argv UNUSED)
 	BUG("a %s message", "BUG");
 }
 
+static int ut_011signal(int argc, const char **argv)
+{
+	const char *usage_error = "expect <bool common>";
+	int common = 0;
+
+	if (argc != 1 || get_i(&common, argv[0]))
+		die("%s", usage_error);
+
+	/*
+	 * There is no strong reason SIGSEGV is ignored by trace2 - it's just
+	 * not included by sigchain_push_common().
+	 */
+	raise(common ? SIGINT : SIGSEGV);
+	return 0; /*unreachable*/
+}
+
 /*
  * Single-threaded timer test.  Create several intervals using the
  * TEST1 timer.  The test script can verify that an aggregate Trace2
@@ -482,6 +498,7 @@ static struct unit_test ut_table[] = {
 	{ ut_008bug,      "008bug",    "" },
 	{ ut_009bug_BUG,  "009bug_BUG","" },
 	{ ut_010bug_BUG,  "010bug_BUG","" },
+	{ ut_011signal,   "011signal","" },
 
 	{ ut_100timer,    "100timer",  "<count> <ms_delay>" },
 	{ ut_101timer,    "101timer",  "<count> <ms_delay> <threads>" },
diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh
index c312657a12..c34ccc518c 100755
--- a/t/t0210-trace2-normal.sh
+++ b/t/t0210-trace2-normal.sh
@@ -244,6 +244,28 @@ test_expect_success 'bug messages followed by BUG() are written to trace2' '
 	test_cmp expect actual
 '
 
+test_expect_success 'trace2 reports common signals' '
+	test_when_finished "rm trace.normal actual" &&
+
+	# signals are fatal, so expect this to fail
+	! env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 011signal 1 &&
+
+	perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+
+	test_grep "signal elapsed:" actual
+'
+
+test_expect_success 'trace2 ignores uncommon signals' '
+	test_when_finished "rm trace.normal actual" &&
+
+	# signals are fatal, so expect this to fail
+	! env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 011signal 0 &&
+
+	perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+
+	! test_grep "signal elapsed:" actual
+'
+
 sane_unset GIT_TRACE2_BRIEF
 
 # Now test without environment variables and get all Trace2 settings
diff --git a/trace2.c b/trace2.c
index f894532d05..3692010f5d 100644
--- a/trace2.c
+++ b/trace2.c
@@ -231,7 +231,7 @@ void trace2_initialize_fl(const char *file, int line)
 	tr2_sid_get();
 
 	atexit(tr2main_atexit_handler);
-	sigchain_push(SIGPIPE, tr2main_signal_handler);
+	sigchain_push_common(tr2main_signal_handler);
 	tr2tls_init();
 
 	/*
-- 
2.45.0.118.g7fe29c98d7-goog

Re: [PATCH] trace2: intercept all common signals

[Emily Shaffer]

On Fri, May 10, 2024 at 10:22 AM Emily Shaffer <emilyshaffer@google.com> wrote:
>
> From: Emily Shaffer <nasamuffin@google.com>
>
> We already use trace2 to find out about unexpected pipe breakages, which
> is nice for detecting bugs or system problems, by adding a handler for
> SIGPIPE which simply writes a trace2 line. However, there are a handful
> of other common signals which we might want to snoop on:
>
>  - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in
>    frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)
>  - SIGHUP, when the network closes unexpectedly (indicating there may be
>    a problem to solve)
>
> There are lots more signals which we might find useful later, but at
> least let's teach trace2 to report these egregious ones. Conveniently,
> they're also already covered by the `_common` variants in sigchain.[ch].
>
> Sigchain itself is already tested via helper/test-sigchain.c, and trace2
> is tested in a number of places - let's also add tests demonstrating
> that sigchain + trace2 works correctly.
>
> Signed-off-by: Emily Shaffer <nasamuffin@google.com>
> ---

Missed including the CI results. They're passing[1] with the exception
of the osx-gcc run, which seems to also be failing on the latest
'master'[2] and looks to be failing in setup rather than in test run.

1: https://github.com/nasamuffin/git/actions/runs/9035666915
2: https://github.com/nasamuffin/git/actions/runs/9036080205/job/24832209129

>  t/helper/test-trace2.c   | 17 +++++++++++++++++
>  t/t0210-trace2-normal.sh | 22 ++++++++++++++++++++++
>  trace2.c                 |  2 +-
>  3 files changed, 40 insertions(+), 1 deletion(-)
>
> diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c
> index 1adac29a57..8970956ea8 100644
> --- a/t/helper/test-trace2.c
> +++ b/t/helper/test-trace2.c
> @@ -231,6 +231,22 @@ static int ut_010bug_BUG(int argc UNUSED, const char **argv UNUSED)
>         BUG("a %s message", "BUG");
>  }
>
> +static int ut_011signal(int argc, const char **argv)
> +{
> +       const char *usage_error = "expect <bool common>";
> +       int common = 0;
> +
> +       if (argc != 1 || get_i(&common, argv[0]))
> +               die("%s", usage_error);
> +
> +       /*
> +        * There is no strong reason SIGSEGV is ignored by trace2 - it's just
> +        * not included by sigchain_push_common().
> +        */
> +       raise(common ? SIGINT : SIGSEGV);
> +       return 0; /*unreachable*/
> +}
> +
>  /*
>   * Single-threaded timer test.  Create several intervals using the
>   * TEST1 timer.  The test script can verify that an aggregate Trace2
> @@ -482,6 +498,7 @@ static struct unit_test ut_table[] = {
>         { ut_008bug,      "008bug",    "" },
>         { ut_009bug_BUG,  "009bug_BUG","" },
>         { ut_010bug_BUG,  "010bug_BUG","" },
> +       { ut_011signal,   "011signal","" },
>
>         { ut_100timer,    "100timer",  "<count> <ms_delay>" },
>         { ut_101timer,    "101timer",  "<count> <ms_delay> <threads>" },
> diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh
> index c312657a12..c34ccc518c 100755
> --- a/t/t0210-trace2-normal.sh
> +++ b/t/t0210-trace2-normal.sh
> @@ -244,6 +244,28 @@ test_expect_success 'bug messages followed by BUG() are written to trace2' '
>         test_cmp expect actual
>  '
>
> +test_expect_success 'trace2 reports common signals' '
> +       test_when_finished "rm trace.normal actual" &&
> +
> +       # signals are fatal, so expect this to fail
> +       ! env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 011signal 1 &&
> +
> +       perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
> +
> +       test_grep "signal elapsed:" actual
> +'
> +
> +test_expect_success 'trace2 ignores uncommon signals' '
> +       test_when_finished "rm trace.normal actual" &&
> +
> +       # signals are fatal, so expect this to fail
> +       ! env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 011signal 0 &&
> +
> +       perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
> +
> +       ! test_grep "signal elapsed:" actual
> +'
> +
>  sane_unset GIT_TRACE2_BRIEF
>
>  # Now test without environment variables and get all Trace2 settings
> diff --git a/trace2.c b/trace2.c
> index f894532d05..3692010f5d 100644
> --- a/trace2.c
> +++ b/trace2.c
> @@ -231,7 +231,7 @@ void trace2_initialize_fl(const char *file, int line)
>         tr2_sid_get();
>
>         atexit(tr2main_atexit_handler);
> -       sigchain_push(SIGPIPE, tr2main_signal_handler);
> +       sigchain_push_common(tr2main_signal_handler);
>         tr2tls_init();
>
>         /*
> --
> 2.45.0.118.g7fe29c98d7-goog
>

Re: [PATCH] trace2: intercept all common signals

[Junio C Hamano]

Emily Shaffer <emilyshaffer@google.com> writes:

> From: Emily Shaffer <nasamuffin@google.com>
>
> We already use trace2 to find out about unexpected pipe breakages, which
> is nice for detecting bugs or system problems, by adding a handler for
> SIGPIPE which simply writes a trace2 line. However, there are a handful
> of other common signals which we might want to snoop on:
>
>  - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in
>    frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)
>  - SIGHUP, when the network closes unexpectedly (indicating there may be
>    a problem to solve)
>
> There are lots more signals which we might find useful later, but at
> least let's teach trace2 to report these egregious ones. Conveniently,
> they're also already covered by the `_common` variants in sigchain.[ch].
>
> Sigchain itself is already tested via helper/test-sigchain.c, and trace2
> is tested in a number of places - let's also add tests demonstrating
> that sigchain + trace2 works correctly.
>
> Signed-off-by: Emily Shaffer <nasamuffin@google.com>
> ---
>  t/helper/test-trace2.c   | 17 +++++++++++++++++
>  t/t0210-trace2-normal.sh | 22 ++++++++++++++++++++++
>  trace2.c                 |  2 +-
>  3 files changed, 40 insertions(+), 1 deletion(-)
>
> diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c
> index 1adac29a57..8970956ea8 100644
> --- a/t/helper/test-trace2.c
> +++ b/t/helper/test-trace2.c
> @@ -231,6 +231,22 @@ static int ut_010bug_BUG(int argc UNUSED, const char **argv UNUSED)
>  	BUG("a %s message", "BUG");
>  }
>  
> +static int ut_011signal(int argc, const char **argv)
> +{
> +	const char *usage_error = "expect <bool common>";
> +	int common = 0;
> +
> +	if (argc != 1 || get_i(&common, argv[0]))
> +		die("%s", usage_error);
> +
> +	/*
> +	 * There is no strong reason SIGSEGV is ignored by trace2 - it's just
> +	 * not included by sigchain_push_common().
> +	 */
> +	raise(common ? SIGINT : SIGSEGV);
> +	return 0; /*unreachable*/
> +}
> +
>  /*
>   * Single-threaded timer test.  Create several intervals using the
>   * TEST1 timer.  The test script can verify that an aggregate Trace2
> @@ -482,6 +498,7 @@ static struct unit_test ut_table[] = {
>  	{ ut_008bug,      "008bug",    "" },
>  	{ ut_009bug_BUG,  "009bug_BUG","" },
>  	{ ut_010bug_BUG,  "010bug_BUG","" },
> +	{ ut_011signal,   "011signal","" },
>  
>  	{ ut_100timer,    "100timer",  "<count> <ms_delay>" },
>  	{ ut_101timer,    "101timer",  "<count> <ms_delay> <threads>" },
> diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh
> index c312657a12..c34ccc518c 100755
> --- a/t/t0210-trace2-normal.sh
> +++ b/t/t0210-trace2-normal.sh
> @@ -244,6 +244,28 @@ test_expect_success 'bug messages followed by BUG() are written to trace2' '
>  	test_cmp expect actual
>  '
>  
> +test_expect_success 'trace2 reports common signals' '
> +	test_when_finished "rm trace.normal actual" &&
> +
> +	# signals are fatal, so expect this to fail
> +	! env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 011signal 1 &&

Is it deliberate that this does not use test_must_fail or is it an
oversight?  The same comment applies to all other uses of "! env".

We often see the use of "env" in conjunction with a test that is
expected to fail because

    test_must_fail VAR=VAL cmd

simply does not work.  If you are not using test_expect_fail, then

    ! VAR=VAL cmd

should be sufficient, but it would mean that you will be happy even
if the way "cmd" dies is not in a controlled way (e.g. due to
receiving a signal).

Ah, perhaps that is it?  Is "test-tool trace2 011signal 1" raise a
signal to kill itself and after showing the event in the trace
stream it is expected to die the narual death of receiving the same
signal by re-raising it?

If that is what is happening here, not using test_must_fail is
absolutely the right thing to do, but then I doubt you need "env"
there.  Also, if we know what signal is raised, then we should also
know the exit status from this (i.e. signal number plus 128 or
something) that we want to validate?  I dunno.


> diff --git a/trace2.c b/trace2.c
> index f894532d05..3692010f5d 100644
> --- a/trace2.c
> +++ b/trace2.c
> @@ -231,7 +231,7 @@ void trace2_initialize_fl(const char *file, int line)
>  	tr2_sid_get();
>  
>  	atexit(tr2main_atexit_handler);
> -	sigchain_push(SIGPIPE, tr2main_signal_handler);
> +	sigchain_push_common(tr2main_signal_handler);
>  	tr2tls_init();
>  
>  	/*

Re: [PATCH] trace2: intercept all common signals

[Emily Shaffer]

On Fri, May 10, 2024 at 11:47 AM Junio C Hamano <gitster@pobox.com> wrote:
>
> Emily Shaffer <emilyshaffer@google.com> writes:
>
> > From: Emily Shaffer <nasamuffin@google.com>
> >
> > We already use trace2 to find out about unexpected pipe breakages, which
> > is nice for detecting bugs or system problems, by adding a handler for
> > SIGPIPE which simply writes a trace2 line. However, there are a handful
> > of other common signals which we might want to snoop on:
> >
> >  - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in
> >    frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)
> >  - SIGHUP, when the network closes unexpectedly (indicating there may be
> >    a problem to solve)
> >
> > There are lots more signals which we might find useful later, but at
> > least let's teach trace2 to report these egregious ones. Conveniently,
> > they're also already covered by the `_common` variants in sigchain.[ch].
> >
> > Sigchain itself is already tested via helper/test-sigchain.c, and trace2
> > is tested in a number of places - let's also add tests demonstrating
> > that sigchain + trace2 works correctly.
> >
> > Signed-off-by: Emily Shaffer <nasamuffin@google.com>
> > ---
> >  t/helper/test-trace2.c   | 17 +++++++++++++++++
> >  t/t0210-trace2-normal.sh | 22 ++++++++++++++++++++++
> >  trace2.c                 |  2 +-
> >  3 files changed, 40 insertions(+), 1 deletion(-)
> >
> > diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c
> > index 1adac29a57..8970956ea8 100644
> > --- a/t/helper/test-trace2.c
> > +++ b/t/helper/test-trace2.c
> > @@ -231,6 +231,22 @@ static int ut_010bug_BUG(int argc UNUSED, const char **argv UNUSED)
> >       BUG("a %s message", "BUG");
> >  }
> >
> > +static int ut_011signal(int argc, const char **argv)
> > +{
> > +     const char *usage_error = "expect <bool common>";
> > +     int common = 0;
> > +
> > +     if (argc != 1 || get_i(&common, argv[0]))
> > +             die("%s", usage_error);
> > +
> > +     /*
> > +      * There is no strong reason SIGSEGV is ignored by trace2 - it's just
> > +      * not included by sigchain_push_common().
> > +      */
> > +     raise(common ? SIGINT : SIGSEGV);
> > +     return 0; /*unreachable*/
> > +}
> > +
> >  /*
> >   * Single-threaded timer test.  Create several intervals using the
> >   * TEST1 timer.  The test script can verify that an aggregate Trace2
> > @@ -482,6 +498,7 @@ static struct unit_test ut_table[] = {
> >       { ut_008bug,      "008bug",    "" },
> >       { ut_009bug_BUG,  "009bug_BUG","" },
> >       { ut_010bug_BUG,  "010bug_BUG","" },
> > +     { ut_011signal,   "011signal","" },
> >
> >       { ut_100timer,    "100timer",  "<count> <ms_delay>" },
> >       { ut_101timer,    "101timer",  "<count> <ms_delay> <threads>" },
> > diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh
> > index c312657a12..c34ccc518c 100755
> > --- a/t/t0210-trace2-normal.sh
> > +++ b/t/t0210-trace2-normal.sh
> > @@ -244,6 +244,28 @@ test_expect_success 'bug messages followed by BUG() are written to trace2' '
> >       test_cmp expect actual
> >  '
> >
> > +test_expect_success 'trace2 reports common signals' '
> > +     test_when_finished "rm trace.normal actual" &&
> > +
> > +     # signals are fatal, so expect this to fail
> > +     ! env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 011signal 1 &&
>
> Is it deliberate that this does not use test_must_fail or is it an
> oversight?  The same comment applies to all other uses of "! env".
>
> We often see the use of "env" in conjunction with a test that is
> expected to fail because
>
>     test_must_fail VAR=VAL cmd
>
> simply does not work.  If you are not using test_expect_fail, then
>
>     ! VAR=VAL cmd
>
> should be sufficient, but it would mean that you will be happy even
> if the way "cmd" dies is not in a controlled way (e.g. due to
> receiving a signal).
>
> Ah, perhaps that is it?  Is "test-tool trace2 011signal 1" raise a
> signal to kill itself and after showing the event in the trace
> stream it is expected to die the narual death of receiving the same
> signal by re-raising it?

Yes, it is because test_must_fail expects "natural" death. You can
tell test_must_fail which signal you'd expect to receive, in theory,
but I didn't get it to work (and it will be tricky to provide the
correct signal in shell - I had originally hardcoded signal ints in
sh, but then moved the signal enum->int resolution into
helper/test-trace2.c because the alternative is doing some nasty
grepping on other shell utility outputs, since the signal codes aren't
platform/arch consistent).

Anyway, I will try it without `env`.

>
> If that is what is happening here, not using test_must_fail is
> absolutely the right thing to do, but then I doubt you need "env"
> there.  Also, if we know what signal is raised, then we should also
> know the exit status from this (i.e. signal number plus 128 or
> something) that we want to validate?  I dunno.

We could? But I don't feel strongly about it. If I specify the exit
status, the test will be brittle if we change the exit codes later
(for example, 128 or -1 for all error exits is kind of an antipattern;
it might be nice to ask Git to return meaningful error codes depending
on what went wrong, in the future). We are already checking later on
during the test_grep that we exited due to a fatal signal.

Thanks for the feedback - I'll get going on a v2 and aim to send it
later today, since I don't hear you saying that the patch's overall
goal is objectionable.

While I'm at it, since you pointed out ! instead of test_must_fail, I
wondered if I should change "! test_grep" as well - but when I grep t/
it looks like it's not usual to use `test_must_fail test_grep`, but
instead to use `test_grep ! <omitted pattern> <file>`. I'll change
that too.

I also wonder - do we want to capture SIGKILL as well? Some people may
have muscle memory for `kill -9` (I do, for better or worse) instead
of gentler `kill`. My intent was to notice any indication of user
frustration resulting in manual termination, which would include `kill
-9` too...

 - Emily

Re: [PATCH] trace2: intercept all common signals

[Jeff King]

On Fri, May 10, 2024 at 12:34:07PM -0700, Emily Shaffer wrote:

> Yes, it is because test_must_fail expects "natural" death. You can
> tell test_must_fail which signal you'd expect to receive, in theory,
> but I didn't get it to work (and it will be tricky to provide the
> correct signal in shell - I had originally hardcoded signal ints in
> sh, but then moved the signal enum->int resolution into
> helper/test-trace2.c because the alternative is doing some nasty
> grepping on other shell utility outputs, since the signal codes aren't
> platform/arch consistent).

We have test_match_signal(). Unfortunately it's not integrated with
test_expect_code(), so you have to do:

  { thing_which_fails; OUT=$?; } &&
  test_match_signal 15 "$OUT"

See 5263e22cba (t7006: simplify exit-code checks for sigpipe tests,
2021-11-21) for an example.

> I also wonder - do we want to capture SIGKILL as well? Some people may
> have muscle memory for `kill -9` (I do, for better or worse) instead
> of gentler `kill`. My intent was to notice any indication of user
> frustration resulting in manual termination, which would include `kill
> -9` too...

You can't catch SIGKILL; its whole purpose is to be un-catchable.

-Peff

Re: [PATCH] trace2: intercept all common signals

[Emily Shaffer]

On Fri, May 10, 2024 at 12:46 PM Jeff King <peff@peff.net> wrote:
>
> On Fri, May 10, 2024 at 12:34:07PM -0700, Emily Shaffer wrote:
>
> > Yes, it is because test_must_fail expects "natural" death. You can
> > tell test_must_fail which signal you'd expect to receive, in theory,
> > but I didn't get it to work (and it will be tricky to provide the
> > correct signal in shell - I had originally hardcoded signal ints in
> > sh, but then moved the signal enum->int resolution into
> > helper/test-trace2.c because the alternative is doing some nasty
> > grepping on other shell utility outputs, since the signal codes aren't
> > platform/arch consistent).
>
> We have test_match_signal(). Unfortunately it's not integrated with
> test_expect_code(), so you have to do:
>
>   { thing_which_fails; OUT=$?; } &&
>   test_match_signal 15 "$OUT"

Right, what I meant above is that `15` isn't portable, I'd have to get
the correct int value of SIGINT/SIGSEGV from some other shell utility
at test time.

>
> See 5263e22cba (t7006: simplify exit-code checks for sigpipe tests,
> 2021-11-21) for an example.
>
> > I also wonder - do we want to capture SIGKILL as well? Some people may
> > have muscle memory for `kill -9` (I do, for better or worse) instead
> > of gentler `kill`. My intent was to notice any indication of user
> > frustration resulting in manual termination, which would include `kill
> > -9` too...
>
> You can't catch SIGKILL; its whole purpose is to be un-catchable.

Duh :') Thanks.

>
> -Peff

Re: [PATCH] trace2: intercept all common signals

[Jeff King]

On Fri, May 10, 2024 at 12:49:06PM -0700, Emily Shaffer wrote:

> > We have test_match_signal(). Unfortunately it's not integrated with
> > test_expect_code(), so you have to do:
> >
> >   { thing_which_fails; OUT=$?; } &&
> >   test_match_signal 15 "$OUT"
> 
> Right, what I meant above is that `15` isn't portable, I'd have to get
> the correct int value of SIGINT/SIGSEGV from some other shell utility
> at test time.

Yes, but we already rely on it elsewhere (like t0005), and the idea of
test_match_signal is that it would convert from "standard" numbers to
something platform specific. Though aside from Windows (where the signal
number is sometimes lost entirely) we've never had to actually do such
conversion so far; "15" really is standard.

If your primary concern, though, is the trace2 output and not the exit
code of the program, then it may not be worth worrying too much about.

-Peff

Re: [PATCH] trace2: intercept all common signals

[Junio C Hamano]

Emily Shaffer <nasamuffin@google.com> writes:

> While I'm at it, since you pointed out ! instead of test_must_fail, I
> wondered if I should change "! test_grep" as well - but when I grep t/
> it looks like it's not usual to use `test_must_fail test_grep`, but
> instead to use `test_grep ! <omitted pattern> <file>`. I'll change
> that too.

"! test_grep" is an anti-pattern.  We should have a documentation
somewhere in t/README or nearby (if we don't, somebody please add
one).

The point of test_grep is "when we expect to see hits, we do show
them to the standard output even if we just used a bare 'grep', but
when such a test fails, we can easily miss the failure, because the
failure is signalled only by $? and no output---hence, test_grep
helper loudly says that we expected to find something but we did not
see any".  Using "! test_grep" will make "! grep" louder in a wrong
case.  That is the whole reason why "test_grep !" exists.

> I also wonder - do we want to capture SIGKILL as well?

An eternally interesting question is "How would you catch an
uncatchable signal?" ;-)

Re: [PATCH] trace2: intercept all common signals

[Jeff King]

On Fri, May 10, 2024 at 01:34:42PM -0700, Junio C Hamano wrote:

> Emily Shaffer <nasamuffin@google.com> writes:
> 
> > While I'm at it, since you pointed out ! instead of test_must_fail, I
> > wondered if I should change "! test_grep" as well - but when I grep t/
> > it looks like it's not usual to use `test_must_fail test_grep`, but
> > instead to use `test_grep ! <omitted pattern> <file>`. I'll change
> > that too.
> 
> "! test_grep" is an anti-pattern.  We should have a documentation
> somewhere in t/README or nearby (if we don't, somebody please add
> one).

Better than documentation, maybe something like:

diff --git a/t/check-non-portable-shell.pl b/t/check-non-portable-shell.pl
index b2b28c2ced..7de2c30aa0 100755
--- a/t/check-non-portable-shell.pl
+++ b/t/check-non-portable-shell.pl
@@ -51,6 +51,7 @@ sub err {
 		err q(quote "$val" in 'local var=$val');
 	/^\s*([A-Z0-9_]+=(\w*|(["']).*?\3)\s+)+(\w+)/ and exists($func{$4}) and
 		err '"FOO=bar shell_func" assignment extends beyond "shell_func"';
+	/! test_grep/ and err 'do not invert test_* functions';
 	$line = '';
 	# this resets our $. for each file
 	close ARGV if eof;

There's at least one other case already. If you shorten it to just "!
test_" to catch more functions, you can see there are a lot of wrong
test_cmp invocations, too (maybe not quite as bad because we don't
produce a specific message, but we'd yield a confusing diff output).

But I think we can't cover everything; there are some like
test_have_prereq which obviously are invertible.

-Peff

Re: [PATCH] trace2: intercept all common signals

[Jeff King]

On Fri, May 10, 2024 at 10:22:43AM -0700, Emily Shaffer wrote:

> From: Emily Shaffer <nasamuffin@google.com>
> 
> We already use trace2 to find out about unexpected pipe breakages, which
> is nice for detecting bugs or system problems, by adding a handler for
> SIGPIPE which simply writes a trace2 line. However, there are a handful
> of other common signals which we might want to snoop on:
> 
>  - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in
>    frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)
>  - SIGHUP, when the network closes unexpectedly (indicating there may be
>    a problem to solve)
> 
> There are lots more signals which we might find useful later, but at
> least let's teach trace2 to report these egregious ones. Conveniently,
> they're also already covered by the `_common` variants in sigchain.[ch].

I think this would be a useful thing to have, but having looked at the
trace2 signal code, this is almost certain to cause racy deadlocks.

The exact details depend on the specific trace2 target backend, but
looking at the various fn_signal() methods, they rely on allocations via
strbufs. This is a problem in signal handlers because we can get a
signal at any time, including when other code is inside malloc() holding
a lock. And then further calls to malloc() will block forever on that
lock.

We should be able to do a quick experiment. Try this snippet, which
repeatedly kills "git log -p" (which is likely to be allocating memory)
and waits for it to exit. Eventually each invocation will stall on a
deadlock:

-- >8 --
doit() {
	me=$1
	i=0
	while true; do
		GIT_TRACE2=1 ./git log -p >/dev/null 2>&1 &
		sleep 0.1
		kill $!
		wait $! 2>/dev/null
		i=$((i+1))
		echo $me:$i
	done
}

for i in $(seq 1 64); do
	doit $i &
done
-- >8 --

I didn't have the patience to wait for all of them to stall, but if you
let it run for a bit and check "ps", you'll see some git processes which
are hanging. Stracing shows them stuck on a lock, like:

  $ strace -p 1838693
  strace: Process 1838693 attached
  futex(0x7facf02df3e0, FUTEX_WAIT_PRIVATE, 2, NULL^Cstrace: Process 1838693 detached
   <detached ...>

This problem existed before your patch. I imagine it was much less
likely (or perhaps even impossible) with SIGPIPE though, because we'd
see that signal only when in a write() syscall, which implies we're not
in malloc(). Whereas we can get SIGTERM, etc, any time.

Obviously the script above is meant to exacerbate the situation, and
most runs would be fine. But over the course of normal use across many
users and many runs, I think we would see this in practice. I think your
test won't because it triggers the signal only from raise().

So I think before doing this, we'd need to clean up the trace2 signal
code to avoid any allocations.

-Peff

Re: [PATCH] trace2: intercept all common signals

[Emily Shaffer]

On Fri, May 10, 2024 at 12:41 PM Jeff King <peff@peff.net> wrote:
>
> On Fri, May 10, 2024 at 10:22:43AM -0700, Emily Shaffer wrote:
>
> > From: Emily Shaffer <nasamuffin@google.com>
> >
> > We already use trace2 to find out about unexpected pipe breakages, which
> > is nice for detecting bugs or system problems, by adding a handler for
> > SIGPIPE which simply writes a trace2 line. However, there are a handful
> > of other common signals which we might want to snoop on:
> >
> >  - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in
> >    frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)
> >  - SIGHUP, when the network closes unexpectedly (indicating there may be
> >    a problem to solve)
> >
> > There are lots more signals which we might find useful later, but at
> > least let's teach trace2 to report these egregious ones. Conveniently,
> > they're also already covered by the `_common` variants in sigchain.[ch].
>
> I think this would be a useful thing to have, but having looked at the
> trace2 signal code, this is almost certain to cause racy deadlocks.
>
> The exact details depend on the specific trace2 target backend, but
> looking at the various fn_signal() methods, they rely on allocations via
> strbufs. This is a problem in signal handlers because we can get a
> signal at any time, including when other code is inside malloc() holding
> a lock. And then further calls to malloc() will block forever on that
> lock.
>
> We should be able to do a quick experiment. Try this snippet, which
> repeatedly kills "git log -p" (which is likely to be allocating memory)
> and waits for it to exit. Eventually each invocation will stall on a
> deadlock:
>
> -- >8 --
> doit() {
>         me=$1
>         i=0
>         while true; do
>                 GIT_TRACE2=1 ./git log -p >/dev/null 2>&1 &
>                 sleep 0.1
>                 kill $!
>                 wait $! 2>/dev/null
>                 i=$((i+1))
>                 echo $me:$i
>         done
> }
>
> for i in $(seq 1 64); do
>         doit $i &
> done
> -- >8 --
>
> I didn't have the patience to wait for all of them to stall, but if you
> let it run for a bit and check "ps", you'll see some git processes which
> are hanging. Stracing shows them stuck on a lock, like:
>
>   $ strace -p 1838693
>   strace: Process 1838693 attached
>   futex(0x7facf02df3e0, FUTEX_WAIT_PRIVATE, 2, NULL^Cstrace: Process 1838693 detached
>    <detached ...>
>
> This problem existed before your patch. I imagine it was much less
> likely (or perhaps even impossible) with SIGPIPE though, because we'd
> see that signal only when in a write() syscall, which implies we're not
> in malloc(). Whereas we can get SIGTERM, etc, any time.
>
> Obviously the script above is meant to exacerbate the situation, and
> most runs would be fine. But over the course of normal use across many
> users and many runs, I think we would see this in practice. I think your
> test won't because it triggers the signal only from raise().
>
> So I think before doing this, we'd need to clean up the trace2 signal
> code to avoid any allocations.

I started to look into doing this, and it's actually really tricky.
I've got a sample diff here
(https://github.com/git/git/commit/bf8a5084ede2b9c476e0cf90b7f198c52573fba7);
I'll need to do it for the other two trace formats as well. But, the
entire trace2 library relies heavily on strbuf, which doesn't have a
stack-allocated form. I'm also not sure how we can guarantee the
no-alloc-ness of these - maybe there's some flag we can give to one of
the analyzers or something? - so I'm worried about backsliding in the
future.

Anyway, I won't have time to work on these again until the end of next
week. If this looks like a reasonable direction I'll pick it up again
then; otherwise, maybe it makes sense for the fn_signal() dispatcher
to just time out if the handler process doesn't terminate in, say, 1s?

 - Emily

>
> -Peff

Re: [PATCH] trace2: intercept all common signals

[Jeff King]

On Mon, May 13, 2024 at 09:21:54AM -0700, Emily Shaffer wrote:

> I started to look into doing this, and it's actually really tricky.
> I've got a sample diff here
> (https://github.com/git/git/commit/bf8a5084ede2b9c476e0cf90b7f198c52573fba7);
> I'll need to do it for the other two trace formats as well. But, the
> entire trace2 library relies heavily on strbuf, which doesn't have a
> stack-allocated form. I'm also not sure how we can guarantee the
> no-alloc-ness of these - maybe there's some flag we can give to one of
> the analyzers or something? - so I'm worried about backsliding in the
> future.

Looking briefly over that patch, a few thoughts:

  - rather than try to make the generic trace2 printing functions handle
    both the alloc and fixed-buffer cases, if the signal handlers only
    need a limited set of functions, it might be easier to just let them
    live in a totally parallel universe. For the simple printing case
    that's not too much extra code, and then the complications are
    limited to the signal-handling functions themselves. It's a bit more
    tricky with json, but we might be able to get away with just
    hand-forming it into a buffer, given the relative simplicity of it.

    In some cases you might need to precompute and stash buffers ahead
    of time that could be used by the signal handler (e.g., the whole
    tr2_sid thing).

  - the opposite approach might be: stop using any allocating functions
    in the trace2 code. There's a certain simplicity there, even for
    non-signal functions, that we know we're just touching a few
    fixed-size buffers, and you can never create a weird DoS by tweaking
    the tracing code. But it would mean rewriting a lot of it (including
    json formatting stuff) without many of our usual strbuf niceties.

    This is more or less the approach we take with error(), die(), etc,
    which are built on vreportf() and its fixed buffer.

  - you probably don't want to use xsnprintf(). That function is for
    cases where it's a bug to truncate, and we're just asserting that
    everything fit as expected. For your purposes, you probably want
    regular snprintf(). Again, see vreportf().

I don't think there's an easy static analysis solution here. It's more
than just allocation, too. Anything that holds a lock is a potential
problem (e.g., stdio streams), and likewise anything that looks at
global state that might be in the middle of being mutated.

So overall it is a pretty thorny problem, and for the most part we've
just tried to keep what we do inside signal handlers to a minimum
(usually cleanup, but even there we have to be careful not to do things
like build up allocated paths for recursive removal).

> Anyway, I won't have time to work on these again until the end of next
> week. If this looks like a reasonable direction I'll pick it up again
> then; otherwise, maybe it makes sense for the fn_signal() dispatcher
> to just time out if the handler process doesn't terminate in, say, 1s?

The timeout would help with locks, but not other weird logic bugs you
can get into. Fundamentally you really want to do as little as possible
from a signal handler.

-Peff

Re: [PATCH] trace2: intercept all common signals

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

>   - the opposite approach might be: stop using any allocating functions
>     in the trace2 code. There's a certain simplicity there, even for
>     non-signal functions, that we know we're just touching a few
>     fixed-size buffers, and you can never create a weird DoS by tweaking
>     the tracing code. But it would mean rewriting a lot of it (including
>     json formatting stuff) without many of our usual strbuf niceties.
>
>     This is more or less the approach we take with error(), die(), etc,
>     which are built on vreportf() and its fixed buffer.

Would another approach be to add various trace2 functions that use
strbuf() allocation a way to tell if they are called from a signal
handing codepath, and punt (by doing nothing if needed, but
hopefully we have enough slop in the buffer to say "hey we got
interrupted so no more detailed report for you, sorry") if that is
the case?

> So overall it is a pretty thorny problem, and for the most part we've
> just tried to keep what we do inside signal handlers to a minimum
> (usually cleanup, but even there we have to be careful not to do things
> like build up allocated paths for recursive removal).

Yes, I agree that it is the right approach to do very little in a
signal handler.

Re: [PATCH] trace2: intercept all common signals

[Jeff King]

On Thu, May 16, 2024 at 09:32:36AM -0700, Junio C Hamano wrote:

> Jeff King <peff@peff.net> writes:
> 
> >   - the opposite approach might be: stop using any allocating functions
> >     in the trace2 code. There's a certain simplicity there, even for
> >     non-signal functions, that we know we're just touching a few
> >     fixed-size buffers, and you can never create a weird DoS by tweaking
> >     the tracing code. But it would mean rewriting a lot of it (including
> >     json formatting stuff) without many of our usual strbuf niceties.
> >
> >     This is more or less the approach we take with error(), die(), etc,
> >     which are built on vreportf() and its fixed buffer.
> 
> Would another approach be to add various trace2 functions that use
> strbuf() allocation a way to tell if they are called from a signal
> handing codepath, and punt (by doing nothing if needed, but
> hopefully we have enough slop in the buffer to say "hey we got
> interrupted so no more detailed report for you, sorry") if that is
> the case?

We do use that "in_signal" flag in other handlers. E.g., when
run-command avoids calling free() in a signal, and the tempfile code
avoids using stdio. But in the case of these trace functions, I think
they'd all need to be rewritten to avoid strbufs. That message
formatting is the whole point, and there is no way to have a strbuf
which truncates rather than growing (though it is something we've
discussed).

So I think we either need to rip strbufs out of most of trace2, or let
these signal paths re-implement the formatting in a super-simple way.

-Peff