extensions: use ui.log() interface to provide detailed loading information

The output format changes and the messages will be sent to stderr instead of
stdout, but I don't think that matters.

mercurial/extensions.py

@@ -1,843 +1,844 b''
 # extensions.py - extension handling for mercurial
 #
 # Copyright 2005-2007 Matt Mackall <[e-mail]>
 #
 # This software may be used and distributed according to the terms of the
 # GNU General Public License version 2 or any later version.
 
 from __future__ import absolute_import
 
 import ast
 import collections
 import functools
 import imp
 import inspect
 import os
 
 from .i18n import (
     _,
     gettext,
 )
 
 from . import (
     cmdutil,
     configitems,
     error,
     pycompat,
     util,
 )
 
 from .utils import (
     stringutil,
 )
 
 _extensions = {}
 _disabledextensions = {}
 _aftercallbacks = {}
 _order = []
 _builtin = {
     'hbisect',
     'bookmarks',
     'color',
     'parentrevspec',
     'progress',
     'interhg',
     'inotify',
     'hgcia'
 }
 
 def extensions(ui=None):
     if ui:
         def enabled(name):
             for format in ['%s', 'hgext.%s']:
                 conf = ui.config('extensions', format % name)
                 if conf is not None and not conf.startswith('!'):
                     return True
     else:
         enabled = lambda name: True
     for name in _order:
         module = _extensions[name]
         if module and enabled(name):
             yield name, module
 
 def find(name):
     '''return module with given extension name'''
     mod = None
     try:
         mod = _extensions[name]
     except KeyError:
         for k, v in _extensions.iteritems():
             if k.endswith('.' + name) or k.endswith('/' + name):
                 mod = v
                 break
     if not mod:
         raise KeyError(name)
     return mod
 
 def loadpath(path, module_name):
     module_name = module_name.replace('.', '_')
     path = util.normpath(util.expandpath(path))
     module_name = pycompat.fsdecode(module_name)
     path = pycompat.fsdecode(path)
     if os.path.isdir(path):
         # module/__init__.py style
         d, f = os.path.split(path)
         fd, fpath, desc = imp.find_module(f, [d])
         return imp.load_module(module_name, fd, fpath, desc)
     else:
         try:
             return imp.load_source(module_name, path)
         except IOError as exc:
             if not exc.filename:
                 exc.filename = path # python does not fill this
             raise
 
 def _importh(name):
     """import and return the <name> module"""
     mod = __import__(pycompat.sysstr(name))
     components = name.split('.')
     for comp in components[1:]:
         mod = getattr(mod, comp)
     return mod
 
 def _importext(name, path=None, reportfunc=None):
     if path:
         # the module will be loaded in sys.modules
         # choose an unique name so that it doesn't
         # conflicts with other modules
         mod = loadpath(path, 'hgext.%s' % name)
     else:
         try:
             mod = _importh("hgext.%s" % name)
         except ImportError as err:
             if reportfunc:
                 reportfunc(err, "hgext.%s" % name, "hgext3rd.%s" % name)
             try:
                 mod = _importh("hgext3rd.%s" % name)
             except ImportError as err:
                 if reportfunc:
                     reportfunc(err, "hgext3rd.%s" % name, name)
                 mod = _importh(name)
     return mod
 
 def _reportimporterror(ui, err, failed, next):
-    # note: this ui.debug happens before --debug is processed,
+    # note: this ui.log happens before --debug is processed,
     #       Use --config ui.debug=1 to see them.
-    if ui.configbool('devel', 'debug.extensions'):
-        ui.debug('debug.extensions:     - could not import %s (%s): trying %s\n'
-                 % (failed, stringutil.forcebytestr(err), next))
-        if ui.debugflag:
+    ui.log(b'extension', b'    - could not import %s (%s): trying %s\n',
+           failed, stringutil.forcebytestr(err), next)
+    if ui.debugflag and ui.configbool('devel', 'debug.extensions'):
             ui.traceback()
 
 def _rejectunicode(name, xs):
     if isinstance(xs, (list, set, tuple)):
         for x in xs:
             _rejectunicode(name, x)
     elif isinstance(xs, dict):
         for k, v in xs.items():
             _rejectunicode(name, k)
             _rejectunicode(b'%s.%s' % (name, stringutil.forcebytestr(k)), v)
     elif isinstance(xs, type(u'')):
         raise error.ProgrammingError(b"unicode %r found in %s" % (xs, name),
                                      hint="use b'' to make it byte string")
 
 # attributes set by registrar.command
 _cmdfuncattrs = ('norepo', 'optionalrepo', 'inferrepo')
 
 def _validatecmdtable(ui, cmdtable):
     """Check if extension commands have required attributes"""
     for c, e in cmdtable.iteritems():
         f = e[0]
         missing = [a for a in _cmdfuncattrs if not util.safehasattr(f, a)]
         if not missing:
             continue
         raise error.ProgrammingError(
             'missing attributes: %s' % ', '.join(missing),
             hint="use @command decorator to register '%s'" % c)
 
 def _validatetables(ui, mod):
     """Sanity check for loadable tables provided by extension module"""
     for t in ['cmdtable', 'colortable', 'configtable']:
         _rejectunicode(t, getattr(mod, t, {}))
     for t in ['filesetpredicate', 'internalmerge', 'revsetpredicate',
               'templatefilter', 'templatefunc', 'templatekeyword']:
         o = getattr(mod, t, None)
         if o:
             _rejectunicode(t, o._table)
     _validatecmdtable(ui, getattr(mod, 'cmdtable', {}))
 
-def load(ui, name, path, log=lambda *a: None, loadingtime=None):
+def load(ui, name, path, loadingtime=None):
     if name.startswith('hgext.') or name.startswith('hgext/'):
         shortname = name[6:]
     else:
         shortname = name
     if shortname in _builtin:
         return None
     if shortname in _extensions:
         return _extensions[shortname]
-    log('  - loading extension: %s\n', shortname)
+    ui.log(b'extension', b'  - loading extension: %s\n', shortname)
     _extensions[shortname] = None
     with util.timedcm('load extension %s', shortname) as stats:
         mod = _importext(name, path, bind(_reportimporterror, ui))
-    log('  > %s extension loaded in %s\n', shortname, stats)
+    ui.log(b'extension', b'  > %s extension loaded in %s\n', shortname, stats)
     if loadingtime is not None:
         loadingtime[shortname] += stats.elapsed
 
     # Before we do anything with the extension, check against minimum stated
     # compatibility. This gives extension authors a mechanism to have their
     # extensions short circuit when loaded with a known incompatible version
     # of Mercurial.
     minver = getattr(mod, 'minimumhgversion', None)
     if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2):
         msg = _('(third party extension %s requires version %s or newer '
                 'of Mercurial (current: %s); disabling)\n')
         ui.warn(msg % (shortname, minver, util.version()))
         return
-    log('    - validating extension tables: %s\n', shortname)
+    ui.log(b'extension', b'    - validating extension tables: %s\n', shortname)
     _validatetables(ui, mod)
 
     _extensions[shortname] = mod
     _order.append(shortname)
-    log('    - invoking registered callbacks: %s\n', shortname)
+    ui.log(b'extension', b'    - invoking registered callbacks: %s\n',
+           shortname)
     with util.timedcm('callbacks extension %s', shortname) as stats:
         for fn in _aftercallbacks.get(shortname, []):
             fn(loaded=True)
-    log('    > callbacks completed in %s\n', stats)
+    ui.log(b'extension', b'    > callbacks completed in %s\n', stats)
     return mod
 
 def _runuisetup(name, ui):
     uisetup = getattr(_extensions[name], 'uisetup', None)
     if uisetup:
         try:
             uisetup(ui)
         except Exception as inst:
             ui.traceback(force=True)
             msg = stringutil.forcebytestr(inst)
             ui.warn(_("*** failed to set up extension %s: %s\n") % (name, msg))
             return False
     return True
 
 def _runextsetup(name, ui):
     extsetup = getattr(_extensions[name], 'extsetup', None)
     if extsetup:
         try:
             try:
                 extsetup(ui)
             except TypeError:
                 if pycompat.getargspec(extsetup).args:
                     raise
                 extsetup() # old extsetup with no ui argument
         except Exception as inst:
             ui.traceback(force=True)
             msg = stringutil.forcebytestr(inst)
             ui.warn(_("*** failed to set up extension %s: %s\n") % (name, msg))
             return False
     return True
 
 def loadall(ui, whitelist=None):
-    if ui.configbool('devel', 'debug.extensions'):
-        log = lambda msg, *values: ui.debug('debug.extensions: ',
-            msg % values, label='debug.extensions')
-    else:
-        log = lambda *a, **kw: None
     loadingtime = collections.defaultdict(int)
     result = ui.configitems("extensions")
     if whitelist is not None:
         result = [(k, v) for (k, v) in result if k in whitelist]
     newindex = len(_order)
-    log('loading %sextensions\n', 'additional ' if newindex else '')
-    log('- processing %d entries\n', len(result))
+    ui.log(b'extension', b'loading %sextensions\n',
+           'additional ' if newindex else '')
+    ui.log(b'extension', b'- processing %d entries\n', len(result))
     with util.timedcm('load all extensions') as stats:
         for (name, path) in result:
             if path:
                 if path[0:1] == '!':
                     if name not in _disabledextensions:
-                        log('  - skipping disabled extension: %s\n', name)
+                        ui.log(b'extension',
+                               b'  - skipping disabled extension: %s\n', name)
                     _disabledextensions[name] = path[1:]
                     continue
             try:
-                load(ui, name, path, log, loadingtime)
+                load(ui, name, path, loadingtime)
             except Exception as inst:
                 msg = stringutil.forcebytestr(inst)
                 if path:
                     ui.warn(_("*** failed to import extension %s from %s: %s\n")
                             % (name, path, msg))
                 else:
                     ui.warn(_("*** failed to import extension %s: %s\n")
                             % (name, msg))
                 if isinstance(inst, error.Hint) and inst.hint:
                     ui.warn(_("*** (%s)\n") % inst.hint)
                 ui.traceback()
 
-    log('> loaded %d extensions, total time %s\n',
+    ui.log(b'extension', b'> loaded %d extensions, total time %s\n',
         len(_order) - newindex, stats)
     # list of (objname, loadermod, loadername) tuple:
     # - objname is the name of an object in extension module,
     #   from which extra information is loaded
     # - loadermod is the module where loader is placed
     # - loadername is the name of the function,
     #   which takes (ui, extensionname, extraobj) arguments
     #
     # This one is for the list of item that must be run before running any setup
     earlyextraloaders = [
         ('configtable', configitems, 'loadconfigtable'),
     ]
 
-    log('- loading configtable attributes\n')
+    ui.log(b'extension', b'- loading configtable attributes\n')
     _loadextra(ui, newindex, earlyextraloaders)
 
     broken = set()
-    log('- executing uisetup hooks\n')
+    ui.log(b'extension', b'- executing uisetup hooks\n')
     with util.timedcm('all uisetup') as alluisetupstats:
         for name in _order[newindex:]:
-            log('  - running uisetup for %s\n', name)
+            ui.log(b'extension', b'  - running uisetup for %s\n', name)
             with util.timedcm('uisetup %s', name) as stats:
                 if not _runuisetup(name, ui):
-                    log('    - the %s extension uisetup failed\n', name)
+                    ui.log(b'extension',
+                           b'    - the %s extension uisetup failed\n', name)
                     broken.add(name)
-            log('  > uisetup for %s took %s\n', name, stats)
+            ui.log(b'extension', b'  > uisetup for %s took %s\n', name, stats)
             loadingtime[name] += stats.elapsed
-    log('> all uisetup took %s\n', alluisetupstats)
+    ui.log(b'extension', b'> all uisetup took %s\n', alluisetupstats)
 
-    log('- executing extsetup hooks\n')
+    ui.log(b'extension', b'- executing extsetup hooks\n')
     with util.timedcm('all extsetup') as allextetupstats:
         for name in _order[newindex:]:
             if name in broken:
                 continue
-            log('  - running extsetup for %s\n', name)
+            ui.log(b'extension', b'  - running extsetup for %s\n', name)
             with util.timedcm('extsetup %s', name) as stats:
                 if not _runextsetup(name, ui):
-                    log('    - the %s extension extsetup failed\n', name)
+                    ui.log(b'extension',
+                           b'    - the %s extension extsetup failed\n', name)
                     broken.add(name)
-            log('  > extsetup for %s took %s\n', name, stats)
+            ui.log(b'extension', b'  > extsetup for %s took %s\n', name, stats)
             loadingtime[name] += stats.elapsed
-    log('> all extsetup took %s\n', allextetupstats)
+    ui.log(b'extension', b'> all extsetup took %s\n', allextetupstats)
 
     for name in broken:
-        log('    - disabling broken %s extension\n', name)
+        ui.log(b'extension', b'    - disabling broken %s extension\n', name)
         _extensions[name] = None
 
     # Call aftercallbacks that were never met.
-    log('- executing remaining aftercallbacks\n')
+    ui.log(b'extension', b'- executing remaining aftercallbacks\n')
     with util.timedcm('aftercallbacks') as stats:
         for shortname in _aftercallbacks:
             if shortname in _extensions:
                 continue
 
             for fn in _aftercallbacks[shortname]:
-                log('  - extension %s not loaded, notify callbacks\n',
+                ui.log(b'extension',
+                       b'  - extension %s not loaded, notify callbacks\n',
                     shortname)
                 fn(loaded=False)
-    log('> remaining aftercallbacks completed in %s\n', stats)
+    ui.log(b'extension', b'> remaining aftercallbacks completed in %s\n', stats)
 
     # loadall() is called multiple times and lingering _aftercallbacks
     # entries could result in double execution. See issue4646.
     _aftercallbacks.clear()
 
     # delay importing avoids cyclic dependency (especially commands)
     from . import (
         color,
         commands,
         filemerge,
         fileset,
         revset,
         templatefilters,
         templatefuncs,
         templatekw,
     )
 
     # list of (objname, loadermod, loadername) tuple:
     # - objname is the name of an object in extension module,
     #   from which extra information is loaded
     # - loadermod is the module where loader is placed
     # - loadername is the name of the function,
     #   which takes (ui, extensionname, extraobj) arguments
-    log('- loading extension registration objects\n')
+    ui.log(b'extension', b'- loading extension registration objects\n')
     extraloaders = [
         ('cmdtable', commands, 'loadcmdtable'),
         ('colortable', color, 'loadcolortable'),
         ('filesetpredicate', fileset, 'loadpredicate'),
         ('internalmerge', filemerge, 'loadinternalmerge'),
         ('revsetpredicate', revset, 'loadpredicate'),
         ('templatefilter', templatefilters, 'loadfilter'),
         ('templatefunc', templatefuncs, 'loadfunction'),
         ('templatekeyword', templatekw, 'loadkeyword'),
     ]
     with util.timedcm('load registration objects') as stats:
         _loadextra(ui, newindex, extraloaders)
-    log('> extension registration object loading took %s\n', stats)
+    ui.log(b'extension', b'> extension registration object loading took %s\n',
+           stats)
 
     # Report per extension loading time (except reposetup)
     for name in sorted(loadingtime):
-        extension_msg = '> extension %s take a total of %s to load\n'
-        log(extension_msg, name, util.timecount(loadingtime[name]))
+        ui.log(b'extension', b'> extension %s take a total of %s to load\n',
+               name, util.timecount(loadingtime[name]))
 
-    log('extension loading complete\n')
+    ui.log(b'extension', b'extension loading complete\n')
 
 def _loadextra(ui, newindex, extraloaders):
     for name in _order[newindex:]:
         module = _extensions[name]
         if not module:
             continue # loading this module failed
 
         for objname, loadermod, loadername in extraloaders:
             extraobj = getattr(module, objname, None)
             if extraobj is not None:
                 getattr(loadermod, loadername)(ui, name, extraobj)
 
 def afterloaded(extension, callback):
     '''Run the specified function after a named extension is loaded.
 
     If the named extension is already loaded, the callback will be called
     immediately.
 
     If the named extension never loads, the callback will be called after
     all extensions have been loaded.
 
     The callback receives the named argument ``loaded``, which is a boolean
     indicating whether the dependent extension actually loaded.
     '''
 
     if extension in _extensions:
         # Report loaded as False if the extension is disabled
         loaded = (_extensions[extension] is not None)
         callback(loaded=loaded)
     else:
         _aftercallbacks.setdefault(extension, []).append(callback)
 
 def populateui(ui):
     """Run extension hooks on the given ui to populate additional members,
     extend the class dynamically, etc.
 
     This will be called after the configuration is loaded, and/or extensions
     are loaded. In general, it's once per ui instance, but in command-server
     and hgweb, this may be called more than once with the same ui.
     """
     for name, mod in extensions(ui):
         hook = getattr(mod, 'uipopulate', None)
         if not hook:
             continue
         try:
             hook(ui)
         except Exception as inst:
             ui.traceback(force=True)
             ui.warn(_('*** failed to populate ui by extension %s: %s\n')
                     % (name, stringutil.forcebytestr(inst)))
 
 def bind(func, *args):
     '''Partial function application
 
       Returns a new function that is the partial application of args and kwargs
       to func.  For example,
 
           f(1, 2, bar=3) === bind(f, 1)(2, bar=3)'''
     assert callable(func)
     def closure(*a, **kw):
         return func(*(args + a), **kw)
     return closure
 
 def _updatewrapper(wrap, origfn, unboundwrapper):
     '''Copy and add some useful attributes to wrapper'''
     try:
         wrap.__name__ = origfn.__name__
     except AttributeError:
         pass
     wrap.__module__ = getattr(origfn, '__module__')
     wrap.__doc__ = getattr(origfn, '__doc__')
     wrap.__dict__.update(getattr(origfn, '__dict__', {}))
     wrap._origfunc = origfn
     wrap._unboundwrapper = unboundwrapper
 
 def wrapcommand(table, command, wrapper, synopsis=None, docstring=None):
     '''Wrap the command named `command' in table
 
     Replace command in the command table with wrapper. The wrapped command will
     be inserted into the command table specified by the table argument.
 
     The wrapper will be called like
 
       wrapper(orig, *args, **kwargs)
 
     where orig is the original (wrapped) function, and *args, **kwargs
     are the arguments passed to it.
 
     Optionally append to the command synopsis and docstring, used for help.
     For example, if your extension wraps the ``bookmarks`` command to add the
     flags ``--remote`` and ``--all`` you might call this function like so:
 
       synopsis = ' [-a] [--remote]'
       docstring = """
 
       The ``remotenames`` extension adds the ``--remote`` and ``--all`` (``-a``)
       flags to the bookmarks command. Either flag will show the remote bookmarks
       known to the repository; ``--remote`` will also suppress the output of the
       local bookmarks.
       """
 
       extensions.wrapcommand(commands.table, 'bookmarks', exbookmarks,
                              synopsis, docstring)
     '''
     assert callable(wrapper)
     aliases, entry = cmdutil.findcmd(command, table)
     for alias, e in table.iteritems():
         if e is entry:
             key = alias
             break
 
     origfn = entry[0]
     wrap = functools.partial(util.checksignature(wrapper),
                              util.checksignature(origfn))
     _updatewrapper(wrap, origfn, wrapper)
     if docstring is not None:
         wrap.__doc__ += docstring
 
     newentry = list(entry)
     newentry[0] = wrap
     if synopsis is not None:
         newentry[2] += synopsis
     table[key] = tuple(newentry)
     return entry
 
 def wrapfilecache(cls, propname, wrapper):
     """Wraps a filecache property.
 
     These can't be wrapped using the normal wrapfunction.
     """
     propname = pycompat.sysstr(propname)
     assert callable(wrapper)
     for currcls in cls.__mro__:
         if propname in currcls.__dict__:
             origfn = currcls.__dict__[propname].func
             assert callable(origfn)
             def wrap(*args, **kwargs):
                 return wrapper(origfn, *args, **kwargs)
             currcls.__dict__[propname].func = wrap
             break
 
     if currcls is object:
         raise AttributeError(r"type '%s' has no property '%s'" % (
             cls, propname))
 
 class wrappedfunction(object):
     '''context manager for temporarily wrapping a function'''
 
     def __init__(self, container, funcname, wrapper):
         assert callable(wrapper)
         self._container = container
         self._funcname = funcname
         self._wrapper = wrapper
 
     def __enter__(self):
         wrapfunction(self._container, self._funcname, self._wrapper)
 
     def __exit__(self, exctype, excvalue, traceback):
         unwrapfunction(self._container, self._funcname, self._wrapper)
 
 def wrapfunction(container, funcname, wrapper):
     '''Wrap the function named funcname in container
 
     Replace the funcname member in the given container with the specified
     wrapper. The container is typically a module, class, or instance.
 
     The wrapper will be called like
 
       wrapper(orig, *args, **kwargs)
 
     where orig is the original (wrapped) function, and *args, **kwargs
     are the arguments passed to it.
 
     Wrapping methods of the repository object is not recommended since
     it conflicts with extensions that extend the repository by
     subclassing. All extensions that need to extend methods of
     localrepository should use this subclassing trick: namely,
     reposetup() should look like
 
       def reposetup(ui, repo):
           class myrepo(repo.__class__):
               def whatever(self, *args, **kwargs):
                   [...extension stuff...]
                   super(myrepo, self).whatever(*args, **kwargs)
                   [...extension stuff...]
 
           repo.__class__ = myrepo
 
     In general, combining wrapfunction() with subclassing does not
     work. Since you cannot control what other extensions are loaded by
     your end users, you should play nicely with others by using the
     subclass trick.
     '''
     assert callable(wrapper)
 
     origfn = getattr(container, funcname)
     assert callable(origfn)
     if inspect.ismodule(container):
         # origfn is not an instance or class method. "partial" can be used.
         # "partial" won't insert a frame in traceback.
         wrap = functools.partial(wrapper, origfn)
     else:
         # "partial" cannot be safely used. Emulate its effect by using "bind".
         # The downside is one more frame in traceback.
         wrap = bind(wrapper, origfn)
     _updatewrapper(wrap, origfn, wrapper)
     setattr(container, funcname, wrap)
     return origfn
 
 def unwrapfunction(container, funcname, wrapper=None):
     '''undo wrapfunction
 
     If wrappers is None, undo the last wrap. Otherwise removes the wrapper
     from the chain of wrappers.
 
     Return the removed wrapper.
     Raise IndexError if wrapper is None and nothing to unwrap; ValueError if
     wrapper is not None but is not found in the wrapper chain.
     '''
     chain = getwrapperchain(container, funcname)
     origfn = chain.pop()
     if wrapper is None:
         wrapper = chain[0]
     chain.remove(wrapper)
     setattr(container, funcname, origfn)
     for w in reversed(chain):
         wrapfunction(container, funcname, w)
     return wrapper
 
 def getwrapperchain(container, funcname):
     '''get a chain of wrappers of a function
 
     Return a list of functions: [newest wrapper, ..., oldest wrapper, origfunc]
 
     The wrapper functions are the ones passed to wrapfunction, whose first
     argument is origfunc.
     '''
     result = []
     fn = getattr(container, funcname)
     while fn:
         assert callable(fn)
         result.append(getattr(fn, '_unboundwrapper', fn))
         fn = getattr(fn, '_origfunc', None)
     return result
 
 def _disabledpaths():
     '''find paths of disabled extensions. returns a dict of {name: path}'''
     import hgext
     extpath = os.path.dirname(
         os.path.abspath(pycompat.fsencode(hgext.__file__)))
     try: # might not be a filesystem path
         files = os.listdir(extpath)
     except OSError:
         return {}
 
     exts = {}
     for e in files:
         if e.endswith('.py'):
             name = e.rsplit('.', 1)[0]
             path = os.path.join(extpath, e)
         else:
             name = e
             path = os.path.join(extpath, e, '__init__.py')
             if not os.path.exists(path):
                 continue
         if name in exts or name in _order or name == '__init__':
             continue
         exts[name] = path
     for name, path in _disabledextensions.iteritems():
         # If no path was provided for a disabled extension (e.g. "color=!"),
         # don't replace the path we already found by the scan above.
         if path:
             exts[name] = path
     return exts
 
 def _moduledoc(file):
     '''return the top-level python documentation for the given file
 
     Loosely inspired by pydoc.source_synopsis(), but rewritten to
     handle triple quotes and to return the whole text instead of just
     the synopsis'''
     result = []
 
     line = file.readline()
     while line[:1] == '#' or not line.strip():
         line = file.readline()
         if not line:
             break
 
     start = line[:3]
     if start == '"""' or start == "'''":
         line = line[3:]
         while line:
             if line.rstrip().endswith(start):
                 line = line.split(start)[0]
                 if line:
                     result.append(line)
                 break
             elif not line:
                 return None # unmatched delimiter
             result.append(line)
             line = file.readline()
     else:
         return None
 
     return ''.join(result)
 
 def _disabledhelp(path):
     '''retrieve help synopsis of a disabled extension (without importing)'''
     try:
         with open(path, 'rb') as src:
             doc = _moduledoc(src)
     except IOError:
         return
 
     if doc: # extracting localized synopsis
         return gettext(doc)
     else:
         return _('(no help text available)')
 
 def disabled():
     '''find disabled extensions from hgext. returns a dict of {name: desc}'''
     try:
         from hgext import __index__
         return dict((name, gettext(desc))
                     for name, desc in __index__.docs.iteritems()
                     if name not in _order)
     except (ImportError, AttributeError):
         pass
 
     paths = _disabledpaths()
     if not paths:
         return {}
 
     exts = {}
     for name, path in paths.iteritems():
         doc = _disabledhelp(path)
         if doc:
             exts[name] = doc.splitlines()[0]
 
     return exts
 
 def disabledext(name):
     '''find a specific disabled extension from hgext. returns desc'''
     try:
         from hgext import __index__
         if name in _order:  # enabled
             return
         else:
             return gettext(__index__.docs.get(name))
     except (ImportError, AttributeError):
         pass
 
     paths = _disabledpaths()
     if name in paths:
         return _disabledhelp(paths[name])
 
 def _walkcommand(node):
     """Scan @command() decorators in the tree starting at node"""
     todo = collections.deque([node])
     while todo:
         node = todo.popleft()
         if not isinstance(node, ast.FunctionDef):
             todo.extend(ast.iter_child_nodes(node))
             continue
         for d in node.decorator_list:
             if not isinstance(d, ast.Call):
                 continue
             if not isinstance(d.func, ast.Name):
                 continue
             if d.func.id != r'command':
                 continue
             yield d
 
 def _disabledcmdtable(path):
     """Construct a dummy command table without loading the extension module
 
     This may raise IOError or SyntaxError.
     """
     with open(path, 'rb') as src:
         root = ast.parse(src.read(), path)
     cmdtable = {}
     for node in _walkcommand(root):
         if not node.args:
             continue
         a = node.args[0]
         if isinstance(a, ast.Str):
             name = pycompat.sysbytes(a.s)
         elif pycompat.ispy3 and isinstance(a, ast.Bytes):
             name = a.s
         else:
             continue
         cmdtable[name] = (None, [], b'')
     return cmdtable
 
 def _finddisabledcmd(ui, cmd, name, path, strict):
     try:
         cmdtable = _disabledcmdtable(path)
     except (IOError, SyntaxError):
         return
     try:
         aliases, entry = cmdutil.findcmd(cmd, cmdtable, strict)
     except (error.AmbiguousCommand, error.UnknownCommand):
         return
     for c in aliases:
         if c.startswith(cmd):
             cmd = c
             break
     else:
         cmd = aliases[0]
     doc = _disabledhelp(path)
     return (cmd, name, doc)
 
 def disabledcmd(ui, cmd, strict=False):
     '''find cmd from disabled extensions without importing.
     returns (cmdname, extname, doc)'''
 
     paths = _disabledpaths()
     if not paths:
         raise error.UnknownCommand(cmd)
 
     ext = None
     # first, search for an extension with the same name as the command
     path = paths.pop(cmd, None)
     if path:
         ext = _finddisabledcmd(ui, cmd, cmd, path, strict=strict)
     if not ext:
         # otherwise, interrogate each extension until there's a match
         for name, path in paths.iteritems():
             ext = _finddisabledcmd(ui, cmd, name, path, strict=strict)
             if ext:
                 break
     if ext:
         return ext
 
     raise error.UnknownCommand(cmd)
 
 def enabled(shortname=True):
     '''return a dict of {name: desc} of extensions'''
     exts = {}
     for ename, ext in extensions():
         doc = (gettext(ext.__doc__) or _('(no help text available)'))
         if shortname:
             ename = ename.split('.')[-1]
         exts[ename] = doc.splitlines()[0].strip()
 
     return exts
 
 def notloaded():
     '''return short names of extensions that failed to load'''
     return [name for name, mod in _extensions.iteritems() if mod is None]
 
 def moduleversion(module):
     '''return version information from given module as a string'''
     if (util.safehasattr(module, 'getversion')
           and callable(module.getversion)):
         version = module.getversion()
     elif util.safehasattr(module, '__version__'):
         version = module.__version__
     else:
         version = ''
     if isinstance(version, (list, tuple)):
         version = '.'.join(pycompat.bytestr(o) for o in version)
     return version
 
 def ismoduleinternal(module):
     exttestedwith = getattr(module, 'testedwith', None)
     return exttestedwith == "ships-with-hg-core"

mercurial/hg.py

@@ -1,1229 +1,1225 b''
 # hg.py - repository classes for mercurial
 #
 # Copyright 2005-2007 Matt Mackall <[e-mail]>
 # Copyright 2006 Vadim Gelfer <[e-mail]>
 #
 # This software may be used and distributed according to the terms of the
 # GNU General Public License version 2 or any later version.
 
 from __future__ import absolute_import
 
 import errno
 import hashlib
 import os
 import shutil
 import stat
 
 from .i18n import _
 from .node import (
     nullid,
 )
 
 from . import (
     bookmarks,
     bundlerepo,
     cacheutil,
     cmdutil,
     destutil,
     discovery,
     error,
     exchange,
     extensions,
     httppeer,
     localrepo,
     lock,
     logcmdutil,
     logexchange,
     merge as mergemod,
     narrowspec,
     node,
     phases,
     scmutil,
     sshpeer,
     statichttprepo,
     ui as uimod,
     unionrepo,
     url,
     util,
     verify as verifymod,
     vfs as vfsmod,
 )
 
 release = lock.release
 
 # shared features
 sharedbookmarks = 'bookmarks'
 
 def _local(path):
     path = util.expandpath(util.urllocalpath(path))
     return (os.path.isfile(path) and bundlerepo or localrepo)
 
 def addbranchrevs(lrepo, other, branches, revs):
     peer = other.peer() # a courtesy to callers using a localrepo for other
     hashbranch, branches = branches
     if not hashbranch and not branches:
         x = revs or None
         if revs:
             y = revs[0]
         else:
             y = None
         return x, y
     if revs:
         revs = list(revs)
     else:
         revs = []
 
     if not peer.capable('branchmap'):
         if branches:
             raise error.Abort(_("remote branch lookup not supported"))
         revs.append(hashbranch)
         return revs, revs[0]
 
     with peer.commandexecutor() as e:
         branchmap = e.callcommand('branchmap', {}).result()
 
     def primary(branch):
         if branch == '.':
             if not lrepo:
                 raise error.Abort(_("dirstate branch not accessible"))
             branch = lrepo.dirstate.branch()
         if branch in branchmap:
             revs.extend(node.hex(r) for r in reversed(branchmap[branch]))
             return True
         else:
             return False
 
     for branch in branches:
         if not primary(branch):
             raise error.RepoLookupError(_("unknown branch '%s'") % branch)
     if hashbranch:
         if not primary(hashbranch):
             revs.append(hashbranch)
     return revs, revs[0]
 
 def parseurl(path, branches=None):
     '''parse url#branch, returning (url, (branch, branches))'''
 
     u = util.url(path)
     branch = None
     if u.fragment:
         branch = u.fragment
         u.fragment = None
     return bytes(u), (branch, branches or [])
 
 schemes = {
     'bundle': bundlerepo,
     'union': unionrepo,
     'file': _local,
     'http': httppeer,
     'https': httppeer,
     'ssh': sshpeer,
     'static-http': statichttprepo,
 }
 
 def _peerlookup(path):
     u = util.url(path)
     scheme = u.scheme or 'file'
     thing = schemes.get(scheme) or schemes['file']
     try:
         return thing(path)
     except TypeError:
         # we can't test callable(thing) because 'thing' can be an unloaded
         # module that implements __call__
         if not util.safehasattr(thing, 'instance'):
             raise
         return thing
 
 def islocal(repo):
     '''return true if repo (or path pointing to repo) is local'''
     if isinstance(repo, bytes):
         try:
             return _peerlookup(repo).islocal(repo)
         except AttributeError:
             return False
     return repo.local()
 
 def openpath(ui, path):
     '''open path with open if local, url.open if remote'''
     pathurl = util.url(path, parsequery=False, parsefragment=False)
     if pathurl.islocal():
         return util.posixfile(pathurl.localpath(), 'rb')
     else:
         return url.open(ui, path)
 
 # a list of (ui, repo) functions called for wire peer initialization
 wirepeersetupfuncs = []
 
 def _peerorrepo(ui, path, create=False, presetupfuncs=None,
                 intents=None, createopts=None):
     """return a repository object for the specified path"""
     obj = _peerlookup(path).instance(ui, path, create, intents=intents,
                                      createopts=createopts)
     ui = getattr(obj, "ui", ui)
-    if ui.configbool('devel', 'debug.extensions'):
-        log = lambda msg, *values: ui.debug('debug.extensions: ',
-            msg % values, label='debug.extensions')
-    else:
-        log = lambda *a, **kw: None
     for f in presetupfuncs or []:
         f(ui, obj)
-    log('- executing reposetup hooks\n')
+    ui.log(b'extension', b'- executing reposetup hooks\n')
     with util.timedcm('all reposetup') as allreposetupstats:
         for name, module in extensions.extensions(ui):
-            log('  - running reposetup for %s\n' % (name,))
+            ui.log(b'extension', b'  - running reposetup for %s\n', name)
             hook = getattr(module, 'reposetup', None)
             if hook:
                 with util.timedcm('reposetup %r', name) as stats:
                     hook(ui, obj)
-                log('  > reposetup for %s took %s\n', name, stats)
-    log('> all reposetup took %s\n', allreposetupstats)
+                ui.log(b'extension', b'  > reposetup for %s took %s\n',
+                       name, stats)
+    ui.log(b'extension', b'> all reposetup took %s\n', allreposetupstats)
     if not obj.local():
         for f in wirepeersetupfuncs:
             f(ui, obj)
     return obj
 
 def repository(ui, path='', create=False, presetupfuncs=None, intents=None,
                createopts=None):
     """return a repository object for the specified path"""
     peer = _peerorrepo(ui, path, create, presetupfuncs=presetupfuncs,
                        intents=intents, createopts=createopts)
     repo = peer.local()
     if not repo:
         raise error.Abort(_("repository '%s' is not local") %
                          (path or peer.url()))
     return repo.filtered('visible')
 
 def peer(uiorrepo, opts, path, create=False, intents=None, createopts=None):
     '''return a repository peer for the specified path'''
     rui = remoteui(uiorrepo, opts)
     return _peerorrepo(rui, path, create, intents=intents,
                        createopts=createopts).peer()
 
 def defaultdest(source):
     '''return default destination of clone if none is given
 
     >>> defaultdest(b'foo')
     'foo'
     >>> defaultdest(b'/foo/bar')
     'bar'
     >>> defaultdest(b'/')
     ''
     >>> defaultdest(b'')
     ''
     >>> defaultdest(b'http://example.org/')
     ''
     >>> defaultdest(b'http://example.org/foo/')
     'foo'
     '''
     path = util.url(source).path
     if not path:
         return ''
     return os.path.basename(os.path.normpath(path))
 
 def sharedreposource(repo):
     """Returns repository object for source repository of a shared repo.
 
     If repo is not a shared repository, returns None.
     """
     if repo.sharedpath == repo.path:
         return None
 
     if util.safehasattr(repo, 'srcrepo') and repo.srcrepo:
         return repo.srcrepo
 
     # the sharedpath always ends in the .hg; we want the path to the repo
     source = repo.vfs.split(repo.sharedpath)[0]
     srcurl, branches = parseurl(source)
     srcrepo = repository(repo.ui, srcurl)
     repo.srcrepo = srcrepo
     return srcrepo
 
 def share(ui, source, dest=None, update=True, bookmarks=True, defaultpath=None,
           relative=False):
     '''create a shared repository'''
 
     if not islocal(source):
         raise error.Abort(_('can only share local repositories'))
 
     if not dest:
         dest = defaultdest(source)
     else:
         dest = ui.expandpath(dest)
 
     if isinstance(source, bytes):
         origsource = ui.expandpath(source)
         source, branches = parseurl(origsource)
         srcrepo = repository(ui, source)
         rev, checkout = addbranchrevs(srcrepo, srcrepo, branches, None)
     else:
         srcrepo = source.local()
         checkout = None
 
     shareditems = set()
     if bookmarks:
         shareditems.add(sharedbookmarks)
 
     r = repository(ui, dest, create=True, createopts={
         'sharedrepo': srcrepo,
         'sharedrelative': relative,
         'shareditems': shareditems,
     })
 
     postshare(srcrepo, r, defaultpath=defaultpath)
     r = repository(ui, dest)
     _postshareupdate(r, update, checkout=checkout)
     return r
 
 def unshare(ui, repo):
     """convert a shared repository to a normal one
 
     Copy the store data to the repo and remove the sharedpath data.
 
     Returns a new repository object representing the unshared repository.
 
     The passed repository object is not usable after this function is
     called.
     """
 
     destlock = lock = None
     lock = repo.lock()
     try:
         # we use locks here because if we race with commit, we
         # can end up with extra data in the cloned revlogs that's
         # not pointed to by changesets, thus causing verify to
         # fail
 
         destlock = copystore(ui, repo, repo.path)
 
         sharefile = repo.vfs.join('sharedpath')
         util.rename(sharefile, sharefile + '.old')
 
         repo.requirements.discard('shared')
         repo.requirements.discard('relshared')
         repo._writerequirements()
     finally:
         destlock and destlock.release()
         lock and lock.release()
 
     # Removing share changes some fundamental properties of the repo instance.
     # So we instantiate a new repo object and operate on it rather than
     # try to keep the existing repo usable.
     newrepo = repository(repo.baseui, repo.root, create=False)
 
     # TODO: figure out how to access subrepos that exist, but were previously
     #       removed from .hgsub
     c = newrepo['.']
     subs = c.substate
     for s in sorted(subs):
         c.sub(s).unshare()
 
     localrepo.poisonrepository(repo)
 
     return newrepo
 
 def postshare(sourcerepo, destrepo, defaultpath=None):
     """Called after a new shared repo is created.
 
     The new repo only has a requirements file and pointer to the source.
     This function configures additional shared data.
 
     Extensions can wrap this function and write additional entries to
     destrepo/.hg/shared to indicate additional pieces of data to be shared.
     """
     default = defaultpath or sourcerepo.ui.config('paths', 'default')
     if default:
         template = ('[paths]\n'
                     'default = %s\n')
         destrepo.vfs.write('hgrc', util.tonativeeol(template % default))
 
 def _postshareupdate(repo, update, checkout=None):
     """Maybe perform a working directory update after a shared repo is created.
 
     ``update`` can be a boolean or a revision to update to.
     """
     if not update:
         return
 
     repo.ui.status(_("updating working directory\n"))
     if update is not True:
         checkout = update
     for test in (checkout, 'default', 'tip'):
         if test is None:
             continue
         try:
             uprev = repo.lookup(test)
             break
         except error.RepoLookupError:
             continue
     _update(repo, uprev)
 
 def copystore(ui, srcrepo, destpath):
     '''copy files from store of srcrepo in destpath
 
     returns destlock
     '''
     destlock = None
     try:
         hardlink = None
         topic = _('linking') if hardlink else _('copying')
         with ui.makeprogress(topic, unit=_('files')) as progress:
             num = 0
             srcpublishing = srcrepo.publishing()
             srcvfs = vfsmod.vfs(srcrepo.sharedpath)
             dstvfs = vfsmod.vfs(destpath)
             for f in srcrepo.store.copylist():
                 if srcpublishing and f.endswith('phaseroots'):
                     continue
                 dstbase = os.path.dirname(f)
                 if dstbase and not dstvfs.exists(dstbase):
                     dstvfs.mkdir(dstbase)
                 if srcvfs.exists(f):
                     if f.endswith('data'):
                         # 'dstbase' may be empty (e.g. revlog format 0)
                         lockfile = os.path.join(dstbase, "lock")
                         # lock to avoid premature writing to the target
                         destlock = lock.lock(dstvfs, lockfile)
                     hardlink, n = util.copyfiles(srcvfs.join(f), dstvfs.join(f),
                                                  hardlink, progress)
                     num += n
             if hardlink:
                 ui.debug("linked %d files\n" % num)
             else:
                 ui.debug("copied %d files\n" % num)
         return destlock
     except: # re-raises
         release(destlock)
         raise
 
 def clonewithshare(ui, peeropts, sharepath, source, srcpeer, dest, pull=False,
                    rev=None, update=True, stream=False):
     """Perform a clone using a shared repo.
 
     The store for the repository will be located at <sharepath>/.hg. The
     specified revisions will be cloned or pulled from "source". A shared repo
     will be created at "dest" and a working copy will be created if "update" is
     True.
     """
     revs = None
     if rev:
         if not srcpeer.capable('lookup'):
             raise error.Abort(_("src repository does not support "
                                "revision lookup and so doesn't "
                                "support clone by revision"))
 
         # TODO this is batchable.
         remoterevs = []
         for r in rev:
             with srcpeer.commandexecutor() as e:
                 remoterevs.append(e.callcommand('lookup', {
                     'key': r,
                 }).result())
         revs = remoterevs
 
     # Obtain a lock before checking for or cloning the pooled repo otherwise
     # 2 clients may race creating or populating it.
     pooldir = os.path.dirname(sharepath)
     # lock class requires the directory to exist.
     try:
         util.makedir(pooldir, False)
     except OSError as e:
         if e.errno != errno.EEXIST:
             raise
 
     poolvfs = vfsmod.vfs(pooldir)
     basename = os.path.basename(sharepath)
 
     with lock.lock(poolvfs, '%s.lock' % basename):
         if os.path.exists(sharepath):
             ui.status(_('(sharing from existing pooled repository %s)\n') %
                       basename)
         else:
             ui.status(_('(sharing from new pooled repository %s)\n') % basename)
             # Always use pull mode because hardlinks in share mode don't work
             # well. Never update because working copies aren't necessary in
             # share mode.
             clone(ui, peeropts, source, dest=sharepath, pull=True,
                   revs=rev, update=False, stream=stream)
 
     # Resolve the value to put in [paths] section for the source.
     if islocal(source):
         defaultpath = os.path.abspath(util.urllocalpath(source))
     else:
         defaultpath = source
 
     sharerepo = repository(ui, path=sharepath)
     destrepo = share(ui, sharerepo, dest=dest, update=False, bookmarks=False,
                      defaultpath=defaultpath)
 
     # We need to perform a pull against the dest repo to fetch bookmarks
     # and other non-store data that isn't shared by default. In the case of
     # non-existing shared repo, this means we pull from the remote twice. This
     # is a bit weird. But at the time it was implemented, there wasn't an easy
     # way to pull just non-changegroup data.
     exchange.pull(destrepo, srcpeer, heads=revs)
 
     _postshareupdate(destrepo, update)
 
     return srcpeer, peer(ui, peeropts, dest)
 
 # Recomputing branch cache might be slow on big repos,
 # so just copy it
 def _copycache(srcrepo, dstcachedir, fname):
     """copy a cache from srcrepo to destcachedir (if it exists)"""
     srcbranchcache = srcrepo.vfs.join('cache/%s' % fname)
     dstbranchcache = os.path.join(dstcachedir, fname)
     if os.path.exists(srcbranchcache):
         if not os.path.exists(dstcachedir):
             os.mkdir(dstcachedir)
         util.copyfile(srcbranchcache, dstbranchcache)
 
 def clone(ui, peeropts, source, dest=None, pull=False, revs=None,
           update=True, stream=False, branch=None, shareopts=None,
           storeincludepats=None, storeexcludepats=None, depth=None):
     """Make a copy of an existing repository.
 
     Create a copy of an existing repository in a new directory.  The
     source and destination are URLs, as passed to the repository
     function.  Returns a pair of repository peers, the source and
     newly created destination.
 
     The location of the source is added to the new repository's
     .hg/hgrc file, as the default to be used for future pulls and
     pushes.
 
     If an exception is raised, the partly cloned/updated destination
     repository will be deleted.
 
     Arguments:
 
     source: repository object or URL
 
     dest: URL of destination repository to create (defaults to base
     name of source repository)
 
     pull: always pull from source repository, even in local case or if the
     server prefers streaming
 
     stream: stream raw data uncompressed from repository (fast over
     LAN, slow over WAN)
 
     revs: revision to clone up to (implies pull=True)
 
     update: update working directory after clone completes, if
     destination is local repository (True means update to default rev,
     anything else is treated as a revision)
 
     branch: branches to clone
 
     shareopts: dict of options to control auto sharing behavior. The "pool" key
     activates auto sharing mode and defines the directory for stores. The
     "mode" key determines how to construct the directory name of the shared
     repository. "identity" means the name is derived from the node of the first
     changeset in the repository. "remote" means the name is derived from the
     remote's path/URL. Defaults to "identity."
 
     storeincludepats and storeexcludepats: sets of file patterns to include and
     exclude in the repository copy, respectively. If not defined, all files
     will be included (a "full" clone). Otherwise a "narrow" clone containing
     only the requested files will be performed. If ``storeincludepats`` is not
     defined but ``storeexcludepats`` is, ``storeincludepats`` is assumed to be
     ``path:.``. If both are empty sets, no files will be cloned.
     """
 
     if isinstance(source, bytes):
         origsource = ui.expandpath(source)
         source, branches = parseurl(origsource, branch)
         srcpeer = peer(ui, peeropts, source)
     else:
         srcpeer = source.peer() # in case we were called with a localrepo
         branches = (None, branch or [])
         origsource = source = srcpeer.url()
     revs, checkout = addbranchrevs(srcpeer, srcpeer, branches, revs)
 
     if dest is None:
         dest = defaultdest(source)
         if dest:
             ui.status(_("destination directory: %s\n") % dest)
     else:
         dest = ui.expandpath(dest)
 
     dest = util.urllocalpath(dest)
     source = util.urllocalpath(source)
 
     if not dest:
         raise error.Abort(_("empty destination path is not valid"))
 
     destvfs = vfsmod.vfs(dest, expandpath=True)
     if destvfs.lexists():
         if not destvfs.isdir():
             raise error.Abort(_("destination '%s' already exists") % dest)
         elif destvfs.listdir():
             raise error.Abort(_("destination '%s' is not empty") % dest)
 
     createopts = {}
     narrow = False
 
     if storeincludepats is not None:
         narrowspec.validatepatterns(storeincludepats)
         narrow = True
 
     if storeexcludepats is not None:
         narrowspec.validatepatterns(storeexcludepats)
         narrow = True
 
     if narrow:
         # Include everything by default if only exclusion patterns defined.
         if storeexcludepats and not storeincludepats:
             storeincludepats = {'path:.'}
 
         createopts['narrowfiles'] = True
 
     if depth:
         createopts['shallowfilestore'] = True
 
     if srcpeer.capable(b'lfs-serve'):
         # Repository creation honors the config if it disabled the extension, so
         # we can't just announce that lfs will be enabled.  This check avoids
         # saying that lfs will be enabled, and then saying it's an unknown
         # feature.  The lfs creation option is set in either case so that a
         # requirement is added.  If the extension is explicitly disabled but the
         # requirement is set, the clone aborts early, before transferring any
         # data.
         createopts['lfs'] = True
 
         if extensions.disabledext('lfs'):
             ui.status(_('(remote is using large file support (lfs), but it is '
                         'explicitly disabled in the local configuration)\n'))
         else:
             ui.status(_('(remote is using large file support (lfs); lfs will '
                         'be enabled for this repository)\n'))
 
     shareopts = shareopts or {}
     sharepool = shareopts.get('pool')
     sharenamemode = shareopts.get('mode')
     if sharepool and islocal(dest):
         sharepath = None
         if sharenamemode == 'identity':
             # Resolve the name from the initial changeset in the remote
             # repository. This returns nullid when the remote is empty. It
             # raises RepoLookupError if revision 0 is filtered or otherwise
             # not available. If we fail to resolve, sharing is not enabled.
             try:
                 with srcpeer.commandexecutor() as e:
                     rootnode = e.callcommand('lookup', {
                         'key': '0',
                     }).result()
 
                 if rootnode != node.nullid:
                     sharepath = os.path.join(sharepool, node.hex(rootnode))
                 else:
                     ui.status(_('(not using pooled storage: '
                                 'remote appears to be empty)\n'))
             except error.RepoLookupError:
                 ui.status(_('(not using pooled storage: '
                             'unable to resolve identity of remote)\n'))
         elif sharenamemode == 'remote':
             sharepath = os.path.join(
                 sharepool, node.hex(hashlib.sha1(source).digest()))
         else:
             raise error.Abort(_('unknown share naming mode: %s') %
                               sharenamemode)
 
         # TODO this is a somewhat arbitrary restriction.
         if narrow:
             ui.status(_('(pooled storage not supported for narrow clones)\n'))
             sharepath = None
 
         if sharepath:
             return clonewithshare(ui, peeropts, sharepath, source, srcpeer,
                                   dest, pull=pull, rev=revs, update=update,
                                   stream=stream)
 
     srclock = destlock = cleandir = None
     srcrepo = srcpeer.local()
     try:
         abspath = origsource
         if islocal(origsource):
             abspath = os.path.abspath(util.urllocalpath(origsource))
 
         if islocal(dest):
             cleandir = dest
 
         copy = False
         if (srcrepo and srcrepo.cancopy() and islocal(dest)
             and not phases.hassecret(srcrepo)):
             copy = not pull and not revs
 
         # TODO this is a somewhat arbitrary restriction.
         if narrow:
             copy = False
 
         if copy:
             try:
                 # we use a lock here because if we race with commit, we
                 # can end up with extra data in the cloned revlogs that's
                 # not pointed to by changesets, thus causing verify to
                 # fail
                 srclock = srcrepo.lock(wait=False)
             except error.LockError:
                 copy = False
 
         if copy:
             srcrepo.hook('preoutgoing', throw=True, source='clone')
             hgdir = os.path.realpath(os.path.join(dest, ".hg"))
             if not os.path.exists(dest):
                 util.makedirs(dest)
             else:
                 # only clean up directories we create ourselves
                 cleandir = hgdir
             try:
                 destpath = hgdir
                 util.makedir(destpath, notindexed=True)
             except OSError as inst:
                 if inst.errno == errno.EEXIST:
                     cleandir = None
                     raise error.Abort(_("destination '%s' already exists")
                                      % dest)
                 raise
 
             destlock = copystore(ui, srcrepo, destpath)
             # copy bookmarks over
             srcbookmarks = srcrepo.vfs.join('bookmarks')
             dstbookmarks = os.path.join(destpath, 'bookmarks')
             if os.path.exists(srcbookmarks):
                 util.copyfile(srcbookmarks, dstbookmarks)
 
             dstcachedir = os.path.join(destpath, 'cache')
             for cache in cacheutil.cachetocopy(srcrepo):
                 _copycache(srcrepo, dstcachedir, cache)
 
             # we need to re-init the repo after manually copying the data
             # into it
             destpeer = peer(srcrepo, peeropts, dest)
             srcrepo.hook('outgoing', source='clone',
                           node=node.hex(node.nullid))
         else:
             try:
                 # only pass ui when no srcrepo
                 destpeer = peer(srcrepo or ui, peeropts, dest, create=True,
                                 createopts=createopts)
             except OSError as inst:
                 if inst.errno == errno.EEXIST:
                     cleandir = None
                     raise error.Abort(_("destination '%s' already exists")
                                      % dest)
                 raise
 
             if revs:
                 if not srcpeer.capable('lookup'):
                     raise error.Abort(_("src repository does not support "
                                        "revision lookup and so doesn't "
                                        "support clone by revision"))
 
                 # TODO this is batchable.
                 remoterevs = []
                 for rev in revs:
                     with srcpeer.commandexecutor() as e:
                         remoterevs.append(e.callcommand('lookup', {
                             'key': rev,
                         }).result())
                 revs = remoterevs
 
                 checkout = revs[0]
             else:
                 revs = None
             local = destpeer.local()
             if local:
                 if narrow:
                     with local.lock():
                         local.setnarrowpats(storeincludepats, storeexcludepats)
 
                 u = util.url(abspath)
                 defaulturl = bytes(u)
                 local.ui.setconfig('paths', 'default', defaulturl, 'clone')
                 if not stream:
                     if pull:
                         stream = False
                     else:
                         stream = None
                 # internal config: ui.quietbookmarkmove
                 overrides = {('ui', 'quietbookmarkmove'): True}
                 with local.ui.configoverride(overrides, 'clone'):
                     exchange.pull(local, srcpeer, revs,
                                   streamclonerequested=stream,
                                   includepats=storeincludepats,
                                   excludepats=storeexcludepats,
                                   depth=depth)
             elif srcrepo:
                 # TODO lift restriction once exchange.push() accepts narrow
                 # push.
                 if narrow:
                     raise error.Abort(_('narrow clone not available for '
                                         'remote destinations'))
 
                 exchange.push(srcrepo, destpeer, revs=revs,
                               bookmarks=srcrepo._bookmarks.keys())
             else:
                 raise error.Abort(_("clone from remote to remote not supported")
                                  )
 
         cleandir = None
 
         destrepo = destpeer.local()
         if destrepo:
             template = uimod.samplehgrcs['cloned']
             u = util.url(abspath)
             u.passwd = None
             defaulturl = bytes(u)
             destrepo.vfs.write('hgrc', util.tonativeeol(template % defaulturl))
             destrepo.ui.setconfig('paths', 'default', defaulturl, 'clone')
 
             if ui.configbool('experimental', 'remotenames'):
                 logexchange.pullremotenames(destrepo, srcpeer)
 
             if update:
                 if update is not True:
                     with srcpeer.commandexecutor() as e:
                         checkout = e.callcommand('lookup', {
                             'key': update,
                         }).result()
 
                 uprev = None
                 status = None
                 if checkout is not None:
                     # Some extensions (at least hg-git and hg-subversion) have
                     # a peer.lookup() implementation that returns a name instead
                     # of a nodeid. We work around it here until we've figured
                     # out a better solution.
                     if len(checkout) == 20 and checkout in destrepo:
                         uprev = checkout
                     elif scmutil.isrevsymbol(destrepo, checkout):
                         uprev = scmutil.revsymbol(destrepo, checkout).node()
                     else:
                         if update is not True:
                             try:
                                 uprev = destrepo.lookup(update)
                             except error.RepoLookupError:
                                 pass
                 if uprev is None:
                     try:
                         uprev = destrepo._bookmarks['@']
                         update = '@'
                         bn = destrepo[uprev].branch()
                         if bn == 'default':
                             status = _("updating to bookmark @\n")
                         else:
                             status = (_("updating to bookmark @ on branch %s\n")
                                       % bn)
                     except KeyError:
                         try:
                             uprev = destrepo.branchtip('default')
                         except error.RepoLookupError:
                             uprev = destrepo.lookup('tip')
                 if not status:
                     bn = destrepo[uprev].branch()
                     status = _("updating to branch %s\n") % bn
                 destrepo.ui.status(status)
                 _update(destrepo, uprev)
                 if update in destrepo._bookmarks:
                     bookmarks.activate(destrepo, update)
     finally:
         release(srclock, destlock)
         if cleandir is not None:
             shutil.rmtree(cleandir, True)
         if srcpeer is not None:
             srcpeer.close()
     return srcpeer, destpeer
 
 def _showstats(repo, stats, quietempty=False):
     if quietempty and stats.isempty():
         return
     repo.ui.status(_("%d files updated, %d files merged, "
                      "%d files removed, %d files unresolved\n") % (
                    stats.updatedcount, stats.mergedcount,
                    stats.removedcount, stats.unresolvedcount))
 
 def updaterepo(repo, node, overwrite, updatecheck=None):
     """Update the working directory to node.
 
     When overwrite is set, changes are clobbered, merged else
 
     returns stats (see pydoc mercurial.merge.applyupdates)"""
     return mergemod.update(repo, node, branchmerge=False, force=overwrite,
                            labels=['working copy', 'destination'],
                            updatecheck=updatecheck)
 
 def update(repo, node, quietempty=False, updatecheck=None):
     """update the working directory to node"""
     stats = updaterepo(repo, node, False, updatecheck=updatecheck)
     _showstats(repo, stats, quietempty)
     if stats.unresolvedcount:
         repo.ui.status(_("use 'hg resolve' to retry unresolved file merges\n"))
     return stats.unresolvedcount > 0
 
 # naming conflict in clone()
 _update = update
 
 def clean(repo, node, show_stats=True, quietempty=False):
     """forcibly switch the working directory to node, clobbering changes"""
     stats = updaterepo(repo, node, True)
     repo.vfs.unlinkpath('graftstate', ignoremissing=True)
     if show_stats:
         _showstats(repo, stats, quietempty)
     return stats.unresolvedcount > 0
 
 # naming conflict in updatetotally()
 _clean = clean
 
 def updatetotally(ui, repo, checkout, brev, clean=False, updatecheck=None):
     """Update the working directory with extra care for non-file components
 
     This takes care of non-file components below:
 
     :bookmark: might be advanced or (in)activated
 
     This takes arguments below:
 
     :checkout: to which revision the working directory is updated
     :brev: a name, which might be a bookmark to be activated after updating
     :clean: whether changes in the working directory can be discarded
     :updatecheck: how to deal with a dirty working directory
 
     Valid values for updatecheck are (None => linear):
 
      * abort: abort if the working directory is dirty
      * none: don't check (merge working directory changes into destination)
      * linear: check that update is linear before merging working directory
                changes into destination
      * noconflict: check that the update does not result in file merges
 
     This returns whether conflict is detected at updating or not.
     """
     if updatecheck is None:
         updatecheck = ui.config('commands', 'update.check')
         if updatecheck not in ('abort', 'none', 'linear', 'noconflict'):
             # If not configured, or invalid value configured
             updatecheck = 'linear'
     with repo.wlock():
         movemarkfrom = None
         warndest = False
         if checkout is None:
             updata = destutil.destupdate(repo, clean=clean)
             checkout, movemarkfrom, brev = updata
             warndest = True
 
         if clean:
             ret = _clean(repo, checkout)
         else:
             if updatecheck == 'abort':
                 cmdutil.bailifchanged(repo, merge=False)
                 updatecheck = 'none'
             ret = _update(repo, checkout, updatecheck=updatecheck)
 
         if not ret and movemarkfrom:
             if movemarkfrom == repo['.'].node():
                 pass # no-op update
             elif bookmarks.update(repo, [movemarkfrom], repo['.'].node()):
                 b = ui.label(repo._activebookmark, 'bookmarks.active')
                 ui.status(_("updating bookmark %s\n") % b)
             else:
                 # this can happen with a non-linear update
                 b = ui.label(repo._activebookmark, 'bookmarks')
                 ui.status(_("(leaving bookmark %s)\n") % b)
                 bookmarks.deactivate(repo)
         elif brev in repo._bookmarks:
             if brev != repo._activebookmark:
                 b = ui.label(brev, 'bookmarks.active')
                 ui.status(_("(activating bookmark %s)\n") % b)
             bookmarks.activate(repo, brev)
         elif brev:
             if repo._activebookmark:
                 b = ui.label(repo._activebookmark, 'bookmarks')
                 ui.status(_("(leaving bookmark %s)\n") % b)
             bookmarks.deactivate(repo)
 
         if warndest:
             destutil.statusotherdests(ui, repo)
 
     return ret
 
 def merge(repo, node, force=None, remind=True, mergeforce=False, labels=None,
           abort=False):
     """Branch merge with node, resolving changes. Return true if any
     unresolved conflicts."""
     if not abort:
         stats = mergemod.update(repo, node, branchmerge=True, force=force,
                                 mergeforce=mergeforce, labels=labels)
     else:
         ms = mergemod.mergestate.read(repo)
         if ms.active():
             # there were conflicts
             node = ms.localctx.hex()
         else:
             # there were no conficts, mergestate was not stored
             node = repo['.'].hex()
 
         repo.ui.status(_("aborting the merge, updating back to"
                          " %s\n") % node[:12])
         stats = mergemod.update(repo, node, branchmerge=False, force=True,
                                 labels=labels)
 
     _showstats(repo, stats)
     if stats.unresolvedcount:
         repo.ui.status(_("use 'hg resolve' to retry unresolved file merges "
                          "or 'hg merge --abort' to abandon\n"))
     elif remind and not abort:
         repo.ui.status(_("(branch merge, don't forget to commit)\n"))
     return stats.unresolvedcount > 0
 
 def _incoming(displaychlist, subreporecurse, ui, repo, source,
         opts, buffered=False):
     """
     Helper for incoming / gincoming.
     displaychlist gets called with
         (remoterepo, incomingchangesetlist, displayer) parameters,
     and is supposed to contain only code that can't be unified.
     """
     source, branches = parseurl(ui.expandpath(source), opts.get('branch'))
     other = peer(repo, opts, source)
     ui.status(_('comparing with %s\n') % util.hidepassword(source))
     revs, checkout = addbranchrevs(repo, other, branches, opts.get('rev'))
 
     if revs:
         revs = [other.lookup(rev) for rev in revs]
     other, chlist, cleanupfn = bundlerepo.getremotechanges(ui, repo, other,
                                 revs, opts["bundle"], opts["force"])
     try:
         if not chlist:
             ui.status(_("no changes found\n"))
             return subreporecurse()
         ui.pager('incoming')
         displayer = logcmdutil.changesetdisplayer(ui, other, opts,
                                                   buffered=buffered)
         displaychlist(other, chlist, displayer)
         displayer.close()
     finally:
         cleanupfn()
     subreporecurse()
     return 0 # exit code is zero since we found incoming changes
 
 def incoming(ui, repo, source, opts):
     def subreporecurse():
         ret = 1
         if opts.get('subrepos'):
             ctx = repo[None]
             for subpath in sorted(ctx.substate):
                 sub = ctx.sub(subpath)
                 ret = min(ret, sub.incoming(ui, source, opts))
         return ret
 
     def display(other, chlist, displayer):
         limit = logcmdutil.getlimit(opts)
         if opts.get('newest_first'):
             chlist.reverse()
         count = 0
         for n in chlist:
             if limit is not None and count >= limit:
                 break
             parents = [p for p in other.changelog.parents(n) if p != nullid]
             if opts.get('no_merges') and len(parents) == 2:
                 continue
             count += 1
             displayer.show(other[n])
     return _incoming(display, subreporecurse, ui, repo, source, opts)
 
 def _outgoing(ui, repo, dest, opts):
     path = ui.paths.getpath(dest, default=('default-push', 'default'))
     if not path:
         raise error.Abort(_('default repository not configured!'),
                 hint=_("see 'hg help config.paths'"))
     dest = path.pushloc or path.loc
     branches = path.branch, opts.get('branch') or []
 
     ui.status(_('comparing with %s\n') % util.hidepassword(dest))
     revs, checkout = addbranchrevs(repo, repo, branches, opts.get('rev'))
     if revs:
         revs = [repo[rev].node() for rev in scmutil.revrange(repo, revs)]
 
     other = peer(repo, opts, dest)
     outgoing = discovery.findcommonoutgoing(repo, other, revs,
                                             force=opts.get('force'))
     o = outgoing.missing
     if not o:
         scmutil.nochangesfound(repo.ui, repo, outgoing.excluded)
     return o, other
 
 def outgoing(ui, repo, dest, opts):
     def recurse():
         ret = 1
         if opts.get('subrepos'):
             ctx = repo[None]
             for subpath in sorted(ctx.substate):
                 sub = ctx.sub(subpath)
                 ret = min(ret, sub.outgoing(ui, dest, opts))
         return ret
 
     limit = logcmdutil.getlimit(opts)
     o, other = _outgoing(ui, repo, dest, opts)
     if not o:
         cmdutil.outgoinghooks(ui, repo, other, opts, o)
         return recurse()
 
     if opts.get('newest_first'):
         o.reverse()
     ui.pager('outgoing')
     displayer = logcmdutil.changesetdisplayer(ui, repo, opts)
     count = 0
     for n in o:
         if limit is not None and count >= limit:
             break
         parents = [p for p in repo.changelog.parents(n) if p != nullid]
         if opts.get('no_merges') and len(parents) == 2:
             continue
         count += 1
         displayer.show(repo[n])
     displayer.close()
     cmdutil.outgoinghooks(ui, repo, other, opts, o)
     recurse()
     return 0 # exit code is zero since we found outgoing changes
 
 def verify(repo):
     """verify the consistency of a repository"""
     ret = verifymod.verify(repo)
 
     # Broken subrepo references in hidden csets don't seem worth worrying about,
     # since they can't be pushed/pulled, and --hidden can be used if they are a
     # concern.
 
     # pathto() is needed for -R case
     revs = repo.revs("filelog(%s)",
                      util.pathto(repo.root, repo.getcwd(), '.hgsubstate'))
 
     if revs:
         repo.ui.status(_('checking subrepo links\n'))
         for rev in revs:
             ctx = repo[rev]
             try:
                 for subpath in ctx.substate:
                     try:
                         ret = (ctx.sub(subpath, allowcreate=False).verify()
                                or ret)
                     except error.RepoError as e:
                         repo.ui.warn(('%d: %s\n') % (rev, e))
             except Exception:
                 repo.ui.warn(_('.hgsubstate is corrupt in revision %s\n') %
                              node.short(ctx.node()))
 
     return ret
 
 def remoteui(src, opts):
     'build a remote ui from ui or repo and opts'
     if util.safehasattr(src, 'baseui'): # looks like a repository
         dst = src.baseui.copy() # drop repo-specific config
         src = src.ui # copy target options from repo
     else: # assume it's a global ui object
         dst = src.copy() # keep all global options
 
     # copy ssh-specific options
     for o in 'ssh', 'remotecmd':
         v = opts.get(o) or src.config('ui', o)
         if v:
             dst.setconfig("ui", o, v, 'copied')
 
     # copy bundle-specific options
     r = src.config('bundle', 'mainreporoot')
     if r:
         dst.setconfig('bundle', 'mainreporoot', r, 'copied')
 
     # copy selected local settings to the remote ui
     for sect in ('auth', 'hostfingerprints', 'hostsecurity', 'http_proxy'):
         for key, val in src.configitems(sect):
             dst.setconfig(sect, key, val, 'copied')
     v = src.config('web', 'cacerts')
     if v:
         dst.setconfig('web', 'cacerts', util.expandpath(v), 'copied')
 
     return dst
 
 # Files of interest
 # Used to check if the repository has changed looking at mtime and size of
 # these files.
 foi = [('spath', '00changelog.i'),
        ('spath', 'phaseroots'), # ! phase can change content at the same size
        ('spath', 'obsstore'),
        ('path', 'bookmarks'), # ! bookmark can change content at the same size
       ]
 
 class cachedlocalrepo(object):
     """Holds a localrepository that can be cached and reused."""
 
     def __init__(self, repo):
         """Create a new cached repo from an existing repo.
 
         We assume the passed in repo was recently created. If the
         repo has changed between when it was created and when it was
         turned into a cache, it may not refresh properly.
         """
         assert isinstance(repo, localrepo.localrepository)
         self._repo = repo
         self._state, self.mtime = self._repostate()
         self._filtername = repo.filtername
 
     def fetch(self):
         """Refresh (if necessary) and return a repository.
 
         If the cached instance is out of date, it will be recreated
         automatically and returned.
 
         Returns a tuple of the repo and a boolean indicating whether a new
         repo instance was created.
         """
         # We compare the mtimes and sizes of some well-known files to
         # determine if the repo changed. This is not precise, as mtimes
         # are susceptible to clock skew and imprecise filesystems and
         # file content can change while maintaining the same size.
 
         state, mtime = self._repostate()
         if state == self._state:
             return self._repo, False
 
         repo = repository(self._repo.baseui, self._repo.url())
         if self._filtername:
             self._repo = repo.filtered(self._filtername)
         else:
             self._repo = repo.unfiltered()
         self._state = state
         self.mtime = mtime
 
         return self._repo, True
 
     def _repostate(self):
         state = []
         maxmtime = -1
         for attr, fname in foi:
             prefix = getattr(self._repo, attr)
             p = os.path.join(prefix, fname)
             try:
                 st = os.stat(p)
             except OSError:
                 st = os.stat(prefix)
             state.append((st[stat.ST_MTIME], st.st_size))
             maxmtime = max(maxmtime, st[stat.ST_MTIME])
 
         return tuple(state), maxmtime
 
     def copy(self):
         """Obtain a copy of this class instance.
 
         A new localrepository instance is obtained. The new instance should be
         completely independent of the original.
         """
         repo = repository(self._repo.baseui, self._repo.origroot)
         if self._filtername:
             repo = repo.filtered(self._filtername)
         else:
             repo = repo.unfiltered()
         c = cachedlocalrepo(repo)
         c._state = self._state
         c.mtime = self.mtime
         return c

tests/test-bad-extension.t

@@ -1,151 +1,156 b''
+  $ filterlog () {
+  >   sed -e 's!^[0-9/]* [0-9:]* ([0-9]*)>!YYYY/MM/DD HH:MM:SS (PID)>!'
+  > }
+
 ensure that failing ui.atexit handlers report sensibly
 
   $ cat > $TESTTMP/bailatexit.py <<EOF
   > from mercurial import util
   > def bail():
   >     raise RuntimeError('ui.atexit handler exception')
   > 
   > def extsetup(ui):
   >     ui.atexit(bail)
   > EOF
   $ hg -q --config extensions.bailatexit=$TESTTMP/bailatexit.py \
   >  help help
   hg help [-eck] [-s PLATFORM] [TOPIC]
   
   show help for a given topic or a help overview
   error in exit handlers:
   Traceback (most recent call last):
     File "*/mercurial/dispatch.py", line *, in _runexithandlers (glob)
       func(*args, **kwargs)
     File "$TESTTMP/bailatexit.py", line *, in bail (glob)
       raise RuntimeError('ui.atexit handler exception')
   RuntimeError: ui.atexit handler exception
   [255]
 
   $ rm $TESTTMP/bailatexit.py
 
 another bad extension
 
   $ echo 'raise Exception("bit bucket overflow")' > badext.py
   $ abspathexc=`pwd`/badext.py
 
   $ cat >baddocext.py <<EOF
   > """
   > baddocext is bad
   > """
   > EOF
   $ abspathdoc=`pwd`/baddocext.py
 
   $ cat <<EOF >> $HGRCPATH
   > [extensions]
   > gpg =
   > hgext.gpg =
   > badext = $abspathexc
   > baddocext = $abspathdoc
   > badext2 =
   > EOF
 
   $ hg -q help help 2>&1 |grep extension
   *** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow
   *** failed to import extension badext2: No module named *badext2* (glob)
 
 show traceback
 
   $ hg -q help help --traceback 2>&1 | egrep ' extension|^Exception|Traceback|ImportError|ModuleNotFound'
   *** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow
   Traceback (most recent call last):
   Exception: bit bucket overflow
   *** failed to import extension badext2: No module named *badext2* (glob)
   Traceback (most recent call last):
   ImportError: No module named badext2 (no-py3 !)
   ModuleNotFoundError: No module named 'hgext.badext2' (py3 !)
   Traceback (most recent call last): (py3 !)
   ModuleNotFoundError: No module named 'hgext3rd.badext2' (py3 !)
   Traceback (most recent call last): (py3 !)
   ModuleNotFoundError: No module named 'badext2' (py3 !)
 
 names of extensions failed to load can be accessed via extensions.notloaded()
 
   $ cat <<EOF > showbadexts.py
   > from mercurial import commands, extensions, registrar
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > @command(b'showbadexts', norepo=True)
   > def showbadexts(ui, *pats, **opts):
   >     ui.write(b'BADEXTS: %s\n' % b' '.join(sorted(extensions.notloaded())))
   > EOF
   $ hg --config extensions.badexts=showbadexts.py showbadexts 2>&1 | grep '^BADEXTS'
   BADEXTS: badext badext2
 
 #if no-extraextensions
 show traceback for ImportError of hgext.name if devel.debug.extensions is set
 
   $ (hg help help --traceback --debug --config devel.debug.extensions=yes 2>&1) \
   > | grep -v '^ ' \
-  > | egrep 'extension..[^p]|^Exception|Traceback|ImportError|not import|ModuleNotFound'
-  debug.extensions: loading extensions
-  debug.extensions: - processing 5 entries
-  debug.extensions:   - loading extension: gpg
-  debug.extensions:   > gpg extension loaded in * (glob)
-  debug.extensions:     - validating extension tables: gpg
-  debug.extensions:     - invoking registered callbacks: gpg
-  debug.extensions:     > callbacks completed in * (glob)
-  debug.extensions:   - loading extension: badext
+  > | filterlog \
+  > | egrep 'extension..[^p]|^Exception|Traceback|ImportError|^YYYY|not import|ModuleNotFound'
+  YYYY/MM/DD HH:MM:SS (PID)> loading extensions
+  YYYY/MM/DD HH:MM:SS (PID)> - processing 5 entries
+  YYYY/MM/DD HH:MM:SS (PID)>   - loading extension: gpg
+  YYYY/MM/DD HH:MM:SS (PID)>   > gpg extension loaded in * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)>     - validating extension tables: gpg
+  YYYY/MM/DD HH:MM:SS (PID)>     - invoking registered callbacks: gpg
+  YYYY/MM/DD HH:MM:SS (PID)>     > callbacks completed in * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)>   - loading extension: badext
   *** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow
   Traceback (most recent call last):
   Exception: bit bucket overflow
