Re: [RFC PATCH 3/3] trace2: emit "signal" events after calling BUG()

[Josh Steadmon <steadmon@google.com>]

On 2022.05.26 02:30, Ævar Arnfjörð Bjarmason wrote:
> Add a wrapper for the abort(3) function to correspond to the existing
> wrapper for exit(3). See ee4512ed481 (trace2: create new combined
> trace facility, 2019-02-22) for the introduction of the exit(3)
> wrapper. See also the more recent 368b5843158 (common-main.c: call
> exit(), don't return, 2021-12-07) discussing how the exit() wrapper
> macro it and the trace2 machinery interact.
> 
> As reported (off the ML) by Josh Steadmon we have "start" events that
> are not followed by corresponding "exit" events. I first considered
> logging an "exit" here, but that would be incorrect, we didn't call
> exit, on abort() we do the equivalent of:
> 
> 	kill(getpid(), SIGABRT);
> 
> So let's instead update the documentation to note that those
> interested in seeing a marker for process exit need to be looking for
> either an "exit" or a "signal" event.
> 
> We then need to add a *_fl() function similar to the existing
> "tr2main_signal_handler()" function. Until now we'd only been emitting
> these "signal" events from our own signal handlers.
> 
> Reported-by: Josh Steadmon <steadmon@google.com>
> Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
> ---
>  Documentation/technical/api-trace2.txt | 13 +++++++++----
>  git-compat-util.h                      |  9 +++++++++
>  t/t0210-trace2-normal.sh               |  1 +
>  trace2.c                               | 19 +++++++++++++++++++
>  trace2.h                               |  8 ++++++++
>  trace2/tr2_tgt.h                       |  3 +++
>  trace2/tr2_tgt_event.c                 | 11 +++++++++--
>  trace2/tr2_tgt_normal.c                | 11 +++++++++--
>  trace2/tr2_tgt_perf.c                  | 11 +++++++++--
>  9 files changed, 76 insertions(+), 10 deletions(-)
> 
> diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt
> index f4a8a690878..55ecfd8c30c 100644
> --- a/Documentation/technical/api-trace2.txt
> +++ b/Documentation/technical/api-trace2.txt
> @@ -421,7 +421,9 @@ only present on the "start" and "atexit" events.
>  ------------
>  
>  `"exit"`::
> -	This event is emitted when git calls `exit()`.
> +	This event is emitted when git calls `exit()`. This event will
> +	be produced for all regular ending of the git process, but it
> +	might also exit via a "signal".
>  +
>  ------------
>  {
> @@ -435,7 +437,7 @@ only present on the "start" and "atexit" events.
>  `"atexit"`::
>  	This event is emitted by the Trace2 `atexit` routine during
>  	final shutdown.  It should be the last event emitted by the
> -	process.
> +	process, unless it was aborted (see "signal").
>  +
>  (The elapsed time reported here is greater than the time reported in
>  the "exit" event because it runs after all other atexit tasks have
> @@ -452,8 +454,11 @@ completed.)
>  
>  `"signal"`::
>  	This event is emitted when the program is terminated by a user
> -	signal.  Depending on the platform, the signal event may
> -	prevent the "atexit" event from being generated.
> +	signal, which includes git itself calling abort(3). Depending
> +	on the platform, the signal event may prevent the "exit"
> +	and/or "atexit" events from being generated. E.g. if BUG() was
> +	invoked we'll emit an "error" event followed by a "signal"
> +	event, and nothing else.
>  +
>  ------------
>  {
> diff --git a/git-compat-util.h b/git-compat-util.h
> index 58fd813bd01..ea3177b2771 100644
> --- a/git-compat-util.h
> +++ b/git-compat-util.h
> @@ -1403,6 +1403,15 @@ int cmd_main(int, const char **);
>  int trace2_cmd_exit_fl(const char *file, int line, int code);
>  #define exit(code) exit(trace2_cmd_exit_fl(__FILE__, __LINE__, (code)))
>  
> +/*
> + * Intercept calls to abort() to log that we aborted.
> + */
> +void trace2_cmd_signal_fl(const char *file, int line, int signo);
> +#define abort() do { \
> +	trace2_cmd_signal_fl(__FILE__, __LINE__, SIGABRT); \
> +	abort(); \
> +} while (0)
> +
>  /*
>   * You can mark a stack variable with UNLEAK(var) to avoid it being
>   * reported as a leak by tools like LSAN or valgrind. The argument
> diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh
> index 910a6af8058..25fffdba80e 100755
> --- a/t/t0210-trace2-normal.sh
> +++ b/t/t0210-trace2-normal.sh
> @@ -162,6 +162,7 @@ test_expect_success 'BUG messages are written to trace2' '
>  		start _EXE_ trace2 007bug
>  		cmd_name trace2 (trace2)
>  		error the bug message
> +		signal elapsed:_TIME_ code:6
>  	EOF
>  	test_cmp expect actual
>  '
> diff --git a/trace2.c b/trace2.c
> index e01cf77f1a8..250b2424bfa 100644
> --- a/trace2.c
> +++ b/trace2.c
> @@ -230,6 +230,25 @@ int trace2_cmd_exit_fl(const char *file, int line, int code)
>  	return code;
>  }
>  
> +void trace2_cmd_signal_fl(const char *file, int line, int signo)
> +{
> +	struct tr2_tgt *tgt_j;
> +	int j;
> +	uint64_t us_now;
> +	uint64_t us_elapsed_absolute;
> +
> +	if (!trace2_enabled)
> +		return;
> +
> +	us_now = getnanotime() / 1000;
> +	us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
> +
> +	for_each_wanted_builtin (j, tgt_j)
> +		if (tgt_j->pfn_signal_fl)
> +			tgt_j->pfn_signal_fl(file, line, us_elapsed_absolute,
> +					     signo);
> +}
> +
>  void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt,
>  			    va_list ap)
>  {
> diff --git a/trace2.h b/trace2.h
> index 1b109f57d0a..4f456f2fc62 100644
> --- a/trace2.h
> +++ b/trace2.h
> @@ -112,6 +112,14 @@ int trace2_cmd_exit_fl(const char *file, int line, int code);
>  
>  #define trace2_cmd_exit(code) (trace2_cmd_exit_fl(__FILE__, __LINE__, (code)))
>  
> +/*
> + * Emit a 'signal' event. Used to log that we called abort() e.g. via
> + * the BUG() function.
> + */
> +void trace2_cmd_signal_fl(const char *file, int line, int signo);
> +
> +#define trace2_cmd_signal(signo) (trace2_cmd_signal_fl(__FILE__, __LINE__, (signo)))
> +
>  /*
>   * Emit an 'error' event.
>   *
> diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h
> index 65f94e15748..fbc33650c5d 100644
> --- a/trace2/tr2_tgt.h
> +++ b/trace2/tr2_tgt.h
> @@ -20,6 +20,8 @@ typedef void(tr2_tgt_evt_start_fl_t)(const char *file, int line,
>  typedef void(tr2_tgt_evt_exit_fl_t)(const char *file, int line,
>  				    uint64_t us_elapsed_absolute, int code);
>  typedef void(tr2_tgt_evt_signal_t)(uint64_t us_elapsed_absolute, int signo);
> +typedef void(tr2_tgt_evt_signal_fl_t)(const char *file, int line,
> +				      uint64_t us_elapsed_absolute, int signo);
>  typedef void(tr2_tgt_evt_atexit_t)(uint64_t us_elapsed_absolute, int code);
>  
>  typedef void(tr2_tgt_evt_error_va_fl_t)(const char *file, int line,
> @@ -111,6 +113,7 @@ struct tr2_tgt {
>  	tr2_tgt_evt_start_fl_t                  *pfn_start_fl;
>  	tr2_tgt_evt_exit_fl_t                   *pfn_exit_fl;
>  	tr2_tgt_evt_signal_t                    *pfn_signal;
> +	tr2_tgt_evt_signal_fl_t                 *pfn_signal_fl;
>  	tr2_tgt_evt_atexit_t                    *pfn_atexit;
>  	tr2_tgt_evt_error_va_fl_t               *pfn_error_va_fl;
>  	tr2_tgt_evt_command_path_fl_t           *pfn_command_path_fl;
> diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c
> index c5c8cfbbaa0..df947378a51 100644
> --- a/trace2/tr2_tgt_event.c
> +++ b/trace2/tr2_tgt_event.c
> @@ -177,14 +177,15 @@ static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
>  	jw_release(&jw);
>  }
>  
> -static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +static void fn_signal_fl(const char *file, int line,
> +			 uint64_t us_elapsed_absolute, int signo)
>  {
>  	const char *event_name = "signal";
>  	struct json_writer jw = JSON_WRITER_INIT;
>  	double t_abs = (double)us_elapsed_absolute / 1000000.0;
>  
>  	jw_object_begin(&jw, 0);
> -	event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw);
> +	event_fmt_prepare(event_name, file, line, NULL, &jw);
>  	jw_object_double(&jw, "t_abs", 6, t_abs);
>  	jw_object_intmax(&jw, "signo", signo);
>  	jw_end(&jw);
> @@ -193,6 +194,11 @@ static void fn_signal(uint64_t us_elapsed_absolute, int signo)
>  	jw_release(&jw);
>  }
>  
> +static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +{
> +	fn_signal_fl(__FILE__, __LINE__, us_elapsed_absolute, signo);
> +}
> +

I believe the only caller of this would be
trace2.c:tr2main_signal_handler(), so could we just switch that one to
use pfn_signal_fl and get rid of pfn_signal altogether?


>  static void fn_atexit(uint64_t us_elapsed_absolute, int code)
>  {
>  	const char *event_name = "atexit";
> @@ -624,6 +630,7 @@ struct tr2_tgt tr2_tgt_event = {
>  	.pfn_start_fl = fn_start_fl,
>  	.pfn_exit_fl = fn_exit_fl,
>  	.pfn_signal = fn_signal,
> +	.pfn_signal_fl = fn_signal_fl,
>  	.pfn_atexit = fn_atexit,
>  	.pfn_error_va_fl = fn_error_va_fl,
>  	.pfn_command_path_fl = fn_command_path_fl,
> diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c
> index c42fbade7f0..8e2bc5027fe 100644
> --- a/trace2/tr2_tgt_normal.c
> +++ b/trace2/tr2_tgt_normal.c
> @@ -105,17 +105,23 @@ static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
>  	strbuf_release(&buf_payload);
>  }
>  
> -static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +static void fn_signal_fl(const char *file, int line,
> +			 uint64_t us_elapsed_absolute, int signo)
>  {
>  	struct strbuf buf_payload = STRBUF_INIT;
>  	double elapsed = (double)us_elapsed_absolute / 1000000.0;
>  
>  	strbuf_addf(&buf_payload, "signal elapsed:%.6f code:%d", elapsed,
>  		    signo);
> -	normal_io_write_fl(__FILE__, __LINE__, &buf_payload);
> +	normal_io_write_fl(file, line, &buf_payload);
>  	strbuf_release(&buf_payload);
>  }
>  
> +static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +{
> +	fn_signal_fl(__FILE__, __LINE__, us_elapsed_absolute, signo);
> +}
> +
>  static void fn_atexit(uint64_t us_elapsed_absolute, int code)
>  {
>  	struct strbuf buf_payload = STRBUF_INIT;
> @@ -336,6 +342,7 @@ struct tr2_tgt tr2_tgt_normal = {
>  	.pfn_start_fl = fn_start_fl,
>  	.pfn_exit_fl = fn_exit_fl,
>  	.pfn_signal = fn_signal,
> +	.pfn_signal_fl = fn_signal_fl,
>  	.pfn_atexit = fn_atexit,
>  	.pfn_error_va_fl = fn_error_va_fl,
>  	.pfn_command_path_fl = fn_command_path_fl,
> diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c
> index a1eff8bea31..4ce18d3f12e 100644
> --- a/trace2/tr2_tgt_perf.c
> +++ b/trace2/tr2_tgt_perf.c
> @@ -193,18 +193,24 @@ static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
>  	strbuf_release(&buf_payload);
>  }
>  
> -static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +static void fn_signal_fl(const char *file, int line,
> +			 uint64_t us_elapsed_absolute, int signo)
>  {
>  	const char *event_name = "signal";
>  	struct strbuf buf_payload = STRBUF_INIT;
>  
>  	strbuf_addf(&buf_payload, "signo:%d", signo);
>  
> -	perf_io_write_fl(__FILE__, __LINE__, event_name, NULL,
> +	perf_io_write_fl(file, line, event_name, NULL,
>  			 &us_elapsed_absolute, NULL, NULL, &buf_payload);
>  	strbuf_release(&buf_payload);
>  }
>  
> +static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +{
> +	fn_signal_fl(__FILE__, __LINE__, us_elapsed_absolute, signo);
> +}
> +
>  static void fn_atexit(uint64_t us_elapsed_absolute, int code)
>  {
>  	const char *event_name = "atexit";
> @@ -560,6 +566,7 @@ struct tr2_tgt tr2_tgt_perf = {
>  	.pfn_start_fl = fn_start_fl,
>  	.pfn_exit_fl = fn_exit_fl,
>  	.pfn_signal = fn_signal,
> +	.pfn_signal_fl = fn_signal_fl,
>  	.pfn_atexit = fn_atexit,
>  	.pfn_error_va_fl = fn_error_va_fl,
>  	.pfn_command_path_fl = fn_command_path_fl,
> -- 
> 2.36.1.1046.g586767a6996
>