trace2: tolerate failed timestamp formatting

From: Derrick Stolee <[email protected]>

Some users reported issues of repeated messages:

fatal: recursion detected in die handler

This wasn't happening every time, but we eventually captured a GIT_TRACE2_PERF log file with this issue and revealed an interesting internal detail, failing with this message:

unable to format message: %4d-%02d-%02dT%02d:%02d:%02d.%06ldZ

This specific format string tracks to tr2_tbuf_utc_datetime_extended() in trace2/tr2_tbuf.c. This logic began as tr2_tbuf_utc_time() in ee4512ed481 (trace2: create new combined trace facility, 2019-02-22) but was later split in bad229aef23 (trace2: clarify UTC datetime formatting, 2019-04-15).

This use of xsnprintf() is writing a very specific datetime format into a 32-character buffer. The format requires that the input data will not overflow the format digits or the buffer will not hold the result. Since we are using xsnprintf() here, those failures turn into die() events.

This method and its siblings, tr2_tbuf_local_time() and tr2_tbuf_utc_datetime(), are used in the tracing library. The extended form is used only for the 'event' format, which these users were using via a config setting for use in client-side telemetry. The non-extended form is used to help generate the 'SID' that defines the process in the traces.

Not only are these inappropriate times for a failure, but the extended method is called specifially during the 'atexit' event, which was triggering this problem in a loop as the 'atexit' event would be retriggered by the die().

I could not determine the exact cause of why these errors started occuring in a bunch. My best guess is that these users are dogfooding an early operating system version that is more likely to fail in the gettimeofday() function and thus leaves the structures uninitialized and potentially violating the expected values.

However, for full defense-in-depth I made several modifications:

1. Both 'tv' and 'tm' structs are initialized with zero values, allowing an erroring gettimeofday() or gmtime_r() method to leave them zero-valued. A zero-valued date is better than a die() here.

2. Replace the use of xsnprintf() with snprintf() to avoid the possibility of calling die() here. Instead, check the response to see if there was a failure. On failure, put a blank value into the buffer instead of possibly allowing a value that would not format correctly for a trace2 consumer. This value should be seen as obviously wrong and therefore signals a problem.

As the core issue in this code seems to require a system method returning an error, no test accompanies this change.

This change removes all uses of xsnprintf() from the trace2/ directory. There are two uses of xstrdup() that could be considered for removal, but they only die() on out-of-memory errors instead of formatting issues. I chose to leave those in place for now.

---
trace2: tolerate failed timestamp formatting

As mentioned, this is based on real trace logs of failed commands users are seeing.

I wish I had a better way to test this or to be 100% sure that the system call was failing. But users were seeing failures and these seemed like appropriate changes.

Thanks, -Stolee

Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-2178%2Fderrickstolee%2Ftrace2-dont-die-v1
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-2178/derrickstolee/trace2-dont-die-v1
Pull-Request: https://github.com/gitgitgadget/git/pull/2178

 trace2/tr2_tbuf.c | 49 ++++++++++++++++++++++++++++++++---------------
 1 file changed, 34 insertions(+), 15 deletions(-)

index c3b3822ed7..ef57376f3c 100644
@@ -3,45 +3,64 @@
 
 void tr2_tbuf_local_time(struct tr2_tbuf *tb)
 {
-	struct timeval tv;
-	struct tm tm;
+	struct timeval tv = { 0 };
+	struct tm tm = { 0 };
 	time_t secs;
+	int len;
 
 	gettimeofday(&tv, NULL);
 	secs = tv.tv_sec;
 	localtime_r(&secs, &tm);
 
-	xsnprintf(tb->buf, sizeof(tb->buf), "%02d:%02d:%02d.%06ld", tm.tm_hour,
-		  tm.tm_min, tm.tm_sec, (long)tv.tv_usec);
+	len = snprintf(tb->buf, sizeof(tb->buf), "%02d:%02d:%02d.%06ld",
+		       tm.tm_hour, tm.tm_min, tm.tm_sec, (long)tv.tv_usec);
+
+	if (len < 0 || (size_t)len >= sizeof(tb->buf)) {
+		const char *blank = "00:00:00.000000";
+		strlcpy(tb->buf, blank, sizeof(tb->buf));
+	}
 }
 
 void tr2_tbuf_utc_datetime_extended(struct tr2_tbuf *tb)
 {
-	struct timeval tv;
-	struct tm tm;
+	struct timeval tv = { 0 };
+	struct tm tm = { 0 };
 	time_t secs;
+	int len;
 
 	gettimeofday(&tv, NULL);
 	secs = tv.tv_sec;
 	gmtime_r(&secs, &tm);
 
-	xsnprintf(tb->buf, sizeof(tb->buf),
-		  "%4d-%02d-%02dT%02d:%02d:%02d.%06ldZ", tm.tm_year + 1900,
-		  tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec,
-		  (long)tv.tv_usec);
+	len = snprintf(tb->buf, sizeof(tb->buf),
+		       "%4d-%02d-%02dT%02d:%02d:%02d.%06ldZ",
+		       tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
+		       tm.tm_hour, tm.tm_min, tm.tm_sec, (long)tv.tv_usec);
+
+	if (len < 0 || (size_t)len >= sizeof(tb->buf)) {
+		const char *blank = "1900-00-00T00:00:00.000000Z";
+		strlcpy(tb->buf, blank, sizeof(tb->buf));
+	}
 }
 
 void tr2_tbuf_utc_datetime(struct tr2_tbuf *tb)
 {
-	struct timeval tv;
-	struct tm tm;
+	struct timeval tv = { 0 };
+	struct tm tm = { 0 };
 	time_t secs;
+	int len;
 
 	gettimeofday(&tv, NULL);
 	secs = tv.tv_sec;
 	gmtime_r(&secs, &tm);
 
-	xsnprintf(tb->buf, sizeof(tb->buf), "%4d%02d%02dT%02d%02d%02d.%06ldZ",
-		  tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour,
-		  tm.tm_min, tm.tm_sec, (long)tv.tv_usec);
+	len = snprintf(tb->buf, sizeof(tb->buf),
+		       "%4d%02d%02dT%02d%02d%02d.%06ldZ",
+		       tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
+		       tm.tm_hour, tm.tm_min, tm.tm_sec, (long)tv.tv_usec);
+
+	if (len < 0 || (size_t)len >= sizeof(tb->buf)) {
+		const char *blank = "19000000T000000.000000Z";
+		strlcpy(tb->buf, blank, sizeof(tb->buf));
+	}
 }

base-commit: e9019fcafe0040228b8631c30f97ae1adb61bcdc

gitgitgadget

I may be missing some Git for Windows context, but I dug into this a little and I'm not sure 'gettimeofday()' is the culprit...

In my understanding Git for Windows's 'gettext.h' appears[1] to redirect the 'vsnprintf()' inside 'xsnprintf()' to 'libintl_vsnprintf()'. In this case, we have seven '%' placeholders. Gettext can store only six plus its end marker inline, so parsing the seventh causes an allocation before any timestamp values are read.

A failure there would produce the observed -1, after which 'xsnprintf()' dies and trace2 can recurse.

I think that also explains why calling 'snprintf()' directly helps. tr2_tbuf.c doesn't include gettext.h, so I think it bypasses libintl. If I'm reading compat/mingw.c correctly, 'gettimeofday()' fills tv and always returns zero [2], making the zero-initialization unrelated.

Would it make more sense to fix the xsnprintf()/libintl boundary and treat Trace2 reentrancy separately? I still can't explain why the allocation failed, so there may be another GfW-specific piece I’m missing.

I think something like the following (untested) would prevent the redirection to libintl_vsnprintf():

--- 8< ---

index 16f5a63fbb..2976d4e110 100644
@@ -7,7 +7,14 @@
 #include "git-compat-util.h"
 #include "abspath.h"
 #include "parse.h"
+
+/*
+ * xsnprintf() only formats non-translated strings. On MinGW, avoid
+ * redirecting its vsnprintf() call to libintl's allocating replacement.
+ */
+#define _INTL_NO_DEFINE_MACRO_VSNPRINTF
 #include "gettext.h"
+#undef _INTL_NO_DEFINE_MACRO_VSNPRINTF
 #include "strbuf.h"
 #include "trace2.h"
--- >8 ---

Thanks,
Taylor

[1]: https://github.com/git-for-windows/git-sdk-64/blob/1351ad2fc39a1f74c56b2cc2b38107ec8df8eb40/mingw64/include/libintl.h#L731-L754
[2]: https://github.com/microsoft/git/blob/vfs-2.55.0/compat/mingw.c#L1609-L1618

With this perspective, the issue is that gettext is doing dynamic allocation and getting a failure there, which explains the transient nature. This is an interesting idea, and a more likely "application side" error. I'm still curious why this is creeping up for the first time in this burst, since nothing has changed in the application, to my knowledge.

I think that your suggested change has merits and should be pursued. I'll explore it a bit to confirm.

The other justification I'd like to make in my patch is that the xsnprintf() calls die() and the trace2 machinery should be die()-free whenever possible. Solving both possible causes is likely the right long-term approach.

Thanks,
-Stolee

That band-aid may be a good idea, but I would prefer not to see the conditional in a common source file like 'wrapper.c'. Somewhere MinGW-specific would be more appropriate, would it not?

That is indeed worth considering.

You mention a few calls to xstrdup() that can potentially abort, and I agree that anything that triggers malloc() and notices that we are out of memory can probably do little better than to die. But are there other operations that may cause us to exit, even though we are not in an unrecoverable state (such as an out-of-memory condition)?

Thanks.

Yeah, to be clear, I do not think that putting the '#define' here in 'wrapper.c' is appropriate, and included it in my original email only to demonstrate the shape of the proposed solution.

Thanks,
Taylor

Did anything come out of this discussion?

Sorry that I've been unavailable to come back to this thread, but here is what I've learned in the meantime:

* Taylor's hunch that the memory allocation is more likely at fault is seeming more and more correct. When we fixed this issue, other issues around memory allocation came to light.

* For that reason, I'll rework this patch to point at the allocation as the likely reason the parsing fails. Avoiding a die() in the tracing code is still critical.

* Thus, I'll also replace the xstrdup() in the trace code to avoid a die() due to allocation problems.

* I will take a deeper look at this wrapper change and how it might be done in a careful way, as Taylor says his patch was an example only and not the "right" way to do it.

Thanks,
-Stolee

Thanks.

After v1 was posted, based on a concrete example of tracing leading to a recursive die() problem, more evidence has come up to imply that allocations are failing for some users more often. This is potentially an issue with the allocator chosen by Git for Windows, which is being discussed elsewhere.

But the conclusion is this: the trace2 API shouldn't call helpers that might call die(). It's too low-level for that.

In this v2, I have a much more robust approach to removing die() from the trace2 API.

This starts with a new banned-die.h header file at the root of the repo and including it from all trace2 API *.c files. It starts empty, but the later patches will add one method at a time:

* xsnprintf() : This is the original patch, but made more complete by adding the method to banned-die.h.
* xstrdup()
* ALLOC_ARRAY()
* xstrfmt()
* ALLOC_GROW()
* xcalloc()

During each patch, the goal was to have the trace2 logic be "as correct as possible" when an allocation failure occurs. This may mean that we have incomplete messages or dropped trace messages.

The focus here is that the trace2 API should never cause a process-ending failure, because those failures will trigger trace2 API calls while reporting the failure.

Thanks, -Stolee