-  debug.extensions:   - loading extension: baddocext
-  debug.extensions:   > baddocext extension loaded in * (glob)
-  debug.extensions:     - validating extension tables: baddocext
-  debug.extensions:     - invoking registered callbacks: baddocext
-  debug.extensions:     > callbacks completed in * (glob)
-  debug.extensions:   - loading extension: badext2
-  debug.extensions:     - could not import hgext.badext2 (No module named *badext2*): trying hgext3rd.badext2 (glob)
+  YYYY/MM/DD HH:MM:SS (PID)>   - loading extension: baddocext
+  YYYY/MM/DD HH:MM:SS (PID)>   > baddocext extension loaded in * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)>     - validating extension tables: baddocext
+  YYYY/MM/DD HH:MM:SS (PID)>     - invoking registered callbacks: baddocext
+  YYYY/MM/DD HH:MM:SS (PID)>     > callbacks completed in * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)>   - loading extension: badext2
+  YYYY/MM/DD HH:MM:SS (PID)>     - could not import hgext.badext2 (No module named *badext2*): trying hgext3rd.badext2 (glob)
   Traceback (most recent call last):
   ImportError: No module named badext2 (no-py3 !)
   ModuleNotFoundError: No module named 'hgext.badext2' (py3 !)
-  debug.extensions:     - could not import hgext3rd.badext2 (No module named *badext2*): trying badext2 (glob)
+  YYYY/MM/DD HH:MM:SS (PID)>     - could not import hgext3rd.badext2 (No module named *badext2*): trying badext2 (glob)
   Traceback (most recent call last):
   ImportError: No module named badext2 (no-py3 !)
   ModuleNotFoundError: No module named 'hgext.badext2' (py3 !)
   Traceback (most recent call last): (py3 !)
   ModuleNotFoundError: No module named 'hgext3rd.badext2' (py3 !)
   *** failed to import extension badext2: No module named *badext2* (glob)
   Traceback (most recent call last):
   ModuleNotFoundError: No module named 'hgext.badext2' (py3 !)
   Traceback (most recent call last): (py3 !)
   ModuleNotFoundError: No module named 'hgext3rd.badext2' (py3 !)
   Traceback (most recent call last): (py3 !)
   ModuleNotFoundError: No module named 'badext2' (py3 !)
   ImportError: No module named badext2 (no-py3 !)
