[Checkins] SVN: zc.buildout/trunk/src/zc/buildout/ Improved error reporting/handling:

Jim Fulton jim at zope.com
Thu Mar 8 18:33:28 EST 2007


Log message for revision 73082:
  Improved error reporting/handling:
  
  - Added "logical tracebacks" that show functionally what the buildout
    was doing when an error occurs.  Don't show a Python traceback
    unless the -D option is used.
  
  - Added a -D option that causes the buildout to print a traceback and
    start the pdb post-mortem debugger when an error occurs.
  

Changed:
  U   zc.buildout/trunk/src/zc/buildout/buildout.py
  U   zc.buildout/trunk/src/zc/buildout/buildout.txt
  A   zc.buildout/trunk/src/zc/buildout/debugging.txt
  U   zc.buildout/trunk/src/zc/buildout/tests.py

-=-
Modified: zc.buildout/trunk/src/zc/buildout/buildout.py
===================================================================
--- zc.buildout/trunk/src/zc/buildout/buildout.py	2007-03-08 23:29:12 UTC (rev 73081)
+++ zc.buildout/trunk/src/zc/buildout/buildout.py	2007-03-08 23:33:27 UTC (rev 73082)
@@ -1,4 +1,4 @@
-#############################################################################
+############################################################################
 #
 # Copyright (c) 2005 Zope Corporation and Contributors.
 # All Rights Reserved.
@@ -61,6 +61,8 @@
     def __init__(self, config_file, cloptions,
                  user_defaults=True, windows_restart=False):
 
+        __doing__ = 'Initializing'
+        
         self.__windows_restart = windows_restart
 
         # default options
@@ -150,6 +152,8 @@
         return os.path.join(self._buildout_dir, *names)
 
     def bootstrap(self, args):
+        __doing__ = 'Bootstraping'
+
         self._setup_directories()
 
         # Now copy buildout and setuptools eggs, amd record destination eggs:
@@ -180,6 +184,8 @@
             self['buildout']['bin-directory'])
 
     def install(self, install_args):
+        __doing__ = 'Installing'
+
         self._load_extensions()
         self._setup_directories()
 
@@ -271,22 +277,7 @@
                 elif not uninstall_missing:
                     continue
 
-                # ununstall part
-                self._logger.info('Uninstalling %s', part)
-
-                # run uinstall recipe
-                recipe, entry = _recipe(installed_part_options[part])
-                try:
-                    uninstaller = _install_and_load(
-                        recipe, 'zc.buildout.uninstall', entry, self)
-                    self._logger.info('Running uninstall recipe')
-                    uninstaller(part, installed_part_options[part])
-                except (ImportError, pkg_resources.DistributionNotFound), v:
-                    pass
-
-                # remove created files and directories
-                self._uninstall(
-                    installed_part_options[part]['__buildout_installed__'])
+                self._uninstall_part(part, installed_part_options)
                 installed_parts = [p for p in installed_parts if p != part]
 
             # install new parts
@@ -295,7 +286,8 @@
                 saved_options = self[part].copy()
                 recipe = self[part].recipe
                 if part in installed_parts:
-                    self._logger.info('Updating %s', part)
+                    __doing__ = 'Updating %s', part
+                    self._logger.info(*__doing__)
                     old_options = installed_part_options[part]
                     old_installed_files = old_options['__buildout_installed__']
                     try:
@@ -321,14 +313,14 @@
                             installed_files = [installed_files]
                         else:
                             installed_files = list(installed_files)
-                            
 
                         installed_files += [
                             p for p in old_installed_files.split('\n')
                             if p and p not in installed_files]
 
                 else:
