Hibernation: Log uptime and resume offset (#3403)

* Hibernation: Log uptime and resume offset

Uptime seems to have a drift of 1 second due to Hibernation, which is a bug.
To prevent all tests from failing, just log uptime and resume offset details
for debugging purpose.

lisa/tools/hibernation_setup.py

@@ -8,7 +8,7 @@
 from lisa.base_tools import Cat, Systemctl
 from lisa.executable import Tool
 from lisa.operating_system import CBLMariner
-from lisa.util import find_patterns_in_lines
+from lisa.util import find_patterns_in_lines, get_matched_str
 
 from .git import Git
 from .ls import Ls
@@ -28,6 +28,22 @@ class HibernationSetup(Tool):
     # [  159.898806] hv_utils: Sent hibernation uevent
     _uevent_pattern = re.compile(r"^(.*Sent hibernation uevent.*)$", re.MULTILINE)
 
+    """
+    The below shows an example output of `filefrag -v /hibfile.sys`
+    We are interested in the physical offset of the hibfile.
+
+    Filesystem type is: ef53
+    File size of /hibfile is 1048576 (256 blocks of 4096 bytes)
+    ext:     logical_offset:        physical_offset: length:   expected: flags:
+    0:        0..      255:    123456..   123711:    256:             last,unwritten,eof
+    /hibfile: 1 extent found
+    """
+    _hibsys_resume_offset_pattern = re.compile(
+        r"^\s*\d+:\s+\d+\.\.\s+\d+:\s+(\d+)\.\.", re.MULTILINE
+    )
+
+    _cmdline_resume_offset_pattern = re.compile(r"resume_offset=(\d+)")
+
     @property
     def command(self) -> str:
         return "hibernation-setup-tool"
@@ -62,6 +78,18 @@ def check_uevent(self) -> int:
     def hibernate(self) -> None:
         self.node.tools[Systemctl].hibernate()
 
+    def get_hibernate_resume_offset_from_hibfile(self) -> str:
+        filefrag_hibfile = self.node.execute(
+            "filefrag -v /hibfile.sys", sudo=True
+        ).stdout
+        offset = get_matched_str(filefrag_hibfile, self._hibsys_resume_offset_pattern)
+        return offset
+
+    def get_hibernate_resume_offset_from_cmd(self) -> str:
+        cmdline = self.node.tools[Cat].read("/proc/cmdline")
+        offset = get_matched_str(cmdline, self._cmdline_resume_offset_pattern)
+        return offset
+
     def _install(self) -> bool:
         if isinstance(self.node.os, CBLMariner):
             self.node.os.install_packages(["glibc-devel", "kernel-headers", "binutils"])

microsoft/testsuites/power/common.py

@@ -7,6 +7,7 @@
 from assertpy import assert_that
 
 from lisa import Environment, Logger, Node, RemoteNode, features
+from lisa.base_tools.cat import Cat
 from lisa.features import StartStop
 from lisa.features.startstop import VMStatus
 from lisa.operating_system import Redhat, Suse, Ubuntu
@@ -59,6 +60,7 @@ def verify_hibernation(
         _expand_os_partition(node, log)
     hibernation_setup_tool = node.tools[HibernationSetup]
     startstop = node.features[StartStop]
+    cat = node.tools[Cat]
 
     node_nic = node.nics
     lower_nics_before_hibernation = node_nic.get_lower_nics()
@@ -71,7 +73,9 @@ def verify_hibernation(
     # only set up hibernation setup tool for the first time
     hibernation_setup_tool.start()
     uptime = node.tools[Uptime]
+
     uptime_before_hibernation = uptime.since_time()
+    hibfile_offset = hibernation_setup_tool.get_hibernate_resume_offset_from_hibfile()
 
     try:
         startstop.stop(state=features.StopState.Hibernate)
@@ -93,15 +97,25 @@ def verify_hibernation(
         raise LisaException("VM is not in deallocated status after hibernation")
 
     startstop.start()
+
     dmesg = node.tools[Dmesg]
     dmesg.check_kernel_errors(force_run=True, throw_error=throw_error)
 
+    offset_from_cmd = hibernation_setup_tool.get_hibernate_resume_offset_from_cmd()
     uptime_after_hibernation = uptime.since_time()
-    assert_that(uptime_after_hibernation).described_as(
-        "Hibernation should not change uptime."
-    ).is_equal_to(uptime_before_hibernation)
+    offset_from_sys_power = cat.read("/sys/power/resume_offset")
+
+    log.info(
+        "Uptime before Hibernation: "
+        f"{uptime_before_hibernation}, Uptime after Hibernation: "
+        f"{uptime_after_hibernation}"
+    )
+    log.info(
+        f"Hibfile resume offset: {hibfile_offset}, "
+        f"Resume offset from cmdline: {offset_from_cmd}"
+    )
 
-    log.info("Hibernation resume is successful. Uptime is not changed.")
+    log.info(f"Resume offset from /sys/power/resume_offset: {offset_from_sys_power}")
 
     entry_after_hibernation = hibernation_setup_tool.check_entry()
     exit_after_hibernation = hibernation_setup_tool.check_exit()
@@ -125,6 +139,7 @@ def verify_hibernation(
     node_nic.initialize()
     lower_nics_after_hibernation = node_nic.get_lower_nics()
     upper_nics_after_hibernation = node_nic.get_nic_names()
+
     assert_that(len(lower_nics_after_hibernation)).described_as(
         "sriov nics count changes after hibernation."
     ).is_equal_to(len(lower_nics_before_hibernation))