From 9bfcf74c828454cabd5d00265f4781a7bc758ba1 Mon Sep 17 00:00:00 2001 From: Qiumiao Zhang Date: Wed, 20 Mar 2024 19:29:13 +0800 Subject: [PATCH] backport patches from upstream Signed-off-by: Qiumiao Zhang --- ...ead-of-loadConf-in-ratelimiting-duri.patch | 187 ++++++++++ backport-bugfix-cosmetic-data-races.patch | 126 +++++++ ...x-potential-segfault-on-busy-systems.patch | 59 ++++ ...rtup-issue-on-modern-systemd-systems.patch | 188 ++++++++++ ...ssage-loss-duplication-when-monitore.patch | 276 +++++++++++++++ ...rectory-s-fd-leak-in-case-of-inotify.patch | 46 +++ ...ctorys-fd-leak-in-case-of-inotify-on.patch | 197 +++++++++++ ...gfix-reload-on-HUP-did-not-work-when.patch | 326 ++++++++++++++++++ ...kup-tables-fix-static-analyzer-issue.patch | 57 +++ ...msg-cannot-be-parsed-parser-chain-is.patch | 38 ++ ...epreceated-method-SSLv23_method-with.patch | 110 ++++++ ...ubsystem-handle-data-race-gracefully.patch | 36 ++ ...sending-was-not-implemented-properly.patch | 155 +++++++++ ...tcp-send-error-not-properly-reported.patch | 42 +++ ...stcase-for-frequent-imfile-input-fil.patch | 291 ++++++++++++++++ ...file-statefile-delete.sh-INOTIFY-tri.patch | 77 +++++ ...ing-for-HUP-processing-more-reliable.patch | 200 +++++++++++ rsyslog.spec | 41 ++- 18 files changed, 2451 insertions(+), 1 deletion(-) create mode 100644 backport-Use-runConf-instead-of-loadConf-in-ratelimiting-duri.patch create mode 100644 backport-bugfix-cosmetic-data-races.patch create mode 100644 backport-core-bugfix-potential-segfault-on-busy-systems.patch create mode 100644 backport-fix-startup-issue-on-modern-systemd-systems.patch create mode 100644 backport-imfile-bugfix-message-loss-duplication-when-monitore.patch create mode 100644 backport-imfile-fix-ext-directory-s-fd-leak-in-case-of-inotify.patch create mode 100644 backport-imfile-tests-ext-directorys-fd-leak-in-case-of-inotify-on.patch create mode 100644 backport-lookup-tables-bugfix-reload-on-HUP-did-not-work-when.patch create mode 100644 backport-lookup-tables-fix-static-analyzer-issue.patch create mode 100644 backport-mmnormalize-bugfix-if-msg-cannot-be-parsed-parser-chain-is.patch create mode 100644 backport-openssl-Replaced-depreceated-method-SSLv23_method-with.patch create mode 100644 backport-tcp-net-subsystem-handle-data-race-gracefully.patch create mode 100644 backport-tcpflood-bugfix-TCP-sending-was-not-implemented-properly.patch create mode 100644 backport-tcpflood-bugfix-plain-tcp-send-error-not-properly-reported.patch create mode 100644 backport-testbench-add-testcase-for-frequent-imfile-input-fil.patch create mode 100644 backport-testbench-fix-imfile-statefile-delete.sh-INOTIFY-tri.patch create mode 100644 backport-testbench-make-waiting-for-HUP-processing-more-reliable.patch diff --git a/backport-Use-runConf-instead-of-loadConf-in-ratelimiting-duri.patch b/backport-Use-runConf-instead-of-loadConf-in-ratelimiting-duri.patch new file mode 100644 index 0000000..d1daeb1 --- /dev/null +++ b/backport-Use-runConf-instead-of-loadConf-in-ratelimiting-duri.patch @@ -0,0 +1,187 @@ +From ab99d680093d8bdd407665ad444668f3ae65c5b6 Mon Sep 17 00:00:00 2001 +From: alakatos +Date: Fri, 26 Nov 2021 15:34:05 +0100 +Subject: [PATCH] Use runConf instead of loadConf in ratelimiting during + runtime + +Reference:https://github.com/rsyslog/rsyslog/commit/ab99d680093d8bdd407665ad444668f3ae65c5b6 +Conflict:NA +--- + plugins/imfile/imfile.c | 3 +++ + plugins/imklog/imklog.c | 1 + + plugins/imptcp/imptcp.c | 1 + + plugins/imudp/imudp.c | 7 ++++--- + runtime/ratelimit.c | 11 ++++------- + runtime/ratelimit.h | 1 - + tests/imtcp-tls-basic.sh | 1 + + tests/imtcp_conndrop_tls-vg.sh | 1 + + tests/rscript_http_request-vg.sh | 1 + + 9 files changed, 16 insertions(+), 11 deletions(-) + +diff --git a/plugins/imfile/imfile.c b/plugins/imfile/imfile.c +index 09c8743..e064de4 100644 +--- a/plugins/imfile/imfile.c ++++ b/plugins/imfile/imfile.c +@@ -773,6 +773,7 @@ act_obj_add(fs_edge_t *const edge, const char *const name, const int is_file, + act->file_id[0] = '\0'; + act->file_id_prev[0] = '\0'; + act->is_symlink = is_symlink; ++ act->ratelimiter = NULL; + if (source) { /* we are target of symlink */ + CHKmalloc(act->source_name = strdup(source)); + } else { +@@ -800,6 +801,8 @@ act_obj_add(fs_edge_t *const edge, const char *const name, const int is_file, + finalize_it: + if(iRet != RS_RET_OK) { + if(act != NULL) { ++ if (act->ratelimiter != NULL) ++ ratelimitDestruct(act->ratelimiter); + free(act->name); + free(act); + } +diff --git a/plugins/imklog/imklog.c b/plugins/imklog/imklog.c +index 78cfc3b..0a1bc44 100644 +--- a/plugins/imklog/imklog.c ++++ b/plugins/imklog/imklog.c +@@ -343,6 +343,7 @@ CODESTARTbeginCnfLoad + pModConf->bKeepKernelStamp = 0; + pModConf->iFacilIntMsg = klogFacilIntMsg(); + loadModConf->configSetViaV2Method = 0; ++ pModConf->ratelimiter = NULL; + pModConf->ratelimitBurst = 10000; /* arbitrary high limit */ + pModConf->ratelimitInterval = 0; /* off */ + bLegacyCnfModGlobalsPermitted = 1; +diff --git a/plugins/imptcp/imptcp.c b/plugins/imptcp/imptcp.c +index 72e32dd..47c5b91 100644 +--- a/plugins/imptcp/imptcp.c ++++ b/plugins/imptcp/imptcp.c +@@ -1746,6 +1746,7 @@ addListner(modConfData_t __attribute__((unused)) *modConf, instanceConf_t *inst) + + CHKmalloc(pSrv = calloc(1, sizeof(ptcpsrv_t))); + pthread_mutex_init(&pSrv->mutSessLst, NULL); ++ pSrv->ratelimiter = NULL; + pSrv->pSess = NULL; + pSrv->pLstn = NULL; + pSrv->inst = inst; +diff --git a/plugins/imudp/imudp.c b/plugins/imudp/imudp.c +index 6f49aa9..8ddac9c 100644 +--- a/plugins/imudp/imudp.c ++++ b/plugins/imudp/imudp.c +@@ -316,6 +316,7 @@ addListner(instanceConf_t *inst) + newlcnfinfo->sock = newSocks[iSrc]; + newlcnfinfo->pRuleset = inst->pBindRuleset; + newlcnfinfo->dfltTZ = inst->dfltTZ; ++ newlcnfinfo->ratelimiter = NULL; + /* query socket IPv4 vs IPv6 */ + sa.sin_family = 0; /* just to keep CLANG static analyzer happy! */ + if(getsockname(newlcnfinfo->sock, (struct sockaddr*) &sa, &salen) != 0) { +@@ -338,6 +339,9 @@ addListner(instanceConf_t *inst) + inputname, bindName, port, suffix); + dispname[sizeof(dispname)-1] = '\0'; /* just to be on the save side... */ + CHKiRet(ratelimitNew(&newlcnfinfo->ratelimiter, (char*)dispname, NULL)); ++ ratelimitSetLinuxLike(newlcnfinfo->ratelimiter, inst->ratelimitInterval, ++ inst->ratelimitBurst); ++ ratelimitSetThreadSafe(newlcnfinfo->ratelimiter); + if(inst->bAppendPortToInpname) { + snprintf((char*)inpnameBuf, sizeof(inpnameBuf), "%s%s", + inputname, port); +@@ -348,9 +352,6 @@ addListner(instanceConf_t *inst) + CHKiRet(prop.SetString(newlcnfinfo->pInputName, + inputname, ustrlen(inputname))); + CHKiRet(prop.ConstructFinalize(newlcnfinfo->pInputName)); +- ratelimitSetLinuxLike(newlcnfinfo->ratelimiter, inst->ratelimitInterval, +- inst->ratelimitBurst); +- ratelimitSetThreadSafe(newlcnfinfo->ratelimiter); + /* support statistics gathering */ + CHKiRet(statsobj.Construct(&(newlcnfinfo->stats))); + CHKiRet(statsobj.SetName(newlcnfinfo->stats, dispname)); +diff --git a/runtime/ratelimit.c b/runtime/ratelimit.c +index 4590f92..363036c 100644 +--- a/runtime/ratelimit.c ++++ b/runtime/ratelimit.c +@@ -239,7 +239,7 @@ ratelimitMsg(ratelimit_t *__restrict__ const ratelimit, smsg_t *pMsg, smsg_t **p + + *ppRepMsg = NULL; + +- if(ratelimit->bReduceRepeatMsgs || ratelimit->severity > 0) { ++ if(runConf->globals.bReduceRepeatMsgs || ratelimit->severity > 0) { + /* consider early parsing only if really needed */ + if((pMsg->msgFlags & NEEDS_PARSING) != 0) { + if((localRet = parser.ParseMsg(pMsg)) != RS_RET_OK) { +@@ -261,7 +261,7 @@ ratelimitMsg(ratelimit_t *__restrict__ const ratelimit, smsg_t *pMsg, smsg_t **p + ABORT_FINALIZE(RS_RET_DISCARDMSG); + } + } +- if(ratelimit->bReduceRepeatMsgs) { ++ if(runConf->globals.bReduceRepeatMsgs) { + CHKiRet(doLastMessageRepeatedNTimes(ratelimit, pMsg, ppRepMsg)); + } + finalize_it: +@@ -276,7 +276,7 @@ finalize_it: + int + ratelimitChecked(ratelimit_t *ratelimit) + { +- return ratelimit->interval || ratelimit->bReduceRepeatMsgs; ++ return ratelimit->interval || runConf->globals.bReduceRepeatMsgs; + } + + +@@ -349,10 +349,7 @@ ratelimitNew(ratelimit_t **ppThis, const char *modname, const char *dynname) + namebuf[sizeof(namebuf)-1] = '\0'; /* to be on safe side */ + pThis->name = strdup(namebuf); + } +- /* pThis->severity == 0 - all messages are ratelimited */ +- pThis->bReduceRepeatMsgs = loadConf->globals.bReduceRepeatMsgs; +- DBGPRINTF("ratelimit:%s:new ratelimiter:bReduceRepeatMsgs %d\n", +- pThis->name, pThis->bReduceRepeatMsgs); ++ DBGPRINTF("ratelimit:%s:new ratelimiter\n", pThis->name); + *ppThis = pThis; + finalize_it: + RETiRet; +diff --git a/runtime/ratelimit.h b/runtime/ratelimit.h +index ea48395..bb45e79 100644 +--- a/runtime/ratelimit.h ++++ b/runtime/ratelimit.h +@@ -31,7 +31,6 @@ struct ratelimit_s { + unsigned missed; + time_t begin; + /* support for "last message repeated n times */ +- int bReduceRepeatMsgs; /**< shall we do "last message repeated n times" processing? */ + unsigned nsupp; /**< nbr of msgs suppressed */ + smsg_t *pMsg; + sbool bThreadSafe; /**< do we need to operate in Thread-Safe mode? */ +diff --git a/tests/imtcp-tls-basic.sh b/tests/imtcp-tls-basic.sh +index 58c5946..b65e7c4 100755 +--- a/tests/imtcp-tls-basic.sh ++++ b/tests/imtcp-tls-basic.sh +@@ -3,6 +3,7 @@ + # This file is part of the rsyslog project, released under ASL 2.0 + . ${srcdir:=.}/diag.sh init + export NUMMESSAGES=50000 ++export TB_TEST_MAX_RUNTIME=1500 + export QUEUE_EMPTY_CHECK_FUNC=wait_seq_check + # uncomment for debugging support: + #export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +diff --git a/tests/imtcp_conndrop_tls-vg.sh b/tests/imtcp_conndrop_tls-vg.sh +index bb51759..d2de6e8 100755 +--- a/tests/imtcp_conndrop_tls-vg.sh ++++ b/tests/imtcp_conndrop_tls-vg.sh +@@ -1,5 +1,6 @@ + #!/bin/bash + # This file is part of the rsyslog project, released under ASL 2.0 + export USE_VALGRIND="YES" ++export TB_TEST_MAX_RUNTIME=1500 + export NUMMESSAGES=10000 # reduce for slower valgrind run + source ${srcdir:-.}/imtcp_conndrop_tls.sh +diff --git a/tests/rscript_http_request-vg.sh b/tests/rscript_http_request-vg.sh +index e2ebb9c..3584e47 100755 +--- a/tests/rscript_http_request-vg.sh ++++ b/tests/rscript_http_request-vg.sh +@@ -1,3 +1,4 @@ + #!/bin/bash + export USE_VALGRIND="YES" ++export TB_TEST_MAX_RUNTIME=1500 + source ${srcdir:-.}/rscript_http_request.sh +-- +2.19.1 + diff --git a/backport-bugfix-cosmetic-data-races.patch b/backport-bugfix-cosmetic-data-races.patch new file mode 100644 index 0000000..54e3942 --- /dev/null +++ b/backport-bugfix-cosmetic-data-races.patch @@ -0,0 +1,126 @@ +From 929073b080802f1ffd238d077e651e747bd28f7b Mon Sep 17 00:00:00 2001 +From: Rainer Gerhards +Date: Fri, 1 Apr 2022 12:26:57 +0200 +Subject: [PATCH] bugfix: cosmetic data races + +there was a more or less cosmetic data race which could happen when children +processes died in quick sequence. Even then, no real harm happened, as all +children were reaped eventually. + +A similar data race exists for HUP processing. + +However, these races polluted TSAN test runs, and so we fixed them. + +Reference:https://github.com/rsyslog/rsyslog/commit/68ad91fc28c476048b95a64d7b994e5f490ee4df +Conflict:NA +--- + tools/rsyslogd.c | 34 +++++++++++++++++++++++++++++++--- + 1 file changed, 31 insertions(+), 3 deletions(-) + +diff --git a/tools/rsyslogd.c b/tools/rsyslogd.c +index 9dedd2f..a1cbe7c 100644 +--- a/tools/rsyslogd.c ++++ b/tools/rsyslogd.c +@@ -179,7 +179,9 @@ void rsyslogdDoDie(int sig); + #endif + + /* global data items */ +-static int bChildDied; ++static pthread_mutex_t mutChildDied; ++static int bChildDied = 0; ++static pthread_mutex_t mutHadHUP; + static int bHadHUP; + #ifdef HAVE_LIBSYSTEMD + static int g_bRecordQueue; +@@ -1232,7 +1234,9 @@ hdlr_enable(int sig, void (*hdlr)()) + static void + hdlr_sighup(void) + { ++ pthread_mutex_lock(&mutHadHUP); + bHadHUP = 1; ++ pthread_mutex_unlock(&mutHadHUP); + /* at least on FreeBSD we seem not to necessarily awake the main thread. + * So let's do it explicitely. + */ +@@ -1243,7 +1247,9 @@ hdlr_sighup(void) + static void + hdlr_sigchld(void) + { ++ pthread_mutex_lock(&mutChildDied); + bChildDied = 1; ++ pthread_mutex_unlock(&mutChildDied); + } + + static void +@@ -1862,9 +1868,12 @@ wait_timeout(const sigset_t *sigmask) + tvSelectTimeout.tv_sec = 0; + tvSelectTimeout.tv_nsec = wait_period; + do { ++ pthread_mutex_lock(&mutHadHUP); + if(bFinished || bHadHUP) { ++ pthread_mutex_unlock(&mutHadHUP); + break; + } ++ pthread_mutex_unlock(&mutHadHUP); + pselect(1, NULL, NULL, NULL, &tvSelectTimeout, sigmask); + } while(--timeout > 0); + } else { +@@ -1952,6 +1961,7 @@ mainloop(void) + time_t tTime; + sigset_t origmask; + sigset_t sigblockset; ++ int need_free_mutex; + + sigemptyset(&sigblockset); + sigaddset(&sigblockset, SIGTERM); +@@ -1961,14 +1971,28 @@ mainloop(void) + + do { + pthread_sigmask(SIG_BLOCK, &sigblockset, &origmask); ++ pthread_mutex_lock(&mutChildDied); ++ need_free_mutex = 1; + if(bChildDied) { +- reapChild(); + bChildDied = 0; ++ pthread_mutex_unlock(&mutChildDied); ++ need_free_mutex = 0; ++ reapChild(); ++ } ++ if(need_free_mutex) { ++ pthread_mutex_unlock(&mutChildDied); + } + ++ pthread_mutex_lock(&mutHadHUP); ++ need_free_mutex = 1; + if(bHadHUP) { +- doHUP(); + bHadHUP = 0; ++ need_free_mutex = 0; ++ pthread_mutex_unlock(&mutHadHUP); ++ doHUP(); ++ } ++ if(need_free_mutex) { ++ pthread_mutex_unlock(&mutHadHUP); + } + #ifdef HAVE_LIBSYSTEMD + if (g_bRecordQueue) { +@@ -2112,6 +2136,8 @@ main(int argc, char **argv) + * internally by rsyslogd. + */ + ++ pthread_mutex_init(&mutHadHUP, NULL); ++ pthread_mutex_init(&mutChildDied, NULL); + strncpy(progname,argv[0], sizeof(progname)-1); + addrsz = sizeof(srcaddr); + if ((rc = getsockname(0, &srcaddr, &addrsz)) < 0) { +@@ -2169,5 +2195,7 @@ main(int argc, char **argv) + stdlog_close(stdlog_hdl); + #endif + osf_close(); ++ pthread_mutex_destroy(&mutChildDied); ++ pthread_mutex_destroy(&mutHadHUP); + return 0; + } +-- +2.19.1 + diff --git a/backport-core-bugfix-potential-segfault-on-busy-systems.patch b/backport-core-bugfix-potential-segfault-on-busy-systems.patch new file mode 100644 index 0000000..6accf15 --- /dev/null +++ b/backport-core-bugfix-potential-segfault-on-busy-systems.patch @@ -0,0 +1,59 @@ +From 1dfa5f9d836d2153fb76bcbbb235cf5bfdff538b Mon Sep 17 00:00:00 2001 +From: "Konstantin J. Chernov" <> +Date: Mon, 17 Apr 2023 13:22:29 +0200 +Subject: [PATCH] core bugfix: potential segfault on busy systems + +This was discovered by Konstantin J. Chernov in a practicaly deployment. +Here, msg object tag processing caused sporadic segfaults. We did not +hear from similiar cases, but there clearly is potential for problems +because a mutex lock had insufficient range, thus leading to a potential +race. + +The patch is directly from Konstantin J. Chernov, thanks for that. + +Please note that the mutex lock could be minimized as it is not strictly +needed for the pM == NULL case, but this cause is extremely exotic +and the resulting code would be harder to understand. Thus we opt +to do the locking on funtion level (as usual). + +Descriptiond edited by Rainer Gerhards + +closes: https://github.com/rsyslog/rsyslog/issues/5110 + +Reference:https://github.com/rsyslog/rsyslog/commit/1dfa5f9d836d2153fb76bcbbb235cf5bfdff538b +Conflict:NA +--- + runtime/msg.c | 8 +++++++- + 1 file changed, 7 insertions(+), 1 deletion(-) + +diff --git a/runtime/msg.c b/runtime/msg.c +index 03511d3f82..b35bc1dfd2 100644 +--- a/runtime/msg.c ++++ b/runtime/msg.c +@@ -2552,12 +2552,15 @@ tryEmulateTAG(smsg_t *const pM, const sbool bLockMutex) + void ATTR_NONNULL(2,3) + getTAG(smsg_t * const pM, uchar **const ppBuf, int *const piLen, const sbool bLockMutex) + { ++ if(bLockMutex == LOCK_MUTEX) ++ MsgLock(pM); ++ + if(pM == NULL) { + *ppBuf = UCHAR_CONSTANT(""); + *piLen = 0; + } else { + if(pM->iLenTAG == 0) +- tryEmulateTAG(pM, bLockMutex); ++ tryEmulateTAG(pM, MUTEX_ALREADY_LOCKED); + if(pM->iLenTAG == 0) { + *ppBuf = UCHAR_CONSTANT(""); + *piLen = 0; +@@ -2566,6 +2569,9 @@ getTAG(smsg_t * const pM, uchar **const ppBuf, int *const piLen, const sbool bLo + *piLen = pM->iLenTAG; + } + } ++ ++ if(bLockMutex == LOCK_MUTEX) ++ MsgUnlock(pM); + } + + diff --git a/backport-fix-startup-issue-on-modern-systemd-systems.patch b/backport-fix-startup-issue-on-modern-systemd-systems.patch new file mode 100644 index 0000000..f26ffa0 --- /dev/null +++ b/backport-fix-startup-issue-on-modern-systemd-systems.patch @@ -0,0 +1,188 @@ +From 061f186488a9dbe4c3c5d94742b52403c84e0676 Mon Sep 17 00:00:00 2001 +From: Rainer Gerhards +Date: Tue, 26 Sep 2023 14:38:44 +0200 +Subject: [PATCH] fix startup issue on modern systemd systems + +When we startup AND are told to auto-background ourselfs, we must +close all unneeded file descriptors. Not doing this has some +security implications. Traditionally, we do this by iterating +over all possible file descriptor values. This is fairly compatible, +because we need no OS-specific method. However, modern systemd configs +tend to not limit the number of fds, so there are potentially 2^30(*) +fds to close. While this is OKish, it takes some time and makes +systemd think that rsyslog did not properly start up. + +We have now solved this by using the /proc filesystem to obtain our +currently open fds. This works for Linux, as well as Cygwin, NetBSD, +FreeBDS and MacOS. Where not available,and close_range() is available +on the (build) platform, we try to use it. If that fails as well, we +fall back to the traditional method. In our opionion, this fallback +is unproblematic, as on these platforms there is no systemd and in +almost all cases a decent number of fds to close. + +Very special thanks go out to Brennan Kinney, who clearly described +the issue to us on github and also provided ample ways to solve it. +What we did is just implement what we think is the best fit from +rsyslog's PoV. + +(*) Some details below on the number of potentially to close fds. + This is directly from a github posting from Brennan Kinney. +Just to clarify, by default since systemd v240 (2018Q4), that +should be `1024:524288` limit. As in the soft limit is the expected +`1024`. + +The problem is other software shipping misconfiguration in systemd +services that overrides this to something silly like +`LimitNOFILE=infinity`. +- Which will map to the sysctl `fs.nr_open` (_a value systemd + v240 also raises from `2^20` to 2^30`, some distro like Debian are + known to opt-out via patch for the `fs.nr_open` change_). +- With the biggest issue there being that the soft limit was also + set to `infinity` instead of their software requesting to raise + the soft limit to a higher value that the hard limit permits. + `infinity` isn't at all sane though. +- The known source of this misconfiguration is container software such + as Docker and `containerd` (_which would often sync with the + systemd `.service` config from the Docker daemon `dockerd.service`_). + +closes https://github.com/rsyslog/rsyslog/issues/5158 + +Reference:https://github.com/rsyslog/rsyslog/commit/144cc03d90293cc09c4c100dd941226b421709e2 +Conflict:NA +--- + configure.ac | 4 +-- + tools/rsyslogd.c | 68 +++++++++++++++++++++++++++++++++++++++++++----- + 2 files changed, 63 insertions(+), 9 deletions(-) + +diff --git a/configure.ac b/configure.ac +index 6ff0955..49bb316 100644 +--- a/configure.ac ++++ b/configure.ac +@@ -200,7 +200,7 @@ AC_CHECK_HEADERS([malloc.h],[],[],[ + #endif + ] + ]) +-AC_CHECK_HEADERS([fcntl.h locale.h netdb.h netinet/in.h paths.h stddef.h stdlib.h string.h sys/file.h sys/ioctl.h sys/param.h sys/socket.h sys/time.h sys/stat.h unistd.h utmp.h utmpx.h sys/epoll.h sys/prctl.h sys/select.h getopt.h]) ++AC_CHECK_HEADERS([fcntl.h locale.h netdb.h netinet/in.h paths.h stddef.h stdlib.h string.h sys/file.h sys/ioctl.h sys/param.h sys/socket.h sys/time.h sys/stat.h unistd.h utmp.h utmpx.h sys/epoll.h sys/prctl.h sys/select.h getopt.h linux/close_range.h]) + + # Checks for typedefs, structures, and compiler characteristics. + AC_C_CONST +@@ -233,7 +233,7 @@ AC_TYPE_SIGNAL + AC_FUNC_STAT + AC_FUNC_STRERROR_R + AC_FUNC_VPRINTF +-AC_CHECK_FUNCS([flock recvmmsg basename alarm clock_gettime gethostbyname gethostname gettimeofday localtime_r memset mkdir regcomp select setsid socket strcasecmp strchr strdup strerror strndup strnlen strrchr strstr strtol strtoul uname ttyname_r getline malloc_trim prctl epoll_create epoll_create1 fdatasync syscall lseek64 asprintf]) ++AC_CHECK_FUNCS([flock recvmmsg basename alarm clock_gettime gethostbyname gethostname gettimeofday localtime_r memset mkdir regcomp select setsid socket strcasecmp strchr strdup strerror strndup strnlen strrchr strstr strtol strtoul uname ttyname_r getline malloc_trim prctl epoll_create epoll_create1 fdatasync syscall lseek64 asprintf close_range]) + AC_CHECK_FUNC([setns], [AC_DEFINE([HAVE_SETNS], [1], [Define if setns exists.])]) + AC_CHECK_TYPES([off64_t]) + +diff --git a/tools/rsyslogd.c b/tools/rsyslogd.c +index bd19a5b..458b8f6 100644 +--- a/tools/rsyslogd.c ++++ b/tools/rsyslogd.c +@@ -3,7 +3,7 @@ + * because it was either written from scratch by me (rgerhards) or + * contributors who agreed to ASL 2.0. + * +- * Copyright 2004-2022 Rainer Gerhards and Adiscon ++ * Copyright 2004-2023 Rainer Gerhards and Adiscon + * + * This file is part of rsyslog. + * +@@ -27,6 +27,7 @@ + #include + #include + #include ++#include + #include + #include + #ifdef ENABLE_LIBLOGGING_STDLOG +@@ -38,6 +39,9 @@ + # include + #include + #endif ++#if defined(HAVE_LINUX_CLOSE_RANGE_H) ++# include ++#endif + + #include "rsyslog.h" + #include "wti.h" +@@ -358,6 +362,36 @@ finalize_it: + RETiRet; + } + ++ ++ ++/* note: this function is specific to OS'es which provide ++ * the ability to read open file descriptors via /proc. ++ * returns 0 - success, something else otherwise ++ */ ++static int ++close_unneeded_open_files(const char *const procdir, ++ const int beginClose, const int parentPipeFD) ++{ ++ DIR *dir; ++ struct dirent *entry; ++ ++ dir = opendir(procdir); ++ if (dir == NULL) { ++ dbgprintf("closes unneeded files: opendir failed for %s\n", procdir); ++ return 1; ++ } ++ ++ while ((entry = readdir(dir)) != NULL) { ++ const int fd = atoi(entry->d_name); ++ if(fd >= beginClose && (((fd != dbgGetDbglogFd()) && (fd != parentPipeFD)))) { ++ close(fd); ++ } ++ } ++ ++ closedir(dir); ++ return 0; ++} ++ + /* prepares the background processes (if auto-backbrounding) for + * operation. + */ +@@ -403,12 +437,32 @@ prepareBackground(const int parentPipeFD) + } + #endif + +- /* close unnecessary open files */ +- const int endClose = getdtablesize(); +- close(0); +- for(int i = beginClose ; i <= endClose ; ++i) { +- if((i != dbgGetDbglogFd()) && (i != parentPipeFD)) { +- aix_close_it(i); /* AIXPORT */ ++ /* close unnecessary open files - first try to use /proc file system, ++ * if that is not possible iterate through all potentially open file ++ * descriptors. This can be lenghty, but in practice /proc should work ++ * for almost all current systems, and the fallback is primarily for ++ * Solaris and AIX, where we do expect a decent max numbers of fds. ++ */ ++ close(0); /* always close stdin, we do not need it */ ++ ++ /* try Linux, Cygwin, NetBSD */ ++ if(close_unneeded_open_files("/proc/self/fd", beginClose, parentPipeFD) != 0) { ++ /* try MacOS, FreeBSD */ ++ if(close_unneeded_open_files("/proc/fd", beginClose, parentPipeFD) != 0) { ++ /* did not work out, so let's close everything... */ ++ const int endClose = getdtablesize(); ++# if defined(HAVE_CLOSE_RANGE) ++ if(close_range(beginClose, endClose, 0) != 0) { ++ dbgprintf("errno %d after close_range(), fallback to loop\n", errno); ++# endif ++ for(int i = beginClose ; i <= endClose ; ++i) { ++ if((i != dbgGetDbglogFd()) && (i != parentPipeFD)) { ++ aix_close_it(i); /* AIXPORT */ ++ } ++ } ++# if defined(HAVE_CLOSE_RANGE) ++ } ++# endif + } + } + seedRandomNumberForChild(); +-- +2.19.1 + diff --git a/backport-imfile-bugfix-message-loss-duplication-when-monitore.patch b/backport-imfile-bugfix-message-loss-duplication-when-monitore.patch new file mode 100644 index 0000000..53bdda8 --- /dev/null +++ b/backport-imfile-bugfix-message-loss-duplication-when-monitore.patch @@ -0,0 +1,276 @@ +From 5520373959c4513fc60a1be8785ea45f926231b5 Mon Sep 17 00:00:00 2001 +From: Rainer Gerhards +Date: Tue, 31 May 2022 12:03:18 +0200 +Subject: [PATCH] imfile bugfix: message loss/duplication when monitored file + is rotated + +When a to-be-monitored file is being rotated, some messages may be lost or +duplicated. In case of duplication, many file lines may be duplicated +depending on actual timing. The whole bug was primarily timing depenedent +in general. It most often was visible in practice when the monitored +file was very frequently rotated (we had some report with every few +seconds). + +Note that while we try hard to not lose any messages, input file +rotation always has some loss potential. This is inevitable if +the monitored file is being truncated. + +Also note that this bugfix affects imfile, only. It has nothing to do +and no relation to rsyslog output files being rotated on HUP. + +closes: https://github.com/rsyslog/rsyslog/issues/4797 + +Reference:https://github.com/rsyslog/rsyslog/commit/5520373959c4513fc60a1be8785ea45f926231b5 +Conflict:NA +--- + plugins/imfile/imfile.c | 49 +++++++++++++++++++++------- + runtime/stream.c | 58 +++------------------------------ + runtime/stream.h | 5 --- + tests/imfile-logrotate-async.sh | 7 ++-- + 4 files changed, 47 insertions(+), 72 deletions(-) + +diff --git a/plugins/imfile/imfile.c b/plugins/imfile/imfile.c +index e064de4..b0f341e 100644 +--- a/plugins/imfile/imfile.c ++++ b/plugins/imfile/imfile.c +@@ -84,6 +84,7 @@ MODULE_CNFNAME("imfile") + /* defines */ + #define FILE_ID_HASH_SIZE 20 /* max size of a file_id hash */ + #define FILE_ID_SIZE 512 /* how many bytes are used for file-id? */ ++#define FILE_DELETE_DELAY 5 /* how many seconds to wait before finally deleting a gone file */ + + /* Module static data */ + DEF_IMOD_STATIC_DATA /* must be present, starts static data */ +@@ -209,6 +210,7 @@ struct act_obj_s { + ratelimit_t *ratelimiter; + multi_submit_t multiSub; + int is_symlink; ++ time_t time_to_delete; /* Helper variable to DELAY the actual file delete in act_obj_unlink */ + }; + struct fs_edge_s { + fs_node_t *parent; /* node pointing to this edge */ +@@ -774,6 +776,7 @@ act_obj_add(fs_edge_t *const edge, const char *const name, const int is_file, + act->file_id_prev[0] = '\0'; + act->is_symlink = is_symlink; + act->ratelimiter = NULL; ++ act->time_to_delete = 0; + if (source) { /* we are target of symlink */ + CHKmalloc(act->source_name = strdup(source)); + } else { +@@ -827,26 +830,49 @@ detect_updates(fs_edge_t *const edge) + + for(act = edge->active ; act != NULL ; act = act->next) { + DBGPRINTF("detect_updates checking active obj '%s'\n", act->name); +- const int r = lstat(act->name, &fileInfo); ++ // lstat() has the disadvantage, that we get "deleted" when the name has changed ++ // but inode is still the same (like with logrotate) ++ int r = lstat(act->name, &fileInfo); + if(r == -1) { /* object gone away? */ +- DBGPRINTF("object gone away, unlinking: '%s'\n", act->name); +- act_obj_unlink(act); +- restart = 1; ++ /* now let's see if the file itself already exist (e.g. rotated away) */ ++ /* NOTE: this will NOT stall the file. The reason is that when a new file ++ * with the same name is detected, we will not run into this code. ++ TODO: check the full implications, there are for sure some! ++ e.g. file has been closed, so we will never have old inode (but ++ why was it closed then? --> check) ++ */ ++ r = fstat(act->ino, &fileInfo); ++ if(r == -1) { ++ time_t ttNow; ++ time(&ttNow); ++ if (act->time_to_delete == 0) { ++ act->time_to_delete = ttNow; ++ } ++ /* First time we run into this code, we need to give imfile a little time to process ++ * the old file in case a process is still writing into it until the FILE_DELETE_DELAY ++ * is reached OR the inode has changed (see elseif below). In most cases, the ++ * delay will never be reached and the file will be closed when the inode has changed. ++ */ ++ if (act->time_to_delete + FILE_DELETE_DELAY < ttNow) { ++ DBGPRINTF("detect_updates obj gone away, unlinking: '%s', ttDelete: %ld/%ld\n", ++ act->name, act->time_to_delete, ttNow); ++ act_obj_unlink(act); ++ restart = 1; ++ } else { ++ DBGPRINTF("detect_updates obj gone away, keep '%s' open: %ld/%ld/%lds!\n", ++ act->name, act->time_to_delete, ttNow, ttNow - act->time_to_delete); ++ pollFile(act); ++ } ++ } + break; + } else if(fileInfo.st_ino != act->ino) { + DBGPRINTF("file '%s' inode changed from %llu to %llu, unlinking from " + "internal lists\n", act->name, (long long unsigned) act->ino, + (long long unsigned) fileInfo.st_ino); +- if(act->pStrm != NULL) { +- /* we do no need to re-set later, as act_obj_unlink +- * will destroy the strm obj */ +- strmSet_checkRotation(act->pStrm, STRM_ROTATION_DO_NOT_CHECK); +- } + act_obj_unlink(act); + restart = 1; + break; + } +- + } + + if (restart) { +@@ -1102,7 +1128,8 @@ chk_active(const act_obj_t *act, const act_obj_t *const deleted) + static void ATTR_NONNULL() + act_obj_unlink(act_obj_t *act) + { +- DBGPRINTF("act_obj_unlink %p: %s, pStrm %p\n", act, act->name, act->pStrm); ++ DBGPRINTF("act_obj_unlink %p: %s, pStrm %p, ttDelete: %ld\n", ++ act, act->name, act->pStrm, act->time_to_delete); + if(act->prev == NULL) { + act->edge->active = act->next; + } else { +diff --git a/runtime/stream.c b/runtime/stream.c +index 23cde86..d632e8a 100644 +--- a/runtime/stream.c ++++ b/runtime/stream.c +@@ -583,47 +583,6 @@ finalize_it: + } + + +-/* handle the eof case for monitored files. +- * If we are monitoring a file, someone may have rotated it. In this case, we +- * also need to close it and reopen it under the same name. +- * rgerhards, 2008-02-13 +- * The previous code also did a check for file truncation, in which case the +- * file was considered rewritten. However, this potential border case turned +- * out to be a big trouble spot on busy systems. It caused massive message +- * duplication (I guess stat() can return a too-low number under some +- * circumstances). So starting as of now, we only check the inode number and +- * a file change is detected only if the inode changes. -- rgerhards, 2011-01-10 +- */ +-static rsRetVal ATTR_NONNULL() +-strmHandleEOFMonitor(strm_t *const pThis) +-{ +- DEFiRet; +- struct stat statName; +- +- ISOBJ_TYPE_assert(pThis, strm); +- if(stat((char*) pThis->pszCurrFName, &statName) == -1) +- ABORT_FINALIZE(RS_RET_IO_ERROR); +- DBGPRINTF("strmHandleEOFMonitor: stream checking for file change on '%s', inode %u/%u size %llu/%llu\n", +- pThis->pszCurrFName, (unsigned) pThis->inode, (unsigned) statName.st_ino, +- (long long unsigned) pThis->iCurrOffs, (long long unsigned) statName.st_size); +- +- /* Inode unchanged but file size on disk is less than current offset +- * means file was truncated, we also reopen if 'reopenOnTruncate' is on +- */ +- if (pThis->inode != statName.st_ino +- || (pThis->bReopenOnTruncate && statName.st_size < pThis->iCurrOffs)) { +- DBGPRINTF("we had a file change on '%s'\n", pThis->pszCurrFName); +- CHKiRet(strmCloseFile(pThis)); +- CHKiRet(strmOpenFile(pThis)); +- } else { +- ABORT_FINALIZE(RS_RET_EOF); +- } +- +-finalize_it: +- RETiRet; +-} +- +- + /* handle the EOF case of a stream + * The EOF case is somewhat complicated, as the proper action depends on the + * mode the stream is in. If there are multiple files (circular logs, most +@@ -651,11 +610,8 @@ strmHandleEOF(strm_t *const pThis) + case STREAMTYPE_FILE_MONITOR: + DBGOPRINT((obj_t*) pThis, "file '%s' (%d) EOF, rotationCheck %d\n", + pThis->pszCurrFName, pThis->fd, pThis->rotationCheck); +- if(pThis->rotationCheck == STRM_ROTATION_DO_CHECK) { +- CHKiRet(strmHandleEOFMonitor(pThis)); +- } else { +- ABORT_FINALIZE(RS_RET_EOF); +- } ++DBGPRINTF("RGER: EOF!\n"); ++ ABORT_FINALIZE(RS_RET_EOF); + break; + } + +@@ -772,6 +728,7 @@ strmReadBuf(strm_t *pThis, int *padBytes) + } + iLenRead = read(pThis->fd, pThis->pIOBuf, toRead); + DBGOPRINT((obj_t*) pThis, "file %d read %ld bytes\n", pThis->fd, iLenRead); ++ DBGOPRINT((obj_t*) pThis, "file %d read %*s\n", pThis->fd, (unsigned) iLenRead, (char*) pThis->pIOBuf); + /* end crypto */ + if(iLenRead == 0) { + CHKiRet(strmHandleEOF(pThis)); +@@ -1021,6 +978,7 @@ finalize_it: + } + pThis->strtOffs = pThis->iCurrOffs; /* we are at begin of next line */ + } else { ++DBGPRINTF("RGER: strmReadLine iRet %d\n", iRet); + if(*ppCStr != NULL) { + if(cstrLen(*ppCStr) > 0) { + /* we may have an empty string in an unsuccesfull poll or after restart! */ +@@ -2211,14 +2169,6 @@ strmSetReadTimeout(strm_t *const __restrict__ pThis, const int val) + pThis->readTimeout = val; + } + +-void ATTR_NONNULL() +-strmSet_checkRotation(strm_t *const pThis, const int val) { +- ISOBJ_TYPE_assert(pThis, strm); +- assert(val == STRM_ROTATION_DO_CHECK || val == STRM_ROTATION_DO_NOT_CHECK); +- pThis->rotationCheck = val; +-} +- +- + static rsRetVal ATTR_NONNULL() + strmSetbDeleteOnClose(strm_t *const pThis, const int val) + { +diff --git a/runtime/stream.h b/runtime/stream.h +index 2830f7c..c308dd6 100644 +--- a/runtime/stream.h ++++ b/runtime/stream.h +@@ -91,10 +91,6 @@ typedef enum { /* when extending, do NOT change existing modes! */ + STREAMMODE_WRITE_APPEND = 4 + } strmMode_t; + +-/* settings for stream rotation (applies not to all processing modes!) */ +-#define STRM_ROTATION_DO_CHECK 0 +-#define STRM_ROTATION_DO_NOT_CHECK 1 +- + #define STREAM_ASYNC_NUMBUFS 2 /* must be a power of 2 -- TODO: make configurable */ + /* The strm_t data structure */ + typedef struct strm_s { +@@ -241,6 +237,5 @@ void strmSetReadTimeout(strm_t *const __restrict__ pThis, const int val); + const uchar * ATTR_NONNULL() strmGetPrevLineSegment(strm_t *const pThis); + const uchar * ATTR_NONNULL() strmGetPrevMsgSegment(strm_t *const pThis); + int ATTR_NONNULL() strmGetPrevWasNL(const strm_t *const pThis); +-void ATTR_NONNULL() strmSet_checkRotation(strm_t *const pThis, const int val); + + #endif /* #ifndef STREAM_H_INCLUDED */ +diff --git a/tests/imfile-logrotate-async.sh b/tests/imfile-logrotate-async.sh +index 5eba0e0..571dc9d 100755 +--- a/tests/imfile-logrotate-async.sh ++++ b/tests/imfile-logrotate-async.sh +@@ -26,8 +26,8 @@ generate_conf + add_conf ' + $WorkDirectory '$RSYSLOG_DYNNAME'.spool + +-global( debug.whitelist="off" +- debug.files=["rainerscript.c", "ratelimit.c", "ruleset.c", "main Q", "msg.c", "../action.c"] ++global( debug.whitelist="on" ++ debug.files=["imfile.c", "stream.c"] + ) + + module(load="../plugins/imfile/.libs/imfile" mode="inotify" PollingInterval="2") +@@ -72,6 +72,9 @@ ls -li $RSYSLOG_DYNNAME.input* + #wait_file_lines $RSYSLOG_OUT_LOG $msgcount $RETRIES + wait_file_lines + ++touch $RSYSLOG_DYNNAME.input.log ++./msleep 1000 ++ + shutdown_when_empty + wait_shutdown + seq_check +-- +2.19.1 + diff --git a/backport-imfile-fix-ext-directory-s-fd-leak-in-case-of-inotify.patch b/backport-imfile-fix-ext-directory-s-fd-leak-in-case-of-inotify.patch new file mode 100644 index 0000000..f6ad261 --- /dev/null +++ b/backport-imfile-fix-ext-directory-s-fd-leak-in-case-of-inotify.patch @@ -0,0 +1,46 @@ +From fcf72d6ac5662e3cee536eddbae1b4fa9f1aff8a Mon Sep 17 00:00:00 2001 +From: Sergey Kacheev +Date: Mon, 5 Dec 2022 12:36:19 +0700 +Subject: [PATCH] imfile: fix ext directory's fd leak in case of inotify on + symlink + +Reference:https://github.com/rsyslog/rsyslog/commit/fcf72d6ac5662e3cee536eddbae1b4fa9f1aff8a +Conflict:NA +--- + plugins/imfile/imfile.c | 15 +++++++++------ + 1 file changed, 9 insertions(+), 6 deletions(-) + +diff --git a/plugins/imfile/imfile.c b/plugins/imfile/imfile.c +index e922261889..5febd6db67 100644 +--- a/plugins/imfile/imfile.c ++++ b/plugins/imfile/imfile.c +@@ -852,10 +852,13 @@ detect_updates(fs_edge_t *const edge) + * the old file in case a process is still writing into it until the FILE_DELETE_DELAY + * is reached OR the inode has changed (see elseif below). In most cases, the + * delay will never be reached and the file will be closed when the inode has changed. ++ * Directories are deleted without delay. + */ +- if (act->time_to_delete + FILE_DELETE_DELAY < ttNow) { +- DBGPRINTF("detect_updates obj gone away, unlinking: '%s', ttDelete: %lds, ttNow:%ld\n", +- act->name, ttNow - (act->time_to_delete + FILE_DELETE_DELAY), ttNow); ++ sbool is_file = act->edge->is_file; ++ if (!is_file || act->time_to_delete + FILE_DELETE_DELAY < ttNow) { ++ DBGPRINTF("detect_updates obj gone away, unlinking: " ++ "'%s', ttDelete: %lds, ttNow:%ld isFile: %d\n", ++ act->name, ttNow - (act->time_to_delete + FILE_DELETE_DELAY), ttNow, is_file); + act_obj_unlink(act); + restart = 1; + } else { +@@ -1038,9 +1041,9 @@ act_obj_destroy(act_obj_t *const act, const int is_deleted) + act_obj_t *target_act; + for(target_act = act->edge->active ; target_act != NULL ; target_act = target_act->next) { + if(target_act->source_name && !strcmp(target_act->source_name, act->name)) { +- DBGPRINTF("act_obj_destroy: unlinking slink target %s of %s " +- "symlink\n", target_act->name, act->name); +- act_obj_unlink(target_act); ++ DBGPRINTF("act_obj_destroy: detect_updates for parent of target %s of %s symlink\n", ++ target_act->name, act->name); ++ detect_updates(target_act->edge->parent->root->edges); + break; + } + } diff --git a/backport-imfile-tests-ext-directorys-fd-leak-in-case-of-inotify-on.patch b/backport-imfile-tests-ext-directorys-fd-leak-in-case-of-inotify-on.patch new file mode 100644 index 0000000..eff1992 --- /dev/null +++ b/backport-imfile-tests-ext-directorys-fd-leak-in-case-of-inotify-on.patch @@ -0,0 +1,197 @@ +From e8ac82e09f930bf99421cc323c24a9dbf215f9da Mon Sep 17 00:00:00 2001 +From: Sergey Kacheev +Date: Wed, 2 Nov 2022 03:45:31 +0700 +Subject: [PATCH] imfile tests: ext directory's fd leak in case of inotify on + symlink + +Reference:https://github.com/rsyslog/rsyslog/commit/e8ac82e09f930bf99421cc323c24a9dbf215f9da +Conflict:NA +--- + tests/Makefile.am | 2 + + tests/README | 12 ++-- + tests/diag.sh | 33 ++++++++++ + tests/imfile-symlink-ext-tmp-dir-tree.sh | 80 ++++++++++++++++++++++++ + 4 files changed, 123 insertions(+), 4 deletions(-) + create mode 100755 tests/imfile-symlink-ext-tmp-dir-tree.sh + +diff --git a/tests/Makefile.am b/tests/Makefile.am +index 396e159..1063079 100644 +--- a/tests/Makefile.am ++++ b/tests/Makefile.am +@@ -1499,6 +1499,7 @@ TESTS += \ + imfile-rename.sh \ + imfile-symlink.sh \ + imfile-symlink-multi.sh \ ++ imfile-symlink-ext-tmp-dir-tree.sh \ + imfile-logrotate.sh \ + imfile-logrotate-async.sh \ + imfile-logrotate-multiple.sh \ +@@ -2479,6 +2480,7 @@ EXTRA_DIST= \ + imfile-rename.sh \ + imfile-symlink.sh \ + imfile-symlink-multi.sh \ ++ imfile-symlink-ext-tmp-dir-tree.sh \ + imfile-logrotate.sh \ + imfile-logrotate-async.sh \ + imfile-logrotate-copytruncate.sh \ +diff --git a/tests/README b/tests/README +index f0d3bb9..63a15d4 100644 +--- a/tests/README ++++ b/tests/README +@@ -41,15 +41,19 @@ make check + + Running named tests + =================== +-make testname.sh.log ++make testname.log + + For example, to run the imfile-basic.sh test, use + +-make imfile-basic.sh.log ++ make imfile-basic.log + +-Test output is in imfile-basic.sh.log ++Test output is in imfile-basic.log + +-To re-run the test, first remove imfile-basic.sh.log then make again ++To re-run the test, first remove imfile-basic.log then make again ++ ++Or an alternative option is to run ++ ++ make check TESTS='imfile-basic.sh' + + * Using gdb to debug rsyslog during a test run + +diff --git a/tests/diag.sh b/tests/diag.sh +index 8bab35b..14966e0 100755 +--- a/tests/diag.sh ++++ b/tests/diag.sh +@@ -889,6 +889,39 @@ check_journal_testmsg_received() { + fi; + } + ++# checks that among the open files found in /proc//fd/* ++# there is or is not, depending on the calling mode, ++# a link with the specified suffix in the target name ++check_fd_for_pid() { ++ local pid="$1" mode="$2" suffix="$3" target seen ++ seen="false" ++ for fd in $(echo /proc/$pid/fd/*); do ++ target="$(readlink -m "$fd")" ++ if [[ "$target" != *$RSYSLOG_DYNNAME* ]]; then ++ continue ++ fi ++ if ((i % 10 == 0)); then ++ echo "INFO: check target='$target'" ++ fi ++ if [[ "$target" == *$suffix ]]; then ++ seen="true" ++ if [[ "$mode" == "exists" ]]; then ++ echo "PASS: check fd for pid=$pid mode='$mode' suffix='$suffix'" ++ return 0 ++ fi ++ fi ++ done ++ if [[ "$seen" == "false" ]] && [[ "$mode" == "absent" ]]; then ++ echo "PASS: check fd for pid=$pid mode='$mode' suffix='$suffix'" ++ return 0 ++ fi ++ echo "FAIL: check fd for pid=$pid mode='$mode' suffix='$suffix'" ++ if [[ "$mode" != "ignore" ]]; then ++ return 1 ++ fi ++ return 0 ++} ++ + # wait for main message queue to be empty. $1 is the instance. + # we run in a loop to ensure rsyslog is *really* finished when a + # function for the "finished predicate" is defined. This is done +diff --git a/tests/imfile-symlink-ext-tmp-dir-tree.sh b/tests/imfile-symlink-ext-tmp-dir-tree.sh +new file mode 100755 +index 0000000..df15f54 +--- /dev/null ++++ b/tests/imfile-symlink-ext-tmp-dir-tree.sh +@@ -0,0 +1,80 @@ ++#!/bin/bash ++# This test creates multiple symlinks (all watched by rsyslog via wildcard) ++# chained to target files via additional symlinks and checks that all files ++# are recorded with correct corresponding metadata (name of symlink ++# matching configuration). ++# This is part of the rsyslog testbench, released under ASL 2.0 ++. "${srcdir:=.}"/diag.sh init ++. "$srcdir"/diag.sh check-inotify ++ ++# #define FILE_DELETE_DELAY 5 /* how many seconds to wait before finally deleting a gone file */ ++export RSYSLOG_DEBUG="debug nologfuncflow noprintmutexaction nostdout" ++export RSYSLOG_DEBUGLOG="log" ++export TEST_TIMEOUT=30 ++ ++# generate input files first. Note that rsyslog processes it as ++# soon as it start up (so the file should exist at that point). ++generate_conf ++add_conf ' ++# comment out if you need more debug info: ++global( debug.whitelist="on" debug.files=["imfile.c"] ++ workDirectory="./'"$RSYSLOG_DYNNAME"'.work" ++) ++module(load="../plugins/imfile/.libs/imfile" mode="inotify") ++input(type="imfile" File="./'"$RSYSLOG_DYNNAME"'.links/*.log" Tag="file:" ++ Severity="error" Facility="local7" addMetadata="on") ++template(name="outfmt" type="list") { ++ constant(value="HEADER ") ++ property(name="msg" format="json") ++ constant(value=", filename: ") ++ property(name="$!metadata!filename") ++ constant(value=", fileoffset: ") ++ property(name="$!metadata!fileoffset") ++ constant(value="\n") ++} ++if $msg contains "msgnum:" then ++ action( type="omfile" file="'"$RSYSLOG_DYNNAME.out/$RSYSLOG_OUT_LOG"'" template="outfmt") ++' ++ ++mkdir "$RSYSLOG_DYNNAME".links "$RSYSLOG_DYNNAME".work "$RSYSLOG_DYNNAME".out ++ ++printf '\ncreating %s\n' "$RSYSLOG_DYNNAME".targets/container-1/logs/0.log ++mkdir -p "$RSYSLOG_DYNNAME".targets/container-1/logs ++./inputfilegen -m 1 >"$RSYSLOG_DYNNAME".targets/container-1/logs/0.log ++ls -l "$RSYSLOG_DYNNAME".targets/container-1/logs/0.log ++ln -sv "$PWD/$RSYSLOG_DYNNAME".targets/container-1/logs/0.log "$PWD/$RSYSLOG_DYNNAME".links/container-1.log ++printf '%s generated link %s\n' "$(tb_timestamp)" "container-1" ++ls -l "$RSYSLOG_DYNNAME".links/container-1.log ++ ++# Start rsyslog now ++startup ++ ++PID=$(cat "$RSYSLOG_PIDBASE".pid) ++echo "Rsyslog pid $RSYSLOG_PIDBASE.pid=$PID" ++if [[ "$PID" == "" ]]; then ++ error_exit 1 ++fi ++ ++echo "INFO: check files" ++# wait until this files has been opened ++check_fd_for_pid "$PID" exists "container-1/logs/0.log" ++check_fd_for_pid "$PID" exists "container-1/logs" ++ ++echo "INFO: remove watched files" ++rm -vr "$RSYSLOG_DYNNAME".targets/container-1 ++rm -v "$RSYSLOG_DYNNAME".links/container-1.log ++ ++until check_fd_for_pid "$PID" absent "container-1/logs (deleted)"; do ++ if ((_wait_for_absent++ > TEST_TIMEOUT)); then ++ error_exit 1 ++ fi ++ echo "INFO: trigger fd unlinking" ++ ./inputfilegen -m 1 >"$RSYSLOG_DYNNAME".links/gogogo.log ++ ./msleep 1000 ++ rm -v "$RSYSLOG_DYNNAME".links/gogogo.log ++ ./msleep 10 ++done ++ ++shutdown_when_empty ++wait_shutdown ++exit_test +-- +2.19.1 + diff --git a/backport-lookup-tables-bugfix-reload-on-HUP-did-not-work-when.patch b/backport-lookup-tables-bugfix-reload-on-HUP-did-not-work-when.patch new file mode 100644 index 0000000..fc4c1d0 --- /dev/null +++ b/backport-lookup-tables-bugfix-reload-on-HUP-did-not-work-when.patch @@ -0,0 +1,326 @@ +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-2020 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(); + } + diff --git a/backport-lookup-tables-fix-static-analyzer-issue.patch b/backport-lookup-tables-fix-static-analyzer-issue.patch new file mode 100644 index 0000000..2f3e68d --- /dev/null +++ b/backport-lookup-tables-fix-static-analyzer-issue.patch @@ -0,0 +1,57 @@ +From 8d36cbd29d8db7091e13dd8d720b744c7399acf2 Mon Sep 17 00:00:00 2001 +From: Rainer Gerhards +Date: Wed, 2 Aug 2023 13:20:47 +0200 +Subject: [PATCH] lookup tables: fix static analyzer issue + +If something goes really wrong, a lookup table's name would not +be set. That could lead to a NULL pointer access. HOWEVER, this +would require serious bugs in config parameter parsing, as the +lookup table name is a required parameter and the parser will +error out if not set. + +So the bug is mostly cosmetic - but it does not hurt to handle +this case, of course. + +Reference:https://github.com/rsyslog/rsyslog/commit/8d36cbd29d8db7091e13dd8d720b744c7399acf2 +Conflict:NA +--- + runtime/lookup.c | 15 +++++++++++---- + 1 file changed, 11 insertions(+), 4 deletions(-) + +diff --git a/runtime/lookup.c b/runtime/lookup.c +index d9ee53b7ad..44085818c2 100644 +--- a/runtime/lookup.c ++++ b/runtime/lookup.c +@@ -1037,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); +@@ -1051,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 diff --git a/backport-mmnormalize-bugfix-if-msg-cannot-be-parsed-parser-chain-is.patch b/backport-mmnormalize-bugfix-if-msg-cannot-be-parsed-parser-chain-is.patch new file mode 100644 index 0000000..79991f0 --- /dev/null +++ b/backport-mmnormalize-bugfix-if-msg-cannot-be-parsed-parser-chain-is.patch @@ -0,0 +1,38 @@ +From f2bac98f2ada404fb8ed9bc10ff13bfb72366abd Mon Sep 17 00:00:00 2001 +From: Rainer Gerhards +Date: Fri, 9 Jun 2023 14:37:26 +0200 +Subject: [PATCH] mmnormalize bugfix: if msg cannot be parsed, parser chain is + stopped + +When an parser is not able to parse a message, it should indicate this +to rsyslog core, which then activates the next parser(s) inside the +configured parser chain. + +Unfortunatley, mmnormalize always tells core "success", and so no +other parsers are activated. + +closes https://github.com/rsyslog/rsyslog/issues/5148 + +Reference:https://github.com/rsyslog/rsyslog/commit/f2bac98f2ada404fb8ed9bc10ff13bfb72366abd +Conflict:NA +--- + plugins/pmnormalize/pmnormalize.c | 3 ++- + 1 file changed, 2 insertions(+), 1 deletion(-) + +diff --git a/plugins/pmnormalize/pmnormalize.c b/plugins/pmnormalize/pmnormalize.c +index e1a89841bc..4d3ad76e49 100644 +--- a/plugins/pmnormalize/pmnormalize.c ++++ b/plugins/pmnormalize/pmnormalize.c +@@ -234,10 +234,11 @@ CODESTARTparse2 + "json: %s\n", r, fjson_object_to_json_string(json)); + } + fjson_object_put(json); ++ ABORT_FINALIZE(RS_RET_COULD_NOT_PARSE); + } else { + iRet = MsgSetPropsViaJSON_Object(pMsg, json); + } +- ++finalize_it: + ENDparse2 + + diff --git a/backport-openssl-Replaced-depreceated-method-SSLv23_method-with.patch b/backport-openssl-Replaced-depreceated-method-SSLv23_method-with.patch new file mode 100644 index 0000000..330df34 --- /dev/null +++ b/backport-openssl-Replaced-depreceated-method-SSLv23_method-with.patch @@ -0,0 +1,110 @@ +From 888ba77be0b5f6bb33716d51c5d6ce6a16ce3f67 Mon Sep 17 00:00:00 2001 +From: Andre lorbach +Date: Fri, 28 Jul 2023 14:58:50 +0200 +Subject: [PATCH] openssl: Replaced depreceated method SSLv23_method with + TLS_method + +In OpenSSL 1.1.0 and higher, SSLv23_method causes some errors +in TLS handshake from time to time. As this method is depreceated +since 1.1.0, I have replaced it with the follow up method +TLS_method which is the most generic one. + +It fixes the random test failures in tests like +- sndrcv_tls_ossl_anon_rebind.sh + +Also added some debug output in OpenSSL error handling, which is +useful when analysing debug files. + +closes: ./sndrcv_tls_ossl_anon_rebind.sh + +Reference:https://github.com/rsyslog/rsyslog/commit/8d8fe80d871b07ab14f44e4fddb68445601b66b5 +Conflict:NA +--- + runtime/nsd_ossl.c | 19 +++++++++++++++++-- + runtime/nsdsel_ptcp.c | 3 +++ + tests/tcpflood.c | 6 +++++- + 3 files changed, 25 insertions(+), 3 deletions(-) + +diff --git a/runtime/nsd_ossl.c b/runtime/nsd_ossl.c +index 13f6977..2852998 100644 +--- a/runtime/nsd_ossl.c ++++ b/runtime/nsd_ossl.c +@@ -194,10 +194,19 @@ void osslLastSSLErrorMsg(int ret, SSL *ssl, int severity, const char* pszCallSou + int iSSLErr = 0; + if (ssl == NULL) { + /* Output Error Info*/ +- dbgprintf("osslLastSSLErrorMsg: Error in '%s' with ret=%d\n", pszCallSource, ret); ++ DBGPRINTF("osslLastSSLErrorMsg: Error in '%s' with ret=%d\n", pszCallSource, ret); + } else { + /* if object is set, get error code */ + iSSLErr = SSL_get_error(ssl, ret); ++ /* Output Debug as well */ ++ DBGPRINTF("osslLastSSLErrorMsg: %s Error in '%s': '%s(%d)' with ret=%d, errno=%d, sslapi='%s'\n", ++ (iSSLErr == SSL_ERROR_SSL ? "SSL_ERROR_SSL" : ++ (iSSLErr == SSL_ERROR_SYSCALL ? "SSL_ERROR_SYSCALL" : "SSL_ERROR_UNKNOWN")), ++ pszCallSource, ERR_error_string(iSSLErr, NULL), ++ iSSLErr, ++ ret, ++ errno, ++ pszOsslApi); + + /* Output error message */ + LogMsg(0, RS_RET_NO_ERRCODE, severity, "%s Error in '%s': '%s(%d)' with ret=%d\n", +@@ -1256,8 +1265,12 @@ osslInit_ctx(nsd_ossl_t *const pThis) + bHaveKey = 1; + } + +- /* Create main CTX Object */ ++ /* Create main CTX Object. Use SSLv23_method for < Openssl 1.1.0 and TLS_method for all newer versions! */ ++#if OPENSSL_VERSION_NUMBER < 0x10100000L + pThis->ctx = SSL_CTX_new(SSLv23_method()); ++#else ++ pThis->ctx = SSL_CTX_new(TLS_method()); ++#endif + if(bHaveCA == 1 && SSL_CTX_load_verify_locations(pThis->ctx, caFile, NULL) != 1) { + LogError(0, RS_RET_TLS_CERT_ERR, "Error: CA certificate could not be accessed. " + "Check at least: 1) file path is correct, 2) file exist, " +@@ -1502,6 +1515,8 @@ osslHandshakeCheck(nsd_ossl_t *pNsd) + osslLastSSLErrorMsg(res, pNsd->ssl, LOG_WARNING, "osslHandshakeCheck Client"); + ABORT_FINALIZE(RS_RET_NO_ERRCODE /*RS_RET_RETRY*/); + } else { ++ dbgprintf("osslHandshakeCheck: OpenSSL Client handshake failed with %d " ++ "- Aborting handshake.\n", resErr); + osslLastSSLErrorMsg(res, pNsd->ssl, LOG_ERR, "osslHandshakeCheck Client"); + LogMsg(0, RS_RET_NO_ERRCODE, LOG_WARNING, + "nsd_ossl:TLS session terminated with remote syslog server '%s':" +diff --git a/runtime/nsdsel_ptcp.c b/runtime/nsdsel_ptcp.c +index 7a95dfc..2558f09 100644 +--- a/runtime/nsdsel_ptcp.c ++++ b/runtime/nsdsel_ptcp.c +@@ -158,6 +158,9 @@ IsReady(nsdsel_t *const pNsdsel, nsd_t *const pNsd, const nsdsel_waitOp_t waitOp + } + + const short revent = pThis->fds[idx].revents; ++ if (revent & POLLNVAL) { ++ DBGPRINTF("ndssel_ptcp: revent & POLLNVAL is TRUE, something is wrong, revent = %d", revent); ++ } + assert(!(revent & POLLNVAL)); + switch(waitOp) { + case NSDSEL_RD: +diff --git a/tests/tcpflood.c b/tests/tcpflood.c +index 4ad2a5c..fd43323 100644 +--- a/tests/tcpflood.c ++++ b/tests/tcpflood.c +@@ -1194,8 +1194,12 @@ initTLS(void) + ERR_load_BIO_strings(); + ERR_load_crypto_strings(); + +- /* Create main CTX Object */ ++ /* Create main CTX Object. Use SSLv23_method for < Openssl 1.1.0 and TLS_method for all newer versions! */ ++#if OPENSSL_VERSION_NUMBER < 0x10100000L + ctx = SSL_CTX_new(SSLv23_method()); ++#else ++ ctx = SSL_CTX_new(TLS_method()); ++#endif + + if(tlsCAFile != NULL && SSL_CTX_load_verify_locations(ctx, tlsCAFile, NULL) != 1) { + printf("tcpflood: Error, Failed loading CA certificate" +-- +2.33.0 + diff --git a/backport-tcp-net-subsystem-handle-data-race-gracefully.patch b/backport-tcp-net-subsystem-handle-data-race-gracefully.patch new file mode 100644 index 0000000..e448177 --- /dev/null +++ b/backport-tcp-net-subsystem-handle-data-race-gracefully.patch @@ -0,0 +1,36 @@ +From b73ccfb4be883862f1405bd40deca5a111f0c0a2 Mon Sep 17 00:00:00 2001 +From: Rainer Gerhards +Date: Mon, 2 Oct 2023 09:32:07 +0200 +Subject: [PATCH] tcp net subsystem: handle data race gracefully + +It may happen that a socket file descriptor has been closed either +while setting up poll() et al or while being inside the system call. +This was previously treated as error and caused abort in debug +builds. However, it was essentially ignored in production builds. + +This has now been fixed and now is always gracefully ignored. This +most importantly fixes some flakes in CI runs (which were caused +by this situation). + +Reference:https://github.com/rsyslog/rsyslog/commit/b73ccfb4be883862f1405bd40deca5a111f0c0a2 +Conflict:NA +--- + runtime/nsdsel_ptcp.c | 4 ++-- + 1 file changed, 2 insertions(+), 2 deletions(-) + +diff --git a/runtime/nsdsel_ptcp.c b/runtime/nsdsel_ptcp.c +index 2558f09df6..d77c729809 100644 +--- a/runtime/nsdsel_ptcp.c ++++ b/runtime/nsdsel_ptcp.c +@@ -159,9 +159,9 @@ IsReady(nsdsel_t *const pNsdsel, nsd_t *const pNsd, const nsdsel_waitOp_t waitOp + + const short revent = pThis->fds[idx].revents; + if (revent & POLLNVAL) { +- DBGPRINTF("ndssel_ptcp: revent & POLLNVAL is TRUE, something is wrong, revent = %d", revent); ++ DBGPRINTF("ndssel_ptcp: revent & POLLNVAL is TRUE, we had a race, ignoring, revent = %d", revent); ++ *pbIsReady = 0; + } +- assert(!(revent & POLLNVAL)); + switch(waitOp) { + case NSDSEL_RD: + *pbIsReady = revent & POLLIN; diff --git a/backport-tcpflood-bugfix-TCP-sending-was-not-implemented-properly.patch b/backport-tcpflood-bugfix-TCP-sending-was-not-implemented-properly.patch new file mode 100644 index 0000000..5fec84e --- /dev/null +++ b/backport-tcpflood-bugfix-TCP-sending-was-not-implemented-properly.patch @@ -0,0 +1,155 @@ +From 5050249a1ea69ed6ac6b953a7bd722a71b09f9f7 Mon Sep 17 00:00:00 2001 +From: Rainer Gerhards +Date: Thu, 27 Jul 2023 18:15:07 +0200 +Subject: [PATCH] tcpflood bugfix: TCP sending was not implemented properly + +Note: tcpflood is a testbench tool. This bug could lead to testbench +false positives. No way it can affect production deployments. + +The tcpflood tool did improperly assume that a TCP sendto() call +would send messages of any size in a single shot. This is not the +case. It has now been corrected to proper behavior. + +As a side-activity, some int variables which acutally needed to be +size_t have been fixed as well. + +Reference:https://github.com/rsyslog/rsyslog/commit/5050249a1ea69ed6ac6b953a7bd722a71b09f9f7 +Conflict:NA +--- + tests/tcpflood.c | 52 +++++++++++++++++++++++++++++++++++------------- + 1 file changed, 38 insertions(+), 14 deletions(-) + +diff --git a/tests/tcpflood.c b/tests/tcpflood.c +index 7dce5c99a4..ea91b4623f 100644 +--- a/tests/tcpflood.c ++++ b/tests/tcpflood.c +@@ -266,7 +266,7 @@ static enum { TP_UDP, TP_TCP, TP_TLS, TP_RELP_PLAIN, TP_RELP_TLS } transport = T + + /* forward definitions */ + static void initTLSSess(int); +-static int sendTLS(int i, char *buf, int lenBuf); ++static int sendTLS(int i, char *buf, size_t lenBuf); + static void closeTLSSess(int __attribute__((unused)) i); + + #ifdef ENABLE_RELP +@@ -579,7 +579,7 @@ void closeConnections(void) + * of constructing test messages. -- rgerhards, 2010-03-31 + */ + static void +-genMsg(char *buf, size_t maxBuf, int *pLenBuf, struct instdata *inst) ++genMsg(char *buf, size_t maxBuf, size_t *pLenBuf, struct instdata *inst) + { + int edLen; /* actual extra data length to use */ + char extraData[MAX_EXTRADATA_LEN + 1]; +@@ -650,7 +650,7 @@ genMsg(char *buf, size_t maxBuf, int *pLenBuf, struct instdata *inst) + *pLenBuf = snprintf(buf, maxBuf, "%s%c", MsgToSend, frameDelim); + } + if (octateCountFramed == 1) { +- snprintf(payloadLen, sizeof(payloadLen), "%d ", *pLenBuf); ++ snprintf(payloadLen, sizeof(payloadLen), "%zd ", *pLenBuf); + payloadStringLen = strlen(payloadLen); + memmove(buf + payloadStringLen, buf, *pLenBuf); + memcpy(buf, payloadLen, payloadStringLen); +@@ -661,6 +661,29 @@ genMsg(char *buf, size_t maxBuf, int *pLenBuf, struct instdata *inst) + finalize_it: /*EMPTY to keep the compiler happy */; + } + ++ ++static int ++sendPlainTCP(int socknum, char *buf, size_t lenBuf, int *ret_errno) ++{ ++ size_t lenSent; ++ int r, err; ++ ++ lenSent = 0; ++ while(lenSent != lenBuf) { ++ r = send(sockArray[socknum], buf, lenBuf, 0); ++ if(r > 0) { ++ lenSent += r; ++ } else { ++ err = errno; ++ goto finalize_it; ++ } ++ } ++ ++finalize_it: ++ return lenSent; ++} ++ ++ + /* send messages to the tcp connections we keep open. We use + * a very basic format that helps identify the message + * (via msgnum:: e.g. msgnum:00000001:). This format is suitable +@@ -673,8 +696,8 @@ int sendMessages(struct instdata *inst) + { + unsigned i = 0; + int socknum; +- int lenBuf; +- int lenSend = 0; ++ size_t lenBuf; ++ size_t lenSend = 0; + char *statusText = ""; + char buf[MAX_EXTRADATA_LEN + 1024]; + char sendBuf[MAX_SENDBUF]; +@@ -722,8 +745,7 @@ int sendMessages(struct instdata *inst) + exit(1); + } + } +- lenSend = send(sockArray[socknum], buf, lenBuf, 0); +- error_number = errno; ++ lenSend = sendPlainTCP(socknum, buf, lenBuf, &error_number); + } else if(transport == TP_UDP) { + lenSend = sendto(udpsock, buf, lenBuf, 0, &udpRcvr, sizeof(udpRcvr)); + error_number = errno; +@@ -771,8 +793,10 @@ int sendMessages(struct instdata *inst) + printf("\r%5.5u\n", i); + fflush(stdout); + test_rs_strerror_r(error_number, errStr, sizeof(errStr)); +- printf("send() failed \"%s\" at socket %d, index %u, msgNum %lld\n", +- errStr, sockArray[socknum], i, inst->numSent); ++ printf("send() failed \"%s\" at socket %d, index %u, msgNum %lld, " ++ "lenSend %zd, lenBuf %zd\n", ++ errStr, sockArray[socknum], i, inst->numSent, lenSend, ++ lenBuf); + fflush(stderr); + + return(1); +@@ -792,7 +816,7 @@ int sendMessages(struct instdata *inst) + lenSend = sendTLS(socknum, sendBuf, offsSendBuf); + if(lenSend != offsSendBuf) { + fprintf(stderr, "tcpflood: error in send function causes potential " +- "data loss lenSend %d, offsSendBuf %d\n", ++ "data loss lenSend %zd, offsSendBuf %d\n", + lenSend, offsSendBuf); + } + offsSendBuf = 0; +@@ -1375,9 +1399,9 @@ initTLSSess(int i) + + + static int +-sendTLS(int i, char *buf, int lenBuf) ++sendTLS(int i, char *buf, size_t lenBuf) + { +- int lenSent; ++ size_t lenSent; + int r, err; + + lenSent = 0; +@@ -1525,7 +1549,7 @@ initTLSSess(int i) + + + static int +-sendTLS(int i, char *buf, int lenBuf) ++sendTLS(int i, char *buf, size_t lenBuf) + { + int lenSent; + int r; +@@ -1552,7 +1576,7 @@ static void initTLS(void) {} + static void exitTLS(void) {} + static void initTLSSess(int __attribute__((unused)) i) {} + static int sendTLS(int __attribute__((unused)) i, char __attribute__((unused)) *buf, +- int __attribute__((unused)) lenBuf) { return 0; } ++ size_t __attribute__((unused)) lenBuf) { return 0; } + static void closeTLSSess(int __attribute__((unused)) i) {} + # endif + diff --git a/backport-tcpflood-bugfix-plain-tcp-send-error-not-properly-reported.patch b/backport-tcpflood-bugfix-plain-tcp-send-error-not-properly-reported.patch new file mode 100644 index 0000000..05c0ab5 --- /dev/null +++ b/backport-tcpflood-bugfix-plain-tcp-send-error-not-properly-reported.patch @@ -0,0 +1,42 @@ +From c8a2969580935121440f220af03d74ab1dfa5c11 Mon Sep 17 00:00:00 2001 +From: Rainer Gerhards +Date: Wed, 13 Sep 2023 09:33:40 +0200 +Subject: [PATCH] tcpflood bugfix: plain tcp send error not properly reported + +The error code when plain tcp sending failed was improperly returned, +resulting in no meaningful error message. + +Note: tcpflood is a testbench tool, not part of production rsyslog. + +Reference:https://github.com/rsyslog/rsyslog/commit/c8a2969580935121440f220af03d74ab1dfa5c11 +Conflict:NA +--- + tests/tcpflood.c | 6 +++--- + 1 file changed, 3 insertions(+), 3 deletions(-) + +diff --git a/tests/tcpflood.c b/tests/tcpflood.c +index cff4a59dba..12781f55ff 100644 +--- a/tests/tcpflood.c ++++ b/tests/tcpflood.c +@@ -665,10 +665,10 @@ genMsg(char *buf, size_t maxBuf, size_t *pLenBuf, struct instdata *inst) + + + static int +-sendPlainTCP(int socknum, char *buf, size_t lenBuf, int *ret_errno) ++sendPlainTCP(const int socknum, const char *const buf, const size_t lenBuf, int *const ret_errno) + { + size_t lenSent; +- int r, err; ++ int r; + + lenSent = 0; + while(lenSent != lenBuf) { +@@ -676,7 +676,7 @@ sendPlainTCP(int socknum, char *buf, size_t lenBuf, int *ret_errno) + if(r > 0) { + lenSent += r; + } else { +- err = errno; ++ *ret_errno = errno; + goto finalize_it; + } + } diff --git a/backport-testbench-add-testcase-for-frequent-imfile-input-fil.patch b/backport-testbench-add-testcase-for-frequent-imfile-input-fil.patch new file mode 100644 index 0000000..50263f5 --- /dev/null +++ b/backport-testbench-add-testcase-for-frequent-imfile-input-fil.patch @@ -0,0 +1,291 @@ +From 6be9a266ea73466840fa6571f86807069e63340d Mon Sep 17 00:00:00 2001 +From: Rainer Gerhards +Date: Fri, 27 May 2022 13:08:04 +0200 +Subject: [PATCH] testbench: add testcase for frequent imfile input file change + +PoC test, yet incomplete + +This patch not only contains the new test but also supporting +changes to testbench tooling. + +see also: https://github.com/rsyslog/rsyslog/issues/4797 + +Reference:https://github.com/rsyslog/rsyslog/commit/6be9a266ea73466840fa6571f86807069e63340d +Conflict:NA +--- + tests/Makefile.am | 2 + + tests/imfile-logrotate-async.sh | 79 +++++++++++++++++++++++++ + tests/inputfilegen.c | 102 ++++++++++++++++++++++++++++++-- + 3 files changed, 178 insertions(+), 5 deletions(-) + create mode 100755 tests/imfile-logrotate-async.sh + +diff --git a/tests/Makefile.am b/tests/Makefile.am +index b9402aa..396e159 100644 +--- a/tests/Makefile.am ++++ b/tests/Makefile.am +@@ -1500,6 +1500,7 @@ TESTS += \ + imfile-symlink.sh \ + imfile-symlink-multi.sh \ + imfile-logrotate.sh \ ++ imfile-logrotate-async.sh \ + imfile-logrotate-multiple.sh \ + imfile-logrotate-copytruncate.sh \ + imfile-logrotate-nocopytruncate.sh \ +@@ -2479,6 +2480,7 @@ EXTRA_DIST= \ + imfile-symlink.sh \ + imfile-symlink-multi.sh \ + imfile-logrotate.sh \ ++ imfile-logrotate-async.sh \ + imfile-logrotate-copytruncate.sh \ + imfile-logrotate-nocopytruncate.sh \ + imfile-logrotate-multiple.sh \ +diff --git a/tests/imfile-logrotate-async.sh b/tests/imfile-logrotate-async.sh +new file mode 100755 +index 0000000..5eba0e0 +--- /dev/null ++++ b/tests/imfile-logrotate-async.sh +@@ -0,0 +1,79 @@ ++#!/bin/bash ++# This is part of the rsyslog testbench, licensed under ASL 2.0 ++. $srcdir/diag.sh check-inotify-only ++. ${srcdir:=.}/diag.sh init ++check_command_available logrotate ++export NUMMESSAGES=10000 ++export RETRIES=50 ++ ++# Write logrotate config file ++echo '"./'$RSYSLOG_DYNNAME'.input*.log" ++{ ++ #daily ++ rotate 60 ++ missingok ++ notifempty ++ sharedscripts ++ postrotate ++ kill -HUP $(cat '$RSYSLOG_DYNNAME'.inputfilegen_pid) ++ endscript ++ #olddir /logs/old ++ ++}' > $RSYSLOG_DYNNAME.logrotate ++ ++ ++generate_conf ++add_conf ' ++$WorkDirectory '$RSYSLOG_DYNNAME'.spool ++ ++global( debug.whitelist="off" ++ debug.files=["rainerscript.c", "ratelimit.c", "ruleset.c", "main Q", "msg.c", "../action.c"] ++ ) ++ ++module(load="../plugins/imfile/.libs/imfile" mode="inotify" PollingInterval="2") ++ ++input(type="imfile" File="./'$RSYSLOG_DYNNAME'.input*.log" Tag="file:" ++ Severity="error" Facility="local7" addMetadata="on" reopenOnTruncate="on") ++ ++$template outfmt,"%msg:F,58:2%\n" ++if $msg contains "msgnum:" then ++ action(type="omfile" file="'$RSYSLOG_OUT_LOG'" template="outfmt") ++' ++startup ++ ++./inputfilegen -m $NUMMESSAGES -S 5 -B 500 -f $RSYSLOG_DYNNAME.input.log & ++INPUTFILEGEN_PID=$! ++echo "$INPUTFILEGEN_PID" > $RSYSLOG_DYNNAME.inputfilegen_pid ++ ++ ++ ++./msleep 1 ++logrotate --state $RSYSLOG_DYNNAME.logrotate.state -f $RSYSLOG_DYNNAME.logrotate ++./msleep 20 ++echo INPUT FILES: ++ls -li $RSYSLOG_DYNNAME.input* ++logrotate --state $RSYSLOG_DYNNAME.logrotate.state -f $RSYSLOG_DYNNAME.logrotate ++./msleep 20 ++echo INPUT FILES: ++ls -li $RSYSLOG_DYNNAME.input* ++logrotate --state $RSYSLOG_DYNNAME.logrotate.state -f $RSYSLOG_DYNNAME.logrotate ++echo INPUT FILES: ++ls -li $RSYSLOG_DYNNAME.input* ++echo ls ${RSYSLOG_DYNNAME}.spool: ++ls -li ${RSYSLOG_DYNNAME}.spool ++echo INPUT FILES: ++ls -li $RSYSLOG_DYNNAME.input* ++ ++# generate more input after logrotate into new logfile ++#./inputfilegen -m $TESTMESSAGES -i $TESTMESSAGES >> $RSYSLOG_DYNNAME.input.1.log ++#ls -l $RSYSLOG_DYNNAME.input* ++ ++#msgcount=$((2* TESTMESSAGES)) ++#wait_file_lines $RSYSLOG_OUT_LOG $msgcount $RETRIES ++wait_file_lines ++ ++shutdown_when_empty ++wait_shutdown ++seq_check ++#seq_check 0 $TESTMESSAGESFULL ++exit_test +diff --git a/tests/inputfilegen.c b/tests/inputfilegen.c +index 523f82a..ef61229 100644 +--- a/tests/inputfilegen.c ++++ b/tests/inputfilegen.c +@@ -1,5 +1,5 @@ + /* generate an input file suitable for use by the testbench +- * Copyright (C) 2018 by Rainer Gerhards and Adiscon GmbH. ++ * Copyright (C) 2018-2022 by Rainer Gerhards and Adiscon GmbH. + * Copyright (C) 2016-2018 by Pascal Withopf and Adiscon GmbH. + * + * usage: ./inputfilegen num-lines > file +@@ -14,9 +14,20 @@ + * This is especially useful with -s, as the testbench otherwise does + * not know how to do a seq_check. To keep things flexible, can also be + * used with -m (this may aid testbench framework generalization). ++ * -f outputfile ++ * Permits to write data to file "outputfile" instead of stdout. Also ++ * enables support for SIGHUP. ++ * -S sleep time ++ * ms to sleep between sending message bulks (bulks size given by -B) ++ * -B number of messages in bulk ++ * number of messages to send without sleeping as specified in -S. ++ * IGNORED IF -S is not also given! + * Part of rsyslog, licensed under ASL 2.0 + */ ++#include "config.h" + #include ++#include ++#include + #include + #include + #include +@@ -25,10 +36,60 @@ + #else + #include + #endif ++#if defined(__FreeBSD__) ++#include ++#else ++#include ++#endif ++#if defined(HAVE_SYS_SELECT_H) ++#include ++#endif + + #define DEFMSGS 5 + #define NOEXTRADATA -1 + ++static volatile int bHadHUP = 0; ++static void ++hdlr_sighup(int sig) ++{ ++ fprintf(stderr, "had hup, sig %d\n", sig); ++ bHadHUP = 1; ++} ++static void ++sighup_enable() ++{ ++ struct sigaction sigAct; ++ memset(&sigAct, 0, sizeof (sigAct)); ++ sigemptyset(&sigAct.sa_mask); ++ sigAct.sa_handler = hdlr_sighup; ++ sigaction(SIGHUP, &sigAct, NULL); ++} ++ ++void msleep(const int sleepTime) ++{ ++ struct timeval tvSelectTimeout; ++ ++ tvSelectTimeout.tv_sec = sleepTime / 1000; ++ tvSelectTimeout.tv_usec = (sleepTime % 1000) * 1000; /* micro seconds */ ++ if(select(0, NULL, NULL, NULL, &tvSelectTimeout) == -1) { ++ if(errno != EINTR) { ++ perror("select"); ++ exit(1); ++ } ++ } ++} ++ ++static FILE * ++open_output(const char *fn) ++{ ++ FILE *fh_output = fopen(fn, "w"); ++ if(fh_output == NULL) { ++ perror(fn); ++ exit(1); ++ } ++ return fh_output; ++} ++ + int main(int argc, char* argv[]) + { + int c, i; +@@ -39,8 +100,13 @@ int main(int argc, char* argv[]) + long long filesize = -1; + char *extradata = NULL; + const char *msgcntfile = NULL; ++ const char *outputfile = "-"; ++ FILE *fh_output; ++ int sleep_ms = 0; ++ int sleep_msgs = 0; /* messages to xmit between sleeps (if configured) */ ++ int ctr = 0; + +- while((c=getopt(argc, argv, "m:M:i:d:s:")) != -1) { ++ while((c=getopt(argc, argv, "m:M:i:d:s:f:S:B:")) != -1) { + switch(c) { + case 'm': + nmsgs = atoi(optarg); +@@ -57,6 +123,16 @@ int main(int argc, char* argv[]) + case 's': + filesize = atoll(optarg); + break; ++ case 'S': ++ sleep_ms = atoi(optarg); ++ break; ++ case 'B': ++ sleep_msgs = atoi(optarg); ++ break; ++ case 'f': ++ outputfile = optarg; ++ sighup_enable(); ++ break; + case ':': + fprintf(stderr, "Option -%c requires an operand\n", optopt); + errflg++; +@@ -97,17 +173,33 @@ int main(int argc, char* argv[]) + fclose(fh); + } + ++ if(strcmp(outputfile, "-")) { ++ fh_output = open_output(outputfile); ++ } else { ++ fh_output = stdout; ++ } ++ + if(nchars != NOEXTRADATA) { + extradata = (char *)malloc(nchars + 1); + memset(extradata, 'X', nchars); + extradata[nchars] = '\0'; + } + for(i = nmsgstart; i < (nmsgs+nmsgstart); ++i) { +- printf("msgnum:%8.8d:", i); ++ if(sleep_ms > 0 && ctr++ >= sleep_msgs) { ++ msleep(sleep_ms); ++ ctr = 0; ++ } ++ if(bHadHUP) { ++ fclose(fh_output); ++ fh_output = open_output(outputfile); ++ fprintf(stderr, "%s reopened\n", outputfile); ++ bHadHUP = 0; ++ } ++ fprintf(fh_output, "msgnum:%8.8d:", i); + if(nchars != NOEXTRADATA) { +- printf("%s", extradata); ++ fprintf(fh_output, "%s", extradata); + } +- printf("\n"); ++ fprintf(fh_output, "\n"); + } + free(extradata); + return 0; +-- +2.19.1 + diff --git a/backport-testbench-fix-imfile-statefile-delete.sh-INOTIFY-tri.patch b/backport-testbench-fix-imfile-statefile-delete.sh-INOTIFY-tri.patch new file mode 100644 index 0000000..f49aaa6 --- /dev/null +++ b/backport-testbench-fix-imfile-statefile-delete.sh-INOTIFY-tri.patch @@ -0,0 +1,77 @@ +From 127d318fd5ddadc82629c66c22880f4a2b37f3fe Mon Sep 17 00:00:00 2001 +From: Andre lorbach +Date: Wed, 5 Oct 2022 20:41:09 +0200 +Subject: [PATCH] testbench: fix imfile-statefile-delete.sh (INOTIFY trigger) + +Due the patch in PR https://github.com/rsyslog/rsyslog/pull/4895 +state files are deleted with a 5 second delay in order to fix +missing or duplicated messages. However in INOTIFY mode, we need +an INOTIFY event to trigger a poll_tree that triggers the +delayed deletion. The testcase imfile-statefile-delete.sh will now +create empty dummy files after 6 seconds delay in order to trigger +INOTIFY events. + +This fixes & closes https://github.com/rsyslog/rsyslog/issues/4958 + +Reference:https://github.com/rsyslog/rsyslog/commit/e8c6cc91ab39c31366d4e5b6f4d907ade740e257 +Conflict:NA +--- + plugins/imfile/imfile.c | 8 ++++---- + tests/imfile-statefile-delete.sh | 12 ++++++++++-- + 2 files changed, 14 insertions(+), 6 deletions(-) + +diff --git a/plugins/imfile/imfile.c b/plugins/imfile/imfile.c +index b0f341e..635d8e3 100644 +--- a/plugins/imfile/imfile.c ++++ b/plugins/imfile/imfile.c +@@ -854,13 +854,13 @@ detect_updates(fs_edge_t *const edge) + * delay will never be reached and the file will be closed when the inode has changed. + */ + if (act->time_to_delete + FILE_DELETE_DELAY < ttNow) { +- DBGPRINTF("detect_updates obj gone away, unlinking: '%s', ttDelete: %ld/%ld\n", +- act->name, act->time_to_delete, ttNow); ++ DBGPRINTF("detect_updates obj gone away, unlinking: '%s', ttDelete: %lds, ttNow:%ld\n", ++ act->name, ttNow - (act->time_to_delete + FILE_DELETE_DELAY), ttNow); + act_obj_unlink(act); + restart = 1; + } else { +- DBGPRINTF("detect_updates obj gone away, keep '%s' open: %ld/%ld/%lds!\n", +- act->name, act->time_to_delete, ttNow, ttNow - act->time_to_delete); ++ DBGPRINTF("detect_updates obj gone away, keep '%s' open: %ld/%ld/%lds!\n", ++ act->name, act->time_to_delete, ttNow, ttNow - act->time_to_delete); + pollFile(act); + } + } +diff --git a/tests/imfile-statefile-delete.sh b/tests/imfile-statefile-delete.sh +index 4d6a605..cbe4128 100755 +--- a/tests/imfile-statefile-delete.sh ++++ b/tests/imfile-statefile-delete.sh +@@ -5,6 +5,11 @@ + export TESTMESSAGES=1000 + export TESTMESSAGESFULL=999 + export RETRIES=50 ++ ++# Uncomment fdor debuglogs ++#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" ++#export RSYSLOG_DEBUGLOG="$RSYSLOG_DYNNAME.debuglog" ++ + generate_conf + add_conf ' + global(workDirectory="'${RSYSLOG_DYNNAME}'.spool") +@@ -22,8 +27,11 @@ wait_file_lines $RSYSLOG_OUT_LOG $TESTMESSAGES $RETRIES + rm $RSYSLOG_DYNNAME.input + sleep_time_ms=0 + while ls $RSYSLOG_DYNNAME.spool/imfile-state:$inode:* 1> /dev/null 2>&1; do +- ./msleep 10 +- ((sleep_time_ms+=10)) ++ ./msleep 100 ++ ((sleep_time_ms+=100)) ++ if [ $sleep_time_ms -ge 6000 ]; then ++ touch $RSYSLOG_DYNNAME:.tmp ++ fi + if [ $sleep_time_ms -ge 30000 ]; then + printf 'FAIL: state file still exists when it should have been deleted\nspool dir is:\n' + ls -l $RSYSLOG_DYNNAME.spool +-- +2.19.1 + diff --git a/backport-testbench-make-waiting-for-HUP-processing-more-reliable.patch b/backport-testbench-make-waiting-for-HUP-processing-more-reliable.patch new file mode 100644 index 0000000..013589c --- /dev/null +++ b/backport-testbench-make-waiting-for-HUP-processing-more-reliable.patch @@ -0,0 +1,200 @@ +From 3795f2ff3c0bebfea2d3e8af1bf82ac6fee63597 Mon Sep 17 00:00:00 2001 +From: Rainer Gerhards +Date: Wed, 26 Jul 2023 16:58:00 +0200 +Subject: [PATCH] testbench: make waiting for HUP processing more reliable + +The previous approach was more or less delay based. We have now +changed the code to enable imdiag to detect if HUP is underway +and wait until it is completed. The new method still employs some +kind of timeout, but is now quite reliable. Most importantly, +it works great with long-running HUP processing, which can happen +e.g. when querying the system name takes long or some actions need +longer time to persist their HUP processing. + +The new approach will most likely reduce CI flakes and also speed +up testbench runs. The speedup happens from not having to wait a +full delay in cases where we detect HUP is completed (plus reduced +timeout when we cannot clearly detect this - see code comments why +the new method is still considered more reliable than the old one). + +Code note: we needed to slightly re-structure the way actual HUP +processing and the "HUP mutex" is handled. After best analysis, +this does not affect the reliability or speed in production +settings. + +closes https://github.com/rsyslog/rsyslog/issues/5192 + +Reference:https://github.com/rsyslog/rsyslog/commit/0e5444706dfbec105a15414210013c535766e04f +Conflict:NA +--- + dirty.h | 3 ++- + plugins/imdiag/imdiag.c | 38 +++++++++++++++++++++++++++++++++++++- + tests/diag.sh | 19 +++++++++++++++++-- + tools/rsyslogd.c | 20 +++++++++++++++++++- + 4 files changed, 75 insertions(+), 5 deletions(-) + +diff --git a/dirty.h b/dirty.h +index 2d06fae..6353864 100644 +--- a/dirty.h ++++ b/dirty.h +@@ -5,7 +5,7 @@ + * yet a runtime library, because it depends on some functionality + * residing somewhere else. + * +- * Copyright 2007-2014 Rainer Gerhards and Adiscon GmbH. ++ * Copyright 2007-2023 Rainer Gerhards and Adiscon GmbH. + * + * This file is part of rsyslog. + * +@@ -39,6 +39,7 @@ rsRetVal __attribute__((deprecated)) parseAndSubmitMessage(const uchar *hname, + const time_t ttGenTime, ruleset_t *pRuleset); + rsRetVal createMainQueue(qqueue_t **ppQueue, uchar *pszQueueName, struct nvlst *lst); + rsRetVal startMainQueue(qqueue_t *pQueue); ++int get_bHadHUP(void); + + extern int MarkInterval; + extern qqueue_t *pMsgQueue; /* the main message queue */ +diff --git a/plugins/imdiag/imdiag.c b/plugins/imdiag/imdiag.c +index 62669f6..774939a 100644 +--- a/plugins/imdiag/imdiag.c ++++ b/plugins/imdiag/imdiag.c +@@ -5,7 +5,7 @@ + * + * File begun on 2008-07-25 by RGerhards + * +- * Copyright 2008-2020 Adiscon GmbH. ++ * Copyright 2008-2023 Adiscon GmbH. + * + * This file is part of rsyslog. + * +@@ -375,6 +375,40 @@ finalize_it: + RETiRet; + } + ++static rsRetVal ++awaitHUPComplete(tcps_sess_t *pSess) ++{ ++ const int max_tries = 10; ++ const int ms_to_sleep = 50; ++ const char *return_msg; ++ int b_saw_HUP = 0; ++ int tries = max_tries; ++ unsigned actual_tries = 0; ++ DEFiRet; ++ ++ while(tries > 0) { ++ ++actual_tries; ++ if(get_bHadHUP() == 1) { ++ tries = max_tries; ++ b_saw_HUP = 1; ++ } else { ++ --tries; ++ } ++ srSleep(0, ms_to_sleep * 50); ++ } ++ ++ if(b_saw_HUP) { ++ return_msg = "seen HUP request, looks like it has completed"; ++ } else { ++ return_msg = "timeout - looks like_HUP has completed"; ++ } ++ CHKiRet(sendResponse(pSess, "%s [%d tries]\n", return_msg, actual_tries)); ++ DBGPRINTF("imdiag: %s\n", return_msg); ++ ++finalize_it: ++ RETiRet; ++} ++ + static rsRetVal + enableDebug(tcps_sess_t *pSess) + { +@@ -522,6 +556,8 @@ OnMsgReceived(tcps_sess_t *const pSess, uchar *const pRcv, const int iLenMsg) + CHKiRet(blockStatsReporting(pSess)); + } else if(!ustrcmp(cmdBuf, UCHAR_CONSTANT("awaitstatsreport"))) { + CHKiRet(awaitStatsReport(pszMsg, pSess)); ++ } else if(!ustrcmp(cmdBuf, UCHAR_CONSTANT("awaithupcomplete"))) { ++ CHKiRet(awaitHUPComplete(pSess)); + } else if(!ustrcmp(cmdBuf, UCHAR_CONSTANT("enabledebug"))) { + CHKiRet(enableDebug(pSess)); + } else { +diff --git a/tests/diag.sh b/tests/diag.sh +index 14966e0..1168cf8 100755 +--- a/tests/diag.sh ++++ b/tests/diag.sh +@@ -1015,6 +1015,19 @@ quit" + } + + ++# wait for HUP to complete. $1 is the instance ++# note: there is a slight chance HUP was not completed. This can happen if it takes ++# the system very long (> 500ms) to receive the HUP and set the internal flag ++# variable. aka "very very low probability". ++await_HUP_processed() { ++ if [ "$1" == "2" ]; then ++ echo AwaitHUPComplete | $TESTTOOL_DIR/diagtalker -pIMDIAG_PORT2 || error_exit $? ++ else ++ echo AwaitHUPComplete | $TESTTOOL_DIR/diagtalker -p$IMDIAG_PORT || error_exit $? ++ fi ++} ++ ++ + # wait for all pending lookup table reloads to complete $1 is the instance. + await_lookup_table_reload() { + if [ "$1" == "2" ]; then +@@ -1199,8 +1212,10 @@ issue_HUP() { + sleeptime=1000 + fi + kill -HUP $(cat $RSYSLOG_PIDBASE$1.pid) +- printf 'HUP issued to pid %d\n' $(cat $RSYSLOG_PIDBASE$1.pid) +- $TESTTOOL_DIR/msleep $sleeptime ++ printf 'HUP issued to pid %d - waiting for it to become processed\n' \ ++ $(cat $RSYSLOG_PIDBASE$1.pid) ++ await_HUP_processed ++ #$TESTTOOL_DIR/msleep $sleeptime + } + + +diff --git a/tools/rsyslogd.c b/tools/rsyslogd.c +index a1cbe7c..99f5f61 100644 +--- a/tools/rsyslogd.c ++++ b/tools/rsyslogd.c +@@ -232,6 +232,22 @@ setsid(void) + } + #endif + ++/* helper for imdiag. Returns if HUP processing has been requested or ++ * is not yet finished. We know this is racy, but imdiag handles this ++ * part by repeating operations. The mutex look is primarily to force ++ * a memory barrier, so that we have a change to see changes already ++ * written, but not present in the core's cache. ++ * 2023-07-26 Rainer Gerhards ++ */ ++int ++get_bHadHUP(void) ++{ ++ pthread_mutex_lock(&mutHadHUP); ++ const int ret = bHadHUP; ++ pthread_mutex_unlock(&mutHadHUP); ++ /* note: at this point ret can already be invalid */ ++ return ret; ++} + + rsRetVal + queryLocalHostname(void) +@@ -1986,10 +2002,12 @@ mainloop(void) + pthread_mutex_lock(&mutHadHUP); + need_free_mutex = 1; + if(bHadHUP) { +- bHadHUP = 0; + need_free_mutex = 0; + pthread_mutex_unlock(&mutHadHUP); + doHUP(); ++ pthread_mutex_lock(&mutHadHUP); ++ bHadHUP = 0; ++ pthread_mutex_unlock(&mutHadHUP); + } + if(need_free_mutex) { + pthread_mutex_unlock(&mutHadHUP); +-- +2.19.1 + diff --git a/rsyslog.spec b/rsyslog.spec index fc58b30..930bee4 100644 --- a/rsyslog.spec +++ b/rsyslog.spec @@ -7,7 +7,7 @@ Name: rsyslog Version: 8.2110.0 -Release: 18 +Release: 19 Summary: The rocket-fast system for log processing License: (GPLv3+ and ASL 2.0) URL: http://www.rsyslog.com/ @@ -60,6 +60,23 @@ Patch6026: backport-imjournal-add-second-fallback-to-_COMM.patch Patch6027: backport-bugfix-prevent-pot.-segfault-when-switchung.patch Patch6028: backport-core-bugfix-using-uuid-msg-prop-can-deadloc.patch Patch6029: backport-GNUTls-Driver-Fix-memory-leaks-in-gtlsInitC.patch +Patch6030: backport-Use-runConf-instead-of-loadConf-in-ratelimiting-duri.patch +Patch6031: backport-testbench-add-testcase-for-frequent-imfile-input-fil.patch +Patch6032: backport-imfile-bugfix-message-loss-duplication-when-monitore.patch +Patch6033: backport-testbench-fix-imfile-statefile-delete.sh-INOTIFY-tri.patch +Patch6034: backport-imfile-tests-ext-directorys-fd-leak-in-case-of-inotify-on.patch +Patch6035: backport-imfile-fix-ext-directory-s-fd-leak-in-case-of-inotify.patch +Patch6036: backport-core-bugfix-potential-segfault-on-busy-systems.patch +Patch6037: backport-mmnormalize-bugfix-if-msg-cannot-be-parsed-parser-chain-is.patch +Patch6038: backport-bugfix-cosmetic-data-races.patch +Patch6039: backport-testbench-make-waiting-for-HUP-processing-more-reliable.patch +Patch6040: backport-openssl-Replaced-depreceated-method-SSLv23_method-with.patch +Patch6041: backport-lookup-tables-bugfix-reload-on-HUP-did-not-work-when.patch +Patch6042: backport-lookup-tables-fix-static-analyzer-issue.patch +Patch6043: backport-tcpflood-bugfix-TCP-sending-was-not-implemented-properly.patch +Patch6044: backport-tcpflood-bugfix-plain-tcp-send-error-not-properly-reported.patch +Patch6045: backport-fix-startup-issue-on-modern-systemd-systems.patch +Patch6046: backport-tcp-net-subsystem-handle-data-race-gracefully.patch BuildRequires: gcc autoconf automake bison dos2unix flex pkgconfig python3-docutils libtool BuildRequires: libgcrypt-devel libuuid-devel zlib-devel krb5-devel libnet-devel gnutls-devel @@ -534,6 +551,28 @@ done %{_mandir}/man1/rscryutil.1.gz %changelog +* Wed Mar 20 2024 zhangqiumiao - 8.2110.0-19 +- Type:bugfix +- CVE:NA +- SUG:NA +- DESC:tcp net subsystem: handle data race gracefully + fix startup issue on modern systemd systems + tcpflood bugfix: plain tcp send error not properly reported + tcpflood bugfix: TCP sending was not implemented properly + lookup tables: fix static analyzer issue + lookup tables bugfix: reload on HUP did not work when backgrounded + openssl: Replaced depreceated method SSLv23_method with TLS_method + testbench: make waiting for HUP processing more reliable + bugfix: cosmetic data races + mmnormalize bugfix: if msg cannot be parsed, parser chain is stopped + core bugfix: potential segfault on busy systems + imfile: fix ext directory's fd leak in case of inotify on symlink + imfile tests: ext directory's fd leak in case of inotify on symlink + testbench: fix imfile-statefile-delete.sh (INOTIFY trigger) + imfile bugfix: message loss/duplication when monitored file is rotated + testbench: add testcase for frequent imfile input file change + Use runConf instead of loadConf in ratelimiting during runtime + * Mon Oct 30 2023 zhangqiumiao - 8.2110.0-18 - Type:bugfix - ID:NA -- Gitee