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

[Junio C Hamano <gitster@pobox.com>]

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