{"thread":{"id":"55111","subject":"[PATCH] usage: trace2 BUG() invocations","startedAt":"2021-02-05T05:50:02Z","lastAt":"2021-03-27T17:57:52Z","messageCount":12,"participants":["Jonathan Tan","Junio C Hamano","Jeff King","Derrick Stolee","Jeff Hostetler","Ævar Arnfjörð Bjarmason"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"416239","messageId":"20210205054914.104640-1-jonathantanmy@google.com","threadId":"55111","inReplyTo":null,"subject":"[PATCH] usage: trace2 BUG() invocations","fromName":"Jonathan Tan","fromEmail":"jonathantanmy@google.com","sentAt":"2021-02-05T05:49:14Z","receivedAt":"2021-02-05T05:50:02Z","isPatch":true,"sender":{"key":"jonathantanmy@fastmail.com","avatar":null},"body":"die() messages are traced in trace2, but BUG() messages are not. Anyone\ntracking die() messages would have even more reason to track BUG().\nTherefore, write to trace2 when BUG() is invoked.\n\nSigned-off-by: Jonathan Tan \n---\nThis was noticed when we observed at $DAYJOB that a certain BUG()\ninvocation [1] wasn't written to traces.\n\n[1] https://lore.kernel.org/git/YBn3fxFe978Up5Ly@google.com/\n---\n t/helper/test-trace2.c | 9 +++++++++\n t/t0210-trace2-normal.sh | 19 +++++++++++++++++++\n usage.c | 6 ++++++\n 3 files changed, 34 insertions(+)\n\ndiff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c\nindex 823f33ceff..f93633f895 100644\n--- a/t/helper/test-trace2.c\n+++ b/t/helper/test-trace2.c\n@@ -198,6 +198,14 @@ static int ut_006data(int argc, const char **argv)\n \treturn 0;\n }\n \n+static int ut_007bug(int argc, const char **argv)\n+{\n+\t/*\n+\t * Exercise BUG() to ensure that the message is printed to trace2.\n+\t */\n+\tBUG(\"the bug message\");\n+}\n+\n /*\n * Usage:\n * test-tool trace2 \n@@ -214,6 +222,7 @@ static struct unit_test ut_table[] = {\n \t{ ut_004child, \"004child\", \"[]\" },\n \t{ ut_005exec, \"005exec\", \"\" },\n \t{ ut_006data, \"006data\", \"[ ]+\" },\n+\t{ ut_007bug, \"007bug\", \"\" },\n };\n /* clang-format on */\n \ndiff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh\nindex ce7574edb1..81af180c4c 100755\n--- a/t/t0210-trace2-normal.sh\n+++ b/t/t0210-trace2-normal.sh\n@@ -147,6 +147,25 @@ test_expect_success 'normal stream, error event' '\n \ttest_cmp expect actual\n '\n \n+# Verb 007bug\n+#\n+# Check that BUG writes to trace2\n+\n+test_expect_success 'normal stream, exit code 1' '\n+\ttest_when_finished \"rm trace.normal actual expect\" &&\n+\ttest_must_fail env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 007bug &&\n+\tperl \"$TEST_DIRECTORY/t0210/scrub_normal.perl\" actual &&\n+\tcat >expect <<-EOF &&\n+\t\tversion $V\n+\t\tstart _EXE_ trace2 007bug\n+\t\tcmd_name trace2 (trace2)\n+\t\terror the bug message\n+\t\texit elapsed:_TIME_ code:99\n+\t\tatexit elapsed:_TIME_ code:99\n+\tEOF\n+\ttest_cmp expect actual\n+'\n+\n sane_unset GIT_TRACE2_BRIEF\n \n # Now test without environment variables and get all Trace2 settings\ndiff --git a/usage.c b/usage.c\nindex 1868a24f7a..16272c5348 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -273,6 +273,12 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis\n \telse\n \t\tsnprintf(prefix, sizeof(prefix), \"BUG: \");\n \n+\t/*\n+\t * We call this trace2 function first and expect it to va_copy 'params'\n+\t * before using it (because an 'ap' can only be walked once).\n+\t */\n+\ttrace2_cmd_error_va(fmt, params);\n+\n \tvreportf(prefix, fmt, params);\n \tif (BUG_exit_code)\n \t\texit(BUG_exit_code);\n-- \n2.30.0.365.g02bc693789-goog\n\n"},{"id":"416241","messageId":"xmqq1rdv2g3q.fsf@gitster.c.googlers.com","threadId":"55111","inReplyTo":"20210205054914.104640-1-jonathantanmy@google.com","subject":"Re: [PATCH] usage: trace2 BUG() invocations","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-02-05T06:17:29Z","receivedAt":"2021-02-05T06:18:26Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jonathan Tan writes:\n\n> die() messages are traced in trace2, but BUG() messages are not. Anyone\n> tracking die() messages would have even more reason to track BUG().\n> Therefore, write to trace2 when BUG() is invoked.\n>\n> Signed-off-by: Jonathan Tan \n> ---\n> This was noticed when we observed at $DAYJOB that a certain BUG()\n> invocation [1] wasn't written to traces.\n>\n> [1] https://lore.kernel.org/git/YBn3fxFe978Up5Ly@google.com/\n> ---\n> t/helper/test-trace2.c | 9 +++++++++\n> t/t0210-trace2-normal.sh | 19 +++++++++++++++++++\n> usage.c | 6 ++++++\n> 3 files changed, 34 insertions(+)\n\nSounds like a good idea. Expert opinions?\n\n> diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c\n> index 823f33ceff..f93633f895 100644\n> --- a/t/helper/test-trace2.c\n> +++ b/t/helper/test-trace2.c\n> @@ -198,6 +198,14 @@ static int ut_006data(int argc, const char **argv)\n> \treturn 0;\n> }\n> \n> +static int ut_007bug(int argc, const char **argv)\n> +{\n> +\t/*\n> +\t * Exercise BUG() to ensure that the message is printed to trace2.\n> +\t */\n> +\tBUG(\"the bug message\");\n> +}\n> +\n> /*\n> * Usage:\n> * test-tool trace2 \n> @@ -214,6 +222,7 @@ static struct unit_test ut_table[] = {\n> \t{ ut_004child, \"004child\", \"[]\" },\n> \t{ ut_005exec, \"005exec\", \"\" },\n> \t{ ut_006data, \"006data\", \"[ ]+\" },\n> +\t{ ut_007bug, \"007bug\", \"\" },\n> };\n> /* clang-format on */\n> \n> diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh\n> index ce7574edb1..81af180c4c 100755\n> --- a/t/t0210-trace2-normal.sh\n> +++ b/t/t0210-trace2-normal.sh\n> @@ -147,6 +147,25 @@ test_expect_success 'normal stream, error event' '\n> \ttest_cmp expect actual\n> '\n> \n> +# Verb 007bug\n> +#\n> +# Check that BUG writes to trace2\n> +\n> +test_expect_success 'normal stream, exit code 1' '\n> +\ttest_when_finished \"rm trace.normal actual expect\" &&\n> +\ttest_must_fail env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 007bug &&\n> +\tperl \"$TEST_DIRECTORY/t0210/scrub_normal.perl\" actual &&\n> +\tcat >expect <<-EOF &&\n> +\t\tversion $V\n> +\t\tstart _EXE_ trace2 007bug\n> +\t\tcmd_name trace2 (trace2)\n> +\t\terror the bug message\n> +\t\texit elapsed:_TIME_ code:99\n> +\t\tatexit elapsed:_TIME_ code:99\n> +\tEOF\n> +\ttest_cmp expect 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/usage.c b/usage.c\n> index 1868a24f7a..16272c5348 100644\n> --- a/usage.c\n> +++ b/usage.c\n> @@ -273,6 +273,12 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis\n> \telse\n> \t\tsnprintf(prefix, sizeof(prefix), \"BUG: \");\n> \n> +\t/*\n> +\t * We call this trace2 function first and expect it to va_copy 'params'\n> +\t * before using it (because an 'ap' can only be walked once).\n> +\t */\n> +\ttrace2_cmd_error_va(fmt, params);\n> +\n> \tvreportf(prefix, fmt, params);\n> \tif (BUG_exit_code)\n> \t\texit(BUG_exit_code);\n"},{"id":"416249","messageId":"YB0JYPLMC+hbcxCa@coredump.intra.peff.net","threadId":"55111","inReplyTo":"xmqq1rdv2g3q.fsf@gitster.c.googlers.com","subject":"Re: [PATCH] usage: trace2 BUG() invocations","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-02-05T09:01:20Z","receivedAt":"2021-02-05T09:02:05Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Feb 04, 2021 at 10:17:29PM -0800, Junio C Hamano wrote:\n\n> Jonathan Tan writes:\n> \n> > die() messages are traced in trace2, but BUG() messages are not. Anyone\n> > tracking die() messages would have even more reason to track BUG().\n> > Therefore, write to trace2 when BUG() is invoked.\n> >\n> > Signed-off-by: Jonathan Tan \n> > ---\n> > This was noticed when we observed at $DAYJOB that a certain BUG()\n> > invocation [1] wasn't written to traces.\n> >\n> > [1] https://lore.kernel.org/git/YBn3fxFe978Up5Ly@google.com/\n> > ---\n> > t/helper/test-trace2.c | 9 +++++++++\n> > t/t0210-trace2-normal.sh | 19 +++++++++++++++++++\n> > usage.c | 6 ++++++\n> > 3 files changed, 34 insertions(+)\n> \n> Sounds like a good idea. Expert opinions?\n\nI like the overall idea, but it does open the possibility of a BUG() in\nthe trace2 code looping infinitely.\n\nFor instance, injecting this bug:\n\n diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c\n index 6353e8ad91..b386bae402 100644\n --- a/trace2/tr2_tgt_event.c\n +++ b/trace2/tr2_tgt_event.c\n @@ -242,6 +242,7 @@ static void fn_error_va_fl(const char *file, int line, const char *fmt,\n if (fmt && *fmt)\n jw_object_string(&jw, \"fmt\", fmt);\n jw_end(&jw);\n + jw_end(&jw);\n \n tr2_dst_write_line(&tr2dst_event, &jw.json);\n jw_release(&jw);\n\nand running something like:\n\n GIT_TRACE2_EVENT=1 ./git config --file=does.not.exist --list\n\ncurrently yields:\n\n [...a bunch of trace2 lines...]\n Aborted\n BUG: json-writer.c:397: json-writer: too many jw_end(): '{\"event\":\"error\",[...etc...]\n\nWith this patch it loops forever (well, probably until it runs out of\nmemory, but I stopped it after one minute and 10G of RAM). ;)\n\nPresumably triggering this in practice would be pretty rare. But then,\nthe point of BUG() is to find things we do not expect to happen.\n\nWe've had a similar problem on the die() side in the past, and solved it\nwith a recursion flag. But note it gets a bit non-trivial in the face of\nthreads. There's some discussion in 1ece66bc9e (run-command: use\nthread-aware die_is_recursing routine, 2013-04-16).\n\nThat commit talks about a case where \"die()\" in a thread takes down the\nthread but not the whole process. That wouldn't be true here (we'd\nexpect BUG() to take everything down). So a single counter might be OK\nin practice, though I suspect we could trigger the problem racily\nLikewise this is probably a lurking problem when other threaded code\ncalls die(), but we just don't do that often enough for anybody to have\nnoticed.\n\n-Peff\n"},{"id":"416257","messageId":"1051d473-5d1b-1155-8d9e-93eb2cc349f0@gmail.com","threadId":"55111","inReplyTo":"YB0JYPLMC+hbcxCa@coredump.intra.peff.net","subject":"Re: [PATCH] usage: trace2 BUG() invocations","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2021-02-05T12:51:09Z","receivedAt":"2021-02-05T12:55:43Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"On 2/5/2021 4:01 AM, Jeff King wrote:\n> On Thu, Feb 04, 2021 at 10:17:29PM -0800, Junio C Hamano wrote:\n> \n>> Jonathan Tan writes:\n>>\n>>> die() messages are traced in trace2, but BUG() messages are not. Anyone\n>>> tracking die() messages would have even more reason to track BUG().\n>>> Therefore, write to trace2 when BUG() is invoked.\n>>>\n>>> Signed-off-by: Jonathan Tan \n>>> ---\n>>> This was noticed when we observed at $DAYJOB that a certain BUG()\n>>> invocation [1] wasn't written to traces.\n>>>\n>>> [1] https://lore.kernel.org/git/YBn3fxFe978Up5Ly@google.com/\n>>> ---\n>>> t/helper/test-trace2.c | 9 +++++++++\n>>> t/t0210-trace2-normal.sh | 19 +++++++++++++++++++\n>>> usage.c | 6 ++++++\n>>> 3 files changed, 34 insertions(+)\n>>\n>> Sounds like a good idea. Expert opinions?\n> \n> I like the overall idea, but it does open the possibility of a BUG() in\n> the trace2 code looping infinitely.\n\nI also like the idea. This infinite loop is scary.\n\n> We've had a similar problem on the die() side in the past, and solved it\n> with a recursion flag. But note it gets a bit non-trivial in the face of\n> threads. There's some discussion in 1ece66bc9e (run-command: use\n> thread-aware die_is_recursing routine, 2013-04-16).\n> \n> That commit talks about a case where \"die()\" in a thread takes down the\n> thread but not the whole process. That wouldn't be true here (we'd\n> expect BUG() to take everything down). So a single counter might be OK\n> in practice, though I suspect we could trigger the problem racily\n> Likewise this is probably a lurking problem when other threaded code\n> calls die(), but we just don't do that often enough for anybody to have\n> noticed.\n\nWould a simple \"BUG() has been called\" static suffice?\n\ndiff --git a/usage.c b/usage.c\nindex 1868a24f7a..0d2408f79e 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -265,7 +265,11 @@ int BUG_exit_code;\n \n static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params)\n {\n+ static int in_bug = 0;\n char prefix[256];\n+ if (in_bug)\n+ abort();\n+ in_bug = 1;\n \n /* truncation via snprintf is OK here */\n if (file)\n\nNote that the NOTRETURN means we can't no-op with something like\n\n\tif (in_bug)\n\t\treturn;\n\nso the trace2 call would want to be as close to the abort as\npossible to avoid a silent failure. So, in the patch...\n\n>>> diff --git a/usage.c b/usage.c\n>>> index 1868a24f7a..16272c5348 100644\n>>> --- a/usage.c\n>>> +++ b/usage.c\n>>> @@ -273,6 +273,12 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis\n>>> \telse\n>>> \t\tsnprintf(prefix, sizeof(prefix), \"BUG: \");\n>>> \n>>> +\t/*\n>>> +\t * We call this trace2 function first and expect it to va_copy 'params'\n>>> +\t * before using it (because an 'ap' can only be walked once).\n>>> +\t */\n>>> +\ttrace2_cmd_error_va(fmt, params);\n>>> +\n>>> \tvreportf(prefix, fmt, params);\n\nWe would want this vreportf() to be before the call to\ntrace2_cmd_error_va(), right?\n\nThanks,\n-Stolee\n"},{"id":"416259","messageId":"YB1LsacCd4au0P5z@coredump.intra.peff.net","threadId":"55111","inReplyTo":"1051d473-5d1b-1155-8d9e-93eb2cc349f0@gmail.com","subject":"Re: [PATCH] usage: trace2 BUG() invocations","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-02-05T13:44:17Z","receivedAt":"2021-02-05T13:48:23Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Feb 05, 2021 at 07:51:09AM -0500, Derrick Stolee wrote:\n\n> > We've had a similar problem on the die() side in the past, and solved it\n> > with a recursion flag. But note it gets a bit non-trivial in the face of\n> > threads. There's some discussion in 1ece66bc9e (run-command: use\n> > thread-aware die_is_recursing routine, 2013-04-16).\n> > \n> > That commit talks about a case where \"die()\" in a thread takes down the\n> > thread but not the whole process. That wouldn't be true here (we'd\n> > expect BUG() to take everything down). So a single counter might be OK\n> > in practice, though I suspect we could trigger the problem racily\n> > Likewise this is probably a lurking problem when other threaded code\n> > calls die(), but we just don't do that often enough for anybody to have\n> > noticed.\n> \n> Would a simple \"BUG() has been called\" static suffice?\n\nYeah, perhaps. That's what we started with for die(), and what we\nreplaced in the commit I mentioned when it became a problem with\nthreads. But we might be able to get away with it here.\n\n> so the trace2 call would want to be as close to the abort as\n> possible to avoid a silent failure. So, in the patch...\n> [...]\n> We would want this vreportf() to be before the call to\n> trace2_cmd_error_va(), right?\n\nYeah, that is definitely preferable. The die-is-recursing logic is bad\nfor that, and it's annoying. I think it dies with \"woah, I'm recursing\"\nwithout printing anything, because the recursion happens in the handler\nthat does the printing. And I suspect nobody bothered to improve it\nbecause the whole point is that this recursing case shouldn't come up.\nBut if it's easy to make it do the right thing for the BUG() case (and I\nthink it is), we might as well.\n\n-Peff\n"},{"id":"416284","messageId":"20210205200908.805639-1-jonathantanmy@google.com","threadId":"55111","inReplyTo":"20210205054914.104640-1-jonathantanmy@google.com","subject":"[PATCH v2] usage: trace2 BUG() invocations","fromName":"Jonathan Tan","fromEmail":"jonathantanmy@google.com","sentAt":"2021-02-05T20:09:08Z","receivedAt":"2021-02-05T20:10:46Z","isPatch":true,"sender":{"key":"jonathantanmy@fastmail.com","avatar":null},"body":"die() messages are traced in trace2, but BUG() messages are not. Anyone\ntracking die() messages would have even more reason to track BUG().\nTherefore, write to trace2 when BUG() is invoked.\n\nSigned-off-by: Jonathan Tan \n---\nThanks everyone for your suggestions. I've used an in_bug static\nvariable (which does prevent the infinite loop - I injected the bug that\nPeff described and verified that it indeed loops without the mitigation\nand doesn't loop with the mitigation) and moved the trace2 to be below\nthe vreportf (necessitating a va_copy).\n---\n t/helper/test-trace2.c | 9 +++++++++\n t/t0210-trace2-normal.sh | 19 +++++++++++++++++++\n usage.c | 11 +++++++++++\n 3 files changed, 39 insertions(+)\n\ndiff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c\nindex 823f33ceff..f93633f895 100644\n--- a/t/helper/test-trace2.c\n+++ b/t/helper/test-trace2.c\n@@ -198,6 +198,14 @@ static int ut_006data(int argc, const char **argv)\n \treturn 0;\n }\n \n+static int ut_007bug(int argc, const char **argv)\n+{\n+\t/*\n+\t * Exercise BUG() to ensure that the message is printed to trace2.\n+\t */\n+\tBUG(\"the bug message\");\n+}\n+\n /*\n * Usage:\n * test-tool trace2 \n@@ -214,6 +222,7 @@ static struct unit_test ut_table[] = {\n \t{ ut_004child, \"004child\", \"[]\" },\n \t{ ut_005exec, \"005exec\", \"\" },\n \t{ ut_006data, \"006data\", \"[ ]+\" },\n+\t{ ut_007bug, \"007bug\", \"\" },\n };\n /* clang-format on */\n \ndiff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh\nindex ce7574edb1..81af180c4c 100755\n--- a/t/t0210-trace2-normal.sh\n+++ b/t/t0210-trace2-normal.sh\n@@ -147,6 +147,25 @@ test_expect_success 'normal stream, error event' '\n \ttest_cmp expect actual\n '\n \n+# Verb 007bug\n+#\n+# Check that BUG writes to trace2\n+\n+test_expect_success 'normal stream, exit code 1' '\n+\ttest_when_finished \"rm trace.normal actual expect\" &&\n+\ttest_must_fail env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 007bug &&\n+\tperl \"$TEST_DIRECTORY/t0210/scrub_normal.perl\" actual &&\n+\tcat >expect <<-EOF &&\n+\t\tversion $V\n+\t\tstart _EXE_ trace2 007bug\n+\t\tcmd_name trace2 (trace2)\n+\t\terror the bug message\n+\t\texit elapsed:_TIME_ code:99\n+\t\tatexit elapsed:_TIME_ code:99\n+\tEOF\n+\ttest_cmp expect actual\n+'\n+\n sane_unset GIT_TRACE2_BRIEF\n \n # Now test without environment variables and get all Trace2 settings\ndiff --git a/usage.c b/usage.c\nindex 1868a24f7a..1b206de36d 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -266,6 +266,10 @@ int BUG_exit_code;\n static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params)\n {\n \tchar prefix[256];\n+\tva_list params_copy;\n+\tstatic int in_bug;\n+\n+\tva_copy(params_copy, params);\n \n \t/* truncation via snprintf is OK here */\n \tif (file)\n@@ -274,6 +278,13 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis\n \t\tsnprintf(prefix, sizeof(prefix), \"BUG: \");\n \n \tvreportf(prefix, fmt, params);\n+\n+\tif (in_bug)\n+\t\tabort();\n+\tin_bug = 1;\n+\n+\ttrace2_cmd_error_va(fmt, params_copy);\n+\n \tif (BUG_exit_code)\n \t\texit(BUG_exit_code);\n \tabort();\n-- \n2.30.0.365.g02bc693789-goog\n\n"},{"id":"416300","messageId":"7ea4bd72-1229-2652-678c-e78c10eaf5d3@jeffhostetler.com","threadId":"55111","inReplyTo":"1051d473-5d1b-1155-8d9e-93eb2cc349f0@gmail.com","subject":"Re: [PATCH] usage: trace2 BUG() invocations","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2021-02-05T16:34:40Z","receivedAt":"2021-02-05T22:02:16Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 2/5/21 7:51 AM, Derrick Stolee wrote:\n> On 2/5/2021 4:01 AM, Jeff King wrote:\n>> On Thu, Feb 04, 2021 at 10:17:29PM -0800, Junio C Hamano wrote:\n>>\n>>> Jonathan Tan writes:\n>>>\n>>>> die() messages are traced in trace2, but BUG() messages are not. Anyone\n>>>> tracking die() messages would have even more reason to track BUG().\n>>>> Therefore, write to trace2 when BUG() is invoked.\n>>>>\n>>>> Signed-off-by: Jonathan Tan \n>>>> ---\n>>>> This was noticed when we observed at $DAYJOB that a certain BUG()\n>>>> invocation [1] wasn't written to traces.\n>>>>\n>>>> [1] https://lore.kernel.org/git/YBn3fxFe978Up5Ly@google.com/\n>>>> ---\n>>>> t/helper/test-trace2.c | 9 +++++++++\n>>>> t/t0210-trace2-normal.sh | 19 +++++++++++++++++++\n>>>> usage.c | 6 ++++++\n>>>> 3 files changed, 34 insertions(+)\n>>>\n>>> Sounds like a good idea. Expert opinions?\n>>\n>> I like the overall idea, but it does open the possibility of a BUG() in\n>> the trace2 code looping infinitely.\n> \n> I also like the idea. This infinite loop is scary.\n> \n>> We've had a similar problem on the die() side in the past, and solved it\n>> with a recursion flag. But note it gets a bit non-trivial in the face of\n>> threads. There's some discussion in 1ece66bc9e (run-command: use\n>> thread-aware die_is_recursing routine, 2013-04-16).\n>>\n>> That commit talks about a case where \"die()\" in a thread takes down the\n>> thread but not the whole process. That wouldn't be true here (we'd\n>> expect BUG() to take everything down). So a single counter might be OK\n>> in practice, though I suspect we could trigger the problem racily\n>> Likewise this is probably a lurking problem when other threaded code\n>> calls die(), but we just don't do that often enough for anybody to have\n>> noticed.\n> \n> Would a simple \"BUG() has been called\" static suffice?\n> \n> diff --git a/usage.c b/usage.c\n> index 1868a24f7a..0d2408f79e 100644\n> --- a/usage.c\n> +++ b/usage.c\n> @@ -265,7 +265,11 @@ int BUG_exit_code;\n> \n> static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params)\n> {\n> + static int in_bug = 0;\n> char prefix[256];\n> + if (in_bug)\n> + abort();\n> + in_bug = 1;\n> \n> /* truncation via snprintf is OK here */\n> if (file)\n> \n> Note that the NOTRETURN means we can't no-op with something like\n> \n> \tif (in_bug)\n> \t\treturn;\n> \n> so the trace2 call would want to be as close to the abort as\n> possible to avoid a silent failure. So, in the patch...\n> \n>>>> diff --git a/usage.c b/usage.c\n>>>> index 1868a24f7a..16272c5348 100644\n>>>> --- a/usage.c\n>>>> +++ b/usage.c\n>>>> @@ -273,6 +273,12 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis\n>>>> \telse\n>>>> \t\tsnprintf(prefix, sizeof(prefix), \"BUG: \");\n>>>> \n>>>> +\t/*\n>>>> +\t * We call this trace2 function first and expect it to va_copy 'params'\n>>>> +\t * before using it (because an 'ap' can only be walked once).\n>>>> +\t */\n>>>> +\ttrace2_cmd_error_va(fmt, params);\n>>>> +\n>>>> \tvreportf(prefix, fmt, params);\n> \n> We would want this vreportf() to be before the call to\n> trace2_cmd_error_va(), right?\n\nThere's a subtle quirk in the va_list stuff that we can only traverse\nthe list once. So my trace2_ routines always do a `va_copy` and iterate\non it. This leaves the original `params` untouched when it is handed to\n`vreportf()`.\n\nIf we want to reorder the output, we'd need to va_copy it first.\n(Or teach vreporf to always va_copy its arg.)\n\n> \n> Thanks,\n> -Stolee\n> \n"},{"id":"416499","messageId":"YCJ6D1wGgmo1a+KT@coredump.intra.peff.net","threadId":"55111","inReplyTo":"20210205200908.805639-1-jonathantanmy@google.com","subject":"Re: [PATCH v2] usage: trace2 BUG() invocations","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-02-09T12:03:27Z","receivedAt":"2021-02-09T12:05:25Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Feb 05, 2021 at 12:09:08PM -0800, Jonathan Tan wrote:\n\n> die() messages are traced in trace2, but BUG() messages are not. Anyone\n> tracking die() messages would have even more reason to track BUG().\n> Therefore, write to trace2 when BUG() is invoked.\n> \n> Signed-off-by: Jonathan Tan \n> ---\n> Thanks everyone for your suggestions. I've used an in_bug static\n> variable (which does prevent the infinite loop - I injected the bug that\n> Peff described and verified that it indeed loops without the mitigation\n> and doesn't loop with the mitigation) and moved the trace2 to be below\n> the vreportf (necessitating a va_copy).\n\nThanks. I think the single static in_bug is sufficient. We can always\nextend it later if that turns out not to be the case.\n\n> diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh\n> index ce7574edb1..81af180c4c 100755\n> --- a/t/t0210-trace2-normal.sh\n> +++ b/t/t0210-trace2-normal.sh\n> @@ -147,6 +147,25 @@ test_expect_success 'normal stream, error event' '\n> \ttest_cmp expect actual\n> '\n> \n> +# Verb 007bug\n> +#\n> +# Check that BUG writes to trace2\n> +\n> +test_expect_success 'normal stream, exit code 1' '\n\nIs this description accurate? It doesn't really seem like \"exit code 1\".\nMaybe \"99\", though BUG is probably more accurate.\n\n> +\ttest_when_finished \"rm trace.normal actual expect\" &&\n> +\ttest_must_fail env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 007bug &&\n> +\tperl \"$TEST_DIRECTORY/t0210/scrub_normal.perl\" actual &&\n> +\tcat >expect <<-EOF &&\n> +\t\tversion $V\n> +\t\tstart _EXE_ trace2 007bug\n> +\t\tcmd_name trace2 (trace2)\n> +\t\terror the bug message\n> +\t\texit elapsed:_TIME_ code:99\n> +\t\tatexit elapsed:_TIME_ code:99\n> +\tEOF\n> +\ttest_cmp expect actual\n\nI wondered how we triggered the BUG_exit_code magic, since I didn't see\nany environment set up. It turns out that it's hard-coded into\ntest-tool, so we don't need to do anything special here in the test.\n\n-Peff\n"},{"id":"416550","messageId":"20210209193459.3100734-1-jonathantanmy@google.com","threadId":"55111","inReplyTo":"YCJ6D1wGgmo1a+KT@coredump.intra.peff.net","subject":"Re: [PATCH v2] usage: trace2 BUG() invocations","fromName":"Jonathan Tan","fromEmail":"jonathantanmy@google.com","sentAt":"2021-02-09T19:34:59Z","receivedAt":"2021-02-09T20:03:57Z","isPatch":true,"sender":{"key":"jonathantanmy@fastmail.com","avatar":null},"body":"> > +# Verb 007bug\n> > +#\n> > +# Check that BUG writes to trace2\n> > +\n> > +test_expect_success 'normal stream, exit code 1' '\n> \n> Is this description accurate? It doesn't really seem like \"exit code 1\".\n> Maybe \"99\", though BUG is probably more accurate.\n\nAh...you're right. Maybe 'BUG messages are written to trace2' is better.\nIf Junio doesn't do it locally (or if there are other issues that need\nfixing), I'll send out v3.\n"},{"id":"416567","messageId":"xmqqzh0dym71.fsf@gitster.c.googlers.com","threadId":"55111","inReplyTo":"20210209193459.3100734-1-jonathantanmy@google.com","subject":"Re: [PATCH v2] usage: trace2 BUG() invocations","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-02-09T21:18:26Z","receivedAt":"2021-02-09T22:27:44Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jonathan Tan writes:\n\n>> > +# Verb 007bug\n>> > +#\n>> > +# Check that BUG writes to trace2\n>> > +\n>> > +test_expect_success 'normal stream, exit code 1' '\n>> \n>> Is this description accurate? It doesn't really seem like \"exit code 1\".\n>> Maybe \"99\", though BUG is probably more accurate.\n>\n> Ah...you're right. Maybe 'BUG messages are written to trace2' is better.\n> If Junio doesn't do it locally (or if there are other issues that need\n> fixing), I'll send out v3.\n\nIt will risk me forgetting and queueing v2 as-is, and would leave\nyou nobody to blame.\n\nPlease do not assume that I am paying attention to each and every\ndetail of discussions, especially the ones involving well known\nreviewers.\n\n"},{"id":"416571","messageId":"xmqqa6sczy3w.fsf@gitster.c.googlers.com","threadId":"55111","inReplyTo":"20210209193459.3100734-1-jonathantanmy@google.com","subject":"Re: [PATCH v2] usage: trace2 BUG() invocations","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-02-09T22:15:47Z","receivedAt":"2021-02-09T22:55:46Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jonathan Tan writes:\n\n>> > +# Verb 007bug\n>> > +#\n>> > +# Check that BUG writes to trace2\n>> > +\n>> > +test_expect_success 'normal stream, exit code 1' '\n>> \n>> Is this description accurate? It doesn't really seem like \"exit code 1\".\n>> Maybe \"99\", though BUG is probably more accurate.\n>\n> Ah...you're right. Maybe 'BUG messages are written to trace2' is better.\n> If Junio doesn't do it locally (or if there are other issues that need\n> fixing), I'll send out v3.\n\n\nUnless I forget to merge it, this is what I queued.\n\n---- >8 -------- >8 -------- >8 -------- >8 ----\nFrom 0a9dde4a04c1228025d292f44113cb8f9cebbfba Mon Sep 17 00:00:00 2001\nFrom: Jonathan Tan \nDate: Fri, 5 Feb 2021 12:09:08 -0800\nSubject: [PATCH] usage: trace2 BUG() invocations\n\ndie() messages are traced in trace2, but BUG() messages are not. Anyone\ntracking die() messages would have even more reason to track BUG().\nTherefore, write to trace2 when BUG() is invoked.\n\nSigned-off-by: Jonathan Tan \nHelped-by: Jeff King \nSigned-off-by: Junio C Hamano \n---\n t/helper/test-trace2.c | 9 +++++++++\n t/t0210-trace2-normal.sh | 19 +++++++++++++++++++\n usage.c | 11 +++++++++++\n 3 files changed, 39 insertions(+)\n\ndiff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c\nindex 823f33ceff..f93633f895 100644\n--- a/t/helper/test-trace2.c\n+++ b/t/helper/test-trace2.c\n@@ -198,6 +198,14 @@ static int ut_006data(int argc, const char **argv)\n \treturn 0;\n }\n \n+static int ut_007bug(int argc, const char **argv)\n+{\n+\t/*\n+\t * Exercise BUG() to ensure that the message is printed to trace2.\n+\t */\n+\tBUG(\"the bug message\");\n+}\n+\n /*\n * Usage:\n * test-tool trace2 \n@@ -214,6 +222,7 @@ static struct unit_test ut_table[] = {\n \t{ ut_004child, \"004child\", \"[]\" },\n \t{ ut_005exec, \"005exec\", \"\" },\n \t{ ut_006data, \"006data\", \"[ ]+\" },\n+\t{ ut_007bug, \"007bug\", \"\" },\n };\n /* clang-format on */\n \ndiff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh\nindex ce7574edb1..0cf3a63b75 100755\n--- a/t/t0210-trace2-normal.sh\n+++ b/t/t0210-trace2-normal.sh\n@@ -147,6 +147,25 @@ test_expect_success 'normal stream, error event' '\n \ttest_cmp expect actual\n '\n \n+# Verb 007bug\n+#\n+# Check that BUG writes to trace2\n+\n+test_expect_success 'BUG messages are written to trace2' '\n+\ttest_when_finished \"rm trace.normal actual expect\" &&\n+\ttest_must_fail env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 007bug &&\n+\tperl \"$TEST_DIRECTORY/t0210/scrub_normal.perl\" actual &&\n+\tcat >expect <<-EOF &&\n+\t\tversion $V\n+\t\tstart _EXE_ trace2 007bug\n+\t\tcmd_name trace2 (trace2)\n+\t\terror the bug message\n+\t\texit elapsed:_TIME_ code:99\n+\t\tatexit elapsed:_TIME_ code:99\n+\tEOF\n+\ttest_cmp expect actual\n+'\n+\n sane_unset GIT_TRACE2_BRIEF\n \n # Now test without environment variables and get all Trace2 settings\ndiff --git a/usage.c b/usage.c\nindex 1868a24f7a..1b206de36d 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -266,6 +266,10 @@ int BUG_exit_code;\n static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params)\n {\n \tchar prefix[256];\n+\tva_list params_copy;\n+\tstatic int in_bug;\n+\n+\tva_copy(params_copy, params);\n \n \t/* truncation via snprintf is OK here */\n \tif (file)\n@@ -274,6 +278,13 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis\n \t\tsnprintf(prefix, sizeof(prefix), \"BUG: \");\n \n \tvreportf(prefix, fmt, params);\n+\n+\tif (in_bug)\n+\t\tabort();\n+\tin_bug = 1;\n+\n+\ttrace2_cmd_error_va(fmt, params_copy);\n+\n \tif (BUG_exit_code)\n \t\texit(BUG_exit_code);\n \tabort();\n-- \n2.30.0-663-g458e05790b\n\n"},{"id":"420304","messageId":"87mtuoo4ym.fsf@evledraar.gmail.com","threadId":"55111","inReplyTo":"20210205200908.805639-1-jonathantanmy@google.com","subject":"Re: [PATCH v2] usage: trace2 BUG() invocations","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-03-27T17:56:49Z","receivedAt":"2021-03-27T17:57:52Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Fri, Feb 05 2021, Jonathan Tan wrote:\n\n> die() messages are traced in trace2, but BUG() messages are not. Anyone\n> tracking die() messages would have even more reason to track BUG().\n> Therefore, write to trace2 when BUG() is invoked.\n> [...]\n> +# Verb 007bug\n> +#\n> +# Check that BUG writes to trace2\n> +\n> +test_expect_success 'normal stream, exit code 1' '\n> +\ttest_when_finished \"rm trace.normal actual expect\" &&\n> +\ttest_must_fail env GIT_TRACE2=\"$(pwd)/trace.normal\" test-tool trace2 007bug &&\n> +\tperl \"$TEST_DIRECTORY/t0210/scrub_normal.perl\" actual &&\n> +\tcat >expect <<-EOF &&\n> +\t\tversion $V\n> +\t\tstart _EXE_ trace2 007bug\n> +\t\tcmd_name trace2 (trace2)\n> +\t\terror the bug message\n> +\t\texit elapsed:_TIME_ code:99\n> +\t\tatexit elapsed:_TIME_ code:99\n> +\tEOF\n> +\ttest_cmp expect 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/usage.c b/usage.c\n> index 1868a24f7a..1b206de36d 100644\n> --- a/usage.c\n> +++ b/usage.c\n> @@ -266,6 +266,10 @@ int BUG_exit_code;\n> static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params)\n> {\n> \tchar prefix[256];\n> +\tva_list params_copy;\n> +\tstatic int in_bug;\n> +\n> +\tva_copy(params_copy, params);\n> \n> \t/* truncation via snprintf is OK here */\n> \tif (file)\n> @@ -274,6 +278,13 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis\n> \t\tsnprintf(prefix, sizeof(prefix), \"BUG: \");\n> \n> \tvreportf(prefix, fmt, params);\n> +\n> +\tif (in_bug)\n> +\t\tabort();\n> +\tin_bug = 1;\n> +\n> +\ttrace2_cmd_error_va(fmt, params_copy);\n> +\n> \tif (BUG_exit_code)\n> \t\texit(BUG_exit_code);\n> \tabort();\n\nI see it's an existing bug/misfeature of this whole part of trace2 that\nerror()/warning()/usage() etc. don't pass down the file and line number\nof their callers. We'd need to make all of those functions a macro for\nthat to work.\n\nBut it can work for BUG(), since we have the file/line parameters\nthere. Any reason that's not passed down to trace2 in this case, instead\nof calling trace2_cmd_error_va() which'll lose that information?\n\nI.e. if you change your test to use GIT_TRACE2_EVENT you'll see that you\nget an event like:\n\n {\"event\":\"error\"[...]\"file\":\"usage.c\",\"line\":308,\n \"msg\":\"the bug message\",\"fmt\":\"the bug message\"}\n\nIt seems that currently the only way to tell these error events apart\nnow is to hardcode those known usage.c line numbers on the consumer\nside, unless I'm missing something.\n"}]}