Improve debug logging from SDK around transport

[sirosen]

When troubleshooting slow network calls, the calling code wants deep insights into the retry handling logic, to see if any retry-sleep is happening. This adds many more lines of debug to make that information available when debug logging is enabled.

I'm not overly concerned with testing the logging code explicitly (e.g. with log capturing). I think it's enough to try it out and see that it provides useful info in this case. But if anything I've done looks unusual, we can add a test or two for it.

The only thing which is maybe interesting is the __getattr__ call, but that's easy to test as:

>>> x = object()
>>> getattr(x, "__name__", x)
<object object at 0x7f5210ff6de0>

---

I ran a CLI version using this to run down some slow calls.

log sample from modified globus-cli

[INFO] [2021-09-27 19:46:42,402] globus_sdk.services.auth.client.confidential_client::__init__() Finished initializing client, client_id=eec137ba-115b-409b-b0fb-fb5ffe05ae3e
[INFO] [2021-09-27 19:46:42,403] globus_sdk.authorizers.refresh_token::__init__() Setting up RefreshTokenAuthorizer with auth_client=[instance:140095937356416]
[INFO] [2021-09-27 19:46:42,403] globus_sdk.authorizers.renewing::__init__() Setting up a RenewingAuthorizer. It will use an auth type of Bearer and can handle 401s.
[INFO] [2021-09-27 19:46:42,403] globus_sdk.authorizers.renewing::__init__() RenewingAuthorizer will start by using access_tokenwith hash "4d2b55e19911f511a365180e4d126e572b3ef482bba6f22647951926d4c5f042"
[INFO] [2021-09-27 19:46:42,403] globus_sdk.client::__init__() Creating client of type <class 'globus_sdk.services.auth.client.base.AuthClient'> for service "auth"
[DEBUG] [2021-09-27 19:46:42,403] globus_sdk.config.env_vars::_load_var() on lookup, default setting: GLOBUS_SDK_ENVIRONMENT=production
[DEBUG] [2021-09-27 19:46:42,404] globus_sdk.config.env_vars::_load_var() on lookup, default setting: GLOBUS_SDK_VERIFY_SSL=True
[DEBUG] [2021-09-27 19:46:42,404] globus_sdk.config.env_vars::_load_var() on lookup, default setting: GLOBUS_SDK_HTTP_TIMEOUT=60.0
[DEBUG] [2021-09-27 19:46:42,404] globus_sdk.client::__init__() initialized transport of type <class 'globus_sdk.transport.requests.RequestsTransport'>
[DEBUG] [2021-09-27 19:46:42,404] globus_sdk.config.environments::get_service_url() Service URL Lookup for "auth" under env "production"
[DEBUG] [2021-09-27 19:46:42,404] globus_sdk.config.environments::get_service_url() Service URL Lookup Result: "auth" is at "https://auth.globus.org/"
[INFO] [2021-09-27 19:46:42,405] globus_sdk.services.auth.client.base::get_identities() Looking up Globus Auth Identities
[DEBUG] [2021-09-27 19:46:42,405] globus_sdk.services.auth.client.base::get_identities() query_params={'ids': 'ae341a98-d274-11e5-b888-dbae3a8ba545'}
[DEBUG] [2021-09-27 19:46:42,405] globus_sdk.client::get() GET to /v2/api/identities with query_params {'ids': 'ae341a98-d274-11e5-b888-dbae3a8ba545'}
[DEBUG] [2021-09-27 19:46:42,405] globus_sdk.client::request() request will hit URL: https://auth.globus.org/v2/api/identities
[DEBUG] [2021-09-27 19:46:42,405] globus_sdk.transport.requests::request() starting request for https://auth.globus.org/v2/api/identities
[DEBUG] [2021-09-27 19:46:42,405] globus_sdk.transport.requests::request() transport request state initialized
[DEBUG] [2021-09-27 19:46:42,406] globus_sdk.transport.requests::request() transport request retry cycle. attempt=0
[DEBUG] [2021-09-27 19:46:42,406] globus_sdk.authorizers.renewing::ensure_valid_token() RenewingAuthorizer checking expiration time
[DEBUG] [2021-09-27 19:46:42,406] globus_sdk.authorizers.renewing::ensure_valid_token() RenewingAuthorizer determined time has not yet expired
[DEBUG] [2021-09-27 19:46:42,406] globus_sdk.authorizers.renewing::get_authorization_header() bearer token has hash "4d2b55e19911f511a365180e4d126e572b3ef482bba6f22647951926d4c5f042"
[DEBUG] [2021-09-27 19:46:42,406] globus_sdk.transport.requests::request() request about to send
[DEBUG] [2021-09-27 19:46:42,450] globus_sdk.transport.requests::request() request success, still check should-retry
[DEBUG] [2021-09-27 19:46:42,451] globus_sdk.transport.retry::should_retry() ran retry check (default_check_expired_authorization) => RetryCheckResult.no_decision
[DEBUG] [2021-09-27 19:46:42,451] globus_sdk.transport.retry::should_retry() ran retry check (default_check_request_exception) => RetryCheckResult.no_decision
[DEBUG] [2021-09-27 19:46:42,451] globus_sdk.transport.retry::should_retry() ran retry check (default_check_retry_after_header) => RetryCheckResult.no_decision
[DEBUG] [2021-09-27 19:46:42,451] globus_sdk.transport.retry::should_retry() ran retry check (default_check_transient_error) => RetryCheckResult.no_decision
[INFO] [2021-09-27 19:46:42,451] globus_sdk.transport.requests::request() request done (success)
[DEBUG] [2021-09-27 19:46:42,451] globus_sdk.client::request() request made to URL: https://auth.globus.org/v2/api/identities?ids=ae341a98-d274-11e5-b888-dbae3a8ba545
[DEBUG] [2021-09-27 19:46:42,452] globus_sdk.client::request() request completed with response code: 200