imkmsg: add params parseKernelTimestamp and fixKernelTimeStamp

... as module parameters. Here, "parseKernelTimestamp" is modelled
after the same param from imklog. In essence, it permits to ignore
all kernel time stamps and use current time instead.

Parameter fixKernelTimeStamp uses the kernel time stamp during the
initial read loop of /dev/kmsg, but replaced it later ignores it
for later reads.

The reasoning at least for the later is given in a sysklogd commit by
Joachim Wiberg, which we reproduce here to have a stable reference.
The commit itself can be found for example at:

troglobit/sysklogd@9f6fbb3

============== QUOTE ===============
The spec[1] says the /dev/kmsg timestamp is a monotonic clock and in
microseconds.  After a while you realize it's also relative to the boot
of the system, that fact was probably too obvious to be put in the spec.
However, what's *not* in the spec, and what takes a while to realize, is
that this monotonic time is *not* adjusted for suspend/resume cycles ...

On a frequently used laptop this can manifest itself as follows.  The
kernel is stuck on Nov 15, and for the life of me I cannot find any to
adjust for this offset:

    $ dmesg -T |tail -1; date
    [Mon Nov 15 01:42:08 2021] wlan0: Limiting TX power to 23 (23 - 0) dBm as advertised by 18:e8:29:55:b0:62
    Tue 23 Nov 2021 05:20:53 PM CET

Hence this patch.  After initial "emptying" of /dev/kmsg when syslogd
starts up, we raise a flag (denoting done with backlog), and after this
point we ignore the kernel's idea of time and replace it with the actual
time we have now, the same that userspace messages are logged with.

Sure, there will be occasions where there's a LOT of kernel messages to
read and we won't be able to keep track.  Yet, this patch is better than
the current state (where we log Nov 15).

[1]: https://www.kernel.org/doc/Documentation/ABI/testing/dev-kmsg
===========END QUOTE ===============

closes rsyslog#4561
closes rsyslog#5161

contrib/imkmsg/imkmsg.c

@@ -8,7 +8,7 @@
  * To test under Linux:
  * echo test1 > /dev/kmsg
  *
- * Copyright (C) 2008-2014 Adiscon GmbH
+ * Copyright (C) 2008-2023 Adiscon GmbH
  *
  * This file is part of rsyslog.
  *
@@ -70,6 +70,17 @@ static modConfData_t *loadModConf = NULL;/* modConf ptr to use for the current l
 static modConfData_t *runModConf = NULL;/* modConf ptr to use for the current load process */
 static int bLegacyCnfModGlobalsPermitted;/* are legacy module-global config parameters permitted? */
 
+/* module-global parameters */
+static struct cnfparamdescr modpdescr[] = {
+	{ "parsekerneltimestamp", eCmdHdlrBinary, 0 },
+	{ "fixkerneltimestamp", eCmdHdlrBinary, 0 },
+};
+static struct cnfparamblk modpblk =
+	{ CNFPARAMBLK_VERSION,
+	  sizeof(modpdescr)/sizeof(struct cnfparamdescr),
+	  modpdescr
+	};
+
 static prop_t *pInputName = NULL;
 /* there is only one global inputName for all messages generated by this module */
 static prop_t *pLocalHostIP = NULL;	/* a pseudo-constant propterty for 127.0.0.1 */
@@ -182,13 +193,55 @@ CODESTARTbeginCnfLoad
 	pModConf->pConf = pConf;
 	/* init our settings */
 	pModConf->iFacilIntMsg = klogFacilIntMsg();
+	pModConf->bParseKernelStamp = 1; /* TODO: Switch to 0 as better default????? */
+	pModConf->bFixKernelStamp = 0;/* TODO: Switch to 0 as better default????? */
 	loadModConf->configSetViaV2Method = 0;
 	bLegacyCnfModGlobalsPermitted = 1;
 	/* init legacy config vars */
 	initConfigSettings();
 ENDbeginCnfLoad
 
 
