From b6b4f25eda025d3f5a5fcbf2be395bfade03d788 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 2 Aug 2023 10:45:09 +0200 Subject: [PATCH] lookup tables bugfix: reload on HUP did not work when backgrounded Lookup tables were only reloaded on HUP if the -n option was given and rsyslog no backgrounded. This patch fixes the issue. closes: https://github.com/rsyslog/rsyslog/issues/4813 Reference:https://github.com/rsyslog/rsyslog/commit/b6b4f25eda025d3f5a5fcbf2be395bfade03d788 Conflict:NA --- runtime/lookup.c | 68 +++++++++++++++++++------- runtime/lookup.h | 3 +- runtime/rsconf.c | 3 +- tests/Makefile.am | 2 + tests/diag.sh | 14 ++++++ tests/lookup_table-hup-backgrounded.sh | 51 +++++++++++++++++++ tools/rsyslogd.c | 5 +- 7 files changed, 126 insertions(+), 20 deletions(-) create mode 100755 tests/lookup_table-hup-backgrounded.sh diff --git a/runtime/lookup.c b/runtime/lookup.c index 66fb09d51a..d9ee53b7ad 100644 --- a/runtime/lookup.c +++ b/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) { diff --git a/runtime/lookup.h b/runtime/lookup.h index ccfe80d12c..7c0aa28904 100644 --- a/runtime/lookup.h +++ b/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 */ diff --git a/runtime/rsconf.c b/runtime/rsconf.c index ae297e3b82..a7fb272c5e 100644 --- a/runtime/rsconf.c +++ b/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()); diff --git a/tests/Makefile.am b/tests/Makefile.am index 4f0df94328..a9713e0008 100644 --- a/tests/Makefile.am +++ b/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 \ diff --git a/tests/diag.sh b/tests/diag.sh index c8f58ff0fa..493177ad1c 100755 --- a/tests/diag.sh +++ b/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() { diff --git a/tests/lookup_table-hup-backgrounded.sh b/tests/lookup_table-hup-backgrounded.sh new file mode 100755 index 0000000000..bc43c4584f --- /dev/null +++ b/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 diff --git a/tools/rsyslogd.c b/tools/rsyslogd.c index 02fa1028ea..08bd5fd895 100644 --- a/tools/rsyslogd.c +++ b/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(); }