launchpad-reviewers team mailing list archive

[İlker Emre Koç <mp+478219@xxxxxxxxxxxxxxxxxx>]

İlker Emre Koç has proposed merging ~ilkeremrekoc/launchpad-buildd:add-buildlog-timestamp into launchpad-buildd:master.

Commit message:
add timestamp information into buildlogs




Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)

For more details, see:
https://code.launchpad.net/~ilkeremrekoc/launchpad-buildd/+git/launchpad-buildd/+merge/478219

- Added timestamp into buildlogs of subprocesses.
- Updated test-suite to test for the new timestamps.
-- 
Your team Launchpad code reviewers is requested to review the proposed merge of ~ilkeremrekoc/launchpad-buildd:add-buildlog-timestamp into launchpad-buildd:master.

diff --git a/debian/changelog b/debian/changelog
index 6444ec9..5f17cb0 100644
--- a/debian/changelog
+++ b/debian/changelog
@@ -1,9 +1,13 @@
-launchpad-buildd (248) UNRELEASED; urgency=medium
+launchpad-buildd (248) focal; urgency=medium
 
+  [ Jürgen Gmach ]
   * Set REQUESTS_CA_BUNDLE so craft tools can fetch files via requests.
 
- -- Jürgen Gmach <juergen.gmach@xxxxxxxxxxxxx>  Fri, 22 Nov 2024 13:53:23 +0100
+  [ İlker Emre Koç ]
+  * Add a timestamp into buildlogs. 
 
+ -- İlker Emre Koç <ilkeremre.koc@xxxxxxxxxxxxx>  Tue, 10 Dec 2024 16:40:55 +0300 
+ 
 launchpad-buildd (247) focal; urgency=medium
 
   * Wait for pre-seeded snaps to seed and boot up before running LXD commands
diff --git a/lpbuildd/builder.py b/lpbuildd/builder.py
index f821b34..6c5c6b2 100644
--- a/lpbuildd/builder.py
+++ b/lpbuildd/builder.py
@@ -6,6 +6,7 @@
 
 # The basic builder implementation.
 
+from datetime import datetime, timezone
 import hashlib
 import json
 import os
@@ -161,6 +162,12 @@ class BuildManager:
             for arg in args[1:]
         ]
         escaped_args = " ".join(shell_escape(arg) for arg in text_args)
+
+        # Log timestamps in the following form: '[Sun Jun 20 23:21:05 1993]'.
+        # The day field is two characters long and is space padded if the day is 
+        # a single digit, e.g.: 'Wed Jun  9 04:26:40 1993'.
+        self._builder.log(f"[{datetime.now().replace(tzinfo=timezone.utc).ctime()}]\n")
+
         self._builder.log(f"RUN: {command} {escaped_args}\n")
         childfds = {
             0: devnull.fileno() if stdin is None else "w",
diff --git a/lpbuildd/tests/test_builder.py b/lpbuildd/tests/test_builder.py
index 161923f..b43e7e1 100644
--- a/lpbuildd/tests/test_builder.py
+++ b/lpbuildd/tests/test_builder.py
@@ -6,14 +6,16 @@
 Most tests are done on subclasses instead.
 """
 
+from datetime import datetime, timezone
 import io
 import re
 
-from fixtures import TempDir
+from fixtures import MockPatch, TempDir
 from testtools import TestCase
 from testtools.twistedsupport import AsynchronousDeferredRunTest
 from twisted.internet import defer
 from twisted.logger import FileLogObserver, formatEvent, globalLogPublisher
+from unittest import mock
 
 from lpbuildd.builder import Builder, BuildManager, _sanitizeURLs
 from lpbuildd.tests.fakebuilder import FakeConfig
@@ -83,17 +85,32 @@ class TestBuildManager(TestCase):
         builder = Builder(config)
         builder._log = io.BytesIO()
         manager = BuildManager(builder, "123")
+
+        # Mock datetime.datetime.now() method
+        now = datetime.now()
+        mock_datetime = self.useFixture(
+            MockPatch(
+                "lpbuildd.builder.datetime"
+            )
+        ).mock
+        mock_datetime.now = lambda: now
+
         d = defer.Deferred()
         manager.iterate = d.callback
         manager.runSubProcess("echo", ["echo", "hello world"])
         code = yield d
         self.assertEqual(0, code)
+        
+        # Prepare the same timestamp format as the buildlogs
+        timestamp = f"[{now.replace(tzinfo=timezone.utc).ctime()}]\n"
+
         self.assertEqual(
-            b"RUN: echo 'hello world'\n" b"hello world\n",
+            timestamp.encode() + "RUN: echo 'hello world'\n" "hello world\n".encode(),
             builder._log.getvalue(),
         )
+        
         self.assertEqual(
-            "Build log: RUN: echo 'hello world'\n" "Build log: hello world\n",
+            f"Build log: {timestamp}" + "Build log: RUN: echo 'hello world'\n" + "Build log: hello world\n",
             self.log_file.getvalue(),
         )
 
@@ -104,19 +121,41 @@ class TestBuildManager(TestCase):
         builder = Builder(config)
         builder._log = io.BytesIO()
         manager = BuildManager(builder, "123")
+
+        # Mock datetime.datetime.now() method
+        now = datetime.now()
+        mock_datetime = self.useFixture(
+            MockPatch(
+                "lpbuildd.builder.datetime"
+            )
+        ).mock
+        mock_datetime.now = lambda: now
+
         d = defer.Deferred()
         manager.iterate = d.callback
         manager.runSubProcess("echo", ["echo", "\N{SNOWMAN}".encode()])
         code = yield d
         self.assertEqual(0, code)
+
+        # Prepare the same timestamp format as the buildlogs
+        timestamp = f"[{now.replace(tzinfo=timezone.utc).ctime()}]\n"
+
         self.assertEqual(
-            "RUN: echo '\N{SNOWMAN}'\n" "\N{SNOWMAN}\n".encode(),
+            timestamp.encode() + "RUN: echo '\N{SNOWMAN}'\n" "\N{SNOWMAN}\n".encode(),
             builder._log.getvalue(),
         )
+
+        # Separated the tests with self.log_file to ensure the regex tests of 
+        # the second part don't mix with timestamp equality test.
+        self.assertEqual(
+            f"Build log: {timestamp}"[:-1], # Excluding the newline character
+            self.log_file.getvalue().splitlines()[0]
+        )
+
         self.assertEqual(
             ["Build log: RUN: echo '\N{SNOWMAN}'", "Build log: \N{SNOWMAN}"],
             [
                 re.sub(r".*? \[-\] (.*)", r"\1", line)
-                for line in self.log_file.getvalue().splitlines()
+                for line in self.log_file.getvalue().splitlines()[1:]
             ],
         )