Patchwork [2,of,6] blackbox: log the commands that are run

login
register
mail settings
Submitter Durham Goode
Date Feb. 10, 2013, 11:07 a.m.
Message ID <54a25c702a6fface978f.1360494438@dev350.prn1.facebook.com>
Download mbox | patch
Permalink /patch/919/
State Superseded
Commit ddc7268da17692fbdedc851ce2c7ca1778543f97
Headers show

Comments

Durham Goode - Feb. 10, 2013, 11:07 a.m.
# HG changeset patch
# User Durham Goode <durham@fb.com>
# Date 1360429454 28800
# Node ID 54a25c702a6fface978fd1eeb0e6c7140bc9ab8b
# Parent  30544b5277d09002d6cac8c363652f71bb807516
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.
Martin Geisler - Feb. 10, 2013, 2:26 p.m.
Durham Goode <durham@fb.com> writes:

> # HG changeset patch
> # User Durham Goode <durham@fb.com>
> # Date 1360429454 28800
> # Node ID 54a25c702a6fface978fd1eeb0e6c7140bc9ab8b
> # Parent  30544b5277d09002d6cac8c363652f71bb807516
> 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" % (warning, traceback.format_exc()))

The idea is nice and I think we should have such an extension.

The standard logging library works by taking the format string and the
arguments separately: that way you can check if the message will be
logged first and then only spend time formatting it if so. It would be
cool if we could change the signature of ui.log to that standard too.
Bryan O'Sullivan - Feb. 11, 2013, 9:42 p.m.
On Sun, Feb 10, 2013 at 6:26 AM, Martin Geisler <martin@geisler.net> wrote:

> The standard logging library works by taking the format string and the
> arguments separately: that way you can check if the message will be
> logged first and then only spend time formatting it if so. It would be
> cool if we could change the signature of ui.log to that standard too.
>

I think that's a good idea. I already want to do that with our existing
ui.note and such methods.

Patch

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" % (warning, traceback.format_exc()))
         ui.warn(warning)
         raise
 
@@ -736,12 +737,18 @@ 
         ui.warn(_("warning: --repository ignored\n"))
 
     msg = ' '.join(' ' in a and repr(a) or a for a in fullargs)
-    ui.log("command", msg + "\n")
+    ui.log("command", msg)
     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" %
+            (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)