Derrick Stolee (7):
banned-die: create header for banning of functions
trace2: tolerate failed timestamp formatting
trace2: remove use of xstrdup()
trace2: remove use of ALLOC_ARRAY()
trace2: remove use of xstrfmt()
trace2: remove use of ALLOC_GROW()
trace2: remove use of xcalloc()

 banned-die.h            | 32 +++++++++++++++++
 trace2.c                | 51 ++++++++++++++++++++++++---
 trace2/tr2_cfg.c        |  1 +
 trace2/tr2_cmd_name.c   |  1 +
 trace2/tr2_ctr.c        | 11 +++++-
 trace2/tr2_dst.c        |  1 +
 trace2/tr2_sid.c        |  1 +
 trace2/tr2_sysenv.c     |  7 ++--
 trace2/tr2_tbuf.c       | 50 +++++++++++++++++++--------
 trace2/tr2_tgt_event.c  |  1 +
 trace2/tr2_tgt_normal.c |  1 +
 trace2/tr2_tgt_perf.c   |  1 +
 trace2/tr2_tls.c        | 76 +++++++++++++++++++++++++++++++++++++++--
 trace2/tr2_tls.h        |  7 ++++
 trace2/tr2_tmr.c        | 15 ++++++--
 15 files changed, 229 insertions(+), 27 deletions(-)
 create mode 100644 banned-die.h

base-commit: e9019fcafe0040228b8631c30f97ae1adb61bcdc
Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-2178%2Fderrickstolee%2Ftrace2-dont-die-v2
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-2178/derrickstolee/trace2-dont-die-v2
Pull-Request: https://github.com/gitgitgadget/git/pull/2178

Range-diff vs v1:

 -:  ---------- > 1:  84634717e2 banned-die: create header for banning of functions
 1:  95c546bb3b ! 2:  bd45f46a34 trace2: tolerate failed timestamp formatting

@@ Commit message
triggering this problem in a loop as the 'atexit' event would be retriggered by the die().

- I could not determine the exact cause of why these errors started
- occuring in a bunch. My best guess is that these users are dogfooding an
- early operating system version that is more likely to fail in the
- gettimeofday() function and thus leaves the structures uninitialized and
- potentially violating the expected values.
+ Based on other symptoms impacting users on the version reporting these
+ failures, it is most likely that this is actually a failure to allocate
+ memory, which is a specific symptom in Git for Windows. That fork uses a
+ different library for its implementation of vsprintf() which allocates
+ an array when seven or more positional arguments exist in the formatting
+ string, such as this one.

- However, for full defense-in-depth I made several modifications:
+ Ultimately, the trace2 machinery is so low-level that it should not rely on
+ any helper functions that perform error handling with die(), as that can
+ trigger issues that would then be traced, causing this kind of recursive
+ loop.
+
+ These changes help remove any use of die() within this file:

1. Both 'tv' and 'tm' structs are initialized with zero values, allowing an erroring gettimeofday() or gmtime_r() method to leave them
@@ Commit message
but they only die() on out-of-memory errors instead of formatting issues. I chose to leave those in place for now.

+ Helped-by: Taylor Blau <[email protected]>

+ ## banned-die.h ##
+@@
+ #undef die
+ #define die banned(die)
+
++#undef xsnprintf
++#define xsnprintf(...) BANNED(xsnprintf)
++
+ #endif /* BANNED_DIE_H */
+
## trace2/tr2_tbuf.c ##
@@

 -:  ---------- > 3:  ec447a6a77 trace2: remove use of xstrdup()
 -:  ---------- > 4:  db6858d381 trace2: remove use of ALLOC_ARRAY()
 -:  ---------- > 5:  7f0bb405ad trace2: remove use of xstrfmt()
 -:  ---------- > 6:  120cf1967b trace2: remove use of ALLOC_GROW()
 -:  ---------- > 7:  c8fc195a2a trace2: remove use of xcalloc()

gitgitgadget

From: Derrick Stolee <[email protected]>

We have universally-banned functions listed in banned.h since c8af66ab8ad (automatically ban strcpy(), 2018-07-26), but some layers of the code should be more strict than others.

One such example is the trace2 API which runs during atexit() and can prove to cause die()-handler recursion problems if it calls die().

Create a new banned-die.h header file that will ban some Git methods that call die(). Include that in all trace2 API implementation files. This currently only bans die() itself, and that was already not used.

It would be reasonable to name this file trace2/tr2_banned.h to be specific to the trace2 API, but it seems like such a restriction would be valuable to put in some other areas of the code, so adding it at the root of the tree seems like a good long-term approach.

---
 banned-die.h            | 14 ++++++++++++++
 trace2.c                |  1 +
 trace2/tr2_cfg.c        |  1 +
 trace2/tr2_cmd_name.c   |  1 +
 trace2/tr2_ctr.c        |  1 +
 trace2/tr2_dst.c        |  1 +
 trace2/tr2_sid.c        |  1 +
 trace2/tr2_sysenv.c     |  1 +
 trace2/tr2_tbuf.c       |  1 +
 trace2/tr2_tgt_event.c  |  1 +
 trace2/tr2_tgt_normal.c |  1 +
 trace2/tr2_tgt_perf.c   |  1 +
 trace2/tr2_tls.c        |  1 +
 trace2/tr2_tmr.c        |  1 +
 14 files changed, 27 insertions(+)
 create mode 100644 banned-die.h

new file mode 100644
index 0000000000..5eff361e55
@@ -0,0 +1,14 @@
+#ifndef BANNED_DIE_H
+#define BANNED_DIE_H
+
+#include "banned.h"
+
+/*
+ * This header lists functions that must not be used by low-level APIs
+ * because they can cause Git to terminate.
+ */
+
+#undef die
+#define die banned(die)
+
+#endif /* BANNED_DIE_H */

index c23c0a227b..1d0ed2db2b 100644
@@ -17,6 +17,7 @@
 #include "trace2/tr2_tgt.h"
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_tmr.h"
+#include "banned-die.h"
 
 static int trace2_enabled;
 static int trace2_redact = 1;

index bbcfeda60a..06912a3ceb 100644
@@ -7,6 +7,7 @@
 #include "trace2/tr2_cfg.h"
 #include "trace2/tr2_sysenv.h"
 #include "wildmatch.h"
+#include "banned-die.h"
 
 static struct string_list tr2_cfg_patterns = STRING_LIST_INIT_DUP;
 static int tr2_cfg_loaded;

index b7b5a869b7..88f24e8781 100644
@@ -1,6 +1,7 @@
 #include "git-compat-util.h"
 #include "strbuf.h"
 #include "trace2/tr2_cmd_name.h"
+#include "banned-die.h"
 
 #define TR2_ENVVAR_PARENT_NAME "GIT_TRACE2_PARENT_NAME"
 

index ee17bfa86b..3067df4d18 100644
@@ -2,6 +2,7 @@
 #include "trace2/tr2_tgt.h"
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_ctr.h"
+#include "banned-die.h"
 
 /*
  * A global counter block to aggregate values from the partial sums

index 5be892cd5c..686a3e42fc 100644
@@ -5,6 +5,7 @@
 #include "trace2/tr2_dst.h"
 #include "trace2/tr2_sid.h"
 #include "trace2/tr2_sysenv.h"
+#include "banned-die.h"
 
 /*
  * How many attempts we will make at creating an automatically-named trace file.

index 1c1d27b0ee..358f61b301 100644
@@ -3,6 +3,7 @@
 #include "strbuf.h"
 #include "trace2/tr2_tbuf.h"
 #include "trace2/tr2_sid.h"
+#include "banned-die.h"
 
 #define TR2_ENVVAR_PARENT_SID "GIT_TRACE2_PARENT_SID"
 

index 4abc218514..deb3fabff4 100644
@@ -4,6 +4,7 @@
 #include "config.h"
 #include "dir.h"
 #include "tr2_sysenv.h"
+#include "banned-die.h"
 
 /*
  * Each entry represents a trace2 setting.

index c3b3822ed7..86725426f6 100644
@@ -1,5 +1,6 @@
 #include "git-compat-util.h"
 #include "tr2_tbuf.h"
+#include "banned-die.h"
 
 void tr2_tbuf_local_time(struct tr2_tbuf *tb)
 {

index 5a0381791f..a055e19bac 100644
@@ -13,6 +13,7 @@
 #include "trace2/tr2_tgt.h"
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_tmr.h"
+#include "banned-die.h"
 
 static struct tr2_dst tr2dst_event = {
 	.sysenv_var = TR2_SYSENV_EVENT,

index 924736ab36..97d4c5d202 100644
@@ -11,6 +11,7 @@
 #include "trace2/tr2_tgt.h"
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_tmr.h"
+#include "banned-die.h"
 
 static struct tr2_dst tr2dst_normal = {
 	.sysenv_var = TR2_SYSENV_NORMAL,

index 4eb9289f95..1f49d9f922 100644
@@ -14,6 +14,7 @@
 #include "trace2/tr2_tgt.h"
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_tmr.h"
+#include "banned-die.h"
 
 static struct tr2_dst tr2dst_perf = {
 	.sysenv_var = TR2_SYSENV_PERF,

index 7b023c1bfc..ae2d39d2f5 100644
@@ -3,6 +3,7 @@
 #include "thread-utils.h"
 #include "trace.h"
 #include "trace2/tr2_tls.h"
+#include "banned-die.h"
 
 /*
  * Initialize size of the thread stack for nested regions.

index 038181ad9b..a329c466b9 100644
@@ -3,6 +3,7 @@
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_tmr.h"
 #include "trace.h"
+#include "banned-die.h"
 
 #define MY_MAX(a, b) ((a) > (b) ? (a) : (b))
 #define MY_MIN(a, b) ((a) < (b) ? (a) : (b))

gitgitgadget

In other words, the functions banned by including this file are not listed because they are banned from being used in trace2 API, but because they may lead to die(). There may be some other traits that we might want to avoid in certain subset of our code, and we may have similar banned-frotz.h header to prevent direct or indirect use of frotz. Which makes sense to me.

Would the same approach work for the_hash_algo and the_repository, I wonder?

I'd be curious if it would satisfy two directions for those cases:

1. Help declare a subsystem is free of these globals and thus is ready for multi-hash or multi-repo handling.

2. Help declare a subsystem is _not_ free of these globals and thus should not be _reintroduced_ into a subsystem that was declared clean.

We'd need both, in general. And we'd need to continue expanding the banned-*.h files. I am curious as to whether there are static tools that could assist with this.

Thanks,
-Stolee

Don't we already do this? If USE_THE_REPOSITORY_VARIABLE is not defined then we hide several function declarations where we know that they depend on the_repository. It's not perfect as we still expose functions that do rely on it implicitly, but it's easy to remove more function declarations over time by just adding another ifdef.

Maybe we should follow a similar approach with functions that die?

Patrick

[...]

Oops. Yes, a mistake during a rebase.

There is a risk. The "must be last" part is documented in the header, but maybe it should be in a comment here, too.

Thanks,
-Stolee

There's a subtle but big difference between the universal code bans in banned.h and this banned-die.h. In the former case we are deciding strcpy() is unfit for our code base and outlawing it everywhere. The potential problem is in the source code, so catching it while compiling the source code is OK.

But we are not doing that with die(). It is a perfectly OK function in general, but we do not want to ever trigger its runtime effects from certain code paths. Banning it from being called from those code paths can catch _some_ instances, but not any transitive calls. If we call foo(), it may call die() itself, and we would not want to ban foo() from doing so. And recursively for functions called by foo() and so on.

So you end up playing whack-a-mole with functions that might call die() and adding them to this ban list.

I think that's _probably_ the best we can do in practice. I think the framing above suggests that we could approach the problem more directly with a runtime flag: when we enter those code paths, set a flag to avoid the unwanted behavior, and have the low-level code respect that. But die() is a special case here, because we'd want to suppress its no-return behavior. And its callers are not prepared for die() to suddenly start returning because of some global flag.

So I think the whack-a-mole is the best we can do. But I would not want to see this strategy extended to other areas. In most cases some kind of runtime support is probably a better solution.

-Peff

Yes, this makes it tricky to be 100% sure without some kind of static analysis.

This does have some benefit that we can gradually remove these transitive callers in the multi-commit series. But it's unsatisfying as a full protection in the end.

The other alternative that we could consider is to reorganize the codebase in such a way that certain sections of code don't have access to headers that could lead to die() or other "higher" methods that are acceptable for user-facing processes but are best to avoid in library APIs. Even then, we'd need some checks at compile time to avoid crossing boundaries.

I don't think such a reorganization is desirable overall, because that will be very disruptive to the project and file history.

Having some amount of protection through this header gives us a mechanism to demonstrate and enforce some protection.

Thanks,
-Stolee

From: Derrick Stolee <[email protected]>

Some users reported issues of repeated messages:

fatal: recursion detected in die handler

This wasn't happening every time, but we eventually captured a GIT_TRACE2_PERF log file with this issue and revealed an interesting internal detail, failing with this message:

unable to format message: %4d-%02d-%02dT%02d:%02d:%02d.%06ldZ

This specific format string tracks to tr2_tbuf_utc_datetime_extended() in trace2/tr2_tbuf.c. This logic began as tr2_tbuf_utc_time() in ee4512ed481 (trace2: create new combined trace facility, 2019-02-22) but was later split in bad229aef23 (trace2: clarify UTC datetime formatting, 2019-04-15).

This use of xsnprintf() is writing a very specific datetime format into a 32-character buffer. The format requires that the input data will not overflow the format digits or the buffer will not hold the result. Since we are using xsnprintf() here, those failures turn into die() events.

This method and its siblings, tr2_tbuf_local_time() and tr2_tbuf_utc_datetime(), are used in the tracing library. The extended form is used only for the 'event' format, which these users were using via a config setting for use in client-side telemetry. The non-extended form is used to help generate the 'SID' that defines the process in the traces.

Not only are these inappropriate times for a failure, but the extended method is called specifially during the 'atexit' event, which was triggering this problem in a loop as the 'atexit' event would be retriggered by the die().

Based on other symptoms impacting users on the version reporting these failures, it is most likely that this is actually a failure to allocate memory, which is a specific symptom in Git for Windows. That fork uses a different library for its implementation of vsprintf() which allocates an array when seven or more positional arguments exist in the formatting string, such as this one.

Ultimately, the trace2 machinery is so low-level that it should not rely on any helper functions that perform error handling with die(), as that can trigger issues that would then be traced, causing this kind of recursive loop.

These changes help remove any use of die() within this file:

1. Both 'tv' and 'tm' structs are initialized with zero values, allowing an erroring gettimeofday() or gmtime_r() method to leave them zero-valued. A zero-valued date is better than a die() here.

2. Replace the use of xsnprintf() with snprintf() to avoid the possibility of calling die() here. Instead, check the response to see if there was a failure. On failure, put a blank value into the buffer instead of possibly allowing a value that would not format correctly for a trace2 consumer. This value should be seen as obviously wrong and therefore signals a problem.

As the core issue in this code seems to require a system method returning an error, no test accompanies this change.

This change removes all uses of xsnprintf() from the trace2/ directory. There are two uses of xstrdup() that could be considered for removal, but they only die() on out-of-memory errors instead of formatting issues. I chose to leave those in place for now.

---
 banned-die.h      |  3 +++
 trace2/tr2_tbuf.c | 49 ++++++++++++++++++++++++++++++++---------------
 2 files changed, 37 insertions(+), 15 deletions(-)

index 5eff361e55..0e0a794e5d 100644
@@ -11,4 +11,7 @@
 #undef die
 #define die banned(die)
 
+#undef xsnprintf
+#define xsnprintf(...) BANNED(xsnprintf)
+
 #endif /* BANNED_DIE_H */

