From 41f29c5333372a9aa5e0d6e05476ed529326afa5 Mon Sep 17 00:00:00 2001 From: Guilherme Gallo Date: Thu, 6 Apr 2023 01:44:24 -0300 Subject: [PATCH] ci/lava: Update LogFollower for better section handling and history Update the LogFollower class to improve section handling and provide a history of sections encountered during log processing: 1. Add section_history attribute to store the history of encountered GitlabSections. 2. Make LAVA job submitter use the section history feature to improve structural logging. Signed-off-by: Guilherme Gallo Part-of: --- .gitlab-ci/lava/lava_job_submitter.py | 11 +++++++++- .gitlab-ci/lava/utils/gitlab_section.py | 19 +++++++++++++++++ .gitlab-ci/lava/utils/log_follower.py | 36 +++++++++++++++++++++++---------- 3 files changed, 54 insertions(+), 12 deletions(-) diff --git a/.gitlab-ci/lava/lava_job_submitter.py b/.gitlab-ci/lava/lava_job_submitter.py index 7ffdcd2..0372fb4 100755 --- a/.gitlab-ci/lava/lava_job_submitter.py +++ b/.gitlab-ci/lava/lava_job_submitter.py @@ -217,7 +217,7 @@ def bootstrap_log_follower() -> LogFollower: start_collapsed=True, ) print(gl.start()) - return LogFollower(current_section=gl) + return LogFollower(starting_section=gl) def follow_job_execution(job, log_follower): @@ -227,6 +227,7 @@ def follow_job_execution(job, log_follower): job.heartbeat() while not job.is_finished: fetch_logs(job, max_idle_time, log_follower) + structural_log_phases(job, log_follower) # Mesa Developers expect to have a simple pass/fail job result. # If this does not happen, it probably means a LAVA infrastructure error @@ -234,6 +235,14 @@ def follow_job_execution(job, log_follower): if job.status not in ["pass", "fail"]: find_lava_error(job) +def structural_log_phases(job, log_follower): + phases: dict[str, Any] = { + s.header.split(" - ")[0]: { + k: str(getattr(s, k)) for k in ("start_time", "end_time") + } + for s in log_follower.section_history + } + job.log["dut_job_phases"] = phases def print_job_final_status(job): if job.status == "running": diff --git a/.gitlab-ci/lava/utils/gitlab_section.py b/.gitlab-ci/lava/utils/gitlab_section.py index 7e2398d..034afb4 100644 --- a/.gitlab-ci/lava/utils/gitlab_section.py +++ b/.gitlab-ci/lava/utils/gitlab_section.py @@ -11,6 +11,7 @@ if TYPE_CHECKING: from lava.utils.log_section import LogSectionType +# TODO: Add section final status to assist with monitoring @dataclass class GitlabSection: id: str @@ -37,6 +38,14 @@ class GitlabSection: def has_finished(self) -> bool: return self.__end_time is not None + @property + def start_time(self) -> datetime: + return self.__start_time + + @property + def end_time(self) -> Optional[datetime]: + return self.__end_time + def get_timestamp(self, time: datetime) -> str: unix_ts = datetime.timestamp(time) return str(int(unix_ts)) @@ -54,6 +63,16 @@ class GitlabSection: return f"{before_header}{header_wrapper}" + def __str__(self) -> str: + status = "NS" if not self.has_started else "F" if self.has_finished else "IP" + delta = self.delta_time() + elapsed_time = "N/A" if delta is None else str(delta) + return ( + f"GitlabSection({self.id}, {self.header}, {self.type}, " + f"SC={self.start_collapsed}, S={status}, ST={self.start_time}, " + f"ET={self.end_time}, ET={elapsed_time})" + ) + def __enter__(self): print(self.start()) return self diff --git a/.gitlab-ci/lava/utils/log_follower.py b/.gitlab-ci/lava/utils/log_follower.py index 4b18efc..325224d 100644 --- a/.gitlab-ci/lava/utils/log_follower.py +++ b/.gitlab-ci/lava/utils/log_follower.py @@ -32,7 +32,9 @@ from lava.utils.log_section import ( @dataclass class LogFollower: - current_section: Optional[GitlabSection] = None + starting_section: Optional[GitlabSection] = None + _current_section: Optional[GitlabSection] = None + section_history: list[GitlabSection] = field(default_factory=list, init=False) timeout_durations: dict[LogSectionType, timedelta] = field( default_factory=lambda: DEFAULT_GITLAB_SECTION_TIMEOUTS, ) @@ -43,9 +45,11 @@ class LogFollower: _merge_next_line: str = field(default_factory=str, init=False) def __post_init__(self): - section_is_created = bool(self.current_section) + # Make it trigger current_section setter to populate section history + self.current_section = self.starting_section + section_is_created = bool(self._current_section) section_has_started = bool( - self.current_section and self.current_section.has_started + self._current_section and self._current_section.has_started ) self.log_hints = LAVALogHints(self) assert ( @@ -57,10 +61,20 @@ class LogFollower: next(self.gl_section_fix_gen) @property + def current_section(self): + return self._current_section + + @current_section.setter + def current_section(self, new_section: GitlabSection) -> None: + if old_section := self._current_section: + self.section_history.append(old_section) + self._current_section = new_section + + @property def phase(self) -> LogSectionType: return ( - self.current_section.type - if self.current_section + self._current_section.type + if self._current_section else LogSectionType.UNKNOWN ) @@ -75,22 +89,22 @@ class LogFollower: print(line) def watchdog(self): - if not self.current_section: + if not self._current_section: return timeout_duration = self.timeout_durations.get( - self.current_section.type, self.fallback_timeout + self._current_section.type, self.fallback_timeout ) - if self.current_section.delta_time() > timeout_duration: + if self._current_section.delta_time() > timeout_duration: raise MesaCITimeoutError( - f"Gitlab Section {self.current_section} has timed out", + f"Gitlab Section {self._current_section} has timed out", timeout_duration=timeout_duration, ) def clear_current_section(self): - if self.current_section and not self.current_section.has_finished: - self._buffer.append(self.current_section.end()) + if self._current_section and not self._current_section.has_finished: + self._buffer.append(self._current_section.end()) self.current_section = None def update_section(self, new_section: GitlabSection): -- 2.7.4