[RFC PATCH 0/3] trace2: log "signal" end events if we invoke BUG()

[RFC PATCH 0/3] trace2: log "signal" end events if we invoke BUG()

[Ævar Arnfjörð Bjarmason]

Josh Steadmon noted in the Review Club tonight/today/yesterday
(depending on the TZ) that he'd encountered trace2 event streams
without an "exit" event, which as discussed can be seen from usage.c
is due to our invoking of abort() there.

This RFC series aims to rectify that, first we back out of test-tool
specific behavior for BUG() in 1/3, and in 3/3 define abort() to be a
wrapper macro like what we do for exit() already.

I'm not sure about the direction of emitting such a "signal" event,
should we just "fake it" and emit an "exit" event? Probably not, but
I'm not confident in that. For one is the exit code (as in what a
shell would get from $?) when we're killed with SIGABRT guaranteed to
be portable?

But hopefully this gets the ball rolling on a good fix for this by
starting a discussion about what we should be doing here.

One alternate way of dealing with this would be to first split up the
"error" event so that we don't emit "error" for all of BUG(), die(),
error() and warning(), and to instead split those up into "BUG",
"die", "error", "warning".

Once we did that we could pretty much declare that the current
behavior before this series is a feature, and that anyone parsing
trace2 output needs to deal with the stream potentially ending in a
"BUG" event.

Any such event parser will need to deal with at least:

    "start" -> ["exit" | "signal"] (with this series)

So perhaps it's OK to simply say that consumers should expect?

   # Or "error" now, but then you can't distinguish "BUG()" from the
   # rest.
    "start" -> ["exit" | "BUG"]

I think I like that less, but it's worth pointing out as an
alternative. The implementation would certainly be smaller than this
proposed RFC.

Ævar Arnfjörð Bjarmason (3):
  test-tool: don't fake up BUG() exits as code 99
  refs API: rename "abort" callback to avoid macro clash
  trace2: emit "signal" events after calling BUG()

 Documentation/technical/api-trace2.txt | 13 +++++++++----
 git-compat-util.h                      |  9 +++++++++
 refs/debug.c                           |  4 ++--
 refs/files-backend.c                   |  4 ++--
 refs/iterator.c                        |  8 ++++----
 refs/packed-backend.c                  |  2 +-
 refs/ref-cache.c                       |  2 +-
 refs/refs-internal.h                   |  2 +-
 t/helper/test-tool.c                   |  1 -
 t/t0210-trace2-normal.sh               |  5 ++---
 t/t1406-submodule-ref-store.sh         | 10 +++++-----
 t/test-lib-functions.sh                | 13 +++++++++++++
 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 +++++++++--
 usage.c                                |  5 -----
 19 files changed, 106 insertions(+), 35 deletions(-)

-- 
2.36.1.1046.g586767a6996

[RFC PATCH 1/3] test-tool: don't fake up BUG() exits as code 99

[Ævar Arnfjörð Bjarmason]

Change the BUG() function invoked be "test-tool" to be the "real" one,
instead of one that avoids producing core files. In
a86303cb5d5 (test-tool: help verifying BUG() code paths, 2018-05-02)
to test the (then recently added) BUG() function we faked up the
abort() in favor of an exit with code 99.

However, in doing so we've been fooling ourselves when it comes to
what trace2 events we log. The events tested for in
0a9dde4a04c (usage: trace2 BUG() invocations, 2021-02-05) are not the
real ones, but those that we emit only from the "test-tool".

Let's just stop faking it, and call abort(). As a86303cb5d5 notes this
will produce core files on some OS's, but as the default behavior for
that is to dump them in the current directory they'll be placed in the
trash directory that we'll shortly me "rm -rf"-ing.

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---

There's a CI problem with the test_must_BUG wrapper here on Windows:
https://github.com/avar/git/runs/6602059183?check_suite_focus=true#step:6:1361

 t/helper/test-tool.c           |  1 -
 t/t0210-trace2-normal.sh       |  4 +---
 t/t1406-submodule-ref-store.sh | 10 +++++-----
 t/test-lib-functions.sh        | 13 +++++++++++++
 usage.c                        |  5 -----
 5 files changed, 19 insertions(+), 14 deletions(-)

diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c
index 0424f7adf5d..99a10f294f5 100644
--- a/t/helper/test-tool.c
+++ b/t/helper/test-tool.c
@@ -110,7 +110,6 @@ int cmd_main(int argc, const char **argv)
 		OPT_END()
 	};
 
-	BUG_exit_code = 99;
 	argc = parse_options(argc, argv, NULL, options, test_tool_usage,
 			     PARSE_OPT_STOP_AT_NON_OPTION |
 			     PARSE_OPT_KEEP_ARGV0);
diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh
index 37c359bd5a2..910a6af8058 100755
--- a/t/t0210-trace2-normal.sh
+++ b/t/t0210-trace2-normal.sh
@@ -155,15 +155,13 @@ test_expect_success 'normal stream, error event' '
 
 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 &&
+	test_must_BUG 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
 '
diff --git a/t/t1406-submodule-ref-store.sh b/t/t1406-submodule-ref-store.sh
index e6a7f7334b6..6f9a16b7355 100755
--- a/t/t1406-submodule-ref-store.sh
+++ b/t/t1406-submodule-ref-store.sh
@@ -25,15 +25,15 @@ test_expect_success 'pack_refs() not allowed' '
 '
 
 test_expect_success 'create_symref() not allowed' '
-	test_must_fail $RUN create-symref FOO refs/heads/main nothing
+	test_must_BUG $RUN create-symref FOO refs/heads/main nothing
 '
 
 test_expect_success 'delete_refs() not allowed' '
-	test_must_fail $RUN delete-refs 0 nothing FOO refs/tags/new-tag
+	test_must_BUG $RUN delete-refs 0 nothing FOO refs/tags/new-tag
 '
 
 test_expect_success 'rename_refs() not allowed' '
-	test_must_fail $RUN rename-ref refs/heads/main refs/heads/new-main
+	test_must_BUG $RUN rename-ref refs/heads/main refs/heads/new-main
 '
 
 test_expect_success 'for_each_ref(refs/heads/)' '
@@ -89,11 +89,11 @@ test_expect_success 'reflog_exists(HEAD)' '
 '
 
 test_expect_success 'delete_reflog() not allowed' '
-	test_must_fail $RUN delete-reflog HEAD
+	test_must_BUG $RUN delete-reflog HEAD
 '
 
 test_expect_success 'create-reflog() not allowed' '
-	test_must_fail $RUN create-reflog HEAD
+	test_must_BUG $RUN create-reflog HEAD
 '
 
 test_done
diff --git a/t/test-lib-functions.sh b/t/test-lib-functions.sh
index 93c03380d44..61f1f03c099 100644
--- a/t/test-lib-functions.sh
+++ b/t/test-lib-functions.sh
@@ -1167,6 +1167,9 @@ test_must_fail () {
 	then
 		echo >&4 "test_must_fail: command succeeded: $*"
 		return 1
+	elif test_match_signal 6 $exit_code && list_contains "$_test_ok" sigabrt
+	then
+		return 0
 	elif test_match_signal 13 $exit_code && list_contains "$_test_ok" sigpipe
 	then
 		return 0
@@ -1186,6 +1189,16 @@ test_must_fail () {
 	return 0
 } 7>&2 2>&4
 
+# The test_must_BUG() function is a wrapper for test_must_fail which
+# checks that we BUG() out.
+#
+# Currently this checks that we exit with abort(), but in the future
+# we might e.g. check the trace2 logging itself, or otherwise make
+# sure that we used BUG() in particular.
+test_must_BUG () {
+	test_must_fail ok=sigabrt "$@"
+} 7>&2 2>&4
+
 # Similar to test_must_fail, but tolerates success, too.  This is
 # meant to be used in contexts like:
 #
diff --git a/usage.c b/usage.c
index b738dd178b3..bf868b5be1f 100644
--- a/usage.c
+++ b/usage.c
@@ -287,9 +287,6 @@ void warning(const char *warn, ...)
 	va_end(params);
 }
 
-/* Only set this, ever, from t/helper/, when verifying that bugs are caught. */
-int BUG_exit_code;
-
 static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_list params)
 {
 	char prefix[256];
@@ -309,8 +306,6 @@ static NORETURN void BUG_vfl(const char *file, int line, const char *fmt, va_lis
 
 	trace2_cmd_error_va(fmt, params_copy);
 
-	if (BUG_exit_code)
-		exit(BUG_exit_code);
 	abort();
 }
 
-- 
2.36.1.1046.g586767a6996

Re: [RFC PATCH 1/3] test-tool: don't fake up BUG() exits as code 99

[Junio C Hamano]

Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:

> Change the BUG() function invoked be "test-tool" to be the "real" one,
> instead of one that avoids producing core files. In
> a86303cb5d5 (test-tool: help verifying BUG() code paths, 2018-05-02)
> to test the (then recently added) BUG() function we faked up the
> abort() in favor of an exit with code 99.
>
> However, in doing so we've been fooling ourselves when it comes to
> what trace2 events we log. The events tested for in
> 0a9dde4a04c (usage: trace2 BUG() invocations, 2021-02-05) are not the
> real ones, but those that we emit only from the "test-tool".

I can fully agree with the above reasoning, i.e. let's test what we
do use in production, instead of something nobody uses for real, if
we were adding a test for BUG() in vacuum, but why did we have to
"fake" it in the first place?

> Let's just stop faking it, and call abort(). As a86303cb5d5 notes this
> will produce core files on some OS's, but as the default behavior for
> that is to dump them in the current directory they'll be placed in the
> trash directory that we'll shortly me "rm -rf"-ing.

Are we sure that the reason no longer applies?  How do we know?  We
would want to explain that to future developers in the proposed log
message, I would think.

> +	elif test_match_signal 6 $exit_code && list_contains "$_test_ok" sigabrt
> +	then
> +		return 0
>  	elif test_match_signal 13 $exit_code && list_contains "$_test_ok" sigpipe

Not a new problem, but these numberings are probably not very
portable.  I am willing to take this as-is and let people on
minority platforms complain ;-)

Re: [RFC PATCH 1/3] test-tool: don't fake up BUG() exits as code 99

[Junio C Hamano]

Junio C Hamano <gitster@pobox.com> writes:

>> However, in doing so we've been fooling ourselves when it comes to
>> what trace2 events we log. The events tested for in
>> 0a9dde4a04c (usage: trace2 BUG() invocations, 2021-02-05) are not the
>> real ones, but those that we emit only from the "test-tool".
>
> I can fully agree with the above reasoning, i.e. let's test what we
> do use in production, instead of something nobody uses for real, if
> we were adding a test for BUG() in vacuum, but why did we have to
> "fake" it in the first place?
> ...
> Are we sure that the reason no longer applies?  How do we know?  We
> would want to explain that to future developers in the proposed log
> message, I would think.

We can flip it the other way around.  

I do not think I ever saw anybody asked anybody on this list who got
a BUG() message to use the coredump to do something useful.  Don't
modern distros ship with "ulimit -c 0" these days?

It might be possible that a better direction is to introduce
GIT_ABORT_ON_BUG environment or core.abortOnBUG configuration that
chooses between abort() and exit(99), or something like that, and
then we switch to use the latter by default over time?

Re: [RFC PATCH 1/3] test-tool: don't fake up BUG() exits as code 99

[Ævar Arnfjörð Bjarmason]

On Fri, Jun 03 2022, Junio C Hamano wrote:

> Junio C Hamano <gitster@pobox.com> writes:
>
>>> However, in doing so we've been fooling ourselves when it comes to
>>> what trace2 events we log. The events tested for in
>>> 0a9dde4a04c (usage: trace2 BUG() invocations, 2021-02-05) are not the
>>> real ones, but those that we emit only from the "test-tool".
>>
>> I can fully agree with the above reasoning, i.e. let's test what we
>> do use in production, instead of something nobody uses for real, if
>> we were adding a test for BUG() in vacuum, but why did we have to
>> "fake" it in the first place?
>> ...
>> Are we sure that the reason no longer applies?  How do we know?  We
>> would want to explain that to future developers in the proposed log
>> message, I would think.
>
> We can flip it the other way around.  
>
> I do not think I ever saw anybody asked anybody on this list who got
> a BUG() message to use the coredump to do something useful.  Don't
> modern distros ship with "ulimit -c 0" these days?

