imkmsg: add module param parseKernelTimestamp

The parameter permits to select whether or not and when kernel
timestamps shall parsed, that is be used as the actual time a
log message occurs.

This permits to work around problems with the way kernel
timestamps are represented. The reasoning is given in a sysklogd
commit by Joachim Wiberg, which we reproduce below ("QUOTE") to
have a stable reference.

The commit itself can be found for example at:
troglobit/sysklogd@9f6fbb3

The new parameter parseKernelTimestamp has three possible modes:

"startup" - uses the kernel time stamp during the initial read
loop of /dev/kmsg, but replaced it later ignores it for later reads.
This is the DEFAULT setting.

"on" - kernel timestamps are always used and no correction is tried

"off" - kernel timestamps are never used, system time is used instead

Note that there this is a slightly breaking change. Previously, imkmsg
reported similar to "off" mode, now it reports by default in "startup"
mode. We consider this acceptable, as "off" mode timestamps are not
correct for startup. After startup, the behaviour is correct. All in
all, the new default is kind of a bugfix.

============== 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 #4561
closes #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,16 @@ 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", eCmdHdlrGetWord, 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 +192,64 @@ CODESTARTbeginCnfLoad
 	pModConf->pConf = pConf;
 	/* init our settings */
 	pModConf->iFacilIntMsg = klogFacilIntMsg();
+	pModConf->parseKernelStamp = KMSG_PARSE_TS_STARTUP_ONLY;
 	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")) {
+			if(   !es_strconstcmp(pvals[i].val.d.estr, "on")
+			   || !es_strconstcmp(pvals[i].val.d.estr, "always")) {
+				loadModConf->parseKernelStamp = KMSG_PARSE_TS_ALWAYS;
+			} else if(!es_strconstcmp(pvals[i].val.d.estr, "startup")) {
+				loadModConf->parseKernelStamp = KMSG_PARSE_TS_STARTUP_ONLY;
+			} else if(!es_strconstcmp(pvals[i].val.d.estr, "off")) {
+				loadModConf->parseKernelStamp = KMSG_PARSE_TS_OFF;
+			} else {
+				const char *const cstr = es_str2cstr(pvals[i].val.d.estr, NULL);
+				LogError(0, RS_RET_PARAM_ERROR, "imkmsg: unknown "
+					"parse mode '%s'", cstr);
+				free((void*)cstr);
+			}
+		} 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 +315,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 +351,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.
  *
@@ -25,13 +25,20 @@
 #include "rsyslog.h"
 #include "dirty.h"
 
+typedef enum _kernel_ts_parse_mods {
+		KMSG_PARSE_TS_OFF = 0,
+		KMSG_PARSE_TS_ALWAYS = 1,
+		KMSG_PARSE_TS_STARTUP_ONLY = 2
+	} t_kernel_ts_parse_mode;
+
 /* we need to have the modConf type present in all submodules */
 struct modConfData_s {
 	rsconf_t *pConf;
 	int iFacilIntMsg;
 	uchar *pszPath;
 	int console_log_level;
-	sbool bPermitNonKernel;
+	t_kernel_ts_parse_mode parseKernelStamp;
+	sbool bFixKernelStamp;
 	sbool configSetViaV2Method;
 };
 
@@ -62,5 +69,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];
@@ -129,27 +142,32 @@ submitSyslog(uchar *buf)
 		json_object_object_add(json, name, jval);
 	}
 
-	/* calculate timestamp */
-	sysinfo(&info);
-	gettimeofday(&tv, NULL);
+	if(   (pModConf->parseKernelStamp == KMSG_PARSE_TS_ALWAYS)
+	   || ((pModConf->parseKernelStamp == KMSG_PARSE_TS_STARTUP_ONLY) && 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;
 
-	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 +179,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 +202,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 +213,19 @@ 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 +236,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 +245,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 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 +261,7 @@ readkmsg(void)
 			break;
 		}
 
-		submitSyslog(pRcv);
+		submitSyslog(pModConf, pRcv);
 	}
 }
 
@@ -254,10 +285,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;
 }