gitgitgadget

From: Derrick Stolee <[email protected]>

In the previous change, we removed a use of xsprintf() that caused a recursive die() loop when failing to allocate memory. The trace2 library is too low-level to be calling die(), especially because of these recursive loops that can occur during the die handler.

For full defense in depth, we remove the xstrdup() calls from trace2/tr2_sysenv.c.

First, in tr2_sysenv_cb(), we need to handle a failed assignment of the value with a negative return to halt the config parsing loop.

Second, in tr2_sysenv_get(), the method will return NULL when strdup() returns NULL. This return is indistinguishable from the environment variable having no value. That means that all callers know how to handle a NULL response, but no behavior change will occur between the case of no environment being set and detecting an environment variable exists but we fail to duplicate it. This seems an appropriate trade-off, as an allocation failure at this level will likely lead to failure in another system, but at least the trace2 API will not cause the process to fail early.

---
 banned-die.h        | 3 +++
 trace2/tr2_sysenv.c | 6 ++++--
 2 files changed, 7 insertions(+), 2 deletions(-)

index 0e0a794e5d..2e16c4899c 100644
@@ -14,4 +14,7 @@
 #undef xsnprintf
 #define xsnprintf(...) BANNED(xsnprintf)
 
+#undef xstrdup
+#define xstrdup(str) BANNED(xstrdup)
+
 #endif /* BANNED_DIE_H */

index deb3fabff4..4ee273a4ae 100644
@@ -74,7 +74,9 @@ static int tr2_sysenv_cb(const char *key, const char *value,
 			if (!value)
 				return config_error_nonbool(key);
 			free(tr2_sysenv_settings[k].value);
-			tr2_sysenv_settings[k].value = xstrdup(value);
+			tr2_sysenv_settings[k].value = strdup(value);
+			if (!tr2_sysenv_settings[k].value)
+				return -1;
 			return 0;
 		}
 	}

@@ -110,7 +112,7 @@ const char *tr2_sysenv_get(enum tr2_sysenv_variable var)
 		const char *v = getenv(tr2_sysenv_settings[var].env_var_name);
 		if (v && *v) {
 			free(tr2_sysenv_settings[var].value);
-			tr2_sysenv_settings[var].value = xstrdup(v);
+			tr2_sysenv_settings[var].value = strdup(v);
 		}
 		tr2_sysenv_settings[var].getenv_called = 1;
 	}

gitgitgadget

[...]

[...]

    config_with_options ->
      git_config_from_file_with_options ->
        do_config_from_file ->
          do_config_from ->
            git_parse_source ->
              get_value ->
                git_config_include ->
                  tr2_sysenv_cb

Thanks for the careful read! It's particularly important that we don't suggest that the config value is bad because we couldn't allocate memory.

Yes, I believe you are correct. We should return 0 to terminate early without a failure.

That said, I think that the die() in the config code will remain a "safe" place to die(), as we won't re-trigger this config-parsing code during any tracing of that die() message. But it's best to be safe and have the tracing continue to be "best effort" when system calls fail.

Thanks,
-Stolee

From: Derrick Stolee <[email protected]>

The banned-die.h header is used to prevent use of helper methods that call die(). Remove use of the ALLOC_ARRAY() helper, which calls die() on allocation failures. Replace the use in trace2.c with a more direct allocation and soft failure when allocation fails. This prevents die() recursion loops when memory allocation fails and trace2 logs are enabled.

The tricky part about this change is how to handle the results from redact_arg(), which is a 'const char *' result because it might be a pointer directly to the externally-controlled argument. When it is different from the argument, then it is indeed a newly-allocated string that we need to free before returning. This requires using a (char *) cast to allow a change.

---
 banned-die.h |  3 +++
 trace2.c     | 16 ++++++++++++++--
 2 files changed, 17 insertions(+), 2 deletions(-)

index 2e16c4899c..cb2eed75cd 100644
@@ -17,4 +17,7 @@
 #undef xstrdup
 #define xstrdup(str) BANNED(xstrdup)
 
+#undef ALLOC_ARRAY
+#define ALLOC_ARRAY(x, alloc) BANNED(ALLOC_ARRAY)
+
 #endif /* BANNED_DIE_H */

index 1d0ed2db2b..7044276435 100644
@@ -304,7 +304,11 @@ static const char **redact_argv(const char **argv)
 	for (j = 0; argv[j]; j++)
 		; /* keep counting */
 
-	ALLOC_ARRAY(ret, j + 1);
+	ret = calloc(j + 1, sizeof(*ret));
+	if (!ret) {
+		free((char *)redacted);
+		return NULL;
+	}
 	ret[j] = NULL;
 
 	for (j = 0; j < i; j++)

@@ -345,6 +349,8 @@ void trace2_cmd_start_fl(const char *file, int line, const char **argv)
 	us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 
 	redacted = redact_argv(argv);
+	if (!redacted)
+		return;
 
 	for_each_wanted_builtin (j, tgt_j)
 		if (tgt_j->pfn_start_fl)

@@ -513,6 +519,7 @@ void trace2_child_start_fl(const char *file, int line,
 	uint64_t us_now;
 	uint64_t us_elapsed_absolute;
 	const char **orig_argv = cmd->args.v;
+	const char **redacted;
 
 	if (!trace2_enabled)
 		return;

@@ -530,7 +537,10 @@ void trace2_child_start_fl(const char *file, int line,
 	 * temporarily replace the original argv (inside the `strvec`)
 	 * with a possibly redacted version.
 	 */
-	cmd->args.v = redact_argv(orig_argv);
+	redacted = redact_argv(orig_argv);
+	if (!redacted)
+		return;
+	cmd->args.v = redacted;
 
 	for_each_wanted_builtin (j, tgt_j)
 		if (tgt_j->pfn_child_start_fl)

@@ -622,6 +632,8 @@ int trace2_exec_fl(const char *file, int line, const char *exe,
 	exec_id = tr2tls_locked_increment(&tr2_next_exec_id);
 
 	redacted = redact_argv(argv);
+	if (!redacted)
+		return exec_id;
 
 	for_each_wanted_builtin (j, tgt_j)
 		if (tgt_j->pfn_exec_fl)

gitgitgadget

From: Derrick Stolee <[email protected]>

We continue removing the possibility of a die() in the trace2 API by banning xstrfmt(), which calls die() during a failure to format. Instead of allowing a die(), perform a soft failure by failing to output the trace2 data when such a failure occurs.

This requires carefully concatenating strings using memcpy() to construct redacted data to avoid copying password information in traced URLs.

---
 banned-die.h |  3 +++
 trace2.c     | 34 ++++++++++++++++++++++++++++++++--
 2 files changed, 35 insertions(+), 2 deletions(-)

index cb2eed75cd..14aecfdc7a 100644
@@ -17,6 +17,9 @@
 #undef xstrdup
 #define xstrdup(str) BANNED(xstrdup)
 
+#undef xstrfmt
+#define xstrfmt(...) BANNED(xstrfmt)
+
 #undef ALLOC_ARRAY
 #define ALLOC_ARRAY(x, alloc) BANNED(ALLOC_ARRAY)
 

index 7044276435..c37f783fa0 100644
@@ -260,7 +260,10 @@ int trace2_is_enabled(void)
 static const char *redact_arg(const char *arg)
 {
 	const char *p, *colon;
+	const char *redact = ":<REDACTED>";
+	char *redacted;
 	size_t at;
+	size_t prefix_len, suffix_len, redacted_len, redact_len;
 
 	if (!trace2_redact ||
 	    (!skip_prefix(arg, "https://", &p) &&

@@ -275,7 +278,25 @@ static const char *redact_arg(const char *arg)
 	if (!colon)
 		return arg;
 
-	return xstrfmt("%.*s:<REDACTED>%s", (int)(colon - arg), arg, p + at);
+	redact_len = strlen(redact);
+	prefix_len = colon - arg;
+	suffix_len = strlen(p + at);
+
+	if (unsigned_add_overflows(prefix_len, suffix_len) ||
+	    unsigned_add_overflows(prefix_len + suffix_len, redact_len))
+		return NULL;
+
+	redacted_len = prefix_len + suffix_len + redact_len;
+
+	redacted = malloc(redacted_len);
+	if (!redacted)
+		return NULL;
+
+	memcpy(redacted, arg, prefix_len);
+	memcpy(redacted + prefix_len, redact, redact_len - 1);
+	memcpy(redacted + prefix_len + redact_len - 1, p + at,
+	       suffix_len + 1);
+	return redacted;
 }
 
 /*

@@ -300,6 +321,8 @@ static const char **redact_argv(const char **argv)
 
 	if (!argv[i])
 		return argv;
+	if (!redacted)
+		return NULL;
 
 	for (j = 0; argv[j]; j++)
 		; /* keep counting */

@@ -316,7 +339,14 @@ static const char **redact_argv(const char **argv)
 	ret[i] = redacted;
 	for (++i; argv[i]; i++) {
 		redacted = redact_arg(argv[i]);
-		ret[i] = redacted ? redacted : argv[i];
+		if (!redacted) {
+			for (j = 0; j < i; j++)
+				if (ret[j] != argv[j])
+					free((void *)ret[j]);
+			free(ret);
+			return NULL;
+		}
+		ret[i] = redacted;
 	}
 
 	return ret;

gitgitgadget

[...]

[...]

Yeah, if it were (redact_len + 1) it would have worked better, perhaps?

I should have been more careful and realized that we don't have any tests that cover this logic.

We have tests for ":<redacted>" in pkt-line output, but not for the trace2 version.

Thanks,
-Stolee

From: Derrick Stolee <[email protected]>

The ALLOC_GROW() helper can call die() on a failed memory allocation. We need to remove this from the trace2 API code to prevent a recursive die() handler.

This helper is used to track the nested region stack. Use a new skipped_regions member to track how many times a region was entered without being added to the stack, and decrease that amount as we leave each region. This allows us to avoid a failure and instead stop deepening the stack, giving as much nesting behavior as possible without failing the entire process.

---
 banned-die.h     |  3 +++
 trace2/tr2_tls.c | 34 +++++++++++++++++++++++++++++++++-
 trace2/tr2_tls.h |  1 +
 3 files changed, 37 insertions(+), 1 deletion(-)

index 14aecfdc7a..423e7b607d 100644
@@ -23,4 +23,7 @@
 #undef ALLOC_ARRAY
 #define ALLOC_ARRAY(x, alloc) BANNED(ALLOC_ARRAY)
 
+#undef ALLOC_GROW
+#define ALLOC_GROW(x, nr, alloc) BANNED(ALLOC_GROW)
+
 #endif /* BANNED_DIE_H */

index ae2d39d2f5..8596292a94 100644
@@ -108,8 +108,33 @@ void tr2tls_unset_self(void)
 void tr2tls_push_self(uint64_t us_now)
 {
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+	uint64_t *new_array;
+	size_t new_alloc;
+
+	if (ctx->nr_skipped_regions) {
+		ctx->nr_skipped_regions++;
+		return;
+	}
+
+	if (ctx->nr_open_regions < ctx->alloc)
+		return;
+
+	if (ctx->alloc > SIZE_MAX / (2 * sizeof(*ctx->array_us_start))) {
+		ctx->nr_skipped_regions++;
+		return;
+	}
+	new_alloc = ctx->alloc * 2;
+
+	new_array = realloc(ctx->array_us_start,
+			    new_alloc * sizeof(*ctx->array_us_start));
+	if (!new_array) {
+		ctx->nr_skipped_regions++;
+		return;
+	}
+
+	ctx->array_us_start = new_array;
+	ctx->alloc = new_alloc;
 
-	ALLOC_GROW(ctx->array_us_start, ctx->nr_open_regions + 1, ctx->alloc);
 	ctx->array_us_start[ctx->nr_open_regions++] = us_now;
 }
 

@@ -117,6 +142,11 @@ void tr2tls_pop_self(void)
 {
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 
+	if (ctx->nr_skipped_regions) {
+		ctx->nr_skipped_regions--;
+		return;
+	}
+
 	if (!ctx->nr_open_regions)
 		BUG("no open regions in thread '%s'", ctx->thread_name);
 

@@ -137,6 +167,8 @@ uint64_t tr2tls_region_elasped_self(uint64_t us)
 	uint64_t us_start;
 
 	ctx = tr2tls_get_self();
+	if (ctx->nr_skipped_regions)
+		return 0;
 	if (!ctx->nr_open_regions)
 		return 0;
 

index 3bdbf4d275..c365017923 100644
@@ -20,6 +20,7 @@ struct tr2tls_thread_ctx {
 	uint64_t *array_us_start;
 	size_t alloc;
 	size_t nr_open_regions; /* plays role of "nr" in ALLOC_GROW */
+	size_t nr_skipped_regions;
 	int thread_id;
 	struct tr2_timer_block timer_block;
 	struct tr2_counter_block counter_block;

gitgitgadget

Checking out this commit and running

GIT_TRACE2_PERF=1 ./bin-wrappers/git status

dies with

no open regions in thread 'main'

Seems to be fixed by 7/7, though. Maybe a bad splitting?

From: Derrick Stolee <[email protected]>

Remove use of xcalloc() from the trace2 API due to its possible use of die(), which could lead to recursive die() handlers. This is used in the trace2 API to track an array of thread contexts when logging multi- threaded operations.

Instead of killing the process on a failure, we attempt to proceed as much as possible. We replace the dynamic thread context with a statically-allocated context that uses the "unknown" thread name to identify that we are in an error case.

---
 banned-die.h     |  3 ++
 trace2/tr2_ctr.c | 10 ++++++-
 trace2/tr2_tls.c | 73 ++++++++++++++++++++++++++++++++++++------------
 trace2/tr2_tls.h |  6 ++++
 trace2/tr2_tmr.c | 14 ++++++++--
 5 files changed, 85 insertions(+), 21 deletions(-)

index 423e7b607d..3dc521f6b0 100644
@@ -17,6 +17,9 @@
 #undef xstrdup
 #define xstrdup(str) BANNED(xstrdup)
 
+#undef xcalloc
+#define xcalloc(nmemb, size) BANNED(xcalloc)
+
 #undef xstrfmt
 #define xstrfmt(...) BANNED(xstrfmt)
 

index 3067df4d18..5283946e08 100644
@@ -54,7 +54,11 @@ static struct tr2_counter_metadata tr2_counter_metadata[TRACE2_NUMBER_OF_COUNTER
 void tr2_counter_increment(enum trace2_counter_id cid, uint64_t value)
 {
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
-	struct tr2_counter *c = &ctx->counter_block.counter[cid];
+	struct tr2_counter *c;
+
+	if (tr2tls_is_fallback(ctx))
+		return;
+	c = &ctx->counter_block.counter[cid];
 
 	c->value += value;
 

@@ -68,6 +72,8 @@ void tr2_update_final_counters(void)
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 	enum trace2_counter_id cid;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
 	if (!ctx->used_any_counter)
 		return;
 

@@ -89,6 +95,8 @@ void tr2_emit_per_thread_counters(tr2_tgt_evt_counter_t *fn_apply)
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 	enum trace2_counter_id cid;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
 	if (!ctx->used_any_per_thread_counter)
 		return;
 

index c365017923..4a0969c014 100644
@@ -54,6 +54,12 @@ struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_base_name,
  */
 struct tr2tls_thread_ctx *tr2tls_get_self(void);
 
+/*
+ * Return true if the context is the non-allocating fallback used after an
+ * allocation failure. Callers must not modify a fallback context.
+ */
+int tr2tls_is_fallback(const struct tr2tls_thread_ctx *ctx);
+
 /*
  * return true if the current thread is the main thread.
  */

index a329c466b9..b3d26e2b31 100644
@@ -38,8 +38,11 @@ static struct tr2_timer_metadata tr2_timer_metadata[TRACE2_NUMBER_OF_TIMERS] = {
 void tr2_start_timer(enum trace2_timer_id tid)
 {
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
-	struct tr2_timer *t = &ctx->timer_block.timer[tid];
+	struct tr2_timer *t;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
+	t = &ctx->timer_block.timer[tid];
 	t->recursion_count++;
 	if (t->recursion_count > 1)
 		return; /* ignore recursive starts */

@@ -50,10 +53,13 @@ void tr2_start_timer(enum trace2_timer_id tid)
 void tr2_stop_timer(enum trace2_timer_id tid)
 {
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
-	struct tr2_timer *t = &ctx->timer_block.timer[tid];
+	struct tr2_timer *t;
 	uint64_t ns_now;
 	uint64_t ns_interval;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
+	t = &ctx->timer_block.timer[tid];
 	assert(t->recursion_count > 0);
 
 	t->recursion_count--;

@@ -91,6 +97,8 @@ void tr2_update_final_timers(void)
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 	enum trace2_timer_id tid;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
 	if (!ctx->used_any_timer)
 		return;
 

@@ -137,6 +145,8 @@ void tr2_emit_per_thread_timers(tr2_tgt_evt_timer_t *fn_apply)
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 	enum trace2_timer_id tid;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
 	if (!ctx->used_any_per_thread_timer)
 		return;
 

gitgitgadget

OK. This feels like the tip of the iceberg, though. All of strbuf would have to be off-limits, too (both because it calls malloc directly, but also because it will bail if snprintf() returns -1). I won't be surprised if there are other indirect calls hiding in various places (e.g., all of json-writer.c).

I think if you really want to avoid allocations in trace2 it would probably need to be a ground-up no-dependency rewrite.

-Peff

You're absolutely right. Not only in json-writer.c, but several direct calls to the strbuf API. The only real way to fix that would be to create a "safe strbuf" library. This is potentially an interesting direction that I might want to pursue and send an RFC after getting started.

Or to update the dependencies to be "safe". Not an easy thing, either way.

I don't have much knowledge of CodeQL, but the following vibe-coded .ql script is able to detect these transitive calls and demonstrate the issue:

----

import cpp

class Trace2Function extends Function {
Trace2Function() {
getFile().getRelativePath() = "trace2.c" or getFile().getRelativePath().matches("trace2/%.c")
}
}

predicate directlyCalls(Function caller, Function callee) {
exists(FunctionCall call |
call.getEnclosingFunction() = caller and call.getTarget() = callee
)
}

from Trace2Function source, Function sink
where
sink.getName() = "die" and
directlyCalls+(source, sink)
select source, "This Trace2 function can transitively reach die()."

----

Adding such a check now would obviously fail and not provide any ability to demonstrate incremental progress like banned-die.h.

I know that microsoft/git is running CodeQL analysis to look for security issues [1] but doesn't appear to be running specific queries like this one.

[1] https://github.com/microsoft/git/commit/6b367b94752b7ae0fada0629a542e90ea0a1892c

Perhaps this is something we could investigate in the future.

Thanks,
-Stolee

Yes, though at some point the strbuf abstractions don't necessarily make sense, and you want to surface "did we truncate" or "did this result fit" to the caller.

So you probably end up with a whole new string interface (hopefully much more stripped down than what strbuf needs).

Yes. My thinking is that by the time you've pruned the dependencies, you've essentially done that rewrite. So maybe it is all just a matter of perspective. One man's refactor is another's rewrite, or something. :)

Yeah, I think the whack-a-mole can be solved with static analysis that actually understands the complete (possible) call tree. And then you wouldn't even really need your banned-die.h, because you'd have the real thing.

There's probably still a lot of work in rewriting the code to avoid those dependencies, though. And I fear you may hit some part that really needs to call into generic Git code in order to get an answer, which will be hard to pull apart. But maybe not; in theory we are feeding data into trace2, and it never really "asks" the rest of Git anything substantial.

-Peff

Just to be clear, I am not opposed to banned-die.h in the meantime if it is helpful to your goals. The whack-a-mole is not something I would choose to spend time on, but you are welcome to. ;)

-Peff

It's helpful in the sense that it demonstrates progress during the refactor, but it's less helpful as a long-term protection. Which you point out quite well.

I could easily send a v4 that removes patch 1 and all references to banned-die.h with a focus on "die() less in trace2" to start this reduction, but with the knowledge that it isn't sufficient, yet.

Thanks,
-Stolee

NOTE: this v3 is rebased onto a recent 'master' due to conflicts in a test script.

After v1 was posted, based on a concrete example of tracing leading to a recursive die() problem, more evidence has come up to imply that allocations are failing for some users more often. This is potentially an issue with the allocator chosen by Git for Windows, which is being discussed elsewhere.

But the conclusion is this: the trace2 API shouldn't call helpers that might call die(). It's too low-level for that.

In this v2, I have a much more robust approach to removing die() from the trace2 API.

This starts with a new banned-die.h header file at the root of the repo and including it from all trace2 API *.c files. It starts empty, but the later patches will add one method at a time:

* xsnprintf() : This is the original patch, but made more complete by adding the method to banned-die.h.
* xstrdup()
* ALLOC_ARRAY()
* xstrfmt()
* ALLOC_GROW()
* xcalloc()

During each patch, the goal was to have the trace2 logic be "as correct as possible" when an allocation failure occurs. This may mean that we have incomplete messages or dropped trace messages.

The focus here is that the trace2 API should never cause a process-ending failure, because those failures will trigger trace2 API calls while reporting the failure.

Updates in V3
=============

* Peff correctly points out that this is far from complete, as the strbuf library is not safe from die(). The banned-die.h provides incremental demonstration that these changes are showing progress and preventing regression in future changes, but not showing a complete picture. I will start an investigation into a "safe" or "gentle" variant of the strbuf API as a potential direction for these API layers.
* The first patch had a lowercase banned() that should have been uppercase BANNED().
* A 'return -1' was replaced with 'return 0' to avoid a misleading error message.
* The ":<REDACTED>" string length was incorrect. This is fixed and tests are improved to cover this string manipulation. These test changes conflict with changes to use test_grep in 47f79f61983 (t: convert grep assertions to test_grep, 2026-07-06), so this v3 is rebased onto 'master'.
* Patch 6 was previously failing at runtime. The appropriate fix is pulled out of patch 7 and into patch 6.

Thanks, -Stolee

Derrick Stolee (7):
banned-die: create header for banning of functions
trace2: tolerate failed timestamp formatting
trace2: remove use of xstrdup()
trace2: remove use of ALLOC_ARRAY()
trace2: remove use of xstrfmt()
trace2: remove use of ALLOC_GROW()
trace2: remove use of xcalloc()

 banned-die.h            | 32 +++++++++++++++++
 t/t0212-trace2-event.sh | 12 ++++---
 trace2.c                | 52 +++++++++++++++++++++++++---
 trace2/tr2_cfg.c        |  2 ++
 trace2/tr2_cmd_name.c   |  2 ++
 trace2/tr2_ctr.c        | 12 ++++++-
 trace2/tr2_dst.c        |  2 ++
 trace2/tr2_sid.c        |  2 ++
 trace2/tr2_sysenv.c     |  8 +++--
 trace2/tr2_tbuf.c       | 51 +++++++++++++++++++--------
 trace2/tr2_tgt_event.c  |  2 ++
 trace2/tr2_tgt_normal.c |  2 ++
 trace2/tr2_tgt_perf.c   |  2 ++
 trace2/tr2_tls.c        | 77 +++++++++++++++++++++++++++++++++++++++--
 trace2/tr2_tls.h        |  7 ++++
 trace2/tr2_tmr.c        | 16 +++++++--
 16 files changed, 250 insertions(+), 31 deletions(-)
 create mode 100644 banned-die.h

base-commit: c73e85354c275c9d409b26445089bc16940fc527
Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-2178%2Fderrickstolee%2Ftrace2-dont-die-v3
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-2178/derrickstolee/trace2-dont-die-v3
Pull-Request: https://github.com/gitgitgadget/git/pull/2178

Range-diff vs v2:

1: 84634717e2 ! 1: c483a4bf76 banned-die: create header for banning of functions

     @@ banned-die.h (new)
      + */
      +
      +#undef die
     -+#define die banned(die)
     ++#define die BANNED(die)
      +
      +#endif /* BANNED_DIE_H */
      
     @@ trace2.c
       #include "trace2/tr2_tgt.h"
       #include "trace2/tr2_tls.h"
       #include "trace2/tr2_tmr.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       static int trace2_enabled;
     @@ trace2/tr2_cfg.c
       #include "trace2/tr2_cfg.h"
       #include "trace2/tr2_sysenv.h"
       #include "wildmatch.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       static struct string_list tr2_cfg_patterns = STRING_LIST_INIT_DUP;
     @@ trace2/tr2_cmd_name.c
       #include "git-compat-util.h"
       #include "strbuf.h"
       #include "trace2/tr2_cmd_name.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       #define TR2_ENVVAR_PARENT_NAME "GIT_TRACE2_PARENT_NAME"
     @@ trace2/tr2_ctr.c
       #include "trace2/tr2_tgt.h"
       #include "trace2/tr2_tls.h"
       #include "trace2/tr2_ctr.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       /*
     @@ trace2/tr2_dst.c
       #include "trace2/tr2_dst.h"
       #include "trace2/tr2_sid.h"
       #include "trace2/tr2_sysenv.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       /*
     @@ trace2/tr2_sid.c
       #include "strbuf.h"
       #include "trace2/tr2_tbuf.h"
       #include "trace2/tr2_sid.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       #define TR2_ENVVAR_PARENT_SID "GIT_TRACE2_PARENT_SID"
     @@ trace2/tr2_sysenv.c
       #include "config.h"
       #include "dir.h"
       #include "tr2_sysenv.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       /*
     @@ trace2/tr2_tbuf.c
      @@
       #include "git-compat-util.h"
       #include "tr2_tbuf.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       void tr2_tbuf_local_time(struct tr2_tbuf *tb)
     @@ trace2/tr2_tgt_event.c
       #include "trace2/tr2_tgt.h"
       #include "trace2/tr2_tls.h"
       #include "trace2/tr2_tmr.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       static struct tr2_dst tr2dst_event = {
     @@ trace2/tr2_tgt_normal.c
       #include "trace2/tr2_tgt.h"
       #include "trace2/tr2_tls.h"
       #include "trace2/tr2_tmr.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       static struct tr2_dst tr2dst_normal = {
     @@ trace2/tr2_tgt_perf.c
       #include "trace2/tr2_tgt.h"
       #include "trace2/tr2_tls.h"
       #include "trace2/tr2_tmr.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       static struct tr2_dst tr2dst_perf = {
     @@ trace2/tr2_tls.c
       #include "thread-utils.h"
       #include "trace.h"
       #include "trace2/tr2_tls.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       /*
     @@ trace2/tr2_tmr.c
       #include "trace2/tr2_tls.h"
       #include "trace2/tr2_tmr.h"
       #include "trace.h"
     ++/* banned-die must be last. */
      +#include "banned-die.h"
       
       #define MY_MAX(a, b) ((a) > (b) ? (a) : (b))

2: bd45f46a34 ! 2: 754fffb74e trace2: tolerate failed timestamp formatting
@@ Commit message
## banned-die.h ##
@@
#undef die
- #define die banned(die)
+ #define die BANNED(die)

+#undef xsnprintf
+#define xsnprintf(...) BANNED(xsnprintf)
3: ec447a6a77 ! 3: 87d3f1b557 trace2: remove use of xstrdup()
@@ Commit message
trace2/tr2_sysenv.c.

First, in tr2_sysenv_cb(), we need to handle a failed assignment of the
- value with a negative return to halt the config parsing loop.
+ value with a zero-valued return to halt the config parsing loop. Note
+ that we don't want to use a negative return here or we would imply to
+ the config system that the config key or value was somehow invalid; such
+ an output would mask the real issue that the process failed to allocate
+ memory.

Second, in tr2_sysenv_get(), the method will return NULL when strdup() returns NULL. This return is indistinguishable from the environment variable
@@ Commit message
failure at this level will likely lead to failure in another system, but at least the trace2 API will not cause the process to fail early.

+ Helped-by: Elijah Newren <[email protected]>

## banned-die.h ##
@@ trace2/tr2_sysenv.c: static int tr2_sysenv_cb(const char *key, const char *value
- tr2_sysenv_settings[k].value = xstrdup(value);
+ tr2_sysenv_settings[k].value = strdup(value);
+ if (!tr2_sysenv_settings[k].value)
-+ return -1;
++ return 0;
return 0;
}
}

 4:  db6858d381 = 4:  5bf6ab91f3 trace2: remove use of ALLOC_ARRAY()
 5:  7f0bb405ad ! 5:  3e419c5522 trace2: remove use of xstrfmt()

@@ Commit message
construct redacted data to avoid copying password information in traced URLs.

+ Update t0212 to more carefully test this behavior to explicitly include
+ the ":<REDACTED>" string in the appropriate context.
+
+ Helped-by: Elijah Newren <[email protected]>

## banned-die.h ##
@@ banned-die.h
#define ALLOC_ARRAY(x, alloc) BANNED(ALLOC_ARRAY)

+ ## t/t0212-trace2-event.sh ##
+@@ t/t0212-trace2-event.sh: test_expect_success 'unsafe URLs are redacted by default in cmd_start events' ' +
+ GIT_TRACE2_EVENT="$(pwd)/trace.event" \
+ test-tool trace2 300redact_start git clone https://user:[email protected]/ clone2 &&
+- test_grep ! user:pwd trace.event
++ test_grep ! user:pwd trace.event &&
++ test_grep "user:<REDACTED>@example.com/" trace.event
+ '
+
+ test_expect_success 'unsafe URLs are redacted by default in child_start events' '
+@@ t/t0212-trace2-event.sh: test_expect_success 'unsafe URLs are redacted by default in child_start events' +
+ GIT_TRACE2_EVENT="$(pwd)/trace.event" \
+ test-tool trace2 301redact_child_start git clone https://user:[email protected]/ clone2 &&
+- test_grep ! user:pwd trace.event
++ test_grep ! user:pwd trace.event &&
++ test_grep "user:<REDACTED>@example.com/" trace.event
+ '
+
+ test_expect_success 'unsafe URLs are redacted by default in exec events' '
+@@ t/t0212-trace2-event.sh: test_expect_success 'unsafe URLs are redacted by default in exec events' ' +
+ GIT_TRACE2_EVENT="$(pwd)/trace.event" \
+ test-tool trace2 302redact_exec git clone https://user:[email protected]/ clone2 &&
+- test_grep ! user:pwd trace.event
++ test_grep ! user:pwd trace.event &&
++ test_grep "user:<REDACTED>@example.com/" trace.event
+ '
+
+ test_expect_success 'unsafe URLs are redacted by default in def_param events' '
+@@ t/t0212-trace2-event.sh: test_expect_success 'unsafe URLs are redacted by default in def_param events' ' +
+ GIT_TRACE2_EVENT="$(pwd)/trace.event" \
+ test-tool trace2 303redact_def_param url https://user:[email protected]/ &&
+- test_grep ! user:pwd trace.event
++ test_grep ! user:pwd trace.event &&
++ test_grep "user:<REDACTED>@example.com/" trace.event
+ '
+
+ test_done
+
## trace2.c ##
@@ trace2.c: int trace2_is_enabled(void)
static const char *redact_arg(const char *arg)
@@ trace2.c: static const char *redact_arg(const char *arg)
+ suffix_len = strlen(p + at);
+
+ if (unsigned_add_overflows(prefix_len, suffix_len) ||
-+ unsigned_add_overflows(prefix_len + suffix_len, redact_len))
++ unsigned_add_overflows(prefix_len + suffix_len, redact_len) ||
++ unsigned_add_overflows(prefix_len + suffix_len + redact_len, 1))
+ return NULL;
+
-+ redacted_len = prefix_len + suffix_len + redact_len;
++ redacted_len = prefix_len + suffix_len + redact_len + 1;
+
+ redacted = malloc(redacted_len);
+ if (!redacted)
+ return NULL;
+
+ memcpy(redacted, arg, prefix_len);
-+ memcpy(redacted + prefix_len, redact, redact_len - 1);
-+ memcpy(redacted + prefix_len + redact_len - 1, p + at,
-+ suffix_len + 1);
++ memcpy(redacted + prefix_len, redact, redact_len);
++ memcpy(redacted + prefix_len + redact_len, p + at, suffix_len + 1);
+ return redacted;
}

6: 120cf1967b ! 6: ccd284fbeb trace2: remove use of ALLOC_GROW()

     @@ Commit message
          deepening the stack, giving as much nesting behavior as possible without
          failing the entire process.
      
     +    Helped-by: Elijah Newren <[email protected]>
          Signed-off-by: Derrick Stolee <[email protected]>
      
       ## banned-die.h ##
     @@ trace2/tr2_tls.c: void tr2tls_unset_self(void)
      +		return;
      +	}
      +
     -+	if (ctx->nr_open_regions < ctx->alloc)
     -+		return;
     ++	if (ctx->nr_open_regions >= ctx->alloc) {
     ++		if (ctx->alloc >
     ++		    SIZE_MAX / (2 * sizeof(*ctx->array_us_start))) {
     ++			ctx->nr_skipped_regions++;
     ++			return;
     ++		}
     ++		new_alloc = ctx->alloc * 2;
      +
     -+	if (ctx->alloc > SIZE_MAX / (2 * sizeof(*ctx->array_us_start))) {
     -+		ctx->nr_skipped_regions++;
     -+		return;
     -+	}
     -+	new_alloc = ctx->alloc * 2;
     ++		new_array = realloc(ctx->array_us_start,
     ++				    new_alloc * sizeof(*ctx->array_us_start));
     ++		if (!new_array) {
     ++			ctx->nr_skipped_regions++;
     ++			return;
     ++		}
      +
     -+	new_array = realloc(ctx->array_us_start,
     -+			    new_alloc * sizeof(*ctx->array_us_start));
     -+	if (!new_array) {
     -+		ctx->nr_skipped_regions++;
     -+		return;
     ++		ctx->array_us_start = new_array;
     ++		ctx->alloc = new_alloc;
      +	}
     -+
     -+	ctx->array_us_start = new_array;
     -+	ctx->alloc = new_alloc;
       
      -	ALLOC_GROW(ctx->array_us_start, ctx->nr_open_regions + 1, ctx->alloc);
       	ctx->array_us_start[ctx->nr_open_regions++] = us_now;
 7:  c8fc195a2a ! 7:  fa10e8d246 trace2: remove use of xcalloc()
     @@ trace2/tr2_tls.c: void tr2tls_push_self(uint64_t us_now)
       	uint64_t *new_array;
       	size_t new_alloc;
       
     --	if (ctx->nr_skipped_regions) {
     --		ctx->nr_skipped_regions++;
     --		return;
     --	}
     --
     --	if (ctx->nr_open_regions < ctx->alloc)
      +	if (tr2tls_is_fallback(ctx))
     - 		return;
     - 
     --	if (ctx->alloc > SIZE_MAX / (2 * sizeof(*ctx->array_us_start))) {
     -+	if (ctx->nr_skipped_regions) {
     ++		return;
     ++
     + 	if (ctx->nr_skipped_regions) {
       		ctx->nr_skipped_regions++;
       		return;
     - 	}
     --	new_alloc = ctx->alloc * 2;
     - 
     --	new_array = realloc(ctx->array_us_start,
     --			    new_alloc * sizeof(*ctx->array_us_start));
     --	if (!new_array) {
     --		ctx->nr_skipped_regions++;
     --		return;
     -+	if (ctx->nr_open_regions >= ctx->alloc) {
     -+		if (ctx->alloc >
     -+		    SIZE_MAX / (2 * sizeof(*ctx->array_us_start))) {
     -+			ctx->nr_skipped_regions++;
     -+			return;
     -+		}
     -+		new_alloc = ctx->alloc * 2;
     -+
     -+		new_array = realloc(ctx->array_us_start,
     -+				    new_alloc * sizeof(*ctx->array_us_start));
     -+		if (!new_array) {
     -+			ctx->nr_skipped_regions++;
     -+			return;
     -+		}
     -+
     -+		ctx->array_us_start = new_array;
     -+		ctx->alloc = new_alloc;
     - 	}
     - 
     --	ctx->array_us_start = new_array;
     --	ctx->alloc = new_alloc;
     --
     - 	ctx->array_us_start[ctx->nr_open_regions++] = us_now;
     - }
     - 
      @@ trace2/tr2_tls.c: void tr2tls_pop_self(void)
       {
       	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();

gitgitgadget

From: Derrick Stolee <[email protected]>

We have universally-banned functions listed in banned.h since c8af66ab8ad (automatically ban strcpy(), 2018-07-26), but some layers of the code should be more strict than others.

One such example is the trace2 API which runs during atexit() and can prove to cause die()-handler recursion problems if it calls die().

Create a new banned-die.h header file that will ban some Git methods that call die(). Include that in all trace2 API implementation files. This currently only bans die() itself, and that was already not used.

It would be reasonable to name this file trace2/tr2_banned.h to be specific to the trace2 API, but it seems like such a restriction would be valuable to put in some other areas of the code, so adding it at the root of the tree seems like a good long-term approach.

---
 banned-die.h            | 14 ++++++++++++++
 trace2.c                |  2 ++
 trace2/tr2_cfg.c        |  2 ++
 trace2/tr2_cmd_name.c   |  2 ++
 trace2/tr2_ctr.c        |  2 ++
 trace2/tr2_dst.c        |  2 ++
 trace2/tr2_sid.c        |  2 ++
 trace2/tr2_sysenv.c     |  2 ++
 trace2/tr2_tbuf.c       |  2 ++
 trace2/tr2_tgt_event.c  |  2 ++
 trace2/tr2_tgt_normal.c |  2 ++
 trace2/tr2_tgt_perf.c   |  2 ++
 trace2/tr2_tls.c        |  2 ++
 trace2/tr2_tmr.c        |  2 ++
 14 files changed, 40 insertions(+)
 create mode 100644 banned-die.h

new file mode 100644
index 0000000000..1cde4035c1
@@ -0,0 +1,14 @@
+#ifndef BANNED_DIE_H
+#define BANNED_DIE_H
+
+#include "banned.h"
+
+/*
+ * This header lists functions that must not be used by low-level APIs
+ * because they can cause Git to terminate.
+ */
+
+#undef die
+#define die BANNED(die)
+
+#endif /* BANNED_DIE_H */

index c23c0a227b..8c974dee87 100644
@@ -17,6 +17,8 @@
 #include "trace2/tr2_tgt.h"
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_tmr.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 static int trace2_enabled;
 static int trace2_redact = 1;

index bbcfeda60a..757dfeae8d 100644
@@ -7,6 +7,8 @@
 #include "trace2/tr2_cfg.h"
 #include "trace2/tr2_sysenv.h"
 #include "wildmatch.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 static struct string_list tr2_cfg_patterns = STRING_LIST_INIT_DUP;
 static int tr2_cfg_loaded;

index b7b5a869b7..f378bef4cf 100644
@@ -1,6 +1,8 @@
 #include "git-compat-util.h"
 #include "strbuf.h"
 #include "trace2/tr2_cmd_name.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 #define TR2_ENVVAR_PARENT_NAME "GIT_TRACE2_PARENT_NAME"
 

index ee17bfa86b..20618a65b2 100644
@@ -2,6 +2,8 @@
 #include "trace2/tr2_tgt.h"
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_ctr.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 /*
  * A global counter block to aggregate values from the partial sums

index 5be892cd5c..555ac7cb9e 100644
@@ -5,6 +5,8 @@
 #include "trace2/tr2_dst.h"
 #include "trace2/tr2_sid.h"
 #include "trace2/tr2_sysenv.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 /*
  * How many attempts we will make at creating an automatically-named trace file.

index 131b4f5a62..1d4f018f66 100644
@@ -3,6 +3,8 @@
 #include "strbuf.h"
 #include "trace2/tr2_tbuf.h"
 #include "trace2/tr2_sid.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 #define TR2_ENVVAR_PARENT_SID "GIT_TRACE2_PARENT_SID"
 

index 4abc218514..7fa58eba91 100644
@@ -4,6 +4,8 @@
 #include "config.h"
 #include "dir.h"
 #include "tr2_sysenv.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 /*
  * Each entry represents a trace2 setting.

index c3b3822ed7..d623e55a81 100644
@@ -1,5 +1,7 @@
 #include "git-compat-util.h"
 #include "tr2_tbuf.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 void tr2_tbuf_local_time(struct tr2_tbuf *tb)
 {

index 5a0381791f..36a746cc10 100644
@@ -13,6 +13,8 @@
 #include "trace2/tr2_tgt.h"
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_tmr.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 static struct tr2_dst tr2dst_event = {
 	.sysenv_var = TR2_SYSENV_EVENT,

index 924736ab36..82995e510f 100644
@@ -11,6 +11,8 @@
 #include "trace2/tr2_tgt.h"
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_tmr.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 static struct tr2_dst tr2dst_normal = {
 	.sysenv_var = TR2_SYSENV_NORMAL,

index 4eb9289f95..96a5bc7f10 100644
@@ -14,6 +14,8 @@
 #include "trace2/tr2_tgt.h"
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_tmr.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 static struct tr2_dst tr2dst_perf = {
 	.sysenv_var = TR2_SYSENV_PERF,

index 7b023c1bfc..49bd505d62 100644
@@ -3,6 +3,8 @@
 #include "thread-utils.h"
 #include "trace.h"
 #include "trace2/tr2_tls.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 /*
  * Initialize size of the thread stack for nested regions.

index 038181ad9b..275091c693 100644
@@ -3,6 +3,8 @@
 #include "trace2/tr2_tls.h"
 #include "trace2/tr2_tmr.h"
 #include "trace.h"
+/* banned-die must be last. */
+#include "banned-die.h"
 
 #define MY_MAX(a, b) ((a) > (b) ? (a) : (b))
 #define MY_MIN(a, b) ((a) < (b) ? (a) : (b))

gitgitgadget

From: Derrick Stolee <[email protected]>

Some users reported issues of repeated messages:

fatal: recursion detected in die handler

This wasn't happening every time, but we eventually captured a GIT_TRACE2_PERF log file with this issue and revealed an interesting internal detail, failing with this message:

unable to format message: %4d-%02d-%02dT%02d:%02d:%02d.%06ldZ

This specific format string tracks to tr2_tbuf_utc_datetime_extended() in trace2/tr2_tbuf.c. This logic began as tr2_tbuf_utc_time() in ee4512ed481 (trace2: create new combined trace facility, 2019-02-22) but was later split in bad229aef23 (trace2: clarify UTC datetime formatting, 2019-04-15).

This use of xsnprintf() is writing a very specific datetime format into a 32-character buffer. The format requires that the input data will not overflow the format digits or the buffer will not hold the result. Since we are using xsnprintf() here, those failures turn into die() events.

This method and its siblings, tr2_tbuf_local_time() and tr2_tbuf_utc_datetime(), are used in the tracing library. The extended form is used only for the 'event' format, which these users were using via a config setting for use in client-side telemetry. The non-extended form is used to help generate the 'SID' that defines the process in the traces.

Not only are these inappropriate times for a failure, but the extended method is called specifially during the 'atexit' event, which was triggering this problem in a loop as the 'atexit' event would be retriggered by the die().

Based on other symptoms impacting users on the version reporting these failures, it is most likely that this is actually a failure to allocate memory, which is a specific symptom in Git for Windows. That fork uses a different library for its implementation of vsprintf() which allocates an array when seven or more positional arguments exist in the formatting string, such as this one.

Ultimately, the trace2 machinery is so low-level that it should not rely on any helper functions that perform error handling with die(), as that can trigger issues that would then be traced, causing this kind of recursive loop.

These changes help remove any use of die() within this file:

1. Both 'tv' and 'tm' structs are initialized with zero values, allowing an erroring gettimeofday() or gmtime_r() method to leave them zero-valued. A zero-valued date is better than a die() here.

2. Replace the use of xsnprintf() with snprintf() to avoid the possibility of calling die() here. Instead, check the response to see if there was a failure. On failure, put a blank value into the buffer instead of possibly allowing a value that would not format correctly for a trace2 consumer. This value should be seen as obviously wrong and therefore signals a problem.

As the core issue in this code seems to require a system method returning an error, no test accompanies this change.

This change removes all uses of xsnprintf() from the trace2/ directory. There are two uses of xstrdup() that could be considered for removal, but they only die() on out-of-memory errors instead of formatting issues. I chose to leave those in place for now.

---
 banned-die.h      |  3 +++
 trace2/tr2_tbuf.c | 49 ++++++++++++++++++++++++++++++++---------------
 2 files changed, 37 insertions(+), 15 deletions(-)

index 1cde4035c1..589e9cc2bd 100644
@@ -11,4 +11,7 @@
 #undef die
 #define die BANNED(die)
 
+#undef xsnprintf
+#define xsnprintf(...) BANNED(xsnprintf)
+
 #endif /* BANNED_DIE_H */

gitgitgadget

From: Derrick Stolee <[email protected]>

In the previous change, we removed a use of xsprintf() that caused a recursive die() loop when failing to allocate memory. The trace2 library is too low-level to be calling die(), especially because of these recursive loops that can occur during the die handler.

For full defense in depth, we remove the xstrdup() calls from trace2/tr2_sysenv.c.

First, in tr2_sysenv_cb(), we need to handle a failed assignment of the value with a zero-valued return to halt the config parsing loop. Note that we don't want to use a negative return here or we would imply to the config system that the config key or value was somehow invalid; such an output would mask the real issue that the process failed to allocate memory.

Second, in tr2_sysenv_get(), the method will return NULL when strdup() returns NULL. This return is indistinguishable from the environment variable having no value. That means that all callers know how to handle a NULL response, but no behavior change will occur between the case of no environment being set and detecting an environment variable exists but we fail to duplicate it. This seems an appropriate trade-off, as an allocation failure at this level will likely lead to failure in another system, but at least the trace2 API will not cause the process to fail early.

---
 banned-die.h        | 3 +++
 trace2/tr2_sysenv.c | 6 ++++--
 2 files changed, 7 insertions(+), 2 deletions(-)

index 589e9cc2bd..bf16ec5ba9 100644
@@ -14,4 +14,7 @@
 #undef xsnprintf
 #define xsnprintf(...) BANNED(xsnprintf)
 
+#undef xstrdup
+#define xstrdup(str) BANNED(xstrdup)
+
 #endif /* BANNED_DIE_H */

index 7fa58eba91..4a9983caf4 100644
@@ -75,7 +75,9 @@ static int tr2_sysenv_cb(const char *key, const char *value,
 			if (!value)
 				return config_error_nonbool(key);
 			free(tr2_sysenv_settings[k].value);
-			tr2_sysenv_settings[k].value = xstrdup(value);
+			tr2_sysenv_settings[k].value = strdup(value);
+			if (!tr2_sysenv_settings[k].value)
+				return 0;
 			return 0;
 		}
 	}

@@ -111,7 +113,7 @@ const char *tr2_sysenv_get(enum tr2_sysenv_variable var)
 		const char *v = getenv(tr2_sysenv_settings[var].env_var_name);
 		if (v && *v) {
 			free(tr2_sysenv_settings[var].value);
-			tr2_sysenv_settings[var].value = xstrdup(v);
+			tr2_sysenv_settings[var].value = strdup(v);
 		}
 		tr2_sysenv_settings[var].getenv_called = 1;
 	}

gitgitgadget

From: Derrick Stolee <[email protected]>

The banned-die.h header is used to prevent use of helper methods that call die(). Remove use of the ALLOC_ARRAY() helper, which calls die() on allocation failures. Replace the use in trace2.c with a more direct allocation and soft failure when allocation fails. This prevents die() recursion loops when memory allocation fails and trace2 logs are enabled.

The tricky part about this change is how to handle the results from redact_arg(), which is a 'const char *' result because it might be a pointer directly to the externally-controlled argument. When it is different from the argument, then it is indeed a newly-allocated string that we need to free before returning. This requires using a (char *) cast to allow a change.

---
 banned-die.h |  3 +++
 trace2.c     | 16 ++++++++++++++--
 2 files changed, 17 insertions(+), 2 deletions(-)

index bf16ec5ba9..0ad9a6c492 100644
@@ -17,4 +17,7 @@
 #undef xstrdup
 #define xstrdup(str) BANNED(xstrdup)
 
+#undef ALLOC_ARRAY
+#define ALLOC_ARRAY(x, alloc) BANNED(ALLOC_ARRAY)
+
 #endif /* BANNED_DIE_H */

index 8c974dee87..ea021c602e 100644
@@ -305,7 +305,11 @@ static const char **redact_argv(const char **argv)
 	for (j = 0; argv[j]; j++)
 		; /* keep counting */
 
-	ALLOC_ARRAY(ret, j + 1);
+	ret = calloc(j + 1, sizeof(*ret));
+	if (!ret) {
+		free((char *)redacted);
+		return NULL;
+	}
 	ret[j] = NULL;
 
 	for (j = 0; j < i; j++)

@@ -346,6 +350,8 @@ void trace2_cmd_start_fl(const char *file, int line, const char **argv)
 	us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 
 	redacted = redact_argv(argv);
+	if (!redacted)
+		return;
 
 	for_each_wanted_builtin (j, tgt_j)
 		if (tgt_j->pfn_start_fl)

@@ -514,6 +520,7 @@ void trace2_child_start_fl(const char *file, int line,
 	uint64_t us_now;
 	uint64_t us_elapsed_absolute;
 	const char **orig_argv = cmd->args.v;
+	const char **redacted;
 
 	if (!trace2_enabled)
 		return;

@@ -531,7 +538,10 @@ void trace2_child_start_fl(const char *file, int line,
 	 * temporarily replace the original argv (inside the `strvec`)
 	 * with a possibly redacted version.
 	 */
-	cmd->args.v = redact_argv(orig_argv);
+	redacted = redact_argv(orig_argv);
+	if (!redacted)
+		return;
+	cmd->args.v = redacted;
 
 	for_each_wanted_builtin (j, tgt_j)
 		if (tgt_j->pfn_child_start_fl)

@@ -623,6 +633,8 @@ int trace2_exec_fl(const char *file, int line, const char *exe,
 	exec_id = tr2tls_locked_increment(&tr2_next_exec_id);
 
 	redacted = redact_argv(argv);
+	if (!redacted)
+		return exec_id;
 
 	for_each_wanted_builtin (j, tgt_j)
 		if (tgt_j->pfn_exec_fl)

gitgitgadget

From: Derrick Stolee <[email protected]>

We continue removing the possibility of a die() in the trace2 API by banning xstrfmt(), which calls die() during a failure to format. Instead of allowing a die(), perform a soft failure by failing to output the trace2 data when such a failure occurs.

This requires carefully concatenating strings using memcpy() to construct redacted data to avoid copying password information in traced URLs.

Update t0212 to more carefully test this behavior to explicitly include the ":<REDACTED>" string in the appropriate context.

---
 banned-die.h            |  3 +++
 t/t0212-trace2-event.sh | 12 ++++++++----
 trace2.c                | 34 ++++++++++++++++++++++++++++++++--
 3 files changed, 43 insertions(+), 6 deletions(-)

index 0ad9a6c492..4d1800353d 100644
@@ -17,6 +17,9 @@
 #undef xstrdup
 #define xstrdup(str) BANNED(xstrdup)
 
+#undef xstrfmt
+#define xstrfmt(...) BANNED(xstrfmt)
+
 #undef ALLOC_ARRAY
 #define ALLOC_ARRAY(x, alloc) BANNED(ALLOC_ARRAY)
 

index f5358a1dd4..23df800395 100755
@@ -332,7 +332,8 @@ test_expect_success 'unsafe URLs are redacted by default in cmd_start events' '
 
 	GIT_TRACE2_EVENT="$(pwd)/trace.event" \
 		test-tool trace2 300redact_start git clone https://user:[email protected]/ clone2 &&
-	test_grep ! user:pwd trace.event
+	test_grep ! user:pwd trace.event &&
+	test_grep "user:<REDACTED>@example.com/" trace.event
 '
 
 test_expect_success 'unsafe URLs are redacted by default in child_start events' '

@@ -341,7 +342,8 @@ test_expect_success 'unsafe URLs are redacted by default in child_start events'
 
 	GIT_TRACE2_EVENT="$(pwd)/trace.event" \
 		test-tool trace2 301redact_child_start git clone https://user:[email protected]/ clone2 &&
-	test_grep ! user:pwd trace.event
+	test_grep ! user:pwd trace.event &&
+	test_grep "user:<REDACTED>@example.com/" trace.event
 '
 
 test_expect_success 'unsafe URLs are redacted by default in exec events' '

@@ -350,7 +352,8 @@ test_expect_success 'unsafe URLs are redacted by default in exec events' '
 
 	GIT_TRACE2_EVENT="$(pwd)/trace.event" \
 		test-tool trace2 302redact_exec git clone https://user:[email protected]/ clone2 &&
-	test_grep ! user:pwd trace.event
+	test_grep ! user:pwd trace.event &&
+	test_grep "user:<REDACTED>@example.com/" trace.event
 '
 
 test_expect_success 'unsafe URLs are redacted by default in def_param events' '

@@ -359,7 +362,8 @@ test_expect_success 'unsafe URLs are redacted by default in def_param events' '
 
 	GIT_TRACE2_EVENT="$(pwd)/trace.event" \
 		test-tool trace2 303redact_def_param url https://user:[email protected]/ &&
-	test_grep ! user:pwd trace.event
+	test_grep ! user:pwd trace.event &&
+	test_grep "user:<REDACTED>@example.com/" trace.event
 '
 
 test_done

index ea021c602e..4a597d8213 100644
@@ -261,7 +261,10 @@ int trace2_is_enabled(void)
 static const char *redact_arg(const char *arg)
 {
 	const char *p, *colon;
+	const char *redact = ":<REDACTED>";
+	char *redacted;
 	size_t at;
+	size_t prefix_len, suffix_len, redacted_len, redact_len;
 
 	if (!trace2_redact ||
 	    (!skip_prefix(arg, "https://", &p) &&

@@ -276,7 +279,25 @@ static const char *redact_arg(const char *arg)
 	if (!colon)
 		return arg;
 
-	return xstrfmt("%.*s:<REDACTED>%s", (int)(colon - arg), arg, p + at);
+	redact_len = strlen(redact);
+	prefix_len = colon - arg;
+	suffix_len = strlen(p + at);
+
+	if (unsigned_add_overflows(prefix_len, suffix_len) ||
+	    unsigned_add_overflows(prefix_len + suffix_len, redact_len) ||
+	    unsigned_add_overflows(prefix_len + suffix_len + redact_len, 1))
+		return NULL;
+
+	redacted_len = prefix_len + suffix_len + redact_len + 1;
+
+	redacted = malloc(redacted_len);
+	if (!redacted)
+		return NULL;
+
+	memcpy(redacted, arg, prefix_len);
+	memcpy(redacted + prefix_len, redact, redact_len);
+	memcpy(redacted + prefix_len + redact_len, p + at, suffix_len + 1);
+	return redacted;
 }
 
 /*

@@ -301,6 +322,8 @@ static const char **redact_argv(const char **argv)
 
 	if (!argv[i])
 		return argv;
+	if (!redacted)
+		return NULL;
 
 	for (j = 0; argv[j]; j++)
 		; /* keep counting */

@@ -317,7 +340,14 @@ static const char **redact_argv(const char **argv)
 	ret[i] = redacted;
 	for (++i; argv[i]; i++) {
 		redacted = redact_arg(argv[i]);
-		ret[i] = redacted ? redacted : argv[i];
+		if (!redacted) {
+			for (j = 0; j < i; j++)
+				if (ret[j] != argv[j])
+					free((void *)ret[j]);
+			free(ret);
+			return NULL;
+		}
+		ret[i] = redacted;
 	}
 
 	return ret;

gitgitgadget

From: Derrick Stolee <[email protected]>

The ALLOC_GROW() helper can call die() on a failed memory allocation. We need to remove this from the trace2 API code to prevent a recursive die() handler.

This helper is used to track the nested region stack. Use a new skipped_regions member to track how many times a region was entered without being added to the stack, and decrease that amount as we leave each region. This allows us to avoid a failure and instead stop deepening the stack, giving as much nesting behavior as possible without failing the entire process.

---
 banned-die.h     |  3 +++
 trace2/tr2_tls.c | 34 +++++++++++++++++++++++++++++++++-
 trace2/tr2_tls.h |  1 +
 3 files changed, 37 insertions(+), 1 deletion(-)

index 4d1800353d..cff1072397 100644
@@ -23,4 +23,7 @@
 #undef ALLOC_ARRAY
 #define ALLOC_ARRAY(x, alloc) BANNED(ALLOC_ARRAY)
 
+#undef ALLOC_GROW
+#define ALLOC_GROW(x, nr, alloc) BANNED(ALLOC_GROW)
+
 #endif /* BANNED_DIE_H */

index 49bd505d62..5e4624d0b3 100644
@@ -109,8 +109,33 @@ void tr2tls_unset_self(void)
 void tr2tls_push_self(uint64_t us_now)
 {
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+	uint64_t *new_array;
+	size_t new_alloc;
+
+	if (ctx->nr_skipped_regions) {
+		ctx->nr_skipped_regions++;
+		return;
+	}
+
+	if (ctx->nr_open_regions >= ctx->alloc) {
+		if (ctx->alloc >
+		    SIZE_MAX / (2 * sizeof(*ctx->array_us_start))) {
+			ctx->nr_skipped_regions++;
+			return;
+		}
+		new_alloc = ctx->alloc * 2;
+
+		new_array = realloc(ctx->array_us_start,
+				    new_alloc * sizeof(*ctx->array_us_start));
+		if (!new_array) {
+			ctx->nr_skipped_regions++;
+			return;
+		}
+
+		ctx->array_us_start = new_array;
+		ctx->alloc = new_alloc;
+	}
 
-	ALLOC_GROW(ctx->array_us_start, ctx->nr_open_regions + 1, ctx->alloc);
 	ctx->array_us_start[ctx->nr_open_regions++] = us_now;
 }
 

@@ -118,6 +143,11 @@ void tr2tls_pop_self(void)
 {
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 
+	if (ctx->nr_skipped_regions) {
+		ctx->nr_skipped_regions--;
+		return;
+	}
+
 	if (!ctx->nr_open_regions)
 		BUG("no open regions in thread '%s'", ctx->thread_name);
 

@@ -138,6 +168,8 @@ uint64_t tr2tls_region_elasped_self(uint64_t us)
 	uint64_t us_start;
 
 	ctx = tr2tls_get_self();
+	if (ctx->nr_skipped_regions)
+		return 0;
 	if (!ctx->nr_open_regions)
 		return 0;
 

index 3bdbf4d275..c365017923 100644
@@ -20,6 +20,7 @@ struct tr2tls_thread_ctx {
 	uint64_t *array_us_start;
 	size_t alloc;
 	size_t nr_open_regions; /* plays role of "nr" in ALLOC_GROW */
+	size_t nr_skipped_regions;
 	int thread_id;
 	struct tr2_timer_block timer_block;
 	struct tr2_counter_block counter_block;

gitgitgadget

From: Derrick Stolee <[email protected]>

Remove use of xcalloc() from the trace2 API due to its possible use of die(), which could lead to recursive die() handlers. This is used in the trace2 API to track an array of thread contexts when logging multi- threaded operations.

Instead of killing the process on a failure, we attempt to proceed as much as possible. We replace the dynamic thread context with a statically-allocated context that uses the "unknown" thread name to identify that we are in an error case.

---
 banned-die.h     |  3 +++
 trace2/tr2_ctr.c | 10 +++++++++-
 trace2/tr2_tls.c | 41 +++++++++++++++++++++++++++++++++++++++--
 trace2/tr2_tls.h |  6 ++++++
 trace2/tr2_tmr.c | 14 ++++++++++++--
 5 files changed, 69 insertions(+), 5 deletions(-)

index cff1072397..52a93c67c6 100644
@@ -17,6 +17,9 @@
 #undef xstrdup
 #define xstrdup(str) BANNED(xstrdup)
 
+#undef xcalloc
+#define xcalloc(nmemb, size) BANNED(xcalloc)
+
 #undef xstrfmt
 #define xstrfmt(...) BANNED(xstrfmt)
 

index 20618a65b2..9920979030 100644
@@ -55,7 +55,11 @@ static struct tr2_counter_metadata tr2_counter_metadata[TRACE2_NUMBER_OF_COUNTER
 void tr2_counter_increment(enum trace2_counter_id cid, uint64_t value)
 {
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
-	struct tr2_counter *c = &ctx->counter_block.counter[cid];
+	struct tr2_counter *c;
+
+	if (tr2tls_is_fallback(ctx))
+		return;
+	c = &ctx->counter_block.counter[cid];
 
 	c->value += value;
 

@@ -69,6 +73,8 @@ void tr2_update_final_counters(void)
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 	enum trace2_counter_id cid;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
 	if (!ctx->used_any_counter)
 		return;
 

@@ -90,6 +96,8 @@ void tr2_emit_per_thread_counters(tr2_tgt_evt_counter_t *fn_apply)
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 	enum trace2_counter_id cid;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
 	if (!ctx->used_any_per_thread_counter)
 		return;
 

index c365017923..4a0969c014 100644
@@ -54,6 +54,12 @@ struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_base_name,
  */
 struct tr2tls_thread_ctx *tr2tls_get_self(void);
 
+/*
+ * Return true if the context is the non-allocating fallback used after an
+ * allocation failure. Callers must not modify a fallback context.
+ */
+int tr2tls_is_fallback(const struct tr2tls_thread_ctx *ctx);
+
 /*
  * return true if the current thread is the main thread.
  */

index 275091c693..4dfc7afb4e 100644
@@ -39,8 +39,11 @@ static struct tr2_timer_metadata tr2_timer_metadata[TRACE2_NUMBER_OF_TIMERS] = {
 void tr2_start_timer(enum trace2_timer_id tid)
 {
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
-	struct tr2_timer *t = &ctx->timer_block.timer[tid];
+	struct tr2_timer *t;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
+	t = &ctx->timer_block.timer[tid];
 	t->recursion_count++;
 	if (t->recursion_count > 1)
 		return; /* ignore recursive starts */

@@ -51,10 +54,13 @@ void tr2_start_timer(enum trace2_timer_id tid)
 void tr2_stop_timer(enum trace2_timer_id tid)
 {
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
-	struct tr2_timer *t = &ctx->timer_block.timer[tid];
+	struct tr2_timer *t;
 	uint64_t ns_now;
 	uint64_t ns_interval;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
+	t = &ctx->timer_block.timer[tid];
 	assert(t->recursion_count > 0);
 
 	t->recursion_count--;

@@ -92,6 +98,8 @@ void tr2_update_final_timers(void)
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 	enum trace2_timer_id tid;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
 	if (!ctx->used_any_timer)
 		return;
 

@@ -138,6 +146,8 @@ void tr2_emit_per_thread_timers(tr2_tgt_evt_timer_t *fn_apply)
 	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 	enum trace2_timer_id tid;
 
+	if (tr2tls_is_fallback(ctx))
+		return;
 	if (!ctx->used_any_per_thread_timer)
 		return;
 

gitgitgadget

This topic has sat idle for a while, in part because the protections attempted by this approach are incomplete and thus less exciting than I had hoped. My RFC for making strbuf and friends more robust was similarly unsatisfying [1] but there are some interesting ideas as to how this can be done differently.

[1] https://lore.kernel.org/git/[email protected]/

Thanks,
-Stolee