added support for obtaining timestamp for kernel message from message

If the kernel time-stamps messages, time is now take from that
timestamp instead of the system time when the message was read. This
provides much better accuracy. Thanks to Lennart Poettering for
suggesting this feature and his help during implementation.

6 files changed, 130 insertions, 99 deletions

diff --git a/ChangeLog b/ChangeLog
index 4c315819..3459f7d1 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,5 +1,10 @@
 ---------------------------------------------------------------------------
 Version 5.9.1  [V5-DEVEL] (rgerhards), 2011-06-??
+- added support for obtaining timestamp for kernel message from message
+  If the kernel time-stamps messages, time is now take from that
+  timestamp instead of the system time when the message was read. This
+  provides much better accuracy. Thanks to Lennart Poettering for
+  suggesting this feature and his help during implementation.
 - added support for obtaining timestamp from system for imuxsock
   This permits to read the time a message was submitted to the system
   log socket. Most importantly, this is provided in microsecond resolution.
diff --git a/plugins/imklog/bsd.c b/plugins/imklog/bsd.c
index 0a4c7cd4..930bbd11 100644
--- a/plugins/imklog/bsd.c
+++ b/plugins/imklog/bsd.c
@@ -155,18 +155,18 @@ readklog(void)
 
 		for (p = (char*)pRcv; (q = strchr(p, '\n')) != NULL; p = q + 1) {
 			*q = '\0';
-			Syslog(LOG_INFO, (uchar*) p);
+			Syslog(LOG_INFO, (uchar*) p, NULL);
 		}
 		len = strlen(p);
 		if (len >= iMaxLine - 1) {
-			Syslog(LOG_INFO, (uchar*)p);
+			Syslog(LOG_INFO, (uchar*)p, NULL);
 			len = 0;
 		}
 		if (len > 0)
 			memmove(pRcv, p, len + 1);
 	}
 	if (len > 0)
-		Syslog(LOG_INFO, pRcv);
+		Syslog(LOG_INFO, pRcv, NULL);
 
 	if(pRcv != NULL && (size_t) iMaxLine >= sizeof(bufRcv) - 1)
 		free(pRcv);
diff --git a/plugins/imklog/imklog.c b/plugins/imklog/imklog.c
index c09fa4d8..cb28e68e 100644
--- a/plugins/imklog/imklog.c
+++ b/plugins/imklog/imklog.c
@@ -18,7 +18,10 @@
  * Please note that this file replaces the klogd daemon that was
  * also present in pre-v3 versions of rsyslog.
  *
- * Copyright (C) 2008, 2009 by Rainer Gerhards and Adiscon GmbH
+ * To test under Linux:
+ * echo test1 > /dev/kmsg
+ *
+ * Copyright (C) 2008-2011 by Rainer Gerhards and Adiscon GmbH
  *
  * This file is part of rsyslog.
  *
@@ -93,15 +96,21 @@ static prop_t *pLocalHostIP = NULL;	/* a pseudo-constant propterty for 127.0.0.1
  * rgerhards, 2008-04-12
  */
 static rsRetVal
-enqMsg(uchar *msg, uchar* pszTag, int iFacility, int iSeverity)
+enqMsg(uchar *msg, uchar* pszTag, int iFacility, int iSeverity, struct timeval *tp)
 {
-	DEFiRet;
+	struct syslogTime st;
 	msg_t *pMsg;
+	DEFiRet;
 
 	assert(msg != NULL);
 	assert(pszTag != NULL);
 
-	CHKiRet(msgConstruct(&pMsg));
+	if(tp == NULL) {
+		CHKiRet(msgConstruct(&pMsg));
+	} else {
+		datetime.timeval2syslogTime(tp, &st);
+		CHKiRet(msgConstructWithTime(&pMsg, &st, tp->tv_sec));
+	}
 	MsgSetFlowControlType(pMsg, eFLOWCTL_LIGHT_DELAY);
 	MsgSetInputName(pMsg, pInputName);
 	MsgSetRawMsgWOSize(pMsg, (char*)msg);
@@ -174,22 +183,23 @@ rsRetVal imklogLogIntMsg(int priority, char *fmt, ...)
 	va_end(ap);
 
 	iRet = enqMsg((uchar*)pLogMsg, (uchar*) ((iFacilIntMsg == LOG_KERN) ? "kernel:" : "imklog:"),
-		      iFacilIntMsg, LOG_PRI(priority));
+		      iFacilIntMsg, LOG_PRI(priority), NULL);
 
 	RETiRet;
 }
 
 
