| Message ID | 20210205200908.805639-1-jonathantanmy@google.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [v2] usage: trace2 BUG() invocations | expand |
On Fri, Feb 05, 2021 at 12:09:08PM -0800, Jonathan Tan wrote: > die() messages are traced in trace2, but BUG() messages are not. Anyone > tracking die() messages would have even more reason to track BUG(). > Therefore, write to trace2 when BUG() is invoked. > > Signed-off-by: Jonathan Tan <jonathantanmy@google.com> > --- > Thanks everyone for your suggestions. I've used an in_bug static > variable (which does prevent the infinite loop - I injected the bug that > Peff described and verified that it indeed loops without the mitigation > and doesn't loop with the mitigation) and moved the trace2 to be below > the vreportf (necessitating a va_copy). Thanks. I think the single static in_bug is sufficient. We can always extend it later if that turns out not to be the case. > diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh > index ce7574edb1..81af180c4c 100755 > --- a/t/t0210-trace2-normal.sh > +++ b/t/t0210-trace2-normal.sh > @@ -147,6 +147,25 @@ test_expect_success 'normal stream, error event' ' > test_cmp expect actual > ' > > +# Verb 007bug > +# > +# Check that BUG writes to trace2 > + > +test_expect_success 'normal stream, exit code 1' ' Is this description accurate? It doesn't really seem like "exit code 1". Maybe "99", though BUG is probably more accurate. > + test_when_finished "rm trace.normal actual expect" && > + test_must_fail env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 007bug && > + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual && > + cat >expect <<-EOF && > + version $V > + start _EXE_ trace2 007bug > + cmd_name trace2 (trace2) > + error the bug message > + exit elapsed:_TIME_ code:99 > + atexit elapsed:_TIME_ code:99 > + EOF > + test_cmp expect actual I wondered how we triggered the BUG_exit_code magic, since I didn't see any environment set up. It turns out that it's hard-coded into test-tool, so we don't need to do anything special here in the test. -Peff
> > +# Verb 007bug > > +# > > +# Check that BUG writes to trace2 > > + > > +test_expect_success 'normal stream, exit code 1' ' > > Is this description accurate? It doesn't really seem like "exit code 1". > Maybe "99", though BUG is probably more accurate. Ah...you're right. Maybe 'BUG messages are written to trace2' is better. If Junio doesn't do it locally (or if there are other issues that need fixing), I'll send out v3.
Jonathan Tan <jonathantanmy@google.com> writes: >> > +# Verb 007bug >> > +# >> > +# Check that BUG writes to trace2 >> > + >> > +test_expect_success 'normal stream, exit code 1' ' >> >> Is this description accurate? It doesn't really seem like "exit code 1". >> Maybe "99", though BUG is probably more accurate. > > Ah...you're right. Maybe 'BUG messages are written to trace2' is better. > If Junio doesn't do it locally (or if there are other issues that need > fixing), I'll send out v3. It will risk me forgetting and queueing v2 as-is, and would leave you nobody to blame. Please do not assume that I am paying attention to each and every detail of discussions, especially the ones involving well known reviewers.
Jonathan Tan <jonathantanmy@google.com> writes: >> > +# Verb 007bug >> > +# >> > +# Check that BUG writes to trace2 >> > + >> > +test_expect_success 'normal stream, exit code 1' ' >> >> Is this description accurate? It doesn't really seem like "exit code 1". >> Maybe "99", though BUG is probably more accurate. > > Ah...you're right. Maybe 'BUG messages are written to trace2' is better. > If Junio doesn't do it locally (or if there are other issues that need > fixing), I'll send out v3. Unless I forget to merge it, this is what I queued. ---- >8 -------- >8 -------- >8 -------- >8 ---- From 0a9dde4a04c1228025d292f44113cb8f9cebbfba Mon Sep 17 00:00:00 2001 From: Jonathan Tan <jonathantanmy@google.com> Date: Fri, 5 Feb 2021 12:09:08 -0800 Subject: [PATCH] usage: trace2 BUG() invocations die() messages are traced in trace2, but BUG() messages are not. Anyone tracking die() messages would have even more reason to track BUG(). Therefore, write to trace2 when BUG() is invoked. Signed-off-by: Jonathan Tan <jonathantanmy@google.com> Helped-by: Jeff King <peff@peff.net> Signed-off-by: Junio C Hamano <gitster@pobox.com> --- t/helper/test-trace2.c | 9 +++++++++ t/t0210-trace2-normal.sh | 19 +++++++++++++++++++ usage.c | 11 +++++++++++ 3 files changed, 39 insertions(+) diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c index 823f33ceff..f93633f895 100644 --- a/t/helper/test-trace2.c +++ b/t/helper/test-trace2.c @@ -198,6 +198,14 @@ static int ut_006data(int argc, const char **argv) return 0; } +static int ut_007bug(int argc, const char **argv) +{ + /* + * Exercise BUG() to ensure that the message is printed to trace2. + */ + BUG("the bug message"); +} + /* * Usage: * test-tool trace2 <ut_name_1> <ut_usage_1> @@ -214,6 +222,7 @@ static struct unit_test ut_table[] = { { ut_004child, "004child", "[<child_command_line>]" }, { ut_005exec, "005exec", "<git_command_args>" }, { ut_006data, "006data", "[<category> <key> <value>]+" }, + { ut_007bug, "007bug", "" }, }; /* clang-format on */ diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh index ce7574edb1..0cf3a63b75 100755 --- a/t/t0210-trace2-normal.sh +++ b/t/t0210-trace2-normal.sh @@ -147,6 +147,25 @@ test_expect_success 'normal stream, error event' ' test_cmp expect actual ' +# Verb 007bug +# +# Check that BUG writes to trace2 + +test_expect_success 'BUG messages are written to trace2' ' + test_when_finished "rm trace.normal actual expect" && + test_must_fail env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 007bug && + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual && + cat >expect <<-EOF && + version $V + start _EXE_ trace2 007bug + cmd_name trace2 (trace2) + error the bug message + exit elapsed:_TIME_ code:99 + atexit elapsed:_TIME_ code:99 + EOF + test_cmp expect actual +' + sane_unset GIT_TRACE2_BRIEF # Now test without environment variables and get all Trace2 settings diff --git a/usage.c b/usage.c index 1868a24f7a..1b206de36d 100644 --- a/usage.c +++ b/usage.c @@ -266,6 +266,10 @@ int BUG_exit_code; static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params) { char prefix[256]; + va_list params_copy; + static int in_bug; + + va_copy(params_copy, params); /* truncation via snprintf is OK here */ if (file) @@ -274,6 +278,13 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis snprintf(prefix, sizeof(prefix), "BUG: "); vreportf(prefix, fmt, params); + + if (in_bug) + abort(); + in_bug = 1; + + trace2_cmd_error_va(fmt, params_copy); + if (BUG_exit_code) exit(BUG_exit_code); abort();
On Fri, Feb 05 2021, Jonathan Tan wrote: > die() messages are traced in trace2, but BUG() messages are not. Anyone > tracking die() messages would have even more reason to track BUG(). > Therefore, write to trace2 when BUG() is invoked. > [...] > +# Verb 007bug > +# > +# Check that BUG writes to trace2 > + > +test_expect_success 'normal stream, exit code 1' ' > + test_when_finished "rm trace.normal actual expect" && > + test_must_fail env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 007bug && > + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual && > + cat >expect <<-EOF && > + version $V > + start _EXE_ trace2 007bug > + cmd_name trace2 (trace2) > + error the bug message > + exit elapsed:_TIME_ code:99 > + atexit elapsed:_TIME_ code:99 > + EOF > + test_cmp expect actual > +' > + > sane_unset GIT_TRACE2_BRIEF > > # Now test without environment variables and get all Trace2 settings > diff --git a/usage.c b/usage.c > index 1868a24f7a..1b206de36d 100644 > --- a/usage.c > +++ b/usage.c > @@ -266,6 +266,10 @@ int BUG_exit_code; > static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params) > { > char prefix[256]; > + va_list params_copy; > + static int in_bug; > + > + va_copy(params_copy, params); > > /* truncation via snprintf is OK here */ > if (file) > @@ -274,6 +278,13 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis > snprintf(prefix, sizeof(prefix), "BUG: "); > > vreportf(prefix, fmt, params); > + > + if (in_bug) > + abort(); > + in_bug = 1; > + > + trace2_cmd_error_va(fmt, params_copy); > + > if (BUG_exit_code) > exit(BUG_exit_code); > abort(); I see it's an existing bug/misfeature of this whole part of trace2 that error()/warning()/usage() etc. don't pass down the file and line number of their callers. We'd need to make all of those functions a macro for that to work. But it can work for BUG(), since we have the file/line parameters there. Any reason that's not passed down to trace2 in this case, instead of calling trace2_cmd_error_va() which'll lose that information? I.e. if you change your test to use GIT_TRACE2_EVENT you'll see that you get an event like: {"event":"error"[...]"file":"usage.c","line":308, "msg":"the bug message","fmt":"the bug message"} It seems that currently the only way to tell these error events apart now is to hardcode those known usage.c line numbers on the consumer side, unless I'm missing something.
diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c index 823f33ceff..f93633f895 100644 --- a/t/helper/test-trace2.c +++ b/t/helper/test-trace2.c @@ -198,6 +198,14 @@ static int ut_006data(int argc, const char **argv) return 0; } +static int ut_007bug(int argc, const char **argv) +{ + /* + * Exercise BUG() to ensure that the message is printed to trace2. + */ + BUG("the bug message"); +} + /* * Usage: * test-tool trace2 <ut_name_1> <ut_usage_1> @@ -214,6 +222,7 @@ static struct unit_test ut_table[] = { { ut_004child, "004child", "[<child_command_line>]" }, { ut_005exec, "005exec", "<git_command_args>" }, { ut_006data, "006data", "[<category> <key> <value>]+" }, + { ut_007bug, "007bug", "" }, }; /* clang-format on */ diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh index ce7574edb1..81af180c4c 100755 --- a/t/t0210-trace2-normal.sh +++ b/t/t0210-trace2-normal.sh @@ -147,6 +147,25 @@ test_expect_success 'normal stream, error event' ' test_cmp expect actual ' +# Verb 007bug +# +# Check that BUG writes to trace2 + +test_expect_success 'normal stream, exit code 1' ' + test_when_finished "rm trace.normal actual expect" && + test_must_fail env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 007bug && + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual && + cat >expect <<-EOF && + version $V + start _EXE_ trace2 007bug + cmd_name trace2 (trace2) + error the bug message + exit elapsed:_TIME_ code:99 + atexit elapsed:_TIME_ code:99 + EOF + test_cmp expect actual +' + sane_unset GIT_TRACE2_BRIEF # Now test without environment variables and get all Trace2 settings diff --git a/usage.c b/usage.c index 1868a24f7a..1b206de36d 100644 --- a/usage.c +++ b/usage.c @@ -266,6 +266,10 @@ int BUG_exit_code; static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params) { char prefix[256]; + va_list params_copy; + static int in_bug; + + va_copy(params_copy, params); /* truncation via snprintf is OK here */ if (file) @@ -274,6 +278,13 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis snprintf(prefix, sizeof(prefix), "BUG: "); vreportf(prefix, fmt, params); + + if (in_bug) + abort(); + in_bug = 1; + + trace2_cmd_error_va(fmt, params_copy); + if (BUG_exit_code) exit(BUG_exit_code); abort();
die() messages are traced in trace2, but BUG() messages are not. Anyone tracking die() messages would have even more reason to track BUG(). Therefore, write to trace2 when BUG() is invoked. Signed-off-by: Jonathan Tan <jonathantanmy@google.com> --- Thanks everyone for your suggestions. I've used an in_bug static variable (which does prevent the infinite loop - I injected the bug that Peff described and verified that it indeed loops without the mitigation and doesn't loop with the mitigation) and moved the trace2 to be below the vreportf (necessitating a va_copy). --- t/helper/test-trace2.c | 9 +++++++++ t/t0210-trace2-normal.sh | 19 +++++++++++++++++++ usage.c | 11 +++++++++++ 3 files changed, 39 insertions(+)