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

Jonathan Tan [off-list ref] 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 <redacted>
---
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?

On Thu, Feb 04, 2021 at 10:17:29PM -0800, Junio C Hamano wrote:

Jonathan Tan [off-list ref] writes:

quoted

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

On 2/5/2021 4:01 AM, Jeff King wrote:

On Thu, Feb 04, 2021 at 10:17:29PM -0800, Junio C Hamano wrote:

quoted

Jonathan Tan [off-list ref] writes:

quoted

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

quoted

quoted

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

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

quoted

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

On 2/5/21 7:51 AM, Derrick Stolee wrote:

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