diff mercurial/extensions.py @ 40996:6f2510b581a0

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.

--- a/mercurial/extensions.py	Sat Dec 15 16:52:04 2018 +0900
+++ b/mercurial/extensions.py	Sat Dec 15 16:28:29 2018 +0900
@@ -121,13 +121,12 @@
     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.traceback()
+    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)):
@@ -166,7 +165,7 @@
             _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:
@@ -175,11 +174,11 @@
         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
 
@@ -193,16 +192,17 @@
                 '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):
@@ -235,28 +235,25 @@
     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:
@@ -269,8 +266,8 @@
                     ui.warn(_("*** (%s)\n") % inst.hint)
                 ui.traceback()
 
-    log('> loaded %d extensions, total time %s\n',
-        len(_order) - newindex, stats)
+    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
@@ -283,52 +280,55 @@
         ('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',
-                    shortname)
+                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.
@@ -352,7 +352,7 @@
     # - 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'),
@@ -365,14 +365,15 @@
     ]
     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:]: