Core: Add a timestamping and thread ID to logging

8 files changed, 110 insertions, 2 deletions

diff --git a/configure.ac b/configure.ac
index db5c534..792035f 100644
--- a/configure.ac
+++ b/configure.ac
@@ -210,6 +210,7 @@ AM_CONDITIONAL([HAVE_SIGACTION], [test "x$have_sigaction" = "xyes"])
 
 # headers not available on all platforms but required on others
 AC_CHECK_HEADERS([sys/time.h])
+AC_CHECK_FUNCS(gettimeofday)
 
 AM_CFLAGS="-std=gnu99 -Wall -Wundef -Wunused -Wstrict-prototypes -Werror-implicit-function-declaration $nopointersign_cflags -Wshadow"
 
diff --git a/libusb/core.c b/libusb/core.c
index 1a95dd4..2c3de76 100644
--- a/libusb/core.c
+++ b/libusb/core.c
@@ -27,6 +27,10 @@
 #include <string.h>
 #include <sys/types.h>
 
+#ifdef HAVE_SYS_TIME_H
+#include <sys/time.h>
+#endif
+
 #include "libusbi.h"
 
 #if defined(OS_LINUX)
@@ -1665,11 +1669,59 @@ int API_EXPORTED libusb_has_capability(uint32_t capability)
 	return 0;
 }
 
