Use the logging module's features to avoid doing string formatting when we're not actually logging. This helps execution times a little bit.
authorBenjamin Smedberg <benjamin@smedbergs.us>
Wed, 25 Feb 2009 13:48:14 -0500
changeset 176 1a7ac665abd4d9334c8752e3a3dab5c17e82044c
parent 175 482594865681af40760ae1f213d62ca11111867b
child 177 38b633e97cf72ff0f0e343f923496c376e1e45e4
push id103
push userbsmedberg@mozilla.com
push dateWed, 25 Feb 2009 21:20:57 +0000
Use the logging module's features to avoid doing string formatting when we're not actually logging. This helps execution times a little bit.
pymake/command.py
pymake/data.py
pymake/parser.py
pymake/parserdata.py
pymake/process.py
--- a/pymake/command.py
+++ b/pymake/command.py
@@ -56,17 +56,17 @@ This is free software; see the source fo
 THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
 IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
 FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
 AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
 LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
 FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER
 DEALINGS IN THE SOFTWARE."""
 
-log = logging.getLogger('pymake.execution')
+_log = logging.getLogger('pymake.execution')
 
 def main(args, env, cwd, context, cb):
     try:
         makelevel = int(env.get('MAKELEVEL', '0'))
 
         op = OptionParser()
         op.add_option('-f', '--file', '--makefile',
                       action='append',
@@ -116,25 +116,25 @@ def main(args, env, cwd, context, cb):
 
         shortflags.append('j%i' % (options.jobcount,))
 
         makeflags = ''.join(shortflags) + ' ' + ' '.join(longflags)
 
         logging.basicConfig(level=loglevel, **logkwargs)
 
         if context is not None and context.jcount > 1 and options.jobcount == 1:
-            log.debug("-j1 specified, creating new serial execution context")
+            _log.debug("-j1 specified, creating new serial execution context")
             context = process.getcontext(options.jobcount)
             subcontext = True
         elif context is None:
-            log.debug("Creating new execution context, jobcount %s" % options.jobcount)
+            _log.debug("Creating new execution context, jobcount %s", options.jobcount)
             context = process.getcontext(options.jobcount)
             subcontext = True
         else:
-            log.debug("Using parent execution context")
+            _log.debug("Using parent execution context")
             subcontext = False
 
         if options.printdir:
             print "make.py[%i]: Entering directory '%s'" % (makelevel, workdir)
             sys.stdout.flush()
 
         if len(options.makefiles) == 0:
             if os.path.exists(os.path.join(workdir, 'Makefile')):
@@ -166,17 +166,17 @@ def main(args, env, cwd, context, cb):
                                                       realtargets=realtargets, tstack=tstack, i=i+1, firsterror=firsterror)
 
                 makefile.gettarget(realtargets[i]).make(makefile, tstack, [], cb=deferredmake)
                                                                                   
 
         def remakecb(remade, restarts, makefile):
             if remade:
                 if restarts > 0:
-                    log.info("make.py[%i]: Restarting makefile parsing" % (makelevel,))
+                    _log.info("make.py[%i]: Restarting makefile parsing", makelevel)
                 makefile = data.Makefile(restarts=restarts, make='%s %s' % (sys.executable.replace('\\', '/'), makepypath.replace('\\', '/')),
                                          makeflags=makeflags, makelevel=makelevel, workdir=workdir,
                                          context=context, env=env)
 
                 try:
                     overrides.execute(makefile)
                     for f in options.makefiles:
                         makefile.include(f)
@@ -191,17 +191,17 @@ def main(args, env, cwd, context, cb):
                 return
 
             if len(targets) == 0:
                 if makefile.defaulttarget is None:
                     print "No target specified and no default target found."
                     context.defer(cb, 2)
                     return
 
-                log.info("Making default target %s" % (makefile.defaulttarget,))
+                _log.info("Making default target %s", makefile.defaulttarget)
                 realtargets = [makefile.defaulttarget]
                 tstack = ['<default-target>']
             else:
                 realtargets = targets
                 tstack = ['<command-line>']
 
             deferredmake = process.makedeferrable(makecb, makefile=makefile,
                                                   realtargets=realtargets, tstack=tstack, i=1, firsterror=None)
--- a/pymake/data.py
+++ b/pymake/data.py
@@ -4,17 +4,17 @@ A representation of makefile data struct
 
 import logging, re, os
 import parserdata
 import pymake.parser
 import pymake.functions
 import pymake.process
 import pymake.util
 
-log = logging.getLogger('pymake.data')
+_log = logging.getLogger('pymake.data')
 
 class DataError(pymake.util.MakeError):
     pass
 
 class ResolutionError(DataError):
     """
     Raised when dependency resolution fails, either due to recursion or to missing
     prerequisites.This is separately catchable so that implicit rule search can try things
