Repository: gitpython-developers/GitPython

Issue:
Git.refresh warns to stdout and does not log
Warning messages are most often written to standard error. Furthermore, warnings from GitPython, when they are displayed, are in most cases displayed that way unless the caller arranges otherwise, because they are displayed by calling loggers' `warning` methods or, for `DeprecationWarning`s, by calling `warnings.warn`.

However, the warning `Git.refresh` displays when running a test command like `git --version` (with the command being tested used for `git`) fails, and `GIT_PYTHON_REFRESH` is set to `1`, `w`, `warn`, or `warning`, is different. It is printed to standard output. It also does not use any logging facility, so attempts to capture it by configuring Python logging will not succeed.

https://github.com/gitpython-developers/GitPython/blob/d28c20b1dbf18dc60a2b1859e818801bd8d742f2/git/cmd.py#L453-L454

If there is a reason for this behavior, then I think it should be commented or otherwise stated. Otherwise, I am not sure what to do. It may still not be feasible to change, because programs that use GitPython may be relying on the warning being printed to standard output, or on it not being printed to standard error. But if he behavior is going to change in the next major version, then that could be commented and/or this issue could be kept open until then. If the reason is unknown and it is undecided whether the behavior should be changed in the next major release, then a comment could be added just saying that it prints to standard output for backward compatibility.

Discussion:

Patch:
diff --git a/git/cmd.py b/git/cmd.py
index a75d822f..22b5ea99 100644
--- a/git/cmd.py
+++ b/git/cmd.py
@@ -409,15 +409,15 @@ class Git(LazyMixin):
                 # expect GIT_PYTHON_REFRESH to either be unset or be one of the
                 # following values:
                 #
-                #   0|q|quiet|s|silence|n|none
-                #   1|w|warn|warning
-                #   2|r|raise|e|error
+                #   0|q|quiet|s|silence|silent|n|none
+                #   1|w|warn|warning|l|log
+                #   2|r|raise|e|error|exception
 
                 mode = os.environ.get(cls._refresh_env_var, "raise").lower()
 
-                quiet = ["quiet", "q", "silence", "s", "none", "n", "0"]
-                warn = ["warn", "w", "warning", "1"]
-                error = ["error", "e", "raise", "r", "2"]
+                quiet = ["quiet", "q", "silence", "s", "silent", "none", "n", "0"]
+                warn = ["warn", "w", "warning", "log", "l", "1"]
+                error = ["error", "e", "exception", "raise", "r", "2"]
 
                 if mode in quiet:
                     pass
@@ -428,10 +428,10 @@ class Git(LazyMixin):
                         %s
                         All git commands will error until this is rectified.
 
-                        This initial warning can be silenced or aggravated in the future by setting the
+                        This initial message can be silenced or aggravated in the future by setting the
                         $%s environment variable. Use one of the following values:
-                            - %s: for no warning or exception
-                            - %s: for a printed warning
+                            - %s: for no message or exception
+                            - %s: for a warning message (logged at level CRITICAL, displayed by default)
                             - %s: for a raised exception
 
                         Example:
@@ -450,7 +450,7 @@ class Git(LazyMixin):
                     )
 
                     if mode in warn:
-                        print("WARNING: %s" % err)
+                        _logger.critical("WARNING: %s", err)
                     else:
                         raise ImportError(err)
                 else:
@@ -460,8 +460,8 @@ class Git(LazyMixin):
                         %s environment variable has been set but it has been set with an invalid value.
 
                         Use only the following values:
-                            - %s: for no warning or exception
-                            - %s: for a printed warning
+                            - %s: for no message or exception
+                            - %s: for a warning message (logged at level CRITICAL, displayed by default)
                             - %s: for a raised exception
                         """
                         )


Test patch:
diff --git a/test/test_git.py b/test/test_git.py
index a1c6211d..ea3d067e 100644
--- a/test/test_git.py
+++ b/test/test_git.py
@@ -46,9 +46,24 @@ def _patch_out_env(name):
 
 @contextlib.contextmanager
 def _rollback_refresh():
+    old_git_executable = Git.GIT_PYTHON_GIT_EXECUTABLE
+
+    if old_git_executable is None:
+        raise RuntimeError("no executable string (need initial refresh before test)")
+
     try:
-        yield Git.GIT_PYTHON_GIT_EXECUTABLE  # Provide the old value for convenience.
+        yield old_git_executable  # Provide the old value for convenience.
     finally:
+        # The cleanup refresh should always raise an exception if it fails, since if it
+        # fails then previously discovered test results could be misleading and, more
+        # importantly, subsequent tests may be unable to run or give misleading results.
+        # So pre-set a non-None value, so that the cleanup will be a "second" refresh.
+        # This covers cases where a test has set it to None to test a "first" refresh.
+        Git.GIT_PYTHON_GIT_EXECUTABLE = Git.git_exec_name
+
+        # Do the cleanup refresh. This sets Git.GIT_PYTHON_GIT_EXECUTABLE to old_value
+        # in most cases. The reason to call it is to achieve other associated state
+        # changes as well, which include updating attributes of the FetchInfo class.
         refresh()
 
 
@@ -314,7 +329,127 @@ class TestGit(TestBase):
         ):
             self.assertRaises(GitCommandNotFound, self.git.version)
 
-    def test_refresh_bad_absolute_git_path(self):
+    def test_git_exc_name_is_git(self):
+        self.assertEqual(self.git.git_exec_name, "git")
+
+    @ddt.data(("0",), ("q",), ("quiet",), ("s",), ("silence",), ("silent",), ("n",), ("none",))
+    def test_initial_refresh_from_bad_git_path_env_quiet(self, case):
+        """In "q" mode, bad initial path sets "git" and is quiet."""
+        (mode,) = case
+        set_vars = {
+            "GIT_PYTHON_GIT_EXECUTABLE": str(Path("yada").absolute()),  # Any bad path.
+            "GIT_PYTHON_REFRESH": mode,
+        }
+        with _rollback_refresh():
+            type(self.git).GIT_PYTHON_GIT_EXECUTABLE = None  # Simulate startup.
+
+            with mock.patch.dict(os.environ, set_vars):
+                refresh()
+                self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, "git")
+
+    @ddt.data(("1",), ("w",), ("warn",), ("warning",), ("l",), ("log",))
+    def test_initial_refresh_from_bad_git_path_env_warn(self, case):
+        """In "w" mode, bad initial path sets "git" and warns, by logging."""
+        (mode,) = case
+        env_vars = {
+            "GIT_PYTHON_GIT_EXECUTABLE": str(Path("yada").absolute()),  # Any bad path.
+            "GIT_PYTHON_REFRESH": mode,
+        }
+        with _rollback_refresh():
+            type(self.git).GIT_PYTHON_GIT_EXECUTABLE = None  # Simulate startup.
+
+            with mock.patch.dict(os.environ, env_vars):
+                with self.assertLogs(cmd.__name__, logging.CRITICAL) as ctx:
+                    refresh()
+                self.assertEqual(len(ctx.records), 1)
+                message = ctx.records[0].getMessage()
+                self.assertRegex(message, r"\AWARNING: Bad git executable.\n")
+                self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, "git")
+
+    @ddt.data(("2",), ("r",), ("raise",), ("e",), ("error",))
+    def test_initial_refresh_from_bad_git_path_env_error(self, case):
+        """In "e" mode, bad initial path raises an exception."""
+        (mode,) = case
+        env_vars = {
+            "GIT_PYTHON_GIT_EXECUTABLE": str(Path("yada").absolute()),  # Any bad path.
+            "GIT_PYTHON_REFRESH": mode,
+        }
+        with _rollback_refresh():
+            type(self.git).GIT_PYTHON_GIT_EXECUTABLE = None  # Simulate startup.
+
+            with mock.patch.dict(os.environ, env_vars):
+                with self.assertRaisesRegex(ImportError, r"\ABad git executable.\n"):
+                    refresh()
+
+    def test_initial_refresh_from_good_absolute_git_path_env(self):
+        """Good initial absolute path from environment is set."""
+        absolute_path = shutil.which("git")
+
+        with _rollback_refresh():
+            type(self.git).GIT_PYTHON_GIT_EXECUTABLE = None  # Simulate startup.
+
+            with mock.patch.dict(os.environ, {"GIT_PYTHON_GIT_EXECUTABLE": absolute_path}):
+                refresh()
+                self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, absolute_path)
+
+    def test_initial_refresh_from_good_relative_git_path_env(self):
+        """Good initial relative path from environment is kept relative and set."""
+        with _rollback_refresh():
+            # Set the fallback to a string that wouldn't work and isn't "git", so we are
+            # more likely to detect if "git" is not set from the environment variable.
+            with mock.patch.object(type(self.git), "git_exec_name", ""):
+                type(self.git).GIT_PYTHON_GIT_EXECUTABLE = None  # Simulate startup.
+
+                # Now observe if setting the environment variable to "git" takes effect.
+                with mock.patch.dict(os.environ, {"GIT_PYTHON_GIT_EXECUTABLE": "git"}):
+                    refresh()
+                    self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, "git")
+
+    def test_refresh_from_bad_absolute_git_path_env(self):
+        """Bad absolute path from environment is reported and not set."""
+        absolute_path = str(Path("yada").absolute())
+        expected_pattern = rf"\n[ \t]*cmdline: {re.escape(absolute_path)}\Z"
+
+        with _rollback_refresh() as old_git_executable:
+            with mock.patch.dict(os.environ, {"GIT_PYTHON_GIT_EXECUTABLE": absolute_path}):
+                with self.assertRaisesRegex(GitCommandNotFound, expected_pattern):
+                    refresh()
+                self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, old_git_executable)
+
+    def test_refresh_from_bad_relative_git_path_env(self):
+        """Bad relative path from environment is kept relative and reported, not set."""
+        # Relative paths are not resolved when refresh() is called with no arguments, so
+        # use a string that's very unlikely to be a command name found in a path lookup.
+        relative_path = "yada-e47e70c6-acbf-40f8-ad65-13af93c2195b"
+        expected_pattern = rf"\n[ \t]*cmdline: {re.escape(relative_path)}\Z"
+
+        with _rollback_refresh() as old_git_executable:
+            with mock.patch.dict(os.environ, {"GIT_PYTHON_GIT_EXECUTABLE": relative_path}):
+                with self.assertRaisesRegex(GitCommandNotFound, expected_pattern):
+                    refresh()
+                self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, old_git_executable)
+
+    def test_refresh_from_good_absolute_git_path_env(self):
+        """Good absolute path from environment is set."""
+        absolute_path = shutil.which("git")
+
+        with _rollback_refresh():
+            with mock.patch.dict(os.environ, {"GIT_PYTHON_GIT_EXECUTABLE": absolute_path}):
+                refresh()
+                self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, absolute_path)
+
+    def test_refresh_from_good_relative_git_path_env(self):
+        """Good relative path from environment is kept relative and set."""
+        with _rollback_refresh():
+            # Set as the executable name a string that wouldn't work and isn't "git".
+            type(self.git).GIT_PYTHON_GIT_EXECUTABLE = ""
+
+            # Now observe if setting the environment variable to "git" takes effect.
+            with mock.patch.dict(os.environ, {"GIT_PYTHON_GIT_EXECUTABLE": "git"}):
+                refresh()
+                self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, "git")
+
+    def test_refresh_with_bad_absolute_git_path_arg(self):
         """Bad absolute path arg is reported and not set."""
         absolute_path = str(Path("yada").absolute())
         expected_pattern = rf"\n[ \t]*cmdline: {re.escape(absolute_path)}\Z"
@@ -324,7 +459,7 @@ class TestGit(TestBase):
                 refresh(absolute_path)
             self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, old_git_executable)
 
-    def test_refresh_bad_relative_git_path(self):
+    def test_refresh_with_bad_relative_git_path_arg(self):
         """Bad relative path arg is resolved to absolute path and reported, not set."""
         absolute_path = str(Path("yada").absolute())
         expected_pattern = rf"\n[ \t]*cmdline: {re.escape(absolute_path)}\Z"
@@ -334,7 +469,7 @@ class TestGit(TestBase):
                 refresh("yada")
             self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, old_git_executable)
 
-    def test_refresh_good_absolute_git_path(self):
+    def test_refresh_with_good_absolute_git_path_arg(self):
         """Good absolute path arg is set."""
         absolute_path = shutil.which("git")
 
@@ -342,7 +477,7 @@ class TestGit(TestBase):
             refresh(absolute_path)
             self.assertEqual(self.git.GIT_PYTHON_GIT_EXECUTABLE, absolute_path)
 
-    def test_refresh_good_relative_git_path(self):
+    def test_refresh_with_good_relative_git_path_arg(self):
         """Good relative path arg is resolved to absolute path and set."""
         absolute_path = shutil.which("git")
         dirname, basename = osp.split(absolute_path)