--- a/tests/test-blackbox.t	Mon Feb 22 14:43:14 2016 -0800
+++ b/tests/test-blackbox.t	Wed Feb 24 20:04:32 2016 +0000
@@ -13,9 +13,9 @@
   $ echo a > a
   $ hg add a
   $ hg blackbox
-  1970/01/01 00:00:00 bob (*)> add a (glob)
-  1970/01/01 00:00:00 bob (*)> add a exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox (glob)
+  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
 
 incoming change tracking
 
@@ -45,12 +45,12 @@
   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 (*)> pull (glob)
-  1970/01/01 00:00:00 bob (*)> updated served branch cache in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> wrote served branch cache with 1 labels and 2 nodes (glob)
-  1970/01/01 00:00:00 bob (*)> 1 incoming changes - new heads: d02f48003e62 (glob)
-  1970/01/01 00:00:00 bob (*)> pull exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  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
 
 we must not cause a failure if we cannot write to the log
 
@@ -107,12 +107,12 @@
   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 (*)> strip tip (glob)
-  1970/01/01 00:00:00 bob (*)> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/73f6ee326b27-7612e004-backup.hg (glob)
-  1970/01/01 00:00:00 bob (*)> updated base branch cache in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> wrote base branch cache with 1 labels and 2 nodes (glob)
-  1970/01/01 00:00:00 bob (*)> strip tip exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  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
 
 extension and python hooks - use the eol extension for a pythonhook
 
@@ -125,12 +125,12 @@
   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 (*)> update (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 0 tags (glob)
-  1970/01/01 00:00:00 bob (*)> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> exthook-update: echo hooked finished in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> update exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  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
 
 log rotation
 
@@ -151,7 +151,7 @@
   $ hg init blackboxtest3
   $ cd blackboxtest3
   $ hg blackbox
-  1970/01/01 00:00:00 bob (*)> blackbox (glob)
+  1970/01/01 00:00:00 bob (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 +178,9 @@
   
   result: None
   $ hg blackbox
-  1970/01/01 00:00:00 bob (*)> blackbox (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox (glob)
+  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
 
 cleanup
   $ cd ..

--- a/tests/test-obsolete-tag-cache.t	Mon Feb 22 14:43:14 2016 -0800
+++ b/tests/test-obsolete-tag-cache.t	Wed Feb 24 20:04:32 2016 +0000
@@ -68,11 +68,11 @@
   55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> 2/2 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 2 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
+  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
 
 Hiding another changeset should cause the filtered hash to change
 
@@ -88,11 +88,11 @@
   042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> 1/1 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
+  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
 
 Resolving tags on an unfiltered repo writes a separate tags cache
 
@@ -109,8 +109,8 @@
   d75775ffbc6bca1794d300f5571272879bd280da test2
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> --hidden tags (glob)
-  1970/01/01 00:00:00 bob (*)> 2/2 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2 with 3 tags (glob)
-  1970/01/01 00:00:00 bob (*)> --hidden tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
+  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

--- a/tests/test-tags.t	Mon Feb 22 14:43:14 2016 -0800
+++ b/tests/test-tags.t	Wed Feb 24 20:04:32 2016 +0000
@@ -137,12 +137,12 @@
   $ hg identify
   b9154636be93 tip
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> identify (glob)
-  1970/01/01 00:00:00 bob (*)> writing 48 bytes to cache/hgtagsfnodes1 (glob)
-  1970/01/01 00:00:00 bob (*)> 0/1 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> identify exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  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
 
 Failure to acquire lock results in no write
 
@@ -151,12 +151,12 @@
   $ hg identify
   b9154636be93 tip
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> identify (glob)
-  1970/01/01 00:00:00 bob (*)> not writing .hg/cache/hgtagsfnodes1 because lock cannot be acquired (glob)
-  1970/01/01 00:00:00 bob (*)> 0/1 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> identify exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  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
 
   $ fnodescacheexists
   no fnodes cache
@@ -351,12 +351,12 @@
   bar                                1:78391a272241
 
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
-  1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  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
 
 #if unix-permissions no-root
 Errors writing to .hgtags fnodes cache are silently ignored
@@ -372,12 +372,12 @@
   bar                                1:78391a272241
 
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> couldn't write cache/hgtagsfnodes1: [Errno 13] Permission denied: '$TESTTMP/t2/.hg/cache/hgtagsfnodes1' (glob)
-  1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  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
 
   $ chmod a+w .hg/cache/hgtagsfnodes1
 
@@ -387,12 +387,12 @@
   bar                                1:78391a272241
 
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
-  1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  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
 
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=168
@@ -416,11 +416,11 @@
   bar                                1:78391a272241
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
-  1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
+  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
 
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=120
@@ -433,12 +433,12 @@
   bar                                1:78391a272241
 
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
-  1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  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
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=144