I think that part of it was just a side-effect of SIGABRT.

> It might be possible that a better direction is to introduce
> GIT_ABORT_ON_BUG environment or core.abortOnBUG configuration that
> chooses between abort() and exit(99), or something like that, and
> then we switch to use the latter by default over time?

I think the reason for abort() was what's covered in raise(3), i.e. it's
a one-stop-shop to getting "stop it" behavior both under threading and
non-threading, which as e.g. exit(3) discusses wouldn't be thread-safe
with it.

But perhaps that was all premature worrying, we're mostly running
non-threaded, and to the extent that we ever BUG() running into exit(3)
threading issues is probably the least of our worries.

So perhaps we should drop abort() entirely, I don't know. These proposed
patches tried not to do that, but just to log things when we did so.

Re: [RFC PATCH 1/3] test-tool: don't fake up BUG() exits as code 99

[Jeff King]

On Fri, Jun 03, 2022 at 02:05:49PM -0700, Junio C Hamano wrote:

> > Are we sure that the reason no longer applies?  How do we know?  We
> > would want to explain that to future developers in the proposed log
> > message, I would think.
> 
> We can flip it the other way around.  
> 
> I do not think I ever saw anybody asked anybody on this list who got
> a BUG() message to use the coredump to do something useful.  Don't
> modern distros ship with "ulimit -c 0" these days?

Certainly I have found the coredumps useful, though I would expect most
Git developers to be able to run under a debugger and stop at BUG()
anyway. So we could probably live without that, but...

> It might be possible that a better direction is to introduce
> GIT_ABORT_ON_BUG environment or core.abortOnBUG configuration that
> chooses between abort() and exit(99), or something like that, and
> then we switch to use the latter by default over time?

It really should continue to die with a signal (or an exit code that
pretends to be one) to continue triggering even under test_must_fail().

IMHO the whole "let's trigger BUG() intentionally via test-tool" stuff
in t1406 is misguided. It's literally introducing broken code that is
not run in the normal Git binary in order to make sure that it's broken.
If that were the only spot, I'd suggest just getting rid of it entirely.
But the code in t0210 that checks the handling of trace2 and BUG() is
probably worth keeping.

I do agree that an environment variable would be a better selector than
"this code is linked against test-tool". I thought so even back in:

  https://lore.kernel.org/git/20180507090109.GA367@sigill.intra.peff.net/

:) That message also covers the flip-side case discussed earlier in this
thread: why calling abort() unconditionally in the test suite can be a
pain.

-Peff

Re: [RFC PATCH 1/3] test-tool: don't fake up BUG() exits as code 99

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> I do agree that an environment variable would be a better selector than
> "this code is linked against test-tool". I thought so even back in:
>
>   https://lore.kernel.org/git/20180507090109.GA367@sigill.intra.peff.net/
>
> :) That message also covers the flip-side case discussed earlier in this
> thread: why calling abort() unconditionally in the test suite can be a
> pain.

Nice.  Thanks.

Re: [RFC PATCH 1/3] test-tool: don't fake up BUG() exits as code 99

[Ævar Arnfjörð Bjarmason]

On Wed, Jun 08 2022, Jeff King wrote:

> On Fri, Jun 03, 2022 at 02:05:49PM -0700, Junio C Hamano wrote:
>
>> > Are we sure that the reason no longer applies?  How do we know?  We
>> > would want to explain that to future developers in the proposed log
>> > message, I would think.
>> 
>> We can flip it the other way around.  
>> 
>> I do not think I ever saw anybody asked anybody on this list who got
>> a BUG() message to use the coredump to do something useful.  Don't
>> modern distros ship with "ulimit -c 0" these days?
>
> Certainly I have found the coredumps useful, though I would expect most
> Git developers to be able to run under a debugger and stop at BUG()
> anyway. So we could probably live without that, but...
>
>> It might be possible that a better direction is to introduce
>> GIT_ABORT_ON_BUG environment or core.abortOnBUG configuration that
>> chooses between abort() and exit(99), or something like that, and
>> then we switch to use the latter by default over time?
>
> It really should continue to die with a signal (or an exit code that
> pretends to be one) to continue triggering even under test_must_fail().
>
> IMHO the whole "let's trigger BUG() intentionally via test-tool" stuff
> in t1406 is misguided. It's literally introducing broken code that is
> not run in the normal Git binary in order to make sure that it's broken.

