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.
So we are able to obtain high precision timestampis even for messages
that were - as is usual - not formatted with them. This also simplifies
things in regard to local time calculation in chroot environments.
Many thanks to Lennart Poettering for suggesting this feature,
providing some guidance on implementing it and coordinating getting the
necessary support into the Linux kernel.

6 files changed, 132 insertions, 47 deletions

diff --git a/ChangeLog b/ChangeLog
index 6391ab99..c13cc142 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,5 +1,14 @@
 ---------------------------------------------------------------------------
 Version 5.9.1  [V5-DEVEL] (rgerhards), 2011-06-??
+- 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.
+  So we are able to obtain high precision timestampis even for messages
+  that were - as is usual - not formatted with them. This also simplifies
+  things in regard to local time calculation in chroot environments.
+  Many thanks to Lennart Poettering for suggesting this feature,
+  providing some guidance on implementing it and coordinating getting the
+  necessary support into the Linux kernel.
 - bugfix: timestamp was incorrectly calculated for timezones with minute
   offset
   closes: http://bugzilla.adiscon.com/show_bug.cgi?id=271
diff --git a/configure.ac b/configure.ac
index 49d8f2fa..41468f16 100644
--- a/configure.ac
+++ b/configure.ac
@@ -118,6 +118,8 @@ AC_CHECK_FUNCS([flock basename alarm clock_gettime gethostbyname gethostname get
 # let me know! -- rgerhards, 2010-10-06
 AC_CHECK_DECL([SCM_CREDENTIALS], [AC_DEFINE(HAVE_SCM_CREDENTIALS, [1], [set define])], [], [#include <sys/types.h>
 #include <sys/socket.h>])
+AC_CHECK_DECL([SO_TIMESTAMP], [AC_DEFINE(HAVE_SO_TIMESTAMP, [1], [set define])], [], [#include <sys/types.h>
+#include <sys/socket.h>])
 
 # Check for MAXHOSTNAMELEN
 AC_MSG_CHECKING(for MAXHOSTNAMELEN)
diff --git a/doc/imuxsock.html b/doc/imuxsock.html
index ee5db22d..58b3ae54 100644
--- a/doc/imuxsock.html
+++ b/doc/imuxsock.html
@@ -68,9 +68,18 @@ messages that shall be rate-limited.
 be obtained from the log socket itself. If so, the TAG part of the message is rewritten.
 It is recommended to turn this option on, but the default is "off" to keep compatible
 with earlier versions of rsyslog. This option was introduced in 5.7.0.</li>
+<li><b>$InputUnixListenSocketUseSysTimeStamp</b> [<b>on</b>/off] instructs imuxsock
+to obtain message time from the system (via control messages) insted of using time
+recorded inside the message. This may be most useful in combination with systemd. Note:
+this option was introduced with version 5.9.1. Due to the usefulness of it, we
+decided to enable it by default. As such, 5.9.1 and above behave slightly different
+than previous versions. However, we do not see how this could negatively affect
+existing environments.<br>
 <li><b>$SystemLogSocketIgnoreMsgTimestamp</b> [<b>on</b>/off]<br>
 Ignore timestamps included in the messages, applies to messages received via the system log socket.</li>
-<li><b>$OmitLocalLogging</b> (imuxsock) [on/<b>off</b>] -- former -o option</li>
+<li><b>$OmitLocalLogging</b> (imuxsock) [on/<b>off</b>] -- former -o option;
+do NOT listen for the local log socket. This is most useful if you run multiple
+instances of rsyslogd where only one shall handle the system log socket.</li>
 <li><b>$SystemLogSocketName</b> &lt;name-of-socket&gt; -- former -p option</li>
 <li><b>$SystemLogFlowControl</b> [on/<b>off</b>] - specifies if flow control should be applied
 to the system log socket.</li>
@@ -87,6 +96,7 @@ burst in number of messages. Default is 200.
 <li><b>$SystemLogRateLimitSeverity</b> [numerical severity] - specifies the severity of
 messages that shall be rate-limited.
 </li>
+<li><b>$SystemLogUseSysTimeStamp</b> [<b>on</b>/off] the same as $InputUnixListenSocketUseSysTimeStamp, but for the system log socket.
 <li><b>$InputUnixListenSocketCreatePath</b> [on/<b>off</b>] - create directories in the socket path
 if they do not already exist. They are created with 0755 permissions with the owner being the process under
 which rsyslogd runs. The default is not to create directories. Keep in mind, though, that rsyslogd always
diff --git a/plugins/imuxsock/imuxsock.c b/plugins/imuxsock/imuxsock.c
index af034b9f..da9eb993 100644
--- a/plugins/imuxsock/imuxsock.c
+++ b/plugins/imuxsock/imuxsock.c
@@ -6,7 +6,7 @@
  *
  * File begun on 2007-12-20 by RGerhards (extracted from syslogd.c)
  *
- * Copyright 2007-2010 Rainer Gerhards and Adiscon GmbH.
+ * Copyright 2007-2011 Rainer Gerhards and Adiscon GmbH.
  *
  * This file is part of rsyslog.
  *
@@ -136,6 +136,7 @@ typedef struct lstn_s {
 	sbool bCreatePath;	/* auto-creation of socket directory? */
 	sbool bUseCreds;	/* pull original creator credentials from socket */
 	sbool bWritePid;	/* write original PID into tag */
+	sbool bUseSysTimeStamp;	/* use timestamp from system (instead of from message) */
 } lstn_t;
 static lstn_t listeners[MAXFUNIX];
 
@@ -156,6 +157,8 @@ static int bUseFlowCtl = 0;		/* use flow control or not (if yes, only LIGHT is u
 static int bIgnoreTimestamp = 1;	/* ignore timestamps present in the incoming message? */
 static int bWritePid = 0;		/* use credentials from recvmsg() and fixup PID in TAG */
 static int bWritePidSysSock = 0;	/* use credentials from recvmsg() and fixup PID in TAG */
+static int bUseSysTimeStamp = 1;	/* use timestamp from system (rather than from message) */
+static int bUseSysTimeStampSysSock = 1;	/* same, for system log socket */
 #define DFLT_bCreatePath 0
 static int bCreatePath = DFLT_bCreatePath; /* auto-create socket path? */
 #define DFLT_ratelimitInterval 5
@@ -302,6 +305,7 @@ addLstnSocketName(void __attribute__((unused)) *pVal, uchar *pNewVal)
 		listeners[nfd].sockName = pNewVal;
 		listeners[nfd].bUseCreds = (bWritePid || ratelimitInterval) ? 1 : 0;
 		listeners[nfd].bWritePid = bWritePid;
+		listeners[nfd].bUseSysTimeStamp = bUseSysTimeStamp;
 		nfd++;
 	} else {
 		errmsg.LogError(0, NO_ERRCODE, "Out of unix socket name descriptors, ignoring %s\n",
@@ -415,6 +419,10 @@ openLogSocket(lstn_t *pLstn)
 			errmsg.LogError(errno, NO_ERRCODE, "set SCM_CREDENTIALS failed on '%s'", pLstn->sockName);
 			pLstn->bUseCreds = 0;
 		}
+// TODO: move to its own #if
+		if(setsockopt(pLstn->fd, SOL_SOCKET, SO_TIMESTAMP, &one, sizeof(one)) != 0) {
+			errmsg.LogError(errno, NO_ERRCODE, "set SO_TIMESTAMP failed on '%s'", pLstn->sockName);
+		}
 	}
 #	else /* HAVE_SCM_CREDENTIALS */
 	pLstn->bUseCreds = 0;
@@ -505,7 +513,7 @@ fixPID(uchar *bufTAG, int *lenTag, struct ucred *cred)
  * can also mangle it if necessary.
  */
 static inline rsRetVal
-SubmitMsg(uchar *pRcv, int lenRcv, lstn_t *pLstn, struct ucred *cred)
+SubmitMsg(uchar *pRcv, int lenRcv, lstn_t *pLstn, struct ucred *cred, struct timeval *ts)
 {
 	msg_t *pMsg;
 	int lenMsg;
@@ -544,7 +552,13 @@ SubmitMsg(uchar *pRcv, int lenRcv, lstn_t *pLstn, struct ucred *cred)
 		findRatelimiter(pLstn, cred, &ratelimiter); /* ignore error, better so than others... */
 	}
 
-	datetime.getCurrTime(&st, &tt);
+	if(ts == NULL) {
+		datetime.getCurrTime(&st, &tt);
+	} else {
+		datetime.timeval2syslogTime(ts, &st);
+		tt = ts->tv_sec;
+	}
+
 	if(ratelimiter != NULL && !withinRatelimit(ratelimiter, tt, cred->pid)) {
 		STATSCOUNTER_INC(ctrLostRatelimit, mutCtrLostRatelimit);
 		FINALIZE;
@@ -564,8 +578,26 @@ SubmitMsg(uchar *pRcv, int lenRcv, lstn_t *pLstn, struct ucred *cred)
 
 	parse++; lenMsg--; /* '>' */
 
-	if(datetime.ParseTIMESTAMP3164(&(pMsg->tTIMESTAMP), &parse, &lenMsg) != RS_RET_OK) {
-		DBGPRINTF("we have a problem, invalid timestamp in msg!\n");
+	if(ts == NULL) {
+		if(datetime.ParseTIMESTAMP3164(&(pMsg->tTIMESTAMP), &parse, &lenMsg) != RS_RET_OK) {
+			DBGPRINTF("we have a problem, invalid timestamp in msg!\n");
+		}
+	} else { /* if we pulled the time from the system, we need to update the message text */
+		if(lenMsg >= 16) {
+			/* RFC3164 timestamp is 16 bytes long, so assuming a valid stamp,
+			 * we can fixup the message. If the part is smaller, the stamp can
+			 * not be valid and we do not touch the message. Note that there may
+			 * be some scenarios where the message is larg enough but the stamp is
+			 * still invalid. In those cases we will destruct part of the message,
+			 * but this case is considered extremely unlikely and thus not handled
+			 * specifically. -- rgerhards, 2011-06-20
+			 */
+			datetime.formatTimestamp3164(&st, (char*)parse, 0);
+			parse[15] = ' '; /* re-write \0 from fromatTimestamp3164 by SP */
+			/* update "counters" to reflect processed timestamp */
+			parse += 16;
+			lenMsg -= 16;
+		}
 	}
 
 	/* pull tag */
@@ -616,6 +648,7 @@ static rsRetVal readSocket(lstn_t *pLstn)
 	struct cmsghdr *cm;
 #	endif
 	struct ucred *cred;
+	struct timeval *ts;
 	uchar bufRcv[4096+1];
 	char aux[128];
 	uchar *pRcv = NULL; /* receive buffer */
@@ -654,21 +687,32 @@ static rsRetVal readSocket(lstn_t *pLstn)
 	dbgprintf("Message from UNIX socket: #%d\n", pLstn->fd);
 	if(iRcvd > 0) {
 		cred = NULL;
-#		if HAVE_SCM_CREDENTIALS
-		if(pLstn->bUseCreds) {
+		ts = NULL;
+		if(pLstn->bUseCreds || pLstn->bUseSysTimeStamp) {
 			dbgprintf("XXX: pre CM loop, length of control message %d\n", (int) msgh.msg_controllen);
-			for (cm = CMSG_FIRSTHDR(&msgh); cm; cm = CMSG_NXTHDR(&msgh, cm)) {
+			for(cm = CMSG_FIRSTHDR(&msgh); cm; cm = CMSG_NXTHDR(&msgh, cm)) {
 				dbgprintf("XXX: in CM loop, %d, %d\n", cm->cmsg_level, cm->cmsg_type);
-				if (cm->cmsg_level == SOL_SOCKET && cm->cmsg_type == SCM_CREDENTIALS) {
+#				if HAVE_SCM_CREDENTIALS
+				if(   pLstn->bUseCreds
+				   && cm->cmsg_level == SOL_SOCKET && cm->cmsg_type == SCM_CREDENTIALS) {
 					cred = (struct ucred*) CMSG_DATA(cm);
 					dbgprintf("XXX: got credentials pid %d\n", (int) cred->pid);
 					break;
 				}
+#				endif /* HAVE_SCM_CREDENTIALS */
+#				if HAVE_SO_TIMESTAMP
+				if(   pLstn->bUseSysTimeStamp 
+				   && cm->cmsg_level == SOL_SOCKET && cm->cmsg_type == SO_TIMESTAMP) {
+					ts = (struct timeval *)CMSG_DATA(cm);
+					dbgprintf("XXX: got timestamp %ld.%ld\n",
+					  	(long) ts->tv_sec, (long) ts->tv_usec);
+					break;
+				}
+#				endif /* HAVE_SO_TIMESTAMP */
 			}
 			dbgprintf("XXX: post CM loop\n");
 		}
-#		endif /* HAVE_SCM_CREDENTIALS */
-		CHKiRet(SubmitMsg(pRcv, iRcvd, pLstn, cred));
+		CHKiRet(SubmitMsg(pRcv, iRcvd, pLstn, cred, ts));
 	} else if(iRcvd < 0 && errno != EINTR) {
 		char errStr[1024];
 		rs_strerror_r(errno, errStr, sizeof(errStr));
@@ -780,6 +824,7 @@ CODESTARTwillRun
 	listeners[0].ratelimitSev = ratelimitSeveritySysSock;
 	listeners[0].bUseCreds = (bWritePidSysSock || ratelimitIntervalSysSock) ? 1 : 0;
 	listeners[0].bWritePid = bWritePidSysSock;
+	listeners[0].bUseSysTimeStamp = bUseSysTimeStampSysSock;
 
 	sd_fds = sd_listen_fds(0);
 	if (sd_fds < 0) {
@@ -892,6 +937,8 @@ static rsRetVal resetConfigVariables(uchar __attribute__((unused)) *pp, void __a
 	bUseFlowCtl = 0;
 	bWritePid = 0;
 	bWritePidSysSock = 0;
+	bUseSysTimeStamp = 1;
+	bUseSysTimeStampSysSock = 1;
 	bCreatePath = DFLT_bCreatePath;
 	ratelimitInterval = DFLT_ratelimitInterval;
 	ratelimitIntervalSysSock = DFLT_ratelimitInterval;
@@ -927,6 +974,7 @@ CODEmodInit_QueryRegCFSLineHdlr
 	listeners[0].bParseHost = 0;
 	listeners[0].bUseCreds = 0;
 	listeners[0].bCreatePath = 0;
+	listeners[0].bUseSysTimeStamp = 1;
 
 	/* initialize socket names */
 	for(i = 1 ; i < MAXFUNIX ; ++i) {
@@ -958,6 +1006,8 @@ CODEmodInit_QueryRegCFSLineHdlr
 		NULL, &bCreatePath, STD_LOADABLE_MODULE_ID));
 	CHKiRet(omsdRegCFSLineHdlr((uchar *)"inputunixlistensocketusepidfromsystem", 0, eCmdHdlrBinary,
 		NULL, &bWritePid, STD_LOADABLE_MODULE_ID));
+	CHKiRet(omsdRegCFSLineHdlr((uchar *)"inputunixlistensocketusesystimestamp", 0, eCmdHdlrBinary,
+		NULL, &bUseSysTimeStamp, STD_LOADABLE_MODULE_ID));
 	CHKiRet(omsdRegCFSLineHdlr((uchar *)"addunixlistensocket", 0, eCmdHdlrGetWord,
 		addLstnSocketName, NULL, STD_LOADABLE_MODULE_ID));
 	CHKiRet(omsdRegCFSLineHdlr((uchar *)"imuxsockratelimitinterval", 0, eCmdHdlrInt,
@@ -978,6 +1028,8 @@ CODEmodInit_QueryRegCFSLineHdlr
 		setSystemLogTimestampIgnore, NULL, STD_LOADABLE_MODULE_ID));
 	CHKiRet(omsdRegCFSLineHdlr((uchar *)"systemlogsocketflowcontrol", 0, eCmdHdlrBinary,
 		setSystemLogFlowControl, NULL, STD_LOADABLE_MODULE_ID));
+	CHKiRet(omsdRegCFSLineHdlr((uchar *)"systemlogusesystimestamp", 0, eCmdHdlrBinary,
+		NULL, &bUseSysTimeStampSysSock, STD_LOADABLE_MODULE_ID));
 	CHKiRet(omsdRegCFSLineHdlr((uchar *)"systemlogusepidfromsystem", 0, eCmdHdlrBinary,
 		NULL, &bWritePidSysSock, STD_LOADABLE_MODULE_ID));
 	CHKiRet(omsdRegCFSLineHdlr((uchar *)"systemlogratelimitinterval", 0, eCmdHdlrInt,
diff --git a/runtime/datetime.c b/runtime/datetime.c
index f81180ea..89452f1c 100644
--- a/runtime/datetime.c
+++ b/runtime/datetime.c
@@ -55,6 +55,47 @@ static const int tenPowers[6] = { 1, 10, 100, 1000, 10000, 100000 };
 /* ------------------------------ methods ------------------------------ */
 
 
+/** 
+ * Convert struct timeval to syslog_time
+ */
+void
+timeval2syslogTime(struct timeval *tp, struct syslogTime *t)
+{
+	struct tm *tm;
+	struct tm tmBuf;
+	long lBias;
+
+	tm = localtime_r((time_t*) &(tp->tv_sec), &tmBuf);
+
+	t->year = tm->tm_year + 1900;
+	t->month = tm->tm_mon + 1;
+	t->day = tm->tm_mday;
+	t->hour = tm->tm_hour;
+	t->minute = tm->tm_min;
+	t->second = tm->tm_sec;
+	t->secfrac = tp->tv_usec;
+	t->secfracPrecision = 6;
+
+#	if __sun
+		/* Solaris uses a different method of exporting the time zone.
+		 * It is UTC - localtime, which is the opposite sign of mins east of GMT.
+		 */
+		lBias = -(daylight ? altzone : timezone);
+#	elif defined(__hpux)
+		lBias = tz.tz_dsttime ? - tz.tz_minuteswest : 0;
+#	else
+		lBias = tm->tm_gmtoff;
+#	endif
+	if(lBias < 0) {
+		t->OffsetMode = '-';
+		lBias *= -1;
+	} else
+		t->OffsetMode = '+';
+	t->OffsetHour = lBias / 3600;
+	t->OffsetMinute = (lBias % 3600) / 60;
+	t->timeType = TIME_TYPE_RFC5424; /* we have a high precision timestamp */
+}
+
 /**
  * Get the current date/time in the best resolution the operating
  * system has to offer (well, actually at most down to the milli-
@@ -74,9 +115,6 @@ static const int tenPowers[6] = { 1, 10, 100, 1000, 10000, 100000 };
 static void getCurrTime(struct syslogTime *t, time_t *ttSeconds)
 {
 	struct timeval tp;
-	struct tm *tm;
-	struct tm tmBuf;
-	long lBias;
 #	if defined(__hpux)
 	struct timezone tz;
 #	endif
@@ -93,37 +131,7 @@ static void getCurrTime(struct syslogTime *t, time_t *ttSeconds)
 	if(ttSeconds != NULL)
 		*ttSeconds = tp.tv_sec;
 
-	tm = localtime_r((time_t*) &(tp.tv_sec), &tmBuf);
-
-	t->year = tm->tm_year + 1900;
-	t->month = tm->tm_mon + 1;
-	t->day = tm->tm_mday;
-	t->hour = tm->tm_hour;
-	t->minute = tm->tm_min;
-	t->second = tm->tm_sec;
-	t->secfrac = tp.tv_usec;
-	t->secfracPrecision = 6;
-
-#	if __sun
-		/* Solaris uses a different method of exporting the time zone.
-		 * It is UTC - localtime, which is the opposite sign of mins east of GMT.
-		 */
-		lBias = -(daylight ? altzone : timezone);
-#	elif defined(__hpux)
-		lBias = tz.tz_dsttime ? - tz.tz_minuteswest : 0;
-#	else
-		lBias = tm->tm_gmtoff;
-#	endif
-	if(lBias < 0)
-	{
-		t->OffsetMode = '-';
-		lBias *= -1;
-	}
-	else
-		t->OffsetMode = '+';
-	t->OffsetHour = lBias / 3600;
-	t->OffsetMinute = (lBias % 3600) / 60;
-	t->timeType = TIME_TYPE_RFC5424; /* we have a high precision timestamp */
+	timeval2syslogTime(&tp, t);
 }
 
 
@@ -861,6 +869,7 @@ CODESTARTobjQueryInterface(datetime)
 	 */
 	pIf->getCurrTime = getCurrTime;
 	pIf->GetTime = getTime;
+	pIf->timeval2syslogTime = timeval2syslogTime;
 	pIf->ParseTIMESTAMP3339 = ParseTIMESTAMP3339;
 	pIf->ParseTIMESTAMP3164 = ParseTIMESTAMP3164;
 	pIf->formatTimestampToMySQL = formatTimestampToMySQL;
diff --git a/runtime/datetime.h b/runtime/datetime.h
index 70bbf416..2175d6a1 100644
--- a/runtime/datetime.h
+++ b/runtime/datetime.h
@@ -44,8 +44,10 @@ BEGINinterface(datetime) /* name must also be changed in ENDinterface macro! */
 	int (*formatTimestampSecFrac)(struct syslogTime *ts, char* pBuf);
 	/* v3, 2009-11-12 */
 	time_t (*GetTime)(time_t *ttSeconds);
+	/* v6, 2011-06-20 */
+	void (*timeval2syslogTime)(struct timeval *tp, struct syslogTime *t);
 ENDinterface(datetime)
-#define datetimeCURR_IF_VERSION 5 /* increment whenever you change the interface structure! */
+#define datetimeCURR_IF_VERSION 6 /* increment whenever you change the interface structure! */
 /* interface changes:
  * 1 - initial version
  * 2 - not compatible to 1 - bugfix required ParseTIMESTAMP3164 to accept char ** as
@@ -54,6 +56,7 @@ ENDinterface(datetime)
  * 3 - taken by v5 branch!
  * 4 - formatTimestamp3164 takes a third int parameter
  * 5 - merge of versions 3 + 4 (2010-03-09)
+ * 6 - see above
  */
 
 /* prototypes */