From 832b4c617bbab72a83efc825b4d1bb9d2d3fef61 Mon Sep 17 00:00:00 2001 From: Derrick Stolee Date: Mon, 13 Jul 2026 13:35:33 -0400 Subject: [PATCH 1/2] trace2: tolerate failed timestamp formatting 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. Since the formatting string has seven parameters, the underlying formatter needs to allocate a dynamic array to process it. 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. Helped-by: Taylor Blau Signed-off-by: Derrick Stolee --- trace2/tr2_tbuf.c | 49 ++++++++++++++++++++++++++++++++--------------- 1 file changed, 34 insertions(+), 15 deletions(-) diff --git a/trace2/tr2_tbuf.c b/trace2/tr2_tbuf.c index c3b3822ed7e4af..ef57376f3c3e24 100644 --- a/trace2/tr2_tbuf.c +++ b/trace2/tr2_tbuf.c @@ -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)); + } } From fc54bf675eb85ef2831b51d59224378128c1f21d Mon Sep 17 00:00:00 2001 From: Derrick Stolee Date: Sun, 2 Aug 2026 11:25:05 -0400 Subject: [PATCH 2/2] trace2: remove use of xstrdup() 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. Signed-off-by: Derrick Stolee --- trace2/tr2_sysenv.c | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/trace2/tr2_sysenv.c b/trace2/tr2_sysenv.c index 4abc218514fdbc..44db4cda4d0b1c 100644 --- a/trace2/tr2_sysenv.c +++ b/trace2/tr2_sysenv.c @@ -73,7 +73,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; } } @@ -109,7 +111,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; }