threads / patch / 55111

patchusage: trace2 BUG() invocations

Subject: [PATCH] usage: trace2 BUG() invocations

## tl;dr

12 messages between Feb 5, 2021 and Mar 27, 2021. Diffs are folded; open one to read it.

replies: 11people: 6as markdown or json

Jonathan Tan· Feb 5, 2021, 05:49 UTC · lore

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>
---
This was noticed when we observed at $DAYJOB that a certain BUG()
invocation [1] wasn't written to traces.
[1] https://lore.kernel.org/git/YBn3fxFe978Up5Ly@google.com/
---
 t/helper/test-trace2.c   |  9 +++++++++
 t/t0210-trace2-normal.sh | 19 +++++++++++++++++++
 usage.c                  |  6 ++++++
 3 files changed, 34 insertions(+)
Show changes to 3 files +34 −0

t/helper/test-trace2.c, t/t0210-trace2-normal.sh, usage.c

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..16272c5348 100644
--- a/usage.c
+++ b/usage.c
@@ -273,6 +273,12 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis
 	else
 		snprintf(prefix, sizeof(prefix), "BUG: ");
 
+	/*
+	 * We call this trace2 function first and expect it to va_copy 'params'
+	 * before using it (because an 'ap' can only be walked once).
+	 */
+	trace2_cmd_error_va(fmt, params);
+
 	vreportf(prefix, fmt, params);
 	if (BUG_exit_code)
 		exit(BUG_exit_code);

-- 
2.30.0.365.g02bc693789-goog
Junio C Hamano· Feb 5, 2021, 06:17 UTC · re: Jonathan Tan · lore

Re: [PATCH] usage: trace2 BUG() invocations

Jonathan Tan <jonathantanmy@google.com> writes:
Show 15 quoted lines
> 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>
> ---
> This was noticed when we observed at $DAYJOB that a certain BUG()
> invocation [1] wasn't written to traces.
>
> [1] https://lore.kernel.org/git/YBn3fxFe978Up5Ly@google.com/
> ---
>  t/helper/test-trace2.c   |  9 +++++++++
>  t/t0210-trace2-normal.sh | 19 +++++++++++++++++++
>  usage.c                  |  6 ++++++
>  3 files changed, 34 insertions(+)
Sounds like a good idea.  Expert opinions?
Show 74 quoted lines
> 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..16272c5348 100644
> --- a/usage.c
> +++ b/usage.c
> @@ -273,6 +273,12 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis
>  	else
>  		snprintf(prefix, sizeof(prefix), "BUG: ");
>  
> +	/*
> +	 * We call this trace2 function first and expect it to va_copy 'params'
> +	 * before using it (because an 'ap' can only be walked once).
> +	 */
> +	trace2_cmd_error_va(fmt, params);
> +
>  	vreportf(prefix, fmt, params);
>  	if (BUG_exit_code)
>  		exit(BUG_exit_code);
Jeff King· Feb 5, 2021, 09:01 UTC · re: Junio C Hamano · lore

Re: [PATCH] usage: trace2 BUG() invocations

On Thu, Feb 04, 2021 at 10:17:29PM -0800, Junio C Hamano wrote:
Show 19 quoted lines
> Jonathan Tan <jonathantanmy@google.com> writes:
> 
> > 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>
> > ---
> > This was noticed when we observed at $DAYJOB that a certain BUG()
> > invocation [1] wasn't written to traces.
> >
> > [1] https://lore.kernel.org/git/YBn3fxFe978Up5Ly@google.com/
> > ---
> >  t/helper/test-trace2.c   |  9 +++++++++
> >  t/t0210-trace2-normal.sh | 19 +++++++++++++++++++
> >  usage.c                  |  6 ++++++
> >  3 files changed, 34 insertions(+)
> 
> Sounds like a good idea.  Expert opinions?

I like the overall idea, but it does open the possibility of a BUG() in the trace2 code looping infinitely.

