From 6ba2b33a8c66f8deb94f9df0a4f240b48083722c Mon Sep 17 00:00:00 2001
From: Guilherme Gallo <guilherme.gallo@collabora.com>
Date: Mon, 4 Jul 2022 17:34:17 -0300
Subject: [PATCH] ci/lava: Flexibilize section marker regexes

In some jobs, such as
https://gitlab.freedesktop.org/gallo/mesa/-/jobs/24904100, the kmsg is
interleaved with stderr/stdout in serial console, making it difficult to
confidently find the log messages to detect when the DUT is booting,
when the DUT is running etc.

Luckily, LAVA sends redundant messages about their signals. We can use
them to mitigate the chance of missing an interleaved message by being
more open to different messages, using the regex on both `debug` and
`target` LAVA log levels.

Signed-off-by: Guilherme Gallo <guilherme.gallo@collabora.com>
Part-of: <https://gitlab.freedesktop.org/mesa/mesa/-/merge_requests/16323>
---
 .gitlab-ci/lava/utils/lava_log.py       | 42 ++++++++++++++-----------
 .gitlab-ci/tests/utils/test_lava_log.py | 13 ++++++++
 2 files changed, 37 insertions(+), 18 deletions(-)

diff --git a/.gitlab-ci/lava/utils/lava_log.py b/.gitlab-ci/lava/utils/lava_log.py
index 090c9658cd7..36b2979831e 100644
--- a/.gitlab-ci/lava/utils/lava_log.py
+++ b/.gitlab-ci/lava/utils/lava_log.py
@@ -145,7 +145,7 @@ class GitlabSection:
 @dataclass(frozen=True)
 class LogSection:
     regex: Union[Pattern, str]
-    level: str
+    levels: tuple[str]
     section_id: str
     section_header: str
     section_type: LogSectionType
@@ -154,36 +154,38 @@ class LogSection:
     def from_log_line_to_section(
         self, lava_log_line: dict[str, str]
     ) -> Optional[GitlabSection]:
-        if lava_log_line["lvl"] == self.level:
-            if match := re.match(self.regex, lava_log_line["msg"]):
-                section_id = self.section_id.format(*match.groups())
-                section_header = self.section_header.format(*match.groups())
-                return GitlabSection(
-                    id=section_id,
-                    header=section_header,
-                    type=self.section_type,
-                    start_collapsed=self.collapsed,
-                )
+        if lava_log_line["lvl"] not in self.levels:
+            return
+
+        if match := re.search(self.regex, lava_log_line["msg"]):
+            section_id = self.section_id.format(*match.groups())
+            section_header = self.section_header.format(*match.groups())
+            return GitlabSection(
+                id=section_id,
+                header=section_header,
+                type=self.section_type,
+                start_collapsed=self.collapsed,
+            )
 
 
 LOG_SECTIONS = (
     LogSection(
-        regex=re.compile(r".*<STARTTC> (.*)"),
-        level="debug",
+        regex=re.compile(r"<?STARTTC>? ([^>]*)"),
+        levels=("target", "debug"),
         section_id="{}",
         section_header="test_case {}",
         section_type=LogSectionType.TEST_CASE,
     ),
     LogSection(
-        regex=re.compile(r".*<STARTRUN> (\S*)"),
-        level="debug",
+        regex=re.compile(r"<?STARTRUN>? ([^>]*)"),
+        levels=("target", "debug"),
         section_id="{}",
         section_header="test_suite {}",
         section_type=LogSectionType.TEST_SUITE,
     ),
     LogSection(
-        regex=re.compile(r"^<LAVA_SIGNAL_ENDTC ([^>]+)"),
-        level="target",
+        regex=re.compile(r"ENDTC>? ([^>]+)"),
+        levels=("target", "debug"),
         section_id="post-{}",
         section_header="Post test_case {}",
         collapsed=True,
@@ -208,7 +210,7 @@ class LogFollower:
         )
         assert (
             section_is_created == section_has_started
-        ), "Can't follow logs beginning from uninitalized GitLab sections."
+        ), "Can't follow logs beginning from uninitialized GitLab sections."
 
     def __enter__(self):
         return self
@@ -240,6 +242,10 @@ class LogFollower:
             self.current_section = None
 
     def update_section(self, new_section: GitlabSection):
+        # Sections can have redundant regex to find them to mitigate LAVA
+        # interleaving kmsg and stderr/stdout issue.
+        if self.current_section and self.current_section.id == new_section.id:
+            return
         self.clear_current_section()
         self.current_section = new_section
         self._buffer.append(new_section.start())
diff --git a/.gitlab-ci/tests/utils/test_lava_log.py b/.gitlab-ci/tests/utils/test_lava_log.py
index 32325c99d86..24e46ff6e93 100644
--- a/.gitlab-ci/tests/utils/test_lava_log.py
+++ b/.gitlab-ci/tests/utils/test_lava_log.py
@@ -86,11 +86,24 @@ def test_gl_sections():
             "lvl": "debug",
             "msg": "Received signal: <STARTRUN> 0_mesa 5971831_1.3.2.3.1",
         },
+        # Redundant log message which triggers the same Gitlab Section, it
+        # should be ignored, unless the id is different
+        {
+            "dt": datetime.now(),
+            "lvl": "target",
+            "msg": "[    7.778836] <LAVA_SIGNAL_STARTRUN 0_mesa 5971831_1.3.2.3.1>",
+        },
         {
             "dt": datetime.now(),
             "lvl": "debug",
             "msg": "Received signal: <STARTTC> mesa-ci_iris-kbl-traces",
         },
+        # Another redundant log message
+        {
+            "dt": datetime.now(),
+            "lvl": "target",
+            "msg": "[   16.997829] <LAVA_SIGNAL_STARTTC mesa-ci_iris-kbl-traces>",
+        },
         {
             "dt": datetime.now(),
             "lvl": "target",