Repository: gitpython-developers/GitPython (python)

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.

Pull request:
Have initial refresh use a logger to warn
Fixes #1808 

Code changes in the `git` module:

- When the initial call to `git.refresh` that happens on import fails to find a `git` command and is configured to warn, it warns using a logger rather than with `print`. Although this is conceptually a warning, it is emitted with level `CRTICAL`, for the reasons given in ac50d8e (the commit in this PR that changes the tests for it).

- The message is changed to document this.

- A few more values, for existing `GIT_PYTHON_REFRESH` modes, are added as synonyms. No new modes are added, nor are their states expanded. The motivation for adding new synonyms is so `log` achieves logging, i.e., it is another way to say `warn`. But `l` is also added as its short form. (This might ordinarily be objected to on the grounds that, when written as `l` and not the also-recognized `L`, it could be confused with `1`. Fortunately `1` also means `warn`, so `1` and `l` will have the same meaning anyway.) Furthermore, `silent` is added as a synonym of `quiet`, since `silence` is already recognized for that, so `silent` seems likely to be used by accident anyway.

  The reason I have not gone further at this time (as was discussed in [the second part of this comment](https://github.com/gitpython-developers/GitPython/issues/1808#issuecomment-1913709517) and in [this reply](https://github.com/gitpython-developers/GitPython/issues/1808#issuecomment-1914143887)) is it can be made more configurable in the future if it looks like that is valuable, but removing existing configurability could break more uses. Furthermore, because the level is `CRITICAL` which differs from that of any other GitPython messages, the better approach of controlling the effect in an application's own logging configuration may be sufficient.

Test changes:

- Rename some existing tests more specifically, so they are not confused with new ones. These are the tests of subsequent (i.e., non-initial) calls to `git.refresh` when an explicit `path` argument is passed.

- Test subsequent refreshes performed with no arguments. That is, test calls to `git.refresh` with no arguments, without simulating the state of not yet having performed an initial refresh. This behavior is not changed in this pull request, but it makes sense to test it, doing so may avoid confusion with the different initial-refresh behavior when reading the tests, and the important subtlety of when relative paths are and aren't resolved is made clearer.

- Test an initial refresh. This is a refresh with no arguments that is performed on import, but to make the relationship to the other tests clearer, reduce test complexity, and make the tests run faster (since some of them run with all documented values of `GIT_PYTHON_REFRESH`), this simulates that state by setting `Git.GIT_PYTHON_GIT_EXECUTABLE` to `None` rather than starting a Python subprocess to do an import.

  This includes testing the behavioral change made in this PR and described above.

- Test the new synonyms of existing values for `GIT_PYTHON_REFRESH` (such as `log` for `warn`).

I added the tests first. For the initial-refresh test, I first wrote it for the preexisting behavior, modified it for the desired behavior and saw it fail. Then I applied the changes, causing the tests to pass again. Those changes are based on, but not quite the same as, dc62096 as discussed in #1813 and https://github.com/gitpython-developers/GitPython/issues/1808#issuecomment-1913709517.

There is some more information in commit messages, especially ac50d8e.

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)