From 57ed8b354247b74a83bde9cc880ea7227b838386 Mon Sep 17 00:00:00 2001 From: xin liang Date: Tue, 5 Nov 2024 21:48:11 +0800 Subject: [PATCH 1/5] Fix: report.collect: Make sure the log is not None before using it (bsc#1232821) --- crmsh/report/collect.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crmsh/report/collect.py b/crmsh/report/collect.py index 47d735c64..17823b489 100644 --- a/crmsh/report/collect.py +++ b/crmsh/report/collect.py @@ -66,7 +66,7 @@ def collect_ha_logs(context: core.Context) -> None: """ log_list = [get_pcmk_log(), get_corosync_log()] + context.extra_log_list for log in log_list: - if os.path.isfile(log): + if log and os.path.isfile(log): utils.dump_logset(context, log) From 3ea9c44e9510ffb5ead006d93bcccb5781cb1b3e Mon Sep 17 00:00:00 2001 From: xin liang Date: Wed, 6 Nov 2024 14:10:44 +0800 Subject: [PATCH 2/5] Dev: report.utils: Add debug info for the log file types --- crmsh/report/utils.py | 18 +++++++++++++++++- 1 file changed, 17 insertions(+), 1 deletion(-) diff --git a/crmsh/report/utils.py b/crmsh/report/utils.py index cc27118c6..9c67a7a6e 100644 --- a/crmsh/report/utils.py +++ b/crmsh/report/utils.py @@ -29,6 +29,17 @@ class LogType(Enum): AFTER_TIMESPAN = 4 # log after timespan; exclude +def convert_logtype_to_str(log_type: LogType) -> str: + log_type_str = { + LogType.GOOD: "in timespan", + LogType.IRREGULAR: "irregular", + LogType.EMPTY: "empty", + LogType.BEFORE_TIMESPAN: "before timespan", + LogType.AFTER_TIMESPAN: "after timespan" + } + return log_type_str[log_type] + + class ReportGenericError(Exception): pass @@ -44,13 +55,18 @@ def arch_logs(context: core.Context, logf: str) -> Tuple[List[str], LogType]: # like ls -t, newest first for f in sorted(file_list, key=os.path.getmtime, reverse=True): tmp = is_our_log(context, f) + logger.debug2("File %s is %s", f, convert_logtype_to_str(tmp)) if tmp not in (LogType.GOOD, LogType.IRREGULAR): continue log_type = tmp return_list.append(f) if return_list: - logger.debug2(f"Found logs {return_list} in {get_timespan_str(context)}") + logger.debug2( + "Found %s logs: %s", + convert_logtype_to_str(log_type), + ', '.join(return_list) + ) return return_list, log_type From 56db2355a2258a7d2c411b15a730e0476fb9f4f1 Mon Sep 17 00:00:00 2001 From: xin liang Date: Wed, 6 Nov 2024 21:23:36 +0800 Subject: [PATCH 3/5] Fix: report.utils: Fix the performance issue (bsc#1232821) The function `extract_critical_log` can be very slow when processing large log files. The main issue is the inefficiency of the regular expression, which combines multiple wildcards (.*) with alternation (|), leading to excessive backtracking. Additionally, the function reads the entire file into memory, which is not optimal for large files. To improve performance, it is better to use `grep` with the -F option to search for fixed strings. --- crmsh/report/constants.py | 2 +- crmsh/report/utils.py | 14 +++++++------- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/crmsh/report/constants.py b/crmsh/report/constants.py index 62ba97627..84c40c57b 100644 --- a/crmsh/report/constants.py +++ b/crmsh/report/constants.py @@ -3,7 +3,7 @@ BIN_CRM = "/usr/sbin/crm" BIN_COLLECTOR = f"{BIN_CRM} report __collector" COMPRESS_DATA_FLAG = "COMPRESS CRM_REPORT DATA:::" -LOG_PATTERNS = "CRIT: ERROR: error: warning: crit:" +LOG_PATTERNS = ["CRIT:", "ERROR:", "WARNING:", "crit:", "error:", "warning:"] PTEST = "crm_simulate" SSH_OPTS = "-o StrictHostKeyChecking=no -o EscapeChar=none -o ConnectTimeout=15" CHECK_LOG_LINES = 10 diff --git a/crmsh/report/utils.py b/crmsh/report/utils.py index 9c67a7a6e..d6944b204 100644 --- a/crmsh/report/utils.py +++ b/crmsh/report/utils.py @@ -153,15 +153,15 @@ def extract_critical_log(context: core.Context) -> List[str]: Extract warnings and errors from collected log files """ result_list = [] - log_pattern_list = [f".*{p}.*" for p in constants.LOG_PATTERNS.split()] - log_pattern_str = '|'.join(log_pattern_list) + grep_e_option_str = f"-e {' -e '.join(constants.LOG_PATTERNS)}" + shell = sh.ShellUtils() for f in glob.glob(f"{context.work_dir}/*/*.log"): - _list = re.findall(log_pattern_str, crmutils.read_from_file(f)) - if _list: - result_list.append(f"\nWARNINGS or ERRORS in {'/'.join(f.split('/')[3:])}:") - result_list.extend(_list) - + grep_cmd = f"grep -F {grep_e_option_str} {f}" + _, out, _ = shell.get_stdout_stderr(grep_cmd) + if out: + result_list.append(f"\nWARNINGS or ERRORS in {real_path(f)}:") + result_list.append(out) return result_list From 210661b357a6690b678840c829fda7f9a21cd60c Mon Sep 17 00:00:00 2001 From: xin liang Date: Thu, 7 Nov 2024 13:52:54 +0800 Subject: [PATCH 4/5] Dev: report.utils: For a sequence of archived log files, check the modify time No need to check the rest of the files if the from time is greater than the modify time of the file. --- crmsh/report/utils.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/crmsh/report/utils.py b/crmsh/report/utils.py index d6944b204..4fadf307f 100644 --- a/crmsh/report/utils.py +++ b/crmsh/report/utils.py @@ -54,6 +54,9 @@ def arch_logs(context: core.Context, logf: str) -> Tuple[List[str], LogType]: file_list = [logf] + glob.glob(logf+"*[0-9z]") # like ls -t, newest first for f in sorted(file_list, key=os.path.getmtime, reverse=True): + modify_time = os.path.getmtime(f) + if context.from_time > modify_time: + break # no need to check the rest tmp = is_our_log(context, f) logger.debug2("File %s is %s", f, convert_logtype_to_str(tmp)) if tmp not in (LogType.GOOD, LogType.IRREGULAR): From b2dcf6136da591c4bd2aa4dc41314f4fd4fec743 Mon Sep 17 00:00:00 2001 From: xin liang Date: Wed, 6 Nov 2024 22:46:47 +0800 Subject: [PATCH 5/5] Dev: unittests: Adjust unit test for previous commit --- test/unittests/test_report_utils.py | 27 +++++++++++++++------------ 1 file changed, 15 insertions(+), 12 deletions(-) diff --git a/test/unittests/test_report_utils.py b/test/unittests/test_report_utils.py index 6189a8cad..143494635 100644 --- a/test/unittests/test_report_utils.py +++ b/test/unittests/test_report_utils.py @@ -222,22 +222,26 @@ def test_extract_sensitive_value_list(self, mock_extract): class TestUtils(unittest.TestCase): - @mock.patch('builtins.sorted', side_effect=lambda x, *args, **kwargs: x[::-1]) + @mock.patch('os.path.getmtime') @mock.patch('crmsh.report.utils.get_timespan_str') @mock.patch('crmsh.report.utils.logger', spec=crmsh.log.DEBUG2Logger) @mock.patch('glob.glob') @mock.patch('crmsh.report.utils.is_our_log') - def test_arch_logs(self, mock_is_our_log, mock_glob, mock_logger, mock_timespan, mock_sorted): + def test_arch_logs(self, mock_is_our_log, mock_glob, mock_logger, mock_timespan, mock_getmtime): mock_is_our_log.return_value = utils.LogType.GOOD mock_glob.return_value = [] - mock_ctx_inst = mock.Mock() + mock_ctx_inst = mock.Mock(from_time=1691938980.0, to_time=1691982180.0) mock_timespan.return_value = "0101-0202" + mock_getmtime.side_effect = [1691938980.0, 1691938980.0] return_list, log_type = utils.arch_logs(mock_ctx_inst, "file1") self.assertEqual(return_list, ["file1"]) self.assertEqual(log_type, utils.LogType.GOOD) - mock_logger.debug2.assert_called_once_with("Found logs ['file1'] in 0101-0202") + mock_logger.debug2.assert_has_calls([ + mock.call('File %s is %s', 'file1', 'in timespan'), + mock.call('Found %s logs: %s', 'in timespan', 'file1') + ]) @mock.patch('sys.stdout.flush') @mock.patch('traceback.print_exc') @@ -758,16 +762,15 @@ def test_parse_to_timestamp_delta(self): res = utils.parse_to_timestamp("10d") self.assertEqual(int(res), int(expected_timestamp)) - @mock.patch('crmsh.utils.read_from_file') + @mock.patch('crmsh.sh.ShellUtils') @mock.patch('glob.glob') - def test_extract_critical_log(self, mock_glob, mock_read): + def test_extract_critical_log(self, mock_glob, mock_run): mock_glob.return_value = ["/opt/workdir/pacemaker.log"] - mock_read.return_value = """ -line1 -pacemaker-controld[5678]: warning: data -pacemaker-schedulerd[5677]: error: Resource -line4 - """ + mock_run_inst = mock.Mock() + mock_run.return_value = mock_run_inst + data = """pacemaker-controld[5678]: warning: data +pacemaker-schedulerd[5677]: error: Resource""" + mock_run_inst.get_stdout_stderr.return_value = (0, data, None) mock_ctx_inst = mock.Mock(work_dir="/opt/workdir") res = utils.extract_critical_log(mock_ctx_inst) expected_data = """