[PATCH] usage: trace2 BUG() invocations

[PATCH] usage: trace2 BUG() invocations

[Jonathan Tan]

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

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

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

[Junio C Hamano]

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?

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

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

[Jeff King]

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.

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

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

[Derrick Stolee]

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?

Thanks,
-Stolee

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

[Jeff King]

On Fri, Feb 05, 2021 at 07:51:09AM -0500, Derrick Stolee wrote:

> > 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.

> 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

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

[Jeff Hostetler]

On 2/5/21 7:51 AM, Derrick Stolee wrote:
> 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
> 

[PATCH v2] usage: trace2 BUG() invocations

[Jonathan Tan]

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

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

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

[Jeff King]

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

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

[Jonathan Tan]

> > +# 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.

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

[Junio C Hamano]

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.

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

[Junio C Hamano]

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();
-- 
2.30.0-663-g458e05790b

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

[Ævar Arnfjörð Bjarmason]

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.