Fixed glitch in chunked-download code.

Could (and probably will) cause non-terminating loops. General refactors.

Author: dsoprea

gdrivefs/cache/volume.py

@@ -24,7 +24,7 @@ def path_resolver(path):
 
     parent_clause = path_relations.get_clause_from_path(path)
     if not parent_clause:
-        logging.debug("Path [%s] does not exist for split.", path)
+#        logging.debug("Path [%s] does not exist for split.", path)
         raise GdNotFoundError()
 
     return (parent_clause[CLAUSE_ENTRY], parent_clause)
@@ -93,12 +93,7 @@ def remove_entry_recursive(self, entry_id, is_update=False):
             else:
                 stat_files += 1
 
-            try:
-                result = self.__remove_entry(current_entry_id, is_update)
-            except:
-                self.__log.debug("Could not remove entry with ID [%s] "
-                                 "(recursive).", current_entry_id)
-                raise
+            result = self.__remove_entry(current_entry_id, is_update)
 
             removed[current_entry_id] = True
 
@@ -356,8 +351,8 @@ def register_entry(self, normalized_entry):
 
             entry_id = normalized_entry.id
 
-            self.__log.debug("Registering entry with ID [%s] within path-"
-                             "relations.", entry_id)
+#            self.__log.debug("Registering entry with ID [%s] within path-"
+#                             "relations.", entry_id)
 
             if self.is_cached(entry_id, include_placeholders=False):
 #                self.__log.debug("Entry to register with ID [%s] already "
@@ -464,28 +459,28 @@ def register_entry(self, normalized_entry):
         return entry_clause
 
     def __load_all_children(self, parent_id):
-        self.__log.debug("Loading children under parent with ID [%s].",
-                         parent_id)
+#        self.__log.debug("Loading children under parent with ID [%s].",
+#                         parent_id)
 
         with PathRelations.rlock:
             children = drive_proxy('list_files', parent_id=parent_id)
 
             child_ids = [ ]
             if children:
-                self.__log.debug("(%d) children returned and will be "
-                                 "registered.", len(children))
+#                self.__log.debug("(%d) children returned and will be "
+#                                 "registered.", len(children))
 
                 for child in children:
                         self.register_entry(child)
 
-                self.__log.debug("Looking up parent with ID [%s] for all-"
-                                 "children update.", parent_id)
+#                self.__log.debug("Looking up parent with ID [%s] for all-"
+#                                 "children update.", parent_id)
 
                 parent_clause = self.__get_entry_clause_by_id(parent_id)
 
                 parent_clause[4] = True
 
-                self.__log.debug("All children have been loaded.")
+#                self.__log.debug("All children have been loaded.")
 
         return children
 
@@ -494,7 +489,7 @@ def get_children_from_entry_id(self, entry_id):
         entry-ID.
         """
 
-        self.__log.debug("Getting children under entry with ID [%s].",entry_id)
+#        self.__log.debug("Getting children under entry with ID [%s].",entry_id)
 
         with PathRelations.rlock:
             entry_clause = self.__get_entry_clause_by_id(entry_id)
@@ -523,8 +518,8 @@ def get_children_from_entry_id(self, entry_id):
                 self.__log.error(message)
                 raise Exception(message)
 
-            self.__log.debug("(%d) children found.",
-                             len(entry_clause[CLAUSE_CHILDREN]))
+#            self.__log.debug("(%d) children found.",
+#                             len(entry_clause[CLAUSE_CHILDREN]))
 
             return entry_clause[CLAUSE_CHILDREN]
 
@@ -540,7 +535,7 @@ def get_children_entries_from_entry_id(self, entry_id):
 
     def get_clause_from_path(self, filepath):
 
-        self.__log.debug("Getting clause for path [%s].", filepath)
+#        self.__log.debug("Getting clause for path [%s].", filepath)
 
         with PathRelations.rlock:
             path_results = self.find_path_components_goandget(filepath)
@@ -550,7 +545,7 @@ def get_clause_from_path(self, filepath):
                 return None
 
             entry_id = path_results[0][-1]
-            self.__log.debug("Found entry with ID [%s].", entry_id)
+#            self.__log.debug("Found entry with ID [%s].", entry_id)
 
             # Make sure the entry is more than a placeholder.
             self.__get_entry_clause_by_id(entry_id)
@@ -567,8 +562,8 @@ def find_path_components_goandget(self, path):
             previous_results = []
             i = 0
             while 1:
-                self.__log.debug("Attempting to find path-components (go and "
-                                 "get) for path [%s].  CYCLE= (%d)", path, i)
+#                self.__log.debug("Attempting to find path-components (go and "
+#                                 "get) for path [%s].  CYCLE= (%d)", path, i)
 
                 # See how many components can be found in our current cache.
 
@@ -626,8 +621,9 @@ def find_path_components_goandget(self, path):
 
                 filenames_phrase = ', '.join([ candidate.id for candidate
                                                             in children ])
-                self.__log.debug("(%d) candidate children were found: %s",
-                                 len(children), filenames_phrase)
+
+#                self.__log.debug("(%d) candidate children were found: %s",
+#                                 len(children), filenames_phrase)
 
                 i += 1
 
@@ -651,7 +647,7 @@ def __find_path_components(self, path):
             return self.path_cache[path]
 
         with PathRelations.rlock:
-            self.__log.debug("Locating entry information for path [%s].", path)
+#            self.__log.debug("Locating entry information for path [%s].", path)
             root_id = AccountInfo.get_instance().root_id
 
             # Ensure that the root node is loaded.
@@ -668,9 +664,9 @@ def __find_path_components(self, path):
                 child_filename_to_search_fs = utility. \
                     translate_filename_charset(path_parts[i])
 
-                self.__log.debug("Checking for part (%d) [%s] under parent "
-                                 "with ID [%s].",
-                                 i, child_filename_to_search_fs, entry_ptr)
+#                self.__log.debug("Checking for part (%d) [%s] under parent "
+#                                 "with ID [%s].",
+#                                 i, child_filename_to_search_fs, entry_ptr)
 
                 current_clause = self.entry_ll[entry_ptr]
 
@@ -752,20 +748,20 @@ def __get_entries_to_update(self, requested_entry_id):
         parent_ids = drive_proxy('get_parents_containing_id', 
                                  child_id=requested_entry_id)
 
-        self.__log.debug("Found (%d) parents.", len(parent_ids))
+#        self.__log.debug("Found (%d) parents.", len(parent_ids))
 
         affected_entries = [ requested_entry_id ]
         considered_entries = { }
         max_readahead_entries = Conf.get('max_readahead_entries')
         for parent_id in parent_ids:
-            self.__log.debug("Retrieving children for parent with ID [%s].",
-                             parent_id)
+#            self.__log.debug("Retrieving children for parent with ID [%s].",
+#                             parent_id)
 
             child_ids = drive_proxy('get_children_under_parent_id', 
                                     parent_id=parent_id)
 
-            self.__log.debug("(%d) children found under parent with ID [%s].",
-                             len(child_ids), parent_id)
+#            self.__log.debug("(%d) children found under parent with ID [%s].",
+#                             len(child_ids), parent_id)
 
             for child_id in child_ids:
                 if child_id == requested_entry_id:
@@ -817,15 +813,15 @@ def __do_update_for_missing_entry(self, requested_entry_id):
         for entry_id, entry in retrieved.iteritems():
             path_relations.register_entry(entry)
 
-        self.__log.debug("(%d) entries were loaded.", len(retrieved))
+#        self.__log.debug("(%d) entries were loaded.", len(retrieved))
 
         return retrieved
 
     def fault_handler(self, resource_name, requested_entry_id):
         """A requested entry wasn't stored."""
 
-        self.__log.debug("EntryCache has faulted on entry with ID [%s].",
-                         requested_entry_id)
+#        self.__log.debug("EntryCache has faulted on entry with ID [%s].",
+#                         requested_entry_id)
 
         retrieved = self.__do_update_for_missing_entry(requested_entry_id)
 

gdrivefs/gdfs/fsutility.py

@@ -130,8 +130,8 @@ def split_path(filepath_original, pathresolver_cb):
                       (filepath_original))
         raise
 
-    log.debug("File-path [%s] split into filepath [%s] and mime_type "
-              "[%s]." % (filepath_original, filepath, mime_type))
+#    log.debug("File-path [%s] split into filepath [%s] and mime_type "
+#              "[%s]." % (filepath_original, filepath, mime_type))
 
     # Split the file-path into a path and a filename.
 
@@ -141,22 +141,23 @@ def split_path(filepath_original, pathresolver_cb):
 
     try:
         path_resolution = pathresolver_cb(path)
+# TODO(dustin): We need to specify the exception for when a file doesn't exist.
     except:
         log.exception("Exception while getting entry from path [%s]." % (path))
         raise GdNotFoundError()
 
     if not path_resolution:
-        log.debug("Path [%s] does not exist for split." % (path))
+#        log.debug("Path [%s] does not exist for split." % (path))
         raise GdNotFoundError()
 
     (parent_entry, parent_clause) = path_resolution
 
     is_hidden = (filename[0] == '.') if filename else False
 
-    log.debug("File-path [%s] split into parent with ID [%s], path [%s], "
-              "unverified filename [%s], mime-type [%s], and is_hidden [%s]." % 
-              (filepath_original, parent_entry.id, path, filename, 
-               mime_type, is_hidden))
+#    log.debug("File-path [%s] split into parent with ID [%s], path [%s], "
+#              "unverified filename [%s], mime-type [%s], and is_hidden [%s]." % 
+#              (filepath_original, parent_entry.id, path, filename, 
+#               mime_type, is_hidden))
 
     return (parent_clause, path, filename, mime_type, is_hidden)
 

gdrivefs/gdfs/opened_file.py

@@ -467,19 +467,8 @@ def flush(self):
 
         self.__log.debug("Retrieving entry for write-flush.")
 
-        try:
-            entry = self.__get_entry_or_raise()
-        except:
-            self.__log.exception("Could not get entry with ID [%s] for "
-                                 "write-flush." % (self.__entry_id))
-            raise
-
-        try:
-             cache_fault = self.__load_base_from_remote()
-        except:
-            self.__log.exception("Could not load local cache for entry [%s]." % 
-                                 (entry))
-            raise
+        entry = self.__get_entry_or_raise()
+        cache_fault = self.__load_base_from_remote()
 
         with self.__class__.__update_lock:
             if self.__is_dirty is False:

gdrivefs/gdtool/chunked_download.py

@@ -1,4 +1,6 @@
-from time import time
+import logging
+
+from time import time, sleep
 from random import random
 
 from oauth2client import util
@@ -7,6 +9,8 @@
 
 DEFAULT_CHUNK_SIZE = 1024 * 512
 
+_logger = logging.getLogger(__name__)
+
 
 class ChunkedDownload(object):
   """"Download an entry, chunk by chunk. This code is mostly identical to
@@ -56,36 +60,41 @@ def next_chunk(self, num_retries=0):
       apiclient.errors.HttpError if the response was not a 2xx.
       httplib2.HttpLib2Error if a transport error has occured.
     """
+
     headers = {
         'range': 'bytes=%d-%d' % (
             self._progress, self._progress + self._chunksize)
         }
 
     for retry_num in xrange(num_retries + 1):
-      if retry_num > 0:
-        self._sleep(self._rand() * 2**retry_num)
-        logging.warning(
-            'Retry #%d for media download: GET %s, following status: %d'
-            % (retry_num, self._uri, resp.status))
-
-      resp, content = self._http.request(self._uri, headers=headers)
-      if resp.status < 500:
-        break
-
-    if resp.status in [200, 206]:
-      if 'content-location' in resp and resp['content-location'] != self._uri:
+        if retry_num > 0:
+            self._sleep(self._rand() * 2**retry_num)
+            logging.warning(
+                'Retry #%d for media download: GET %s, following status: %d' %
+                (retry_num, self._uri, resp.status))
+
+        resp, content = self._http.request(self._uri, headers=headers)
+        if resp.status < 500:
+            break
+
+    if resp.status not in (200, 206):
+        raise HttpError(resp, content, uri=self._uri)
+
+    if 'content-location' in resp and resp['content-location'] != self._uri:
         self._uri = resp['content-location']
-      self._progress += len(content)
-      self._fd.write(content)
 
-      if 'content-range' in resp:
+    self._progress += len(content)
+    self._fd.write(content)
+
+    if 'content-length' in resp:
+        self._total_size = int(resp['content-length'])
+    elif 'content-range' in resp:
         content_range = resp['content-range']
         length = content_range.rsplit('/', 1)[1]
         self._total_size = int(length)
 
-      if self._progress == self._total_size:
+    if self._progress == self._total_size:
         self._done = True
-      return MediaDownloadProgress(self._progress, self._total_size), self._done
-    else:
-      raise HttpError(resp, content, uri=self._uri)
+
+    return MediaDownloadProgress(self._progress, self._total_size), self._done
 

gdrivefs/gdtool/drive.py

@@ -322,7 +322,7 @@ def download_to_local(self, output_file_path, normalized_entry, mime_type,
         """
 
         self.__log.debug("Downloading entry with ID [%s] and mime-type [%s].", 
-                         (normalized_entry.id, mime_type))
+                         normalized_entry.id, mime_type)
 
         if mime_type != normalized_entry.mime_type and \
                 mime_type not in normalized_entry.download_links:
@@ -377,8 +377,8 @@ def download_to_local(self, output_file_path, normalized_entry, mime_type,
 
         url = normalized_entry.download_links[mime_type]
 
-        self.__log.debug("Downloading file from [%s]." % (url))
-
+#        self.__log.debug("Downloading file from [%s]." % (url))
+#
 #        try:
 #            data_tuple = authed_http.request(url)
 #        except:
@@ -657,7 +657,12 @@ def proxied_method(auto_refresh=True, **kwargs):
 
                     time.sleep((2 ** n) + random.randint(0, 1000) / 1000)
                 except HttpError as e:
-                    error = json.loads(e.content)
+                    try:
+                        error = json.loads(e.content)
+                    except ValueError:
+                        _logger.error("Non-JSON error while doing chunked "
+                                      "download: %s", e.content) 
+                    
                     if error.get('code') == 403 and \
                        error.get('errors')[0].get('reason') \
                        in ['rateLimitExceeded', 'userRateLimitExceeded']:

gdrivefs/gdtool/normal_entry.py

@@ -201,7 +201,7 @@ def xattr_data(self):
 
             attrs = {}
             for a_type, a_dict in data_dict.iteritems():
-                self.__log.debug("Setting [%s]." % (a_type))
+#                self.__log.debug("Setting [%s]." % (a_type))
                 for key, value in a_dict.iteritems():
                     fqkey = ('user.%s.%s' % (a_type, key))
                     attrs[fqkey] = self.__convert(value)

gdrivefs/log_config.py

@@ -7,6 +7,7 @@
 
 default_logger = getLogger()
 default_logger.setLevel(logging.WARNING)
+#default_logger.setLevel(logging.DEBUG)
 
 # Log to syslog.