-/* log a kernel message 
+/* log a kernel message. If tp is non-NULL, it contains the message creation
+ * time to use.
  * rgerhards, 2008-04-14
  */
-rsRetVal Syslog(int priority, uchar *pMsg)
+rsRetVal Syslog(int priority, uchar *pMsg, struct timeval *tp)
 {
-	DEFiRet;
 	int pri = -1;
 	rsRetVal localRet;
+	DEFiRet;
 
-	/* first check if we have two PRIs. This can happen in case of systemd,
+	/* then check if we have two PRIs. This can happen in case of systemd,
 	 * in which case the second PRI is the rigth one.
 	 * TODO: added kernel timestamp support to this PoC. -- rgerhards, 2011-03-18
 	 */
@@ -214,7 +224,7 @@ rsRetVal Syslog(int priority, uchar *pMsg)
 	if(bPermitNonKernel == 0 && LOG_FAC(priority) != LOG_KERN)
 		FINALIZE; /* silently ignore */
 
-	iRet = enqMsg((uchar*)pMsg, (uchar*) "kernel:", LOG_FAC(priority), LOG_PRI(priority));
+	iRet = enqMsg((uchar*)pMsg, (uchar*) "kernel:", LOG_FAC(priority), LOG_PRI(priority), tp);
 
 finalize_it:
 	RETiRet;
diff --git a/plugins/imklog/imklog.h b/plugins/imklog/imklog.h
index c183026d..39bdeb5c 100644
--- a/plugins/imklog/imklog.h
+++ b/plugins/imklog/imklog.h
@@ -5,7 +5,7 @@
  * Major change: 2008-04-09: switched to a driver interface for 
  *     several platforms
  *
- * Copyright 2007-2008 Rainer Gerhards and Adiscon GmbH.
+ * Copyright 2007-2011 Rainer Gerhards and Adiscon GmbH.
  *
  * This file is part of rsyslog.
  *
@@ -56,7 +56,7 @@ extern uchar *pszPath;
 
 /* the functions below may be called by the drivers */
 rsRetVal imklogLogIntMsg(int priority, char *fmt, ...) __attribute__((format(printf,2, 3)));
-rsRetVal Syslog(int priority, uchar *msg);
+rsRetVal Syslog(int priority, uchar *msg, struct timeval *tp);
 
 /* prototypes */
 extern int klog_getMaxLine(void); /* work-around for klog drivers to get configured max line size */
diff --git a/plugins/imklog/linux.c b/plugins/imklog/linux.c
index 727708a5..8d9c8ad7 100644
--- a/plugins/imklog/linux.c
+++ b/plugins/imklog/linux.c
@@ -28,6 +28,8 @@
 #include "rsyslog.h"
 #include <stdlib.h>
 #include <stdio.h>
+#include <ctype.h>
+#include <time.h>
 #include <assert.h>
 #include <signal.h>
 #include <string.h>
@@ -181,6 +183,96 @@ static int copyin( uchar *line,      int space,
     return(i);
 }
 
+
+/* submit a message to imklog Syslog() API. In this function, we check if 
+ * a kernel timestamp is present and, if so, extract and strip it.
+ * Note: this is an extra processing step. We should revisit the whole
+ * idea in v6 and remove all that old stuff that we do not longer need
+ * (like symbol resolution). <-- TODO 
+ * Special thanks to Lennart Poettering for suggesting on how to convert
+ * the kernel timestamp to a realtime timestamp. This method depends on 
+ * the fact the the kernel timestamp is written using the monotonic clock.
+ * Shall that change (very unlikely), this code must be changed as well. Note
+ * that due to the way we generate the delta, we are unable to write the
+ * absolutely correc timestamp (system call overhead of the clock calls
+ * prevents us from doing so). However, the difference is very minor.
+ * rgerhards, 201106-24
+ */
+static void
+submitSyslog(int pri, uchar *buf)
+{
+	long secs;
+	long nsecs;
+	long secOffs;
+	long nsecOffs;
+	unsigned i;
+	unsigned bufsize;
+	struct timespec monotonic, realtime;
+	struct timeval tv;
+	struct timeval *tp = NULL;
+
+	if(buf[3] != '[')
+		goto done;
+	DBGPRINTF("imklog: kernel timestamp detected, extracting it\n");
+
+	/* we now try to parse the timestamp. iff it parses, we assume
+	 * it is a timestamp. Otherwise we know for sure it is no ts ;)
+	 */
+	i = 4; /* first digit after '[' */
+	secs = 0;
+	while(buf[i] && isdigit(buf[i])) {
+		secs = secs * 10 + buf[i] - '0';
+		++i;
+	}
+	if(buf[i] != '.') {
+		DBGPRINTF("no dot --> no kernel timestamp\n");
+		goto done; /* no TS! */
+	}
+	
+	++i; /* skip dot */
+	nsecs = 0;
+	while(buf[i] && isdigit(buf[i])) {
+		nsecs = nsecs * 10 + buf[i] - '0';
+		++i;
+	}
+	if(buf[i] != ']') {
+		DBGPRINTF("no trailing ']' --> no kernel timestamp\n");
+		goto done; /* no TS! */
+	}
+	++i; /* skip ']' */
+
+	/* we have a timestamp */
+	DBGPRINTF("kernel timestamp is %ld %ld\n", secs, nsecs);
+	bufsize= strlen((char*)buf);
+	memcpy(buf+3, buf+i, bufsize - i + 1);
+
+	clock_gettime(CLOCK_MONOTONIC, &monotonic);
+	clock_gettime(CLOCK_REALTIME, &realtime);
+	secOffs = realtime.tv_sec - monotonic.tv_sec;
+	nsecOffs = realtime.tv_nsec - monotonic.tv_nsec;
+	if(nsecOffs < 0) {
+		secOffs--;
+		nsecOffs += 1000000000l;
+	}
+	monotonic.tv_sec, monotonic.tv_nsec,
+	realtime.tv_sec, realtime.tv_nsec,
+	secOffs, nsecOffs);
+	
+	nsecs +=nsecOffs;
+	if(nsecs > 999999999l) {
+		secs++;
+		nsecs -= 1000000000l;
+	}
+	secs += secOffs;
+	tv.tv_sec = secs;
+	tv.tv_usec = nsecs / 1000;
+	tp = &tv;
+
+done:
+	Syslog(pri, buf, tp);
+}
+
+
 /*
  * Messages are separated by "\n".  Messages longer than
  * LOG_LINE_LENGTH are broken up.
@@ -235,7 +327,7 @@ static void LogLine(char *ptr, int len)
 	    //dbgprintf("Line buffer full:\n");
        	    //dbgprintf("\tLine: %s\n", line);
 
-            Syslog(LOG_INFO, line_buff);
+            submitSyslog(LOG_INFO, line_buff);
             line  = line_buff;
             space = sizeof(line_buff)-1;
             parse_state = PARSING_TEXT;
@@ -254,28 +346,24 @@ static void LogLine(char *ptr, int len)
                space -= delta;
                len   -= delta;
 
-               if( space == 0 || len == 0 )
-               {
+               if( space == 0 || len == 0 ) {
 		  break;  /* full line_buff or end of input buffer */
                }
 
