"output" timestamp now taken from mesg's time generated

This enhances performance and, as some have pointed out, is
probably also more consistent with what users expect how
the various output-timestamp related function should work. This
commit needs some more testing.

13 files changed, 59 insertions, 33 deletions

diff --git a/ChangeLog b/ChangeLog
index 346ff39c..0f3d4591 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,5 +1,14 @@
 ---------------------------------------------------------------------------
 Version 3.21.6  [DEVEL] (rgerhards), 2008-10-??
+
+********************************* WARNING *********************************
+This version has a slightly different on-disk format for message entries.
+As a consequence, old queue files being read by this version may have
+an invalid output timestamp, which could result to some malfunction inside
+the output driver. It is recommended to drain queues with the previous
+version before switching to this one.
+********************************* WARNING *********************************
+
 - added $UDPServerTimeRequery option which enables to work with
   less acurate timestamps in favor of performance. This enables querying
   of the time only every n-th time if imudp is running in the tight
diff --git a/action.c b/action.c
index a25eca23..cc62f028 100644
--- a/action.c
+++ b/action.c
@@ -602,7 +602,7 @@ actionWriteToAction(action_t *pAction)
 		 * ... RAWMSG is a problem ... Please note that digital
 		 * signatures inside the message are also invalidated.
 		 */
-		datetime.getCurrTime(&(pMsg->tRcvdAt));
+		datetime.getCurrTime(&(pMsg->tRcvdAt), &(pMsg->ttGenTime));
 		memcpy(&pMsg->tTIMESTAMP, &pMsg->tRcvdAt, sizeof(struct syslogTime));
 		MsgSetMSG(pMsg, (char*)szRepMsg);
 		MsgSetRawMsg(pMsg, (char*)szRepMsg);
@@ -640,6 +640,7 @@ actionWriteToAction(action_t *pAction)
 	 * while in the on-disk queue. Also need to think about a few other implications.
 	 * rgerhards, 2008-09-17
 	 */
+#if 0
 	{
 		struct tm tTm;
 		tTm.tm_sec = pAction->f_pMsg->tRcvdAt.second;
@@ -655,7 +656,10 @@ actionWriteToAction(action_t *pAction)
 /* note: mktime seems to do a stat(/etc/localtime), so this is also sub-optimal! */
 dbgprintf("XXXX create our own timestamp: %ld, system time is %ld\n", pAction->f_time, time(NULL));
 	}
+#endif
 
+		pAction->f_time = pAction->f_pMsg->ttGenTime;
+dbgprintf("XXXX create our own timestamp: %ld, system time is %ld\n", pAction->f_time, time(NULL));
 	//pAction->f_time = getActNow(pAction); /* re-init time flags */
 	/* Note: tLastExec could be set in the if block above, but f_time causes us a hard time
 	 * so far, I do not see a solution to getting rid of it. -- rgerhards, 2008-09-16
diff --git a/dirty.h b/dirty.h
index 58c4ea39..8e7ffd84 100644
--- a/dirty.h
+++ b/dirty.h
@@ -40,7 +40,7 @@
 
 rsRetVal submitMsg(msg_t *pMsg);
 rsRetVal logmsgInternal(int iErr, int pri, uchar *msg, int flags);
-rsRetVal parseAndSubmitMessage(uchar *hname, uchar *hnameIP, uchar *msg, int len, int bParseHost, int flags, flowControl_t flowCtlTypeu, uchar *pszInputName, struct syslogTime *stTime);
+rsRetVal parseAndSubmitMessage(uchar *hname, uchar *hnameIP, uchar *msg, int len, int bParseHost, int flags, flowControl_t flowCtlTypeu, uchar *pszInputName, struct syslogTime *stTime, time_t ttGenTime);
 
 /* TODO: the following 2 need to go in conf obj interface... */
 rsRetVal cflineParseTemplateName(uchar** pp, omodStringRequest_t *pOMSR, int iEntry, int iTplOpts, uchar *dfltTplName);
diff --git a/plugins/imrelp/imrelp.c b/plugins/imrelp/imrelp.c
index f3771237..4515acd7 100644
--- a/plugins/imrelp/imrelp.c
+++ b/plugins/imrelp/imrelp.c
@@ -84,7 +84,7 @@ onSyslogRcv(uchar *pHostname, uchar __attribute__((unused)) *pIP, uchar *pMsg, s
 {
 	DEFiRet;
 	parseAndSubmitMessage(pHostname, (uchar*) "[unset]", pMsg, lenMsg, MSG_PARSE_HOSTNAME,
-			      NOFLAG, eFLOWCTL_LIGHT_DELAY, (uchar*)"imrelp", NULL);
+			      NOFLAG, eFLOWCTL_LIGHT_DELAY, (uchar*)"imrelp", NULL, 0);
 
 	RETiRet;
 }
diff --git a/plugins/imudp/imudp.c b/plugins/imudp/imudp.c
index d13314e8..d58a0d8e 100644
--- a/plugins/imudp/imudp.c
+++ b/plugins/imudp/imudp.c
@@ -155,6 +155,7 @@ BEGINrunInput
 	uchar fromHostIP[NI_MAXHOST];
 	uchar fromHostFQDN[NI_MAXHOST];
 	ssize_t l;
+	time_t ttGenTime;
 	struct syslogTime stTime;
 	int iNbrTimeUsed;
 CODESTARTrunInput
@@ -227,10 +228,11 @@ CODESTARTrunInput
 						       if(net.isAllowedSender(net.pAllowedSenders_UDP,
 							  (struct sockaddr *)&frominet, (char*)fromHostFQDN)) {
 								if((iTimeRequery == 0) || (iNbrTimeUsed++ % iTimeRequery) == 0) {
-									datetime.getCurrTime(&stTime);
+									datetime.getCurrTime(&stTime, &ttGenTime);
 								}
 							       parseAndSubmitMessage(fromHost, fromHostIP, pRcvBuf, l,
-							       MSG_PARSE_HOSTNAME, NOFLAG, eFLOWCTL_NO_DELAY, (uchar*)"imudp", &stTime);
+							       MSG_PARSE_HOSTNAME, NOFLAG, eFLOWCTL_NO_DELAY, (uchar*)"imudp",
+							       &stTime, ttGenTime);
 						       } else {
 							       dbgprintf("%s is not an allowed sender\n", (char*)fromHostFQDN);
 							       if(glbl.GetOption_DisallowWarning) {
diff --git a/plugins/imuxsock/imuxsock.c b/plugins/imuxsock/imuxsock.c
index 77d347d9..efa0365d 100644
--- a/plugins/imuxsock/imuxsock.c
+++ b/plugins/imuxsock/imuxsock.c
@@ -221,7 +221,7 @@ static rsRetVal readSocket(int fd, int iSock)
 	if (iRcvd > 0) {
 		parseAndSubmitMessage(funixHName[iSock] == NULL ? glbl.GetLocalHostName() : funixHName[iSock],
 				      (uchar*)"127.0.0.1", pRcv,
-			 	      iRcvd, funixParseHost[iSock], funixFlags[iSock], funixFlowCtl[iSock], (uchar*)"imuxsock", NULL);
+			 	      iRcvd, funixParseHost[iSock], funixFlags[iSock], funixFlowCtl[iSock], (uchar*)"imuxsock", NULL, 0);
 	} else if (iRcvd < 0 && errno != EINTR) {
 		char errStr[1024];
 		rs_strerror_r(errno, errStr, sizeof(errStr));
diff --git a/runtime/datetime.c b/runtime/datetime.c
index 20ca6191..aa1956d7 100644
--- a/runtime/datetime.c
+++ b/runtime/datetime.c
@@ -62,9 +62,14 @@ DEFobjCurrIf(errmsg)
  * most portable and removes the need for additional structures
  * (but I have to admit it is somewhat "bulky";)).
  *
- * Obviously, all caller-provided pointers must not be NULL...
+ * Obviously, *t must not be NULL...
+ *
+ * rgerhards, 2008-10-07: added ttSeconds to provide a way to 
+ * obtain the second-resolution UNIX timestamp. This is needed
+ * in some situations to minimize time() calls (namely when doing
+ * output processing). This can be left NULL if not needed.
  */
-static void getCurrTime(struct syslogTime *t)
+static void getCurrTime(struct syslogTime *t, time_t *ttSeconds)
 {
 	struct timeval tp;
 	struct tm *tm;
@@ -83,6 +88,9 @@ static void getCurrTime(struct syslogTime *t)
 #	else
 		gettimeofday(&tp, NULL);
 #	endif
+	if(ttSeconds != NULL)
+		*ttSeconds = tp.tv_sec;
+
 	tm = localtime_r((time_t*) &(tp.tv_sec), &tmBuf);
 
 	t->year = tm->tm_year + 1900;
diff --git a/runtime/datetime.h b/runtime/datetime.h
index 2210af02..0739588d 100644
--- a/runtime/datetime.h
+++ b/runtime/datetime.h
@@ -35,7 +35,7 @@ typedef struct datetime_s {
 
 /* interfaces */
 BEGINinterface(datetime) /* name must also be changed in ENDinterface macro! */
-	void (*getCurrTime)(struct syslogTime *t);
+	void (*getCurrTime)(struct syslogTime *t, time_t *ttSeconds);
 	rsRetVal (*ParseTIMESTAMP3339)(struct syslogTime *pTime, char** ppszTS);
 	rsRetVal (*ParseTIMESTAMP3164)(struct syslogTime *pTime, char** pszTS);
 	int (*formatTimestampToMySQL)(struct syslogTime *ts, char* pDst, size_t iLenDst);
diff --git a/runtime/msg.c b/runtime/msg.c
index df8c1572..fd838591 100644
--- a/runtime/msg.c
+++ b/runtime/msg.c
@@ -286,11 +286,12 @@ finalize_it:
  * udp input).
  * rgerhards, 2008-10-06
  */
-rsRetVal msgConstructWithTime(msg_t **ppThis, struct syslogTime *stTime)
+rsRetVal msgConstructWithTime(msg_t **ppThis, struct syslogTime *stTime, time_t ttGenTime)
 {
 	DEFiRet;
 
 	CHKiRet(msgBaseConstruct(ppThis));
+	(*ppThis)->ttGenTime = ttGenTime;
 	memcpy(&(*ppThis)->tRcvdAt, stTime, sizeof(struct syslogTime));
 	memcpy(&(*ppThis)->tTIMESTAMP, stTime, sizeof(struct syslogTime));
 
@@ -316,7 +317,7 @@ rsRetVal msgConstruct(msg_t **ppThis)
 	 * especially as I think there is no codepath currently where it would not be
 	 * required (after I have cleaned up the pathes ;)). -- rgerhards, 2008-10-02
 	 */
-	datetime.getCurrTime(&((*ppThis)->tRcvdAt));
+	datetime.getCurrTime(&((*ppThis)->tRcvdAt), &((*ppThis)->ttGenTime));
 	memcpy(&(*ppThis)->tTIMESTAMP, &(*ppThis)->tRcvdAt, sizeof(struct syslogTime));
 
 finalize_it:
@@ -442,7 +443,7 @@ msg_t* MsgDup(msg_t* pOld)
 	assert(pOld != NULL);
 
 	BEGINfunc
-	if(msgConstruct(&pNew) != RS_RET_OK) {
+	if(msgConstructWithTime(&pNew, &pOld->tTIMESTAMP, pOld->ttGenTime) != RS_RET_OK) {
 		return NULL;
 	}
 
@@ -453,8 +454,7 @@ msg_t* MsgDup(msg_t* pOld)
 	pNew->bParseHOSTNAME = pOld->bParseHOSTNAME;
 	pNew->msgFlags = pOld->msgFlags;
 	pNew->iProtocolVersion = pOld->iProtocolVersion;
-	memcpy(&pNew->tRcvdAt, &pOld->tRcvdAt, sizeof(struct syslogTime));
-	memcpy(&pNew->tTIMESTAMP, &pOld->tTIMESTAMP, sizeof(struct syslogTime));
+	pNew->ttGenTime = pOld->ttGenTime;
 	tmpCOPYSZ(Severity);
 	tmpCOPYSZ(SeverityStr);
 	tmpCOPYSZ(Facility);
@@ -508,6 +508,7 @@ static rsRetVal MsgSerialize(msg_t *pThis, strm_t *pStrm)
 	objSerializeSCALAR(pStrm, iSeverity, SHORT);
 	objSerializeSCALAR(pStrm, iFacility, SHORT);
 	objSerializeSCALAR(pStrm, msgFlags, INT);
+	objSerializeSCALAR(pStrm, ttGenTime, INT);
 	objSerializeSCALAR(pStrm, tRcvdAt, SYSLOGTIME);
 	objSerializeSCALAR(pStrm, tTIMESTAMP, SYSLOGTIME);
 
@@ -1669,7 +1670,7 @@ static uchar *getNOW(eNOWType eNow)
 		return NULL;
 	}
 
-	datetime.getCurrTime(&t);
+	datetime.getCurrTime(&t, NULL);
 	switch(eNow) {
 	case NOW_NOW:
 		snprintf((char*) pBuf, tmpBUFSIZE, "%4.4d-%2.2d-%2.2d", t.year, t.month, t.day);
@@ -2477,6 +2478,8 @@ rsRetVal MsgSetProperty(msg_t *pThis, var_t *pProp)
 		MsgSetPROCID(pThis, (char*) rsCStrGetSzStrNoNULL(pProp->val.pStr));
 	} else if(isProp("pCSMSGID")) {
 		MsgSetMSGID(pThis, (char*) rsCStrGetSzStrNoNULL(pProp->val.pStr));
+ 	} else if(isProp("ttGenTime")) {
+		pThis->ttGenTime = pProp->val.num;
 	} else if(isProp("tRcvdAt")) {
 		memcpy(&pThis->tRcvdAt, &pProp->val.vSyslogTime, sizeof(struct syslogTime));
 	} else if(isProp("tTIMESTAMP")) {
diff --git a/runtime/msg.h b/runtime/msg.h
index d3c0718b..d2fc2f30 100644
--- a/runtime/msg.h
+++ b/runtime/msg.h
@@ -99,6 +99,13 @@ struct msg {
 	cstr_t *pCSAPPNAME;	/* APP-NAME */
 	cstr_t *pCSPROCID;	/* PROCID */
 	cstr_t *pCSMSGID;	/* MSGID */
+	time_t ttGenTime;	/* time msg object was generated, same as tRcvdAt, but a Unix timestamp.
+				   While this field looks redundant, it is required because a Unix timestamp
+				   is used at later processing stages (namely in the output arena). Thanks to
+				   the subleties of how time is defined, there is no reliable way to reconstruct
+				   the Unix timestamp from the syslogTime fields (in practice, we may be close
+				   enough to reliable, but I prefer to leave the subtle things to the OS, where
+				   it obviously is solved in way or another...). */
 	struct syslogTime tRcvdAt;/* time the message entered this program */
 	char *pszRcvdAt3164;	/* time as RFC3164 formatted string (always 15 charcters) */
 	char *pszRcvdAt3339;	/* time as RFC3164 formatted string (32 charcters at most) */
@@ -119,7 +126,7 @@ struct msg {
 PROTOTYPEObjClassInit(msg);
 char* getProgramName(msg_t*);
 rsRetVal msgConstruct(msg_t **ppThis);
-rsRetVal msgConstructWithTime(msg_t **ppThis, struct syslogTime *stTime);
+rsRetVal msgConstructWithTime(msg_t **ppThis, struct syslogTime *stTime, time_t ttGenTime);
 rsRetVal msgDestruct(msg_t **ppM);
 msg_t* MsgDup(msg_t* pOld);
 msg_t *MsgAddRef(msg_t *pM);
diff --git a/runtime/sysvar.c b/runtime/sysvar.c
index 5eec8f67..c102d1f5 100644
--- a/runtime/sysvar.c
+++ b/runtime/sysvar.c
@@ -84,7 +84,7 @@ getNOW(eNOWType eNow, cstr_t **ppStr)
 	uchar szBuf[16];
 	struct syslogTime t;
 
-	datetime.getCurrTime(&t);
+	datetime.getCurrTime(&t, NULL);
 	switch(eNow) {
 	case NOW_NOW:
 		snprintf((char*) szBuf, sizeof(szBuf)/sizeof(uchar), "%4.4d-%2.2d-%2.2d", t.year, t.month, t.day);
diff --git a/tcps_sess.c b/tcps_sess.c
index 7ce9f2f8..13644f45 100644
--- a/tcps_sess.c
+++ b/tcps_sess.c
@@ -230,7 +230,7 @@ PrepareClose(tcps_sess_t *pThis)
 		 */
 		dbgprintf("Extra data at end of stream in legacy syslog/tcp message - processing\n");
 		parseAndSubmitMessage(pThis->fromHost, pThis->fromHostIP, pThis->pMsg, pThis->iMsg, MSG_PARSE_HOSTNAME,
-				      NOFLAG, eFLOWCTL_LIGHT_DELAY, NULL, NULL); /* TODO: add real InputName */
+				      NOFLAG, eFLOWCTL_LIGHT_DELAY, NULL, NULL, 0); /* TODO: add real InputName */
 		pThis->bAtStrtOfFram = 1;
 	}
 
@@ -313,7 +313,7 @@ processDataRcvd(tcps_sess_t *pThis, char c)
 			/* emergency, we now need to flush, no matter if we are at end of message or not... */
 			dbgprintf("error: message received is larger than max msg size, we split it\n");
 			parseAndSubmitMessage(pThis->fromHost, pThis->fromHostIP, pThis->pMsg, pThis->iMsg,
-					      MSG_PARSE_HOSTNAME, NOFLAG, eFLOWCTL_LIGHT_DELAY, NULL, NULL); /* TODO: add real InputName */
+					      MSG_PARSE_HOSTNAME, NOFLAG, eFLOWCTL_LIGHT_DELAY, NULL, NULL, 0); /* TODO: add real InputName */
 			pThis->iMsg = 0;
 			/* we might think if it is better to ignore the rest of the
 			 * message than to treat it as a new one. Maybe this is a good
@@ -324,7 +324,7 @@ processDataRcvd(tcps_sess_t *pThis, char c)
 
 		if(c == '\n' && pThis->eFraming == TCP_FRAMING_OCTET_STUFFING) { /* record delemiter? */
 			parseAndSubmitMessage(pThis->fromHost, pThis->fromHostIP, pThis->pMsg, pThis->iMsg,
-					      MSG_PARSE_HOSTNAME, NOFLAG, eFLOWCTL_LIGHT_DELAY, NULL, NULL); /* TODO: add real InputName */
+					      MSG_PARSE_HOSTNAME, NOFLAG, eFLOWCTL_LIGHT_DELAY, NULL, NULL, 0); /* TODO: add real InputName */
 			pThis->iMsg = 0;
 			pThis->inputState = eAtStrtFram;
 		} else {
@@ -343,7 +343,7 @@ processDataRcvd(tcps_sess_t *pThis, char c)
 			if(pThis->iOctetsRemain < 1) {
 				/* we have end of frame! */
 				parseAndSubmitMessage(pThis->fromHost, pThis->fromHostIP, pThis->pMsg, pThis->iMsg,
-					      MSG_PARSE_HOSTNAME, NOFLAG, eFLOWCTL_LIGHT_DELAY, NULL, NULL); /* TODO: add real InputName */
+					      MSG_PARSE_HOSTNAME, NOFLAG, eFLOWCTL_LIGHT_DELAY, NULL, NULL, 0); /* TODO: add real InputName */
 				pThis->iMsg = 0;
 				pThis->inputState = eAtStrtFram;
 			}
diff --git a/tools/syslogd.c b/tools/syslogd.c
index a6e17d8f..e794e2d1 100644
--- a/tools/syslogd.c
+++ b/tools/syslogd.c
@@ -589,7 +589,7 @@ void untty(void)
  * If stTime is NULL, the current system time is used.
  */
 static inline rsRetVal printline(uchar *hname, uchar *hnameIP, uchar *msg, int bParseHost, int flags, flowControl_t flowCtlType,
-	uchar *pszInputName, struct syslogTime *stTime)
+	uchar *pszInputName, struct syslogTime *stTime, time_t ttGenTime)
 {
 	DEFiRet;
 	register uchar *p;
@@ -600,7 +600,7 @@ static inline rsRetVal printline(uchar *hname, uchar *hnameIP, uchar *msg, int b
 	if(stTime == NULL) {
 		CHKiRet(msgConstruct(&pMsg));
 	} else {
-		CHKiRet(msgConstructWithTime(&pMsg, stTime));
+		CHKiRet(msgConstructWithTime(&pMsg, stTime, ttGenTime));
 	}
 	if(pszInputName != NULL)
 		MsgSetInputName(pMsg, (char*) pszInputName);
@@ -703,7 +703,7 @@ finalize_it:
  */
 rsRetVal
 parseAndSubmitMessage(uchar *hname, uchar *hnameIP, uchar *msg, int len, int bParseHost, int flags, flowControl_t flowCtlType,
-	uchar *pszInputName, struct syslogTime *stTime)
+	uchar *pszInputName, struct syslogTime *stTime, time_t ttGenTime)
 {
 	DEFiRet;
 	register int iMsg;
@@ -814,7 +814,7 @@ parseAndSubmitMessage(uchar *hname, uchar *hnameIP, uchar *msg, int len, int bPa
 			 */
 			if(iMsg == iMaxLine) {
 				*(pMsg + iMsg) = '\0'; /* space *is* reserved for this! */
-				printline(hname, hnameIP, tmpline, bParseHost, flags, flowCtlType, pszInputName, stTime);
+				printline(hname, hnameIP, tmpline, bParseHost, flags, flowCtlType, pszInputName, stTime, ttGenTime);
 			} else {
 				/* This case in theory never can happen. If it happens, we have
 				 * a logic error. I am checking for it, because if I would not,
@@ -866,7 +866,7 @@ parseAndSubmitMessage(uchar *hname, uchar *hnameIP, uchar *msg, int len, int bPa
 	*(pMsg + iMsg) = '\0'; /* space *is* reserved for this! */
 
 	/* typically, we should end up here! */
-	printline(hname, hnameIP, tmpline, bParseHost, flags, flowCtlType, pszInputName, stTime);
+	printline(hname, hnameIP, tmpline, bParseHost, flags, flowCtlType, pszInputName, stTime, ttGenTime);
 
 finalize_it:
 	if(tmpline != NULL)
@@ -1358,13 +1358,6 @@ static int parseRFCSyslogMsg(msg_t *pMsg, int flags)
 	} else {
 		/* we can not parse, so we get the system we
 		 * received the data from.
-	datetime.getCurrTime(&((*ppThis)->tRcvdAt));
-	datetime.getCurrTime(&((*ppThis)->tRcvdAt));
-	datetime.getCurrTime(&((*ppThis)->tRcvdAt));
-	datetime.getCurrTime(&((*ppThis)->tRcvdAt));
-	datetime.getCurrTime(&((*ppThis)->tRcvdAt));
-	datetime.getCurrTime(&((*ppThis)->tRcvdAt));
-	datetime.getCurrTime(&((*ppThis)->tRcvdAt));
 		 */
 		MsgSetHOSTNAME(pMsg, getRcvFrom(pMsg));
 	}