Fix: report.utils: Fix the performance issue (bsc#1232821) (#1606)

port from #1605

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)
 
 

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

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
 
@@ -43,14 +54,22 @@ 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):
             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
 
 
@@ -137,15 +156,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
 
 

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 = """