This is an archive of the discontinued Mercurial Phabricator instance.

Differential D12005

blackbox: add milliseconds to blackbox logs by default
ClosedPublic

Authored by valentin.gatienbaron on Jan 18 2022, 12:45 AM.

Details

Reviewers
Alphare
Group Reviewers
hg-reviewers
Commits
rHG011f5218ff2d: blackbox: add milliseconds to blackbox logs by default
Summary

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.

Diff Detail

Repository
rHG Mercurial
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.

Revision Contents
Changeset List

Diff 31703

hgext/blackbox.py

b'track', b'track',
default=lambda: [b'*'], default=lambda: [b'*'],
) )
configitem( configitem(
b'blackbox', b'blackbox',
b'ignore', b'ignore',
default=lambda: [b'chgserver', b'cmdserver', b'extension'], default=lambda: [b'chgserver', b'cmdserver', b'extension'],
) )
configitem( configitem(b'blackbox', b'date-format', default=b'')
b'blackbox',
b'date-format',
default=b'%Y/%m/%d %H:%M:%S',
)
_lastlogger = loggingutil.proxylogger() _lastlogger = loggingutil.proxylogger()
class blackboxlogger(object): class blackboxlogger(object):
def __init__(self, ui, repo): def __init__(self, ui, repo):
self._repo = repo self._repo = repo
self._trackedevents = set(ui.configlist(b'blackbox', b'track')) self._trackedevents = set(ui.configlist(b'blackbox', b'track'))
self._inlog = True self._inlog = True
try: try:
self._log(ui, event, msg, opts) self._log(ui, event, msg, opts)
finally: finally:
self._inlog = False self._inlog = False
def _log(self, ui, event, msg, opts): def _log(self, ui, event, msg, opts):
default = ui.configdate(b'devel', b'default-date') 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() user = procutil.getuser()
pid = b'%d' % procutil.getpid() pid = b'%d' % procutil.getpid()
changed = b'' changed = b''
ctx = self._repo[None] ctx = self._repo[None]
parents = ctx.parents() parents = ctx.parents()
rev = b'+'.join([hex(p.node()) for p in parents]) rev = b'+'.join([hex(p.node()) for p in parents])
if ui.configbool(b'blackbox', b'dirty') and ctx.dirty( if ui.configbool(b'blackbox', b'dirty') and ctx.dirty(
missing=True, merge=False, branch=False missing=True, merge=False, branch=False
count = 0 count = 0
output = [] output = []
for line in reversed(lines): for line in reversed(lines):
if count >= limit: if count >= limit:
break break
# count the commands by matching lines like: 2013/01/23 19:13:36 root> # 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 count += 1
output.append(line) output.append(line)
ui.status(b'\n'.join(reversed(output))) ui.status(b'\n'.join(reversed(output)))

tests/test-blackbox.t

$ hg init blackboxtest $ hg init blackboxtest
$ cd blackboxtest $ cd blackboxtest
command, exit codes, and duration command, exit codes, and duration
$ echo a > a $ echo a > a
$ hg add a $ hg add a
$ hg blackbox --config blackbox.dirty=True $ 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.000 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.000 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.000 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)> blackbox --config *blackbox.dirty=True* (glob)
failure exit code failure exit code
$ rm ./.hg/blackbox.log $ rm ./.hg/blackbox.log
$ hg add non-existent $ hg add non-existent
non-existent: $ENOENT$ non-existent: $ENOENT$
[1] [1]
$ hg blackbox $ hg blackbox
1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add non-existent 1970/01/01 00:00:00.000 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.000 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)> blackbox
abort exit code abort exit code
$ rm ./.hg/blackbox.log $ rm ./.hg/blackbox.log
$ hg abortcmd 2> /dev/null $ hg abortcmd 2> /dev/null
[255] [255]
$ hg blackbox -l 2 $ 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.000 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)> blackbox -l 2
unhandled exception unhandled exception
$ rm ./.hg/blackbox.log $ rm ./.hg/blackbox.log
#if chg #if chg
(chg exits 255 because it fails to receive an exit code) (chg exits 255 because it fails to receive an exit code)
$ hg crash 2>/dev/null $ hg crash 2>/dev/null
[255] [255]
#else #else
(hg exits 1 because Python default exit code for uncaught exception is 1) (hg exits 1 because Python default exit code for uncaught exception is 1)
$ hg crash 2>/dev/null $ hg crash 2>/dev/null
[1] [1]
#endif #endif
$ hg blackbox -l 2 $ 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.000 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)> blackbox -l 2
alias expansion is logged alias expansion is logged
$ rm ./.hg/blackbox.log $ rm ./.hg/blackbox.log
$ hg confuse $ hg confuse
$ hg blackbox $ hg blackbox
1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> confuse 1970/01/01 00:00:00.000 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.000 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.000 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)> blackbox
recursive aliases work correctly recursive aliases work correctly
$ rm ./.hg/blackbox.log $ rm ./.hg/blackbox.log
$ hg so-confusing $ hg so-confusing
$ hg blackbox $ hg blackbox
1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> so-confusing 1970/01/01 00:00:00.000 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.000 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.000 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.000 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)> blackbox
custom date format custom date format
$ rm ./.hg/blackbox.log $ rm ./.hg/blackbox.log
$ hg --config blackbox.date-format='%Y-%m-%d @ %H:%M:%S' \ $ hg --config blackbox.date-format='%Y-%m-%d @ %H:%M:%S' \
> --config devel.default-date='1334347993 0' --traceback status > --config devel.default-date='1334347993 0' --traceback status
A a A a
$ hg blackbox $ 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 (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) 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 incoming change tracking
create two heads to verify that we only see one change in the log later create two heads to verify that we only see one change in the log later
$ hg commit -ma $ hg commit -ma
$ hg up null $ hg up null
0 files updated, 0 files merged, 1 files removed, 0 files unresolved 0 files updated, 0 files merged, 1 files removed, 0 files unresolved
$ echo b > b $ echo b > b
searching for changes searching for changes
adding changesets adding changesets
adding manifests adding manifests
adding file changes adding file changes
added 1 changesets with 1 changes to 1 files added 1 changesets with 1 changes to 1 files
new changesets d02f48003e62 new changesets d02f48003e62
(run 'hg update' to get a working copy) (run 'hg update' to get a working copy)
$ hg blackbox -l 6 $ 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.000 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.000 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.000 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.000 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.000 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)> blackbox -l 6
we must not cause a failure if we cannot write to the log we must not cause a failure if we cannot write to the log
$ hg rollback $ hg rollback
repository tip rolled back to revision 1 (undo pull) repository tip rolled back to revision 1 (undo pull)
$ mv .hg/blackbox.log .hg/blackbox.log- $ mv .hg/blackbox.log .hg/blackbox.log-
$ mkdir .hg/blackbox.log $ mkdir .hg/blackbox.log
$ touch d $ touch d
$ hg commit -Amd $ hg commit -Amd
adding d adding d
created new head created new head
$ hg strip tip $ hg strip tip
0 files updated, 0 files merged, 1 files removed, 0 files unresolved 0 files updated, 0 files merged, 1 files removed, 0 files unresolved
saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob) saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
$ hg blackbox -l 6 $ hg blackbox -l 6
1970/01/01 00:00:00 bob @73f6ee326b27d820b0472f1a825e3a50f3dc489b (5000)> strip tip 1970/01/01 00:00:00.000 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.000 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.000 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.000 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.000 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 @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> blackbox -l 6
extension and python hooks - use the eol extension for a pythonhook extension and python hooks - use the eol extension for a pythonhook
$ echo '[extensions]' >> .hg/hgrc $ echo '[extensions]' >> .hg/hgrc
$ echo 'eol=' >> .hg/hgrc $ echo 'eol=' >> .hg/hgrc
$ echo '[hooks]' >> .hg/hgrc $ echo '[hooks]' >> .hg/hgrc
$ echo 'update = echo hooked' >> .hg/hgrc $ echo 'update = echo hooked' >> .hg/hgrc
$ hg update $ hg update
The fsmonitor extension is incompatible with the eol extension and has been disabled. (fsmonitor !) The fsmonitor extension is incompatible with the eol extension and has been disabled. (fsmonitor !)
hooked hooked
1 files updated, 0 files merged, 0 files removed, 0 files unresolved 1 files updated, 0 files merged, 0 files removed, 0 files unresolved
updated to "d02f48003e62: c" updated to "d02f48003e62: c"
1 other heads for branch "default" 1 other heads for branch "default"
$ cat >> .hg/hgrc <<EOF $ cat >> .hg/hgrc <<EOF
> [extensions] > [extensions]
> # disable eol, because it is not needed for subsequent tests > # disable eol, because it is not needed for subsequent tests
> # (in addition, keeping it requires extra care for fsmonitor) > # (in addition, keeping it requires extra care for fsmonitor)
> eol=! > eol=!
> EOF > EOF
$ hg blackbox -l 5 $ hg blackbox -l 5
1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> update (no-chg !) 1970/01/01 00:00:00.000 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.000 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.000 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.000 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.000 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 @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> blackbox -l 5
log rotation log rotation
$ echo '[blackbox]' >> .hg/hgrc $ echo '[blackbox]' >> .hg/hgrc
$ echo 'maxsize = 20 b' >> .hg/hgrc $ echo 'maxsize = 20 b' >> .hg/hgrc
$ echo 'maxfiles = 3' >> .hg/hgrc $ echo 'maxfiles = 3' >> .hg/hgrc
$ hg status $ hg status
$ hg status $ hg status
$ hg status $ hg status
$ hg tip -q $ hg tip -q
2:d02f48003e62 2:d02f48003e62
$ ls .hg/blackbox.log* $ ls .hg/blackbox.log*
.hg/blackbox.log .hg/blackbox.log
.hg/blackbox.log.1 .hg/blackbox.log.1
.hg/blackbox.log.2 .hg/blackbox.log.2
$ cd .. $ cd ..
$ hg init blackboxtest3 $ hg init blackboxtest3
$ cd blackboxtest3 $ cd blackboxtest3
$ hg blackbox $ hg blackbox
1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> init blackboxtest3 exited 0 after * seconds (glob) 1970/01/01 00:00:00.000 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)> blackbox
$ mv .hg/blackbox.log .hg/blackbox.log- $ mv .hg/blackbox.log .hg/blackbox.log-
$ mkdir .hg/blackbox.log $ mkdir .hg/blackbox.log
$ sed -e 's/\(.*test1.*\)/#\1/; s#\(.*commit2.*\)#os.rmdir(".hg/blackbox.log")\ $ sed -e 's/\(.*test1.*\)/#\1/; s#\(.*commit2.*\)#os.rmdir(".hg/blackbox.log")\
> os.rename(".hg/blackbox.log-", ".hg/blackbox.log")\ > os.rename(".hg/blackbox.log-", ".hg/blackbox.log")\
> \1#' $TESTDIR/test-dispatch.py > ../test-dispatch.py > \1#' $TESTDIR/test-dispatch.py > ../test-dispatch.py
$ "$PYTHON" $TESTDIR/blackbox-readonly-dispatch.py $ "$PYTHON" $TESTDIR/blackbox-readonly-dispatch.py
running: --debug add foo running: --debug add foo
warning: cannot write to blackbox.log: Is a directory (no-windows !) warning: cannot write to blackbox.log: Is a directory (no-windows !)
files: foo files: foo
extra: branch=default extra: branch=default
description: description:
commit2 commit2
result: 0 result: 0
$ hg blackbox $ hg blackbox
1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> updating the branch cache 1970/01/01 00:00:00.000 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.000 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.000 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.000 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.000 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.000 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.000 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.000 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.000 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)> blackbox
Skip rotation if the .hg is read-only Skip rotation if the .hg is read-only
#if unix-permissions #if unix-permissions
$ chmod -w .hg $ chmod -w .hg
$ hg log -r. -T '{rev}\n' --config blackbox.maxsize=1 --debug $ 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 rename '$TESTTMP/blackboxtest3/.hg/blackbox.log.1' to '$TESTTMP/blackboxtest3/.hg/blackbox.log': Permission denied
warning: cannot write to blackbox.log: Permission denied warning: cannot write to blackbox.log: Permission denied
$ cat >> .hg/hgrc << EOF $ cat >> .hg/hgrc << EOF
> [blackbox] > [blackbox]
> logsource = True > logsource = True
> track = * > track = *
> EOF > EOF
(only look for entries with specific logged sources, otherwise this test is (only look for entries with specific logged sources, otherwise this test is
pretty brittle) pretty brittle)
$ hg blackbox | egrep '\[command(finish)?\]' $ 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.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 bob @0000000000000000000000000000000000000000 (5000) [command]> blackbox 1970/01/01 00:00:00.000 bob @0000000000000000000000000000000000000000 (5000) [command]> blackbox
$ cd $TESTTMP $ cd $TESTTMP
#if chg #if chg
when using chg, blackbox.log should get rotated correctly when using chg, blackbox.log should get rotated correctly
$ cat > $TESTTMP/noop.py << EOF $ cat > $TESTTMP/noop.py << EOF
> from __future__ import absolute_import > from __future__ import absolute_import
[255] [255]
#else #else
(hg exits 1 because Python default exit code for uncaught exception is 1) (hg exits 1 because Python default exit code for uncaught exception is 1)
$ hg raise 2>/dev/null $ hg raise 2>/dev/null
[1] [1]
#endif #endif
$ head -1 .hg/blackbox.log $ 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 $ tail -2 .hg/blackbox.log
RuntimeError: raise RuntimeError: raise