I haven't looked at that ref code in particular, but in general adding
coverage for the case we actually expect to defend against with BUG()
via a test-tool is something I think we could use in more cases.

E.g. parse-options.c will BUG() out on various bad options structs,
there it makes sense to feed those bad structs in to make sure our
assertion code is doing what we still expect, but we don't have those
tests.

> If that were the only spot, I'd suggest just getting rid of it entirely.
> But the code in t0210 that checks the handling of trace2 and BUG() is
> probably worth keeping.

Yes, we definitely want to test what *actually* happens as far as 

> I do agree that an environment variable would be a better selector than
> "this code is linked against test-tool". I thought so even back in:
>
>   https://lore.kernel.org/git/20180507090109.GA367@sigill.intra.peff.net/
>
> :) That message also covers the flip-side case discussed earlier in this
> thread: why calling abort() unconditionally in the test suite can be a
> pain.

I didn't know about that Jenkins case, but in any case I think we can
probably stop worrying about this given that we haven't had complaints
about ac14de13b22 (t4058: explore duplicate tree entry handling in a bit
more detail, 2020-12-11) (although I've noticed in in "dmesg" before).

I.e. since v2.31.0 running the test suite has produced at least 2
segfaults per run:

    $ (sudo dmesg -c; ./t4058-diff-duplicates.sh) >/dev/null; sudo dmesg | grep segfault
    [17687265.247252] git[11336]: segfault at 40 ip 0000000000700916 sp 00007ffc10d5dda0 error 4 in git[405000+33d000]
    [17687265.297027] git[11397]: segfault at 40 ip 0000000000700916 sp 00007ffd7dfd5310 error 4 in git[405000+33d000]

Perhaps those tests aren't valuable, but I think that shows that the
GIT_BUG_ABORT approach you suggested should probably be tweaked to
instead be some test prereq like SEGFAULT_AND_ABORT_OK.

On the other hand those segfaults in t4058 should probably be converted
to a BUG()...

Re: [RFC PATCH 1/3] test-tool: don't fake up BUG() exits as code 99

[Jeff King]

On Thu, Jun 09, 2022 at 10:09:25AM +0200, Ævar Arnfjörð Bjarmason wrote:

> > IMHO the whole "let's trigger BUG() intentionally via test-tool" stuff
> > in t1406 is misguided. It's literally introducing broken code that is
> > not run in the normal Git binary in order to make sure that it's broken.
> 
> I haven't looked at that ref code in particular, but in general adding
> coverage for the case we actually expect to defend against with BUG()
> via a test-tool is something I think we could use in more cases.
> 
> E.g. parse-options.c will BUG() out on various bad options structs,
> there it makes sense to feed those bad structs in to make sure our
> assertion code is doing what we still expect, but we don't have those
> tests.

These seem like low-value tests to me. Once you've identified a case in
parse-options.c that should BUG(), it's not very many lines of code to
detect it and call the function. But to then create a test case,
including a harness that triggers the internal code in such a way that
is designed never to happen in the production code, seems much more
error prone to me.

I.e., it is very unlikely to me that such a test case will find an
actual problem, and it carries a lot of scaffolding cost.

Meanwhile the much more likely problem is that a BUG() can be triggered,
but we simply don't have test coverage of the right cases. Once you've
identified the case, the problem can be demonstrated (and fixed) in the
production code.

> I didn't know about that Jenkins case, but in any case I think we can
> probably stop worrying about this given that we haven't had complaints
> about ac14de13b22 (t4058: explore duplicate tree entry handling in a bit
> more detail, 2020-12-11) (although I've noticed in in "dmesg" before).

I didn't notice those ones. It's probable that the CI instance I was
using at GitHub changed under the hood. And GitHub is more likely than
most people to run git's test suite in a CI environment. :) So yeah, it
may not matter that much. I do still think dumping cores around the
filesystem (remembering that they do not always go into the trash
directory) and polluting the kernel log are a bit unfriendly. If we can
avoid it easily, it might be worth doing.

> On the other hand those segfaults in t4058 should probably be converted
> to a BUG()...

Agreed. Those stack-exhaustion ones (which were what originally alerted
me to the Jenkins issue) are hard to catch.

-Peff

Re: [RFC PATCH 1/3] test-tool: don't fake up BUG() exits as code 99

[Ævar Arnfjörð Bjarmason]

On Fri, Jun 03 2022, Junio C Hamano wrote:

> Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:
>
>> Change the BUG() function invoked be "test-tool" to be the "real" one,
>> instead of one that avoids producing core files. In
>> a86303cb5d5 (test-tool: help verifying BUG() code paths, 2018-05-02)
>> to test the (then recently added) BUG() function we faked up the
>> abort() in favor of an exit with code 99.
>>
>> However, in doing so we've been fooling ourselves when it comes to
>> what trace2 events we log. The events tested for in
>> 0a9dde4a04c (usage: trace2 BUG() invocations, 2021-02-05) are not the
>> real ones, but those that we emit only from the "test-tool".
>
> I can fully agree with the above reasoning, i.e. let's test what we
> do use in production, instead of something nobody uses for real, if
> we were adding a test for BUG() in vacuum, but why did we have to
> "fake" it in the first place?

Per a86303cb5d5 (test-tool: help verifying BUG() code paths, 2018-05-02)
I think it was to get rid of coredump clutter outside of trash
directories (which would require some non-standard config), which
doesn't seem worth it.

>> Let's just stop faking it, and call abort(). As a86303cb5d5 notes this
>> will produce core files on some OS's, but as the default behavior for
>> that is to dump them in the current directory they'll be placed in the
>> trash directory that we'll shortly me "rm -rf"-ing.
>
> Are we sure that the reason no longer applies?  How do we know?  We
> would want to explain that to future developers in the proposed log
> message, I would think.

I was trying to get the above across, i.e. that the reasoning still
applies, but that the fakery isn't worth it.

>> +	elif test_match_signal 6 $exit_code && list_contains "$_test_ok" sigabrt
>> +	then
>> +		return 0
>>  	elif test_match_signal 13 $exit_code && list_contains "$_test_ok" sigpipe
>
> Not a new problem, but these numberings are probably not very
> portable.  I am willing to take this as-is and let people on
> minority platforms complain ;-)

I'll test it better for portability before a non-RFC.

[RFC PATCH 2/3] refs API: rename "abort" callback to avoid macro clash

[Ævar Arnfjörð Bjarmason]

In a subsequent commit we'll add an abort() macro to wrap the abort(3)
function, unfortunately due to C syntax semantics having such a macro
would be a compilation error as long as we're invoking callbacks named
"abort()".

So let's rename the callback "abort" callback added in
3bc581b9406 (refs: introduce an iterator interface, 2016-06-18) to
"end", which is the alternate naming that commit itself discusses,
i.e. it says:

    * ref_iterator_advance(): move to the next reference in the iteration
    * ref_iterator_abort(): end the iteration before it is exhausted
    * ref_iterator_peel(): peel the reference currently being looked at

Just as "peel=peel we can change that "abort=end" pair to be
"end=end", let's leave "advance=move".

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---
 refs/debug.c          | 4 ++--
 refs/files-backend.c  | 4 ++--
 refs/iterator.c       | 8 ++++----
 refs/packed-backend.c | 2 +-
 refs/ref-cache.c      | 2 +-
 refs/refs-internal.h  | 2 +-
 6 files changed, 11 insertions(+), 11 deletions(-)

diff --git a/refs/debug.c b/refs/debug.c
index eed8bc94b04..3364a7fb261 100644
--- a/refs/debug.c
+++ b/refs/debug.c
@@ -214,7 +214,7 @@ static int debug_ref_iterator_abort(struct ref_iterator *ref_iterator)
 {
 	struct debug_ref_iterator *diter =
 		(struct debug_ref_iterator *)ref_iterator;
-	int res = diter->iter->vtable->abort(diter->iter);
+	int res = diter->iter->vtable->end(diter->iter);
 	trace_printf_key(&trace_refs, "iterator_abort: %d\n", res);
 	return res;
 }
@@ -222,7 +222,7 @@ static int debug_ref_iterator_abort(struct ref_iterator *ref_iterator)
 static struct ref_iterator_vtable debug_ref_iterator_vtable = {
 	.advance = debug_ref_iterator_advance,
 	.peel = debug_ref_iterator_peel,
-	.abort = debug_ref_iterator_abort,
+	.end = debug_ref_iterator_abort,
 };
 
 static struct ref_iterator *
diff --git a/refs/files-backend.c b/refs/files-backend.c
index 8db7882aacb..3f0dde4ae10 100644
--- a/refs/files-backend.c
+++ b/refs/files-backend.c
@@ -824,7 +824,7 @@ static int files_ref_iterator_abort(struct ref_iterator *ref_iterator)
 static struct ref_iterator_vtable files_ref_iterator_vtable = {
 	.advance = files_ref_iterator_advance,
 	.peel = files_ref_iterator_peel,
-	.abort = files_ref_iterator_abort,
+	.end = files_ref_iterator_abort,
 };
 
 static struct ref_iterator *files_ref_iterator_begin(
@@ -2224,7 +2224,7 @@ static int files_reflog_iterator_abort(struct ref_iterator *ref_iterator)
 static struct ref_iterator_vtable files_reflog_iterator_vtable = {
 	.advance = files_reflog_iterator_advance,
 	.peel = files_reflog_iterator_peel,
-	.abort = files_reflog_iterator_abort,
+	.end = files_reflog_iterator_abort,
 };
 
 static struct ref_iterator *reflog_iterator_begin(struct ref_store *ref_store,
diff --git a/refs/iterator.c b/refs/iterator.c
index b2e56bae1c6..f4a9546adb6 100644
--- a/refs/iterator.c
+++ b/refs/iterator.c
@@ -21,7 +21,7 @@ int ref_iterator_peel(struct ref_iterator *ref_iterator,
 
 int ref_iterator_abort(struct ref_iterator *ref_iterator)
 {
-	return ref_iterator->vtable->abort(ref_iterator);
+	return ref_iterator->vtable->end(ref_iterator);
 }
 
 void base_ref_iterator_init(struct ref_iterator *iter,
@@ -66,7 +66,7 @@ static int empty_ref_iterator_abort(struct ref_iterator *ref_iterator)
 static struct ref_iterator_vtable empty_ref_iterator_vtable = {
 	.advance = empty_ref_iterator_advance,
 	.peel = empty_ref_iterator_peel,
-	.abort = empty_ref_iterator_abort,
+	.end = empty_ref_iterator_abort,
 };
 
 struct ref_iterator *empty_ref_iterator_begin(void)
@@ -203,7 +203,7 @@ static int merge_ref_iterator_abort(struct ref_iterator *ref_iterator)
 static struct ref_iterator_vtable merge_ref_iterator_vtable = {
 	.advance = merge_ref_iterator_advance,
 	.peel = merge_ref_iterator_peel,
-	.abort = merge_ref_iterator_abort,
+	.end = merge_ref_iterator_abort,
 };
 
 struct ref_iterator *merge_ref_iterator_begin(
@@ -380,7 +380,7 @@ static int prefix_ref_iterator_abort(struct ref_iterator *ref_iterator)
 static struct ref_iterator_vtable prefix_ref_iterator_vtable = {
 	.advance = prefix_ref_iterator_advance,
 	.peel = prefix_ref_iterator_peel,
-	.abort = prefix_ref_iterator_abort,
+	.end = prefix_ref_iterator_abort,
 };
 
 struct ref_iterator *prefix_ref_iterator_begin(struct ref_iterator *iter0,
diff --git a/refs/packed-backend.c b/refs/packed-backend.c
index 97b68377673..ad23f734b0f 100644
--- a/refs/packed-backend.c
+++ b/refs/packed-backend.c
@@ -913,7 +913,7 @@ static int packed_ref_iterator_abort(struct ref_iterator *ref_iterator)
 static struct ref_iterator_vtable packed_ref_iterator_vtable = {
 	.advance = packed_ref_iterator_advance,
 	.peel = packed_ref_iterator_peel,
-	.abort = packed_ref_iterator_abort
+	.end = packed_ref_iterator_abort
 };
 
 static struct ref_iterator *packed_ref_iterator_begin(
diff --git a/refs/ref-cache.c b/refs/ref-cache.c
index 32afd8a40b0..b4acaac2fb5 100644
--- a/refs/ref-cache.c
+++ b/refs/ref-cache.c
@@ -458,7 +458,7 @@ static int cache_ref_iterator_abort(struct ref_iterator *ref_iterator)
 static struct ref_iterator_vtable cache_ref_iterator_vtable = {
 	.advance = cache_ref_iterator_advance,
 	.peel = cache_ref_iterator_peel,
-	.abort = cache_ref_iterator_abort
+	.end = cache_ref_iterator_abort
 };
 
 struct ref_iterator *cache_ref_iterator_begin(struct ref_cache *cache,
diff --git a/refs/refs-internal.h b/refs/refs-internal.h
index 69f93b0e2ac..7f462273fba 100644
--- a/refs/refs-internal.h
+++ b/refs/refs-internal.h
@@ -478,7 +478,7 @@ typedef int ref_iterator_abort_fn(struct ref_iterator *ref_iterator);
 struct ref_iterator_vtable {
 	ref_iterator_advance_fn *advance;
 	ref_iterator_peel_fn *peel;
-	ref_iterator_abort_fn *abort;
+	ref_iterator_abort_fn *end;
 };
 
 /*
-- 
2.36.1.1046.g586767a6996

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

[Ævar Arnfjörð Bjarmason]

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

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

[Bagas Sanjaya]

On Thu, May 26, 2022 at 02:30:44AM +0200, Ævar Arnfjörð Bjarmason wrote:
>  `"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".
>  +

The second 'this' can be elided, thus says "This event is emitted ...
and will be produced ...".

>  ------------
>  {
> @@ -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").
>  +

Looks OK.

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

So in case of BUG() trigger, there may not be exit event due to user
signal right? I'm expecting system (not user) signal in that case.

-- 
An old man doll... just what I always wanted! - Clara

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

[Josh Steadmon]

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
> 

Re: [RFC PATCH 0/3] trace2: log "signal" end events if we invoke BUG()

[Junio C Hamano]

Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:

> (depending on the TZ) that he'd encountered trace2 event streams
> without an "exit" event, which as discussed can be seen from usage.c
> is due to our invoking of abort() there.

Josh, is this related to the "in rare cases" thing we discussed on
the "run-command: don't spam trace2_child_exit()" thread?

https://lore.kernel.org/git/4616d09ffa632bd2c9e308a713c4bdf2a1328c3c.1651179450.git.steadmon@google.com/

Re: [RFC PATCH 0/3] trace2: log "signal" end events if we invoke BUG()

[Josh Steadmon]

On 2022.05.25 18:20, Junio C Hamano wrote:
> Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:
> 
> > (depending on the TZ) that he'd encountered trace2 event streams
> > without an "exit" event, which as discussed can be seen from usage.c
> > is due to our invoking of abort() there.
> 
> Josh, is this related to the "in rare cases" thing we discussed on
> the "run-command: don't spam trace2_child_exit()" thread?
> 
> https://lore.kernel.org/git/4616d09ffa632bd2c9e308a713c4bdf2a1328c3c.1651179450.git.steadmon@google.com/
> 

No, this is a much more frequent issue than the repeated "child_exit"
events from that thread. Any time Git exits without calling our exit()
wrapper, we don't log any "exit" events (and presumably skip "atexit"
as well).