From 24858fcde53adabaf75b513355ca2452a032f66a Mon Sep 17 00:00:00 2001
From: nick <nick@bytemark.co.uk>
Date: Thu, 6 Jun 2013 11:57:05 +0100
Subject: [PATCH] logging: Add a timestamp to the log messages we emit

---
 README.proxy.txt |  5 ++++-
 README.txt       |  5 ++++-
 Rakefile         |  2 +-
 src/util.c       | 26 +++++++++++++++++++++++---
 src/util.h       |  7 ++++++-
 5 files changed, 38 insertions(+), 7 deletions(-)

diff --git a/README.proxy.txt b/README.proxy.txt
index 157a542..a5c8b43 100644
--- a/README.proxy.txt
+++ b/README.proxy.txt
@@ -94,7 +94,10 @@ error to set both --verbose and --quiet.  The last one wins.
 
 The log line format is:
 
-  <LEVEL>:<PID> <THREAD> <SOURCEFILE>:<SOURCELINE>: <MSG>
+  <TIMESTAMP> <LEVEL>:<PID> <THREAD> <SOURCEFILE>:<SOURCELINE>: <MSG>
+
+*TIMESTAMP*:
+  Time the log entry was made. This is expressed as milliseconds since the epoc.
 
 *LEVEL*:
   This will be one of 'D', 'I', 'W', 'E', 'F' in increasing order of
diff --git a/README.txt b/README.txt
index 1dd7ef6..0441e3b 100644
--- a/README.txt
+++ b/README.txt
@@ -278,7 +278,10 @@ error to set both --verbose and --quiet.  The last one wins.
 
 The log line format is:
 
-  <LEVEL>:<PID> <THREAD> <SOURCEFILE>:<SOURCELINE>: <MSG>
+  <TIMESTAMP> <LEVEL>:<PID> <THREAD> <SOURCEFILE>:<SOURCELINE>: <MSG>
+
+*TIMESTAMP*:
+  Time the log entry was made. This is expressed as milliseconds since the epoc.
 
 *LEVEL*:
   This will be one of 'D', 'I', 'W', 'E', 'F' in increasing order of
diff --git a/Rakefile b/Rakefile
index 68546cc..cc18e19 100644
--- a/Rakefile
+++ b/Rakefile
@@ -22,7 +22,7 @@ TEST_SOURCES = FileList['tests/unit/*.c']
 TEST_OBJECTS = TEST_SOURCES.pathmap( "%{^tests/unit,build/tests}X.o" )
 
 LIBS    = %w( pthread )
-LDFLAGS = []
+LDFLAGS = ["-lrt"]
 CCFLAGS = %w(
              -D_GNU_SOURCE=1
              -Wall
diff --git a/src/util.c b/src/util.c
index aff72be..1c72266 100644
--- a/src/util.c
+++ b/src/util.c
@@ -6,10 +6,11 @@
 #include <errno.h>
 #include <malloc.h>
 #include <unistd.h>
+#include <time.h>
 
 #include "util.h"
 
-pthread_key_t cleanup_handler_key; 
+pthread_key_t cleanup_handler_key;
 
 int log_level = 2;
 
@@ -21,10 +22,10 @@ void error_init(void)
 void error_handler(int fatal)
 {
 	DECLARE_ERROR_CONTEXT(context);
-	
+
 	if (context) {
 		longjmp(context->jmp, fatal ? 1 : 2 );
-	} 
+	}
 	else {
 		if ( fatal ) { abort(); }
 		else { pthread_exit((void*) 1); }
@@ -50,6 +51,25 @@ void mylog(int line_level, const char* format, ...)
 	va_end(argptr);
 }
 
+uint64_t monotonic_time_ms()
+{
+	struct timespec ts;
+	uint64_t seconds_ms, nanoseconds_ms;
+
+	FATAL_IF_NEGATIVE(
+		clock_gettime(CLOCK_MONOTONIC, &ts),
+		SHOW_ERRNO( "clock_gettime failed" )
+	);
+
+	seconds_ms = ts.tv_sec;
+	seconds_ms = seconds_ms * 1000;
+
+	nanoseconds_ms = ts.tv_nsec;
+	nanoseconds_ms = nanoseconds_ms / 1000000;
+
+	return seconds_ms + nanoseconds_ms;
+}
+
 
 void* xrealloc(void* ptr, size_t size)
 {
diff --git a/src/util.h b/src/util.h
index 06ed003..90abf21 100644
--- a/src/util.h
+++ b/src/util.h
@@ -8,6 +8,7 @@
 #include <stdlib.h>
 #include <sys/types.h>
 #include <unistd.h>
+#include <inttypes.h>
 
 void* xrealloc(void* ptr, size_t size);
 void* xmalloc(size_t size);
@@ -85,9 +86,13 @@ void error_handler(int fatal);
 /* mylog a line at the given level (0 being most verbose) */
 void mylog(int line_level, const char* format, ...);
 
+/* Returns the current time, in milliseconds, from CLOCK_MONOTONIC */
+uint64_t monotonic_time_ms(void);
+
+
 #define levstr(i) (i==0?'D':(i==1?'I':(i==2?'W':(i==3?'E':'F'))))
 
-#define myloglev(level, msg, ...) mylog( level, "%c:%d %p %s:%d: "msg"\n", levstr(level), getpid(),pthread_self(), __FILE__, __LINE__, ##__VA_ARGS__ )
+#define myloglev(level, msg, ...) mylog( level, "%"PRIu64":%c:%d %p %s:%d: "msg"\n", monotonic_time_ms(), levstr(level), getpid(),pthread_self(), __FILE__, __LINE__, ##__VA_ARGS__ )
 
 #ifdef DEBUG
 #  define debug(msg, ...) myloglev(0, msg, ##__VA_ARGS__)