@@ -229,17 +229,17 @@ class Variables(object):
     def set(self, name, flavor, source, value):
         assert flavor in (self.FLAVOR_RECURSIVE, self.FLAVOR_SIMPLE)
         assert source in (self.SOURCE_OVERRIDE, self.SOURCE_COMMANDLINE, self.SOURCE_MAKEFILE, self.SOURCE_ENVIRONMENT, self.SOURCE_AUTOMATIC)
         assert isinstance(value, str), "expected str, got %s" % type(value)
 
         prevflavor, prevsource, prevvalue = self.get(name)
         if prevsource is not None and source > prevsource:
             # TODO: give a location for this warning
-            log.warning("not setting variable '%s', set by higher-priority source to value '%s'" % (name, prevvalue))
+            _log.info("not setting variable '%s', set by higher-priority source to value '%s'" % (name, prevvalue))
             return
 
         self._map[name] = (flavor, source, value)
 
     def append(self, name, source, value, variables, makefile):
         assert source in (self.SOURCE_OVERRIDE, self.SOURCE_MAKEFILE, self.SOURCE_AUTOMATIC)
         assert isinstance(value, str)
         
@@ -445,33 +445,31 @@ class Target(object):
     def resolveimplicitrule(self, makefile, targetstack, rulestack):
         """
         Try to resolve an implicit rule to build this target.
         """
         # The steps in the GNU make manual Implicit-Rule-Search.html are very detailed. I hope they can be trusted.
 
         indent = getindent(targetstack)
 
-        log.info(indent + "Trying to find implicit rule to make '%s'" % (self.target,))
+        _log.info("%sSearching for implicit rule to make '%s'", indent, self.target)
 
         dir, s, file = self.target.rpartition('/')
         dir = dir + s
 
         candidates = [] # list of PatternRuleInstance
 
         hasmatch = any((r.hasspecificmatch(file) for r in makefile.implicitrules))
-        log.debug("Does any implicit rule match '%s'? %s" % (self.target, hasmatch))
 
         for r in makefile.implicitrules:
             if r in rulestack:
-                log.info(indent + " %s: Avoiding implicit rule recursion" % (r.loc,))
+                _log.info("%s %s: Avoiding implicit rule recursion", indent, r.loc)
                 continue
 
             if not len(r.commands):
-                log.info(indent + " %s: Has no commands" % (r.loc,))
                 continue
 
             for ri in r.matchesfor(dir, file, hasmatch):
                 candidates.append(ri)
             
         newcandidates = []
 
         for r in candidates:
@@ -480,22 +478,22 @@ class Target(object):
                 t = makefile.gettarget(p)
                 t.resolvevpath(makefile)
                 if not t.explicit and t.mtime is None:
                     depfailed = p
                     break
 
             if depfailed is not None:
                 if r.doublecolon:
-                    log.info(indent + " Terminal rule at %s doesn't match: prerequisite '%s' not mentioned and doesn't exist." % (r.loc, depfailed))
+                    _log.info("%s Terminal rule at %s doesn't match: prerequisite '%s' not mentioned and doesn't exist.", indent, r.loc, depfailed)
                 else:
                     newcandidates.append(r)
                 continue
 
