Requester.__log() breaking redirect authentication

[dannyscript]

Summary

The debug level authentication redaction found in Requester.__log() https://github.com/PyGithub/PyGithub/blob/master/github/Requester.py#L631 seems to be breaking authentication on redirect. This seems to be a long-standing issue, reported as early as 2016 #470 and then i believe mistakenly closed. The same user also submitted a PR https://github.com/PyGithub/PyGithub/pull/471/files which looks like it would solve the issue (and does solve it in my local testing).

I also think this may be some of the root cause for other open/past issues with people seeing authentication failures. It took a while of digging for me to find out that DEBUG was just enabled isEnabledFor(logging.DEBUG) in my environment. It does work to set logging to a higher level or disable debug with logging.disable(logging.DEBUG), but that is not the ideal solution.

My particular use case is the redirect on moved/renamed repo's. This only comes into play when authentication is being used (whether it is needed or not, providing bad auth will cause the problem).

Reproduce

1. Create a repo to rename, rename the repo
   https://github.com/dannyscript/testmove -> https://github.com/dannyscript/testmoved
   (I'll leave that repo sitting there in case anyone wants to test against an already renamed repo)
2. import and create an instance

from github import Github
github_api = 'https://api.github.com'
ghe = Github(base_url=github_api)

3. Test

ghe.get_repo('dannyscript/testmoved')
Out[5]: Repository(full_name="dannyscript/testmoved")  <--- Success new name
ghe.get_repo('dannyscript/testmove')
Out[6]: Repository(full_name="dannyscript/testmoved")  <--- Success old name

4. Enable logging at DEBUG level

import logging
logging.basicConfig(level=logging.DEBUG)

5. Repeat step 3, still works, just more logs

ghe.get_repo('dannyscript/testmoved') <--- Success new name
DEBUG:urllib3.connectionpool:https://api.github.com:443 "GET /repos/dannyscript/testmoved HTTP/1.1" 200 1173
DEBUG:github.Requester:GET https://api.github.com/repos/dannyscript/testmoved [...]
Out[9]: Repository(full_name="dannyscript/testmoved")
ghe.get_repo('dannyscript/testmove')  <--- Success old name
DEBUG:urllib3.connectionpool:https://api.github.com:443 "GET /repos/dannyscript/testmove HTTP/1.1" 301 150  <--- Success on redirect
DEBUG:github.Requester:GET https://api.github.com/repos/dannyscript/testmove [...]
DEBUG:urllib3.connectionpool:https://api.github.com:443 "GET /repositories/370880167 HTTP/1.1" 200 1173
DEBUG:github.Requester:GET https://api.github.com/repositories/370880167 [...]
Out[10]: Repository(full_name="dannyscript/testmoved")

6. Create a personal token, set up new instance

token = 'ghp_***'
ghe = Github(base_url=github_api, login_or_token=token)
# Note that logging at DEBUG level is still enabled

7. Redirect fails once authentication is expected and not found on the second (redirected) request.

ghe.get_repo('dannyscript/testmoved')
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): api.github.com:443
DEBUG:urllib3.connectionpool:https://api.github.com:443 "GET /repos/dannyscript/testmoved HTTP/1.1" 200 None
DEBUG:github.Requester:GET https://api.github.com/repos/dannyscript/testmoved [...]
Out[13]: Repository(full_name="dannyscript/testmoved")  <--- Success new name
ghe.get_repo('dannyscript/testmove')
DEBUG:urllib3.connectionpool:https://api.github.com:443 "GET /repos/dannyscript/testmove HTTP/1.1" 301 150  <--- Success on redirect
DEBUG:github.Requester:GET https://api.github.com/repos/dannyscript/testmove [...]
DEBUG:urllib3.connectionpool:https://api.github.com:443 "GET /repositories/370880167 HTTP/1.1" 401 80
DEBUG:github.Requester:GET https://api.github.com/repositories/370880167 [...]
{"message":"Bad credentials","documentation_url":"https://docs.github.com/rest"}  <--- Failure on old name
Traceback (most recent call last):
  File "[...]/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-14-27dc175904e2>", line 1, in <module>
    ghe.get_repo('dannyscript/testmove')
  File "[...]/lib/python3.6/site-packages/github/MainClass.py", line 325, in get_repo
    "GET", "%s%s" % (url_base, full_name_or_id)
  File "[...]/lib/python3.6/site-packages/github/Requester.py", line 319, in requestJsonAndCheck
    verb, url, parameters, headers, input, self.__customConnection(url)
  File "[...]/lib/python3.6/site-packages/github/Requester.py", line 342, in __check
    raise self.__createException(status, responseHeaders, output)
github.GithubException.BadCredentialsException: 401 {"message": "Bad credentials", "documentation_url": "https://docs.github.com/rest"}

Environment

Mac
python 3.6.8
I have tested on PyGithub version 1.55 (current), but that example may have been on 1.51 in case any of the stacktrace line numbers look weird

[s-t-e-v-e-n-k]

That's a brilliant point, thank you for the in-depth analysis. We clearly need to operate on a copy of the headers since we transform them, I'm just trying to work out how to test it.

[dannyscript]

Oh, wow.. i wish I had hit refresh on the issue before spending time today messing around with debug logging. I submitted a simple PR, but by all means use yours. Just happy to see it getting fixed :-D