From 3e37ad3b929847f0f97f5439301fc83f72c3154c Mon Sep 17 00:00:00 2001
From: Lukas Zapletal <lzap+git@redhat.com>
Date: Tue, 22 Jul 2025 17:40:36 +0200
Subject: [PATCH] monitor: add duration to JSON logger

Although duration of each stage could be calculated from the start and
end timestamps, it is more convenient to have it directly in the log
entry. This way we can avoid calculating it in the client code.
---
 osbuild/monitor.py       | 10 ++++++++++
 test/mod/test_monitor.py |  1 +
 2 files changed, 11 insertions(+)

diff --git a/osbuild/monitor.py b/osbuild/monitor.py
index 267c093f..5f87f78a 100644
--- a/osbuild/monitor.py
+++ b/osbuild/monitor.py
@@ -168,6 +168,7 @@ class Progress:
 def log_entry(message: Optional[str] = None,
               context: Optional[Context] = None,
               progress: Optional[Progress] = None,
+              duration: Optional[float] = None,
               result: Union[BuildResult, DownloadResult, None] = None,
               ) -> dict:
     """
@@ -182,6 +183,7 @@ def log_entry(message: Optional[str] = None,
         "context": context.as_dict() if context else None,
         "progress": progress.as_dict() if progress else None,
         "timestamp": time.time(),
+        "duration": duration,
     })
 
 
@@ -320,6 +322,7 @@ class JSONSeqMonitor(BaseMonitor):
         self._progress = Progress("pipelines/sources", total_steps)
         self._context = Context(origin="org.osbuild")
         self._jsonseq_mu = Lock()
+        self._module_start_time: Optional[float] = None
 
     def begin(self, pipeline: osbuild.Pipeline):
         self._context.set_pipeline(pipeline)
@@ -341,6 +344,7 @@ class JSONSeqMonitor(BaseMonitor):
     def _module(self, module: osbuild.Stage):
         self._context.set_stage(module)
         self.log(f"Starting module {module.name}", origin="osbuild.monitor")
+        self._module_start_time = time.monotonic()
 
     def result(self, result: Union[BuildResult, DownloadResult]) -> None:
         """ Called when the module (stage or download) is finished
@@ -368,10 +372,16 @@ class JSONSeqMonitor(BaseMonitor):
             removed = len(result.output) - max_output_len
             result.output = f"[...{removed} bytes hidden...]\n{result.output[removed:]}"
 
+        # If the module has a timestamp, we can calculate the duration.
+        duration = None
+        if self._module_start_time is not None:
+            duration = time.monotonic() - self._module_start_time
+
         self._jsonseq(log_entry(
             f"Finished module {result.name}",
             context=self._context.with_origin("osbuild.monitor"),
             progress=self._progress,
+            duration=duration,
             # We should probably remove the "output" key from the result
             # as it is redundant, each output already generates a "log()"
             # message that is streamed to the client.
diff --git a/test/mod/test_monitor.py b/test/mod/test_monitor.py
index 73d810fc..6c8e5c03 100644
--- a/test/mod/test_monitor.py
+++ b/test/mod/test_monitor.py
@@ -304,6 +304,7 @@ def test_json_progress_monitor():
             "output": "some output",
             "success": True,
         }
+        assert logitem["duration"] > 0
         i += 1
 
         logitem = json.loads(log[i])