Enhance swss-common logging by writing a warning log when a command fails due to Redis loading the dataset. (#986)

Enhance swss-common logging by writing a warning log when a command fails due to Redis loading the dataset.

Why I did it
Fix issue sonic-net/sonic-buildimage#17472
sonic-db-cli write error log, this is because sonic-db-cli execute PING command when Redis is loading dataset.

How I did it
When command failed because Redis is loading dataset, write warning log instead of error log.

Description for the changelog
Enhance swss-common logging by writing a warning log when a command fails due to Redis loading the dataset.

Author: liuh-80

common/redisreply.cpp

@@ -4,7 +4,6 @@
 #include <vector>
 #include <iostream>
 #include <sstream>
-#include <system_error>
 #include <functional>
 #include <boost/algorithm/string.hpp>
 
@@ -60,22 +59,6 @@ static set<string> g_strToBoolCommands = {
                         "SET"
                         };
 
-template <typename FUNC>
-inline void guard(FUNC func, const char* command)
-{
-    try
-    {
-        func();
-    }
-    catch (const system_error& ex)
-    {
-        // Combine more error message and throw again
-        string errmsg = "RedisReply catches system_error: command: " + string(command) + ", reason: " + ex.what();
-        SWSS_LOG_ERROR("%s", errmsg.c_str());
-        throw system_error(ex.code(), errmsg.c_str());
-    }
-}
-
 RedisReply::RedisReply(RedisContext *ctx, const RedisCommand& command)
 {
     int rc = command.appendTo(ctx->getContext());

common/redisreply.h

@@ -4,6 +4,8 @@
 #include <hiredis/hiredis.h>
 #include <string>
 #include <stdexcept>
+#include <system_error>
+#include "logger.h"
 #include "rediscommand.h"
 
 namespace swss {
@@ -114,5 +116,31 @@ class RedisReply
     redisReply *m_reply;
 };
 
+template <typename FUNC>
+inline void guard(FUNC func, const char* command)
+{
+    try
+    {
+        func();
+    }
+    catch (const std::system_error& ex)
+    {
+        // Combine more error message and throw again
+        std::string reason = ex.what();
+        std::string errmsg = "RedisReply catches system_error: command: " + std::string(command) + ", reason: " + reason;
+        // C++ does not have a startswith function. To ensure the search begins at the start of the string 'reason', pass pos = 0
+        if (reason.rfind("LOADING ", 0) == 0)
+        {
+            // The command will fail when Redis is loading the dataset.
+            SWSS_LOG_WARN("%s", errmsg.c_str());
+        }
+        else
+        {
+            SWSS_LOG_ERROR("%s", errmsg.c_str());
+        }
+        throw std::system_error(ex.code(), errmsg.c_str());
+    }
+}
+
 }
 #endif

tests/redis_ut.cpp

@@ -3,15 +3,16 @@
 #include <thread>
 #include <algorithm>
 #include <deque>
-#include <gmock/gmock.h>
 #include <system_error>
+#include <gmock/gmock.h>
 #include "gtest/gtest.h"
 #include "common/dbconnector.h"
 #include "common/producertable.h"
 #include "common/consumertable.h"
 #include "common/notificationconsumer.h"
 #include "common/notificationproducer.h"
 #include "common/redisclient.h"
+#include "common/redisreply.h"
 #include "common/select.h"
 #include "common/selectableevent.h"
 #include "common/selectabletimer.h"
@@ -1171,3 +1172,32 @@ TEST(Connector, connectFail)
         }
     }, std::system_error);
 }
+
+TEST(Redisreply, guard)
+{
+    // Improve test coverage for guard() method.
+    string command = "test";
+    EXPECT_THROW({
+        try
+        {
+            guard([&]{throw system_error(make_error_code(errc::io_error), "LOADING Redis is loading the dataset in memory");}, command.c_str());
+        }
+        catch(const std::system_error& e)
+        {
+            EXPECT_THAT(e.what(), HasSubstr("LOADING Redis is loading the dataset in memory"));
+            throw;
+        }
+    }, std::system_error);
+
+    EXPECT_THROW({
+        try
+        {
+            guard([&]{throw system_error(make_error_code(errc::io_error), "Command failed");}, command.c_str());
+        }
+        catch(const std::system_error& e)
+        {
+            EXPECT_THAT(e.what(), HasSubstr("Command failed"));
+            throw;
+        }
+    }, std::system_error);
+}

tests/test_redis_loading.py

@@ -0,0 +1,74 @@
+import os
+import time
+from swsscommon import swsscommon
+
+TEST_TIMEOUT = 10
+REDIS_RECORD_COUNT = 2000000
+
+
+def wait_redis_ready():
+    end_time = time.time() + TEST_TIMEOUT
+    while time.time() < end_time:
+        result = os.popen(r'redis-cli ping').read()
+        if "PONG" in result:
+            break
+        time.sleep(1)
+
+
+def generate_redis_dump():
+    print("generate redis dump")
+    # generate a large redis dataset to reproduce LOADING exception
+    db = swsscommon.SonicV2Connector(use_unix_socket_path=True)
+    db.connect("TEST_DB")
+    id = REDIS_RECORD_COUNT
+    while id > 0:
+        id -= 1
+        db.set("TEST_DB", "record:{}".format(id), "field", "value{}".format(id))
+
+    # create dump file
+    os.popen(r"redis-cli save")
+
+
+def test_redis_loading_exception(capfd):
+    """ Test write warning message to syslog when redis is loading data.
+    The redis loading data exception is difficult to reproduce, it's only happen when redis service starting and loading massive data.
+    This test will create one million data dump and restart redis server, however on fast device the test will failed.
+    Currently the test can pass on developer's devbox.
+    So this test only report error message when test failed, please developer run this test manually to verify this scenario.
+    """
+
+    # cleanup redis data
+    os.popen(r"redis-cli FLUSHALL")
+
+    generate_redis_dump()
+
+    print("restart redis service")
+    os.popen(r"sudo service redis-server restart")
+
+    # write swss log to stderr, so capfd can capture it
+    swsscommon.Logger.swssOutputNotify("", "STDERR")
+    swsscommon.Logger.setMinPrio(swsscommon.Logger.SWSS_NOTICE)
+
+    end_time = time.time() + TEST_TIMEOUT
+    loading_exception = False
+    while time.time() < end_time:
+        try:
+            db = swsscommon.DBConnector("CONFIG_DB", 0, True)
+            db.keys("test")
+        except Exception as e:
+            error = "{}".format(e)
+            if "LOADING" in error:
+                break
+
+    # wait for redis load dataset finish
+    wait_redis_ready()
+
+    # cleanup test data
+    os.popen(r"redis-cli FLUSHALL")
+    os.popen(r"redis-cli save")
+
+    captured_log = capfd.readouterr().err
+    expected = 'WARN:- guard: RedisReply catches system_error: command: *2\\r\\n$4\\r\\nKEYS\\r\\n$4\\r\\ntest\\r\\n, reason: LOADING Redis is loading the dataset in memory'
+    if expected not in captured_log:
+        print("Test redis loading data exception failed, could not find expected warning message from swsscommon syslog: {}".format(expected))
+