[PATCH 1 of 2 V2] blackbox: fix recording exit codes (issue3938)

[Durham Goode]

# HG changeset patch
# User Durham Goode <durham at fb.com>
# Date 1369269107 25200
#      Wed May 22 17:31:47 2013 -0700
# Node ID 5a27f1294beaf297888aed7dc0f2247bdb4032e8
# Parent  36dcf472ffc63bc20869e223dbde0a0fbf453a91
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.

diff --git a/mercurial/dispatch.py b/mercurial/dispatch.py
--- a/mercurial/dispatch.py
+++ b/mercurial/dispatch.py
@@ -62,7 +62,16 @@
             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 @@
     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,
-                         cmdpats, cmdoptions)
-        return ret
+        return runcommand(lui, repo, cmd, fullargs, ui, options, d,
+                          cmdpats, cmdoptions)
     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()
 
diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
--- a/tests/test-blackbox.t
+++ b/tests/test-blackbox.t
@@ -26,7 +26,7 @@
   $ 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 @@
   $ 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 @@
   $ 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 @@
   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
 
diff --git a/tests/test-progress.t b/tests/test-progress.t
--- a/tests/test-progress.t
+++ b/tests/test-progress.t
@@ -167,7 +167,6 @@
 
   $ 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 @@
 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)
+  loop [ <=>                                              ] 2\r (no-eol) (esc)
+  loop [  <=>                                             ] 3\r (no-eol) (esc)
                                                               \r (no-eol) (esc)