[eventd]: Close rsyslog plugin when rsyslog SIGTERM and EOF is sent t…

…o stream (sonic-net#18835)

Fix sonic-net#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

@@ -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 %}

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<string> params, vector<EventParam>& 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,25 +73,25 @@ bool RsyslogPlugin::createRegexList() {
         vector<EventParam> eventParams;
         try {
             string eventRegex = jsonList[i]["regex"];
-	    regexString = timestampRegex + eventRegex;
+            regexString = timestampRegex + eventRegex;
             string tag = jsonList[i]["tag"];
             vector<string> params = jsonList[i]["params"];
-	    vector<string> timestampParams = { "month", "day", "time" };
-	    params.insert(params.begin(), timestampParams.begin(), timestampParams.end());
+            vector<string> timestampParams = { "month", "day", "time" };
+            params.insert(params.begin(), timestampParams.begin(), timestampParams.end());
             regex expr(regexString);
             expression = expr;
             parseParams(params, eventParams);
             rs.params = eventParams;
             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<SyslogParser>(new SyslogParser());
     m_moduleName = moduleName;
     m_regexPath = regexPath;
+    RsyslogPlugin::g_running = true;
 }

src/sonic-eventd/rsyslog_plugin/rsyslog_plugin.h

@@ -9,6 +9,7 @@ extern "C"
 }
 #include <string>
 #include <memory>
+#include <csignal>
 #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<SyslogParser> m_parser;
     event_handle_t m_eventHandle;

src/sonic-eventd/rsyslog_plugin_tests/rsyslog_plugin_ut.cpp

@@ -8,6 +8,7 @@ extern "C"
 #include <fstream>
 #include <memory>
 #include <regex>
+#include <thread>
 #include "gtest/gtest.h"
 #include <nlohmann/json.hpp>
 #include "events.h"
@@ -253,6 +254,31 @@ TEST(rsyslog_plugin, onMessage_noParams) {
     infile.close();
 }
 
+TEST(rsyslog_plugin, run) {
+    unique_ptr<RsyslogPlugin> 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<RsyslogPlugin> 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<TimestampFormatter> formatter(new TimestampFormatter());