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).

hgext/blackbox.py

@@ -35,6 +35,8 b' import errno'
 import re
 
 from mercurial.i18n import _
+from mercurial.node import hex
+
 from mercurial import (
     cmdutil,
     util,
@@ -64,6 +66,12 b' 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 b' 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
 

tests/test-blackbox.t

@@ -12,10 +12,13 b' 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 b' 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 b' 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 b' extension and python hooks - use the eol'
   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 b' 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 b' 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 ..

tests/test-obsolete-tag-cache.t

@@ -68,11 +68,11 b' Hiding a non-tip changeset should change'
   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 b' Hiding another changeset should cause th'
   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 b' Resolving tags on an unfiltered repo wri'
   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

tests/test-tags.t

@@ -137,12 +137,12 b' Tag cache debug info written to blackbox'
   $ 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 b' Failure to acquire lock results in no wr'
   $ 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 b' Extra junk data at the end should get ov'
   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 b' Errors writing to .hgtags fnodes cache a'
   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 b' Errors writing to .hgtags fnodes cache a'
   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 b" Stripping doesn't truncate the tags cach"
   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 b" Stripping doesn't truncate the tags cach"
   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