blackbox: fix recording exit codes (issue3938)

Previously the blackbox wrapped runcommand, but this failed to see the error
codes that were created if an exception occurred. I moved that logging to now
wrap _runcatch, so it can observe and log the actual error code (such as when
a user ctrl+c's during a command).

Updated the tests as well. Tested the change by running all the tests with the
blackbox extension enabled and verifying nothing broke (aside from things that
printed what extensions were enabeld).

The progress tests are affected by calls to time.time() so they needed to be
updated to pass.

mercurial/dispatch.py

@@ -62,7 +62,16 b' def dispatch(req):'
             ferr.write(_("hg: parse error: %s\n") % inst.args[0])
         return -1
 
-    return _runcatch(req)
+    msg = ' '.join(' ' in a and repr(a) or a for a in req.args)
+    starttime = time.time()
+    ret = None
+    try:
+        ret = _runcatch(req)
+        return ret
+    finally:
+        duration = time.time() - starttime
+        req.ui.log("commandfinish", "%s exited %s after %0.2f seconds\n",
+                   msg, ret or 0, duration)
 
 def _runcatch(req):
     def catchterm(*args):
@@ -764,16 +773,10 b' def _dispatch(req):'
     msg = ' '.join(' ' in a and repr(a) or a for a in fullargs)
     ui.log("command", '%s\n', msg)
     d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)
-    starttime = time.time()
-    ret = None
     try:
-        ret = runcommand(lui, repo, cmd, fullargs, ui, options, d,
+        return runcommand(lui, repo, cmd, fullargs, ui, options, d,
                          cmdpats, cmdoptions)
-        return ret
     finally:
-        duration = time.time() - starttime
-        ui.log("commandfinish", "%s exited %s after %0.2f seconds\n",
-               cmd, ret, duration)
         if repo and repo != req.repo:
             repo.close()
 

tests/test-blackbox.t

@@ -26,7 +26,7 b' command, exit codes, and duration'
   $ hg add a
   $ hg blackbox
   1970/01/01 00:00:00 bob> add a
-  1970/01/01 00:00:00 bob> add exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob> add a exited 0 after * seconds (glob)
 
 incoming change tracking
 
@@ -58,7 +58,7 b' clone, commit, pull'
   $ hg blackbox -l 3
   1970/01/01 00:00:00 bob> pull
   1970/01/01 00:00:00 bob> 1 incoming changes - new heads: d02f48003e62
-  1970/01/01 00:00:00 bob> pull exited None after * seconds (glob)
+  1970/01/01 00:00:00 bob> pull exited 0 after * seconds (glob)
 
 we must not cause a failure if we cannot write to the log
 
@@ -118,7 +118,7 b' backup bundles get logged'
   $ hg blackbox -l 3
   1970/01/01 00:00:00 bob> strip tip
   1970/01/01 00:00:00 bob> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
-  1970/01/01 00:00:00 bob> strip exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob> strip tip exited 0 after * seconds (glob)
 
 extension and python hooks - use the eol extension for a pythonhook
 
@@ -133,7 +133,7 b' extension and python hooks - use the eol'
   1970/01/01 00:00:00 bob> update
   1970/01/01 00:00:00 bob> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
   1970/01/01 00:00:00 bob> exthook-update: echo hooked finished in * seconds (glob)
-  1970/01/01 00:00:00 bob> update exited False after * seconds (glob)
+  1970/01/01 00:00:00 bob> update exited 0 after * seconds (glob)
 
 log rotation
 

tests/test-progress.t

@@ -167,7 +167,6 b' test delay time estimates'
 
   $ hg -y loop 8
   \r (no-eol) (esc)
-  loop [====>                                     ] 1/8 1m18s\r (no-eol) (esc)
   loop [=========>                                ] 2/8 1m07s\r (no-eol) (esc)
   loop [===============>                            ] 3/8 56s\r (no-eol) (esc)
   loop [=====================>                      ] 4/8 45s\r (no-eol) (esc)
@@ -204,7 +203,6 b' test delay time estimates'
 Time estimates should not fail when there's no end point:
   $ hg -y loop -- -4
   \r (no-eol) (esc)
-  loop [ <=>                                              ] 1\r (no-eol) (esc)
   loop [  <=>                                             ] 2\r (no-eol) (esc)
   loop [   <=>                                            ] 3\r (no-eol) (esc)
                                                               \r (no-eol) (esc)