Patchwork [6,of,8] blackbox: store the blackbox ui object instead of the log file

login
register
mail settings
Submitter timeless@mozdev.org
Date Feb. 24, 2016, 8:10 p.m.
Message ID <cc84ed9b974032db3b77.1456344650@waste.org>
Download mbox | patch
Permalink /patch/13371/
State Accepted
Headers show

Comments

timeless@mozdev.org - Feb. 24, 2016, 8:10 p.m.
# HG changeset patch
# User timeless <timeless@mozdev.org>
# Date 1454519104 0
#      Wed Feb 03 17:05:04 2016 +0000
# Node ID cc84ed9b974032db3b779206b93fb6864e4673ee
# Parent  1c7c84429436f4a27fed1749963458267c12288e
blackbox: store the blackbox ui object instead of the log file

Without this, the last logged entry didn't have access to
the repository, and thus couldn't report its version
(and especially that an add or similar dirtied it).

A side-effect is that one repo leaks until process exit...
Augie Fackler - Feb. 25, 2016, 5:59 p.m.
On Wed, Feb 24, 2016 at 02:10:50PM -0600, timeless wrote:
> # HG changeset patch
> # User timeless <timeless@mozdev.org>
> # Date 1454519104 0
> #      Wed Feb 03 17:05:04 2016 +0000
> # Node ID cc84ed9b974032db3b779206b93fb6864e4673ee
> # Parent  1c7c84429436f4a27fed1749963458267c12288e
> blackbox: store the blackbox ui object instead of the log file

Queued 1-6. Will look at 7 and 8 shortly, but 7 looked like it was
complicated enough that it'll take some extra time.

