curl: use realtime in trace timestamps

Timestamps in trace logs used a mix of realtime and monotonic time
sources, leading to fractional seconds carrying wrong values. Use
realtime only, so the correct nanoseconds are printed.

Fixes #15614
Reported-by: jethrogb on github
Closes #15641

diff --git a/src/tool_cb_dbg.c b/src/tool_cb_dbg.c
index 195127bd8bad051fd59a3bf7057cd98c3cc7f411..3a701e648a8283a9f4c2c2904c2df76a5ed9c455 100644 (file)
--- a/src/tool_cb_dbg.c
+++ b/src/tool_cb_dbg.c
@@ -44,20 +44,10 @@ static const char *hms_for_sec(time_t tv_sec)
 {
   static time_t cached_tv_sec;
   static char hms_buf[12];
-  static time_t epoch_offset;
-  static int known_epoch;
 
   if(tv_sec != cached_tv_sec) {
-    struct tm *now;
-    time_t secs;
-    /* recalculate */
-    if(!known_epoch) {
-      epoch_offset = time(NULL) - tv_sec;
-      known_epoch = 1;
-    }
-    secs = epoch_offset + tv_sec;
     /* !checksrc! disable BANNEDFUNC 1 */
-    now = localtime(&secs);  /* not thread safe but we do not care */
+    struct tm *now = localtime(&tv_sec);  /* not thread safe either */
     msnprintf(hms_buf, sizeof(hms_buf), "%02d:%02d:%02d",
               now->tm_hour, now->tm_min, now->tm_sec);
     cached_tv_sec = tv_sec;
@@ -108,7 +98,7 @@ int tool_debug_cb(CURL *handle, curl_infotype type,
   (void)handle; /* not used */
 
   if(config->tracetime) {
-    tv = tvnow();
+    tv = tvrealnow();
     msnprintf(timebuf, sizeof(timebuf), "%s.%06ld ",
               hms_for_sec(tv.tv_sec), (long)tv.tv_usec);
   }

diff --git a/src/tool_util.c b/src/tool_util.c
index e657dacf0c71e2425bd6c03dd37c2cb71c64f3de..69b1d2b42acc7ea16a4e24769c61b860ea915444 100644 (file)
--- a/src/tool_util.c
+++ b/src/tool_util.c
@@ -125,6 +125,43 @@ struct timeval tvnow(void)
 
 #endif
 
+#if defined(_WIN32)
+
+struct timeval tvrealnow(void)
+{
+  /* UNIX EPOCH (1970-01-01) in FILETIME (1601-01-01) as 64-bit value */
+  static const curl_uint64_t EPOCH = (curl_uint64_t)116444736000000000ULL;
+  SYSTEMTIME systime;
+  FILETIME ftime; /* 100ns since 1601-01-01, as double 32-bit value */
+  curl_uint64_t time; /* 100ns since 1601-01-01, as 64-bit value */
+  struct timeval now;
+
+  GetSystemTime(&systime);
+  SystemTimeToFileTime(&systime, &ftime);
+  time = ((curl_uint64_t)ftime.dwLowDateTime);
+  time += ((curl_uint64_t)ftime.dwHighDateTime) << 32;
+
+  now.tv_sec  = (long)((time - EPOCH) / 10000000L); /* unit is 100ns */
+  now.tv_usec = (long)(systime.wMilliseconds * 1000);
+  return now;
+}
+
+#else
+
+struct timeval tvrealnow(void)
+{
+  struct timeval now;
+#ifdef HAVE_GETTIMEOFDAY
+  (void)gettimeofday(&now, NULL);
+#else
+  now.tv_sec = time(NULL);
+  now.tv_usec = 0;
+#endif
+  return now;
+}
+
+#endif
+
 /*
  * Make sure that the first argument is the more recent time, as otherwise
  * we will get a weird negative time-diff back...

diff --git a/src/tool_util.h b/src/tool_util.h
index 9fec7e8737e11135b93f56b973bb94f659f85dec..9a4e87dc438030ea010899a8b9b3c278109e00ac 100644 (file)
--- a/src/tool_util.h
+++ b/src/tool_util.h
@@ -25,8 +25,17 @@
  ***************************************************************************/
 #include "tool_setup.h"
 
+/**
+ * Return timeval of the MONOTONIC timer, depending on platform
+ * this may be completely unrelated to the REALTIME.
+ */
 struct timeval tvnow(void);
 
+/**
+ * Return timeval of the REALTIME clock.
+ */
+struct timeval tvrealnow(void);
+
 /*
  * Make sure that the first argument (t1) is the more recent time and t2 is
  * the older time, as otherwise you get a weird negative time-diff back...