blackbox: log working directory version

Without this, while you could see the list of commands run,
it wasn't possible to identify what they were doing, because commads
could rely on revsets (including remote input which varies over time).
This commit is contained in:
timeless 2016-02-09 19:16:06 +00:00
parent 0100803916
commit 1cee322d64
4 changed files with 105 additions and 84 deletions

View File

@ -35,6 +35,8 @@ import errno
import re
from mercurial.i18n import _
from mercurial.node import hex
from mercurial import (
cmdutil,
util,
@ -64,6 +66,12 @@ def _closelog(vfs):
del filehandles[path]
fp.close()
def hexfn(node):
if node is None:
return None
else:
return hex(node)
def wrapui(ui):
class blackboxui(ui.__class__):
@util.propertycache
@ -131,17 +139,27 @@ def wrapui(ui):
user = util.getuser()
pid = str(util.getpid())
formattedmsg = msg[0] % msg[1:]
rev = '(unknown)'
if util.safehasattr(self, '_bbrepo'):
ctx = self._bbrepo[None]
if ctx.rev() is not None:
rev = hexfn(ctx.node())
else:
parents = ctx.parents()
rev = ('+'.join([hexfn(p.node()) for p in parents]))
try:
fp.write('%s %s (%s)> %s' %
(date, user, pid, formattedmsg))
fp.write('%s %s @%s (%s)> %s' %
(date, user, rev, pid, formattedmsg))
fp.flush()
except IOError as err:
self.debug('warning: cannot write to blackbox.log: %s\n' %
err.strerror)
lastfp = fp
if not lastfp or util.safehasattr(self, '_bbrepo'):
lastfp = fp
def setrepo(self, repo):
self._bbvfs = repo.vfs
self._bbrepo = repo
ui.__class__ = blackboxui

View File

@ -12,10 +12,13 @@ command, exit codes, and duration
$ echo a > a
$ hg add a
$ hg id > /dev/null
$ hg blackbox
1970/01/01 00:00:00 bob (5000)> add a
1970/01/01 00:00:00 bob (5000)> add a exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox
1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add a
1970/01/01 00:00:00 bob @(unknown) (5000)> add a exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> id
1970/01/01 00:00:00 bob @(unknown) (5000)> id exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox
incoming change tracking
@ -45,12 +48,12 @@ clone, commit, pull
added 1 changesets with 1 changes to 1 files
(run 'hg update' to get a working copy)
$ hg blackbox -l 6
1970/01/01 00:00:00 bob (5000)> pull
1970/01/01 00:00:00 bob (5000)> updated served branch cache in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> wrote served branch cache with 1 labels and 2 nodes
1970/01/01 00:00:00 bob (5000)> 1 incoming changes - new heads: d02f48003e62
1970/01/01 00:00:00 bob (5000)> pull exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 6
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> pull
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> updated served branch cache in * seconds (glob)
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote served branch cache with 1 labels and 2 nodes
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> 1 incoming changes - new heads: d02f48003e62
1970/01/01 00:00:00 bob @(unknown) (5000)> pull exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> blackbox -l 6
we must not cause a failure if we cannot write to the log
@ -107,12 +110,12 @@ backup bundles get logged
0 files updated, 0 files merged, 1 files removed, 0 files unresolved
saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
$ hg blackbox -l 6
1970/01/01 00:00:00 bob (5000)> strip tip
1970/01/01 00:00:00 bob (5000)> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/73f6ee326b27-7612e004-backup.hg (glob)
1970/01/01 00:00:00 bob (5000)> updated base branch cache in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> wrote base branch cache with 1 labels and 2 nodes
1970/01/01 00:00:00 bob (5000)> strip tip exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 6
1970/01/01 00:00:00 bob @73f6ee326b27d820b0472f1a825e3a50f3dc489b (5000)> strip tip
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/73f6ee326b27-7612e004-backup.hg
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> updated base branch cache in * seconds (glob)
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote base branch cache with 1 labels and 2 nodes
1970/01/01 00:00:00 bob @(unknown) (5000)> strip tip exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> blackbox -l 6
extension and python hooks - use the eol extension for a pythonhook
@ -125,12 +128,12 @@ extension and python hooks - use the eol extension for a pythonhook
1 files updated, 0 files merged, 0 files removed, 0 files unresolved
1 other heads for branch "default"
$ hg blackbox -l 6
1970/01/01 00:00:00 bob (5000)> update
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 0 tags
1970/01/01 00:00:00 bob (5000)> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> exthook-update: echo hooked finished in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> update exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 6
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> update
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> writing .hg/cache/tags2-visible with 0 tags
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
1970/01/01 00:00:00 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> exthook-update: echo hooked finished in * seconds (glob)
1970/01/01 00:00:00 bob @(unknown) (5000)> update exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> blackbox -l 6
log rotation
@ -151,7 +154,7 @@ log rotation
$ hg init blackboxtest3
$ cd blackboxtest3
$ hg blackbox
1970/01/01 00:00:00 bob (5000)> blackbox
1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox
$ mv .hg/blackbox.log .hg/blackbox.log-
$ mkdir .hg/blackbox.log
$ sed -e 's/\(.*test1.*\)/#\1/; s#\(.*commit2.*\)#os.rmdir(".hg/blackbox.log")\nos.rename(".hg/blackbox.log-", ".hg/blackbox.log")\n\1#' $TESTDIR/test-dispatch.py > ../test-dispatch.py
@ -178,9 +181,9 @@ log rotation
result: None
$ hg blackbox
1970/01/01 00:00:00 bob (5000)> blackbox
1970/01/01 00:00:00 bob (5000)> blackbox exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox
1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox
1970/01/01 00:00:00 bob @(unknown) (5000)> blackbox exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> blackbox
cleanup
$ cd ..

View File

@ -68,11 +68,11 @@ Hiding a non-tip changeset should change filtered hash and cause tags recompute
55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1
$ hg blackbox -l 5
1970/01/01 00:00:00 bob (5000)> tags
1970/01/01 00:00:00 bob (5000)> 2/2 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 2 tags
1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 5
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> tags
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> 2/2 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> writing .hg/cache/tags2-visible with 2 tags
1970/01/01 00:00:00 bob @(unknown) (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5
Hiding another changeset should cause the filtered hash to change
@ -88,11 +88,11 @@ Hiding another changeset should cause the filtered hash to change
042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
$ hg blackbox -l 5
1970/01/01 00:00:00 bob (5000)> tags
1970/01/01 00:00:00 bob (5000)> 1/1 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 5
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> tags
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> 1/1 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob @(unknown) (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5
Resolving tags on an unfiltered repo writes a separate tags cache
@ -109,8 +109,8 @@ Resolving tags on an unfiltered repo writes a separate tags cache
d75775ffbc6bca1794d300f5571272879bd280da test2
$ hg blackbox -l 5
1970/01/01 00:00:00 bob (5000)> --hidden tags
1970/01/01 00:00:00 bob (5000)> 2/2 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2 with 3 tags
1970/01/01 00:00:00 bob (5000)> --hidden tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 5
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> --hidden tags
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> 2/2 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> writing .hg/cache/tags2 with 3 tags
1970/01/01 00:00:00 bob @(unknown) (5000)> --hidden tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5

View File

@ -137,12 +137,12 @@ Tag cache debug info written to blackbox log
$ hg identify
b9154636be93 tip
$ hg blackbox -l 6
1970/01/01 00:00:00 bob (5000)> identify
1970/01/01 00:00:00 bob (5000)> writing 48 bytes to cache/hgtagsfnodes1
1970/01/01 00:00:00 bob (5000)> 0/1 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob (5000)> identify exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 6
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> identify
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> writing 48 bytes to cache/hgtagsfnodes1
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> 0/1 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob @(unknown) (5000)> identify exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l 6
Failure to acquire lock results in no write
@ -151,12 +151,12 @@ Failure to acquire lock results in no write
$ hg identify
b9154636be93 tip
$ hg blackbox -l 6
1970/01/01 00:00:00 bob (5000)> identify
1970/01/01 00:00:00 bob (5000)> not writing .hg/cache/hgtagsfnodes1 because lock cannot be acquired
1970/01/01 00:00:00 bob (5000)> 0/1 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob (5000)> identify exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 6
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> identify
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> not writing .hg/cache/hgtagsfnodes1 because lock cannot be acquired
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> 0/1 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob @(unknown) (5000)> identify exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l 6
$ fnodescacheexists
no fnodes cache
@ -351,12 +351,12 @@ Extra junk data at the end should get overwritten on next cache update
bar 1:78391a272241
$ hg blackbox -l 6
1970/01/01 00:00:00 bob (5000)> tags
1970/01/01 00:00:00 bob (5000)> writing 24 bytes to cache/hgtagsfnodes1
1970/01/01 00:00:00 bob (5000)> 2/3 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 6
1970/01/01 00:00:00 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> tags
1970/01/01 00:00:00 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> writing 24 bytes to cache/hgtagsfnodes1
1970/01/01 00:00:00 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> 2/3 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob @(unknown) (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> blackbox -l 6
#if unix-permissions no-root
Errors writing to .hgtags fnodes cache are silently ignored
@ -372,12 +372,12 @@ Errors writing to .hgtags fnodes cache are silently ignored
bar 1:78391a272241
$ hg blackbox -l 6
1970/01/01 00:00:00 bob (5000)> tags
1970/01/01 00:00:00 bob (5000)> couldn't write cache/hgtagsfnodes1: [Errno 13] Permission denied: '$TESTTMP/t2/.hg/cache/hgtagsfnodes1' (glob)
1970/01/01 00:00:00 bob (5000)> 2/3 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 6
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> tags
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> couldn't write cache/hgtagsfnodes1: [Errno 13] Permission denied: '$TESTTMP/t2/.hg/cache/hgtagsfnodes1'
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> 2/3 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob @(unknown) (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> blackbox -l 6
$ chmod a+w .hg/cache/hgtagsfnodes1
@ -387,12 +387,12 @@ Errors writing to .hgtags fnodes cache are silently ignored
bar 1:78391a272241
$ hg blackbox -l 6
1970/01/01 00:00:00 bob (5000)> tags
1970/01/01 00:00:00 bob (5000)> writing 24 bytes to cache/hgtagsfnodes1
1970/01/01 00:00:00 bob (5000)> 2/3 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 6
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> tags
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> writing 24 bytes to cache/hgtagsfnodes1
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> 2/3 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob @(unknown) (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> blackbox -l 6
$ f --size .hg/cache/hgtagsfnodes1
.hg/cache/hgtagsfnodes1: size=168
@ -416,11 +416,11 @@ Stripping doesn't truncate the tags cache until new data is available
bar 1:78391a272241
$ hg blackbox -l 5
1970/01/01 00:00:00 bob (5000)> writing 24 bytes to cache/hgtagsfnodes1
1970/01/01 00:00:00 bob (5000)> 2/3 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 5
1970/01/01 00:00:00 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> writing 24 bytes to cache/hgtagsfnodes1
1970/01/01 00:00:00 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> 2/3 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob @(unknown) (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> blackbox -l 5
$ f --size .hg/cache/hgtagsfnodes1
.hg/cache/hgtagsfnodes1: size=120
@ -433,12 +433,12 @@ Stripping doesn't truncate the tags cache until new data is available
bar 1:78391a272241
$ hg blackbox -l 6
1970/01/01 00:00:00 bob (5000)> tags
1970/01/01 00:00:00 bob (5000)> writing 24 bytes to cache/hgtagsfnodes1
1970/01/01 00:00:00 bob (5000)> 2/3 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob (5000)> blackbox -l 6
1970/01/01 00:00:00 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> tags
1970/01/01 00:00:00 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> writing 24 bytes to cache/hgtagsfnodes1
1970/01/01 00:00:00 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> 2/3 cache hits/lookups in * seconds (glob)
1970/01/01 00:00:00 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> writing .hg/cache/tags2-visible with 1 tags
1970/01/01 00:00:00 bob @(unknown) (5000)> tags exited 0 after * seconds (glob)
1970/01/01 00:00:00 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> blackbox -l 6
$ f --size .hg/cache/hgtagsfnodes1
.hg/cache/hgtagsfnodes1: size=144