From bf6ed6a704408e6ef09864e93f5ed7e790523dd6 Mon Sep 17 00:00:00 2001 From: junchao Date: Tue, 16 Aug 2022 09:52:52 +0800 Subject: [PATCH 1/3] Add test case for syslog rate limit feature Change-Id: I11f29fa1a2265e2ba8c9a4ea4bac6ed2a0bb5a25 --- tests/syslog/log_generator.py | 15 ++ tests/syslog/test_syslog_rate_limit.py | 217 +++++++++++++++++++++++++ 2 files changed, 232 insertions(+) create mode 100644 tests/syslog/log_generator.py create mode 100644 tests/syslog/test_syslog_rate_limit.py diff --git a/tests/syslog/log_generator.py b/tests/syslog/log_generator.py new file mode 100644 index 00000000000..c00a7f4a6af --- /dev/null +++ b/tests/syslog/log_generator.py @@ -0,0 +1,15 @@ +import time +from sonic_py_common.logger import Logger + +logger = Logger(log_identifier="rate-limit-test") +logger.set_min_log_priority_info() + +begin = 1 +end = 101 + +while begin <= end: + logger.log_info('This is a test log: {}'.format(begin)) + begin += 1 + +# Let log flush to file +time.sleep(2) diff --git a/tests/syslog/test_syslog_rate_limit.py b/tests/syslog/test_syslog_rate_limit.py new file mode 100644 index 00000000000..f1ca79ba251 --- /dev/null +++ b/tests/syslog/test_syslog_rate_limit.py @@ -0,0 +1,217 @@ +import logging +import os +import pytest +import random + +from tests.common.config_reload import config_reload +from tests.common.utilities import skip_release +from tests.common.helpers.assertions import pytest_assert +from tests.common.plugins.loganalyzer.loganalyzer import LogAnalyzer +from tests.common.helpers.sonic_db import SonicDbCli + +logger = logging.getLogger(__name__) + +RATE_LIMIT_BURST = 100 +RATE_LIMIT_INTERVAL = 10 +# Generate 101 packets in tests/syslog/log_generator.py, so that 1 log message will be dropped by rsyslogd +LOG_MESSAGE_GENERATE_COUNT = 101 +BASE_DIR = os.path.dirname(os.path.abspath(__file__)) +LOCAL_LOG_GENERATOR_FILE = os.path.join(BASE_DIR, 'log_generator.py') +REMOTE_LOG_GENERATOR_FILE = os.path.join('/tmp', 'log_generator.py') +DOCKER_LOG_GENERATOR_FILE = '/log_generator.py' +# rsyslogd prints this log when rate-limiting reached +LOG_EXPECT_SYSLOG_RATE_LIMIT_REACHED = '.*begin to drop messages due to rate-limiting.*' +# Log pattern for tests/syslog/log_generator.py +LOG_EXPECT_LAST_MESSAGE = '.*{}rate-limit-test: This is a test log:.*' + +pytestmark = [ + pytest.mark.topology("any") +] + + +@pytest.fixture(autouse=True, scope="module") +def check_image_version(rand_selected_dut): + """Skips this test if the SONiC image installed on DUT is older than 202205 + + Args: + duthost: Hostname of DUT. + + Returns: + None. + """ + skip_release(rand_selected_dut, ["201811", "201911", "202012", "202106", "202205"]) + + +@pytest.fixture(autouse=True, scope="module") +def restore_rate_limit(rand_selected_dut): + """Fixture to automatically restore syslog rate limit configuration + + Args: + rand_selected_dut (object): DUT host object + """ + container_data = rand_selected_dut.show_and_parse('show syslog rate-limit-container') + host_data = rand_selected_dut.show_and_parse('show syslog rate-limit-host') + + yield + + for item in container_data: + rand_selected_dut.command('config syslog rate-limit-container {} -b {} -i {}'.format(item['service'], item['burst'], item['interval'])) + + rand_selected_dut.command('config syslog rate-limit-host -b {} -i {}'.format(host_data[0]['burst'], host_data[0]['interval'])) + rand_selected_dut.command('config save -y') + + +def test_syslog_rate_limit(rand_selected_dut): + """Test case for syslog rate limit + + Args: + rand_selected_dut (object): DUT host object + """ + # Copy tests/syslog/log_generator.py to DUT + rand_selected_dut.copy(src=LOCAL_LOG_GENERATOR_FILE, dest=REMOTE_LOG_GENERATOR_FILE) + + verify_container_rate_limit(rand_selected_dut) + verify_host_rate_limit(rand_selected_dut) + + # Save configuration and reload, verify the configuration can be loaded + logger.info('Persist syslog rate limit configuration to DB and do config reload') + rand_selected_dut.command('config save -y') + config_reload(rand_selected_dut) + + # database does not support syslog rate limit configuration persist + verify_container_rate_limit(rand_selected_dut, ignore_containers=['database']) + verify_host_rate_limit(rand_selected_dut) + + +def verify_container_rate_limit(rand_selected_dut, ignore_containers=[]): + """Config syslog rate limit for each container and verify it works. Basic flow: + 1. For each container + 2. Filter disabled container + 3. Filter un-supported container + 4. Config syslog rate limit + 5. Verify syslog rate limit with "show syslog rate-limit-container" command + 6. Generate syslog via a script and verify the rate limit configuration works + 7. Disable syslog rate limit by setting interval and burst to 0 + 8. Verify syslog rate limit with "show syslog rate-limit-container" command + 9. Generate syslog via a script and verify there is no rate limit anymore + + Args: + rand_selected_dut (object): DUT host object + ignore_containers (list): container list that will be ignored for this test + """ + config_db = SonicDbCli(rand_selected_dut, 'CONFIG_DB') + feature_data = rand_selected_dut.show_and_parse('show feature status') + random.shuffle(feature_data) + for item in feature_data: + service_name = item['feature'] + if service_name in ignore_containers: + continue + + logger.info('Start syslog rate limit test for container {}'.format(service_name)) + if item['state'] in ['disabled', 'always_disabled']: + logger.info('Container {} is {}'.format(service_name, item['state'])) + verify_config_rate_limit_fail(rand_selected_dut, service_name) + continue + + support_syslog_rate_limit = config_db.hget_key_value('FEATURE|{}'.format(service_name), 'support_syslog_rate_limit') + if support_syslog_rate_limit.lower() != 'true': + logger.info('Container {} does not support syslog rate limit configuration'.format(service_name)) + verify_config_rate_limit_fail(rand_selected_dut, service_name) + continue + + rand_selected_dut.command('config syslog rate-limit-container {} -b {} -i {}'.format(service_name, RATE_LIMIT_BURST, RATE_LIMIT_INTERVAL)) + rate_limit_data = rand_selected_dut.show_and_parse('show syslog rate-limit-container {}'.format(service_name)) + pytest_assert(rate_limit_data[0]['interval'] == str(RATE_LIMIT_INTERVAL), 'Expect rate limit interval {}, actual {}'.format(RATE_LIMIT_INTERVAL, rate_limit_data[0]['interval'])) + pytest_assert(rate_limit_data[0]['burst'] == str(RATE_LIMIT_BURST), 'Expect rate limit burst {}, actual {}'.format(RATE_LIMIT_BURST, rate_limit_data[0]['burst'])) + + rand_selected_dut.command('docker cp {} {}:{}'.format(REMOTE_LOG_GENERATOR_FILE, service_name, DOCKER_LOG_GENERATOR_FILE)) + verify_rate_limit_with_log_generator(rand_selected_dut, + service_name, + 'syslog_rate_limit_{}-interval_{}_burst_{}'.format(service_name, RATE_LIMIT_INTERVAL, RATE_LIMIT_BURST), + [LOG_EXPECT_SYSLOG_RATE_LIMIT_REACHED, LOG_EXPECT_LAST_MESSAGE.format(service_name + '#')], + RATE_LIMIT_BURST + 1) + + rand_selected_dut.command('config syslog rate-limit-container {} -b {} -i {}'.format(service_name, 0, 0)) + rate_limit_data = rand_selected_dut.show_and_parse('show syslog rate-limit-container {}'.format(service_name)) + pytest_assert(rate_limit_data[0]['interval'] == '0', 'Expect rate limit interval {}, actual {}'.format(0, rate_limit_data[0]['interval'])) + pytest_assert(rate_limit_data[0]['burst'] == '0', 'Expect rate limit burst {}, actual {}'.format(0, rate_limit_data[0]['burst'])) + + verify_rate_limit_with_log_generator(rand_selected_dut, + service_name, + 'syslog_rate_limit_{}-interval_{}_burst_{}'.format(service_name, 0, 0), + [LOG_EXPECT_LAST_MESSAGE.format(service_name + '#')], + LOG_MESSAGE_GENERATE_COUNT) + break # we only randomly test 1 container to reduce test time + + +def verify_host_rate_limit(rand_selected_dut): + """Config syslog rate limit for host and verify it works. Basic flow: + 1. Config syslog rate limit + 2. Verify syslog rate limit with "show syslog rate-limit-host" command + 3. Generate syslog via a script and verify the rate limit configuration works + 4. Disable syslog rate limit by setting interval and burst to 0 + 5. Verify syslog rate limit with "show syslog rate-limit-host" command + 6. Generate syslog via a script and verify there is no rate limit anymore + + Args: + rand_selected_dut (object): DUT host object + """ + logger.info('Start syslog rate limit test for host') + rand_selected_dut.command('config syslog rate-limit-host -b {} -i {}'.format(RATE_LIMIT_BURST, RATE_LIMIT_INTERVAL)) + rate_limit_data = rand_selected_dut.show_and_parse('show syslog rate-limit-host') + pytest_assert(rate_limit_data[0]['interval'] == str(RATE_LIMIT_INTERVAL), 'Expect rate limit interval {}, actual {}'.format(RATE_LIMIT_INTERVAL, rate_limit_data[0]['interval'])) + pytest_assert(rate_limit_data[0]['burst'] == str(RATE_LIMIT_BURST), 'Expect rate limit burst {}, actual {}'.format(RATE_LIMIT_BURST, rate_limit_data[0]['burst'])) + + verify_rate_limit_with_log_generator(rand_selected_dut, + 'host', + 'syslog_rate_limit_host_interval_{}_burst_{}'.format(RATE_LIMIT_INTERVAL, RATE_LIMIT_BURST), + [LOG_EXPECT_SYSLOG_RATE_LIMIT_REACHED, LOG_EXPECT_LAST_MESSAGE.format('')], + RATE_LIMIT_BURST + 1, + is_host=True) + + rand_selected_dut.command('config syslog rate-limit-host -b {} -i {}'.format(0, 0)) + rate_limit_data = rand_selected_dut.show_and_parse('show syslog rate-limit-host') + pytest_assert(rate_limit_data[0]['interval'] == '0', 'Expect rate limit interval {}, actual {}'.format(0, rate_limit_data[0]['interval'])) + pytest_assert(rate_limit_data[0]['burst'] == '0', 'Expect rate limit burst {}, actual {}'.format(0, rate_limit_data[0]['burst'])) + + verify_rate_limit_with_log_generator(rand_selected_dut, + 'host', + 'syslog_rate_limit_host_interval_{}_burst_{}'.format(0, 0), + [LOG_EXPECT_LAST_MESSAGE.format('')], + LOG_MESSAGE_GENERATE_COUNT, + is_host=True) + + +def verify_config_rate_limit_fail(duthost, service_name): + """For service that does not support rate limit configuration, verify that config rate limit fails + + Args: + duthost (object): DUT object + service_name (str): Service name + """ + output = duthost.command('config syslog rate-limit-container {} -b {} -i {}'.format(service_name, RATE_LIMIT_BURST, RATE_LIMIT_INTERVAL), module_ignore_errors=True)['stderr'] + pytest_assert('Error' in output, 'Error: config syslog rate limit for {}: {}'.format(service_name, output)) + + +def verify_rate_limit_with_log_generator(duthost, service_name, log_marker, expect_log_regex, expect_log_matches, is_host=False): + """Generator syslog with a script and verify that syslog rate limit reached + + Args: + duthost (object): DUT host object + service_name (str): Service name + log_marker (str): Log start marker + expect_log_regex (list): A list of expected log message regular expression + expect_log_matches (int): Number of log lines matches the expect_log_regex + is_host (bool, optional): Verify on host side or container side. Defaults to False. + """ + loganalyzer = LogAnalyzer(ansible_host=duthost, marker_prefix=log_marker) + loganalyzer.expect_regex = expect_log_regex + loganalyzer.expected_matches_target = expect_log_matches + + if is_host: + run_generator_cmd = "python3 {}".format(REMOTE_LOG_GENERATOR_FILE) + else: + run_generator_cmd = "docker exec -i {} bash -c 'python3 {}'".format(service_name, DOCKER_LOG_GENERATOR_FILE) + + with loganalyzer: + duthost.command(run_generator_cmd) From b8e21f38bbf4d33b689c8b49e56477315acecd81 Mon Sep 17 00:00:00 2001 From: junchao Date: Wed, 26 Oct 2022 16:01:34 +0800 Subject: [PATCH 2/3] Fix format issue Change-Id: Ic9ed9183f8838b240c6b7f5a4b39aefa1133507b --- tests/syslog/test_syslog_rate_limit.py | 92 ++++++++++++++++---------- 1 file changed, 57 insertions(+), 35 deletions(-) diff --git a/tests/syslog/test_syslog_rate_limit.py b/tests/syslog/test_syslog_rate_limit.py index f1ca79ba251..f272f7fd551 100644 --- a/tests/syslog/test_syslog_rate_limit.py +++ b/tests/syslog/test_syslog_rate_limit.py @@ -55,9 +55,11 @@ def restore_rate_limit(rand_selected_dut): yield for item in container_data: - rand_selected_dut.command('config syslog rate-limit-container {} -b {} -i {}'.format(item['service'], item['burst'], item['interval'])) + rand_selected_dut.command('config syslog rate-limit-container {} -b {} -i {}'.format( + item['service'], item['burst'], item['interval'])) - rand_selected_dut.command('config syslog rate-limit-host -b {} -i {}'.format(host_data[0]['burst'], host_data[0]['interval'])) + rand_selected_dut.command('config syslog rate-limit-host -b {} -i {}'.format( + host_data[0]['burst'], host_data[0]['interval'])) rand_selected_dut.command('config save -y') @@ -113,35 +115,46 @@ def verify_container_rate_limit(rand_selected_dut, ignore_containers=[]): verify_config_rate_limit_fail(rand_selected_dut, service_name) continue - support_syslog_rate_limit = config_db.hget_key_value('FEATURE|{}'.format(service_name), 'support_syslog_rate_limit') + support_syslog_rate_limit = config_db.hget_key_value('FEATURE|{}'.format(service_name), + 'support_syslog_rate_limit') if support_syslog_rate_limit.lower() != 'true': logger.info('Container {} does not support syslog rate limit configuration'.format(service_name)) verify_config_rate_limit_fail(rand_selected_dut, service_name) continue - rand_selected_dut.command('config syslog rate-limit-container {} -b {} -i {}'.format(service_name, RATE_LIMIT_BURST, RATE_LIMIT_INTERVAL)) + rand_selected_dut.command('config syslog rate-limit-container {} -b {} -i {}'.format( + service_name, RATE_LIMIT_BURST, RATE_LIMIT_INTERVAL)) rate_limit_data = rand_selected_dut.show_and_parse('show syslog rate-limit-container {}'.format(service_name)) - pytest_assert(rate_limit_data[0]['interval'] == str(RATE_LIMIT_INTERVAL), 'Expect rate limit interval {}, actual {}'.format(RATE_LIMIT_INTERVAL, rate_limit_data[0]['interval'])) - pytest_assert(rate_limit_data[0]['burst'] == str(RATE_LIMIT_BURST), 'Expect rate limit burst {}, actual {}'.format(RATE_LIMIT_BURST, rate_limit_data[0]['burst'])) - - rand_selected_dut.command('docker cp {} {}:{}'.format(REMOTE_LOG_GENERATOR_FILE, service_name, DOCKER_LOG_GENERATOR_FILE)) + pytest_assert(rate_limit_data[0]['interval'] == str(RATE_LIMIT_INTERVAL), + 'Expect rate limit interval {}, actual {}'.format(RATE_LIMIT_INTERVAL, + rate_limit_data[0]['interval'])) + pytest_assert(rate_limit_data[0]['burst'] == str(RATE_LIMIT_BURST), + 'Expect rate limit burst {}, actual {}'.format(RATE_LIMIT_BURST, rate_limit_data[0]['burst'])) + + rand_selected_dut.command( + 'docker cp {} {}:{}'.format(REMOTE_LOG_GENERATOR_FILE, service_name, DOCKER_LOG_GENERATOR_FILE)) verify_rate_limit_with_log_generator(rand_selected_dut, - service_name, - 'syslog_rate_limit_{}-interval_{}_burst_{}'.format(service_name, RATE_LIMIT_INTERVAL, RATE_LIMIT_BURST), - [LOG_EXPECT_SYSLOG_RATE_LIMIT_REACHED, LOG_EXPECT_LAST_MESSAGE.format(service_name + '#')], - RATE_LIMIT_BURST + 1) + service_name, + 'syslog_rate_limit_{}-interval_{}_burst_{}'.format(service_name, + RATE_LIMIT_INTERVAL, + RATE_LIMIT_BURST), + [LOG_EXPECT_SYSLOG_RATE_LIMIT_REACHED, + LOG_EXPECT_LAST_MESSAGE.format(service_name + '#')], + RATE_LIMIT_BURST + 1) rand_selected_dut.command('config syslog rate-limit-container {} -b {} -i {}'.format(service_name, 0, 0)) rate_limit_data = rand_selected_dut.show_and_parse('show syslog rate-limit-container {}'.format(service_name)) - pytest_assert(rate_limit_data[0]['interval'] == '0', 'Expect rate limit interval {}, actual {}'.format(0, rate_limit_data[0]['interval'])) - pytest_assert(rate_limit_data[0]['burst'] == '0', 'Expect rate limit burst {}, actual {}'.format(0, rate_limit_data[0]['burst'])) + pytest_assert(rate_limit_data[0]['interval'] == '0', + 'Expect rate limit interval {}, actual {}'.format(0, rate_limit_data[0]['interval'])) + pytest_assert(rate_limit_data[0]['burst'] == '0', + 'Expect rate limit burst {}, actual {}'.format(0, rate_limit_data[0]['burst'])) verify_rate_limit_with_log_generator(rand_selected_dut, - service_name, - 'syslog_rate_limit_{}-interval_{}_burst_{}'.format(service_name, 0, 0), - [LOG_EXPECT_LAST_MESSAGE.format(service_name + '#')], - LOG_MESSAGE_GENERATE_COUNT) - break # we only randomly test 1 container to reduce test time + service_name, + 'syslog_rate_limit_{}-interval_{}_burst_{}'.format(service_name, 0, 0), + [LOG_EXPECT_LAST_MESSAGE.format(service_name + '#')], + LOG_MESSAGE_GENERATE_COUNT) + break # we only randomly test 1 container to reduce test time def verify_host_rate_limit(rand_selected_dut): @@ -159,27 +172,33 @@ def verify_host_rate_limit(rand_selected_dut): logger.info('Start syslog rate limit test for host') rand_selected_dut.command('config syslog rate-limit-host -b {} -i {}'.format(RATE_LIMIT_BURST, RATE_LIMIT_INTERVAL)) rate_limit_data = rand_selected_dut.show_and_parse('show syslog rate-limit-host') - pytest_assert(rate_limit_data[0]['interval'] == str(RATE_LIMIT_INTERVAL), 'Expect rate limit interval {}, actual {}'.format(RATE_LIMIT_INTERVAL, rate_limit_data[0]['interval'])) - pytest_assert(rate_limit_data[0]['burst'] == str(RATE_LIMIT_BURST), 'Expect rate limit burst {}, actual {}'.format(RATE_LIMIT_BURST, rate_limit_data[0]['burst'])) + pytest_assert(rate_limit_data[0]['interval'] == str(RATE_LIMIT_INTERVAL), + 'Expect rate limit interval {}, actual {}'.format(RATE_LIMIT_INTERVAL, + rate_limit_data[0]['interval'])) + pytest_assert(rate_limit_data[0]['burst'] == str(RATE_LIMIT_BURST), + 'Expect rate limit burst {}, actual {}'.format(RATE_LIMIT_BURST, rate_limit_data[0]['burst'])) verify_rate_limit_with_log_generator(rand_selected_dut, - 'host', - 'syslog_rate_limit_host_interval_{}_burst_{}'.format(RATE_LIMIT_INTERVAL, RATE_LIMIT_BURST), - [LOG_EXPECT_SYSLOG_RATE_LIMIT_REACHED, LOG_EXPECT_LAST_MESSAGE.format('')], - RATE_LIMIT_BURST + 1, - is_host=True) + 'host', + 'syslog_rate_limit_host_interval_{}_burst_{}'.format(RATE_LIMIT_INTERVAL, + RATE_LIMIT_BURST), + [LOG_EXPECT_SYSLOG_RATE_LIMIT_REACHED, LOG_EXPECT_LAST_MESSAGE.format('')], + RATE_LIMIT_BURST + 1, + is_host=True) rand_selected_dut.command('config syslog rate-limit-host -b {} -i {}'.format(0, 0)) rate_limit_data = rand_selected_dut.show_and_parse('show syslog rate-limit-host') - pytest_assert(rate_limit_data[0]['interval'] == '0', 'Expect rate limit interval {}, actual {}'.format(0, rate_limit_data[0]['interval'])) - pytest_assert(rate_limit_data[0]['burst'] == '0', 'Expect rate limit burst {}, actual {}'.format(0, rate_limit_data[0]['burst'])) + pytest_assert(rate_limit_data[0]['interval'] == '0', + 'Expect rate limit interval {}, actual {}'.format(0, rate_limit_data[0]['interval'])) + pytest_assert(rate_limit_data[0]['burst'] == '0', + 'Expect rate limit burst {}, actual {}'.format(0, rate_limit_data[0]['burst'])) verify_rate_limit_with_log_generator(rand_selected_dut, - 'host', - 'syslog_rate_limit_host_interval_{}_burst_{}'.format(0, 0), - [LOG_EXPECT_LAST_MESSAGE.format('')], - LOG_MESSAGE_GENERATE_COUNT, - is_host=True) + 'host', + 'syslog_rate_limit_host_interval_{}_burst_{}'.format(0, 0), + [LOG_EXPECT_LAST_MESSAGE.format('')], + LOG_MESSAGE_GENERATE_COUNT, + is_host=True) def verify_config_rate_limit_fail(duthost, service_name): @@ -189,11 +208,14 @@ def verify_config_rate_limit_fail(duthost, service_name): duthost (object): DUT object service_name (str): Service name """ - output = duthost.command('config syslog rate-limit-container {} -b {} -i {}'.format(service_name, RATE_LIMIT_BURST, RATE_LIMIT_INTERVAL), module_ignore_errors=True)['stderr'] + cmd = 'config syslog rate-limit-container {} -b {} -i {}'.format( + service_name, RATE_LIMIT_BURST, RATE_LIMIT_INTERVAL) + output = duthost.command(cmd, module_ignore_errors=True)['stderr'] pytest_assert('Error' in output, 'Error: config syslog rate limit for {}: {}'.format(service_name, output)) -def verify_rate_limit_with_log_generator(duthost, service_name, log_marker, expect_log_regex, expect_log_matches, is_host=False): +def verify_rate_limit_with_log_generator(duthost, service_name, log_marker, expect_log_regex, expect_log_matches, + is_host=False): """Generator syslog with a script and verify that syslog rate limit reached Args: From e03b0cc9169a99ef247757f848ad3d76406a4e24 Mon Sep 17 00:00:00 2001 From: junchao Date: Tue, 20 Dec 2022 11:32:08 +0800 Subject: [PATCH 3/3] Fix issue caused by latest review comment Change-Id: I6c99fb62ac1482283278615b12b1cd02a807b5a9 --- tests/syslog/test_syslog_rate_limit.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/syslog/test_syslog_rate_limit.py b/tests/syslog/test_syslog_rate_limit.py index f272f7fd551..853e1be443f 100644 --- a/tests/syslog/test_syslog_rate_limit.py +++ b/tests/syslog/test_syslog_rate_limit.py @@ -112,7 +112,6 @@ def verify_container_rate_limit(rand_selected_dut, ignore_containers=[]): logger.info('Start syslog rate limit test for container {}'.format(service_name)) if item['state'] in ['disabled', 'always_disabled']: logger.info('Container {} is {}'.format(service_name, item['state'])) - verify_config_rate_limit_fail(rand_selected_dut, service_name) continue support_syslog_rate_limit = config_db.hget_key_value('FEATURE|{}'.format(service_name),