tests/test-blackbox.t
author Pierre-Yves David <pierre-yves.david@octobus.net>
Mon, 14 Dec 2020 11:32:24 +0100
changeset 46149 294d5aca4ff5
parent 45967 a2104b9b1787
child 46314 95a615dd77bf
permissions -rw-r--r--
copies: iterate over children directly (instead of parents) Before this change we would gather all parent → child edges and iterate on all parent, gathering copy information for children and aggregating them from there. They are not strict requirement for edges to be processed in that specific order. We could also simply iterate over all "children" revision and aggregate data from both parents at the same time. This patch does that. It make various things simpler: * since both parents are processed at the same time, we no longer need to cache data for merge (see next changeset for details), * we no longer need nested loop to process data, * we no longer need to store partial merge data for a rev from distinct loop interaction to another when processing merges, * we no longer need to build a full parent -> children mapping (we only rely on a simpler "parent -> number of children" map (for memory efficiency), * the data access pattern is now simpler (from lower revisions to higher revisions) and entirely predicable. That predictability open the way to prefetching and parallel processing. So that new iterations order requires simpler code and open the way to interesting optimisation. The effect on performance is quite good. In the worse case, we don't see any significant negative impact. And in the best case, the reduction of roundtrip to Python provide us with a significant speed. Some example below: Repo Case Source-Rev Dest-Rev # of revisions old time new time Difference Factor time per rev --------------------------------------------------------------------------------------------------------------------------------------------------------------- mozilla-try x00000_revs_x00000_added_0_copies dc8a3ca7010e d16fde900c9c : 34414 revs, 0.962867 s, 0.502584 s, -0.460283 s, × 0.5220, 14 µs/rev mozilla-try x0000_revs_xx000_added_x_copies 156f6e2674f2 4d0f2c178e66 : 8598 revs, 0.110717 s, 0.076323 s, -0.034394 s, × 0.6894, 8 µs/rev # full comparison between the previous changeset and this one Repo Case Source-Rev Dest-Rev # of revisions old time new time Difference Factor time per rev --------------------------------------------------------------------------------------------------------------------------------------------------------------- mercurial x_revs_x_added_0_copies ad6b123de1c7 39cfcef4f463 : 1 revs, 0.000048 s, 0.000041 s, -0.000007 s, × 0.8542, 41 µs/rev mercurial x_revs_x_added_x_copies 2b1c78674230 0c1d10351869 : 6 revs, 0.000153 s, 0.000102 s, -0.000051 s, × 0.6667, 17 µs/rev mercurial x000_revs_x000_added_x_copies 81f8ff2a9bf2 dd3267698d84 : 1032 revs, 0.004209 s, 0.004254 s, +0.000045 s, × 1.0107, 4 µs/rev pypy x_revs_x_added_0_copies aed021ee8ae8 099ed31b181b : 9 revs, 0.000203 s, 0.000282 s, +0.000079 s, × 1.3892, 31 µs/rev pypy x_revs_x000_added_0_copies 4aa4e1f8e19a 359343b9ac0e : 1 revs, 0.000059 s, 0.000048 s, -0.000011 s, × 0.8136, 48 µs/rev pypy x_revs_x_added_x_copies ac52eb7bbbb0 72e022663155 : 7 revs, 0.000194 s, 0.000211 s, +0.000017 s, × 1.0876, 30 µs/rev pypy x_revs_x00_added_x_copies c3b14617fbd7 ace7255d9a26 : 1 revs, 0.000380 s, 0.000375 s, -0.000005 s, × 0.9868, 375 µs/rev pypy x_revs_x000_added_x000_copies df6f7a526b60 a83dc6a2d56f : 6 revs, 0.010588 s, 0.010574 s, -0.000014 s, × 0.9987, 1762 µs/rev pypy x000_revs_xx00_added_0_copies 89a76aede314 2f22446ff07e : 4785 revs, 0.048961 s, 0.049974 s, +0.001013 s, × 1.0207, 10 µs/rev pypy x000_revs_x000_added_x_copies 8a3b5bfd266e 2c68e87c3efe : 6780 revs, 0.083612 s, 0.084300 s, +0.000688 s, × 1.0082, 12 µs/rev pypy x000_revs_x000_added_x000_copies 89a76aede314 7b3dda341c84 : 5441 revs, 0.058579 s, 0.060128 s, +0.001549 s, × 1.0264, 11 µs/rev pypy x0000_revs_x_added_0_copies d1defd0dc478 c9cb1334cc78 : 43645 revs, 0.736783 s, 0.686542 s, -0.050241 s, × 0.9318, 15 µs/rev pypy x0000_revs_xx000_added_0_copies bf2c629d0071 4ffed77c095c : 2 revs, 0.022050 s, 0.009277 s, -0.012773 s, × 0.4207, 4638 µs/rev pypy x0000_revs_xx000_added_x000_copies 08ea3258278e d9fa043f30c0 : 11316 revs, 0.120800 s, 0.114733 s, -0.006067 s, × 0.9498, 10 µs/rev netbeans x_revs_x_added_0_copies fb0955ffcbcd a01e9239f9e7 : 2 revs, 0.000140 s, 0.000081 s, -0.000059 s, × 0.5786, 40 µs/rev netbeans x_revs_x000_added_0_copies 6f360122949f 20eb231cc7d0 : 2 revs, 0.000114 s, 0.000107 s, -0.000007 s, × 0.9386, 53 µs/rev netbeans x_revs_x_added_x_copies 1ada3faf6fb6 5a39d12eecf4 : 3 revs, 0.000224 s, 0.000173 s, -0.000051 s, × 0.7723, 57 µs/rev netbeans x_revs_x00_added_x_copies 35be93ba1e2c 9eec5e90c05f : 9 revs, 0.000723 s, 0.000698 s, -0.000025 s, × 0.9654, 77 µs/rev netbeans x000_revs_xx00_added_0_copies eac3045b4fdd 51d4ae7f1290 : 1421 revs, 0.009665 s, 0.009248 s, -0.000417 s, × 0.9569, 6 µs/rev netbeans x000_revs_x000_added_x_copies e2063d266acd 6081d72689dc : 1533 revs, 0.014820 s, 0.015446 s, +0.000626 s, × 1.0422, 10 µs/rev netbeans x000_revs_x000_added_x000_copies ff453e9fee32 411350406ec2 : 5750 revs, 0.076049 s, 0.074373 s, -0.001676 s, × 0.9780, 12 µs/rev netbeans x0000_revs_xx000_added_x000_copies 588c2d1ced70 1aad62e59ddd : 66949 revs, 0.683603 s, 0.639870 s, -0.043733 s, × 0.9360, 9 µs/rev mozilla-central x_revs_x_added_0_copies 3697f962bb7b 7015fcdd43a2 : 2 revs, 0.000161 s, 0.000088 s, -0.000073 s, × 0.5466, 44 µs/rev mozilla-central x_revs_x000_added_0_copies dd390860c6c9 40d0c5bed75d : 8 revs, 0.000234 s, 0.000199 s, -0.000035 s, × 0.8504, 24 µs/rev mozilla-central x_revs_x_added_x_copies 8d198483ae3b 14207ffc2b2f : 9 revs, 0.000247 s, 0.000171 s, -0.000076 s, × 0.6923, 19 µs/rev mozilla-central x_revs_x00_added_x_copies 98cbc58cc6bc 446a150332c3 : 7 revs, 0.000630 s, 0.000592 s, -0.000038 s, × 0.9397, 84 µs/rev mozilla-central x_revs_x000_added_x000_copies 3c684b4b8f68 0a5e72d1b479 : 3 revs, 0.003286 s, 0.003151 s, -0.000135 s, × 0.9589, 1050 µs/rev mozilla-central x_revs_x0000_added_x0000_copies effb563bb7e5 c07a39dc4e80 : 6 revs, 0.062441 s, 0.061612 s, -0.000829 s, × 0.9867, 10268 µs/rev mozilla-central x000_revs_xx00_added_0_copies 6100d773079a 04a55431795e : 1593 revs, 0.005423 s, 0.005381 s, -0.000042 s, × 0.9923, 3 µs/rev mozilla-central x000_revs_x000_added_x_copies 9f17a6fc04f9 2d37b966abed : 41 revs, 0.005919 s, 0.003742 s, -0.002177 s, × 0.6322, 91 µs/rev mozilla-central x000_revs_x000_added_x000_copies 7c97034feb78 4407bd0c6330 : 7839 revs, 0.062597 s, 0.061983 s, -0.000614 s, × 0.9902, 7 µs/rev mozilla-central x0000_revs_xx000_added_0_copies 9eec5917337d 67118cc6dcad : 615 revs, 0.043551 s, 0.019861 s, -0.023690 s, × 0.4560, 32 µs/rev mozilla-central x0000_revs_xx000_added_x000_copies f78c615a656c 96a38b690156 : 30263 revs, 0.192475 s, 0.188101 s, -0.004374 s, × 0.9773, 6 µs/rev mozilla-central x00000_revs_x0000_added_x0000_copies 6832ae71433c 4c222a1d9a00 : 153721 revs, 1.955575 s, 1.806696 s, -0.148879 s, × 0.9239, 11 µs/rev mozilla-central x00000_revs_x00000_added_x000_copies 76caed42cf7c 1daa622bbe42 : 204976 revs, 2.886501 s, 2.682987 s, -0.203514 s, × 0.9295, 13 µs/rev mozilla-try x_revs_x_added_0_copies aaf6dde0deb8 9790f499805a : 2 revs, 0.001181 s, 0.000852 s, -0.000329 s, × 0.7214, 426 µs/rev mozilla-try x_revs_x000_added_0_copies d8d0222927b4 5bb8ce8c7450 : 2 revs, 0.001189 s, 0.000859 s, -0.000330 s, × 0.7225, 429 µs/rev mozilla-try x_revs_x_added_x_copies 092fcca11bdb 936255a0384a : 4 revs, 0.000563 s, 0.000150 s, -0.000413 s, × 0.2664, 37 µs/rev mozilla-try x_revs_x00_added_x_copies b53d2fadbdb5 017afae788ec : 2 revs, 0.001548 s, 0.001158 s, -0.000390 s, × 0.7481, 579 µs/rev mozilla-try x_revs_x000_added_x000_copies 20408ad61ce5 6f0ee96e21ad : 1 revs, 0.027782 s, 0.027240 s, -0.000542 s, × 0.9805, 27240 µs/rev mozilla-try x_revs_x0000_added_x0000_copies effb563bb7e5 c07a39dc4e80 : 6 revs, 0.062781 s, 0.062824 s, +0.000043 s, × 1.0007, 10470 µs/rev mozilla-try x000_revs_xx00_added_0_copies 6100d773079a 04a55431795e : 1593 revs, 0.005778 s, 0.005463 s, -0.000315 s, × 0.9455, 3 µs/rev mozilla-try x000_revs_x000_added_x_copies 9f17a6fc04f9 2d37b966abed : 41 revs, 0.006192 s, 0.004238 s, -0.001954 s, × 0.6844, 103 µs/rev mozilla-try x000_revs_x000_added_x000_copies 1346fd0130e4 4c65cbdabc1f : 6657 revs, 0.065391 s, 0.064113 s, -0.001278 s, × 0.9805, 9 µs/rev mozilla-try x0000_revs_x_added_0_copies 63519bfd42ee a36a2a865d92 : 40314 revs, 0.317216 s, 0.294063 s, -0.023153 s, × 0.9270, 7 µs/rev mozilla-try x0000_revs_x_added_x_copies 9fe69ff0762d bcabf2a78927 : 38690 revs, 0.303119 s, 0.281493 s, -0.021626 s, × 0.9287, 7 µs/rev mozilla-try x0000_revs_xx000_added_x_copies 156f6e2674f2 4d0f2c178e66 : 8598 revs, 0.110717 s, 0.076323 s, -0.034394 s, × 0.6894, 8 µs/rev mozilla-try x0000_revs_xx000_added_0_copies 9eec5917337d 67118cc6dcad : 615 revs, 0.045739 s, 0.020390 s, -0.025349 s, × 0.4458, 33 µs/rev mozilla-try x0000_revs_xx000_added_x000_copies 89294cd501d9 7ccb2fc7ccb5 : 97052 revs, 3.098021 s, 3.023879 s, -0.074142 s, × 0.9761, 31 µs/rev mozilla-try x0000_revs_x0000_added_x0000_copies e928c65095ed e951f4ad123a : 52031 revs, 0.771480 s, 0.735549 s, -0.035931 s, × 0.9534, 14 µs/rev mozilla-try x00000_revs_x_added_0_copies 6a320851d377 1ebb79acd503 : 363753 revs, 18.813422 s, 18.568900 s, -0.244522 s, × 0.9870, 51 µs/rev mozilla-try x00000_revs_x00000_added_0_copies dc8a3ca7010e d16fde900c9c : 34414 revs, 0.962867 s, 0.502584 s, -0.460283 s, × 0.5220, 14 µs/rev mozilla-try x00000_revs_x_added_x_copies 5173c4b6f97c 95d83ee7242d : 362229 revs, 18.684923 s, 18.356645 s, -0.328278 s, × 0.9824, 50 µs/rev mozilla-try x00000_revs_x000_added_x_copies 9126823d0e9c ca82787bb23c : 359344 revs, 18.296305 s, 18.250393 s, -0.045912 s, × 0.9975, 50 µs/rev mozilla-try x00000_revs_x0000_added_x0000_copies 8d3fafa80d4b eb884023b810 : 192665 revs, 3.061887 s, 2.792459 s, -0.269428 s, × 0.9120, 14 µs/rev mozilla-try x00000_revs_x00000_added_x0000_copies 1b661134e2ca 1ae03d022d6d : 228985 revs, 103.869641 s, 107.697264 s, +3.827623 s, × 1.0369, 470 µs/rev mozilla-try x00000_revs_x00000_added_x000_copies 9b2a99adc05e 8e29777b48e6 : 382065 revs, 64.262957 s, 63.961040 s, -0.301917 s, × 0.9953, 167 µs/rev Differential Revision: https://phab.mercurial-scm.org/D9422

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)

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

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

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

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

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

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

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)> pull
  1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> updated branch cache (served) in * seconds (glob)
  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)> 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

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 (base) in * seconds (glob)
  1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote branch cache (base) 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

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 --cmdserver chgunix --address $TESTTMP.chgsock/server.* --daemon-postexec 'chdir:/' (glob) (chg !)
  1970/01/01 00:00:00 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
  $ 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

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
  $ 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)
  $ tail -2 .hg/blackbox.log
  RuntimeError: raise