For instance, injecting this bug:
  diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c
  index 6353e8ad91..b386bae402 100644
  --- a/trace2/tr2_tgt_event.c
  +++ b/trace2/tr2_tgt_event.c
  @@ -242,6 +242,7 @@ static void fn_error_va_fl(const char *file, int line, const char *fmt,
          if (fmt && *fmt)
                  jw_object_string(&jw, "fmt", fmt);
          jw_end(&jw);
  +       jw_end(&jw);
   
          tr2_dst_write_line(&tr2dst_event, &jw.json);
          jw_release(&jw);
and running something like:
  GIT_TRACE2_EVENT=1 ./git config --file=does.not.exist --list
currently yields:
  [...a bunch of trace2 lines...]
  Aborted
  BUG: json-writer.c:397: json-writer: too many jw_end(): '{"event":"error",[...etc...]

With this patch it loops forever (well, probably until it runs out of memory, but I stopped it after one minute and 10G of RAM). ;)

Presumably triggering this in practice would be pretty rare. But then, the point of BUG() is to find things we do not expect to happen.

We've had a similar problem on the die() side in the past, and solved it with a recursion flag. But note it gets a bit non-trivial in the face of threads. There's some discussion in 1ece66bc9e (run-command: use thread-aware die_is_recursing routine, 2013-04-16).

That commit talks about a case where "die()" in a thread takes down the thread but not the whole process. That wouldn't be true here (we'd expect BUG() to take everything down). So a single counter might be OK in practice, though I suspect we could trigger the problem racily Likewise this is probably a lurking problem when other threaded code calls die(), but we just don't do that often enough for anybody to have noticed.

-Peff
Derrick Stolee· Feb 5, 2021, 12:51 UTC · re: Jeff King · lore

Re: [PATCH] usage: trace2 BUG() invocations

On 2/5/2021 4:01 AM, Jeff King wrote:
Show 24 quoted lines
> On Thu, Feb 04, 2021 at 10:17:29PM -0800, Junio C Hamano wrote:
> 
>> Jonathan Tan <jonathantanmy@google.com> writes:
>>
>>> 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>
>>> ---
>>> This was noticed when we observed at $DAYJOB that a certain BUG()
>>> invocation [1] wasn't written to traces.
>>>
>>> [1] https://lore.kernel.org/git/YBn3fxFe978Up5Ly@google.com/
>>> ---
>>>  t/helper/test-trace2.c   |  9 +++++++++
>>>  t/t0210-trace2-normal.sh | 19 +++++++++++++++++++
>>>  usage.c                  |  6 ++++++
>>>  3 files changed, 34 insertions(+)
>>
>> Sounds like a good idea.  Expert opinions?
> 
> I like the overall idea, but it does open the possibility of a BUG() in
> the trace2 code looping infinitely.
I also like the idea. This infinite loop is scary.
Show 12 quoted lines
> We've had a similar problem on the die() side in the past, and solved it
> with a recursion flag. But note it gets a bit non-trivial in the face of
> threads. There's some discussion in 1ece66bc9e (run-command: use
> thread-aware die_is_recursing routine, 2013-04-16).
> 
> That commit talks about a case where "die()" in a thread takes down the
> thread but not the whole process. That wouldn't be true here (we'd
> expect BUG() to take everything down). So a single counter might be OK
> in practice, though I suspect we could trigger the problem racily
> Likewise this is probably a lurking problem when other threaded code
> calls die(), but we just don't do that often enough for anybody to have
> noticed.
Would a simple "BUG() has been called" static suffice?
Show changes to usage.c +4 −1
diff --git a/usage.c b/usage.c
index 1868a24f7a..0d2408f79e 100644
--- a/usage.c
+++ b/usage.c
@@ -265,7 +265,11 @@ int BUG_exit_code;
 
 static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params)
 {
+       static int in_bug = 0;
        char prefix[256];
+       if (in_bug)
+               abort();
+       in_bug = 1;
 
        /* truncation via snprintf is OK here */
        if (file)

Note that the NOTRETURN means we can't no-op with something like

	if (in_bug)
		return;

so the trace2 call would want to be as close to the abort as
possible to avoid a silent failure. So, in the patch...

>>> diff --git a/usage.c b/usage.c
>>> index 1868a24f7a..16272c5348 100644
>>> --- a/usage.c
>>> +++ b/usage.c
>>> @@ -273,6 +273,12 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis
>>>  	else
>>>  		snprintf(prefix, sizeof(prefix), "BUG: ");
>>>  
>>> +	/*
>>> +	 * We call this trace2 function first and expect it to va_copy 'params'
>>> +	 * before using it (because an 'ap' can only be walked once).
>>> +	 */
>>> +	trace2_cmd_error_va(fmt, params);
>>> +
>>>  	vreportf(prefix, fmt, params);

We would want this vreportf() to be before the call to
trace2_cmd_error_va(), right?

Thanks,
-Stolee
Jeff King· Feb 5, 2021, 13:44 UTC · re: Derrick Stolee · lore

Re: [PATCH] usage: trace2 BUG() invocations

On Fri, Feb 05, 2021 at 07:51:09AM -0500, Derrick Stolee wrote:
Show 14 quoted lines
> > We've had a similar problem on the die() side in the past, and solved it
> > with a recursion flag. But note it gets a bit non-trivial in the face of
> > threads. There's some discussion in 1ece66bc9e (run-command: use
> > thread-aware die_is_recursing routine, 2013-04-16).
> > 
> > That commit talks about a case where "die()" in a thread takes down the
> > thread but not the whole process. That wouldn't be true here (we'd
> > expect BUG() to take everything down). So a single counter might be OK
> > in practice, though I suspect we could trigger the problem racily
> > Likewise this is probably a lurking problem when other threaded code
> > calls die(), but we just don't do that often enough for anybody to have
> > noticed.
> 
> Would a simple "BUG() has been called" static suffice?