-            log.info(indent + "Found implicit rule at %s for target '%s'" % (r.loc, self.target))
+            _log.info("%sFound implicit rule at %s for target '%s'", indent, r.loc, self.target)
             self.rules.append(r)
             return
 
         # Try again, but this time with chaining and without terminal (double-colon) rules
 
         for r in newcandidates:
             newrulestack = rulestack + [r.prule]
 
@@ -504,24 +502,24 @@ class Target(object):
                 t = makefile.gettarget(p)
                 try:
                     t.resolvedeps(makefile, targetstack, newrulestack, True)
                 except ResolutionError:
                     depfailed = p
                     break
 
             if depfailed is not None:
-                log.info(indent + " Rule at %s doesn't match: prerequisite '%s' could not be made." % (r.loc, depfailed))
+                _log.info("%s Rule at %s doesn't match: prerequisite '%s' could not be made.", indent, r.loc, depfailed)
                 continue
 
-            log.info(indent + "Found implicit rule at %s for target '%s'" % (r.loc, self.target))
+            _log.info("%sFound implicit rule at %s for target '%s'", indent, r.loc, self.target)
             self.rules.append(r)
             return
 
-        log.info(indent + "Couldn't find implicit rule to remake '%s'" % (self.target,))
+        _log.info("%sCouldn't find implicit rule to remake '%s'", indent, self.target)
 
     def ruleswithcommands(self):
         "The number of rules with commands"
         return reduce(lambda i, rule: i + (len(rule.commands) > 0), self.rules, 0)
 
     def resolvedeps(self, makefile, targetstack, rulestack, required):
         """
         Resolve the actual path of this target, using vpath if necessary.
@@ -543,17 +541,17 @@ class Target(object):
         if self.target in targetstack:
             raise ResolutionError("Recursive dependency: %s -> %s" % (
                     " -> ".join(targetstack), self.target))
 
         targetstack = targetstack + [self.target]
         
         indent = getindent(targetstack)
 
-        log.info(indent + "Considering target '%s'" % (self.target,))
+        _log.info("%sConsidering target '%s'", indent, self.target)
 
         self.resolvevpath(makefile)
 
         # Sanity-check our rules. If we're single-colon, only one rule should have commands
         ruleswithcommands = self.ruleswithcommands()
         if len(self.rules) and not self.isdoublecolon():
             if ruleswithcommands > 1:
                 # In GNU make this is a warning, not an error. I'm going to be stricter.
@@ -570,17 +568,16 @@ class Target(object):
         # Otherwise, we don't know how to make it.
         if not len(self.rules) and self.mtime is None and not any((len(rule.prerequisites) > 0
                                                                    for rule in self.rules)):
             if required:
                 raise ResolutionError("No rule to make target '%s' needed by %r" % (self.target,
                                                                                     targetstack))
 
         for r in self.rules:
-            log.info(indent + "Will remake target '%s' using rule at %s" % (self.target, r.loc))
             newrulestack = rulestack + [r]
             for d in r.prerequisites:
                 dt = makefile.gettarget(d)
                 if dt.explicit:
                     continue
 
                 dt.resolvedeps(makefile, targetstack, newrulestack, True)
 
@@ -646,31 +643,27 @@ class Target(object):
 
         We store our old mtime so that $? can calculate out-of-date prerequisites.
         """
         self.realmtime = self.mtime
         self.mtime = None
         self.vpathtarget = self.target
 
     def _notifyerror(self, makefile, e):
-        log.debug("Making target '%s' failed with error %s" % (self.target, e))
-
         if self._state == MAKESTATE_FINISHED:
             # multiple callbacks failed. The first one already finished us, so we ignore this one
             return
 
         self._state = MAKESTATE_FINISHED
         self._makeerror = e
         for cb in self._callbacks:
             makefile.context.defer(cb, error=e, didanything=None)
         del self._callbacks 
 
     def _notifysuccess(self, makefile, didanything):
