Improve logging and exceptions.

gclient.py

 #!/usr/bin/python
 # Copyright (c) 2010 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.
 
 """Meta checkout manager supporting both Subversion and GIT.
 
 Files
   .gclient      : Current client configuration, written by 'config' command.
                   Format is a Python script defining 'solutions', a list whose
@@ skipping 167 matching lines @@
       raise gclient_utils.Error('deps_file name must not be a path, just a '
                                 'filename. %s' % self.deps_file)
 
   def LateOverride(self, url):
     """Resolves the parsed url from url.
 
     Manages From() keyword accordingly. Do not touch self.parsed_url nor
     self.url because it may called with other urls due to From()."""
     overriden_url = self.get_custom_deps(self.name, url)
     if overriden_url != url:
-      logging.debug('%s, %s was overriden to %s' % (self.name, url,
+      logging.info('%s, %s was overriden to %s' % (self.name, url,
           overriden_url))
       return overriden_url
     elif isinstance(url, self.FromImpl):
       ref = [dep for dep in self.tree(True) if url.module_name == dep.name]
       if not ref:
         raise gclient_utils.Error('Failed to find one reference to %s. %s' % (
             url.module_name, ref))
       # It may happen that len(ref) > 1 but it's no big deal.
       ref = ref[0]
       sub_target = url.sub_target_name or self.name
       # Make sure the referenced dependency DEPS file is loaded and file the
       # inner referenced dependency.
       ref.ParseDepsFile(False)
       found_dep = None
       for d in ref.dependencies:
         if d.name == sub_target:
           found_dep = d
           break
       if not found_dep:
         raise gclient_utils.Error(
-            'Couldn\'t find %s in %s, referenced by %s' % (
-            sub_target, ref.name, self.name))
+            'Couldn\'t find %s in %s, referenced by %s\n%s' % (
+                sub_target, ref.name, self.name, str(self.root_parent())))
       # Call LateOverride() again.
       parsed_url = found_dep.LateOverride(found_dep.url)
-      logging.debug('%s, %s to %s' % (self.name, url, parsed_url))
+      logging.info('%s, %s to %s' % (self.name, url, parsed_url))
       return parsed_url
     elif isinstance(url, basestring):
       parsed_url = urlparse.urlparse(url)
       if not parsed_url[0]:
         # A relative url. Fetch the real base.
         path = parsed_url[2]
         if not path.startswith('/'):
           raise gclient_utils.Error(
               'relative DEPS entry \'%s\' must begin with a slash' % url)
         # Create a scm just to query the full url.
         parent_url = self.parent.parsed_url
         if isinstance(parent_url, self.FileImpl):
           parent_url = parent_url.file_location
         scm = gclient_scm.CreateSCM(parent_url, self.root_dir(), None)
         parsed_url = scm.FullUrlForRelativeUrl(url)
       else:
         parsed_url = url
-      logging.debug('%s, %s -> %s' % (self.name, url, parsed_url))
+      logging.info('%s, %s -> %s' % (self.name, url, parsed_url))
       return parsed_url
     elif isinstance(url, self.FileImpl):
       parsed_url = url
-      logging.debug('%s, %s -> %s (File)' % (self.name, url, parsed_url))
+      logging.info('%s, %s -> %s (File)' % (self.name, url, parsed_url))
       return parsed_url
     elif url is None:
       return None
     else:
       raise gclient_utils.Error('Unkown url type')
 
   def ParseDepsFile(self, direct_reference):
     """Parses the DEPS file for this dependency."""
     if direct_reference:
       # Maybe it was referenced earlier by a From() keyword but it's now
       # directly referenced.
       self.direct_reference = direct_reference
     if self.deps_parsed:
+      logging.debug('%s was already parsed' % self.name)
       return
     self.deps_parsed = True
     filepath = os.path.join(self.root_dir(), self.name, self.deps_file)
     if not os.path.isfile(filepath):
+      logging.info('%s: No DEPS file found at %s' % (self.name, filepath))
       return
     deps_content = gclient_utils.FileRead(filepath)
+    logging.debug(deps_content)
 
     # Eval the content.
     # One thing is unintuitive, vars= {} must happen before Var() use.
     local_scope = {}
     var = self.VarImpl(self.custom_vars, local_scope)
     global_scope = {
       'File': self.FileImpl,
       'From': self.FromImpl,
       'Var': var.Lookup,
       'deps_os': {},
@@ skipping 33 matching lines @@
       rel_deps = {}
       for d, url in deps.items():
         # normpath is required to allow DEPS to use .. in their
         # dependency local path.
         rel_deps[os.path.normpath(os.path.join(self.name, d))] = url
       deps = rel_deps
 
     # Convert the deps into real Dependency.
     for name, url in deps.iteritems():
       if name in [s.name for s in self.dependencies]:
-        raise
+        raise gclient_utils.Error(
+            'The same name "%s" appears multiple times in the deps section' %
+                name)
       self.dependencies.append(Dependency(self, name, url, None, None, None,
           None))
     # Sorting by name would in theory make the whole thing coherent, since
     # subdirectories will be sorted after the parent directory, but that doens't
     # work with From() that fetch from a dependency with a name being sorted
     # later. But if this would be removed right now, many projects wouldn't be
     # able to sync anymore.
     self.dependencies.sort(key=lambda x: x.name)
-    logging.info('Loaded: %s' % str(self))
+    logging.debug('Loaded: %s' % str(self))
 
   def RunCommandRecursively(self, options, revision_overrides,
                             command, args, pm):
     """Runs 'command' before parsing the DEPS in case it's a initial checkout
     or a revert."""
     assert self._file_list == []
     # When running runhooks, there's no need to consult the SCM.
     # All known hooks are expected to run unconditionally regardless of working
     # copy state, so skip the SCM status check.
     run_scm = command not in ('runhooks', None)
@@ skipping 75 matching lines @@
           pattern = re.compile(hook_dict['pattern'])
           matching_file_list = [f for f in file_list if pattern.search(f)]
           if matching_file_list:
             self._RunHookAction(hook_dict, matching_file_list)
     if self.recursion_limit():
       for s in self.dependencies:
         s.RunHooksRecursively(options)
 
   def _RunHookAction(self, hook_dict, matching_file_list):
     """Runs the action from a single hook."""
+    # A single DEPS file can specify multiple hooks so this function can be
+    # called multiple times on a single Dependency.
+    #assert self.hooks_ran == False
     self.hooks_ran = True
-    logging.info(hook_dict)
-    logging.info(matching_file_list)
+    logging.debug(hook_dict)
+    logging.debug(matching_file_list)
     command = hook_dict['action'][:]
     if command[0] == 'python':
       # If the hook specified "python" as the first item, the action is a
       # Python script.  Run it by starting a new copy of the same
       # interpreter.
       command[0] = sys.executable
 
     if '$matching_files' in command:
       splice_index = command.index('$matching_files')
       command[splice_index:splice_index + 1] = matching_file_list
@@ skipping 33 matching lines @@
     return self.custom_deps.get(name, url)
 
   def file_list(self):
     result = self._file_list[:]
     for d in self.dependencies:
       result.extend(d.file_list())
     return result
 
   def __str__(self):
     out = []
-    for i in ('name', 'url', 'safesync_url', 'custom_deps', 'custom_vars',
-              'deps_hooks', '_file_list', 'processed',
-              'hooks_ran'):
+    for i in ('name', 'url', 'parsed_url', 'safesync_url', 'custom_deps',
+              'custom_vars', 'deps_hooks', '_file_list', 'processed',
+              'hooks_ran', 'deps_parsed'):
       # 'deps_file'
       if self.__dict__[i]:
         out.append('%s: %s' % (i, self.__dict__[i]))
 
     for d in self.dependencies:
       out.extend(['  ' + x for x in str(d).splitlines()])
       out.append('')
     return '\n'.join(out)
 
   def __repr__(self):
     return '%s: %s' % (self.name, self.url)
 
   def hierarchy(self):
     """Returns a human-readable hierarchical reference to a Dependency."""
     out = '%s(%s)' % (self.name, self.url)
     i = self.parent
     while i and i.name:
       out = '%s(%s) -> %s' % (i.name, i.url, out)
       i = i.parent
     return out
 
+  def root_parent(self):
+    """Returns the root object, normally a GClient object."""
+    d = self
+    while d.parent:
+      d = d.parent
+    return d
+
 
 class GClient(Dependency):
   """Object that represent a gclient checkout. A tree of Dependency(), one per
   solution or DEPS entry."""
 
   DEPS_OS_CHOICES = {
     "win32": "win",
     "win": "win",
     "cygwin": "win",
     "darwin": "mac",
@@ skipping 266 matching lines @@
       # Print the snapshot configuration file
       print(self.DEFAULT_SNAPSHOT_FILE_TEXT % {'solution_list': new_gclient})
     else:
       entries = sorted(self.tree(False), key=lambda i: i.name)
       for entry in entries:
         entry_url = GetURLAndRev(entry.name, entry.parsed_url)
         line = '%s: %s' % (entry.name, entry_url)
         if not entry is entries[-1]:
           line += ';'
         print line
-    logging.debug(str(self))
+    logging.info(str(self))
 
   def ParseDepsFile(self, direct_reference):
     """No DEPS to parse for a .gclient file."""
     self.direct_reference = True
     self.deps_parsed = True
 
   def root_dir(self):
     """Root directory of gclient checkout."""
     return self._root_dir
 
@@ skipping 389 matching lines @@
     return CMDhelp(parser, argv)
   except gclient_utils.Error, e:
     print >> sys.stderr, 'Error: %s' % str(e)
     return 1
 
 
 if '__main__' == __name__:
   sys.exit(Main(sys.argv[1:]))
 
 # vim: ts=2:sw=2:tw=80:et: