Merge pull request #59 from Microsoft/users/tedchamb/regen

Add more info when debug logging is enabled.

Author: tedchamb

vsts/vsts/_file_cache.py

@@ -33,13 +33,13 @@ def load(self):
         try:
             if os.path.isfile(self.file_name):
                 if self.max_age > 0 and os.stat(self.file_name).st_mtime + self.max_age < time.clock():
-                    logging.info('Cache file expired: %s', file=self.file_name)
+                    logging.debug('Cache file expired: %s', file=self.file_name)
                     os.remove(self.file_name)
                 else:
-                    logging.info('Loading cache file: %s', self.file_name)
+                    logging.debug('Loading cache file: %s', self.file_name)
                     self.data = get_file_json(self.file_name, throw_on_empty=False) or {}
             else:
-                logging.info('Cache file does not exist: %s', self.file_name)
+                logging.debug('Cache file does not exist: %s', self.file_name)
         except Exception as ex:
             logging.exception(ex)
             # file is missing or corrupt so attempt to delete it

vsts/vsts/vss_client.py

@@ -50,8 +50,11 @@ def _send_request(self, request, headers=None, content=None, **operation_config)
         """
         if TRACE_ENV_VAR in os.environ and os.environ[TRACE_ENV_VAR] == 'true':
             print(request.method + ' ' + request.url)
+        logging.debug('%s %s', request.method, request.url)
+        logging.debug('Request content: %s', content)
         response = self._client.send(request=request, headers=headers,
                                      content=content, **operation_config)
+        logging.debug('Response content: %s', response.content)
         if response.status_code < 200 or response.status_code >= 300:
             self._handle_error(request, response)
         return response
@@ -66,6 +69,14 @@ def _send(self, http_method, location_id, version, route_values=None,
         negotiated_version = self._negotiate_request_version(
             self._get_resource_location(location_id),
             version)
+
+        if version != negotiated_version:
+            logging.info("Negotiated api version from '%s' down to '%s'. This means the client is newer than the server.",
+                         version,
+                         negotiated_version)
+        else:
+            logging.debug("Api version '%s'", negotiated_version)
+
         # Construct headers
         headers = {'Content-Type': media_type + '; charset=utf-8',
                    'Accept': 'application/json;api-version=' + negotiated_version}
@@ -139,14 +150,14 @@ def _get_resource_locations(self, all_host_types):
         # Next check for options cached on disk
         if not all_host_types and OPTIONS_FILE_CACHE[self.normalized_url]:
             try:
-                logging.info('File cache hit for options on: %s', self.normalized_url)
+                logging.debug('File cache hit for options on: %s', self.normalized_url)
                 self._locations = self._base_deserialize.deserialize_data(OPTIONS_FILE_CACHE[self.normalized_url],
                                                                           '[ApiResourceLocation]')
                 return self._locations
             except DeserializationError as ex:
                 logging.exception(str(ex))
         else:
-            logging.info('File cache miss for options on: %s', self.normalized_url)
+            logging.debug('File cache miss for options on: %s', self.normalized_url)
 
         # Last resort, make the call to the server
         options_uri = self._combine_url(self.config.base_url, '_apis')

vsts/vsts/vss_connection.py

@@ -77,14 +77,14 @@ def _get_resource_areas(self, force=False):
             location_client = LocationClient(self.base_url, self._creds)
             if not force and RESOURCE_FILE_CACHE[location_client.normalized_url]:
                 try:
-                    logging.info('File cache hit for resources on: %s', location_client.normalized_url)
+                    logging.debug('File cache hit for resources on: %s', location_client.normalized_url)
                     self._resource_areas = location_client._base_deserialize.deserialize_data(RESOURCE_FILE_CACHE[location_client.normalized_url],
                                                                                               '[ResourceAreaInfo]')
                     return self._resource_areas
                 except Exception as ex:
                     logging.exception(str(ex))
             elif not force:
-                logging.info('File cache miss for resources on: %s', location_client.normalized_url)
+                logging.debug('File cache miss for resources on: %s', location_client.normalized_url)
             self._resource_areas = location_client.get_resource_areas()
             if self._resource_areas is None:
                 # For OnPrem environments we get an empty collection wrapper.