+BEGINsetModCnf
+	struct cnfparamvals *pvals = NULL;
+	int i;
+CODESTARTsetModCnf
+	pvals = nvlstGetParams(lst, &modpblk, NULL);
+	if(pvals == NULL) {
+		LogError(0, RS_RET_MISSING_CNFPARAMS, "error processing module "
+				"config parameters [module(...)]");
+		ABORT_FINALIZE(RS_RET_MISSING_CNFPARAMS);
+	}
+
+	if(Debug) {
+		dbgprintf("module (global) param blk for imkmsg:\n");
+		cnfparamsPrint(&modpblk, pvals);
+	}
+
+	for(i = 0 ; i < modpblk.nParams ; ++i) {
+		if(!pvals[i].bUsed)
+			continue;
+		if(!strcmp(modpblk.descr[i].name, "parsekerneltimestamp")) {
+			loadModConf->bParseKernelStamp = (int) pvals[i].val.d.n;
+		} else if(!strcmp(modpblk.descr[i].name, "fixkerneltimestamp")) {
+			loadModConf->bFixKernelStamp = (int) pvals[i].val.d.n;
+		} else {
+			LogMsg(0, RS_RET_INTERNAL_ERROR, LOG_WARNING,
+				"imkmsg: RSYSLOG BUG, non-handled param '%s' in "
+				"beginCnfLoad\n", modpblk.descr[i].name);
+		}
+	}
+
+	/* disable legacy module-global config directives */
+	bLegacyCnfModGlobalsPermitted = 0;
+	loadModConf->configSetViaV2Method = 1;
+
+finalize_it:
+	if(pvals != NULL)
+		cnfparamvalsDestruct(pvals, &modpblk);
+ENDsetModCnf
+
+
 BEGINendCnfLoad
 CODESTARTendCnfLoad
 	if(!loadModConf->configSetViaV2Method) {
@@ -254,6 +307,7 @@ CODESTARTqueryEtryPt
 CODEqueryEtryPt_STD_IMOD_QUERIES
 CODEqueryEtryPt_STD_CONF2_QUERIES
 CODEqueryEtryPt_STD_CONF2_PREPRIVDROP_QUERIES
+CODEqueryEtryPt_STD_CONF2_setModCnf_QUERIES
 ENDqueryEtryPt
 
 static rsRetVal resetConfigVariables(uchar __attribute__((unused)) *pp, void __attribute__((unused)) *pVal)
@@ -289,5 +343,3 @@ CODEmodInit_QueryRegCFSLineHdlr
 	CHKiRet(omsdRegCFSLineHdlr((uchar *)"resetconfigvariables", 1, eCmdHdlrCustomHandler,
 			resetConfigVariables, NULL, STD_LOADABLE_MODULE_ID));
 ENDmodInit
-/* vim:set ai:
- */

contrib/imkmsg/imkmsg.h

@@ -1,7 +1,7 @@
 /* imkmsg.h
  * These are the definitions for the kmsg message generation module.
  *
- * Copyright 2007-2012 Rainer Gerhards and Adiscon GmbH.
+ * Copyright 2007-2023 Rainer Gerhards and Adiscon GmbH.
  *
  * This file is part of rsyslog.
  *
@@ -31,7 +31,8 @@ struct modConfData_s {
 	int iFacilIntMsg;
 	uchar *pszPath;
 	int console_log_level;
-	sbool bPermitNonKernel;
+	sbool bParseKernelStamp;
+	sbool bFixKernelStamp;
 	sbool configSetViaV2Method;
 };
 
@@ -62,5 +63,3 @@ extern char * ExpandKadds(char *, char *);
 extern void SetParanoiaLevel(int);
 
 #endif /* #ifndef IMKLOG_H_INCLUDED */
-/* vi:set ai:
- */

contrib/imkmsg/kmsg.c

@@ -4,7 +4,7 @@
  * For a general overview, see head comment in imkmsg.c.
  * This is heavily based on imklog bsd.c file.
  *
- * Copyright 2008-2014 Adiscon GmbH
+ * Copyright 2008-2023 Adiscon GmbH
  *
  * This file is part of rsyslog.
  *
@@ -44,6 +44,18 @@
 
 /* globals */
 static int	fklog = -1;	/* kernel log fd */
+static int	bInInitialReading = 1; /* are we in the intial kmsg reading phase? */
+/* Note: There is a problem with kernel log time.
+ * See https://github.com/troglobit/sysklogd/commit/9f6fbb3301e571d8af95f8d771469291384e9e95
+ * We use the same work-around if bFixKernelStamp is on, and use the kernel log time
+ * only for past records, which we assume to be from recent boot. Later on, we do not
+ * use them but system time.
+ * UNFORTUNATELY, with /dev/kmsg, we always get old messages on startup. That means we
+ * may also pull old messages. We do not address this right now, as for 10 years "old
+ * messages" was pretty acceptable. So we wait until someone complains. Hint: we could
+ * do a seek to the end of kmsg if desired to not pull old messages.
+ * 2023-10-31 rgerhards
+ */
 
 #ifndef _PATH_KLOG
 #	define _PATH_KLOG "/dev/kmsg"
@@ -54,10 +66,11 @@ static int	fklog = -1;	/* kernel log fd */
  * from the rest.
  */
 static void
-submitSyslog(uchar *buf)
+submitSyslog(modConfData_t *const pModConf, const uchar *buf)
 {
 	long offs = 0;
 	struct timeval tv;
+	struct timeval *tp = NULL;
 	struct sysinfo info;
 	unsigned long int timestamp = 0;
 	char name[1024];
@@ -85,6 +98,7 @@ submitSyslog(uchar *buf)
 	json_object_object_add(json, "sequnum", jval);
 
 	/* get timestamp */
+	DBGPRINTF("kmsg: getting timestamp, buf: %s\n", buf);
 	for (; isdigit(*buf); buf++) {
 		timestamp = (timestamp * 10) + (*buf - '0');
 	}
@@ -129,27 +143,33 @@ submitSyslog(uchar *buf)
 		json_object_object_add(json, name, jval);
 	}
 
-	/* calculate timestamp */
-	sysinfo(&info);
-	gettimeofday(&tv, NULL);
+	if(pModConf->bParseKernelStamp || (pModConf->bFixKernelStamp && bInInitialReading) ) {
+DBGPRINTF("imkmsg: bParserKernelStamp or fix and intial reading, val %d\n", bInInitialReading);
+		/* calculate timestamp */
+		sysinfo(&info);
+		gettimeofday(&tv, NULL);
 
-	/* get boot time */
-	tv.tv_sec -= info.uptime;
+		/* get boot time */
+		tv.tv_sec -= info.uptime;
 
-	tv.tv_sec += timestamp / 1000000;
-	tv.tv_usec += timestamp % 1000000;
+		tv.tv_sec += timestamp / 1000000;
+		tv.tv_usec += timestamp % 1000000;
+DBGPRINTF("imkmsg: uptime %ld, timestamp %lu, tv %lu - %lu\n", info.uptime, timestamp, tv.tv_sec, tv.tv_usec);
 
-	while (tv.tv_usec < 0) {
-		tv.tv_sec--;
-		tv.tv_usec += 1000000;
-	}
+		while (tv.tv_usec < 0) {
+			tv.tv_sec--;
+			tv.tv_usec += 1000000;
+		}
 
-	while (tv.tv_usec >= 1000000) {
-		tv.tv_sec++;
-		tv.tv_usec -= 1000000;
+		while (tv.tv_usec >= 1000000) {
+			tv.tv_sec++;
+			tv.tv_usec -= 1000000;
+		}
+
+		tp = &tv;
 	}
 
-	Syslog(priority, (uchar *)msg, &tv, json);
+	Syslog(priority, (uchar *)msg, tp, json);
 }
 
 
@@ -161,7 +181,7 @@ klogWillRunPrePrivDrop(modConfData_t __attribute__((unused)) *pModConf)
 	char errmsg[2048];
 	DEFiRet;
 
-	fklog = open(_PATH_KLOG, O_RDONLY, 0);
+	fklog = open(_PATH_KLOG, O_RDONLY | O_NONBLOCK, 0);
 	if (fklog < 0) {
 		imkmsgLogIntMsg(LOG_ERR, "imkmsg: cannot open kernel log (%s): %s.",
 			_PATH_KLOG, rs_strerror_r(errno, errmsg, sizeof(errmsg)));
@@ -184,7 +204,7 @@ klogWillRunPostPrivDrop(modConfData_t __attribute__((unused)) *pModConf)
 	/* this normally returns EINVAL */
 	/* on an OpenVZ VM, we get EPERM */
 	r = read(fklog, NULL, 0);
-	if (r < 0 && errno != EINVAL) {
+	if (r < 0 && errno != EINVAL && errno != EAGAIN && errno != EWOULDBLOCK) {
 		imkmsgLogIntMsg(LOG_ERR, "imkmsg: cannot open kernel log (%s): %s.",
 			_PATH_KLOG, rs_strerror_r(errno, errmsg, sizeof(errmsg)));
 		fklog = -1;
@@ -195,11 +215,18 @@ klogWillRunPostPrivDrop(modConfData_t __attribute__((unused)) *pModConf)
 	RETiRet;
 }
 
+
+static void
+change_reads_to_blocking(const int fd) {
+  const int flags = fcntl(fd, F_GETFL, 0);
+  fcntl(fd, F_SETFL, flags & ~O_NONBLOCK);
+}
+
 /* Read kernel log while data are available, each read() reads one
  * record of printk buffer.
  */
 static void
-readkmsg(void)
+readkmsg(modConfData_t *const pModConf)
 {
 	int i;
 	uchar pRcv[8192+1];
@@ -210,7 +237,6 @@ readkmsg(void)
 
 		/* every read() from the opened device node receives one record of the printk buffer */
 		i = read(fklog, pRcv, 8192);
-
 		if (i > 0) {
 			/* successful read of message of nonzero length */
 			pRcv[i] = '\0';
@@ -220,7 +246,13 @@ readkmsg(void)
 			continue;
 		} else {
 			/* something went wrong - error or zero length message */
-			if (i < 0 && errno != EINTR && errno != EAGAIN) {
+			if(i < 0 && (errno == EAGAIN || errno == EWOULDBLOCK)) {
+				DBGPRINTF("imkmsg: initial read done, changing to non-blocking mode\n");
+				change_reads_to_blocking(fklog);
+				bInInitialReading = 0;
+				continue;
+			}
+			if(i < 0 && errno != EINTR && errno != EAGAIN) {
 				/* error occurred */
 				imkmsgLogIntMsg(LOG_ERR,
 				       "imkmsg: error reading kernel log - shutting down: %s",
@@ -230,7 +262,7 @@ readkmsg(void)
 			break;
 		}
 
-		submitSyslog(pRcv);
+		submitSyslog(pModConf, pRcv);
 	}
 }
 
@@ -254,10 +286,10 @@ rsRetVal klogAfterRun(modConfData_t *pModConf)
  * "message pull" mechanism.
  * rgerhards, 2008-04-09
  */
-rsRetVal klogLogKMsg(modConfData_t __attribute__((unused)) *pModConf)
+rsRetVal klogLogKMsg(modConfData_t *const pModConf)
 {
 	DEFiRet;
-	readkmsg();
+	readkmsg(pModConf);
 	RETiRet;
 }