+/* this is defined in libusbi.h if needed */
+#ifdef LIBUSB_GETTIMEOFDAY_WIN32
+/*
+ * gettimeofday
+ * Implementation according to:
+ * The Open Group Base Specifications Issue 6
+ * IEEE Std 1003.1, 2004 Edition
+ */
+
+/*
+ *  THIS SOFTWARE IS NOT COPYRIGHTED
+ *
+ *  This source code is offered for use in the public domain. You may
+ *  use, modify or distribute it freely.
+ *
+ *  This code is distributed in the hope that it will be useful but
+ *  WITHOUT ANY WARRANTY. ALL WARRANTIES, EXPRESS OR IMPLIED ARE HEREBY
+ *  DISCLAIMED. This includes but is not limited to warranties of
+ *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
+ *
+ *  Contributed by:
+ *  Danny Smith <dannysmith@users.sourceforge.net>
+ */
+
+/* Offset between 1/1/1601 and 1/1/1970 in 100 nanosec units */
+#define _W32_FT_OFFSET (116444736000000000)
+
+int usbi_gettimeofday(struct timeval *tp, void *tzp)
+ {
+  union {
+    unsigned __int64 ns100; /*time since 1 Jan 1601 in 100ns units */
+    FILETIME ft;
+  }  _now;
+
+  if(tp)
+    {
+      GetSystemTimeAsFileTime (&_now.ft);
+      tp->tv_usec=(long)((_now.ns100 / 10) % 1000000 );
+      tp->tv_sec= (long)((_now.ns100 - _W32_FT_OFFSET) / 10000000);
+    }
+  /* Always return 0 as per Open Group Base Specifications Issue 6.
+     Do not set errno on error.  */
+  return 0;
+}
+#endif
+
 void usbi_log_v(struct libusb_context *ctx, enum usbi_log_level level,
 	const char *function, const char *format, va_list args)
 {
 	FILE *stream = stdout;
 	const char *prefix;
+	struct timeval now;
+	static struct timeval first = { 0, 0 };
 
 #ifndef ENABLE_DEBUG_LOGGING
 	USBI_GET_CONTEXT(ctx);
@@ -1681,6 +1733,20 @@ void usbi_log_v(struct libusb_context *ctx, enum usbi_log_level level,
 		return;
 #endif
 
+	usbi_gettimeofday(&now, NULL);
+	if (!first.tv_sec) {
+		first.tv_sec = now.tv_sec;
+		first.tv_usec = now.tv_usec;
+		fprintf(stream, "[timestamp] [threadID] facility level [function call] <message>\n");
+		fprintf(stream, "--------------------------------------------------------------------------------\n");
+	}
+	if (now.tv_usec < first.tv_usec) {
+		now.tv_sec--;
+		now.tv_usec += 1000000;
+	}
+	now.tv_sec -= first.tv_sec;
+	now.tv_usec -= first.tv_usec;
+
 	switch (level) {
 	case LOG_LEVEL_INFO:
 		prefix = "info";
@@ -1703,7 +1769,8 @@ void usbi_log_v(struct libusb_context *ctx, enum usbi_log_level level,
 		break;
 	}
 
-	fprintf(stream, "libusb:%s [%s] ", prefix, function);
+	fprintf(stream, "[%2d.%06d] [%08x] libusbx: %s [%s] ",
+		(int)now.tv_sec, (int)now.tv_usec, usbi_get_tid(), prefix, function);
 
 	vfprintf(stream, format, args);
 
diff --git a/libusb/libusbi.h b/libusb/libusbi.h
index 0aa6bf9..b8abab5 100644
--- a/libusb/libusbi.h
+++ b/libusb/libusbi.h
@@ -209,6 +209,18 @@ static inline void usbi_dbg(const char *format, ...)
 #include <os/poll_windows.h>
 #endif
 
+#if defined(OS_WINDOWS) && !defined(__GCC__)
+#undef HAVE_GETTIMEOFDAY
+int usbi_gettimeofday(struct timeval *tp, void *tzp);
+#define LIBUSB_GETTIMEOFDAY_WIN32
+#define HAVE_USBI_GETTIMEOFDAY
+#else
+#ifdef HAVE_GETTIMEOFDAY
+#define usbi_gettimeofday(tv, tz) gettimeofday((tv), (tz))
+#define HAVE_USBI_GETTIMEOFDAY
+#endif
+#endif
+
 extern struct libusb_context *usbi_default_context;
 
 struct libusb_context {
diff --git a/libusb/os/threads_posix.c b/libusb/os/threads_posix.c
index fb040ce..8e9b490 100644
--- a/libusb/os/threads_posix.c
+++ b/libusb/os/threads_posix.c
@@ -19,6 +19,13 @@
  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
  */
 
+#if defined(__linux__)
+# include <unistd.h>
+# include <sys/syscall.h>
+#elif defined(__APPLE__)
+# include <mach/mach.h>
+#endif
+
 #ifdef _XOPEN_SOURCE
 # if _XOPEN_SOURCE < 500
 #  undef _XOPEN_SOURCE
@@ -53,3 +60,16 @@ finish:
 
 	return err;
 }
+
+int usbi_get_tid(void)
+{
+	int ret = -1;
+#if defined(__linux__)
+	ret = syscall(SYS_gettid);
+#elif defined(__APPLE__)
+	ret = mach_thread_self();
+	mach_port_deallocate(mach_task_self(), ret);
+#endif
+/* TODO: OpenBSD and NetBSD thread ID support */
+	return ret;
+}
diff --git a/libusb/os/threads_posix.h b/libusb/os/threads_posix.h
index db4de28..5f66b6a 100644
--- a/libusb/os/threads_posix.h
+++ b/libusb/os/threads_posix.h
@@ -45,4 +45,6 @@
 
 extern int usbi_mutex_init_recursive(pthread_mutex_t *mutex, pthread_mutexattr_t *attr);
 
+int usbi_get_tid(void);
+
 #endif /* LIBUSB_THREADS_POSIX_H */
diff --git a/libusb/os/threads_windows.c b/libusb/os/threads_windows.c
index bb5c4c8..aceca36 100644
--- a/libusb/os/threads_windows.c
+++ b/libusb/os/threads_windows.c
@@ -204,3 +204,7 @@ int usbi_cond_timedwait(usbi_cond_t *cond,
 
 	return usbi_cond_intwait(cond, mutex, millis);
 }
+
+int usbi_get_tid(void) {
+	return GetCurrentThreadId();
+}
diff --git a/libusb/os/threads_windows.h b/libusb/os/threads_windows.h
index 764a98c..3dbae02 100644
--- a/libusb/os/threads_windows.h
+++ b/libusb/os/threads_windows.h
@@ -82,4 +82,6 @@ int usbi_cond_timedwait(usbi_cond_t *cond,
 int usbi_cond_broadcast(usbi_cond_t *cond);
 int usbi_cond_signal(usbi_cond_t *cond);
 
+int usbi_get_tid(void);
+
 #endif /* LIBUSB_THREADS_WINDOWS_H */
diff --git a/libusb/version.h b/libusb/version.h
index a2ed4a0..deb8bb6 100644
--- a/libusb/version.h
+++ b/libusb/version.h
@@ -9,7 +9,7 @@
 #define LIBUSB_MICRO 10
 #endif
 #ifndef LIBUSB_NANO
-#define LIBUSB_NANO 10492
+#define LIBUSB_NANO 10493
 #endif
 /* LIBUSB_RC is the release candidate suffix. Should normally be empty. */
 #ifndef LIBUSB_RC