-        log.debug("Making target '%s' succeeded" % (self.target,))
-
         self._state = MAKESTATE_FINISHED
         self._makeerror = None
         self._didanything = didanything
 
         for cb in self._callbacks:
             makefile.context.defer(cb, error=None, didanything=didanything)
 
         del self._callbacks
@@ -687,30 +680,26 @@ class Target(object):
         * execute each command (asynchronous, makeself.commandcb)
 
         @param cb A callback function to notify when remaking is finished. It is called
                thusly: callback(error=exception/None, didanything=True/False/None)
                If there is no asynchronous activity to perform, the callback may be called directly.
         """
         if self._state == MAKESTATE_FINISHED:
             if self._makeerror is not None:
-                log.debug("Already made target '%s', got error %s" % (self.target, self._makeerror))
                 cb(error=self._makeerror, didanything=False) #XXX?
             else:
-                log.debug("Already made target '%s'" % (self.target,))
                 cb(error=None, didanything=self._didanything)
             return
             
         if self._state == MAKESTATE_WORKING:
-            log.debug("Already making target '%s', adding callback. targetstack %r" % (self.target, targetstack))
             self._callbacks.append(cb)
             return
 
         assert self._state == MAKESTATE_NONE
-        log.debug("Starting to make target '%s', targetstack %r" % (self.target, targetstack))
 
         self._state = MAKESTATE_WORKING
         self._callbacks = [cb]
 
         indent = getindent(targetstack)
 
         # this object exists solely as a container to subvert python's read-only closures
         o = pymake.util.makeobject(('unmadedeps', 'didanything', 'error'))
@@ -761,49 +750,49 @@ class Target(object):
             commands = []
             if len(self.rules) == 0:
                 pass
             elif self.isdoublecolon():
                 for r, deps in _resolvedrules:
                     remake = False
                     if len(deps) == 0:
                         if avoidremakeloop:
-                            log.info(indent + "Not remaking %s using rule at %s because it would introduce an infinite loop." % (self.target, r.loc))
+                            _log.info("%sNot remaking %s using rule at %s because it would introduce an infinite loop.", indent, self.target, r.loc)
                         else:
-                            log.info(indent + "Remaking %s using rule at %s because there are no prerequisites listed for a double-colon rule." % (self.target, r.loc))
+                            _log.info("%sRemaking %s using rule at %s because there are no prerequisites listed for a double-colon rule.", indent, self.target, r.loc)
                             remake = True
                     else:
                         if self.mtime is None:
-                            log.info(indent + "Remaking %s using rule at %s because it doesn't exist or is a forced target" % (self.target, r.loc))
+                            _log.info("%sRemaking %s using rule at %s because it doesn't exist or is a forced target", indent, self.target, r.loc)
                             remake = True
                         else:
                             for d in deps:
                                 if mtimeislater(d.mtime, self.mtime):
-                                    log.info(indent + "Remaking %s using rule at %s because %s is newer." % (self.target, r.loc, d.target))
+                                    _log.info("%sRemaking %s using rule at %s because %s is newer.", indent, self.target, r.loc, d.target)
                                     remake = True
                                     break
                     if remake:
                         self._beingremade()
                         commands.extend(r.getcommands(self, makefile))
             else:
                 commandrule = None
                 remake = False
                 if self.mtime is None:
-                    log.info(indent + "Remaking %s because it doesn't exist or is a forced target" % (self.target,))
+                    _log.info("%sRemaking %s because it doesn't exist or is a forced target", indent, self.target)
                     remake = True
 
                 for r, deps in _resolvedrules:
                     if len(r.commands):
                         assert commandrule is None, "Two command rules for a single-colon target?"
                         commandrule = r
 
                     if not remake:
                         for d in deps:
                             if mtimeislater(d.mtime, self.mtime):
-                                log.info(indent + "Remaking %s because %s is newer" % (self.target, d.target))
+                                _log.info("%sRemaking %s because %s is newer", indent, self.target, d.target)
                                 remake = True
 
                 if remake:
                     self._beingremade()
                     if commandrule is not None:
                         commands.extend(commandrule.getcommands(self, makefile))
 
             def commandcb(error):
@@ -818,17 +807,16 @@ class Target(object):
 
             commandcb(None)
                     
         try:
             self.resolvedeps(makefile, targetstack, rulestack, required)
             assert self.vpathtarget is not None, "Target was never resolved!"
 
             _resolvedrules = [(r, [makefile.gettarget(p) for p in r.prerequisites]) for r in self.rules]
-            log.debug("resolvedrules for %r: %r" % (self.target, _resolvedrules))
 
             targetstack = targetstack + [self.target]
 
             o.didanything = False
             o.unmadedeps = 1
             o.error = None
 
             depiterator = iterdeps()
@@ -1176,31 +1164,27 @@ class Makefile(object):
             self.gettarget(path).explicit = True
         elif required:
             raise DataError("Attempting to include file '%s' which doesn't exist." % (path,), loc)
 
     def addvpath(self, pattern, dirs):
         """
         Add a directory to the vpath search for the given pattern.
         """
-        log.info("Adding vpath directive: pattern '%s' directories %r" % (pattern, dirs))
         self._patternvpaths.append((pattern, dirs))
 
     def clearvpath(self, pattern):
         """
         Clear vpaths for the given pattern.
         """
-        log.info("Clearing vpath directives for pattern '%s'" % (pattern,))
-
         self._patternvpaths = [(p, dirs)
                                for p, dirs in self._patternvpaths
                                if not p.match(pattern)]
 
     def clearallvpaths(self):
-        log.info("Clearing all vpath directives")
         self._patternvpaths = []
 
     def getvpath(self, target):
         vp = list(self._vpath)
         for p, dirs in self._patternvpaths:
             if p.match(target):
                 vp.extend(dirs)
 
--- a/pymake/parser.py
+++ b/pymake/parser.py
@@ -19,17 +19,17 @@ nest parenthesized syntax.
 
 This file parses into the data structures defined in the parserdata module. Those classes are what actually
 do the dirty work of "executing" the parsed data into a Makefile data structure.
 """
 
 import logging, re, os
 import data, functions, util, parserdata
 
