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

@@ -121,12 +121,11 b' def _importext(name, path=None, reportfu'
     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):
@@ -166,7 +165,7 b' def _validatetables(ui, mod):'
             _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 b' def load(ui, name, path, log=lambda *a: '
         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 b' def load(ui, name, path, log=lambda *a: '
                 '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 b' def _runextsetup(name, ui):'
     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,7 +266,7 b' def loadall(ui, whitelist=None):'
                     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,
@@ -283,52 +280,55 b' def loadall(ui, whitelist=None):'
         ('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.
@@ -352,7 +352,7 b' def loadall(ui, whitelist=None):'
     # - 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 b' def loadall(ui, whitelist=None):'
     ]
     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:]:

mercurial/hg.py

@@ -160,23 +160,19 b' def _peerorrepo(ui, path, create=False, '
     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)

tests/test-bad-extension.t

@@ -1,3 +1,7 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
@@ -82,29 +86,30 b' show traceback for ImportError of hgext.'
 
   $ (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 !)
@@ -118,27 +123,27 b' show traceback for ImportError of hgext.'
   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

tests/test-extension-timing.t

@@ -41,54 +41,58 b' Test basic extension support'
   $ 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 ..