git_command: Augment underlying git errors with suggestions

This change appends suggestions to the underlying git error to make the
error slightly more actionable.

DD: go/improve-repo-error-reporting & go/tee-repo-stderr

Bug: b/292704435
Change-Id: I2bf8bea5fca42c6a9acd2fadc70f58f22456e027
Reviewed-on: https://gerrit-review.googlesource.com/c/git-repo/+/387774
Commit-Queue: Aravind Vasudevan <aravindvasudev@google.com>
Reviewed-by: Jason Chang <jasonnc@google.com>
Tested-by: Aravind Vasudevan <aravindvasudev@google.com>
Reviewed-by: Aravind Vasudevan <aravindvasudev@google.com>

git_command.py

@@ -15,6 +15,7 @@
 import functools
 import json
 import os
+import re
 import subprocess
 import sys
 from typing import Any, Optional
@@ -24,6 +25,7 @@ from error import RepoExitError
 from git_refs import HEAD
 from git_trace2_event_log_base import BaseEventLog
 import platform_utils
+from repo_logging import RepoLogger
 from repo_trace import IsTrace
 from repo_trace import REPO_TRACE
 from repo_trace import Trace
@@ -50,9 +52,11 @@ DEFAULT_GIT_FAIL_MESSAGE = "git command failure"
 ERROR_EVENT_LOGGING_PREFIX = "RepoGitCommandError"
 # Common line length limit
 GIT_ERROR_STDOUT_LINES = 1
-GIT_ERROR_STDERR_LINES = 1
+GIT_ERROR_STDERR_LINES = 10
 INVALID_GIT_EXIT_CODE = 126
 
+logger = RepoLogger(__file__)
+
 
 class _GitCall(object):
     @functools.lru_cache(maxsize=None)
@@ -60,7 +64,7 @@ class _GitCall(object):
         ret = Wrapper().ParseGitVersion()
         if ret is None:
             msg = "fatal: unable to detect git version"
-            print(msg, file=sys.stderr)
+            logger.error(msg)
             raise GitRequireError(msg)
         return ret
 
@@ -135,10 +139,11 @@ def GetEventTargetPath():
         # `git config --get` is documented to produce an exit status of `1`
         # if the requested variable is not present in the configuration.
         # Report any other return value as an error.
