From 228d59a576dc836a070e0269b97b48da6b2f032d Mon Sep 17 00:00:00 2001 From: Yuriy Volynets Date: Thu, 1 Aug 2019 18:44:57 +0300 Subject: [PATCH 1/8] Added loganalyzer for pytest. Updated existed loganalyzer. --- ansible/library/extract_log.py | 8 +- .../files/tools/loganalyzer/loganalyzer.py | 68 +++--- .../loganalyzer/loganalyzer_common_match.txt | 4 +- tests/conftest.py | 18 ++ tests/loganalyzer/README.md | 90 ++++++++ tests/loganalyzer/__init__.py | 0 tests/loganalyzer/loganalyzer.py | 193 ++++++++++++++++++ .../loganalyzer/loganalyzer_common_expect.txt | 1 + .../loganalyzer/loganalyzer_common_ignore.txt | 1 + .../loganalyzer/loganalyzer_common_match.txt | 1 + tests/loganalyzer/system_msg_handler.py | 1 + 11 files changed, 355 insertions(+), 30 deletions(-) create mode 100755 tests/loganalyzer/README.md create mode 100755 tests/loganalyzer/__init__.py create mode 100755 tests/loganalyzer/loganalyzer.py create mode 120000 tests/loganalyzer/loganalyzer_common_expect.txt create mode 120000 tests/loganalyzer/loganalyzer_common_ignore.txt create mode 120000 tests/loganalyzer/loganalyzer_common_match.txt create mode 120000 tests/loganalyzer/system_msg_handler.py diff --git a/ansible/library/extract_log.py b/ansible/library/extract_log.py index 032771ef51f..9cf8c1cf5ea 100644 --- a/ansible/library/extract_log.py +++ b/ansible/library/extract_log.py @@ -80,8 +80,6 @@ from datetime import datetime from ansible.module_utils.basic import * -from pprint import pprint - def extract_lines(directory, filename, target_string): path = os.path.join(directory, filename) @@ -100,6 +98,7 @@ def extract_lines(directory, filename, target_string): return result + def extract_number(s): """Extracts number from string, if not number found returns 0""" ns = re.findall(r'\d+', s) @@ -112,6 +111,10 @@ def extract_number(s): def convert_date(s): dt = None re_result = re.findall(r'^\S{3}\s{1,2}\d{1,2} \d{2}:\d{2}:\d{2}\.?\d*', s) + # Workaround for pytest-ansible + loc = locale.getlocale() + locale.setlocale(locale.LC_ALL, (None, None)) + if len(re_result) > 0: str_date = re_result[0] try: @@ -122,6 +125,7 @@ def convert_date(s): re_result = re.findall(r'^\d{4}-\d{2}-\d{2}\.\d{2}:\d{2}:\d{2}\.\d{6}', s) str_date = re_result[0] dt = datetime.strptime(str_date, '%Y-%m-%d.%X.%f') + locale.setlocale(locale.LC_ALL, loc) return dt diff --git a/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py b/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py index 8875e874b47..ebbed02ea8f 100644 --- a/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py +++ b/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py @@ -32,7 +32,7 @@ comment_key = '#' system_log_file = '/var/log/syslog' -#-- List of ERROR codes to be returned by LogAnalyzer +#-- List of ERROR codes to be returned by AnsibleLogAnalyzer err_duplicate_start_marker = -1 err_duplicate_end_marker = -2 err_no_end_marker = -3 @@ -40,7 +40,7 @@ err_invalid_string_format = -5 err_invalid_input = -6 -class LogAnalyzer: +class AnsibleLogAnalyzer: ''' @summary: Overview of functionality @@ -52,10 +52,10 @@ class LogAnalyzer: AND will not match set of 'ignore' regex expressions, will be considered a 'match' and will be reported. - LogAnalyzer will be called initially before any test has ran, and will be + AnsibleLogAnalyzer will be called initially before any test has ran, and will be instructed to place 'start' marker into all log files to be analyzed. - When tests have ran, LogAnalyzer will be instructed to place end-marker - into the log files. After this, LogAnalyzer will be invoked to perform the + When tests have ran, AnsibleLogAnalyzer will be instructed to place end-marker + into the log files. After this, AnsibleLogAnalyzer will be invoked to perform the analysis of logs. The analysis will be performed on specified log files. For each log file only the content between start/end markers will be analyzed. @@ -105,25 +105,41 @@ def create_end_marker(self): return self.end_marker_prefix + "-" + self.run_id #--------------------------------------------------------------------- - def place_marker(self, log_file_list, marker): + def place_marker_to_file(self, log_file, marker): ''' @summary: Place marker into each log file specified. + @param log_file : File path, to be applied with marker. + @param marker: Marker to be placed into log files. + ''' + if not len(log_file) or self.is_filename_stdin(log_file): + self.print_diagnostic_message('Log file {} not found. Skip adding marker.'.format(log_file)) + self.print_diagnostic_message('log file:{}, place marker {}'.format(log_file, marker)) + with open(log_file, 'a') as file: + file.write(marker) + file.write('\n') + file.flush() + + def place_marker_to_syslog(self, marker): + ''' + @summary: Place marker into '/dev/log'. + @param marker: Marker to be placed into syslog. + ''' + + syslogger = self.init_sys_logger() + syslogger.info(marker) + syslogger.info('\n') + + def place_marker(self, log_file_list, marker): + ''' + @summary: Place marker into '/dev/log' and each log file specified. @param log_file_list : List of file paths, to be applied with marker. @param marker: Marker to be placed into log files. ''' for log_file in log_file_list: - if not len(log_file) or self.is_filename_stdin(log_file): - continue - self.print_diagnostic_message('log file:%s, place marker %s'%(log_file, marker)) - with open(log_file, 'a') as file: - file.write(marker) - file.write('\n') - file.flush() + self.place_marker_to_file(log_file, marker) - syslogger = self.init_sys_logger() - syslogger.info(marker) - syslogger.info('\n') + self.place_marker_to_syslog(marker) return #--------------------------------------------------------------------- @@ -183,6 +199,7 @@ def create_msg_regex(self, file_lsit): skipinitialspace=True) for index, row in enumerate(csvreader): + row = [item for item in row if item != ""] self.print_diagnostic_message('[diagnostic]:processing row:%d' % index) self.print_diagnostic_message('row:%s'% row) try: @@ -202,13 +219,10 @@ def create_msg_regex(self, file_lsit): 'must be \'s\'(string) or \'r\'(regex)' %(filename,index)) - #-- One error message per line - error_string = row[1] - if (is_regex): - messages_regex.append(error_string) + messages_regex.extend(row[1:]) else: - messages_regex.append(self.error_to_regx(error_string)) + messages_regex.append(self.error_to_regx(row[1:])) except Exception as e: print 'ERROR: line %d is formatted incorrectly in file %s. Skipping line' % (index, filename) @@ -426,6 +440,8 @@ def check_action(action, log_files_in, out_dir, match_files_in, ignore_files_in, if (action == 'init'): ret_code = True + elif (action == 'add_end_marker'): + ret_code = True elif (action == 'analyze'): if out_dir is None or len(out_dir) == 0: print 'ERROR: missing required out_dir for analyze action' @@ -500,12 +516,10 @@ def write_result_file(run_id, out_dir, analysis_result_per_file, messages_regex_ out_file.write('Total matches:%d\n' % match_cnt) # Find unused regex matches for regex in messages_regex_e: - regex_used = False for line in expected_lines_total: if re.search(regex, line): - regex_used = True break - if not regex_used: + else: unused_regex_messages.append(regex) out_file.write('Total expected and found matches:%d\n' % expected_cnt) @@ -515,7 +529,6 @@ def write_result_file(run_id, out_dir, analysis_result_per_file, messages_regex_ out_file.write("\n-------------------------------------------------\n\n") out_file.flush() - #--------------------------------------------------------------------- def write_summary_file(run_id, out_dir, analysis_result_per_file, unused_regex_messages): @@ -607,7 +620,7 @@ def main(argv): usage() sys.exit(err_invalid_input) - analyzer = LogAnalyzer(run_id, verbose) + analyzer = AnsibleLogAnalyzer(run_id, verbose) log_file_list = filter(None, log_files_in.split(tokenizer)) @@ -635,6 +648,9 @@ def main(argv): unused_regex_messages = [] write_result_file(run_id, out_dir, result, messages_regex_e, unused_regex_messages) write_summary_file(run_id, out_dir, result, unused_regex_messages) + elif (action == "add_end_marker"): + analyzer.place_marker(log_file_list, analyzer.create_end_marker()) + return 0 else: print 'Unknown action:%s specified' % action diff --git a/ansible/roles/test/files/tools/loganalyzer/loganalyzer_common_match.txt b/ansible/roles/test/files/tools/loganalyzer/loganalyzer_common_match.txt index d17c702965f..23c2870e4a9 100644 --- a/ansible/roles/test/files/tools/loganalyzer/loganalyzer_common_match.txt +++ b/ansible/roles/test/files/tools/loganalyzer/loganalyzer_common_match.txt @@ -1,6 +1,6 @@ r, "\.ERR", "\.WARN", "crash" r, "kernel:.*Oops", "kernel:.*hung", "kernel.*oom\s" r, "kernel:.*scheduling", "kernel:.*atomic", "kernel:.*panic" -r, "kernel:.*\serr", "kernel:.*allocation", "kernel:.*kill", -r, "kernel:.*kmemleak.*","kernel:.* Err:" +r, "kernel:.*\serr", "kernel:.*allocation", "kernel:.*kill" +r, "kernel:.*kmemleak.*", "kernel:.* Err:" s, "ERR" diff --git a/tests/conftest.py b/tests/conftest.py index e5380c840a6..4436a6c6fca 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -3,6 +3,7 @@ import yaml import ipaddr as ipaddress +from loganalyzer.loganalyzer import LogAnalyzer from ansible_host import AnsibleHost @@ -45,6 +46,7 @@ def __init__(self, testbed_file): def pytest_addoption(parser): parser.addoption("--testbed", action="store", default=None, help="testbed name") parser.addoption("--testbed_file", action="store", default=None, help="testbed file name") + parser.addoption("--disable_loganalyzer", action="store_true", default=False, help="disable loganalyzer analysis for 'loganalyzer' fixture") @pytest.fixture(scope="session") @@ -87,3 +89,19 @@ def eos(): with open('eos/eos.yml') as stream: eos = yaml.safe_load(stream) return eos + +@pytest.fixture(autouse=True) +def loganalyzer(duthost, request): + loganalyzer = LogAnalyzer(ansible_host=duthost, marker_prefix=request.node.name) + # Add start marker into DUT syslog + marker = loganalyzer.init() + yield loganalyzer + if not request.config.getoption("--disable_loganalyzer") and "disable_loganalyzer" not in request.keywords: + # Read existed common regular expressions located with legacy loganalyzer module + loganalyzer.load_common_config() + # Parse syslog and process result. Raise "LogAnalyzerError" exception if: total match or expected missing match is not equal to zero + loganalyzer.analyze(marker) + else: + # Add end marker into DUT syslog + loganalyzer._add_end_marker(marker) + diff --git a/tests/loganalyzer/README.md b/tests/loganalyzer/README.md new file mode 100755 index 00000000000..4f1e1d3d967 --- /dev/null +++ b/tests/loganalyzer/README.md @@ -0,0 +1,90 @@ +#### Loganalyzer API usage example + +Below is described possibility of loganalyzer fixture/module usage. + +##### Loganalyzer fixture +In the root conftest there is implemented "loganalyzer" pytest fixture, which starts automatically for all test cases. +Fixture main flow: +- loganalyzer will add start marker before test case start +- loganalyzer will add stop marker after test case finish +- if loganalyzer analysis is not disabled for current test case it will analyze DUT syslog and display results. +If loganalyzer find specified messages which corresponds to defined regular expressions, it will display found messages and pytest will generate 'error'. + +##### To skip loganalyzer analysis for: +- all test cases - use pytest command line option ```--disable_loganalyzer``` +- specific test case: mark test case with ```@disable_loganalyzer``` decorator. Example is shown below. + +```python +import pytest +import time +import os +import sys +import logging + +from ansible_host import ansible_host +sys.path.append(os.path.join(os.path.split(__file__)[0], "loganalyzer")) +from loganalyzer.loganalyzer import LogAnalyzer +from loganalyzer.loganalyzer import COMMON_MATCH +from lib.helpers import disable_loganalyzer + + +def adder(x, y=10, z=0): + """ + Syslog on the DUT will be verified during this callback execution. Expected that this callback will do some stuff on the DUT side. + """ + return x + y + +def test_loganalyzer_functionality(localhost, ansible_adhoc, testbed): + """ + @summary: Example of loganalyzer usage + """ + hostname = testbed['dut'] + ans_host = ansible_host(ansible_adhoc, hostname) + + log = LogAnalyzer(ansible_host=ans_host, marker_prefix="test_loganalyzer") + # Read existed common regular expressions located with legacy loganalyzer module + log.load_common_config() + # Add start marker to the DUT syslog + marker = log.init() + # Emulate that new error messages appears in the syslog + time.sleep(1) + ans_host.command("echo '---------- ERR: text 1 error --------------' >> /var/log/syslog") + ans_host.command("echo '---------- THRESHOLD_CLEAR test1 xyz test2 --------------' >> /var/log/syslog") + time.sleep(2) + ans_host.command("echo '---------- kernel: says Oops --------------' >> /var/log/syslog") + + # Perform syslog analysis based on added messages + result = log.analyze(marker) + if not result: + pytest.fail("Log analyzer failed.") + assert result["total"]["match"] == 2, "Found errors: {}".format(result) + # Download extracted syslog file from DUT to the local host + log.save_extracted_log(dest="/tmp/log/syslog") + + # Example: update previously configured marker + # Now start marker will have new prefix + log.update_marker_prefix("test_bgp") + + # Execute function and analyze logs during function execution + # Return tuple of (FUNCTION_RESULT, LOGANALYZER_RESULT) + run_cmd_result = log.run_cmd(adder, 5, y=5, z=11) + + # Clear current regexp match list + log.match_regex = [] + # Load regular expressions from the specified file + reg_exp = log.parse_regexp_file(src=COMMON_MATCH) + # Extend existed match regular expresiions with previously read + log.match_regex.extend(reg_exp) + + # Verify that new regular expressions are found by log analyzer. Again add new error message to the syslog. + marker = log.init() + ans_host.command("echo '---------- kernel: says Oops --------------' >> /var/log/syslog") + result = log.analyze(marker) + if not result: + pytest.fail("Log analyzer failed.") + assert result["total"]["match"] == 1, "Found errors: {}".format(result) + +@disable_loganalyzer +def test_skipped_test(localhost, ansible_adhoc, testbed): + pass +``` diff --git a/tests/loganalyzer/__init__.py b/tests/loganalyzer/__init__.py new file mode 100755 index 00000000000..e69de29bb2d diff --git a/tests/loganalyzer/loganalyzer.py b/tests/loganalyzer/loganalyzer.py new file mode 100755 index 00000000000..02e605cc146 --- /dev/null +++ b/tests/loganalyzer/loganalyzer.py @@ -0,0 +1,193 @@ +import sys +import logging +import os +import re + +import time +from os.path import join, split +from os.path import normpath + +import system_msg_handler +ANSIBLE_LOGANALYZER_MODULE = system_msg_handler.__file__.replace(r".pyc", ".py") + +from system_msg_handler import AnsibleLogAnalyzer as ansible_loganalyzer +COMMON_MATCH = join(split(__file__)[0], "loganalyzer_common_match.txt") +COMMON_IGNORE = join(split(__file__)[0], "loganalyzer_common_ignore.txt") +COMMON_EXPECT = join(split(__file__)[0], "loganalyzer_common_expect.txt") +SYSLOG_TMP_FOLDER = "/tmp/pytest-run/syslog" + + +class LogAnalyzer: + def __init__(self, ansible_host, marker_prefix, dut_run_dir="/tmp"): + self.ansible_host = ansible_host + self.dut_run_dir = dut_run_dir + self.extracted_syslog = os.path.join(self.dut_run_dir, "syslog") + self.marker_prefix = marker_prefix + self.ansible_loganalyzer = ansible_loganalyzer(self.marker_prefix, False) + + self.match_regex = [] + self.expect_regex = [] + self.ignore_regex = [] + + def _add_end_marker(self, marker): + """ + @summary: Add stop marker into syslog on the DUT. + + @return: True for successfull execution False otherwise + """ + self.ansible_host.copy(src=ANSIBLE_LOGANALYZER_MODULE, dest=os.path.join(self.dut_run_dir, "loganalyzer.py")) + + cmd = "python {run_dir}/loganalyzer.py --action add_end_marker --run_id {marker}".format(run_dir=self.dut_run_dir, marker=marker) + + logging.debug("Adding end marker '{}'".format(marker)) + self.ansible_host.command(cmd) + + def update_marker_prefix(self, marker_prefix): + """ + @summary: Update configured marker prefix + """ + self.marker_prefix = marker_prefix + + def load_common_config(self): + """ + @summary: Load regular expressions from common files, which are localted in folder with legacy loganalyzer. + Loaded regular expressions are used by "analyze" method to match expected text in the downloaded log file. + """ + self.match_regex = self.ansible_loganalyzer.create_msg_regex([COMMON_MATCH])[1] + self.ignore_regex = self.ansible_loganalyzer.create_msg_regex([COMMON_IGNORE])[1] + self.expect_regex = self.ansible_loganalyzer.create_msg_regex([COMMON_EXPECT])[1] + + def parse_regexp_file(self, src): + """ + @summary: Get regular expressions defined in src file. + """ + return self.ansible_loganalyzer.create_msg_regex([src])[1] + + def run_cmd(self, callback, *args, **kwargs): + """ + @summary: Initialize loganalyzer, execute function and analyze syslog. + + @param callback: Python callable or function to be executed. + @param args: Input arguments for callback function. + @param kwargs: Input arguments for callback function. + + @return: Tuple of two items: (callback(*args, **kwargs) -> VALUE, self.analyze() -> dict) + """ + marker = self.init() + try: + call_result = callback(*args, **kwargs) + except Exception as err: + logging.error("Error during callback execution:\n{}".format(err)) + logging.debug("Log alaysis result\n".format(self.analyze())) + raise err + analysis_result = self.analyze(marker) + return call_result, analysis_result + + def init(self): + """ + @summary: Add start marker into syslog on the DUT. + + @return: True for successfull execution False otherwise + """ + logging.debug("Loganalyzer init") + + self.ansible_host.copy(src=ANSIBLE_LOGANALYZER_MODULE, dest=os.path.join(self.dut_run_dir, "loganalyzer.py")) + + start_marker = ".".join((self.marker_prefix, time.strftime("%Y-%m-%d-%H:%M:%S", time.gmtime()))) + cmd = "python {run_dir}/loganalyzer.py --action init --run_id {start_marker}".format(run_dir=self.dut_run_dir, start_marker=start_marker) + + logging.debug("Adding start marker '{}'".format(start_marker)) + self.ansible_host.command(cmd) + return start_marker + + def analyze(self, marker): + """ + @summary: Extract syslog logs based on the start/stop markers and compose one file. Download composed file, analyze file based on defined regular expressions. + + @return: For successfull analysis phase return filled in analyzer_summary dictionary. Otherwise return empty dictionary - {}. + """ + logging.debug("Loganalyzer analyze") + analyzer_summary = {"total": {"match": 0, "expected_match": 0, "expected_missing_match": 0}, + "match_files": {}, + "match_messages": {}, + "expect_messages": {}, + "unused_expected_regexp": [] + } + tmp_folder = ".".join((SYSLOG_TMP_FOLDER, time.strftime("%Y-%m-%d-%H:%M:%S", time.gmtime()))) + self.ansible_loganalyzer.run_id = marker + + # Add end marker into DUT syslog + self._add_end_marker(marker) + + try: + # Disable logrotate cron task + self.ansible_host.command("sed -i 's/^/#/g' /etc/cron.d/logrotate") + + logging.debug("Waiting for logrotate from previous cron task run to finish") + # Wait for logrotate from previous cron task run to finish + end = time.time() + 60 + while time.time() < end: + # Verify for exception because self.ansible_host automatically handle command return codes and raise exception for none zero code + try: + self.ansible_host.command("pgrep -f logrotate") + except Exception: + break + else: + time.sleep(5) + continue + else: + logging.error("Logrotate from previous task was not finished during 60 seconds") + + # On DUT extract syslog files from /var/log/ and create one file by location - /tmp/syslog + self.ansible_host.extract_log(directory='/var/log', file_prefix='syslog', start_string='start-LogAnalyzer-{}'.format(marker), target_filename=self.extracted_syslog) + finally: + # Enable logrotate cron task back + self.ansible_host.command("sed -i 's/^#//g' /etc/cron.d/logrotate") + + # Download extracted logs from the DUT to the temporal folder defined in SYSLOG_TMP_FOLDER + self.ansible_host.fetch(dest=tmp_folder, src=self.extracted_syslog, flat="yes") + + match_messages_regex = re.compile('|'.join(self.match_regex)) if len(self.match_regex) else None + ignore_messages_regex = re.compile('|'.join(self.ignore_regex)) if len(self.ignore_regex) else None + expect_messages_regex = re.compile('|'.join(self.expect_regex)) if len(self.expect_regex) else None + + analyzer_parse_result = self.ansible_loganalyzer.analyze_file_list([tmp_folder], match_messages_regex, ignore_messages_regex, expect_messages_regex) + # Print syslog file content and remove the file + with open(tmp_folder) as fo: + logging.debug("Syslog content:\n\n{}".format(fo.read())) + os.remove(tmp_folder) + + total_match_cnt = 0 + total_expect_cnt = 0 + expected_lines_total = [] + unused_regex_messages = [] + + for key, value in analyzer_parse_result.iteritems(): + matching_lines, expecting_lines = value + analyzer_summary["total"]["match"] += len(matching_lines) + analyzer_summary["total"]["expected_match"] += len(expecting_lines) + analyzer_summary["match_files"][key] = {"match": len(matching_lines), "expected_match": len(expecting_lines)} + analyzer_summary["match_messages"][key] = matching_lines + analyzer_summary["expect_messages"][key] = expecting_lines + expected_lines_total.extend(expecting_lines) + + # Find unused regex matches + for regex in self.expect_regex: + for line in expected_lines_total: + if re.search(regex, line): + break + else: + unused_regex_messages.append(regex) + analyzer_summary["total"]["expected_missing_match"] = len(unused_regex_messages) + analyzer_summary["unused_expected_regexp"] = unused_regex_messages + + return analyzer_summary + + def save_extracted_log(self, dest): + """ + @summary: Download extracted syslog log file to the ansible host. + + @param dest: File path to store downloaded log file. + """ + self.ansible_host.fetch(dest=dest, src=self.extracted_syslog, flat="yes") + diff --git a/tests/loganalyzer/loganalyzer_common_expect.txt b/tests/loganalyzer/loganalyzer_common_expect.txt new file mode 120000 index 00000000000..2ae3246b088 --- /dev/null +++ b/tests/loganalyzer/loganalyzer_common_expect.txt @@ -0,0 +1 @@ +../../ansible/roles/test/files/tools/loganalyzer/loganalyzer_common_expect.txt \ No newline at end of file diff --git a/tests/loganalyzer/loganalyzer_common_ignore.txt b/tests/loganalyzer/loganalyzer_common_ignore.txt new file mode 120000 index 00000000000..ad2643fb427 --- /dev/null +++ b/tests/loganalyzer/loganalyzer_common_ignore.txt @@ -0,0 +1 @@ +../../ansible/roles/test/files/tools/loganalyzer/loganalyzer_common_ignore.txt \ No newline at end of file diff --git a/tests/loganalyzer/loganalyzer_common_match.txt b/tests/loganalyzer/loganalyzer_common_match.txt new file mode 120000 index 00000000000..1f865571b62 --- /dev/null +++ b/tests/loganalyzer/loganalyzer_common_match.txt @@ -0,0 +1 @@ +../../ansible/roles/test/files/tools/loganalyzer/loganalyzer_common_match.txt \ No newline at end of file diff --git a/tests/loganalyzer/system_msg_handler.py b/tests/loganalyzer/system_msg_handler.py new file mode 120000 index 00000000000..4fd54f816fc --- /dev/null +++ b/tests/loganalyzer/system_msg_handler.py @@ -0,0 +1 @@ +../../ansible/roles/test/files/tools/loganalyzer/loganalyzer.py \ No newline at end of file From ec6f5388d4b1ffb562155996b26ca3833e5bd411 Mon Sep 17 00:00:00 2001 From: Yuriy Volynets Date: Thu, 1 Aug 2019 18:44:57 +0300 Subject: [PATCH 2/8] Added loganalyzer for pytest. Updated existed loganalyzer. --- tests/lib/__init__.py | 0 tests/lib/helpers.py | 15 +++++++++++++++ 2 files changed, 15 insertions(+) create mode 100755 tests/lib/__init__.py create mode 100755 tests/lib/helpers.py diff --git a/tests/lib/__init__.py b/tests/lib/__init__.py new file mode 100755 index 00000000000..e69de29bb2d diff --git a/tests/lib/helpers.py b/tests/lib/helpers.py new file mode 100755 index 00000000000..ede8e48817e --- /dev/null +++ b/tests/lib/helpers.py @@ -0,0 +1,15 @@ +import pytest +import logging +import decorator + +def disable_loganalyzer(func): + """ + Decorator to disable loganalyzer analysis after test case execution + """ + def wrapper(func, *args, **kwargs): + logging.debug("Disabling loganalyzer...") + try: + func(*args, **kwargs) + finally: + pytest.disable_loganalyzer = True + return decorator.decorator(wrapper, func) From 8d9dd99d4445077acf377ebe2a3ee577c12282be Mon Sep 17 00:00:00 2001 From: Yuriy Volynets Date: Wed, 7 Aug 2019 18:23:38 +0300 Subject: [PATCH 3/8] Added fixes based on comments --- tests/conftest.py | 3 +- tests/lib/__init__.py | 0 tests/lib/helpers.py | 15 -------- tests/loganalyzer/__init__.py | 1 + tests/loganalyzer/loganalyzer.py | 65 +++++++++++++++++++++++++------- 5 files changed, 54 insertions(+), 30 deletions(-) delete mode 100755 tests/lib/__init__.py delete mode 100755 tests/lib/helpers.py diff --git a/tests/conftest.py b/tests/conftest.py index 4436a6c6fca..4f0f3bffb64 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -3,9 +3,8 @@ import yaml import ipaddr as ipaddress -from loganalyzer.loganalyzer import LogAnalyzer from ansible_host import AnsibleHost - +from loganalyzer import LogAnalyzer pytest_plugins = ('ptf_fixtures', 'ansible_fixtures') diff --git a/tests/lib/__init__.py b/tests/lib/__init__.py deleted file mode 100755 index e69de29bb2d..00000000000 diff --git a/tests/lib/helpers.py b/tests/lib/helpers.py deleted file mode 100755 index ede8e48817e..00000000000 --- a/tests/lib/helpers.py +++ /dev/null @@ -1,15 +0,0 @@ -import pytest -import logging -import decorator - -def disable_loganalyzer(func): - """ - Decorator to disable loganalyzer analysis after test case execution - """ - def wrapper(func, *args, **kwargs): - logging.debug("Disabling loganalyzer...") - try: - func(*args, **kwargs) - finally: - pytest.disable_loganalyzer = True - return decorator.decorator(wrapper, func) diff --git a/tests/loganalyzer/__init__.py b/tests/loganalyzer/__init__.py index e69de29bb2d..e32a3567489 100755 --- a/tests/loganalyzer/__init__.py +++ b/tests/loganalyzer/__init__.py @@ -0,0 +1 @@ +from .loganalyzer import LogAnalyzer, COMMON_MATCH, COMMON_IGNORE, COMMON_EXPECT, LogAnalyzerError diff --git a/tests/loganalyzer/loganalyzer.py b/tests/loganalyzer/loganalyzer.py index 02e605cc146..058387a60bb 100755 --- a/tests/loganalyzer/loganalyzer.py +++ b/tests/loganalyzer/loganalyzer.py @@ -2,21 +2,27 @@ import logging import os import re - import time +import pprint +import system_msg_handler + +from system_msg_handler import AnsibleLogAnalyzer as ansible_loganalyzer from os.path import join, split from os.path import normpath -import system_msg_handler ANSIBLE_LOGANALYZER_MODULE = system_msg_handler.__file__.replace(r".pyc", ".py") - -from system_msg_handler import AnsibleLogAnalyzer as ansible_loganalyzer COMMON_MATCH = join(split(__file__)[0], "loganalyzer_common_match.txt") COMMON_IGNORE = join(split(__file__)[0], "loganalyzer_common_ignore.txt") COMMON_EXPECT = join(split(__file__)[0], "loganalyzer_common_expect.txt") SYSLOG_TMP_FOLDER = "/tmp/pytest-run/syslog" +class LogAnalyzerError(Exception): + """Raised when loganalyzer found matches during analysis phase.""" + def __repr__(self): + return pprint.pformat(self.message) + + class LogAnalyzer: def __init__(self, ansible_host, marker_prefix, dut_run_dir="/tmp"): self.ansible_host = ansible_host @@ -28,6 +34,7 @@ def __init__(self, ansible_host, marker_prefix, dut_run_dir="/tmp"): self.match_regex = [] self.expect_regex = [] self.ignore_regex = [] + self._markers = [] def _add_end_marker(self, marker): """ @@ -42,6 +49,32 @@ def _add_end_marker(self, marker): logging.debug("Adding end marker '{}'".format(marker)) self.ansible_host.command(cmd) + def __enter__(self): + """ + Store start markers which are used in analyze phase. + """ + self._markers.append(self.init()) + + def __exit__(self, *args): + """ + Analyze syslog messages. + """ + self.analyze(self._markers.pop()) + + def _verify_log(self, result): + """ + Verify that total match and expected missing match equals to zero or raise exception otherwise. + Verify that expected_match is not equal to zero when there is configured expected regexp in self.expect_regex list + """ + if not result: + raise LogAnalyzerError("Log analyzer failed - no result.") + if result["total"]["match"] != 0 or result["total"]["expected_missing_match"] != 0: + raise LogAnalyzerError(result) + + # Check for negative case + if self.expect_regex and result["total"]["expected_match"] == 0: + raise LogAnalyzerError(result) + def update_marker_prefix(self, marker_prefix): """ @summary: Update configured marker prefix @@ -69,19 +102,20 @@ def run_cmd(self, callback, *args, **kwargs): @param callback: Python callable or function to be executed. @param args: Input arguments for callback function. - @param kwargs: Input arguments for callback function. + @param kwargs: Input key value arguments for callback function. - @return: Tuple of two items: (callback(*args, **kwargs) -> VALUE, self.analyze() -> dict) + @return: Callback execution result """ marker = self.init() try: call_result = callback(*args, **kwargs) except Exception as err: logging.error("Error during callback execution:\n{}".format(err)) - logging.debug("Log alaysis result\n".format(self.analyze())) + logging.debug("Log analysis result\n".format(self.analyze(marker))) raise err - analysis_result = self.analyze(marker) - return call_result, analysis_result + self.analyze(marker) + + return call_result def init(self): """ @@ -100,11 +134,14 @@ def init(self): self.ansible_host.command(cmd) return start_marker - def analyze(self, marker): + def analyze(self, marker, fail=True): """ @summary: Extract syslog logs based on the start/stop markers and compose one file. Download composed file, analyze file based on defined regular expressions. - @return: For successfull analysis phase return filled in analyzer_summary dictionary. Otherwise return empty dictionary - {}. + @param marker: Marker obtained from "init" method. + @param fail: Flag to enable/disable raising exception when loganalyzer find error messages. + + @return: If "fail" is False - return dictionary of parsed syslog summary, if dictionary can't be parsed - return empty dictionary. If "fail" is True and if found match messages - raise exception. """ logging.debug("Loganalyzer analyze") analyzer_summary = {"total": {"match": 0, "expected_match": 0, "expected_missing_match": 0}, @@ -181,7 +218,10 @@ def analyze(self, marker): analyzer_summary["total"]["expected_missing_match"] = len(unused_regex_messages) analyzer_summary["unused_expected_regexp"] = unused_regex_messages - return analyzer_summary + if fail: + self._verify_log(analyzer_summary) + else: + return analyzer_summary def save_extracted_log(self, dest): """ @@ -190,4 +230,3 @@ def save_extracted_log(self, dest): @param dest: File path to store downloaded log file. """ self.ansible_host.fetch(dest=dest, src=self.extracted_syslog, flat="yes") - From 0055f38b2ce27805e65ef7e7fad750da2e27aede Mon Sep 17 00:00:00 2001 From: yvolynets-mlnx <50697593+yvolynets-mlnx@users.noreply.github.com> Date: Wed, 7 Aug 2019 19:17:52 +0300 Subject: [PATCH 4/8] Update README.md --- tests/loganalyzer/README.md | 181 +++++++++++++++++++++++------------- 1 file changed, 114 insertions(+), 67 deletions(-) diff --git a/tests/loganalyzer/README.md b/tests/loganalyzer/README.md index 4f1e1d3d967..81d6409e4b8 100755 --- a/tests/loganalyzer/README.md +++ b/tests/loganalyzer/README.md @@ -10,81 +10,128 @@ Fixture main flow: - if loganalyzer analysis is not disabled for current test case it will analyze DUT syslog and display results. If loganalyzer find specified messages which corresponds to defined regular expressions, it will display found messages and pytest will generate 'error'. -##### To skip loganalyzer analysis for: +#### To skip loganalyzer analysis for: - all test cases - use pytest command line option ```--disable_loganalyzer``` -- specific test case: mark test case with ```@disable_loganalyzer``` decorator. Example is shown below. +- specific test case: mark test case with ```@pytest.mark.disable_loganalyzer``` decorator. Example is shown below. + +#### Notes: +loganalyzer.init() - can be called several times without calling "loganalyzer.analyze(marker)" between calls. Each call return its unique marker, which is used for "analyze" phase - loganalyzer.analyze(marker). + + +### Loganalyzer usage example + +#### Example calling loganalyzer init/analyze methods automatically by using with statement ```python -import pytest -import time -import os -import sys -import logging - -from ansible_host import ansible_host -sys.path.append(os.path.join(os.path.split(__file__)[0], "loganalyzer")) -from loganalyzer.loganalyzer import LogAnalyzer -from loganalyzer.loganalyzer import COMMON_MATCH -from lib.helpers import disable_loganalyzer - - -def adder(x, y=10, z=0): - """ - Syslog on the DUT will be verified during this callback execution. Expected that this callback will do some stuff on the DUT side. - """ - return x + y - -def test_loganalyzer_functionality(localhost, ansible_adhoc, testbed): - """ - @summary: Example of loganalyzer usage - """ - hostname = testbed['dut'] - ans_host = ansible_host(ansible_adhoc, hostname) - - log = LogAnalyzer(ansible_host=ans_host, marker_prefix="test_loganalyzer") # Read existed common regular expressions located with legacy loganalyzer module - log.load_common_config() + loganalyzer.load_common_config() + # Analyze syslog for code executed inside with statement + with loganalyzer as analyzer: + logging.debug("============== Test steps ===================") + # Add test code here ... + time.sleep(1) + + # Separately analyze syslog for code executed inside each with statement + with loganalyzer as analyzer: + # Clear current regexp match list if there is a need to have clear configuration + loganalyzer.match_regex = [] + # Load regular expressions from the specified file + reg_exp = loganalyzer.parse_regexp_file(src=COMMON_MATCH) + # Extend currently configured match criteria (regular expressions) with data read from "COMMON_MATCH" file + loganalyzer.match_regex.extend(reg_exp) + # Add test code here ... + # Here will be executed syslog analysis on context manager __exit__ + time.sleep(1) + with loganalyzer as analyzer: + # Clear current regexp match list if there is a need to have clear configuration + loganalyzer.match_regex = [] + # Set match criteria (regular expression) to custom regexp - "test:.*Error" + loganalyzer.match_regex.extend(["test:.*Error"]) + # Add test code here ... + # Here will be executed syslog analysis on context manager __exit__ + time.sleep(1) + with loganalyzer as analyzer: + # Add test code here ... + # Here will be executed syslog analysis on context manager __exit__ + time.sleep(1) +``` + +#### Example calling loganalyzer init/analyze methods directly in test case + # Example 1 + # Read existed common regular expressions located with legacy loganalyzer module + loganalyzer.load_common_config() + # Add start marker to the DUT syslog + marker = loganalyzer.init() + # PERFORM TEST CASE STEPS ... + # Verify that error messages were not found in DUT syslog. Exception will be raised if in DUT syslog will be found messages which fits regexp defined in COMMON_MATCH + loganalyzer.analyze(marker) + + # Example 2 + # Read existed common regular expressions located with legacy loganalyzer module + loganalyzer.load_common_config() # Add start marker to the DUT syslog - marker = log.init() - # Emulate that new error messages appears in the syslog - time.sleep(1) - ans_host.command("echo '---------- ERR: text 1 error --------------' >> /var/log/syslog") - ans_host.command("echo '---------- THRESHOLD_CLEAR test1 xyz test2 --------------' >> /var/log/syslog") - time.sleep(2) - ans_host.command("echo '---------- kernel: says Oops --------------' >> /var/log/syslog") - - # Perform syslog analysis based on added messages - result = log.analyze(marker) - if not result: - pytest.fail("Log analyzer failed.") - assert result["total"]["match"] == 2, "Found errors: {}".format(result) + marker = loganalyzer.init() + # PERFORM TEST CASE STEPS ... + # Get summary of analyzed DUT syslog + result = loganalyzer.analyze(marker, fail=False) + # Verify that specific amount of error messages found in syslog # Negative test case + assert result["total"]["match"] == 2, "Not found expected errors: {}".format(result) + + # Example 3 # Download extracted syslog file from DUT to the local host - log.save_extracted_log(dest="/tmp/log/syslog") + loganalyzer.save_extracted_log(dest="/tmp/log/syslog") - # Example: update previously configured marker - # Now start marker will have new prefix - log.update_marker_prefix("test_bgp") + # Example 4 + # Update previously configured marker + # Now start marker will have new prefix - test_bgp + loganalyzer.update_marker_prefix("test_bgp") - # Execute function and analyze logs during function execution - # Return tuple of (FUNCTION_RESULT, LOGANALYZER_RESULT) - run_cmd_result = log.run_cmd(adder, 5, y=5, z=11) + def get_platform_info(dut): + """ + Example callback which gets DUT platform information and returns obtained string + """ + return dut.command("show platform summary") + # Example 5 + # Execute specific function and analyze logs during function execution + run_cmd_result = loganalyzer.run_cmd(get_platform_info, ans_host) + # Process result of "get_platform_info" callback + assert all(item in run_cmd_result["stdout"] for item in ["Platform", "HwSKU", "ASIC"]) is True, "Unexpected output returned after command execution: {}".format(run_cmd_result) + + # Example 6 # Clear current regexp match list - log.match_regex = [] - # Load regular expressions from the specified file - reg_exp = log.parse_regexp_file(src=COMMON_MATCH) - # Extend existed match regular expresiions with previously read - log.match_regex.extend(reg_exp) - - # Verify that new regular expressions are found by log analyzer. Again add new error message to the syslog. - marker = log.init() - ans_host.command("echo '---------- kernel: says Oops --------------' >> /var/log/syslog") - result = log.analyze(marker) - if not result: - pytest.fail("Log analyzer failed.") - assert result["total"]["match"] == 1, "Found errors: {}".format(result) - -@disable_loganalyzer -def test_skipped_test(localhost, ansible_adhoc, testbed): - pass + loganalyzer.match_regex = [] + # Load regular expressions from the specified file defined in COMMON_MATCH variable + reg_exp = loganalyzer.parse_regexp_file(src=COMMON_MATCH) + # Extend currently configured match criteria (regular expressions) with data read from "COMMON_MATCH" file + loganalyzer.match_regex.extend(reg_exp) + marker = loganalyzer.init() + # PERFORM TEST CASE STEPS ... + # Verify that error messages were not found in DUT syslog. Exception will be raised if in DUT syslog will be found messages which fits regexp defined in COMMON_MATCH + loganalyzer.analyze(marker) + + # Example 7 + loganalyzer.expect_regex = [] + # Add specific EXPECTED regular expression + # Means that in the DUT syslog loganalyzer will search for message which matches with "kernel:.*Oops" regular expression + # If such message will not be present in DUT syslog, it will raise exception + loganalyzer.expect_regex.append("kernel:.*Oops") + # Add start marker to the DUT syslog + marker = loganalyzer.init() + # PERFORM TEST CASE STEPS ... + # Verify that expected error messages WERE FOUND in DUT syslog. Exception will be raised if in DUT syslog will NOT be found messages which fits to "kernel:.*Oops" regular expression + loganalyzer.analyze(marker) + + # Example 8 + loganalyzer.expect_regex = [] + # Add specific EXPECTED regular expression + # Means that in the DUT syslog loganalyzer will search for message which matches with "kernel:.*Oops" regular expression + # If such message will not be present in DUT syslog, it will raise exception + loganalyzer.expect_regex.append("kernel:.*Oops") + # Add start marker to the DUT syslog + marker = loganalyzer.init() + # PERFORM TEST CASE STEPS ... + # Verify that expected error messages WERE FOUND in DUT syslog. Exception will be raised if in DUT syslog will NOT be found messages which fits to "kernel:.*Oops" regular expression + loganalyzer.run_cmd(ans_host.command, "echo '---------- kernel: says Oops --------------' >> /var/log/syslog") + ``` From 4d95015c78d2615f29bdcee0c40242965e35041c Mon Sep 17 00:00:00 2001 From: yvolynets-mlnx <50697593+yvolynets-mlnx@users.noreply.github.com> Date: Wed, 7 Aug 2019 19:26:21 +0300 Subject: [PATCH 5/8] Update README.md --- tests/loganalyzer/README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/loganalyzer/README.md b/tests/loganalyzer/README.md index 81d6409e4b8..352d233acc6 100755 --- a/tests/loganalyzer/README.md +++ b/tests/loganalyzer/README.md @@ -57,6 +57,7 @@ loganalyzer.init() - can be called several times without calling "loganalyzer.an ``` #### Example calling loganalyzer init/analyze methods directly in test case +```python # Example 1 # Read existed common regular expressions located with legacy loganalyzer module loganalyzer.load_common_config() @@ -133,5 +134,4 @@ loganalyzer.init() - can be called several times without calling "loganalyzer.an # PERFORM TEST CASE STEPS ... # Verify that expected error messages WERE FOUND in DUT syslog. Exception will be raised if in DUT syslog will NOT be found messages which fits to "kernel:.*Oops" regular expression loganalyzer.run_cmd(ans_host.command, "echo '---------- kernel: says Oops --------------' >> /var/log/syslog") - ``` From 61608280b4f0162ee8aed22b90ea3084b913b3e5 Mon Sep 17 00:00:00 2001 From: Yuriy Volynets Date: Thu, 8 Aug 2019 15:26:57 +0300 Subject: [PATCH 6/8] Added minor fixes based on comments. Signed-off-by: Yuriy Volynets --- ansible/roles/test/files/tools/loganalyzer/loganalyzer.py | 3 ++- tests/loganalyzer/loganalyzer.py | 2 +- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py b/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py index ebbed02ea8f..f1b4b1a132e 100644 --- a/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py +++ b/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py @@ -407,10 +407,11 @@ def usage(): print ' init - initialize analysis by placing start-marker' print ' to all log files specified in --logs parameter.' print ' analyze - perform log analysis of files specified in --logs parameter.' + print ' add_end_marker - add end marker to all log files specified in --logs parameter.' print '--out_dir path Directory path where to place output files, ' print ' must be present when --action == analyze' print '--logs path{,path} List of full paths to log files to be analyzed.' - print ' Implicetly system log file will be also processed' + print ' Implicitly system log file will be also processed' print '--run_id string String passed to loganalyzer, uniquely identifying ' print ' analysis session. Used to construct start/end markers. ' print '--match_files_in path{,path} List of paths to files containing strings. A string from log file' diff --git a/tests/loganalyzer/loganalyzer.py b/tests/loganalyzer/loganalyzer.py index 058387a60bb..8d9b8b1e663 100755 --- a/tests/loganalyzer/loganalyzer.py +++ b/tests/loganalyzer/loganalyzer.py @@ -182,7 +182,7 @@ def analyze(self, marker, fail=True): self.ansible_host.command("sed -i 's/^#//g' /etc/cron.d/logrotate") # Download extracted logs from the DUT to the temporal folder defined in SYSLOG_TMP_FOLDER - self.ansible_host.fetch(dest=tmp_folder, src=self.extracted_syslog, flat="yes") + self.save_extracted_log(dest=tmp_folder) match_messages_regex = re.compile('|'.join(self.match_regex)) if len(self.match_regex) else None ignore_messages_regex = re.compile('|'.join(self.ignore_regex)) if len(self.ignore_regex) else None From 87bd46b9f4392dd6fdd3495bcbd53d75ea67e0a5 Mon Sep 17 00:00:00 2001 From: Yuriy Volynets Date: Tue, 13 Aug 2019 18:07:47 +0300 Subject: [PATCH 7/8] Added minor fix. Signed-off-by: Yuriy Volynets --- ansible/roles/test/files/tools/loganalyzer/loganalyzer.py | 7 +++++-- tests/loganalyzer/README.md | 2 -- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py b/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py index f1b4b1a132e..0d963610681 100644 --- a/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py +++ b/ansible/roles/test/files/tools/loganalyzer/loganalyzer.py @@ -203,8 +203,11 @@ def create_msg_regex(self, file_lsit): self.print_diagnostic_message('[diagnostic]:processing row:%d' % index) self.print_diagnostic_message('row:%s'% row) try: - #-- Ignore commented Lines and Empty Lines - if (not row or row[0].startswith(comment_key)): + #-- Ignore Empty Lines + if not row: + continue + #-- Ignore commented Lines + if row[0].startswith(comment_key): self.print_diagnostic_message('[diagnostic]:skipping row[0]:%s' % row[0]) continue diff --git a/tests/loganalyzer/README.md b/tests/loganalyzer/README.md index 352d233acc6..db9cc80fa38 100755 --- a/tests/loganalyzer/README.md +++ b/tests/loganalyzer/README.md @@ -129,8 +129,6 @@ loganalyzer.init() - can be called several times without calling "loganalyzer.an # Means that in the DUT syslog loganalyzer will search for message which matches with "kernel:.*Oops" regular expression # If such message will not be present in DUT syslog, it will raise exception loganalyzer.expect_regex.append("kernel:.*Oops") - # Add start marker to the DUT syslog - marker = loganalyzer.init() # PERFORM TEST CASE STEPS ... # Verify that expected error messages WERE FOUND in DUT syslog. Exception will be raised if in DUT syslog will NOT be found messages which fits to "kernel:.*Oops" regular expression loganalyzer.run_cmd(ans_host.command, "echo '---------- kernel: says Oops --------------' >> /var/log/syslog") From b96898e0f41d5f7bc862e165ce123b4cd9f879a0 Mon Sep 17 00:00:00 2001 From: yvolynets-mlnx <50697593+yvolynets-mlnx@users.noreply.github.com> Date: Wed, 21 Aug 2019 19:24:43 +0300 Subject: [PATCH 8/8] Added 'disable_loganalyzer' marker --- tests/platform/test_reboot.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/platform/test_reboot.py b/tests/platform/test_reboot.py index a402b408acf..cd9aa29c75e 100644 --- a/tests/platform/test_reboot.py +++ b/tests/platform/test_reboot.py @@ -22,6 +22,8 @@ from check_transceiver_status import check_transceiver_basic from check_transceiver_status import all_transceivers_detected +pytestmark = [pytest.mark.disable_loganalyzer] + def reboot_and_check(localhost, dut, reboot_type="cold"): """