dispatch: have dispatch.dispatch and dispatch._runcatch emit trace events

Differential Revision: https://phab.mercurial-scm.org/D4345

mercurial/dispatch.py

@@ -21,6 +21,8 b' import traceback'
 
 from .i18n import _
 
+from hgdemandimport import tracing
+
 from . import (
     cmdutil,
     color,
@@ -84,7 +86,8 b' class request(object):'
 def run():
     "run the command in sys.argv"
     initstdio()
-    req = request(pycompat.sysargv[1:])
+    with tracing.log('parse args into request'):
+        req = request(pycompat.sysargv[1:])
     err = None
     try:
         status = dispatch(req)
@@ -176,182 +179,184 b' def _formatargs(args):'
 
 def dispatch(req):
     """run the command specified in req.args; returns an integer status code"""
-    if req.ferr:
-        ferr = req.ferr
-    elif req.ui:
-        ferr = req.ui.ferr
-    else:
-        ferr = procutil.stderr
+    with tracing.log('dispatch.dispatch'):
+        if req.ferr:
+            ferr = req.ferr
+        elif req.ui:
+            ferr = req.ui.ferr
+        else:
+            ferr = procutil.stderr
 
-    try:
-        if not req.ui:
-            req.ui = uimod.ui.load()
-        req.earlyoptions.update(_earlyparseopts(req.ui, req.args))
-        if req.earlyoptions['traceback']:
-            req.ui.setconfig('ui', 'traceback', 'on', '--traceback')
+        try:
+            if not req.ui:
+                req.ui = uimod.ui.load()
+            req.earlyoptions.update(_earlyparseopts(req.ui, req.args))
+            if req.earlyoptions['traceback']:
+                req.ui.setconfig('ui', 'traceback', 'on', '--traceback')
 
-        # set ui streams from the request
-        if req.fin:
-            req.ui.fin = req.fin
-        if req.fout:
-            req.ui.fout = req.fout
-        if req.ferr:
-            req.ui.ferr = req.ferr
-    except error.Abort as inst:
-        ferr.write(_("abort: %s\n") % inst)
-        if inst.hint:
-            ferr.write(_("(%s)\n") % inst.hint)
-        return -1
-    except error.ParseError as inst:
-        _formatparse(ferr.write, inst)
-        return -1
+            # set ui streams from the request
+            if req.fin:
+                req.ui.fin = req.fin
+            if req.fout:
+                req.ui.fout = req.fout
+            if req.ferr:
+                req.ui.ferr = req.ferr
+        except error.Abort as inst:
+            ferr.write(_("abort: %s\n") % inst)
+            if inst.hint:
+                ferr.write(_("(%s)\n") % inst.hint)
+            return -1
+        except error.ParseError as inst:
+            _formatparse(ferr.write, inst)
+            return -1
 
-    msg = _formatargs(req.args)
-    starttime = util.timer()
-    ret = 1  # default of Python exit code on unhandled exception
-    try:
-        ret = _runcatch(req) or 0
-    except error.ProgrammingError as inst:
-        req.ui.error(_('** ProgrammingError: %s\n') % inst)
-        if inst.hint:
-            req.ui.error(_('** (%s)\n') % inst.hint)
-        raise
-    except KeyboardInterrupt as inst:
+        msg = _formatargs(req.args)
+        starttime = util.timer()
+        ret = 1  # default of Python exit code on unhandled exception
         try:
-            if isinstance(inst, error.SignalInterrupt):
-                msg = _("killed!\n")
-            else:
-                msg = _("interrupted!\n")
-            req.ui.error(msg)
-        except error.SignalInterrupt:
-            # maybe pager would quit without consuming all the output, and
-            # SIGPIPE was raised. we cannot print anything in this case.
-            pass
-        except IOError as inst:
-            if inst.errno != errno.EPIPE:
-                raise
-        ret = -1
-    finally:
-        duration = util.timer() - starttime
-        req.ui.flush()
-        if req.ui.logblockedtimes:
-            req.ui._blockedtimes['command_duration'] = duration * 1000
-            req.ui.log('uiblocked', 'ui blocked ms',
-                       **pycompat.strkwargs(req.ui._blockedtimes))
-        req.ui.log("commandfinish", "%s exited %d after %0.2f seconds\n",
-                   msg, ret & 255, duration)
-        try:
-            req._runexithandlers()
-        except: # exiting, so no re-raises
-            ret = ret or -1
-    return ret
+            ret = _runcatch(req) or 0
+        except error.ProgrammingError as inst:
+            req.ui.error(_('** ProgrammingError: %s\n') % inst)
+            if inst.hint:
+                req.ui.error(_('** (%s)\n') % inst.hint)
+            raise
+        except KeyboardInterrupt as inst:
+            try:
+                if isinstance(inst, error.SignalInterrupt):
+                    msg = _("killed!\n")
+                else:
+                    msg = _("interrupted!\n")
+                req.ui.error(msg)
+            except error.SignalInterrupt:
+                # maybe pager would quit without consuming all the output, and
+                # SIGPIPE was raised. we cannot print anything in this case.
+                pass
+            except IOError as inst:
+                if inst.errno != errno.EPIPE:
+                    raise
+            ret = -1
+        finally:
+            duration = util.timer() - starttime
+            req.ui.flush()
+            if req.ui.logblockedtimes:
+                req.ui._blockedtimes['command_duration'] = duration * 1000
+                req.ui.log('uiblocked', 'ui blocked ms',
+                           **pycompat.strkwargs(req.ui._blockedtimes))
+            req.ui.log("commandfinish", "%s exited %d after %0.2f seconds\n",
+                       msg, ret & 255, duration)
+            try:
+                req._runexithandlers()
+            except: # exiting, so no re-raises
+                ret = ret or -1
+        return ret
 
 def _runcatch(req):
-    def catchterm(*args):
-        raise error.SignalInterrupt
+    with tracing.log('dispatch._runcatch'):
+        def catchterm(*args):
+            raise error.SignalInterrupt
 
-    ui = req.ui
-    try:
-        for name in 'SIGBREAK', 'SIGHUP', 'SIGTERM':
-            num = getattr(signal, name, None)
-            if num:
-                signal.signal(num, catchterm)
-    except ValueError:
-        pass # happens if called in a thread
-
-    def _runcatchfunc():
-        realcmd = None
+        ui = req.ui
         try:
-            cmdargs = fancyopts.fancyopts(req.args[:], commands.globalopts, {})
-            cmd = cmdargs[0]
-            aliases, entry = cmdutil.findcmd(cmd, commands.table, False)
-            realcmd = aliases[0]
-        except (error.UnknownCommand, error.AmbiguousCommand,
-                IndexError, getopt.GetoptError):
-            # Don't handle this here. We know the command is
-            # invalid, but all we're worried about for now is that
-            # it's not a command that server operators expect to
-            # be safe to offer to users in a sandbox.
-            pass
-        if realcmd == 'serve' and '--stdio' in cmdargs:
-            # We want to constrain 'hg serve --stdio' instances pretty
-            # closely, as many shared-ssh access tools want to grant
-            # access to run *only* 'hg -R $repo serve --stdio'. We
-            # restrict to exactly that set of arguments, and prohibit
-            # any repo name that starts with '--' to prevent
-            # shenanigans wherein a user does something like pass
-            # --debugger or --config=ui.debugger=1 as a repo
-            # name. This used to actually run the debugger.
-            if (len(req.args) != 4 or
-                req.args[0] != '-R' or
-                req.args[1].startswith('--') or
-                req.args[2] != 'serve' or
-                req.args[3] != '--stdio'):
-                raise error.Abort(
-                    _('potentially unsafe serve --stdio invocation: %s') %
-                    (stringutil.pprint(req.args),))
+            for name in 'SIGBREAK', 'SIGHUP', 'SIGTERM':
+                num = getattr(signal, name, None)
+                if num:
+                    signal.signal(num, catchterm)
+        except ValueError:
+            pass # happens if called in a thread
 
-        try:
-            debugger = 'pdb'
-            debugtrace = {
-                'pdb': pdb.set_trace
-            }
-            debugmortem = {
-                'pdb': pdb.post_mortem
-            }
+        def _runcatchfunc():
+            realcmd = None
+            try:
+                cmdargs = fancyopts.fancyopts(
+                    req.args[:], commands.globalopts, {})
+                cmd = cmdargs[0]
+                aliases, entry = cmdutil.findcmd(cmd, commands.table, False)
+                realcmd = aliases[0]
+            except (error.UnknownCommand, error.AmbiguousCommand,
+                    IndexError, getopt.GetoptError):
+                # Don't handle this here. We know the command is
+                # invalid, but all we're worried about for now is that
+                # it's not a command that server operators expect to
+                # be safe to offer to users in a sandbox.
+                pass
+            if realcmd == 'serve' and '--stdio' in cmdargs:
+                # We want to constrain 'hg serve --stdio' instances pretty
+                # closely, as many shared-ssh access tools want to grant
+                # access to run *only* 'hg -R $repo serve --stdio'. We
+                # restrict to exactly that set of arguments, and prohibit
+                # any repo name that starts with '--' to prevent
+                # shenanigans wherein a user does something like pass
+                # --debugger or --config=ui.debugger=1 as a repo
+                # name. This used to actually run the debugger.
+                if (len(req.args) != 4 or
+                    req.args[0] != '-R' or
+                    req.args[1].startswith('--') or
+                    req.args[2] != 'serve' or
+                    req.args[3] != '--stdio'):
+                    raise error.Abort(
+                        _('potentially unsafe serve --stdio invocation: %s') %
+                        (stringutil.pprint(req.args),))
 
-            # read --config before doing anything else
-            # (e.g. to change trust settings for reading .hg/hgrc)
-            cfgs = _parseconfig(req.ui, req.earlyoptions['config'])
-
-            if req.repo:
-                # copy configs that were passed on the cmdline (--config) to
-                # the repo ui
-                for sec, name, val in cfgs:
-                    req.repo.ui.setconfig(sec, name, val, source='--config')
+            try:
+                debugger = 'pdb'
+                debugtrace = {
+                    'pdb': pdb.set_trace
+                }
+                debugmortem = {
+                    'pdb': pdb.post_mortem
+                }
 
-            # developer config: ui.debugger
-            debugger = ui.config("ui", "debugger")
-            debugmod = pdb
-            if not debugger or ui.plain():
-                # if we are in HGPLAIN mode, then disable custom debugging
-                debugger = 'pdb'
-            elif req.earlyoptions['debugger']:
-                # This import can be slow for fancy debuggers, so only
-                # do it when absolutely necessary, i.e. when actual
-                # debugging has been requested
-                with demandimport.deactivated():
-                    try:
-                        debugmod = __import__(debugger)
-                    except ImportError:
-                        pass # Leave debugmod = pdb
+                # read --config before doing anything else
+                # (e.g. to change trust settings for reading .hg/hgrc)
+                cfgs = _parseconfig(req.ui, req.earlyoptions['config'])
+
+                if req.repo:
+                    # copy configs that were passed on the cmdline (--config) to
+                    # the repo ui
+                    for sec, name, val in cfgs:
+                        req.repo.ui.setconfig(sec, name, val, source='--config')
 
-            debugtrace[debugger] = debugmod.set_trace
-            debugmortem[debugger] = debugmod.post_mortem
+                # developer config: ui.debugger
+                debugger = ui.config("ui", "debugger")
+                debugmod = pdb
+                if not debugger or ui.plain():
+                    # if we are in HGPLAIN mode, then disable custom debugging
+                    debugger = 'pdb'
+                elif req.earlyoptions['debugger']:
+                    # This import can be slow for fancy debuggers, so only
+                    # do it when absolutely necessary, i.e. when actual
+                    # debugging has been requested
+                    with demandimport.deactivated():
+                        try:
+                            debugmod = __import__(debugger)
+                        except ImportError:
+                            pass # Leave debugmod = pdb
 
-            # enter the debugger before command execution
-            if req.earlyoptions['debugger']:
-                ui.warn(_("entering debugger - "
-                        "type c to continue starting hg or h for help\n"))
+                debugtrace[debugger] = debugmod.set_trace
+                debugmortem[debugger] = debugmod.post_mortem
 
-                if (debugger != 'pdb' and
-                    debugtrace[debugger] == debugtrace['pdb']):
-                    ui.warn(_("%s debugger specified "
-                              "but its module was not found\n") % debugger)
-                with demandimport.deactivated():
-                    debugtrace[debugger]()
-            try:
-                return _dispatch(req)
-            finally:
-                ui.flush()
-        except: # re-raises
-            # enter the debugger when we hit an exception
-            if req.earlyoptions['debugger']:
-                traceback.print_exc()
-                debugmortem[debugger](sys.exc_info()[2])
-            raise
+                # enter the debugger before command execution
+                if req.earlyoptions['debugger']:
+                    ui.warn(_("entering debugger - "
+                            "type c to continue starting hg or h for help\n"))
 
-    return _callcatch(ui, _runcatchfunc)
+                    if (debugger != 'pdb' and
+                        debugtrace[debugger] == debugtrace['pdb']):
+                        ui.warn(_("%s debugger specified "
+                                  "but its module was not found\n") % debugger)
+                    with demandimport.deactivated():
+                        debugtrace[debugger]()
+                try:
+                    return _dispatch(req)
+                finally:
+                    ui.flush()
+            except: # re-raises
+                # enter the debugger when we hit an exception
+                if req.earlyoptions['debugger']:
+                    traceback.print_exc()
+                    debugmortem[debugger](sys.exc_info()[2])
+                raise
+        return _callcatch(ui, _runcatchfunc)
 
 def _callcatch(ui, func):
     """like scmutil.callcatch but handles more high-level exceptions about