-                    self._logger.info('Installing %s', part)
+                    __doing__ = 'Installing %s', part
+                    self._logger.info(*__doing__)
                     installed_files = recipe.install()
                     if installed_files is None:
                         self._logger.warning(
@@ -356,7 +348,28 @@
             
             self._save_installed_options(installed_part_options)
 
+    def _uninstall_part(self, part, installed_part_options):
+        # ununstall part
+        __doing__ = 'Uninstalling %s', part
+        self._logger.info(*__doing__)
+
+        # run uinstall recipe
+        recipe, entry = _recipe(installed_part_options[part])
+        try:
+            uninstaller = _install_and_load(
+                recipe, 'zc.buildout.uninstall', entry, self)
+            self._logger.info('Running uninstall recipe')
+            uninstaller(part, installed_part_options[part])
+        except (ImportError, pkg_resources.DistributionNotFound), v:
+            pass
+
+        # remove created files and directories
+        self._uninstall(
+            installed_part_options[part]['__buildout_installed__'])
+
+
     def _setup_directories(self):
+        __doing__ = 'Setting up buildout directories'
 
         # Create buildout directories
         for name in ('bin', 'parts', 'eggs', 'develop-eggs'):
@@ -368,6 +381,8 @@
     def _develop(self):
         """Install sources by running setup.py develop on them
         """
+        __doing__ = 'Processing directories listed in the develop option'
+
         develop = self['buildout'].get('develop')
         if not develop:
             return ''
@@ -382,6 +397,7 @@
                 for setup in develop.split():
                     setup = self._buildout_path(setup)
                     self._logger.info("Develop: %s", setup)
+                    __doing__ = 'Processing develop directory %s', setup
                     zc.buildout.easy_install.develop(setup, dest)
             except:
                 # if we had an error, we need to roll back changes, by
@@ -482,9 +498,8 @@
             _save_options(part, installed_options[part], f)
         f.close()
 
-    def _error(self, message, *args, **kw):
-        self._logger.error(message, *args, **kw)
-        sys.exit(1)
+    def _error(self, message, *args):
+        raise zc.buildout.UserError(message % args)
 
     def _setup_logging(self):
         root_logger = logging.getLogger()
@@ -513,6 +528,7 @@
     def _maybe_upgrade(self):
         # See if buildout or setuptools need to be upgraded.
         # If they do, do the upgrade and restart the buildout process.
+        __doing__ = 'Checking for upgrades'
 
         if not self.newest:
             return
@@ -537,6 +553,8 @@
         if not upgraded:
             return
 
+        __doing__ = 'Upgrading'
+
         should_run = realpath(
             os.path.join(os.path.abspath(self['buildout']['bin-directory']),
                          'buildout')
@@ -583,6 +601,7 @@
         sys.exit(os.spawnv(os.P_WAIT, sys.executable, args))
 
     def _load_extensions(self):
+        __doing__ = 'Loading extensions'
         specs = self['buildout'].get('extensions', '').split()
         if specs:
             path = [self['buildout']['develop-eggs-directory']]
@@ -628,6 +647,7 @@
     runsetup = setup # backward compat.
 
     def __getitem__(self, section):
+        __doing__ = 'Getting section %s', section
         try:
             return self._data[section]
         except KeyError:
@@ -657,12 +677,13 @@
 
 
 def _install_and_load(spec, group, entry, buildout):
+    __doing__ = 'Loading recipe %s', spec
     try:
-
         req = pkg_resources.Requirement.parse(spec)
 
         buildout_options = buildout['buildout']
         if pkg_resources.working_set.find(req) is None:
+            __doing__ = 'Installing recipe %s', spec
             if buildout.offline:
                 dest = None
                 path = [buildout_options['develop-eggs-directory'],
@@ -681,6 +702,7 @@
                 newest=buildout.newest,
                 )
 
+        __doing__ = 'Loading %s recipe entry %s:%s', group, spec, entry
         return pkg_resources.load_entry_point(
             req.project_name, group, entry)
 
@@ -700,6 +722,8 @@
         self._data = {}
 
     def _initialize(self):
+        name = self.name
+        __doing__ = 'Initializing section %s', name
         # force substitutions
         for k in self._raw:
             self.get(k)
@@ -712,8 +736,9 @@
         buildout = self.buildout
         recipe_class = _install_and_load(reqs, 'zc.buildout', entry, buildout)
 
-        self.recipe = recipe_class(buildout, self.name, self)
-        buildout._parts.append(self.name)
+        __doing__ = 'Initializing part %s', name
+        self.recipe = recipe_class(buildout, name, self)
+        buildout._parts.append(name)
 
     def get(self, option, default=None, seen=None):
         try:
@@ -725,6 +750,8 @@
         if v is None:
             return default
 
+        __doing__ = 'Getting option %s:%s', self.name, option
+
         if '${' in v:
             key = self.name, option
             if seen is None:
@@ -732,10 +759,6 @@
             elif key in seen:
                 raise zc.buildout.UserError(
                     "Circular reference in substitutions.\n"
-                    "We're evaluating %s\nand are referencing: %s.\n"
-                    % (", ".join([":".join(k) for k in seen]),
-                       ":".join(key)
-                       )
                     )
             else:
                 seen.append(key)
@@ -789,8 +812,7 @@
 
         v = self.get(key)
         if v is None:
-            raise MissingOption("Missing option: %s:%s"
-                                % (self.name, key))
+            raise MissingOption("Missing option: %s:%s" % (self.name, key))
         return v
 
     def __setitem__(self, option, value):
@@ -954,10 +976,39 @@
 
     return recipe, entry
 
+def _doing():
+    _, v, tb = sys.exc_info()
+    message = str(v)
+    doing = []
+    while tb is not None:
+        d = tb.tb_frame.f_locals.get('__doing__')
+        if d:
+            doing.append(d)
+        tb = tb.tb_next
+        
+    if doing:
+        sys.stderr.write('While:\n')
+        for d in doing:
+            if not isinstance(d, str):
+                d = d[0] % d[1:]
+            sys.stderr.write('  %s\n' % d)
+
 def _error(*message):
     sys.stderr.write('Error: ' + ' '.join(message) +'\n')
     sys.exit(1)
 
+_internal_error_template = """
+An internal error occured due to a bug in either zc.buildout or in a
+recipe being used:
+
+%s:
+%s
+"""
+
+def _internal_error(v):
+    sys.stderr.write(_internal_error_template % (v.__class__.__name__, v))
+    
+
 _usage = """\
 Usage: buildout [options] [assignments] [command [command arguments]]
 
@@ -1011,6 +1062,12 @@
     new distributions if installed distributions satisfy it's
     requirements. 
 
+  -D
+
+    Debug errors.  If an error occurs, then the post-mortem debugger
+    will be started. This is especially useful for debuging recipe
+    problems.
+
 Assignments are of the form: section:option=value and are used to
 provide configuration options that override those given in the
 configuration file.  For example, to run the buildout in offline mode,
@@ -1046,11 +1103,12 @@
     options = []
     windows_restart = False
     user_defaults = True
+    debug = False
     while args:
         if args[0][0] == '-':
             op = orig_op = args.pop(0)
             op = op[1:]
-            while op and op[0] in 'vqhWUoOnN':
+            while op and op[0] in 'vqhWUoOnND':
                 if op[0] == 'v':
                     verbosity += 10
                 elif op[0] == 'q':
@@ -1067,6 +1125,8 @@
                     options.append(('buildout', 'newest', 'true'))
                 elif op[0] == 'N':
                     options.append(('buildout', 'newest', 'false'))
+                elif op[0] == 'D':
+                    debug = True
                 else:
                     _help()
                 op = op[1:]
@@ -1110,8 +1170,21 @@
             buildout = Buildout(config_file, options,
                                 user_defaults, windows_restart)
             getattr(buildout, command)(args)
-        except zc.buildout.UserError, v:
-            _error(str(v))
+        except SystemExit:
+            pass
+        except Exception, v:
+            _doing()
+            if debug:
+                exc_info = sys.exc_info()
+                import pdb, traceback
+                traceback.print_exception(*exc_info)
+                sys.stderr.write('\nStarting pdb:\n')
+                pdb.post_mortem(exc_info[2])
+            else:
+                if isinstance(v, zc.buildout.UserError):
+                    _error(str(v))
+                else:
+                    _internal_error(v)
             
     finally:
             logging.shutdown()

Modified: zc.buildout/trunk/src/zc/buildout/buildout.txt
===================================================================
--- zc.buildout/trunk/src/zc/buildout/buildout.txt	2007-03-08 23:29:12 UTC (rev 73081)
+++ zc.buildout/trunk/src/zc/buildout/buildout.txt	2007-03-08 23:33:27 UTC (rev 73082)
@@ -120,9 +120,7 @@
     ... class Mkdir:
     ...
     ...     def __init__(self, buildout, name, options):
-    ...         self.buildout = buildout
-    ...         self.name = name
-    ...         self.options = options
+    ...         self.name, self.options = name, options
     ...         options['path'] = os.path.join(
     ...                               buildout['buildout']['directory'],
     ...                               options['path'],
@@ -367,10 +365,10 @@
 If a user makes an error, an error needs to be printed and work needs
 to stop.  This is accomplished by logging a detailed error message and
 then raising a (or an instance of a subclass of a)
-zc.buildout.UserError exception.  Raising UserError causes the
-buildout to print the error and exit without printing a traceback.  In
-the sample above, of someone gives a non-existant directory to create
-the directory in:
+zc.buildout.UserError exception.  Raising an error other than a
+UserError still displays the error, but labels it as a bug in the
+buildout software or recipe. In the sample above, of someone gives a
+non-existant directory to create the directory in:
 
 
     >>> write(sample_buildout, 'buildout.cfg',
@@ -389,6 +387,10 @@
     >>> print system(buildout),
     buildout: Develop: /sample-buildout/recipes
     data-dir: Cannot create /xxx/mydata. /xxx is not a directory.
+    While:
+      Installing
+      Getting section data-dir
+      Initializing part data-dir
     Error: Invalid Path
 
 
@@ -813,6 +815,8 @@
     ... """)
 
     >>> print system(buildout + ' -c ' + server_url + '/remote.cfg'),
+    While:
+      Initializing
     Error: Missing option: buildout:directory
 
 Normally, the buildout directory defaults to directory

Added: zc.buildout/trunk/src/zc/buildout/debugging.txt
===================================================================
--- zc.buildout/trunk/src/zc/buildout/debugging.txt	2007-03-08 23:29:12 UTC (rev 73081)
+++ zc.buildout/trunk/src/zc/buildout/debugging.txt	2007-03-08 23:33:27 UTC (rev 73082)
@@ -0,0 +1,96 @@
+Debugging buildouts
+===================
+
+Buildouts can be pretty complex.  When things go wrong, it isn't
+always obvious why.  Errors can occur due to problems in user input or
+due to bugs in zc.buildout or recipes.  When an error occurs, Python's
+post-mortem debugger can be used to inspect the state of the buildout
+or recipe code were there error occured.  To enable this, use the -D
+option to the buildout.  Let's create a recipe that has a bug:
+
+    >>> mkdir(sample_buildout, 'recipes')
+
+    >>> write(sample_buildout, 'recipes', 'mkdir.py', 
+    ... """
+    ... import os, zc.buildout
+    ...
+    ... class Mkdir:
+    ...
+    ...     def __init__(self, buildout, name, options):
+    ...         self.name, self.options = name, options
+    ...         options['path'] = os.path.join(
+    ...                               buildout['buildout']['directory'],
+    ...                               options['path'],
+    ...                               )
+    ...
+    ...     def install(self):
+    ...         directory = self.options['directory']
+    ...         os.mkdir(directory)
+    ...         return directory
+    ...
+    ...     def update(self):
+    ...         pass
+    ... """)
+
+    >>> write(sample_buildout, 'recipes', 'setup.py',
+    ... """
+    ... from setuptools import setup
+    ... 
+    ... setup(name = "recipes",
+    ...       entry_points = {'zc.buildout': ['mkdir = mkdir:Mkdir']},
+    ...       )
+    ... """)
+
+And create a buildout that uses it:
+
+    >>> write(sample_buildout, 'buildout.cfg',
+    ... """
+    ... [buildout]
+    ... develop = recipes
+    ... parts = data-dir
+    ...
+    ... [data-dir]
+    ... recipe = recipes:mkdir
+    ... path = mystuff
+    ... """)
+
+If we run the buildout, we'll get an error:
+
+    >>> print system(buildout),
+    buildout: Develop: /sample-buildout/recipes
+    buildout: Installing data-dir
+    While:
+      Installing data-dir
+    Error: Missing option: data-dir:directory
+
+
+If we want to debug the error, we can add the -D option. Here's we'll
+supply some input:
+
+    >>> print system(buildout+" -D", """\
+    ... up
+    ... p self.options.keys()
+    ... q
+    ... """),
+    buildout: Develop: /tmp/tmpozk_tH/_TEST_/sample-buildout/recipes
+    buildout: Installing data-dir
+    While:
+      Installing data-dir
+    Traceback (most recent call last):
+      File "/zc/buildout/buildout.py", line 1173, in main
+        getattr(buildout, command)(args)
+      File "/zc/buildout/buildout.py", line 324, in install
+        installed_files = recipe.install()
+      File "/sample-buildout/recipes/mkdir.py", line 14, in install
+        directory = self.options['directory']
+      File "/zc/buildout/buildout.py", line 815, in __getitem__
+        raise MissingOption("Missing option: %s:%s" % (self.name, key))
+    MissingOption: Missing option: data-dir:directory
+    <BLANKLINE>
+    Starting pdb:
+    > /zc/buildout/buildout.py(815)__getitem__()
+    -> raise MissingOption("Missing option: %s:%s" % (self.name, key))
+    (Pdb) > /sample-buildout/recipes/mkdir.py(14)install()
+    -> directory = self.options['directory']
+    (Pdb) ['path', 'recipe']
+    (Pdb) 


Property changes on: zc.buildout/trunk/src/zc/buildout/debugging.txt
___________________________________________________________________
Name: svn:eol-style
   + native

Modified: zc.buildout/trunk/src/zc/buildout/tests.py
===================================================================
--- zc.buildout/trunk/src/zc/buildout/tests.py	2007-03-08 23:29:12 UTC (rev 73081)
+++ zc.buildout/trunk/src/zc/buildout/tests.py	2007-03-08 23:33:27 UTC (rev 73082)
@@ -116,9 +116,15 @@
 
     >>> print system(os.path.join(sample_buildout, 'bin', 'buildout')),
     ... # doctest: +NORMALIZE_WHITESPACE +ELLIPSIS
+    While:
+      Initializing
+      Getting section buildout
+      Initializing section buildout
+      Getting option buildout:y
+      Getting option buildout:z
+      Getting option buildout:x
+      Getting option buildout:y
     Error: Circular reference in substitutions.
-    We're evaluating buildout:y, buildout:z, buildout:x
-    and are referencing: buildout:y.
 
 It is an error to use funny characters in variable refereces:
 
@@ -131,6 +137,11 @@
     ... ''')
 
     >>> print system(os.path.join(sample_buildout, 'bin', 'buildout')),
+    While:
+      Initializing
+      Getting section buildout
+      Initializing section buildout
+      Getting option buildout:x
     Error: The section name in substitution, ${bui$ldout:y},
     has invalid characters.
 
@@ -143,6 +154,11 @@
     ... ''')
 
     >>> print system(os.path.join(sample_buildout, 'bin', 'buildout')),
