[PATCH] trace2: tolerate failed timestamp formatting

[PATCH] trace2: tolerate failed timestamp formatting

[Derrick Stolee via GitGitGadget]

From: Derrick Stolee <stolee@gmail.com>

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.

Signed-off-by: Derrick Stolee <stolee@gmail.com>
---
    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(-)

diff --git a/trace2/tr2_tbuf.c b/trace2/tr2_tbuf.c
index c3b3822ed7..ef57376f3c 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));
+	}
 }

base-commit: e9019fcafe0040228b8631c30f97ae1adb61bcdc
-- 
gitgitgadget