This is an archive of the discontinued Mercurial Phabricator instance.

Differential D5002

extensions: fix up many many debug logs that use %r
ClosedPublic

Authored by durin42 on Oct 12 2018, 12:53 PM.

Details

Reviewers
indygreg
Group Reviewers
hg-reviewers
Commits
rHG09a37a5d8f5d: extensions: fix up many many debug logs that use %r
Summary

This gets us a bunch closer on Python 3, but I'll still have to use a
ton of sad globs. A previous version of this patch tried to preserve
the %r formatting, but upon review Yuya noted that special characters
in extension names is very unlikely, so we can just use %s and not
sweat the quoting.

Diff Detail

Repository
rHG Mercurial
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.

Event Timeline

durin42 created this revision.Oct 12 2018, 12:53 PM
indygreg requested changes to this revision.Oct 12 2018, 1:31 PM
indygreg added a subscriber: indygreg.
indygreg added inline comments.
mercurial/extensions.py
178

Can't we just switch to %s?

181

Ditto.

200–202

Ditto.

254

Ditto.

This revision now requires changes to proceed.Oct 12 2018, 1:31 PM
durin42 added a comment.Oct 14 2018, 9:01 AM

Switching to %s loses some quotes I like having.

mercurial/extensions.py
178

That'll result in less quoting in the output, and I like having the quoting.

pulkit added a subscriber: pulkit.Oct 19 2018, 5:09 PM

How do we want to move forward with this?

  1. use pycompat.bytestr() as this patch does
  2. use '%s' and add quotes in the output

This is one the failure breaking python3-buildbot.

yuja added a subscriber: yuja.Oct 19 2018, 8:26 PM
  1. use pycompat.bytestr() as this patch does
  2. use '%s' and add quotes in the output

I think they can be just "... '%s'" given extension names are unlikely to
contain meta characters.

durin42 edited the summary of this revision. (Show Details)Oct 23 2018, 11:31 AM
durin42 updated this revision to Diff 12323.
Closed by commit rHG09a37a5d8f5d: extensions: fix up many many debug logs that use %r (authored by durin42). · Explain WhyOct 24 2018, 7:42 AM
This revision was automatically updated to reflect the committed changes.

Revision Contents
Changeset List

Diff 12334

mercurial/extensions.py

if name.startswith('hgext.') or name.startswith('hgext/'): if name.startswith('hgext.') or name.startswith('hgext/'):
shortname = name[6:] shortname = name[6:]
else: else:
shortname = name shortname = name
if shortname in _builtin: if shortname in _builtin:
return None return None
if shortname in _extensions: if shortname in _extensions:
return _extensions[shortname] return _extensions[shortname]
log(' - loading extension: %r\n', shortname) log(' - loading extension: %s\n', shortname)
indygregUnsubmitted
Not Done

Can't we just switch to %s?

indygreg: Can't we just switch to `%s`?
durin42AuthorUnsubmitted
Not Done

That'll result in less quoting in the output, and I like having the quoting.

durin42: That'll result in less quoting in the output, and I like having the quoting.
_extensions[shortname] = None _extensions[shortname] = None
with util.timedcm('load extension %r', shortname) as stats: with util.timedcm('load extension %s', shortname) as stats:
mod = _importext(name, path, bind(_reportimporterror, ui)) mod = _importext(name, path, bind(_reportimporterror, ui))
indygregUnsubmitted
Not Done

Ditto.

indygreg: Ditto.
log(' > %r extension loaded in %s\n', shortname, stats) log(' > %s extension loaded in %s\n', shortname, stats)
if loadingtime is not None: if loadingtime is not None:
loadingtime[shortname] += stats.elapsed loadingtime[shortname] += stats.elapsed
# Before we do anything with the extension, check against minimum stated # Before we do anything with the extension, check against minimum stated
# compatibility. This gives extension authors a mechanism to have their # compatibility. This gives extension authors a mechanism to have their
# extensions short circuit when loaded with a known incompatible version # extensions short circuit when loaded with a known incompatible version
# of Mercurial. # of Mercurial.
minver = getattr(mod, 'minimumhgversion', None) minver = getattr(mod, 'minimumhgversion', None)
if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2): if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2):
ui.warn(_('(third party extension %s requires version %s or newer ' ui.warn(_('(third party extension %s requires version %s or newer '
'of Mercurial; disabling)\n') % (shortname, minver)) 'of Mercurial; disabling)\n') % (shortname, minver))
return return
log(' - validating extension tables: %r\n', shortname) log(' - validating extension tables: %s\n', shortname)
_validatetables(ui, mod) _validatetables(ui, mod)
_extensions[shortname] = mod _extensions[shortname] = mod
_order.append(shortname) _order.append(shortname)
log(' - invoking registered callbacks: %r\n', shortname) log(' - invoking registered callbacks: %s\n', shortname)
with util.timedcm('callbacks extension %r', shortname) as stats: with util.timedcm('callbacks extension %s', shortname) as stats:
for fn in _aftercallbacks.get(shortname, []): for fn in _aftercallbacks.get(shortname, []):
indygregUnsubmitted
Not Done

