Add timestamp to log

Also, the ERR() and WARN() now have the timestamp and the PID
information.

Fixes #519

Signed-off-by: David Goulet <dgoulet@efficios.com>

diff --git a/src/common/error.c b/src/common/error.c
index eec9b7a3e3e6645d803cf03dff8590571199a438..93b69843db7c1cd7984216d6c013dcd84939f5be 100644 (file)
--- a/src/common/error.c
+++ b/src/common/error.c
@@ -17,6 +17,7 @@
 
 #define _GNU_SOURCE
 #include <assert.h>
+#include <inttypes.h>
 
 #include <lttng/lttng-error.h>
 #include <common/common.h>
@@ -25,6 +26,42 @@
 
 #define ERROR_INDEX(code) (code - LTTNG_OK)
 
+/* TLS variable that contains the time of one single log entry. */
+DEFINE_URCU_TLS(struct log_time, error_log_time);
+
+const char *log_add_time(void)
+{
+       int ret;
+       struct tm tm, *res;
+       struct timespec tp;
+       time_t now;
+
+       ret = clock_gettime(CLOCK_REALTIME, &tp);
+       if (ret < 0) {
+               goto error;
+       }
+       now = (time_t) tp.tv_sec;
+
+       res = localtime_r(&now, &tm);
+       if (!res) {
+               goto error;
+       }
+
+       /* Format time in the TLS variable. */
+       ret = snprintf(error_log_time.str, sizeof(error_log_time.str),
+                       "%02d:%02d:%02d.%06ld",
+                       tm.tm_hour, tm.tm_min, tm.tm_sec, tp.tv_nsec);
+       if (ret < 0) {
+               goto error;
+       }
+
+       return error_log_time.str;
+
+error:
+       /* Return an empty string on error so logging is not affected. */
+       return "";
+}
+
 /*
  * Human readable error message.
  */

diff --git a/src/common/error.h b/src/common/error.h
index f8c0a1d06198bf218687a0ed8e67f3036ecba5d5..1b000ab7a58759bcf62422368d4d05474454ef95 100644 (file)
--- a/src/common/error.h
+++ b/src/common/error.h
@@ -22,6 +22,8 @@
 #include <stdio.h>
 #include <stdint.h>
 #include <string.h>
+#include <urcu/tls-compat.h>
+#include <time.h>
 
 #ifndef _GNU_SOURCE
 #error "lttng-tools error.h needs _GNU_SOURCE"
@@ -34,6 +36,17 @@
 #define XSTR(d) STR(d)
 #define STR(s) #s
 
+/*
+ * Contains the string of the log entry time. This is used as a thread local
+ * storage so we don't race between thread and also avoid memory allocation
+ * every time a log is fired.
+ */
+struct log_time {
+       /* Format: 00:00:00.000000 plus NULL byte. */
+       char str[16];
+};
+extern DECLARE_URCU_TLS(struct log_time, error_log_time);
+
 extern int lttng_opt_quiet;
 extern int lttng_opt_verbose;
 
@@ -69,17 +82,17 @@ extern int lttng_opt_verbose;
 
 /* Three level of debug. Use -v, -vv or -vvv for the levels */
 #define _ERRMSG(msg, type, fmt, args...) __lttng_print(type, msg \
-               " [%ld/%ld]: " fmt " (in %s() at " __FILE__ ":" XSTR(__LINE__) ")\n", \
-                       (long) getpid(), (long) gettid(), ## args, __func__)
+               " - %s [%ld/%ld]: " fmt " (in %s() at " __FILE__ ":" XSTR(__LINE__) ")\n", \
+                       log_add_time(), (long) getpid(), (long) gettid(), ## args, __func__)
 
 #define MSG(fmt, args...) \
        __lttng_print(PRINT_MSG, fmt "\n", ## args)
 #define _MSG(fmt, args...) \
        __lttng_print(PRINT_MSG, fmt, ## args)
 #define ERR(fmt, args...) \
-       __lttng_print(PRINT_ERR, "Error: " fmt "\n", ## args)
+       _ERRMSG("ERROR", PRINT_ERR, fmt, ## args)
 #define WARN(fmt, args...) \
-       __lttng_print(PRINT_WARN, "Warning: " fmt "\n", ## args)
+       _ERRMSG("WARN", PRINT_WARN, fmt, ## args)
 
 #define BUG(fmt, args...) _ERRMSG("BUG", PRINT_BUG, fmt, ## args)
 
@@ -115,4 +128,11 @@ extern int lttng_opt_verbose;
 
 const char *error_get_str(int32_t code);
 
+/*
+ * Function that format the time and return the reference of log_time.str to
+ * the caller. On error, an empty string is returned thus no time will be
+ * printed in the log.
+ */
+const char *log_add_time();
+
 #endif /* _ERROR_H */