Merge pull request #5208 from rgerhards/i4813

lookup tables bugfix: reload on HUP did not work when backgrounded

runtime/lookup.c

@@ -1,7 +1,7 @@
 /* lookup.c
  * Support for lookup tables in RainerScript.
  *
- * Copyright 2013-2018 Adiscon GmbH.
+ * Copyright 2013-2023 Adiscon GmbH.
  *
  * This file is part of the rsyslog runtime library.
  *
@@ -75,6 +75,7 @@ lookupTableReloader(void *self);
 static void
 lookupStopReloader(lookup_ref_t *pThis);
 
+
 /* create a new lookup table object AND include it in our list of
  * lookup tables.
  */
@@ -83,24 +84,12 @@ lookupNew(lookup_ref_t **ppThis)
 {
 	lookup_ref_t *pThis = NULL;
 	lookup_t *t = NULL;
-	int initialized = 0;
 	DEFiRet;
 
 	CHKmalloc(pThis = calloc(1, sizeof(lookup_ref_t)));
 	CHKmalloc(t = calloc(1, sizeof(lookup_t)));
-	CHKiConcCtrl(pthread_rwlock_init(&pThis->rwlock, NULL));
-	initialized++; /*1*/
-	CHKiConcCtrl(pthread_mutex_init(&pThis->reloader_mut, NULL));
-	initialized++; /*2*/
-	CHKiConcCtrl(pthread_cond_init(&pThis->run_reloader, NULL));
-	initialized++; /*3*/
-	CHKiConcCtrl(pthread_attr_init(&pThis->reloader_thd_attr));
-	initialized++; /*4*/
 	pThis->do_reload = pThis->do_stop = 0;
 	pThis->reload_on_hup = 1; /*DO reload on HUP (default)*/
-	CHKiConcCtrl(pthread_create(&pThis->reloader, &pThis->reloader_thd_attr,
-		lookupTableReloader, pThis));
-	initialized++; /*5*/
 
 	pThis->next = NULL;
 	if(loadConf->lu_tabs.root == NULL) {
@@ -115,7 +104,38 @@ lookupNew(lookup_ref_t **ppThis)
 	*ppThis = pThis;
 finalize_it:
 	if(iRet != RS_RET_OK) {
-		LogError(errno, iRet, "a lookup table could not be initialized: "
+		LogError(errno, iRet, "a lookup table could not be initialized");
+		free(t);
+		free(pThis);
+	}
+	RETiRet;
+}
+
+/* activate a lookup table entry once rsyslog is ready to do so */
+static rsRetVal
+lookupActivateTable(lookup_ref_t *pThis)
+{
+	DEFiRet;
+	int initialized = 0;
+
+	DBGPRINTF("lookupActivateTable called\n");
+	CHKiConcCtrl(pthread_rwlock_init(&pThis->rwlock, NULL));
+	initialized++; /*1*/
+	CHKiConcCtrl(pthread_mutex_init(&pThis->reloader_mut, NULL));
+	initialized++; /*2*/
+	CHKiConcCtrl(pthread_cond_init(&pThis->run_reloader, NULL));
+	initialized++; /*3*/
+	CHKiConcCtrl(pthread_attr_init(&pThis->reloader_thd_attr));
+	initialized++; /*4*/
+	pThis->do_reload = pThis->do_stop = 0;
+	CHKiConcCtrl(pthread_create(&pThis->reloader, &pThis->reloader_thd_attr,
+		lookupTableReloader, pThis));
+	initialized++; /*5*/
+
+
+finalize_it:
+	if(iRet != RS_RET_OK) {
+		LogError(errno, iRet, "a lookup table could not be activated: "
 			"failed at init-step %d (please enable debug logs for details)",
 			initialized);
 		/* Can not happen with current code, but might occur in the future when
@@ -128,8 +148,6 @@ lookupNew(lookup_ref_t **ppThis)
 		if (initialized > 2) pthread_cond_destroy(&pThis->run_reloader);
 		if (initialized > 1) pthread_mutex_destroy(&pThis->reloader_mut);
 		if (initialized > 0) pthread_rwlock_destroy(&pThis->rwlock);
-		free(t);
-		free(pThis);
 	}
 	RETiRet;
 }
@@ -846,8 +864,8 @@ lookupTableReloader(void *self)
 		if (pThis->do_stop) {
 			break;
 		} else if (pThis->do_reload) {
-			pThis->do_reload = 0;
 			lookupDoReload(pThis);
+			pThis->do_reload = 0;
 		} else {
 			pthread_cond_wait(&pThis->run_reloader, &pThis->reloader_mut);
 		}
@@ -868,6 +886,22 @@ lookupDoHUP(void)
 	}
 }
 
+/* activate lookup table system config
+ * most importantly, this means tarting the lookup table reloader thread in the
+ * right process space - it is a difference if we fork or not!
+ */
+void
+lookupActivateConf(void)
+{
+	DBGPRINTF("lookup tables: activate config \n");
+	lookup_ref_t *luref;
+	for(luref = runConf->lu_tabs.root ; luref != NULL ; luref = luref->next) {
+		DBGPRINTF("lookup actiate: processing %p\n", luref);
+		lookupActivateTable(luref);
+	}
+	DBGPRINTF("lookup tables: activate done\n");
+}
+
 uint
 lookupPendingReloadCount(void)
 {
@@ -1003,11 +1037,18 @@ lookupTableDefProcessCnf(struct cnfobj *o)
 			  "param '%s'\n", modpblk.descr[i].name);
 		}
 	}
+	const uchar *const lu_name = lu->name; /* we need a const to keep TSAN happy :-( */
+	const uchar *const lu_filename = lu->filename; /* we need a const to keep TSAN happy :-( */
+	if(lu_name == NULL || lu_filename == NULL) {
+		iRet = RS_RET_INTERNAL_ERROR;
+		LogError(0, iRet, "internal error: lookup table name not set albeit being mandatory");
+		ABORT_FINALIZE(iRet);
+	}
 #ifdef HAVE_PTHREAD_SETNAME_NP
-	thd_name_len = ustrlen(lu->name) + strlen(reloader_prefix) + 1;
+	thd_name_len = ustrlen(lu_name) + strlen(reloader_prefix) + 1;
 	CHKmalloc(reloader_thd_name = malloc(thd_name_len));
 	strcpy(reloader_thd_name, reloader_prefix);
-	strcpy(reloader_thd_name + strlen(reloader_prefix), (char*) lu->name);
+	strcpy(reloader_thd_name + strlen(reloader_prefix), (char*) lu_name);
 	reloader_thd_name[thd_name_len - 1] = '\0';
 #if defined(__NetBSD__)
 	pthread_setname_np(lu->reloader, "%s", reloader_thd_name);
@@ -1017,9 +1058,9 @@ lookupTableDefProcessCnf(struct cnfobj *o)
 	pthread_setname_np(lu->reloader, reloader_thd_name);
 #endif
 #endif
-	CHKiRet(lookupReadFile(lu->self, lu->name, lu->filename));
+	CHKiRet(lookupReadFile(lu->self, lu_name, lu_filename));
 	LogMsg(0, RS_RET_OK, LOG_INFO, "lookup table '%s' loaded from file '%s'",
-		lu->name, lu->filename);
+		lu_name, lu->filename);
 
 finalize_it:
 #ifdef HAVE_PTHREAD_SETNAME_NP

runtime/lookup.h

@@ -1,6 +1,6 @@
 /* header for lookup.c
  *
- * Copyright 2013 Adiscon GmbH.
+ * Copyright 2013-2023 Adiscon GmbH.
  *
  * This file is part of the rsyslog runtime library.
  *
@@ -111,5 +111,6 @@ void lookupDoHUP(void);
 rsRetVal lookupReload(lookup_ref_t *pThis, const uchar *stub_value_if_reload_fails);
 uint lookupPendingReloadCount(void);
 rsRetVal lookupClassInit(void);
+void lookupActivateConf(void);
 
 #endif /* #ifndef INCLUDED_LOOKUP_H */

runtime/rsconf.c

@@ -2,7 +2,7 @@
  *
  * Module begun 2011-04-19 by Rainer Gerhards
  *
- * Copyright 2011-2022 Adiscon GmbH.
+ * Copyright 2011-2023 Adiscon GmbH.
  *
  * This file is part of the rsyslog runtime library.
  *
@@ -1038,6 +1038,7 @@ activate(rsconf_t *cnf)
 
 	CHKiRet(dropPrivileges(cnf));
 
+	lookupActivateConf();
 	tellModulesActivateConfig();
 	startInputModules();
 	CHKiRet(activateActions());

tests/Makefile.am

@@ -480,6 +480,7 @@ TESTS +=  \
 	incltest_dir_empty_wildcard.sh \
 	linkedlistqueue.sh \
 	lookup_table.sh \
+	lookup_table-hup-backgrounded.sh \
 	lookup_table_no_hup_reload.sh \
 	key_dereference_on_uninitialized_variable_space.sh \
 	array_lookup_table.sh \
@@ -2893,6 +2894,7 @@ EXTRA_DIST= \
 	rscript_re_match.sh \
 	rscript_re_match-dbl_quotes.sh \
 	lookup_table.sh \
+	lookup_table-hup-backgrounded.sh \
 	lookup_table_no_hup_reload.sh \
 	lookup_table_no_hup_reload-vg.sh \
 	lookup_table_rscript_reload.sh \

tests/diag.sh

@@ -130,6 +130,20 @@ skip_platform() {
 
 }
 
+# function to skip a test if TSAN is enabled
+# This is necessary as TSAN does not properly handle thread creation
+# after fork() - which happens regularly in rsyslog if backgrounding
+# is activated.
+# $1 is the reason why TSAN is not supported
+# note: we depend on CFLAGS to properly reflect build options (what
+#       usually is the case when the testbench is run)
+skip_TSAN() {
+	if [[ "$CFLAGS" == *"sanitize=thread"* ]]; then
+		printf 'test incompatible with TSAN because of %s\n' "$1"
+		exit 77
+	fi
+}
+
 
 # a consistent format to output testbench timestamps
 tb_timestamp() {

tests/lookup_table-hup-backgrounded.sh

@@ -0,0 +1,51 @@
+#!/bin/bash
+# test for lookup-table and HUP based reloading of it
+# added 2015-09-30 by singh.janmejay
+# This file is part of the rsyslog project, released under ASL 2.0
+. ${srcdir:=.}/diag.sh init
+skip_TSAN
+generate_conf
+add_conf '
+lookup_table(name="xlate" file="'$RSYSLOG_DYNNAME'.xlate.lkp_tbl" reloadOnHUP="on")
+
+template(name="outfmt" type="string" string="- %msg% %$.lkp%\n")
+
+set $.lkp = lookup("xlate", $msg);
+
+action(type="omfile" file=`echo $RSYSLOG_OUT_LOG` template="outfmt")
+'
+cp -f $srcdir/testsuites/xlate.lkp_tbl $RSYSLOG_DYNNAME.xlate.lkp_tbl
+export RSTB_DAEMONIZE="YES"
+startup
+injectmsg  0 3
+wait_queueempty
+content_check "msgnum:00000000: foo_old"
+content_check "msgnum:00000001: bar_old"
+assert_content_missing "baz"
+cp -f $srcdir/testsuites/xlate_more.lkp_tbl $RSYSLOG_DYNNAME.xlate.lkp_tbl
+issue_HUP
+await_lookup_table_reload
+injectmsg  0 3
+wait_queueempty
+content_check "msgnum:00000000: foo_new"
+content_check "msgnum:00000001: bar_new"
+content_check "msgnum:00000002: baz"
+cp -f $srcdir/testsuites/xlate_more_with_duplicates_and_nomatch.lkp_tbl $RSYSLOG_DYNNAME.xlate.lkp_tbl
+issue_HUP
+await_lookup_table_reload
+injectmsg  0 10
+echo doing shutdown
+shutdown_when_empty
+echo wait on shutdown
+wait_shutdown
+content_check "msgnum:00000000: foo_latest"
+content_check "msgnum:00000001: quux"
+content_check "msgnum:00000002: baz_latest"
+content_check "msgnum:00000003: foo_latest"
+content_check "msgnum:00000004: foo_latest"
+content_check "msgnum:00000005: baz_latest"
+content_check "msgnum:00000006: foo_latest"
+content_check "msgnum:00000007: baz_latest"
+content_check "msgnum:00000008: baz_latest"
+content_check "msgnum:00000009: quux"
+exit_test

tools/rsyslogd.c

@@ -1861,7 +1861,6 @@ parseAndSubmitMessage(const uchar *const hname, const uchar *const hnameIP, cons
  */
 DEFFUNC_llExecFunc(doHUPActions)
 {
-	dbgprintf("doHUP called\n");
 	actionCallHUPHdlr((action_t*) pData);
 	return RS_RET_OK; /* we ignore errors, we can not do anything either way */
 }
@@ -1882,6 +1881,7 @@ doHUP(void)
 {
 	char buf[512];
 
+	DBGPRINTF("doHUP: doing modules\n");
 	if(ourConf->globals.bLogStatusMsgs) {
 		snprintf(buf, sizeof(buf),
 			 "[origin software=\"rsyslogd\" " "swVersion=\"" VERSION
@@ -1893,8 +1893,11 @@ doHUP(void)
 
 	queryLocalHostname(); /* re-read our name */
 	ruleset.IterateAllActions(ourConf, doHUPActions, NULL);
+	DBGPRINTF("doHUP: doing modules\n");
 	modDoHUP();
+	DBGPRINTF("doHUP: doing lookup tables\n");
 	lookupDoHUP();
+	DBGPRINTF("doHUP: doing errmsgs\n");
 	errmsgDoHUP();
 }