>
> Without this, the last logged entry didn't have access to
> the repository, and thus couldn't report its version
> (and especially that an add or similar dirtied it).
>
> A side-effect is that one repo leaks until process exit...
>
> diff --git a/hgext/blackbox.py b/hgext/blackbox.py
> --- a/hgext/blackbox.py
> +++ b/hgext/blackbox.py
> @@ -54,7 +54,7 @@
>  # be specifying the version(s) of Mercurial they are tested with, or
>  # leave the attribute unspecified.
>  testedwith = 'internal'
> -lastfp = None
> +lastui = None
>
>  filehandles = {}
>
> @@ -115,15 +115,19 @@
>                      fp = _openlog(self._bbvfs)
>              return fp
>
> +        def _bbwrite(self, fmt, *args):
> +            self._bbfp.write(fmt % args)
> +            self._bbfp.flush()
> +
>          def log(self, event, *msg, **opts):
> -            global lastfp
> +            global lastui
>              super(blackboxui, self).log(event, *msg, **opts)
>
>              if not '*' in self.track and not event in self.track:
>                  return
>
> -            if util.safehasattr(self, '_blackbox'):
> -                fp = self._blackbox
> +            if util.safehasattr(self, '_bbfp'):
> +                ui = self
>              elif util.safehasattr(self, '_bbvfs'):
>                  try:
>                      self._bbfp = self._openlogfile()
> @@ -132,41 +136,41 @@
>                                 err.strerror)
>                      del self._bbvfs
>                      self._bbfp = None
> -                fp = self._bbfp
> +                ui = self
>              else:
>                  # certain ui instances exist outside the context of
>                  # a repo, so just default to the last blackbox that
>                  # was seen.
> -                fp = lastfp
> +                ui = lastui
>
> -            if fp:
> +            if (util.safehasattr(ui, '_bbfp') and
> +                ui._bbfp is not None):
>                  date = util.datestr(None, '%Y/%m/%d %H:%M:%S')
>                  user = util.getuser()
>                  pid = str(util.getpid())
>                  formattedmsg = msg[0] % msg[1:]
>                  rev = '(unknown)'
>                  changed = ''
> -                if util.safehasattr(self, '_bbrepo'):
> -                    ctx = self._bbrepo[None]
> +                if util.safehasattr(ui, '_bbrepo'):
> +                    ctx = ui._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]))
> -                        if (self.configbool('blackbox', 'dirty', False) and (
> -                            any(self._bbrepo.status()) or
> +                        if (ui.configbool('blackbox', 'dirty', False) and (
> +                            any(ui._bbrepo.status()) or
>                              any(ctx.sub(s).dirty() for s in ctx.substate)
>                          )):
>                              changed = '+'
>                  try:
> -                    fp.write('%s %s @%s%s (%s)> %s' %
> -                        (date, user, rev, changed, pid, formattedmsg))
> -                    fp.flush()
> +                    ui._bbwrite('%s %s @%s%s (%s)> %s',
> +                        date, user, rev, changed, pid, formattedmsg)
>                  except IOError as err:
>                      self.debug('warning: cannot write to blackbox.log: %s\n' %
>                                 err.strerror)
> -                if not lastfp or util.safehasattr(self, '_bbrepo'):
> -                    lastfp = fp
> +                if not lastui or util.safehasattr(ui, '_bbrepo'):
> +                    lastui = ui
>
>          def setrepo(self, repo):
>              self._bbvfs = repo.vfs
> diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
> --- a/tests/test-blackbox.t
> +++ b/tests/test-blackbox.t
> @@ -12,12 +12,9 @@
>
>    $ echo a > a
>    $ hg add a
> -  $ hg id --config blackbox.dirty=True > /dev/null
>    $ hg blackbox --config blackbox.dirty=True
>    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 --config blackbox.dirty=True exited 0 after * seconds (glob)
> +  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add a exited 0 after * seconds (glob)
>    1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000+ (5000)> blackbox
>
>  incoming change tracking
> @@ -52,7 +49,7 @@
>    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)> 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
> @@ -114,7 +111,7 @@
>    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)> 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
> @@ -132,7 +129,7 @@
>    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)> update exited 0 after * seconds (glob)
>    1970/01/01 00:00:00 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> blackbox -l 6
>
>  log rotation
> @@ -182,7 +179,7 @@
>    result: None
>    $ hg 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 @0000000000000000000000000000000000000000 (5000)> blackbox exited 0 after * seconds (glob)
>    1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> blackbox
>
>  cleanup
> diff --git a/tests/test-obsolete-tag-cache.t b/tests/test-obsolete-tag-cache.t
> --- a/tests/test-obsolete-tag-cache.t
> +++ b/tests/test-obsolete-tag-cache.t
> @@ -71,7 +71,7 @@
>    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)> 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
> @@ -91,7 +91,7 @@
>    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)> 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
> @@ -112,5 +112,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)> --hidden tags exited 0 after * seconds (glob)
>    1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5
> diff --git a/tests/test-tags.t b/tests/test-tags.t
> --- a/tests/test-tags.t
> +++ b/tests/test-tags.t
> @@ -141,7 +141,7 @@
>    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)> 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
> @@ -155,7 +155,7 @@
>    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)> identify exited 0 after * seconds (glob)
>    1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l 6
>
>    $ fnodescacheexists
> @@ -218,7 +218,7 @@
>    (branch merge, don't forget to commit)
>    $ hg blackbox -l3
>    1970/01/01 00:00:00 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28 (5000)> merge 1
> -  1970/01/01 00:00:00 bob @(unknown) (5000)> merge 1 exited 0 after * seconds (glob)
> +  1970/01/01 00:00:00 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28+b9154636be938d3d431e75a7c906504a079bfe07 (5000)> merge 1 exited 0 after * seconds (glob)
>    1970/01/01 00:00:00 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28+b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l3
>    $ hg id
>    c8edf04160c7+b9154636be93+ tip
> @@ -359,7 +359,7 @@
>    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)> tags exited 0 after * seconds (glob)
>    1970/01/01 00:00:00 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> blackbox -l 6
>
>  #if unix-permissions no-root
> @@ -380,7 +380,7 @@
>    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)> tags exited 0 after * seconds (glob)
>    1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> blackbox -l 6
>
>    $ chmod a+w .hg/cache/hgtagsfnodes1
> @@ -395,7 +395,7 @@
>    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)> tags exited 0 after * seconds (glob)
>    1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> blackbox -l 6
>
>    $ f --size .hg/cache/hgtagsfnodes1
> @@ -423,7 +423,7 @@
>    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)> tags exited 0 after * seconds (glob)
>    1970/01/01 00:00:00 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> blackbox -l 5
>
>    $ f --size .hg/cache/hgtagsfnodes1
> @@ -441,7 +441,7 @@
>    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)> 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
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel

Patch

diff --git a/hgext/blackbox.py b/hgext/blackbox.py
--- a/hgext/blackbox.py
+++ b/hgext/blackbox.py
@@ -54,7 +54,7 @@ 
 # be specifying the version(s) of Mercurial they are tested with, or
 # leave the attribute unspecified.
 testedwith = 'internal'
-lastfp = None
+lastui = None
 
 filehandles = {}
 
@@ -115,15 +115,19 @@ 
                     fp = _openlog(self._bbvfs)
             return fp
 
+        def _bbwrite(self, fmt, *args):
+            self._bbfp.write(fmt % args)
+            self._bbfp.flush()
+
         def log(self, event, *msg, **opts):
-            global lastfp
+            global lastui
             super(blackboxui, self).log(event, *msg, **opts)
 
             if not '*' in self.track and not event in self.track:
                 return
 
-            if util.safehasattr(self, '_blackbox'):
-                fp = self._blackbox
+            if util.safehasattr(self, '_bbfp'):
+                ui = self
             elif util.safehasattr(self, '_bbvfs'):
                 try:
                     self._bbfp = self._openlogfile()