-        print(
+        logger.error(
             "repo: error: 'git config --get' call failed with return code: "
-            "%r, stderr: %r" % (retval, p.stderr),
+            "%r, stderr: %r",
-            file=sys.stderr,
+            retval,
+            p.stderr,
         )
     return path
 
@@ -212,7 +217,7 @@ def git_require(min_version, fail=False, msg=""):
         if msg:
             msg = " for " + msg
         error_msg = "fatal: git %s or later required%s" % (need, msg)
-        print(error_msg, file=sys.stderr)
+        logger.error(error_msg)
         raise GitRequireError(error_msg)
     return False
 
@@ -297,6 +302,7 @@ class GitCommand(object):
         self.project = project
         self.cmdv = cmdv
         self.verify_command = verify_command
+        self.stdout, self.stderr = None, None
 
         # Git on Windows wants its paths only using / for reliability.
         if platform_utils.isWindows():
@@ -326,14 +332,6 @@ class GitCommand(object):
                 command.append("--progress")
         command.extend(cmdv[1:])
 
-        stdin = subprocess.PIPE if input else None
-        stdout = subprocess.PIPE if capture_stdout else None
-        stderr = (
-            subprocess.STDOUT
-            if merge_output
-            else (subprocess.PIPE if capture_stderr else None)
-        )
-
         event_log = (
             BaseEventLog(env=env, add_init_count=True)
             if add_event_log
@@ -344,9 +342,9 @@ class GitCommand(object):
             self._RunCommand(
                 command,
                 env,
-                stdin=stdin,
+                capture_stdout=capture_stdout,
-                stdout=stdout,
+                capture_stderr=capture_stderr,
-                stderr=stderr,
+                merge_output=merge_output,
                 ssh_proxy=ssh_proxy,
                 cwd=cwd,
                 input=input,
@@ -377,13 +375,46 @@ class GitCommand(object):
         self,
         command,
         env,
-        stdin=None,
+        capture_stdout=False,
-        stdout=None,
+        capture_stderr=False,
-        stderr=None,
+        merge_output=False,
         ssh_proxy=None,
         cwd=None,
         input=None,
     ):
+        # Set subprocess.PIPE for streams that need to be captured.
+        stdin = subprocess.PIPE if input else None
+        stdout = subprocess.PIPE if capture_stdout else None
+        stderr = (
+            subprocess.STDOUT
+            if merge_output
+            else (subprocess.PIPE if capture_stderr else None)
+        )
+
+        # tee_stderr acts like a tee command for stderr, in that, it captures
+        # stderr from the subprocess and streams it back to sys.stderr, while
+        # keeping a copy in-memory.
+        # This allows us to store stderr logs from the subprocess into
+        # GitCommandError.
+        # Certain git operations, such as `git push`, writes diagnostic logs,
+        # such as, progress bar for pushing, into stderr. To ensure we don't
+        # break git's UX, we need to write to sys.stderr as we read from the
+        # subprocess. Setting encoding or errors makes subprocess return
+        # io.TextIOWrapper, which is line buffered. To avoid line-buffering
+        # while tee-ing stderr, we unset these kwargs. See GitCommand._Tee
+        # for tee-ing between the streams.
+        # We tee stderr iff the caller doesn't want to capture any stream to
+        # not disrupt the existing flow.
+        # See go/tee-repo-stderr for more context.
+        tee_stderr = False
+        kwargs = {"encoding": "utf-8", "errors": "backslashreplace"}
+        if not (stdin or stdout or stderr):
+            tee_stderr = True
+            # stderr will be written back to sys.stderr even though it is
+            # piped here.
+            stderr = subprocess.PIPE
+            kwargs = {}
+
         dbg = ""
         if IsTrace():
             global LAST_CWD
@@ -430,11 +461,10 @@ class GitCommand(object):
                     command,
                     cwd=cwd,
                     env=env,
-                    encoding="utf-8",
-                    errors="backslashreplace",
                     stdin=stdin,
                     stdout=stdout,
                     stderr=stderr,
+                    **kwargs,
                 )
             except Exception as e:
                 raise GitPopenCommandError(
@@ -449,12 +479,44 @@ class GitCommand(object):
             self.process = p
 
             try:
+                if tee_stderr:
+                    # tee_stderr streams stderr to sys.stderr while capturing
+                    # a copy within self.stderr. tee_stderr is only enabled
+                    # when the caller wants to pipe no stream.
+                    self.stderr = self._Tee(p.stderr, sys.stderr)
+                else:
                     self.stdout, self.stderr = p.communicate(input=input)
             finally:
                 if ssh_proxy:
                     ssh_proxy.remove_client(p)
             self.rc = p.wait()
 
+    @staticmethod
+    def _Tee(in_stream, out_stream):
+        """Writes text from in_stream to out_stream while recording in buffer.
+
+        Args:
+            in_stream: I/O stream to be read from.
+            out_stream: I/O stream to write to.
+
+        Returns:
+            A str containing everything read from the in_stream.
+        """
+        buffer = ""
+        chunk = in_stream.read1()
+        while chunk:
+            # Convert to str.
+            if not hasattr(chunk, "encode"):
+                chunk = chunk.decode("utf-8", "backslashreplace")
+
+            buffer += chunk
+            out_stream.write(chunk)
+            out_stream.flush()
+
+            chunk = in_stream.read1()
+
+        return buffer
+
     @staticmethod
     def _GetBasicEnv():
         """Return a basic env for running git under.
@@ -517,6 +579,29 @@ class GitCommandError(GitError):
     raised exclusively from non-zero exit codes returned from git commands.
     """
 
+    # Tuples with error formats and suggestions for those errors.
+    _ERROR_TO_SUGGESTION = [
+        (
+            re.compile("couldn't find remote ref .*"),
+            "Check if the provided ref exists in the remote.",
+        ),
+        (
+            re.compile("unable to access '.*': .*"),
+            (
+                "Please make sure you have the correct access rights and the "
+                "repository exists."
+            ),
+        ),
+        (
+            re.compile("'.*' does not appear to be a git repository"),
+            "Are you running this repo command outside of a repo workspace?",
+        ),
+        (
+            re.compile("not a git repository"),
+            "Are you running this repo command outside of a repo workspace?",
+        ),
+    ]
+
     def __init__(
         self,
         message: str = DEFAULT_GIT_FAIL_MESSAGE,
@@ -533,16 +618,37 @@ class GitCommandError(GitError):
         self.git_stdout = git_stdout
         self.git_stderr = git_stderr
 
+    @property
+    @functools.lru_cache
+    def suggestion(self):
+        """Returns helpful next steps for the given stderr."""
+        if not self.git_stderr:
+            return self.git_stderr
+
+        for err, suggestion in self._ERROR_TO_SUGGESTION:
+            if err.search(self.git_stderr):
+                return suggestion
+
+        return None
+
     def __str__(self):
         args = "[]" if not self.command_args else " ".join(self.command_args)
         error_type = type(self).__name__
-        return f"""{error_type}: {self.message}
+        string = f"{error_type}: '{args}' on {self.project} failed"
-    Project: {self.project}
+
-    Args: {args}
+        if self.message != DEFAULT_GIT_FAIL_MESSAGE:
-    Stdout:
+            string += f": {self.message}"
-{self.git_stdout}
+
-    Stderr:
+        if self.git_stdout:
-{self.git_stderr}"""
+            string += f"\nstdout: {self.git_stdout}"
+
+        if self.git_stderr:
+            string += f"\nstderr: {self.git_stderr}"
+
+        if self.suggestion:
+            string += f"\nsuggestion: {self.suggestion}"
+
+        return string
 
 
 class GitPopenCommandError(GitError):

project.py

@@ -1135,7 +1135,7 @@ class Project(object):
         url = branch.remote.ReviewUrl(self.UserEmail, validate_certs)
         if url is None:
             raise UploadError("review not configured", project=self.name)
-        cmd = ["push"]
+        cmd = ["push", "--progress"]
         if dryrun:
             cmd.append("-n")
 

tests/test_git_command.py

@@ -14,6 +14,7 @@
 
 """Unittests for the git_command.py module."""
 
+import io
 import os
 import re
 import subprocess
@@ -74,6 +75,10 @@ class GitCommandWaitTest(unittest.TestCase):
         class MockPopen(object):
             rc = 0
 
+            def __init__(self):
+                self.stdout = io.BufferedReader(io.BytesIO())
+                self.stderr = io.BufferedReader(io.BytesIO())
+
             def communicate(
                 self, input: str = None, timeout: float = None
             ) -> [str, str]:
@@ -117,6 +122,115 @@ class GitCommandWaitTest(unittest.TestCase):
         self.assertEqual(1, r.Wait())
 
 
+class GitCommandStreamLogsTest(unittest.TestCase):
+    """Tests the GitCommand class stderr log streaming cases."""
+
+    def setUp(self):
+        self.mock_process = mock.MagicMock()
+        self.mock_process.communicate.return_value = (None, None)
+        self.mock_process.wait.return_value = 0
+
+        self.mock_popen = mock.MagicMock()
+        self.mock_popen.return_value = self.mock_process
+        mock.patch("subprocess.Popen", self.mock_popen).start()
+
+    def tearDown(self):
+        mock.patch.stopall()
+
+    def test_does_not_stream_logs_when_input_is_set(self):
+        git_command.GitCommand(None, ["status"], input="foo")
+
+        self.mock_popen.assert_called_once_with(
+            ["git", "status"],
+            cwd=None,
+            env=mock.ANY,
+            encoding="utf-8",
+            errors="backslashreplace",
+            stdin=subprocess.PIPE,
+            stdout=None,
+            stderr=None,
+        )
+        self.mock_process.communicate.assert_called_once_with(input="foo")
+        self.mock_process.stderr.read1.assert_not_called()
+
+    def test_does_not_stream_logs_when_stdout_is_set(self):
+        git_command.GitCommand(None, ["status"], capture_stdout=True)
+
+        self.mock_popen.assert_called_once_with(
+            ["git", "status"],
+            cwd=None,
+            env=mock.ANY,
+            encoding="utf-8",
+            errors="backslashreplace",
+            stdin=None,
+            stdout=subprocess.PIPE,
+            stderr=None,
+        )
+        self.mock_process.communicate.assert_called_once_with(input=None)
+        self.mock_process.stderr.read1.assert_not_called()
+
+    def test_does_not_stream_logs_when_stderr_is_set(self):
+        git_command.GitCommand(None, ["status"], capture_stderr=True)
+
+        self.mock_popen.assert_called_once_with(
+            ["git", "status"],
+            cwd=None,
+            env=mock.ANY,
+            encoding="utf-8",
+            errors="backslashreplace",
+            stdin=None,
+            stdout=None,
+            stderr=subprocess.PIPE,
+        )
+        self.mock_process.communicate.assert_called_once_with(input=None)
+        self.mock_process.stderr.read1.assert_not_called()
+
+    def test_does_not_stream_logs_when_merge_output_is_set(self):
+        git_command.GitCommand(None, ["status"], merge_output=True)
+
+        self.mock_popen.assert_called_once_with(
+            ["git", "status"],
+            cwd=None,
+            env=mock.ANY,
+            encoding="utf-8",
+            errors="backslashreplace",
+            stdin=None,
+            stdout=None,
+            stderr=subprocess.STDOUT,
+        )
+        self.mock_process.communicate.assert_called_once_with(input=None)
+        self.mock_process.stderr.read1.assert_not_called()
+
+    @mock.patch("sys.stderr")
+    def test_streams_stderr_when_no_stream_is_set(self, mock_stderr):
+        logs = "\n".join(
+            [
+                "Enumerating objects: 5, done.",
+                "Counting objects: 100% (5/5), done.",
+                "Writing objects: 100% (3/3), 330 bytes | 330 KiB/s, done.",
+                "remote: Processing changes: refs: 1, new: 1, done ",
+                "remote: SUCCESS",
+            ]
+        )
+        self.mock_process.stderr = io.BufferedReader(
+            io.BytesIO(bytes(logs, "utf-8"))
+        )
+
+        cmd = git_command.GitCommand(None, ["push"])
+
+        self.mock_popen.assert_called_once_with(
+            ["git", "push"],
+            cwd=None,
+            env=mock.ANY,
+            stdin=None,
+            stdout=None,
+            stderr=subprocess.PIPE,
+        )
+        self.mock_process.communicate.assert_not_called()
+        mock_stderr.write.assert_called_once_with(logs)
+        self.assertEqual(cmd.stderr, logs)
+
+
 class GitCallUnitTest(unittest.TestCase):
     """Tests the _GitCall class (via git_command.git)."""
 
@@ -214,3 +328,22 @@ class GitRequireTests(unittest.TestCase):
         with self.assertRaises(git_command.GitRequireError) as e:
             git_command.git_require((2,), fail=True, msg="so sad")
             self.assertNotEqual(0, e.code)
+
+
+class GitCommandErrorTest(unittest.TestCase):
+    """Test for the GitCommandError class."""
+
+    def test_augument_stderr(self):
+        self.assertEqual(
+            git_command.GitCommandError(
+                git_stderr="couldn't find remote ref refs/heads/foo"
+            ).suggestion,
+            "Check if the provided ref exists in the remote.",
+        )
+
+        self.assertEqual(
+            git_command.GitCommandError(
+                git_stderr="'foobar' does not appear to be a git repository"
+            ).suggestion,
+            "Are you running this repo command outside of a repo workspace?",
+        )