tests/test-devel-warnings.t

mercurial.dispatch:* in _runcommand (glob) mercurial.dispatch:* in _runcommand (glob)
mercurial.dispatch:* in <lambda> (glob) mercurial.dispatch:* in <lambda> (glob)
mercurial.util:* in check (glob) mercurial.util:* in check (glob)
$TESTTMP/buggylocking.py:* in oldanddeprecated (glob) $TESTTMP/buggylocking.py:* in oldanddeprecated (glob)
#endif #endif
#if no-chg no-pyoxidizer #if no-chg no-pyoxidizer
$ hg blackbox -l 7 $ hg blackbox -l 7
1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated 1970/01/01 00:00:00.000 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)> devel-warn: foorbar is deprecated, go shopping
(compatibility will be dropped after Mercurial-42.1337, update your code.) at: $TESTTMP/buggylocking.py:* (oldanddeprecated) (glob) (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.000 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.000 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)> devel-warn: foorbar is deprecated, go shopping
(compatibility will be dropped after Mercurial-42.1337, update your code.) at: (compatibility will be dropped after Mercurial-42.1337, update your code.) at:
*/hg:* in <module> (glob) (?) */hg:* in <module> (glob) (?)
*/mercurial/dispatch.py:* in run (glob) */mercurial/dispatch.py:* in run (glob)
*/mercurial/dispatch.py:* in dispatch (glob) */mercurial/dispatch.py:* in dispatch (glob)
*/mercurial/dispatch.py:* in _rundispatch (glob) */mercurial/dispatch.py:* in _rundispatch (glob)
*/mercurial/dispatch.py:* in _runcatch (glob) */mercurial/dispatch.py:* in _runcatch (glob)
*/mercurial/dispatch.py:* in _callcatch (glob) */mercurial/dispatch.py:* in _callcatch (glob)
*/mercurial/scmutil.py* in callcatch (glob) */mercurial/scmutil.py* in callcatch (glob)
*/mercurial/dispatch.py:* in _runcatchfunc (glob) */mercurial/dispatch.py:* in _runcatchfunc (glob)
*/mercurial/dispatch.py:* in _dispatch (glob) */mercurial/dispatch.py:* in _dispatch (glob)
*/mercurial/dispatch.py:* in runcommand (glob) */mercurial/dispatch.py:* in runcommand (glob)
*/mercurial/dispatch.py:* in _runcommand (glob) */mercurial/dispatch.py:* in _runcommand (glob)
*/mercurial/dispatch.py:* in <lambda> (glob) */mercurial/dispatch.py:* in <lambda> (glob)
*/mercurial/util.py:* in check (glob) */mercurial/util.py:* in check (glob)
$TESTTMP/buggylocking.py:* in oldanddeprecated (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.000 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)> blackbox -l 7
#endif #endif
#if chg no-pyoxidizer #if chg no-pyoxidizer
$ hg blackbox -l 7 $ hg blackbox -l 7
1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated 1970/01/01 00:00:00.000 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)> devel-warn: foorbar is deprecated, go shopping
(compatibility will be dropped after Mercurial-42.1337, update your code.) at: $TESTTMP/buggylocking.py:* (oldanddeprecated) (glob) (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.000 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.000 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)> devel-warn: foorbar is deprecated, go shopping
(compatibility will be dropped after Mercurial-42.1337, update your code.) at: (compatibility will be dropped after Mercurial-42.1337, update your code.) at:
*/hg:* in <module> (glob) */hg:* in <module> (glob)
*/mercurial/dispatch.py:* in run (glob) */mercurial/dispatch.py:* in run (glob)
*/mercurial/dispatch.py:* in dispatch (glob) */mercurial/dispatch.py:* in dispatch (glob)
*/mercurial/dispatch.py:* in _rundispatch (glob) */mercurial/dispatch.py:* in _rundispatch (glob)
*/mercurial/dispatch.py:* in _runcatch (glob) */mercurial/dispatch.py:* in _runcatch (glob)
*/mercurial/dispatch.py:* in _callcatch (glob) */mercurial/dispatch.py:* in _callcatch (glob)
*/mercurial/scmutil.py:* in callcatch (glob) */mercurial/scmutil.py:* in callcatch (glob)
*/mercurial/scmutil.py:* in callcatch (glob) */mercurial/scmutil.py:* in callcatch (glob)
*/mercurial/dispatch.py:* in _runcatchfunc (glob) */mercurial/dispatch.py:* in _runcatchfunc (glob)
*/mercurial/dispatch.py:* in _dispatch (glob) */mercurial/dispatch.py:* in _dispatch (glob)
*/mercurial/dispatch.py:* in runcommand (glob) */mercurial/dispatch.py:* in runcommand (glob)
*/mercurial/dispatch.py:* in _runcommand (glob) */mercurial/dispatch.py:* in _runcommand (glob)
*/mercurial/dispatch.py:* in <lambda> (glob) */mercurial/dispatch.py:* in <lambda> (glob)
*/mercurial/util.py:* in check (glob) */mercurial/util.py:* in check (glob)
$TESTTMP/buggylocking.py:* in oldanddeprecated (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.000 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)> blackbox -l 7
#endif #endif
#if pyoxidizer #if pyoxidizer
$ hg blackbox -l 7 $ hg blackbox -l 7
1970/01/01 00:00:00 bob @cb9a9f314b8b07ba71012fcdbc544b5a4d82ff5b (5000)> oldanddeprecated 1970/01/01 00:00:00.000 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)> devel-warn: foorbar is deprecated, go shopping
(compatibility will be dropped after Mercurial-42.1337, update your code.) at: $TESTTMP/buggylocking.py:* (oldanddeprecated) (glob) (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.000 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.000 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)> devel-warn: foorbar is deprecated, go shopping
(compatibility will be dropped after Mercurial-42.1337, update your code.) at: (compatibility will be dropped after Mercurial-42.1337, update your code.) at:
<string>:* in <module> (glob) <string>:* in <module> (glob)
mercurial.dispatch:* in run (glob) mercurial.dispatch:* in run (glob)
mercurial.dispatch:* in dispatch (glob) mercurial.dispatch:* in dispatch (glob)
mercurial.dispatch:* in _rundispatch (glob) mercurial.dispatch:* in _rundispatch (glob)
mercurial.dispatch:* in _runcatch (glob) mercurial.dispatch:* in _runcatch (glob)
mercurial.dispatch:* in _callcatch (glob) mercurial.dispatch:* in _callcatch (glob)
mercurial.scmutil* in callcatch (glob) mercurial.scmutil* in callcatch (glob)
mercurial.dispatch:* in _runcatchfunc (glob) mercurial.dispatch:* in _runcatchfunc (glob)
mercurial.dispatch:* in _dispatch (glob) mercurial.dispatch:* in _dispatch (glob)
mercurial.dispatch:* in runcommand (glob) mercurial.dispatch:* in runcommand (glob)
mercurial.dispatch:* in _runcommand (glob) mercurial.dispatch:* in _runcommand (glob)
mercurial.dispatch:* in <lambda> (glob) mercurial.dispatch:* in <lambda> (glob)
mercurial.util:* in check (glob) mercurial.util:* in check (glob)
$TESTTMP/buggylocking.py:* in oldanddeprecated (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.000 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)> blackbox -l 7
#endif #endif
Test programming error failure: Test programming error failure:
$ hg buggytransaction 2>&1 | egrep -v '^ ' $ hg buggytransaction 2>&1 | egrep -v '^ '
** Unknown exception encountered with possibly-broken third-party extension "buggylocking" (version N/A) ** Unknown exception encountered with possibly-broken third-party extension "buggylocking" (version N/A)
** which supports versions unknown of Mercurial. ** which supports versions unknown of Mercurial.
** Please disable "buggylocking" and try your action again. ** Please disable "buggylocking" and try your action again.

