[PATCH 2 of 6 V2] blackbox: log the commands that are run

Durham Goode durham at fb.com
Tue Feb 12 17:12:54 CST 2013


# HG changeset patch
# User Durham Goode <durham at fb.com>
# Date 1360429454 28800
#      Sat Feb 09 09:04:14 2013 -0800
# Node ID 61c66397b9a01d8e08333db6b220f882fe10c209
# Parent  248720a9332a9fac80d5f1ab2e19b106cf44e90b
blackbox: log the commands that are run

Uses ui.log to log which commands are run, their exit code, the time taken,
and any unhandled exceptions thrown.

Example log lines:
2013/02/09 08:35:19 durham> add foo
2013/02/09 08:35:19 durham> add exited 0 after 0.02 seconds

Updates the progress tests because they use a mocked time.time() which these
changes affect.

diff --git a/mercurial/dispatch.py b/mercurial/dispatch.py
--- a/mercurial/dispatch.py
+++ b/mercurial/dispatch.py
@@ -247,6 +247,7 @@
                     (_("** Mercurial Distributed SCM (version %s)\n") % myver) +
                     (_("** Extensions loaded: %s\n") %
                      ", ".join([x[0] for x in extensions.extensions()])))
+        ui.log("commandexception", "%s\n%s\n", warning, traceback.format_exc())
         ui.warn(warning)
         raise
 
@@ -738,10 +739,16 @@
     msg = ' '.join(' ' in a and repr(a) or a for a in fullargs)
     ui.log("command", msg + "\n")
     d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)
+    starttime = time.time()
+    ret = None
     try:
-        return runcommand(lui, repo, cmd, fullargs, ui, options, d,
+        ret = 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()
 
diff --git a/tests/test-progress.t b/tests/test-progress.t
--- a/tests/test-progress.t
+++ b/tests/test-progress.t
@@ -167,6 +167,7 @@
 
   $ 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)
@@ -203,6 +204,7 @@
 Time estimates should not fail when there's no end point:
   $ hg -y loop -- -4
   \r (no-eol) (esc)
-  loop [ <=>                                              ] 2\r (no-eol) (esc)
-  loop [  <=>                                             ] 3\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)


More information about the Mercurial-devel mailing list