Don't suppress messages when logging is not configured #1813

EliahKagan · 2024-01-26T09:26:50Z

This stops adding NullHandler instances to GitPython's loggers. As noted in #1806, when they were added in #300 this prevented errors when GitPython logged messages and logging was not enabled, but since Python 3.2 there is a logger of last resort providing a nicer default behavior of showing the messages. (They are still shown with better formatting if logging is configured, even if just done with logging.basicConfig(), so applications should still typically configure logging.)

This also makes a few more minor related changes, detailed in the commit messages. This includes changing variable names from log to _logger, as mentioned in #1806 (comment), as well as consistently passing __name__ to logging.getLogger instead of hard-coding names in a few places, as mentioned in #1808 (comment).

The major effect of the changes here is that messages of level WARNING or higher are not suppressed by default anymore, even when logging is not configured. So I could have included a change here to take care of #1808 as well, such as dc62096. But I plan to introduce that in a future pull request instead, because it would be best to add tests for it, which I think should build on the tests proposed in #1812. If both #1812 and this PR are merged, I can add tests followed by the changes from dc62096 that would make them pass. (If they are not merged, or they are merged with major changes, then that will also clarify how to move forward with making a warning from the initial refresh use the logging framework.)

This shows as resolving several CodeQL alerts and also adding new alerts that correspond exactly to them. This happens as a result of renaming log to _logger; CodeQL considers the alert resolved because there are no more calls to log, and issues new equivalent alerts for the same situations with _logger. The new alerts produce a failing Code scanning results check for the PR.

This has each module use `__name__` for the path to its own logger. Previously, most modules did this several hard-coded their names in calls to logging.getLogger.

These globals were nonpublic, because even though they were named without leading underscores, they all appeared in modules in which __all__ was defined and did not list them. (They remain nonpublic.) This renaming is to avoid confusion between those log attributes ang logging features of Git itself ("git log", "git reflog"), and more importantly, with the related git.refs.log module, referred to by the log attribute of the git.refs module, and the log attribute of the git module (git/__init__.py has a * import from git.refs).

This changes a couple tests that access specific loggers to use the logger name instead, as code outside GitPython should do.

This stops adding `NullHandler` instances to GitPython's loggers. As noted in gitpython-developers#1806, when they were added in gitpython-developers#300 this prevented errors when GitPython logged messages and logging was not enabled, but since Python 3.2 there is a logger of last resort providing a nicer default behavior of showing the messages. (They are still shown with better formatting if logging is configured, even if just done with logging.basicConfig(), so applications should still typically configure logging.)

git/repo/base.py

git/cmd.py

@@ -146,7 +145,7 @@
                        handler(line)

        except Exception as ex:
-            log.error(f"Pumping {name!r} of cmd({remove_password_if_present(cmdline)}) failed due to: {ex!r}")
+            _logger.error(f"Pumping {name!r} of cmd({remove_password_if_present(cmdline)}) failed due to: {ex!r}")


git/cmd.py

Byron

Thanks a lot for your help!

Once CI is green I will merge this PR and hope this can pave the way to improve the git.refresh() messaging as well :).

Byron · 2024-01-26T17:02:15Z

It looks like pypi packages fail to refresh in the cygwin job for some reason, the last one timed out after 6h.

Merging anyway.

EliahKagan · 2024-01-26T20:45:20Z

Sorry about leaving this in the draft state without explanation. I had hoped to check if the CodeQL results would cause a "Code scanning results" failure in the merge commit, as well as to improve on, or if not then to describe, the new Cygwin failure where pip blocks indefinitely while downloading some packages. But the problem in the Cygwin run appears separate from the changes in this PR. At some point in time between #1812 and this PR, something changed so that pip never finishes downloading wheel. If the workflow is edited to make it not download wheel, then it never finishes downloading codecov. Fortunately, my having left it this way did not prevent you from merging it.

It looks like the current situation on this repository's main branch is difficult to evaluate because many more CI checks on the pushed merge commit have been cancelled than are affected by either of these issues. Would you be willing to rerun the CI workflows on 10cdd03 other than the Cygwin one?

Byron · 2024-01-26T21:04:23Z

Apologies for the premature merge, indeed I considered all failures unrelated and decided to just ignore them, particularly after having seen 6h timeouts for Cygwin. After restarting CI on the 10cdd03 , Cygwin still hangs. Does that mean that Cygwin based workflows don't work for anyone right now? That would be major breakage and I have no idea how it can stall forever.

EliahKagan · 2024-01-26T22:33:06Z