tests/test-obsolete-tag-cache.t

test1 0:55482a6fb4b1 test1 0:55482a6fb4b1
$ cat .hg/cache/tags2-visible $ cat .hg/cache/tags2-visible
5 2942a772f72a444bef4bef13874d515f50fa27b6 f34fbc9a9769ba9eff5aff3d008a6b49f85c08b1 5 2942a772f72a444bef4bef13874d515f50fa27b6 f34fbc9a9769ba9eff5aff3d008a6b49f85c08b1
042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2 042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1 55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1
$ hg blackbox -l 5 $ hg blackbox -l 5
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> tags 1970/01/01 00:00:00.000 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.000 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.000 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.000 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)> blackbox -l 5
Hiding another changeset should cause the filtered hash to change Hiding another changeset should cause the filtered hash to change
$ hg debugobsolete -d '0 0' d75775ffbc6bca1794d300f5571272879bd280da -u dummyuser $ hg debugobsolete -d '0 0' d75775ffbc6bca1794d300f5571272879bd280da -u dummyuser
1 new obsolescence markers 1 new obsolescence markers
obsoleted 1 changesets obsoleted 1 changesets
$ hg debugobsolete -d '0 0' 5f97d42da03fd56f3b228b03dfe48af5c0adf75b -u dummyuser $ hg debugobsolete -d '0 0' 5f97d42da03fd56f3b228b03dfe48af5c0adf75b -u dummyuser
1 new obsolescence markers 1 new obsolescence markers
obsoleted 1 changesets obsoleted 1 changesets
$ hg tags $ hg tags
tip 5:2942a772f72a tip 5:2942a772f72a
head2 4:042eb6bfcc49 head2 4:042eb6bfcc49
$ cat .hg/cache/tags2-visible $ cat .hg/cache/tags2-visible
5 2942a772f72a444bef4bef13874d515f50fa27b6 2fce1eec33263d08a4d04293960fc73a555230e4 5 2942a772f72a444bef4bef13874d515f50fa27b6 2fce1eec33263d08a4d04293960fc73a555230e4
042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2 042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
$ hg blackbox -l 5 $ hg blackbox -l 5
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> tags 1970/01/01 00:00:00.000 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.000 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.000 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.000 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)> blackbox -l 5
Resolving tags on an unfiltered repo writes a separate tags cache Resolving tags on an unfiltered repo writes a separate tags cache
$ hg --hidden tags $ hg --hidden tags
tip 5:2942a772f72a tip 5:2942a772f72a
head2 4:042eb6bfcc49 head2 4:042eb6bfcc49
test2 2:d75775ffbc6b test2 2:d75775ffbc6b
test1 0:55482a6fb4b1 test1 0:55482a6fb4b1
$ cat .hg/cache/tags2 $ cat .hg/cache/tags2
5 2942a772f72a444bef4bef13874d515f50fa27b6 5 2942a772f72a444bef4bef13874d515f50fa27b6
042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2 042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1 55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1
d75775ffbc6bca1794d300f5571272879bd280da test2 d75775ffbc6bca1794d300f5571272879bd280da test2
$ hg blackbox -l 5 $ hg blackbox -l 5
1970/01/01 00:00:00 bob @2942a772f72a444bef4bef13874d515f50fa27b6 (5000)> --hidden tags 1970/01/01 00:00:00.000 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.000 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.000 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.000 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)> blackbox -l 5

tests/test-tags.t

#endif #endif
Tag cache debug info written to blackbox log Tag cache debug info written to blackbox log
$ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1 $ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1
$ hg identify $ hg identify
b9154636be93 tip b9154636be93 tip
$ hg blackbox -l 6 $ hg blackbox -l 6
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> identify 1970/01/01 00:00:00.000 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.000 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.000 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.000 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.000 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)> blackbox -l 6
Failure to acquire lock results in no write Failure to acquire lock results in no write
$ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1 $ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1
$ echo 'foo:1' > .hg/store/lock $ echo 'foo:1' > .hg/store/lock
$ hg identify $ hg identify
b9154636be93 tip b9154636be93 tip
$ hg blackbox -l 6 $ hg blackbox -l 6
1970/01/01 00:00:00 bob @b9154636be938d3d431e75a7c906504a079bfe07 (5000)> identify 1970/01/01 00:00:00.000 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.000 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.000 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.000 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.000 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)> blackbox -l 6
$ fnodescacheexists $ fnodescacheexists
no fnodes cache no fnodes cache
$ rm .hg/store/lock $ rm .hg/store/lock
$ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1 $ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1
$ hg identify $ hg identify
0040: 00 00 00 00 00 00 00 00 |........| 0040: 00 00 00 00 00 00 00 00 |........|
Merge the two heads: Merge the two heads:
$ hg merge 1 $ hg merge 1
1 files updated, 0 files merged, 0 files removed, 0 files unresolved 1 files updated, 0 files merged, 0 files removed, 0 files unresolved
(branch merge, don't forget to commit) (branch merge, don't forget to commit)
$ hg blackbox -l3 $ hg blackbox -l3
1970/01/01 00:00:00 bob @c8edf04160c7f731e4589d66ab3ab3486a64ac28 (5000)> merge 1 1970/01/01 00:00:00.000 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.000 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+b9154636be938d3d431e75a7c906504a079bfe07 (5000)> blackbox -l3
$ hg id $ hg id
c8edf04160c7+b9154636be93+ tip c8edf04160c7+b9154636be93+ tip
$ hg status $ hg status
M .hgtags M .hgtags
$ hg commit -m "merge" $ hg commit -m "merge"
Create a fake head, make sure tag not visible afterwards: Create a fake head, make sure tag not visible afterwards:
$ echo dummy1 > foo $ echo dummy1 > foo
$ hg commit -m throwaway1 $ hg commit -m throwaway1
$ hg tags $ hg tags
tip 5:8dbfe60eff30 tip 5:8dbfe60eff30
bar 1:78391a272241 bar 1:78391a272241
$ hg blackbox -l 6 $ hg blackbox -l 6
1970/01/01 00:00:00 bob @8dbfe60eff306a54259cfe007db9e330e7ecf866 (5000)> tags 1970/01/01 00:00:00.000 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.000 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.000 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.000 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.000 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)> blackbox -l 6
On junk data + missing cache entries, hg also overwrites the junk. On junk data + missing cache entries, hg also overwrites the junk.
$ rm -f .hg/cache/tags2-visible $ rm -f .hg/cache/tags2-visible
>>> import os >>> import os
>>> with open(".hg/cache/hgtagsfnodes1", "ab+") as fp: >>> with open(".hg/cache/hgtagsfnodes1", "ab+") as fp:
... fp.seek(-10, os.SEEK_END) and None ... fp.seek(-10, os.SEEK_END) and None
... fp.truncate() and None ... fp.truncate() and None
$ chmod a-w .hg/cache/hgtagsfnodes1 $ chmod a-w .hg/cache/hgtagsfnodes1
$ rm -f .hg/cache/tags2-visible $ rm -f .hg/cache/tags2-visible
$ hg tags $ hg tags
tip 6:b968051b5cf3 tip 6:b968051b5cf3
bar 1:78391a272241 bar 1:78391a272241
$ hg blackbox -l 6 $ hg blackbox -l 6
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> tags 1970/01/01 00:00:00.000 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.000 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.000 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.000 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.000 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)> blackbox -l 6
$ chmod a+w .hg/cache/hgtagsfnodes1 $ chmod a+w .hg/cache/hgtagsfnodes1
$ rm -f .hg/cache/tags2-visible $ rm -f .hg/cache/tags2-visible
$ hg tags $ hg tags
tip 6:b968051b5cf3 tip 6:b968051b5cf3
bar 1:78391a272241 bar 1:78391a272241
$ hg blackbox -l 6 $ hg blackbox -l 6
1970/01/01 00:00:00 bob @b968051b5cf3f624b771779c6d5f84f1d4c3fb5d (5000)> tags 1970/01/01 00:00:00.000 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.000 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.000 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.000 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.000 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)> blackbox -l 6
$ f --size .hg/cache/hgtagsfnodes1 $ f --size .hg/cache/hgtagsfnodes1
.hg/cache/hgtagsfnodes1: size=168 .hg/cache/hgtagsfnodes1: size=168
$ hg -q --config extensions.strip= strip -r 6 --no-backup $ hg -q --config extensions.strip= strip -r 6 --no-backup
#endif #endif
Stripping doesn't truncate the tags cache until new data is available Stripping doesn't truncate the tags cache until new data is available
$ rm -f .hg/cache/hgtagsfnodes1 .hg/cache/tags2-visible $ rm -f .hg/cache/hgtagsfnodes1 .hg/cache/tags2-visible
$ hg tags $ hg tags
tip 5:8dbfe60eff30 tip 5:8dbfe60eff30
bar 1:78391a272241 bar 1:78391a272241
$ f --size .hg/cache/hgtagsfnodes1 $ f --size .hg/cache/hgtagsfnodes1
.hg/cache/hgtagsfnodes1: size=144 .hg/cache/hgtagsfnodes1: size=144
$ hg -q --config extensions.strip= strip -r 5 --no-backup $ hg -q --config extensions.strip= strip -r 5 --no-backup
$ hg tags $ hg tags
tip 4:0c192d7d5e6b tip 4:0c192d7d5e6b
bar 1:78391a272241 bar 1:78391a272241
$ hg blackbox -l 5 $ 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.000 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.000 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.000 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.000 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)> blackbox -l 5
$ f --size .hg/cache/hgtagsfnodes1 $ f --size .hg/cache/hgtagsfnodes1
.hg/cache/hgtagsfnodes1: size=120 .hg/cache/hgtagsfnodes1: size=120
$ echo dummy > foo $ echo dummy > foo
$ hg commit -m throwaway3 $ hg commit -m throwaway3
$ hg tags $ hg tags
tip 5:035f65efb448 tip 5:035f65efb448
bar 1:78391a272241 bar 1:78391a272241
$ hg blackbox -l 6 $ hg blackbox -l 6
1970/01/01 00:00:00 bob @035f65efb448350f4772141702a81ab1df48c465 (5000)> tags 1970/01/01 00:00:00.000 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.000 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.000 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.000 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.000 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)> blackbox -l 6
$ f --size .hg/cache/hgtagsfnodes1 $ f --size .hg/cache/hgtagsfnodes1
.hg/cache/hgtagsfnodes1: size=144 .hg/cache/hgtagsfnodes1: size=144
$ hg -q --config extensions.strip= strip -r 5 --no-backup $ hg -q --config extensions.strip= strip -r 5 --no-backup
Test tag removal: Test tag removal:
$ hg tag --remove bar # rev 5 $ hg tag --remove bar # rev 5