-               if( *ptr == '\0' )  /* zero byte */
-               {
+               if( *ptr == '\0' )  /* zero byte */ {
                   ptr++;	/* skip zero byte */
                   space -= 1;
                   len   -= 1;
-
 		  break;
 	       }
 
-               if( *ptr == '\n' )  /* newline */
-               {
+               if( *ptr == '\n' )  /* newline */ {
                   ptr++;	/* skip newline */
                   space -= 1;
                   len   -= 1;
 
                   *line = 0;  /* force null terminator */
-	          Syslog(LOG_INFO, line_buff);
+	          submitSyslog(LOG_INFO, line_buff);
                   line  = line_buff;
                   space = sizeof(line_buff)-1;
 		  if (symbols_twice) {
@@ -285,9 +373,7 @@ static void LogLine(char *ptr, int len)
 			  skip_symbol_lookup = 1;
 			  ptr = save_ptr;
 			  len = save_len;
-		      }
-		      else
-		      {
+		      } else {
 			  skip_symbol_lookup = 0;
 			  save_ptr = ptr;
 			  save_len = len;
@@ -295,8 +381,7 @@ static void LogLine(char *ptr, int len)
 		  }
                   break;
                }
-               if( *ptr == '[' )   /* possible kernel symbol */
-               {
+               if( *ptr == '[' )   /* possible kernel symbol */ {
                   *line++ = *ptr++;
                   space -= 1;
                   len   -= 1;
@@ -310,8 +395,7 @@ static void LogLine(char *ptr, int len)
                break;
         
         case PARSING_SYMSTART:
-               if( *ptr != '<' )
-               {
+               if( *ptr != '<' ) {
                   parse_state = PARSING_TEXT;        /* not a symbol */
                   break;
                }
diff --git a/plugins/imklog/solaris.c b/plugins/imklog/solaris.c
index 8a6d5af1..0a169cdd 100644
--- a/plugins/imklog/solaris.c
+++ b/plugins/imklog/solaris.c
@@ -80,74 +80,6 @@ klogWillRun(void)
 }
 
 
-#if 0
-/* Read /dev/klog while data are available, split into lines.
- * Contrary to standard BSD syslogd, we do a blocking read. We can
- * afford this as imklog is running on its own threads. So if we have
- * a single file, it really doesn't matter if we wait inside a 1-file
- * select or the read() directly.
- */
-static void
-readklog(void)
-{
-	char *p, *q;
-	int len, i;
-	int iMaxLine;
-	uchar bufRcv[4096+1];
-	uchar *pRcv = NULL; /* receive buffer */
-
-	iMaxLine = klog_getMaxLine();
-
-	/* we optimize performance: if iMaxLine is below 4K (which it is in almost all
-	 * cases, we use a fixed buffer on the stack. Only if it is higher, heap memory
-	 * is used. We could use alloca() to achive a similar aspect, but there are so
-	 * many issues with alloca() that I do not want to take that route.
-	 * rgerhards, 2008-09-02
-	 */
-	if((size_t) iMaxLine < sizeof(bufRcv) - 1) {
-		pRcv = bufRcv;
-	} else {
-		if((pRcv = (uchar*) malloc(sizeof(uchar) * (iMaxLine + 1))) == NULL)
-			iMaxLine = sizeof(bufRcv) - 1; /* better this than noting */
-	}
-
-	len = 0;
-	for (;;) {
-		dbgprintf("----------imklog(BSD) waiting for kernel log line\n");
-		i = read(fklog, pRcv + len, iMaxLine - len);
-		if (i > 0) {
-			pRcv[i + len] = '\0';
-		} else {
-			if (i < 0 && errno != EINTR && errno != EAGAIN) {
-				imklogLogIntMsg(LOG_ERR,
-				       "imklog error %d reading kernel log - shutting down imklog",
-				       errno);
-				fklog = -1;
-			}
-			break;
-		}
-
-		for(p = pRcv; (q = strchr(p, '\n')) != NULL; p = q + 1) {
-			*q = '\0';
-			Syslog(LOG_INFO, (uchar*) p);
-		}
-		len = strlen(p);
-		if (len >= iMaxLine - 1) {
-			Syslog(LOG_INFO, (uchar*)p);
-			len = 0;
-		}
-		if (len > 0)
-			memmove(pRcv, p, len + 1);
-	}
-	if (len > 0)
-		Syslog(LOG_INFO, pRcv);
-
-	if(pRcv != NULL && (size_t) iMaxLine >= sizeof(bufRcv) - 1)
-		free(pRcv);
-}
-#endif
-
-
 /* to be called in the module's AfterRun entry point
  * rgerhards, 2008-04-09
  */