If we're going to have a bugfix release by the end of the week, I
wouldn't mind also having at least one useful new feature besides the fix.
Timestamped logging looks like a good candidate, but we may want to
improve on Peter's implementation. As indicated, I wouldn't mind having
a thread ID, and I'm also not sure about setting the time origin to the
very first log message, as currently done. If the user plans to monitor
multiple logs, it may be useful to have the origin coincide with a
global system event (eg. boot) or some epoch, rather than something
arbitrary.
On the other hand, it seems that most usb monitoring utilities (usbmon
as well as Microsoft's NetMon) use their own origins and don't bother
much about sync with other apps (Usbmon also seems to use a 32 bit
microsecond counter, that loops about once every hour), and I guess
trying to provide a stamp indexed on a global event that works across
all platforms would add in complexity.
Right now, the attached would be my current improvement on Peter's
proposal for timestamped/tid-ed logging.
The resulting log output would be something like this:
[ 2.636405] [0000040c] libusbx: debug [libusb_close]
[ 2.636405] [0000040c] libusbx: debug [libusb_unref_device] destroy
device 1.2
[ 2.652005] [0000040c] libusbx: debug [libusb_exit]
[ 2.652005] [0000040c] libusbx: debug [libusb_exit] destroying
default context
[ 2.652005] [0000040c] libusbx: debug [usbi_remove_pollfd] remove fd 3
[ 2.652005] [000003a0] libusbx: debug
[windows_clock_gettime_threaded] timer thread quitting
For the timestamp (first field), I'm using the same formatting as a
(timestamped) Linux dmesg provides, with the same behaviour for extra
spaces. As for the thread ID (second field), it is an int on all
platforms, so fixed 32 bit should do. I'm not sure many platforms will
run into large tids though, so the padding zeroes may be an overkill.
Also note that on POSIX, the tid is obtained through
syscall(SYS_gettid). I expect it to work everywhere, but I have only
tested the call on Linux.
Regards,
/Pete
>From b941193f7e2e1a6ec07b5536cfc264dcd5dff659 Mon Sep 17 00:00:00 2001
From: Peter Stuge <pe...@stuge.se>
Date: Wed, 2 May 2012 17:04:00 +0000
Subject: [PATCH] Core: Add a timestamping and thread ID to logging
---
configure.ac | 1 +
libusb/core.c | 67 ++++++++++++++++++++++++++++++++++++++++++-
libusb/libusbi.h | 12 ++++++++
libusb/os/threads_posix.c | 7 ++++
libusb/os/threads_posix.h | 2 +
libusb/os/threads_windows.c | 4 ++
libusb/os/threads_windows.h | 2 +
libusb/version.h | 2 +-
8 files changed, 95 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..e4f83d8 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 <dannysm...@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,18 @@ 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;
+ }
+ 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 +1767,8 @@ void usbi_log_v(struct libusb_context *ctx, enum
usbi_log_level level,
break;
}
- fprintf(stream, "libusb:%s [%s] ", prefix, function);
+ fprintf(stream, "[%5d.%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 c3d2158..dcfbc02 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..7feeb34 100644
--- a/libusb/os/threads_posix.c
+++ b/libusb/os/threads_posix.c
@@ -19,6 +19,9 @@
* Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
*/
+#include <unistd.h>
+#include <sys/syscall.h>
+
#ifdef _XOPEN_SOURCE
# if _XOPEN_SOURCE < 500
# undef _XOPEN_SOURCE
@@ -53,3 +56,7 @@ finish:
return err;
}
+
+int usbi_get_tid(void) {
+ return syscall(SYS_gettid);
+}
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 ef81eba..c0df768 100644
--- a/libusb/version.h
+++ b/libusb/version.h
@@ -9,7 +9,7 @@
#define LIBUSB_MICRO 10
#endif
#ifndef LIBUSB_NANO
-#define LIBUSB_NANO 10488
+#define LIBUSB_NANO 10489
#endif
/* LIBUSB_RC is the release candidate suffix. Should normally be empty. */
#ifndef LIBUSB_RC
--
1.7.9.msysgit.0
------------------------------------------------------------------------------
Live Security Virtual Conference
Exclusive live event will cover all the ways today's security and
threat landscape has changed and how IT managers can respond. Discussions
will include endpoint security, mobile security and the latest in malware
threats. http://www.accelacomm.com/jaw/sfrnl04242012/114/50122263/
_______________________________________________
libusbx-devel mailing list
libusbx-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/libusbx-devel