@@ -132,41 +136,41 @@ 
                                err.strerror)
                     del self._bbvfs
                     self._bbfp = None
-                fp = self._bbfp
+                ui = self
             else:
                 # certain ui instances exist outside the context of
                 # a repo, so just default to the last blackbox that
                 # was seen.
-                fp = lastfp
+                ui = lastui
 
-            if fp:
+            if (util.safehasattr(ui, '_bbfp') and
+                ui._bbfp is not None):
                 date = util.datestr(None, '%Y/%m/%d %H:%M:%S')
                 user = util.getuser()
                 pid = str(util.getpid())
                 formattedmsg = msg[0] % msg[1:]
                 rev = '(unknown)'
                 changed = ''
-                if util.safehasattr(self, '_bbrepo'):
-                    ctx = self._bbrepo[None]
+                if util.safehasattr(ui, '_bbrepo'):
+                    ctx = ui._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]))
-                        if (self.configbool('blackbox', 'dirty', False) and (
-                            any(self._bbrepo.status()) or
+                        if (ui.configbool('blackbox', 'dirty', False) and (
+                            any(ui._bbrepo.status()) or
                             any(ctx.sub(s).dirty() for s in ctx.substate)
                         )):
                             changed = '+'
                 try:
-                    fp.write('%s %s @%s%s (%s)> %s' %
-                        (date, user, rev, changed, pid, formattedmsg))
-                    fp.flush()
+                    ui._bbwrite('%s %s @%s%s (%s)> %s',
+                        date, user, rev, changed, pid, formattedmsg)
                 except IOError as err:
                     self.debug('warning: cannot write to blackbox.log: %s\n' %
                                err.strerror)
-                if not lastfp or util.safehasattr(self, '_bbrepo'):
-                    lastfp = fp
+                if not lastui or util.safehasattr(ui, '_bbrepo'):
+                    lastui = ui
 
         def setrepo(self, repo):
             self._bbvfs = repo.vfs
diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
--- a/tests/test-blackbox.t
+++ b/tests/test-blackbox.t
@@ -12,12 +12,9 @@ 
 
   $ echo a > a
   $ hg add a
-  $ hg id --config blackbox.dirty=True > /dev/null
   $ hg blackbox --config blackbox.dirty=True
   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 --config blackbox.dirty=True exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add a exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000+ (5000)> blackbox
 
 incoming change tracking
@@ -52,7 +49,7 @@ 
   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)> 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
@@ -114,7 +111,7 @@ 
   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)> 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
@@ -132,7 +129,7 @@ 
   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)> update exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> blackbox -l 6
 
 log rotation
@@ -182,7 +179,7 @@ 
   result: None
   $ hg 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 @0000000000000000000000000000000000000000 (5000)> blackbox exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> blackbox
 
 cleanup
diff --git a/tests/test-obsolete-tag-cache.t b/tests/test-obsolete-tag-cache.t
--- a/tests/test-obsolete-tag-cache.t
+++ b/tests/test-obsolete-tag-cache.t
@@ -71,7 +71,7 @@ 
   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)> 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
@@ -91,7 +91,7 @@ 
   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)> 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
@@ -112,5 +112,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)> --hidden tags exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5
diff --git a/tests/test-tags.t b/tests/test-tags.t
--- a/tests/test-tags.t
+++ b/tests/test-tags.t
@@ -141,7 +141,7 @@ 
   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)> 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
@@ -155,7 +155,7 @@ 
   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)> identify exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l 6
 
   $ fnodescacheexists
@@ -218,7 +218,7 @@ 
   (branch merge, don't forget to commit)
   $ hg blackbox -l3
   1970/01/01 00:00:00 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28 (5000)> merge 1
-  1970/01/01 00:00:00 bob @(unknown) (5000)> merge 1 exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28+b9154636be938d3d431e75a7c906504a079bfe07 (5000)> merge 1 exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28+b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l3
   $ hg id
   c8edf04160c7+b9154636be93+ tip
@@ -359,7 +359,7 @@ 
   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)> tags exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> blackbox -l 6
 
 #if unix-permissions no-root
@@ -380,7 +380,7 @@ 
   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)> tags exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> blackbox -l 6
 
   $ chmod a+w .hg/cache/hgtagsfnodes1
@@ -395,7 +395,7 @@ 
   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)> tags exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> blackbox -l 6
 
   $ f --size .hg/cache/hgtagsfnodes1
@@ -423,7 +423,7 @@ 
   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)> tags exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> blackbox -l 5
 
   $ f --size .hg/cache/hgtagsfnodes1
@@ -441,7 +441,7 @@ 
   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)> 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