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

["Ævar Arnfjörð Bjarmason" <avarab@gmail.com>]

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.