Mercurial > hg
changeset 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.
| author | Yuya Nishihara <yuya@tcha.org> |
|---|---|
| date | Sat, 15 Dec 2018 16:28:29 +0900 |
| parents | 19178aeb9b43 |
| children | 038108a9811c |
| files | mercurial/extensions.py mercurial/hg.py tests/test-bad-extension.t tests/test-extension-timing.t |
| diffstat | 4 files changed, 138 insertions(+), 132 deletions(-) [+] |
line wrap: on
line diff
--- 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:]:
--- a/mercurial/hg.py Sat Dec 15 16:52:04 2018 +0900 +++ b/mercurial/hg.py Sat Dec 15 16:28:29 2018 +0900 @@ -160,23 +160,19 @@ 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)
--- a/tests/test-bad-extension.t Sat Dec 15 16:52:04 2018 +0900 +++ b/tests/test-bad-extension.t Sat Dec 15 16:28:29 2018 +0900 @@ -1,3 +1,7 @@ + $ 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 @@ $ (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 @@ 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
--- a/tests/test-extension-timing.t Sat Dec 15 16:52:04 2018 +0900 +++ b/tests/test-extension-timing.t Sat Dec 15 16:28:29 2018 +0900 @@ -41,54 +41,58 @@ $ 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 ..