blackbox: add milliseconds to blackbox logs by default

The current second granularity is often not specific enough to
determine whether an hg command is happening before or after some
other event.

Given that starting a process takes on the order of 1ms (well, for
native processes. It's quite a bit more for python processes),
microseconds seems like unnecessary noise.

This also lines up behavior with the rust version, where we already
switched to millisecond precision.

Differential Revision: https://phab.mercurial-scm.org/D12005

hgext/blackbox.py

@@ -1,232 +1,237 b''
 # blackbox.py - log repository events to a file for post-mortem debugging
 #
 # Copyright 2010 Nicolas Dumazet
 # Copyright 2013 Facebook, Inc.
 #
 # This software may be used and distributed according to the terms of the
 # GNU General Public License version 2 or any later version.
 
 """log repository events to a blackbox for debugging
 
 Logs event information to .hg/blackbox.log to help debug and diagnose problems.
 The events that get logged can be configured via the blackbox.track and
 blackbox.ignore config keys.
 
 Examples::
 
   [blackbox]
   track = *
   ignore = pythonhook
   # dirty is *EXPENSIVE* (slow);
   # each log entry indicates `+` if the repository is dirty, like :hg:`id`.
   dirty = True
   # record the source of log messages
   logsource = True
 
   [blackbox]
   track = command, commandfinish, commandexception, exthook, pythonhook
 
   [blackbox]
   track = incoming
 
   [blackbox]
   # limit the size of a log file
   maxsize = 1.5 MB
   # rotate up to N log files when the current one gets too big
   maxfiles = 3
 
   [blackbox]
   # Include microseconds in log entries with %f (see Python function
   # datetime.datetime.strftime)
   date-format = %Y-%m-%d @ %H:%M:%S.%f
 
 """
 
 from __future__ import absolute_import
 
 import re
 
 from mercurial.i18n import _
 from mercurial.node import hex
 
 from mercurial import (
     encoding,
     loggingutil,
     registrar,
 )
 from mercurial.utils import (
     dateutil,
     procutil,
 )
 
 # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for
 # extensions which SHIP WITH MERCURIAL. Non-mainline extensions should
 # be specifying the version(s) of Mercurial they are tested with, or
 # leave the attribute unspecified.
 testedwith = b'ships-with-hg-core'
 
 cmdtable = {}
 command = registrar.command(cmdtable)
 
 configtable = {}
 configitem = registrar.configitem(configtable)
 
 configitem(
     b'blackbox',
     b'dirty',
     default=False,
 )
 configitem(
     b'blackbox',
     b'maxsize',
     default=b'1 MB',
 )
 configitem(
     b'blackbox',
     b'logsource',
     default=False,
 )
 configitem(
     b'blackbox',
     b'maxfiles',
     default=7,
 )
 configitem(
     b'blackbox',
     b'track',
     default=lambda: [b'*'],
 )
 configitem(
     b'blackbox',
     b'ignore',
     default=lambda: [b'chgserver', b'cmdserver', b'extension'],
 )
-configitem(
-    b'blackbox',
-    b'date-format',
-    default=b'%Y/%m/%d %H:%M:%S',
-)
+configitem(b'blackbox', b'date-format', default=b'')
 
 _lastlogger = loggingutil.proxylogger()
 
 
 class blackboxlogger(object):
     def __init__(self, ui, repo):
         self._repo = repo
         self._trackedevents = set(ui.configlist(b'blackbox', b'track'))
         self._ignoredevents = set(ui.configlist(b'blackbox', b'ignore'))
         self._maxfiles = ui.configint(b'blackbox', b'maxfiles')
         self._maxsize = ui.configbytes(b'blackbox', b'maxsize')
         self._inlog = False
 
     def tracked(self, event):
         return (
             b'*' in self._trackedevents and event not in self._ignoredevents
         ) or event in self._trackedevents
 
     def log(self, ui, event, msg, opts):
         # self._log() -> ctx.dirty() may create new subrepo instance, which
         # ui is derived from baseui. So the recursion guard in ui.log()
         # doesn't work as it's local to the ui instance.
         if self._inlog:
             return
         self._inlog = True
         try:
             self._log(ui, event, msg, opts)
         finally:
             self._inlog = False
 
     def _log(self, ui, event, msg, opts):
         default = ui.configdate(b'devel', b'default-date')
-        date = dateutil.datestr(default, ui.config(b'blackbox', b'date-format'))
+        dateformat = ui.config(b'blackbox', b'date-format')
+        if dateformat:
+            date = dateutil.datestr(default, dateformat)
+        else:
+            # We want to display milliseconds (more precision seems
+            # unnecessary).  Since %.3f is not supported, use %f and truncate
+            # microseconds.
+            date = dateutil.datestr(default, b'%Y/%m/%d %H:%M:%S.%f')[:-3]
         user = procutil.getuser()
         pid = b'%d' % procutil.getpid()
         changed = b''
         ctx = self._repo[None]
         parents = ctx.parents()
         rev = b'+'.join([hex(p.node()) for p in parents])
         if ui.configbool(b'blackbox', b'dirty') and ctx.dirty(
             missing=True, merge=False, branch=False
         ):
             changed = b'+'
         if ui.configbool(b'blackbox', b'logsource'):
             src = b' [%s]' % event
         else:
             src = b''
         try:
             fmt = b'%s %s @%s%s (%s)%s> %s'
             args = (date, user, rev, changed, pid, src, msg)
             with loggingutil.openlogfile(
                 ui,
                 self._repo.vfs,
                 name=b'blackbox.log',
                 maxfiles=self._maxfiles,
                 maxsize=self._maxsize,
             ) as fp:
                 fp.write(fmt % args)
         except (IOError, OSError) as err:
             # deactivate this to avoid failed logging again
             self._trackedevents.clear()
             ui.debug(
                 b'warning: cannot write to blackbox.log: %s\n'
                 % encoding.strtolocal(err.strerror)
             )
             return
         _lastlogger.logger = self
 
 
 def uipopulate(ui):
     ui.setlogger(b'blackbox', _lastlogger)
 
 
 def reposetup(ui, repo):
     # During 'hg pull' a httppeer repo is created to represent the remote repo.
     # It doesn't have a .hg directory to put a blackbox in, so we don't do
     # the blackbox setup for it.
     if not repo.local():
         return
 
     # Since blackbox.log is stored in the repo directory, the logger should be
     # instantiated per repository.
     logger = blackboxlogger(ui, repo)
     ui.setlogger(b'blackbox', logger)
 
     # Set _lastlogger even if ui.log is not called. This gives blackbox a
     # fallback place to log
     if _lastlogger.logger is None:
         _lastlogger.logger = logger
 
     repo._wlockfreeprefix.add(b'blackbox.log')
 
 
 @command(
     b'blackbox',
     [
         (b'l', b'limit', 10, _(b'the number of events to show')),
     ],
     _(b'hg blackbox [OPTION]...'),
     helpcategory=command.CATEGORY_MAINTENANCE,
     helpbasic=True,
 )
 def blackbox(ui, repo, *revs, **opts):
     """view the recent repository events"""
 
     if not repo.vfs.exists(b'blackbox.log'):
         return
 
     limit = opts.get('limit')
     fp = repo.vfs(b'blackbox.log', b'r')
     lines = fp.read().split(b'\n')
 
     count = 0
     output = []
     for line in reversed(lines):
         if count >= limit:
             break
 
         # count the commands by matching lines like: 2013/01/23 19:13:36 root>
-        if re.match(br'^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line):
+        if re.match(
+            br'^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}(.\d*)? .*> .*', line
+        ):
             count += 1
         output.append(line)
 
     ui.status(b'\n'.join(reversed(output)))

tests/test-blackbox.t

@@ -1,499 +1,499 b''
 setup
 
   $ cat > myextension.py <<EOF
   > from mercurial import error, registrar
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > @command(b'crash', [], b'hg crash')
   > def crash(ui, *args, **kwargs):
   >     raise Exception("oops")
   > @command(b'abortcmd', [], b'hg abortcmd')
   > def abort(ui, *args, **kwargs):
   >     raise error.Abort(b"oops")
   > EOF
   $ abspath=`pwd`/myextension.py
 
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
   > blackbox=
   > mock=$TESTDIR/mockblackbox.py
   > mq=
   > myextension=$TESTTMP/myextension.py
   > [alias]
   > confuse = log --limit 3
   > so-confusing = confuse --style compact
   > EOF
 
   $ hg init blackboxtest
   $ cd blackboxtest
 
 command, exit codes, and duration
 
   $ echo a > a
   $ hg add a
   $ hg blackbox --config blackbox.dirty=True
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> init blackboxtest exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add a
-  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 --config *blackbox.dirty=True* (glob)
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> init blackboxtest exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> add a
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> add a exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000+ (5000)> blackbox --config *blackbox.dirty=True* (glob)
 
 failure exit code
   $ rm ./.hg/blackbox.log
   $ hg add non-existent
   non-existent: $ENOENT$
   [1]
   $ hg blackbox
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add non-existent
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add non-existent exited 1 after * seconds (glob)
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> add non-existent
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> add non-existent exited 1 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> blackbox
 
 abort exit code
   $ rm ./.hg/blackbox.log
   $ hg abortcmd 2> /dev/null
   [255]
   $ hg blackbox -l 2
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> abortcmd exited 255 after * seconds (glob)
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox -l 2
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> abortcmd exited 255 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> blackbox -l 2
 
 unhandled exception
   $ rm ./.hg/blackbox.log
 #if chg
  (chg exits 255 because it fails to receive an exit code)
   $ hg crash 2>/dev/null
   [255]
 #else
  (hg exits 1 because Python default exit code for uncaught exception is 1)
   $ hg crash 2>/dev/null
   [1]
 #endif
   $ hg blackbox -l 2
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> crash exited 1 after * seconds (glob)
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox -l 2
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> crash exited 1 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> blackbox -l 2
 
 alias expansion is logged
   $ rm ./.hg/blackbox.log
   $ hg confuse
   $ hg blackbox
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> confuse
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> alias 'confuse' expands to 'log --limit 3'
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> confuse exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> confuse
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> alias 'confuse' expands to 'log --limit 3'
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> confuse exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> blackbox
 
 recursive aliases work correctly
   $ rm ./.hg/blackbox.log
   $ hg so-confusing
   $ hg blackbox
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> so-confusing
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> alias 'so-confusing' expands to 'confuse --style compact'
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> alias 'confuse' expands to 'log --limit 3'
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> so-confusing exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> so-confusing
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> alias 'so-confusing' expands to 'confuse --style compact'
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> alias 'confuse' expands to 'log --limit 3'
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> so-confusing exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> blackbox
 
 custom date format
   $ rm ./.hg/blackbox.log
   $ hg --config blackbox.date-format='%Y-%m-%d @ %H:%M:%S' \
   >    --config devel.default-date='1334347993 0' --traceback status
   A a
   $ hg blackbox
   2012-04-13 @ 20:13:13 bob @0000000000000000000000000000000000000000 (5000)> --config *blackbox.date-format=%Y-%m-%d @ %H:%M:%S* --config *devel.default-date=1334347993 0* --traceback status (glob)
   2012-04-13 @ 20:13:13 bob @0000000000000000000000000000000000000000 (5000)> --config *blackbox.date-format=%Y-%m-%d @ %H:%M:%S* --config *devel.default-date=1334347993 0* --traceback status exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> blackbox
 
 incoming change tracking
 
 create two heads to verify that we only see one change in the log later
   $ hg commit -ma
   $ hg up null
   0 files updated, 0 files merged, 1 files removed, 0 files unresolved
   $ echo b > b
   $ hg commit -Amb
   adding b
   created new head
 
 clone, commit, pull
   $ hg clone . ../blackboxtest2
   updating to branch default
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ echo c > c
   $ hg commit -Amc
   adding c
   $ cd ../blackboxtest2
   $ hg pull
   pulling from $TESTTMP/blackboxtest
   searching for changes
   adding changesets
   adding manifests
   adding file changes
   added 1 changesets with 1 changes to 1 files
   new changesets d02f48003e62
   (run 'hg update' to get a working copy)
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote branch cache (served) with 1 labels and 2 nodes
-  1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> updated branch cache (served.hidden) in * seconds (glob)
-  1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote branch cache (served.hidden) 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 @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> pull exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> blackbox -l 6
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote branch cache (served) with 1 labels and 2 nodes
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> updated branch cache (served.hidden) in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote branch cache (served.hidden) with 1 labels and 2 nodes
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> 1 incoming changes - new heads: d02f48003e62
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> pull exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> blackbox -l 6
 
 we must not cause a failure if we cannot write to the log
 
   $ hg rollback
   repository tip rolled back to revision 1 (undo pull)
 
   $ mv .hg/blackbox.log .hg/blackbox.log-
   $ mkdir .hg/blackbox.log
   $ hg --debug incoming
   warning: cannot write to blackbox.log: * (glob)
   comparing with $TESTTMP/blackboxtest
   query 1; heads
   searching for changes
   all local changesets known remotely
   changeset:   2:d02f48003e62c24e2659d97d30f2a83abe5d5d51
   tag:         tip
   phase:       draft
   parent:      1:6563da9dcf87b1949716e38ff3e3dfaa3198eb06
   parent:      -1:0000000000000000000000000000000000000000
   manifest:    2:ab9d46b053ebf45b7996f2922b9893ff4b63d892
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   files+:      c
   extra:       branch=default
   description:
   c
   
   
   $ hg pull
   pulling from $TESTTMP/blackboxtest
   searching for changes
   adding changesets
   adding manifests
   adding file changes
   added 1 changesets with 1 changes to 1 files
   new changesets d02f48003e62
   (run 'hg update' to get a working copy)
 
 a failure reading from the log is fatal
 
   $ hg blackbox -l 3
   abort: *$TESTTMP/blackboxtest2/.hg/blackbox.log* (glob)
   [255]
 
   $ rmdir .hg/blackbox.log
   $ mv .hg/blackbox.log- .hg/blackbox.log
 
 backup bundles get logged
 
   $ touch d
   $ hg commit -Amd
   adding d
   created new head
   $ hg strip tip
   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 @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 branch cache (immutable) in * seconds (glob)
-  1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote branch cache (immutable) with 1 labels and 2 nodes
-  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
+  1970/01/01 00:00:00.000 bob @73f6ee326b27d820b0472f1a825e3a50f3dc489b (5000)> strip tip
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/73f6ee326b27-7612e004-backup.hg
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> updated branch cache (immutable) in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote branch cache (immutable) with 1 labels and 2 nodes
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> strip tip exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> blackbox -l 6
 
 extension and python hooks - use the eol extension for a pythonhook
 
   $ echo '[extensions]' >> .hg/hgrc
   $ echo 'eol=' >> .hg/hgrc
   $ echo '[hooks]' >> .hg/hgrc
   $ echo 'update = echo hooked' >> .hg/hgrc
   $ hg update
   The fsmonitor extension is incompatible with the eol extension and has been disabled. (fsmonitor !)
   hooked
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   updated to "d02f48003e62: c"
   1 other heads for branch "default"
   $ cat >> .hg/hgrc <<EOF
   > [extensions]
   > # disable eol, because it is not needed for subsequent tests
   > # (in addition, keeping it requires extra care for fsmonitor)
   > eol=!
   > EOF
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> update (no-chg !)
-  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 @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> update exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> serve --no-profile --cmdserver chgunix --address $TESTTMP.chgsock/server.* --daemon-postexec 'chdir:/' (glob) (chg !)
-  1970/01/01 00:00:00 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> blackbox -l 5
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> update (no-chg !)
+  1970/01/01 00:00:00.000 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> exthook-update: echo hooked finished in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> update exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> serve --no-profile --cmdserver chgunix --address $TESTTMP.chgsock/server.* --daemon-postexec 'chdir:/' (glob) (chg !)
+  1970/01/01 00:00:00.000 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> blackbox -l 5
 
 log rotation
 
   $ echo '[blackbox]' >> .hg/hgrc
   $ echo 'maxsize = 20 b' >> .hg/hgrc
   $ echo 'maxfiles = 3' >> .hg/hgrc
   $ hg status
   $ hg status
   $ hg status
   $ hg tip -q
   2:d02f48003e62
   $ ls .hg/blackbox.log*
   .hg/blackbox.log
   .hg/blackbox.log.1
   .hg/blackbox.log.2
   $ cd ..
 
   $ hg init blackboxtest3
   $ cd blackboxtest3
   $ hg blackbox
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> init blackboxtest3 exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> init blackboxtest3 exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 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")\
   > os.rename(".hg/blackbox.log-", ".hg/blackbox.log")\
   > \1#' $TESTDIR/test-dispatch.py > ../test-dispatch.py
   $ "$PYTHON" $TESTDIR/blackbox-readonly-dispatch.py
   running: --debug add foo
   warning: cannot write to blackbox.log: Is a directory (no-windows !)
   warning: cannot write to blackbox.log: $TESTTMP/blackboxtest3/.hg/blackbox.log: Access is denied (windows !)
   adding foo
   result: 0
   running: --debug commit -m commit1 -d 2000-01-01 foo
   warning: cannot write to blackbox.log: Is a directory (no-windows !)
   warning: cannot write to blackbox.log: $TESTTMP/blackboxtest3/.hg/blackbox.log: Access is denied (windows !)
   committing files:
   foo
   committing manifest
   committing changelog
   updating the branch cache
   committed changeset 0:0e46349438790c460c5c9f7546bfcd39b267bbd2
   result: 0
   running: --debug commit -m commit2 -d 2000-01-02 foo
   committing files:
   foo
   committing manifest
   committing changelog
   updating the branch cache
   committed changeset 1:45589e459b2edfbf3dbde7e01f611d2c1e7453d7
   result: 0
   running: --debug log -r 0
   changeset:   0:0e46349438790c460c5c9f7546bfcd39b267bbd2
   phase:       draft
   parent:      -1:0000000000000000000000000000000000000000
   parent:      -1:0000000000000000000000000000000000000000
   manifest:    0:9091aa5df980aea60860a2e39c95182e68d1ddec
   user:        test
   date:        Sat Jan 01 00:00:00 2000 +0000
   files+:      foo
   extra:       branch=default
   description:
   commit1
   
   
   result: 0
   running: --debug log -r tip
   changeset:   1:45589e459b2edfbf3dbde7e01f611d2c1e7453d7
   tag:         tip
   phase:       draft
   parent:      0:0e46349438790c460c5c9f7546bfcd39b267bbd2
   parent:      -1:0000000000000000000000000000000000000000
   manifest:    1:895aa9b7886f89dd017a6d62524e1f9180b04df9
   user:        test
   date:        Sun Jan 02 00:00:00 2000 +0000
   files:       foo
   extra:       branch=default
   description:
   commit2
   
   
   result: 0
   $ hg blackbox
-  1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> updating the branch cache
-  1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> updated branch cache (served) in * seconds (glob)
-  1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> wrote branch cache (served) with 1 labels and 1 nodes
-  1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> --debug commit -m commit2 -d 2000-01-02 foo exited 0 after *.?? seconds (glob)
-  1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> --debug log -r 0
-  1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> writing .hg/cache/tags2-visible with 0 tags
-  1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> --debug log -r 0 exited 0 after *.?? seconds (glob)
-  1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> --debug log -r tip
-  1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> --debug log -r tip exited 0 after *.?? seconds (glob)
-  1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> blackbox
+  1970/01/01 00:00:00.000 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> updating the branch cache
+  1970/01/01 00:00:00.000 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> updated branch cache (served) in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> wrote branch cache (served) with 1 labels and 1 nodes
+  1970/01/01 00:00:00.000 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> --debug commit -m commit2 -d 2000-01-02 foo exited 0 after *.?? seconds (glob)
+  1970/01/01 00:00:00.000 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> --debug log -r 0
+  1970/01/01 00:00:00.000 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> writing .hg/cache/tags2-visible with 0 tags
+  1970/01/01 00:00:00.000 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> --debug log -r 0 exited 0 after *.?? seconds (glob)
+  1970/01/01 00:00:00.000 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> --debug log -r tip
+  1970/01/01 00:00:00.000 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> --debug log -r tip exited 0 after *.?? seconds (glob)
+  1970/01/01 00:00:00.000 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> blackbox
 
 Skip rotation if the .hg is read-only
 
 #if unix-permissions
   $ chmod -w .hg
   $ hg log -r. -T '{rev}\n' --config blackbox.maxsize=1 --debug
   warning: cannot rename '$TESTTMP/blackboxtest3/.hg/blackbox.log.1' to '$TESTTMP/blackboxtest3/.hg/blackbox.log': Permission denied
   warning: cannot write to blackbox.log: Permission denied
   1
   $ chmod +w .hg
 #endif
 
 Test log recursion from dirty status check
 
   $ cat > ../r.py <<EOF
   > from mercurial import context, error, extensions
   > x=[False]
   > def status(orig, *args, **opts):
   >     args[0].repo().ui.log(b"broken", b"recursion?")
   >     return orig(*args, **opts)
   > def reposetup(ui, repo):
   >     extensions.wrapfunction(context.basectx, 'status', status)
   > EOF
   $ hg id --config extensions.x=../r.py --config blackbox.dirty=True
   45589e459b2e tip
 
 cleanup
   $ cd ..
 
 Test missing log directory, which shouldn't be created automatically
 
   $ cat <<'EOF' > closeremove.py
   > def reposetup(ui, repo):
   >     class rmrepo(repo.__class__):
   >         def close(self):
   >             super(rmrepo, self).close()
   >             self.ui.debug(b'removing %s\n' % self.vfs.base)
   >             self.vfs.rmtree()
   >     repo.__class__ = rmrepo
   > EOF
 
   $ hg init gone
   $ cd gone
   $ cat <<'EOF' > .hg/hgrc
   > [extensions]
   > closeremove = ../closeremove.py
   > EOF
   $ hg log --debug
   removing $TESTTMP/gone/.hg
   warning: cannot write to blackbox.log: $ENOENT$ (no-windows !)
   warning: cannot write to blackbox.log: $TESTTMP/gone/.hg/blackbox.log: $ENOTDIR$ (windows !)
   $ cd ..
 
 blackbox should disable itself if track is empty
 
   $ hg --config blackbox.track= init nothing_tracked
   $ cd nothing_tracked
   $ cat >> .hg/hgrc << EOF
   > [blackbox]
   > track =
   > EOF
   $ hg blackbox
   $ cd $TESTTMP
 
 a '*' entry in blackbox.track is interpreted as log everything
 
   $ hg --config blackbox.track='*' \
   >    --config blackbox.logsource=True \
   >    init track_star
   $ cd track_star
   $ cat >> .hg/hgrc << EOF
   > [blackbox]
   > logsource = True
   > track = *
   > EOF
 (only look for entries with specific logged sources, otherwise this test is
 pretty brittle)
   $ hg blackbox | egrep '\[command(finish)?\]'
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000) [commandfinish]> --config *blackbox.track=* --config *blackbox.logsource=True* init track_star exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000) [command]> blackbox
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000) [commandfinish]> --config *blackbox.track=* --config *blackbox.logsource=True* init track_star exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000) [command]> blackbox
   $ cd $TESTTMP
 
 #if chg
 
 when using chg, blackbox.log should get rotated correctly
 
   $ cat > $TESTTMP/noop.py << EOF
   > from __future__ import absolute_import
   > import time
   > from mercurial import registrar, scmutil
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > @command(b'noop')
   > def noop(ui, repo):
   >     pass
   > EOF
 
   $ hg init blackbox-chg
   $ cd blackbox-chg
 
   $ cat > .hg/hgrc << EOF
   > [blackbox]
   > maxsize = 500B
   > [extensions]
   > # extension change forces chg to restart
   > noop=$TESTTMP/noop.py
   > EOF
 
   $ "$PYTHON" -c 'print("a" * 400)' > .hg/blackbox.log
   $ chg noop
   $ chg noop
   $ chg noop
   $ chg noop
   $ chg noop
 
   $ cat > showsize.py << 'EOF'
   > import os
   > import sys
   > limit = 500
   > for p in sys.argv[1:]:
   >     size = os.stat(p).st_size
   >     if size >= limit:
   >         desc = '>='
   >     else:
   >         desc = '<'
   >     print('%s: %s %d' % (p, desc, limit))
   > EOF
 
   $ "$PYTHON" showsize.py .hg/blackbox*
   .hg/blackbox.log: < 500
   .hg/blackbox.log.1: >= 500
   .hg/blackbox.log.2: >= 500
 
   $ cd ..
 
 With chg, blackbox should not create the log file if the repo is gone
 
   $ hg init repo1
   $ hg --config extensions.a=! -R repo1 log
   $ rm -rf $TESTTMP/repo1
   $ hg --config extensions.a=! init repo1
 
 #endif
 
 blackbox should work if repo.ui.log is not called (issue5518)
 
   $ cat > $TESTTMP/raise.py << EOF
   > from __future__ import absolute_import
   > from mercurial import registrar, scmutil
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > @command(b'raise')
   > def raisecmd(*args):
   >     raise RuntimeError('raise')
   > EOF
 
   $ cat >> $HGRCPATH << EOF
   > [blackbox]
   > track = commandexception
   > [extensions]
   > raise=$TESTTMP/raise.py
   > EOF
 
   $ hg init $TESTTMP/blackbox-exception-only
   $ cd $TESTTMP/blackbox-exception-only
 
 #if chg
  (chg exits 255 because it fails to receive an exit code)
   $ hg raise 2>/dev/null
   [255]
 #else
  (hg exits 1 because Python default exit code for uncaught exception is 1)
   $ hg raise 2>/dev/null
   [1]
 #endif
 
   $ head -1 .hg/blackbox.log
-  1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> ** Unknown exception encountered with possibly-broken third-party extension "mock" (version N/A)
+  1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000)> ** Unknown exception encountered with possibly-broken third-party extension "mock" (version N/A)
   $ tail -2 .hg/blackbox.log
   RuntimeError: raise
   

tests/test-devel-warnings.t

@@ -1,470 +1,470 b''
 
   $ cat << EOF > buggylocking.py
   > """A small extension that tests our developer warnings
   > """
   > 
   > from mercurial import error, registrar, repair, util
   > 
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > 
   > @command(b'buggylocking', [], '')
   > def buggylocking(ui, repo):
   >     lo = repo.lock()
   >     wl = repo.wlock()
   >     wl.release()
   >     lo.release()
   > 
   > @command(b'buggytransaction', [], '')
   > def buggylocking(ui, repo):
   >     tr = repo.transaction(b'buggy')
   >     # make sure we rollback the transaction as we don't want to rely on the__del__
   >     tr.release()
   > 
   > @command(b'properlocking', [], '')
   > def properlocking(ui, repo):
   >     """check that reentrance is fine"""
   >     wl = repo.wlock()
   >     lo = repo.lock()
   >     tr = repo.transaction(b'proper')
   >     tr2 = repo.transaction(b'proper')
   >     lo2 = repo.lock()
   >     wl2 = repo.wlock()
   >     wl2.release()
   >     lo2.release()
   >     tr2.close()
   >     tr.close()
   >     lo.release()
   >     wl.release()
   > 
   > @command(b'nowaitlocking', [], '')
   > def nowaitlocking(ui, repo):
   >     lo = repo.lock()
   >     wl = repo.wlock(wait=False)
   >     wl.release()
   >     lo.release()
   > 
   > @command(b'no-wlock-write', [], '')
   > def nowlockwrite(ui, repo):
   >     with repo.vfs(b'branch', b'a'):
   >         pass
   > 
   > @command(b'no-lock-write', [], '')
   > def nolockwrite(ui, repo):
   >     with repo.svfs(b'fncache', b'a'):
   >         pass
   > 
   > @command(b'stripintr', [], '')
   > def stripintr(ui, repo):
   >     lo = repo.lock()
   >     tr = repo.transaction(b'foobar')
   >     try:
   >         repair.strip(repo.ui, repo, [repo[b'.'].node()])
   >     finally:
   >         lo.release()
   > @command(b'oldanddeprecated', [], '')
   > def oldanddeprecated(ui, repo):
   >     """test deprecation warning API"""
   >     def foobar(ui):
   >         ui.deprecwarn(b'foorbar is deprecated, go shopping', b'42.1337')
   >     foobar(ui)
   > @command(b'nouiwarning', [], '')
   > def nouiwarning(ui, repo):
   >     util.nouideprecwarn(b'this is a test', b'13.37')
   > @command(b'programmingerror', [], '')
   > def programmingerror(ui, repo):
   >     raise error.ProgrammingError(b'something went wrong', hint=b'try again')
   > EOF
 
   $ cat << EOF >> $HGRCPATH
   > [extensions]
   > buggylocking=$TESTTMP/buggylocking.py
   > mock=$TESTDIR/mockblackbox.py
   > blackbox=
   > [devel]
   > all-warnings=1
   > [blackbox]
   > track = command, commandexception, commandfinish, develwarn
   > EOF
 
   $ hg init lock-checker
   $ cd lock-checker
   $ hg buggylocking
   devel-warn: "wlock" acquired after "lock" at: $TESTTMP/buggylocking.py:* (buggylocking) (glob)
   $ cat << EOF >> $HGRCPATH
   > [devel]
   > all=0
   > check-locks=1
   > EOF
   $ hg buggylocking
   devel-warn: "wlock" acquired after "lock" at: $TESTTMP/buggylocking.py:* (buggylocking) (glob)
 #if no-chg no-pyoxidizer
   $ hg buggylocking --traceback
   devel-warn: "wlock" acquired after "lock" at:
    */hg:* in <module> (glob) (?)
    */mercurial/dispatch.py:* in run (glob)
    */mercurial/dispatch.py:* in dispatch (glob)
    */mercurial/dispatch.py:* in _rundispatch (glob)
    */mercurial/dispatch.py:* in _runcatch (glob)
    */mercurial/dispatch.py:* in _callcatch (glob)
    */mercurial/scmutil.py* in callcatch (glob)
    */mercurial/dispatch.py:* in _runcatchfunc (glob)
    */mercurial/dispatch.py:* in _dispatch (glob)
    */mercurial/dispatch.py:* in runcommand (glob)
    */mercurial/dispatch.py:* in _runcommand (glob)
    */mercurial/dispatch.py:* in <lambda> (glob)
    */mercurial/util.py:* in check (glob)
    $TESTTMP/buggylocking.py:* in buggylocking (glob)
 #endif
 #if chg no-pyoxidizer
   $ hg buggylocking --traceback
   devel-warn: "wlock" acquired after "lock" at:
    */hg:* in <module> (glob) (?)
    */mercurial/dispatch.py:* in run (glob)
    */mercurial/dispatch.py:* in dispatch (glob)
    */mercurial/dispatch.py:* in _rundispatch (glob)
    */mercurial/dispatch.py:* in _runcatch (glob)
    */mercurial/dispatch.py:* in _callcatch (glob)
    */mercurial/scmutil.py:* in callcatch (glob)
    */mercurial/dispatch.py:* in _runcatchfunc (glob)
    */mercurial/dispatch.py:* in _dispatch (glob)
    */mercurial/dispatch.py:* in runcommand (glob)
    */mercurial/dispatch.py:* in _runcommand (glob)
    */mercurial/dispatch.py:* in <lambda> (glob)
    */mercurial/util.py:* in check (glob)
    */mercurial/commands.py:* in serve (glob)
    */mercurial/server.py:* in runservice (glob)
    */mercurial/commandserver.py:* in run (glob)
    */mercurial/commandserver.py:* in _mainloop (glob)
    */mercurial/commandserver.py:* in _acceptnewconnection (glob)
    */mercurial/commandserver.py:* in _runworker (glob)
    */mercurial/commandserver.py:* in _serverequest (glob)
    */mercurial/commandserver.py:* in serve (glob)
    */mercurial/commandserver.py:* in serveone (glob)
    */mercurial/chgserver.py:* in runcommand (glob)
    */mercurial/commandserver.py:* in runcommand (glob)
    */mercurial/commandserver.py:* in _dispatchcommand (glob)
    */mercurial/dispatch.py:* in dispatch (glob)
    */mercurial/dispatch.py:* in _rundispatch (glob)
    */mercurial/dispatch.py:* in _runcatch (glob)
    */mercurial/dispatch.py:* in _callcatch (glob)
    */mercurial/scmutil.py:* in callcatch (glob)
    */mercurial/dispatch.py:* in _runcatchfunc (glob)
    */mercurial/dispatch.py:* in _dispatch (glob)
    */mercurial/dispatch.py:* in runcommand (glob)
    */mercurial/dispatch.py:* in _runcommand (glob)
    */mercurial/dispatch.py:* in <lambda> (glob)
    */mercurial/util.py:* in check (glob)
    $TESTTMP/buggylocking.py:* in buggylocking (glob)
 #endif
 #if pyoxidizer
   $ hg buggylocking --traceback
   devel-warn: "wlock" acquired after "lock" at:
    <string>:* (glob)
    mercurial.dispatch:* in run (glob)
    mercurial.dispatch:* in dispatch (glob)
    mercurial.dispatch:* in _rundispatch (glob)
    mercurial.dispatch:* in _runcatch (glob)
    mercurial.dispatch:* in _callcatch (glob)
    mercurial.scmutil:* in callcatch (glob)
    mercurial.dispatch:* in _runcatchfunc (glob)
    mercurial.dispatch:* in _dispatch (glob)
    mercurial.dispatch:* in runcommand (glob)
    mercurial.dispatch:* in _runcommand (glob)
    mercurial.dispatch:* in <lambda> (glob)
    mercurial.util:* in check (glob)
    $TESTTMP/buggylocking.py:* in buggylocking (glob)
 #endif
   $ hg properlocking
   $ hg nowaitlocking
 
 Writing without lock
 
   $ hg no-wlock-write
   devel-warn: write with no wlock: "branch" at: $TESTTMP/buggylocking.py:* (nowlockwrite) (glob)
 
   $ hg no-lock-write
   devel-warn: write with no lock: "fncache" at: $TESTTMP/buggylocking.py:* (nolockwrite) (glob)
 
 Stripping from a transaction
 
   $ echo a > a
   $ hg add a
   $ hg commit -m a
   $ hg stripintr 2>&1 | egrep -v '^(\*\*|  )'
   Traceback (most recent call last):
   *ProgrammingError: cannot strip from inside a transaction (glob)
 
   $ hg oldanddeprecated
   devel-warn: foorbar is deprecated, go shopping
   (compatibility will be dropped after Mercurial-42.1337, update your code.) at: $TESTTMP/buggylocking.py:* (oldanddeprecated) (glob)
 
 #if no-chg no-pyoxidizer
   $ hg oldanddeprecated --traceback
   devel-warn: foorbar is deprecated, go shopping
   (compatibility will be dropped after Mercurial-42.1337, update your code.) at:
    */hg:* in <module> (glob) (?)
    */mercurial/dispatch.py:* in run (glob)
    */mercurial/dispatch.py:* in dispatch (glob)
    */mercurial/dispatch.py:* in _rundispatch (glob)
    */mercurial/dispatch.py:* in _runcatch (glob)
    */mercurial/dispatch.py:* in _callcatch (glob)
    */mercurial/scmutil.py* in callcatch (glob)
    */mercurial/dispatch.py:* in _runcatchfunc (glob)
    */mercurial/dispatch.py:* in _dispatch (glob)
    */mercurial/dispatch.py:* in runcommand (glob)
    */mercurial/dispatch.py:* in _runcommand (glob)
    */mercurial/dispatch.py:* in <lambda> (glob)
    */mercurial/util.py:* in check (glob)
    $TESTTMP/buggylocking.py:* in oldanddeprecated (glob)
 #endif
 #if chg no-pyoxidizer
   $ hg oldanddeprecated --traceback
   devel-warn: foorbar is deprecated, go shopping
   (compatibility will be dropped after Mercurial-42.1337, update your code.) at:
    */hg:* in <module> (glob)
    */mercurial/dispatch.py:* in run (glob)
    */mercurial/dispatch.py:* in dispatch (glob)
    */mercurial/dispatch.py:* in _rundispatch (glob)
    */mercurial/dispatch.py:* in _runcatch (glob)
    */mercurial/dispatch.py:* in _callcatch (glob)
    */mercurial/scmutil.py:* in callcatch (glob)
    */mercurial/dispatch.py:* in _runcatchfunc (glob)
    */mercurial/dispatch.py:* in _dispatch (glob)
    */mercurial/dispatch.py:* in runcommand (glob)
    */mercurial/dispatch.py:* in _runcommand (glob)
    */mercurial/dispatch.py:* in <lambda> (glob)
    */mercurial/util.py:* in check (glob)
    */mercurial/commands.py:* in serve (glob)
    */mercurial/server.py:* in runservice (glob)
    */mercurial/commandserver.py:* in run (glob)
    */mercurial/commandserver.py:* in _mainloop (glob)
    */mercurial/commandserver.py:* in _acceptnewconnection (glob)
    */mercurial/commandserver.py:* in _runworker (glob)
    */mercurial/commandserver.py:* in _serverequest (glob)
    */mercurial/commandserver.py:* in serve (glob)
    */mercurial/commandserver.py:* in serveone (glob)
    */mercurial/chgserver.py:* in runcommand (glob)
    */mercurial/commandserver.py:* in runcommand (glob)
    */mercurial/commandserver.py:* in _dispatchcommand (glob)
    */mercurial/dispatch.py:* in dispatch (glob)
    */mercurial/dispatch.py:* in _rundispatch (glob)
    */mercurial/dispatch.py:* in _runcatch (glob)
    */mercurial/dispatch.py:* in _callcatch (glob)
    */mercurial/scmutil.py:* in callcatch (glob)
    */mercurial/dispatch.py:* in _runcatchfunc (glob)
    */mercurial/dispatch.py:* in _dispatch (glob)
    */mercurial/dispatch.py:* in runcommand (glob)
    */mercurial/dispatch.py:* in _runcommand (glob)
    */mercurial/dispatch.py:* in <lambda> (glob)
    */mercurial/util.py:* in check (glob)
    $TESTTMP/buggylocking.py:* in oldanddeprecated (glob)
 #endif
 #if pyoxidizer
   $ hg oldanddeprecated --traceback
   devel-warn: foorbar is deprecated, go shopping
   (compatibility will be dropped after Mercurial-42.1337, update your code.) at:
    <string>:* (glob)
    mercurial.dispatch:* in run (glob)
    mercurial.dispatch:* in dispatch (glob)
    mercurial.dispatch:* in _rundispatch (glob)
    mercurial.dispatch:* in _runcatch (glob)
    mercurial.dispatch:* in _callcatch (glob)
    mercurial.scmutil:* in callcatch (glob)
    mercurial.dispatch:* in _runcatchfunc (glob)
    mercurial.dispatch:* in _dispatch (glob)
    mercurial.dispatch:* in runcommand (glob)
    mercurial.dispatch:* in _runcommand (glob)
    mercurial.dispatch:* in <lambda> (glob)
    mercurial.util:* in check (glob)
    $TESTTMP/buggylocking.py:* in oldanddeprecated (glob)
 #endif
 
 #if no-chg no-pyoxidizer
   $ hg blackbox -l 7
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
   (compatibility will be dropped after Mercurial-42.1337, update your code.) at: $TESTTMP/buggylocking.py:* (oldanddeprecated) (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
   (compatibility will be dropped after Mercurial-42.1337, update your code.) at:
    */hg:* in <module> (glob) (?)
    */mercurial/dispatch.py:* in run (glob)
    */mercurial/dispatch.py:* in dispatch (glob)
    */mercurial/dispatch.py:* in _rundispatch (glob)
    */mercurial/dispatch.py:* in _runcatch (glob)
    */mercurial/dispatch.py:* in _callcatch (glob)
    */mercurial/scmutil.py* in callcatch (glob)
    */mercurial/dispatch.py:* in _runcatchfunc (glob)
    */mercurial/dispatch.py:* in _dispatch (glob)
    */mercurial/dispatch.py:* in runcommand (glob)
    */mercurial/dispatch.py:* in _runcommand (glob)
    */mercurial/dispatch.py:* in <lambda> (glob)
    */mercurial/util.py:* in check (glob)
    $TESTTMP/buggylocking.py:* in oldanddeprecated (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> blackbox -l 7
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> blackbox -l 7
 #endif
 #if chg no-pyoxidizer
   $ hg blackbox -l 7
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
   (compatibility will be dropped after Mercurial-42.1337, update your code.) at: $TESTTMP/buggylocking.py:* (oldanddeprecated) (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
   (compatibility will be dropped after Mercurial-42.1337, update your code.) at:
    */hg:* in <module> (glob)
    */mercurial/dispatch.py:* in run (glob)
    */mercurial/dispatch.py:* in dispatch (glob)
    */mercurial/dispatch.py:* in _rundispatch (glob)
    */mercurial/dispatch.py:* in _runcatch (glob)
    */mercurial/dispatch.py:* in _callcatch (glob)
    */mercurial/scmutil.py:* in callcatch (glob)
    */mercurial/dispatch.py:* in _runcatchfunc (glob)
    */mercurial/dispatch.py:* in _dispatch (glob)
    */mercurial/dispatch.py:* in runcommand (glob)
    */mercurial/dispatch.py:* in _runcommand (glob)
    */mercurial/dispatch.py:* in <lambda> (glob)
    */mercurial/util.py:* in check (glob)
    */mercurial/commands.py:* in serve (glob)
    */mercurial/server.py:* in runservice (glob)
    */mercurial/commandserver.py:* in run (glob)
    */mercurial/commandserver.py:* in _mainloop (glob)
    */mercurial/commandserver.py:* in _acceptnewconnection (glob)
    */mercurial/commandserver.py:* in _runworker (glob)
    */mercurial/commandserver.py:* in _serverequest (glob)
    */mercurial/commandserver.py:* in serve (glob)
    */mercurial/commandserver.py:* in serveone (glob)
    */mercurial/chgserver.py:* in runcommand (glob)
    */mercurial/commandserver.py:* in runcommand (glob)
    */mercurial/commandserver.py:* in _dispatchcommand (glob)
    */mercurial/dispatch.py:* in dispatch (glob)
    */mercurial/dispatch.py:* in _rundispatch (glob)
    */mercurial/dispatch.py:* in _runcatch (glob)
    */mercurial/dispatch.py:* in _callcatch (glob)
    */mercurial/scmutil.py:* in callcatch (glob)
    */mercurial/dispatch.py:* in _runcatchfunc (glob)
    */mercurial/dispatch.py:* in _dispatch (glob)
    */mercurial/dispatch.py:* in runcommand (glob)
    */mercurial/dispatch.py:* in _runcommand (glob)
    */mercurial/dispatch.py:* in <lambda> (glob)
    */mercurial/util.py:* in check (glob)
    $TESTTMP/buggylocking.py:* in oldanddeprecated (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> blackbox -l 7
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> blackbox -l 7
 #endif
 #if pyoxidizer
   $ hg blackbox -l 7
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
   (compatibility will be dropped after Mercurial-42.1337, update your code.) at: $TESTTMP/buggylocking.py:* (oldanddeprecated) (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> devel-warn: foorbar is deprecated, go shopping
   (compatibility will be dropped after Mercurial-42.1337, update your code.) at:
    <string>:* in <module> (glob)
    mercurial.dispatch:* in run (glob)
    mercurial.dispatch:* in dispatch (glob)
    mercurial.dispatch:* in _rundispatch (glob)
    mercurial.dispatch:* in _runcatch (glob)
    mercurial.dispatch:* in _callcatch (glob)
    mercurial.scmutil* in callcatch (glob)
    mercurial.dispatch:* in _runcatchfunc (glob)
    mercurial.dispatch:* in _dispatch (glob)
    mercurial.dispatch:* in runcommand (glob)
    mercurial.dispatch:* in _runcommand (glob)
    mercurial.dispatch:* in <lambda> (glob)
    mercurial.util:* in check (glob)
    $TESTTMP/buggylocking.py:* in oldanddeprecated (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> blackbox -l 7
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated --traceback exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> blackbox -l 7
 #endif
 
 Test programming error failure:
 
   $ hg buggytransaction 2>&1 | egrep -v '^  '
   ** Unknown exception encountered with possibly-broken third-party extension "buggylocking" (version N/A)
   ** which supports versions unknown of Mercurial.
   ** Please disable "buggylocking" and try your action again.
   ** If that fixes the bug please report it to the extension author.
   ** Python * (glob)
   ** Mercurial Distributed SCM (*) (glob)
   ** Extensions loaded: * (glob)
   ** ProgrammingError: transaction requires locking
   Traceback (most recent call last):
   *ProgrammingError: transaction requires locking (glob)
 
   $ hg programmingerror 2>&1 | egrep -v '^  '
   ** Unknown exception encountered with possibly-broken third-party extension "buggylocking" (version N/A)
   ** which supports versions unknown of Mercurial.
   ** Please disable "buggylocking" and try your action again.
   ** If that fixes the bug please report it to the extension author.
   ** Python * (glob)
   ** Mercurial Distributed SCM (*) (glob)
   ** Extensions loaded: * (glob)
   ** ProgrammingError: something went wrong
   ** (try again)
   Traceback (most recent call last):
   *ProgrammingError: something went wrong (glob)
 
 Old style deprecation warning
 
   $ hg nouiwarning
   $TESTTMP/buggylocking.py:*: DeprecationWarning: this is a test (glob)
   (compatibility will be dropped after Mercurial-13.37, update your code.)
     util.nouideprecwarn(b'this is a test', b'13.37')
 
 (disabled outside of test run)
 
   $ HGEMITWARNINGS= hg nouiwarning
 
 Test warning on config option access and registration
 
   $ cat << EOF > ${TESTTMP}/buggyconfig.py
   > """A small extension that tests our developer warnings for config"""
   > 
   > from mercurial import configitems, registrar
   > 
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > 
   > configtable = {}
   > configitem = registrar.configitem(configtable)
   > 
   > configitem(b'test', b'some', default=b'foo')
   > configitem(b'test', b'dynamic', default=configitems.dynamicdefault)
   > configitem(b'test', b'callable', default=list)
   > # overwrite a core config
   > configitem(b'ui', b'quiet', default=False)
   > configitem(b'ui', b'interactive', default=None)
   > 
   > @command(b'buggyconfig')
   > def cmdbuggyconfig(ui, repo):
   >     repo.ui.config(b'ui', b'quiet', True)
   >     repo.ui.config(b'ui', b'interactive', False)
   >     repo.ui.config(b'test', b'some', b'bar')
   >     repo.ui.config(b'test', b'some', b'foo')
   >     repo.ui.config(b'test', b'dynamic', b'some-required-default')
   >     repo.ui.config(b'test', b'dynamic')
   >     repo.ui.config(b'test', b'callable', [])
   >     repo.ui.config(b'test', b'callable', b'foo')
   >     repo.ui.config(b'test', b'unregistered')
   >     repo.ui.config(b'unregistered', b'unregistered')
   > EOF
 
   $ hg --config "extensions.buggyconfig=${TESTTMP}/buggyconfig.py" buggyconfig
   devel-warn: extension 'buggyconfig' overwrite config item 'ui.interactive' at: */mercurial/extensions.py:* (_loadextra) (glob) (no-pyoxidizer !)
   devel-warn: extension 'buggyconfig' overwrite config item 'ui.quiet' at: */mercurial/extensions.py:* (_loadextra) (glob) (no-pyoxidizer !)
   devel-warn: extension 'buggyconfig' overwrite config item 'ui.interactive' at: mercurial.extensions:* (_loadextra) (glob) (pyoxidizer !)
   devel-warn: extension 'buggyconfig' overwrite config item 'ui.quiet' at: mercurial.extensions:* (_loadextra) (glob) (pyoxidizer !)
   devel-warn: specifying a mismatched default value for a registered config item: 'ui.quiet' 'True' at: $TESTTMP/buggyconfig.py:* (cmdbuggyconfig) (glob)
   devel-warn: specifying a mismatched default value for a registered config item: 'ui.interactive' 'False' at: $TESTTMP/buggyconfig.py:* (cmdbuggyconfig) (glob)
   devel-warn: specifying a mismatched default value for a registered config item: 'test.some' 'bar' at: $TESTTMP/buggyconfig.py:* (cmdbuggyconfig) (glob)
   devel-warn: config item requires an explicit default value: 'test.dynamic' at: $TESTTMP/buggyconfig.py:* (cmdbuggyconfig) (glob)
   devel-warn: specifying a mismatched default value for a registered config item: 'test.callable' 'foo' at: $TESTTMP/buggyconfig.py:* (cmdbuggyconfig) (glob)
   devel-warn: accessing unregistered config item: 'test.unregistered' at: $TESTTMP/buggyconfig.py:* (cmdbuggyconfig) (glob)
   devel-warn: accessing unregistered config item: 'unregistered.unregistered' at: $TESTTMP/buggyconfig.py:* (cmdbuggyconfig) (glob)
 
   $ cd ..

tests/test-obsolete-tag-cache.t

@@ -1,125 +1,125 b''
   $ cat >> $HGRCPATH << EOF
   > [extensions]
   > blackbox=
   > rebase=
   > mock=$TESTDIR/mockblackbox.py
   > 
   > [blackbox]
   > track = command, commandfinish, tagscache
   > 
   > [experimental]
   > evolution.createmarkers=True
   > EOF
 
 Create a repo with some tags
 
   $ hg init repo
   $ cd repo
   $ echo initial > foo
   $ hg -q commit -A -m initial
   $ hg tag -m 'test tag' test1
   $ echo first > first
   $ hg -q commit -A -m first
   $ hg tag -m 'test2 tag' test2
   $ hg -q up -r 0
   $ echo newhead > newhead
   $ hg commit -A -m newhead
   adding newhead
   created new head
   $ hg tag -m 'test head 2 tag' head2
 
   $ hg log -G -T '{rev}:{node|short} {tags} {desc}\n'
   @  5:2942a772f72a tip test head 2 tag
   |
   o  4:042eb6bfcc49 head2 newhead
   |
   | o  3:c3cb30f2d2cd  test2 tag
   | |
   | o  2:d75775ffbc6b test2 first
   | |
   | o  1:5f97d42da03f  test tag
   |/
   o  0:55482a6fb4b1 test1 initial
   
 
 Trigger tags cache population by doing something that accesses tags info
 
   $ hg tags
   tip                                5:2942a772f72a
   head2                              4:042eb6bfcc49
   test2                              2:d75775ffbc6b
   test1                              0:55482a6fb4b1
 
   $ cat .hg/cache/tags2-visible
   5 2942a772f72a444bef4bef13874d515f50fa27b6
   042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
   55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1
   d75775ffbc6bca1794d300f5571272879bd280da test2
 
 Hiding a non-tip changeset should change filtered hash and cause tags recompute
 
   $ hg debugobsolete -d '0 0' c3cb30f2d2cd0aae008cc91a07876e3c5131fd22 -u dummyuser
   1 new obsolescence markers
   obsoleted 1 changesets
 
   $ hg tags
   tip                                5:2942a772f72a
   head2                              4:042eb6bfcc49
   test1                              0:55482a6fb4b1
 
   $ cat .hg/cache/tags2-visible
   5 2942a772f72a444bef4bef13874d515f50fa27b6 f34fbc9a9769ba9eff5aff3d008a6b49f85c08b1
   042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
   55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1
 
   $ hg 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 @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> tags
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> 2/2 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> writing .hg/cache/tags2-visible with 2 tags
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5
 
 Hiding another changeset should cause the filtered hash to change
 
   $ hg debugobsolete -d '0 0' d75775ffbc6bca1794d300f5571272879bd280da -u dummyuser
   1 new obsolescence markers
   obsoleted 1 changesets
   $ hg debugobsolete -d '0 0' 5f97d42da03fd56f3b228b03dfe48af5c0adf75b -u dummyuser
   1 new obsolescence markers
   obsoleted 1 changesets
 
   $ hg tags
   tip                                5:2942a772f72a
   head2                              4:042eb6bfcc49
 
   $ cat .hg/cache/tags2-visible
   5 2942a772f72a444bef4bef13874d515f50fa27b6 2fce1eec33263d08a4d04293960fc73a555230e4
   042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
 
   $ hg 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 @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> tags
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> 1/1 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5
 
 Resolving tags on an unfiltered repo writes a separate tags cache
 
   $ hg --hidden tags
   tip                                5:2942a772f72a
   head2                              4:042eb6bfcc49
   test2                              2:d75775ffbc6b
   test1                              0:55482a6fb4b1
 
   $ cat .hg/cache/tags2
   5 2942a772f72a444bef4bef13874d515f50fa27b6
   042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
   55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1
   d75775ffbc6bca1794d300f5571272879bd280da test2
 
   $ hg 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 @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> --hidden tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> --hidden tags
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> 2/2 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> writing .hg/cache/tags2 with 3 tags
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> --hidden tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> blackbox -l 5

tests/test-tags.t

@@ -1,935 +1,935 b''
 setup
 
   $ cat >> $HGRCPATH << EOF
   > [extensions]
   > blackbox=
   > mock=$TESTDIR/mockblackbox.py
   > [blackbox]
   > track = command, commandfinish, tagscache
   > EOF
 
 Helper functions:
 
   $ cacheexists() {
   >   [ -f .hg/cache/tags2-visible ] && echo "tag cache exists" || echo "no tag cache"
   > }
 
   $ fnodescacheexists() {
   >   [ -f .hg/cache/hgtagsfnodes1 ] && echo "fnodes cache exists" || echo "no fnodes cache"
   > }
 
   $ dumptags() {
   >     rev=$1
   >     echo "rev $rev: .hgtags:"
   >     hg cat -r$rev .hgtags
   > }
 
 # XXX need to test that the tag cache works when we strip an old head
 # and add a new one rooted off non-tip: i.e. node and rev of tip are the
 # same, but stuff has changed behind tip.
 
 Setup:
 
   $ hg init t
   $ cd t
   $ cacheexists
   no tag cache
   $ fnodescacheexists
   no fnodes cache
   $ hg id
   000000000000 tip
   $ cacheexists
   no tag cache
   $ fnodescacheexists
   no fnodes cache
   $ echo a > a
   $ hg add a
   $ hg commit -m "test"
   $ hg co
   0 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ hg identify
   acb14030fe0a tip
   $ hg identify -r 'wdir()'
   acb14030fe0a tip
   $ cacheexists
   tag cache exists
 No fnodes cache because .hgtags file doesn't exist
 (this is an implementation detail)
   $ fnodescacheexists
   no fnodes cache
 
 Try corrupting the cache
 
   $ printf 'a b' > .hg/cache/tags2-visible
   $ hg identify
   acb14030fe0a tip
   $ cacheexists
   tag cache exists
   $ fnodescacheexists
   no fnodes cache
   $ hg identify
   acb14030fe0a tip
 
 Create local tag with long name:
 
   $ T=`hg identify --debug --id`
   $ hg tag -l "This is a local tag with a really long name!"
   $ hg tags
   tip                                0:acb14030fe0a
   This is a local tag with a really long name!     0:acb14030fe0a
   $ rm .hg/localtags
 
 Create a tag behind hg's back:
 
   $ echo "$T first" > .hgtags
   $ cat .hgtags
   acb14030fe0a21b60322c440ad2d20cf7685a376 first
   $ hg add .hgtags
   $ hg commit -m "add tags"
   $ hg tags
   tip                                1:b9154636be93
   first                              0:acb14030fe0a
   $ hg identify
   b9154636be93 tip
 
 We should have a fnodes cache now that we have a real tag
 The cache should have an empty entry for rev 0 and a valid entry for rev 1.
 
 
   $ fnodescacheexists
   fnodes cache exists
   $ f --size --hexdump .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=48
   0000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0010: ff ff ff ff ff ff ff ff b9 15 46 36 26 b7 b4 a7 |..........F6&...|
   0020: 73 e0 9e e3 c5 2f 51 0e 19 e0 5e 1f f9 66 d8 59 |s..../Q...^..f.Y|
   $ hg debugtagscache
   0 acb14030fe0a21b60322c440ad2d20cf7685a376 missing
   1 b9154636be938d3d431e75a7c906504a079bfe07 26b7b4a773e09ee3c52f510e19e05e1ff966d859
 
 Repeat with cold tag cache:
 
   $ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1
   $ hg identify
   b9154636be93 tip
 
   $ fnodescacheexists
   fnodes cache exists
   $ f --size --hexdump .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=48
   0000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0010: ff ff ff ff ff ff ff ff b9 15 46 36 26 b7 b4 a7 |..........F6&...|
   0020: 73 e0 9e e3 c5 2f 51 0e 19 e0 5e 1f f9 66 d8 59 |s..../Q...^..f.Y|
 
 And again, but now unable to write tag cache or lock file:
 
 #if unix-permissions no-fsmonitor
 
   $ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1
   $ chmod 555 .hg/cache
   $ hg identify
   b9154636be93 tip
   $ chmod 755 .hg/cache
 
 (this block should be protected by no-fsmonitor, because "chmod 555 .hg"
 makes watchman fail at accessing to files under .hg)
 
   $ chmod 555 .hg
   $ hg identify
   b9154636be93 tip
   $ chmod 755 .hg
 #endif
 
 Tag cache debug info written to blackbox log
 
   $ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1
   $ hg identify
   b9154636be93 tip
   $ hg 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/2 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 @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> identify exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l 6
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> identify
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> writing 48 bytes to cache/hgtagsfnodes1
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> 0/2 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> identify exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l 6
 
 Failure to acquire lock results in no write
 
   $ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1
   $ echo 'foo:1' > .hg/store/lock
   $ hg identify
   b9154636be93 tip
   $ hg 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/2 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 @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> identify exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l 6
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> identify
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> not writing .hg/cache/hgtagsfnodes1 because lock cannot be acquired
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> 0/2 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> identify exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l 6
 
   $ fnodescacheexists
   no fnodes cache
 
   $ rm .hg/store/lock
 
   $ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1
   $ hg identify
   b9154636be93 tip
 
 Create a branch:
 
   $ echo bb > a
   $ hg status
   M a
   $ hg identify
   b9154636be93+ tip
   $ hg co first
   0 files updated, 0 files merged, 1 files removed, 0 files unresolved
   $ hg id
   acb14030fe0a+ first
   $ hg id -r 'wdir()'
   acb14030fe0a+ first
   $ hg -v id
   acb14030fe0a+ first
   $ hg status
   M a
   $ echo 1 > b
   $ hg add b
   $ hg commit -m "branch"
   created new head
 
 Creating a new commit shouldn't append the .hgtags fnodes cache until
 tags info is accessed
 
   $ f --size --hexdump .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=48
   0000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0010: ff ff ff ff ff ff ff ff b9 15 46 36 26 b7 b4 a7 |..........F6&...|
   0020: 73 e0 9e e3 c5 2f 51 0e 19 e0 5e 1f f9 66 d8 59 |s..../Q...^..f.Y|
 
   $ hg id
   c8edf04160c7 tip
 
 First 4 bytes of record 3 are changeset fragment
 
   $ f --size --hexdump .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=72
   0000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0010: ff ff ff ff ff ff ff ff b9 15 46 36 26 b7 b4 a7 |..........F6&...|
   0020: 73 e0 9e e3 c5 2f 51 0e 19 e0 5e 1f f9 66 d8 59 |s..../Q...^..f.Y|
   0030: c8 ed f0 41 00 00 00 00 00 00 00 00 00 00 00 00 |...A............|
   0040: 00 00 00 00 00 00 00 00                         |........|
 
 Merge the two heads:
 
   $ hg merge 1
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   (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 @c8edf04160c7f731e4589d66ab3ab3486a64ac28+b9154636be938d3d431e75a7c906504a079bfe07 (5000)> merge 1 exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28+b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l3
+  1970/01/01 00:00:00.000 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28 (5000)> merge 1
+  1970/01/01 00:00:00.000 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28+b9154636be938d3d431e75a7c906504a079bfe07 (5000)> merge 1 exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28+b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l3
   $ hg id
   c8edf04160c7+b9154636be93+ tip
   $ hg status
   M .hgtags
   $ hg commit -m "merge"
 
 Create a fake head, make sure tag not visible afterwards:
 
   $ cp .hgtags tags
   $ hg tag last
   $ hg rm .hgtags
   $ hg commit -m "remove"
 
   $ mv tags .hgtags
   $ hg add .hgtags
   $ hg commit -m "readd"
   $ 
   $ hg tags
   tip                                6:35ff301afafe
   first                              0:acb14030fe0a
 
 Add invalid tags:
 
   $ echo "spam" >> .hgtags
   $ echo >> .hgtags
   $ echo "foo bar" >> .hgtags
   $ echo "a5a5 invalid" >> .hg/localtags
   $ cat .hgtags
   acb14030fe0a21b60322c440ad2d20cf7685a376 first
   spam
   
   foo bar
   $ hg commit -m "tags"
 
 Report tag parse error on other head:
 
   $ hg up 3
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ echo 'x y' >> .hgtags
   $ hg commit -m "head"
   created new head
 
   $ hg tags --debug
   .hgtags@75d9f02dfe28, line 2: cannot parse entry
   .hgtags@75d9f02dfe28, line 4: node 'foo' is not well formed
   .hgtags@c4be69a18c11, line 2: node 'x' is not well formed
   tip                                8:c4be69a18c11e8bc3a5fdbb576017c25f7d84663
   first                              0:acb14030fe0a21b60322c440ad2d20cf7685a376
   $ hg tip
   changeset:   8:c4be69a18c11
   tag:         tip
   parent:      3:ac5e980c4dc0
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     head
   
 
 Test tag precedence rules:
 
   $ cd ..
   $ hg init t2
   $ cd t2
   $ echo foo > foo
   $ hg add foo
   $ hg ci -m 'add foo'      # rev 0
   $ hg tag bar              # rev 1
   $ echo >> foo
   $ hg ci -m 'change foo 1' # rev 2
   $ hg up -C 1
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ hg tag -r 1 -f bar      # rev 3
   $ hg up -C 1
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ echo >> foo
   $ hg ci -m 'change foo 2' # rev 4
   created new head
   $ hg tags
   tip                                4:0c192d7d5e6b
   bar                                1:78391a272241
 
 Repeat in case of cache effects:
 
   $ hg tags
   tip                                4:0c192d7d5e6b
   bar                                1:78391a272241
 
 Detailed dump of tag info:
 
   $ hg heads -q             # expect 4, 3, 2
   4:0c192d7d5e6b
   3:6fa450212aeb
   2:7a94127795a3
   $ dumptags 2
   rev 2: .hgtags:
   bbd179dfa0a71671c253b3ae0aa1513b60d199fa bar
   $ dumptags 3
   rev 3: .hgtags:
   bbd179dfa0a71671c253b3ae0aa1513b60d199fa bar
   bbd179dfa0a71671c253b3ae0aa1513b60d199fa bar
   78391a272241d70354aa14c874552cad6b51bb42 bar
   $ dumptags 4
   rev 4: .hgtags:
   bbd179dfa0a71671c253b3ae0aa1513b60d199fa bar
 
 Dump cache:
 
   $ cat .hg/cache/tags2-visible
   4 0c192d7d5e6b78a714de54a2e9627952a877e25a
   bbd179dfa0a71671c253b3ae0aa1513b60d199fa bar
   bbd179dfa0a71671c253b3ae0aa1513b60d199fa bar
   78391a272241d70354aa14c874552cad6b51bb42 bar
 
   $ f --size --hexdump .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=120
   0000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0010: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0020: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0030: 7a 94 12 77 0c 04 f2 a8 af 31 de 17 fa b7 42 28 |z..w.....1....B(|
   0040: 78 ee 5a 2d ad bc 94 3d 6f a4 50 21 7d 3b 71 8c |x.Z-...=o.P!};q.|
   0050: 96 4e f3 7b 89 e5 50 eb da fd 57 89 e7 6c e1 b0 |.N.{..P...W..l..|
   0060: 0c 19 2d 7d 0c 04 f2 a8 af 31 de 17 fa b7 42 28 |..-}.....1....B(|
   0070: 78 ee 5a 2d ad bc 94 3d                         |x.Z-...=|
 
 Corrupt the .hgtags fnodes cache
 Extra junk data at the end should get overwritten on next cache update
 
   $ echo extra >> .hg/cache/hgtagsfnodes1
   $ echo dummy1 > foo
   $ hg commit -m throwaway1
 
   $ hg tags
   tip                                5:8dbfe60eff30
   bar                                1:78391a272241
 
   $ hg 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)> 3/4 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 @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> blackbox -l 6
+  1970/01/01 00:00:00.000 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> tags
+  1970/01/01 00:00:00.000 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> writing 24 bytes to cache/hgtagsfnodes1
+  1970/01/01 00:00:00.000 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> 3/4 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00.000 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> blackbox -l 6
 
 On junk data + missing cache entries, hg also overwrites the junk.
 
   $ rm -f .hg/cache/tags2-visible
   >>> import os
   >>> with open(".hg/cache/hgtagsfnodes1", "ab+") as fp:
   ...     fp.seek(-10, os.SEEK_END) and None
   ...     fp.truncate() and None
 
   $ hg debugtagscache | tail -2
   4 0c192d7d5e6b78a714de54a2e9627952a877e25a 0c04f2a8af31de17fab7422878ee5a2dadbc943d
   5 8dbfe60eff306a54259cfe007db9e330e7ecf866 missing
   $ hg tags
   tip                                5:8dbfe60eff30
   bar                                1:78391a272241
   $ hg debugtagscache | tail -2
   4 0c192d7d5e6b78a714de54a2e9627952a877e25a 0c04f2a8af31de17fab7422878ee5a2dadbc943d
   5 8dbfe60eff306a54259cfe007db9e330e7ecf866 0c04f2a8af31de17fab7422878ee5a2dadbc943d
 
 If the 4 bytes of node hash for a record don't match an existing node, the entry
 is flagged as invalid.
 
   >>> import os
   >>> with open(".hg/cache/hgtagsfnodes1", "rb+") as fp:
   ...     fp.seek(-24, os.SEEK_END) and None
   ...     fp.write(b'\xde\xad') and None
 
   $ f --size --hexdump .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=144
   0000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0010: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0020: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0030: 7a 94 12 77 0c 04 f2 a8 af 31 de 17 fa b7 42 28 |z..w.....1....B(|
   0040: 78 ee 5a 2d ad bc 94 3d 6f a4 50 21 7d 3b 71 8c |x.Z-...=o.P!};q.|
   0050: 96 4e f3 7b 89 e5 50 eb da fd 57 89 e7 6c e1 b0 |.N.{..P...W..l..|
   0060: 0c 19 2d 7d 0c 04 f2 a8 af 31 de 17 fa b7 42 28 |..-}.....1....B(|
   0070: 78 ee 5a 2d ad bc 94 3d de ad e6 0e 0c 04 f2 a8 |x.Z-...=........|
   0080: af 31 de 17 fa b7 42 28 78 ee 5a 2d ad bc 94 3d |.1....B(x.Z-...=|
 
   $ hg debugtagscache | tail -2
   4 0c192d7d5e6b78a714de54a2e9627952a877e25a 0c04f2a8af31de17fab7422878ee5a2dadbc943d
   5 8dbfe60eff306a54259cfe007db9e330e7ecf866 invalid
 
   $ hg tags
   tip                                5:8dbfe60eff30
   bar                                1:78391a272241
 
 BUG: If the filenode part of an entry in hgtagsfnodes is corrupt and
 tags2-visible is missing, `hg tags` aborts.  Corrupting the leading 4 bytes of
 node hash (as above) doesn't seem to trigger the issue.  Also note that the
 debug command hides the corruption, both with and without tags2-visible.
 
   $ mv .hg/cache/hgtagsfnodes1 .hg/cache/hgtagsfnodes1.bak
   $ hg debugupdatecaches
 
   >>> import os
   >>> with open(".hg/cache/hgtagsfnodes1", "rb+") as fp:
   ...     fp.seek(-16, os.SEEK_END) and None
   ...     fp.write(b'\xde\xad') and None
 
   $ f --size --hexdump .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=144
   0000: bb d1 79 df 00 00 00 00 00 00 00 00 00 00 00 00 |..y.............|
   0010: 00 00 00 00 00 00 00 00 78 39 1a 27 0c 04 f2 a8 |........x9.'....|
   0020: af 31 de 17 fa b7 42 28 78 ee 5a 2d ad bc 94 3d |.1....B(x.Z-...=|
   0030: 7a 94 12 77 0c 04 f2 a8 af 31 de 17 fa b7 42 28 |z..w.....1....B(|
   0040: 78 ee 5a 2d ad bc 94 3d 6f a4 50 21 7d 3b 71 8c |x.Z-...=o.P!};q.|
   0050: 96 4e f3 7b 89 e5 50 eb da fd 57 89 e7 6c e1 b0 |.N.{..P...W..l..|
   0060: 0c 19 2d 7d 0c 04 f2 a8 af 31 de 17 fa b7 42 28 |..-}.....1....B(|
   0070: 78 ee 5a 2d ad bc 94 3d 8d bf e6 0e 0c 04 f2 a8 |x.Z-...=........|
   0080: de ad de 17 fa b7 42 28 78 ee 5a 2d ad bc 94 3d |......B(x.Z-...=|
 
   $ hg debugtagscache | tail -2
   4 0c192d7d5e6b78a714de54a2e9627952a877e25a 0c04f2a8af31de17fab7422878ee5a2dadbc943d
   5 8dbfe60eff306a54259cfe007db9e330e7ecf866 0c04f2a8deadde17fab7422878ee5a2dadbc943d (unknown node)
 
   $ rm -f .hg/cache/tags2-visible
   $ hg debugtagscache | tail -2
   4 0c192d7d5e6b78a714de54a2e9627952a877e25a 0c04f2a8af31de17fab7422878ee5a2dadbc943d
   5 8dbfe60eff306a54259cfe007db9e330e7ecf866 0c04f2a8deadde17fab7422878ee5a2dadbc943d (unknown node)
 
   $ hg tags
   tip                                5:8dbfe60eff30
   bar                                1:78391a272241
 
 BUG: Unless this file is restored, the `hg tags` in the next unix-permissions
 conditional will fail: "abort: data/.hgtags.i@0c04f2a8dead: no match found"
 
   $ mv .hg/cache/hgtagsfnodes1.bak .hg/cache/hgtagsfnodes1
 
 #if unix-permissions no-root
 Errors writing to .hgtags fnodes cache are silently ignored
 
   $ echo dummy2 > foo
   $ hg commit -m throwaway2
 
   $ chmod a-w .hg/cache/hgtagsfnodes1
   $ rm -f .hg/cache/tags2-visible
 
   $ hg tags
   tip                                6:b968051b5cf3
   bar                                1:78391a272241
 
   $ hg 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 *] * (glob)
-  1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> 2/4 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 @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> blackbox -l 6
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> tags
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> couldn't write cache/hgtagsfnodes1: [Errno *] * (glob)
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> 2/4 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> blackbox -l 6
 
   $ chmod a+w .hg/cache/hgtagsfnodes1
 
   $ rm -f .hg/cache/tags2-visible
   $ hg tags
   tip                                6:b968051b5cf3
   bar                                1:78391a272241
 
   $ hg 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/4 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 @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> blackbox -l 6
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> tags
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> writing 24 bytes to cache/hgtagsfnodes1
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> 2/4 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> blackbox -l 6
 
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=168
 
   $ hg -q --config extensions.strip= strip -r 6 --no-backup
 #endif
 
 Stripping doesn't truncate the tags cache until new data is available
 
   $ rm -f .hg/cache/hgtagsfnodes1 .hg/cache/tags2-visible
   $ hg tags
   tip                                5:8dbfe60eff30
   bar                                1:78391a272241
 
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=144
 
   $ hg -q --config extensions.strip= strip -r 5 --no-backup
   $ hg tags
   tip                                4:0c192d7d5e6b
   bar                                1:78391a272241
 
   $ hg 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/4 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 @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> blackbox -l 5
+  1970/01/01 00:00:00.000 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> writing 24 bytes to cache/hgtagsfnodes1
+  1970/01/01 00:00:00.000 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> 2/4 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00.000 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @0c192d7d5e6b78a714de54a2e9627952a877e25a (5000)> blackbox -l 5
 
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=120
 
   $ echo dummy > foo
   $ hg commit -m throwaway3
 
   $ hg tags
   tip                                5:035f65efb448
   bar                                1:78391a272241
 
   $ hg 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)> 3/4 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 @035f65efb448350f4772141702a81ab1df48c465 (5000)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> blackbox -l 6
+  1970/01/01 00:00:00.000 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> tags
+  1970/01/01 00:00:00.000 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> writing 24 bytes to cache/hgtagsfnodes1
+  1970/01/01 00:00:00.000 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> 3/4 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00.000 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00.000 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00.000 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> blackbox -l 6
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=144
 
   $ hg -q --config extensions.strip= strip -r 5 --no-backup
 
 Test tag removal:
 
   $ hg tag --remove bar     # rev 5
   $ hg tip -vp
   changeset:   5:5f6e8655b1c7
   tag:         tip
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   files:       .hgtags
   description:
   Removed tag bar
   
   
   diff -r 0c192d7d5e6b -r 5f6e8655b1c7 .hgtags
   --- a/.hgtags	Thu Jan 01 00:00:00 1970 +0000
   +++ b/.hgtags	Thu Jan 01 00:00:00 1970 +0000
   @@ -1,1 +1,3 @@
    bbd179dfa0a71671c253b3ae0aa1513b60d199fa bar
   +78391a272241d70354aa14c874552cad6b51bb42 bar
   +0000000000000000000000000000000000000000 bar
   
   $ hg tags
   tip                                5:5f6e8655b1c7
   $ hg tags                 # again, try to expose cache bugs
   tip                                5:5f6e8655b1c7
 
 Remove nonexistent tag:
 
   $ hg tag --remove foobar
   abort: tag 'foobar' does not exist
   [10]
   $ hg tip
   changeset:   5:5f6e8655b1c7
   tag:         tip
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     Removed tag bar
   
 
 Undo a tag with rollback:
 
   $ hg rollback             # destroy rev 5 (restore bar)
   repository tip rolled back to revision 4 (undo commit)
   working directory now based on revision 4
   $ hg tags
   tip                                4:0c192d7d5e6b
   bar                                1:78391a272241
   $ hg tags
   tip                                4:0c192d7d5e6b
   bar                                1:78391a272241
 
 Test tag rank:
 
   $ cd ..
   $ hg init t3
   $ cd t3
   $ echo foo > foo
   $ hg add foo
   $ hg ci -m 'add foo'       # rev 0
   $ hg tag -f bar            # rev 1 bar -> 0
   $ hg tag -f bar            # rev 2 bar -> 1
   $ hg tag -fr 0 bar         # rev 3 bar -> 0
   $ hg tag -fr 1 bar         # rev 4 bar -> 1
   $ hg tag -fr 0 bar         # rev 5 bar -> 0
   $ hg tags
   tip                                5:85f05169d91d
   bar                                0:bbd179dfa0a7
   $ hg co 3
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ echo barbar > foo
   $ hg ci -m 'change foo'    # rev 6
   created new head
   $ hg tags
   tip                                6:735c3ca72986
   bar                                0:bbd179dfa0a7
 
 Don't allow moving tag without -f:
 
   $ hg tag -r 3 bar
   abort: tag 'bar' already exists (use -f to force)
   [10]
   $ hg tags
   tip                                6:735c3ca72986
   bar                                0:bbd179dfa0a7
 
 Strip 1: expose an old head:
 
   $ hg --config extensions.mq= strip 5
   saved backup bundle to $TESTTMP/t3/.hg/strip-backup/*-backup.hg (glob)
   $ hg tags                  # partly stale cache
   tip                                5:735c3ca72986
   bar                                1:78391a272241
   $ hg tags                  # up-to-date cache
   tip                                5:735c3ca72986
   bar                                1:78391a272241
 
 Strip 2: destroy whole branch, no old head exposed
 
   $ hg --config extensions.mq= strip 4
   saved backup bundle to $TESTTMP/t3/.hg/strip-backup/*-backup.hg (glob)
   $ hg tags                  # partly stale
   tip                                4:735c3ca72986
   bar                                0:bbd179dfa0a7
   $ rm -f .hg/cache/tags2-visible
   $ hg tags                  # cold cache
   tip                                4:735c3ca72986
   bar                                0:bbd179dfa0a7
 
 Test tag rank with 3 heads:
 
   $ cd ..
   $ hg init t4
   $ cd t4
   $ echo foo > foo
   $ hg add
   adding foo
   $ hg ci -m 'add foo'                 # rev 0
   $ hg tag bar                         # rev 1 bar -> 0
   $ hg tag -f bar                      # rev 2 bar -> 1
   $ hg up -qC 0
   $ hg tag -fr 2 bar                   # rev 3 bar -> 2
   $ hg tags
   tip                                3:197c21bbbf2c
   bar                                2:6fa450212aeb
   $ hg up -qC 0
   $ hg tag -m 'retag rev 0' -fr 0 bar  # rev 4 bar -> 0, but bar stays at 2
 
 Bar should still point to rev 2:
 
   $ hg tags
   tip                                4:3b4b14ed0202
   bar                                2:6fa450212aeb
 
 Test that removing global/local tags does not get confused when trying
 to remove a tag of type X which actually only exists as a type Y:
 
   $ cd ..
   $ hg init t5
   $ cd t5
   $ echo foo > foo
   $ hg add
   adding foo
   $ hg ci -m 'add foo'                 # rev 0
 
   $ hg tag -r 0 -l localtag
   $ hg tag --remove localtag
   abort: tag 'localtag' is not a global tag
   [10]
   $ 
   $ hg tag -r 0 globaltag
   $ hg tag --remove -l globaltag
   abort: tag 'globaltag' is not a local tag
   [10]
   $ hg tags -v
   tip                                1:a0b6fe111088
   localtag                           0:bbd179dfa0a7 local
   globaltag                          0:bbd179dfa0a7
 
 Templated output:
 
  (immediate values)
 
   $ hg tags -T '{pad(tag, 9)} {rev}:{node} ({type})\n'
   tip       1:a0b6fe111088c8c29567d3876cc466aa02927cae ()
   localtag  0:bbd179dfa0a71671c253b3ae0aa1513b60d199fa (local)
   globaltag 0:bbd179dfa0a71671c253b3ae0aa1513b60d199fa ()
 
  (ctx/revcache dependent)
 
   $ hg tags -T '{pad(tag, 9)} {rev} {file_adds}\n'
   tip       1 .hgtags
   localtag  0 foo
   globaltag 0 foo
 
   $ hg tags -T '{pad(tag, 9)} {rev}:{node|shortest}\n'
   tip       1:a0b6
   localtag  0:bbd1
   globaltag 0:bbd1
 
 Test for issue3911
 
   $ hg tag -r 0 -l localtag2
   $ hg tag -l --remove localtag2
   $ hg tags -v
   tip                                1:a0b6fe111088
   localtag                           0:bbd179dfa0a7 local
   globaltag                          0:bbd179dfa0a7
 
   $ hg tag -r 1 -f localtag
   $ hg tags -v
   tip                                2:5c70a037bb37
   localtag                           1:a0b6fe111088
   globaltag                          0:bbd179dfa0a7
 
   $ hg tags -v
   tip                                2:5c70a037bb37
   localtag                           1:a0b6fe111088
   globaltag                          0:bbd179dfa0a7
 
   $ hg tag -r 1 localtag2
   $ hg tags -v
   tip                                3:bbfb8cd42be2
   localtag2                          1:a0b6fe111088
   localtag                           1:a0b6fe111088
   globaltag                          0:bbd179dfa0a7
 
   $ hg tags -v
   tip                                3:bbfb8cd42be2
   localtag2                          1:a0b6fe111088
   localtag                           1:a0b6fe111088
   globaltag                          0:bbd179dfa0a7
 
   $ cd ..
 
 Create a repository with tags data to test .hgtags fnodes transfer
 
   $ hg init tagsserver
   $ cd tagsserver
   $ touch foo
   $ hg -q commit -A -m initial
   $ hg tag -m 'tag 0.1' 0.1
   $ echo second > foo
   $ hg commit -m second
   $ hg tag -m 'tag 0.2' 0.2
   $ hg tags
   tip                                3:40f0358cb314
   0.2                                2:f63cc8fe54e4
   0.1                                0:96ee1d7354c4
   $ cd ..
 
 Cloning should pull down hgtags fnodes mappings and write the cache file
 
   $ hg clone --pull tagsserver tagsclient
   requesting all changes
   adding changesets
   adding manifests
   adding file changes
   added 4 changesets with 4 changes to 2 files
   new changesets 96ee1d7354c4:40f0358cb314
   updating to branch default
   2 files updated, 0 files merged, 0 files removed, 0 files unresolved
 
 Missing tags2* files means the cache wasn't written through the normal mechanism.
 
   $ ls tagsclient/.hg/cache
   branch2-base
   branch2-immutable
   branch2-served
   branch2-served.hidden
   branch2-visible
   branch2-visible-hidden
   hgtagsfnodes1
   rbc-names-v1
   rbc-revs-v1
   tags2
   tags2-served
 
 Cache should contain the head only, even though other nodes have tags data
 
   $ f --size --hexdump tagsclient/.hg/cache/hgtagsfnodes1
   tagsclient/.hg/cache/hgtagsfnodes1: size=96
   0000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0010: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0020: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0030: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0040: ff ff ff ff ff ff ff ff 40 f0 35 8c 19 e0 a7 d3 |........@.5.....|
   0050: 8a 5c 6a 82 4d cf fb a5 87 d0 2f a3 1e 4f 2f 8a |.\j.M...../..O/.|
 
 Running hg tags should produce tags2* file and not change cache
 
   $ hg -R tagsclient tags
   tip                                3:40f0358cb314
   0.2                                2:f63cc8fe54e4
   0.1                                0:96ee1d7354c4
 
   $ ls tagsclient/.hg/cache
   branch2-base
   branch2-immutable
   branch2-served
   branch2-served.hidden
   branch2-visible
   branch2-visible-hidden
   hgtagsfnodes1
   rbc-names-v1
   rbc-revs-v1
   tags2
   tags2-served
   tags2-visible
 
   $ f --size --hexdump tagsclient/.hg/cache/hgtagsfnodes1
   tagsclient/.hg/cache/hgtagsfnodes1: size=96
   0000: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0010: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0020: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0030: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
   0040: ff ff ff ff ff ff ff ff 40 f0 35 8c 19 e0 a7 d3 |........@.5.....|
   0050: 8a 5c 6a 82 4d cf fb a5 87 d0 2f a3 1e 4f 2f 8a |.\j.M...../..O/.|
 
 Check that the bundle includes cache data
 
   $ hg -R tagsclient bundle --all ./test-cache-in-bundle-all-rev.hg
   4 changesets found
   $ hg debugbundle ./test-cache-in-bundle-all-rev.hg
   Stream params: {Compression: BZ}
   changegroup -- {nbchanges: 4, version: 02} (mandatory: True)
       96ee1d7354c4ad7372047672c36a1f561e3a6a4c
       c4dab0c2fd337eb9191f80c3024830a4889a8f34
       f63cc8fe54e4d326f8d692805d70e092f851ddb1
       40f0358cb314c824a5929ee527308d90e023bc10
   hgtagsfnodes -- {} (mandatory: True)
   cache:rev-branch-cache -- {} (mandatory: False)
 
 Check that local clone includes cache data
 
   $ hg clone tagsclient tags-local-clone
   updating to branch default
   2 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ (cd tags-local-clone/.hg/cache/; ls -1 tag*)
   tags2
   tags2-served
   tags2-visible
 
 Avoid writing logs on trying to delete an already deleted tag
   $ hg init issue5752
   $ cd issue5752
   $ echo > a
   $ hg commit -Am 'add a'
   adding a
   $ hg tag a
   $ hg tags
   tip                                1:bd7ee4f3939b
   a                                  0:a8a82d372bb3
   $ hg log
   changeset:   1:bd7ee4f3939b
   tag:         tip
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     Added tag a for changeset a8a82d372bb3
   
   changeset:   0:a8a82d372bb3
   tag:         a
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     add a
   
   $ hg tag --remove a
   $ hg log
   changeset:   2:e7feacc7ec9e
   tag:         tip
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     Removed tag a
   
   changeset:   1:bd7ee4f3939b
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     Added tag a for changeset a8a82d372bb3
   
   changeset:   0:a8a82d372bb3
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     add a
   
   $ hg tag --remove a
   abort: tag 'a' is already removed
   [10]
   $ hg log
   changeset:   2:e7feacc7ec9e
   tag:         tip
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     Removed tag a
   
   changeset:   1:bd7ee4f3939b
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     Added tag a for changeset a8a82d372bb3
   
   changeset:   0:a8a82d372bb3
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     add a
   
   $ cat .hgtags
   a8a82d372bb35b42ff736e74f07c23bcd99c371f a
   a8a82d372bb35b42ff736e74f07c23bcd99c371f a
   0000000000000000000000000000000000000000 a