-log = logging.getLogger('pymake.parser')
+_log = logging.getLogger('pymake.parser')
 
 class SyntaxError(util.MakeError):
     pass
 
 def findlast(func, iterable):
     for i in iterable:
         if func(i):
             f = i
@@ -442,20 +442,20 @@ def parsefile(pathname):
     pathname = os.path.realpath(pathname)
 
     mtime = os.path.getmtime(pathname)
 
     if pathname in _parsecache:
         oldmtime, stmts = _parsecache[pathname]
 
         if mtime == oldmtime:
-            log.debug("Using '%s' from the parser cache.", pathname)
+            _log.debug("Using '%s' from the parser cache.", pathname)
             return stmts
 
-        log.debug("Not using '%s' from the parser cache, mtimes don't match: was %s, now %s" % (pathname, oldmtime, mtime))
+        _log.debug("Not using '%s' from the parser cache, mtimes don't match: was %s, now %s", pathname, oldmtime, mtime)
 
     stmts = parsestream(open(pathname, "rU"), pathname)
     _parsecache[pathname] = mtime, stmts
     return stmts
 
 def parsestream(fd, filename):
     """
     Parse a stream of makefile into a parser data structure.
@@ -790,17 +790,17 @@ def parsemakesyntax(d, startat, stopon, 
                 stacktop.substfrom = stacktop.expansion
                 stacktop.parsestate = PARSESTATE_SUBSTTO
                 stacktop.expansion = data.Expansion()
                 stacktop.tokenlist = TokenList.get((stacktop.closebrace, '$'))
             elif token in (')', '}'):
                 # A substitution of the form $(VARNAME:.ee) is probably a mistake, but make
                 # parses it. Issue a warning. Combine the varname and substfrom expansions to
                 # make the compatible varname. See tests/var-substitutions.mk SIMPLE3SUBSTNAME
-                log.warning("%s: Variable reference looks like substitution without =" % (stacktop.loc, ))
+                _log.warning("%s: Variable reference looks like substitution without =", stacktop.loc)
                 stacktop.varname.append(':')
                 stacktop.varname.concat(stacktop.expansion)
                 stack.pop()
                 stack[-1].expansion.append(functions.VariableRef(stacktop.loc, stacktop.varname))
             else:
                 assert False, "Not reached, PARSESTATE_SUBSTFROM"
         elif stacktop.parsestate == PARSESTATE_SUBSTTO:
             assert token in  (')','}'), "Not reached, PARSESTATE_SUBSTTO"
--- a/pymake/parserdata.py
+++ b/pymake/parserdata.py
@@ -96,17 +96,16 @@ class Override(Statement):
     def execute(self, makefile, context):
         makefile.overrides.append(self.s)
 
     def dump(self, fd, indent):
         print >>fd, indent, "Override: %r" % (self.s,)
 
 class DummyRule(object):
     def addcommand(self, r):
-        _log.debug("Discarding rule at %s" % (r.loc,))
         pass
 
 class Rule(Statement):
     def __init__(self, targetexp, depexp, doublecolon):
         assert isinstance(targetexp, data.Expansion)
         assert isinstance(depexp, data.Expansion)
         
         self.targetexp = targetexp
@@ -285,18 +284,16 @@ class IfdefCondition(Condition):
     def __init__(self, exp):
         assert isinstance(exp, data.Expansion)
         self.exp = exp
 
     def evaluate(self, makefile):
         vname = self.exp.resolve(makefile, makefile.variables)
         flavor, source, value = makefile.variables.get(vname, expand=False)
 
-        _log.debug("ifdef at %s: vname: %r value is %r" % (self.exp.loc, vname, value))
-
         if value is None:
             return not self.expected
 
         return (len(value) > 0) == self.expected
 
     def __str__(self):
         return "ifdef (expected=%s) %r" % (self.expected, self.exp)
 
@@ -329,17 +326,17 @@ class ConditionBlock(Statement):
 
     def append(self, statement):
         self._groups[-1][1].append(statement)
 
     def execute(self, makefile, context):
         i = 0
         for c, statements in self._groups:
             if c.evaluate(makefile):
-                _log.debug("Condition at %s met by clause #%i" % (self.loc, i))
+                _log.debug("Condition at %s met by clause #%i", self.loc, i)
                 statements.execute(makefile, context)
                 return
 
             i += 1
 
     def dump(self, fd, indent):
         print >>fd, indent, "ConditionBlock"
 
--- a/pymake/process.py
+++ b/pymake/process.py
@@ -5,41 +5,53 @@ parsing command lines into argv and maki
 
 import subprocess, shlex, re, logging, sys, traceback, os
 import command, util
 if sys.platform=='win32':
     import win32process
 
 _log = logging.getLogger('pymake.process')
 
-blacklist = re.compile(r'[=\\$><;*?[{~`|&]')
+_blacklist = re.compile(r'[=\\$><;*?[{~`|&]')
 def clinetoargv(cline):
     """
     If this command line can safely skip the shell, return an argv array.