+    While:
+      Initializing
+      Getting section buildout
+      Initializing section buildout
+      Getting option buildout:x
     Error: The option name in substitution, ${buildout:y{z},
     has invalid characters.
 
@@ -157,6 +173,11 @@
     ... ''')
 
     >>> print system(os.path.join(sample_buildout, 'bin', 'buildout')),
+    While:
+      Initializing
+      Getting section buildout
+      Initializing section buildout
+      Getting option buildout:x
     Error: The substitution, ${parts},
     doesn't contain a colon.
 
@@ -169,6 +190,11 @@
     ... ''')
 
     >>> print system(os.path.join(sample_buildout, 'bin', 'buildout')),
+    While:
+      Initializing
+      Getting section buildout
+      Initializing section buildout
+      Getting option buildout:x
     Error: The substitution, ${buildout:y:z},
     has too many colons.
 
@@ -181,6 +207,9 @@
     ... ''')
 
     >>> print system(os.path.join(sample_buildout, 'bin', 'buildout')),
+    While:
+      Installing
+      Getting section x
     Error: The referenced section, 'x', was not defined.
 
 and all parts have to have a specified recipe:
@@ -196,6 +225,8 @@
     ... ''')
 
     >>> print system(os.path.join(sample_buildout, 'bin', 'buildout')),
+    While:
+      Installing
     Error: Missing option: x:recipe
 
 """
@@ -478,6 +509,12 @@
     new distributions if installed distributions satisfy it's
     requirements. 
 <BLANKLINE>
+  -D
+<BLANKLINE>
+    Debug errors.  If an error occurs, then the post-mortem debugger
+    will be started. This is especially useful for debuging recipe
+    problems.
+<BLANKLINE>
 Assignments are of the form: section:option=value and are used to
 provide configuration options that override those given in the
 configuration file.  For example, to run the buildout in offline mode,
@@ -555,6 +592,12 @@
     new distributions if installed distributions satisfy it's
     requirements. 
 <BLANKLINE>
+  -D
+<BLANKLINE>
+    Debug errors.  If an error occurs, then the post-mortem debugger
+    will be started. This is especially useful for debuging recipe
+    problems.
+<BLANKLINE>
 Assignments are of the form: section:option=value and are used to
 provide configuration options that override those given in the
 configuration file.  For example, to run the buildout in offline mode,
@@ -1233,6 +1276,55 @@
     
     """
 
+def internal_errors():
+    """Internal errors are clearly marked and don't generate tracebacks:
+
+    >>> mkdir(sample_buildout, 'recipes')
+
+    >>> write(sample_buildout, 'recipes', 'mkdir.py', 
+    ... '''
+    ... class Mkdir:
+    ...     def __init__(self, buildout, name, options):
+    ...         self.name, self.options = name, options
+    ...         options['path'] = os.path.join(
+    ...                               buildout['buildout']['directory'],
+    ...                               options['path'],
+    ...                               )
+    ... ''')
+
+    >>> write(sample_buildout, 'recipes', 'setup.py',
+    ... '''
+    ... from setuptools import setup
+    ... setup(name = "recipes",
+    ...       entry_points = {'zc.buildout': ['mkdir = mkdir:Mkdir']},
+    ...       )
+    ... ''')
+
+    >>> write(sample_buildout, 'buildout.cfg',
+    ... '''
+    ... [buildout]
+    ... develop = recipes
+    ... parts = data-dir
+    ...
+    ... [data-dir]
+    ... recipe = recipes:mkdir
+    ... ''')
+
+    >>> print system(buildout),
+    buildout: Develop: /sample-buildout/recipes
+    While:
+      Installing
+      Getting section data-dir
+      Initializing part data-dir
+    <BLANKLINE>
+    An internal error occured due to a bug in either zc.buildout or in a
+    recipe being used:
+    <BLANKLINE>
+    NameError:
+    global name 'os' is not defined
+    """
+    
+
 ######################################################################
     
 def create_sample_eggs(test, executable=sys.executable):
@@ -1440,6 +1532,17 @@
                 'picked \\1 = V.V'),
                ])
             ),
+        doctest.DocFileSuite(
+            'debugging.txt',
+            setUp=zc.buildout.testing.buildoutSetUp,
+            tearDown=zc.buildout.testing.buildoutTearDown,
+            checker=renormalizing.RENormalizing([
+               zc.buildout.testing.normalize_path,
+               (re.compile(r'\S+buildout.py'), 'buildout.py'),
+               (re.compile(r'line \d+'), 'line NNN'),
+               (re.compile(r'py\(\d+\)'), 'py(NNN)'),
+               ])
+            ),
 
         doctest.DocFileSuite(
             'update.txt',



More information about the Checkins mailing list