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.
--- a/mercurial/dispatch.py Tue Feb 12 14:08:33 2013 -0800
+++ b/mercurial/dispatch.py Sat Feb 09 09:04:14 2013 -0800
@@ -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,
- cmdpats, cmdoptions)
+ 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()
--- a/tests/test-progress.t Tue Feb 12 14:08:33 2013 -0800
+++ b/tests/test-progress.t Sat Feb 09 09:04:14 2013 -0800
@@ -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)