+    @returns argv, badchar
     """
 
-    if blacklist.search(cline) is not None:
-        return None
+    m = _blacklist.search(cline)
+    if m is not None:
+        return None, m.group(0)
 
-    return shlex.split(cline, comments=True)
+    return shlex.split(cline, comments=True), None
 
 shellwords = (':', '.', 'break', 'cd', 'continue', 'exec', 'exit', 'export',
               'getopts', 'hash', 'pwd', 'readonly', 'return', 'shift', 
               'test', 'times', 'trap', 'umask', 'unset', 'alias',
               'set', 'bind', 'builtin', 'caller', 'command', 'declare',
               'echo', 'enable', 'help', 'let', 'local', 'logout', 
               'printf', 'read', 'shopt', 'source', 'type', 'typeset',
               'ulimit', 'unalias', 'set')
 
 def call(cline, env, cwd, loc, cb, context, echo):
-    argv = clinetoargv(cline)
     #TODO: call this once up-front somewhere and save the result?
     shell, msys = util.checkmsyscompat()
-    if argv is None or (len(argv) and argv[0] in shellwords) or (msys and cline.startswith('/')):
-        _log.debug("%s: Running command through shell because of shell metacharacters" % (loc,))
+
+    shellreason = None
+    if msys and cline.startswith('/'):
+        shellreason = "command starts with /"
+    else:
+        argv, badchar = clinetoargv(cline)
+        if argv is None:
+            shellreason = "command contains shell-special character '%s'" % (badchar,)
+        elif argv[0] in shellwords:
+            shellreason = "command starts with shell primitive '%s'" % (argv[0],)
+
+    if shellreason is not None:
+        _log.debug("%s: using shell: %s: '%s'", loc, shellreason, cline)
         if msys:
             cline = [shell, "-c", cline]
         context.call(cline, shell=not msys, env=env, cwd=cwd, cb=cb, echo=echo)
         return
 
     if not len(argv):
         cb(res=0)
         return
@@ -53,17 +65,16 @@ def call(cline, env, cwd, loc, cb, conte
         command.main(argv[2:], env, cwd, context, cb)
         return
 
     if argv[0].find('/') != -1:
         executable = os.path.join(cwd, argv[0])
     else:
         executable = None
 
-    _log.debug("%s: skipping shell, no metacharacters found" % (loc,))
     context.call(argv, executable=executable, shell=False, env=env, cwd=cwd, cb=cb, echo=echo)
 
 def statustoresult(status):
     """
     Convert the status returned from waitpid into a prettier numeric result.
     """
     sig = status & 0xFF
     if sig:
@@ -93,30 +104,29 @@ class ParallelContext(object):
 
     def finish(self):
         assert len(self.pending) == 0 and len(self.running) == 0, "pending: %i running: %i" % (len(self.pending), len(self.running))
         self._allcontexts.remove(self)
 
     def run(self):
         while len(self.pending) and len(self.running) < self.jcount:
             cb, args, kwargs = self.pending.pop(0)
-            _log.debug("Running callback %r with args %r kwargs %r" % (cb, args, kwargs))
             cb(*args, **kwargs)
 
     def defer(self, cb, *args, **kwargs):
         self.pending.append((cb, args, kwargs))
 
     def _docall(self, argv, executable, shell, env, cwd, cb, echo):
             if echo is not None:
                 print echo
             try:
                 p = subprocess.Popen(argv, executable=executable, shell=shell, env=env, cwd=cwd)
             except OSError, e:
-                _log.info("Process with argv %r raised exception: %s" % (argv, e))
-                cb(2)
+                print >>sys.stderr, e
+                cb(-127)
                 return
 
             self.running.append((p, cb))
 
     def call(self, argv, shell, env, cwd, cb, echo, executable=None):
         """
         Asynchronously call the process
         """
@@ -142,18 +152,16 @@ class ParallelContext(object):
             return pid == process.pid
 
     @staticmethod
     def spin():
         """
         Spin the 'event loop', and never return.
         """
 
-        _log.debug("Spinning the event loop")
-
         while True:
             clist = list(ParallelContext._allcontexts)
             for c in clist:
                 c.run()
 
             dowait = any((len(c.running) for c in ParallelContext._allcontexts))
 
             if dowait: