From cbb3df9e8b819a176757ff6323988d2323342068 Mon Sep 17 00:00:00 2001 From: Zain Budhwani <99770260+zbud-msft@users.noreply.github.com> Date: Tue, 14 May 2024 18:08:14 -0700 Subject: [PATCH] [eventd]: Close rsyslog plugin when rsyslog SIGTERM and EOF is sent to stream (#18835) Fix #18771 Microsoft ADO (number only):27882794 How I did it Add signalOnClose for omprog as well as close rsyslog plugin when receives an EOF. How to verify it Verify rsyslog_plugin is running inside bgp or swss container Run docker exec -it bgp supervisorctl restart rsyslogd Before change: This will not kill current rsyslog_plugin process but instead rsyslogd will now break off its end of writing to cin and send EOF to rsyslog_plugin, however will not send a signal SIGTERM or SIGKILL to rsyslog_plugin. Therefore, rsyslog plugin will run in an infinite loop forever, constantly calling getline raising CPU to 100% inside docker. After change of adding signalOnClose="on" to conf file inside omprog, rsyslogd will now send SIGTERM to rsyslog_plugin process running inside container, and rsyslog_plugin will die. ? ( ): rsyslog_plugin/578637 ... [continued]: read()) = -1 (unknown) (INTERNAL ERROR: strerror_r(512, [buf], 128)=22) UT (will add sonic-mgmt testcase for storming events with logs) RCA: 1. When rsyslogd is terminated, no signal is sent to child process of rsyslog_plugin meaning that rsyslog_plugin will be constantly trying to read from cin with no writer on the other end of the pipe. This leads to rsyslog_plugin process will constantly be reading via getline infinitely. 2. Because rsyslog is terminated and the spawned rsyslog_plugin is still alive, when rsyslog starts backup again, and log is triggered, a new rsyslog_plugin will be spawned for that rsyslog process, which can lead to many "ghost" rsyslog_plugin processes that will be at high CPU usage. --- files/build_templates/rsyslog_plugin.conf.j2 | 1 + .../rsyslog_plugin/rsyslog_plugin.cpp | 27 ++++++++++--------- .../rsyslog_plugin/rsyslog_plugin.h | 8 ++++++ .../rsyslog_plugin_ut.cpp | 26 ++++++++++++++++++ 4 files changed, 50 insertions(+), 12 deletions(-) diff --git a/files/build_templates/rsyslog_plugin.conf.j2 b/files/build_templates/rsyslog_plugin.conf.j2 index 4628bea70e62..56ec0f71d3f1 100644 --- a/files/build_templates/rsyslog_plugin.conf.j2 +++ b/files/build_templates/rsyslog_plugin.conf.j2 @@ -12,6 +12,7 @@ if re_match($programname, "{{ proc.name }}") then { action(type="omprog" binary="/usr/bin/rsyslog_plugin -r /etc/rsyslog.d/{{ proc.parse_json }} -m {{ yang_module }}" output="/var/log/rsyslog_plugin.log" + signalOnClose="on" template="prog_msg") } {% endfor %} diff --git a/src/sonic-eventd/rsyslog_plugin/rsyslog_plugin.cpp b/src/sonic-eventd/rsyslog_plugin/rsyslog_plugin.cpp index 6df0a73b0210..52a70fd182ae 100644 --- a/src/sonic-eventd/rsyslog_plugin/rsyslog_plugin.cpp +++ b/src/sonic-eventd/rsyslog_plugin/rsyslog_plugin.cpp @@ -9,6 +9,8 @@ using json = nlohmann::json; +bool RsyslogPlugin::g_running; + bool RsyslogPlugin::onMessage(string msg, lua_State* luaState) { string tag; event_params_t paramDict; @@ -30,18 +32,18 @@ void parseParams(vector params, vector& eventParams) { if(params[i].empty()) { SWSS_LOG_ERROR("Empty param provided in regex file\n"); continue; - } + } EventParam ep = EventParam(); auto delimPos = params[i].find(':'); if(delimPos == string::npos) { // no lua code ep.paramName = params[i]; } else { ep.paramName = params[i].substr(0, delimPos); - ep.luaCode = params[i].substr(delimPos + 1); + ep.luaCode = params[i].substr(delimPos + 1); if(ep.luaCode.empty()) { SWSS_LOG_ERROR("Lua code missing after :\n"); } - } + } eventParams.push_back(ep); } } @@ -71,11 +73,11 @@ bool RsyslogPlugin::createRegexList() { vector eventParams; try { string eventRegex = jsonList[i]["regex"]; - regexString = timestampRegex + eventRegex; + regexString = timestampRegex + eventRegex; string tag = jsonList[i]["tag"]; vector params = jsonList[i]["params"]; - vector timestampParams = { "month", "day", "time" }; - params.insert(params.begin(), timestampParams.begin(), timestampParams.end()); + vector timestampParams = { "month", "day", "time" }; + params.insert(params.begin(), timestampParams.begin(), timestampParams.end()); regex expr(regexString); expression = expr; parseParams(params, eventParams); @@ -83,13 +85,13 @@ bool RsyslogPlugin::createRegexList() { rs.tag = tag; rs.regexExpression = expression; regexList.push_back(rs); - } catch (nlohmann::detail::type_error& deException) { + } catch (nlohmann::detail::type_error& deException) { SWSS_LOG_ERROR("Missing required key, throws exception: %s\n", deException.what()); return false; } catch (regex_error& reException) { SWSS_LOG_ERROR("Invalid regex, throws exception: %s\n", reException.what()); - return false; - } + return false; + } } if(regexList.empty()) { @@ -104,11 +106,11 @@ bool RsyslogPlugin::createRegexList() { } void RsyslogPlugin::run() { + signal(SIGTERM, RsyslogPlugin::signalHandler); lua_State* luaState = luaL_newstate(); luaL_openlibs(luaState); - while(true) { - string line; - getline(cin, line); + string line; + while(RsyslogPlugin::g_running && getline(cin, line)) { if(line.empty()) { continue; } @@ -132,4 +134,5 @@ RsyslogPlugin::RsyslogPlugin(string moduleName, string regexPath) { m_parser = unique_ptr(new SyslogParser()); m_moduleName = moduleName; m_regexPath = regexPath; + RsyslogPlugin::g_running = true; } diff --git a/src/sonic-eventd/rsyslog_plugin/rsyslog_plugin.h b/src/sonic-eventd/rsyslog_plugin/rsyslog_plugin.h index 0811b5f3032f..ae6c9baf9630 100644 --- a/src/sonic-eventd/rsyslog_plugin/rsyslog_plugin.h +++ b/src/sonic-eventd/rsyslog_plugin/rsyslog_plugin.h @@ -9,6 +9,7 @@ extern "C" } #include #include +#include #include "syslog_parser.h" #include "events.h" #include "logger.h" @@ -24,10 +25,17 @@ using namespace swss; class RsyslogPlugin { public: + static bool g_running; int onInit(); bool onMessage(string msg, lua_State* luaState); void run(); RsyslogPlugin(string moduleName, string regexPath); + static void signalHandler(int signum) { + if (signum == SIGTERM) { + SWSS_LOG_INFO("Rsyslog plugin received SIGTERM, shutting down"); + RsyslogPlugin::g_running = false; + } + } private: unique_ptr m_parser; event_handle_t m_eventHandle; diff --git a/src/sonic-eventd/rsyslog_plugin_tests/rsyslog_plugin_ut.cpp b/src/sonic-eventd/rsyslog_plugin_tests/rsyslog_plugin_ut.cpp index 5ff41d11dd70..aafd357006eb 100644 --- a/src/sonic-eventd/rsyslog_plugin_tests/rsyslog_plugin_ut.cpp +++ b/src/sonic-eventd/rsyslog_plugin_tests/rsyslog_plugin_ut.cpp @@ -8,6 +8,7 @@ extern "C" #include #include #include +#include #include "gtest/gtest.h" #include #include "events.h" @@ -253,6 +254,31 @@ TEST(rsyslog_plugin, onMessage_noParams) { infile.close(); } +TEST(rsyslog_plugin, run) { + unique_ptr plugin(new RsyslogPlugin("test_mod_name", "./rsyslog_plugin_tests/test_regex_5.rc.json")); + EXPECT_EQ(0, plugin->onInit()); + istringstream ss(""); + streambuf* cinbuf = cin.rdbuf(); + cin.rdbuf(ss.rdbuf()); + plugin->run(); + cin.rdbuf(cinbuf); +} + +TEST(rsyslog_plugin, run_SIGTERM) { + unique_ptr plugin(new RsyslogPlugin("test_mod_name", "./rsyslog_plugin_tests/test_regex_5.rc.json")); + EXPECT_EQ(0, plugin->onInit()); + EXPECT_TRUE(RsyslogPlugin::g_running); + thread pluginThread([&]() { + plugin->run(); + }); + + RsyslogPlugin::signalHandler(SIGTERM); + + pluginThread.join(); + + EXPECT_FALSE(RsyslogPlugin::g_running); +} + TEST(timestampFormatter, changeTimestampFormat) { unique_ptr formatter(new TimestampFormatter());