tests/test-logtoprocess.t

obsolescence: add test case A-6 for obsolescence markers exchange

About 3 years ago, in August 2014, the logic to select what markers to select on
push was ported from the evolve extension to Mercurial core. However, for some
unclear reasons, the tests for that logic were not ported alongside.
I realised it a couple of weeks ago while working on another push related issue.
I've made a clean up pass on the tests and they are now ready to integrate the
core test suite. This series of changesets do not change any logic. I just adds
test for logic that has been around for about 10 versions of Mercurial.

They are a patch for each test case. It makes it easier to review and postpone
one with documentation issues without rejecting the wholes series.

This patch introduce case A6:

  new markers between changesets already known on both side

Each test case comes it in own test file. It help parallelism and does not
introduce a significant overhead from having a single unified giant test file.
Here are timing  to support this claim.

# Multiple test files version:
# run-tests.py --local -j 1 test-exchange-*.t
53.40s user 6.82s system 85% cpu 1:10.76 total
52.79s user 6.97s system 85% cpu 1:09.97 total
52.94s user 6.82s system 85% cpu 1:09.69 total

# Single test file version:
# run-tests.py --local -j 1 test-exchange-obsmarkers.t
52.97s user 6.85s system 85% cpu 1:10.10 total
52.64s user 6.79s system 85% cpu 1:09.63 total
53.70s user 7.00s system 85% cpu 1:11.17 total

ATTENTION: logtoprocess runs commands asynchronously. Be sure to append "| cat"
to hg commands, to wait for the output, if you want to test its output.
Otherwise the test will be flaky.

Test if logtoprocess correctly captures command-related log calls.

  $ hg init
  $ cat > $TESTTMP/foocommand.py << EOF
  > from mercurial import cmdutil
  > from time import sleep
  > cmdtable = {}
  > command = cmdutil.command(cmdtable)
  > @command('foo', [])
  > def foo(ui, repo):
  >     ui.log('foo', 'a message: %(bar)s\n', bar='spam')
  > EOF
  $ cp $HGRCPATH $HGRCPATH.bak
  $ cat >> $HGRCPATH << EOF
  > [extensions]
  > logtoprocess=
  > foocommand=$TESTTMP/foocommand.py
  > [logtoprocess]
  > command=echo 'logtoprocess command output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$MSG2"
  > commandfinish=echo 'logtoprocess commandfinish output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$MSG2";
  >     echo "\$MSG3"
  > foo=echo 'logtoprocess foo output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$OPT_BAR"
  > EOF

Running a command triggers both a ui.log('command') and a
ui.log('commandfinish') call. The foo command also uses ui.log.

Use sort to avoid ordering issues between the various processes we spawn:
  $ hg foo | cat | sort
  
  
  
  0
  a message: spam
  command
  commandfinish
  foo
  foo
  foo
  foo
  foo exited 0 after * seconds (glob)
  logtoprocess command output:
  logtoprocess commandfinish output:
  logtoprocess foo output:
  spam

Confirm that logging blocked time catches stdio properly:
  $ cp $HGRCPATH.bak $HGRCPATH
  $ cat >> $HGRCPATH << EOF
  > [extensions]
  > logtoprocess=
  > pager=
  > [logtoprocess]
  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms"
  > [ui]
  > logblockedtimes=True
  > EOF

  $ hg log | cat
  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)