trace2: tolerate failed timestamp formatting#2178
Open
derrickstolee wants to merge 1 commit into
Open
Conversation
derrickstolee
force-pushed
the
trace2-dont-die
branch
3 times, most recently
from
July 13, 2026 20:06
7bde852 to
a7cddd7
Compare
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 ee4512e (trace2: create new combined trace facility, 2019-02-22) but was later split in bad229a (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. Signed-off-by: Derrick Stolee <stolee@gmail.com>
derrickstolee
force-pushed
the
trace2-dont-die
branch
from
July 14, 2026 13:38
a7cddd7 to
95c546b
Compare
derrickstolee
marked this pull request as ready for review
July 15, 2026 16:10
Author
|
/submit |
|
Submitted as pull.2178.git.1784131932489.gitgitgadget@gmail.com To fetch this version into To fetch this version to local tag |
|
This branch is now known as |
|
This patch series was integrated into seen via git@a124029. |
|
There was a status update in the "New Topics" section about the branch The trace2 telemetry library has been updated to tolerate failures from system calls like 'gettimeofday()' and datetime formatting functions, replacing potential program crashes with blank placeholder timestamps in the traces. Needs review. source: <pull.2178.git.1784131932489.gitgitgadget@gmail.com> |
|
Taylor Blau wrote on the Git mailing list (how to reply to this email): On Wed, Jul 15, 2026 at 04:12:11PM +0000, Derrick Stolee via GitGitGadget wrote:
> 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.
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< ---
diff --git a/wrapper.c b/wrapper.c
index 16f5a63fbb..2976d4e110 100644
--- a/wrapper.c
+++ b/wrapper.c
@@ -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 |
|
User |
|
Derrick Stolee wrote on the Git mailing list (how to reply to this email): On 7/17/2026 12:24 PM, Taylor Blau wrote:
> On Wed, Jul 15, 2026 at 04:12:11PM +0000, Derrick Stolee via GitGitGadget wrote:
>> 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.
>
> 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.
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 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 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
|
|
There was a status update in the "Cooking" section about the branch The 'trace2' telemetry library has been updated to tolerate failures from system calls like 'gettimeofday()' and datetime formatting functions, replacing potential program crashes with blank placeholder timestamps in the traces. Waiting for response. cf. <alpXW5U6sndZtgqV@com-79390> source: <pull.2178.git.1784131932489.gitgitgadget@gmail.com> |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
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
cc: gitster@pobox.com
cc: Taylor Blau ttaylorr@openai.com