Thanks for rerunning the checks on 10cdd03. I see everything other than the Cygwin job is okay. (I suspected this, since it is the situation in my fork since fast-forwarding, but I wasn't sure if there was more going on related to their cancellation.)

Apologies for the premature merge, indeed I considered all failures unrelated and decided to just ignore them

The merge seems fine to me--no need to apologize. The CodeQL failure was due to the changes here, though the new alerts were replacing equivalent previous alerts. But I think you're mainly talking about the Cygwin failure, which is not from the changes here. It happens even when rerunning the Cygwin test job on a commit where it has successfully completed before.

Does that mean that Cygwin based workflows don't work for anyone right now?

They're probably not broken for everyone, because the problem seems only to happen with pip, and only when attempting to download some packages from PyPI but not others. I am also unable to reproduce it locally. But it may be that such use is broken for everyone, or that Cygwin-based jobs are otherwise degraded for everyone. Or there could be a subtle bug in the test-cygwin.yml workflow that combines with an external change to produce the problem, as in #1784.

That would be major breakage and I have no idea how it can stall forever.

Even though pip has a default socket timeout of 15 seconds as documented in the output pip --help for the --timeout option, I wonder if some network operation is still stalling, which seems to happen on Windows sometimes (#525, #530, 8364597, #1676 (comment)). Even though it doesn't happen when the native Windows jobs run pip, I still wonder if that is involved.

~~Strange low-level-ish network for downloading specific files is unusual but has been known to happen on CI (actions/runner-images#8791).~~ (Actually that is not known to be specific to particular files, sorry.)

My guess is that it's something else, though. I'll look into it further.

EliahKagan · 2024-01-28T08:13:42Z

I've learned enough about the Cygwin problem to find what I believe to be a reasonable workaround, which I've proposed in #1814 along with my findings.

This is instead of the current behavior writing the message to stdout. This commit does not change the behavior of the code under test, but it changes tests to assert the following: - "Bad git executable" messages are logged, at level CRITICAL. - "log" (and "l") is recognized as another synonym of "warn". - "silent" is recognized as a synonym of "quiet" (as "silence" is). Although it is ambiguous whether this should be logged at level ERROR or CRITICAL, because git.refresh is still expected to be usable and can be called manually, not having a working git is a condition in which GitPython, and any program that really relies on its functionality, should be expected not work. That is the general rationale for using CRIICAL here. There are also two specific reasons: - Existing messages GitPython logs as ERROR typically represent errors in individual operations on repositories, which could fail without indicating that GitPython's overall functionality is in an unusable state. Using the higher CRITICAL level for this situation makes sense for contrast. - Prior to gitpython-developers#1813, logging messsges emitted from GitPython modules, no matter the level, were suppressed when logging was not configured, but because this message was printed instead of being logged, it was still shown. Now that it is to be logged, there may be a benefit to have an easy way for someone to bring back a close approximation of the old behavior. Having this message be at a higher logging level makes that easier to do. (This is a less important reason, as that should rarely be done.) test_initial_refresh_from_bad_git_path_env_warn is the main changed test. All tests should pass again once code is changed for gitpython-developers#1808.

EliahKagan added 4 commits January 25, 2024 21:19

Use consistent style for passing logger name

987dbf4

This has each module use `__name__` for the path to its own logger. Previously, most modules did this several hard-coded their names in calls to logging.getLogger.

Don't access logger in tests by nonpublic attribute

78a82b3

This changes a couple tests that access specific loggers to use the logger name instead, as code outside GitPython should do.

github-advanced-security bot found potential problems Jan 26, 2024

View reviewed changes

EliahKagan mentioned this pull request Jan 26, 2024

(Test PR) Investigate CodeQL output (from logging branch) EliahKagan/GitPython#1

Closed

Byron mentioned this pull request Jan 26, 2024

Git.refresh warns to stdout and does not log #1808

Closed

Byron approved these changes Jan 26, 2024

View reviewed changes

Byron marked this pull request as ready for review January 26, 2024 17:01

Byron merged commit 10cdd03 into gitpython-developers:main Jan 26, 2024
20 of 22 checks passed

EliahKagan deleted the logging branch January 26, 2024 20:45

EliahKagan mentioned this pull request Jan 28, 2024

Pin Python 3.9.16 on Cygwin CI #1814

Merged

EliahKagan mentioned this pull request Feb 2, 2024

Have initial refresh use a logger to warn #1815

Merged

EliahKagan mentioned this pull request Feb 19, 2024

NullHandler added to all but git.repo.base logger #1806

Closed

This was referenced Feb 29, 2024

Revise docstrings, comments, and a few messages #1850

Merged

(Test PR) Investigate CodeQL output (from copyedit branch) EliahKagan/GitPython#4

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Don't suppress messages when logging is not configured #1813

Don't suppress messages when logging is not configured #1813

EliahKagan commented Jan 26, 2024 •

edited

Loading

Byron left a comment

Byron commented Jan 26, 2024

EliahKagan commented Jan 26, 2024

Byron commented Jan 26, 2024

EliahKagan commented Jan 26, 2024 •

edited

Loading

EliahKagan commented Jan 28, 2024

Don't suppress messages when logging is not configured #1813

Don't suppress messages when logging is not configured #1813

Conversation

EliahKagan commented Jan 26, 2024 • edited Loading

Byron left a comment

Choose a reason for hiding this comment

Byron commented Jan 26, 2024

EliahKagan commented Jan 26, 2024

Byron commented Jan 26, 2024

EliahKagan commented Jan 26, 2024 • edited Loading

EliahKagan commented Jan 28, 2024

EliahKagan commented Jan 26, 2024 •

edited

Loading

EliahKagan commented Jan 26, 2024 •

edited

Loading