Add debug logging to auth.py.

auth.py

 # Copyright 2015 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 """Google OAuth2 related functions."""
 
 import BaseHTTPServer
 import collections
 import datetime
 import functools
@@ skipping 227 matching lines @@
   def __init__(self, token_cache_key, config):
     assert isinstance(config, AuthConfig)
     assert config.use_oauth2
     self._access_token = None
     self._config = config
     self._lock = threading.Lock()
     self._token_cache_key = token_cache_key
     self._external_token = None
     if config.refresh_token_json:
       self._external_token = _read_refresh_token_json(config.refresh_token_json)
+    logging.debug('Using auth config %r', config)
 
   def login(self):
     """Performs interactive login flow if necessary.
 
     Raises:
       AuthenticationError on error or if interrupted.
     """
     if self._external_token:
       raise AuthenticationError(
           'Can\'t run login flow when using --auth-refresh-token-json.')
@@ skipping 41 matching lines @@
       force_refresh: forcefully refresh access token even if it is not expired.
       allow_user_interaction: True to enable blocking for user input if needed.
 
     Raises:
       AuthenticationError on error or if authentication flow was interrupted.
       LoginRequiredError if user interaction is required, but
           allow_user_interaction is False.
     """
     with self._lock:
       if force_refresh:
+        logging.debug('Forcing access token refresh')
         self._access_token = self._create_access_token(allow_user_interaction)
         return self._access_token
 
       # Load from on-disk cache on a first access.
       if not self._access_token:
         self._access_token = self._load_access_token()
 
       # Refresh if expired or missing.
       if not self._access_token or _needs_refresh(self._access_token):
         # Maybe some other process already updated it, reload from the cache.
@@ skipping 55 matching lines @@
   ## Private methods.
 
   def _get_storage(self):
     """Returns oauth2client.Storage with cached tokens."""
     # Do not mix cache keys for different externally provided tokens.
     if self._external_token:
       token_hash = hashlib.sha1(self._external_token.refresh_token).hexdigest()
       cache_key = '%s:refresh_tok:%s' % (self._token_cache_key, token_hash)
     else:
       cache_key = self._token_cache_key
+    logging.debug(
+        'Using token storage %r (cache key %r)', OAUTH_TOKENS_CACHE, cache_key)
     return multistore_file.get_credential_storage_custom_string_key(
         OAUTH_TOKENS_CACHE, cache_key)
 
   def _get_cached_credentials(self):
     """Returns oauth2client.Credentials loaded from storage."""
     storage = self._get_storage()
     credentials = storage.get()
 
+    _log_credentials_info('cached token', credentials)
+
     # Is using --auth-refresh-token-json?
     if self._external_token:
       # Cached credentials are valid and match external token -> use them. It is
       # important to reuse credentials from the storage because they contain
       # cached access token.
       valid = (
           credentials and not credentials.invalid and
           credentials.refresh_token == self._external_token.refresh_token and
           credentials.client_id == self._external_token.client_id and
           credentials.client_secret == self._external_token.client_secret)
       if valid:
+        logging.debug('Cached credentials match external refresh token')
         return credentials
       # Construct new credentials from externally provided refresh token,
       # associate them with cache storage (so that access_token will be placed
       # in the cache later too).
+      logging.debug('Putting external refresh token into the cache')
       credentials = client.OAuth2Credentials(
           access_token=None,
           client_id=self._external_token.client_id,
           client_secret=self._external_token.client_secret,
           refresh_token=self._external_token.refresh_token,
           token_expiry=None,
           token_uri='https://accounts.google.com/o/oauth2/token',
           user_agent=None,
           revoke_uri=None)
       credentials.set_store(storage)
       storage.put(credentials)
       return credentials
 
     # Not using external refresh token -> return whatever is cached.
     return credentials if (credentials and not credentials.invalid) else None
 
   def _load_access_token(self):
     """Returns cached AccessToken if it is not expired yet."""
+    logging.debug('Reloading access token from cache')
     creds = self._get_cached_credentials()
     if not creds or not creds.access_token or creds.access_token_expired:
+      logging.debug('Access token is missing or expired')
       return None
     return AccessToken(str(creds.access_token), creds.token_expiry)
 
   def _create_access_token(self, allow_user_interaction=False):
     """Mints and caches a new access token, launching OAuth2 dance if necessary.
 
     Uses cached refresh token, if present. In that case user interaction is not
     required and function will finish quietly. Otherwise it will launch 3-legged
     OAuth2 flow, that needs user interaction.
 
     Args:
       allow_user_interaction: if True, allow interaction with the user (e.g.
           reading standard input, or launching a browser).
 
     Returns:
       AccessToken.
 
     Raises:
       AuthenticationError on error or if authentication flow was interrupted.
       LoginRequiredError if user interaction is required, but
           allow_user_interaction is False.
     """
+    logging.debug(
+        'Making new access token (allow_user_interaction=%r)',
+        allow_user_interaction)
     credentials = self._get_cached_credentials()
 
     # 3-legged flow with (perhaps cached) refresh token.
     refreshed = False
     if credentials and not credentials.invalid:
       try:
+        logging.debug('Attempting to refresh access_token')
         credentials.refresh(httplib2.Http())
+        _log_credentials_info('refreshed token', credentials)
         refreshed = True
       except client.Error as err:
         logging.warning(
             'OAuth error during access token refresh (%s). '
             'Attempting a full authentication flow.', err)
 
     # Refresh token is missing or invalid, go through the full flow.
     if not refreshed:
       # Can't refresh externally provided token.
       if self._external_token:
         raise AuthenticationError(
             'Token provided via --auth-refresh-token-json is no longer valid.')
       if not allow_user_interaction:
+        logging.debug('Requesting user to login')
         raise LoginRequiredError(self._token_cache_key)
+      logging.debug('Launching OAuth browser flow')
       credentials = _run_oauth_dance(self._config)
+      _log_credentials_info('new token', credentials)
 
     logging.info(
         'OAuth access_token refreshed. Expires in %s.',
         credentials.token_expiry - datetime.datetime.utcnow())
     storage = self._get_storage()
     credentials.set_store(storage)
     storage.put(credentials)
     return AccessToken(str(credentials.access_token), credentials.token_expiry)
 
 
@@ skipping 25 matching lines @@
 def _needs_refresh(access_token):
   """True if AccessToken should be refreshed."""
   if access_token.expires_at is not None:
     # Allow 5 min of clock skew between client and backend.
     now = datetime.datetime.utcnow() + datetime.timedelta(seconds=300)
     return now >= access_token.expires_at
   # Token without expiration time never expires.
   return False
 
 
+def _log_credentials_info(title, credentials):
+  """Dumps (non sensitive) part of client.Credentials object to debug log."""
+  if not credentials:
+    logging.debug('No %s', title)

[nodir, 2015/04/21 00:01:11]

I think there is only one case that (not credentials). I'd move this line there,
because "No %s" is odd in other cases

[Vadim Sh., 2015/04/21 00:04:21]

Done. Though I still prefer to be defensive and check that credentials != None.

+  else:
+    logging.debug('%s info: %r', title, {
+        'access_token_expired': credentials.access_token_expired,
+        'has_access_token': bool(credentials.access_token),
+        'invalid': credentials.invalid,
+        'now': datetime.datetime.utcnow(),

[nodir, 2015/04/21 00:01:12]

Please say utcnow

[Vadim Sh., 2015/04/21 00:04:21]

Done.

+        'token_expiry': credentials.token_expiry,
+    })
+
+
 def _run_oauth_dance(config):
   """Perform full 3-legged OAuth2 flow with the browser.
 
   Returns:
     oauth2client.Credentials.
 
   Raises:
     AuthenticationError on errors.
   """
   flow = client.OAuth2WebServerFlow(
@@ skipping 93 matching lines @@
     self.end_headers()
     query = self.path.split('?', 1)[-1]
     query = dict(urlparse.parse_qsl(query))
     self.server.query_params = query
     self.wfile.write('<html><head><title>Authentication Status</title></head>')
     self.wfile.write('<body><p>The authentication flow has completed.</p>')
     self.wfile.write('</body></html>')
 
   def log_message(self, _format, *args):
     """Do not log messages to stdout while running as command line program."""