Yeah, perhaps. That's what we started with for die(), and what we replaced in the commit I mentioned when it became a problem with threads. But we might be able to get away with it here.

Show 5 quoted lines
> so the trace2 call would want to be as close to the abort as
> possible to avoid a silent failure. So, in the patch...
> [...]
> We would want this vreportf() to be before the call to
> trace2_cmd_error_va(), right?

Yeah, that is definitely preferable. The die-is-recursing logic is bad for that, and it's annoying. I think it dies with "woah, I'm recursing" without printing anything, because the recursion happens in the handler that does the printing. And I suspect nobody bothered to improve it because the whole point is that this recursing case shouldn't come up. But if it's easy to make it do the right thing for the BUG() case (and I think it is), we might as well.

-Peff
Jeff Hostetler· Feb 5, 2021, 16:34 UTC · re: Derrick Stolee · lore

Re: [PATCH] usage: trace2 BUG() invocations

On 2/5/21 7:51 AM, Derrick Stolee wrote:
Show 86 quoted lines
> On 2/5/2021 4:01 AM, Jeff King wrote:
>> On Thu, Feb 04, 2021 at 10:17:29PM -0800, Junio C Hamano wrote:
>>
>>> Jonathan Tan <jonathantanmy@google.com> writes:
>>>
>>>> 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>
>>>> ---
>>>> This was noticed when we observed at $DAYJOB that a certain BUG()
>>>> invocation [1] wasn't written to traces.
>>>>
>>>> [1] https://lore.kernel.org/git/YBn3fxFe978Up5Ly@google.com/
>>>> ---
>>>>   t/helper/test-trace2.c   |  9 +++++++++
>>>>   t/t0210-trace2-normal.sh | 19 +++++++++++++++++++
>>>>   usage.c                  |  6 ++++++
>>>>   3 files changed, 34 insertions(+)
>>>
>>> Sounds like a good idea.  Expert opinions?
>>
>> I like the overall idea, but it does open the possibility of a BUG() in
>> the trace2 code looping infinitely.
> 
> I also like the idea. This infinite loop is scary.
> 
>> We've had a similar problem on the die() side in the past, and solved it
>> with a recursion flag. But note it gets a bit non-trivial in the face of
>> threads. There's some discussion in 1ece66bc9e (run-command: use
>> thread-aware die_is_recursing routine, 2013-04-16).
>>
>> That commit talks about a case where "die()" in a thread takes down the
>> thread but not the whole process. That wouldn't be true here (we'd
>> expect BUG() to take everything down). So a single counter might be OK
>> in practice, though I suspect we could trigger the problem racily
>> Likewise this is probably a lurking problem when other threaded code
>> calls die(), but we just don't do that often enough for anybody to have
>> noticed.
> 
> Would a simple "BUG() has been called" static suffice?
> 
> diff --git a/usage.c b/usage.c
> index 1868a24f7a..0d2408f79e 100644
> --- a/usage.c
> +++ b/usage.c
> @@ -265,7 +265,11 @@ int BUG_exit_code;
>   
>   static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params)
>   {
> +       static int in_bug = 0;
>          char prefix[256];
> +       if (in_bug)
> +               abort();
> +       in_bug = 1;
>   
>          /* truncation via snprintf is OK here */
>          if (file)
> 
> Note that the NOTRETURN means we can't no-op with something like
> 
> 	if (in_bug)
> 		return;
> 
> so the trace2 call would want to be as close to the abort as
> possible to avoid a silent failure. So, in the patch...
> 
>>>> diff --git a/usage.c b/usage.c
>>>> index 1868a24f7a..16272c5348 100644
>>>> --- a/usage.c
>>>> +++ b/usage.c
>>>> @@ -273,6 +273,12 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis
>>>>   	else
>>>>   		snprintf(prefix, sizeof(prefix), "BUG: ");
>>>>   
>>>> +	/*
>>>> +	 * We call this trace2 function first and expect it to va_copy 'params'
>>>> +	 * before using it (because an 'ap' can only be walked once).
>>>> +	 */
>>>> +	trace2_cmd_error_va(fmt, params);
>>>> +
>>>>   	vreportf(prefix, fmt, params);
> 
> We would want this vreportf() to be before the call to
> trace2_cmd_error_va(), right?

There's a subtle quirk in the va_list stuff that we can only traverse the list once. So my trace2_ routines always do a `va_copy` and iterate on it. This leaves the original `params` untouched when it is handed to `vreportf()`.

If we want to reorder the output, we'd need to va_copy it first. (Or teach vreporf to always va_copy its arg.)

> 
> Thanks,
> -Stolee
>
Jonathan Tan· Feb 5, 2021, 20:09 UTC · re: Jonathan Tan · lore

[PATCH v2] 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>
---
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(+)
Show changes to 3 files +39 −0

t/helper/test-trace2.c, t/t0210-trace2-normal.sh, usage.c

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();

-- 
2.30.0.365.g02bc693789-goog
Jeff King· Feb 9, 2021, 12:03 UTC · re: Jonathan Tan · lore

Re: [PATCH v2] usage: trace2 BUG() invocations

On Fri, Feb 05, 2021 at 12:09:08PM -0800, Jonathan Tan wrote:
Show 11 quoted lines
> 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.

Show 13 quoted lines
> 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.

Show 12 quoted lines
> +	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
Jonathan Tan· Feb 9, 2021, 19:34 UTC · re: Jeff King · lore

Re: [PATCH v2] usage: trace2 BUG() invocations

Show 8 quoted lines
> > +# 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.

Junio C Hamano· Feb 9, 2021, 21:18 UTC · re: Jonathan Tan · lore

Re: [PATCH v2] usage: trace2 BUG() invocations

Jonathan Tan <jonathantanmy@google.com> writes:
Show 12 quoted lines
>> > +# 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.

Junio C Hamano· Feb 9, 2021, 22:15 UTC · re: Jonathan Tan · lore

Re: [PATCH v2] usage: trace2 BUG() invocations

Jonathan Tan <jonathantanmy@google.com> writes:
Show 12 quoted lines
>> > +# 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(+)
Show changes to 3 files +39 −0

t/helper/test-trace2.c, t/t0210-trace2-normal.sh, usage.c

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();

-- 
2.30.0-663-g458e05790b
Ævar Arnfjörð Bjarmason· Mar 27, 2021, 17:56 UTC · re: Jonathan Tan · lore

Re: [PATCH v2] usage: trace2 BUG() invocations

On Fri, Feb 05 2021, Jonathan Tan wrote:
Show 55 quoted lines
> 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.

← back to recent threads