# HG changeset patch
# User Durham Goode <durham@fb.com>
# Date 1369269107 25200
# Node ID 41e39a0299cb1b57c377c48236b99ec607c3a216
# Parent  e9b571a8c67fd354836014ae206871db49b5eed7
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 -r e9b571a8c67f -r 41e39a0299cb mercurial/dispatch.py
--- a/mercurial/dispatch.py	Tue May 21 15:31:56 2013 -0500
+++ b/mercurial/dispatch.py	Wed May 22 17:31:47 2013 -0700
@@ -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 -r e9b571a8c67f -r 41e39a0299cb tests/test-blackbox.t
--- a/tests/test-blackbox.t	Tue May 21 15:31:56 2013 -0500
+++ b/tests/test-blackbox.t	Wed May 22 17:31:47 2013 -0700
@@ -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 -r e9b571a8c67f -r 41e39a0299cb tests/test-progress.t
--- a/tests/test-progress.t	Tue May 21 15:31:56 2013 -0500
+++ b/tests/test-progress.t	Wed May 22 17:31:47 2013 -0700
@@ -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)