-  debug.extensions: > loaded 2 extensions, total time * (glob)
-  debug.extensions: - loading configtable attributes
-  debug.extensions: - executing uisetup hooks
-  debug.extensions:   - running uisetup for gpg
-  debug.extensions:   > uisetup for gpg took * (glob)
-  debug.extensions:   - running uisetup for baddocext
-  debug.extensions:   > uisetup for baddocext took * (glob)
-  debug.extensions: > all uisetup took * (glob)
-  debug.extensions: - executing extsetup hooks
-  debug.extensions:   - running extsetup for gpg
-  debug.extensions:   > extsetup for gpg took * (glob)
-  debug.extensions:   - running extsetup for baddocext
-  debug.extensions:   > extsetup for baddocext took * (glob)
-  debug.extensions: > all extsetup took * (glob)
-  debug.extensions: - executing remaining aftercallbacks
-  debug.extensions: > remaining aftercallbacks completed in * (glob)
-  debug.extensions: - loading extension registration objects
-  debug.extensions: > extension registration object loading took * (glob)
-  debug.extensions: > extension baddocext take a total of * to load (glob)
-  debug.extensions: > extension gpg take a total of * to load (glob)
-  debug.extensions: extension loading complete
+  YYYY/MM/DD HH:MM:SS (PID)> > loaded 2 extensions, total time * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - loading configtable attributes
+  YYYY/MM/DD HH:MM:SS (PID)> - executing uisetup hooks
+  YYYY/MM/DD HH:MM:SS (PID)>   - running uisetup for gpg
+  YYYY/MM/DD HH:MM:SS (PID)>   > uisetup for gpg took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)>   - running uisetup for baddocext
+  YYYY/MM/DD HH:MM:SS (PID)>   > uisetup for baddocext took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> > all uisetup took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - executing extsetup hooks
+  YYYY/MM/DD HH:MM:SS (PID)>   - running extsetup for gpg
+  YYYY/MM/DD HH:MM:SS (PID)>   > extsetup for gpg took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)>   - running extsetup for baddocext
+  YYYY/MM/DD HH:MM:SS (PID)>   > extsetup for baddocext took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> > all extsetup took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - executing remaining aftercallbacks
+  YYYY/MM/DD HH:MM:SS (PID)> > remaining aftercallbacks completed in * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - loading extension registration objects
+  YYYY/MM/DD HH:MM:SS (PID)> > extension registration object loading took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> > extension baddocext take a total of * to load (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> > extension gpg take a total of * to load (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> extension loading complete
 #endif
 
 confirm that there's no crash when an extension's documentation is bad
 
   $ hg help --keyword baddocext
   *** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow
   *** failed to import extension badext2: No module named *badext2* (glob)
   Topics:
   
    extensions Using Additional Features

tests/test-extension-timing.t

@@ -1,96 +1,100 b''
 Test basic extension support
 
   $ cat > foobar.py <<EOF
   > import os
   > from mercurial import commands, registrar
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > configtable = {}
   > configitem = registrar.configitem(configtable)
   > configitem(b'tests', b'foo', default=b"Foo")
   > def uisetup(ui):
   >     ui.debug(b"uisetup called [debug]\\n")
   >     ui.write(b"uisetup called\\n")
   >     ui.status(b"uisetup called [status]\\n")
   >     ui.flush()
   > def reposetup(ui, repo):
   >     ui.write(b"reposetup called for %s\\n" % os.path.basename(repo.root))
   >     ui.write(b"ui %s= repo.ui\\n" % (ui == repo.ui and b"=" or b"!"))
   >     ui.flush()
   > @command(b'foo', [], b'hg foo')
   > def foo(ui, *args, **kwargs):
   >     foo = ui.config(b'tests', b'foo')
   >     ui.write(foo)
   >     ui.write(b"\\n")
   > @command(b'bar', [], b'hg bar', norepo=True)
   > def bar(ui, *args, **kwargs):
   >     ui.write(b"Bar\\n")
   > EOF
   $ abspath=`pwd`/foobar.py
 
   $ mkdir barfoo
   $ cp foobar.py barfoo/__init__.py
   $ barfoopath=`pwd`/barfoo
 
   $ hg init a
   $ cd a
   $ echo foo > file
   $ hg add file
   $ hg commit -m 'add file'
 
   $ echo '[extensions]' >> $HGRCPATH
   $ echo "foobar = $abspath" >> $HGRCPATH
 
+  $ filterlog () {
+  >   sed -e 's!^[0-9/]* [0-9:]* ([0-9]*)>!YYYY/MM/DD HH:MM:SS (PID)>!'
+  > }
+
 Test extension setup timings
 
-  $ hg foo --traceback --config devel.debug.extensions=yes --debug 2>&1
-  debug.extensions: loading extensions
-  debug.extensions: - processing 1 entries
-  debug.extensions:   - loading extension: foobar
-  debug.extensions:   > foobar extension loaded in * (glob)
-  debug.extensions:     - validating extension tables: foobar
-  debug.extensions:     - invoking registered callbacks: foobar
-  debug.extensions:     > callbacks completed in * (glob)
-  debug.extensions: > loaded 1 extensions, total time * (glob)
-  debug.extensions: - loading configtable attributes
-  debug.extensions: - executing uisetup hooks
-  debug.extensions:   - running uisetup for foobar
+  $ hg foo --traceback --config devel.debug.extensions=yes --debug 2>&1 | filterlog
+  YYYY/MM/DD HH:MM:SS (PID)> loading extensions
+  YYYY/MM/DD HH:MM:SS (PID)> - processing 1 entries
+  YYYY/MM/DD HH:MM:SS (PID)>   - loading extension: foobar
+  YYYY/MM/DD HH:MM:SS (PID)>   > foobar extension loaded in * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)>     - validating extension tables: foobar
+  YYYY/MM/DD HH:MM:SS (PID)>     - invoking registered callbacks: foobar
+  YYYY/MM/DD HH:MM:SS (PID)>     > callbacks completed in * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> > loaded 1 extensions, total time * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - loading configtable attributes
+  YYYY/MM/DD HH:MM:SS (PID)> - executing uisetup hooks
+  YYYY/MM/DD HH:MM:SS (PID)>   - running uisetup for foobar
   uisetup called [debug]
   uisetup called
   uisetup called [status]
-  debug.extensions:   > uisetup for foobar took * (glob)
-  debug.extensions: > all uisetup took * (glob)
-  debug.extensions: - executing extsetup hooks
-  debug.extensions:   - running extsetup for foobar
-  debug.extensions:   > extsetup for foobar took * (glob)
-  debug.extensions: > all extsetup took * (glob)
-  debug.extensions: - executing remaining aftercallbacks
-  debug.extensions: > remaining aftercallbacks completed in * (glob)
-  debug.extensions: - loading extension registration objects
-  debug.extensions: > extension registration object loading took * (glob)
-  debug.extensions: > extension foobar take a total of * to load (glob)
-  debug.extensions: extension loading complete
-  debug.extensions: loading additional extensions
-  debug.extensions: - processing 1 entries
-  debug.extensions: > loaded 0 extensions, total time * (glob)
-  debug.extensions: - loading configtable attributes
-  debug.extensions: - executing uisetup hooks
-  debug.extensions: > all uisetup took * (glob)
-  debug.extensions: - executing extsetup hooks
-  debug.extensions: > all extsetup took * (glob)
-  debug.extensions: - executing remaining aftercallbacks
-  debug.extensions: > remaining aftercallbacks completed in * (glob)
-  debug.extensions: - loading extension registration objects
-  debug.extensions: > extension registration object loading took * (glob)
-  debug.extensions: extension loading complete
-  debug.extensions: - executing reposetup hooks
-  debug.extensions:   - running reposetup for foobar
+  YYYY/MM/DD HH:MM:SS (PID)>   > uisetup for foobar took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> > all uisetup took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - executing extsetup hooks
+  YYYY/MM/DD HH:MM:SS (PID)>   - running extsetup for foobar
+  YYYY/MM/DD HH:MM:SS (PID)>   > extsetup for foobar took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> > all extsetup took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - executing remaining aftercallbacks
+  YYYY/MM/DD HH:MM:SS (PID)> > remaining aftercallbacks completed in * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - loading extension registration objects
+  YYYY/MM/DD HH:MM:SS (PID)> > extension registration object loading took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> > extension foobar take a total of * to load (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> extension loading complete
+  YYYY/MM/DD HH:MM:SS (PID)> loading additional extensions
+  YYYY/MM/DD HH:MM:SS (PID)> - processing 1 entries
+  YYYY/MM/DD HH:MM:SS (PID)> > loaded 0 extensions, total time * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - loading configtable attributes
+  YYYY/MM/DD HH:MM:SS (PID)> - executing uisetup hooks
+  YYYY/MM/DD HH:MM:SS (PID)> > all uisetup took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - executing extsetup hooks
+  YYYY/MM/DD HH:MM:SS (PID)> > all extsetup took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - executing remaining aftercallbacks
+  YYYY/MM/DD HH:MM:SS (PID)> > remaining aftercallbacks completed in * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> - loading extension registration objects
+  YYYY/MM/DD HH:MM:SS (PID)> > extension registration object loading took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> extension loading complete
+  YYYY/MM/DD HH:MM:SS (PID)> - executing reposetup hooks
+  YYYY/MM/DD HH:MM:SS (PID)>   - running reposetup for foobar
   reposetup called for a
   ui == repo.ui
-  debug.extensions:   > reposetup for foobar took * (glob)
-  debug.extensions: > all reposetup took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)>   > reposetup for foobar took * (glob)
+  YYYY/MM/DD HH:MM:SS (PID)> > all reposetup took * (glob)
   Foo
 
   $ cd ..
 
   $ echo 'foobar = !' >> $HGRCPATH