From 5088c0ee692b16ff09bf466ad0252c6daa64fe24 Mon Sep 17 00:00:00 2001
From: Lukas Zapletal <lzap+git@redhat.com>
Date: Tue, 22 Jul 2025 16:54:33 +0200
Subject: [PATCH] monitor: fix duration calculation
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

When fully cached manifest is used, the duration used to print an
incorrect value of 55 years:

    python3 -m osbuild --libdir . ./test/data/manifests/fedora-boot.json
    ⏱  Duration: 1753191578s

This patch fixes the duration calculation to use the correct timestamp
from the manifest by using monotonic timer instead. Additionally, it
prints nothing when there was no module executed. Finally, it improves
the formatting of the duration output.
---
 osbuild/monitor.py       |  9 +++++----
 test/mod/test_monitor.py | 26 ++++++++++++++++++++++++++
 2 files changed, 31 insertions(+), 4 deletions(-)

diff --git a/osbuild/monitor.py b/osbuild/monitor.py
index 0393aab1..267c093f 100644
--- a/osbuild/monitor.py
+++ b/osbuild/monitor.py
@@ -258,11 +258,12 @@ class LogMonitor(BaseMonitor):
 
     def __init__(self, fd: int, total_steps: int = 0):
         super().__init__(fd, total_steps)
-        self.timer_start = 0
+        self._module_start_time: Optional[float] = None
 
     def result(self, result: Union[BuildResult, DownloadResult]) -> None:
-        duration = int(time.time() - self.timer_start)
-        self.out.write(f"\n⏱  Duration: {duration}s\n")
+        if self._module_start_time is not None:
+            duration = time.monotonic() - self._module_start_time
+            self.out.write(f"\n⏱  Duration: {duration:.2f}s\n")
 
     def begin(self, pipeline):
         self.out.term(vt.bold, clear=True)
@@ -304,7 +305,7 @@ class LogMonitor(BaseMonitor):
         json.dump(options, self.out, indent=2)
         self.out.write("\n")
 
-        self.timer_start = time.time()
+        self._module_start_time = time.monotonic()
 
     def log(self, message, origin: Optional[str] = None):
         self.out.write(message)
diff --git a/test/mod/test_monitor.py b/test/mod/test_monitor.py
index 1eef7553..73d810fc 100644
--- a/test/mod/test_monitor.py
+++ b/test/mod/test_monitor.py
@@ -57,6 +57,31 @@ class TapeMonitor(osbuild.monitor.BaseMonitor):
 
 
 class TestMonitor(unittest.TestCase):
+    @unittest.skipUnless(test.TestBase.can_bind_mount(), "root-only")
+    def test_log_monitor_no_duration(self):
+        index = osbuild.meta.Index(os.curdir)
+
+        runner = Runner(index.detect_host_runner())
+        pipeline = osbuild.Pipeline("pipeline", runner=runner)
+
+        with tempfile.TemporaryDirectory() as tmpdir:
+            storedir = os.path.join(tmpdir, "store")
+
+            logfile = os.path.join(tmpdir, "log.txt")
+
+            with open(logfile, "w", encoding="utf8") as log, ObjectStore(storedir) as store:
+                monitor = LogMonitor(log.fileno())
+                res = pipeline.run(store,
+                                   monitor,
+                                   libdir=os.path.abspath(os.curdir))
+                monitor.result(res)
+
+                with open(logfile, encoding="utf8") as f:
+                    log = f.read()
+
+            assert res
+            self.assertNotIn("Duration", log)
+
     @unittest.skipUnless(test.TestBase.can_bind_mount(), "root-only")
     def test_log_monitor_vfuncs(self):
         # Checks the basic functioning of the LogMonitor
@@ -86,6 +111,7 @@ class TestMonitor(unittest.TestCase):
             assert res
             self.assertIn(pipeline.stages[0].id, log)
             self.assertIn("isthisthereallife", log)
+            self.assertIn("Duration", log)
 
     @unittest.skipUnless(test.TestBase.can_bind_mount(), "root-only")
     def test_monitor_integration(self):