Ditto.

indygreg: Ditto.
fn(loaded=True) fn(loaded=True)
log(' > callbacks completed in %s\n', stats) log(' > callbacks completed in %s\n', stats)
return mod return mod
def _runuisetup(name, ui): def _runuisetup(name, ui):
uisetup = getattr(_extensions[name], 'uisetup', None) uisetup = getattr(_extensions[name], 'uisetup', None)
if uisetup: if uisetup:
try: try:
newindex = len(_order) newindex = len(_order)
log('loading %sextensions\n', 'additional ' if newindex else '') log('loading %sextensions\n', 'additional ' if newindex else '')
log('- processing %d entries\n', len(result)) log('- processing %d entries\n', len(result))
with util.timedcm('load all extensions') as stats: with util.timedcm('load all extensions') as stats:
for (name, path) in result: for (name, path) in result:
if path: if path:
if path[0:1] == '!': if path[0:1] == '!':
if name not in _disabledextensions: if name not in _disabledextensions:
log(' - skipping disabled extension: %r\n', name) log(' - skipping disabled extension: %s\n', name)
indygregUnsubmitted
Not Done

Ditto.

indygreg: Ditto.
_disabledextensions[name] = path[1:] _disabledextensions[name] = path[1:]
continue continue
try: try:
load(ui, name, path, log, loadingtime) load(ui, name, path, log, loadingtime)
except Exception as inst: except Exception as inst:
msg = stringutil.forcebytestr(inst) msg = stringutil.forcebytestr(inst)
if path: if path:
ui.warn(_("*** failed to import extension %s from %s: %s\n") ui.warn(_("*** failed to import extension %s from %s: %s\n")
log('- loading configtable attributes\n') log('- loading configtable attributes\n')
_loadextra(ui, newindex, earlyextraloaders) _loadextra(ui, newindex, earlyextraloaders)
broken = set() broken = set()
log('- executing uisetup hooks\n') log('- executing uisetup hooks\n')
with util.timedcm('all uisetup') as alluisetupstats: with util.timedcm('all uisetup') as alluisetupstats:
for name in _order[newindex:]: for name in _order[newindex:]:
log(' - running uisetup for %r\n', name) log(' - running uisetup for %s\n', name)
with util.timedcm('uisetup %r', name) as stats: with util.timedcm('uisetup %s', name) as stats:
if not _runuisetup(name, ui): if not _runuisetup(name, ui):
log(' - the %r extension uisetup failed\n', name) log(' - the %s extension uisetup failed\n', name)
broken.add(name) broken.add(name)
log(' > uisetup for %r took %s\n', name, stats) log(' > uisetup for %s took %s\n', name, stats)
loadingtime[name] += stats.elapsed loadingtime[name] += stats.elapsed
log('> all uisetup took %s\n', alluisetupstats) log('> all uisetup took %s\n', alluisetupstats)
log('- executing extsetup hooks\n') log('- executing extsetup hooks\n')
with util.timedcm('all extsetup') as allextetupstats: with util.timedcm('all extsetup') as allextetupstats:
for name in _order[newindex:]: for name in _order[newindex:]:
if name in broken: if name in broken:
continue continue
log(' - running extsetup for %r\n', name) log(' - running extsetup for %s\n', name)
with util.timedcm('extsetup %r', name) as stats: with util.timedcm('extsetup %s', name) as stats:
if not _runextsetup(name, ui): if not _runextsetup(name, ui):
log(' - the %r extension extsetup failed\n', name) log(' - the %s extension extsetup failed\n', name)
broken.add(name) broken.add(name)
log(' > extsetup for %r took %s\n', name, stats) log(' > extsetup for %s took %s\n', name, stats)
loadingtime[name] += stats.elapsed loadingtime[name] += stats.elapsed
log('> all extsetup took %s\n', allextetupstats) log('> all extsetup took %s\n', allextetupstats)
for name in broken: for name in broken:
log(' - disabling broken %r extension\n', name) log(' - disabling broken %s extension\n', name)
_extensions[name] = None _extensions[name] = None
# Call aftercallbacks that were never met. # Call aftercallbacks that were never met.
log('- executing remaining aftercallbacks\n') log('- executing remaining aftercallbacks\n')
with util.timedcm('aftercallbacks') as stats: with util.timedcm('aftercallbacks') as stats:
for shortname in _aftercallbacks: for shortname in _aftercallbacks:
if shortname in _extensions: if shortname in _extensions:
continue continue
for fn in _aftercallbacks[shortname]: for fn in _aftercallbacks[shortname]:
log(' - extension %r not loaded, notify callbacks\n', log(' - extension %s not loaded, notify callbacks\n',
shortname) shortname)
fn(loaded=False) fn(loaded=False)
log('> remaining aftercallbacks completed in %s\n', stats) log('> remaining aftercallbacks completed in %s\n', stats)
# loadall() is called multiple times and lingering _aftercallbacks # loadall() is called multiple times and lingering _aftercallbacks
# entries could result in double execution. See issue4646. # entries could result in double execution. See issue4646.
_aftercallbacks.clear() _aftercallbacks.clear()

mercurial/hg.py

log('- executing reposetup hooks\n') log('- executing reposetup hooks\n')
with util.timedcm('all reposetup') as allreposetupstats: with util.timedcm('all reposetup') as allreposetupstats:
for name, module in extensions.extensions(ui): for name, module in extensions.extensions(ui):
log(' - running reposetup for %s\n' % (name,)) log(' - running reposetup for %s\n' % (name,))
hook = getattr(module, 'reposetup', None) hook = getattr(module, 'reposetup', None)
if hook: if hook:
with util.timedcm('reposetup %r', name) as stats: with util.timedcm('reposetup %r', name) as stats:
hook(ui, obj) hook(ui, obj)
log(' > reposetup for %r took %s\n', name, stats) log(' > reposetup for %s took %s\n', name, stats)
log('> all reposetup took %s\n', allreposetupstats) log('> all reposetup took %s\n', allreposetupstats)
if not obj.local(): if not obj.local():
for f in wirepeersetupfuncs: for f in wirepeersetupfuncs:
f(ui, obj) f(ui, obj)
return obj return obj
def repository(ui, path='', create=False, presetupfuncs=None, intents=None, def repository(ui, path='', create=False, presetupfuncs=None, intents=None,
createopts=None): createopts=None):

tests/test-bad-extension.t

#if no-extraextensions #if no-extraextensions
show traceback for ImportError of hgext.name if devel.debug.extensions is set 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) \ $ (hg help help --traceback --debug --config devel.debug.extensions=yes 2>&1) \
> | grep -v '^ ' \ > | grep -v '^ ' \
> | egrep 'extension..[^p]|^Exception|Traceback|ImportError|not import|ModuleNotFound' > | egrep 'extension..[^p]|^Exception|Traceback|ImportError|not import|ModuleNotFound'
debug.extensions: loading extensions debug.extensions: loading extensions
debug.extensions: - processing 5 entries debug.extensions: - processing 5 entries
debug.extensions: - loading extension: 'gpg' debug.extensions: - loading extension: gpg
debug.extensions: > 'gpg' extension loaded in * (glob) debug.extensions: > gpg extension loaded in * (glob)
debug.extensions: - validating extension tables: 'gpg' debug.extensions: - validating extension tables: gpg
debug.extensions: - invoking registered callbacks: 'gpg' debug.extensions: - invoking registered callbacks: gpg
debug.extensions: > callbacks completed in * (glob) debug.extensions: > callbacks completed in * (glob)
debug.extensions: - loading extension: 'badext' debug.extensions: - loading extension: badext
*** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow *** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow
Traceback (most recent call last): Traceback (most recent call last):
Exception: bit bucket overflow Exception: bit bucket overflow
debug.extensions: - loading extension: 'baddocext' debug.extensions: - loading extension: baddocext
debug.extensions: > 'baddocext' extension loaded in * (glob) debug.extensions: > baddocext extension loaded in * (glob)
debug.extensions: - validating extension tables: 'baddocext' debug.extensions: - validating extension tables: baddocext
debug.extensions: - invoking registered callbacks: 'baddocext' debug.extensions: - invoking registered callbacks: baddocext
debug.extensions: > callbacks completed in * (glob) debug.extensions: > callbacks completed in * (glob)
debug.extensions: - loading extension: 'badext2' debug.extensions: - loading extension: badext2
debug.extensions: - could not import hgext.badext2 (No module named *badext2*): trying hgext3rd.badext2 (glob) debug.extensions: - could not import hgext.badext2 (No module named *badext2*): trying hgext3rd.badext2 (glob)
Traceback (most recent call last): Traceback (most recent call last):
ImportError: No module named badext2 (no-py3 !) ImportError: No module named badext2 (no-py3 !)
ModuleNotFoundError: No module named 'hgext.badext2' (py3 !) ModuleNotFoundError: No module named 'hgext.badext2' (py3 !)
debug.extensions: - could not import hgext3rd.badext2 (No module named *badext2*): trying badext2 (glob) debug.extensions: - could not import hgext3rd.badext2 (No module named *badext2*): trying badext2 (glob)
Traceback (most recent call last): Traceback (most recent call last):
ImportError: No module named badext2 (no-py3 !) ImportError: No module named badext2 (no-py3 !)
ModuleNotFoundError: No module named 'hgext.badext2' (py3 !) ModuleNotFoundError: No module named 'hgext.badext2' (py3 !)
Traceback (most recent call last): (py3 !) Traceback (most recent call last): (py3 !)
ModuleNotFoundError: No module named 'hgext3rd.badext2' (py3 !) ModuleNotFoundError: No module named 'hgext3rd.badext2' (py3 !)
*** failed to import extension badext2: No module named *badext2* (glob) *** failed to import extension badext2: No module named *badext2* (glob)
Traceback (most recent call last): Traceback (most recent call last):
ModuleNotFoundError: No module named 'hgext.badext2' (py3 !) ModuleNotFoundError: No module named 'hgext.badext2' (py3 !)
Traceback (most recent call last): (py3 !) Traceback (most recent call last): (py3 !)
ModuleNotFoundError: No module named 'hgext3rd.badext2' (py3 !) ModuleNotFoundError: No module named 'hgext3rd.badext2' (py3 !)
Traceback (most recent call last): (py3 !) Traceback (most recent call last): (py3 !)
ModuleNotFoundError: No module named 'badext2' (py3 !) ModuleNotFoundError: No module named 'badext2' (py3 !)
ImportError: No module named badext2 (no-py3 !) ImportError: No module named badext2 (no-py3 !)
debug.extensions: > loaded 2 extensions, total time * (glob) debug.extensions: > loaded 2 extensions, total time * (glob)
debug.extensions: - loading configtable attributes debug.extensions: - loading configtable attributes
debug.extensions: - executing uisetup hooks debug.extensions: - executing uisetup hooks
debug.extensions: - running uisetup for 'gpg' debug.extensions: - running uisetup for gpg
debug.extensions: > uisetup for 'gpg' took * (glob) debug.extensions: > uisetup for gpg took * (glob)
debug.extensions: - running uisetup for 'baddocext' debug.extensions: - running uisetup for baddocext
debug.extensions: > uisetup for 'baddocext' took * (glob) debug.extensions: > uisetup for baddocext took * (glob)
debug.extensions: > all uisetup took * (glob) debug.extensions: > all uisetup took * (glob)
debug.extensions: - executing extsetup hooks debug.extensions: - executing extsetup hooks
debug.extensions: - running extsetup for 'gpg' debug.extensions: - running extsetup for gpg
debug.extensions: > extsetup for 'gpg' took * (glob) debug.extensions: > extsetup for gpg took * (glob)
debug.extensions: - running extsetup for 'baddocext' debug.extensions: - running extsetup for baddocext
debug.extensions: > extsetup for 'baddocext' took * (glob) debug.extensions: > extsetup for baddocext took * (glob)
debug.extensions: > all extsetup took * (glob) debug.extensions: > all extsetup took * (glob)
debug.extensions: - executing remaining aftercallbacks debug.extensions: - executing remaining aftercallbacks
debug.extensions: > remaining aftercallbacks completed in * (glob) debug.extensions: > remaining aftercallbacks completed in * (glob)
debug.extensions: - loading extension registration objects debug.extensions: - loading extension registration objects
debug.extensions: > extension registration object loading took * (glob) debug.extensions: > extension registration object loading took * (glob)
debug.extensions: > extension baddocext take a total of * to load (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 gpg take a total of * to load (glob)
debug.extensions: extension loading complete debug.extensions: extension loading complete

tests/test-extension-timing.t

$ echo '[extensions]' >> $HGRCPATH $ echo '[extensions]' >> $HGRCPATH
$ echo "foobar = $abspath" >> $HGRCPATH $ echo "foobar = $abspath" >> $HGRCPATH
Test extension setup timings Test extension setup timings
$ hg foo --traceback --config devel.debug.extensions=yes --debug 2>&1 $ hg foo --traceback --config devel.debug.extensions=yes --debug 2>&1
debug.extensions: loading extensions debug.extensions: loading extensions
debug.extensions: - processing 1 entries debug.extensions: - processing 1 entries
debug.extensions: - loading extension: 'foobar' debug.extensions: - loading extension: foobar
debug.extensions: > 'foobar' extension loaded in * (glob) debug.extensions: > foobar extension loaded in * (glob)
debug.extensions: - validating extension tables: 'foobar' debug.extensions: - validating extension tables: foobar
debug.extensions: - invoking registered callbacks: 'foobar' debug.extensions: - invoking registered callbacks: foobar
debug.extensions: > callbacks completed in * (glob) debug.extensions: > callbacks completed in * (glob)
debug.extensions: > loaded 1 extensions, total time * (glob) debug.extensions: > loaded 1 extensions, total time * (glob)
debug.extensions: - loading configtable attributes debug.extensions: - loading configtable attributes
debug.extensions: - executing uisetup hooks debug.extensions: - executing uisetup hooks
debug.extensions: - running uisetup for 'foobar' debug.extensions: - running uisetup for foobar
uisetup called [debug] uisetup called [debug]
uisetup called uisetup called
uisetup called [status] uisetup called [status]
debug.extensions: > uisetup for 'foobar' took * (glob) debug.extensions: > uisetup for foobar took * (glob)
debug.extensions: > all uisetup took * (glob) debug.extensions: > all uisetup took * (glob)
debug.extensions: - executing extsetup hooks debug.extensions: - executing extsetup hooks
debug.extensions: - running extsetup for 'foobar' debug.extensions: - running extsetup for foobar
debug.extensions: > extsetup for 'foobar' took * (glob) debug.extensions: > extsetup for foobar took * (glob)
debug.extensions: > all extsetup took * (glob) debug.extensions: > all extsetup took * (glob)
debug.extensions: - executing remaining aftercallbacks debug.extensions: - executing remaining aftercallbacks
debug.extensions: > remaining aftercallbacks completed in * (glob) debug.extensions: > remaining aftercallbacks completed in * (glob)
debug.extensions: - loading extension registration objects debug.extensions: - loading extension registration objects
debug.extensions: > extension registration object loading took * (glob) debug.extensions: > extension registration object loading took * (glob)
debug.extensions: > extension foobar take a total of * to load (glob) debug.extensions: > extension foobar take a total of * to load (glob)
debug.extensions: extension loading complete debug.extensions: extension loading complete
debug.extensions: loading additional extensions debug.extensions: loading additional extensions
debug.extensions: - processing 1 entries debug.extensions: - processing 1 entries
debug.extensions: > loaded 0 extensions, total time * (glob) debug.extensions: > loaded 0 extensions, total time * (glob)
debug.extensions: - loading configtable attributes debug.extensions: - loading configtable attributes
debug.extensions: - executing uisetup hooks debug.extensions: - executing uisetup hooks
debug.extensions: > all uisetup took * (glob) debug.extensions: > all uisetup took * (glob)
debug.extensions: - executing extsetup hooks debug.extensions: - executing extsetup hooks
debug.extensions: > all extsetup took * (glob) debug.extensions: > all extsetup took * (glob)
debug.extensions: - executing remaining aftercallbacks debug.extensions: - executing remaining aftercallbacks
debug.extensions: > remaining aftercallbacks completed in * (glob) debug.extensions: > remaining aftercallbacks completed in * (glob)
debug.extensions: - loading extension registration objects debug.extensions: - loading extension registration objects
debug.extensions: > extension registration object loading took * (glob) debug.extensions: > extension registration object loading took * (glob)
debug.extensions: extension loading complete debug.extensions: extension loading complete
debug.extensions: - executing reposetup hooks debug.extensions: - executing reposetup hooks
debug.extensions: - running reposetup for foobar debug.extensions: - running reposetup for foobar
reposetup called for a reposetup called for a
ui == repo.ui ui == repo.ui
debug.extensions: > reposetup for 'foobar' took * (glob) debug.extensions: > reposetup for foobar took * (glob)
debug.extensions: > all reposetup took * (glob) debug.extensions: > all reposetup took * (glob)
Foo Foo
$ cd .. $ cd ..
$ echo 'foobar = !' >> $HGRCPATH $ echo 'foobar = !' >> $HGRCPATH