project: trace fetchcmd and reprojectcmd executions

Wrap repo.fetchcmd and repo.reprojectcmd subprocess invocations in
Trace blocks so TRACE_FILE records START/END spans for custom fetch and
reproject commands alongside standard Git commands.

Bug: 564817989
Change-Id: I68a4d863370e7c46d144e35e5826d01b386b9b07
Reviewed-on: https://gerrit-review.googlesource.com/c/git-repo/+/649603
Commit-Queue: Gavin Mak <gavinmak@google.com>
Tested-by: Gavin Mak <gavinmak@google.com>
Reviewed-by: Haamed Gheibi <haamed@google.com>
Reviewed-by: Gavin Mak <gavinmak@google.com>

project.py

@@ -3293,28 +3293,35 @@ class Project:
 
         stdout = None if verbose else subprocess.PIPE
         stderr = None if verbose else subprocess.PIPE
-        try:
-            p = subprocess.run(
-                cmd_str,
-                shell=True,
-                cwd=self.manifest.topdir,
-                env=env,
-                stdout=stdout,
-                stderr=stderr,
-                text=True,
-            )
-
-            if p.returncode != 0:
-                logger.error(
-                    "error: fetchcmd failed with exit code %d", p.returncode
+        with repo_trace.Trace(
+            "fetchcmd %s %s (REPO_PATH=%s REPO_TREV=%s)",
+            self.gitdir,
+            cmd_str,
+            self.relpath,
+            repo_trev or "",
+        ):
+            try:
+                p = subprocess.run(
+                    cmd_str,
+                    shell=True,
+                    cwd=self.manifest.topdir,
+                    env=env,
+                    stdout=stdout,
+                    stderr=stderr,
+                    text=True,
                 )
-                if not verbose:
-                    logger.error("stderr: %s", p.stderr)
-                return False
 
-        except Exception as e:
-            logger.error("error: Failed to execute fetchcmd: %s", e)
-            return False
+                if p.returncode != 0:
+                    logger.error(
+                        "error: fetchcmd failed with exit code %d", p.returncode
+                    )
+                    if not verbose:
+                        logger.error("stderr: %s", p.stderr)
+                    return False
+
+            except Exception as e:
+                logger.error("error: Failed to execute fetchcmd: %s", e)
+                return False
 
         # Verify postconditions.
         if not IsId(self.revisionExpr):
@@ -4153,20 +4160,27 @@ class Project:
             print(f"Running reprojectcmd: {cmd_str} for {self.name}")
 
         output = None if verbose else subprocess.PIPE
-        try:
-            p = subprocess.run(
-                cmd_str,
-                shell=True,
-                cwd=self.manifest.topdir,
-                env=env,
-                stdout=output,
-                stderr=None if verbose else subprocess.STDOUT,
-                text=True,
-            )
-        except OSError as e:
-            raise LocalSyncFail(
-                f"failed to run reprojectcmd: {e}", project=self.name
-            )
+        with repo_trace.Trace(
+            "reprojectcmd %s %s (REPO_PATH=%s REPO_TREV=%s)",
+            self.gitdir,
+            cmd_str,
+            self.relpath,
+            revid,
+        ):
+            try:
+                p = subprocess.run(
+                    cmd_str,
+                    shell=True,
+                    cwd=self.manifest.topdir,
+                    env=env,
+                    stdout=output,
+                    stderr=None if verbose else subprocess.STDOUT,
+                    text=True,
+                )
+            except OSError as e:
+                raise LocalSyncFail(
+                    f"failed to run reprojectcmd: {e}", project=self.name
+                )
         if p.returncode != 0:
             msg = f"reprojectcmd exited with {p.returncode}"
             if p.stdout:

tests/test_project.py

@@ -3609,6 +3609,54 @@ class FetchCmdTests(unittest.TestCase):
             proj._ApplyCloneBundle.assert_not_called()
             proj._CustomFetch.assert_called_once()
 
+    def test_fetch_cmd_traces_execution(self) -> None:
+        """Test _CustomFetch traces execution and propagates trace OSError."""
+        with utils_for_test.TempGitTree() as tempdir:
+            sha = "0123456789abcdef0123456789abcdef01234567"
+            proj = self._get_project(tempdir)
+            proj.revisionId = None
+            proj.revisionExpr = "main"
+            proj.bare_git.ResolveCommit.return_value = sha
+            mock_remote = mock.MagicMock()
+            mock_remote.ToLocal.return_value = "refs/remotes/origin/main"
+            proj.GetRemote = mock.MagicMock(return_value=mock_remote)
+
+            with mock.patch("repo_trace.Trace") as mock_trace, mock.patch(
+                "subprocess.run"
+            ) as mock_run:
+                mock_run.return_value = mock.MagicMock(returncode=0, stderr="")
+                self.assertTrue(proj._CustomFetch())
+
+            mock_trace.assert_called_once_with(
+                "fetchcmd %s %s (REPO_PATH=%s REPO_TREV=%s)",
+                proj.gitdir,
+                "echo hi",
+                proj.relpath,
+                "",
+            )
+
+            proj.revisionId = sha
+            with mock.patch("repo_trace.Trace") as mock_trace, mock.patch(
+                "subprocess.run"
+            ) as mock_run:
+                mock_run.return_value = mock.MagicMock(returncode=0, stderr="")
+                self.assertTrue(proj._CustomFetch())
+
+            mock_trace.assert_called_once_with(
+                "fetchcmd %s %s (REPO_PATH=%s REPO_TREV=%s)",
+                proj.gitdir,
+                "echo hi",
+                proj.relpath,
+                sha,
+            )
+
+            with mock.patch(
+                "repo_trace.Trace", side_effect=OSError("trace disk full")
+            ), mock.patch("subprocess.run") as mock_run:
+                with self.assertRaises(OSError):
+                    proj._CustomFetch()
+                mock_run.assert_not_called()
+
 
 class ReprojectCmdTests(unittest.TestCase):
     """Tests for the repo.reprojectcmd feature."""
@@ -4135,6 +4183,32 @@ class ReprojectCmdTests(unittest.TestCase):
                 mock_allrefs.assert_not_called()
                 proj.bare_git.ResolveCommit.assert_not_called()
 
+    def test_reproject_traces_execution(self) -> None:
+        """Test _Reproject traces execution and propagates trace OSError."""
+        with utils_for_test.TempGitTree() as tempdir:
+            proj = self._get_project(tempdir)
+            with mock.patch("repo_trace.Trace") as mock_trace:
+                self._reproject(proj)
+
+            mock_trace.assert_called_once_with(
+                "reprojectcmd %s %s (REPO_PATH=%s REPO_TREV=%s)",
+                proj.gitdir,
+                "echo reproject",
+                proj.relpath,
+                self.REVID,
+            )
+
+            with mock.patch(
+                "git_command.GitCommand", side_effect=self._git_command()
+            ), mock.patch(
+                "repo_trace.Trace", side_effect=OSError("trace disk full")
+            ), mock.patch(
+                "subprocess.run"
+            ) as mock_run:
+                with self.assertRaises(OSError):
+                    proj._Reproject(self.REVID)
+                mock_run.assert_not_called()
+
 
 class ReprojectCmdGitTests(unittest.TestCase):
     """Tests running the reprojectcmd contract against a real Git checkout."""