Have initial refresh use a logger to warn

[EliahKagan]

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 and in this reply) 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 #1808 (comment).

There is some more information in commit messages, especially ac50d8e.

[Byron]

Thanks so much! With this PR it seems reasonable to claim that the messaging in GitPython is finally consistent. Everything uses logging, and messages are no suppressed by default.

I particularly love that you managed to do test-driven development here, that's the way (for those who have the experience to set up such tests in the first place).

Admission: I only skimmed the tests themselves due to my own state of mind and the trust in the PRs author.

[EliahKagan]

Although it's not really an inconsistency in the sense that you mean, I should mention that the way the message is prefixed is imperfect. I am unsure if there is a better way. The message itself begins, as before:

WARNING: Bad git executable.

When logging is not configured, logging.lastResort prints that to standard error just like that. However, if logging has been configured, then most commonly a prefix indicating the logger and level is shown. In particular, when logging.basicConfig() is called with no arguments to configure logging, the actual logged message is of course the same, but the way it is displayed begins:

CRITICAL:git.cmd:WARNING: Bad git executable.

That's a bit weird, but I'm unsure if anything should be done to change it. I don't recommend having the message itself differ based on whether or not or how logging is configured. But maybe WARNING should be changed to to Warning so it looks less like a contradictory indication of a logging level? Then again, that may make it slightly less visible when no prefix is shown. I am not sure.

With this PR it seems reasonable to claim that the messaging in GitPython is finally consistent.

I plan to look for possible remaining inconsistencies, so I'll try to either comment here about not finding them, or open one or more issues or PRs for any that I do find.

Everything uses logging, and messages are no suppressed by default.

I agree. In particular, I looked for other print statements in the git module and did not find them.

Admission: I only skimmed the tests themselves due to my own state of mind and the trust in the PRs author.

The tests contain some code duplication. The ways of reducing it that I thought of didn't seem like they would necessarily be improvements, though future changes might worsen the situation and make it more important to extract shared logic, if it becomes important to test more combinations of environment variables.

I bring this up only in case you already happened to notice that the duplication, or volume of the new tests, made them less scrutable than ideal. If that was the case, I can take another look at them.

[Byron]

That's a bit weird, but I'm unsure if anything should be done to change it. I don't recommend having the message itself differ based on whether or not or how logging is configured. But maybe WARNING should be changed to to Warning so it looks less like a contradictory indication of a logging level? Then again, that may make it slightly less visible when no prefix is shown. I am not sure.

My intuition here is to remove it, and allow logging to deal with levels so GitPython can focus on the message.

I bring this up only in case you already happened to notice that the duplication, or volume of the new tests, made them less scrutable than ideal. If that was the case, I can take another look at them.

I would not suggest to spend time on any deduplication, it was just me feeling a bit rushed while still thinking the PR should be merged, all things considered.

[EliahKagan]

The one other inconsistency I found in the messages is that the git command used is shown only in the exception message on a subsequent refresh, but not shown in exception message from an initial refresh or in the logged message on an initial refresh in warn mode.

I am unsure if this should really be changed or if it even really is a real inconsistency. ImportError is raised on an initial failed refresh, while GitCommandNotFoundError is raised on a failed subsequent refresh.

I suspect the reason it was not included was that there was never originally a goal to include it anywhere, which may also partially explain #1809. Even though #1809 is fixed by the changes in #1812, I don't think this necessarily means the other messages--which are not in any way inaccurate or misleading--need to be expanded to include that information.

Other than the above, I can think of two other reasons the information may not be included in those messages, one of which is obsolete but the other of which may still be applicable:

• Obsolete reason: In rare cases the path could be sensitive. It is not sensitive enough that it shouldn't be logged, but the message used to be printed to standard output with print rather than using the logging framework, and some applications (e.g., web applications) that use GitPython might make standard output accessible to users who are not fully trusted. This is a marginal reason and I suspect it was not even a factor, but even if this was the reason, it is not applicable anymore because logging is used since #1808.
• Still-relevant reason: The message is already long and complicated enough. If it gave a path and the path is git, then the user probably already knew that. When the path is not git, that is useful debugging information, especially if the user expected it to be git, and this may be a reason to include the path. However, it is possible that some users would try to make git available at that path, rather than configuring the path differently as described in the rest of the message. When investigating problems interactively, one may call refresh manually, but then one gets a GitCommandNotFound exception with the path.

I would not suggest to spend time on any deduplication, it was just me feeling a bit rushed while still thinking the PR should be merged, all things considered.

No problem! If we end up showing the command in more messages as discussed above, then the duplication in the tests (to test such a change) might become worse, in which case I'll take another look. Otherwise I won't worry about it.

My intuition here is to remove it, and allow logging to deal with levels so GitPython can focus on the message.

I've made that change in #1816.