{"thread":{"id":"61453","subject":"[PATCH] trace2: intercept all common signals","startedAt":"2024-05-10T17:22:49Z","lastAt":"2024-05-23T09:36:45Z","messageCount":14,"participants":["Emily Shaffer","Junio C Hamano","Jeff King"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"494482","messageId":"20240510172243.3529851-1-emilyshaffer@google.com","threadId":"61453","inReplyTo":null,"subject":"[PATCH] trace2: intercept all common signals","fromName":"Emily Shaffer","fromEmail":"emilyshaffer@google.com","sentAt":"2024-05-10T17:22:43Z","receivedAt":"2024-05-10T17:22:49Z","isPatch":true,"sender":{"key":"nasamuffin@google.com","avatar":"https://avatars.githubusercontent.com/u/1606826?v=4"},"body":"From: Emily Shaffer \n\nWe already use trace2 to find out about unexpected pipe breakages, which\nis nice for detecting bugs or system problems, by adding a handler for\nSIGPIPE which simply writes a trace2 line. However, there are a handful\nof other common signals which we might want to snoop on:\n\n - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in\n frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)\n - SIGHUP, when the network closes unexpectedly (indicating there may be\n a problem to solve)\n\nThere are lots more signals which we might find useful later, but at\nleast let's teach trace2 to report these egregious ones. Conveniently,\nthey're also already covered by the `_common` variants in sigchain.[ch].\n\nSigchain itself is already tested via helper/test-sigchain.c, and trace2\nis tested in a number of places - let's also add tests demonstrating\nthat sigchain + trace2 works correctly.\n\nSigned-off-by: Emily Shaffer \n---\n t/helper/test-trace2.c | 17 +++++++++++++++++\n t/t0210-trace2-normal.sh | 22 ++++++++++++++++++++++\n trace2.c | 2 +-\n 3 files changed, 40 insertions(+), 1 deletion(-)\n\ndiff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c\nindex 1adac29a57..8970956ea8 100644\n--- a/t/helper/test-trace2.c\n+++ b/t/helper/test-trace2.c\n@@ -231,6 +231,22 @@ static int ut_010bug_BUG(int argc UNUSED, const char **argv UNUSED)\n \tBUG(\"a %s message\", \"BUG\");\n }\n \n+static int ut_011signal(int argc, const char **argv)\n+{\n+\tconst char *usage_error = \"expect \";\n+\tint common = 0;\n+\n+\tif (argc != 1 || get_i(&common, argv[0]))\n+\t\tdie(\"%s\", usage_error);\n+\n+\t/*\n+\t * There is no strong reason SIGSEGV is ignored by trace2 - it's just\n+\t * not included by sigchain_push_common().\n+\t */\n+\traise(common ? SIGINT : SIGSEGV);\n+\treturn 0; /*unreachable*/\n+}\n+\n /*\n * Single-threaded timer test. Create several intervals using the\n * TEST1 timer. The test script can verify that an aggregate Trace2\n@@ -482,6 +498,7 @@ static struct unit_test ut_table[] = {\n \t{ ut_008bug, \"008bug\", \"\" },\n \t{ ut_009bug_BUG, \"009bug_BUG\",\"\" },\n \t{ ut_010bug_BUG, \"010bug_BUG\",\"\" },\n+\t{ ut_011signal, \"011signal\",\"\" },\n \n \t{ ut_100timer, \"100timer\", \" \" },\n \t{ ut_101timer, \"101timer\", \" \" },\ndiff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh\nindex c312657a12..c34ccc518c 100755\n--- a/t/t0210-trace2-normal.sh\n+++ b/t/t0210-trace2-normal.sh\n@@ -244,6 +244,28 @@ test_expect_success 'bug messages followed by BUG() are written to trace2' '\n \ttest_cmp expect actual\n '\n \n+test_expect_success 'trace2 reports common signals' '\n+\ttest_when_finished \"rm trace.normal actual\" &&\n+\n+\t# signals are fatal, so expect this to fail\n+\t! env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 011signal 1 &&\n+\n+\tperl \"$TEST_DIRECTORY/t0210/scrub_normal.perl\" actual &&\n+\n+\ttest_grep \"signal elapsed:\" actual\n+'\n+\n+test_expect_success 'trace2 ignores uncommon signals' '\n+\ttest_when_finished \"rm trace.normal actual\" &&\n+\n+\t# signals are fatal, so expect this to fail\n+\t! env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 011signal 0 &&\n+\n+\tperl \"$TEST_DIRECTORY/t0210/scrub_normal.perl\" actual &&\n+\n+\t! test_grep \"signal elapsed:\" actual\n+'\n+\n sane_unset GIT_TRACE2_BRIEF\n \n # Now test without environment variables and get all Trace2 settings\ndiff --git a/trace2.c b/trace2.c\nindex f894532d05..3692010f5d 100644\n--- a/trace2.c\n+++ b/trace2.c\n@@ -231,7 +231,7 @@ void trace2_initialize_fl(const char *file, int line)\n \ttr2_sid_get();\n \n \tatexit(tr2main_atexit_handler);\n-\tsigchain_push(SIGPIPE, tr2main_signal_handler);\n+\tsigchain_push_common(tr2main_signal_handler);\n \ttr2tls_init();\n \n \t/*\n-- \n2.45.0.118.g7fe29c98d7-goog\n\n"},{"id":"494484","messageId":"CAJoAoZkkDxhJtXfLx-4++9JuaSr5xJ4Da4_ijVZP05DkLhHDcQ@mail.gmail.com","threadId":"61453","inReplyTo":"20240510172243.3529851-1-emilyshaffer@google.com","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Emily Shaffer","fromEmail":"nasamuffin@google.com","sentAt":"2024-05-10T17:57:33Z","receivedAt":"2024-05-10T17:57:48Z","isPatch":true,"sender":{"key":"nasamuffin@google.com","avatar":"https://avatars.githubusercontent.com/u/1606826?v=4"},"body":"On Fri, May 10, 2024 at 10:22 AM Emily Shaffer wrote:\n>\n> From: Emily Shaffer \n>\n> We already use trace2 to find out about unexpected pipe breakages, which\n> is nice for detecting bugs or system problems, by adding a handler for\n> SIGPIPE which simply writes a trace2 line. However, there are a handful\n> of other common signals which we might want to snoop on:\n>\n> - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in\n> frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)\n> - SIGHUP, when the network closes unexpectedly (indicating there may be\n> a problem to solve)\n>\n> There are lots more signals which we might find useful later, but at\n> least let's teach trace2 to report these egregious ones. Conveniently,\n> they're also already covered by the `_common` variants in sigchain.[ch].\n>\n> Sigchain itself is already tested via helper/test-sigchain.c, and trace2\n> is tested in a number of places - let's also add tests demonstrating\n> that sigchain + trace2 works correctly.\n>\n> Signed-off-by: Emily Shaffer \n> ---\n\nMissed including the CI results. They're passing[1] with the exception\nof the osx-gcc run, which seems to also be failing on the latest\n'master'[2] and looks to be failing in setup rather than in test run.\n\n1: https://github.com/nasamuffin/git/actions/runs/9035666915\n2: https://github.com/nasamuffin/git/actions/runs/9036080205/job/24832209129\n\n> t/helper/test-trace2.c | 17 +++++++++++++++++\n> t/t0210-trace2-normal.sh | 22 ++++++++++++++++++++++\n> trace2.c | 2 +-\n> 3 files changed, 40 insertions(+), 1 deletion(-)\n>\n> diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c\n> index 1adac29a57..8970956ea8 100644\n> --- a/t/helper/test-trace2.c\n> +++ b/t/helper/test-trace2.c\n> @@ -231,6 +231,22 @@ static int ut_010bug_BUG(int argc UNUSED, const char **argv UNUSED)\n> BUG(\"a %s message\", \"BUG\");\n> }\n>\n> +static int ut_011signal(int argc, const char **argv)\n> +{\n> + const char *usage_error = \"expect \";\n> + int common = 0;\n> +\n> + if (argc != 1 || get_i(&common, argv[0]))\n> + die(\"%s\", usage_error);\n> +\n> + /*\n> + * There is no strong reason SIGSEGV is ignored by trace2 - it's just\n> + * not included by sigchain_push_common().\n> + */\n> + raise(common ? SIGINT : SIGSEGV);\n> + return 0; /*unreachable*/\n> +}\n> +\n> /*\n> * Single-threaded timer test. Create several intervals using the\n> * TEST1 timer. The test script can verify that an aggregate Trace2\n> @@ -482,6 +498,7 @@ static struct unit_test ut_table[] = {\n> { ut_008bug, \"008bug\", \"\" },\n> { ut_009bug_BUG, \"009bug_BUG\",\"\" },\n> { ut_010bug_BUG, \"010bug_BUG\",\"\" },\n> + { ut_011signal, \"011signal\",\"\" },\n>\n> { ut_100timer, \"100timer\", \" \" },\n> { ut_101timer, \"101timer\", \" \" },\n> diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh\n> index c312657a12..c34ccc518c 100755\n> --- a/t/t0210-trace2-normal.sh\n> +++ b/t/t0210-trace2-normal.sh\n> @@ -244,6 +244,28 @@ test_expect_success 'bug messages followed by BUG() are written to trace2' '\n> test_cmp expect actual\n> '\n>\n> +test_expect_success 'trace2 reports common signals' '\n> + test_when_finished \"rm trace.normal actual\" &&\n> +\n> + # signals are fatal, so expect this to fail\n> + ! env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 011signal 1 &&\n> +\n> + perl \"$TEST_DIRECTORY/t0210/scrub_normal.perl\" actual &&\n> +\n> + test_grep \"signal elapsed:\" actual\n> +'\n> +\n> +test_expect_success 'trace2 ignores uncommon signals' '\n> + test_when_finished \"rm trace.normal actual\" &&\n> +\n> + # signals are fatal, so expect this to fail\n> + ! env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 011signal 0 &&\n> +\n> + perl \"$TEST_DIRECTORY/t0210/scrub_normal.perl\" actual &&\n> +\n> + ! test_grep \"signal elapsed:\" actual\n> +'\n> +\n> sane_unset GIT_TRACE2_BRIEF\n>\n> # Now test without environment variables and get all Trace2 settings\n> diff --git a/trace2.c b/trace2.c\n> index f894532d05..3692010f5d 100644\n> --- a/trace2.c\n> +++ b/trace2.c\n> @@ -231,7 +231,7 @@ void trace2_initialize_fl(const char *file, int line)\n> tr2_sid_get();\n>\n> atexit(tr2main_atexit_handler);\n> - sigchain_push(SIGPIPE, tr2main_signal_handler);\n> + sigchain_push_common(tr2main_signal_handler);\n> tr2tls_init();\n>\n> /*\n> --\n> 2.45.0.118.g7fe29c98d7-goog\n>\n"},{"id":"494488","messageId":"xmqqv83l4i86.fsf@gitster.g","threadId":"61453","inReplyTo":"20240510172243.3529851-1-emilyshaffer@google.com","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2024-05-10T18:47:21Z","receivedAt":"2024-05-10T18:47:26Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Emily Shaffer writes:\n\n> From: Emily Shaffer \n>\n> We already use trace2 to find out about unexpected pipe breakages, which\n> is nice for detecting bugs or system problems, by adding a handler for\n> SIGPIPE which simply writes a trace2 line. However, there are a handful\n> of other common signals which we might want to snoop on:\n>\n> - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in\n> frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)\n> - SIGHUP, when the network closes unexpectedly (indicating there may be\n> a problem to solve)\n>\n> There are lots more signals which we might find useful later, but at\n> least let's teach trace2 to report these egregious ones. Conveniently,\n> they're also already covered by the `_common` variants in sigchain.[ch].\n>\n> Sigchain itself is already tested via helper/test-sigchain.c, and trace2\n> is tested in a number of places - let's also add tests demonstrating\n> that sigchain + trace2 works correctly.\n>\n> Signed-off-by: Emily Shaffer \n> ---\n> t/helper/test-trace2.c | 17 +++++++++++++++++\n> t/t0210-trace2-normal.sh | 22 ++++++++++++++++++++++\n> trace2.c | 2 +-\n> 3 files changed, 40 insertions(+), 1 deletion(-)\n>\n> diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c\n> index 1adac29a57..8970956ea8 100644\n> --- a/t/helper/test-trace2.c\n> +++ b/t/helper/test-trace2.c\n> @@ -231,6 +231,22 @@ static int ut_010bug_BUG(int argc UNUSED, const char **argv UNUSED)\n> \tBUG(\"a %s message\", \"BUG\");\n> }\n> \n> +static int ut_011signal(int argc, const char **argv)\n> +{\n> +\tconst char *usage_error = \"expect \";\n> +\tint common = 0;\n> +\n> +\tif (argc != 1 || get_i(&common, argv[0]))\n> +\t\tdie(\"%s\", usage_error);\n> +\n> +\t/*\n> +\t * There is no strong reason SIGSEGV is ignored by trace2 - it's just\n> +\t * not included by sigchain_push_common().\n> +\t */\n> +\traise(common ? SIGINT : SIGSEGV);\n> +\treturn 0; /*unreachable*/\n> +}\n> +\n> /*\n> * Single-threaded timer test. Create several intervals using the\n> * TEST1 timer. The test script can verify that an aggregate Trace2\n> @@ -482,6 +498,7 @@ static struct unit_test ut_table[] = {\n> \t{ ut_008bug, \"008bug\", \"\" },\n> \t{ ut_009bug_BUG, \"009bug_BUG\",\"\" },\n> \t{ ut_010bug_BUG, \"010bug_BUG\",\"\" },\n> +\t{ ut_011signal, \"011signal\",\"\" },\n> \n> \t{ ut_100timer, \"100timer\", \" \" },\n> \t{ ut_101timer, \"101timer\", \" \" },\n> diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh\n> index c312657a12..c34ccc518c 100755\n> --- a/t/t0210-trace2-normal.sh\n> +++ b/t/t0210-trace2-normal.sh\n> @@ -244,6 +244,28 @@ test_expect_success 'bug messages followed by BUG() are written to trace2' '\n> \ttest_cmp expect actual\n> '\n> \n> +test_expect_success 'trace2 reports common signals' '\n> +\ttest_when_finished \"rm trace.normal actual\" &&\n> +\n> +\t# signals are fatal, so expect this to fail\n> +\t! env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 011signal 1 &&\n\nIs it deliberate that this does not use test_must_fail or is it an\noversight? The same comment applies to all other uses of \"! env\".\n\nWe often see the use of \"env\" in conjunction with a test that is\nexpected to fail because\n\n test_must_fail VAR=VAL cmd\n\nsimply does not work. If you are not using test_expect_fail, then\n\n ! VAR=VAL cmd\n\nshould be sufficient, but it would mean that you will be happy even\nif the way \"cmd\" dies is not in a controlled way (e.g. due to\nreceiving a signal).\n\nAh, perhaps that is it? Is \"test-tool trace2 011signal 1\" raise a\nsignal to kill itself and after showing the event in the trace\nstream it is expected to die the narual death of receiving the same\nsignal by re-raising it?\n\nIf that is what is happening here, not using test_must_fail is\nabsolutely the right thing to do, but then I doubt you need \"env\"\nthere. Also, if we know what signal is raised, then we should also\nknow the exit status from this (i.e. signal number plus 128 or\nsomething) that we want to validate? I dunno.\n\n\n> diff --git a/trace2.c b/trace2.c\n> index f894532d05..3692010f5d 100644\n> --- a/trace2.c\n> +++ b/trace2.c\n> @@ -231,7 +231,7 @@ void trace2_initialize_fl(const char *file, int line)\n> \ttr2_sid_get();\n> \n> \tatexit(tr2main_atexit_handler);\n> -\tsigchain_push(SIGPIPE, tr2main_signal_handler);\n> +\tsigchain_push_common(tr2main_signal_handler);\n> \ttr2tls_init();\n> \n> \t/*\n"},{"id":"494493","messageId":"CAJoAoZmvzZaLN6cQkH4XeD9-=OwWFjT1adRA1oFHaUVyVWwLXQ@mail.gmail.com","threadId":"61453","inReplyTo":"xmqqv83l4i86.fsf@gitster.g","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Emily Shaffer","fromEmail":"nasamuffin@google.com","sentAt":"2024-05-10T19:34:07Z","receivedAt":"2024-05-10T19:34:24Z","isPatch":true,"sender":{"key":"nasamuffin@google.com","avatar":"https://avatars.githubusercontent.com/u/1606826?v=4"},"body":"On Fri, May 10, 2024 at 11:47 AM Junio C Hamano wrote:\n>\n> Emily Shaffer writes:\n>\n> > From: Emily Shaffer \n> >\n> > We already use trace2 to find out about unexpected pipe breakages, which\n> > is nice for detecting bugs or system problems, by adding a handler for\n> > SIGPIPE which simply writes a trace2 line. However, there are a handful\n> > of other common signals which we might want to snoop on:\n> >\n> > - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in\n> > frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)\n> > - SIGHUP, when the network closes unexpectedly (indicating there may be\n> > a problem to solve)\n> >\n> > There are lots more signals which we might find useful later, but at\n> > least let's teach trace2 to report these egregious ones. Conveniently,\n> > they're also already covered by the `_common` variants in sigchain.[ch].\n> >\n> > Sigchain itself is already tested via helper/test-sigchain.c, and trace2\n> > is tested in a number of places - let's also add tests demonstrating\n> > that sigchain + trace2 works correctly.\n> >\n> > Signed-off-by: Emily Shaffer \n> > ---\n> > t/helper/test-trace2.c | 17 +++++++++++++++++\n> > t/t0210-trace2-normal.sh | 22 ++++++++++++++++++++++\n> > trace2.c | 2 +-\n> > 3 files changed, 40 insertions(+), 1 deletion(-)\n> >\n> > diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c\n> > index 1adac29a57..8970956ea8 100644\n> > --- a/t/helper/test-trace2.c\n> > +++ b/t/helper/test-trace2.c\n> > @@ -231,6 +231,22 @@ static int ut_010bug_BUG(int argc UNUSED, const char **argv UNUSED)\n> > BUG(\"a %s message\", \"BUG\");\n> > }\n> >\n> > +static int ut_011signal(int argc, const char **argv)\n> > +{\n> > + const char *usage_error = \"expect \";\n> > + int common = 0;\n> > +\n> > + if (argc != 1 || get_i(&common, argv[0]))\n> > + die(\"%s\", usage_error);\n> > +\n> > + /*\n> > + * There is no strong reason SIGSEGV is ignored by trace2 - it's just\n> > + * not included by sigchain_push_common().\n> > + */\n> > + raise(common ? SIGINT : SIGSEGV);\n> > + return 0; /*unreachable*/\n> > +}\n> > +\n> > /*\n> > * Single-threaded timer test. Create several intervals using the\n> > * TEST1 timer. The test script can verify that an aggregate Trace2\n> > @@ -482,6 +498,7 @@ static struct unit_test ut_table[] = {\n> > { ut_008bug, \"008bug\", \"\" },\n> > { ut_009bug_BUG, \"009bug_BUG\",\"\" },\n> > { ut_010bug_BUG, \"010bug_BUG\",\"\" },\n> > + { ut_011signal, \"011signal\",\"\" },\n> >\n> > { ut_100timer, \"100timer\", \" \" },\n> > { ut_101timer, \"101timer\", \" \" },\n> > diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh\n> > index c312657a12..c34ccc518c 100755\n> > --- a/t/t0210-trace2-normal.sh\n> > +++ b/t/t0210-trace2-normal.sh\n> > @@ -244,6 +244,28 @@ test_expect_success 'bug messages followed by BUG() are written to trace2' '\n> > test_cmp expect actual\n> > '\n> >\n> > +test_expect_success 'trace2 reports common signals' '\n> > + test_when_finished \"rm trace.normal actual\" &&\n> > +\n> > + # signals are fatal, so expect this to fail\n> > + ! env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 011signal 1 &&\n>\n> Is it deliberate that this does not use test_must_fail or is it an\n> oversight? The same comment applies to all other uses of \"! env\".\n>\n> We often see the use of \"env\" in conjunction with a test that is\n> expected to fail because\n>\n> test_must_fail VAR=VAL cmd\n>\n> simply does not work. If you are not using test_expect_fail, then\n>\n> ! VAR=VAL cmd\n>\n> should be sufficient, but it would mean that you will be happy even\n> if the way \"cmd\" dies is not in a controlled way (e.g. due to\n> receiving a signal).\n>\n> Ah, perhaps that is it? Is \"test-tool trace2 011signal 1\" raise a\n> signal to kill itself and after showing the event in the trace\n> stream it is expected to die the narual death of receiving the same\n> signal by re-raising it?\n\nYes, it is because test_must_fail expects \"natural\" death. You can\ntell test_must_fail which signal you'd expect to receive, in theory,\nbut I didn't get it to work (and it will be tricky to provide the\ncorrect signal in shell - I had originally hardcoded signal ints in\nsh, but then moved the signal enum->int resolution into\nhelper/test-trace2.c because the alternative is doing some nasty\ngrepping on other shell utility outputs, since the signal codes aren't\nplatform/arch consistent).\n\nAnyway, I will try it without `env`.\n\n>\n> If that is what is happening here, not using test_must_fail is\n> absolutely the right thing to do, but then I doubt you need \"env\"\n> there. Also, if we know what signal is raised, then we should also\n> know the exit status from this (i.e. signal number plus 128 or\n> something) that we want to validate? I dunno.\n\nWe could? But I don't feel strongly about it. If I specify the exit\nstatus, the test will be brittle if we change the exit codes later\n(for example, 128 or -1 for all error exits is kind of an antipattern;\nit might be nice to ask Git to return meaningful error codes depending\non what went wrong, in the future). We are already checking later on\nduring the test_grep that we exited due to a fatal signal.\n\nThanks for the feedback - I'll get going on a v2 and aim to send it\nlater today, since I don't hear you saying that the patch's overall\ngoal is objectionable.\n\nWhile I'm at it, since you pointed out ! instead of test_must_fail, I\nwondered if I should change \"! test_grep\" as well - but when I grep t/\nit looks like it's not usual to use `test_must_fail test_grep`, but\ninstead to use `test_grep ! `. I'll change\nthat too.\n\nI also wonder - do we want to capture SIGKILL as well? Some people may\nhave muscle memory for `kill -9` (I do, for better or worse) instead\nof gentler `kill`. My intent was to notice any indication of user\nfrustration resulting in manual termination, which would include `kill\n-9` too...\n\n - Emily\n"},{"id":"494494","messageId":"20240510194118.GA1954863@coredump.intra.peff.net","threadId":"61453","inReplyTo":"20240510172243.3529851-1-emilyshaffer@google.com","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-05-10T19:41:18Z","receivedAt":"2024-05-10T19:41:25Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, May 10, 2024 at 10:22:43AM -0700, Emily Shaffer wrote:\n\n> From: Emily Shaffer \n> \n> We already use trace2 to find out about unexpected pipe breakages, which\n> is nice for detecting bugs or system problems, by adding a handler for\n> SIGPIPE which simply writes a trace2 line. However, there are a handful\n> of other common signals which we might want to snoop on:\n> \n> - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in\n> frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)\n> - SIGHUP, when the network closes unexpectedly (indicating there may be\n> a problem to solve)\n> \n> There are lots more signals which we might find useful later, but at\n> least let's teach trace2 to report these egregious ones. Conveniently,\n> they're also already covered by the `_common` variants in sigchain.[ch].\n\nI think this would be a useful thing to have, but having looked at the\ntrace2 signal code, this is almost certain to cause racy deadlocks.\n\nThe exact details depend on the specific trace2 target backend, but\nlooking at the various fn_signal() methods, they rely on allocations via\nstrbufs. This is a problem in signal handlers because we can get a\nsignal at any time, including when other code is inside malloc() holding\na lock. And then further calls to malloc() will block forever on that\nlock.\n\nWe should be able to do a quick experiment. Try this snippet, which\nrepeatedly kills \"git log -p\" (which is likely to be allocating memory)\nand waits for it to exit. Eventually each invocation will stall on a\ndeadlock:\n\n-- >8 --\ndoit() {\n\tme=$1\n\ti=0\n\twhile true; do\n\t\tGIT_TRACE2=1 ./git log -p >/dev/null 2>&1 &\n\t\tsleep 0.1\n\t\tkill $!\n\t\twait $! 2>/dev/null\n\t\ti=$((i+1))\n\t\techo $me:$i\n\tdone\n}\n\nfor i in $(seq 1 64); do\n\tdoit $i &\ndone\n-- >8 --\n\nI didn't have the patience to wait for all of them to stall, but if you\nlet it run for a bit and check \"ps\", you'll see some git processes which\nare hanging. Stracing shows them stuck on a lock, like:\n\n $ strace -p 1838693\n strace: Process 1838693 attached\n futex(0x7facf02df3e0, FUTEX_WAIT_PRIVATE, 2, NULL^Cstrace: Process 1838693 detached\n \n\nThis problem existed before your patch. I imagine it was much less\nlikely (or perhaps even impossible) with SIGPIPE though, because we'd\nsee that signal only when in a write() syscall, which implies we're not\nin malloc(). Whereas we can get SIGTERM, etc, any time.\n\nObviously the script above is meant to exacerbate the situation, and\nmost runs would be fine. But over the course of normal use across many\nusers and many runs, I think we would see this in practice. I think your\ntest won't because it triggers the signal only from raise().\n\nSo I think before doing this, we'd need to clean up the trace2 signal\ncode to avoid any allocations.\n\n-Peff\n"},{"id":"494495","messageId":"20240510194630.GB1954863@coredump.intra.peff.net","threadId":"61453","inReplyTo":"CAJoAoZmvzZaLN6cQkH4XeD9-=OwWFjT1adRA1oFHaUVyVWwLXQ@mail.gmail.com","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-05-10T19:46:30Z","receivedAt":"2024-05-10T19:46:31Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, May 10, 2024 at 12:34:07PM -0700, Emily Shaffer wrote:\n\n> Yes, it is because test_must_fail expects \"natural\" death. You can\n> tell test_must_fail which signal you'd expect to receive, in theory,\n> but I didn't get it to work (and it will be tricky to provide the\n> correct signal in shell - I had originally hardcoded signal ints in\n> sh, but then moved the signal enum->int resolution into\n> helper/test-trace2.c because the alternative is doing some nasty\n> grepping on other shell utility outputs, since the signal codes aren't\n> platform/arch consistent).\n\nWe have test_match_signal(). Unfortunately it's not integrated with\ntest_expect_code(), so you have to do:\n\n { thing_which_fails; OUT=$?; } &&\n test_match_signal 15 \"$OUT\"\n\nSee 5263e22cba (t7006: simplify exit-code checks for sigpipe tests,\n2021-11-21) for an example.\n\n> I also wonder - do we want to capture SIGKILL as well? Some people may\n> have muscle memory for `kill -9` (I do, for better or worse) instead\n> of gentler `kill`. My intent was to notice any indication of user\n> frustration resulting in manual termination, which would include `kill\n> -9` too...\n\nYou can't catch SIGKILL; its whole purpose is to be un-catchable.\n\n-Peff\n"},{"id":"494496","messageId":"CAJoAoZkXTo69AiowTVFvKyZBCo2B73hPp2ys+oZyOLU5qxAgFw@mail.gmail.com","threadId":"61453","inReplyTo":"20240510194630.GB1954863@coredump.intra.peff.net","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Emily Shaffer","fromEmail":"nasamuffin@google.com","sentAt":"2024-05-10T19:49:06Z","receivedAt":"2024-05-10T19:49:21Z","isPatch":true,"sender":{"key":"nasamuffin@google.com","avatar":"https://avatars.githubusercontent.com/u/1606826?v=4"},"body":"On Fri, May 10, 2024 at 12:46 PM Jeff King wrote:\n>\n> On Fri, May 10, 2024 at 12:34:07PM -0700, Emily Shaffer wrote:\n>\n> > Yes, it is because test_must_fail expects \"natural\" death. You can\n> > tell test_must_fail which signal you'd expect to receive, in theory,\n> > but I didn't get it to work (and it will be tricky to provide the\n> > correct signal in shell - I had originally hardcoded signal ints in\n> > sh, but then moved the signal enum->int resolution into\n> > helper/test-trace2.c because the alternative is doing some nasty\n> > grepping on other shell utility outputs, since the signal codes aren't\n> > platform/arch consistent).\n>\n> We have test_match_signal(). Unfortunately it's not integrated with\n> test_expect_code(), so you have to do:\n>\n> { thing_which_fails; OUT=$?; } &&\n> test_match_signal 15 \"$OUT\"\n\nRight, what I meant above is that `15` isn't portable, I'd have to get\nthe correct int value of SIGINT/SIGSEGV from some other shell utility\nat test time.\n\n>\n> See 5263e22cba (t7006: simplify exit-code checks for sigpipe tests,\n> 2021-11-21) for an example.\n>\n> > I also wonder - do we want to capture SIGKILL as well? Some people may\n> > have muscle memory for `kill -9` (I do, for better or worse) instead\n> > of gentler `kill`. My intent was to notice any indication of user\n> > frustration resulting in manual termination, which would include `kill\n> > -9` too...\n>\n> You can't catch SIGKILL; its whole purpose is to be un-catchable.\n\nDuh :') Thanks.\n\n>\n> -Peff\n"},{"id":"494499","messageId":"20240510200522.GD1954863@coredump.intra.peff.net","threadId":"61453","inReplyTo":"CAJoAoZkXTo69AiowTVFvKyZBCo2B73hPp2ys+oZyOLU5qxAgFw@mail.gmail.com","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-05-10T20:05:22Z","receivedAt":"2024-05-10T20:05:24Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, May 10, 2024 at 12:49:06PM -0700, Emily Shaffer wrote:\n\n> > We have test_match_signal(). Unfortunately it's not integrated with\n> > test_expect_code(), so you have to do:\n> >\n> > { thing_which_fails; OUT=$?; } &&\n> > test_match_signal 15 \"$OUT\"\n> \n> Right, what I meant above is that `15` isn't portable, I'd have to get\n> the correct int value of SIGINT/SIGSEGV from some other shell utility\n> at test time.\n\nYes, but we already rely on it elsewhere (like t0005), and the idea of\ntest_match_signal is that it would convert from \"standard\" numbers to\nsomething platform specific. Though aside from Windows (where the signal\nnumber is sometimes lost entirely) we've never had to actually do such\nconversion so far; \"15\" really is standard.\n\nIf your primary concern, though, is the trace2 output and not the exit\ncode of the program, then it may not be worth worrying too much about.\n\n-Peff\n"},{"id":"494504","messageId":"xmqqle4h4d99.fsf@gitster.g","threadId":"61453","inReplyTo":"CAJoAoZmvzZaLN6cQkH4XeD9-=OwWFjT1adRA1oFHaUVyVWwLXQ@mail.gmail.com","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2024-05-10T20:34:42Z","receivedAt":"2024-05-10T20:34:45Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Emily Shaffer writes:\n\n> While I'm at it, since you pointed out ! instead of test_must_fail, I\n> wondered if I should change \"! test_grep\" as well - but when I grep t/\n> it looks like it's not usual to use `test_must_fail test_grep`, but\n> instead to use `test_grep ! `. I'll change\n> that too.\n\n\"! test_grep\" is an anti-pattern. We should have a documentation\nsomewhere in t/README or nearby (if we don't, somebody please add\none).\n\nThe point of test_grep is \"when we expect to see hits, we do show\nthem to the standard output even if we just used a bare 'grep', but\nwhen such a test fails, we can easily miss the failure, because the\nfailure is signalled only by $? and no output---hence, test_grep\nhelper loudly says that we expected to find something but we did not\nsee any\". Using \"! test_grep\" will make \"! grep\" louder in a wrong\ncase. That is the whole reason why \"test_grep !\" exists.\n\n> I also wonder - do we want to capture SIGKILL as well?\n\nAn eternally interesting question is \"How would you catch an\nuncatchable signal?\" ;-)\n"},{"id":"494523","messageId":"20240510222030.GD1962678@coredump.intra.peff.net","threadId":"61453","inReplyTo":"xmqqle4h4d99.fsf@gitster.g","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-05-10T22:20:30Z","receivedAt":"2024-05-10T22:20:31Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, May 10, 2024 at 01:34:42PM -0700, Junio C Hamano wrote:\n\n> Emily Shaffer writes:\n> \n> > While I'm at it, since you pointed out ! instead of test_must_fail, I\n> > wondered if I should change \"! test_grep\" as well - but when I grep t/\n> > it looks like it's not usual to use `test_must_fail test_grep`, but\n> > instead to use `test_grep ! `. I'll change\n> > that too.\n> \n> \"! test_grep\" is an anti-pattern. We should have a documentation\n> somewhere in t/README or nearby (if we don't, somebody please add\n> one).\n\nBetter than documentation, maybe something like:\n\ndiff --git a/t/check-non-portable-shell.pl b/t/check-non-portable-shell.pl\nindex b2b28c2ced..7de2c30aa0 100755\n--- a/t/check-non-portable-shell.pl\n+++ b/t/check-non-portable-shell.pl\n@@ -51,6 +51,7 @@ sub err {\n \t\terr q(quote \"$val\" in 'local var=$val');\n \t/^\\s*([A-Z0-9_]+=(\\w*|([\"']).*?\\3)\\s+)+(\\w+)/ and exists($func{$4}) and\n \t\terr '\"FOO=bar shell_func\" assignment extends beyond \"shell_func\"';\n+\t/! test_grep/ and err 'do not invert test_* functions';\n \t$line = '';\n \t# this resets our $. for each file\n \tclose ARGV if eof;\n\nThere's at least one other case already. If you shorten it to just \"!\ntest_\" to catch more functions, you can see there are a lot of wrong\ntest_cmp invocations, too (maybe not quite as bad because we don't\nproduce a specific message, but we'd yield a confusing diff output).\n\nBut I think we can't cover everything; there are some like\ntest_have_prereq which obviously are invertible.\n\n-Peff\n"},{"id":"494637","messageId":"CAJoAoZmdU281buNTm+K0wHMunsbzbZ6NXFdqh=PkDUwQKfpYEg@mail.gmail.com","threadId":"61453","inReplyTo":"20240510194118.GA1954863@coredump.intra.peff.net","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Emily Shaffer","fromEmail":"nasamuffin@google.com","sentAt":"2024-05-13T16:21:54Z","receivedAt":"2024-05-13T16:22:09Z","isPatch":true,"sender":{"key":"nasamuffin@google.com","avatar":"https://avatars.githubusercontent.com/u/1606826?v=4"},"body":"On Fri, May 10, 2024 at 12:41 PM Jeff King wrote:\n>\n> On Fri, May 10, 2024 at 10:22:43AM -0700, Emily Shaffer wrote:\n>\n> > From: Emily Shaffer \n> >\n> > We already use trace2 to find out about unexpected pipe breakages, which\n> > is nice for detecting bugs or system problems, by adding a handler for\n> > SIGPIPE which simply writes a trace2 line. However, there are a handful\n> > of other common signals which we might want to snoop on:\n> >\n> > - SIGINT, SIGTERM, or SIGQUIT, when a user manually cancels a command in\n> > frustration or mistake (via Ctrl-C, Ctrl-D, or `kill`)\n> > - SIGHUP, when the network closes unexpectedly (indicating there may be\n> > a problem to solve)\n> >\n> > There are lots more signals which we might find useful later, but at\n> > least let's teach trace2 to report these egregious ones. Conveniently,\n> > they're also already covered by the `_common` variants in sigchain.[ch].\n>\n> I think this would be a useful thing to have, but having looked at the\n> trace2 signal code, this is almost certain to cause racy deadlocks.\n>\n> The exact details depend on the specific trace2 target backend, but\n> looking at the various fn_signal() methods, they rely on allocations via\n> strbufs. This is a problem in signal handlers because we can get a\n> signal at any time, including when other code is inside malloc() holding\n> a lock. And then further calls to malloc() will block forever on that\n> lock.\n>\n> We should be able to do a quick experiment. Try this snippet, which\n> repeatedly kills \"git log -p\" (which is likely to be allocating memory)\n> and waits for it to exit. Eventually each invocation will stall on a\n> deadlock:\n>\n> -- >8 --\n> doit() {\n> me=$1\n> i=0\n> while true; do\n> GIT_TRACE2=1 ./git log -p >/dev/null 2>&1 &\n> sleep 0.1\n> kill $!\n> wait $! 2>/dev/null\n> i=$((i+1))\n> echo $me:$i\n> done\n> }\n>\n> for i in $(seq 1 64); do\n> doit $i &\n> done\n> -- >8 --\n>\n> I didn't have the patience to wait for all of them to stall, but if you\n> let it run for a bit and check \"ps\", you'll see some git processes which\n> are hanging. Stracing shows them stuck on a lock, like:\n>\n> $ strace -p 1838693\n> strace: Process 1838693 attached\n> futex(0x7facf02df3e0, FUTEX_WAIT_PRIVATE, 2, NULL^Cstrace: Process 1838693 detached\n> \n>\n> This problem existed before your patch. I imagine it was much less\n> likely (or perhaps even impossible) with SIGPIPE though, because we'd\n> see that signal only when in a write() syscall, which implies we're not\n> in malloc(). Whereas we can get SIGTERM, etc, any time.\n>\n> Obviously the script above is meant to exacerbate the situation, and\n> most runs would be fine. But over the course of normal use across many\n> users and many runs, I think we would see this in practice. I think your\n> test won't because it triggers the signal only from raise().\n>\n> So I think before doing this, we'd need to clean up the trace2 signal\n> code to avoid any allocations.\n\nI started to look into doing this, and it's actually really tricky.\nI've got a sample diff here\n(https://github.com/git/git/commit/bf8a5084ede2b9c476e0cf90b7f198c52573fba7);\nI'll need to do it for the other two trace formats as well. But, the\nentire trace2 library relies heavily on strbuf, which doesn't have a\nstack-allocated form. I'm also not sure how we can guarantee the\nno-alloc-ness of these - maybe there's some flag we can give to one of\nthe analyzers or something? - so I'm worried about backsliding in the\nfuture.\n\nAnyway, I won't have time to work on these again until the end of next\nweek. If this looks like a reasonable direction I'll pick it up again\nthen; otherwise, maybe it makes sense for the fn_signal() dispatcher\nto just time out if the handler process doesn't terminate in, say, 1s?\n\n - Emily\n\n>\n> -Peff\n"},{"id":"494854","messageId":"20240516071127.GA83658@coredump.intra.peff.net","threadId":"61453","inReplyTo":"CAJoAoZmdU281buNTm+K0wHMunsbzbZ6NXFdqh=PkDUwQKfpYEg@mail.gmail.com","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-05-16T07:11:27Z","receivedAt":"2024-05-16T07:18:12Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, May 13, 2024 at 09:21:54AM -0700, Emily Shaffer wrote:\n\n> I started to look into doing this, and it's actually really tricky.\n> I've got a sample diff here\n> (https://github.com/git/git/commit/bf8a5084ede2b9c476e0cf90b7f198c52573fba7);\n> I'll need to do it for the other two trace formats as well. But, the\n> entire trace2 library relies heavily on strbuf, which doesn't have a\n> stack-allocated form. I'm also not sure how we can guarantee the\n> no-alloc-ness of these - maybe there's some flag we can give to one of\n> the analyzers or something? - so I'm worried about backsliding in the\n> future.\n\nLooking briefly over that patch, a few thoughts:\n\n - rather than try to make the generic trace2 printing functions handle\n both the alloc and fixed-buffer cases, if the signal handlers only\n need a limited set of functions, it might be easier to just let them\n live in a totally parallel universe. For the simple printing case\n that's not too much extra code, and then the complications are\n limited to the signal-handling functions themselves. It's a bit more\n tricky with json, but we might be able to get away with just\n hand-forming it into a buffer, given the relative simplicity of it.\n\n In some cases you might need to precompute and stash buffers ahead\n of time that could be used by the signal handler (e.g., the whole\n tr2_sid thing).\n\n - the opposite approach might be: stop using any allocating functions\n in the trace2 code. There's a certain simplicity there, even for\n non-signal functions, that we know we're just touching a few\n fixed-size buffers, and you can never create a weird DoS by tweaking\n the tracing code. But it would mean rewriting a lot of it (including\n json formatting stuff) without many of our usual strbuf niceties.\n\n This is more or less the approach we take with error(), die(), etc,\n which are built on vreportf() and its fixed buffer.\n\n - you probably don't want to use xsnprintf(). That function is for\n cases where it's a bug to truncate, and we're just asserting that\n everything fit as expected. For your purposes, you probably want\n regular snprintf(). Again, see vreportf().\n\nI don't think there's an easy static analysis solution here. It's more\nthan just allocation, too. Anything that holds a lock is a potential\nproblem (e.g., stdio streams), and likewise anything that looks at\nglobal state that might be in the middle of being mutated.\n\nSo overall it is a pretty thorny problem, and for the most part we've\njust tried to keep what we do inside signal handlers to a minimum\n(usually cleanup, but even there we have to be careful not to do things\nlike build up allocated paths for recursive removal).\n\n> Anyway, I won't have time to work on these again until the end of next\n> week. If this looks like a reasonable direction I'll pick it up again\n> then; otherwise, maybe it makes sense for the fn_signal() dispatcher\n> to just time out if the handler process doesn't terminate in, say, 1s?\n\nThe timeout would help with locks, but not other weird logic bugs you\ncan get into. Fundamentally you really want to do as little as possible\nfrom a signal handler.\n\n-Peff\n"},{"id":"494899","messageId":"xmqqwmntra3f.fsf@gitster.g","threadId":"61453","inReplyTo":"20240516071127.GA83658@coredump.intra.peff.net","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2024-05-16T16:32:36Z","receivedAt":"2024-05-16T16:32:45Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> - the opposite approach might be: stop using any allocating functions\n> in the trace2 code. There's a certain simplicity there, even for\n> non-signal functions, that we know we're just touching a few\n> fixed-size buffers, and you can never create a weird DoS by tweaking\n> the tracing code. But it would mean rewriting a lot of it (including\n> json formatting stuff) without many of our usual strbuf niceties.\n>\n> This is more or less the approach we take with error(), die(), etc,\n> which are built on vreportf() and its fixed buffer.\n\nWould another approach be to add various trace2 functions that use\nstrbuf() allocation a way to tell if they are called from a signal\nhanding codepath, and punt (by doing nothing if needed, but\nhopefully we have enough slop in the buffer to say \"hey we got\ninterrupted so no more detailed report for you, sorry\") if that is\nthe case?\n\n> So overall it is a pretty thorny problem, and for the most part we've\n> just tried to keep what we do inside signal handlers to a minimum\n> (usually cleanup, but even there we have to be careful not to do things\n> like build up allocated paths for recursive removal).\n\nYes, I agree that it is the right approach to do very little in a\nsignal handler.\n\n"},{"id":"495371","messageId":"20240523093643.GG1306938@coredump.intra.peff.net","threadId":"61453","inReplyTo":"xmqqwmntra3f.fsf@gitster.g","subject":"Re: [PATCH] trace2: intercept all common signals","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-05-23T09:36:43Z","receivedAt":"2024-05-23T09:36:45Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, May 16, 2024 at 09:32:36AM -0700, Junio C Hamano wrote:\n\n> Jeff King writes:\n> \n> > - the opposite approach might be: stop using any allocating functions\n> > in the trace2 code. There's a certain simplicity there, even for\n> > non-signal functions, that we know we're just touching a few\n> > fixed-size buffers, and you can never create a weird DoS by tweaking\n> > the tracing code. But it would mean rewriting a lot of it (including\n> > json formatting stuff) without many of our usual strbuf niceties.\n> >\n> > This is more or less the approach we take with error(), die(), etc,\n> > which are built on vreportf() and its fixed buffer.\n> \n> Would another approach be to add various trace2 functions that use\n> strbuf() allocation a way to tell if they are called from a signal\n> handing codepath, and punt (by doing nothing if needed, but\n> hopefully we have enough slop in the buffer to say \"hey we got\n> interrupted so no more detailed report for you, sorry\") if that is\n> the case?\n\nWe do use that \"in_signal\" flag in other handlers. E.g., when\nrun-command avoids calling free() in a signal, and the tempfile code\navoids using stdio. But in the case of these trace functions, I think\nthey'd all need to be rewritten to avoid strbufs. That message\nformatting is the whole point, and there is no way to have a strbuf\nwhich truncates rather than growing (though it is something we've\ndiscussed).\n\nSo I think we either need to rip strbufs out of most of trace2, or let\nthese signal paths re-implement the formatting in a super-simple way.\n\n-Peff\n"}]}