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.

1 files changed, 63 insertions, 11 deletions

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,