core: Miscellaneous internal logging cleanup

  * Correct comments for usbi_{sn,vsn}printf(); strings are terminated
    with a NUL byte (ASCII value), not NULL (pointer value)
  * Make usbi_log_v() static; it is not used anywhere else in the
    library
  * Remove an unnecessary NUL-termination
  * Remove check for LIBUSB_LOG_LEVEL_NONE in log_str()
  * Remove UNICODE case for system logging on Windows; it was only used
    for WinCE
  * Remove 'usbi_' prefix from static functions
  * Simplify check for whether the logging level is sufficiently high to
    allow the message to be printed
  * Avoid calling usbi_clock_gettime() unless the timestamp will
    actually be used
  * Use the monotonic clock for logging timestamps; this prevents jumps
    in the timestamps if the system clock is changed
  * Use TIMESPEC_SUB() macro to get relative timestamp instead of
    open-coding the calculation
  * Use PRIxPTR to print sys_dev in libusb_wrap_sys_device() instead of
    casting to a void pointer

Signed-off-by: Chris Dickens <christopher.a.dickens@gmail.com>

diff --git a/libusb/core.c b/libusb/core.c
index e103724..f106a68 100644 (file)
--- a/libusb/core.c
+++ b/libusb/core.c
@@ -1251,7 +1251,7 @@ int API_EXPORTED libusb_wrap_sys_device(libusb_context *ctx, intptr_t sys_dev,
        size_t priv_size = usbi_backend.device_handle_priv_size;
        int r;
 
-       usbi_dbg("wrap_sys_device %p", (void *)sys_dev);
+       usbi_dbg("wrap_sys_device 0x%" PRIxPTR, (uintptr_t)sys_dev);
 
        ctx = usbi_get_context(ctx);
 
@@ -1266,7 +1266,7 @@ int API_EXPORTED libusb_wrap_sys_device(libusb_context *ctx, intptr_t sys_dev,
 
        r = usbi_backend.wrap_sys_device(ctx, _dev_handle, sys_dev);
        if (r < 0) {
-               usbi_dbg("wrap_sys_device %p returns %d", (void *)sys_dev, r);
+               usbi_dbg("wrap_sys_device 0x%" PRIxPTR " returns %d", (uintptr_t)sys_dev, r);
                usbi_mutex_destroy(&_dev_handle->lock);
                free(_dev_handle);
                return r;
@@ -2264,9 +2264,8 @@ int API_EXPORTED libusb_init(libusb_context **context)
 
        usbi_mutex_static_lock(&default_context_lock);
 
-       if (!timestamp_origin.tv_sec) {
-               usbi_clock_gettime(USBI_CLOCK_REALTIME, &timestamp_origin);
-       }
+       if (!timestamp_origin.tv_sec)
+               usbi_clock_gettime(USBI_CLOCK_MONOTONIC, &timestamp_origin);
 
        if (!context && usbi_default_context) {
                usbi_dbg("reusing default context");
@@ -2482,94 +2481,88 @@ int API_EXPORTED libusb_has_capability(uint32_t capability)
 #ifdef LIBUSB_PRINTF_WIN32
 /*
  * Prior to VS2015, Microsoft did not provide the snprintf() function and
- * provided a vsnprintf() that did not guarantee NULL-terminated output.
+ * provided a vsnprintf() that did not guarantee NUL-terminated output.
  * Microsoft did provide a _snprintf() function, but again it did not
  * guarantee NULL-terminated output.
  *
- * The below implementations guarantee NULL-terminated output and are
+ * The below implementations guarantee NUL-terminated output and are
  * C99 compliant.
  */
 
 int usbi_snprintf(char *str, size_t size, const char *format, ...)
 {
-       va_list ap;
+       va_list args;
        int ret;
 
-       va_start(ap, format);
-       ret = usbi_vsnprintf(str, size, format, ap);
-       va_end(ap);
+       va_start(args, format);
+       ret = usbi_vsnprintf(str, size, format, args);
+       va_end(args);
 
        return ret;
 }
 
-int usbi_vsnprintf(char *str, size_t size, const char *format, va_list ap)
+int usbi_vsnprintf(char *str, size_t size, const char *format, va_list args)
 {
        int ret;
 
-       ret = _vsnprintf(str, size, format, ap);
+       ret = _vsnprintf(str, size, format, args);
        if (ret < 0 || ret == (int)size) {
-               /* Output is truncated, ensure buffer is NULL-terminated and
+               /* Output is truncated, ensure buffer is NUL-terminated and
                 * determine how many characters would have been written. */
                str[size - 1] = '\0';
                if (ret < 0)
-                       ret = _vsnprintf(NULL, 0, format, ap);
+                       ret = _vsnprintf(NULL, 0, format, args);
        }
 
        return ret;
 }
 #endif /* LIBUSB_PRINTF_WIN32 */
 
-static void usbi_log_str(enum libusb_log_level level, const char *str)
+static void log_str(enum libusb_log_level level, const char *str)
 {
 #if defined(USE_SYSTEM_LOGGING_FACILITY)
-#if defined(_WIN32)
-#if !defined(UNICODE)
-       OutputDebugStringA(str);
-#else
-       WCHAR wbuf[USBI_MAX_LOG_LEN];
-       if (MultiByteToWideChar(CP_UTF8, 0, str, -1, wbuf, sizeof(wbuf)) != 0)
-               OutputDebugStringW(wbuf);
-#endif
-#elif defined(__ANDROID__)
-       int priority = ANDROID_LOG_UNKNOWN;
+#if defined(__ANDROID__)
+       int priority;
        switch (level) {
-       case LIBUSB_LOG_LEVEL_NONE: return;
        case LIBUSB_LOG_LEVEL_ERROR: priority = ANDROID_LOG_ERROR; break;
        case LIBUSB_LOG_LEVEL_WARNING: priority = ANDROID_LOG_WARN; break;
        case LIBUSB_LOG_LEVEL_INFO: priority = ANDROID_LOG_INFO; break;
        case LIBUSB_LOG_LEVEL_DEBUG: priority = ANDROID_LOG_DEBUG; break;
+       default: priority = ANDROID_LOG_UNKNOWN;
        }
        __android_log_write(priority, "libusb", str);
+#elif defined(_WIN32)
+       UNUSED(level);
+       OutputDebugStringA(str);
 #elif defined(HAVE_SYSLOG)
-       int syslog_level = LOG_INFO;
+       int syslog_level;
        switch (level) {
-       case LIBUSB_LOG_LEVEL_NONE: return;
        case LIBUSB_LOG_LEVEL_ERROR: syslog_level = LOG_ERR; break;
        case LIBUSB_LOG_LEVEL_WARNING: syslog_level = LOG_WARNING; break;
        case LIBUSB_LOG_LEVEL_INFO: syslog_level = LOG_INFO; break;
        case LIBUSB_LOG_LEVEL_DEBUG: syslog_level = LOG_DEBUG; break;
+       default: syslog_level = LOG_INFO;
        }
        syslog(syslog_level, "%s", str);
 #else /* All of gcc, Clang, Xcode seem to use #warning */
 #warning System logging is not supported on this platform. Logging to stderr will be used instead.
+       UNUSED(level);
        fputs(str, stderr);
 #endif
 #else
        /* Global log handler */
-       if (log_handler != NULL)
+       if (log_handler)
                log_handler(NULL, level, str);
        else
                fputs(str, stderr);
 #endif /* USE_SYSTEM_LOGGING_FACILITY */
-       UNUSED(level);
 }
 
-void usbi_log_v(struct libusb_context *ctx, enum libusb_log_level level,
+static void log_v(struct libusb_context *ctx, enum libusb_log_level level,
        const char *function, const char *format, va_list args)
 {
        const char *prefix;
        char buf[USBI_MAX_LOG_LEN];
-       struct timespec now;
        int global_debug, header_len, text_len;
        static int has_debug_header_been_displayed = 0;
 
@@ -2577,7 +2570,7 @@ void usbi_log_v(struct libusb_context *ctx, enum libusb_log_level level,
        global_debug = 1;
        UNUSED(ctx);
 #else
-       enum libusb_log_level ctx_level = LIBUSB_LOG_LEVEL_NONE;
+       enum libusb_log_level ctx_level;
 
        ctx = usbi_get_context(ctx);
        if (ctx)
@@ -2585,34 +2578,13 @@ void usbi_log_v(struct libusb_context *ctx, enum libusb_log_level level,
        else
                ctx_level = get_env_debug_level();
 
-       if (ctx_level == LIBUSB_LOG_LEVEL_NONE)
-               return;
-       if (level == LIBUSB_LOG_LEVEL_WARNING && ctx_level < LIBUSB_LOG_LEVEL_WARNING)
-               return;
-       if (level == LIBUSB_LOG_LEVEL_INFO && ctx_level < LIBUSB_LOG_LEVEL_INFO)
-               return;
-       if (level == LIBUSB_LOG_LEVEL_DEBUG && ctx_level < LIBUSB_LOG_LEVEL_DEBUG)
+       if (ctx_level < level)
                return;
 
        global_debug = (ctx_level == LIBUSB_LOG_LEVEL_DEBUG);
 #endif
 
-       usbi_clock_gettime(USBI_CLOCK_REALTIME, &now);
-       if ((global_debug) && (!has_debug_header_been_displayed)) {
-               has_debug_header_been_displayed = 1;
-               usbi_log_str(LIBUSB_LOG_LEVEL_DEBUG, "[timestamp] [threadID] facility level [function call] <message>" USBI_LOG_LINE_END);
-               usbi_log_str(LIBUSB_LOG_LEVEL_DEBUG, "--------------------------------------------------------------------------------" USBI_LOG_LINE_END);
-       }
-       if (now.tv_nsec < timestamp_origin.tv_nsec) {
-               now.tv_sec--;
-               now.tv_nsec += 1000000000L;
-       }
-       now.tv_sec -= timestamp_origin.tv_sec;
-       now.tv_nsec -= timestamp_origin.tv_nsec;
-
        switch (level) {
-       case LIBUSB_LOG_LEVEL_NONE:
-               return;
        case LIBUSB_LOG_LEVEL_ERROR:
                prefix = "error";
                break;
@@ -2631,21 +2603,31 @@ void usbi_log_v(struct libusb_context *ctx, enum libusb_log_level level,
        }
 
        if (global_debug) {
+               struct timespec timestamp;
+
+               if (!has_debug_header_been_displayed) {
+                       has_debug_header_been_displayed = 1;
+                       log_str(LIBUSB_LOG_LEVEL_DEBUG, "[timestamp] [threadID] facility level [function call] <message>" USBI_LOG_LINE_END);
+                       log_str(LIBUSB_LOG_LEVEL_DEBUG, "--------------------------------------------------------------------------------" USBI_LOG_LINE_END);
+               }
+
+               usbi_clock_gettime(USBI_CLOCK_MONOTONIC, &timestamp);
+               TIMESPEC_SUB(&timestamp, &timestamp_origin, &timestamp);
+
                header_len = snprintf(buf, sizeof(buf),
                        "[%2ld.%06ld] [%08x] libusb: %s [%s] ",
-                       (long)now.tv_sec, (long)(now.tv_nsec / 1000L), usbi_get_tid(), prefix, function);
+                       (long)timestamp.tv_sec, (long)(timestamp.tv_nsec / 1000L), usbi_get_tid(), prefix, function);
        } else {
                header_len = snprintf(buf, sizeof(buf),
                        "libusb: %s [%s] ", prefix, function);
        }
 
        if (header_len < 0 || header_len >= (int)sizeof(buf)) {
-               /* Somehow snprintf failed to write to the buffer,
+               /* Somehow snprintf() failed to write to the buffer,
                 * remove the header so something useful is output. */
                header_len = 0;
        }
-       /* Make sure buffer is NUL terminated */
-       buf[header_len] = '\0';
+
        text_len = vsnprintf(buf + header_len, sizeof(buf) - (size_t)header_len,
                format, args);
        if (text_len < 0 || text_len + header_len >= (int)sizeof(buf)) {
@@ -2659,9 +2641,9 @@ void usbi_log_v(struct libusb_context *ctx, enum libusb_log_level level,
        }
        strcpy(buf + header_len + text_len, USBI_LOG_LINE_END);
 
-       usbi_log_str(level, buf);
+       log_str(level, buf);
 
-       /* Per context log handler */
+       /* Per-context log handler */
 #ifndef ENABLE_DEBUG_LOGGING
        if (ctx && ctx->log_handler)
                ctx->log_handler(ctx, level, buf);
@@ -2673,9 +2655,9 @@ void usbi_log(struct libusb_context *ctx, enum libusb_log_level level,
 {
        va_list args;
 
-       va_start (args, format);
-       usbi_log_v(ctx, level, function, format, args);
-       va_end (args);
+       va_start(args, format);
+       log_v(ctx, level, function, format, args);
+       va_end(args);
 }
 
 #endif /* ENABLE_LOGGING */

diff --git a/libusb/libusbi.h b/libusb/libusbi.h
index e8a0f35..94d10d7 100644 (file)
--- a/libusb/libusbi.h
+++ b/libusb/libusbi.h
@@ -27,6 +27,7 @@
 #include <config.h>
 
 #include <assert.h>
+#include <inttypes.h>
 #include <stdarg.h>
 #include <stddef.h>
 #include <stdlib.h>
@@ -265,16 +266,13 @@ static inline void *usbi_reallocf(void *ptr, size_t size)
 #define snprintf usbi_snprintf
 #define vsnprintf usbi_vsnprintf
 int usbi_snprintf(char *dst, size_t size, const char *format, ...);
-int usbi_vsnprintf(char *dst, size_t size, const char *format, va_list ap);
+int usbi_vsnprintf(char *dst, size_t size, const char *format, va_list args);
 #define LIBUSB_PRINTF_WIN32
 #endif /* defined(_MSC_VER) && (_MSC_VER < 1900) */
 
 void usbi_log(struct libusb_context *ctx, enum libusb_log_level level,
        const char *function, const char *format, ...) USBI_PRINTFLIKE(4, 5);
 
-void usbi_log_v(struct libusb_context *ctx, enum libusb_log_level level,
-       const char *function, const char *format, va_list args) USBI_PRINTFLIKE(4, 0);
-
 #define _usbi_log(ctx, level, ...) usbi_log(ctx, level, __func__, __VA_ARGS__)
 
 #define usbi_err(ctx, ...)     _usbi_log(ctx, LIBUSB_LOG_LEVEL_ERROR, __VA_ARGS__)

diff --git a/libusb/os/sunos_usb.c b/libusb/os/sunos_usb.c
index 42a8254..46866fb 100644 (file)
--- a/libusb/os/sunos_usb.c
+++ b/libusb/os/sunos_usb.c
@@ -37,7 +37,6 @@
 #include <sys/usb/clients/ugen/usb_ugen.h>
 #include <sys/usb/usba.h>
 #include <sys/pci.h>
-#include <inttypes.h>
 
 #include "libusbi.h"
 #include "sunos_usb.h"

diff --git a/libusb/os/windows_common.c b/libusb/os/windows_common.c
index 917d24d..cf151a6 100644 (file)
--- a/libusb/os/windows_common.c
+++ b/libusb/os/windows_common.c
@@ -25,7 +25,6 @@
 #include <config.h>
 
 #include <errno.h>
-#include <inttypes.h>
 #include <process.h>
 #include <stdio.h>
 

diff --git a/libusb/os/windows_winusb.c b/libusb/os/windows_winusb.c
index 1b982ed..97215e1 100644 (file)
--- a/libusb/os/windows_winusb.c
+++ b/libusb/os/windows_winusb.c
@@ -32,7 +32,6 @@
 #include <fcntl.h>
 #include <process.h>
 #include <stdio.h>
-#include <inttypes.h>
 #include <objbase.h>
 #include <winioctl.h>
 

diff --git a/libusb/version_nano.h b/libusb/version_nano.h
index 65fa0d7..3c7f971 100644 (file)
--- a/libusb/version_nano.h
+++ b/libusb/version_nano.h
@@ -1 +1 @@
-#define LIBUSB_NANO 11555
+#define LIBUSB_NANO 11556